search

genodelabs / genode

Genode OS Framework
https://genode.org/
Other
1.08k stars 255 forks source link

disconnecting a USB device sporadically leads to disfunctional USB HID devices on re-connect #5371

Open atopia opened 4 weeks ago

atopia commented 4 weeks ago

Plugging in (and passing through) my LaCie Mobile Drive, a UAS-capable USB-C hard drive appears to temporarily freeze the usb driver. The procedure below worked without fail on 24.04. Therefore a regression in #5356.

The drive is plugged in and routed to the vbox VM via an existing rule in /config/usb. In the VM, a quirk disables UAS (see #5041) and the drive is used via usb-storage.

First time

Plugging in the drive:

[runtime -> usb] usb 4-1: new SuperSpeed USB device number 8 using xhci_hcd
[runtime] child "usb-4-8"
[runtime]   RAM quota:  5896K
[runtime]   cap quota:  66
[runtime]   ELF binary: usb_block
[runtime]   priority:   2
[runtime]   provides service Block
[runtime] child "usb-4-8.part"
[runtime]   RAM quota:  7944K
[runtime]   cap quota:  66
runtime]   ELF binary: part_block
runtime]   priority:   2
runtime]   provides service Block
leitzentrale -> nitpicker] Warning: Gui (wm -> runtime -> leitzentrale -> runtime_dialog) not enough RAM to preserve buffer content during resize

As observed on later experiments, this messages seems to appear when the drive is mounted in the VM (and the usb_part node disappears):

leitzentrale -> manager] Error: usb-4-8.part got stuck

Doing a backup, umounting the partition from Linux and unplugging the device. At this point, the USB HID devices get stuck and the spinning FAN indicates that a component is busy-looping (sorry I didn't get top_view to check):

runtime -> vbox6-block -> vbox] Warning: sched_yield called 100000 times

Finally, restarting usb via a version="2" in /config/managed/runtime restores the HID devices and stops the busy loop.

Second try

With the restarted usb component, just plugging in the device, umounting from Linux and unplugging:

[runtime -> usb] usb 4-1: new SuperSpeed USB device number 5 using xhci_hcd
[runtime] child "usb-4-5"
[runtime]   RAM quota:  5896K
[runtime]   cap quota:  66
[runtime]   ELF binary: usb_block
[runtime]   priority:   2
[runtime]   provides service Block
[runtime] child "usb-4-5.part"
[runtime]   RAM quota:  7944K
[runtime]   cap quota:  66
[runtime]   ELF binary: part_block
[runtime]   priority:   2
[runtime]   provides service Block
[leitzentrale -> nitpicker] Warning: Gui (wm -> runtime -> leitzentrale -> runtime_dialog) not enough RAM to preserve buffer content during resize
[leitzentrale -> manager] Error: usb-4-5.part got stuck
[runtime -> usb] usb 4-1: USB disconnect, device number 5

This time, the HID devices do not get stuck.

Third try

[runtime -> usb] usb 4-1: new SuperSpeed USB device number 5 using xhci_hcd
[runtime] child "usb-4-5"
[runtime]   RAM quota:  5896K
[runtime]   cap quota:  66
[runtime]   ELF binary: usb_block
[runtime]   priority:   2
[runtime]   provides service Block
[runtime] child "usb-4-5.part"
[runtime]   RAM quota:  7944K
[runtime]   cap quota:  66
[runtime]   ELF binary: part_block
[runtime]   priority:   2
[runtime]   provides service Block
[leitzentrale -> nitpicker] Warning: Gui (wm -> runtime -> leitzentrale -> runtime_dialog) not enough RAM to preserve buffer content during resize
[leitzentrale -> manager] Error: usb-4-5.part got stuck
[runtime -> usb] usb 4-1: USB disconnect, device number 5

At this point, the HID devices get stuck again. However, when re-inserting the hard drive for a forth try (without restarting usb) it is still passed through to vbox.

Fourth / fifth / sixth try

Re-inserting the USB keyboard re-enables it withouth restart of usb:

[runtime -> vbox6-block -> vbox] Warning: attempt to handle the same signal context twice (nested)
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> usb] usb 4-1: new SuperSpeed USB device number 6 using xhci_hcd
[runtime] child "usb-4-6"
[runtime]   RAM quota:  5896K
[runtime]   cap quota:  66
[runtime]   ELF binary: usb_block
[runtime]   priority:   2
[runtime]   provides service Block
[runtime] child "usb-4-6.part"
[runtime]   RAM quota:  7944K
[runtime]   cap quota:  66
[runtime]   ELF binary: part_block
[runtime]   priority:   2
[runtime]   provides service Block
[leitzentrale -> manager] Error: usb-4-6.part got stuck
[runtime -> usb] usb 4-1: USB disconnect, device number 6
[runtime -> system_shell -> /bin/bash -> 12] Warning: sigaltstack using self chosen stack is not supported - stack ptr is ignored !!!
[runtime -> system_shell -> terminal] Warning: Alternate Screen (new xterm code) not implemented
[runtime -> system_shell -> terminal] Warning: Application Cursor Keys not implemented
[runtime -> vbox6-block -> vbox] Warning: sched_yield called 100000 times
[runtime -> usb] usb 1-1: new high-speed USB device number 7 using xhci_hcd
[runtime -> usb] usb usb4-port1: config error
[runtime] child "usb-1-7"
[runtime]   RAM quota:  5896K
[runtime]   cap quota:  66
[runtime]   ELF binary: usb_block
[runtime]   priority:   2
[runtime]   provides service Block
[runtime] child "usb-1-7.part"
[runtime]   RAM quota:  7944K
[runtime]   cap quota:  66
[runtime]   ELF binary: part_block
[runtime]   priority:   2
[runtime]   provides service Block
[leitzentrale -> manager] Error: usb-1-7.part got stuck
[runtime -> usb] usb 1-1: USB disconnect, device number 7
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> usb] usb 1-3.2: USB disconnect, device number 4
[runtime -> usb_hid] usb usb-1-4: USB disconnect, device number 0
[runtime -> usb_hid] Disconnected device: input0
[runtime -> usb_hid] Disconnected device: input1
[runtime -> usb_hid] Disconnected device: input2
[runtime -> usb_hid] Disconnected device: input3
[runtime -> usb_hid] Disconnected device: input4
[runtime -> usb_hid] Disconnected device: input5
[runtime -> usb] usb 1-3.2: new full-speed USB device number 8 using xhci_hcd
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint as /devices/usb-1-8/0-0:1.0/0003:17EF:6047.0005/input/input8
[runtime -> usb_hid] Connected device: input8 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint at usb-usbbus-0/input0) 
[runtime -> usb_hid] hid-generic 0003:17EF:6047.0005: input: USB HID v1.00 Keyboard [Lenovo ThinkPad Compact USB Keyboard with TrackPoint] on usb-usbbus-0/input0
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint Mouse as /devices/usb-1-8/0-0:1.1/0003:17EF:6047.0006/input/input9
[runtime -> usb_hid] Connected device: input9 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint Mouse at usb-usbbus-0/input1) MOUSE
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint Consumer Control as /devices/usb-1-8/0-0:1.1/0003:17EF:6047.0006/input/input10
[runtime -> usb_hid] Connected device: input10 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint Consumer Control at usb-usbbus-0/input1) 
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint as /devices/usb-1-8/0-0:1.1/0003:17EF:6047.0006/input/input11
[runtime -> usb_hid] Connected device: input11 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint at usb-usbbus-0/input1) 
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint as /devices/usb-1-8/0-0:1.1/0003:17EF:6047.0006/input/input12
[runtime -> usb_hid] Connected device: input12 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint at usb-usbbus-0/input1) 
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint as /devices/usb-1-8/0-0:1.1/0003:17EF:6047.0006/input/input13
[runtime -> usb_hid] Connected device: input13 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint at usb-usbbus-0/input1) 
[runtime -> usb_hid] hid-generic 0003:17EF:6047.0006: input: USB HID v1.00 Mouse [Lenovo ThinkPad Compact USB Keyboard with TrackPoint] on usb-usbbus-0/input1
[runtime -> usb] usb 4-1: new SuperSpeed USB device number 7 using xhci_hcd
[runtime] child "usb-4-7"
[runtime]   RAM quota:  5896K
[runtime]   cap quota:  66
[runtime]   ELF binary: usb_block
[runtime]   priority:   2
[runtime]   provides service Block
[runtime] child "usb-4-7.part"
[runtime]   RAM quota:  7944K
[runtime]   cap quota:  66
[runtime]   ELF binary: part_block
[runtime]   priority:   2
[runtime]   provides service Block
[leitzentrale -> manager] Error: usb-4-7.part got stuck
[runtime -> usb] usb 4-1: USB disconnect, device number 7
[runtime -> usb] usb 4-1: new SuperSpeed USB device number 8 using xhci_hcd
[runtime] child "usb-4-8"
[runtime]   RAM quota:  5896K
[runtime]   cap quota:  66
[runtime]   ELF binary: usb_block
[runtime]   priority:   2
[runtime]   provides service Block
[runtime] child "usb-4-8.part"
[runtime]   RAM quota:  7944K
[runtime]   cap quota:  66
[runtime]   ELF binary: part_block
[runtime]   priority:   2
[runtime]   provides service Block
[leitzentrale -> manager] Error: usb-4-8.part got stuck
[runtime -> usb] usb 4-1: USB disconnect, device number 8
[runtime -> system_shell -> terminal] Warning: Application Cursor Keys not implemented
[runtime -> system_shell -> terminal] Warning: Alternate Screen (new xterm code) not implemented
[runtime -> system_shell -> /bin/bash -> 13] Warning: sigaltstack using self chosen stack is not supported - stack ptr is ignored !!!
[runtime -> system_shell -> terminal] Warning: Alternate Screen (new xterm code) not implemented
[runtime -> system_shell -> terminal] Warning: Application Cursor Keys not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> vbox6-block -> vbox] Warning: pathconf: pathconf not implemented
[runtime -> system_shell -> terminal] Warning: Application Cursor Keys not implemented
[runtime -> system_shell -> terminal] Warning: Alternate Screen (new xterm code) not implemented
[runtime -> system_shell -> /bin/bash -> 14] Warning: sigaltstack using self chosen stack is not supported - stack ptr is ignored !!!
[runtime -> system_shell -> terminal] Warning: Alternate Screen (new xterm code) not implemented
[runtime -> system_shell -> terminal] Warning: Application Cursor Keys not implemented

Retry without passthrough

Inserting the device on a rebooted system without passthrough rule leads to the following log output:

[runtime -> usb] usb 4-1: new SuperSpeed USB device number 5 using xhci_hcd
[runtime] child "usb-4-5"
[runtime]   RAM quota:  5896K
[runtime]   cap quota:  66
[runtime]   ELF binary: usb_block
[runtime]   priority:   2
[runtime]   provides service Block
[runtime] child "usb-4-5.part"
[runtime]   RAM quota:  7944K
[runtime]   cap quota:  66
[runtime]   ELF binary: part_block
[runtime]   priority:   2
[runtime]   provides service Block
[runtime -> usb-4-5] Warning: The device has vanished, will halt.
[leitzentrale -> nitpicker] Warning: Gui (wm -> runtime -> leitzentrale -> runtime_dialog) not enough RAM to preserve buffer content during resize
[leitzentrale -> manager] Error: usb-4-5.part got stuck
[runtime -> usb] usb 4-1: reset SuperSpeed USB device number 5 using xhci_hcd
atopia commented 4 weeks ago

@skalk I would appreciate any debugging hints to gather more meaningful information at your convenience.

atopia commented 4 weeks ago

Probably connected to the "sdc reader control transfer" issue?

chelmuth commented 4 weeks ago

Probably connected to the "sdc reader control transfer" issue?

For a quick test of this suspicion, you may add a timeout as last parameter of the constructor at https://github.com/genodelabs/genode/blob/7c2362ff9b2c632640b8f96e54d526fafe627a91/repos/libports/src/lib/qemu-usb/host.cc#L906-L907

EDIT Sorry I missed the local implementation of Device::Urb in host.cc. So, you have to adapt this to instantiate a Urb with timeout.

atopia commented 4 weeks ago

Thanks for the hint! I changed the base constructor in

https://github.com/genodelabs/genode/blob/7c2362ff9b2c632640b8f96e54d526fafe627a91/repos/libports/src/lib/qemu-usb/host.cc#L290-L292

to add a timeout of 5000.

Not sure how vbox and part_block are supposed to interact, now I get 

[runtime -> usb] usb 4-1: new SuperSpeed USB device number 8 using xhci_hcd
[runtime] child "usb-4-8"
[runtime]   RAM quota:  5896K
[runtime]   cap quota:  66
[runtime]   ELF binary: usb_block
[runtime]   priority:   2
[runtime]   provides service Block
[runtime] child "usb-4-8.part"
[runtime]   RAM quota:  7944K
[runtime]   cap quota:  66
[runtime]   ELF binary: part_block
[runtime]   priority:   2
[runtime]   provides service Block
/* about 5sec delay here */
[leitzentrale -> manager] Error: usb-4-8.part got stuck

I haven't managed to reproduce the hang in the usb component though.

chelmuth commented 4 weeks ago

If I'm not mistaken, a potential usb_block hang should be addressed in os/src/driver/usb_block.

atopia commented 4 weeks ago

The usb component seems to get stuck sporadically when disconnecting devices, even without any connected usb mass storage devices and with no devices passed through to vbox. I have gathered two report logs and may have recorded report dumps that I can correlate with at least one of the hangs, but the logs don't give any obvious hints. In any case the usb_hid driver registers the re-connected devices but they don't appear to generate input events. Restarting usb resolves the problem. I haven't managed to reliably reproduce the issue. For reference the end of a log showing the disconnects (by disconnecting my external display with its internal USB dock) and after re-plugging the display the newly registered but disfunctional devices:

[runtime -> usb] usb 1-3: USB disconnect, device number 2
[runtime -> usb] usb 1-3.1: USB disconnect, device number 3
[runtime -> usb] usb 1-3.2: USB disconnect, device number 4
[runtime -> usb] usb 1-3.4: USB disconnect, device number 5
[runtime -> usb] usb 1-3.5: USB disconnect, device number 6
[runtime -> usb_hid] usb usb-1-4: USB disconnect, device number 0
[runtime -> usb_hid] Disconnected device: input0
[runtime -> usb_hid] Disconnected device: input1
[runtime -> usb_hid] Disconnected device: input2
[runtime -> usb_hid] Disconnected device: input3
[runtime -> usb_hid] Disconnected device: input4
[runtime -> usb_hid] Disconnected device: input5
[runtime -> usb_hid] usb usb-1-5: USB disconnect, device number 1
[runtime -> usb_hid] Disconnected device: input7
[runtime -> usb_hid] usb usb-1-6: USB disconnect, device number 2
[runtime -> usb] usb 4-3: USB disconnect, device number 2
[runtime -> usb] usb 4-3.1: USB disconnect, device number 3
[runtime -> usb] usb 4-3.1.2: USB disconnect, device number 4
[runtime -> intel_fb]      eDP-1:  enable name='2160x1350' id=1  mirror   mode=2160x1350@60  fb=3840x2160
[runtime -> intel_fb]      eDP-1:  enable name='2160x1350' id=1  mirror   mode=2160x1350@60  fb=3840x2160
[runtime -> intel_fb]      eDP-1:  enable name='2160x1350' id=1  mirror   mode=2160x1350@60  fb=3840x2160
[runtime -> system_shell -> /bin/bash -> 1] Warning: sigaltstack using self chosen stack is not supported - stack ptr is ignored !!!
[runtime -> system_shell -> terminal] Warning: Alternate Screen (new xterm code) not implemented
[runtime -> system_shell -> terminal] Warning: Application Cursor Keys not implemented
[runtime -> system_shell -> /bin/bash -> 1] Warning: chmod: chmod not implemented
[runtime -> intel_fb]      eDP-1:  enable name='2160x1350' id=1  mirror   mode=2160x1350@60  fb=3840x2160
[runtime -> sticks_blue_backdrop] Warning: attempt to handle the same signal context twice (nested)
[runtime -> intel_fb]      eDP-1: capture 2160x1350 with  framebuffer 3840x2160
[runtime -> intel_fb]      eDP-1:  enable name='2160x1350' id=1  mirror   mode=2160x1350@60  fb=3840x2160
[runtime -> intel_fb]      eDP-1:  enable name='2160x1350' id=1  mirror   mode=2160x1350@60  fb=3840x2160
[runtime -> system_shell -> terminal] Warning: attempt to handle the same signal context twice (nested)
[core] [init -> nitpicker] Warning: Gui (backdrop) not enough RAM to preserve buffer content during resize
[core] [init -> nitpicker] Warning: Gui (backdrop) not enough RAM to preserve buffer content during resize
[runtime -> usb] usb 1-3: new high-speed USB device number 7 using xhci_hcd
[runtime -> usb] usb 4-3: new SuperSpeed Plus Gen 2x1 USB device number 5 using xhci_hcd
[runtime -> usb] hub 4-3:1.0: USB hub found
[runtime -> usb] hub 4-3:1.0: 4 ports detected
[runtime -> usb] hub 1-3:1.0: USB hub found
[runtime -> usb] hub 1-3:1.0: 5 ports detected
[runtime -> usb] usb 4-3.1: new SuperSpeed Plus Gen 2x1 USB device number 6 using xhci_hcd
[runtime -> usb] hub 4-3.1:1.0: USB hub found
[runtime -> usb] hub 4-3.1:1.0: 4 ports detected
[runtime -> usb] usb 1-3.1: new high-speed USB device number 8 using xhci_hcd
[runtime -> usb] hub 1-3.1:1.0: USB hub found
[runtime -> usb] hub 1-3.1:1.0: 5 ports detected
[runtime -> usb] usb 1-3.2: new full-speed USB device number 9 using xhci_hcd
[runtime -> usb] usb 4-3.1.2: new SuperSpeed USB device number 7 using xhci_hcd
[runtime] child "usb_hid"
[runtime]   RAM quota:  11016K
[runtime]   cap quota:  146
[runtime]   ELF binary: usb_hid
[runtime]   priority:   1
[runtime -> usb_hid] SLUB: HWalign=64, Order=0-1, MinObjects=0, CPUs=1, Nodes=1
[runtime -> usb_hid] clocksource: dde_counter: mask: 0xffffffffffffff max_cycles: 0x1d854df40, max_idle_ns: 3526361616960 ns
[runtime -> usb_hid] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[runtime -> usb_hid] usbcore: registered new interface driver usbfs
[runtime -> usb_hid] usbcore: registered new interface driver hub
[runtime -> usb_hid] usbcore: registered new device driver usb
[runtime -> usb_hid] clocksource: Switched to clocksource dde_counter
[runtime -> usb_hid] usbcore: registered new interface driver usbhid
[runtime -> usb_hid] hid_core: USB HID core driver
[runtime -> usb_hid] sched_clock: Marking stable (0, 3757000)->(4594000, -837000)
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint as /devices/usb-1-9/0-0:1.0/0003:17EF:6047.0001/input/input0
[runtime -> usb_hid] Connected device: input0 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint at usb-usbbus-0/input0) 
[runtime -> usb_hid] hid-generic 0003:17EF:6047.0001: input: USB HID v1.00 Keyboard [Lenovo ThinkPad Compact USB Keyboard with TrackPoint] on usb-usbbus-0/input0
[runtime -> usb] usb 1-3.4: new low-speed USB device number 10 using xhci_hcd
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint Mouse as /devices/usb-1-9/0-0:1.1/0003:17EF:6047.0002/input/input1
[runtime -> usb_hid] Connected device: input1 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint Mouse at usb-usbbus-0/input1) MOUSE
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint Consumer Control as /devices/usb-1-9/0-0:1.1/0003:17EF:6047.0002/input/input2
[runtime -> usb_hid] Connected device: input2 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint Consumer Control at usb-usbbus-0/input1) 
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint as /devices/usb-1-9/0-0:1.1/0003:17EF:6047.0002/input/input3
[runtime -> usb_hid] Connected device: input3 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint at usb-usbbus-0/input1) 
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint as /devices/usb-1-9/0-0:1.1/0003:17EF:6047.0002/input/input4
[runtime -> usb_hid] Connected device: input4 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint at usb-usbbus-0/input1) 
[runtime -> usb_hid] input: Lenovo ThinkPad Compact USB Keyboard with TrackPoint as /devices/usb-1-9/0-0:1.1/0003:17EF:6047.0002/input/input5
[runtime -> usb_hid] Connected device: input5 (Lenovo ThinkPad Compact USB Keyboard with TrackPoint at usb-usbbus-0/input1) 
[runtime -> usb_hid] hid-generic 0003:17EF:6047.0002: input: USB HID v1.00 Mouse [Lenovo ThinkPad Compact USB Keyboard with TrackPoint] on usb-usbbus-0/input1
[runtime -> usb_hid] input: Logitech USB-PS/2 Optical Mouse as /devices/usb-1-10/0-0:1.0/0003:046D:C00E.0003/input/input7
[runtime -> usb_hid] Connected device: input7 (Logitech USB-PS/2 Optical Mouse at usb-usbbus-0/input0) MOUSE
[runtime -> usb_hid] hid-generic 0003:046D:C00E.0003: input: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-usbbus-0/input0
[runtime -> usb] usb 1-3.5: new high-speed USB device number 11 using xhci_hcd
[runtime -> usb_hid] hid-generic 0003:0BDA:1100.0004: device has no listeners, quitting
chelmuth commented 3 weeks ago

I could not reproduce this issue with Lenovo ThinkVision P24h20 up to now. It would be good to decouple USB and display function in your test case. May you try to reproduce the behavior with a dedicated USB3 Hub on the affected USB-C connector?

Also, how does disfunctional devices manifest? From the log I'd expect the device are initialized successfully in usb_hid. Please add a <log motion="true"> node to the event_filter config for testing.

cnuke commented 3 weeks ago

@atopia with a device now at hand I also noticed problems when using UAS device, I'll look into that.

cnuke commented 3 weeks ago

@atopia it would be nice if you could give commit 3218e5b a try.

atopia commented 3 weeks ago

I could not reproduce this issue with Lenovo ThinkVision P24h20 up to now. It would be good to decouple USB and display function in your test case. May you try to reproduce the behavior with a dedicated USB3 Hub on the affected USB-C connector?

My Lenovo USB3 travel dock is at the office, but I can try to borrow a Lenovo USB-C dock later.

Also, how does disfunctional devices manifest? From the log I'd expect the device are initialized successfully in usb_hid. Please add a <log motion="true"> node to the event_filter config for testing.

Thanks for the hint. What I meant by "disfunctional" is that both physical USB HID devices (a Lenovo keyboard and a Logitech mouse) silently stopped working, without any log output from usb or usb_hid, until I restarted the usb* component.

atopia commented 3 weeks ago

@atopia it would be nice if you could give commit 3218e5b a try.

I have added the commit to my daily driver setup. So far I haven't experienced any issues when connecting and disconnecting my UAS drive, I will let you know if any USB problems resurface. I'm curious if the problem is actually a manifestation of the USB hub reset you mentioned elsewhere? Or is it probably not connected, as the hub reset would trigger USB disconnect in the log, whereas in my case ostensibly connected devices just failed silently?

cnuke commented 3 weeks ago

@atopia thanks for testing. The commit is only there to make it possible to use the UAS device in the first place, which is not possibie without the commit (at least for devices that have the same interface ordering where the UAS interface comes before the BOT interface) and so far is unrelated to the USB hub issue IMHO. (Of course a “misbehaving” client could influence the usb_host driver to trigger the problem more easily.)

cnuke commented 1 week ago

@chelmuth if @skalk does not have any objections, commit 3218e5b could be merged to staging.

skalk commented 1 week ago

@chelmuth @cnuke I'll still have a look into libusb, where this change might interfere with, or better to say, which potentially needs additional care.

cnuke commented 1 week ago

@chelmuth @cnuke I'll still have a look into libusb, where this change might interfere with, or better to say, which potentially needs additional care.

Fine with me, so let's post-pone merging the commit until this is resolved.

skalk commented 1 week ago

@chelmuth @cnuke I'll still have a look into libusb, where this change might interfere with, or better to say, which potentially needs additional care.

I'm pretty sure we need additional care within libusb. Therefore, unfortunately I wouldn't recommend to take the commit on staging before the release.

chelmuth commented 6 days ago

@cnuke would you mind to wrap up the findings in this issue regarding USB hub behavior and the still pending merge of the alt-setting fix?

cnuke commented 5 days ago

No problem, I finished the alternate-settings portion but the hub related stuff is still incomplete - I am going to post both in one go tomorrow.

cnuke commented 4 days ago

The pending alt-setting fix addresses selecting the proper interface for interacting with the device's end-points (EPs). At the moment the first one where the interface-number matches is chosen because the alternate-settings-number is not checked and the Usb::Interface stores the wrong EPs for the interface.

So with devices that feature interfaces with multiple alternate-settings the wrong end-points are propagated to the USB client component and depending on how the component operates it fails to drive the USB device. This is the case with the usb_block driver component that ends up using the wrong end-points (from interface 0 and alt-setting 1) with UAS-capable devices, although it asked for the bulk-only interface that is 0:0 (see Usb::Device::_interface_index() that is used by Usb::Interface::Interface()).

Under the hood, because the UAS-EPs are used but the bulk-only interface is currently active (the driver appears to not support changing alternate-setting so I guess we got lucky), the usb_host driver rightfully dismisses the request (EINVAL ends up being treat as ENOENT that in return leads to Warning: The device has vanished, will halt. message in the LOG) and the usb_block driver enters its sleep_forever() state. The subsequent Error: usb-X-Y.part got stuckmessage points to the sculpt_manager cleaning up the components at this point.

USB-pass-through on the other hand works because the qemu-usb library parses the device report and sets up its own representation of the interfaces and end-points (via List_model<>) and uses that. However, one has to wait until the sculpt_manager removed the components before the device is no longer claimed and the VM may use it.

So commit 3218e5b fixes the problem at hand but will probably break the libusb binding as there Usb::Interface::Index{idx, 0} is always used AFAICT and this change will now a select a different alternate-setting then before.

Using USB hubs can complicate things further, depending on a hub being externally powered (active) or not (passive) and if multiple hubs are chained.

In case such an UAS-device is connected to a passive hub① which itself is connected to a passive hub②, you might observe that already plugged-in devices are re-connected (see usb_hid LOG messages). The same can be observed if you attach a new passive hub② to a passive hub① (that has devices, a mouse and a stick, attached) already attached to the host. When this happens, on hub①, the mouse gets re-connected, while the stick stays untouched (most of the time at least, sometimes it gets re-connected as well).

Since the identical behaviour can be observed using Ubuntu 24.04 (6.8.x) directly on the same system, interacting with passive hubs in that manner might be a “user error” because this issue seems to be absent when hub① is actively powered.