search

LudovicRousseau / CCID

CCID driver
https://ccid.apdu.fr/
GNU Lesser General Public License v2.1
229 stars 79 forks source link

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

Open rubygoldbergmachineinc opened 10 months ago

rubygoldbergmachineinc commented 10 months ago

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 commented 10 months ago

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?

rubygoldbergmachineinc commented 10 months ago

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

LudovicRousseau commented 10 months ago

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

rubygoldbergmachineinc commented 10 months ago

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 commented 10 months ago

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 commented 10 months ago

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