raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.01k stars 4.95k forks source link

[USB VL805 RPI4] Unexpected crash for all USB devices with no way to detect new USB devices #5926

Open qrp73 opened 7 months ago

qrp73 commented 7 months ago

Describe the bug

It happens during web surfing in chromium-browser. Mouse and keyboard just stopped but browser still shows animation on the page. I was able to connect with SSH. Tried to force kill chromium-browser, then I tried to disconnect all USB devices and reconnect it again. Nothing helps. Mouse and keyboard still not worked. After reboot all works ok.

Steps to reproduce the behaviour

it unexpectedly happens during web browsing in chromium-browser. In background there was two apps: VLC player hidden in tray and playing web radio and sdrpp (opengl app) in minimized state.

it happens on Raspberry Pi 4B with VIA USB chip (2109:3431 VIA Labs, Inc. Hub).

Device (s)

Raspberry Pi 4 Mod. B

System

$ cat /etc/rpi-issue Raspberry Pi reference 2023-09-22 Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 40f37458ae7cadea1aec913ae10b5e7008ebce0a, stage4

$ vcgencmd version Oct 17 2023 15:39:16 Copyright (c) 2012 Broadcom version 30f0c5e4d076da3ab4f341d88e7d505760b93ad7 (clean) (release) (start)

$ uname -a Linux raspi 6.1.0-rpi8-rpi-v8 #1 SMP PREEMPT Debian 1:6.1.73-1+rpt1 (2024-01-25) aarch64 GNU/Linux

$ lsusb Bus 002 Device 002: ID 0951:1666 Kingston Technology DataTraveler 100 G3/G4/SE9 G2/50 Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub Bus 001 Device 007: ID 3302:3352 Synaptics CX31993 384Khz HIFI AUDIO Bus 001 Device 006: ID 1c4f:0026 SiGma Micro Keyboard Bus 001 Device 005: ID 046d:c051 Logitech, Inc. G3 (MX518) Optical Mouse Bus 001 Device 004: ID 0bda:2838 Realtek Semiconductor Corp. RTL2838 DVB-T Bus 001 Device 003: ID 214b:7250 Huasheng Electronics USB2.0 HUB Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

Logs

log when it happened:

Feb 05 20:05:47 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1835008 bytes), total 32768 (slots), used 62 (slots)
Feb 05 20:05:48 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1835008 bytes), total 32768 (slots), used 62 (slots)
Feb 05 20:09:39 raspi kernel: usb 1-1.4: USB disconnect, device number 3
Feb 05 20:09:39 raspi kernel: usb 1-1.4.1: USB disconnect, device number 13
Feb 05 20:09:39 raspi kernel: usb 1-1.4.4: Unable to submit urb #1: -19 at snd_usb_queue_pending_output_urbs
Feb 05 20:09:39 raspi kernel: usb 1-1.4.2: USB disconnect, device number 5
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: get_status error
Feb 05 20:09:39 raspi thd[678]: Error reading device '/dev/input/event2'
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi kernel: usb 1-1.4.3: USB disconnect, device number 6
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi thd[678]: Error reading device '/dev/input/event3'
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi thd[678]: Error reading device '/dev/input/event4'
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:39 raspi thd[678]: Error reading device '/dev/input/event5'
Feb 05 20:09:40 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:40 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:40 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 05 20:09:40 raspi kernel: usb 1-1.4.4: USB disconnect, device number 7
Feb 05 20:09:40 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_status error: No such device
Feb 05 20:09:40 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_recover error: No such device
Feb 05 20:09:40 raspi pipewire[177104]: spa.alsa: get_status error
Feb 05 20:09:40 raspi pipewire[177104]: spa.alsa: front:2: snd_pcm_drop No such device
Feb 05 20:09:40 raspi pipewire[177104]: spa.alsa: front:2: close failed: No such device
Feb 05 20:09:40 raspi thd[678]: Error reading device '/dev/input/event6'
Feb 05 20:09:40 raspi kernel: usb 1-1.4: new high-speed USB device number 14 using xhci_hcd
Feb 05 20:09:40 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 05 20:09:40 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 05 20:09:40 raspi kernel: usb 1-1.4: new high-speed USB device number 15 using xhci_hcd
Feb 05 20:09:40 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 05 20:09:41 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 05 20:09:41 raspi kernel: usb 1-1-port4: attempt power cycle
Feb 05 20:09:41 raspi kernel: usb 1-1.4: new high-speed USB device number 16 using xhci_hcd
Feb 05 20:09:41 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 05 20:09:42 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 05 20:09:42 raspi kernel: usb 1-1.4: device not accepting address 16, error -71
Feb 05 20:09:42 raspi kernel: usb 1-1.4: new high-speed USB device number 17 using xhci_hcd
Feb 05 20:09:42 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 05 20:09:42 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 05 20:09:42 raspi kernel: usb 1-1.4: device not accepting address 17, error -71
Feb 05 20:09:42 raspi kernel: usb 1-1-port4: unable to enumerate USB device

After reconnecting USB devices:

Feb 05 20:12:18 raspi systemd[1]: pcscd.service: Deactivated successfully.
Feb 05 20:15:44 raspi kernel: usb 1-1.4: new high-speed USB device number 18 using xhci_hcd
Feb 05 20:15:44 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 05 20:15:44 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 05 20:15:44 raspi kernel: usb 1-1.4: new high-speed USB device number 19 using xhci_hcd
Feb 05 20:15:44 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 05 20:15:45 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 05 20:15:45 raspi kernel: usb 1-1-port4: attempt power cycle
Feb 05 20:15:45 raspi kernel: usb 1-1.4: new high-speed USB device number 20 using xhci_hcd
Feb 05 20:15:45 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 05 20:15:46 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 05 20:15:46 raspi kernel: usb 1-1.4: device not accepting address 20, error -71
Feb 05 20:15:46 raspi kernel: usb 1-1.4: new high-speed USB device number 21 using xhci_hcd
Feb 05 20:15:46 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 05 20:15:46 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 05 20:15:46 raspi kernel: usb 1-1.4: device not accepting address 21, error -71
Feb 05 20:15:46 raspi kernel: usb 1-1-port4: unable to enumerate USB device

Additional context

probably it may be related to https://github.com/raspberrypi/bookworm-feedback/issues/83

pelwell commented 7 months ago

How much RAM does this 4B have?

qrp73 commented 7 months ago

4GB RAM, but I don't think it was related to memory, because it was happened with 2 tabs on chromium-browser and about 2GB free

qrp73 commented 7 months ago

just catch the same issue:

Feb 08 18:34:14 raspi systemd[1]: Finished apt-daily.service - Daily apt download activities.
Feb 08 18:34:14 raspi systemd[1]: apt-daily.service: Consumed 1.486s CPU time.
Feb 08 19:05:53 raspi kernel: usb 1-1.4: USB disconnect, device number 3
Feb 08 19:05:53 raspi kernel: usb 1-1.4.1: USB disconnect, device number 17
Feb 08 19:05:53 raspi kernel: usb 1-1.4.2: USB disconnect, device number 5
Feb 08 19:05:53 raspi kernel: usb 1-1.4.4: Unable to submit urb #0: -19 at snd_usb_queue_pending_output_urbs
Feb 08 19:05:53 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi kernel: usb 1-1.4.3: USB disconnect, device number 6
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: get_status error
Feb 08 19:05:53 raspi thd[707]: Error reading device '/dev/input/event2'
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi thd[707]: Error reading device '/dev/input/event3'
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi thd[707]: Error reading device '/dev/input/event4'
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi thd[707]: Error reading device '/dev/input/event5'
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_start: Broken pipe
Feb 08 19:05:53 raspi kernel: usb 1-1.4.4: USB disconnect, device number 7
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_status error: No such device
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_recover error: No such device
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: get_status error
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_status error: No such device
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_recover error: No such device
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: get_status error
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: snd_pcm_drop No such device
Feb 08 19:05:53 raspi pipewire[1526]: spa.alsa: front:2: close failed: No such device
Feb 08 19:05:53 raspi thd[707]: Error reading device '/dev/input/event6'
Feb 08 19:05:53 raspi kernel: usb 1-1.4: new high-speed USB device number 18 using xhci_hcd
Feb 08 19:05:53 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 08 19:05:54 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 08 19:05:54 raspi kernel: usb 1-1.4: new high-speed USB device number 19 using xhci_hcd
Feb 08 19:05:54 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 08 19:05:54 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 08 19:05:54 raspi kernel: usb 1-1-port4: attempt power cycle
Feb 08 19:05:55 raspi kernel: usb 1-1.4: new high-speed USB device number 20 using xhci_hcd
Feb 08 19:05:55 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 08 19:05:55 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 08 19:05:55 raspi kernel: usb 1-1.4: device not accepting address 20, error -71
Feb 08 19:05:55 raspi kernel: usb 1-1.4: new high-speed USB device number 21 using xhci_hcd
Feb 08 19:05:55 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 08 19:05:56 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 08 19:05:56 raspi kernel: usb 1-1.4: device not accepting address 21, error -71
Feb 08 19:05:56 raspi kernel: usb 1-1-port4: unable to enumerate USB device
Feb 08 19:06:29 raspi sshd[224087]: Accepted password for *** from 192.168.1.*** port 54519 ssh2

it happens when I opened chromium-browser with one tab and lightweight page (bulleten forum). At the moment of issue 3 processes was active: 1) VLC in tray-minimized state playing web radio 2) sdrpp (opengl app) 3) chromium-browser with one tab and lightweight page

The issue happens when I started chromium-browser, just after open window.

It seems that this issue was added with one of the latest apt update last week, before that I never had such issues.

Looks like some bug in the driver for RPI4 onboard USB controller (VIA).

qrp73 commented 6 months ago

Catch it again with the same symptoms. It happens when rpi stayed in idle state, running sdrpp in minimized state (it receives 20 Mbps continuous stream from RTLSDR dongle) and firefox with empty tabs.

This time I switched to rpi-update next before it happened, to check if more fresh kernel can fix this issue, but it still exists.

$ uname -a
Linux raspi 6.6.16-v8+ #1728 SMP PREEMPT Tue Feb  6 17:21:42 GMT 2024 aarch64 GNU/Linux

connected usb devices

$ lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 012: ID 3302:3352 Synaptics CX31993 384Khz HIFI AUDIO
Bus 001 Device 011: ID 1c4f:0026 SiGma Micro Keyboard
Bus 001 Device 010: ID 046d:c051 Logitech, Inc. G3 (MX518) Optical Mouse
Bus 001 Device 009: ID 0bda:2838 Realtek Semiconductor Corp. RTL2838 DVB-T
Bus 001 Device 008: ID 214b:7250 Huasheng Electronics USB2.0 HUB
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

logs:

Feb 11 21:17:01 raspi CRON[384082]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 11 21:17:01 raspi CRON[384083]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 11 21:17:01 raspi CRON[384082]: pam_unix(cron:session): session closed for user root
Feb 11 21:17:04 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:08 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:11 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:14 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:17 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:20 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:23 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:26 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:30 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:33 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:36 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:39 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:42 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:45 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:49 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:52 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:55 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:17:58 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:01 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:04 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:07 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:11 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:14 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:17 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:20 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:23 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:26 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:29 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:33 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:36 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:39 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:42 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:45 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:48 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:51 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:55 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:18:58 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:01 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:04 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:07 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:10 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:13 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:17 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:20 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:25 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:29 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:34 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:37 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:40 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:43 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:46 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:50 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:53 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:56 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:19:59 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:02 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:06 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:09 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:15 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:20 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:24 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:27 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:30 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:34 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:37 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:40 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:44 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:49 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:20:58 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:01 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:05 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:10 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:17 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:21 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:26 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:39 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:42 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:45 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:48 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:51 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:21:55 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:00 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:04 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:09 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:14 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:19 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:24 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:28 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:33 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:37 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:41 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:44 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:47 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:50 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:53 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:22:56 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:23:06 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:23:09 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:23:25 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:24:54 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:26:23 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:27:52 raspi kernel: vc4-drm gpu: [drm] *ERROR* Failed to allocate DLIST entry. Requested size=17. ret=-28. DISPCTRL is aa0c020e
Feb 11 21:29:56 raspi kernel: usb 1-1.4: USB disconnect, device number 34
Feb 11 21:29:56 raspi kernel: usb 1-1.4.1: USB disconnect, device number 35
Feb 11 21:29:56 raspi kernel: usb 1-1.4.4: Unable to submit urb #1: -19 at snd_usb_queue_pending_output_urbs
Feb 11 21:29:56 raspi kernel: usb 1-1.4.2: USB disconnect, device number 36
Feb 11 21:29:56 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 11 21:29:56 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 11 21:29:56 raspi pulseaudio[3925]: Could not recover from POLLERR|POLLNVAL|POLLHUP and XRUN: Broken pipe
Feb 11 21:29:56 raspi rtkit-daemon[1046]: Supervising 6 threads of 3 processes of 1 users.
Feb 11 21:29:56 raspi rtkit-daemon[1046]: Successfully made thread 385182 of process 3925 owned by '1000' RT at priority 5.
Feb 11 21:29:56 raspi rtkit-daemon[1046]: Supervising 7 threads of 3 processes of 1 users.
Feb 11 21:29:56 raspi kernel: usb 1-1.4.4: 1:0: usb_set_interface failed (-19)
Feb 11 21:29:56 raspi kernel: usb 1-1.4.3: USB disconnect, device number 37
Feb 11 21:29:57 raspi kernel: usb 1-1.4.4: USB disconnect, device number 38
Feb 11 21:29:57 raspi kernel: usb 1-1.4: new high-speed USB device number 39 using xhci_hcd
Feb 11 21:29:57 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 11 21:29:57 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 11 21:29:57 raspi kernel: usb 1-1.4: new high-speed USB device number 40 using xhci_hcd
Feb 11 21:29:57 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 11 21:29:58 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 11 21:29:58 raspi kernel: usb 1-1-port4: attempt power cycle
Feb 11 21:29:58 raspi kernel: usb 1-1.4: new high-speed USB device number 41 using xhci_hcd
Feb 11 21:29:58 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 11 21:29:59 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 11 21:29:59 raspi kernel: usb 1-1.4: device not accepting address 41, error -71
Feb 11 21:29:59 raspi kernel: usb 1-1.4: new high-speed USB device number 42 using xhci_hcd
Feb 11 21:29:59 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 11 21:29:59 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 11 21:29:59 raspi kernel: usb 1-1.4: device not accepting address 42, error -71
Feb 11 21:29:59 raspi kernel: usb 1-1-port4: unable to enumerate USB device
Feb 11 22:17:01 raspi CRON[389118]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 11 22:17:01 raspi CRON[389119]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 11 22:17:01 raspi CRON[389118]: pam_unix(cron:session): session closed for user root
Feb 11 23:17:01 raspi CRON[394033]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 11 23:17:01 raspi CRON[394034]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 11 23:17:01 raspi CRON[394033]: pam_unix(cron:session): session closed for user root
Feb 12 00:00:18 raspi systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service...
Feb 12 00:00:18 raspi systemd[1]: Starting logrotate.service - Rotate log files...
Feb 12 00:00:18 raspi systemd[1]: Stopping cups-browsed.service - Make remote CUPS printers available locally...
Feb 12 00:00:18 raspi systemd[1]: cups-browsed.service: Deactivated successfully.
Feb 12 00:00:18 raspi systemd[1]: Stopped cups-browsed.service - Make remote CUPS printers available locally.
Feb 12 00:00:18 raspi systemd[1]: Stopping cups.service - CUPS Scheduler...
Feb 12 00:00:18 raspi systemd[1]: cups.service: Deactivated successfully.
Feb 12 00:00:18 raspi systemd[1]: Stopped cups.service - CUPS Scheduler.
Feb 12 00:00:18 raspi systemd[1]: cups.path: Deactivated successfully.
Feb 12 00:00:18 raspi systemd[1]: Stopped cups.path - CUPS Scheduler.
Feb 12 00:00:18 raspi systemd[1]: Stopping cups.path - CUPS Scheduler...
Feb 12 00:00:18 raspi systemd[1]: Started cups.path - CUPS Scheduler.
Feb 12 00:00:18 raspi systemd[1]: cups.socket: Deactivated successfully.
Feb 12 00:00:18 raspi systemd[1]: Closed cups.socket - CUPS Scheduler.
Feb 12 00:00:18 raspi systemd[1]: Stopping cups.socket - CUPS Scheduler...
Feb 12 00:00:18 raspi systemd[1]: Listening on cups.socket - CUPS Scheduler.
Feb 12 00:00:18 raspi systemd[1]: Starting cups.service - CUPS Scheduler...
Feb 12 00:00:18 raspi systemd[1]: Started cups.service - CUPS Scheduler.
Feb 12 00:00:18 raspi systemd[1]: Started cups-browsed.service - Make remote CUPS printers available locally.
Feb 12 00:00:18 raspi systemd[1]: logrotate.service: Deactivated successfully.
Feb 12 00:00:18 raspi systemd[1]: Finished logrotate.service - Rotate log files.
Feb 12 00:00:18 raspi systemd[1]: dpkg-db-backup.service: Deactivated successfully.
Feb 12 00:00:18 raspi systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service.
Feb 12 00:17:01 raspi CRON[399001]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 12 00:17:01 raspi CRON[399002]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 12 00:17:02 raspi CRON[399001]: pam_unix(cron:session): session closed for user root
Feb 12 01:17:01 raspi CRON[403876]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 12 01:17:01 raspi CRON[403877]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 12 01:17:01 raspi CRON[403876]: pam_unix(cron:session): session closed for user root
-- Boot 
6by9 commented 6 months ago

Failed to allocate DLIST entry is #5674 (fix merged to rpi-6.6.y on Friday).

It's just possible that the DRM issue is triggering issues in the USB subsystem, but you haven't mentioned it being in previous logs.

qrp73 commented 6 months ago

The log is full of these errors about allocate DLIST entry, it happens a bunch of time everyday. I'm not sure if it related with this USB driver issue, but since it happens a lot of time just before USB issue, I included it in the log.

There are also thousands of records with DLIST error before quoted log records, for example there are a bunch of these errors about one-two hours before I leave the computer, but all worked ok.

I will try to update to latest rpi-6.6.y and check if it happens again.

qrp73 commented 6 months ago

it happens again, now on latest rpi-6.6.y:

$ cat /etc/rpi-issue
Raspberry Pi reference 2023-09-22
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 40f37458ae7cadea1aec913ae10b5e7008ebce0a, stage4

$ vcgencmd version
Dec  8 2023 12:36:15 
Copyright (c) 2012 Broadcom
version e02d33b3122450accf9dea471a177d3b5623f5ad (clean) (release) (start)

$ uname -a
Linux raspi 6.6.16-v8+ #1 SMP PREEMPT Mon Feb 12 18:08:41 UTC 2024 aarch64 GNU/Linux

logs:

Feb 15 16:17:01 raspi CRON[170754]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 15 16:17:01 raspi CRON[170755]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 15 16:17:01 raspi CRON[170754]: pam_unix(cron:session): session closed for user root
Feb 15 17:17:01 raspi CRON[175743]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 15 17:17:01 raspi CRON[175744]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 15 17:17:01 raspi CRON[175743]: pam_unix(cron:session): session closed for user root
Feb 15 18:17:01 raspi CRON[180792]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 15 18:17:01 raspi CRON[180793]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 15 18:17:01 raspi CRON[180792]: pam_unix(cron:session): session closed for user root
Feb 15 19:17:01 raspi CRON[185823]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 15 19:17:01 raspi CRON[185824]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 15 19:17:01 raspi CRON[185823]: pam_unix(cron:session): session closed for user root
Feb 15 19:48:35 raspi kernel: usb 1-1.4: USB disconnect, device number 3
Feb 15 19:48:35 raspi kernel: usb 1-1.4.1: USB disconnect, device number 10
Feb 15 19:48:35 raspi kernel: usb 1-1.4.4: Unable to submit urb #2: -19 at snd_usb_queue_pending_output_urbs
Feb 15 19:48:35 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 15 19:48:35 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 15 19:48:35 raspi kernel: usb 1-1.4.2: USB disconnect, device number 5
Feb 15 19:48:35 raspi pulseaudio[1032]: Could not recover from POLLERR|POLLNVAL|POLLHUP and XRUN: Broken pipe
Feb 15 19:48:35 raspi thd[688]: Error reading device '/dev/input/event0'
Feb 15 19:48:35 raspi rtkit-daemon[1047]: Supervising 4 threads of 2 processes of 1 users.
Feb 15 19:48:35 raspi kernel: usb 1-1.4.3: USB disconnect, device number 6
Feb 15 19:48:35 raspi rtkit-daemon[1047]: Successfully made thread 188393 of process 1032 owned by '1000' RT at priority 5.
Feb 15 19:48:35 raspi rtkit-daemon[1047]: Supervising 5 threads of 2 processes of 1 users.
Feb 15 19:48:35 raspi kernel: usb 1-1.4.4: 1:0: usb_set_interface failed (-19)
Feb 15 19:48:35 raspi thd[688]: Error reading device '/dev/input/event1'
Feb 15 19:48:35 raspi thd[688]: Error reading device '/dev/input/event2'
Feb 15 19:48:35 raspi thd[688]: Error reading device '/dev/input/event3'
Feb 15 19:48:35 raspi kernel: usb 1-1.4.4: USB disconnect, device number 7
Feb 15 19:48:35 raspi thd[688]: Error reading device '/dev/input/event4'
Feb 15 19:48:35 raspi kernel: usb 1-1.4: new high-speed USB device number 11 using xhci_hcd
Feb 15 19:48:35 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 15 19:48:36 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 15 19:48:36 raspi kernel: usb 1-1.4: new high-speed USB device number 12 using xhci_hcd
Feb 15 19:48:36 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 15 19:48:36 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 15 19:48:36 raspi kernel: usb 1-1-port4: attempt power cycle
Feb 15 19:48:37 raspi kernel: usb 1-1.4: new high-speed USB device number 13 using xhci_hcd
Feb 15 19:48:37 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 15 19:48:37 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 15 19:48:37 raspi kernel: usb 1-1.4: device not accepting address 13, error -71
Feb 15 19:48:37 raspi kernel: usb 1-1.4: new high-speed USB device number 14 using xhci_hcd
Feb 15 19:48:37 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 15 19:48:37 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 15 19:48:38 raspi kernel: usb 1-1.4: device not accepting address 14, error -71
Feb 15 19:48:38 raspi kernel: usb 1-1-port4: unable to enumerate USB device
qrp73 commented 6 months ago

just happens again:

Feb 16 16:15:14 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 524288 bytes), total 32768 (slots), used 1640 (slots)
Feb 16 16:15:14 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 466944 bytes), total 32768 (slots), used 2 (slots)
Feb 16 16:15:14 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 524288 bytes), total 32768 (slots), used 84 (slots)
Feb 16 16:15:14 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 524288 bytes), total 32768 (slots), used 1640 (slots)
Feb 16 16:15:15 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 466944 bytes), total 32768 (slots), used 2 (slots)
Feb 16 16:15:15 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 524288 bytes), total 32768 (slots), used 84 (slots)
Feb 16 16:15:55 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 524288 bytes), total 32768 (slots), used 806 (slots)
Feb 16 16:15:56 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 524288 bytes), total 32768 (slots), used 806 (slots)
Feb 16 16:17:01 raspi CRON[84653]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 16 16:17:01 raspi CRON[84654]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 16 16:17:01 raspi CRON[84653]: pam_unix(cron:session): session closed for user root
Feb 16 17:07:47 raspi pulseaudio[1055]: Failed to find a working profile.
Feb 16 17:07:47 raspi pulseaudio[1055]: Failed to load module "module-alsa-card" (argument: "device_id="1" name="platform-fef00700.hdmi" card_name="alsa_card>
Feb 16 17:07:48 raspi pulseaudio[1055]: Failed to find a working profile.
Feb 16 17:07:48 raspi pulseaudio[1055]: Failed to load module "module-alsa-card" (argument: "device_id="2" name="platform-fef05700.hdmi" card_name="alsa_card>
Feb 16 17:08:01 raspi pulseaudio[1055]: Failed to find a working profile.
Feb 16 17:08:01 raspi pulseaudio[1055]: Failed to load module "module-alsa-card" (argument: "device_id="1" name="platform-fef00700.hdmi" card_name="alsa_card>
Feb 16 17:08:01 raspi pulseaudio[1055]: Failed to find a working profile.
Feb 16 17:08:01 raspi pulseaudio[1055]: Failed to load module "module-alsa-card" (argument: "device_id="2" name="platform-fef05700.hdmi" card_name="alsa_card>
Feb 16 17:14:48 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 2887680 bytes), total 32768 (slots), used 512 (slots)
Feb 16 17:14:48 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1306624 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:14:49 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 2887680 bytes), total 32768 (slots), used 512 (slots)
Feb 16 17:14:49 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1306624 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:17:01 raspi CRON[90021]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Feb 16 17:17:01 raspi CRON[90022]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Feb 16 17:17:01 raspi CRON[90021]: pam_unix(cron:session): session closed for user root
Feb 16 17:19:52 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 413696 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:19:52 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1708032 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:19:52 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 2768896 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:19:52 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 413696 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:19:53 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1708032 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:19:53 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 978944 bytes), total 32768 (slots), used 26 (slots)
Feb 16 17:19:53 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 294912 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:19:53 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 282624 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:19:53 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 978944 bytes), total 32768 (slots), used 26 (slots)
Feb 16 17:19:53 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 294912 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:20:07 raspi kernel: swiotlb_tbl_map_single: 1 callbacks suppressed
Feb 16 17:20:07 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 495616 bytes), total 32768 (slots), used 96 (slots)
Feb 16 17:20:07 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 413696 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:20:07 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1048576 bytes), total 32768 (slots), used 70 (slots)
Feb 16 17:20:07 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 495616 bytes), total 32768 (slots), used 96 (slots)
Feb 16 17:20:07 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 413696 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:20:07 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1048576 bytes), total 32768 (slots), used 70 (slots)
Feb 16 17:31:04 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 446464 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:31:04 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1048576 bytes), total 32768 (slots), used 176 (slots)
Feb 16 17:31:05 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 524288 bytes), total 32768 (slots), used 134 (slots)
Feb 16 17:31:05 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 446464 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:31:05 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1048576 bytes), total 32768 (slots), used 176 (slots)
Feb 16 17:31:05 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 524288 bytes), total 32768 (slots), used 134 (slots)
Feb 16 17:31:06 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 413696 bytes), total 32768 (slots), used 446 (slots)
Feb 16 17:31:06 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1159168 bytes), total 32768 (slots), used 2 (slots)
Feb 16 17:31:06 raspi kernel: vc4-drm gpu: swiotlb buffer is full (sz: 413696 bytes), total 32768 (slots), used 446 (slots)
Feb 16 17:32:49 raspi kernel: usb 1-1.4: USB disconnect, device number 21
Feb 16 17:32:49 raspi kernel: usb 1-1.4.1: USB disconnect, device number 28
Feb 16 17:32:49 raspi kernel: usb 1-1.4.2: USB disconnect, device number 23
Feb 16 17:32:49 raspi kernel: usb 1-1.4.4: Unable to submit urb #1: -19 at snd_usb_queue_pending_output_urbs
Feb 16 17:32:49 raspi pulseaudio[1055]: Could not recover from POLLERR|POLLNVAL|POLLHUP and XRUN: Broken pipe
Feb 16 17:32:49 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 16 17:32:49 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 16 17:32:49 raspi rtkit-daemon[1071]: Supervising 4 threads of 2 processes of 1 users.
Feb 16 17:32:49 raspi kernel: usb 1-1.4.3: USB disconnect, device number 26
Feb 16 17:32:50 raspi rtkit-daemon[1071]: Successfully made thread 91746 of process 1055 owned by '1000' RT at priority 5.
Feb 16 17:32:50 raspi rtkit-daemon[1071]: Supervising 5 threads of 2 processes of 1 users.
Feb 16 17:32:50 raspi kernel: usb 1-1.4.4: 1:0: usb_set_interface failed (-19)
Feb 16 17:32:50 raspi kernel: usb 1-1.4.4: USB disconnect, device number 25
Feb 16 17:32:50 raspi kernel: usb 1-1.4: new high-speed USB device number 29 using xhci_hcd
Feb 16 17:32:50 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 16 17:32:50 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 16 17:32:51 raspi kernel: usb 1-1.4: new high-speed USB device number 30 using xhci_hcd
Feb 16 17:32:51 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 16 17:32:51 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 16 17:32:51 raspi kernel: usb 1-1-port4: attempt power cycle
Feb 16 17:32:52 raspi kernel: usb 1-1.4: new high-speed USB device number 31 using xhci_hcd
Feb 16 17:32:52 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 16 17:32:52 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 16 17:32:52 raspi kernel: usb 1-1.4: device not accepting address 31, error -71
Feb 16 17:32:52 raspi kernel: usb 1-1.4: new high-speed USB device number 32 using xhci_hcd
Feb 16 17:32:52 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 16 17:32:52 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 16 17:32:52 raspi kernel: usb 1-1.4: device not accepting address 32, error -71
Feb 16 17:32:52 raspi kernel: usb 1-1-port4: unable to enumerate USB device

Note, these issues start to happens with last apt upgrade last week. Previously it never failed under the same conditions.

qrp73 commented 6 months ago

it happens again:

Feb 20 08:22:54 raspi rtkit-daemon[1075]: Supervising 5 threads of 3 processes of 1 users.
Feb 20 08:22:54 raspi rtkit-daemon[1075]: Supervising 5 threads of 3 processes of 1 users.
Feb 20 08:23:59 raspi rtkit-daemon[1075]: Supervising 5 threads of 3 processes of 1 users.
Feb 20 08:23:59 raspi rtkit-daemon[1075]: Supervising 5 threads of 3 processes of 1 users.
Feb 20 08:24:17 raspi kernel: usb 1-1.4: USB disconnect, device number 3
Feb 20 08:24:17 raspi kernel: usb 1-1.4.1: USB disconnect, device number 10
Feb 20 08:24:17 raspi kernel: usb 1-1.4.2: USB disconnect, device number 11
Feb 20 08:24:17 raspi kernel: usb 1-1.4.4: Unable to submit urb #0: -19 at snd_usb_queue_pending_output_urbs
Feb 20 08:24:17 raspi pulseaudio[1060]: Could not recover from POLLERR|POLLNVAL|POLLHUP and XRUN: Broken pipe
Feb 20 08:24:17 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 20 08:24:17 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 20 08:24:17 raspi rtkit-daemon[1075]: Supervising 5 threads of 3 processes of 1 users.
Feb 20 08:24:17 raspi kernel: usb 1-1.4.3: USB disconnect, device number 6
Feb 20 08:24:17 raspi rtkit-daemon[1075]: Successfully made thread 419716 of process 1060 owned by '1000' RT at priority 5.
Feb 20 08:24:17 raspi rtkit-daemon[1075]: Supervising 6 threads of 3 processes of 1 users.
Feb 20 08:24:17 raspi kernel: usb 1-1.4.4: 1:0: usb_set_interface failed (-19)
Feb 20 08:24:17 raspi thd[744]: Error reading device '/dev/input/event1'
Feb 20 08:24:17 raspi thd[744]: Error reading device '/dev/input/event2'
Feb 20 08:24:17 raspi thd[744]: Error reading device '/dev/input/event3'
Feb 20 08:24:17 raspi kernel: usb 1-1.4.4: USB disconnect, device number 7
Feb 20 08:24:17 raspi thd[744]: Error reading device '/dev/input/event4'
Feb 20 08:24:17 raspi kernel: usb 1-1.4: new high-speed USB device number 12 using xhci_hcd
Feb 20 08:24:17 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 20 08:24:18 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 20 08:24:18 raspi kernel: usb 1-1.4: new high-speed USB device number 13 using xhci_hcd
Feb 20 08:24:18 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 20 08:24:18 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 20 08:24:18 raspi kernel: usb 1-1-port4: attempt power cycle
Feb 20 08:24:19 raspi kernel: usb 1-1.4: new high-speed USB device number 14 using xhci_hcd
Feb 20 08:24:19 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 20 08:24:19 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 20 08:24:19 raspi kernel: usb 1-1.4: device not accepting address 14, error -71
Feb 20 08:24:19 raspi kernel: usb 1-1.4: new high-speed USB device number 15 using xhci_hcd
Feb 20 08:24:19 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 20 08:24:19 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 20 08:24:20 raspi kernel: usb 1-1.4: device not accepting address 15, error -71
Feb 20 08:24:20 raspi kernel: usb 1-1-port4: unable to enumerate USB device
Feb 20 08:24:54 raspi kernel: usb 1-1.4: new high-speed USB device number 16 using xhci_hcd
Feb 20 08:24:54 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 20 08:24:54 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 20 08:24:54 raspi kernel: usb 1-1.4: new high-speed USB device number 17 using xhci_hcd
Feb 20 08:24:54 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 20 08:24:55 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 20 08:24:55 raspi kernel: usb 1-1-port4: attempt power cycle
Feb 20 08:24:55 raspi kernel: usb 1-1.4: new high-speed USB device number 18 using xhci_hcd
Feb 20 08:24:55 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 20 08:24:56 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 20 08:24:56 raspi kernel: usb 1-1.4: device not accepting address 18, error -71
Feb 20 08:24:56 raspi kernel: usb 1-1.4: new high-speed USB device number 19 using xhci_hcd
Feb 20 08:24:56 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 20 08:24:56 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 20 08:24:56 raspi kernel: usb 1-1.4: device not accepting address 19, error -71
Feb 20 08:24:56 raspi kernel: usb 1-1-port4: unable to enumerate USB device
qrp73 commented 6 months ago

Probably this issue: https://forums.raspberrypi.com/viewtopic.php?t=365719 is also related to this critical issue of USB ports on RPI4 with VL805.

Something is going wrong with VL805 firmware and it leads to unexpected stop for all USB ports on RPI4. And there is no way to reload it when it happens, only system reboot can help.

qrp73 commented 6 months ago

just catch this issue again (all USB ports are failed and going into non-recoverable state) it happens in firefox when I wrote bug report for issue #5980:

connected USB devices during issue (keyboard, mouse, CX31993 sound DAC, RTLSDRv3):

$ lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 007: ID 3302:3352 Synaptics CX31993 384Khz HIFI AUDIO
Bus 001 Device 006: ID 1c4f:0026 SiGma Micro Keyboard
Bus 001 Device 005: ID 046d:c051 Logitech, Inc. G3 (MX518) Optical Mouse
Bus 001 Device 004: ID 0bda:2838 Realtek Semiconductor Corp. RTL2838 DVB-T
Bus 001 Device 003: ID 214b:7250 Huasheng Electronics USB2.0 HUB
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

the log:

Feb 22 23:15:28 raspi kernel: usb 1-1.4: USB disconnect, device number 3
Feb 22 23:15:28 raspi kernel: usb 1-1.4.1: USB disconnect, device number 4
Feb 22 23:15:28 raspi kernel: usb 1-1.4.4: Unable to submit urb #0: -19 at snd_usb_queue_pending_output_urbs
Feb 22 23:15:28 raspi kernel: usb 1-1.4.2: USB disconnect, device number 5
Feb 22 23:15:28 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 22 23:15:28 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 22 23:15:28 raspi pulseaudio[1049]: Could not recover from POLLERR|POLLNVAL|POLLHUP and XRUN: Broken pipe
Feb 22 23:15:28 raspi rtkit-daemon[1065]: Supervising 5 threads of 3 processes of 1 users.
Feb 22 23:15:28 raspi thd[705]: Error reading device '/dev/input/event0'
Feb 22 23:15:28 raspi rtkit-daemon[1065]: Successfully made thread 17014 of process 1049 owned by '1000' RT at priority 5.
Feb 22 23:15:28 raspi rtkit-daemon[1065]: Supervising 6 threads of 3 processes of 1 users.
Feb 22 23:15:28 raspi kernel: usb 1-1.4.4: 1:0: usb_set_interface failed (-19)
Feb 22 23:15:28 raspi kernel: usb 1-1.4.3: USB disconnect, device number 6
Feb 22 23:15:28 raspi thd[705]: Error reading device '/dev/input/event1'
Feb 22 23:15:28 raspi thd[705]: Error reading device '/dev/input/event2'
Feb 22 23:15:28 raspi thd[705]: Error reading device '/dev/input/event3'
Feb 22 23:15:28 raspi kernel: usb 1-1.4.4: USB disconnect, device number 7
Feb 22 23:15:28 raspi thd[705]: Error reading device '/dev/input/event4'
Feb 22 23:15:28 raspi kernel: usb 1-1.4: new high-speed USB device number 8 using xhci_hcd
Feb 22 23:15:28 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 22 23:15:29 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 22 23:15:29 raspi kernel: usb 1-1.4: new high-speed USB device number 9 using xhci_hcd
Feb 22 23:15:29 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 22 23:15:29 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 22 23:15:29 raspi kernel: usb 1-1-port4: attempt power cycle
Feb 22 23:15:30 raspi kernel: usb 1-1.4: new high-speed USB device number 10 using xhci_hcd
Feb 22 23:15:30 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 22 23:15:30 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 22 23:15:30 raspi kernel: usb 1-1.4: device not accepting address 10, error -71
Feb 22 23:15:30 raspi kernel: usb 1-1.4: new high-speed USB device number 11 using xhci_hcd
Feb 22 23:15:30 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 22 23:15:30 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 22 23:15:31 raspi kernel: usb 1-1.4: device not accepting address 11, error -71
Feb 22 23:15:31 raspi kernel: usb 1-1-port4: unable to enumerate USB device
qrp73 commented 6 months ago

it happens again, now with some new records:

Feb 29 20:38:18 raspi kernel: bcm2835-codec bcm2835-codec: bcm2835_codec_flush_buffers: Timeout waiting for buffers to be returned - 0 outstanding
Feb 29 20:52:27 raspi kernel: usb 1-1.4: USB disconnect, device number 3
Feb 29 20:52:27 raspi kernel: usb 1-1.4.1: USB disconnect, device number 4
Feb 29 20:52:27 raspi kernel: usb 1-1.4.2: USB disconnect, device number 5
Feb 29 20:52:27 raspi kernel: usb 1-1.4.4: Unable to submit urb #0: -19 at snd_usb_queue_pending_output_urbs
Feb 29 20:52:27 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 29 20:52:27 raspi kernel: usb 1-1.4.4: cannot submit urb 0, error -19: no device
Feb 29 20:52:27 raspi thd[707]: Error reading device '/dev/input/event0'
Feb 29 20:52:27 raspi rtkit-daemon[1065]: Supervising 5 threads of 2 processes of 1 users.
Feb 29 20:52:27 raspi kernel: usb 1-1.4.3: USB disconnect, device number 6
Feb 29 20:52:27 raspi rtkit-daemon[1065]: Successfully made thread 156400 of process 1049 owned by '1000' RT at priority 5.
Feb 29 20:52:27 raspi rtkit-daemon[1065]: Supervising 6 threads of 2 processes of 1 users.
Feb 29 20:52:27 raspi kernel: usb 1-1.4.4: 1:0: usb_set_interface failed (-19)
Feb 29 20:52:27 raspi thd[707]: Error reading device '/dev/input/event1'
Feb 29 20:52:27 raspi thd[707]: Error reading device '/dev/input/event2'
Feb 29 20:52:27 raspi thd[707]: Error reading device '/dev/input/event3'
Feb 29 20:52:27 raspi kernel: usb 1-1.4.4: USB disconnect, device number 7
Feb 29 20:52:27 raspi thd[707]: Error reading device '/dev/input/event4'
Feb 29 20:52:27 raspi kernel: usb 1-1.4: new high-speed USB device number 9 using xhci_hcd
Feb 29 20:52:28 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 29 20:52:28 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 29 20:52:28 raspi kernel: usb 1-1.4: new high-speed USB device number 10 using xhci_hcd
Feb 29 20:52:28 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 29 20:52:28 raspi kernel: usb 1-1.4: device descriptor read/64, error -71
Feb 29 20:52:28 raspi kernel: usb 1-1-port4: attempt power cycle
Feb 29 20:52:29 raspi kernel: usb 1-1.4: new high-speed USB device number 11 using xhci_hcd
Feb 29 20:52:29 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 29 20:52:29 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 29 20:52:29 raspi kernel: usb 1-1.4: device not accepting address 11, error -71
Feb 29 20:52:29 raspi kernel: usb 1-1.4: new high-speed USB device number 12 using xhci_hcd
Feb 29 20:52:29 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 29 20:52:30 raspi kernel: usb 1-1.4: Device not responding to setup address.
Feb 29 20:52:30 raspi kernel: usb 1-1.4: device not accepting address 12, error -71
Feb 29 20:52:30 raspi kernel: usb 1-1-port4: unable to enumerate USB device

I tried to disconnect all USB devices and reconnect again, but it don't help. The only way to fix it is to reboot the system from ssh or with power off button (because keyboard and mouse is not available after this issue)

qrp73 commented 6 months ago

It seems that the user has the same issue on RPI4: https://forums.raspberrypi.com/viewtopic.php?t=363593

Exactly the same symptoms, the system stops to respond on mouse and keyboard and don't see any USB device after that even if you reconnect it. You can still connect with SSH, but all USB devices don't respond until system reboot. It happens every 2-3 days.

Old bookworm versions don't had such issue and worked stable more long time with no need to reboot to restore access to USB devices.

qrp73 commented 6 months ago

just to clarify, PSU is ok (15W genuine RPI4 PSU), peak current consumption is 1.2 Amps, average power consumption 0.9-1.0 Amps. There is no undervoltage event, the power is strongly ok.

qrp73 commented 6 months ago

it happens again. I notice this issue with failure of all USB devices happens after long kernel up-time - about 1-2 days.

I tried to remove external USB hub to check if this issue can be related with it.

qrp73 commented 6 months ago

Preliminary this issue is related to USB hub driver. I tried disconnect USB hub and connect all devices directly to RPI. Now it works flawlessly for 2 days. I still monitoring it, but at a glance it looks that this issue don't appears without USB hub.

I'm using this USB hub (variant USB Gray-B with USB-A connector): https://www.aliexpress.com/item/1005005802405660.html

Any chance to fix driver for this USB hub?