search

daynix / UsbDk

Usb Drivers Development Kit for Windows
Apache License 2.0
553 stars 142 forks source link

Windows XP 32bit use libusb and UsbDk not support usb hub hot-plugging？ #76

Open BruceMok opened 5 years ago

BruceMok commented 5 years ago

I know XP is old but i have this use case so would like to see if it can work.

system architecture： +-----------+ +-----------+ virt-viewer < ------- > spice-gtk +-----------+ +-----------+
+------------+------------+ libusb libusbredir +------------+----------- -+

+-----------------+ UsbDk +-----------------+

spice client is remote-viewer 6.0 version of spice-gtk is 0.34 version of spice protocol is 0.12.13 version of libusb is 1.0.22 version of usbDk is 1.0.21

issue： When i plug in a hub, it work well and redirect. Then i plug out this hub, virt-viewer GUI blocking and have no response. I add some log in libusb source code, it seems to blocking at "windows_usbdk.c":

static void usbdk_close(struct libusb_device_handle *dev_handle)
{
        ......
    if (!usbdk_helper.StopRedirect(priv->redirector_handle)) {
        usbi_err(HANDLE_CTX(dev_handle), "Redirector shutdown failed");
    }
       ......
}

This issue 100% appears on Windows XP 32bit， but never appears on Win7 or Win10. Log as below：

(remote-viewer.exe:3180): GSpice-WARNING **: notify_dev_state_change remove

(remote-viewer.exe:3180): GSpice-WARNING **: notify_dev_state_change remove

(remote-viewer.exe:3180): GSpice-WARNING **: 【USB】 RMV ENEVT!

(remote-viewer.exe:3180): GSpice-WARNING **: 【USB】 RMV 1 spice_usb_device_manager_remove_dev

(remote-viewer.exe:3180): GSpice-WARNING **: 【USB】 RMV 2 disconnect_device_sync 02e463f0 [67.250000] [00000308] libusb: debug [libusb_get_bus_number] core.libusb_get_bus_number [67.250000] [00000308] libusb: debug [libusb_get_bus_number] core.libusb_get_bus_number

(remote-viewer.exe:3180): GSpice-WARNING **: 【USB】 RMV 3 disconnect device from usb channel 042e7368

(remote-viewer.exe:3180): GSpice-WARNING **: 【yanke】 disconnect_device 1

(remote-viewer.exe:3180): GSpice-WARNING **: 【yanke】 disconnect_device 2

(remote-viewer.exe:3180): GSpice-WARNING **: 【yanke】 disconnect_device 3 [67.250000] [00000308] libusb: debug [libusb_release_interface] interface 0 [67.250000] [00000308] libusb: debug [libusb_release_interface] interface 1 [67.250000] [00000308] libusb: debug [libusb_release_interface] interface 2 [67.250000] [00000308] libusb: debug [libusb_release_interface] interface 3 [67.250000] [00000308] libusb: debug [libusb_reset_device] [67.250000] [00000308] libusb: error [usbdk_reset_device] ResetDevice failed: [2] 系统找不到指定的文件。 [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328] core.libusb_close start! [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]libusb_close --- 0 [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]libusb_close --- 1 [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]libusb_close --- 2 [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]libusb_close --- 3 [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]ibusb_close --- 4 [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]libusb_close --- 5 [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]libusb_close --- 6 [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]libusb_close --- 7 [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]libusb_close --- 8 [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]libusb_close --- 9 [67.250000] [00000e44] libusb: debug [handle_events] poll() returned 1 [67.250000] [00000e44] libusb: debug [handle_events] caught a fish on the event pipe [67.250000] [00000e44] libusb: debug [handle_events] someone is closing a device [67.250000] [00000e44] libusb: debug [libusb_get_next_timeout] no URBs, no timeout! [67.250000] [00000e44] libusb: debug [libusb_try_lock_events] someone else is closing a device [67.250000] [00000308] libusb: debug [libusb_close] [10:40:14.328]libusb_close --- 10 [67.250000] [00000e44] libusb: debug [libusb_event_handler_active] someone else is closing a device [67.250000] [00000e44] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling [67.250000] [00000308] libusb: debug [usbdk_close] 10:40:14.328 yanke:usbdk_close start... [127.250000] [00000e44] libusb: debug [libusb_get_next_timeout] no URBs, no timeout! [127.250000] [00000e44] libusb: debug [libusb_try_lock_events] someone else is closing a device [127.250000] [00000e44] libusb: debug [libusb_event_handler_active] someone else is closing a device [127.250000] [00000e44] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling

(remote-viewer.exe:3180): GSpice-WARNING **: session: disconnecting 0

(remote-viewer.exe:3180): GSpice-WARNING **: [spice_session_init] Supported channels: main, display, inputs, cursor, playback, record, usbredir, webdav

(remote-viewer.exe:3180): GSpice-WARNING **: ==== set_property, auto-connect filter set to 0x03,-1,-1,-1,0|-1,-1,-1,-1,1

(remote-viewer.exe:3180): GSpice-WARNING **: 【USB-DEVICE-MANAGER】 spice_usb_device_manager_initable_init [138.062500] [000009e0] libusb: debug [libusb_init] core.libusb_init=== start! [138.062500] [000009e0] libusb: debug [libusb_init] libusb v1.0.22.11312 [138.062500] [000009e0] libusb: debug [libusb_init] core.libusb_init=== list_add [138.062500] [000009e0] libusb: debug [libusb_init] core.libusb_init=== usbi_backend.init [138.062500] [000009e0] libusb: debug [windows_init] ------------------windows_nt_common.windows_init start [138.062500] [000009e0] libusb: debug [windows_init] windows_nt_common.windows_init FOCUS init_count=2 [138.062500] [000009e0] libusb: debug [windows_init] ------------------FOCUS usbdk_backend.init START r=-99 [138.062500] [000009e0] libusb: debug [usbdk_init] FOCUS windows_usbdk.usbdk_init... start [138.062500] [000009e0] libusb: debug [windows_init] ------------------FOCUS usbdk_backend.init [usbdk_available = true] [138.062500] [000009e0] libusb: debug [windows_init] ------------------FOCUS usbdk_backend.init END r=0 [138.062500] [000009e0] libusb: debug [windows_init] ------------------windows_nt_common.windows_init end [138.062500] [000009e0] libusb: debug [usbi_add_pollfd] add fd 4 events 1 [138.062500] [000009e0] libusb: debug [libusb_init] core.libusb_init=== end [138.062500] [000009e0] libusb: debug [libusb_get_device_list] core.libusb_get_device_list [138.062500] [000009e0] libusb: debug [libusb_get_device_list] [138.062500] [000009e0] libusb: debug [usbdk_get_device_list] usbdk_get_device_list ==================== [138.093750] [000009e0] libusb: debug [winusb_get_device_list] allocating new device for session [1AC0] [138.093750] [000009e0] libusb: debug [usbi_connect_device] core.usbi_connect_device [138.093750] [000009e0] libusb: debug [winusb_get_device_list] allocating new device for session [1AFC] [138.093750] [000009e0] libusb: debug [usbi_connect_device] core.usbi_connect_device [138.093750] [000009e0] libusb: debug [winusb_get_device_list] allocating new device for session [1BD4] [138.093750] [000009e0] libusb: debug [usbi_connect_device] core.usbi_connect_device [138.093750] [000009e0] libusb: debug [winusb_get_device_list] allocating new device for session [1C24] [138.093750] [000009e0] libusb: debug [usbi_connect_device] core.usbi_connect_device [138.093750] [000009e0] libusb: debug [get_api_type] driver(s): WinUSB [138.093750] [000009e0] libusb: debug [get_api_type] matched driver name against WinUSB [138.093750] [000009e0] libusb: debug [winusb_get_device_list] allocating new device for session [8F4] [138.093750] [000009e0] libusb: debug [usbi_connect_device] core.usbi_connect_device [138.093750] [000009e0] libusb: debug [get_api_type] driver(s): HidUsb [138.093750] [000009e0] libusb: debug [get_api_type] matched driver name against HID API [138.093750] [000009e0] libusb: debug [winusb_get_device_list] allocating new device for session [1538] [138.093750] [000009e0] libusb: debug [usbi_connect_device] core.usbi_connect_device [138.093750] [000009e0] libusb: debug [get_api_type] driver(s): usbccgp [138.093750] [000009e0] libusb: debug [get_api_type] matched driver name against Composite API [138.093750] [000009e0] libusb: debug [winusb_get_device_list] allocating new device for session [1584] [138.093750] [000009e0] libusb: debug [usbi_connect_device] core.usbi_connect_device [138.093750] [000009e0] libusb: debug [get_api_type] driver(s): TcUsb

ybendito commented 5 years ago

Unfortunately, this is not so simple to reproduce this problem without bare metal XP which hard to find. There is almost no difference between UsbDk for XP and for Win7. Let's collect UsbDk logs: Use https://github.com/daynix/UsbDk/blob/master/Tools/Trace/UsbDkLogman.bat All commands below are for administrator command line: 1) remove the hub of the interest 1) uninstall UsbDk (usbdkcontroller-u) 2) start usbdkLogman.bat in separate admin console in writable directory 3) install UsbDk (usbdkcontroller-i) 4) connect the hub and redirect the device 5) remove the hub, if the remote-viewer stopped responding, wait 2 min 6) hit enter in the console of usbdkLogman.bat and collect the ETL file 7) inform us which release of UsbDk you use.

BruceMok commented 5 years ago

I use usbdkLogman.bat on XP, an error occurs :

UsbDkLogman_error

Unknown parameter "-ow" The syntax of the command is incorrect error: Unrecognized whether the passed sample name is a valid VMI data provider

So i delete the parameter "-ow", follow your comment collect UsbDk logs. Meanwhile, i collect a DebugView log. By the way, i connect a U disk on the hub, it can be redirect and work well, when i plug out the hub, remote-viewer stopped responding. Version of UsbDk is 1.0.21.

UsbDk_log.zip DebugView.LOG

ybendito commented 5 years ago

I'm not able to decode the log with symbols of 1.0.21 Do you run your own compilation or the installation of released usbdk MSI?

BruceMok commented 5 years ago

Sorry, i run my own compilation yesterday. I run the installation of released usbdk MSI today, but can not decode the log too. UsbDk_Logman_log.zip

I run my own compilation again(no source code be modified), follow the "UsbDk\Documentation\Tracing.txt" and use "UsbDkTrace.bat"catch some debug logs. UsbDk_trace_log2.LOG

ybendito commented 5 years ago

Due to unknown reason UsbDk does not receive any indication of hub or device removal. According to the log, the device was redirected at ~ 11:49:47 and from then there is no indication that it (or its hub) was removed. If the device was unplugged, expected surprise removal flow and it does not happen. Do you stop redirection manually in remote-viewer?

BruceMok commented 5 years ago

I do nothing in remote-viewer. When the device was unplugged at 11:50:13, libusb call the function "UsbDk_StopRedirect" of UsbDkHelper.c. I added some debugging information in this function：

    try
    {
        // if the driver is unaccessible the constructor raises exception
        // there is a question whether this check is required and whether this is correct thing to do
        // for now we leave it as is with TODO to investigate it in corner case flow
        // (for example UsbDk uninstall when there is active redirection)
        OutputDebugString(TEXT("UsbDk_StopRedirect 0"));
        UsbDkDriverAccess checkDriverAccess;
        OutputDebugString(TEXT("UsbDk_StopRedirect 1"));
        unique_ptr<REDIRECTED_DEVICE_HANDLE> deviceHandle(unpackHandle<REDIRECTED_DEVICE_HANDLE>(DeviceHandle));
        OutputDebugString(TEXT("UsbDk_StopRedirect 2"));
        deviceHandle->RedirectorAccess.reset();
        //deviceHandle->RedirectorAccess = nullptr;
        OutputDebugString(TEXT("UsbDk_StopRedirect 3"));      
        return TRUE;
    }

According to the log, function "UsbDk_StopRedirect" only print three debugging information, not found the fourth(i don't know if this is normal):

00002813 11:50:13 [3724] Driver file operation error. GetOverlappedResult failed (A device attached to the system is not functioning. Error code = 31)
00002814 11:50:13 [3724] Driver file operation error. GetOverlappedResult failed (A device attached to the system is not functioning. Error code = 31)
00002815 11:50:13 [3724] UsbDk_StopRedirect 0 00002816 11:50:13 [3724] UsbDk_StopRedirect 1 00002817 11:50:13 [3724] UsbDk_StopRedirect 2

BruceMok commented 5 years ago

I tested another connection method, the u disk directly connected to my laptop(Lenovo E49, XP 32 bit). unplug u disk, remote-viewer still work well. UsbDk trace log seems normal: UsbDk_log_trace3.LOG

I am very confused, once i use a hub connect some device and unplug the hub, remote-viewer will stop responding. But if i unplug the device which connected this hub, everything is fine.