search

mvp / uhubctl

uhubctl - USB hub per-port power control
Other
2.23k stars 232 forks source link

Random/Unexpected Hub Reset - Re-powers ALL ports when only one was commanded. #562

Closed mungewell closed 7 months ago

mungewell commented 7 months ago

I picked up some 'Pluggable' 7-port USB3.x Hubs (Model: USB3-HUB7BC) for some automated testing. These are mostly working well, however I have the occasional reset causing issue.

When first connected (and with a number of Picos connected) it reports as:

# uhubctl 
Current status for hub 2-1.1 [2109:8110 VIA Labs, Inc. USB3.0 Hub, USB 3.00, 4 ports, ppps]
  Port 1: 02a0 power 5gbps Rx.Detect
  Port 2: 02a0 power 5gbps Rx.Detect
  Port 3: 02a0 power 5gbps Rx.Detect
  Port 4: 02a0 power 5gbps Rx.Detect
Current status for hub 2-1 [2109:8110 VIA Labs, Inc. USB3.0 Hub, USB 3.00, 4 ports, ppps]
  Port 1: 0263 power 5gbps U3 enable connect [2109:8110 VIA Labs, Inc. USB3.0 Hub, USB 3.00, 4 ports, ppps]
  Port 2: 02a0 power 5gbps Rx.Detect
  Port 3: 02a0 power 5gbps Rx.Detect
  Port 4: 02a0 power 5gbps Rx.Detect
Current status for hub 1-1.1 [2109:2811 VIA Labs, Inc. USB2.0 Hub, USB 2.10, 4 ports, ppps]
  Port 1: 0103 power enable connect [2e8a:0005 MicroPython Board in FS mode e66034f71f583724]
  Port 2: 0103 power enable connect [2e8a:0005 MicroPython Board in FS mode e66034f71f7e9136]
  Port 3: 0103 power enable connect [2e8a:0005 MicroPython Board in FS mode e66180109f726025]
  Port 4: 0103 power enable connect [2e8a:0005 MicroPython Board in FS mode e66180109f3c5824]
Current status for hub 1-1 [2109:2811 VIA Labs, Inc. USB2.0 Hub, USB 2.10, 4 ports, ppps]
  Port 1: 0503 power highspeed enable connect [2109:2811 VIA Labs, Inc. USB2.0 Hub, USB 2.10, 4 ports, ppps]
  Port 2: 0103 power enable connect [2e8a:0005 MicroPython Board in FS mode e66180109f79a525]
  Port 3: 0100 power
  Port 4: 0100 power

# lsusb
Bus 002 Device 015: ID 2109:8110 VIA Labs, Inc. Hub
Bus 002 Device 014: ID 2109:8110 VIA Labs, Inc. Hub
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 005: ID 0cf3:e301 Qualcomm Atheros Communications 
Bus 001 Device 004: ID 187c:0527 Alienware Corporation AW13
Bus 001 Device 003: ID 0c45:6708 Microdia Integrated_Webcam_FHD
Bus 001 Device 002: ID 046d:c52b Logitech, Inc. Unifying Receiver
Bus 001 Device 116: ID 2e8a:0005 MicroPython Board in FS mode
Bus 001 Device 120: ID 2e8a:0005 MicroPython Board in FS mode
Bus 001 Device 119: ID 2e8a:0005 MicroPython Board in FS mode
Bus 001 Device 118: ID 2e8a:0005 MicroPython Board in FS mode
Bus 001 Device 117: ID 2e8a:0005 MicroPython Board in FS mode
Bus 001 Device 115: ID 2109:2811 VIA Labs, Inc. Hub
Bus 001 Device 114: ID 2109:2811 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

My automation script looks for all the 'ttyACM's on the system and enumerates where they are connected. It then turns them all off in turn, and then back on in turn (with the idea to keep Linux enumeration the same - ie ttyACM0 is the same physical device).

When processing the 'turn on' I occasionally see a reset in syslog, and then magically all the devices are powered on.... the following my best understanding on what happens.

All devices are turned off, and (in this specific case) I request to power on the port where ttyACM0 is expected.

Current status for hub 2-1.1 [2109:8110 VIA Labs, Inc. USB3.0 Hub, USB 3.00, 4 ports, ppps]
  Port 1: 0080 off
Sent power on request
New status for hub 2-1.1 [2109:8110 VIA Labs, Inc. USB3.0 Hub, USB 3.00, 4 ports, ppps]
  Port 1: 02a0 power 5gbps Rx.Detect
Current status for hub 1-1.1 [2109:2811 VIA Labs, Inc. USB2.0 Hub, USB 2.10, 4 ports, ppps]
  Port 1: 0000 off
Sent power on request
New status for hub 1-1.1 [2109:2811 VIA Labs, Inc. USB2.0 Hub, USB 2.10, 4 ports, ppps]
  Port 1: 0101 power connect []

Capturing from ttyACM0
Sun 21 Apr 2024 08:13:07 PM MDT

At this point grabserial failed to bond to the ttyACM0 serial port, and complained it didn't exist.

Just after this happening, I see this message in syslog

2024-04-21T20:13:08.770916-06:00 the-void kernel: [97045.284527] usb 1-1.1: reset high-speed USB device number 91 using xhci_hcd

And all the Pico enumerate in quick succession, where as they would normally be spaced by ~12s

grep "USB ACM device" syslog
...
2024-04-21T20:10:06.954843-06:00 the-void kernel: [96863.464143] cdc_acm 1-1.1.2:1.0: ttyACM2: USB ACM device
2024-04-21T20:10:18.530878-06:00 the-void kernel: [96875.040296] cdc_acm 1-1.1.3:1.0: ttyACM3: USB ACM device
2024-04-21T20:10:30.270867-06:00 the-void kernel: [96886.779288] cdc_acm 1-1.1.4:1.0: ttyACM4: USB ACM device
2024-04-21T20:11:24.234896-06:00 the-void kernel: [96940.746080] cdc_acm 1-1.1.1:1.0: ttyACM0: USB ACM device
2024-04-21T20:11:32.182887-06:00 the-void kernel: [96948.694438] cdc_acm 1-1.2:1.0: ttyACM1: USB ACM device
2024-04-21T20:11:43.890800-06:00 the-void kernel: [96960.402469] cdc_acm 1-1.1.2:1.0: ttyACM2: USB ACM device
2024-04-21T20:11:55.334869-06:00 the-void kernel: [96971.848117] cdc_acm 1-1.1.3:1.0: ttyACM3: USB ACM device
2024-04-21T20:12:07.482888-06:00 the-void kernel: [96983.995552] cdc_acm 1-1.1.4:1.0: ttyACM4: USB ACM device

[reset occurs]
2024-04-21T20:13:09.326859-06:00 the-void kernel: [97045.840429] cdc_acm 1-1.1.1:1.0: ttyACM0: USB ACM device
2024-04-21T20:13:12.766885-06:00 the-void kernel: [97049.282722] cdc_acm 1-1.2:1.0: ttyACM1: USB ACM device
2024-04-21T20:13:13.126789-06:00 the-void kernel: [97049.641567] cdc_acm 1-1.1.2:1.0: ttyACM2: USB ACM device
2024-04-21T20:13:13.702885-06:00 the-void kernel: [97050.218501] cdc_acm 1-1.1.3:1.0: ttyACM3: USB ACM device
2024-04-21T20:13:14.638830-06:00 the-void kernel: [97051.154073] cdc_acm 1-1.1.4:1.0: ttyACM4: USB ACM device

I also suspect that the reset is 'de-enumerating' the previous devices which were turned on during that cycle. I may be able to script around that issue - although devices may not enum in the same order!

mvp commented 7 months ago

Please read this FAQ item https://github.com/mvp/uhubctl?tab=readme-ov-file#power-comes-back-on-after-few-seconds-on-linux

Long story short, by bar most reliable way to fix this is to upgrade your host to Linux kernel 6.x.

mungewell commented 7 months ago

Thanks for the link, but I don't think that this applies in my case.

Mostly my automation script is able cycle the power as required, as seen in the grep of syslog previously the ttyACMs came back on-line with gap between. In the (occasional) reset case, the hub appears to enable them together and they are quickly enumerated.

I'm not sure whether this is a code or hardware problem, it could even be the Pico glitching and getting stuck...

mvp commented 7 months ago

It is most likely Linux kernel USB and/or USB serial driver doing something unexpected. Not likely that uhubctl can fix that. But, that said, for kernel 6.x, uhubctl is using different method to control USB power compared to older kernels - main difference being that for kernel 6.x uhubctl makes use of explicit power off control provided by kernel itself, whereas in older kernels this is not as well defined - power off is sent directly to the hub, anf kernel doesn't explicitly know current power state, which sometimes makes it sporadically trigger device reset.

mvp commented 7 months ago

Closing this as not actionable by uhubctl