Kernel crash with "USB disconnect"

[JulianGu001]

Describe the bug

Hi

We use Pi3 as BLE Host, and the BLE Device we developed connect to Pi3 via USB port.
Recently, we encounter a kernel crash ocacionally, which looks has something to do with kernel. Could you please help to give some comment?

Steps to reproduce the behaviour

normal BLE traffice via USB

Device (s)

Raspberry Pi 3 Mod. B+

System

cat /etc/rpi-issue
Raspberry Pi reference 2021-10-30
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 288b21fc27e128ea6b330777aca68e0061ebf4fe, stage5

vcgencmd version
Nov 18 2021 16:18:09
Copyright (c) 2012 Broadcom
version d9b293558b4cef6aabedcc53c178e7604de90788 (clean) (release) (start)

uname -a
Linux raspberrypi 5.10.63-v7+ #1488 SMP Thu Nov 18 16:14:44 GMT 2021 armv7l GNU/Linux

Logs

Feb 15 14:56:24 raspberrypi systemd[1]: Starting PackageKit Daemon...
Feb 15 14:56:25 raspberrypi PackageKit: daemon start
Feb 15 14:56:25 raspberrypi dbus-daemon[391]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Feb 15 14:56:25 raspberrypi systemd[1]: Started PackageKit Daemon.
Feb 15 14:56:28 raspberrypi kernel: [ 32.234612] Voltage normalised (0x00000000)
Feb 15 14:56:30 raspberrypi PackageKit: refresh-cache transaction /70_bcccadca from uid 1000 finished with success after 4662ms
Feb 15 14:56:36 raspberrypi systemd[1]: systemd-fsckd.service: Succeeded.
Feb 15 14:56:37 raspberrypi PackageKit: get-updates transaction /71_dccdecbc from uid 1000 finished with success after 7596ms
Feb 15 14:56:47 raspberrypi systemd[1]: systemd-hostnamed.service: Succeeded.
Feb 15 14:57:43 raspberrypi systemd[1]: Started Session 4 of user pi.
Feb 15 15:00:41 raspberrypi systemd[1]: Started Session 5 of user pi.
Feb 15 15:00:49 raspberrypi systemd[1]: Started Session 6 of user pi.
Feb 15 15:00:50 raspberrypi kernel: [ 294.318866] Under-voltage detected! (0x00050005)
Feb 15 15:00:54 raspberrypi kernel: [ 298.478989] Voltage normalised (0x00000000)
Feb 15 15:01:06 raspberrypi qesl_me_agent: [cpu1, tid:1206]:run_thread: thread id 1206, thread name Agent_Main_Thre started
Feb 15 15:01:06 raspberrypi qesl_me_agent: [cpu0, tid:1205]:PostMessage Thread Name = Agent_Main_Thread
Feb 15 15:01:06 raspberrypi qesl_me_agent: [cpu1, tid:1206]:UDS client: Init...
Feb 15 15:01:06 raspberrypi qesl_me_agent: [cpu1, tid:1206]:TCP client: Init...
Feb 15 15:01:06 raspberrypi qesl_me_agent: [cpu1, tid:1206]: Processing event 0
Feb 15 15:01:06 raspberrypi qesl_me_agent: [cpu1, tid:1206]: Default Case
Feb 15 15:01:08 raspberrypi qesl_ap_daemon: [cpu1, tid:1210]:qesl_ap_daemon log level: QESL_AP_LOG_LEVEL_API
Feb 15 15:01:08 raspberrypi qesl_ap_daemon: [cpu1, tid:1210]:qesl_ap_daemon version: 2.1.186.20210518.
Feb 15 15:01:08 raspberrypi qesl_ap_daemon: [cpu1, tid:1210]::: QESL ap starting
Feb 15 15:01:08 raspberrypi qesl_ap_daemon: [cpu1, tid:1210]:[API] Creating threads ++++++
Feb 15 15:01:08 raspberrypi qesl_ap_daemon: [cpu1, tid:1210]:[API] Creating threads ------
Feb 15 15:01:08 raspberrypi qesl_ap_daemon: [cpu1, tid:1210]:#12[API] qesl_ap_open_stack().
Feb 15 15:01:08 raspberrypi qesl_ap_daemon: usb receive hci event data len = 14
Feb 15 15:01:08 raspberrypi qesl_ap_daemon: usb receive hci event data len = 16
Feb 15 15:01:08 raspberrypi qesl_ap_daemon: usb receive hci event data len = 4
Feb 15 15:01:09 raspberrypi qesl_me_agent: [cpu2, tid:1207]:UDS client: Reconnect Server Failed -- No such file or directory
Feb 15 15:01:09 raspberrypi qesl_me_agent: [cpu0, tid:1208]:TCP client: Reconnect Server Failed -- Connection refused
Feb 15 15:01:09 raspberrypi qesl_me_agent: [cpu0, tid:1208]:TCP client:connect Server 10.233.66.61:6666 success...
Feb 15 15:01:09 raspberrypi kernel: [ 313.434541] usb 1-1.1.2: USB disconnect, device number 4
Feb 15 15:01:09 raspberrypi kernel: [ 313.435472] ------------[ cut here ]------------
Feb 15 15:01:09 raspberrypi kernel: [ 313.435503] WARNING: CPU: 0 PID: 35 at fs/sysfs/group.c:281 sysfs_remove_group+0xa8/0xac
Feb 15 15:01:09 raspberrypi kernel: [ 313.435517] sysfs group 'power' not found for kobject 'SS1BTUSB0'
Feb 15 15:01:09 raspberrypi kernel: [ 313.435528] Modules linked in: rfcomm cmac algif_hash aes_arm_bs crypto_simd cryptd algif_skcipher af_alg bnep hci_uart 8021q garp stp llc SS1BTUSBM(O) snd_soc_hdmi_codec btusb btrtl btintel btbcm bluetooth ecdh_generic ecc brcmfmac vc4 brcmutil cec drm_kms_helper snd_soc_core sha256_generic snd_compress snd_pcm_dmaengine syscopyarea sysfillrect sysimgblt fb_sys_fops raspberrypi_hwmon cfg80211 rfkill i2c_bcm2835 bcm2835_codec(C) snd_bcm2835(C) v4l2_mem2mem bcm2835_isp(C) snd_pcm videobuf2_dma_contig bcm2835_v4l2(C) bcm2835_mmal_vchiq(C) snd_timer videobuf2_vmalloc videobuf2_memops snd videobuf2_v4l2 videobuf2_common vc_sm_cma(C) videodev mc fixed uio_pdrv_genirq uio i2c_dev drm drm_panel_orientation_quirks backlight fuse ip_tables x_tables ipv6
Feb 15 15:01:09 raspberrypi kernel: [ 313.436276] CPU: 0 PID: 35 Comm: kworker/0:2 Tainted: G C O 5.10.63-v7+ #1488
Feb 15 15:01:09 raspberrypi kernel: [ 313.436283] Hardware name: BCM2835
Feb 15 15:01:09 raspberrypi kernel: [ 313.436301] Workqueue: usb_hub_wq hub_event
Feb 15 15:01:09 raspberrypi kernel: [ 313.436313] Backtrace:
Feb 15 15:01:09 raspberrypi kernel: [ 313.436338] [<809f0cb0>] (dump_backtrace) from [<809f1040>] (show_stack+0x20/0x24)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436353] r7:ffffffff r6:00000000 r5:60000013 r4:80fe5e54
Feb 15 15:01:09 raspberrypi kernel: [ 313.436371] [<809f1020>] (show_stack) from [<809f5250>] (dump_stack+0xcc/0xf8)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436389] [<809f5184>] (dump_stack) from [<8011eca0>] (__warn+0xfc/0x114)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436406] r10:81fe8800 r9:00000009 r8:803ed74c r7:00000119 r6:00000009 r5:803ed74c
Feb 15 15:01:09 raspberrypi kernel: [ 313.436415] r4:80d21060 r3:80f05050
Feb 15 15:01:09 raspberrypi kernel: [ 313.436431] [<8011eba4>] (__warn) from [<809f16c0>] (warn_slowpath_fmt+0xa4/0xd8)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436445] r7:00000119 r6:80d21060 r5:80f05008 r4:80d21108
Feb 15 15:01:09 raspberrypi kernel: [ 313.436462] [<809f1620>] (warn_slowpath_fmt) from [<803ed74c>] (sysfs_remove_group+0xa8/0xac)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436478] r9:7f26e5fc r8:82458c20 r7:80f05008 r6:8425b000 r5:80b48d58 r4:00000000
Feb 15 15:01:09 raspberrypi kernel: [ 313.436497] [<803ed6a4>] (sysfs_remove_group) from [<8071be40>] (dpm_sysfs_remove+0x58/0x6c)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436508] r6:00000000 r5:8425b044 r4:8425b000
Feb 15 15:01:09 raspberrypi kernel: [ 313.436528] [<8071bde8>] (dpm_sysfs_remove) from [<8070c124>] (device_del+0xc0/0x420)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436538] r5:8425b044 r4:8425b000
Feb 15 15:01:09 raspberrypi kernel: [ 313.436556] [<8070c064>] (device_del) from [<8070c5c0>] (device_destroy+0x54/0x78)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436572] r10:81fe8800 r9:7f26e5fc r8:00000000 r7:00000001 r6:00000000 r5:8425b000
Feb 15 15:01:09 raspberrypi kernel: [ 313.436581] r4:80f05008
Feb 15 15:01:09 raspberrypi kernel: [ 313.436598] [<8070c56c>] (device_destroy) from [<8079a6e8>] (usb_deregister_dev+0x40/0xe0)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436608] r5:82458c00 r4:810ee698
Feb 15 15:01:09 raspberrypi kernel: [ 313.436637] [<8079a6a8>] (usb_deregister_dev) from [<7f26a224>] (USBDisconnect+0x120/0x1d8 [SS1BTUSBM])
Feb 15 15:01:09 raspberrypi kernel: [ 313.436650] r7:00000001 r6:00000004 r5:7f26e5c0 r4:84c0b000
Feb 15 15:01:09 raspberrypi kernel: [ 313.436679] [<7f26a104>] (USBDisconnect [SS1BTUSBM]) from [<80797e0c>] (usb_unbind_interface+0x78/0x240)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436695] r9:7f26e5fc r8:81fe8878 r7:82458e20 r6:7f26e5fc r5:00000000 r4:81fe8878
Feb 15 15:01:09 raspberrypi kernel: [ 313.436716] [<80797d94>] (usb_unbind_interface) from [<807125f4>] (device_release_driver_internal+0x10c/0x1c0)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436732] r10:00000002 r9:82458200 r8:81fe8878 r7:80f05008 r6:7f26e5fc r5:00000000
Feb 15 15:01:09 raspberrypi kernel: [ 313.436740] r4:82458e20
Feb 15 15:01:09 raspberrypi kernel: [ 313.436756] [<807124e8>] (device_release_driver_internal) from [<807126c8>] (device_release_driver+0x20/0x24)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436769] r7:80f05008 r6:80ff82e4 r5:82458e20 r4:816a8b30
Feb 15 15:01:09 raspberrypi kernel: [ 313.436785] [<807126a8>] (device_release_driver) from [<80710d98>] (bus_remove_device+0xdc/0x108)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436801] [<80710cbc>] (bus_remove_device) from [<8070c1f4>] (device_del+0x190/0x420)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436814] r7:80f05008 r6:00000000 r5:0000e504 r4:82458e20
Feb 15 15:01:09 raspberrypi kernel: [ 313.436832] [<8070c064>] (device_del) from [<807954f4>] (usb_disable_device+0x98/0x134)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436847] r10:00000002 r9:82458200 r8:82458800 r7:82458e00 r6:00000000 r5:00000002
Feb 15 15:01:09 raspberrypi kernel: [ 313.436856] r4:81fe8800
Feb 15 15:01:09 raspberrypi kernel: [ 313.436872] [<8079545c>] (usb_disable_device) from [<8078bb30>] (usb_disconnect+0xcc/0x248)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436888] r9:82458200 r8:82458800 r7:81fe8878 r6:81fe88bc r5:82458200 r4:81fe8800
Feb 15 15:01:09 raspberrypi kernel: [ 313.436903] [<8078ba64>] (usb_disconnect) from [<8078dbd0>] (hub_event+0xae0/0x1308)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436919] r10:00000002 r9:81f53d00 r8:00000101 r7:00000002 r6:81fe8400 r5:82458200
Feb 15 15:01:09 raspberrypi kernel: [ 313.436927] r4:00000000
Feb 15 15:01:09 raspberrypi kernel: [ 313.436945] [<8078d0f0>] (hub_event) from [<8013b900>] (process_one_work+0x250/0x5a0)
Feb 15 15:01:09 raspberrypi kernel: [ 313.436961] r10:00000000 r9:00000000 r8:00000000 r7:baad0900 r6:baacb6c0 r5:81685a00
Feb 15 15:01:09 raspberrypi kernel: [ 313.436969] r4:81f53d00
Feb 15 15:01:09 raspberrypi kernel: [ 313.436986] [<8013b6b0>] (process_one_work) from [<8013bcb0>] (worker_thread+0x60/0x5c4)
Feb 15 15:01:09 raspberrypi kernel: [ 313.437001] r10:baacb6c0 r9:80f03d00 r8:baacb6d8 r7:00000008 r6:baacb6c0 r5:81685a14
Feb 15 15:01:09 raspberrypi kernel: [ 313.437009] r4:81685a00
Feb 15 15:01:09 raspberrypi kernel: [ 313.437028] [<8013bc50>] (worker_thread) from [<80143790>] (kthread+0x170/0x174)
Feb 15 15:01:09 raspberrypi kernel: [ 313.437043] r10:81523e74 r9:81685a00 r8:8013bc50 r7:816ae000 r6:00000000 r5:81692480
Feb 15 15:01:09 raspberrypi kernel: [ 313.437052] r4:815aa1c0
Feb 15 15:01:09 raspberrypi kernel: [ 313.437068] [<80143620>] (kthread) from [<801000ec>] (ret_from_fork+0x14/0x28)
Feb 15 15:01:09 raspberrypi kernel: [ 313.437077] Exception stack(0x816affb0 to 0x816afff8)
Feb 15 15:01:09 raspberrypi kernel: [ 313.437089] ffa0: 00000000 00000000 00000000 00000000
Feb 15 15:01:09 raspberrypi kernel: [ 313.437103] ffc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Feb 15 15:01:09 raspberrypi kernel: [ 313.437116] ffe0: 00000000 00000000 00000000 00000000 00000013 00000000
Feb 15 15:01:09 raspberrypi kernel: [ 313.437131] r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80143620
Feb 15 15:01:09 raspberrypi kernel: [ 313.437139] r4:81692480
Feb 15 15:01:09 raspberrypi kernel: [ 313.437150] ---[ end trace 3123588614d40e23 ]---
Feb 15 15:01:10 raspberrypi kernel: [ 313.739142] usb 1-1.1.2: new high-speed USB device number 6 using dwc_otg
Feb 15 15:01:10 raspberrypi kernel: [ 313.870133] usb 1-1.1.2: New USB device found, idVendor=05c6, idProduct=9903, bcdDevice= 0.01
Feb 15 15:01:10 raspberrypi kernel: [ 313.870158] usb 1-1.1.2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Feb 15 15:01:10 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status...
Feb 15 15:01:10 raspberrypi mtp-probe: checking bus 1, device 6: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1/1-1.1.2"
Feb 15 15:01:10 raspberrypi mtp-probe: bus: 1, device: 6 was not an MTP device
Feb 15 15:01:10 raspberrypi bluetoothd[739]: profiles/sap/server.c:sap_server_register() Sap driver initialization failed.
Feb 15 15:01:10 raspberrypi bluetoothd[739]: sap-server: Operation not permitted (1)
Feb 15 15:01:10 raspberrypi bluetoothd[739]: Endpoint registered: sender=:1.23 path=/MediaEndpoint/A2DPSink/sbc
Feb 15 15:01:10 raspberrypi bluetoothd[739]: Endpoint registered: sender=:1.23 path=/MediaEndpoint/A2DPSource/sbc
Feb 15 15:01:10 raspberrypi bluetoothd[739]: Endpoint unregistered: sender=:1.23 path=/MediaEndpoint/A2DPSink/sbc
Feb 15 15:01:10 raspberrypi bluetoothd[739]: Endpoint unregistered: sender=:1.23 path=/MediaEndpoint/A2DPSource/sbc
Feb 15 15:01:10 raspberrypi kernel: [ 314.082694] Bluetooth: hci1: urb e971643a failed to resubmit (2)
Feb 15 15:01:10 raspberrypi kernel: [ 314.082741] Bluetooth: hci1: urb 130e8340 failed to resubmit (2)
Feb 15 15:01:10 raspberrypi kernel: [ 314.082765] Bluetooth: hci1: urb e11796f2 failed to resubmit (2)
Feb 15 15:01:10 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status.

Additional context

No response

[pelwell]

Feb 15 15:00:50 raspberrypi kernel: [ 294.318866] Under-voltage detected! (0x00050005)

Any system where under-voltage is being detected is liable to suffer a variety of problems, particularly with external USB devices. Rethink your power strategy (e.g. using a powered hub), and try again.

[JulianGu001]

We saw this crash many times, not every time with the "Under-voltage detected! (0x00050005)".

[pelwell]

The onboard under-voltage is crude - it measures the voltage at one location and looks for a large shortfall. There is plenty of room for problems at other points on the board that aren't detected, and that's why we don't investigate problems on systems where they have been seen to occur - it just wastes time.

[P33M]

It should be noted that the average trip point of the undervoltage detection IC is not guaranteed to be above the minimum requirement for USB VBus. Therefore power deficiencies that do not cause events to be logged may still result in inadequate VBus - hence the stardard recommendation to use a powered USB hub to rule out power issues causing device disconnects.