Identiv 3700F occasionally fails to power up card

[jeremyherbert]

I am using PCSC 0.9.1 with an Identiv uTrust 3700F and an NTAG213/NTAG216 NFC tag. It works quite well, but occasionally it is unable to power up the card and has a blinking red light on the device. I am testing on both raspbian and xubuntu 20.04, both show the same issue.

I can't reproduce this problem with the device connected to Windows with the Identiv diagnostic tool. I also can't reproduce the issue using a uTrust 3720F connected to PCSC on linux.

If I leave the tag there, eventually the red blinking status light turns green again (indicating idle or no card detected) and no matter how long I leave the card there it will not read it. Is it possible to configure PCSC to retry the connection if it fails ?

Below is the log of me swiping a tag on and off a number of times, the line which contains "ifdhandler.c:1251:IFDHPowerICC() PowerUp failed" is what corresponds to the issue.

log.txt

[LudovicRousseau]

The "error" is reported by the reader itself.

00000012 [140608650942208] ifdhandler.c:1183:IFDHPowerICC() action: PowerUp, usb:04e6/5790:libudev:0:/dev/bus/usb/002/007 (lun: 0)
00000011 [140608650942208] -> 000000 62 00 00 00 00 00 4E 00 00 00 
00021137 [140608650942208] <- 000000 80 00 00 00 00 00 4E 41 FE 00 
00000045 [140608650942208] commands.c:246:CmdPowerOn Card absent or mute
00000008 [140608650942208] ifdhandler.c:1251:IFDHPowerICC() PowerUp failed

The reader reports: card absent or mute. So there is no point trying a power up again.

I could modify the CCID driver to try again a new power up.
But that should be very specific to this reader. And I am not sure at all that would solve the problem.

Try with the attached patch for the CCID driver.
patch.txt

[jeremyherbert]

Thank you! This does indeed fix the problem. I applied to this to the latest git master for CCID, tested on both ubuntu and raspbian.

I also had a python script using pyscard that was returning blank events to the CardConnectionObserver (the ccevent variable was just ([], [])) when this error occurred, and that is also resolved now too.

[jeremyherbert]

Here is the rough log output now:

00000350 [3048170480] <- 000000 81 00 00 00 00 00 A2 01 00 01
00000041 [3048170480] ifdhandler.c:2008:IFDHICCPresence() Card present
00000042 [3048170480] ifdhandler.c:1887:IFDHICCPresence() usb:04e6/5790:libudev:0:/dev/bus/usb/001/004 (lun: 0)
00000043 [3048170480] -> 000000 65 00 00 00 00 00 A3 00 00 00
00000386 [3048170480] <- 000000 81 00 00 00 00 00 A3 01 00 01
00000040 [3048170480] ifdhandler.c:2008:IFDHICCPresence() Card present
00000039 [3048170480] ifdhandler.c:1185:IFDHPowerICC() action: PowerUp, usb:04e6/5790:libudev:0:/dev/bus/usb/001/004 (lun: 0)
00000044 [3048170480] -> 000000 62 00 00 00 00 00 A4 00 00 00
00019741 [3048170480] <- 000000 80 00 00 00 00 00 A4 41 FE 00
00000042 [3048170480] commands.c:246:CmdPowerOn Card absent or mute
00000036 [3048170480] ifdhandler.c:1253:IFDHPowerICC() PowerUp failed
00000041 [3048170480] -> 000000 62 00 00 00 00 00 A5 00 00 00
00038922 [3048170480] <- 000000 80 14 00 00 00 00 A5 00 00 00 3B 8F 80 01 80 4F 0C A0 00 00 03 06 03 00 03 00 00 00 00 68
00000045 [3048170480] eventhandler.c:406:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
00000040 [3048170480] eventhandler.c:423:EHStatusHandlerThread() Card inserted into Identiv uTrust 3700 F CL Reader [uTrust 3700 F CL Reader] (55021722281945) 00 00
00000051 [3048170480] Card ATR: 3B 8F 80 01 80 4F 0C A0 00 00 03 06 03 00 03 00 00 00 00 68
00000039 [3048170480] ifdhandler.c:318:IFDHPolling() usb:04e6/5790:libudev:0:/dev/bus/usb/001/004 (lun: 0) 5000 ms
00000042 [3048170480] ccid_usb.c:1340:InterruptRead() before (0), timeout: 5000 ms
00961085 [3048170480] ccid_usb.c:1386:InterruptRead() after (0) (0)
00000048 [3048170480] NotifySlotChange: 50 02
00000042 [3048170480] ifdhandler.c:1887:IFDHICCPresence() usb:04e6/5790:libudev:0:/dev/bus/usb/001/004 (lun: 0)
00000043 [3048170480] -> 000000 65 00 00 00 00 00 A6 00 00 00
00165855 [3048170480] <- 000000 81 00 00 00 00 00 A6 01 00 01
00000042 [3048170480] ifdhandler.c:2008:IFDHICCPresence() Card absent
00000037 [3048170480] eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
00000040 [3048170480] ifdhandler.c:1887:IFDHICCPresence() usb:04e6/5790:libudev:0:/dev/bus/usb/001/004 (lun: 0)
00000043 [3048170480] -> 000000 65 00 00 00 00 00 A7 00 00 00
00000349 [3048170480] <- 000000 81 00 00 00 00 00 A7 01 00 01
00000041 [3048170480] ifdhandler.c:2008:IFDHICCPresence() Card present
00000038 [3048170480] ifdhandler.c:318:IFDHPolling() usb:04e6/5790:libudev:0:/dev/bus/usb/001/004 (lun: 0) 600000 ms

[LudovicRousseau]

That is interesting.
The patch is dangerous so I will NOT apply it to the official version of the driver. If the card is really mute then the driver will loop forever.

To write a correct fix I would like to know what the Windows driver is doing to avoid the problem. Maybe it does something completely different.

I moved the reader from the list "Should work but untested by me" to the list "Unsupported or partly supported CCID readers".
https://ccid.apdu.fr/ccid/unsupported.html#0x04E60x5790

[jeremyherbert]

I have a beagle USB protocol analyser, would it help if I captured some dumps from the device communication under windows?

[LudovicRousseau]

Yes. That would help.

[jeremyherbert]

I have been playing around with this further on windows. It seems that I can reproduce the problem on windows if the diagnostic software is not running. If it is running, I have not been able to get it to fail, but the accesses slow down quite a bit; I have the tag in the field for 2-3 seconds before the LED changes from green to orange and the device starts sending USB transfers. So I wonder if this is perhaps a timing issue (other than the fact that there is clearly a bug in the reader firmware)?

I have attached two logs of the USB packets. "tag_reader_failure.tdc" is a log with the diagnostic software not running and some tag startup failures. "tag_reader_working.tdc" is a log with the diagnostic software running. In both cases I swiped the tag in and out of the reader field a number of times.

You can view the files in the free viewer tool from Beagle: https://www.totalphase.com/products/data-center/ ; if that is a problem let me know and I think I can export them as CSV, although the software interface is much more helpful in my experience.

usb_dumps.zip

[jeremyherbert]

I should add: with the diagnostic software running, both the detection and reaction of the reader to the tag entering and tag leaving the field is delayed significantly. Ie the light will take ~2s to go from green to orange when putting the tag on the reader, and ~2s to go from orange to green after removing the tag from the field.

[jeremyherbert]

I have tried the following patch and it also works, basically just wrapping the CmdPowerOn call in a for loop to repeat it a second time if it fails the first time. Would something like this be acceptable in the CCID codebase? Could also put it behind an if statement to limit its use to the 3700F only.

diff --git a/src/ifdhandler.c b/src/ifdhandler.c
index 294e7e5..0a8c4fd 100644
--- a/src/ifdhandler.c
+++ b/src/ifdhandler.c
@@ -1235,23 +1235,27 @@ EXTERNAL RESPONSECODE IFDHPowerICC(DWORD Lun, DWORD Action,
 			 */
 			ccid_descriptor->readTimeout = 60*1000;
 
-			nlength = sizeof(pcbuffer);
-			return_value = CmdPowerOn(reader_index, &nlength, pcbuffer,
-				PowerOnVoltage);
+			for (int i=0; i<2; i++) {
+				nlength = sizeof(pcbuffer);
+				return_value = CmdPowerOn(reader_index, &nlength, pcbuffer,
+					PowerOnVoltage);
 
-			/* set back the old timeout */
-			ccid_descriptor->readTimeout = oldReadTimeout;
+				/* set back the old timeout */
+				ccid_descriptor->readTimeout = oldReadTimeout;
 
-			if (return_value != IFD_SUCCESS)
-			{
-				/* used by GemCore SIM PRO: no card is present */
-				if (GEMCORESIMPRO == ccid_descriptor -> readerID)
-					get_ccid_descriptor(reader_index)->dwSlotStatus
-						= IFD_ICC_NOT_PRESENT;
+				if (return_value != IFD_SUCCESS)
+				{
+					/* used by GemCore SIM PRO: no card is present */
+					if (GEMCORESIMPRO == ccid_descriptor -> readerID)
+						get_ccid_descriptor(reader_index)->dwSlotStatus
+							= IFD_ICC_NOT_PRESENT;
 
-				DEBUG_CRITICAL("PowerUp failed");
-				return_value = IFD_ERROR_POWER_ACTION;
-				goto end;
+					DEBUG_CRITICAL("PowerUp failed");
+					return_value = IFD_ERROR_POWER_ACTION;
+					if (i == 1) goto end;
+				} else {
+					break;
+				}
 			}
 
 			/* Power up successful, set state variable to memorise it */

(edit: tidy up the patch a little)

[LudovicRousseau]

You traces contains PC_to_RDR_Escape frames (frames with 6Bh as the 1st byte). These frames are NOT documented by the CCID specification and are used to send proprietary commands to the reader.
For example we have:

6B 02 00 00 00 00 00 00 00 00 AC FF
6B 01 00 00 00 00 01 00 00 00 13
6B 07 00 00 00 00 02 00 00 00 FF 70 04 E6 01 03 00

In the working case you can see you have the command 6B 01 00 00 00 00 48 00 00 00 02 before the exchange. Maybe this command is used to wait for a tag. Maybe not.

Without the documentation from Identiv/SCM it is nearly impossible to know what these commands are doing.

I sent an email to Identiv/SCM asking what they plan to do. We will see...

[calaib]

Please check with firmware v1.19 now available on Identiv website.

[jeremyherbert]

I can confirm that I was able to reproduce the problem before the update, and after I can not reproduce it anymore. So I would consider this fixed. Thank you for your help!

@LudovicRousseau You can move the 3700F back into the supported list and close this issue if you feel this is acceptable.

[LudovicRousseau]

Done.
The reader is back in the "should work" list
https://ccid.apdu.fr/ccid/shouldwork.html#0x04E60x5790