[Bug 231742] libusb_handle_events_completed() does not return after a transfer is cancelled

bugzilla-noreply at freebsd.org bugzilla-noreply at freebsd.org
Wed Sep 26 15:44:29 UTC 2018 

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=231742

            Bug ID: 231742
           Summary: libusb_handle_events_completed() does not return after
                    a transfer is cancelled
           Product: Base System
           Version: 10.4-STABLE
          Hardware: Any
                OS: Any
            Status: New
          Severity: Affects Some People
          Priority: ---
         Component: usb
          Assignee: usb at FreeBSD.org
          Reporter: ludovic.rousseau+freebsd at gmail.com

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

-- 
You are receiving this mail because:
You are the assignee for the bug.

More information about the freebsd-usb mailing list