From owner-freebsd-usb@freebsd.org Wed Sep 26 15:44:29 2018 Return-Path: Delivered-To: freebsd-usb@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id CC1BA10B0298 for ; Wed, 26 Sep 2018 15:44:28 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from mailman.ysv.freebsd.org (mailman.ysv.freebsd.org [IPv6:2001:1900:2254:206a::50:5]) by mx1.freebsd.org (Postfix) with ESMTP id 6A1B382E5F for ; Wed, 26 Sep 2018 15:44:28 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: by mailman.ysv.freebsd.org (Postfix) id 2EBB210B0295; Wed, 26 Sep 2018 15:44:28 +0000 (UTC) Delivered-To: usb@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 0CC4C10B0294 for ; Wed, 26 Sep 2018 15:44:28 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from mxrelay.ysv.freebsd.org (mxrelay.ysv.freebsd.org [IPv6:2001:1900:2254:206a::19:3]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "mxrelay.ysv.freebsd.org", Issuer "Let's Encrypt Authority X3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id A280082E5C for ; Wed, 26 Sep 2018 15:44:27 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from kenobi.freebsd.org (kenobi.freebsd.org [IPv6:2001:1900:2254:206a::16:76]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mxrelay.ysv.freebsd.org (Postfix) with ESMTPS id EF9601CB7E for ; Wed, 26 Sep 2018 15:44:26 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from kenobi.freebsd.org ([127.0.1.118]) by kenobi.freebsd.org (8.15.2/8.15.2) with ESMTP id w8QFiQY6064710 for ; Wed, 26 Sep 2018 15:44:26 GMT (envelope-from bugzilla-noreply@freebsd.org) Received: (from www@localhost) by kenobi.freebsd.org (8.15.2/8.15.2/Submit) id w8QFiQU1064709 for usb@FreeBSD.org; Wed, 26 Sep 2018 15:44:26 GMT (envelope-from bugzilla-noreply@freebsd.org) X-Authentication-Warning: kenobi.freebsd.org: www set sender to bugzilla-noreply@freebsd.org using -f From: bugzilla-noreply@freebsd.org To: usb@FreeBSD.org Subject: [Bug 231742] libusb_handle_events_completed() does not return after a transfer is cancelled Date: Wed, 26 Sep 2018 15:44:26 +0000 X-Bugzilla-Reason: AssignedTo X-Bugzilla-Type: new X-Bugzilla-Watch-Reason: None X-Bugzilla-Product: Base System X-Bugzilla-Component: usb X-Bugzilla-Version: 10.4-STABLE X-Bugzilla-Keywords: X-Bugzilla-Severity: Affects Some People X-Bugzilla-Who: ludovic.rousseau+freebsd@gmail.com X-Bugzilla-Status: New X-Bugzilla-Resolution: X-Bugzilla-Priority: --- X-Bugzilla-Assigned-To: usb@FreeBSD.org X-Bugzilla-Flags: X-Bugzilla-Changed-Fields: bug_id short_desc product version rep_platform op_sys bug_status bug_severity priority component assigned_to reporter Message-ID: Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-Bugzilla-URL: https://bugs.freebsd.org/bugzilla/ Auto-Submitted: auto-generated MIME-Version: 1.0 X-BeenThere: freebsd-usb@freebsd.org X-Mailman-Version: 2.1.27 Precedence: list List-Id: FreeBSD support for USB List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 26 Sep 2018 15:44:29 -0000 https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=3D231742 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@FreeBSD.org Reporter: ludovic.rousseau+freebsd@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 transf= ers 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()=20 00000005 [683937920] ccid_usb.c:1331:InterruptRead()=20 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 clean= ing function 00000008 [679489664] readerfactory.c:1362:RFCleanupReaders() Stopping reade= r: Inside Secure AT90SCR200 00 00 00000005 [679489664] readerfactory.c:610:RFRemoveReader() UnrefReader() cou= nt 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()=20 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 stom= ped. 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=20 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=20 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 clean= ing function 00000008 [679489664] readerfactory.c:1362:RFCleanupReaders() Stopping reade= r: Inside Secure AT90SCR200 00 00 00000005 [679489664] readerfactory.c:610:RFRemoveReader() UnrefReader() cou= nt 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()=20 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 stom= ped. 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=20 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=20 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 reade= r: SMSC USX101x Reader (EF149371) 01 00 00000006 [679489664] readerfactory.c:610:RFRemoveReader() UnrefReader() cou= nt 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 =3D=3D 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 --=20 You are receiving this mail because: You are the assignee for the bug.=