UsbDkHelper: StartRedirect hangs when detaching a Bluetooth device

leoetlino commented 7 years ago

Hello, We have recently switched to using usbdk for libusb on Windows, but it appears that UsbDkHelper is not working quite right for Bluetooth adapters; it causes us to hang whenever we try to open the device (it's stuck in StartRedirect).

Here is the relevant stack trace:

    [External Code] 
    UsbDkHelper.dll!00007ffdaeb3cd3a()  Unknown
>   Dolphin.exe!usbdk_open(libusb_device_handle * dev_handle) Line 421  C
    Dolphin.exe!libusb_open(libusb_device * dev, libusb_device_handle * * dev_handle) Line 1268 C
    Dolphin.exe!IOS::HLE::Device::BluetoothReal::OpenDevice(libusb_device * device) Line 561    C++

Steps to reproduce:

Download the latest version of Dolphin.
In the Controller configuration dialog, select "Passthrough a Bluetooth adapter".
Plug in an adapter. Make sure Windows is seeing it as a Bluetooth adapter.
Start a Wii title (game, channel, anything using a Wii remote).
Dolphin should now hang on a black screen, when it tries to use the adapter.

I think this may be due to Windows's Bluetooth stack still using the driver or something, because if you manage to open the driver before the Bluetooth adapter is detected by the stack, or if you install WinUSB/libusbk for the adapter, then usbdk is able to redirect the device just fine.

Unfortunately, DebugView didn't show anything useful (it only tells us it's hanging after libusb_open, which we already know).

Do you have any idea what is wrong? Do we need to detach the system driver first (like on Linux)? Thanks!

dmitryfleytman commented 7 years ago

Hello,

No, there is no need to detach the system driver, UsbDk does this automatically.

In order to understand what might be wrong, please collect UsbDk log as described at https://github.com/daynix/UsbDk/blob/master/Documentation/Tracing.txt#L52

Thanks, Dmitry

leoetlino commented 7 years ago

Thanks for the quick reply. Here is the trace log: https://dolphin.leolam.fr/UsbDkTrace.etl

dmitryfleytman commented 7 years ago

Log contains:

[5]33C4.3254::02/08/2017-12:53:33.222 [UsbDk]CUsbDkControlDevice::AddRedirect Success. New redirections list: [5]33C4.3254::02/08/2017-12:53:33.222 [UsbDk]CUsbDkRedirection::Dump Redirect: DevID: USB\VID_0A12&PID_0001, InstanceID: 1

According to the log, redirection was successful, however it is too short for some reason.

Could you do the following:

Reboot your system
Run tracing scripts
Reproduce the problem
Wait 5 minutes
Stop tracing and pick-up the trace file

Thanks, Dmitry

leoetlino commented 7 years ago

Done, here is the new trace: http://www.filedropper.com/usbdktrace_1

This time, the open eventually failed with LIBUSB_ERROR_OTHER. Another thing I forgot to note: even though the open fails or hangs, the Bluetooth system driver is still detached.

dmitryfleytman commented 7 years ago

This log contains more info.

[4]0004.1010::02/08/2017-14:21:32.819 [UsbDk]::operator() Starting relations array processing: [4]0004.1010::02/08/2017-14:21:32.819 [UsbDk]CDeviceRelations::Dump Array size: 1 (ptr: FFFFAE0AC6D0EFF0) [4]0004.1010::02/08/2017-14:21:32.819 [UsbDk]CDeviceRelations::ForEachIf<bool #0: FFFFAE0AC6295060 [3]0004.1010::02/08/2017-14:21:32.827 [UsbDk]CUsbDkHubFilterStrategy::RegisterNewChild Registering new child (PDO: FFFFAE0AC6295060): [3]0004.1010::02/08/2017-14:21:32.827 [UsbDk]CRegText::Dump ID: USB\VID_0A12&PID_0001 [3]0004.1010::02/08/2017-14:21:32.827 [UsbDk]CRegText::Dump ID: 1 [3]0004.1010::02/08/2017-14:21:32.848 [UsbDk]CUsbDkHubFilterStrategy::ApplyRedirectionPolicy Not attaching to device stack for 0xFFFFAE0AC6295060 [3]0004.1010::02/08/2017-14:21:32.848 [UsbDk]::operator() Finished relations array processing [5]0FC8.0504::02/08/2017-14:21:43.243 [UsbDk]CUsbDkControlDevice::AddRedirect Success. New redirections list: [5]0FC8.0504::02/08/2017-14:21:43.243 [UsbDk]CUsbDkRedirection::Dump Redirect: DevID: USB\VID_0A12&PID_0001, InstanceID: 1 [5]0004.1158::02/08/2017-14:21:43.274 [UsbDk]::operator() Starting relations array processing: [5]0004.1158::02/08/2017-14:21:43.274 [UsbDk]CDeviceRelations::Dump Array size: 0 (ptr: FFFFAE0AC6C94E60) [5]0004.1158::02/08/2017-14:21:43.274 [UsbDk]CWdmList<CUsbDkChildDevice,CWdmSpinLock,CCountingObject,CScalarDeleter Deleting child object: [5]0004.1158::02/08/2017-14:21:43.274 [UsbDk]CUsbDkChildDevice::Dump Child device 0xFFFFAE0AC6295060: [5]0004.1158::02/08/2017-14:21:43.274 [UsbDk]CRegText::Dump ID: USB\VID_0A12&PID_0001 [5]0004.1158::02/08/2017-14:21:43.274 [UsbDk]CRegText::Dump ID: 1 [5]0004.1158::02/08/2017-14:21:43.274 [UsbDk]::operator() Finished relations array processing [5]0FC8.0504::02/08/2017-14:23:43.243 [UsbDk]CUsbDkControlDevice::AddRedirect Wait for redirector attachment failed. 0x00000102(STATUS_TIMEOUT) [5]0FC8.0504::02/08/2017-14:23:43.243 [UsbDk]CUsbDkControlDevice::GetPDOByDeviceID PDO was not found [5]0FC8.0504::02/08/2017-14:23:43.243 [UsbDk]CUsbDkControlDevice::AddRedirectRollBack Roll-back reset failed. 0xc0000225(STATUS_NOT_FOUND)

An interesting thing has happened - UsbDk initiated reset of the device, it turned off and never turned on again.

Could you please collect more info:

Having your device attached, dump USB state with UsbView after system reboot (see https://github.com/daynix/UsbDk/blob/master/Documentation/UsbInfo.txt)
When your application is stuck in libusb_open, dump USB state again
When your application is stuck in libusb_open, try to re-plug the device and see if this helps

Thanks, Dmitry

leoetlino commented 7 years ago

Hmm. I wonder if this may have to do with the fact that I'm testing it in a VM (with SPICE). I'll try to test this on a real machine.

JMC47 commented 7 years ago

usbview.zip

I did the steps you provided on my Windows machine to speed this up. For me, Dolphin hangs when closing (the device works until then.) When I close Dolphin, the emulator hardlocks, but Windows seems to have the bluetooth back (it returns to the docket and seems to work?) Unplugging it doesn't seem to unfreeze Dolphin.

The logs provided should have both states (just plugged in, no boots of Dolphin and Dolphin froze, device seemingly returned to windows.)

sameehj commented 7 years ago

Which UsbDk version are you using? Can you still reproduce with the most recent version of UsbDk?

@JMC47 can you provide a UsbDk trace for the close operation? does it happen only with a specific bluetooth device? what Windows OS are you using?

dmitryfleytman commented 7 years ago

Closing for now. Please reopen in case problem still exists with the latest build.

daynix / UsbDk

UsbDkHelper: StartRedirect hangs when detaching a Bluetooth device #35