0

Short version: Running ubuntu 18.04.02 in a Hyper-V VM as a client of usbip and ubuntu 18.04 on a raspberry pi as a usb server. The Hyper-V VM is running Home Assistant (as hass.io) in a docker container. When the Hyper-V vm is rebooted, sometimes, the usbip service cannot reconnect to the rPi's server side until the rPi's usbip service is restarted.

It appears this only occurs when the Hyper-V VM is rebooted from inside the (--privileged) docker container; if rebooted from the ubuntu shell then it works.

Both clients are using the usbip from linux-tools-generic (not the prior standalone package) and identify as version 2. I have packaged both in a service, the server side running as type forking, the client as one-time. On a fresh boot of both they work fine.

Here is the logging (with debug on) for a reboot of the client side (Hyper-V) that fails to connect. Apologies for the length, have pruned quite a bit, but not sure what of what is left is relevant.

This is from the client when all is working and you can see the attached remote port:

root@ha:~# usbip port
Imported USB devices
====================
Port 00: <Port in Use> at Full Speed(12Mbps)
       Cygnal Integrated Products, Inc. : unknown product (10c4:8a2a)
       1-1 -> usbip://192.168.132.100:3240/1-1.2
           -> remote bus/dev 001/004

Reboot from docker on the Hyper-V (usbip client) side, here's the log from the shutdown:

May  2 13:07:04 ha NetworkManager[1181]: <info>  [1556802424.0981] device changed (path: /sys/devices/LNXSYSTM:00/LNXSYBUS:00/ACPI0004:00/VMBUS:00/f8091f75-727b-47ed-85fd-ce642aa4be61/net/eth0, iface: eth0)
May  2 13:07:04 ha ModemManager[964]: <info>  (tty/ttyUSB1): released by modem /sys/devices/platform/vhci_hcd.0/usb1/1-1
May  2 13:07:04 ha ModemManager[964]: <warn>  [plugin manager] task 0,ttyUSB1: error when checking support with plugin 'Iridium': 'Operation was cancelled'
May  2 13:07:04 ha ModemManager[964]: <warn>  [plugin manager] task 0,ttyUSB1: failed: Operation was cancelled
May  2 13:07:04 ha NetworkManager[1181]: <info>  [1556802424.1522] device changed (path: /sys/devices/virtual/net/docker0, iface: docker0)

Here is the same shutdown info from the server (rPi usbip server) side; note the rPi was not shut down, this is just in response to the Hyper-V shutdown (or more precisely I think these are just routine and there appears to be no real response to the Hyper-V shutdown, unless that heartbeat is, but they do appear periodically anyway):

May  2 13:06:56 ubuntu kernel: [41155.172199] usbip-host 1-1.2: endpoint 0 is stalled
May  2 13:06:56 ubuntu kernel: [41155.176078] usbip-host 1-1.2: endpoint 0 is stalled
May  2 13:07:03 ubuntu usbipd: usbipd: debug: usbipd.c:573:[do_standalone_mode] heartbeat timeout on ppoll()

This is back on Hyper-V when it reboots

May  2 13:11:27 ha kernel: [    2.810394] systemd[1]: Set hostname to <ha>.
May  2 13:11:27 ha kernel: [    2.977418] systemd[1]: /lib/systemd/system/usbip.service:9: Ignoring unknown escape sequences: "/usr/lib/linux-tools/$(uname -r)/usbip detach --port=$(/usr/lib/linux-tools/$(uname -r)/usbip port | grep '<Port in Use>' | sed -E 's/^Port ([0-9][0-9]).*/\1/')"

Note: the above line comes from the ExecStop part of the service definition -- how it is running on boot BEFORE service start not sure, but I think this did nothing. The error I think comes because (at this point) there is no port to find and detach.

May  2 13:11:28 ha sh[1380]: usbip: error: recv op_common
May  2 13:11:28 ha sh[1380]: usbip: error: query
May  2 13:11:28 ha systemd[1]: Starting Docker Application Container Engine...
May  2 13:11:28 ha systemd[1]: usbip.service: Main process exited, code=exited, status=1/FAILURE
May  2 13:11:28 ha systemd[1]: usbip.service: Failed with result 'exit-code'.
May  2 13:11:28 ha systemd[1]: Failed to start usbip client.
May  2 13:11:28 ha systemd[1]: Started Permit User Sessions.

This failure prevented the service from starting, and it will not start manually either (same error see below). At this point on the client can see the remote device, but cannot attach to it, as this manual example shows:

root@ha:~# usbip list -r zwave
Exportable USB devices
======================
 - zwave
      1-1.2: Cygnal Integrated Products, Inc. : unknown product (10c4:8a2a)
           : /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2
           : (Defined at Interface level) (00/00/00)
           :  0 - Vendor Specific Class / unknown subclass / unknown protocol (ff/00/00)
           :  1 - Vendor Specific Class / unknown subclass / unknown protocol (ff/00/00)

root@ha:~# usbip port
Imported USB devices
====================
root@ha:~# usbip attach -r zwave -b 1-1.2
usbip: error: recv op_common
usbip: error: query

But on the server (rPi) the response to the above commands show the following when it tries to connect. Note that the client first does a list to get the bus id, then the attach, so you see the connection for the list, then the failure on the attach.

May  2 13:11:28 ubuntu usbipd: usbipd: debug: usbipd.c:568:[do_standalone_mode] read event on fd[0]=4
May  2 13:11:28 ubuntu usbipd: usbipd: info: connection from 192.168.132.254:34686
May  2 13:11:28 ubuntu usbipd: usbipd: info: received request: 0x8005(6)
May  2 13:11:28 ubuntu usbipd: usbipd: info: exportable devices: 1
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:91:[dump_usb_device] path                 = /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:92:[dump_usb_device] busid                = 1-1.2
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:98:[dump_usb_device] Device(C/SC/P)       = (Defined at Interface level) (00/00/00)
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:100:[dump_usb_device] bcdDevice            = 100
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:105:[dump_usb_device] Vendor/Product       = unknown vendor : unknown product (10c4:8a2a)
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:107:[dump_usb_device] bNumConfigurations   = 1
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:108:[dump_usb_device] bNumInterfaces       = 2
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:111:[dump_usb_device] speed                = Full Speed(12Mbps)
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:113:[dump_usb_device] busnum               = 1
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:114:[dump_usb_device] devnum               = 4
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:84:[dump_usb_interface] Interface(C/SC/P)    = unknown class / unknown subclass / unknown protocol (ff/00/00)
May  2 13:11:28 ubuntu usbipd: libusbip: debug: usbip_common.c:84:[dump_usb_interface] Interface(C/SC/P)    = unknown class / unknown subclass / unknown protocol (ff/00/00)
May  2 13:11:28 ubuntu usbipd: usbipd: info: request 0x8005(6): complete
May  2 13:11:28 ubuntu usbipd: usbipd: debug: usbipd.c:568:[do_standalone_mode] read event on fd[0]=4
May  2 13:11:28 ubuntu usbipd: usbipd: info: connection from 192.168.132.254:34688
May  2 13:11:28 ubuntu usbipd: usbipd: info: received request: 0x8003(6)
May  2 13:11:28 ubuntu usbipd: usbipd: info: found requested device: 1-1.2
May  2 13:11:28 ubuntu usbipd: usbip: debug: usbip_host_common.c:233:[usbip_export_device] device not available: 1-1.2
May  2 13:11:28 ubuntu usbipd: usbip: debug: usbip_host_common.c:239:[usbip_export_device] status SDEV_ST_USED
May  2 13:11:28 ubuntu usbipd: usbipd: debug: usbipd.c:152:[recv_request_import] import request busid 1-1.2: failed
May  2 13:11:28 ubuntu usbipd: usbipd: info: request 0x8003(6): failed

What's odd in the above is it appears to say the device is there, but then says not available with a SDEV_ST_USED status, as though it is in use and reserved in some fashion (as though it did not release earlier?).

And again, some times (by inference but without certainty when the ubuntu shell reboots as opposed to docker causing ubuntu to reboot) it works properly.

Note the rPi service continues to run, so it will not auto-restart; the connection fails not the service. A manual restart on first the rPi server, then the HyperV VM client, causes it to work properly. I can auto-restart the client in the service definition but that does no good, as it requires the rPi usbip service to restart to clear things up.

Yes, the short answer is to remember to always reboot from ubuntu not the docker container.

But... is there a more robust answer? Is there some configuration or setup issue that may be preventing the server side from cleaning up properly?

I guess in theory I can script the restart of the client to force a remote restart of the server (and wait for it to be ready) but that seems pretty fragile.

Any insights?

PS. I should note that the reverse situation is also a problem - if I restart the usbip service on the rPi the clent (Hyper-V VM) thinks it is still connected but will not work, and requires a restart as well. This is less problematic as the rPi server needs to be rebooted very infrequently, whereas I am developing on the Home Assistant software and it gets rebooted often. But the underlying problem is similar - restarting one end can break the other.

  • The error message for the usbip detach command looks suspicious - it's entirely possible that if the detach fails to execute, than a later attempt to connect can also fail, because the other side still assumes a connection in a certain state. So the first thing I'd do is to look at usbip.service and fix whatever the quoting issues are (you might need to read systemd documenation for that). – dirkt May 3 at 10:52
  • 1
    I am 99% sure that's not an issue. What happens (I have dug into it a bit more) is that the ExecStop for the service does a port command to get what is attached. If nothing is attached it throws that error. Normally something is attached because, well, it started. The dilemma here is that for reasons unclear ExecStop is running on system boot before the service even starts. So I think the error is spurious. That syntax error does not occur on a successful service start followed by a stop (or restart), it only occurs on boot. – Linwood May 3 at 14:32
  • 1
    Incidentally, over in the Home Assistant forum another user doing much the same has seen the same issue, and their solution is to script a remote service restart. Ugly but functional I think, but begs the question why the remote USB server is not releasing properly. But confirming it is affecting others. community.home-assistant.io/t/… – Linwood May 3 at 14:36

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.