cezanne / usbip-win

USB/IP for Windows
GNU General Public License v3.0
1.94k stars 349 forks source link

attach_ude error #220

Closed chllcy closed 3 years ago

chllcy commented 3 years ago

hi,I'm used ude to test usbip.the usbip-win version is the latest version(Commits on Jan 13, 2021) image

at first,it work well.but after try many times,it work error,and can't recover.even uninstall_ude and install_ude。and the error is the same。how to solve it?

C:\test\x64>usbip attach_ude -r 192.168.2.67 -b 6-1.3 usbip: info: CTRL-C received

C:\test\x64>usbip attach_ude -r 192.168.2.67 -b 6-1.3 usbip: error: usbip_vhci_attach_device: DeviceIoControl failed: err: 0x57 usbip: error: import device usbip: error: read_devbuf: failed to read: err: 0x6

cezanne commented 3 years ago

@chllcy : Can you retry with dev branch ?

chllcy commented 3 years ago

@cezanne thanks,I compile usbip(dev branch),but usbip don't contain install_ude or attach_ude

C:\test\x64>usbip help usage: usbip [--debug] [--tcp-port PORT] [version] [help]

attach Attach a remote USB device(WDM or ude) detach Detach a remote USB device list List exportable or local USB devices bind Bind device to usbip stub driver unbind Unbind device from usbip stub driver install Install usbip vhci driver uninstall Uninstall usbip vhci driver port Show imported USB devices

cezanne commented 3 years ago

@chllcy : Please use install and attach for vhci(ude) as described in README.md at dev branch.

darthcloud commented 3 years ago

I get the same error using your latest release base on dev branch (v0.3.3) PS C:\usbip> ./usbip.exe attach -r 192.168.86.64 -b 2-1 usbip: error: usbip_vhci_attach_device: DeviceIoControl failed: err: 0x57 usbip: error: import device usbip: error: read_devbuf: failed to read: err: 0x6 usbipwin033.zip

kernel etl log in zip

cezanne commented 3 years ago

@darthcloud : Sorry, wrong zip uploaded. I have reloaded a correct zip. A new release will display more clarified error messages. Please retry.

darthcloud commented 3 years ago

@cezanne With your new zip everything work for me now can't reproduce issue anymore! Thanks

Here the kernel log in case it might be interesting, I tested 2 different device back to back with no issue. usbipwin033-2.zip

cezanne commented 3 years ago

@darthcloud : Thanks for your trace log.

chllcy commented 3 years ago

@cezanne I test with dev branch $ git log -1 commit d2c6da06156d8cc2b797b512828c7f9f20ac0142 (HEAD -> dev, tag: v0.3.3-dev, origin/dev) Author: KyungWoon Cho cezanne@codemayo.com Date: Fri Jan 15 21:09:12 2021 +0900

err()->dbg() in userspace library

with 2 usb device,at first it work well.but after try some times, the first usb attach is ok,and the second attach is fail.only one busid attach success.Two usb busids are attached in two different cmd console at the same time。

first time, I first attach 6-1.3,then attach 6-1.4 failed.

C:\test\x64>usbip -d attach -r 192.168.2.67 -b 6-1.3
usbip: debug: usbip.c:151:[run_command] running command: attach
usbip: debug: usbip_vhci.c:61:[usbip_vhci_driver_open] device path: \\?\root#usb#0000#{d35f7840-6a0c-11d2-b841-00c04fad5171}
usbip: debug: usbip_attach.c:62:[import_device] got free port: 3

C:\test\x64>usbip attach -r 192.168.2.67 -b 6-1.4
usbip: error: usbip_vhci_attach_device: DeviceIoControl failed: err: 0x57
usbip: error: failed to attach

second I first attach 6-1.4,then attach 6-1.3 fail

C:\test\x64>usbip -d attach -r 192.168.2.67 -b 6-1.4
usbip: debug: usbip.c:151:[run_command] running command: attach
usbip: debug: usbip_vhci.c:61:[usbip_vhci_driver_open] device path: \\?\root#usb#0000#{d35f7840-6a0c-11d2-b841-00c04fad5171}
usbip: debug: usbip_attach.c:62:[import_device] got free port: 3

C:\test\x64>usbip attach -r 192.168.2.67 -b 6-1.3
usbip: error: usbip_vhci_attach_device: DeviceIoControl failed: err: 0x57
usbip: error: failed to attach

test with traceview.exe image

LogSession_011821_120516.zip

cezanne commented 3 years ago

@chllcy : Maximum number of ports of vhci(ude) was 4. So your 5th attach seemed to fail. I raised the maximum number to 16 and newly built 0.3.3 zip has been uploaded. Please check again.

chllcy commented 3 years ago

thanks @cezanne I had used only two usb devices,and kill process and then restart repeat. after some times, it said no available port? is it some thing wrong?

C:\test\x64>usbip -d attach -r 192.168.2.67 -b 6-1.3
usbip: debug: usbip.c:151:[run_command] running command: attach
usbip: debug: usbip_vhci.c:61:[usbip_vhci_driver_open] device path: \\?\root#usb#0000#{d35f7840-6a0c-11d2-b841-00c04fad5171}
usbip: debug: usbip_attach.c:62:[import_device] got free port: 15

C:\test\x64>usbip -d attach -r 192.168.2.67 -b 6-1.4
usbip: debug: usbip.c:151:[run_command] running command: attach
usbip: debug: usbip_vhci.c:61:[usbip_vhci_driver_open] device path: \\?\root#usb#0000#{d35f7840-6a0c-11d2-b841-00c04fad5171}
usbip: debug: usbip_attach.c:57:[import_device] no free port
usbip: error: no available port
cezanne commented 3 years ago

@chllcy :

I had used only two usb devices,and kill process and then restart repeat. after some times, it said no available port? is it some thing wrong?

Yes, good testing. Killing process seems not to free an used port. I'll inspect it.

cezanne commented 3 years ago

@chllcy : Ctrl+C on command window will free the port. And detach command in another command window can also free safely.

cezanne commented 3 years ago

@chllcy : Please check 1e41e257aa3780be63026dce746be78521c5b0c0 at dev branch. This enables to reclaim a used port even when the attach process is killed instead of Ctrl+C.

chllcy commented 3 years ago

@cezanne thanks,I test for many times, at first it work well,but at last the mouse and keyboard can't work(attach is ok).the port free seems to be working fine.

wireshark log below usbip_range.zip

traceview.log LogSession_011921_101945.zip


another log at first it attach ok,but mouse and keyboard can't work.after about two minutes windows blue screen.

usbip2_range.zip LogSession_011921_105616.zip

cezanne commented 3 years ago

@chllcy : Your trace files can't be displayed with the pdb in 0.3.3 release. Wireshark dumps are also not useful to find a problem. (Too low level dumps) Forwarder logs would be more helpful. By the way, keyboard & mouse are one of working good devices. How can I reproduce your test? What's your usbip server? Your HID device is a simple one?

chllcy commented 3 years ago

@cezanne thanks, I will test and get usbip forwarder log tomorrow. my usbip server is arm linux(4.4.194-gd59efcfa). what I test is just to start windows usbip, and test keyboard and mouse work well?and then kill usbip process and auto restart usbip repeatly.

my device info

[    2.294804] usb 6-1.3: New USB device found, idVendor=1b1c, idProduct=1b3a
[    2.295449] usb 6-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.296148] usb 6-1.3: Product: Corsair Gaming K70 RAPIDFIRE Keyboard 
[    2.296774] usb 6-1.3: Manufacturer: Corsair

[    2.615967] usb 6-1.4: New USB device found, idVendor=0b05, idProduct=1816
[    2.616619] usb 6-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    2.617305] usb 6-1.4: Product: GX860
[    2.617635] usb 6-1.4: Manufacturer: ASUS Gaming Mouse

my usbip_vhci_ude.pdb

usbip_vhci_ude.zip

cezanne commented 3 years ago

@chllcy :

then kill usbip process and auto restart usbip repeatly.

Very tough test. 😄 There was little timing gap between kill and restart. That's the distinct difference from the other previous tests. I'll try in your way. Device types or usbip server doesn't matter.

chllcy commented 3 years ago

@cezanne if I build usbip with forwarder log,It's difficult to reproduce the scene where the keyboard and mouse cannot be used(Tried more than a hundred times)。 but if I used usbip no forwarder log,it's easy to reproduce.and sometime windows will blue screen after a few minutes,


C:\test\x64>usbip -d attach -r 192.168.2.67 -b 6-1.3 usbip: debug: usbip.c:151:[run_command] running command: attach usbip: debug: usbip_vhci.c:61:[usbip_vhci_driver_open] device path: \?\root#usb#0000#{d35f7840-6a0c-11d2-b841-00c04fad5171} usbip: debug: usbip_attach.c:62:[import_device] got free port: 0

I had test with usbip with forward log and usbip no forward log.

  1. no forward log usbip,the keyboard can't work exception_keyboard.zip

  2. with forward log usbip, the keyboard work well. normal_keyboard.zip

usbip_vhci_ude.zip

Compare two traceview log. the left is abnormal,the is normal keyboard.The difference starts with seq 107 image

cezanne commented 3 years ago

@chllcy :

Your logs have two different error cases: request cancel and BSOD.

Let me try to resolve the former case first.
Usbip request seemed to be cancelled by an upper function driver due to no response from a usbip server. The cancellation occurred after 5 seconds. (Look msg #183 and #188 in LogSession_012021_164635.etl) I suspect that a usbip server did not send a response. Can you share kernel logs of a server ? And did you suffer from this problem with single device? And what happens if repetitive attach/detach commands are executed without killing process?

if I build usbip with forwarder log,It's difficult to reproduce the scene where the keyboard and mouse cannot be used(Tried more than a hundred times)。 but if I used usbip no forwarder log,it's easy to reproduce.and sometime windows will blue screen after a few minutes,

Forwarder log requires many file ios and incurs some delay on server. In that case, a usbip server seemed to respond well.

Compare two traceview log. the left is abnormal,the is normal keyboard.The difference starts with seq 107

That difference is ok. It means that the request was pending in queue.

chllcy commented 3 years ago

@cezanne part of usbip dmesg log.if I should build kernel with more usbip log?

[ 2610.970630] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.971569] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.972478] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.973401] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.974351] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.975293] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.976212] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.977138] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.978057] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.979051] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.980235] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2610.981595] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2611.058391] usbip-host 6-1.4: reset full-speed USB device number 4 using xhci-hcd
[ 2611.154420] usbip-host 6-1.4: device reset
[ 2611.218354] usbip-host 6-1.3: reset full-speed USB device number 3 using xhci-hcd
[ 2611.314438] usbip-host 6-1.3: device reset
[ 2611.350182] usbip-host 6-1.4: stub up
[ 2611.356442] usbip-host 6-1.3: stub up
[ 2611.442620] usbip-host 6-1.3: reset full-speed USB device number 3 using xhci-hcd
[ 2611.570700] usbip-host 6-1.3: device reset
[ 2611.573445] usbip-host 6-1.3: stub up
[ 2631.986860] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2631.987811] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2631.988736] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2631.989656] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2631.990572] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2631.991503] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2631.992687] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2631.993646] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2631.994598] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2631.995612] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2631.997009] usbip-host 6-1.3: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[ 2632.082771] usbip-host 6-1.4: reset full-speed USB device number 4 using xhci-hcd
[ 2632.178511] usbip-host 6-1.4: device reset
[ 2632.242491] usbip-host 6-1.3: reset full-speed USB device number 3 using xhci-hcd
[ 2632.339267] usbip-host 6-1.3: device reset
[ 2632.848914] usbip-host 6-1.3: stub up
[ 2632.860499] usbip-host 6-1.4: stub up
[ 2632.978380] usbip-host 6-1.4: reset full-speed USB device number 4 using xhci-hcd
[ 2633.106701] usbip-host 6-1.4: device reset
[ 2633.107883] usbip-host 6-1.4: stub up

yesterday I tested with usbip,when the keyboard was abnormal happened.I used usbip(no forward log) to attach only keyboard(single device),it still failed.but if I used usbip(with forward log) to attach,it work well.

And did you suffer from this problem with single device? And what happens if repetitive attach/detach commands are executed without killing process?

today I will test with only one device(with Ctrl+C to stop attach).

chllcy commented 3 years ago

I find when the keyboard can't work. the dmesg with log [ 286.102154] usbip-host 6-1.4: unlinked by a call to usb_unlink_urb()

exception
[  278.505974] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[  278.507251] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[  278.508646] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[  278.509817] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[  278.595999] usbip-host 6-1.4: reset full-speed USB device number 4 using xhci-hcd
[  278.690950] usbip-host 6-1.4: device reset
[  280.516298] usbip-host 6-1.4: lock for reset
[  280.582250] usbhid_init_reports >> hid->vendor=0x1b1c  hid->product=0x1b3a
[  280.582896] hid-generic 0003:1B1C:1B3A.0041: timeout initializing reports
[  280.585616] input: Corsair Corsair Gaming K70 RAPIDFIRE Keyboard  as /devices/platform/usb1/fe900000.dwc3/xhci-hcd.5.auto/usb6/6-1/6-1.4/6-1.4:1.0/0003:1B1C:1B3A.0041/input/input45
[  280.641277] hid-generic 0003:1B1C:1B3A.0041: input,hidraw0: USB HID v1.11 Keyboard [Corsair Corsair Gaming K70 RAPIDFIRE Keyboard ] on usb-xhci-hcd.5.auto-1.4/input0
[  280.653773] usbhid_init_reports >> hid->vendor=0x1b1c  hid->product=0x1b3a
[  280.654625] hid-generic 0003:1B1C:1B3A.0042: usb_submit_urb(ctrl) failed: -1
[  280.659883] hid-generic 0003:1B1C:1B3A.0042: timeout initializing reports
[  280.669836] input: Corsair Corsair Gaming K70 RAPIDFIRE Keyboard  as /devices/platform/usb1/fe900000.dwc3/xhci-hcd.5.auto/usb6/6-1/6-1.4/6-1.4:1.1/0003:1B1C:1B3A.0042/input/input46
[  280.725075] hid-generic 0003:1B1C:1B3A.0042: input,hiddev0,hidraw1: USB HID v1.11 Keyboard [Corsair Corsair Gaming K70 RAPIDFIRE Keyboard ] on usb-xhci-hcd.5.auto-1.4/input1
[  280.731323] usbhid 6-1.4:1.2: couldn't find an input interrupt endpoint
[  280.803398] usbip-host 6-1.4: usbip-host: register new device (bus 6 dev 4)
[  280.868837] usbip-host 6-1.4: stub up
[  286.102154] usbip-host 6-1.4: unlinked by a call to usb_unlink_urb()
work well
[  328.022404] usbip-host 6-1.4: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
[  328.098462] usbip-host 6-1.4: reset full-speed USB device number 4 using xhci-hcd
[  328.194962] usbip-host 6-1.4: device reset
[  330.042278] usbip-host 6-1.4: lock for reset
[  330.086860] usbhid_init_reports >> hid->vendor=0x1b1c  hid->product=0x1b3a
[  330.087609] hid-generic 0003:1B1C:1B3A.0043: timeout initializing reports
[  330.089398] input: Corsair Corsair Gaming K70 RAPIDFIRE Keyboard  as /devices/platform/usb1/fe900000.dwc3/xhci-hcd.5.auto/usb6/6-1/6-1.4/6-1.4:1.0/0003:1B1C:1B3A.0043/input/input47
[  330.143550] hid-generic 0003:1B1C:1B3A.0043: input,hidraw0: USB HID v1.11 Keyboard [Corsair Corsair Gaming K70 RAPIDFIRE Keyboard ] on usb-xhci-hcd.5.auto-1.4/input0
[  330.155815] usbhid_init_reports >> hid->vendor=0x1b1c  hid->product=0x1b3a
[  330.156917] hid-generic 0003:1B1C:1B3A.0044: usb_submit_urb(ctrl) failed: -1
[  330.157641] hid-generic 0003:1B1C:1B3A.0044: timeout initializing reports
[  330.161693] input: Corsair Corsair Gaming K70 RAPIDFIRE Keyboard  as /devices/platform/usb1/fe900000.dwc3/xhci-hcd.5.auto/usb6/6-1/6-1.4/6-1.4:1.1/0003:1B1C:1B3A.0044/input/input48
[  330.221017] hid-generic 0003:1B1C:1B3A.0044: input,hiddev0,hidraw1: USB HID v1.11 Keyboard [Corsair Corsair Gaming K70 RAPIDFIRE Keyboard ] on usb-xhci-hcd.5.auto-1.4/input1
[  330.223869] usbhid 6-1.4:1.2: couldn't find an input interrupt endpoint
[  330.339743] usbip-host 6-1.4: usbip-host: register new device (bus 6 dev 4)
[  330.408626] usbip-host 6-1.4: stub up
cezanne commented 3 years ago

@chllcy :

[ 286.102154] usbip-host 6-1.4: unlinked by a call to usb_unlink_urb()

That log means that your client cancelled a requested urb. My guess for cancellation is that your server had not sent a response for the cancelled urb. Unfortunately, your dmesg logs don't have a usefull clue.

Have you tried with a device other than keyboard?

chllcy commented 3 years ago

thanks,next time I will use usbip-win server to test if this problem exist. I know little about usbip. It seems that usbip does not support audio,so usb headset can't work.