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

LIBUSB_ERROR_IO in ccid | identiv uTrust 3700 reader becomes unresponsive (off/no light) #120

Open
rubygoldbergmachineinc opened this issue Nov 3, 2023 · 6 comments
Open

LIBUSB_ERROR_IO in ccid | identiv uTrust 3700 reader becomes unresponsive (off/no light) #120

rubygoldbergmachineinc opened this issue Nov 3, 2023 · 6 comments
Assignees
@LudovicRousseau
Labels
invalid

Comments

@rubygoldbergmachineinc
Copy link

rubygoldbergmachineinc commented Nov 3, 2023 •
edited

Os: "Ubuntu 20.04.4 LTS"

libusb-1.0-0/focal,now 2:1.0.23-2build1 amd64 [installed,automatic]
libccid/focal,now 1.4.31-1 amd64 [installed,automatic]
libpcsclite1/focal,now 1.8.26-3 amd64 [installed,automatic]

Error logs:

Nov 2 17:21:26 device11 systemd[1]: isc-dhcp-server.service: Scheduled restart job, restart counter is at 75265.
Nov 2 17:21:26 device11 systemd[1]: Stopped ISC DHCP IPv4 server.
Nov 2 17:21:26 device11 systemd[1]: Starting ISC DHCP IPv4 server...
Nov 2 17:21:26 device11 verify_dhcpd_interface.py[341441]: Subnet for interface is: None
Nov 2 17:21:26 device11 verify_dhcpd_interface.py[341441]: Subnet is None, did not match: 192.168.0.0
Nov 2 17:21:26 device11 systemd[1]: isc-dhcp-server.service: Control process exited, code=exited, status=253/n/a
Nov 2 17:21:26 device11 systemd[1]: isc-dhcp-server.service: Failed with result 'exit-code'.
Nov 2 17:21:26 device11 systemd[1]: Failed to start ISC DHCP IPv4 server.
Nov 2 17:21:31 device11 systemd[1]: isc-dhcp-server.service: Scheduled restart job, restart counter is at 75266.
Nov 2 17:21:31 device11 systemd[1]: Stopped ISC DHCP IPv4 server.
Nov 2 17:21:31 device11 systemd[1]: Starting ISC DHCP IPv4 server...
Nov 2 17:21:32 device11 verify_dhcpd_interface.py[341475]: Subnet for interface is: None
Nov 2 17:21:32 device11 verify_dhcpd_interface.py[341475]: Subnet is None, did not match: 192.168.0.0
Nov 2 17:21:32 device11 systemd[1]: isc-dhcp-server.service: Control process exited, code=exited, status=253/n/a
Nov 2 17:21:32 device11 systemd[1]: isc-dhcp-server.service: Failed with result 'exit-code'.
Nov 2 17:21:32 device11 systemd[1]: Failed to start ISC DHCP IPv4 server.
Nov 2 17:21:34 device11 pcscd[9395]: 24515664 commands.c:1523:CCID_Receive Activity aborted by Host
Nov 2 17:21:34 device11 pcscd[9395]: 00000043 ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
Nov 2 17:21:34 device11 pcscd[9395]: 00000012 winscard.c:1620:SCardTransmit() Card not transacted: 0x80100016
Nov 2 17:21:36 device11 pcscd[9395]: 01642974 commands.c:1523:CCID_Receive Activity aborted by Host
Nov 2 17:21:36 device11 pcscd[9395]: 00000038 ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
Nov 2 17:21:36 device11 pcscd[9395]: 00000009 winscard.c:1620:SCardTransmit() Card not transacted: 0x80100016
Nov 2 17:21:37 device11 pcscd[9395]: 01228676 winscard.c:338:SCardConnect() Error powering up card: 2148532329 0x80100069
Nov 2 17:21:37 device11 pcscd[9395]: 00000025 winscard.c:344:SCardConnect() Card Not Powered
Nov 2 17:21:37 device11 systemd[1]: isc-dhcp-server.service: Scheduled restart job, restart counter is at 75267.
Nov 2 17:21:37 device11 systemd[1]: Stopped ISC DHCP IPv4 server.
Nov 2 17:21:37 device11 systemd[1]: Starting ISC DHCP IPv4 server...
Nov 2 17:21:38 device11 verify_dhcpd_interface.py[341508]: Subnet for interface is: None
Nov 2 17:21:38 device11 verify_dhcpd_interface.py[341508]: Subnet is None, did not match: 192.168.0.0
Nov 2 17:21:38 device11 systemd[1]: isc-dhcp-server.service: Control process exited, code=exited, status=253/n/a
Nov 2 17:21:38 device11 systemd[1]: isc-dhcp-server.service: Failed with result 'exit-code'.
Nov 2 17:21:38 device11 systemd[1]: Failed to start ISC DHCP IPv4 server.
Nov 2 17:21:38 device11 pcscd[9395]: 01209472 commands.c:249:CmdPowerOn Card absent or mute
Nov 2 17:21:38 device11 pcscd[9395]: 00000043 ifdhandler.c:1221:IFDHPowerICC() PowerUp failed
Nov 2 17:21:38 device11 pcscd[9395]: 00000016 eventhandler.c:439:EHStatusHandlerThread() Error powering up card.
Nov 2 17:21:41 device11 bash[4291]: 240.10.1.3 - - [02/Nov/2023:17:21:41 -0400] "POST /gantry/writeToKeyboard HTTP/1.1" 200 2 "-" "okhttp/3.14.1"
Nov 2 17:21:42 device11 pcscd[9395]: 03536068 winscard.c:929:SCardDisconnect() Error powering down card: 2148532329 0x80100069
Nov 2 17:21:42 device11 pcscd[9395]: 03536068 winscard.c:929:SCardDisconnect() Error powering down card: 2148532329 0x80100069
Nov 2 17:21:43 device11 systemd[1]: isc-dhcp-server.service: Scheduled restart job, restart counter is at 75268.
Nov 2 17:21:43 device11 systemd[1]: Stopped ISC DHCP IPv4 server.
Nov 2 17:21:43 device11 systemd[1]: Starting ISC DHCP IPv4 server...
Nov 2 17:21:43 device11 bash[4291]: 127.0.0.1 - - [02/Nov/2023:17:21:43 -0400] "GET /peripherals HTTP/1.1" 200 19 "-" "python-requests/2.22.0"
Nov 2 17:21:43 device11 verify_dhcpd_interface.py[341567]: Subnet for interface is: None
Nov 2 17:21:43 device11 verify_dhcpd_interface.py[341567]: Subnet is None, did not match: 192.168.0.0
Nov 2 17:21:43 device11 systemd[1]: isc-dhcp-server.service: Control process exited, code=exited, status=253/n/a
Nov 2 17:21:43 device11 systemd[1]: isc-dhcp-server.service: Failed with result 'exit-code'.
Nov 2 17:21:43 device11 systemd[1]: Failed to start ISC DHCP IPv4 server.
Nov 2 17:21:49 device11 systemd[1]: isc-dhcp-server.service: Scheduled restart job, restart counter is at 75269.
Nov 2 17:21:49 device11 systemd[1]: Stopped ISC DHCP IPv4 server.
Nov 2 17:21:49 device11 systemd[1]: Starting ISC DHCP IPv4 server...
Nov 2 17:21:49 device11 verify_dhcpd_interface.py[341612]: Subnet for interface is: None
Nov 2 17:21:49 device11 verify_dhcpd_interface.py[341612]: Subnet is None, did not match: 192.168.0.0
Nov 2 17:21:49 device11 systemd[1]: isc-dhcp-server.service: Control process exited, code=exited, status=253/n/a
Nov 2 17:21:49 device11 systemd[1]: isc-dhcp-server.service: Failed with result 'exit-code'.
Nov 2 17:21:49 device11 systemd[1]: Failed to start ISC DHCP IPv4 server.
Nov 2 17:21:50 device11 pcscd[9395]: 08331752 ccid_usb.c:896:ReadUSB() read failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:50 device11 pcscd[9395]: 00000029 ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
Nov 2 17:21:50 device11 pcscd[9395]: 00000008 winscard.c:1620:SCardTransmit() Card not transacted: 0x80100016
Nov 2 17:21:50 device11 pcscd[9395]: 00316652 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:50 device11 pcscd[9395]: 00000028 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:50 device11 pcscd[9395]: 00000009 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:51 device11 pcscd[9395]: 00634173 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:51 device11 pcscd[9395]: 00000025 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:51 device11 pcscd[9395]: 00000008 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:51 device11 pcscd[9395]: 00051359 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:51 device11 pcscd[9395]: 00000024 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:51 device11 pcscd[9395]: 00000009 winscard.c:929:SCardDisconnect() Error powering down card: 2148532246 0x80100016
Nov 2 17:21:51 device11 pcscd[9395]: 00000383 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:51 device11 pcscd[9395]: 00000021 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:51 device11 pcscd[9395]: 00000012 winscard.c:338:SCardConnect() Error powering up card: 2148532246 0x80100016
Nov 2 17:21:51 device11 pcscd[9395]: 00000010 winscard.c:344:SCardConnect() Card Not Powered
Nov 2 17:21:52 device11 pcscd[9395]: 00396177 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:52 device11 pcscd[9395]: 00000045 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:52 device11 pcscd[9395]: 00000008 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:52 device11 pcscd[9395]: 00000008 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:52 device11 pcscd[9395]: 00447913 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:52 device11 pcscd[9395]: 00000027 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:52 device11 pcscd[9395]: 00000007 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:52 device11 pcscd[9395]: 00448009 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:52 device11 pcscd[9395]: 00000052 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:52 device11 pcscd[9395]: 00000010 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:53 device11 pcscd[9395]: 00447936 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:53 device11 pcscd[9395]: 00000045 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:53 device11 pcscd[9395]: 00000009 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:53 device11 pcscd[9395]: 00447955 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:53 device11 pcscd[9395]: 00000049 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:53 device11 pcscd[9395]: 00000009 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:54 device11 pcscd[9395]: 00447894 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:54 device11 pcscd[9395]: 00000028 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:54 device11 pcscd[9395]: 00000008 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:54 device11 pcscd[9395]: 00448006 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:54 device11 pcscd[9395]: 00000044 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:54 device11 pcscd[9395]: 00000009 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:54 device11 systemd[1]: isc-dhcp-server.service: Scheduled restart job, restart counter is at 75270.
Nov 2 17:21:54 device11 systemd[1]: Stopped ISC DHCP IPv4 server.
Nov 2 17:21:54 device11 systemd[1]: Starting ISC DHCP IPv4 server...
Nov 2 17:21:55 device11 pcscd[9395]: 00447936 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:55 device11 pcscd[9395]: 00000063 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 2 17:21:55 device11 pcscd[9395]: 00000018 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022237223359) 00 00
Nov 2 17:21:55 device11 verify_dhcpd_interface.py[341651]: Subnet for interface is: None
Nov 2 17:21:55 device11 verify_dhcpd_interface.py[341651]: Subnet is None, did not match: 192.168.0.0
Nov 2 17:21:55 device11 systemd[1]: isc-dhcp-server.service: Control process exited, code=exited, status=253/n/a
Nov 2 17:21:55 device11 systemd[1]: isc-dhcp-server.service: Failed with result 'exit-code'.
Nov 2 17:21:55 device11 systemd[1]: Failed to start ISC DHCP IPv4 server.
Nov 2 17:21:55 device11 pcscd[9395]: 00447936 ccid_usb.c:857:WriteUSB() write failed (1/11): -1 LIBUSB_ERROR_IO
Nov 2 17:21:55 device11 pcscd[9395]: 00000054 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
@LudovicRousseau
Copy link
Owner

From your logs:

 Nov 2 17:21:34 device11 pcscd[9395]: 24515664 commands.c:1523:CCID_Receive Activity aborted by Host

The reader responded with an error code: Activity aborted by Host
I never saw this error before.

After that you have USB errors:

 Nov 2 17:21:50 device11 pcscd[9395]: 08331752 ccid_usb.c:896:ReadUSB() read failed (1/11): -1 LIBUSB_ERROR_IO

Are you able to reproduce the problem?

@LudovicRousseau LudovicRousseau self-assigned this Nov 3, 2023
@rubygoldbergmachineinc
Copy link
Author

We have occurrence of the problem on our devices, however, not able to reproduce it for lack of a pattern.

@LudovicRousseau
Copy link
Owner

It looks like a reader firmware issue for me.
I can't do much in the CCID driver.

@rubygoldbergmachineinc
Copy link
Author

Additional logs for reference

Nov 4 11:08:52 device11dhcpd[6151]: DHCPACK on 192.168.1.4 to 98:f0:7b:be:91:90 (levon) via enp0s31f6
Nov 4 11:08:53 device11bash[4150]: 127.0.0.1 - - [04/Nov/2023:11:08:53 -0400] "POST /peripherals/98:f0:7b:be:91:90 HTTP/1.1" 200 7 "-" "python-requests/2.22.0"
Nov 4 11:08:53 device11pcscd[10151]: 09562901 commands.c:1523:CCID_Receive Activity aborted by Host
Nov 4 11:08:53 device11pcscd[10151]: 00000021 ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
Nov 4 11:08:53 device11pcscd[10151]: 00000005 winscard.c:1620:SCardTransmit() Card not transacted: 0x80100016
Nov 4 11:08:54 device11pcscd[10151]: 01283203 ccid_usb.c:896:ReadUSB() read failed (1/2): -1 LIBUSB_ERROR_IO
Nov 4 11:08:54 device11pcscd[10151]: 00000020 ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
Nov 4 11:08:54 device11pcscd[10151]: 00000006 winscard.c:1620:SCardTransmit() Card not transacted: 0x80100016
Nov 4 11:08:54 device11pcscd[10151]: 00295911 ccid_usb.c:857:WriteUSB() write failed (1/2): -1 LIBUSB_ERROR_IO
Nov 4 11:08:54 device11pcscd[10151]: 00000026 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 4 11:08:54 device11pcscd[10151]: 00000005 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022243214673) 00 00
Nov 4 11:08:55 device11pcscd[10151]: 00631984 ccid_usb.c:857:WriteUSB() write failed (1/2): -1 LIBUSB_ERROR_IO
Nov 4 11:08:55 device11pcscd[10151]: 00000020 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 4 11:08:55 device11pcscd[10151]: 00000005 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022243214673) 00 00
Nov 4 11:08:55 device11pcscd[10151]: 00073007 ccid_usb.c:857:WriteUSB() write failed (1/2): -1 LIBUSB_ERROR_IO
Nov 4 11:08:55 device11pcscd[10151]: 00000016 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 4 11:08:55 device11pcscd[10151]: 00000005 winscard.c:929:SCardDisconnect() Error powering down card: 2148532246 0x80100016
Nov 4 11:08:55 device11pcscd[10151]: 00000230 ccid_usb.c:857:WriteUSB() write failed (1/2): -1 LIBUSB_ERROR_IO
Nov 4 11:08:55 device11pcscd[10151]: 00000009 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 4 11:08:55 device11pcscd[10151]: 00000005 winscard.c:338:SCardConnect() Error powering up card: 2148532246 0x80100016
Nov 4 11:08:55 device11pcscd[10151]: 00000003 winscard.c:344:SCardConnect() Card Not Powered
Nov 4 11:08:55 device11pcscd[10151]: 00374669 ccid_usb.c:857:WriteUSB() write failed (1/2): -1 LIBUSB_ERROR_IO
Nov 4 11:08:55 device11pcscd[10151]: 00000018 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 4 11:08:55 device11pcscd[10151]: 00000005 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55022243214673) 00 00
Nov 4 11:08:56 device11pcscd[10151]: 00447968 ccid_usb.c:857:WriteUSB() write failed (1/2): -1 LIBUSB_ERROR_IO
Nov 4 11:08:56 device11pcscd[10151]: 00000017 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
Nov 4 11:08:56 device11pcscd[10151]: 00000005 eventhandler.c:336:EHStatusHandlerThread() Error communicating to

@LudovicRousseau
Copy link
Owner

It is as if the reader received an ABORT command. But the driver does not send such command.

You can try to generate logs as documented in https://ccid.apdu.fr/#support
This may generate a lot of logs before the problem occurs.

@LudovicRousseau
Copy link
Owner

Your problem will be difficult to analyse and fix.
I propose you contact me by email. See https://blog.apdu.fr/articles/about_me/

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@LudovicRousseau LudovicRousseau

Labels
invalid
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@LudovicRousseau @rubygoldbergmachineinc