Virtualhere client says device in use, but cannot actually use the device.

Submitted by sakorkko on #1

Hello,

Everything works as intended, but when I start testing the device on the client side it suddenly disappears. The client can list the hub and device, and shows that it is in use. However lsusb does not show it and I cannot interact with it. The issue resolves with re-plugging the device and it shows up again.

The test consists of sending a break signal to UART and then waiting for it to activate again repeatedly. The test works on a direct connection just fine. I cut out some of the urb messages from below, they seemed to appear when the test was running.

If you need more information ask away.

SERVER INFO
Linux debian 4.9.0-6-amd64 #1 SMP Debian 4.9.88-1+deb9u1 (2018-05-07) x86_64 GNU/Linux
vhusbdx86_64 v3.6.6

CLIENT INFO
Linux localhost 4.9.0-6-amd64 #1 SMP Debian 4.9.82-1+deb9u3 (2018-03-02) x86_64 GNU/Linux
VirtualHere Client 4.5.3

CLIENT -T LIST
VirtualHere Client IPC, below are the available devices:
(Value in brackets = address, * = Auto-Use)

Desktop Hub (debian:7575)
*--> DAPLink CMSIS-DAP (debian.12) (In-use by you)

Auto-Find currently on
Auto-Use All currently on
Reverse Lookup currently on
VirtualHere Client not running as a service

CLIENT LSUSB
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 010 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 009 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 008 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 007 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 006 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 004: ID 8087:0aa7 Intel Corp.
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

SERVER LSUSB
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 004: ID 8087:0aa7 Intel Corp.
Bus 001 Device 006: ID 0d28:0204 NXP LPC1768 <--- this one
Bus 001 Device 002: ID 046d:c52b Logitech, Inc. Unifying Receiver
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

CLIENT DMESG
[ 8104.227978] vhci_hcd: the urb (seqnum 370951) was already given back
[ 8104.230601] vhci_hcd: unlink->seqnum 370952
[ 8104.233041] vhci_hcd: the urb (seqnum 370952) was already given back
[ 8104.235413] vhci_hcd: unlink->seqnum 370960
[ 8104.237694] vhci_hcd: the urb (seqnum 370960) was already given back
[ 8104.240038] vhci_hcd: unlink->seqnum 370969
[ 8104.241706] vhci_hcd: the urb (seqnum 370969) was already given back
[ 8104.243356] vhci_hcd: unlink->seqnum 370976
[ 8104.244948] vhci_hcd: the urb (seqnum 370976) was already given back
[ 8104.246584] vhci_hcd: unlink->seqnum 370978
[ 8104.248164] vhci_hcd: the urb (seqnum 370978) was already given back
[ 8104.249751] vhci_hcd: unlink->seqnum 370985
[ 8104.251330] vhci_hcd: the urb (seqnum 370985) was already given back
[ 8104.252937] vhci_hcd: unlink->seqnum 370986
[ 8104.254511] vhci_hcd: the urb (seqnum 370986) was already given back
[ 8104.256102] vhci_hcd: unlink->seqnum 370988
[ 8104.257680] vhci_hcd: the urb (seqnum 370988) was already given back
[ 8104.618091] vhci_hcd: unlink->seqnum 371393
[ 8104.621887] vhci_hcd: the urb (seqnum 371393) was already given back
[ 8104.624528] usbip_core: unknown command
[ 8104.626963] vhci_hcd: unknown pdu 768
[ 8104.629372] usbip_core: unknown command
[ 8104.631876] vhci_hcd: stop threads
[ 8104.633558] vhci_hcd: release socket
[ 8104.635084] vhci_hcd: unlink cleanup rx 371392
[ 8104.636598] vhci_hcd: disconnect device
[ 8104.638155] usb 3-1: USB disconnect, device number 6
[ 8104.662413] FAT-fs (sdc): unable to read boot sector to mark fs as dirty
[ 8104.701950] cdc_acm 3-1:1.1: acm_port_activate - usb_submit_urb(ctrl irq) failed

SERVER DMESG
[ 2212.855773] usb 1-2: new full-speed USB device number 6 using xhci_hcd
[ 2212.998052] usb 1-2: New USB device found, idVendor=0d28, idProduct=0204
[ 2212.998060] usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 2212.998065] usb 1-2: Product: DAPLink CMSIS-DAP
[ 2212.998069] usb 1-2: Manufacturer: ARM
[ 2212.998074] usb 1-2: SerialNumber: 0240000031754e4500250018948500386461000097969900
[ 2213.120096] usb 1-2: reset full-speed USB device number 6 using xhci_hcd

CLIENT VIRTULAHERE LOG
11:03:23 INFO :Log Started
11:03:23 INFO :VirtualHere Client 4.5.3 starting (Compiled: Jun 3 2018 14:03:41)
11:03:23 INFO :Using config at /home/raas/clientconfig.ini
11:03:23 INFO :IPC available at /tmp/vhclient
11:03:23 INFO :Auto-find using Bonjour - on
11:03:23 INFO :Auto-find using Bonjour SSL - on
11:03:23 INFO :ReverseLookupService listening on port 7573
11:49:55 INFO :VirtualHere USB Server Trial Edition (192.168.130.41:7575)
14:03:14 INFO :Warning did not find pending usbip packet sn=630269 to unlink
14:03:14 INFO :Warning did not find pending usbip packet sn=630274 to unlink
14:03:14 INFO :Warning did not find pending usbip packet sn=630286 to unlink
14:03:19 INFO :Warning did not find pending usbip packet sn=632191 to unlink
14:03:19 INFO :Warning did not find pending usbip packet sn=632212 to unlink
14:03:19 INFO :Warning did not find pending usbip packet sn=632228 to unlink
14:03:19 INFO :Warning did not find pending usbip packet sn=632243 to unlink
14:03:19 INFO :Warning did not find pending usbip packet sn=632247 to unlink
14:03:41 INFO :Warning did not find pending usbip packet sn=632709 to unlink
14:03:45 INFO :Warning did not find pending usbip packet sn=633017 to unlink
14:03:57 INFO :Warning did not find pending usbip packet sn=635307 to unlink
14:03:57 INFO :Warning did not find pending usbip packet sn=635312 to unlink
14:03:57 INFO :Warning did not find pending usbip packet sn=635322 to unlink
14:03:57 INFO :Warning did not find pending usbip packet sn=635324 to unlink

SERVER VIRTUALHERE LOG
Wed Jun 13 11:18:24 2018 LOG_WARNING Error 22 discarding urb 0xb064a0 for device /sys//devices/pci0000:00/0000:00:15.0/usb1/1-2, Invalid argument (abort endpoint)
Wed Jun 13 11:18:24 2018 LOG_WARNING Error 22 discarding urb 0xb065a0 for device /sys//devices/pci0000:00/0000:00:15.0/usb1/1-2, Invalid argument (abort endpoint)
Wed Jun 13 11:18:24 2018 LOG_WARNING Error 22 discarding urb 0xb066a0 for device /sys//devices/pci0000:00/0000:00:15.0/usb1/1-2, Invalid argument (abort endpoint)
Wed Jun 13 11:18:24 2018 LOG_WARNING Error 22 discarding urb 0xb067a0 for device /sys//devices/pci0000:00/0000:00:15.0/usb1/1-2, Invalid argument (abort endpoint)
Wed Jun 13 11:18:24 2018 LOG_WARNING Error 22 discarding urb 0xb068a0 for device /sys//devices/pci0000:00/0000:00:15.0/usb1/1-2, Invalid argument (abort endpoint)
Wed Jun 13 11:18:24 2018 LOG_WARNING Error 22 discarding urb 0xb060a0 for device /sys//devices/pci0000:00/0000:00:15.0/usb1/1-2, Invalid argument (abort endpoint)
Wed Jun 13 11:18:24 2018 LOG_WARNING Error 22 discarding urb 0xb06120 for device /sys//devices/pci0000:00/0000:00:15.0/usb1/1-2, Invalid argument (abort endpoint)

Thanks.

Submitted by Michael on Fri, 2018/06/15 - 20:07

#2

If it says that then you have a bug in the kernel. I suggest updating to the latest kernel 4.15 or later

Submitted by sakorkko on Fri, 2018/06/15 - 21:11

#3

Ok, will try. Thanks for response. I will update on this next week when I have more time.

Submitted by sakorkko on Wed, 2018/06/20 - 17:30

#4

Okay, here is the update.

Problem persists on the new kernel. While building it I enabled some USBIP debugging which increased the dmesg log on the server.

Below are some logs from the time of disconnection. Seems like this is still related to the kernel. If you have any ideas they would be appreciated.

Thanks
sakorkko

SERVER UNAME
Linux debian 4.17.2 #1 SMP Mon Jun 18 07:22:11 BST 2018 x86_64 GNU/Linux

SERVER DMESG
no output

SERVER VHLOG
Wed Jun 20 07:35:13 2018 LOG_INFO >>> Starting VirtualHere USB Server v3.6.6 (Built: May 10 2018, 20:47:31)<<<
Wed Jun 20 07:35:13 2018 LOG_INFO Using configuration /home/arm/config.ini
Wed Jun 20 07:35:13 2018 LOG_INFO Server licensed to=unlicensed max_devices=1
Wed Jun 20 07:35:13 2018 LOG_INFO Using large URB's
Wed Jun 20 07:35:13 2018 LOG_INFO Listening on all network interfaces at TCP port 7575
Wed Jun 20 07:35:13 2018 LOG_INFO Claiming 8 ports on hub /dev/bus/usb/001/001
Wed Jun 20 07:35:13 2018 LOG_INFO Found Full speed device [0d28:0204] "ARM, DAPLink CMSIS-DAP" at address 11
Wed Jun 20 07:35:13 2018 LOG_INFO Claiming 7 ports on hub /dev/bus/usb/002/001
Wed Jun 20 07:35:21 2018 LOG_INFO 192.168.130.72 connected as connection 1
Wed Jun 20 07:35:22 2018 LOG_INFO Device 11 [0d28:0204] BOUND to connection 1
Wed Jun 20 07:36:06 2018 LOG_WARNING Error 22 discarding urb 0x9b9620 for device /sys/bus/usb/devices/1-1, Invalid argument (abort endpoint)
Wed Jun 20 07:36:06 2018 LOG_WARNING Error 22 discarding urb 0x9b9720 for device /sys/bus/usb/devices/1-1, Invalid argument (abort endpoint)
Wed Jun 20 07:36:06 2018 LOG_WARNING Error 22 discarding urb 0x9b9820 for device /sys/bus/usb/devices/1-1, Invalid argument (abort endpoint)
Wed Jun 20 07:36:06 2018 LOG_WARNING Error 22 discarding urb 0x9b9bc0 for device /sys/bus/usb/devices/1-1, Invalid argument (abort endpoint)
Wed Jun 20 07:36:06 2018 LOG_WARNING Error 22 discarding urb 0x9b9cc0 for device /sys/bus/usb/devices/1-1, Invalid argument (abort endpoint)
Wed Jun 20 07:36:06 2018 LOG_WARNING Error 22 discarding urb 0x9b9dc0 for device /sys/bus/usb/devices/1-1, Invalid argument (abort endpoint)

CLIENT UNAME
Linux localhost 4.17.2 #1 SMP Mon Jun 18 15:55:18 EEST 2018 x86_64 GNU/Linux

CLIENT DMESG
[69848.354459] usb 3-1: devnum(7) devpath(1) usb speed(full-speed)
[69848.354461] usbip_core: usbip_dump_usb_device:94: tt hub ttport 1
[69848.354462] usb 3-1:
[69848.354463] usbip_core: usbip_dump_usb_device:98: 0
[69848.354464] usbip_core: usbip_dump_usb_device:98: 1
[69848.354466] usbip_core: usbip_dump_usb_device:98: 2
[69848.354467] usbip_core: usbip_dump_usb_device:98: 3
[69848.354469] usbip_core: usbip_dump_usb_device:98: 4
[69848.354470] usbip_core: usbip_dump_usb_device:98: 5
[69848.354472] usbip_core: usbip_dump_usb_device:98: 6
[69848.354473] usbip_core: usbip_dump_usb_device:98: 7
[69848.354475] usbip_core: usbip_dump_usb_device:98: 8
[69848.354476] usbip_core: usbip_dump_usb_device:98: 9
[69848.354478] usbip_core: usbip_dump_usb_device:98: 10
[69848.354479] usbip_core: usbip_dump_usb_device:98: 11
[69848.354481] usbip_core: usbip_dump_usb_device:98: 12
[69848.354482] usbip_core: usbip_dump_usb_device:98: 13
[69848.354484] usbip_core: usbip_dump_usb_device:98: 14
[69848.354485] usbip_core: usbip_dump_usb_device:98: 15
[69848.354487] usbip_core: usbip_dump_usb_device:99:
[69848.354490] usb 3-1: toggle0(IN) :
[69848.354491] usbip_core: usbip_dump_usb_device:103: 0
[69848.354492] usbip_core: usbip_dump_usb_device:103: 0
[69848.354493] usbip_core: usbip_dump_usb_device:103: 0
[69848.354494] usbip_core: usbip_dump_usb_device:103: 0
[69848.354496] usbip_core: usbip_dump_usb_device:103: 0
[69848.354497] usbip_core: usbip_dump_usb_device:103: 0
[69848.354498] usbip_core: usbip_dump_usb_device:103: 0
[69848.354499] usbip_core: usbip_dump_usb_device:103: 0
[69848.354500] usbip_core: usbip_dump_usb_device:103: 0
[69848.354501] usbip_core: usbip_dump_usb_device:103: 0
[69848.354502] usbip_core: usbip_dump_usb_device:103: 0
[69848.354504] usbip_core: usbip_dump_usb_device:103: 0
[69848.354505] usbip_core: usbip_dump_usb_device:103: 0
[69848.354506] usbip_core: usbip_dump_usb_device:103: 0
[69848.354508] usbip_core: usbip_dump_usb_device:103: 0
[69848.354509] usbip_core: usbip_dump_usb_device:103: 0
[69848.354511] usbip_core: usbip_dump_usb_device:104:
[69848.354514] usb 3-1: toggle1(OUT):
[69848.354515] usbip_core: usbip_dump_usb_device:108: 0
[69848.354516] usbip_core: usbip_dump_usb_device:108: 0
[69848.354517] usbip_core: usbip_dump_usb_device:108: 0
[69848.354518] usbip_core: usbip_dump_usb_device:108: 0
[69848.354519] usbip_core: usbip_dump_usb_device:108: 0
[69848.354521] usbip_core: usbip_dump_usb_device:108: 0
[69848.354522] usbip_core: usbip_dump_usb_device:108: 0
[69848.354523] usbip_core: usbip_dump_usb_device:108: 0
[69848.354524] usbip_core: usbip_dump_usb_device:108: 0
[69848.354525] usbip_core: usbip_dump_usb_device:108: 0
[69848.354526] usbip_core: usbip_dump_usb_device:108: 0
[69848.354527] usbip_core: usbip_dump_usb_device:108: 0
[69848.354529] usbip_core: usbip_dump_usb_device:108: 0
[69848.354530] usbip_core: usbip_dump_usb_device:108: 0
[69848.354532] usbip_core: usbip_dump_usb_device:108: 0
[69848.354533] usbip_core: usbip_dump_usb_device:108: 0
[69848.354535] usbip_core: usbip_dump_usb_device:109:
[69848.354538] usb 3-1: epmaxp_in :
[69848.354539] usbip_core: usbip_dump_usb_device:115: 64
[69848.354541] usbip_core: usbip_dump_usb_device:115: 64
[69848.354542] usbip_core: usbip_dump_usb_device:115: 64
[69848.354543] usbip_core: usbip_dump_usb_device:115: 16
[69848.354544] usbip_core: usbip_dump_usb_device:115: 64
[69848.354545] usbip_core: usbip_dump_usb_device:117:
[69848.354547] usb 3-1: epmaxp_out :
[69848.354548] usbip_core: usbip_dump_usb_device:123: 64
[69848.354549] usbip_core: usbip_dump_usb_device:123: 64
[69848.354550] usbip_core: usbip_dump_usb_device:123: 64
[69848.354552] usbip_core: usbip_dump_usb_device:123: 64
[69848.354555] usbip_core: usbip_dump_usb_device:125:
[69848.354557] usb 3-1: parent usb3, bus vhci_hcd.0
[69848.354558] usb 3-1: have_langid 1, string_langid 1033
[69848.354560] usb 3-1: maxchild 0
[69848.354562] usb 3-1: pipe :c0420780
[69848.354563] usbip_core: usbip_dump_pipe:65: dev(7) ep(4) [IN]
[69848.354565] usbip_core: usbip_dump_pipe:78: BULK
[69848.354568] usb 3-1: status :0
[69848.354570] usb 3-1: transfer_flags :00000204
[69848.354572] usb 3-1: transfer_buffer_length:128
[69848.354573] usb 3-1: actual_length :9
[69848.354575] usb 3-1: start_frame :0
[69848.354577] usb 3-1: number_of_packets :0
[69848.354578] usb 3-1: interval :0
[69848.354580] usb 3-1: error_count :0
[69848.354581] vhci_hcd: vhci_recv_ret_submit:93: now giveback urb 4607013
[69848.354594] vhci_hcd: vhci_recv_ret_submit:101: Leave
[69848.354596] vhci_hcd: vhci_rx_pdu:195: Enter
[69848.354597] usbip_core: usbip_recv:314: enter
[69848.354617] vhci_hcd: vhci_tx_loop:209: pending urbs ?, now wake up
[69848.354619] vhci_hcd: vhci_send_cmd_submit:73: setup txdata urb seqnum 4607031
[69848.354621] vhci_hcd: setup_cmd_submit_pdu:18: URB, local devnum 7, remote devid 4
[69848.354626] vhci_hcd: vhci_send_cmd_submit:116: send txdata
[69848.354679] usbip_core: usbip_recv:328: vhci_rx :
[69848.354681] usbip_core: usbip_recv:332: receiving....
[69848.354685] usbip-core00000000: 000b0000 00010000 ff030000 0098ffff
[69848.354687] usbip-core00000010: 00000000 00000000 00000000 00000000
[69848.354689] usbip-core00000020: 00000000 39000000 62613038 66656463
[69848.354691] usbip_core: usbip_recv:335: received, osize 48 ret 48 size 0 total 48
[69848.354692] usbip_core: usbip_header_correct_endian:515: unknown command
[69848.354702] usbip_core: usbip_dump_header:266: BASE: cmd 2816 seq 256 devid 1023 dir 4294940672 ep 0
[69848.354703] usbip_core: usbip_dump_header:295: unknown command
[69848.354706] vhci_hcd: vhci_rx_pdu:241: unknown pdu 2816
[69848.354710] usbip_core: usbip_dump_header:266: BASE: cmd 2816 seq 256 devid 1023 dir 4294940672 ep 0
[69848.354711] usbip_core: usbip_dump_header:295: unknown command
[69848.354723] usbip_core: event_handler:71: pending event 5
[69848.354727] vhci_hcd: vhci_shutdown_connection:981: shutdown tcp_socket 13
[69848.354818] vhci_hcd: vhci_tx_loop:209: pending urbs ?, now wake up
[69848.354831] vhci_hcd: vhci_shutdown_connection:994: stop threads
[69848.354842] vhci_hcd: vhci_shutdown_connection:1002: release socket
[69848.354846] vhci_hcd: vhci_device_unlink_cleanup:938: unlink cleanup rx 4605180
[69848.354853] vhci_hcd: vhci_device_unlink_cleanup:943: the urb (seqnum 4605180) was already given back
[69848.354858] vhci_hcd: rh_port_disconnect:195: rh_port_disconnect 0
[69848.354862] vhci_hcd: vhci_hub_status:249: port 0 status changed
[69848.354865] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354867] vhci_hcd: vhci_shutdown_connection:1028: disconnect device
[69848.354868] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354871] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354875] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354877] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354878] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354880] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354882] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354884] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354886] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354889] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354892] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354893] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354895] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354897] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354898] vhci_hcd: vhci_urb_dequeue:910: leave
[69848.354903] vhci_hcd: vhci_hub_control:335: typeReq a300 wValue 0 wIndex 1
[69848.354905] vhci_hcd: vhci_hub_control:417: GetPortStatus port 1
[69848.354907] vhci_hcd: vhci_hub_control:472: GetPortStatus bye 102 1
[69848.354909] vhci_hcd: vhci_hub_control:609: port 0
[69848.354910] vhci_hcd: dump_port_status_diff:128: status prev -> new: 00010102 -> 00010102
[69848.354912] vhci_hcd: dump_port_status_diff:142: ENABLE
[69848.354913] vhci_hcd: dump_port_status_diff:142: POWER
[69848.354914] vhci_hcd: dump_port_status_diff:142: C_CONNECTION
[69848.354916] vhci_hcd: dump_port_status_diff:150:
[69848.354917] vhci_hcd: vhci_hub_control:617: bye
[69848.354918] vhci_hcd: vhci_hub_status:249: port 0 status changed
[69848.354937] vhci_hcd: vhci_hub_control:335: typeReq 2301 wValue 10 wIndex 1
[69848.354939] vhci_hcd: vhci_hub_control:384: ClearPortFeature: default 10
[69848.354940] vhci_hcd: vhci_hub_control:609: port 0
[69848.354941] vhci_hcd: dump_port_status_diff:128: status prev -> new: 00010102 -> 00000102
[69848.354943] vhci_hcd: dump_port_status_diff:142: ENABLE
[69848.354944] vhci_hcd: dump_port_status_diff:142: POWER
[69848.354945] vhci_hcd: dump_port_status_diff:142: -C_CONNECTION
[69848.354946] vhci_hcd: dump_port_status_diff:150:
[69848.354948] vhci_hcd: vhci_hub_control:617: bye
[69848.354985] usb 3-1: USB disconnect, device number 7
[69848.396204] FAT-fs (sdb): unable to read boot sector to mark fs as dirty
[69848.449863] vhci_hcd: vhci_hub_control:335: typeReq a300 wValue 0 wIndex 1
[69848.449867] vhci_hcd: vhci_hub_control:417: GetPortStatus port 1
[69848.449869] vhci_hcd: vhci_hub_control:472: GetPortStatus bye 102 0
[69848.449871] vhci_hcd: vhci_hub_control:609: port 0
[69848.449872] vhci_hcd: dump_port_status_diff:128: status prev -> new: 00000102 -> 00000102
[69848.449874] vhci_hcd: dump_port_status_diff:142: ENABLE
[69848.449875] vhci_hcd: dump_port_status_diff:142: POWER
[69848.449877] vhci_hcd: dump_port_status_diff:150:
[69848.449878] vhci_hcd: vhci_hub_control:617: bye
[69848.484222] vhci_hcd: vhci_hub_control:335: typeReq a300 wValue 0 wIndex 1
[69848.484225] vhci_hcd: vhci_hub_control:417: GetPortStatus port 1
[69848.484227] vhci_hcd: vhci_hub_control:472: GetPortStatus bye 102 0
[69848.484229] vhci_hcd: vhci_hub_control:609: port 0
[69848.484230] vhci_hcd: dump_port_status_diff:128: status prev -> new: 00000102 -> 00000102
[69848.484232] vhci_hcd: dump_port_status_diff:142: ENABLE
[69848.484234] vhci_hcd: dump_port_status_diff:142: POWER
[69848.484235] vhci_hcd: dump_port_status_diff:150:
[69848.484236] vhci_hcd: vhci_hub_control:617: bye
[69848.520167] vhci_hcd: vhci_hub_control:335: typeReq a300 wValue 0 wIndex 1
[69848.520171] vhci_hcd: vhci_hub_control:417: GetPortStatus port 1
[69848.520172] vhci_hcd: vhci_hub_control:472: GetPortStatus bye 102 0
[69848.520174] vhci_hcd: vhci_hub_control:609: port 0
[69848.520176] vhci_hcd: dump_port_status_diff:128: status prev -> new: 00000102 -> 00000102
[69848.520178] vhci_hcd: dump_port_status_diff:142: ENABLE
[69848.520179] vhci_hcd: dump_port_status_diff:142: POWER
[69848.520180] vhci_hcd: dump_port_status_diff:150:
[69848.520182] vhci_hcd: vhci_hub_control:617: bye
[69848.556206] vhci_hcd: vhci_hub_control:335: typeReq a300 wValue 0 wIndex 1
[69848.556210] vhci_hcd: vhci_hub_control:417: GetPortStatus port 1
[69848.556212] vhci_hcd: vhci_hub_control:472: GetPortStatus bye 102 0
[69848.556213] vhci_hcd: vhci_hub_control:609: port 0
[69848.556216] vhci_hcd: dump_port_status_diff:128: status prev -> new: 00000102 -> 00000102
[69848.556217] vhci_hcd: dump_port_status_diff:142: ENABLE
[69848.556219] vhci_hcd: dump_port_status_diff:142: POWER
[69848.556220] vhci_hcd: dump_port_status_diff:150:
[69848.556222] vhci_hcd: vhci_hub_control:617: bye
[69848.592249] vhci_hcd: vhci_hub_control:335: typeReq a300 wValue 0 wIndex 1
[69848.592253] vhci_hcd: vhci_hub_control:417: GetPortStatus port 1
[69848.592255] vhci_hcd: vhci_hub_control:472: GetPortStatus bye 102 0
[69848.592256] vhci_hcd: vhci_hub_control:609: port 0
[69848.592258] vhci_hcd: dump_port_status_diff:128: status prev -> new: 00000102 -> 00000102
[69848.592260] vhci_hcd: dump_port_status_diff:142: ENABLE
[69848.592261] vhci_hcd: dump_port_status_diff:142: POWER
[69848.592263] vhci_hcd: dump_port_status_diff:150:
[69848.592264] vhci_hcd: vhci_hub_control:617: bye
[69848.592286] vhci_hcd: vhci_hub_control:335: typeReq 2301 wValue 1 wIndex 1
[69848.592288] vhci_hcd: vhci_hub_control:384: ClearPortFeature: default 1
[69848.592289] vhci_hcd: vhci_hub_control:609: port 0
[69848.592291] vhci_hcd: dump_port_status_diff:128: status prev -> new: 00000102 -> 00000100
[69848.592292] vhci_hcd: dump_port_status_diff:142: -ENABLE
[69848.592293] vhci_hcd: dump_port_status_diff:142: POWER
[69848.592294] vhci_hcd: dump_port_status_diff:150:
[69848.592295] vhci_hcd: vhci_hub_control:617: bye
[69848.592311] vhci_hcd: vhci_hub_control:335: typeReq a300 wValue 0 wIndex 1
[69848.592312] vhci_hcd: vhci_hub_control:417: GetPortStatus port 1
[69848.592314] vhci_hcd: vhci_hub_control:472: GetPortStatus bye 100 0
[69848.592315] vhci_hcd: vhci_hub_control:609: port 0
[69848.592316] vhci_hcd: dump_port_status_diff:128: status prev -> new: 00000100 -> 00000100
[69848.592318] vhci_hcd: dump_port_status_diff:142: POWER
[69848.592319] vhci_hcd: dump_port_status_diff:150:
[69848.592320] vhci_hcd: vhci_hub_control:617: bye
[69848.592345] usb usb3: vhci_bus_suspend

CLIENT VHLOG
09:30:51 INFO :Log Started
09:30:51 INFO :VirtualHere Client 4.5.3 starting (Compiled: Jun 3 2018 14:03:41)
09:30:51 INFO :Using config at /home/raas/clientconfig.ini
09:30:51 INFO :IPC available at /tmp/vhclient
09:35:21 INFO :VirtualHere USB Server Trial Edition (192.168.130.72:7575)
09:36:06 INFO :Warning did not find pending usbip packet sn=4491022 to unlink
09:36:06 INFO :Warning did not find pending usbip packet sn=4491024 to unlink
09:36:06 INFO :Warning did not find pending usbip packet sn=4491025 to unlink
09:36:06 INFO :Warning did not find pending usbip packet sn=4491026 to unlink
09:36:06 INFO :Warning did not find pending usbip packet sn=4491027 to unlink
09:36:06 INFO :Warning did not find pending usbip packet sn=4491028 to unlink

Submitted by Michael on Thu, 2018/06/21 - 01:08

#5

Ok thanks for that, it will take a few days for me to analyze this log, ill post a response early next week...

Submitted by sakorkko on Mon, 2018/06/25 - 15:55

#7

It is actually this one: https://os.mbed.com/platforms/FRDM-K64F/
I am also using another board (Nucleo f429zi) for testing with the same results.

The connection fails after around 30 minutes so it does work for a while. I will try flashing the board without resetting each time next.
I am trying to pinpoint the issue myself as well. As far as I can tell now, it breaks around here (taken above):
[69848.354692] usbip_core: usbip_header_correct_endian:515: unknown command
[69848.354702] usbip_core: usbip_dump_header:266: BASE: cmd 2816 seq 256 devid 1023 dir 4294940672 ep 0
[69848.354703] usbip_core: usbip_dump_header:295: unknown command
[69848.354706] vhci_hcd: vhci_rx_pdu:241: unknown pdu 2816
[69848.354710] usbip_core: usbip_dump_header:266: BASE: cmd 2816 seq 256 devid 1023 dir 4294940672 ep 0
[69848.354711] usbip_core: usbip_dump_header:295: unknown command

So maybe it is still in the kernel side of things. I am not that familiar with the Usbip in Linux yet.

Thank you for the support.

Submitted by Michael on Wed, 2018/06/27 - 19:11

#9

Ok this will be too complicated to fix while im on holidays. Im back in late july. If you find something in the client that shows the issue i will try to fix. otherwise i will revisit this issue (and get one of those DAPLink devices) and i will test then.

Submitted by sakorkko on Thu, 2018/06/28 - 18:42

#10

Okay no problem. I got an update, but I don't want to intrude on your holiday so I can wait. You can read it when you are back.

I found something new when reading usbmon with wireshark and comparing the client and server activity.
There was a URB_COMPLETE packet from the virtual hub on the client side that seems to trigger the issue. It only shows in the client. It comes from the hub interface 1 (3.1.1). Checked with lsusb and there is no interface with the number 1. There was no corresponding URB_SUBMIT packet so it lines up with the dmesg log. The communication ends after that packet. Communication simply stops on the server side.
I attached the weird URB packet, client side packet capture and the hub lsusb -v output for the hub.

packet capture file:
https://drive.google.com/file/d/1fKiMq2rjAr_m3SppOjn7GsooZ6oHnXb3/view
Device is on 3.7.X in the capture.

Weird URB packet
Frame 11861: 66 bytes on wire (528 bits), 66 bytes captured (528 bits) on interface 0
Interface id: 0 (usbmon3)
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Jun 27, 2018 16:42:07.969879000 FLE Summer Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1530106927.969879000 seconds
[Time delta from previous captured frame: 0.000001000 seconds]
[Time delta from previous displayed frame: 0.000001000 seconds]
[Time since reference or first frame: 57.275427000 seconds]
Frame Number: 11861
Frame Length: 66 bytes (528 bits)
Capture Length: 66 bytes (528 bits)
[Frame is marked: True]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
[Source: 3.1.1]
[Destination: host]
URB id: 0xffff954772859000
URB type: URB_COMPLETE ('C')
URB transfer type: URB_INTERRUPT (0x01)
Endpoint: 0x81, Direction: IN
1... .... = Direction: IN (1)
.000 0001 = Endpoint value: 1
Device: 1
URB bus id: 3
Device setup request: not relevant ('-')
Data: present (0)
URB sec: 1530106927
URB usec: 969879
URB status: Success (0)
URB length [bytes]: 2
Data length [bytes]: 2
[bInterfaceClass: Unknown (0xffff)]
Unused Setup Header
Interval: 2048
Start frame: 0
Copy of Transfer Flags: 0x00000200
Number of ISO descriptors: 0
Leftover Capture Data: 0200

lsusb -s 003:001 -v (the virtual hub)
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 9 Hub
bDeviceSubClass 0 Unused
bDeviceProtocol 1 Single TT
bMaxPacketSize0 64
idVendor 0x1d6b Linux Foundation
idProduct 0x0002 2.0 root hub
bcdDevice 4.17
iManufacturer 3 Linux 4.17.2 vhci_hcd
iProduct 2 USB/IP Virtual Host Controller
iSerial 1 vhci_hcd.0
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 25
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xe0
Self Powered
Remote Wakeup
MaxPower 0mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 9 Hub
bInterfaceSubClass 0 Unused
bInterfaceProtocol 0 Full speed (or root) hub
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0004 1x 4 bytes
bInterval 12
Hub Descriptor:
bLength 11
bDescriptorType 41
nNbrPorts 8
wHubCharacteristic 0x0001
Per-port power switching
Ganged overcurrent protection
TT think time 8 FS bits
bPwrOn2PwrGood 0 * 2 milli seconds
bHubContrCurrent 0 milli Ampere
DeviceRemovable 0x00 0x00
PortPwrCtrlMask 0xff 0xff
Hub Port Status:
Port 1: 0000.0100 power
Port 2: 0000.0100 power
Port 3: 0000.0100 power
Port 4: 0000.0100 power
Port 5: 0000.0100 power
Port 6: 0000.0100 power
Port 7: 0000.0100 power
Port 8: 0000.0100 power
Device Status: 0x0001
Self Powered

Submitted by Michael on Wed, 2018/08/15 - 17:47

#11

Ive got this device now so i can do some testing over the next week to find the issue...

Submitted by Michael on Fri, 2018/08/17 - 20:31

#12

This is fixed in client 4.5.7

Submitted by sakorkko on Mon, 2018/08/20 - 16:05

#13

Okay, I will try again this week with the newer version.

Submitted by sakorkko on Fri, 2018/08/24 - 21:41

#14

Okay, after some testing seems that this issue is fixed.

Thank you for the support!

Submitted by Michael on Fri, 2018/08/24 - 23:36

#15

OK great, yes there was a race condition that i fixed in the linux client