Hello, This bug may be related to Bug #231076. This time I use 2 USB devices instead of 1. When my program exits it stops every USB transfers. I use interrupts transfers with a long timeout to read card events. So with 2 readers I have 2 such USB interrupt transfers. The first transfer is cancelled fine and I can close the reader connection. The second transfer is also cancelled with no error but libusb_handle_events_completed() does NOT return and my program is blocked. Here is a log trace when 1 reader is used: ^CLIBUSB_FUNCTION: libusb_handle_events_locked leave 01528296 [679490304] pcscdaemon.c:193:signal_thread() Received signal: 2 00000011 [679490304] pcscdaemon.c:226:signal_thread() Preparing for suicide LIBUSB_FUNCTION: libusb_handle_events_timeout_completed exit 00000012 [683937920] ccid_usb.c:1333:InterruptRead() ret: -10 00000007 [683937920] ccid_usb.c:1336:InterruptRead() 00000005 [683937920] ccid_usb.c:1331:InterruptRead() LIBUSB_FUNCTION: libusb_handle_events_timeout_completed enter LIBUSB_FUNCTION: libusb_handle_events_locked enter LIBUSB_FUNCTION: libusb10_handle_events_sub enter 01658982 [679490944] hotplug_libusb.c:403:HPRescanUsbBus() Hotplug stopped 00010624 [679489664] readerfactory.c:1353:RFCleanupReaders() entering cleaning function 00000008 [679489664] readerfactory.c:1362:RFCleanupReaders() Stopping reader: Inside Secure AT90SCR200 00 00 00000005 [679489664] readerfactory.c:610:RFRemoveReader() UnrefReader() count was: 1 00000003 [679489664] eventhandler.c:175:EHDestroyEventHandler() Stomping thread. 00000004 [679489664] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB1, usb:2406/6407:libusb-1.0:0:2:0 (lun: 0) 00000004 [679489664] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB2, usb:2406/6407:libusb-1.0:0:2:0 (lun: 0) 00000004 [679489664] eventhandler.c:200:EHDestroyEventHandler() Request stopping of polling thread 00000004 [679489664] ifdhandler.c:346:IFDHStopPolling() usb:2406/6407:libusb-1.0:0:2:0 (lun: 0) LIBUSB_FUNCTION: libusb_cancel_transfer enter libusb10.c:1556 LIBUSB_FUNCTION: libusb_cancel_transfer leave retval: 0 LIBUSB_FUNCTION: libusb_handle_events_locked leave LIBUSB_FUNCTION: libusb_handle_events_timeout_completed exit 00000809 [683937920] ccid_usb.c:1333:InterruptRead() ret: 0 00000005 [683937920] ccid_usb.c:1355:InterruptRead() 00000004 [683937920] ccid_usb.c:1362:InterruptRead() after (0) (3) 00000004 [683937920] ccid_usb.c:1377:InterruptRead() InterruptRead (0/2): 3 00425691 [683937920] eventhandler.c:504:EHStatusHandlerThread() Die 00000030 [679489664] eventhandler.c:215:EHDestroyEventHandler() Thread stomped. 00000007 [679489664] readerfactory.c:1126:RFUnInitializeReader() Attempting shutdown of Inside Secure AT90SCR200 00 00. 00000006 [679489664] ifdhandler.c:284:IFDHCloseChannel() usb:2406/6407:libusb-1.0:0:2:0 (lun: 0) 00000006 [679489664] -> 000000 63 00 00 00 00 00 09 00 00 00 LIBUSB_FUNCTION: libusb_bulk_transfer enter LIBUSB_FUNCTION: libusb_submit_transfer enter LIBUSB_FUNCTION: libusb_submit_transfer leave 0 LIBUSB_FUNCTION: libusb_handle_events_timeout_completed enter LIBUSB_FUNCTION: libusb_handle_events_locked enter LIBUSB_FUNCTION: libusb10_handle_events_sub enter LIBUSB_TRANSFER: sync I/O done LIBUSB_FUNCTION: libusb_handle_events_locked leave LIBUSB_FUNCTION: libusb_handle_events_timeout_completed exit LIBUSB_FUNCTION: libusb_bulk_transfer leave LIBUSB_FUNCTION: libusb_bulk_transfer enter LIBUSB_FUNCTION: libusb_submit_transfer enter LIBUSB_FUNCTION: libusb_submit_transfer leave 0 LIBUSB_FUNCTION: libusb_handle_events_timeout_completed enter LIBUSB_FUNCTION: libusb_handle_events_locked enter LIBUSB_FUNCTION: libusb10_handle_events_sub enter LIBUSB_TRANSFER: sync I/O done LIBUSB_FUNCTION: libusb_handle_events_locked leave LIBUSB_FUNCTION: libusb_handle_events_timeout_completed exit LIBUSB_FUNCTION: libusb_bulk_transfer leave 00000310 [679489664] <- 000000 81 00 00 00 00 00 09 01 00 00 00000004 [679489664] ccid_usb.c:942:CloseUSB() Closing USB device: 0/2 00000003 [679489664] ccid_usb.c:952:CloseUSB() Last slot closed. Release resources 00008782 [679489664] ccid_usb.c:189:close_libusb_if_needed() libusb_exit 00000016 [679489664] readerfactory.c:987:RFUnloadReader() Unloading reader driver. 00000027 [679489664] winscard_svc.c:155:ContextsDeinitialize() remaining threads: 0 00000005 [679489664] pcscdaemon.c:785:at_exit() cleaning /var/run/pcscd Now a trace when 2 readers are used: ^C02182975 [679490304] pcscdaemon.c:193:signal_thread() Received signal: 2 00000011 [679490304] pcscdaemon.c:226:signal_thread() Preparing for suicide 00971124 [679490944] hotplug_libusb.c:403:HPRescanUsbBus() Hotplug stopped 00933563 [679489664] readerfactory.c:1353:RFCleanupReaders() entering cleaning function 00000008 [679489664] readerfactory.c:1362:RFCleanupReaders() Stopping reader: Inside Secure AT90SCR200 00 00 00000005 [679489664] readerfactory.c:610:RFRemoveReader() UnrefReader() count was: 1 00000004 [679489664] eventhandler.c:175:EHDestroyEventHandler() Stomping thread. 00000004 [679489664] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB1, usb:2406/6407:libusb-1.0:0:2:0 (lun: 0) 00000004 [679489664] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB2, usb:2406/6407:libusb-1.0:0:2:0 (lun: 0) 00000003 [679489664] eventhandler.c:200:EHDestroyEventHandler() Request stopping of polling thread 00000004 [679489664] ifdhandler.c:346:IFDHStopPolling() usb:2406/6407:libusb-1.0:0:2:0 (lun: 0) LIBUSB_FUNCTION: libusb_cancel_transfer enter libusb10.c:1556 LIBUSB_FUNCTION: libusb_cancel_transfer leave retval: 0 LIBUSB_FUNCTION: libusb_handle_events_locked leave LIBUSB_FUNCTION: libusb_handle_events_timeout_completed exit 00000817 [683937920] ccid_usb.c:1333:InterruptRead() ret: 0 00000006 [683937920] ccid_usb.c:1355:InterruptRead() 00000005 [683937920] ccid_usb.c:1362:InterruptRead() after (0) (3) 00000005 [683937920] ccid_usb.c:1377:InterruptRead() InterruptRead (0/2): 3 LIBUSB_FUNCTION: libusb_wait_for_event ERROR tv LIBUSB_FUNCTION: libusb_handle_events_locked leave LIBUSB_FUNCTION: libusb_handle_events_locked enter LIBUSB_FUNCTION: libusb_wait_for_event enter 00425967 [683937920] eventhandler.c:504:EHStatusHandlerThread() Die 00000037 [679489664] eventhandler.c:215:EHDestroyEventHandler() Thread stomped. 00000007 [679489664] readerfactory.c:1126:RFUnInitializeReader() Attempting shutdown of Inside Secure AT90SCR200 00 00. 00000008 [679489664] ifdhandler.c:284:IFDHCloseChannel() usb:2406/6407:libusb-1.0:0:2:0 (lun: 0) 00000006 [679489664] -> 000000 63 00 00 00 00 00 09 00 00 00 LIBUSB_FUNCTION: libusb_bulk_transfer enter LIBUSB_FUNCTION: libusb_submit_transfer enter LIBUSB_FUNCTION: libusb_submit_transfer leave 0 LIBUSB_FUNCTION: libusb_handle_events_timeout_completed enter LIBUSB_FUNCTION: libusb_handle_events_locked enter LIBUSB_FUNCTION: libusb10_handle_events_sub enter LIBUSB_TRANSFER: sync I/O done LIBUSB_FUNCTION: libusb_handle_events_locked leave LIBUSB_FUNCTION: libusb_handle_events_timeout_completed exit LIBUSB_FUNCTION: libusb_bulk_transfer leave LIBUSB_FUNCTION: libusb_bulk_transfer enter LIBUSB_FUNCTION: libusb_submit_transfer enter LIBUSB_FUNCTION: libusb_wait_for_event ERROR tv LIBUSB_FUNCTION: libusb_handle_events_locked leave LIBUSB_FUNCTION: libusb_handle_events_locked enter LIBUSB_FUNCTION: libusb_wait_for_event enter LIBUSB_FUNCTION: libusb_submit_transfer leave 0 LIBUSB_FUNCTION: libusb_handle_events_timeout_completed enter LIBUSB_FUNCTION: libusb_handle_events_locked enter LIBUSB_FUNCTION: libusb10_handle_events_sub enter LIBUSB_TRANSFER: sync I/O done LIBUSB_FUNCTION: libusb_handle_events_locked leave LIBUSB_FUNCTION: libusb_handle_events_timeout_completed exit LIBUSB_FUNCTION: libusb_bulk_transfer leave LIBUSB_FUNCTION: libusb_wait_for_event ERROR tv LIBUSB_FUNCTION: libusb_handle_events_locked leave LIBUSB_FUNCTION: libusb_handle_events_locked enter LIBUSB_FUNCTION: libusb_wait_for_event enter 00000325 [679489664] <- 000000 81 00 00 00 00 00 09 01 00 00 00000014 [679489664] ccid_usb.c:942:CloseUSB() Closing USB device: 0/2 00000003 [679489664] ccid_usb.c:952:CloseUSB() Last slot closed. Release resources 00008720 [679489664] readerfactory.c:1362:RFCleanupReaders() Stopping reader: SMSC USX101x Reader (EF149371) 01 00 00000006 [679489664] readerfactory.c:610:RFRemoveReader() UnrefReader() count was: 1 00000003 [679489664] eventhandler.c:175:EHDestroyEventHandler() Stomping thread. 00000004 [679489664] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB1, usb:0424/1100:libusb-1.0:0:3:0 (lun: 10000) 00000004 [679489664] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB2, usb:0424/1100:libusb-1.0:0:3:0 (lun: 10000) 00000004 [679489664] eventhandler.c:200:EHDestroyEventHandler() Request stopping of polling thread 00000004 [679489664] ifdhandler.c:346:IFDHStopPolling() usb:0424/1100:libusb-1.0:0:3:0 (lun: 10000) LIBUSB_FUNCTION: libusb_cancel_transfer enter libusb10.c:1556 LIBUSB_FUNCTION: libusb_cancel_transfer leave retval: 0 I modified libUSB to add some more debug. The 2 traces are identical except for this sequence: LIBUSB_FUNCTION: libusb_wait_for_event ERROR tv LIBUSB_FUNCTION: libusb_handle_events_locked leave LIBUSB_FUNCTION: libusb_handle_events_locked enter LIBUSB_FUNCTION: libusb_wait_for_event enter libusb_wait_for_event() returns because it is in the case "tv == NULL" at https://github.com/freebsd/freebsd/blob/master/lib/libusb/libusb10_io.c#L312 The sequence is present 3 times in the case of 2 USB devices. it looks like libusb_cancel_transfer() has (also) an impact to another transfer. I use the same libUSB context for the 2 devices and all the USB transfers. I added logs in libusb_cancel_transfer(). For the 2 transfers that I cancel the program goes into the case /* make sure the queue doesn't stall */ at line 1544 https://github.com/freebsd/freebsd/blob/master/lib/libusb/libusb10.c#L1544 I always get this problem when I quit my program with 2 USB devices. So it is easy to reproduce. Thanks
Do you have multiple threads waiting for events on the same context when there are two devices present?
LibUSB in FreeBSD only allows one thread to do the actual polling. The other threads are just sleeping on a conditional variable. There might be a race if one thread exits, that polling will stop, but that might be fixable by broadcasting on the condition variable used internally.
Created attachment 197544 [details] LibUSB patch Can you try this patch?
Yes, I use different threads with the same libUSB context. For each USB smart card reader I have 2 threads: - one thread is waiting some data from an interrupt point - one thread is used to send commands/receive data from the reader using 2 other IN/OUT end points So with 2 devices I have 4 threads using the same libUSB context. If I understand correctly I should already have issues with only 1 reader and 2 threads. Maybe that could explain some behaviour I see. I will try your patch tomorrow. Note: my program works fine on GNU/Linux :-)
Your patch does fix the issue. Great. Thanks
A commit references this bug: Author: hselasky Date: Fri Sep 28 10:28:22 UTC 2018 New revision: 338993 URL: https://svnweb.freebsd.org/changeset/base/338993 Log: When multiple threads are involved receiving completion events in LibUSB make sure there is always a master polling thread, by setting the "ctx_handler" field in the context. Else the reception of completion events can stop. This happens if event threads are created and destroyed during runtime. Found by: Ludovic Rousseau <ludovic.rousseau+freebsd@gmail.com> PR: 231742 MFC after: 1 week Approved by: re (kib) Sponsored by: Mellanox Technologies Changes: head/lib/libusb/libusb10_io.c
A commit references this bug: Author: hselasky Date: Fri Oct 5 07:49:01 UTC 2018 New revision: 339189 URL: https://svnweb.freebsd.org/changeset/base/339189 Log: MFC r338993: When multiple threads are involved receiving completion events in LibUSB make sure there is always a master polling thread, by setting the "ctx_handler" field in the context. Else the reception of completion events can stop. This happens if event threads are created and destroyed during runtime. Found by: Ludovic Rousseau <ludovic.rousseau+freebsd@gmail.com> PR: 231742 Sponsored by: Mellanox Technologies Changes: _U stable/11/ stable/11/lib/libusb/libusb10_io.c
A commit references this bug: Author: hselasky Date: Fri Oct 5 07:50:45 UTC 2018 New revision: 339190 URL: https://svnweb.freebsd.org/changeset/base/339190 Log: MFC r338993: When multiple threads are involved receiving completion events in LibUSB make sure there is always a master polling thread, by setting the "ctx_handler" field in the context. Else the reception of completion events can stop. This happens if event threads are created and destroyed during runtime. Found by: Ludovic Rousseau <ludovic.rousseau+freebsd@gmail.com> PR: 231742 Sponsored by: Mellanox Technologies Changes: _U stable/10/ stable/10/lib/libusb/libusb10_io.c
A commit references this bug: Author: hselasky Date: Fri Oct 5 07:52:28 UTC 2018 New revision: 339191 URL: https://svnweb.freebsd.org/changeset/base/339191 Log: MFC r338993: When multiple threads are involved receiving completion events in LibUSB make sure there is always a master polling thread, by setting the "ctx_handler" field in the context. Else the reception of completion events can stop. This happens if event threads are created and destroyed during runtime. Found by: Ludovic Rousseau <ludovic.rousseau+freebsd@gmail.com> PR: 231742 Sponsored by: Mellanox Technologies Changes: _U stable/9/lib/ _U stable/9/lib/libusb/ stable/9/lib/libusb/libusb10_io.c