libusb icon indicating copy to clipboard operation
libusb copied to clipboard
verified publisher icon libusb

USB hub reference is not decremented when a handle to a connected device is closed.

Open Oldanko opened this issue 3 years ago • 21 comments

I have written a program to output the number of references to connected USB devices to see how the number changes after different USB events. As a result, I've observed that when I libusb_open a device that is connected to the USB hub, the number of references to that device increases by one, as well as the number of references to the USB hub. However, when I libusb_close the device, the number of references to the device decreases by one, but the number of references to the USB hub stays the same.

In order to write this program, as I couldn't find a function to get the number of references in libusb, I've added a function with the following definition: void LIBUSB_CALL libusb_refcnt_device(libusb_device *dev, long* refcnt) { *refcnt = usbi_atomic_load(&dev->refcnt); }

Following is the C++ code of the program:

#include <iostream>
#include <vector>
#include "libusb/libusb.h"

void print_ref_cnts(libusb_context *context) {
    libusb_device **devs;
    auto devs_size = libusb_get_device_list(context, &devs);

    for(ssize_t i = 0; i < devs_size; i++) {
        auto p_device = devs[i];
        libusb_device_descriptor descriptor{};
        libusb_get_device_descriptor(p_device, &descriptor);

        long refs;
        libusb_refcnt_device(p_device, &refs);

        std::cout << std::hex
                  << " 0x" << descriptor.idVendor
                  << " 0x" << descriptor.idProduct
                  << std::dec
                  << " " << refs << std::endl;
    }

    libusb_free_device_list(devs, true);
}

auto open_devices(libusb_context *context, unsigned short vendor_id, unsigned short product_id) {
    libusb_device **devs;
    auto devs_size = libusb_get_device_list(context, &devs);

    std::vector<libusb_device_handle*> handles;

    for(ssize_t i = 0; i < devs_size; i++) {
        libusb_device_descriptor descriptor{};
        libusb_get_device_descriptor(devs[i], &descriptor);
        if(descriptor.idVendor == vendor_id && descriptor.idProduct == product_id) {
            libusb_device_handle* dh;
            libusb_open(devs[i], &dh);
            handles.push_back(dh);
        }
    }

    libusb_free_device_list(devs, true);
    return handles;
}

int main() {
    libusb_context *context;
    libusb_init(&context);

    std::string s;
    while(std::getline(std::cin, s)) {
        std::cout << "Before opening\n";
        print_ref_cnts(context);
        auto handles = open_devices(context, 0x9da, 0x9090);
        std::cout << "After opening\n";
        print_ref_cnts(context);
        for(auto dh : handles)
            libusb_close(dh);
    }

    libusb_exit(context);
}

The program performs the following actions in a loop:

  1. Read a line of std::cin input
  2. Outpust vendor id, product id, and the number of references of every item in the list of connected devices.
  3. Attempts to open devices that match given vendor id and product id.
  4. Outpust vendor id, product id, and the number of references of every item in the list of connected devices again.
  5. Closes any opened devices in step 3

While the program waits for the std::cin input, I performed the following actions, each having a corresponding entry in the resulting console output:

  1. Disconnected the USB hub and a mouse with the vendor id and the product id which are being searched for.
  2. Connect the USB hub
  3. Connect the mouse to the hub
  4. No changes

The program produced the following output:

Nothing connected
Before opening
 0x8086 0x9d2f 4
 0xbda 0xb00b 1
 0x9da 0xfa10 1
 0x4ca 0x706e 1
After opening
 0x8086 0x9d2f 4
 0xbda 0xb00b 1
 0x9da 0xfa10 1
 0x4ca 0x706e 1
Hub Connected
Before opening
 0x8086 0x9d2f 5
 0xbda 0xb00b 1
 0x9da 0xfa10 1
 0x4ca 0x706e 1
 0x1a40 0x101 2
 0x639 0x7210 1
After opening
 0x8086 0x9d2f 5
 0xbda 0xb00b 1
 0x9da 0xfa10 1
 0x4ca 0x706e 1
 0x1a40 0x101 2
 0x639 0x7210 1
Mouse connected
Before opening
 0x8086 0x9d2f 5
 0xbda 0xb00b 1
 0x9da 0xfa10 1
 0x4ca 0x706e 1
 0x1a40 0x101 3
 0x639 0x7210 1
 0x9da 0x9090 1
After opening
 0x8086 0x9d2f 6
 0xbda 0xb00b 1
 0x9da 0xfa10 1
 0x4ca 0x706e 1
 0x1a40 0x101 4
 0x639 0x7210 1
 0x9da 0x9090 2
No changes
Before opening
 0x8086 0x9d2f 7
 0xbda 0xb00b 1
 0x9da 0xfa10 1
 0x4ca 0x706e 1
 0x1a40 0x101 4
 0x639 0x7210 1
 0x9da 0x9090 1
After opening
 0x8086 0x9d2f 9
 0xbda 0xb00b 1
 0x9da 0xfa10 1
 0x4ca 0x706e 1
 0x1a40 0x101 5
 0x639 0x7210 1
 0x9da 0x9090 2

From the logs we can conclude, that the hub VID=0x1a40 and PID=0x101, mouse VID=0x9da PID=0x9090. Before the mouse is connected (Hub Connected), the hub's reference count is 2 (presumably itself and the 0x639 0x7210?). After the mouse is connected but before creating a handle to it (Mouse connected - Before opening), the hub's reference count is incremented, and the mouse's reference count is set to 1. After opening the mouse (Mouse connected - After opening), both the hub's and the mouse's reference counts are incremented. However, after the mouse's device handle is closed (No changes - Before opening), the mouse's reference count is decremented, but the hub's reference count stays the same. You can also see an increasing reference count of the 0x8086 0x9d2f.

I hope I haven't made any mistakes with this. This looks like incorrect behavior to me, but I'm not certain about it.

Oldanko avatar Jul 14 '22 15:07 Oldanko

Which OS are you testing this? And a mouse is probably not a good tool to test libusb, especially if you use Windows.

mcuee avatar Jul 16 '22 10:07 mcuee

@Oldanko

Any updates on this? If you test under Windows, please also take note libusb Windows does not support hotplug.

mcuee avatar Mar 27 '23 03:03 mcuee

@tormodvolden and @hjelmn

Just wonder if it makes sense to add this new function mentioned by @Oldanko. It may be useful for debugging purpose.

void LIBUSB_CALL libusb_refcnt_device(libusb_device *dev, long* refcnt) 
{ 
    *refcnt = usbi_atomic_load(&dev->refcnt); 
}

mcuee avatar Mar 30 '23 12:03 mcuee

No, I don't think such a function should be added. An application shouldn't need to query these values. Hopefully the function is only needed here for debugging this issue in particular. Otherwise if this would be a more widespread problem we should provide necessary info in the debug log.

tormodvolden avatar Mar 30 '23 15:03 tormodvolden

No, I don't think such a function should be added. An application shouldn't need to query these values. Hopefully the function is only needed here for debugging this issue in particular. Otherwise if this would be a more widespread problem we should provide necessary info in the debug log.

I agree with you that we do not need a new function here.

On the other hand, I think it is good to add some debug info for reference count. I am trying to debug the following issue but it seems to be difficult without the debug log.

  • #988

mcuee avatar Mar 31 '23 01:03 mcuee

Maybe there is no need to create a new function, just adding some debug logs will help.

diff --git a/libusb/core.c b/libusb/core.c
index 17e61172..5a7680e8 100644
--- a/libusb/core.c
+++ b/libusb/core.c
@@ -1272,6 +1272,7 @@ libusb_device * LIBUSB_CALL libusb_ref_device(libusb_device *dev)
        long refcnt;

        refcnt = usbi_atomic_inc(&dev->refcnt);
+       usbi_dbg(DEVICE_CTX(dev), "Device %d.%d reference count increased to %ld", dev->bus_number, dev->device_address, refcnt);
        assert(refcnt >= 2);

        return dev;
@@ -1290,6 +1291,7 @@ void API_EXPORTED libusb_unref_device(libusb_device *dev)
                return;

        refcnt = usbi_atomic_dec(&dev->refcnt);
+       usbi_dbg(DEVICE_CTX(dev), "Device %d.%d reference count decreased to %ld", dev->bus_number, dev->device_address, refcnt);
        assert(refcnt >= 0);

        if (refcnt == 0) {

mcuee avatar Mar 31 '23 13:03 mcuee

With the above patch, here is the debug output under Windows. From the run log it seems to me the reference count handling is working. Many of the clean-ups are carried out just before libusb_exit.

05E3:0612 is an external USB Type C Hub (SuperSpeed). 0781:5591 is a Sandisk USB drive connected to the Type C Hub. 8086:A0ED and 8086:9A13 are the two root hubs. 05E3:0610 is an internal full speed USB hub. 046d:c528 is Logitech USB receiver 8087:0026 is Intel USB Bluetooth controller 17CA:0575 is Egistec Touch Fingerprint sensor 04F2:B6DD is Chicony USB camera.

click for the detailed debug log under Windows 
MINGW64 /c/work/libusb/libusb_test/libusb_issue1165
$ ./examples/testlibusb.exe
Dev (bus 2, device 2): 05E3 - 0612 speed: 5G
Dev (bus 2, device 3): 0781 - 5591 speed: 5G
Dev (bus 1, device 2): 8087 - 0026 speed: 12M
Dev (bus 1, device 5): 04F2 - B6DD speed: 480M
Dev (bus 1, device 3): 1C7A - 0575 speed: 480M
Dev (bus 1, device 0): 8086 - A0ED speed: 5G
Dev (bus 1, device 7): 05E3 - 0610 speed: 480M
Dev (bus 1, device 1): 046D - C52B speed: 12M
  Manufacturer:              Logitech
  Product:                   USB Receiver
Dev (bus 2, device 0): 8086 - 9A13 speed: 5G

$ export LIBUSB_DEBUG=4

$ ./examples/testlibusb.exe
[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.001153] [00002648] libusb: debug [libusb_init_context] created default context
[ 0.001447] [00002648] libusb: debug [libusb_init_context] libusb v1.0.26.11791
[ 0.001766] [00002648] libusb: debug [usbi_add_event_source] add HANDLE 00000000000000b0 events 0
[ 0.001901] [00002648] libusb: debug [usbi_io_init] using timer for timeouts
[ 0.002019] [00002648] libusb: debug [usbi_add_event_source] add HANDLE 00000000000000b4 events 0
[ 0.002151] [00002648] libusb: debug [get_windows_version] Windows 11 64-bit
[ 0.002283] [00002648] libusb: debug [htab_create] using 1021 entries hash table
[ 0.003816] [00002648] libusb: info [winusbx_init] WinUSB DLL available (with isoch support)
[ 0.005348] [00002648] libusb: debug [winusbx_init] libusbK DLL found, version: 3.1.0.0
[ 0.007095] [00002648] libusb: info [windows_init] UsbDk backend is not available
[ 0.007290] [00002648] libusb: debug [libusb_get_device_list]
[ 0.007438] [000035e0] libusb: debug [windows_iocp_thread] I/O completion thread started
[ 0.014352] [00002648] libusb: debug [winusb_get_device_list] allocating new device for session [5]
[ 0.014652] [00002648] libusb: debug [winusb_get_device_list] allocating new device for session [6]
[ 0.014773] [00002648] libusb: debug [winusb_get_device_list] allocating new device for session [7]
[ 0.014910] [00002648] libusb: debug [winusb_get_device_list] allocating new device for session [8]
[ 0.015369] [00002648] libusb: debug [get_api_type] driver(s): WUDFRd
[ 0.015533] [00002648] libusb: debug [get_api_type] lower filter driver(s): WinUsb
[ 0.015639] [00002648] libusb: debug [get_api_type] matched lower filter driver name against WinUSB
[ 0.015754] [00002648] libusb: debug [winusb_get_device_list] allocating new device for session [1E]
[ 0.015926] [00002648] libusb: debug [get_api_type] driver(s): BTHUSB
[ 0.016047] [00002648] libusb: debug [get_api_type] lower filter driver(s): ibtusb
[ 0.016149] [00002648] libusb: debug [winusb_get_device_list] allocating new device for session [3E]
[ 0.016421] [00002648] libusb: debug [get_api_type] driver(s): usbccgp
[ 0.016543] [00002648] libusb: debug [get_api_type] matched driver name against Composite API
[ 0.016659] [00002648] libusb: debug [winusb_get_device_list] allocating new device for session [70]
[ 0.016779] [00002648] libusb: debug [get_api_type] driver(s): usbccgp
[ 0.016888] [00002648] libusb: debug [get_api_type] matched driver name against Composite API
[ 0.016997] [00002648] libusb: debug [winusb_get_device_list] allocating new device for session [71]
[ 0.017142] [00002648] libusb: debug [get_api_type] driver(s): USBSTOR
[ 0.017265] [00002648] libusb: debug [winusb_get_device_list] allocating new device for session [72]
[ 0.017517] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.017613] [00002648] libusb: debug [enumerate_hcd_root_hub] assigning HCD 'PCI\VEN_8086&DEV_A0ED&SUBSYS_15451025&REV_20\3&11583659&0&A0' bus number 1
[ 0.017662] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 1
[ 0.017714] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.017752] [00002648] libusb: debug [enumerate_hcd_root_hub] assigning HCD 'PCI\VEN_8086&DEV_9A13&SUBSYS_72708086&REV_01\3&11583659&0&68' bus number 2
[ 0.017792] [00002648] libusb: debug [libusb_unref_device] Device 2.0 reference count decreased to 1
[ 0.018683] [00002648] libusb: debug [libusb_ref_device] Device 2.0 reference count increased to 2
[ 0.018866] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.018961] [00002648] libusb: debug [winusb_get_device_list] found existing device for session [5]
[ 0.019167] [00002648] libusb: debug [init_device] found 1 configurations (current config: 1)
[ 0.019268] [00002648] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 31 bytes)
[ 0.019373] [00002648] libusb: debug [init_device] (bus: 2, addr: 2, depth: 1, port: 2): 'USB\VID_05E3&PID_0612\5&1A00B1C&0&2'
[ 0.019476] [00002648] libusb: debug [libusb_ref_device] Device 2.2 reference count increased to 3
[ 0.019676] [00002648] libusb: debug [libusb_ref_device] Device 2.2 reference count increased to 4
[ 0.019757] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.019816] [00002648] libusb: debug [winusb_get_device_list] found existing device for session [72]
[ 0.019916] [00002648] libusb: debug [init_device] found 1 configurations (current config: 1)
[ 0.019970] [00002648] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 44 bytes)
[ 0.020022] [00002648] libusb: debug [init_device] (bus: 2, addr: 3, depth: 2, port: 2): 'USB\VID_0781&PID_5591\0401D5032AFA44996ADA6E7FB56B51153C7D26AC8C49311D73C10CF96B01E67412E700000000000000000000DE646461000810189155810714AA1A5B'
[ 0.020080] [00002648] libusb: debug [libusb_ref_device] Device 2.3 reference count increased to 3
[ 0.020180] [00002648] libusb: debug [libusb_ref_device] Device 1.0 reference count increased to 2
[ 0.020226] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.020271] [00002648] libusb: debug [winusb_get_device_list] found existing device for session [3E]
[ 0.020353] [00002648] libusb: debug [init_device] found 1 configurations (current config: 1)
[ 0.020407] [00002648] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 200 bytes)
[ 0.020457] [00002648] libusb: debug [init_device] (bus: 1, addr: 2, depth: 1, port: 10): 'USB\VID_8087&PID_0026\5&586B51A&0&10'
[ 0.020502] [00002648] libusb: debug [libusb_ref_device] Device 1.2 reference count increased to 3
[ 0.020615] [00002648] libusb: debug [winusb_get_device_list] extra GUID: {16126A05-3179-4589-9DB8-952AFFD297D5}
[ 0.020754] [00002648] libusb: debug [libusb_ref_device] Device 1.0 reference count increased to 3
[ 0.020868] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.020985] [00002648] libusb: debug [winusb_get_device_list] found existing device for session [70]
[ 0.021131] [00002648] libusb: debug [init_device] found 1 configurations (current config: 1)
[ 0.021254] [00002648] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 512 bytes)
[ 0.021356] [00002648] libusb: debug [init_device] (bus: 1, addr: 5, depth: 1, port: 5): 'USB\VID_04F2&PID_B6DD\0001'
[ 0.021458] [00002648] libusb: debug [libusb_ref_device] Device 1.5 reference count increased to 3
[ 0.021621] [00002648] libusb: debug [winusb_get_device_list] extra GUID: {20348E47-A897-468E-9D0E-56307802FC2A}
[ 0.021689] [00002648] libusb: debug [libusb_ref_device] Device 1.0 reference count increased to 4
[ 0.021744] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.021791] [00002648] libusb: debug [winusb_get_device_list] found existing device for session [1E]
[ 0.021888] [00002648] libusb: debug [init_device] found 1 configurations (current config: 1)
[ 0.021943] [00002648] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 46 bytes)
[ 0.021998] [00002648] libusb: debug [init_device] (bus: 1, addr: 3, depth: 1, port: 7): 'USB\VID_1C7A&PID_0575\077E2F9A'
[ 0.022047] [00002648] libusb: debug [libusb_ref_device] Device 1.3 reference count increased to 3
[ 0.022151] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.022201] [00002648] libusb: debug [libusb_unref_device] Device 0.0 reference count decreased to 1
[ 0.022331] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.022438] [00002648] libusb: debug [libusb_unref_device] Device 0.0 reference count decreased to 1
[ 0.022620] [00002648] libusb: debug [libusb_ref_device] Device 1.0 reference count increased to 5
[ 0.022804] [00002648] libusb: debug [init_root_hub] root hub 'USB\ROOT_HUB30\4&12C539F&0&0' reports 16 ports
[ 0.022949] [00002648] libusb: debug [init_device] (bus: 1, addr: 0, depth: 0, port: 0): 'USB\ROOT_HUB30\4&12C539F&0&0'
[ 0.023056] [00002648] libusb: debug [libusb_ref_device] Device 1.0 reference count increased to 6
[ 0.023225] [00002648] libusb: debug [libusb_ref_device] Device 1.5 reference count increased to 4
[ 0.023318] [00002648] libusb: debug [libusb_unref_device] Device 1.5 reference count decreased to 3
[ 0.023474] [00002648] libusb: debug [libusb_ref_device] Device 1.0 reference count increased to 7
[ 0.023563] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.023619] [00002648] libusb: debug [winusb_get_device_list] found existing device for session [8]
[ 0.023715] [00002648] libusb: debug [init_device] found 1 configurations (current config: 1)
[ 0.023773] [00002648] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 41 bytes)
[ 0.023828] [00002648] libusb: debug [init_device] (bus: 1, addr: 7, depth: 1, port: 2): 'USB\VID_05E3&PID_0610\5&586B51A&0&2'
[ 0.023878] [00002648] libusb: debug [libusb_ref_device] Device 1.7 reference count increased to 3
[ 0.023982] [00002648] libusb: debug [winusb_get_device_list] extra GUID: {E421D5D8-BD56-AA84-7553-28C83FC89083}
[ 0.024036] [00002648] libusb: debug [libusb_ref_device] Device 1.0 reference count increased to 8
[ 0.024084] [00002648] libusb: debug [libusb_ref_device] Device 0.0 reference count increased to 2
[ 0.024131] [00002648] libusb: debug [winusb_get_device_list] found existing device for session [71]
[ 0.024209] [00002648] libusb: debug [init_device] found 1 configurations (current config: 1)
[ 0.024263] [00002648] libusb: debug [cache_config_descriptors] cached config descriptor 0 (bConfigurationValue=1, 84 bytes)
[ 0.024319] [00002648] libusb: debug [init_device] (bus: 1, addr: 1, depth: 1, port: 3): 'USB\VID_046D&PID_C52B\5&586B51A&0&3'
[ 0.024368] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 3
[ 0.024462] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 4
[ 0.024512] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 3
[ 0.024614] [00002648] libusb: debug [libusb_ref_device] Device 2.0 reference count increased to 3
[ 0.024723] [00002648] libusb: debug [init_root_hub] root hub 'USB\ROOT_HUB30\4&1A63DC7C&0&0' reports 5 ports
[ 0.024787] [00002648] libusb: debug [init_device] (bus: 2, addr: 0, depth: 0, port: 0): 'USB\ROOT_HUB30\4&1A63DC7C&0&0'
[ 0.024835] [00002648] libusb: debug [libusb_ref_device] Device 2.0 reference count increased to 4
[ 0.025092] [00002648] libusb: debug [winusb_get_device_list] unlisted ancestor for 'HID\SYNA7DAB&COL01\5&2F64DFEA&0&0000' (non USB HID, newly connected, etc.) - ignoring
[ 0.025172] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 4
[ 0.025221] [00002648] libusb: debug [winusb_get_device_list] setting composite interface for [71]:
[ 0.025268] [00002648] libusb: debug [set_composite_interface] interface[1] = \\?\HID#VID_046D&PID_C52B&MI_01&COL01#7&1119BFB4&0&0000#{4D1E55B2-F16F-11CF-88CB-001111000030}
[ 0.025326] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 3
[ 0.025400] [00002648] libusb: debug [libusb_ref_device] Device 1.2 reference count increased to 4
[ 0.025447] [00002648] libusb: debug [libusb_unref_device] Device 1.2 reference count decreased to 3
[ 0.025555] [00002648] libusb: debug [libusb_ref_device] Device 1.2 reference count increased to 4
[ 0.025603] [00002648] libusb: debug [libusb_unref_device] Device 1.2 reference count decreased to 3
[ 0.025670] [00002648] libusb: debug [libusb_ref_device] Device 1.2 reference count increased to 4
[ 0.025718] [00002648] libusb: debug [libusb_unref_device] Device 1.2 reference count decreased to 3
[ 0.025783] [00002648] libusb: debug [winusb_get_device_list] unlisted ancestor for 'HID\INTC816\3&D2322F2&0&0000' (non USB HID, newly connected, etc.) - ignoring
[ 0.025861] [00002648] libusb: debug [winusb_get_device_list] unlisted ancestor for 'HID\SYNA7DAB&COL02\5&2F64DFEA&0&0001' (non USB HID, newly connected, etc.) - ignoring
[ 0.025937] [00002648] libusb: debug [winusb_get_device_list] unlisted ancestor for 'HID\SYNA7DAB&COL03\5&2F64DFEA&0&0002' (non USB HID, newly connected, etc.) - ignoring
[ 0.026014] [00002648] libusb: debug [winusb_get_device_list] unlisted ancestor for 'HID\SYNA7DAB&COL04\5&2F64DFEA&0&0003' (non USB HID, newly connected, etc.) - ignoring
[ 0.026094] [00002648] libusb: debug [winusb_get_device_list] unlisted ancestor for 'HID\CONVERTEDDEVICE&COL02\5&32CF90E6&0&0001' (non USB HID, newly connected, etc.) - ignoring
[ 0.026165] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 4
[ 0.026213] [00002648] libusb: debug [winusb_get_device_list] setting composite interface for [71]:
[ 0.026260] [00002648] libusb: debug [set_composite_interface] interface[1] already set - ignoring HID collection: HID\VID_046D&PID_C52B&MI_01&COL02\7&1119BFB4&0&0001
[ 0.026317] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 3
[ 0.026385] [00002648] libusb: debug [winusb_get_device_list] unlisted ancestor for 'HID\CONVERTEDDEVICE&COL03\5&32CF90E6&0&0002' (non USB HID, newly connected, etc.) - ignoring
[ 0.026456] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 4
[ 0.026504] [00002648] libusb: debug [winusb_get_device_list] setting composite interface for [71]:
[ 0.026551] [00002648] libusb: debug [set_composite_interface] interface[1] already set - ignoring HID collection: HID\VID_046D&PID_C52B&MI_01&COL03\7&1119BFB4&0&0002
[ 0.026608] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 3
[ 0.026672] [00002648] libusb: debug [winusb_get_device_list] unlisted ancestor for 'HID\10251229\3&9D5D338&0&0000' (non USB HID, newly connected, etc.) - ignoring
[ 0.026760] [00002648] libusb: debug [winusb_get_device_list] unlisted ancestor for 'HID\CONVERTEDDEVICE&COL01\5&32CF90E6&0&0000' (non USB HID, newly connected, etc.) - ignoring
[ 0.026832] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 4
[ 0.026880] [00002648] libusb: debug [winusb_get_device_list] setting composite interface for [71]:
[ 0.026926] [00002648] libusb: debug [set_composite_interface] interface[1] already set - ignoring HID collection: HID\VID_046D&PID_C52B&MI_01&COL04\7&1119BFB4&0&0003
[ 0.026982] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 3
[ 0.027044] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 4
[ 0.027091] [00002648] libusb: debug [winusb_get_device_list] setting composite interface for [71]:
[ 0.027138] [00002648] libusb: debug [set_composite_interface] interface[2] = \\?\HID#VID_046D&PID_C52B&MI_02&COL01#7&12BD7E0E&0&0000#{4D1E55B2-F16F-11CF-88CB-001111000030}
[ 0.027195] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 3
[ 0.027255] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 4
[ 0.027302] [00002648] libusb: debug [winusb_get_device_list] setting composite interface for [71]:
[ 0.027349] [00002648] libusb: debug [set_composite_interface] interface[2] already set - ignoring HID collection: HID\VID_046D&PID_C52B&MI_02&COL02\7&12BD7E0E&0&0001
[ 0.027405] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 3
[ 0.027466] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 4
[ 0.027513] [00002648] libusb: debug [winusb_get_device_list] setting composite interface for [71]:
[ 0.027562] [00002648] libusb: debug [set_composite_interface] interface[2] already set - ignoring HID collection: HID\VID_046D&PID_C52B&MI_02&COL03\7&12BD7E0E&0&0002
[ 0.027618] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 3
[ 0.027678] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 4
[ 0.027726] [00002648] libusb: debug [winusb_get_device_list] setting composite interface for [71]:
[ 0.027773] [00002648] libusb: debug [set_composite_interface] interface[0] = \\?\HID#VID_046D&PID_C52B&MI_00#7&34F0FD76&0&0000#{4D1E55B2-F16F-11CF-88CB-001111000030}\KBD
[ 0.027830] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 3
[ 0.028345] [00002648] libusb: debug [get_api_type] driver(s): WUDFRd
[ 0.028464] [00002648] libusb: debug [get_api_type] lower filter driver(s): WinUsb
[ 0.028514] [00002648] libusb: debug [get_api_type] matched lower filter driver name against WinUSB
[ 0.028563] [00002648] libusb: debug [libusb_ref_device] Device 1.0 reference count increased to 9
[ 0.028611] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 8
[ 0.029292] [00002648] libusb: debug [libusb_unref_device] Device 2.2 reference count decreased to 3
[ 0.029404] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 7
[ 0.029452] [00002648] libusb: debug [libusb_unref_device] Device 2.0 reference count decreased to 3
[ 0.029499] [00002648] libusb: debug [libusb_unref_device] Device 1.7 reference count decreased to 2
[ 0.029546] [00002648] libusb: debug [libusb_unref_device] Device 1.3 reference count decreased to 2
[ 0.029641] [00002648] libusb: debug [libusb_unref_device] Device 1.2 reference count decreased to 2
[ 0.029698] [00002648] libusb: debug [libusb_unref_device] Device 1.5 reference count decreased to 2
[ 0.029748] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 2
[ 0.029798] [00002648] libusb: debug [libusb_unref_device] Device 2.3 reference count decreased to 2
[ 0.029844] [00002648] libusb: debug [libusb_unref_device] Device 2.2 reference count decreased to 2
[ 0.029888] [00002648] libusb: debug [libusb_unref_device] Device 2.3 reference count decreased to 1
[ 0.029937] [00002648] libusb: debug [libusb_unref_device] Device 1.2 reference count decreased to 1
[ 0.029990] [00002648] libusb: debug [libusb_unref_device] Device 1.5 reference count decreased to 1
[ 0.030036] [00002648] libusb: debug [libusb_unref_device] Device 1.3 reference count decreased to 1
[ 0.030080] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 6
[ 0.030125] [00002648] libusb: debug [libusb_unref_device] Device 1.7 reference count decreased to 1
[ 0.030176] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 1
[ 0.030231] [00002648] libusb: debug [libusb_unref_device] Device 2.0 reference count decreased to 2
[ 0.030282] [00002648] libusb: debug [libusb_ref_device] Device 2.2 reference count increased to 3
[ 0.030329] [00002648] libusb: debug [libusb_ref_device] Device 2.3 reference count increased to 2
[ 0.030376] [00002648] libusb: debug [libusb_ref_device] Device 1.2 reference count increased to 2
[ 0.030445] [00002648] libusb: debug [libusb_ref_device] Device 1.5 reference count increased to 2
[ 0.030505] [00002648] libusb: debug [libusb_ref_device] Device 1.3 reference count increased to 2
[ 0.030582] [00002648] libusb: debug [libusb_ref_device] Device 1.0 reference count increased to 7
[ 0.030639] [00002648] libusb: debug [libusb_ref_device] Device 1.7 reference count increased to 2
[ 0.030714] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 2
[ 0.030785] [00002648] libusb: debug [libusb_ref_device] Device 2.0 reference count increased to 3
[ 0.030865] [00002648] libusb: debug [libusb_unref_device] Device 2.2 reference count decreased to 2
[ 0.030929] [00002648] libusb: debug [libusb_unref_device] Device 2.3 reference count decreased to 1
[ 0.030980] [00002648] libusb: debug [libusb_unref_device] Device 1.2 reference count decreased to 1
[ 0.031029] [00002648] libusb: debug [libusb_unref_device] Device 1.5 reference count decreased to 1
[ 0.031077] [00002648] libusb: debug [libusb_unref_device] Device 1.3 reference count decreased to 1
[ 0.031125] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 6
[ 0.031173] [00002648] libusb: debug [libusb_unref_device] Device 1.7 reference count decreased to 1
[ 0.031222] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 1
[ 0.031275] [00002648] libusb: debug [libusb_unref_device] Device 2.0 reference count decreased to 2
[ 0.031331] [00002648] libusb: debug [libusb_get_device_descriptor]
Dev (bus 2, device 2): 05E3 - 0612 speed: 5G
[ 0.032935] [00002648] libusb: debug [libusb_open] open 2.2
[ 0.032983] [00002648] libusb: debug [libusb_ref_device] Device 2.2 reference count increased to 3
[ 0.033033] [00002648] libusb: debug [winusb_open] unsupported API call for 'open' (unrecognized device driver)
[ 0.033083] [00002648] libusb: debug [libusb_open] open 2.2 returns -12
[ 0.033130] [00002648] libusb: debug [libusb_unref_device] Device 2.2 reference count decreased to 2
[ 0.033179] [00002648] libusb: debug [libusb_get_device_descriptor]
Dev (bus 2, device 3): 0781 - 5591 speed: 5G
[ 0.034747] [00002648] libusb: debug [libusb_open] open 2.3
[ 0.034799] [00002648] libusb: debug [libusb_ref_device] Device 2.3 reference count increased to 2
[ 0.034848] [00002648] libusb: debug [winusb_open] unsupported API call for 'open' (unrecognized device driver)
[ 0.034901] [00002648] libusb: debug [libusb_open] open 2.3 returns -12
[ 0.034961] [00002648] libusb: debug [libusb_unref_device] Device 2.3 reference count decreased to 1
[ 0.035014] [00002648] libusb: debug [libusb_get_device_descriptor]
Dev (bus 1, device 2): 8087 - 0026 speed: 12M
[ 0.036604] [00002648] libusb: debug [libusb_open] open 1.2
[ 0.036658] [00002648] libusb: debug [libusb_ref_device] Device 1.2 reference count increased to 2
[ 0.036707] [00002648] libusb: debug [winusb_open] unsupported API call for 'open' (unrecognized device driver)
[ 0.036756] [00002648] libusb: debug [libusb_open] open 1.2 returns -12
[ 0.036803] [00002648] libusb: debug [libusb_unref_device] Device 1.2 reference count decreased to 1
[ 0.036852] [00002648] libusb: debug [libusb_get_device_descriptor]
Dev (bus 1, device 5): 04F2 - B6DD speed: 480M
[ 0.038455] [00002648] libusb: debug [libusb_open] open 1.5
[ 0.038502] [00002648] libusb: debug [libusb_ref_device] Device 1.5 reference count increased to 2
[ 0.038553] [00002648] libusb: debug [libusb_open] open 1.5 returns -5
[ 0.038601] [00002648] libusb: debug [libusb_unref_device] Device 1.5 reference count decreased to 1
[ 0.038650] [00002648] libusb: debug [libusb_get_device_descriptor]
Dev (bus 1, device 3): 1C7A - 0575 speed: 480M
[ 0.040352] [00002648] libusb: debug [libusb_open] open 1.3
[ 0.040432] [00002648] libusb: debug [libusb_ref_device] Device 1.3 reference count increased to 2
[ 0.040767] [00002648] libusb: error [winusbx_open] could not open device \\?\USB#VID_1C7A&PID_0575#077E2F9A#{A5DCBF10-6530-11D2-901F-00C04FB951ED} (interface 0): [5] Access is denied.
[ 0.040883] [00002648] libusb: debug [libusb_open] open 1.3 returns -3
[ 0.040943] [00002648] libusb: debug [libusb_unref_device] Device 1.3 reference count decreased to 1
[ 0.040993] [00002648] libusb: debug [libusb_get_device_descriptor]
Dev (bus 1, device 0): 8086 - A0ED speed: 5G
[ 0.042541] [00002648] libusb: debug [libusb_open] open 1.0
[ 0.042595] [00002648] libusb: debug [libusb_ref_device] Device 1.0 reference count increased to 7
[ 0.042646] [00002648] libusb: debug [winusb_open] unsupported API call for 'open' (unrecognized device driver)
[ 0.042695] [00002648] libusb: debug [libusb_open] open 1.0 returns -12
[ 0.042742] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 6
[ 0.042790] [00002648] libusb: debug [libusb_get_device_descriptor]
Dev (bus 1, device 7): 05E3 - 0610 speed: 480M
[ 0.044406] [00002648] libusb: debug [libusb_open] open 1.7
[ 0.044453] [00002648] libusb: debug [libusb_ref_device] Device 1.7 reference count increased to 2
[ 0.044500] [00002648] libusb: debug [winusb_open] unsupported API call for 'open' (unrecognized device driver)
[ 0.044548] [00002648] libusb: debug [libusb_open] open 1.7 returns -12
[ 0.044594] [00002648] libusb: debug [libusb_unref_device] Device 1.7 reference count decreased to 1
[ 0.044641] [00002648] libusb: debug [libusb_get_device_descriptor]
Dev (bus 1, device 1): 046D - C52B speed: 12M
[ 0.046252] [00002648] libusb: debug [libusb_open] open 1.1
[ 0.046316] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 2
[ 0.046386] [00002648] libusb: warning [hid_open] could not open HID device in R/W mode (keyboard or mouse?) - trying without
[ 0.046465] [00002648] libusb: warning [hid_open] could not open HID device in R/W mode (keyboard or mouse?) - trying without
[ 0.046649] [00002648] libusb: debug [hid_open] set maximum input buffer size to 512
[ 0.046733] [00002648] libusb: debug [hid_open] 0 HID input report value(s) found
[ 0.046785] [00002648] libusb: debug [hid_open] 0 HID output report value(s) found
[ 0.046833] [00002648] libusb: debug [hid_open] 0 HID feature report value(s) found
[ 0.047641] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 3
[ 0.047745] [00002648] libusb: debug [libusb_submit_transfer] transfer 0000021ee1512a60
[ 0.047797] [00002648] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.047849] [00002648] libusb: debug [composite_submit_control_transfer] trying to skip restricted interface #0 (HID keyboard or mouse?)
[ 0.047899] [00002648] libusb: debug [composite_submit_control_transfer] trying to skip restricted interface #1 (HID keyboard or mouse?)
[ 0.047948] [00002648] libusb: debug [composite_submit_control_transfer] using interface 2
[ 0.047996] [00002648] libusb: debug [libusb_claim_interface] interface 0
[ 0.048043] [00002648] libusb: debug [hid_claim_interface] claimed interface 0
[ 0.048095] [00002648] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 0.048144] [00002648] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 0.048192] [00002648] libusb: debug [hid_submit_control_transfer] will use interface 0
[ 0.048240] [00002648] libusb: debug [_hid_get_descriptor] LIBUSB_DT_STRING
[ 0.048287] [00002648] libusb: debug [windows_force_sync_completion] transfer 0000021ee1512a60, length 4
[ 0.048342] [00002648] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.048395] [00002648] libusb: debug [handle_events] event sources modified, reallocating event data
[ 0.048450] [00002648] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 0.048343] [000035e0] libusb: debug [windows_iocp_thread] transfer 0000021ee1512a60 completed, length 4
[ 0.048565] [00002648] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 0.048616] [00002648] libusb: debug [handle_event_trigger] event triggered
[ 0.048663] [00002648] libusb: debug [windows_handle_transfer_completion] handling transfer 0000021ee1512a60 completion with errcode 0, length 4
[ 0.048714] [00002648] libusb: debug [libusb_release_interface] interface 0
[ 0.048761] [00002648] libusb: debug [auto_release] auto-released interface 0
[ 0.048809] [00002648] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.048858] [00002648] libusb: debug [usbi_handle_transfer_completion] transfer 0000021ee1512a60 has callback 00007ffb601992c0
[ 0.048907] [00002648] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.048955] [00002648] libusb: debug [libusb_free_transfer] transfer 0000021ee1512a60
[ 0.049003] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 2
[ 0.049052] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 3
[ 0.049100] [00002648] libusb: debug [libusb_submit_transfer] transfer 0000021ee1512a60
[ 0.049150] [00002648] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.049199] [00002648] libusb: debug [composite_submit_control_transfer] trying to skip restricted interface #0 (HID keyboard or mouse?)
[ 0.049255] [00002648] libusb: debug [composite_submit_control_transfer] trying to skip restricted interface #1 (HID keyboard or mouse?)
[ 0.049337] [00002648] libusb: debug [composite_submit_control_transfer] using interface 2
[ 0.049397] [00002648] libusb: debug [libusb_claim_interface] interface 0
[ 0.049449] [00002648] libusb: debug [hid_claim_interface] claimed interface 0
[ 0.049512] [00002648] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 0.049564] [00002648] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 0.049608] [00002648] libusb: debug [hid_submit_control_transfer] will use interface 0
[ 0.049663] [00002648] libusb: debug [_hid_get_descriptor] LIBUSB_DT_STRING
[ 0.049711] [00002648] libusb: debug [windows_force_sync_completion] transfer 0000021ee1512a60, length 18
[ 0.049758] [00002648] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.049814] [00002648] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 0.049762] [000035e0] libusb: debug [windows_iocp_thread] transfer 0000021ee1512a60 completed, length 18
[ 0.049939] [00002648] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 0.049986] [00002648] libusb: debug [handle_event_trigger] event triggered
[ 0.050031] [00002648] libusb: debug [windows_handle_transfer_completion] handling transfer 0000021ee1512a60 completion with errcode 0, length 18
[ 0.050077] [00002648] libusb: debug [libusb_release_interface] interface 0
[ 0.050121] [00002648] libusb: debug [auto_release] auto-released interface 0
[ 0.050164] [00002648] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.050210] [00002648] libusb: debug [usbi_handle_transfer_completion] transfer 0000021ee1512a60 has callback 00007ffb601992c0
[ 0.050258] [00002648] libusb: debug [sync_transfer_cb] actual_length=18
[ 0.050306] [00002648] libusb: debug [libusb_free_transfer] transfer 0000021ee1512a60
[ 0.050351] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 2
  Manufacturer:              Logitech
[ 0.051809] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 3
[ 0.051864] [00002648] libusb: debug [libusb_submit_transfer] transfer 0000021ee1512a60
[ 0.051912] [00002648] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.051963] [00002648] libusb: debug [composite_submit_control_transfer] trying to skip restricted interface #0 (HID keyboard or mouse?)
[ 0.052016] [00002648] libusb: debug [composite_submit_control_transfer] trying to skip restricted interface #1 (HID keyboard or mouse?)
[ 0.052065] [00002648] libusb: debug [composite_submit_control_transfer] using interface 2
[ 0.052114] [00002648] libusb: debug [libusb_claim_interface] interface 0
[ 0.052168] [00002648] libusb: debug [hid_claim_interface] claimed interface 0
[ 0.052219] [00002648] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 0.052270] [00002648] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 0.052317] [00002648] libusb: debug [hid_submit_control_transfer] will use interface 0
[ 0.052365] [00002648] libusb: debug [_hid_get_descriptor] LIBUSB_DT_STRING
[ 0.052413] [00002648] libusb: debug [windows_force_sync_completion] transfer 0000021ee1512a60, length 4
[ 0.052475] [00002648] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.052535] [00002648] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 0.052479] [000035e0] libusb: debug [windows_iocp_thread] transfer 0000021ee1512a60 completed, length 4
[ 0.052652] [00002648] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 0.052704] [00002648] libusb: debug [handle_event_trigger] event triggered
[ 0.052752] [00002648] libusb: debug [windows_handle_transfer_completion] handling transfer 0000021ee1512a60 completion with errcode 0, length 4
[ 0.052802] [00002648] libusb: debug [libusb_release_interface] interface 0
[ 0.052849] [00002648] libusb: debug [auto_release] auto-released interface 0
[ 0.052897] [00002648] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.052946] [00002648] libusb: debug [usbi_handle_transfer_completion] transfer 0000021ee1512a60 has callback 00007ffb601992c0
[ 0.052994] [00002648] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.053042] [00002648] libusb: debug [libusb_free_transfer] transfer 0000021ee1512a60
[ 0.053089] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 2
[ 0.053137] [00002648] libusb: debug [libusb_ref_device] Device 1.1 reference count increased to 3
[ 0.053185] [00002648] libusb: debug [libusb_submit_transfer] transfer 0000021ee1512a60
[ 0.053232] [00002648] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.053281] [00002648] libusb: debug [composite_submit_control_transfer] trying to skip restricted interface #0 (HID keyboard or mouse?)
[ 0.053330] [00002648] libusb: debug [composite_submit_control_transfer] trying to skip restricted interface #1 (HID keyboard or mouse?)
[ 0.053378] [00002648] libusb: debug [composite_submit_control_transfer] using interface 2
[ 0.053424] [00002648] libusb: debug [libusb_claim_interface] interface 0
[ 0.053471] [00002648] libusb: debug [hid_claim_interface] claimed interface 0
[ 0.053521] [00002648] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 0.053570] [00002648] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 0.053619] [00002648] libusb: debug [hid_submit_control_transfer] will use interface 0
[ 0.053667] [00002648] libusb: debug [_hid_get_descriptor] LIBUSB_DT_STRING
[ 0.053714] [00002648] libusb: debug [windows_force_sync_completion] transfer 0000021ee1512a60, length 26
[ 0.053764] [00002648] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.053819] [00002648] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 0.053768] [000035e0] libusb: debug [windows_iocp_thread] transfer 0000021ee1512a60 completed, length 26
[ 0.053933] [00002648] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 0.053984] [00002648] libusb: debug [handle_event_trigger] event triggered
[ 0.054033] [00002648] libusb: debug [windows_handle_transfer_completion] handling transfer 0000021ee1512a60 completion with errcode 0, length 26
[ 0.054083] [00002648] libusb: debug [libusb_release_interface] interface 0
[ 0.054130] [00002648] libusb: debug [auto_release] auto-released interface 0
[ 0.054177] [00002648] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.054226] [00002648] libusb: debug [usbi_handle_transfer_completion] transfer 0000021ee1512a60 has callback 00007ffb601992c0
[ 0.054275] [00002648] libusb: debug [sync_transfer_cb] actual_length=26
[ 0.054322] [00002648] libusb: debug [libusb_free_transfer] transfer 0000021ee1512a60
[ 0.054374] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 2
  Product:                   USB Receiver
[ 0.055838] [00002648] libusb: debug [libusb_close]
[ 0.055921] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 1
[ 0.055970] [00002648] libusb: debug [libusb_get_device_descriptor]
Dev (bus 2, device 0): 8086 - 9A13 speed: 5G
[ 0.057523] [00002648] libusb: debug [libusb_open] open 2.0
[ 0.057570] [00002648] libusb: debug [libusb_ref_device] Device 2.0 reference count increased to 3
[ 0.057620] [00002648] libusb: debug [winusb_open] unsupported API call for 'open' (unrecognized device driver)
[ 0.057669] [00002648] libusb: debug [libusb_open] open 2.0 returns -12
[ 0.057715] [00002648] libusb: debug [libusb_unref_device] Device 2.0 reference count decreased to 2
[ 0.057763] [00002648] libusb: debug [libusb_unref_device] Device 2.2 reference count decreased to 1
[ 0.057810] [00002648] libusb: debug [libusb_unref_device] Device 2.3 reference count decreased to 0
[ 0.057858] [00002648] libusb: debug [libusb_unref_device] destroy device 2.3
[ 0.057906] [00002648] libusb: debug [libusb_unref_device] Device 2.2 reference count decreased to 0
[ 0.057953] [00002648] libusb: debug [libusb_unref_device] destroy device 2.2
[ 0.058001] [00002648] libusb: debug [libusb_unref_device] Device 2.0 reference count decreased to 1
[ 0.058056] [00002648] libusb: debug [libusb_unref_device] Device 1.2 reference count decreased to 0
[ 0.058104] [00002648] libusb: debug [libusb_unref_device] destroy device 1.2
[ 0.058150] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 5
[ 0.058199] [00002648] libusb: debug [libusb_unref_device] Device 1.5 reference count decreased to 0
[ 0.058247] [00002648] libusb: debug [libusb_unref_device] destroy device 1.5
[ 0.058295] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 4
[ 0.058343] [00002648] libusb: debug [libusb_unref_device] Device 1.3 reference count decreased to 0
[ 0.058390] [00002648] libusb: debug [libusb_unref_device] destroy device 1.3
[ 0.058436] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 3
[ 0.058490] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 2
[ 0.058537] [00002648] libusb: debug [libusb_unref_device] Device 1.7 reference count decreased to 0
[ 0.058584] [00002648] libusb: debug [libusb_unref_device] destroy device 1.7
[ 0.058632] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 1
[ 0.058681] [00002648] libusb: debug [libusb_unref_device] Device 1.1 reference count decreased to 0
[ 0.058729] [00002648] libusb: debug [libusb_unref_device] destroy device 1.1
[ 0.058776] [00002648] libusb: debug [libusb_unref_device] Device 1.0 reference count decreased to 0
[ 0.058824] [00002648] libusb: debug [libusb_unref_device] destroy device 1.0
[ 0.058874] [00002648] libusb: debug [libusb_unref_device] Device 2.0 reference count decreased to 0
[ 0.058922] [00002648] libusb: debug [libusb_unref_device] destroy device 2.0
[ 0.058971] [00002648] libusb: debug [libusb_exit] destroying default context
[ 0.059026] [000035e0] libusb: debug [windows_iocp_thread] I/O completion thread exiting
[ 0.059449] [00002648] libusb: debug [usbi_remove_event_source] remove HANDLE 00000000000000b4
[ 0.059511] [00002648] libusb: debug [usbi_remove_event_source] remove HANDLE 00000000000000b0

mcuee avatar Mar 31 '23 13:03 mcuee

More debug logs are here, for Linux, macOS and Windows. It seems to me that libusb has no issues. It is just the cleanup is at the end. So if you print the reference count in the middle, it may seem to have an issue. But I have not tried to hotplug stuff.

  • https://github.com/libusb/libusb/issues/988

@Oldanko Please post the debug log to see if there is a real issue or not. Thanks. You may want to try my patch as well to print the increase/decrease of the reference count in detail.

mcuee avatar Apr 02 '23 12:04 mcuee

I can see this problem on Windows: I poll the device list frequently (all 100-500 ms) to detect new devices. When a device is opened and is closed after polling the device list in between then the reference count of the hubs is not decremented correctly and we get the error "device still referenced" on libusb_close.

// LibusbTest.cpp : 

#include <iostream>
#include <stdio.h>
#include "libusb.h"

void* my_device = NULL;
libusb_context* libusbContext = nullptr;
libusb_device** devList = nullptr;

void LIBUSB_CALL libusb_log_callback( libusb_context* ctx, enum libusb_log_level level, const char* str )
{
    if (ctx!=NULL )
        return;
    std::cout << str;
}

int poll_devices( int* devCount)
{
    *devCount = libusb_get_device_list( libusbContext, &devList );
    if ( *devCount <= 0 )
    {
        libusb_exit( libusbContext );
        return -1;
    }

    void* help;
    int my_cnt = 0;
    unsigned char dummy_str[255];

    for ( int i = 0; i < *devCount; ++i )
    {
        libusb_device_descriptor desc;
        libusb_device_handle* handle = nullptr;
        libusb_get_device_descriptor( devList[i], &desc );

        if ( (my_device == NULL) && (i>0) )
        {
            // we have found our device and we open it now. for real usage we are looking for vendor and product.
            if ( libusb_open( devList[i], &handle ) != LIBUSB_SUCCESS )
                continue;
            my_device = handle;
            std::cout << "DEVICE_" << i << ":0x" << std::hex << handle << " V:" << std::hex << desc.idVendor << "\r\n";
        }
    }
    libusb_free_device_list( devList, 1 );
    return 0;
}


int main()
{
    if ( libusb_init( &libusbContext ) != LIBUSB_SUCCESS )
        return -1;

    libusb_set_log_cb( libusbContext, libusb_log_callback, LIBUSB_LOG_CB_CONTEXT );  // LIBUSB_LOG_CB_GLOBAL |
    libusb_set_option( libusbContext, LIBUSB_OPTION_LOG_LEVEL, LIBUSB_LOG_LEVEL_DEBUG );

    int devCount = 0;
    for ( int i = 0; i<10; i++ )
    {
        int error = poll_devices( &devCount );
        if ( error < 0 )
            return -1;
        Sleep( 100 );
    }
  
    if ( my_device )
    {
        std::cout << "close my device";
        libusb_close( (libusb_device_handle*)my_device);
    }

    libusb_exit( libusbContext );
}

wbnov avatar May 25 '23 15:05 wbnov

@wbnov

I can reproduce your issue (device still referenced warning messages`) with your test code under Windows 10 and latest git.

But if I carry out a minor change and it will be okay under Windows. I tend to think your test code is not right since libusb_open and libusb_close have to match.

$ diff -u libusbtest_1165.cpp libusbtest_1165mod.cpp
--- libusbtest_1165.cpp 2023-05-31 11:30:16.564270800 +0800
+++ libusbtest_1165mod.cpp      2023-05-31 13:56:09.879722500 +0800
@@ -41,6 +41,8 @@
                 continue;
             my_device = handle;
             std::cout << "DEVICE_" << i << ":0x" << std::hex << handle << " V:" << std::hex << desc.idVendor << "\r\n";
+                       std::cout << "close my device";
+                       libusb_close( (libusb_device_handle*)my_device);
         }
     }
     libusb_free_device_list( devList, 1 );
@@ -64,12 +66,6 @@
             return -1;
         Sleep( 100 );
     }
-
-    if ( my_device )
-    {
-        std::cout << "close my device";
-        libusb_close( (libusb_device_handle*)my_device);
-    }

     libusb_exit( libusbContext );
 }

mcuee avatar May 31 '23 05:05 mcuee

@wbnov

Please try my modification to see it works for you or not. Thanks.

mcuee avatar May 31 '23 06:05 mcuee

The purpose of this program is to keep my devices open to work with them and close them after work is done. That is normally after days or month. So I use frequently polling for devices with my vendor and product id with libusb_get_device_list. If a new device that I need is found it is opened (libusb_open) and is kept open until my program is closed. And that is outside the loop of detecting devices and hence after libusb_free_device_list(). So I cannot use that modification.

wbnov avatar May 31 '23 07:05 wbnov

The purpose of this program is to keep my devices open to work with them and close them after work is done. That is normally after days or month. So I use frequently polling for devices with my vendor and product id with libusb_get_device_list. If a new device that I need is found it is opened (libusb_open) and is kept open until my program is closed. And that is outside the loop of detecting devices and hence after libusb_free_device_list(). So I cannot use that modification.

I see, I believe your issue will be sorted out if hotplig is supported under Windows. Unfortunately due to lack of Windows developers, hotplug will not be ready for Windows any time soon.

  • https://github.com/libusb/libusb/issues/86

Sorry but I can not offer more help to you in this case. You may have to live with the limitations for now.

@tormodvolden Just wonder if you have some other suggestions.

mcuee avatar May 31 '23 11:05 mcuee

@mcuee For now I have added some code to free all remaining devices on libusb_exit. So there are no remaining memory leaks. I think this could help many other users because polling the device list and then using dedicated devices is commonly used. Maybe you could add this repairing to the repository.

usbi_hotplug_exit( _ctx );
usbi_io_exit( _ctx );

/* now free all remaining devices
 *   because of a bug in libusb some hubs remain referenced  */
for (int cnt = 0; cnt < 100; cnt++)
{
	if (list_empty( &(ctx)->usb_devs ))
		break;
	for_each_device( _ctx, dev ) {
		usbi_warn( _ctx, "device %d.%d still referenced - free here",
			dev->bus_number, dev->device_address );
		if (usbi_backend.destroy_device)
			usbi_backend.destroy_device( dev );
		list_del( &dev->list );
		DEVICE_CTX( dev ) = NULL;
		free( dev );
		break;
	}
}

wbnov avatar Jul 21 '23 09:07 wbnov

Maybe you could add this repairing to the repository.

@wbnov

Please create a PR. Thanks.

mcuee avatar Jul 26 '23 01:07 mcuee

@tormodvolden

How do you like the ideas mentioned by @wbnov? Thanks.

mcuee avatar Oct 09 '23 05:10 mcuee