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

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

Closed
tsailer opened this issue Feb 28, 2017 · 38 comments
Closed

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

tsailer opened this issue Feb 28, 2017 · 38 comments

Comments

@tsailer
Copy link

tsailer commented Feb 28, 2017

With UsbDk 1.0.17:

./UsbDkController.exe -n
Enumerate USB devices
Found 6 USB devices:
0. FilterID: 1, Port: 1, ID: 8087:8001, Configs: 1, Speed: 3
USB\VID_8087&PID_8001 1
Descriptor for configuration #0: size 25

  1. FilterID: 3, Port: 3, ID: 8087:0a2a, Configs: 1, Speed: 2
    USB\VID_8087&PID_0A2A 3
    Descriptor for configuration #0: size 177
  2. FilterID: 3, Port: 6, ID: 1bcf:2b8d, Configs: 1, Speed: 3
    USB\VID_1BCF&PID_2B8D 6
    Descriptor for configuration #0: size 737
  3. FilterID: 3, Port: 7, ID: 0a5c:5804, Configs: 1, Speed: 2
    USB\VID_0A5C&PID_5804 0123456789ABCD
    Descriptor for configuration #0: size 269
  4. FilterID: 5, Port: 1, ID: 0403:6010, Configs: 1, Speed: 3
    USB\VID_0403&PID_6010 AX00000003
    Descriptor for configuration #0: size 55
  5. 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
Copy link
Contributor

Did it work with UsbDk 1.0.16?

@dmitryfleytman
Copy link
Contributor

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

@tsailer
Copy link
Author

tsailer commented Feb 28, 2017

1.0.16 works

@tsailer
Copy link
Author

tsailer commented Feb 28, 2017

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

tsailer commented Mar 1, 2017

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

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

tsailer commented Mar 1, 2017

Non-working case

UsbDkTrace.zip

@tsailer
Copy link
Author

tsailer commented Mar 1, 2017

Working...
UsbDkTrace.zip

@tsailer
Copy link
Author

tsailer commented Mar 8, 2017

any news?

@dmitryfleytman
Copy link
Contributor

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

tsailer commented Mar 24, 2017

any news?

@ybendito
Copy link
Collaborator

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

tsailer commented Mar 27, 2017

image

@ybendito
Copy link
Collaborator

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

tsailer commented Mar 27, 2017

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

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

tsailer commented Mar 28, 2017

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

@tsailer
Copy link
Author

tsailer commented Mar 28, 2017

Without delay
usbdknotworking.zip

@tsailer
Copy link
Author

tsailer commented Mar 28, 2017

With 300ms delay
usbdkworking.zip

@ybendito
Copy link
Collaborator

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

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

@ybendito
Copy link
Collaborator

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

@tsailer
Copy link
Author

tsailer commented Mar 29, 2017

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:
0. FilterID: 5, Port: 1, ID: 8087:8001, Configs: 1, Speed: 3
USB\VID_8087&PID_8001 1
Descriptor for configuration #0: size 25

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

@ybendito
Copy link
Collaborator

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

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

@ybendito
Copy link
Collaborator

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

@tsailer
Copy link
Author

tsailer commented Mar 29, 2017

Another try...

usbdkworking.zip

usbdknotworking.zip

@ybendito
Copy link
Collaborator

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

@ybendito
Copy link
Collaborator

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

Ecco commented Apr 22, 2017

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

Hi @Ecco ,

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

Dmitry

@Ecco
Copy link

Ecco commented Apr 23, 2017

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

  • I'm encountering that issue on Windows 7
  • It's not libusb_open per se that fails in my case but libusb_get_device_list.
  • The buggy sequence seems to be "libusb_get_device_list", "libusb_open", "libusb_close", and then a last "libusb_get_device_list". At this point, the initial device (that I just opened and closed) isn't there anymore.

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

@dmitryfleytman
Copy link
Contributor

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

@Ecco
Copy link

Ecco commented Apr 23, 2017

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

@dmitryfleytman
Copy link
Contributor

@Ecco

  1. We are not sure if FTDI devices visible with UsbDkController, but not to libusbx #39 and Regression: DeviceIoControl failed from libusb_open immediately after libusb_close on Windows 10 #43 are the same, waiting for answers from @tsailer
  2. The problem you observe is exactly the same as described in Regression: DeviceIoControl failed from libusb_open immediately after libusb_close on Windows 10 #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
Copy link
Contributor

Hi @tsailer

Did you have a chance to check the private build provided by Yuri (#39 (comment)).

Thanks,
Dmitry

@tsailer
Copy link
Author

tsailer commented May 15, 2017

Hi @dmitryfleytman,

please see the logs in the comment from March 29

Thanks,
Thomas

@ybendito
Copy link
Collaborator

ybendito commented Jun 4, 2017

This issue is the same as #43
The root cause is commit 848bb79 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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants