Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Windows: Freezing in Kernel with libusb-win32 #1255

Open
sonatique opened this issue Mar 1, 2023 · 98 comments
Open

Windows: Freezing in Kernel with libusb-win32 #1255

sonatique opened this issue Mar 1, 2023 · 98 comments
Labels
libusbk_libusb0 Windows libusbk backend for libusbk.sys and libusb0.sys windows

Comments

@sonatique
Copy link
Contributor

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.

@mcuee mcuee added windows question Technical support, will be closed if deemed not a libusb issue. Please use mailing list. labels Mar 1, 2023
@mcuee
Copy link
Member

mcuee commented Mar 1, 2023

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

@sonatique
Copy link
Contributor Author

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.

@mcuee
Copy link
Member

mcuee commented Mar 1, 2023

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.

@sonatique
Copy link
Contributor Author

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?

@tormodvolden
Copy link
Contributor

tormodvolden commented Mar 1, 2023

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.

@mcuee mcuee added libusbk_libusb0 Windows libusbk backend for libusbk.sys and libusb0.sys and removed question Technical support, will be closed if deemed not a libusb issue. Please use mailing list. labels Mar 2, 2023
@sonatique
Copy link
Contributor Author

sonatique commented Mar 2, 2023

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
Copy link
Contributor Author

sonatique commented Mar 5, 2023

I am wondering whether the "freezes" I experience are somehow related to what is described in #1127 . I will try with the code proposed in this PR as well.

@mcuee
Copy link
Member

mcuee commented Aug 15, 2023

@sonatique

Any updates on this issue? Thanks.

@sonatique
Copy link
Contributor Author

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

@sonatique sonatique changed the title Windows question: why is libusbK used in place of libusb0 despite SUB_API_LIBUSB0 being defined? Windows: Freezing in Kernel with libusb-win32 (was question: why is libusbK used in place of libusb0 despite SUB_API_LIBUSB0 being defined?) Sep 19, 2023
@sonatique
Copy link
Contributor Author

sonatique commented Sep 19, 2023

@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
Copy link
Contributor Author

I am wondering whether this #1018 may help, I will give it a try

@tormodvolden
Copy link
Contributor

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.

@sonatique
Copy link
Contributor Author

@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
Copy link
Contributor Author

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

@mcuee
Copy link
Member

mcuee commented Sep 19, 2023

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

@sonatique
Copy link
Contributor Author

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..

@tormodvolden
Copy link
Contributor

tormodvolden commented Sep 19, 2023

@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").

@sonatique
Copy link
Contributor Author

@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?

@tormodvolden
Copy link
Contributor

tormodvolden commented Sep 19, 2023

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
Copy link
Contributor

tormodvolden commented Sep 19, 2023

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.

@dontech
Copy link

dontech commented Sep 20, 2023

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

@sonatique
Copy link
Contributor Author

@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
Copy link
Contributor Author

@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
Copy link
Contributor Author

sonatique commented Sep 20, 2023

@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
Copy link
Contributor Author

@mcuee :
Update: actually I see this line (not in DebugView in my console) "(libusbK.dll)[k_Init_Version] libusb0.sys v1.3.0.0" but the problem is that I see this line printed for every submit_transfer. I mean: everytime I call submit_transfer I get this debug line printed. This doesn't seem very good.

And yes: I can try with a direct libusb-win32.dll only program, let's see if I can do this.

@sonatique
Copy link
Contributor Author

@mcuee : update (sorry for posting frantically):
What I see in my console is:
For each successful transfer before cable removal:
(libusbK.dll)[k_Init_Version] libusb0.sys v1.3.0.0

When I remove the cable, those 2 lines, only once:

[ERR](libusbK.dll)[usb_control_msg] sending control message failed(libusbK.dll)[k_Init_Version] libusb0.sys v1.3.0.0
[ERR](libusbK.dll)[usb_control_msg] sending control message failed(libusbK.dll)[k_Init_Version] libusb0.sys v0.0.0.0

Then after, this line for each false successful transfer:
(libusbK.dll)[k_Init_Version] libusb0.sys v0.0.0.0

So it seems that somehow libusb0.sys is unloaded, but libubsK do not correctly handle this...

@mcuee
Copy link
Member

mcuee commented Oct 10, 2023

@sonatique

Can you create an issue with libusbK project so that @TravisRo can take a look when he is available? Thanks.

@tormodvolden
Copy link
Contributor

If you can debug a bit, please check the calling stack when k_Init_Version is called for a transfer, because that is a bit weird although an issue on its own. And the return value from k_Init_Version after unplugging, also inside it SubmitSimpleSyncRequestEx() -> Ioctl_Sync -> DeviceIoControl(). Somewhere a failure is ignored or turned into success.

@sonatique
Copy link
Contributor Author

@tormodvolden

I wonder what you can see with IRP logging, for instance to see where these IRPs are going after the libusb0.sys (apparently) has been unloaded.

I am not very successful in using IRP. I must be missing something. I did what is explained under the link you posted earlier:
verifier /volatile /flags 0x410 /adddriver libusb0.sys

and then tried to use dc2wmiparser but not matter what I do not get any output

@tormodvolden
Copy link
Contributor

I have no experience with it. I also not sure if that tracing (on libusb0.sys) will do anything after libusb0.sys has been unloaded. It may confirm that is actually has been unloaded though.

@sonatique
Copy link
Contributor Author

@tormodvolden :
OK, here is something I think is interesting, purely looking a libusb-1.0 code for now (I'll look at libusbK later)
the "k_Init" log line come from here (I will look at libusbK code later):

if (!WinUSBX[sub_api].Initialize(file_handle, &winusb_handle)) { (windows_winusb.c Line 2918
sam3u_benchmark.exe!winusbx_claim_interface(int sub_api, libusb_device_handle * dev_handle, unsigned char iface) Line 2971
sam3u_benchmark.exe!winusb_claim_interface(libusb_device_handle * dev_handle, unsigned char iface) Line 2169
sam3u_benchmark.exe!windows_claim_interface(libusb_device_handle * dev_handle, unsigned char interface_number) Line 688
sam3u_benchmark.exe!libusb_claim_interface(libusb_device_handle * dev_handle, int interface_number) Line 1792
sam3u_benchmark.exe!auto_claim(libusb_transfer * transfer, int * interface_number, int api_type) Line 635
sam3u_benchmark.exe!winusbx_submit_control_transfer(int sub_api, usbi_transfer * itransfer) Line 3136
sam3u_benchmark.exe!winusb_submit_transfer(usbi_transfer * itransfer) Line 2284
sam3u_benchmark.exe!windows_submit_transfer(usbi_transfer * itransfer) Line 755
sam3u_benchmark.exe!libusb_submit_transfer(libusb_transfer * transfer) Line 1563
sam3u_benchmark.exe!libusb_control_transfer(libusb_device_handle * dev_handle, unsigned char bmRequestType, unsigned char bRequest, unsigned short wValue, unsigned short wIndex, unsigned char * data, unsigned short wLength, unsigned int timeout) Line 132
sam3u_benchmark.exe!main() Line 236

libusb-1.0 call Initialize for every auto_claim, and I get one auto_claim per control_transfer since in this case I do not claim an interface before issuing my control transfers in loop.

But, if I do claim_interface before executing my control transfer loop, I get a completely different outcome:

  1. only one single (libusbK.dll)[k_Init_Version] libusb0.sys v1.3.0.0 line when doing the claim_interface
  2. nothing while looping control tranfers with cable attached
  3. one [ERR](libusbK.dll)[usb_control_msg] sending control message failed for each control transfer attempt after i unplugged the cable, which is the expected behavior.

So my issue is specific to cases where auto_claim -> Initialized is called, as if calling Initialize after driver unload would trigger a wrong behavior of libusbK

@sonatique
Copy link
Contributor Author

sonatique commented Oct 10, 2023

Well, probably that libusb-1.0 code around the call to Initialize should understand that the device is no longer there, I am investigating why

file_handle = handle_priv->interface_handle[iface].dev_handle;
if (!HANDLE_VALID(file_handle))
	return LIBUSB_ERROR_NOT_FOUND;

does not return, for instance.

EDIT: well, no, it's the Initialize call that should fail, I think, at least this is the expectation from libusb-1.0:

if (!WinUSBX[sub_api].Initialize(file_handle, &winusb_handle)) {
	handle_priv->interface_handle[iface].api_handle = INVALID_HANDLE_VALUE;
	err = GetLastError();
	switch (err) {
	case ERROR_BAD_COMMAND:
		// The device was disconnected
		usbi_err(ctx, "could not access interface %u: %s", iface, windows_error_str(0));
		return LIBUSB_ERROR_NO_DEVICE;

I think libusb-1.0 expect a non-zero return value from Initialize and then fail with LIBUSB_ERROR_NO_DEVICE, I cannot say whether this expectation is correct or not.

@tormodvolden
Copy link
Contributor

But I still think, both in the case of failing control transfer reported as success, and the failing version retrieval reported as success, the DeviceIoControl() should have failed, and I don't think it does here.

@tormodvolden
Copy link
Contributor

tormodvolden commented Oct 10, 2023

I think libusb-1.0 expect a non-zero return value from Initialize and then fail with LIBUSB_ERROR_NO_DEVICE, I cannot say whether this expectation is correct or not.

Yes, I also think Initialize should have failed already when it fails to retrieve the version information. But I wonder if it is the same underlying issue as in the control transfers, that the DeviceIoControl() returns success.

@sonatique
Copy link
Contributor Author

Yes, something is strange in libubsK: if I breakpoint break right before the call to Initialize (from libusb-1.0), remove the cable, then go on with the execution, every subsequent calls (including claim_interface) are successful.

So I think the root bug lies in libubsK Initialize

@sonatique
Copy link
Contributor Author

Well, I instrumented libusbK code and run my faulting scenario. All I can say is that DeviceIoControl (and GetOverlappedResult) inside function Ioctl_Sync (lusbk_ioctl.c) called from k_Init_version, both return success code but fail to populate version with something, so we get this 0.0.0.0 version.

This is very strange to me, especially since doing something similar from inside libusbK solution (for instance using open-device example and removing the cable in between the enumeration and the init) works, I mean : fails as expected.

So far I didn't figure out what could produce this behavior. I am thinking about some level of caching, but I don't know.

If DeviceIoControl continues to work after cable removal, then this explains why control transfer are successful, but I have no idea why DeviceIoControl does not fail in the case where is it eventually called from within libusb-1.0

@tormodvolden
Copy link
Contributor

I won't exclude the possibility of a bug in libusb0.sys or the driver stack. That's also why I would like to be sure the driver is indeed unloaded, and not being passed IRPs from the I/O manager any longer. In our case userspace has been given a handle from CreateFileA() and is using it with DeviceIoControl() after the physical device has been removed. I am not sure what happens in detail. Since the driver unload has at least been initiated by the I/O manager, I would think the device object was already removed, but then I would expect DeviceIoControl() to fail. Actually I also thought the driver unload would only be called after all file handles have been closed, even if the physical device has disappeared. libusb is not closing it but maybe libusbk does in some cases?

@sonatique
Copy link
Contributor Author

At this point I have to say I am a bit lost. I did not succeed in showing IRPs. What I observe is that if I run my program which does claim_interface, then a few control transfer, then break, then remove then cable then continue, everything happens as if the device was there: all transfer are returned to have successfully transferfed bytes.

The only way to get errors it to remove the cable at some point during the control transfer, in which case I get errors from this point on.

Indeed I don't see libusb-1.0 closing any handle up disconnection, maybe because hot plug is not supported. All handles seems to stay valid after removal if removal does not occur right in the middle of an operation, and low level / driver calls made from libusbK dll all succeed.

I will try to reproduce with libusb-win32 only.

@sonatique
Copy link
Contributor Author

I switched to libusb-win32 source code, latest master commit from github.

I opened bulk.c from project testbulk. I just modified defines for VID and PID, then did the following:

  1. I put a breakpoint after usb_claim_interface (breakpoint at line 118) and I started the program in Debug with my device plugged-in
  2. When the breakpoint hit, I disconnected my USB device, and dragged the execution pointer back to the usb_claim_interface call
  3. Continued execution: the call to usb_claim_interface succeeded. ... with no device.

Looking at the code I can see this call is eventually implemented with DeviceIoControl, and so, again this call fails to fail when there is no device.

I have no idea why, and for now I don't know how to go on.

@tormodvolden
Copy link
Contributor

I switched to libusb-win32 source code, latest master commit from github.

So this is using libusb-win32 library/dll -> libusb0.sys without any libusbK involved? If you see the same here, it looks like libusb0.sys (or driver installation) is at fault.

Maybe an experienced driver developer like @dontech could help us to get closer?

@mcuee
Copy link
Member

mcuee commented Oct 10, 2023

Ah, I think this may be due to the fact that libusb-win32 API does not support hotplug. Same for libusb-1.0 under Windows.

libusbK API does support hotplug. Can you use libusbK API and libusb0.sys to see if that works?

@tormodvolden
Copy link
Contributor

I believe hotplug support would help here, but I don't see it as necessary. If a transfer cannot be completed successfully (whether due to unplugging or something else) there should be an error.

@sonatique
Copy link
Contributor Author

Can you use libusbK API and libusb0.sys to see if that works?
@mcuee : here is what I did: I took current libusbK source from github and used open-device example (open-device.c). I just modified VID/PID to suit my device.
I then put a breakpoint at line 97 success == SubmitSImpleSyncRequestEx of function k_Init_Version in file lusbk_kbnd_libusbk.c

Previously I verified that my libusb-1.0 test program indeed call this line (I put some printf in libubsK, like right before this line, code, compiled the dll and made sure to use it from libusb-1.0.

So: when I run in debug, with my device initially plugged-in: first call so SubmitSimpleSyncRequestEx succeed (as expected).
Then I drag the execution pointer to the same call again, but before continuing I disconnected my device. This second call fails.

This is the expected behavior but I have no idea what is the magic that makes it works, while something similaire called from libusb-1.0 will result in the second call (while disconnected) succeed.

I will be happy to continue to help you, but at this point the experiment is quite simple and you should be able to reproduce with any device, I guess, maybe it's easier.

Anyway, if I have new idea on how to further comprehend the problem I'll try, but I am a bit stuck right now.

@mcuee
Copy link
Member

mcuee commented Oct 10, 2023

@sonatique
Thanks a lot for carrying out the detailed testing. I will see if I can reproduce the issue.

Just a summary of your findings. Is the following correct?

  1. libusbK.dll + libusb0.sys --> it works as expected
  2. libusb-1.0.dll + libusbK.dll + libusb0.sys --> it does not work as expected
  3. libusb0.dll + libusb0.sys --> it does not work as expected.

@tormodvolden

I believe hotplug support would help here, but I don't see it as necessary. If a transfer cannot be completed successfully (whether due to unplugging or something else) there should be an error.

I will agree with you here.

@sonatique
Copy link
Contributor Author

@mcuee : yes, correct. I tested this as carefully as I can to avoid going in the wrong direction, though I struggle to find a logic in these results.

@sonatique
Copy link
Contributor Author

@mcuee @dontech

@sonatique, could you possibly try the ARM64 build now that it builds?

So I tested1.3.0.0 on Windows 10/11 x64 as well as Windows 11 ARM64 and it worked fine in all cases. I didn't see any functional issue so far, thanks!

Strangely, while installation of it worked like a charm under x64, the signature was considered invalid under Windows 11 ARM64. I was still able to install it and run an application using it, though. This seems to be a different behavior than on Windows x64, I think, where a failed signature verification completely prevent installation.

So far I wasn't able to figure out whether the cause of this installation glitch under ARM64 is caused by my INF file or by something else. While the signature of libusb0.sys is said to be valid by Explorer under ARM64 (right click on the file), something goes wrong during the install process.. I'll try to figure out why.

@mcuee
Copy link
Member

mcuee commented Oct 12, 2023

@sonatique
Thanks a lot for the updates.
Did you need to disable driver check to install the ARM64 driver? Do you need to enable test signing? How do you install the driver under ARM64?

Reference: as of now, Zadig does not work with Windows 11 on ARM64.
pbatard/libwdi#289

@sonatique
Copy link
Contributor Author

sonatique commented Oct 12, 2023

@mcuee
As far as I can tell (but I am little experienced with Windows ARM), the behavior is a bit different from what I expected based on my experience with Windows x64. On recent Windows x64, either your driver is signed or is not and you cannot install a non properly signed driver, I think there is no option to give a waiver.

Since the driver is signed, on Windows x64 there was no warning, no nothing, installation went straight.

On ARM64 I got a red warning dialog telling me that the publisher is unknow, but gave me the choice to install anyway and afterward it didn't complain anymore.

I did not disable signing check nor enable test signing, I used plain configuration.

I installed the driver under ARM64 using the same CAT / INF file I use for Windows x64, just modified for adding ARM64 (I signed the .cat, but not the .sys)

But maybe I did a mistake causing the red warning, I don't know. Maybe someone with more experience could tell.

As of now I can not share my CAT / INF, I'll try to see if I can later. Do you know whether there exist a reference for it? Could Zadig be considered a reference? Maybe the fact that Zading is having issue as well as I do could be caused by an issue on Windows ARM64 itself, I don't know

@mcuee
Copy link
Member

mcuee commented Oct 12, 2023

I did not disable signing check nor enable test signing, I used plain configuration.

I installed the driver under ARM64 using the same CAT / INF file I use for Windows x64, just modified for adding ARM64 (I signed the .cat, but not the .sys)

But maybe I did a mistake causing the red warning, I don't know. Maybe someone with more experience could tell.

Interesting. Thanks for the info.

So you have a valid code signing certificate (and it is an EV certificate), right?

Then you sign the driver package to get a signed cat file under Windows 11 on ARM64, and then it works, even though there is a red warning dialog telling you that the publisher is unknown. libusb0.sys was already signed in this case by @dontech.

This is very interesting. Supposedly the right way is to submit the driver package to Microsoft and carry out attestation signing which is what @dontech has done to get signed libusb0.sys. But you did not need to do that.

And from what you mentioned, your method will not work for Windows 11 on x64, but strangely it works under WIndows 11 on ARM64. Interesting.

@pbatard
You may be interested to know this Windows 11 on ARM64 behavior.

@sonatique
Copy link
Contributor Author

@mcuee :
I do not have an EV, I only have an OV. That's why I can sign the "driver package" (CAT file) but not the libusb0.sys itself.

Actually I tried to things: an INF based on the "legacy" system where the driver ends-up installed in system32/drivers. (The problem is that it is not unique: different app could end-up installing different version of libsub0.sys and the last one will override previous one, but that is the way of doing that has been used so far).
With this approach I got the red warning on ARM64 (nothing on x64), but I was able to install anyway without any other trick than clicking on "install anyway", and everything was working fine afterward.

I also tried the more modern approach where the file ends up in the "Driver Store" with a unique name. I would prefer using this method. This worked without glitch for x64, but completely failed on ARM64: I just got a dialog saying "Windows encountered a problem installing the driver for your device" but no mention of signing issue (or any other issue).

I am currently trying to understand how I could get more details about this error. DebugView doesn't work at all on ARM64, and I have no idea so far where to look for logs or something that could give me a hint about what is wrong.

@dontech
Copy link

dontech commented Dec 29, 2023

OK, I think i need to install WIN11 ARM64 on one of my boxes and debug the problem. I added ARM64 more or less blind-folded and did not have any way of verifying this.

@dontech
Copy link

dontech commented Dec 30, 2023

Strangely, while installation of it worked like a charm under x64, the signature was considered invalid under Windows 11 ARM64. I was still able to install it and run an application using it, though. This seems to be a different behavior than on Windows x64, I think, where a failed signature verification completely prevent installation.

So far I wasn't able to figure out whether the cause of this installation glitch under ARM64 is caused by my INF file or by something else. While the signature of libusb0.sys is said to be valid by Explorer under ARM64 (right click on the file), something goes wrong during the install process.. I'll try to figure out why.

I have now tried this myself on ARM64 Windows 11. It seems to work great.

I tried both:

  1. Signed version.
  2. Unsigned version, with driver signing checks disabled.

Both worked without any problems.
So, I am fairly sure your INF is broken or something similar.

@dontech
Copy link

dontech commented Dec 30, 2023

@sonatique I can recommend using the INF file from the repository under "ddk_make" as a template. This seems to work great on all supported platforms.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
libusbk_libusb0 Windows libusbk backend for libusbk.sys and libusb0.sys windows
Projects
None yet
Development

No branches or pull requests

5 participants