Can the USB receiving timeout cause ifdwrapper.c:374:IFDStatusICC() Card not transacted: 612?

[asbai]

We are developing an application using a CCID compatible USB smart card chip. The host environment where our application runs uses libpcsclite to provide a smart card interface, and its configuration is:

• ARMv7a processor
• OpenWRT 14.07 (linux 3.14) with following packages:
  • libusb-1.0_1.0.9-1_imx6ul.ipk
  • libpcsclite_1.8.11-1_imx6ul.ipk
  • pcscd_1.8.11-1_imx6ul.ipk
  • ccid_1.4.17-1_imx6ul.ipk

Our application uses the SCardTransmit API to communicate with the smart card. It works very well in the Windows environment (using Microsoft's official winscard.dll, our app also supports Windows).

On the above-mentioned OpenWRT host computer based on pcsclite, most of the commands can also work normally. Only one command will fail every time it is executed:

00000000 pcscdaemon.c:266:main() pcscd set to foreground with debug send to stdout
00003086 configfile.l:286:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00001877 configfile.l:298:DBGetReaderListDir() Skipping non regular file: .
00001824 configfile.l:298:DBGetReaderListDir() Skipping non regular file: ..
00001667 pcscdaemon.c:571:main() pcsc-lite 1.8.11 daemon ready.
00011572 hotplug_libusb.c:541:HPAddHotPluggable() Adding USB device: 1:17:0
00005242 readerfactory.c:1015:RFInitializeReader() Attempting startup of PANJIA TECH RACK NODE (V1) 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00002541 readerfactory.c:900:RFBindFunctions() Loading IFD Handler 3.0
00019283 readerfactory.c:353:RFAddReader() Using the pcscd polling thread
00005158 readerfactory.c:1356:RFWaitForReaderInit() Waiting init for reader: PANJIA TECH RACK NODE (V1) 00 00
00001071 hotplug_libusb.c:448:HPEstablishUSBNotifications() Driver ifd-ccid.bundle does not support IFD_GENERATE_HOTPLUG. Using active polling instead.
00001545 hotplug_libusb.c:457:HPEstablishUSBNotifications() Polling forced every 1 second(s)
00007330 eventhandler.c:292:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
00001580 Card ATR: 3B 64 00 00 48 53 31 34
00408483 eventhandler.c:481:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
05134449 winscard_msg_srv.c:256:ProcessEventsServer() Common channel packet arrival
00000213 winscard_msg_srv.c:268:ProcessEventsServer() ProcessCommonChannelRequest detects: 0
00000059 pcscdaemon.c:137:SVCServiceRunLoop() A new context thread creation is requested: 0
00001350 winscard_svc.c:334:ContextThread() Authorized PC/SC client
00001410 winscard_svc.c:338:ContextThread() Thread is started: dwClientID=0, threadContext @0x1cba0b8
00001332 winscard_svc.c:356:ContextThread() Received command: CMD_VERSION from client 0
00001519 winscard_svc.c:368:ContextThread() Client is protocol version 4:3
00001295 winscard_svc.c:388:ContextThread() CMD_VERSION rv=0x0 for client 0
00001616 winscard_svc.c:356:ContextThread() Received command: ESTABLISH_CONTEXT from client 0
00000810 winscard.c:219:SCardEstablishContext() Establishing Context: 0x3E8C0B00
00000145 winscard_svc.c:449:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 0
00001150 winscard_svc.c:356:ContextThread() Received command: CMD_GET_READERS_STATE from client 0
00000794 winscard_svc.c:356:ContextThread() Received command: CONNECT from client 0
00000804 winscard_svc.c:487:ContextThread() Authorized client for 'PANJIA TECH RACK NODE (V1) 00 00'
00000179 winscard.c:261:SCardConnect() Attempting Connect to PANJIA TECH RACK NODE (V1) 00 00 using protocol: 3
00000135 readerfactory.c:771:RFReaderInfo() RefReader() count was: 1
00005567 winscard.c:336:SCardConnect() power up complete.
00000204 Card ATR: 3B 64 00 00 48 53 31 34
00000115 winscard.c:356:SCardConnect() powerState: POWER_STATE_INUSE
00000716 prothandler.c:113:PHSetProtocol() Attempting PTS to T=0
00001986 winscard.c:435:SCardConnect() Active Protocol: T=0
00000200 winscard.c:455:SCardConnect() hCard Identity: 1c4b8f91
00000136 winscard.c:516:SCardConnect() UnrefReader() count was: 2
00000154 winscard_svc.c:501:ContextThread() CONNECT rv=0x0 for client 0
00001515 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 0
00001044 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
00000619 winscard.c:1613:SCardTransmit() Send Protocol: T=0
00000147 APDU: 00 00 00 00 04
00002495 SW: 01 00 00 80 90 00
00000711 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
00000621 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 0
00001888 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 0
00000832 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
00000143 winscard.c:1613:SCardTransmit() Send Protocol: T=0
00000447 APDU: 00 01 00 00 D1 01 00 00 00 00 AC 4D 00 00 1A 1E A8 F3 B8 CB D9 C6 F2 C4 74 90 37 D0 3E A8 7B 98 19 0E 72 CB F2 34 AD 4B 83 41 D9 6C 78 D7 B9 DA 40 92 46 12 07 D3 18 5C AF AC A4 E3 A1 A0 52 BC B1 F8 1B D7 6F DF 90 33 C7 C0 41 FA E9 CD 58 5F 64 18 D0 EA F7 23 DF E8 58 60 38 A0 B6 6F 40 5F BA 05 37 02 FA 21 CE 6E DE AE 12 ED 48 D2 89 F1 25 1A 87 E8 B6 E8 B4 F2 BB 90 AA 77 F1 E4 08 99 55 94 FA CE EE 1D 59 93 38 83 CA D3 E4 08 95 26 C8 A3 57 B5 21 D2 91 D0 3D 7D 57 B8 15 2D 3E DB 1A 2F C7 EF 7E AC 4D 81 5B 93 37 E7 E6 06 FB E4 56 E7 DF 0D 45 11 84 51 45 48 91 9F F7 C2 9D 07 72 A9 BF 2C DE D1 B5 10 A4 82 D3 19 94 06 1C DB D8 93 FB 59 20 40
01645996 SW: 90 00   <---- **LONG TIME RETURN**
00000208 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
00000123 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 0
00003005 ifdwrapper.c:374:IFDStatusICC() Card not transacted: 612
00000208 eventhandler.c:339:EHStatusHandlerThread() Error communicating to: PANJIA TECH RACK NODE (V1) 00 00
00002174 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 0
00000528 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
00000498 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
00001484 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x80100017 for client 0
00001075 winscard_svc.c:356:ContextThread() Received command: RECONNECT from client 0
00000400 winscard.c:530:SCardReconnect() Attempting reconnect to token.
00002093 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
00000353 winscard.c:819:SCardReconnect() UnrefReader() count was: 2
00000282 winscard_svc.c:520:ContextThread() RECONNECT rv=0x80100017 for client 0
00025889 winscard_svc.c:356:ContextThread() Received command: DISCONNECT from client 0
00001010 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
00000110 winscard.c:876:SCardDisconnect() Active Contexts: -1
00000049 winscard.c:877:SCardDisconnect() dwDisposition: 0
00000053 winscard.c:1042:SCardDisconnect() powerState: POWER_STATE_GRACE_PERIOD
00000049 winscard.c:1069:SCardDisconnect() UnrefReader() count was: 2
00000051 winscard_svc.c:538:ContextThread() DISCONNECT rv=0x0 for client 0
00001566 winscard_svc.c:356:ContextThread() Received command: RELEASE_CONTEXT from client 0
00001206 winscard.c:230:SCardReleaseContext() Releasing Context: 0x3E8C0B00
00000117 winscard_svc.c:464:ContextThread() RELEASE_CONTEXT rv=0x0 for client 0
00000833 winscard_svc.c:348:ContextThread() Client die: 0
00000159 winscard_svc.c:981:MSGCleanupClient() Thread is stopping: dwClientID=0, threadContext @0x1cba0b8
00000056 winscard_svc.c:987:MSGCleanupClient() Freeing SCONTEXT @0x1cba0b8
00360316 eventhandler.c:493:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
00008390 eventhandler.c:407:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
00002936 eventhandler.c:422:EHStatusHandlerThread() Card inserted into PANJIA TECH RACK NODE (V1) 00 00
00001721 Card ATR: 3B 64 00 00 48 53 31 34
00406293 eventhandler.c:481:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED

We found that for the host, the only difference between this command and other (can run normally) commands is the longer execution time (this command needs to erase several hundred KB of on-chip Flash).

We did not find a document describing what time unit is used in the first column of the log, we guess it is a number of microseconds. So 01645996 SW: 90 00 means that this command has been executed for 1.6s before returning the result (0x9000) to the host, right?

We quickly checked the source code of libccid and found that the default timeout of its ReadUSB function seems to be 3 seconds （not sure)? Is it possible that the timeout triggered here or elsewhere in pcsclite or pcscd caused this error?

In addition, are there any options for configuring timeout in Info.plist or elsewhere?

Thanks :-)

[LudovicRousseau]

I do not have the "PANJIA TECH RACK NODE" reader in my list. I guess you added support for this reader yourself. Exact?

I need a full pcscd log. See https://ccid.apdu.fr/#support

[asbai]

Dear Ludovic,

Thanks for your kindly reply. In fact, we have studied this link carefully before submitting this issue. But because we are using libccid and pcsclite in an embedded device with limited resources, we cannot run the toolchain directly on the device.

The OpenWRT official package does not seem to contain the parse tool. Please let me know if this tool is already included in a package. Otherwise, we can only try to generate it through cross-compilation.

Thanks :-)

[LudovicRousseau]

You can build and run parse on any Unix system. No need to run the command on the target system.

What I asked is the complete pcscd log.

sudo LIBCCID_ifdLogLevel=0x000F pcscd --foreground --debug --apdu --color | tee log.txt

[asbai]

Hi Ludovic,

We found the problem: this smart card chip sometimes returns a 0-byte empty message before returning the RDR_to_PC_DataBlock message. We believe this should be the cause of the problem.

In addition, pcscd has some execution efficiency problems in our compact embedded environment (500 requests per second vs. 330 requests per second). We ended up using libusb to communicate directly with the chip.

Thanks :-)

[LudovicRousseau]

It looks like the Zero Length Packet issue. See https://ludovicrousseau.blogspot.com/2017/03/gemalto-idbridge-k30-k50-ct30-and-zero.html

You are using my CCID driver (ifd-ccid.bundle) that already uses libusb.
I guess your "efficiency problems" is related to the USB hotplug mechanism. I see you configured pcsc-lite with --disable-libudev and --enable-libusb.
I am really surprised by the 500 requests per second. Your log indicates: Polling forced every 1 second(s) so the USB bus is scanned every 1 second.

[asbai]

Hi Ludovic,

Let me clear it:

1. What we call 500RPS means that 500 PC_to_RDR_XfrBlock messages of 230 bytes can be sent per second, and 500 RDR_to_PC_DataBlock messages of the same size can be received. This has nothing to do with the USB device scan every second.

2. I know that libccid is based on libusb, so I gave the version number of libusb we used at the beginning of this issue :-)

3. I guess the fundamental reason that libpcsclite can only achieve 330RPS is: in a compact embedded environment with limited resources, the dependency path of libpcsclite --> pscsd --> libccid --> libusb is too long, and it also involves IPC communication.

So in this kind of embedded environment, once the intermediate dependencies of libpcsclite --> IPC --> pscsd --> libccid are omitted, directly calling libusb can greatly improve the performance.

For reference, we can also achieve 500 SCardTransmit calls per second on a Thinkpad P51 Windows machine with the same 230 bytes message.

Thanks :-)