Device is "in use" but unable to use.

Hi Michael,

Been using virtualhere for awhile and it's been great, but between now and 2 weeks ago, the device/server/client hasn't been working well.
Some issues:
1) Unable to see android hub.
1a) Used reverse connection or specify hubs as a workaround and....
2) Can connect and device in use, but connection seems spotty. (This was with via android hotspot)
3) When using home network with internet, client is able to see, identify, and "use" device, but was unable to actually use the device.

Not sure if it is an OS issue, but I've tested with Nexus 5 and 6p as well as Win 10 and 8.1
Below is the system message for android usb server. (Near the bottom I tried plugging and replugging a few times)

Thanks for the support

--------- beginning of main
08-12 16:28:05.905 21926 21926 W System : ClassLoader referenced unknown path: /data/app/com.virtualhere.androidserver-1/lib/arm
08-12 16:28:05.994 21926 21939 D OpenGLRenderer: Use EGL_SWAP_BEHAVIOR_PRESERVED: true
08-12 16:28:06.047 21926 21939 I Adreno-EGL: : EGL 1.4 QUALCOMM build: Nondeterministic_AU_msm8974_LA.BF.1.1.3_RB1__release_AU (Ia6c73e7530)
08-12 16:28:06.047 21926 21939 I Adreno-EGL: OpenGL ES Shader Compiler Version: E031.29.00.00
08-12 16:28:06.047 21926 21939 I Adreno-EGL: Build Date: 12/04/15 Fri
08-12 16:28:06.047 21926 21939 I Adreno-EGL: Local Branch: mybranch17080070
08-12 16:28:06.047 21926 21939 I Adreno-EGL: Remote Branch: quic/LA.BF.1.1.3_rb1.5
08-12 16:28:06.047 21926 21939 I Adreno-EGL: Local Patches: NONE
08-12 16:28:06.047 21926 21939 I Adreno-EGL: Reconstruct Branch: NOTHING
08-12 16:28:06.054 21926 21939 I OpenGLRenderer: Initialized EGL, version 1.4
08-12 16:28:06.136 21926 21926 E vhusbd-service: Opening local exception: Connection refused
08-12 16:28:06.179 21926 21948 I vhusbd : Fri Aug 12 23:28:06 2016 LOG_INFO >>> Starting VirtualHere USB Server v2.9.8 (Built: Jul 15 2016, 13:54:35)<<<
08-12 16:28:06.179 21926 21948 I vhusbd : Fri Aug 12 23:28:06 2016 LOG_INFO Using configuration /data/data/com.virtualhere.androidserver/config.ini
08-12 16:28:06.195 21926 21948 I vhusbd : Fri Aug 12 23:28:06 2016 LOG_INFO Server licensed to=unlicensed max_devices=1
08-12 16:28:06.195 21926 21948 I vhusbd : Fri Aug 12 23:28:06 2016 LOG_INFO Using large URB's
08-12 16:28:06.195 21926 21948 I vhusbd : Fri Aug 12 23:28:06 2016 LOG_DEBUG TCPServer starting...
08-12 16:28:06.195 21926 21948 I vhusbd : Fri Aug 12 23:28:06 2016 LOG_INFO Listening on all network interfaces at port 7575
08-12 16:28:06.195 21926 21948 I vhusbd : VirtualHere USB Server is running...press CTRL-C to stop
08-12 16:28:19.865 21926 21926 I ListPopupWindow: Could not find method setEpicenterBounds(Rect) on PopupWindow. Oh well.
08-12 16:28:34.141 21926 21948 I vhusbd : Fri Aug 12 23:28:34 2016 LOG_DEBUG 192.168.1.11 connected
08-12 16:28:57.004 21926 21948 I vhusbd : Fri Aug 12 23:28:57 2016 LOG_DEBUG Not a device .
08-12 16:28:57.004 21926 21948 I vhusbd : Fri Aug 12 23:28:57 2016 LOG_DEBUG Not a device ..
08-12 16:28:57.005 21926 21948 I vhusbd : Fri Aug 12 23:28:57 2016 LOG_DEBUG Found /dev/bus/usb/001/002 in /sys/bus/usb/devices/1-1 (bus/usb/001/002)
08-12 16:28:57.006 21953 21953 W vhusbdan: type=1400 audit(0.0:214): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:28:57.006 21953 21953 W vhusbdan: type=1400 audit(0.0:215): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:28:57.010 21926 21948 I vhusbd : Fri Aug 12 23:28:57 2016 LOG_ERR Error 1 creating device node at /data/data/com.virtualhere.androidserver/bus_usb_001_001, Operation not permitted
08-12 16:28:57.010 21926 21948 I vhusbd : Fri Aug 12 23:28:57 2016 LOG_WARNING Warning, some features may not be available, error 22 making parent hub node at (null), Invalid argument
08-12 16:28:57.011 21926 21948 I vhusbd : Fri Aug 12 23:28:57 2016 LOG_WARNING Warning, error 2 opening the hub ((null)) file descriptor some functionality may not be available, No such file or directory
08-12 16:28:57.011 21926 21948 I vhusbd : Fri Aug 12 23:28:57 2016 LOG_INFO Found Low speed device [04d8:004f] "Ambu, Smart Baby" at address 11
08-12 16:28:57.758 21926 21948 I vhusbd : Fri Aug 12 23:28:57 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:29:17.194 21926 21948 I vhusbd : Fri Aug 12 23:29:17 2016 LOG_INFO Device 11 [04d8:004f] SURPRISE UNBOUND from connection 1
08-12 16:29:17.194 21926 21948 I vhusbd : Fri Aug 12 23:29:17 2016 LOG_INFO Unmanaging device 11 [04d8:004f]
08-12 16:29:17.784 21926 22019 D UsbDeviceConnectionJNI: close
08-12 16:29:25.333 21953 21953 W vhusbdan: type=1400 audit(0.0:216): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:29:25.336 21953 21953 W vhusbdan: type=1400 audit(0.0:217): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:29:25.338 21926 21948 I vhusbd : Fri Aug 12 23:29:25 2016 LOG_DEBUG Not a device .
08-12 16:29:25.338 21926 21948 I vhusbd : Fri Aug 12 23:29:25 2016 LOG_DEBUG Not a device ..
08-12 16:29:25.338 21926 21948 I vhusbd : Fri Aug 12 23:29:25 2016 LOG_DEBUG Found /dev/bus/usb/001/003 in /sys/bus/usb/devices/1-1 (bus/usb/001/003)
08-12 16:29:25.340 21926 21948 I vhusbd : Fri Aug 12 23:29:25 2016 LOG_ERR Error 1 creating device node at /data/data/com.virtualhere.androidserver/bus_usb_001_001, Operation not permitted
08-12 16:29:25.340 21926 21948 I vhusbd : Fri Aug 12 23:29:25 2016 LOG_WARNING Warning, some features may not be available, error 22 making parent hub node at (null), Invalid argument
08-12 16:29:25.340 21926 21948 I vhusbd : Fri Aug 12 23:29:25 2016 LOG_WARNING Warning, error 2 opening the hub ((null)) file descriptor some functionality may not be available, No such file or directory
08-12 16:29:25.341 21926 21948 I vhusbd : Fri Aug 12 23:29:25 2016 LOG_INFO Found Low speed device [04d8:004f] "Ambu, Smart Baby" at address 11
08-12 16:29:25.642 21926 21948 I vhusbd : Fri Aug 12 23:29:25 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:29:28.406 21926 21948 I vhusbd : Fri Aug 12 23:29:28 2016 LOG_INFO Device 11 [04d8:004f] UNBOUND from connection 1
08-12 16:29:29.210 21926 21948 I vhusbd : Fri Aug 12 23:29:29 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:29:46.020 21926 21948 I vhusbd : Fri Aug 12 23:29:46 2016 LOG_INFO Device 11 [04d8:004f] UNBOUND from connection 1
08-12 16:29:47.952 21926 21948 I vhusbd : Fri Aug 12 23:29:47 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:29:51.940 21926 21948 I vhusbd : Fri Aug 12 23:29:51 2016 LOG_INFO Device 11 [04d8:004f] UNBOUND from connection 1
08-12 16:29:53.981 21926 21948 I vhusbd : Fri Aug 12 23:29:53 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:30:19.617 21926 21948 I vhusbd : Fri Aug 12 23:30:19 2016 LOG_INFO Device 11 [04d8:004f] UNBOUND from connection 1
08-12 16:30:21.006 21926 21948 I vhusbd : Fri Aug 12 23:30:21 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:30:42.165 21926 21948 I vhusbd : Fri Aug 12 23:30:42 2016 LOG_INFO Device 11 [04d8:004f] SURPRISE UNBOUND from connection 1
08-12 16:30:42.168 21926 21948 I vhusbd : Fri Aug 12 23:30:42 2016 LOG_INFO Unmanaging device 11 [04d8:004f]
08-12 16:30:42.751 21926 21941 D UsbDeviceConnectionJNI: close
08-12 16:30:45.476 21953 21953 W vhusbdan: type=1400 audit(0.0:218): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:30:45.476 21953 21953 W vhusbdan: type=1400 audit(0.0:219): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:30:45.479 21926 21948 I vhusbd : Fri Aug 12 23:30:45 2016 LOG_DEBUG Not a device .
08-12 16:30:45.480 21926 21948 I vhusbd : Fri Aug 12 23:30:45 2016 LOG_DEBUG Not a device ..
08-12 16:30:45.480 21926 21948 I vhusbd : Fri Aug 12 23:30:45 2016 LOG_DEBUG Found /dev/bus/usb/001/004 in /sys/bus/usb/devices/1-1 (bus/usb/001/004)
08-12 16:30:45.481 21926 21948 I vhusbd : Fri Aug 12 23:30:45 2016 LOG_ERR Error 1 creating device node at /data/data/com.virtualhere.androidserver/bus_usb_001_001, Operation not permitted
08-12 16:30:45.481 21926 21948 I vhusbd : Fri Aug 12 23:30:45 2016 LOG_WARNING Warning, some features may not be available, error 22 making parent hub node at (null), Invalid argument
08-12 16:30:45.481 21926 21948 I vhusbd : Fri Aug 12 23:30:45 2016 LOG_WARNING Warning, error 2 opening the hub ((null)) file descriptor some functionality may not be available, No such file or directory
08-12 16:30:45.483 21926 21948 I vhusbd : Fri Aug 12 23:30:45 2016 LOG_INFO Found Low speed device [04d8:004f] "Ambu, Smart Baby" at address 11
08-12 16:30:52.870 21926 21948 I vhusbd : Fri Aug 12 23:30:52 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:31:24.118 21926 21948 I vhusbd : Fri Aug 12 23:31:24 2016 LOG_INFO Device 11 [04d8:004f] UNBOUND from connection 1
08-12 16:31:26.041 21926 21948 I vhusbd : Fri Aug 12 23:31:26 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:31:31.288 21926 21948 I vhusbd : Fri Aug 12 23:31:31 2016 LOG_INFO Device 11 [04d8:004f] UNBOUND from connection 1
08-12 16:31:33.623 21926 21948 I vhusbd : Fri Aug 12 23:31:33 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:31:39.656 21926 21948 I vhusbd : Fri Aug 12 23:31:39 2016 LOG_INFO Device 11 [04d8:004f] SURPRISE UNBOUND from connection 1
08-12 16:31:39.657 21926 21948 I vhusbd : Fri Aug 12 23:31:39 2016 LOG_INFO Unmanaging device 11 [04d8:004f]
08-12 16:31:40.213 21926 22002 D UsbDeviceConnectionJNI: close
08-12 16:31:46.033 21953 21953 W vhusbdan: type=1400 audit(0.0:220): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:31:46.033 21953 21953 W vhusbdan: type=1400 audit(0.0:221): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:31:46.035 21926 21948 I vhusbd : Fri Aug 12 23:31:46 2016 LOG_DEBUG Not a device .
08-12 16:31:46.035 21926 21948 I vhusbd : Fri Aug 12 23:31:46 2016 LOG_DEBUG Not a device ..
08-12 16:31:46.036 21926 21948 I vhusbd : Fri Aug 12 23:31:46 2016 LOG_DEBUG Found /dev/bus/usb/001/005 in /sys/bus/usb/devices/1-1 (bus/usb/001/005)
08-12 16:31:46.037 21926 21948 I vhusbd : Fri Aug 12 23:31:46 2016 LOG_ERR Error 1 creating device node at /data/data/com.virtualhere.androidserver/bus_usb_001_001, Operation not permitted
08-12 16:31:46.037 21926 21948 I vhusbd : Fri Aug 12 23:31:46 2016 LOG_WARNING Warning, some features may not be available, error 22 making parent hub node at (null), Invalid argument
08-12 16:31:46.038 21926 21948 I vhusbd : Fri Aug 12 23:31:46 2016 LOG_WARNING Warning, error 2 opening the hub ((null)) file descriptor some functionality may not be available, No such file or directory
08-12 16:31:46.039 21926 21948 I vhusbd : Fri Aug 12 23:31:46 2016 LOG_INFO Found Low speed device [04d8:004f] "Ambu, Smart Baby" at address 11
08-12 16:31:49.268 21926 21948 I vhusbd : Fri Aug 12 23:31:49 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:32:19.533 21926 21939 D OpenGLRenderer: endAllStagingAnimators on 0xb3858f00 (cq) with handle 0x9ec7db60
08-12 16:32:46.373 21926 21948 I vhusbd : Fri Aug 12 23:32:46 2016 LOG_INFO Device 11 [04d8:004f] SURPRISE UNBOUND from connection 1
08-12 16:32:46.373 21926 21948 I vhusbd : Fri Aug 12 23:32:46 2016 LOG_INFO Unmanaging device 11 [04d8:004f]
08-12 16:32:46.957 21926 22029 D UsbDeviceConnectionJNI: close
08-12 16:32:49.866 21953 21953 W vhusbdan: type=1400 audit(0.0:222): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:32:49.866 21953 21953 W vhusbdan: type=1400 audit(0.0:223): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:32:49.871 21926 21948 I vhusbd : Fri Aug 12 23:32:49 2016 LOG_DEBUG Not a device .
08-12 16:32:49.871 21926 21948 I vhusbd : Fri Aug 12 23:32:49 2016 LOG_DEBUG Not a device ..
08-12 16:32:49.871 21926 21948 I vhusbd : Fri Aug 12 23:32:49 2016 LOG_DEBUG Found /dev/bus/usb/001/006 in /sys/bus/usb/devices/1-1 (bus/usb/001/006)
08-12 16:32:49.874 21926 21948 I vhusbd : Fri Aug 12 23:32:49 2016 LOG_ERR Error 1 creating device node at /data/data/com.virtualhere.androidserver/bus_usb_001_001, Operation not permitted
08-12 16:32:49.874 21926 21948 I vhusbd : Fri Aug 12 23:32:49 2016 LOG_WARNING Warning, some features may not be available, error 22 making parent hub node at (null), Invalid argument
08-12 16:32:49.875 21926 21948 I vhusbd : Fri Aug 12 23:32:49 2016 LOG_WARNING Warning, error 2 opening the hub ((null)) file descriptor some functionality may not be available, No such file or directory
08-12 16:32:49.875 21926 21948 I vhusbd : Fri Aug 12 23:32:49 2016 LOG_INFO Found Low speed device [04d8:004f] "Ambu, Smart Baby" at address 11
08-12 16:32:54.708 21926 21939 D OpenGLRenderer: endAllStagingAnimators on 0xa9ce2880 (cq) with handle 0x9ec7db70
08-12 16:33:20.821 21926 21948 I vhusbd : Fri Aug 12 23:33:20 2016 LOG_INFO Unmanaging device 11 [04d8:004f]
08-12 16:33:21.387 21926 21958 D UsbDeviceConnectionJNI: close
08-12 16:34:05.559 21926 21948 I vhusbd : Fri Aug 12 23:34:05 2016 LOG_DEBUG Not a device .
08-12 16:34:05.566 21953 21953 W vhusbdan: type=1400 audit(0.0:224): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:34:05.566 21953 21953 W vhusbdan: type=1400 audit(0.0:225): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:34:05.569 21926 21948 I vhusbd : Fri Aug 12 23:34:05 2016 LOG_DEBUG Not a device ..
08-12 16:34:05.569 21926 21948 I vhusbd : Fri Aug 12 23:34:05 2016 LOG_DEBUG Found /dev/bus/usb/001/007 in /sys/bus/usb/devices/1-1 (bus/usb/001/007)
08-12 16:34:05.570 21926 21948 I vhusbd : Fri Aug 12 23:34:05 2016 LOG_ERR Error 1 creating device node at /data/data/com.virtualhere.androidserver/bus_usb_001_001, Operation not permitted
08-12 16:34:05.571 21926 21948 I vhusbd : Fri Aug 12 23:34:05 2016 LOG_WARNING Warning, some features may not be available, error 22 making parent hub node at (null), Invalid argument
08-12 16:34:05.571 21926 21948 I vhusbd : Fri Aug 12 23:34:05 2016 LOG_WARNING Warning, error 2 opening the hub ((null)) file descriptor some functionality may not be available, No such file or directory
08-12 16:34:05.572 21926 21948 I vhusbd : Fri Aug 12 23:34:05 2016 LOG_INFO Found Low speed device [04d8:004f] "Ambu, Smart Baby" at address 11
08-12 16:34:08.183 21926 21939 D OpenGLRenderer: endAllStagingAnimators on 0x9ca25680 (cq) with handle 0x9ec7d8a0
08-12 16:34:09.995 21926 21948 I vhusbd : Fri Aug 12 23:34:09 2016 LOG_INFO Device 11 [04d8:004f] BOUND to connection 1
08-12 16:34:12.764 21926 21939 D OpenGLRenderer: endAllStagingAnimators on 0x9caa1100 (cq) with handle 0x9ec7da20
08-12 16:34:25.134 21926 21926 W InputEventReceiver: Attempted to finish an input event but the input event receiver has already been disposed.

#2

I updated the android server on the 15th July 2016 (i.e one month ago). It might be a tough question but do you remember it working after you got this update? Im trying to determine if it might be something in the latest virtualhere update. Or, if it has been working with the latest virtualhere update up until 2 weeks ago, then its probably something with android, was android kernel updated then?

#3

Yes it was working after the update. I am not sure about the nexus 6p updates, but there were about 2 security updates from July 15th to present for nexus 5, although the Nexus 5 have recently been rooted to CM13

#4

I think you should try stock on the nexus5 , i doubt the security updates are the issue its likely the kernel

#5

It was a little hard to follow so I'm not sure if it's solved or not.
I had a very similar problem, except the server was an old version and running on a pi2 server.
I stopped the client, started an old version I had backuped and all works well now.
I tried to reboot and reuse the "current" client and the symptoms are still the same (device shown in use by me, but not "usb plugin" notification and impossible to use the device).
So it seems there is a problem with the drivers embarked with the current version

#6

Im not sure about that because the drivers havent changed for about 6 months, there was a small bug fix in the win7 driver about 2 months ago and that was it. And server side, nothing much has changed in more than a year. So Im almost certain is a kernel issue, with some bug in the new kernel has caused the usb bus to lock sometimes. Whats likely happening is the virtualhere is issuing an abort endpoint, when the device needs to stopped being used, and that command is never completed so virtualhere cannot finish unusing the device.

#7

I'll give it another run the next couple days. Nexus 6p was stock and had the issue while previously didn't. But Nexus 6p did have an update in this past month.
I was using up to date server and client during the process.

Was this section
08-12 16:34:05.566 21953 21953 W vhusbdan: type=1400 audit(0.0:224): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
08-12 16:34:05.566 21953 21953 W vhusbdan: type=1400 audit(0.0:225): avc: denied { search } for name="usb" dev="tmpfs" ino=10407429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0

the USB lock?

#8

No, i think that is the new android auditing log, it just notices that a call to the path tmpfs was denied (which virtualhere previously logged as (..."Error 1 creating device node") and just logs it, that call is not critical so virtualhere falls back to another method of operation which should be fine.

I only have a nexus 5x that i test on, so far i havent noticed any differences. I test using a USB disk, a logitech usb speaker system and a bluetooth dongle plugged into the nexus 5x usb-3c -> USB A Female adapter and so far its fine. My Nexus is running MTC20F 6.0.1 android

When you connect the cpr dummy to android and share it and then use it in windows, can you right click on the windows start button and select "Device manager" and see if its listed there either as a Unkown Device or under the USB section. It might have an error code there?

Also one other thing, when you use a USB adapter on the phone to plugin a USB device, i notice that usually you need to actually remove the usb cable completely from the phone and then plug the cable attached to the usb device back in. If you just remove the device from the end of the adapter cable then nexus ssometimes doesnt notice a new device. It seems the cable is holding some "plugged in" sensor. So when you plug/unplug your cpr dummy you should remove the whole usb cable from the phone, not just the CPR cable

If you want you could install and old stock nexus binary from here https://developers.google.com/android/nexus/images and see if that resolves the issue. If it does then ill need to see what google has changed regarding security stuff, or log a bug with them. VirtualHere doesnt rely on any security holes to work so im not sure..