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.

Sign up for GitHub

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

Jump to bottom

ccid_usb.c:888:ReadUSB() read failed (1/6): -7 LIBUSB_ERROR_TIMEOUT #66

Closed
nicolasbadia opened this issue Jul 28, 2019 · 6 comments
Closed

ccid_usb.c:888:ReadUSB() read failed (1/6): -7 LIBUSB_ERROR_TIMEOUT #66

nicolasbadia opened this issue Jul 28, 2019 · 6 comments

Comments

@nicolasbadia
Copy link

nicolasbadia commented Jul 28, 2019 •
edited
Loading

Here is an issue related to #29 which is still causing me some troubles...
I had initially the issue only on Raspberry Pi, but it now also happens on Ubuntu 18 (with multiple NUC).
I can manage to have PCSC working if the reader is connected and if I restart pcscd. But after a reboot or if I unplug and replug it, it does not work anymore. Here are some log.

When I unplug it the first time after a pcscd restart:

10187660 [1974600688] ccid_usb.c:1352:InterruptRead() after (0) (4)
00000052 [1974600688] ccid_usb.c:1367:InterruptRead() InterruptRead (1/6): 4
00148098 [1965028336] hotplug_libudev.c:645:HPEstablishUSBNotifications() USB Device removed
00001045 [1965028336] hotplug_libudev.c:363:HPRemoveDevice() Removing USB device[0]: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) at /dev/bus/usb/001/006
00000047 [1965028336] readerfactory.c:610:RFRemoveReader() UnrefReader() count was: 1
00000022 [1965028336] eventhandler.c:175:EHDestroyEventHandler() Stomping thread.
00000024 [1965028336] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB1, usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000019 [1965028336] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB2, usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000016 [1965028336] eventhandler.c:200:EHDestroyEventHandler() Request stopping of polling thread
00000017 [1965028336] ifdhandler.c:346:IFDHStopPolling() usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00250846 [1974600688] eventhandler.c:504:EHStatusHandlerThread() Die
00001384 [1965028336] eventhandler.c:215:EHDestroyEventHandler() Thread stomped.
00000044 [1965028336] readerfactory.c:1126:RFUnInitializeReader() Attempting shutdown of Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) 00 00.
00000025 [1965028336] ifdhandler.c:284:IFDHCloseChannel() usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000049 [1965028336] -> 000000 63 00 00 00 00 00 06 00 00 00
00000071 [1965028336] ccid_usb.c:859:WriteUSB() write failed (1/6): -4 LIBUSB_ERROR_NO_DEVICE
00000021 [1965028336] ccid_usb.c:941:CloseUSB() Closing USB device: 1/6
00000015 [1965028336] ccid_usb.c:951:CloseUSB() Last slot closed. Release resources
00000104 [1965028336] ccid_usb.c:189:close_libusb_if_needed() libusb_exit
00000592 [1965028336] readerfactory.c:987:RFUnloadReader() Unloading reader driver.
00000280 [1965028336] winscard_svc.c:820:MSGSignalClient() Signal client: 14
00000025 [1965028336] winscard_svc.c:823:MSGSignalClient() SIGNAL rv=0x0 for client 14
00000062 [1965028336] winscard_svc.c:820:MSGSignalClient() Signal client: 15
00000018 [1965028336] winscard_svc.c:823:MSGSignalClient() SIGNAL rv=0x0 for client 15
00000208 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 15
00000065 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14
00000304 [1954542576] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 14
00000302 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 14
00000226 [1944056816] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 15
00000620 [1954542576] winscard_svc.c:440:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 14
00000101 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 15
00000058 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000089 [1944056816] winscard_svc.c:440:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 15
00000138 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14
00000028 [1954542576] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 14
00000074 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 15
00000025 [1944056816] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 15
00000498 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 15
00000327 [1944056816] winscard_svc.c:440:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 15
00006484 [1944056816] winscard_svc.c:362:ContextThread() Received command: RELEASE_CONTEXT from client 15
00000071 [1944056816] winscard.c:229:SCardReleaseContext() Releasing Context: 0x5E3F7849
00000023 [1944056816] winscard_svc.c:474:ContextThread() RELEASE_CONTEXT rv=0x0 for client 15
00000133 [1944056816] winscard_svc.c:354:ContextThread() Client die: 15
00000064 [1944056816] winscard_svc.c:1057:MSGCleanupClient() Thread is stopping: dwClientID=15, threadContext @0x1538268
00000021 [1944056816] winscard_svc.c:1063:MSGCleanupClient() Freeing SCONTEXT @0x1538268

When I plug back:

06377972 [1965028336] hotplug_libudev.c:651:HPEstablishUSBNotifications() USB Device add
00000917 [1965028336] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x04E6, PID: 0x5790, path: /dev/bus/usb/001/007
00000039 [1965028336] hotplug_libudev.c:436:HPAddDevice() Adding USB device: Identiv uTrust 3700 F CL Reader
00000428 [1965028336] readerfactory.c:1075:RFInitializeReader() Attempting startup of Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00001228 [1965028336] readerfactory.c:950:RFBindFunctions() Loading IFD Handler 3.0
00000156 [1965028336] ifdhandler.c:1961:init_driver() Driver version: 1.4.30
00006751 [1965028336] ifdhandler.c:1978:init_driver() LogLevel: 0x0003
00000059 [1965028336] ifdhandler.c:1989:init_driver() DriverOptions: 0x0000
00001544 [1965028336] ifdhandler.c:2002:init_driver() LogLevel from LIBCCID_ifdLogLevel: 0x000F
00000025 [1965028336] ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 0, device: usb:04e6/5790:libudev:0:/dev/bus/usb/001/007
00000023 [1965028336] ccid_usb.c:237:OpenUSBByName() Reader index: 0, Device: usb:04e6/5790:libudev:0:/dev/bus/usb/001/007
00000047 [1965028336] ccid_usb.c:269:OpenUSBByName() interface_number: 0
00000017 [1965028336] ccid_usb.c:270:OpenUSBByName() usb bus/device: 1/7
00000019 [1965028336] ccid_usb.c:302:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00012979 [1965028336] ccid_usb.c:320:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau ([email protected])
00000840 [1965028336] ccid_usb.c:321:OpenUSBByName() ifdProductString: Generic CCID driver
00000487 [1965028336] ccid_usb.c:322:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later version.
00015353 [1965028336] ccid_usb.c:406:OpenUSBByName() Try device: 1/7
00000839 [1965028336] ccid_usb.c:416:OpenUSBByName() vid/pid : 04E6/5790
00000450 [1965028336] ccid_usb.c:483:OpenUSBByName() Checking device: 1/7
00000427 [1965028336] ccid_usb.c:554:OpenUSBByName() Trying to open USB bus/device: 1/7
00000932 [1965028336] ccid_usb.c:660:OpenUSBByName() Found Vendor/Product: 04E6/5790 (Identiv uTrust 3700 F CL Reader)
00000691 [1965028336] ccid_usb.c:662:OpenUSBByName() Using USB bus/device: 1/7
00000445 [1965028336] ccid_usb.c:722:OpenUSBByName() bNumDataRatesSupported is 0
00184263 [1965028336] ccid_usb.c:1306:InterruptRead() before (0)
00001087 [1965028336] ccid_usb.c:1352:InterruptRead() after (0) (0)
00000599 [1965028336] NotifySlotChange: 50 02
00000496 [1965028336] -> 000000 65 00 00 00 00 00 00 00 00 00
00727751 [1965028336] <- 000000 81 00 00 00 00 00 00 42 FE 01
00001267 [1965028336] -> 000000 65 00 00 00 00 00 01 00 00 00
00101211 [1965028336] ccid_usb.c:898:ReadUSB() read failed (1/7): -7 LIBUSB_ERROR_TIMEOUT
00001024 [1965028336] -> 000000 65 00 00 00 00 00 02 00 00 00
00101268 [1965028336] ccid_usb.c:898:ReadUSB() read failed (1/7): -7 LIBUSB_ERROR_TIMEOUT
00001039 [1965028336] ifdhandler.c:194:CreateChannelByNameOrChannel() failed
00000809 [1965028336] ccid_usb.c:941:CloseUSB() Closing USB device: 1/7
00000781 [1965028336] ccid_usb.c:951:CloseUSB() Last slot closed. Release resources
00001023 [1965028336] ccid_usb.c:189:close_libusb_if_needed() libusb_exit
00001549 [1965028336] readerfactory.c:1106:RFInitializeReader() Open Port 0x200000 Failed (usb:04e6/5790:libudev:0:/dev/bus/usb/001/007)
00000036 [1965028336] readerfactory.c:376:RFAddReader() Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) init failed.
00000025 [1965028336] readerfactory.c:610:RFRemoveReader() UnrefReader() count was: 1
00000017 [1965028336] readerfactory.c:1126:RFUnInitializeReader() Attempting shutdown of Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) 00 00.
00000017 [1965028336] readerfactory.c:987:RFUnloadReader() Unloading reader driver.
00000259 [1965028336] winscard_svc.c:820:MSGSignalClient() Signal client: 14
00000023 [1965028336] winscard_svc.c:823:MSGSignalClient() SIGNAL rv=0x0 for client 14
00000064 [1965028336] hotplug_libudev.c:523:HPAddDevice() Failed adding USB device: Identiv uTrust 3700 F CL Reader
00000143 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14
00000033 [1954542576] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 14

When I unplug it again:
04982847 [1965028336] hotplug_libudev.c:645:HPEstablishUSBNotifications() USB Device removed

The reader is a still an "Identiv uTrust 3700 F CL Reader".
Here are the related software versions:

  • pcsc-lite version 1.8.23
  • libusb-1.0-0: 2:1.0.21-2

Any idea of what is going wrong ?
Should I contact Identiv ? I'm asking because we recently had a chance to test a reader from another vendor, and it works perfectly...
@LudovicRousseau
Copy link
Owner

Please generate a new log as documented at https://ccid.apdu.fr/#support

@nicolasbadia
Copy link
Author

I've updated the issue. Here is also the complete log :

00000000 debuglog.c:299:DebugLogSetLevel() debug level=debug
00000066 debuglog.c:320:DebugLogSetCategory() Debug options: APDU
00000011 [1995943984] pcscdaemon.c:352:main() Force colored logs
00000118 [1995943984] utils.c:82:GetDaemonPid() Can't open /var/run/pcscd/pcscd.pid: No such file or directory
00000237 [1995943984] configfile.l:284:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000054 [1995943984] configfile.l:321:DBGetReaderListDir() Skipping non regular file: ..
00000010 [1995943984] configfile.l:321:DBGetReaderListDir() Skipping non regular file: .
00000009 [1995943984] configfile.l:360:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000120 [1995943984] pcscdaemon.c:662:main() pcsc-lite 1.8.24 daemon ready.
00010994 [1995943984] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000579 [1995943984] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000612 [1995943984] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0424, PID: 0x9514, path: /dev/bus/usb/001/002
00000658 [1995943984] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0424, PID: 0xEC00, path: /dev/bus/usb/001/003
00000616 [1995943984] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0424, PID: 0x9514, path: /dev/bus/usb/001/002
00000609 [1995943984] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x04E6, PID: 0x5790, path: /dev/bus/usb/001/006
00000024 [1995943984] hotplug_libudev.c:436:HPAddDevice() Adding USB device: Identiv uTrust 3700 F CL Reader
00000231 [1995943984] readerfactory.c:1075:RFInitializeReader() Attempting startup of Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00000801 [1995943984] readerfactory.c:950:RFBindFunctions() Loading IFD Handler 3.0
00000098 [1995943984] ifdhandler.c:1961:init_driver() Driver version: 1.4.30
00003246 [1995943984] ifdhandler.c:1978:init_driver() LogLevel: 0x0003
00000026 [1995943984] ifdhandler.c:1989:init_driver() DriverOptions: 0x0000
00000762 [1995943984] ifdhandler.c:2002:init_driver() LogLevel from LIBCCID_ifdLogLevel: 0x000F
00000015 [1995943984] ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 0, device: usb:04e6/5790:libudev:0:/dev/bus/usb/001/006
00000013 [1995943984] ccid_usb.c:237:OpenUSBByName() Reader index: 0, Device: usb:04e6/5790:libudev:0:/dev/bus/usb/001/006
00000027 [1995943984] ccid_usb.c:269:OpenUSBByName() interface_number: 0
00000010 [1995943984] ccid_usb.c:270:OpenUSBByName() usb bus/device: 1/6
00000010 [1995943984] ccid_usb.c:302:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00003247 [1995943984] ccid_usb.c:320:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau ([email protected])
00000020 [1995943984] ccid_usb.c:321:OpenUSBByName() ifdProductString: Generic CCID driver
00000012 [1995943984] ccid_usb.c:322:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later version.
00007876 [1995943984] ccid_usb.c:406:OpenUSBByName() Try device: 1/6
00000027 [1995943984] ccid_usb.c:416:OpenUSBByName() vid/pid : 04E6/5790
00000013 [1995943984] ccid_usb.c:483:OpenUSBByName() Checking device: 1/6
00000010 [1995943984] ccid_usb.c:554:OpenUSBByName() Trying to open USB bus/device: 1/6
00089042 [1995943984] ccid_usb.c:660:OpenUSBByName() Found Vendor/Product: 04E6/5790 (Identiv uTrust 3700 F CL Reader)
00000031 [1995943984] ccid_usb.c:662:OpenUSBByName() Using USB bus/device: 1/6
00000013 [1995943984] ccid_usb.c:722:OpenUSBByName() bNumDataRatesSupported is 0
00005212 [1995943984] ccid_usb.c:1306:InterruptRead() before (0)
00100123 [1995943984] ccid_usb.c:1352:InterruptRead() after (0) (2)
00000037 [1995943984] -> 000000 65 00 00 00 00 00 00 00 00 00
00000297 [1995943984] <- 000000 81 00 00 00 00 00 01 42 FE 01
00000022 [1995943984] -> 000000 65 00 00 00 00 00 01 00 00 00
00658019 [1995943984] <- 000000 81 00 00 00 00 00 02 42 FE 01
00000059 [1995943984] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB3, usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000020 [1995943984] readerfactory.c:396:RFAddReader() Using the reader polling thread
00000020 [1995943984] ifdhandler.c:1821:IFDHICCPresence() usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000032 [1995943984] -> 000000 65 00 00 00 00 00 02 00 00 00
00000496 [1995943984] <- 000000 81 00 00 00 00 00 00 42 FE 01
00000025 [1995943984] ccid_usb.c:920:ReadUSB() Duplicate frame detected
00000224 [1995943984] <- 000000 81 00 00 00 00 00 01 42 FE 01
00000022 [1995943984] ccid_usb.c:920:ReadUSB() Duplicate frame detected
00000226 [1995943984] <- 000000 81 00 00 00 00 00 02 42 FE 01
00000024 [1995943984] ifdhandler.c:1942:IFDHICCPresence() Card absent
00000308 [1974600688] ifdhandler.c:1821:IFDHICCPresence() usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000047 [1974600688] -> 000000 65 00 00 00 00 00 03 00 00 00
00730824 [1974600688] <- 000000 81 00 00 00 00 00 03 42 FE 01
00000054 [1974600688] ifdhandler.c:1942:IFDHICCPresence() Card absent
00000047 [1974600688] ifdhandler.c:1821:IFDHICCPresence() usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000038 [1974600688] -> 000000 65 00 00 00 00 00 04 00 00 00
00000529 [1974600688] <- 000000 81 00 00 00 00 00 04 42 FE 01
00000023 [1974600688] ifdhandler.c:1942:IFDHICCPresence() Card absent
00000031 [1974600688] ifdhandler.c:310:IFDHPolling() usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0) 600000 ms
00000018 [1974600688] ccid_usb.c:1306:InterruptRead() before (0)
00000002 [1995943984] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFAE, usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000087 [1995943984] ifdhandler.c:476:IFDHGetCapabilities() Reader supports 1 slot(s)
00000354 [1974600688] ccid_usb.c:1352:InterruptRead() after (0) (0)
00000028 [1974600688] NotifySlotChange: 50 02
00000020 [1974600688] ifdhandler.c:1821:IFDHICCPresence() usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000031 [1974600688] -> 000000 65 00 00 00 00 00 05 00 00 00
00000621 [1974600688] <- 000000 81 00 00 00 00 00 05 42 FE 01
00000115 [1974600688] ifdhandler.c:1942:IFDHICCPresence() Card absent
00000023 [1974600688] ifdhandler.c:310:IFDHPolling() usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0) 600000 ms
00000018 [1974600688] ccid_usb.c:1306:InterruptRead() before (0)
00001827 [1995943984] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0424, PID: 0x9514, path: /dev/bus/usb/001/002
01621335 [1995943984] winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
00000060 [1995943984] winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 14
00000010 [1995943984] pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 14
00000219 [1954542576] winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000013 [1954542576] winscard_svc.c:344:ContextThread() Thread is started: dwClientID=14, threadContext @0x1523e30
00000027 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_VERSION from client 14
00000016 [1954542576] winscard_svc.c:374:ContextThread() Client is protocol version 4:4
00000368 [1954542576] winscard_svc.c:394:ContextThread() CMD_VERSION rv=0x0 for client 14
00000111 [1954542576] winscard_svc.c:362:ContextThread() Received command: ESTABLISH_CONTEXT from client 14
00000022 [1954542576] winscard.c:215:SCardEstablishContext() Establishing Context: 0x50AA0697
00000010 [1954542576] winscard_svc.c:459:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 14
00000249 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14
00000326 [1954542576] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 14
00000095 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 14
00000018 [1954542576] winscard_svc.c:440:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 14
00000055 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14
00000015 [1954542576] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 14
00000337 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 14
00000018 [1954542576] winscard_svc.c:440:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 14
00751520 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000123 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14
00000020 [1954542576] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 14
00009386 [1995943984] winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
00000064 [1995943984] winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 15
00000010 [1995943984] pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 15
00000255 [1944056816] winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000019 [1944056816] winscard_svc.c:344:ContextThread() Thread is started: dwClientID=15, threadContext @0x1538268
00000030 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_VERSION from client 15
00000016 [1944056816] winscard_svc.c:374:ContextThread() Client is protocol version 4:4
00000010 [1944056816] winscard_svc.c:394:ContextThread() CMD_VERSION rv=0x0 for client 15
00000498 [1944056816] winscard_svc.c:362:ContextThread() Received command: ESTABLISH_CONTEXT from client 15
00000037 [1944056816] winscard.c:215:SCardEstablishContext() Establishing Context: 0x5E3F7849
00000011 [1944056816] winscard_svc.c:459:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 15
00000095 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 15
00000112 [1944056816] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 15
00000404 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 15
00000032 [1944056816] winscard_svc.c:440:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 15
00000110 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 15
00000021 [1944056816] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 15
10187660 [1974600688] ccid_usb.c:1352:InterruptRead() after (0) (4)
00000052 [1974600688] ccid_usb.c:1367:InterruptRead() InterruptRead (1/6): 4
00148098 [1965028336] hotplug_libudev.c:645:HPEstablishUSBNotifications() USB Device removed
00001045 [1965028336] hotplug_libudev.c:363:HPRemoveDevice() Removing USB device[0]: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) at /dev/bus/usb/001/006
00000047 [1965028336] readerfactory.c:610:RFRemoveReader() UnrefReader() count was: 1
00000022 [1965028336] eventhandler.c:175:EHDestroyEventHandler() Stomping thread.
00000024 [1965028336] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB1, usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000019 [1965028336] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB2, usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000016 [1965028336] eventhandler.c:200:EHDestroyEventHandler() Request stopping of polling thread
00000017 [1965028336] ifdhandler.c:346:IFDHStopPolling() usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00250846 [1974600688] eventhandler.c:504:EHStatusHandlerThread() Die
00001384 [1965028336] eventhandler.c:215:EHDestroyEventHandler() Thread stomped.
00000044 [1965028336] readerfactory.c:1126:RFUnInitializeReader() Attempting shutdown of Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) 00 00.
00000025 [1965028336] ifdhandler.c:284:IFDHCloseChannel() usb:04e6/5790:libudev:0:/dev/bus/usb/001/006 (lun: 0)
00000049 [1965028336] -> 000000 63 00 00 00 00 00 06 00 00 00
00000071 [1965028336] ccid_usb.c:859:WriteUSB() write failed (1/6): -4 LIBUSB_ERROR_NO_DEVICE
00000021 [1965028336] ccid_usb.c:941:CloseUSB() Closing USB device: 1/6
00000015 [1965028336] ccid_usb.c:951:CloseUSB() Last slot closed. Release resources
00000104 [1965028336] ccid_usb.c:189:close_libusb_if_needed() libusb_exit
00000592 [1965028336] readerfactory.c:987:RFUnloadReader() Unloading reader driver.
00000280 [1965028336] winscard_svc.c:820:MSGSignalClient() Signal client: 14
00000025 [1965028336] winscard_svc.c:823:MSGSignalClient() SIGNAL rv=0x0 for client 14
00000062 [1965028336] winscard_svc.c:820:MSGSignalClient() Signal client: 15
00000018 [1965028336] winscard_svc.c:823:MSGSignalClient() SIGNAL rv=0x0 for client 15
00000208 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 15
00000065 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14
00000304 [1954542576] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 14
00000302 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 14
00000226 [1944056816] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 15
00000620 [1954542576] winscard_svc.c:440:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 14
00000101 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 15
00000058 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000089 [1944056816] winscard_svc.c:440:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 15
00000138 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14
00000028 [1954542576] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 14
00000074 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 15
00000025 [1944056816] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 15
00000498 [1944056816] winscard_svc.c:362:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 15
00000327 [1944056816] winscard_svc.c:440:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 15
00006484 [1944056816] winscard_svc.c:362:ContextThread() Received command: RELEASE_CONTEXT from client 15
00000071 [1944056816] winscard.c:229:SCardReleaseContext() Releasing Context: 0x5E3F7849
00000023 [1944056816] winscard_svc.c:474:ContextThread() RELEASE_CONTEXT rv=0x0 for client 15
00000133 [1944056816] winscard_svc.c:354:ContextThread() Client die: 15
00000064 [1944056816] winscard_svc.c:1057:MSGCleanupClient() Thread is stopping: dwClientID=15, threadContext @0x1538268
00000021 [1944056816] winscard_svc.c:1063:MSGCleanupClient() Freeing SCONTEXT @0x1538268
06377972 [1965028336] hotplug_libudev.c:651:HPEstablishUSBNotifications() USB Device add
00000917 [1965028336] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x04E6, PID: 0x5790, path: /dev/bus/usb/001/007
00000039 [1965028336] hotplug_libudev.c:436:HPAddDevice() Adding USB device: Identiv uTrust 3700 F CL Reader
00000428 [1965028336] readerfactory.c:1075:RFInitializeReader() Attempting startup of Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00001228 [1965028336] readerfactory.c:950:RFBindFunctions() Loading IFD Handler 3.0
00000156 [1965028336] ifdhandler.c:1961:init_driver() Driver version: 1.4.30
00006751 [1965028336] ifdhandler.c:1978:init_driver() LogLevel: 0x0003
00000059 [1965028336] ifdhandler.c:1989:init_driver() DriverOptions: 0x0000
00001544 [1965028336] ifdhandler.c:2002:init_driver() LogLevel from LIBCCID_ifdLogLevel: 0x000F
00000025 [1965028336] ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 0, device: usb:04e6/5790:libudev:0:/dev/bus/usb/001/007
00000023 [1965028336] ccid_usb.c:237:OpenUSBByName() Reader index: 0, Device: usb:04e6/5790:libudev:0:/dev/bus/usb/001/007
00000047 [1965028336] ccid_usb.c:269:OpenUSBByName() interface_number: 0
00000017 [1965028336] ccid_usb.c:270:OpenUSBByName() usb bus/device: 1/7
00000019 [1965028336] ccid_usb.c:302:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00012979 [1965028336] ccid_usb.c:320:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau ([email protected])
00000840 [1965028336] ccid_usb.c:321:OpenUSBByName() ifdProductString: Generic CCID driver
00000487 [1965028336] ccid_usb.c:322:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later version.
00015353 [1965028336] ccid_usb.c:406:OpenUSBByName() Try device: 1/7
00000839 [1965028336] ccid_usb.c:416:OpenUSBByName() vid/pid : 04E6/5790
00000450 [1965028336] ccid_usb.c:483:OpenUSBByName() Checking device: 1/7
00000427 [1965028336] ccid_usb.c:554:OpenUSBByName() Trying to open USB bus/device: 1/7
00000932 [1965028336] ccid_usb.c:660:OpenUSBByName() Found Vendor/Product: 04E6/5790 (Identiv uTrust 3700 F CL Reader)
00000691 [1965028336] ccid_usb.c:662:OpenUSBByName() Using USB bus/device: 1/7
00000445 [1965028336] ccid_usb.c:722:OpenUSBByName() bNumDataRatesSupported is 0
00184263 [1965028336] ccid_usb.c:1306:InterruptRead() before (0)
00001087 [1965028336] ccid_usb.c:1352:InterruptRead() after (0) (0)
00000599 [1965028336] NotifySlotChange: 50 02
00000496 [1965028336] -> 000000 65 00 00 00 00 00 00 00 00 00
00727751 [1965028336] <- 000000 81 00 00 00 00 00 00 42 FE 01
00001267 [1965028336] -> 000000 65 00 00 00 00 00 01 00 00 00
00101211 [1965028336] ccid_usb.c:898:ReadUSB() read failed (1/7): -7 LIBUSB_ERROR_TIMEOUT
00001024 [1965028336] -> 000000 65 00 00 00 00 00 02 00 00 00
00101268 [1965028336] ccid_usb.c:898:ReadUSB() read failed (1/7): -7 LIBUSB_ERROR_TIMEOUT
00001039 [1965028336] ifdhandler.c:194:CreateChannelByNameOrChannel() failed
00000809 [1965028336] ccid_usb.c:941:CloseUSB() Closing USB device: 1/7
00000781 [1965028336] ccid_usb.c:951:CloseUSB() Last slot closed. Release resources
00001023 [1965028336] ccid_usb.c:189:close_libusb_if_needed() libusb_exit
00001549 [1965028336] readerfactory.c:1106:RFInitializeReader() Open Port 0x200000 Failed (usb:04e6/5790:libudev:0:/dev/bus/usb/001/007)
00000036 [1965028336] readerfactory.c:376:RFAddReader() Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) init failed.
00000025 [1965028336] readerfactory.c:610:RFRemoveReader() UnrefReader() count was: 1
00000017 [1965028336] readerfactory.c:1126:RFUnInitializeReader() Attempting shutdown of Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722297869) 00 00.
00000017 [1965028336] readerfactory.c:987:RFUnloadReader() Unloading reader driver.
00000259 [1965028336] winscard_svc.c:820:MSGSignalClient() Signal client: 14
00000023 [1965028336] winscard_svc.c:823:MSGSignalClient() SIGNAL rv=0x0 for client 14
00000064 [1965028336] hotplug_libudev.c:523:HPAddDevice() Failed adding USB device: Identiv uTrust 3700 F CL Reader
00000143 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14
00000033 [1954542576] winscard_svc.c:832:MSGSendReaderStates() Send reader states: 14
04982847 [1965028336] hotplug_libudev.c:645:HPEstablishUSBNotifications() USB Device removed

@LudovicRousseau
Copy link
Owner

It looks like your reader firmware is bogus.
You have:

00000037 [1995943984] -> 000000 65 00 00 00 00 00 00 00 00 00
00000297 [1995943984] <- 000000 81 00 00 00 00 00 01 42 FE 01
00000022 [1995943984] -> 000000 65 00 00 00 00 00 01 00 00 00
00658019 [1995943984] <- 000000 81 00 00 00 00 00 02 42 FE 01

The 7th byte is bSeq "Sequence number for command.". The number in the response should be the same as in the command.

So the sequence should be:

00000037 [1995943984] -> 000000 65 00 00 00 00 00 00 00 00 00
00000297 [1995943984] <- 000000 81 00 00 00 00 00 *00* 42 FE 01
00000022 [1995943984] -> 000000 65 00 00 00 00 00 01 00 00 00
00658019 [1995943984] <- 000000 81 00 00 00 00 00 *01* 42 FE 01

After that you have:

00000032 [1995943984] -> 000000 65 00 00 00 00 00 02 00 00 00
00000496 [1995943984] <- 000000 81 00 00 00 00 00 00 42 FE 01
00000025 [1995943984] ccid_usb.c:920:ReadUSB() Duplicate frame detected
00000224 [1995943984] <- 000000 81 00 00 00 00 00 01 42 FE 01
00000022 [1995943984] ccid_usb.c:920:ReadUSB() Duplicate frame detected
00000226 [1995943984] <- 000000 81 00 00 00 00 00 02 42 FE 01
00000024 [1995943984] ifdhandler.c:1942:IFDHICCPresence() Card absent

Which indicates the same problem.

Report the problem to Identiv support.
It is not a problem in pcsc-lite or the CCID driver.

@nicolasbadia
Copy link
Author

Thanks a lot for the quick answer, I will report that to Identiv...

@jaredvacanti
Copy link

@nicolasbadia can you share where you purchased your reader? Was it purchased directly? I am aware of counterfeit issues with other readers. Do you suspect this is the case, or is it genuine bug?

@nicolasbadia
Copy link
Author

@jaredvacanti yes it was a real reader. I believe Identiv submitted a patch for this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@LudovicRousseau @nicolasbadia @jaredvacanti