search

daynix / UsbDk

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

FTDI devices visible with UsbDkController, but not to libusbx #39

Closed tsailer closed 7 years ago

tsailer commented 7 years ago

With UsbDk 1.0.17:

./UsbDkController.exe -n Enumerate USB devices Found 6 USB devices:

  1. FilterID: 1, Port: 1, ID: 8087:8001, Configs: 1, Speed: 3 USB\VID_8087&PID_8001 1 Descriptor for configuration #0: size 25
  2. FilterID: 3, Port: 3, ID: 8087:0a2a, Configs: 1, Speed: 2 USB\VID_8087&PID_0A2A 3 Descriptor for configuration #0: size 177
  3. FilterID: 3, Port: 6, ID: 1bcf:2b8d, Configs: 1, Speed: 3 USB\VID_1BCF&PID_2B8D 6 Descriptor for configuration #0: size 737
  4. FilterID: 3, Port: 7, ID: 0a5c:5804, Configs: 1, Speed: 2 USB\VID_0A5C&PID_5804 0123456789ABCD Descriptor for configuration #0: size 269
  5. FilterID: 5, Port: 1, ID: 0403:6010, Configs: 1, Speed: 3 USB\VID_0403&PID_6010 AX00000003 Descriptor for configuration #0: size 55
  6. FilterID: 71, Port: 1, ID: 0403:6010, Configs: 1, Speed: 2 FTDIBUS\VID_0403+PID_6010+AX00000003B 0000 Descriptor for configuration #0: size 32

Output from libusb_get_device_list: index 0 vendor 0x8087 product 0x8001 index 1 vendor 0x8087 product 0x0a2a index 2 vendor 0x1bcf product 0x2b8d index 3 vendor 0x0a5c product 0x5804

This is with the fedora mingw libusbx. Name : mingw64-libusbx Version : 1.0.21 Release : 1.fc25 Architecture: noarch Install Date: Mon 27 Feb 2017 02:35:09 PM CET Group : Unspecified Size : 333790 License : LGPLv2+ Signature : RSA/SHA256, Sat 29 Oct 2016 03:58:53 PM CEST, Key ID 4089d8f2fdb19c98 Source RPM : mingw-libusbx-1.0.21-1.fc25.src.rpm Build Date : Sat 29 Oct 2016 03:56:47 PM CEST Build Host : buildvm-22.phx2.fedoraproject.org Relocations : (not relocatable) Packager : Fedora Project Vendor : Fedora Project URL : http://libusbx.org/ Summary : MinGW library which allows userspace access to USB devices Description : This package contains the header files and libraries needed to develop applications that use libusbx.

This is on Windows 7. It is somewhat erratic, sometimes the ftdi devices are there, more often however not.

dmitryfleytman commented 7 years ago

Did it work with UsbDk 1.0.16?

dmitryfleytman commented 7 years ago

Could you please post log of libusbx for the problematic case?

tsailer commented 7 years ago

1.0.16 works

tsailer commented 7 years ago

[timestamp] [threadID] facility level [function call]

[ 0.000000] [00000d44] libusb: debug [libusb_init] created default context [ 0.000000] [00000d44] libusb: debug [libusb_init] libusb v1.0.21.11156 [ 0.000000] [00000d44] libusb: debug [setup_cancel_io] Will use CancelIoEx for I/O cancellation [ 0.000000] [00000d44] libusb: debug [windows_init_clock] hires timer available (Frequency: 2240966 Hz) [ 0.000000] [00000d44] libusb: debug [windows_init_clock] timer thread will run on core #0 [ 0.000000] [00000d44] libusb: debug [htab_create] using 1021 entries hash table [ 0.000000] [00000d44] libusb: debug [usbi_add_pollfd] add fd 0 events 1 [ 0.000000] [00000d44] libusb: debug [libusb_get_device_list] [ 0.000000] [00000d44] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00000d44] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00000d44] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00000d44] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00000d44] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00000d44] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00000d44] libusb: debug [libusb_unref_device] destroy device 1.2 [ 0.000000] [00000d44] libusb: debug [libusb_unref_device] destroy device 2.4 [ 0.000000] [00000d44] libusb: debug [libusb_unref_device] destroy device 2.7 [ 0.000000] [00000d44] libusb: debug [libusb_unref_device] destroy device 2.8 [ 0.000000] [00000d44] libusb: debug [libusb_open] open 7.3 [ 0.200028] [00000d44] libusb: debug [libusb_get_device_descriptor] [ 0.200028] [00000d44] libusb: debug [libusb_alloc_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_submit_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200028] [00000d44] libusb: debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200028] [00000d44] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200028] [00000d44] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200028] [00000d44] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200028] [00000d44] libusb: debug [handle_events] poll() returned 1 [ 0.200028] [00000d44] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200028] [00000d44] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200028] [00000d44] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 4 [ 0.200028] [00000d44] libusb: debug [usbi_handle_transfer_completion] transfer 00000000013DBB68 has callback 000000006B607750 [ 0.200028] [00000d44] libusb: debug [sync_transfer_cb] actual_length=4 [ 0.200028] [00000d44] libusb: debug [libusb_free_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_alloc_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_submit_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200028] [00000d44] libusb: debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200028] [00000d44] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200028] [00000d44] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200028] [00000d44] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200028] [00000d44] libusb: debug [handle_events] poll() returned 1 [ 0.200028] [00000d44] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200028] [00000d44] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200028] [00000d44] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 18 [ 0.200028] [00000d44] libusb: debug [usbi_handle_transfer_completion] transfer 00000000013DBB68 has callback 000000006B607750 [ 0.200028] [00000d44] libusb: debug [sync_transfer_cb] actual_length=18 [ 0.200028] [00000d44] libusb: debug [libusb_free_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_alloc_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_submit_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200028] [00000d44] libusb: debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200028] [00000d44] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200028] [00000d44] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200028] [00000d44] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200028] [00000d44] libusb: debug [handle_events] poll() returned 1 [ 0.200028] [00000d44] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200028] [00000d44] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200028] [00000d44] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 4 [ 0.200028] [00000d44] libusb: debug [usbi_handle_transfer_completion] transfer 00000000013DBB68 has callback 000000006B607750 [ 0.200028] [00000d44] libusb: debug [sync_transfer_cb] actual_length=4 [ 0.200028] [00000d44] libusb: debug [libusb_free_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_alloc_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_submit_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200028] [00000d44] libusb: debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200028] [00000d44] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200028] [00000d44] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200028] [00000d44] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200028] [00000d44] libusb: debug [handle_events] poll() returned 1 [ 0.200028] [00000d44] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200028] [00000d44] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200028] [00000d44] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 44 [ 0.200028] [00000d44] libusb: debug [usbi_handle_transfer_completion] transfer 00000000013DBB68 has callback 000000006B607750 [ 0.200028] [00000d44] libusb: debug [sync_transfer_cb] actual_length=44 [ 0.200028] [00000d44] libusb: debug [libusb_free_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_alloc_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_submit_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200028] [00000d44] libusb: debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200028] [00000d44] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200028] [00000d44] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200028] [00000d44] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200028] [00000d44] libusb: debug [handle_events] poll() returned 1 [ 0.200028] [00000d44] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200028] [00000d44] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200028] [00000d44] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 4 [ 0.200028] [00000d44] libusb: debug [usbi_handle_transfer_completion] transfer 00000000013DBB68 has callback 000000006B607750 [ 0.200028] [00000d44] libusb: debug [sync_transfer_cb] actual_length=4 [ 0.200028] [00000d44] libusb: debug [libusb_free_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_alloc_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [libusb_submit_transfer] transfer 00000000013DBB68 [ 0.200028] [00000d44] libusb: debug [usbi_add_pollfd] add fd 1 events 1

tsailer commented 7 years ago

Another trace

[timestamp] [threadID] facility level [function call]

[ 0.000000] [00002820] libusb: debug [libusb_init] created default context [ 0.000000] [00002820] libusb: debug [libusb_init] libusb v1.0.21.11156 [ 0.000000] [00002820] libusb: debug [setup_cancel_io] Will use CancelIoEx for I/O cancellation [ 0.000000] [00002820] libusb: debug [windows_init_clock] hires timer available (Frequency: 2240966 Hz) [ 0.000000] [00002820] libusb: debug [windows_init_clock] timer thread will run on core #0 [ 0.000000] [00002820] libusb: debug [htab_create] using 1021 entries hash table [ 0.000000] [00002820] libusb: debug [usbi_add_pollfd] add fd 0 events 1 [ 0.000000] [00002820] libusb: debug [libusb_get_device_list] [ 0.000000] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.000000] [00002820] libusb: debug [libusb_unref_device] destroy device 1.2 [ 0.000000] [00002820] libusb: debug [libusb_unref_device] destroy device 2.4 [ 0.000000] [00002820] libusb: debug [libusb_unref_device] destroy device 2.7 [ 0.000000] [00002820] libusb: debug [libusb_unref_device] destroy device 2.8 [ 0.000000] [00002820] libusb: debug [libusb_open] open 7.3 [ 0.200034] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.200034] [00002820] libusb: debug [libusb_alloc_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_submit_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200034] [00002820] libusb: debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200034] [00002820] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200034] [00002820] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200034] [00002820] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200034] [00002820] libusb: debug [handle_events] poll() returned 1 [ 0.200034] [00002820] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200034] [00002820] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200034] [00002820] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 4 [ 0.200034] [00002820] libusb: debug [usbi_handle_transfer_completion] transfer 000000000418D658 has callback 000000006B607750 [ 0.200034] [00002820] libusb: debug [sync_transfer_cb] actual_length=4 [ 0.200034] [00002820] libusb: debug [libusb_free_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_alloc_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_submit_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200034] [00002820] libusb: debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200034] [00002820] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200034] [00002820] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200034] [00002820] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200034] [00002820] libusb: debug [handle_events] poll() returned 1 [ 0.200034] [00002820] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200034] [00002820] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200034] [00002820] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 18 [ 0.200034] [00002820] libusb: debug [usbi_handle_transfer_completion] transfer 000000000418D658 has callback 000000006B607750 [ 0.200034] [00002820] libusb: debug [sync_transfer_cb] actual_length=18 [ 0.200034] [00002820] libusb: debug [libusb_free_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_alloc_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_submit_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200034] [00002820] libusb: debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200034] [00002820] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200034] [00002820] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200034] [00002820] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200034] [00002820] libusb: debug [handle_events] poll() returned 1 [ 0.200034] [00002820] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200034] [00002820] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200034] [00002820] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 4 [ 0.200034] [00002820] libusb: debug [usbi_handle_transfer_completion] transfer 000000000418D658 has callback 000000006B607750 [ 0.200034] [00002820] libusb: debug [sync_transfer_cb] actual_length=4 [ 0.200034] [00002820] libusb: debug [libusb_free_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_alloc_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_submit_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200034] [00002820] libusb: debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200034] [00002820] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200034] [00002820] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200034] [00002820] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200034] [00002820] libusb: debug [handle_events] poll() returned 1 [ 0.200034] [00002820] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200034] [00002820] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200034] [00002820] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 44 [ 0.200034] [00002820] libusb: debug [usbi_handle_transfer_completion] transfer 000000000418D658 has callback 000000006B607750 [ 0.200034] [00002820] libusb: debug [sync_transfer_cb] actual_length=44 [ 0.200034] [00002820] libusb: debug [libusb_free_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_alloc_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_submit_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200034] [00002820] libusb: debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200034] [00002820] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200034] [00002820] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200034] [00002820] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200034] [00002820] libusb: debug [handle_events] poll() returned 1 [ 0.200034] [00002820] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200034] [00002820] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200034] [00002820] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 4 [ 0.200034] [00002820] libusb: debug [usbi_handle_transfer_completion] transfer 000000000418D658 has callback 000000006B607750 [ 0.200034] [00002820] libusb: debug [sync_transfer_cb] actual_length=4 [ 0.200034] [00002820] libusb: debug [libusb_free_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_alloc_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_submit_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [usbi_add_pollfd] add fd 1 events 1 [ 0.200034] [00002820] libusb:Targets: 00000003 debug [libusb_get_next_timeout] next timeout in 1.000000s [ 0.200034] [00002820] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling [ 0.200034] [00002820] libusb: debug [handle_events] poll fds modified, reallocating [ 0.200034] [00002820] libusb: debug [handle_events] poll() 2 fds with timeout in 1000ms [ 0.200034] [00002820] libusb: debug [handle_events] poll() returned 1 [ 0.200034] [00002820] libusb: debug [windows_handle_events] checking fd 1 with revents = 0001 [ 0.200034] [00002820] libusb: debug [usbi_remove_pollfd] remove fd 1 [ 0.200034] [00002820] libusb: debug [windows_transfer_callback] handling I/O completion with errcode 0, size 22 [ 0.200034] [00002820] libusb: debug [usbi_handle_transfer_completion] transfer 000000000418D658 has callback 000000006B607750 [ 0.200034] [00002820] libusb: debug [sync_transfer_cb] actual_length=22 [ 0.200034] [00002820] libusb: debug [libusb_free_transfer] transfer 000000000418D658 [ 0.200034] [00002820] libusb: debug [libusb_close] [ 0.200034] [00002820] libusb: debug [libusb_open] open 41.3 [ 0.200034] [00002820] libusb: error [usbdk_open] Redirector startup failed [ 0.200034] [00002820] libusb: debug [libusb_open] open 41.3 returns -99 [ 0.200034] [00002820] libusb: debug [libusb_unref_device] destroy device 7.3 [ 0.200034] [00002820] libusb: debug [libusb_unref_device] destroy device 41.3 [ 0.200034] [00002820] libusb: debug [libusb_exit] [ 0.200034] [00002820] libusb: debug [libusb_exit] destroying default context [ 0.200034] [00002820] libusb: debug [usbi_remove_pollfd] remove fd 0 [ 0.200034] [0000295c] libusb: debug [windows_clock_gettime_threaded] timer thread quitting [ 0.200034] [00002820] libusb: debug [libusb_init] created default context [ 0.200034] [00002820] libusb: debug [libusb_init] libusb v1.0.21.11156 [ 0.200034] [00002820] libusb: debug [setup_cancel_io] Will use CancelIoEx for I/O cancellation [ 0.200034] [00002820] libusb: debug [windows_init_clock] hires timer available (Frequency: 2240966 Hz) [ 0.200034] [00002820] libusb: debug [windows_init_clock] timer thread will run on core #0 [ 0.200034] [00002820] libusb: debug [htab_create] using 1021 entries hash table [ 0.200034] [00002820] libusb: debug [usbi_add_pollfd] add fd 0 events 1 [ 0.200034] [00002820] libusb: debug [libusb_get_device_list] [ 0.200034] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.200034] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.200034] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.200034] [00002820] libusb: debug [libusb_get_device_descriptor] [ 0.200034] [00002820] libusb: debug [libusb_unref_device] destroy device 1.2 [ 0.200034] [00002820] libusb: debug [libusb_unref_device] destroy device 2.4 [ 0.200034] [00002820] libusb: debug [libusb_unref_device] destroy device 2.7 [ 0.200034] [00002820] libusb: debug [libusb_unref_device] destroy device 2.8 [ 0.200034] [00002820] libusb: debug [libusb_exit] [ 0.200034] [00002820] libusb: debug [libusb_exit] destroying default context [ 0.200034] [00002820] libusb: debug [usbi_remove_pollfd] remove fd 0 [ 0.200034] [000012d0] libusb: debug [windows_clock_gettime_threaded] timer thread quitting

dmitryfleytman commented 7 years ago

Hmmm, that is interesting. Could you please also provide UsbDk traces for case when devices appear in the list and cases when they don't. It is important to have UsbDk device trace from device plug and until libusb_get_device_list return.

(As usually see this for instructions on trace collection)

Thanks in advance, Dmitry

tsailer commented 7 years ago

Non-working case

UsbDkTrace.zip

tsailer commented 7 years ago

Working... UsbDkTrace.zip

tsailer commented 7 years ago

any news?

dmitryfleytman commented 7 years ago

Hi,

Not yet.

Sorry for the delay, we are busy with Win10 support and a bunch of other tasks. This bug is next in the queue.

~Dmitry

tsailer commented 7 years ago

any news?

ybendito commented 7 years ago

We do not reproduce any problem with similar FTDI device. Something is definitely going wrong as FTDIBUS... device shall not be listed under UsbDk controller. Can you please provide additional info (no spice connection required):

  1. Do we understand it correctly that on the same UsbDk version 1.0-17 the redirection sometimes works, sometimes does not?
  2. On client machine please open device manager, select View - "Devices by connection", under one of USB hubs locate USB Serial Converter with PnP ID (visible in Properties->Details->Hardware IDs) USB\VID_0403&PID_6010, under it locate device with PnP ID USB\VID_0403&PID_6010&MI_01, for it select Properties->Driver->Driver Details and attach a screenshot of "Driver File Details" window.

Thanks

tsailer commented 7 years ago

image

ybendito commented 7 years ago

Are these screenshots for USB\VID_0403&PID_6010&MI_00 and USB\VID_0403&PID_6010&MI_01? Do we understand it correctly that on the same UsbDk version 1.0-17 the redirection sometimes works, sometimes does not?

tsailer commented 7 years ago

Yes.

I did some further experiments, it seems to be timing sensitive. A delay of about 300ms between enumerating and connecting seems to make it work

ybendito commented 7 years ago

https://drive.google.com/file/d/0B9gp3tZmgMhdMmVtX3pRZ1pYQlE/view?usp=sharing

Please try this private build of UsbDk. It requires test signing to be enabled on the machine (see readme.txt inside). If it does not fix the problem, please do the record as was done earlier.

tsailer commented 7 years ago

I don't see any change in behaviour...

tsailer commented 7 years ago

Without delay usbdknotworking.zip

tsailer commented 7 years ago

With 300ms delay usbdkworking.zip

ybendito commented 7 years ago

Can you please verify that installed UsbDk is this one. Due to some reason one of records dated March 1. What is the timestamp of %windir%\system32\drivers\usbdk.sys? Are you working with Win7 x86 or x64?

ybendito commented 7 years ago

Additionally: please provide the result of "usbdkcontroller.exe -n"

ybendito commented 7 years ago

I'm quite sure the latest logs provided are done with UsbDk driver 1.0-17 and not with private version. Please recheck.

tsailer commented 7 years ago

Timestamp: Created: Yesterday, ‎28. ‎März ‎2017, ‏‎13:03:36 Modified: Montag, ‎27. ‎März ‎2017, ‏‎19:02:04 Signature: WDKTestCert yuri.benditovich,131140395240021131 File Size: 80'960 bytes

So it looks to me like it was indeed the test version.

This is Win7 x64

./UsbDkController.exe -n Enumerate USB devices Found 5 USB devices:

  1. FilterID: 5, Port: 1, ID: 8087:8001, Configs: 1, Speed: 3 USB\VID_8087&PID_8001 1 Descriptor for configuration #0: size 25
  2. FilterID: 9, Port: 3, ID: 8087:0a2a, Configs: 1, Speed: 2 USB\VID_8087&PID_0A2A 3 Descriptor for configuration #0: size 177
  3. FilterID: 9, Port: 6, ID: 1bcf:2b8d, Configs: 1, Speed: 3 USB\VID_1BCF&PID_2B8D 6 Descriptor for configuration #0: size 737
  4. FilterID: 9, Port: 7, ID: 0a5c:5804, Configs: 1, Speed: 2 USB\VID_0A5C&PID_5804 0123456789ABCD Descriptor for configuration #0: size 269
  5. FilterID: 11, Port: 3, ID: 0403:6010, Configs: 1, Speed: 3 USB\VID_0403&PID_6010 AX00000004 Descriptor for configuration #0: size 55
ybendito commented 7 years ago

Now, it seems OK and FTDIBUS device is not enumerated (as it should be). If the functional problem still happens (as it was with 1.0-17), please make a record when redirection does not work and (if possible) when it does. Previous records were done with 1.0-17 (I can see it by trace events that are different in test version). Thanks, Yuri

ybendito commented 7 years ago

usbdkworking.zip and usbdknotworking.zip are identical, the file contains inside zip with logs from UsbDk-1.0-17 dated March 1

ybendito commented 7 years ago

I would suggest to keep old ETL files aside and then delete them before making record.

tsailer commented 7 years ago

Another try...

usbdkworking.zip

usbdknotworking.zip

ybendito commented 7 years ago

Can you please attach the image of this specific model of FTDI device?

ybendito commented 7 years ago

With private build of UsbDk is it still happens the FTDI device is enumerated in UsbDkController and not visible in lubusb list? Can you please describe exactly what you do via libusb?

Ecco commented 7 years ago

I'm experiencing the same problem. Listing devices with libusb using UsbDk as a driver sometimes misses some device. It's very erratic. I'm doing something very simple : scan devices using libusb, and open the one I'm interested in if I find it. I noticed that doing that same routine twice in a row will work the first time and fail the second one.

dmitryfleytman commented 7 years ago

Hi @Ecco ,

It looks like you experience the same problem as #43, please see my comments there for explanations and possible solutions.

Dmitry

Ecco commented 7 years ago

@dmitryfleytman That seems like a very good explanation. Several thins:

Would that mean that this issue (#39) is just another manifestation of the same root cause as #43?

dmitryfleytman commented 7 years ago

We are not sure yet. Waiting for answers from @tsailer...

Ecco commented 7 years ago

@dmitryfleytman Ooops sorry, I edited my comment while you were replying. Please see udpated version above.

dmitryfleytman commented 7 years ago

@Ecco

  1. We are not sure if #39 and #43 are the same, waiting for answers from @tsailer
  2. The problem you observe is exactly the same as described in #43, after device close, there is a time frame (usually around 0.5 sec) when just closed device is not visible to the system.
dmitryfleytman commented 7 years ago

Hi @tsailer

Did you have a chance to check the private build provided by Yuri (https://github.com/daynix/UsbDk/issues/39#issuecomment-290565168).

Thanks, Dmitry

tsailer commented 7 years ago

Hi @dmitryfleytman,

please see the logs in the comment from March 29

Thanks, Thomas

ybendito commented 7 years ago

This issue is the same as https://github.com/daynix/UsbDk/issues/43 The root cause is commit https://github.com/daynix/UsbDk/commit/848bb79ac2379c1ce0681088320f4ae504f2bce3 that increases the time between libusb_close() and device availability for next redirect operation. Even before the change it was not guaranteed that the device is available immediately after libusb_close() returns. After deep internal discussion we decided to keep the behavior as it is in 0.17 and up. External applications using libusb should either wait for hotplug event related to the device of interest or wait for the device to re-appear in libusb device list. After that, libusb_open() will work as expected.