Error when using slow-starting device

Submitted by Nikkoura on #1

Hello,

I am using a VKB joystick with VirtualHere. When the joystick is already connected server-side, when starting the client

- I see the joystick rebooting (it embeds a micro-controller with LEDs)
- Client side, I got a 'Error using this device' pop-up
- Then the joystick finishes it boot sequence, and it becomes correctly used by the client.

I guess that the latency introduced by its microcontroller boot is the culprit for this error message.

Here are the server-side logs:

2023-02-26 18:43:05 INFO :Unmanaging device 124 [231d:3201]
2023-02-26 18:43:07 ERROR :Cannot complete the capture of device at address 48292608, perhaps it has disappeared?
2023-02-26 18:43:07 ERROR :Error binding device 124 [231d:3201] to connection 6, BIND_ERROR
2023-02-26 18:43:08 INFO :Found Full speed device [231d:3201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  L  " at address 124
2023-02-26 18:43:10 INFO :Device 124 [231d:3201] BOUND to connection 6

Is there a per-device setting which could help avoiding these error messages? (which are not very problematic, since everything works fine a few seconds after)

Submitted by Nikkoura on Wed, 2023/03/01 - 07:09

#3

This time I did not have the error popup: the additional wait does the trick.

There are still some error messages in the server log, but it does not bother me :)

Thanks a lot!

Submitted by Michael on Wed, 2023/03/01 - 09:15

#4

Ok use that build now and later on in a future release i will add a way to specify the delay per device.

Submitted by Nikkoura on Sat, 2023/03/11 - 21:17

#5

Hello,

When updating to stock v4.5.2 or v4.5.3, it seems I am having again the same error messages. Do I have to set something in the server configuration to set the delay?

Thanks a lot!

Submitted by Michael on Sat, 2023/03/11 - 21:34

#6

Stock 4.5.3 should now automatically wait 3 seconds when using your joystick (4.5.2 does not contain this fix)  Are you sure you are running 4.5.3? Could you paste a few lines like in the above post when you try to use the joystick with 4.5.3

Submitted by Nikkoura on Sat, 2023/03/11 - 22:10

#7

When starting client with the joysticks already plugged in on the server side:

2023-03-11 13:04:45 INFO :Unmanaging device 130 [231d:3200]
2023-03-11 13:04:46 ERROR :Cannot complete the capture of device at address 130, perhaps it has disappeared?
2023-03-11 13:04:46 ERROR :Error binding device 130 [231d:3200] to connection 1, BIND_ERROR
2023-03-11 13:04:48 INFO :Found Full speed device [231d:3200] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  R  " at address 130
2023-03-11 13:04:48 INFO :Device 126 [28de:1142] BOUND to connection 1
2023-03-11 13:04:49 INFO :Unmanaging device 124 [231d:3201]
2023-03-11 13:04:50 ERROR :Cannot complete the capture of device at address 124, perhaps it has disappeared?
2023-03-11 13:04:50 ERROR :Error binding device 124 [231d:3201] to connection 1, BIND_ERROR
2023-03-11 13:04:51 INFO :Found Full speed device [231d:3201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  L  " at address 124
2023-03-11 13:04:52 INFO :Device 130 [231d:3200] BOUND to connection 1
2023-03-11 13:04:56 INFO :Device 124 [231d:3201] BOUND to connection 1

 If however client and server are already connected before the devices are plugged in, all is fine:

2023-03-11 13:07:00 INFO :Found Full speed device [231d:3201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  L  " at address 124
2023-03-11 13:07:05 INFO :Device 124 [231d:3201] BOUND to connection 1
2023-03-11 13:07:13 INFO :Found Full speed device [231d:3200] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  R  " at address 130
2023-03-11 13:07:15 INFO :Device 130 [231d:3200] BOUND to connection 1

 

Also, I failed to tell you earlier that there I have several devices by VKB, all sharing the same vendorId... and the same behavior.

Submitted by Michael on Sun, 2023/03/12 - 08:13

#8

OK i see the problem it changes its device id between 3200 and 3201. I will fix this in the next day or so and let you know when its ready...

Submitted by Nikkoura on Sun, 2023/03/12 - 20:32

#9

Wait, no!

There are really 2 separate USB devices:

- 231d:3200 (left handed joystick)

- 231d:3201 (right handed joystick)

And not shown here, I also have a rudder: 231d:011f

All 3 are based on the same STM32 microcontroller, and the same behavior when booting up.

 

The manufacturer also have sells many other controllers based on the same platform. I think it is safe to consider that the whole 231d vendorid exhibits the same boot process.

Maybe you can use this vendorid value as a trigger for the extended wait time?

Submitted by Nikkoura on Thu, 2023/03/16 - 07:23

#11

First test scenario: 3 VKB devices connected on the server side (231d:3200, 231d:3201 and 231d:011f). Server not running, client running and trying to connect to server, with auto-use enabled.
I then start the VH server. Error dialog box on the client side, and the following server-side:

2023-03-15 22:16:44 INFO :>>> Starting VirtualHere USB Server v4.5.4 (Built: Mar 13 2023, 07:48:52)<<<
2023-03-15 22:16:44 INFO :Using configuration C:\Users\frede\scoop\apps\virtualhere-server\current\config.ini
2023-03-15 22:16:44 INFO :Using SSL Server certificate at C:\\Users\\frede\\scoop\\persist\\virtualhere-server\\server.pem
2023-03-15 22:16:44 INFO :Using SSL CA at C:\\Users\\frede\\scoop\\persist\\virtualhere-server\\ca.pem
2023-03-15 22:16:44 INFO :Clients are required to use SSL Client certificates
2023-03-15 22:16:44 INFO :Server licensed to=<redacted> max_devices=unlimited
2023-03-15 22:16:44 INFO :Listening on all network interfaces at TCP SSL port 7574 (IPv6 dual-stack)
2023-03-15 22:16:44 INFO :Found Full speed device [231d:3200] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  R  " at address 130
2023-03-15 22:16:44 INFO :Found Full speed device [231d:3201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  L  " at address 124
2023-03-15 22:16:44 INFO :Found Full speed device [231d:011f] "VKB-Sim © Alex Oz 2021,  VKBsim T-Rudder " at address 141
2023-03-15 22:16:55 INFO : <redacted> connected as connection 1 (TCP SSL with Client Certificate:cert. version     : 1
serial number     : 01
issuer name       : <redacted>
subject name      : <redacted>
issued  on        : 2021-05-11 15:04:37
expires on        : 2031-05-09 15:04:37
signed using      : RSA with SHA-256
RSA key size      : 2048 bits
)
2023-03-15 22:16:56 INFO :Unmanaging device 130 [231d:3200]
2023-03-15 22:16:57 ERROR :Cannot complete the capture of device at address 130, perhaps it has disappeared?
2023-03-15 22:16:57 ERROR :Error binding device 130 [231d:3200] to connection 1, BIND_ERROR
2023-03-15 22:16:58 INFO :Found Full speed device [231d:3200] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  R  " at address 130
2023-03-15 22:16:59 INFO :Unmanaging device 124 [231d:3201]
2023-03-15 22:17:00 ERROR :Cannot complete the capture of device at address 124, perhaps it has disappeared?
2023-03-15 22:17:01 ERROR :Error binding device 124 [231d:3201] to connection 1, BIND_ERROR
2023-03-15 22:17:02 INFO :Unmanaging device 141 [231d:011f]
2023-03-15 22:17:03 INFO :Found Full speed device [231d:3201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  L  " at address 124
2023-03-15 22:17:04 ERROR :Cannot complete the capture of device at address 141, perhaps it has disappeared?
2023-03-15 22:17:04 ERROR :Error binding device 141 [231d:011f] to connection 1, BIND_ERROR
2023-03-15 22:17:06 INFO :Found Full speed device [231d:011f] "VKB-Sim © Alex Oz 2021,  VKBsim T-Rudder " at address 141
2023-03-15 22:17:08 INFO :Device 130 [231d:3200] BOUND to connection 1
2023-03-15 22:17:13 INFO :Device 124 [231d:3201] BOUND to connection 1
2023-03-15 22:17:18 INFO :Device 141 [231d:011f] BOUND to connection 1

Second test scenario: no devices plugged on server side. Client and server are connected.
I then plug the devices. No error dialog box, no error in server-side logs:

2023-03-15 22:04:34 INFO :Found Full speed device [231d:011f] "VKB-Sim © Alex Oz 2021,  VKBsim T-Rudder " at address 141
2023-03-15 22:04:38 INFO :Device 141 [231d:011f] BOUND to connection 1
2023-03-15 22:04:39 INFO :Found Full speed device [231d:3201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  L  " at address 124
2023-03-15 22:04:43 INFO :Found Full speed device [231d:3200] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO OT  R  " at address 130
2023-03-15 22:04:44 INFO :Device 124 [231d:3201] BOUND to connection 1
2023-03-15 22:04:49 INFO :Device 130 [231d:3200] BOUND to connection 1

Submitted by Michael on Thu, 2023/03/16 - 08:44

#12

Thanks for the detailed info, it gives me an idea:

When the virtualhere server is running, it will disable USB Power saving for all attached and newly attached USB devices.

(Some USB devices enter power saving mode and dont like being woken up by virtualhere to be redirected. They might drop off the bus and come back again, this is why powersaving is disabled by virtualhere)

If the server is not running then the usb devices might be in USB power saving mode. When virtualhere goes to redirect them, they "wake up" and reset themselves to full power and then are ready to be redirected.

This appears to be shown in the logs you have posted.


To turn off powersaving manually do this: Find the 3 devices listed in Windows Device manager. Right click on Each and is there a "Power Management" tab? If so then UNcheck "Allow the computer to turn off this device to save power"

Submitted by Barvo on Thu, 2023/03/16 - 09:49

#13

Hello,

I am having the exact same issues as the above user. I also attempted all of your troubleshooting steps to no avail including changing the power setting.

Not only am I having the exact same issues but I have the exact same equipment! (3 vkb devices, two are joysticks and one are pedals). 

Submitted by Barvo on Thu, 2023/03/16 - 11:23

#14

to clarify i don't have the EXACT same devices if that matters:

2023-03-15 22:21:16 INFO :Found Full speed device [231d:0201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO  L  " at address 1
2023-03-15 22:21:16 INFO :Found Full speed device [231d:011f] "VKB-Sim © Alex Oz 2021,  VKBsim T-Rudder " at address 13
2023-03-15 22:21:16 INFO :Found Full speed device [231d:0204] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO  R SEM " at address 12

the error does behave the same way in the logs:

2023-03-15 20:24:38 INFO :Unmanaging device 1 [231d:0201]
2023-03-15 20:24:39 ERROR :Cannot complete the capture of device at address 1, perhaps it has disappeared?
2023-03-15 20:24:39 ERROR :Error binding device 1 [231d:0201] to connection 4, BIND_ERROR
2023-03-15 20:24:41 INFO :Found Full speed device [231d:0201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO  L  " at address 1

Submitted by Michael on Thu, 2023/03/16 - 11:23

#15

@Barvo, could you start the virtualhere server then click Settings->View Server Log->Clear Log

Then exit the virtualhere server and download this new test build

https://www.virtualhere.com/sites/default/files/usbserver/test/vhusbdwi…

then run that and send me the server log by clicking Settings->View Server Log->Copy to clipboard and paste into this forum

Submitted by Barvo on Thu, 2023/03/16 - 11:53

#16

2023-03-15 22:51:15 INFO :Connection 3 successfully removed (reason:server shutdown)
2023-03-15 22:51:16 INFO :Connection 4 successfully removed (reason:server shutdown)
2023-03-15 22:51:17 INFO :Unmanaging device 13 [231d:011f]
2023-03-15 22:51:17 INFO :Unmanaging device 12 [231d:0204]
2023-03-15 22:51:17 INFO :Unmanaging device 1 [231d:0201]
2023-03-15 22:51:17 INFO :Unmanaging device 2 [041e:3256]
2023-03-15 22:51:17 INFO :Unmanaging device 3 [8087:0029]
2023-03-15 22:51:17 INFO :Unmanaging device 4 [1050:0407]
2023-03-15 22:51:17 INFO :Unmanaging device 5 [046d:085e]
2023-03-15 22:51:17 INFO :Unmanaging device 6 [320f:5044]
2023-03-15 22:51:17 INFO :Unmanaging device 7 [046d:c547]
2023-03-15 22:51:17 INFO :Unmanaging device 8 [045e:02fe]
2023-03-15 22:51:17 INFO :Unmanaging device 9 [0b05:18f3]
2023-03-15 22:51:17 INFO :Unmanaging device 10 [0fd9:0060]
2023-03-15 22:51:17 INFO :Unmanaging device 11 [2f96:0200]
2023-03-15 22:51:17 INFO :>>> Shutdown <<<
2023-03-15 22:51:33 INFO :>>> Starting VirtualHere USB Server v4.5.4 (Built: Mar 16 2023, 11:20:33)<<<
2023-03-15 22:51:33 INFO :Using configuration C:\Users\Torvald\Downloads\config.ini
2023-03-15 22:51:33 INFO :Server licensed to=unlicensed max_devices=1
2023-03-15 22:51:33 INFO :Listening on all network interfaces at TCP port 7575 (IPv6 dual-stack)
2023-03-15 22:51:37 INFO :192.168.2.242 connected as connection 1 (Standard TCP)
2023-03-15 22:51:39 INFO :192.168.2.160 connected as connection 2 (Standard TCP)
2023-03-15 22:51:39 ERROR :Error loading string descriptor (too small bytes returned) for device on port 4
2023-03-15 22:51:39 ERROR :Error loading string descriptor (too small bytes returned) for device on port 4
2023-03-15 22:51:39 INFO :Found Full speed device [231d:011f] "VKB-Sim © Alex Oz 2021,  VKBsim T-Rudder " at address 13
2023-03-15 22:51:39 INFO :Found Full speed device [231d:0204] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO  R SEM " at address 12
2023-03-15 22:51:39 INFO :Found Full speed device [231d:0201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO  L  " at address 1
2023-03-15 22:51:39 INFO :Found High speed device [041e:3256] "Creative Technology Ltd, Sound BlasterX G6" at address 2
2023-03-15 22:51:39 INFO :Found Full speed device [8087:0029] "0x8087, 0x0029" at address 3
2023-03-15 22:51:39 INFO :Found Full speed device [1050:0407] "Yubico, YubiKey OTP+FIDO+CCID" at address 4
2023-03-15 22:51:39 INFO :Found Super speed device [046d:085e] "0x046d, Logitech BRIO" at address 5
2023-03-15 22:51:39 INFO :Found Full speed device [320f:5044] "Glorious, GMMK Pro ANSI" at address 6
2023-03-15 22:51:39 INFO :Found Full speed device [046d:c547] "Logitech, USB Receiver" at address 7
2023-03-15 22:51:39 INFO :Found High speed device [045e:02fe] "Microsoft Inc., XBOX ACC" at address 8
2023-03-15 22:51:39 INFO :Found Full speed device [0b05:18f3] "AsusTek Computer Inc., AURA LED Controller" at address 9
2023-03-15 22:51:39 INFO :Found High speed device [0fd9:0060] "Elgato Systems, Stream Deck" at address 10
2023-03-15 22:51:39 INFO :Found Full speed device [2f96:0200] "0x2f96, 0x0200" at address 11
2023-03-15 22:51:54 INFO :Unmanaging device 1 [231d:0201]
2023-03-15 22:51:55 INFO :initatedEviceCapture OK
2023-03-15 22:51:56 INFO :Waiting for device 1 to reappear...
2023-03-15 22:51:56 INFO :Found Full speed device [231d:0201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO  L  " at address 1
2023-03-15 22:51:57 INFO :Waiting for device 1 to reappear...
2023-03-15 22:51:57 ERROR :Capturing USB\VID_2109&PID_2812\6&C1A2E2F&0&2,USB\VID_231D&PID_0201\7&114BE024&0&1,1, SetupDiEnumDeviceInterfaces failed, No more data is available. (0x00000103)
2023-03-15 22:51:58 ERROR :Error binding device 1 [231d:0201] to connection 1, BIND_ERROR
 

Submitted by Barvo on Thu, 2023/03/16 - 13:06

#18

2023-03-16 00:04:28 INFO :>>> Starting VirtualHere USB Server v4.5.4 (Built: Mar 16 2023, 12:26:41)<<<
2023-03-16 00:04:28 INFO :Using configuration C:\Users\Torvald\Downloads\config.ini
2023-03-16 00:04:28 INFO :Server licensed to=unlicensed max_devices=1
2023-03-16 00:04:28 INFO :Listening on all network interfaces at TCP port 7575 (IPv6 dual-stack)
2023-03-16 00:04:29 ERROR :Error loading string descriptor (too small bytes returned) for device on port 4
2023-03-16 00:04:29 ERROR :Error loading string descriptor (too small bytes returned) for device on port 4
2023-03-16 00:04:29 INFO :Found Full speed device [231d:011f] "VKB-Sim © Alex Oz 2021,  VKBsim T-Rudder " at address 13
2023-03-16 00:04:29 INFO :Found Full speed device [231d:0204] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO  R SEM " at address 12
2023-03-16 00:04:29 INFO :Found Full speed device [231d:0201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO  L  " at address 1
2023-03-16 00:04:29 INFO :Found High speed device [041e:3256] "Creative Technology Ltd, Sound BlasterX G6" at address 2
2023-03-16 00:04:29 INFO :Found Full speed device [8087:0029] "0x8087, 0x0029" at address 3
2023-03-16 00:04:29 INFO :Found Full speed device [1050:0407] "Yubico, YubiKey OTP+FIDO+CCID" at address 4
2023-03-16 00:04:29 INFO :Found Super speed device [046d:085e] "0x046d, Logitech BRIO" at address 5
2023-03-16 00:04:29 INFO :Found Full speed device [320f:5044] "Glorious, GMMK Pro ANSI" at address 6
2023-03-16 00:04:29 INFO :Found Full speed device [046d:c547] "Logitech, USB Receiver" at address 7
2023-03-16 00:04:29 INFO :Found High speed device [045e:02fe] "Microsoft Inc., XBOX ACC" at address 8
2023-03-16 00:04:29 INFO :Found Full speed device [0b05:18f3] "AsusTek Computer Inc., AURA LED Controller" at address 9
2023-03-16 00:04:29 INFO :Found High speed device [0fd9:0060] "Elgato Systems, Stream Deck" at address 10
2023-03-16 00:04:29 INFO :Found Full speed device [2f96:0200] "0x2f96, 0x0200" at address 11
2023-03-16 00:04:50 INFO :192.168.2.242 connected as connection 1 (Standard TCP)
2023-03-16 00:04:57 INFO :Unmanaging device 1 [231d:0201]
2023-03-16 00:04:58 INFO :initatedEviceCapture OK
2023-03-16 00:04:59 INFO :Waiting for device 1 to reappear...
2023-03-16 00:04:59 INFO :Found Full speed device [231d:0201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO  L  " at address 1
2023-03-16 00:05:00 INFO :Waiting for device 1 to reappear...
2023-03-16 00:05:01 INFO :Waiting for device 1 interface to reappear...
2023-03-16 00:05:02 INFO :Waiting for device 1 interface to reappear...
2023-03-16 00:05:03 ERROR :Capturing USB\VID_2109&PID_2812\6&C1A2E2F&0&2,USB\VID_231D&PID_0201\7&114BE024&0&1,1, SetupDiEnumDeviceInterfaces failed, No more data is available. (0x00000103)
2023-03-16 00:05:04 ERROR :Error binding device 1 [231d:0201] to connection 1, BIND_ERROR

Submitted by Barvo on Thu, 2023/03/16 - 13:22

#20

Same issue. If it helps, when I measure the time it takes for the joystick to become responsive after plugging it in physically it's under 3 seconds. 

2023-03-16 00:17:53 INFO :Unmanaging device 1 [231d:0201]
2023-03-16 00:17:54 INFO :Waiting for device 1 to reappear...
2023-03-16 00:17:55 INFO :Found Full speed device [231d:0201] "VKB-Sim © Alex Oz 2021,  VKBsim Gladiator EVO  L  " at address 1
2023-03-16 00:17:55 INFO :Waiting for device 1 to reappear...
2023-03-16 00:17:56 INFO :Waiting for device 1 interface to reappear...
2023-03-16 00:17:57 INFO :Waiting for device 1 interface to reappear...
2023-03-16 00:17:58 INFO :Waiting for device 1 interface to reappear...
2023-03-16 00:17:59 INFO :Waiting for device 1 interface to reappear...
2023-03-16 00:18:00 INFO :Waiting for device 1 interface to reappear...
2023-03-16 00:18:01 INFO :Waiting for device 1 interface to reappear...
2023-03-16 00:18:02 ERROR :Capturing USB\VID_2109&PID_2812\6&C1A2E2F&0&2,USB\VID_231D&PID_0201\7&114BE024&0&1,1, SetupDiEnumDeviceInterfaces failed, No more data is available. (0x00000103)
2023-03-16 00:18:03 ERROR :Error binding device 1 [231d:0201] to connection 1, BIND_ERROR

Submitted by Nikkoura on Thu, 2023/03/16 - 16:29

#22

Michael, you’ve nailed it. 
 

The VKB controllers have a configurable firmware. The configuration tool does include a setting for power management, enabled by default. 
I switched it off on one of the devices, and boom, problem solved for this device.  
I will more thoroughly test this evening and keep you posted. 
 

@Barvo: in vkbdevcfg, try unchecking the « Eco » checkbox in the « Global >> Common » tabs for each of your controllers. 

Submitted by Michael on Thu, 2023/03/16 - 16:53

#23

OK great, this issue was starting to drive me crazy :)

Submitted by Barvo on Thu, 2023/03/16 - 22:23

#24

That did the trick. What a strange and awesome coincidence we were both having this problem at the same time. I never knew about the eco setting in devcfg and certainly would have missed it. Thanks to both of you for your help!