Client permanently hangs when tunneling USB sound devices

Client permanently hangs when tunneling USB sound devices with raspberry pi as server. This is a first-time occurrance: It was recently attempted and is failing from the start, rather than having worked in the past and failing recently.

Devices which produce failure:
FUNCubeDongle Pro+ (2 sound and 1 HID subdevice)
UAC 3556B sound dongle

Devices confirmed to work:
Generic USB flash drive

Steps to produce:
Server:
Attach device to rPI
sudo ./vhusbdpin
Client:
sudo ./vhui64
Raspberry hub -> FUNCubeDongle [or UAC2556B] -> Use
5 seconds pass
Client screen freezes, unresponsive.

Client:
PC 3.13.0-30-generic #54-Ubuntu SMP Mon Jun 9 22:45:01 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
VirtualHere v2.3.6

Server:
RaspberryPI 3.12.23+ #692 PREEMPT Thu Jun 26 20:15:50 BST 2014 armv6l
vhusbdpin v1.8.4

$ sudo rpi-update
*** Raspberry Pi firmware updater by Hexxeh, enhanced by AndrewS and Dom
*** Performing self-update
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 135 100 135 0 0 203 0 --:--:-- --:--:-- --:--:-- 302
100 7026 100 7026 0 0 4521 0 0:00:01 0:00:01 --:--:-- 48791
*** Relaunching after update
*** Raspberry Pi firmware updater by Hexxeh, enhanced by AndrewS and Dom
*** Your firmware is already up to date

Interestingly, these devices will tunnel successfully with client and server being a PC or laptop running ubuntu 14.04. I have also been able to use the rPI as a client for an xbox controller as a test. (jstest) Using usbip isntead of virtualhere results in no errors (binds to port 0) but device doesn't show up in lsusb. Concerned with bandwidth issues on the rPI's root bus, I calculated the FUNCube's bandwidth (pre-overhead) to be ~5.8Mbps.

#2

Interestingly, these devices will tunnel successfully with client and server being a PC or laptop running ubuntu 14.04.

That basically tells me that the pi is not powerful enough to stream your particular audio stream. Could you try putting the pi on turbo mode using raspi-config

#3

Going further on your lead, more observations:

Set rPI to turbo OC.
Started rPI server w/ usb keyboard and screen attached with -d & switch active.
Once the server started all keyboard input was ignored on server(rPI).
Power-cycle rPI. Ran `vhusbdpin -d & top` and top displayed and updated on regular intervals but still no response to keyboard. Connected to rPI with VH client, client PC ran a bit longer this time; was able to find tunneled device in lsusb and alsamixer but client PC hanged once trying to actually talk to the HID component of FUNCube. Didn't get to trying to talk to the sound device yet- it's a narrow window to test as much as possible before the client freezes. During the whole event, top registered peak CPU usage of about 5% on rPI.

#4

Another update: Though rPI no longer reads the keyboard when vhusbdpin starts, I am able to tunnel said keyboard and use it.

#5

Suspected underpowered USB on rPI, put FCDPP behind powered hub. No change.
Built and installed libusb and libhid on rPI. No change.
Using fcdctl was able to verify that the rPI can properly communicate with the FCDPP.
It appears the client-end hanging is initialized from any attempt to communicate with FCDPP. Turning off pulseaudio kept it from grabbing the FCDPP's sound devices which saved the client from hanging immediately, however using QTHID (sends simple HID commands to FCDPP without involving the sound portions) instantly hanged the machine.
Suspected buggy firmware in FCDPP perhaps breaking USB spec and tripping up VH, however no publicly-available firmware upgdate is known for FCDPP.
When USB device initializes, does it request a specific amount of bandwidth and then HV/usbip sets up a stream at that bandwidth, even if nothing is being sent over the stream at the moment? Could this then cause the overload even if simple HID command blocks are being sent or read?

#6

Thanks for the detailed feedback. The reason the keyboard becomes disabled is because it is being taken by the usb server. You should turn on AutoAttachToKernel ( https://www.virtualhere.com/configuration_faq ) that will keep it bound to the raspbian kernel if its not in use.

Regarding the locking, virtualhere does not use synchronous calls to usbip in linux. Everything is async. Could you check the /var/log/syslog.log file. That will show any issues with usbip.

Also dont use the -d flag because that is for debugging and will slow down the server. Use the -b for background.

The bandwidth requests are granted and ignored in virtualhere as it doesnt allocate bandwidth specifically. Its a best effort basis for Isochronous which means frame number etc are simulated rather than exact. however this is ok for almost all devices..

#7

Client:
Jul 3 10:55:49 client kernel: [158226.913266] vhci_hcd vhci_hcd: rhport(0) sockfd(16) devid(112) speed(2)
Jul 3 10:55:49 client kernel: [158226.913402] vhci_hcd: changed 1
Jul 3 10:55:49 client kernel: [158227.018885] vhci_hcd: changed 0
Jul 3 10:55:49 client kernel: [158227.126994] usb 8-1: new full-speed USB device number 2 using vhci_hcd
Jul 3 10:55:49 client kernel: [158227.239019] usb 8-1: SetAddress Request (2) to port 0
Jul 3 10:55:49 client kernel: [158227.270119] usb 8-1: New USB device found, idVendor=04d8, idProduct=fb31
Jul 3 10:55:49 client kernel: [158227.270130] usb 8-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Jul 3 10:55:49 client kernel: [158227.270137] usb 8-1: Product: FUNcube Dongle V2.0
Jul 3 10:55:49 client kernel: [158227.270143] usb 8-1: Manufacturer: Hanlincrest Ltd.
Jul 3 10:55:49 client kernel: [158227.279313] hid-generic 0003:04D8:FB31.0002: hiddev0,hidraw1: USB HID v1.11 Device [Hanlincrest Ltd. FUNcube Dongle V2.0 ] on usb-vhci_hcd-1/input2
Jul 3 10:55:50 client kernel: [158228.214599] 2:1:1: cannot get freq at ep 0x81
Jul 3 10:55:50 client kernel: [158228.218014] usbcore: registered new interface driver snd-usb-audio
Jul 3 10:55:51 client kernel: [158228.901674] 2:1:1: cannot get freq at ep 0x81
Jul 3 10:55:51 client kernel: [158228.939030] 2:1:1: cannot get freq at ep 0x81
Jul 3 10:55:51 client kernel: [158229.048338] 2:1:1: cannot get freq at ep 0x81
Jul 3 10:55:51 client kernel: [158229.085695] 2:1:1: cannot get freq at ep 0x81
Jul 3 10:55:51 client kernel: [158229.096452] vhci_hcd: Not yet implemented
Jul 3 10:55:51 client kernel: [158229.098122] usb 8-1: total length of iso packets 360 not equal to actual length of buffer 0
Jul 3 10:55:51 client kernel: [158229.098221] vhci_hcd: stop threads
Jul 3 10:55:51 client kernel: [158229.098232] vhci_hcd: release socket
Jul 3 10:55:51 client kernel: [158229.098238] vhci_hcd: changed 1
Jul 3 10:55:51 client kernel: [158229.098247] vhci_hcd: disconnect device
Jul 3 10:55:51 client kernel: [158229.098346] usb 8-1: USB disconnect, device number 2
Jul 3 10:55:51 client kernel: [158229.099210] vhci_hcd: dequeue a urb ffff8800b5d1db00
Jul 3 10:55:51 client kernel: [158229.099219] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099223] vhci_hcd: gives back urb ffff8800b5d1db00
Jul 3 10:55:51 client kernel: [158229.099230] vhci_hcd: dequeue a urb ffff8800b5d1de00
Jul 3 10:55:51 client kernel: [158229.099234] vhci_hcd: dequeue a urb ffff8800b5d1d600
Jul 3 10:55:51 client kernel: [158229.099238] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099242] vhci_hcd: gives back urb ffff8800b5d1d600
Jul 3 10:55:51 client kernel: [158229.099246] vhci_hcd: dequeue a urb ffff8800b5d1dc00
Jul 3 10:55:51 client kernel: [158229.099250] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099254] vhci_hcd: gives back urb ffff8800b5d1dc00
Jul 3 10:55:51 client kernel: [158229.099258] vhci_hcd: dequeue a urb ffff8800b5d1d200
Jul 3 10:55:51 client kernel: [158229.099261] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099265] vhci_hcd: gives back urb ffff8800b5d1d200
Jul 3 10:55:51 client kernel: [158229.099269] vhci_hcd: dequeue a urb ffff8800b5d1da00
Jul 3 10:55:51 client kernel: [158229.099273] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099276] vhci_hcd: gives back urb ffff8800b5d1da00
Jul 3 10:55:51 client kernel: [158229.099281] vhci_hcd: dequeue a urb ffff8800b5d1d800
Jul 3 10:55:51 client kernel: [158229.099285] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099288] vhci_hcd: gives back urb ffff8800b5d1d800
Jul 3 10:55:51 client kernel: [158229.099292] vhci_hcd: dequeue a urb ffff8800b5d1d000
Jul 3 10:55:51 client kernel: [158229.099296] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099335] vhci_hcd: gives back urb ffff8800b5d1d000
Jul 3 10:55:51 client kernel: [158229.099340] vhci_hcd: dequeue a urb ffff8800b60afb00
Jul 3 10:55:51 client kernel: [158229.099344] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099347] vhci_hcd: gives back urb ffff8800b60afb00
Jul 3 10:55:51 client kernel: [158229.099352] vhci_hcd: dequeue a urb ffff8800af266c00
Jul 3 10:55:51 client kernel: [158229.099355] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099359] vhci_hcd: gives back urb ffff8800af266c00
Jul 3 10:55:51 client kernel: [158229.099363] vhci_hcd: dequeue a urb ffff8800af266b00
Jul 3 10:55:51 client kernel: [158229.099366] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099370] vhci_hcd: gives back urb ffff8800af266b00
Jul 3 10:55:51 client kernel: [158229.099374] vhci_hcd: dequeue a urb ffff8800af266200
Jul 3 10:55:51 client kernel: [158229.099378] vhci_hcd: device ffff88012faa4268 seems to be disconnected
Jul 3 10:55:51 client kernel: [158229.099381] vhci_hcd: gives back urb ffff8800af266200

Server:
$ tail /var/log/syslog
Jul 3 10:54:10 raspberrypi vhusbdpin: TCPServer (7575) started
Jul 3 10:54:10 raspberrypi vhusbdpin: Cannot open usb serial number file, No such file or directory
Jul 3 10:54:10 raspberrypi vhusbdpin: Found Full speed device [04d8:fb31] "Hanlincrest Ltd., FUNcube Dongle V2.0 " at address 112,
Jul 3 10:54:11 raspberrypi vhusbdpin: Successfully advertised service 'VirtualHere USB Sharing' over dns-sd (Bonjour/avahi)
Jul 3 10:55:39 raspberrypi vhusbdpin: 192.168.1.208 connected
Jul 3 10:55:49 raspberrypi kernel: [ 333.665457] usb 1-1.2: reset full-speed USB device number 4 using dwc_otg
Jul 3 10:55:49 raspberrypi vhusbdpin: Device 112 BOUND to connection 1
Jul 3 10:56:58 raspberrypi vhusbdpin: Removing connection 1 (timeout)...
Jul 3 10:56:58 raspberrypi vhusbdpin: Device 112 UNBOUND from connection 1
Jul 3 10:57:01 raspberrypi vhusbdpin: Connection 1 successfully removed

#8

Looking further into the vhci: Not yet implemented notice, source code at
http://lxr.free-electrons.com/source/drivers/staging/usbip/vhci_hcd.c
... shows at line 927 the error message from the function vhci_get_frame_number(...)
Things seem to fall apart after that point.
Perhaps this is linked with the synthetic frame number mentioned in your earlier message?
The `cannot get freq at ep 0x81` error can be disregarded; this occurs on properly functioning system as well without problems when using FCDPP.

#9

I think the "cannot get frame number" error is ok because it still works when the server is a pc. (I suspect that it is ignoring the frame number anyway even though it is asking for it.) My guess from the info you have given is that the usbip submits an isochronous packet to the linux broadcom hub driver and that is actually where the bug is and it locks on that submit....The desktop usb hub driver is pretty robust as its very mature...Its a bit like the webcam issue. For quite a while virtualhere whould not work with webcams on raspbian. Recently they fixed something in the broadcom usb hub driver and that fixed the issue. Perhaps they will fix something in the broadcom hub driver for this and it will work...

#10

ok thank you

#11

The news coming in points at a problem in the Raspberry Pi's USB stack. It also refers to the Isochronous throughput limits as mentioned by Michael.
Developer of the FUNCube Dongle Pro+ has created degradative workarounds for the FCDPP on the raspberry pi.
http://www.funcubedongle.com/?p=1647

The issue demonstrated by Howard appears likely cause of VirtualHere crashes in this scenario.

#12

This is an update in reproducing this problem after switching to the BeagleBone Black.
SUMMARY: There seem to be two problems with piping a FCDPP's USB identity over network.

One has to do the client-side kernel panic after prolonged use. This happens with both
VirtualHere and USBIP 1.1.1. Using client kernel 4.0.1 increases the time before a panic but does not
eliminate it. This effect is sharply hastened if the client is in a VM. It smells like one or
more bugs in linux lernel combined with insufficient sanity checking and a possible race condition.

The other is severe choppiness occuring in the USB audio device while it is streaming.
Thermal and power issues have been ruled out. Clocking up worsens the situation.
This may be a BeagleBoneBlack problem and will be hard to prove.

Before new kernel:
Beaglebone: Linux beaglebone 3.8.13-bone70 #1 SMP Fri Jan 23 02:15:42 UTC 2015 armv7l GNU/Linux
Client: Linux krogoth 3.13.0-49-generic #83-Ubuntu SMP Fri Apr 10 20:11:33 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
Tested with usbip 1.1.1 on both ends (compiled from kernel source), still freezes after a few min.
Tested on ubuntu 14.04 live DVD as client, issue persists.
Update client kernel to mainline 4.0
... issue persists
Attempt using usbip 1.1.1 on both ends
... issue persists
BBB test image: http://software-dl.ti.com/sitara_linux/esd/processor-sdk/PROCESSOR-SDK-…
Switched BBB server to the am335x image you linked:
Linux am335x-evm 3.14.26-g2489c02 #1 Fri Apr 10 14:59:04 EDT 2015 armv7l GNU/Linux
... am335x image cannot detect FCDPP when it is behind an external hub, Hub is a VIA "USB 2.0Hub" ID# 2109:2811 which offers 5Gb transfer, packaged as a 4-port Amazon Basics USB3 Hub.
Directly-connecting FCDPP to BeagleBone USB port...
***Occasional hiccups, no kernel panic yet***
Ran fine for about 20 min, audio suddenly chops severely and persistently.
When severe choppiness kicks in, vhusbdarmhf system usage spikes from 40% steady to 90% steady
and system responsiveness becomes very poor. Stopping audio stream and restarting
sometimes fixes, sometimes not. Worse when clock is *increased*.
echo performance > /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
... issue persists.
Choppiness now occur immediately on attempts.
Reboot server
.... issue persists
"The was an error sharing this device" "Operation not permitted"
Re-attempt, no error.
Reboot server
.... issue persists
Suspect bad state of client or network. Reboot client.
.... issue persists
Disconnected BBB server, perform traceroute to previously-used IP to clear switches
.... runs fine for 10sec then back to severe hiccups.
Keep all FDCPP-using software closed until dongle connects over VH
.... issue persists
traceroute shows sane hops both ways.
Unplug-replug client ethernet
.... issue persists
Close HID program and run audio portion alone
.... issue persists
Restart vhusbdarmhf on server
.... issue persists
Set source and sink in GRC to "ok to block"
.... issue persists
Remove client and server from network and connect directly with a linksys NAT
"There was an error sharing this device." "Operation not permitted (-1)"
Retry, use, no error.
Get unexpected message "Connecting to USB Hub" while already connected.
....Restart vhuip64, still get message.
Unplug, replug FCDPP
....Issue persists on 1-on-1 network.
No new server dmesg lines when hiccup kicks in.
Server: rm config.ini, restart vhusbdarmhf
....issue persists.
Back to normal network setup
echo userspace > /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
Experiment with different speed settings, chppiness seem to fix turning speed down to lowest setting.
echo 300000 > /sys/devices/system/cpu/cpu0/cpufreq/scaling_setspeed
...thermal issue? Optic probe measured 40C normal, 45C hiccuping. Pretty low.
When the audio chops the ssh connection slows severely as well.
Used the following to reduce load-based hiccuping but does not reduce the clock-based hiccuping:
nice -n -10 ./vhusbdarmhf
Suspect under-powered at higher clock
Switch to 1A 5V barrel power supply
.... issue persists
Attempt boot in angstrom with FCDPP directly connected instead of hub.
.... issue persists
Switch to 3A 5V barrel power supply
.... issue persists
Attempted fresh install w/ Ubuntu 14.04 VirtualBox
.... issue persists
Upgraded client VM to 15.04 (kernel 3.19-0)
.... issue persists
Upgrade client VM kernel to 4.0.1
.... issue persists. ssh pipe connection to BBB mysteriously closed.
Client switching to 14.04 machine...
Suspect audio or HID conflict
Server (Am335x) blacklist modules snd_usb_audio, usbhid, hid
.... still have choppiness, no panic yet.

#13

Wow you have been doing some serious testing 7cuShmid3! Im not sure i can add anything useful to this list as i still suspect a bug or something is in the kernel. Can you try the client in windows? Regarding the panic if possible could you run this http://packages.ubuntu.com/search?keywords=linux-crashdump on your linux system.

I dont have the resources to debug the linux kernel, however it may provide an insight into where exactly the panic is occuring At least it might point to which part of the usb stack, either in core or in the OMAP usb driver glue..