search

dorssel / usbipd-win

Windows software for sharing locally connected USB devices to other machines, including Hyper-V guests and WSL 2.
GNU General Public License v3.0
3.54k stars 229 forks source link

Unbind or unplug by itself while attached when fastboot transfer is huge (more than 1224 KB) #645

Closed lucmann closed 1 year ago

lucmann commented 1 year ago

Description

I am trying to download binaries to flash on my HiKey970 board via USB Type-C. With the help of usbipd, I manage to connect the board from my WSL2 Ubuntu 20.04 and start to download some binaries. However, something goes wrong once the downloaded binary size exceeds some limits.

I noticed that USBSUP_XFER_DNR -> ETIME -> -62 in usbipd log which is also mentioned in #297. I tried usbipd bind --force --busid 1-13 but didn't work for me. I don't think it's same issue with that.

Any hint to me for this situation? thanks in advance.

target reported max download size of 134217728 bytes
sending 'ptable' (24 KB)...
OKAY [  0.002s]
writing 'ptable'...
OKAY [  0.003s]
finished. total time: 0.006s

target reported max download size of 134217728 bytes
sending 'xloader' (164 KB)...
OKAY [  0.009s]
writing 'xloader'...
OKAY [  0.009s]
finished. total time: 0.018s

target reported max download size of 134217728 bytes
sending 'fastboot' (1152 KB)...
OKAY [  0.054s]
writing 'fastboot'...
OKAY [  0.059s]
finished. total time: 0.113s

target reported max download size of 134217728 bytes
sending 'fip' (1224 KB)...
OKAY [  0.061s]
writing 'fip'...
OKAY [  0.058s]
finished. total time: 0.120s

target reported max download size of 134217728 bytes
sending 'boot' (65536 KB)...
OKAY [  3.259s]
writing 'boot'...
FAILED (status read failed (No such device))
finished. total time: 8.389s

< waiting for any device >
^C
➜  hikey970-ubuntu-image-install git:(master) ✗ lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
➜  hikey970-ubuntu-image-install git:(master) ✗ lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 013: ID 18d1:d00d Google Inc. HiKey970
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

System Info

usbipd --version 3.0.0+361.Branch.master.Sha.89d4b327c99a4eecc9b583e1843a428aae3c9270

~ fastboot --version fastboot version 1:8.1.0+r23-5ubuntu2 Installed as /usr/lib/android-sdk/platform-tools/fastboot

dorssel commented 1 year ago

dbug: Usbipd.AttachedClient[1000] USBSUP_XFER_DNR -> ETIME -> -62 dbug: Usbipd.ConnectedClient[1000] Unbind or unplug while attached

This is what that means:

  1. The device did not respond (DNR) to a URB. This error is simply passed to the client. However, the client did not receive it because of the next log.
  2. Windows no longer sees the device as connected to the host and reports an "unplug event". Hence, usbipd-win closes the socket to the client, to "simulate" the unplug.

2 happens immediately after 1, so the error from 1 did not even make it to the client (WSL). That's the reason Linux only logs

vhci_hcd: connection closed

What causes this? Not sure, but I'll make a guess. It looks like the device resets itself at some stage during flashing. Maybe that is even normal; e.g. at the end. This is seen by Windows as unplug/replug events. The unplug detaches the device, but does not automatically attach it again after reset/replug. You would need to use --auto-attach for that.

lucmann commented 1 year ago

Hi, @dorssel , thank you for the explanation. --auto-attach could make the flashing end up incompletely. I am not sure if the binaries themselves cause this reset or disconnection, i.e. its size or format something.

C:\Windows\System32>usbipd wsl attach --busid 1-13 --auto-attach
usbipd: info: Starting endless attach loop; press Ctrl+C to quit.
Attached
Detached
usbip: error: Attach Request for 1-13 failed - Device not found
Attached
Detached
usbip: error: Attach Request for 1-13 failed - Device not found
Attached

- WSL2 stdout/stderr

target reported max download size of 134217728 bytes sending 'fastboot' (1152 KB)... OKAY [ 0.058s] writing 'fastboot'... OKAY [ 0.059s] finished. total time: 0.117s

target reported max download size of 134217728 bytes sending 'fip' (1224 KB)... OKAY [ 0.059s] writing 'fip'... OKAY [ 0.058s] finished. total time: 0.117s

target reported max download size of 134217728 bytes sending 'boot' (65536 KB)... OKAY [ 3.250s] writing 'boot'... FAILED (status read failed (No such device)) finished. total time: 8.328s

< waiting for any device > target reported max download size of 134217728 bytes erasing 'system'... OKAY [ 0.304s] sending sparse 'system' 1/6 (129097 KB)... OKAY [ 6.916s] writing 'system' 1/6... FAILED (status read failed (No such device)) finished. total time: 45.086s

Update Done!


- WSL2 kernel side log

[Thu Jun 29 08:01:02 2023] usb 1-1: SetAddress Request (15) to port 0 [Thu Jun 29 08:01:02 2023] usb 1-1: New USB device found, idVendor=18d1, idProduct=d00d, bcdDevice= 1.00 [Thu Jun 29 08:01:02 2023] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [Thu Jun 29 08:01:02 2023] usb 1-1: Product: HiKey970 [Thu Jun 29 08:01:02 2023] usb 1-1: Manufacturer: 96Boards [Thu Jun 29 08:01:02 2023] usb 1-1: SerialNumber: 7E07ACD9028D1B7D [Thu Jun 29 08:01:48 2023] vhci_hcd: connection closed [Thu Jun 29 08:01:48 2023] vhci_hcd: stop threads [Thu Jun 29 08:01:48 2023] vhci_hcd: release socket [Thu Jun 29 08:01:48 2023] vhci_hcd: disconnect device [Thu Jun 29 08:01:48 2023] usb 1-1: USB disconnect, device number 15 [Thu Jun 29 08:01:54 2023] vhci_hcd vhci_hcd.0: pdev(0) rhport(0) sockfd(3) [Thu Jun 29 08:01:54 2023] vhci_hcd vhci_hcd.0: devid(65549) speed(3) speed_str(high-speed) [Thu Jun 29 08:01:54 2023] vhci_hcd vhci_hcd.0: Device attached [Thu Jun 29 08:01:55 2023] usb 1-1: new high-speed USB device number 16 using vhci_hcd [Thu Jun 29 08:01:55 2023] usb 1-1: SetAddress Request (16) to port 0 [Thu Jun 29 08:01:55 2023] usb 1-1: New USB device found, idVendor=18d1, idProduct=d00d, bcdDevice= 1.00 [Thu Jun 29 08:01:55 2023] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [Thu Jun 29 08:01:55 2023] usb 1-1: Product: HiKey970 [Thu Jun 29 08:01:55 2023] usb 1-1: Manufacturer: 96Boards [Thu Jun 29 08:01:55 2023] usb 1-1: SerialNumber: 7E07ACD9028D1B7D [Thu Jun 29 08:02:35 2023] vhci_hcd: connection closed [Thu Jun 29 08:02:35 2023] vhci_hcd: stop threads [Thu Jun 29 08:02:35 2023] vhci_hcd: release socket [Thu Jun 29 08:02:35 2023] vhci_hcd: disconnect device [Thu Jun 29 08:02:35 2023] usb 1-1: USB disconnect, device number 16 [Thu Jun 29 08:02:42 2023] vhci_hcd vhci_hcd.0: pdev(0) rhport(0) sockfd(3) [Thu Jun 29 08:02:42 2023] vhci_hcd vhci_hcd.0: devid(65549) speed(3) speed_str(high-speed) [Thu Jun 29 08:02:42 2023] vhci_hcd vhci_hcd.0: Device attached [Thu Jun 29 08:02:42 2023] usb 1-1: new high-speed USB device number 17 using vhci_hcd [Thu Jun 29 08:02:42 2023] usb 1-1: SetAddress Request (17) to port 0 [Thu Jun 29 08:02:42 2023] usb 1-1: New USB device found, idVendor=18d1, idProduct=d00d, bcdDevice= 1.00 [Thu Jun 29 08:02:42 2023] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [Thu Jun 29 08:02:42 2023] usb 1-1: Product: HiKey970 [Thu Jun 29 08:02:42 2023] usb 1-1: Manufacturer: 96Boards [Thu Jun 29 08:02:42 2023] usb 1-1: SerialNumber: 7E07ACD9028D1B7D

dorssel commented 1 year ago

This could be timing/latency related, since small transfers work and large ones do not. Can you provide a capture as explained in https://github.com/dorssel/usbipd-win/wiki/Troubleshooting#usb-capture?

lucmann commented 1 year ago

I did that as the link said, but didn't get the output PcapNg file. BTW, before start usbipd server, the file C:\Users\luc\fastboot.pcapng doesn't exist yet, usbipd would create it, wouldn't it?.

> usbipd --version
3.0.0+361.Branch.master.Sha.89d4b327c99a4eecc9b583e1843a428aae3c9270
C:\Windows\System32>usbipd server Logging:LogLevel:Default=Trace 'usbipd:PcapNg:Path=C:\Users\luc\fastboot.pcapng'
dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
      Hosting starting
dbug: Usbipd.PcapNg[1000]
      usbipd:PcapNg:Path = ''
dbug: Usbipd.Server[1000]
      3.0.0+361.Branch.master.Sha.89d4b327c99a4eecc9b583e1843a428aae3c9270
dbug: Usbipd.Server[1000]
      usbipd:TcpKeepAliveInterval = 500 ms
dbug: Usbipd.Server[1000]
      usbipd:TcpKeepAliveTime = 10000 ms
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
      Content root path: C:\Program Files\usbipd-win\
dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
      Hosting started
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.Server[1000]
      connection close: Unable to read beyond the end of the stream.
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.ConnectedClient[1000]
      Claiming took 118 ms
info: Usbipd.ConnectedClient[1]
      Client 172.27.245.96 claimed device at 1-10 (USB\VID_18D1&PID_D00D\7E07ACD9028D1B7D).
dbug: Usbipd.AttachedClient[1000]
      Trapped SET_CONFIGURATION: 1
dbug: Usbipd.AttachedClient[1000]
      USBSUP_XFER_DNR -> ETIME -> -62
dbug: Usbipd.ConnectedClient[1000]
      Unbind or unplug while attached
info: Usbipd.ConnectedClient[2]
      Client 172.27.245.96 released device at 1-10 (USB\VID_18D1&PID_D00D\7E07ACD9028D1B7D).
dbug: Usbipd.Server[1000]
      connection close: The operation was canceled.
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.ConnectedClient[1000]
      Claiming took 219 ms
info: Usbipd.ConnectedClient[1]
      Client 172.27.245.96 claimed device at 1-10 (USB\VID_18D1&PID_D00D\7E07ACD9028D1B7D).
dbug: Usbipd.AttachedClient[1000]
      Trapped SET_CONFIGURATION: 1
dbug: Usbipd.AttachedClient[1000]
      USBSUP_XFER_DNR -> ETIME -> -62
dbug: Usbipd.ConnectedClient[1000]
      Unbind or unplug while attached
info: Usbipd.ConnectedClient[2]
      Client 172.27.245.96 released device at 1-10 (USB\VID_18D1&PID_D00D\7E07ACD9028D1B7D).
dbug: Usbipd.Server[1000]
      connection close: The operation was canceled.
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.Server[1000]
      connection closed
dbug: Usbipd.Server[1000]
      new connection from 172.27.245.96
dbug: Usbipd.ConnectedClient[1000]
      Received opcode: OP_REQ_IMPORT
dbug: Usbipd.ConnectedClient[1000]
      Claiming took 223 ms
info: Usbipd.ConnectedClient[1]
      Client 172.27.245.96 claimed device at 1-10 (USB\VID_18D1&PID_D00D\7E07ACD9028D1B7D).
dbug: Usbipd.AttachedClient[1000]
      Trapped SET_CONFIGURATION: 1
dorssel commented 1 year ago

dbug: Usbipd.PcapNg[1000] usbipd:PcapNg:Path = ''

I checked why this happens, as you did specify a file. Turns out the documented syntax only works for PowerShell. For CMD prompts the syntax requires double quotes:

usbipd server Logging:LogLevel:Default=Trace "usbipd:PcapNg:Path=C:\Users\luc\fastboot.pcapng"

EDIT: Turns out that PowerShell also accepts double quotes, so I've updated the wiki to use double quotes (which works on both).

lucmann commented 1 year ago

dbug: Usbipd.PcapNg[1000] usbipd:PcapNg:Path = ''

Sorry about my negligence. Now I get the capture. thanks for your time.

dorssel commented 1 year ago

With respect to the full log file:

All in all: the transfer is successful. The device resets at the end. Very similar to https://github.com/dorssel/usbipd-win/issues/647#issuecomment-1613884733. Is the device working at the end? Maybe you can lower the sleep time in the auto-attach script (or even make it a busy loop). That will reduce the latency between detach and attach.

lucmann commented 1 year ago

thank you for your analysis. the device doesn't work in the end. I switched to connect the board to a physical Ubuntu 20.04 host, it turns out the same issue. indeed looks like device resetting during the time when fastboot flash boot boot-hikey970.uefi.img. I guess I should go for help to HiKey970 community now.