libusb icon indicating copy to clipboard operation
libusb copied to clipboard

Windows: Freezing in Kernel with libusb-win32

Open sonatique opened this issue 1 year ago • 98 comments

And does this mean that, even if a given device is "officially" using libusb0 (i.e. libusb0.sys, libusb0.dll reported by Device Manager), then in the end all functions of winusb_interface are backed by libusbK implementation and none of libusb0 code will be called?

I am having this understanding based on this code snippet from windows_winsub.c, funciton winusbx_init, line 2505:

// NB: The below for loop works because the sub_api value for WinUSB
// is a higher value than that of libusbK and libusb0
for (; sub_api < SUB_API_WINUSB; sub_api++) {
    libusbK_Set(sub_api, AbortPipe, true);
    libusbK_Set(sub_api, ControlTransfer, true);
    libusbK_Set(sub_api, FlushPipe, true);
    libusbK_Set(sub_api, Free, true);
    libusbK_Set(sub_api, GetAssociatedInterface, true);
    libusbK_Set(sub_api, Initialize, true);
    libusbK_Set(sub_api, ReadPipe, true);
    libusbK_Set(sub_api, ResetPipe, true);
    libusbK_Set(sub_api, SetCurrentAlternateSetting, true);
    libusbK_Set(sub_api, SetPipePolicy, true);
    libusbK_Set(sub_api, WritePipe, true);
//etc.

sub_api takes value from 0 to 1, i.e. SUB_API_LIBUBSK and SUB_API_LIBUSB0, meanig that function pointers corresponding to libusb0 are actually pointing to libusbK.

Thank you in advance for your help understanding this. Best regards.

sonatique avatar Mar 01 '23 12:03 sonatique

libusb0.dll (libusb-win32 API) library is not used. libusbK.dll will talk to libusb0.sys directly through IOCTLs. libusbK.sys (KMDF based) supports all the IOCTLs from libusb0.sys (WDM based). https://github.com/mcuee/libusbk/blob/master/libusbK/src/drv_api.h

Does the following Wiki FAQ entry answer your question? https://github.com/libusb/libusb/wiki/FAQ#user-content-libusbwin32_libusbK_and_libusb_project_what_about_openusb

  1. WinUSB.sys kernel driver from Microsoft, through WinUSB.dll from Microsoft (if libusbK.dll is not present), or through libusbK.dll from libusbK project if libusbK.dll is present. libusb-1.0.dll --> WinUSB.dll --> WinUSB.sys (if libusbK.dll is not present) libusb-1.0.dll --> libusbK.dll --> WinUSB.dll --> WinUSB.sys

Edit --> Wiki updated. For libusb 1.0.24 onwards, it is alway use the following scheme, regardless of the presence of libusbK.dll. libusb-1.0.dll --> WinUSB.dll --> WinUSB.sys

  1. libusbK.sys kernel driver from libusbK project, through libusbK.dll libusb-1.0.dll --> libusbK.dll --> libusbK.sys

  2. libusb0.sys kernel driver from libusb-win32 project, through libusbK.dll from libusbK project libusb-1.0.dll --> libusbK.dll --> libusb0.sys

mcuee avatar Mar 01 '23 12:03 mcuee

Hello, thank you for your prompt response. Sorry that I missed the Wiki FAQ. Yes I got my answers, thank you.

The reason behind it is that I have an issue with libusb_clear_halt: when called to a libusb0.sys device, it sometimes freeze completely, making the whole process unkillable. I am trying to understand where in the call it freezes exactly and started by looking at libusb sources.

But then I guess I shall have a look a libusbK so start with.

sonatique avatar Mar 01 '23 12:03 sonatique

Just wondering what is the version of libusb0.sys are you using? You may want to try the latest 1.2.7.3 release if you are still using the older libusb0.sys 1.2.6.0 version.

Does the problem occure if you switch to WinUSB driver or libusbK.sys driver? If you suspect libusbK.dll issue, you may want to remove libusbK.dll and use WinUSB driver to try it out.

Another thing, some devices may choke at libusb_clear_halt due to FW bugs (eg: USB data toggle) problem and may need libusb_reset to go back to the normal state.

mcuee avatar Mar 01 '23 12:03 mcuee

Hello @mcuee : I am using 1.2.7.3 indeed. And this behavior is happening with plain physical Windows (in case you wonder if I am on virtual machine, since I posted PR #1202 .

I still need to test with switching drivers indeed, though it is currently not an option to use them for real, beside for testing.

And yes: I am pretty sure that there is some bugs in the device FW. Right before I get a freezing clear_halt I can see failed ControlTransfer (out), that should not happen.

What I see is that as soon as I have a failed ControlTransfer, the next clear_halt will freeze for ever.

My problem is that I currently don't have access to the FW, so fixing the bug is not an option. I am writing complicated code to detect the failure condition and try a way to reset the device withtout freezing or causing other issues on the software side.

However, I feel like having a function that can freeze so hard that it prevent even Task Manager from killing its calling process, with no way of cancelling it, is not something that is desirable in general.

I don't understand why clear_halt could not return with an error if it can not do its task in a reasonable amount of time. And I didn't test yet, but I am pretty sure (based on what I observed so far) that reset_device would freeze as well.

Did I miss something in the API that could either let me specify a timeout for those functions, or let me call another function to cancel them?

sonatique avatar Mar 01 '23 14:03 sonatique

Interesting. However buggy the device is, this shouldn't freeze the program or the machine if a timeout* is given.

There are some parts in libusb0.sys, especially the error paths, that I am unsure about. Do you have the WDK so that you can build and test patched drivers? Can you reproduce this in a VM (would be nice for such tests)?

*) if not in the high-level API, there should be some timeout /somewhere/. libusb0.sys uses the timeout specified in the IOCTL, also for clear_feature.

tormodvolden avatar Mar 01 '23 18:03 tormodvolden

Thank you for your interest in my issue. "However buggy the device is, this shouldn't freeze the program": yes, that's my point, I am happy that we agree.

As for now I am working on finding a workaround at the application level, that's the priority.

But in parallel I will swap drivers to better understand who is responsible for this behavior, and in the end decide whether I could try to fix it or rather change driver for good. I should be able to build patched libusb0.sys versions if it happens that this code is where the freeze occurs.

For reference: my device is made of a FX3 connected to a Zynq. The issue happen when the Zynq is power-cycled while the FX3 is kept alive. It occurs with a probabily of 1/5 approximately, so there is probably some dependency of the exact timing of the events.

Also, I just noticed that I have the same issue with various devices when I hiibernate my computer, remove the devices, then wake it up: it seems that some part of the library / driver do not realize what just happened and go on with the tasks they were doing. If I call clear_halt at this point, it will freeze 100% of the times.

sonatique avatar Mar 02 '23 08:03 sonatique

I am wondering whether the "freezes" I experience are somehow related to what is described in https://github.com/libusb/libusb/pull/1127 . I will try with the code proposed in this PR as well.

sonatique avatar Mar 05 '23 21:03 sonatique

@sonatique

Any updates on this issue? Thanks.

mcuee avatar Aug 15 '23 23:08 mcuee

@mcuee : Regarding the "freeze": I should soon be able to reproduce it and study it more in depth. I'll keep you posted

sonatique avatar Aug 22 '23 13:08 sonatique

@mcuee : So I have been able to reproduce a similar issue, quite easily actually. I made a while(1){...} loop issuing libusb_control_transfer of type Out|Vendor|Device to a previously open device. The detail of the transfer doesn't really matter but it corresponds to a command that is supported by the physical device (FX2). In this loop I also print the return value if < 0.

I start the program, I can see that control transfer out are correctly transmitted and received, then I simply disconnect the USB cable (physically).

The behavior that occurs depends on the driver used. With libusb0.sys 1.2.7.3, the next transfer will fail with error code LIBUSB_ERROR_IO, but the next one will completely freeze the program. Since I am launching my program from Visual Studio I can break. I see that the program is stuck in the call at line 3157 of windows_winusb.c if (!WinUSBX[sub_api].ControlTransfer(winusb_handle, *setup ... and I can see that it is somewhere in libusbK.dll.

From there I have an unkillable process that will stay there until I reboot the OS.

Using kernel debugger I can see that it is frozen somewhere within libusb0:

0: kd> !process 0 7 sam3u_benchmark.exe
PROCESS ffffb38cbaec2080
    SessionId: 1  Cid: 6adc    Peb: e03fc78000  ParentCid: 5924
    DirBase: 6b7b63002  ObjectTable: ffff9d02c8118cc0  HandleCount:   2.
    Image: sam3u_benchmark.exe
    VadRoot ffffb38cbaddf300 Vads 53 Clone 0 Private 324. Modified 259. Locked 0.
    DeviceMap ffff9d02a64ea090
    Token                             ffff9d02c9093060
    ElapsedTime                       01:14:28.309
    UserTime                          00:00:00.046
    KernelTime                        00:00:00.046
    QuotaPoolUsage[PagedPool]         107520
    QuotaPoolUsage[NonPagedPool]      7456
    Working Set Sizes (now,min,max)  (1532, 50, 345) (6128KB, 200KB, 1380KB)
    PeakWorkingSetSize                1885
    VirtualSize                       4183 Mb
    PeakVirtualSize                   4188 Mb
    PageFaultCount                    2017
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      535

        THREAD ffffb38cbaac1080  Cid 6adc.4274  Teb: 000000e03fc79000 Win32Thread: ffffb38cbadd08f0 WAIT: (Executive) KernelMode Non-Alertable
            ffffae0f7001b5f0  NotificationEvent
        IRP List:
            ffffb38cba1b6a20: (0006,0508) Flags: 00060030  Mdl: 00000000
        Not impersonating
        DeviceMap                 ffff9d02a64ea090
        Owning Process            ffffb38cbaec2080       Image:         sam3u_benchmark.exe
        Attached Process          N/A            Image:         N/A
        Wait Start TickCount      402061
        Context Switch Count      7847           IdealProcessor: 2
        UserTime                  00:00:00.250
        KernelTime                00:00:00.078
        Win32 Start Address 0x00007ff6c81234f4
        Stack Init ffffae0f7001bc90 Current ffffae0f7001b1d0
        Base ffffae0f7001c000 Limit ffffae0f70016000 Call 0000000000000000
        Priority 8 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
        Child-SP          RetAddr           : Args to Child                                                           : Call Site
        ffffae0f`7001b210 fffff802`4fc1bca0 : 00000000`00000008 00000000`ffffffff 00000000`00000000 ffffb38c`a9187158 : nt!KiSwapContext+0x76
        ffffae0f`7001b350 fffff802`4fc1b1cf : 00000801`000005fd 00000000`00000000 ffffae0f`7001b510 00000000`00000000 : nt!KiSwapThread+0x500
        ffffae0f`7001b400 fffff802`4fc1aa73 : ffffae0f`00000000 00000000`00000000 00000000`00000300 ffffb38c`baac11c0 : nt!KiCommitThreadWait+0x14f
        ffffae0f`7001b4a0 fffff802`8e363f2a : ffffae0f`7001b5f0 00000000`00000000 ffffae0f`7001b600 00000000`00000000 : nt!KeWaitForSingleObject+0x233
        ffffae0f`7001b590 fffff802`8e36713e : 001f0003`ffff0000 fffff802`8e369b50 ffffae0f`7001b7e0 00000000`00000000 : libusb0+0x3f2a
        ffffae0f`7001b620 fffff802`8e362bc0 : ffffb38c`ba8ce1a0 00000000`00000000 ffffb38c`ba8ce1a0 ffffb38c`9bfeca00 : libusb0+0x713e
        ffffae0f`7001b720 fffff802`8e3614b9 : 00000000`00000002 ffffb38c`ba1b6a20 00000000`00000000 00000000`00000000 : libusb0+0x2bc0
        ffffae0f`7001b7d0 fffff802`4fc10665 : ffffb38c`b9034500 00000000`00000000 ffffae0f`20206f49 00000000`00000020 : libusb0+0x14b9
        ffffae0f`7001b800 fffff802`50000fec : 00000000`00000002 00000000`00000000 ffffb38c`b9034500 ffffb38c`baec2080 : nt!IofCallDriver+0x55
        ffffae0f`7001b840 fffff802`50000c41 : ffffb38c`ba1b6e98 ffffae0f`7001bb80 00000000`00040005 ffffb38c`ba1b6e98 : nt!IopSynchronousServiceTail+0x34c
        ffffae0f`7001b8e0 fffff802`4fffffb6 : 00000000`00000000 00000000`000002fc 00000000`00000000 000000e0`3feff890 : nt!IopXxxControlFile+0xc71
        ffffae0f`7001ba20 fffff802`4fe105f8 : ffffb38c`baac1080 000000e0`3feff7b8 ffffae0f`7001baa8 00000000`00000000 : nt!NtDeviceIoControlFile+0x56
        ffffae0f`7001ba90 00007ffc`d950cf34 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt!KiSystemServiceCopyEnd+0x28 (TrapFrame @ ffffae0f`7001bb00)
        000000e0`3feff788 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : 0x00007ffc`d950cf34


0: kd> !processirps ffffb38cbaec2080
**** PROCESS ffffb38cbaec2080 (Image: sam3u_benchmar) ****

Checking threads for IRPs.

  Thread ffffb38cbaac1080:

    IRP ffffb38cba1b6a20 - Owned by \Driver\libusb0 for device libusb00001 (ffffb38cba8ce050)

Checking file objects for IRPs.

I tried to have a look at libusb-win32 source code, but so far I didn't understand exactly what is the issue, and I doubt I will.

Using Zadig to replace driver by either WinUSB or libusbK and trying the same experiment result in no freeze at all: after I unplugged the USB cable, libusb_control_transfer simply returns LIBUSB_ERROR_NOT_FOUND .

So, it is not exactly the issue with libusb_clear_halt, but it shows that there is a problem with libusb0.sys, I guess

I think this also shows that there is no real problem with libsub-1.0 itself.

sonatique avatar Sep 19 '23 09:09 sonatique

I am wondering whether this https://github.com/libusb/libusb/pull/1018 may help, I will give it a try

sonatique avatar Sep 19 '23 09:09 sonatique

I don't think 1018 will help for the kernel hang, but it is in any case appreciated if you test that PR. I notice your kernel dump is stuck in KeWaitForSingleObject() which is called from the libusb.sys parts that I mentioned above. From looking at the code I had a suspicion that the IRP locking is not done properly and there is a chance of races or deadlocks. I started working on some patches (based on the MS documentation) but haven't been able to test them myself. I could compile it with the WDK but didn't figure out the installation part. I can push this to an experimental libusb.sys PR and hope someone can look at it or test it.

tormodvolden avatar Sep 19 '23 10:09 tormodvolden

@tormodvolden : thank you. I can try to build a patched libusb0.sys and try again, or better just try to replace mine with your built libusb0.sys. I'll do this soon.

sonatique avatar Sep 19 '23 10:09 sonatique

@tormodvolden : would you mind attaching a built libusb0.sys containing your latest patch somewhere? Thanks in advance!

sonatique avatar Sep 19 '23 10:09 sonatique

@dontech Please help to look at this issue and https://github.com/mcuee/libusb-win32/pull/38, when you got the time. Thanks.

mcuee avatar Sep 19 '23 10:09 mcuee

I don't think 1018 will help for the kernel hang, but it is in any case appreciated if you test that PR....

Ok, no, it doesn't help with kernel hang, but I get 2 control transfer fails (with ERROR_IO) before the freeze ;-)

I was hoping that the windows_force_sync_completion that you added in case of failure could help putting the driver back on track. Maybe it does a little bit but not enough

Apart from this I see no difference under normal behavior in between master and your PR. I guess this is good..

sonatique avatar Sep 19 '23 11:09 sonatique

@sonatique : This should be the patched libusb.sys. I also included the other build artifacts (from running make_all.bat in libusb/ddk_make in a "Windows Win7 x64 Free Build Environment" window).

libusb-win32-PR38.zip

I have done minimal testing of the patched libusb.sys with xusb just to see that it works and doesn't BSOD (copied the file into system32/drivers in a Recovery Command Line window and rebooted with "Disable driver signature enforcement").

tormodvolden avatar Sep 19 '23 11:09 tormodvolden

@tormodvolden : so I tested your patched libusb0.sys by replacing my current one with yours (and of course rebooting with disabled driver signature enforcement). I then repeated the exact same procedure as described above: instead of kernal hang now I get:

  1. at the instant when I disconnect the cable: ERROR_IO once (like before)
  2. then ERROR_NO_DEVICE 5 times
  3. then OK again.

So very good improvement since no hang at all, but still strange behavior I think: While 1 and 2 seems OK to me, perfectly making sens with respect to the situation, I am puzzled by the fact that calls resume to returning OK when there is no longer a cable connected to any devices. Worse is that the returned value is 8, i.e. the expected written byte count of my request (that I correctly get as well before disconnecting).

I thank you very much for this attempt, and for sure it goes into the right direction, but I think it is not usable as is since it could fool the application into thinking everything is fine when there are no longer any device attached.

Anyway this "disable driver signature enforcement" thing makes me think we are doomed: we cannot any longer use driver that we built ourselves (I am yes we could use them but not distribute them, etc.), so basically we are stuck with staying with driver we built before the change in requirements made by MS, or switch to using WinUSB.... This basically makes any futur special driver development meaningless, expect maybe for niche/hobby things. What do you think?

sonatique avatar Sep 19 '23 15:09 sonatique

Thanks for testing this. I am very glad that the hang went away. I also wonder why "then OK again" happens. Can you please attach debug logs?

This is still with PR 1018 applied, right?

I wish I could provide a debug build of libusb0.sys so that we can see driver debug output with DebugView but I haven't figured out what to do in in the ddk_build folder to enable this. Maybe @dontech can help.

For signed libusb0.sys driver updates, this is still possible because dontech has the appropriate certifications to sign it.

tormodvolden avatar Sep 19 '23 15:09 tormodvolden

Here is a debug build, I gave it version number 1.2.7.101. The size is larger, however I don't see anything in DebugView from it. (Built in CMD.exe window with CMD /C make.cmd "arch=x64" "outdir=.\x64" "DEBUGMODE=true" "app=driver") libusb0_sys_PR38_dbg.zip

EDIT: Seems to work fine with DebugView.

tormodvolden avatar Sep 19 '23 16:09 tormodvolden

New snapshots: https://sourceforge.net/projects/libusb-win32/files/libusb-win32-snapshots/20230920/

dontech avatar Sep 20 '23 01:09 dontech

@tormodvolden : OK here are some results with your debug build (was tricky because of the overwhelming amount of log produced by the very fast looping). Yes my last message was still with 1018 applied, you were right. I test with and without it. My procedure is as follow: I start with libusb debug log disabled but DebugView enabled I start the vendor request write loop and remove the cable as promptly as possible (after 50-150 loops). In my program when I ses the first non-OK error returned, I enable libusb debug logging. I then allow 5 non-error returns, then exit the loop (otherwise it will loop forever) Basically what we see is that the driver correctly report 1 or 2 failed requests (I guess this is during the removal of the cable) then says " SURPRISE_REMOVAL" and basically doesn't do anything anymore after it (which is correct I guess). However libusb-1.0 happily continues to return "8 bytes written" forever after a few error messages. The behavior is slightly different with or with PR 1018 applied, but not fundamentally. I think that while you definitively fixed something in the driver (congratulation!) this also shows an issue in libusb-1.0 that shall be fixed sooner or later.

Here are some logs:

Current master, commit 6bf2db6 (without PR 1018)

Output from my modified sam3u_benchmark (a few printf and libusb-1.0 debug-level logs): (each initial dot represent a successful write request before cable removal, debug logs enable after first error, you can see 5 times "Write Success: 8" after cable removal that shouldn't be there in my opinion)

................................................................................................................................Write Error: LIBUSB_ERROR_IO
[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 8.419228] [00005030] libusb: debug [libusb_submit_transfer] transfer 000001C8A73B6ED0
[ 8.419306] [00005030] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 8.419374] [00005030] libusb: debug [libusb_claim_interface] interface 0
[ 8.419484] [00005030] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 8.419585] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 8.419694] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 8.419798] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 8.419901] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 8.420005] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 8.420090] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 8.420174] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 8.420256] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 8.420331] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 8.420406] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 8.420488] [00005030] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 8.420496] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.420555] [00005030] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 8.420635] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.420759] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.420811] [00005030] libusb: warning [winusbx_submit_control_transfer] ControlTransfer failed: [433] A device which does not exist was specified.
[ 8.420826] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.420888] [00005030] libusb: debug [libusb_release_interface] interface 0
[ 8.420954] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF490 for handle 000001C8A73AC060
[ 8.421014] [00005030] libusb: debug [auto_release] auto-released interface 0
[ 8.421132] [00005030] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 8.421195] [00005030] libusb: debug [libusb_free_transfer] transfer 000001C8A73B6ED0
Write Error: LIBUSB_ERROR_IO
[ 8.421305] [00005030] libusb: debug [libusb_submit_transfer] transfer 000001C8A73B6250
[ 8.421365] [00005030] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 8.421431] [00005030] libusb: debug [libusb_claim_interface] interface 0
[ 8.421543] [00005030] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 8.421607] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 8.421671] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 8.421735] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 8.421799] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 8.421863] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 8.421926] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 8.421990] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 8.422054] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 8.422117] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 8.422181] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 8.425566] [00005030] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 8.425574] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.425672] [00005030] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 8.425773] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.426573] [00005030] libusb: warning [winusbx_submit_control_transfer] ControlTransfer failed: [433] A device which does not exist was specified.
[ 8.427751] [00005030] libusb: debug [libusb_release_interface] interface 0
[ 8.427038] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.429355] [00005030] libusb: debug [auto_release] auto-released interface 0
[ 8.429386] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.433532] [00005030] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 8.435055] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF490 for handle 000001C8A73AC060
[ 8.436228] [00005030] libusb: debug [libusb_free_transfer] transfer 000001C8A73B6250
Write Error: LIBUSB_ERROR_IO
[ 8.439056] [00005030] libusb: debug [libusb_submit_transfer] transfer 000001C8A73B6A20
[ 8.441373] [00005030] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 8.442644] [00005030] libusb: debug [libusb_claim_interface] interface 0
[ 8.443847] [00005030] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 8.444156] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 8.444519] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 8.444877] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 8.445235] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 8.445601] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 8.445958] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 8.446318] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 8.446676] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 8.447036] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 8.447397] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 8.459424] [00005030] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 8.459447] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.463051] [00005030] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 8.471193] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.471303] [00005030] libusb: debug [windows_force_sync_completion] transfer 000001C8A73B6A20, length 8
[ 8.472865] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.472948] [00005030] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 8.473046] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.473123] [00005030] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 8.473197] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.475256] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF490 for handle 000001C8A73AC060
[ 8.476195] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF6E0 for handle 000001C8A73AC060
[ 8.479137] [0000022c] libusb: debug [windows_iocp_thread] transfer 000001C8A73B6A20 completed, length 8
[ 8.479878] [00005030] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 8.480743] [00005030] libusb: debug [handle_event_trigger] event triggered
[ 8.483541] [00005030] libusb: debug [windows_handle_transfer_completion] handling transfer 000001C8A73B6A20 completion with errcode 0, length 8
[ 8.484122] [00005030] libusb: debug [libusb_release_interface] interface 0
[ 8.485335] [00005030] libusb: debug [auto_release] auto-released interface 0
[ 8.496615] [00005030] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 8.497406] [00005030] libusb: debug [usbi_handle_transfer_completion] transfer 000001C8A73B6A20 has callback 00007FF6B735E0A0
[ 8.498418] [00005030] libusb: debug [sync_transfer_cb] actual_length=8
[ 8.499575] [00005030] libusb: debug [libusb_free_transfer] transfer 000001C8A73B6A20
Write success: 8
[ 8.505085] [00005030] libusb: debug [libusb_submit_transfer] transfer 000001C8A73B6570
[ 8.505702] [00005030] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 8.506494] [00005030] libusb: debug [libusb_claim_interface] interface 0
[ 8.509794] [00005030] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 8.510684] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 8.513465] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 8.514106] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 8.515212] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 8.517959] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 8.522047] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 8.523008] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 8.527624] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 8.528107] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 8.529032] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 8.532296] [00005030] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 8.540188] [00005030] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 8.532327] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.543112] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.541467] [00005030] libusb: debug [windows_force_sync_completion] transfer 000001C8A73B6570, length 8
[ 8.543970] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.547244] [00005030] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 8.548309] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.557011] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.553902] [00005030] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 8.557975] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF490 for handle 000001C8A73AC060
[ 8.560364] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF6E0 for handle 000001C8A73AC060
[ 8.563082] [0000022c] libusb: debug [windows_iocp_thread] transfer 000001C8A73B6570 completed, length 8
[ 8.567223] [00005030] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 8.567849] [00005030] libusb: debug [handle_event_trigger] event triggered
[ 8.568779] [00005030] libusb: debug [windows_handle_transfer_completion] handling transfer 000001C8A73B6570 completion with errcode 0, length 8
[ 8.573575] [00005030] libusb: debug [libusb_release_interface] interface 0
[ 8.575026] [00005030] libusb: debug [auto_release] auto-released interface 0
[ 8.577640] [00005030] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 8.579673] [00005030] libusb: debug [usbi_handle_transfer_completion] transfer 000001C8A73B6570 has callback 00007FF6B735E0A0
[ 8.583736] [00005030] libusb: debug [sync_transfer_cb] actual_length=8
[ 8.585581] [00005030] libusb: debug [libusb_free_transfer] transfer 000001C8A73B6570
Write success: 8
[ 8.589452] [00005030] libusb: debug [libusb_submit_transfer] transfer 000001C8A73B6700
[ 8.592970] [00005030] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 8.598861] [00005030] libusb: debug [libusb_claim_interface] interface 0
[ 8.600418] [00005030] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 8.603804] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 8.604639] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 8.607109] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 8.608704] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 8.615445] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 8.616793] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 8.620379] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 8.621306] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 8.624464] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 8.627409] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 8.631611] [00005030] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 8.631619] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.632847] [00005030] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 8.633705] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.637117] [00005030] libusb: debug [windows_force_sync_completion] transfer 000001C8A73B6700, length 8
[ 8.637897] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.641652] [00005030] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 8.649680] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.653124] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.652045] [00005030] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 8.654108] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF490 for handle 000001C8A73AC060
[ 8.661444] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF6E0 for handle 000001C8A73AC060
[ 8.662706] [0000022c] libusb: debug [windows_iocp_thread] transfer 000001C8A73B6700 completed, length 8
[ 8.665566] [00005030] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 8.666599] [00005030] libusb: debug [handle_event_trigger] event triggered
[ 8.669646] [00005030] libusb: debug [windows_handle_transfer_completion] handling transfer 000001C8A73B6700 completion with errcode 0, length 8
[ 8.671557] [00005030] libusb: debug [libusb_release_interface] interface 0
[ 8.674588] [00005030] libusb: debug [auto_release] auto-released interface 0
[ 8.679727] [00005030] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 8.681142] [00005030] libusb: debug [usbi_handle_transfer_completion] transfer 000001C8A73B6700 has callback 00007FF6B735E0A0
[ 8.684371] [00005030] libusb: debug [sync_transfer_cb] actual_length=8
[ 8.685385] [00005030] libusb: debug [libusb_free_transfer] transfer 000001C8A73B6700
Write success: 8
[ 8.689750] [00005030] libusb: debug [libusb_submit_transfer] transfer 000001C8A73B60C0
[ 8.691778] [00005030] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 8.695974] [00005030] libusb: debug [libusb_claim_interface] interface 0
[ 8.696581] [00005030] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 8.699721] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 8.700513] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 8.704694] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 8.711344] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 8.711453] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 8.712531] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 8.713372] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 8.716377] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 8.717335] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 8.720377] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 8.725171] [00005030] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 8.726596] [00005030] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 8.725197] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.728993] [00005030] libusb: debug [windows_force_sync_completion] transfer 000001C8A73B60C0, length 8
[ 8.732260] [00005030] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 8.729756] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.733253] [00005030] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 8.739764] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.744699] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.745605] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.747951] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF490 for handle 000001C8A73AC060
[ 8.749491] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF6E0 for handle 000001C8A73AC060
[ 8.757539] [0000022c] libusb: debug [windows_iocp_thread] transfer 000001C8A73B60C0 completed, length 8
[ 8.759295] [00005030] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 8.762304] [00005030] libusb: debug [handle_event_trigger] event triggered
[ 8.763414] [00005030] libusb: debug [windows_handle_transfer_completion] handling transfer 000001C8A73B60C0 completion with errcode 0, length 8
[ 8.766538] [00005030] libusb: debug [libusb_release_interface] interface 0
[ 8.772771] [00005030] libusb: debug [auto_release] auto-released interface 0
[ 8.774109] [00005030] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 8.776988] [00005030] libusb: debug [usbi_handle_transfer_completion] transfer 000001C8A73B60C0 has callback 00007FF6B735E0A0
[ 8.777873] [00005030] libusb: debug [sync_transfer_cb] actual_length=8
[ 8.781585] [00005030] libusb: debug [libusb_free_transfer] transfer 000001C8A73B60C0
Write success: 8
[ 8.788513] [00005030] libusb: debug [libusb_submit_transfer] transfer 000001C8A73B60C0
[ 8.789714] [00005030] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 8.790733] [00005030] libusb: debug [libusb_claim_interface] interface 0
[ 8.793009] [00005030] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 8.795397] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 8.797804] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 8.804794] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 8.806287] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 8.809378] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 8.810180] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 8.813881] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 8.819853] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 8.822366] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 8.825645] [00005030] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 8.826503] [00005030] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 8.826536] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.829273] [00005030] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 8.833415] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.838664] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.834144] [00005030] libusb: debug [windows_force_sync_completion] transfer 000001C8A73B60C0, length 8
[ 8.840119] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.840219] [00005030] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 8.843145] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF3B0 for handle 000001C8A73AC060
[ 8.845239] [00005030] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 8.849923] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF490 for handle 000001C8A73AC060
[ 8.854244] [0000022c] libusb: debug [windows_iocp_thread] ignoring overlapped 000000570ADDF6E0 for handle 000001C8A73AC060
[ 8.854991] [0000022c] libusb: debug [windows_iocp_thread] transfer 000001C8A73B60C0 completed, length 8
[ 8.858186] [00005030] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 8.859808] [00005030] libusb: debug [handle_event_trigger] event triggered
[ 8.860879] [00005030] libusb: debug [windows_handle_transfer_completion] handling transfer 000001C8A73B60C0 completion with errcode 0, length 8
[ 8.866586] [00005030] libusb: debug [libusb_release_interface] interface 0
[ 8.868117] [00005030] libusb: debug [auto_release] auto-released interface 0
[ 8.868201] [00005030] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 8.871375] [00005030] libusb: debug [usbi_handle_transfer_completion] transfer 000001C8A73B60C0 has callback 00007FF6B735E0A0
[ 8.872444] [00005030] libusb: debug [sync_transfer_cb] actual_length=8
[ 8.875452] [00005030] libusb: debug [libusb_free_transfer] transfer 000001C8A73B60C0
Write success: 8
[ 8.883051] [00005030] libusb: debug [libusb_release_interface] interface 2
[ 8.884022] [00005030] libusb: debug [libusb_close]
[ 8.886817] [00005030] libusb: debug [libusb_unref_device] destroy device 1.21
[ 8.887928] [00005030] libusb: debug [libusb_unref_device] destroy device 1.0
[ 8.890850] [00005030] libusb: debug [libusb_exit] destroying default context
[ 8.893641] [0000022c] libusb: debug [windows_iocp_thread] I/O completion thread exiting
[ 8.906918] [00005030] libusb: debug [usbi_remove_event_source] remove HANDLE 000000000000009C
[ 8.907080] [00005030] libusb: debug [usbi_remove_event_source] remove HANDLE 0000000000000098
Done

Corresponding libusb0.sys driver debug log: N times this: (1 for every successful transfer before cable removal)

libusb0-sys:[get_descriptor] buffer size: 9 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[get_descriptor] buffer size: 88 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[vendor_class_request] type: vendor
libusb0-sys:[vendor_class_request] recipient: device
libusb0-sys:[vendor_class_request] request: 0xf3
libusb0-sys:[vendor_class_request] value: 0x03e8
libusb0-sys:[vendor_class_request] index: 0x0024
libusb0-sys:[vendor_class_request] size: 8
libusb0-sys:[vendor_class_request] direction: out
libusb0-sys:[vendor_class_request] timeout: 1000
libusb0-sys:dbg [call_usbd_ex] status = 00000000h
libusb0-sys:[vendor_class_request] 8 bytes transmitted

then:

libusb0-sys:[get_descriptor] buffer size: 9 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[get_descriptor] buffer size: 88 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[vendor_class_request] type: vendor
libusb0-sys:[vendor_class_request] recipient: device
libusb0-sys:[vendor_class_request] request: 0xf3
libusb0-sys:[vendor_class_request] value: 0x03e8
libusb0-sys:[vendor_class_request] index: 0x0024
libusb0-sys:[vendor_class_request] size: 8
libusb0-sys:[vendor_class_request] direction: out
libusb0-sys:[vendor_class_request] timeout: 1000
libusb0-sys:dbg [call_usbd_ex] status = C0000001h
libusb0-sys:err [vendor_class_request] request failed: status: 0xc0000001, urb-status: 0xc0000011
libusb0-sys:[get_descriptor] buffer size: 9 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[get_descriptor] buffer size: 88 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[vendor_class_request] type: vendor
libusb0-sys:[vendor_class_request] recipient: device
libusb0-sys:[vendor_class_request] request: 0xf3
libusb0-sys:[vendor_class_request] value: 0x03e8
libusb0-sys:[vendor_class_request] index: 0x0024
libusb0-sys:[vendor_class_request] size: 8
libusb0-sys:[vendor_class_request] direction: out
libusb0-sys:[vendor_class_request] timeout: 1000
libusb0-sys:dbg [call_usbd_ex] status = C000000Eh
libusb0-sys:err [vendor_class_request] request failed: status: 0xc000000e, urb-status: 0x80000300
libusb0-sys:[get_descriptor] buffer size: 9 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[get_descriptor] buffer size: 88 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[vendor_class_request] type: vendor
libusb0-sys:[vendor_class_request] recipient: device
libusb0-sys:[vendor_class_request] request: 0xf3
libusb0-sys:[vendor_class_request] value: 0x03e8
libusb0-sys:[vendor_class_request] index: 0x0024
libusb0-sys:[vendor_class_request] size: 8
libusb0-sys:[vendor_class_request] direction: out
libusb0-sys:[vendor_class_request] timeout: 1000
libusb0-sys:dbg [call_usbd_ex] status = C000000Eh
libusb0-sys:err [vendor_class_request] request failed: status: 0xc000000e, urb-status: 0x80000300
libusb0-sys:[dispatch_pnp] IRP_MN_SURPRISE_REMOVAL: is-filter=N usb\vid_1500&pid_0008&rev_0100
libusb0-sys:[set_filter_interface_key] updated interface registry with LUsb0 direct-access symbolic link. id=-1
libusb0-sys:[dispatch_pnp] IRP_MN_REMOVE_DEVICE: is-filter=N usb\vid_1500&pid_0008&rev_0100
libusb0-sys:[dispatch_pnp] deleting device #1 usb\vid_1500&pid_0008&rev_0100
libusb0-sys:[unload] [unloading-driver] v1.2.7.101

With PR 1018 commits (3) applied on top of current master (commit 6bf2db6)

my program output:

............................................Write Error: LIBUSB_ERROR_PIPE
[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 6.517168] [00003850] libusb: debug [libusb_submit_transfer] transfer 000001EBBEC26570
[ 6.517247] [00003850] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 6.517315] [00003850] libusb: debug [libusb_claim_interface] interface 0
[ 6.517427] [00003850] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 6.517511] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 6.517599] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 6.517685] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 6.517772] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 6.517857] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 6.517933] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 6.518008] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 6.518072] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 6.518136] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 6.518200] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 6.518283] [00003850] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 6.518290] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.518347] [00003850] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 6.518428] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.518553] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.518623] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.518690] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF130 for handle 000001EBBEC1C060
[ 6.518717] [00003850] libusb: debug [windows_force_sync_completion] transfer 000001EBBEC26570, length 8
[ 6.518760] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF380 for handle 000001EBBEC1C060
[ 6.518825] [00003850] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 6.518890] [00005d64] libusb: debug [windows_iocp_thread] transfer 000001EBBEC26570 completed, length 8
[ 6.518954] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 6.519081] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 6.519142] [00003850] libusb: debug [handle_event_trigger] event triggered
[ 6.519199] [00003850] libusb: debug [windows_handle_transfer_completion] handling transfer 000001EBBEC26570 completion with errcode 0, length 8
[ 6.519274] [00003850] libusb: debug [libusb_release_interface] interface 0
[ 6.519332] [00003850] libusb: debug [auto_release] auto-released interface 0
[ 6.519390] [00003850] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 6.519451] [00003850] libusb: debug [usbi_handle_transfer_completion] transfer 000001EBBEC26570 has callback 00007FF70EF6E0A0
[ 6.519518] [00003850] libusb: debug [sync_transfer_cb] actual_length=8
[ 6.519575] [00003850] libusb: debug [libusb_free_transfer] transfer 000001EBBEC26570
Write success: 8
[ 6.519686] [00003850] libusb: debug [libusb_submit_transfer] transfer 000001EBBEC26BB0
[ 6.519745] [00003850] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 6.519811] [00003850] libusb: debug [libusb_claim_interface] interface 0
[ 6.519922] [00003850] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 6.519984] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 6.520048] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 6.520112] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 6.520176] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 6.520253] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 6.520702] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 6.521072] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 6.521506] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 6.521874] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 6.522250] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 6.522629] [00003850] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 6.522652] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.523020] [00003850] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 6.523418] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.523918] [00003850] libusb: debug [winusbx_submit_control_transfer] ControlTransfer returned: [433] A device which does not exist was specified.
[ 6.524195] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.524591] [00003850] libusb: debug [windows_force_sync_completion] transfer 000001EBBEC26BB0, length 0
[ 6.524981] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.525546] [00003850] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 6.535056] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF130 for handle 000001EBBEC1C060
[ 6.536982] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 6.538079] [00005d64] libusb: debug [windows_iocp_thread] transfer 000001EBBEC26BB0 completed, length 0
[ 6.539649] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 6.540836] [00003850] libusb: debug [handle_event_trigger] event triggered
[ 6.542121] [00003850] libusb: debug [windows_handle_transfer_completion] GetOverlappedResult true, but Internal not reset
[ 6.543681] [00003850] libusb: debug [windows_handle_transfer_completion] handling transfer 000001EBBEC26BB0 completion with errcode 433, length 0
[ 6.544052] [00003850] libusb: debug [windows_handle_transfer_completion] detected device removed
[ 6.544438] [00003850] libusb: debug [libusb_release_interface] interface 0
[ 6.544809] [00003850] libusb: debug [auto_release] auto-released interface 0
[ 6.545180] [00003850] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 6.545541] [00003850] libusb: debug [usbi_handle_transfer_completion] transfer 000001EBBEC26BB0 has callback 00007FF70EF6E0A0
[ 6.545899] [00003850] libusb: debug [sync_transfer_cb] actual_length=0
[ 6.546256] [00003850] libusb: debug [libusb_free_transfer] transfer 000001EBBEC26BB0
Write Error: LIBUSB_ERROR_NO_DEVICE
[ 6.546973] [00003850] libusb: debug [libusb_submit_transfer] transfer 000001EBBEC26A20
[ 6.547329] [00003850] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 6.547691] [00003850] libusb: debug [libusb_claim_interface] interface 0
[ 6.548102] [00003850] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 6.548414] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 6.548765] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 6.549128] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 6.549487] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 6.549846] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 6.550208] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 6.550567] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 6.550929] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 6.551288] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 6.551680] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 6.552093] [00003850] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 6.552100] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.552483] [00003850] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 6.552879] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.553677] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.553266] [00003850] libusb: debug [windows_force_sync_completion] transfer 000001EBBEC26A20, length 8
[ 6.554092] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.554494] [00003850] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 6.554887] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.555281] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 6.555660] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF130 for handle 000001EBBEC1C060
[ 6.556454] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF380 for handle 000001EBBEC1C060
[ 6.557156] [00005d64] libusb: debug [windows_iocp_thread] transfer 000001EBBEC26A20 completed, length 8
[ 6.560304] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 6.561059] [00003850] libusb: debug [handle_event_trigger] event triggered
[ 6.561612] [00003850] libusb: debug [windows_handle_transfer_completion] handling transfer 000001EBBEC26A20 completion with errcode 0, length 8
[ 6.562004] [00003850] libusb: debug [libusb_release_interface] interface 0
[ 6.562407] [00003850] libusb: debug [auto_release] auto-released interface 0
[ 6.562755] [00003850] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 6.563111] [00003850] libusb: debug [usbi_handle_transfer_completion] transfer 000001EBBEC26A20 has callback 00007FF70EF6E0A0
[ 6.563467] [00003850] libusb: debug [sync_transfer_cb] actual_length=8
[ 6.563817] [00003850] libusb: debug [libusb_free_transfer] transfer 000001EBBEC26A20
Write success: 8
[ 6.564539] [00003850] libusb: debug [libusb_submit_transfer] transfer 000001EBBEC26890
[ 6.564888] [00003850] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 6.565263] [00003850] libusb: debug [libusb_claim_interface] interface 0
[ 6.565668] [00003850] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 6.565971] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 6.566340] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 6.566703] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 6.567060] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 6.567415] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 6.567768] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 6.568128] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 6.568518] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 6.568871] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 6.569245] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 6.569615] [00003850] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 6.569955] [00003850] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 6.569631] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.570349] [00003850] libusb: debug [windows_force_sync_completion] transfer 000001EBBEC26890, length 8
[ 6.570692] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.571047] [00003850] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 6.571404] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.571758] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 6.572112] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.572843] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.573246] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF130 for handle 000001EBBEC1C060
[ 6.573626] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF380 for handle 000001EBBEC1C060
[ 6.574009] [00005d64] libusb: debug [windows_iocp_thread] transfer 000001EBBEC26890 completed, length 8
[ 6.574636] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 6.577322] [00003850] libusb: debug [handle_event_trigger] event triggered
[ 6.628121] [00003850] libusb: debug [windows_handle_transfer_completion] handling transfer 000001EBBEC26890 completion with errcode 0, length 8
[ 6.630763] [00003850] libusb: debug [libusb_release_interface] interface 0
[ 6.631749] [00003850] libusb: debug [auto_release] auto-released interface 0
[ 6.632711] [00003850] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 6.633696] [00003850] libusb: debug [usbi_handle_transfer_completion] transfer 000001EBBEC26890 has callback 00007FF70EF6E0A0
[ 6.634680] [00003850] libusb: debug [sync_transfer_cb] actual_length=8
[ 6.635659] [00003850] libusb: debug [libusb_free_transfer] transfer 000001EBBEC26890
Write success: 8
[ 6.638079] [00003850] libusb: debug [libusb_submit_transfer] transfer 000001EBBEC26250
[ 6.638267] [00003850] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 6.643045] [00003850] libusb: debug [libusb_claim_interface] interface 0
[ 6.650627] [00003850] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 6.652873] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 6.656719] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 6.663164] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 6.665659] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 6.672003] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 6.673027] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 6.675388] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 6.678462] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 6.679655] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 6.681568] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 6.682379] [00003850] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 6.682402] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.685302] [00003850] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 6.687470] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.693397] [00003850] libusb: debug [windows_force_sync_completion] transfer 000001EBBEC26250, length 8
[ 6.697093] [00003850] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 6.697974] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 6.694806] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.707621] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.709260] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.712007] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF130 for handle 000001EBBEC1C060
[ 6.712559] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF380 for handle 000001EBBEC1C060
[ 6.713466] [00005d64] libusb: debug [windows_iocp_thread] transfer 000001EBBEC26250 completed, length 8
[ 6.716522] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 6.720847] [00003850] libusb: debug [handle_event_trigger] event triggered
[ 6.721757] [00003850] libusb: debug [windows_handle_transfer_completion] handling transfer 000001EBBEC26250 completion with errcode 0, length 8
[ 6.726026] [00003850] libusb: debug [libusb_release_interface] interface 0
[ 6.727340] [00003850] libusb: debug [auto_release] auto-released interface 0
[ 6.730707] [00003850] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 6.732219] [00003850] libusb: debug [usbi_handle_transfer_completion] transfer 000001EBBEC26250 has callback 00007FF70EF6E0A0
[ 6.733249] [00003850] libusb: debug [sync_transfer_cb] actual_length=8
[ 6.739814] [00003850] libusb: debug [libusb_free_transfer] transfer 000001EBBEC26250
Write success: 8
[ 6.744496] [00003850] libusb: debug [libusb_submit_transfer] transfer 000001EBBEC26700
[ 6.747847] [00003850] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 6.754674] [00003850] libusb: debug [libusb_claim_interface] interface 0
[ 6.755693] [00003850] libusb: debug [winusbx_claim_interface] claimed interface 0
[ 6.756695] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 01 to interface 0
[ 6.757921] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 81 to interface 0
[ 6.758702] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 02 to interface 0
[ 6.759673] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 82 to interface 0
[ 6.763133] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 04 to interface 0
[ 6.770820] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 84 to interface 0
[ 6.771367] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 06 to interface 0
[ 6.772461] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 86 to interface 0
[ 6.775258] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 08 to interface 0
[ 6.776078] [00003850] libusb: debug [windows_assign_endpoints] (re)assigned endpoint 88 to interface 0
[ 6.777180] [00003850] libusb: debug [auto_claim] auto-claimed interface 0 for control request
[ 6.780525] [00003850] libusb: debug [winusbx_submit_control_transfer] will use interface 0
[ 6.777203] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.781416] [00003850] libusb: debug [windows_force_sync_completion] transfer 000001EBBEC26700, length 8
[ 6.785266] [00003850] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 6.782356] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.789323] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() for 2 HANDLEs with timeout in 60000ms
[ 6.790875] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.797809] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.801010] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF050 for handle 000001EBBEC1C060
[ 6.805666] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF130 for handle 000001EBBEC1C060
[ 6.807316] [00005d64] libusb: debug [windows_iocp_thread] ignoring overlapped 0000008742CFF380 for handle 000001EBBEC1C060
[ 6.810022] [00005d64] libusb: debug [windows_iocp_thread] transfer 000001EBBEC26700 completed, length 8
[ 6.811182] [00003850] libusb: debug [usbi_wait_for_events] WaitForMultipleObjects() returned 0
[ 6.813847] [00003850] libusb: debug [handle_event_trigger] event triggered
[ 6.814729] [00003850] libusb: debug [windows_handle_transfer_completion] handling transfer 000001EBBEC26700 completion with errcode 0, length 8
[ 6.817569] [00003850] libusb: debug [libusb_release_interface] interface 0
[ 6.824278] [00003850] libusb: debug [auto_release] auto-released interface 0
[ 6.827328] [00003850] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 6.827931] [00003850] libusb: debug [usbi_handle_transfer_completion] transfer 000001EBBEC26700 has callback 00007FF70EF6E0A0
[ 6.828740] [00003850] libusb: debug [sync_transfer_cb] actual_length=8
[ 6.830738] [00003850] libusb: debug [libusb_free_transfer] transfer 000001EBBEC26700
Write success: 8
[ 6.835323] [00003850] libusb: debug [libusb_release_interface] interface 2
[ 6.835970] [00003850] libusb: debug [libusb_close]
[ 6.836863] [00003850] libusb: debug [libusb_unref_device] destroy device 1.17
[ 6.840537] [00003850] libusb: debug [libusb_unref_device] destroy device 1.0
[ 6.841437] [00003850] libusb: debug [libusb_exit] destroying default context
[ 6.844722] [00005d64] libusb: debug [windows_iocp_thread] I/O completion thread exiting
[ 6.852441] [00003850] libusb: debug [usbi_remove_event_source] remove HANDLE 00000000000000A0
[ 6.852551] [00003850] libusb: debug [usbi_remove_event_source] remove HANDLE 000000000000009C
Done

Corresponding libusb0.sys driver debug log: N times this: (1 for every successful transfer before cable removal)

libusb0-sys:[get_descriptor] buffer size: 9 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[get_descriptor] buffer size: 88 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[vendor_class_request] type: vendor
libusb0-sys:[vendor_class_request] recipient: device
libusb0-sys:[vendor_class_request] request: 0xf3
libusb0-sys:[vendor_class_request] value: 0x03e8
libusb0-sys:[vendor_class_request] index: 0x0024
libusb0-sys:[vendor_class_request] size: 8
libusb0-sys:[vendor_class_request] direction: out
libusb0-sys:[vendor_class_request] timeout: 1000
libusb0-sys:dbg [call_usbd_ex] status = 00000000h
libusb0-sys:[vendor_class_request] 8 bytes transmitted

then:

libusb0-sys:[get_descriptor] buffer size: 9 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[get_descriptor] buffer size: 88 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[vendor_class_request] type: vendor
libusb0-sys:[vendor_class_request] recipient: device
libusb0-sys:[vendor_class_request] request: 0xf3
libusb0-sys:[vendor_class_request] value: 0x03e8
libusb0-sys:[vendor_class_request] index: 0x0024
libusb0-sys:[vendor_class_request] size: 8
libusb0-sys:[vendor_class_request] direction: out
libusb0-sys:[vendor_class_request] timeout: 1000
libusb0-sys:dbg [call_usbd_ex] status = C0000001h
libusb0-sys:err [vendor_class_request] request failed: status: 0xc0000001, urb-status: 0xc0000011
libusb0-sys:[get_descriptor] buffer size: 9 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[get_descriptor] buffer size: 88 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[vendor_class_request] type: vendor
libusb0-sys:[vendor_class_request] recipient: device
libusb0-sys:[vendor_class_request] request: 0xf3
libusb0-sys:[vendor_class_request] value: 0x03e8
libusb0-sys:[vendor_class_request] index: 0x0024
libusb0-sys:[vendor_class_request] size: 8
libusb0-sys:[vendor_class_request] direction: out
libusb0-sys:[vendor_class_request] timeout: 1000
libusb0-sys:dbg [call_usbd_ex] status = 00000000h
libusb0-sys:[vendor_class_request] 8 bytes transmitted
libusb0-sys:[get_descriptor] buffer size: 9 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[get_descriptor] buffer size: 88 type: 0002 recipient: 0000 index: 0000 language id: 0000 timeout: 0
libusb0-sys:[vendor_class_request] type: vendor
libusb0-sys:[vendor_class_request] recipient: device
libusb0-sys:[vendor_class_request] request: 0xf3
libusb0-sys:[vendor_class_request] value: 0x03e8
libusb0-sys:[vendor_class_request] index: 0x0024
libusb0-sys:[vendor_class_request] size: 8
libusb0-sys:[vendor_class_request] direction: out
libusb0-sys:[vendor_class_request] timeout: 1000
libusb0-sys:dbg [call_usbd_ex] status = C000000Eh
libusb0-sys:err [vendor_class_request] request failed: status: 0xc000000e, urb-status: 0x80000300
libusb0-sys:[dispatch_pnp] IRP_MN_SURPRISE_REMOVAL: is-filter=N usb\vid_1500&pid_0008&rev_0100
libusb0-sys:[set_filter_interface_key] updated interface registry with LUsb0 direct-access symbolic link. id=-1
libusb0-sys:[dispatch_pnp] IRP_MN_REMOVE_DEVICE: is-filter=N usb\vid_1500&pid_0008&rev_0100
libusb0-sys:[dispatch_pnp] deleting device #2 usb\vid_1500&pid_0008&rev_0100
libusb0-sys:[unload] [unloading-driver] v1.2.7.101

sonatique avatar Sep 20 '23 09:09 sonatique

@tormodvolden @dontech : I just tried with 1.2.7.4 snapshot of libusb0.sys driver (thanks for it) and got the same results (minus the driver logs obviously)

sonatique avatar Sep 20 '23 09:09 sonatique

@tormodvolden : I retested exactly the same with libusbK and WinUSB drivers, and (as previously mentionned) I get a completely, and in my opinion correct, behavior: After cable removal I only get error codes returned (ERROR_NO_DEVICE, then ERROR_NOT_FOUND) when I attempt to write control requests. So, I don't know what to think: it seems that libusb-1.0 correctly returns an error code when the driver correctly does what it is supposed to do, but with your hang-corrected libusb0.sys, the behavior of libusb is wrong, while the driver itself seems to correctly stop doing anything after cable removal. Maybe libusb0.sys misses a status that libusb-1.0 will understand...

As of now, I would say that unfortunately current libusb-1.0 is not usable with libusb0.sys:: with version <= 1.2.7.3 we get a kernel hang and with >= 1.2.7.4 we incorrectly get OK status for write request that can not physically be completed successfully...

What do you think? Are there any reasonably possible improvements?

Thank you anyway, this at least gave me some precious indications.

EDIT: Could the "return success after cable removal problem" caused by libusbK.dll? And not by libusb-1.0 nor libusb0.sys? Given the results this is what seems to be the most probable to me... I don't understand why the "removal during transfer" would end-up in a different state than "removal while idle" except if there is a bug in libusbK.dll in the specific code that interact with libusb0.sys

sonatique avatar Sep 20 '23 10:09 sonatique

@dontech : side question: any plan to compile libusb0.sys for ARM64, by luck?

sonatique avatar Sep 20 '23 11:09 sonatique

@dontech : side question: any plan to compile libusb0.sys for ARM64, by luck?

You can add your comments here.

  • https://github.com/mcuee/libusb-win32/issues/29

Related issue:

  • https://github.com/mcuee/libusb-win32/issues/30

mcuee avatar Sep 20 '23 11:09 mcuee

Thanks for the informative debug logs. Surely there is still something wrong with error propagation.

Could the "return success after cable removal problem" caused by libusbK.dll? And not by libusb-1.0 nor libusb0.sys?

In theory yes, but it could also be remaining bugs in libusb.sys or libusb-1.0. Is there a debug version of libusbK.dll that reports something in DebugView? EDIT: There is -debug.7z here https://sourceforge.net/projects/libusbk/files/libusbK-release/3.1.0.0/

There is also this in the log with PR 1018: [ 6.542121] [00003850] libusb: debug [windows_handle_transfer_completion] GetOverlappedResult true, but Internal not reset This is something I need to look closer at, because it breaks some of my assumptions.

Another oddity in the PR 1018 libusb0-sys output is that there is a successful transfer after the first failing one. I don't know if this is a coincidence that could also happen without 1018.

tormodvolden avatar Sep 20 '23 13:09 tormodvolden

I just tried with 1.2.7.4 snapshot of libusb0.sys driver (thanks for it) and got the same results (minus the driver logs obviously)

libusb-win32-bin-debug-1.2.7.4.zip should give you driver debug output.

tormodvolden avatar Sep 20 '23 14:09 tormodvolden

It seems from the debug logs, if I have correlated the libusb and kernel logs correctly, that there is a good match between the kernel call_usbd_ex() status and the libusb transfer status as long as the driver is loaded. As soon as the PNP management unloads the driver, the false transfer success appears. I am not sure what happens with device objects and ioctl's and so forth in this case, it is possible that this needs special care by the library/DLL ("Whenever a client opens a handle to a pnp device, it should register for pnp notification and close the handle when the system notifies the device is being removed" [1]).

We can see that the unload routine is being called, but it is also not clear from the log whether the driver is successfully unloaded ("The fact that unload-routine is called doesn't mean the driver unload is successful" [1]). This can maybe be checked through other means.

[1] https://techcommunity.microsoft.com/t5/microsoft-usb-blog/why-doesn-t-my-driver-unload/ba-p/270680

tormodvolden avatar Sep 20 '23 18:09 tormodvolden

@dontech : side question: any plan to compile libusb0.sys for ARM64, by luck?

Yes. I can probably get it to compile, but I don't currently have a windows device to compile with.

And yes, we also need to port to new SDK first, as the current one does not support ARM at all.

dontech avatar Sep 20 '23 19:09 dontech