Error in eID viewer when quickly unplugging/inserting card

[Wannes123]

Hi,

When quickly unplugging/inserting a card (the same or other card), the eID viewer gives the following error:

D: CSCblogtest called C_WaitForSlotEvent with retVal: 00000006 D: CSCblogtest called Handling state transition for event TOKEN_REMOVED D: CSCblogtest called Leaving state TOKEN_ERROR D: CSCblogtest called Leaving state TOKEN D: CSCblogtest called Entering state READY (target) D: CSCbnewstate called STATE_READY D: CSCblogtest called Entering state NO_TOKEN (parent) D: CSCbNewSrc called EID_VWR_SRC_NONE D: CSCblogtest called State transition for TOKEN_REMOVED complete D: CSCblogtest called Handling state transition for event TOKEN_INSERTED D: CSCblogtest called Leaving state READY D: CSCblogtest called Leaving state NO_TOKEN D: CSCblogtest called Entering state TOKEN (target) D: CSCbnewstate called STATE_TOKEN D: CSCblogtest called C_OpenSession(slot, 0x00000004, 0, 0, &session) returned 0xe0 D: CSCblogtest called Entering state TOKEN_ID (child) D: CSCbnewstate called STATE_TOKEN_ID D: CSCblogtest called C_FindObjectsInit(session, &attr, 1) returned 0xb3 D: CSCblogtest called Handling state transition for event STATE_ERROR D: CSCblogtest called Leaving state TOKEN_ID D: CSCblogtest called C_FindObjectsFinal(session) returned 0xb3 D: CSCblogtest called Entering state TOKEN_ERROR (target) D: CSCbnewstate called STATE_TOKEN_ERROR D: CSCblogtest called State transition for STATE_ERROR complete D: CSCblogtest called State transition detected, aborting handling of TOKEN_INSERTED D: CSCblogtest called C_WaitForSlotEvent with retVal: 00000006 D: CSCblogtest called Handling state transition for event TOKEN_REMOVED D: CSCblogtest called Leaving state TOKEN_ERROR D: CSCblogtest called Leaving state TOKEN D: CSCblogtest called Entering state READY (target) D: CSCbnewstate called STATE_READY D: CSCblogtest called Entering state NO_TOKEN (parent) D: CSCbNewSrc called EID_VWR_SRC_NONE D: CSCblogtest called State transition for TOKEN_REMOVED complete

Grts

[yoe]

There is no actual error here. These are all log messages about state changes.

What I see is:

• Card gets removed
• Card gets added
• Card gets removed again

... and a few read errors, most likely the result of the card being removed.

What exactly is the problem?

[Wannes123]

The problem is, the latest inserted card is not read if inserted too quickly: you do not see any data in the eID viewer.

[Frederikus]

I've been trying to reproduce this issue, but did not succeed so far.

I started the viewer, inserted the card, removed during it being read and immediately re-inserted it. Also tried with a full read first, then remove and immediately re-insert twice. Card always get read again (all tests with same card)

[Wannes123]

Hi,

I seems I can only reproduce it with an internal card reader on a hp laptop, so it might be a hardware thing.

Grts,

[yoe]

If you want to make sure of that, please compile the "issue-34" branch, and run the viewer. It should show a message whenever a "card removed" or "card inserted" event occurs.

If we do indeed not get any information from the card reader, then it's not something we can fix, obviously.

[Wannes123]

Hi,

I do not have the necessary software installed to make compiles. I only use the eID viewer application as provided on the official website.

Grts,

[Frederikus]

or could you enable the pkcs#11 logging? The manuel for that can be found here: https://eid.belgium.be/en/specific-problems#7483

This should show the card insertion/removal events on a lower level the the eid viewer.

[Wannes123]

2017-06-27 13:17:31 - 6792|6428 - cardlayer - DEBUG: SCardEstablishContext(): 0x0 2017-06-27 13:17:31 - 6792|6428 - cardlayer - DEBUG: SCardListReaders(): 0x8010002e 2017-06-27 13:17:31 - 6792|1588 - cardlayer - DEBUG: SCardListReaders(): 0x8010002e 2017-06-27 13:17:31 - 6792|1588 - cardlayer - DEBUG: SCardListReaders(): 0x8010002e 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: SCardListReaders(): 0x0 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: SCardConnect(Generic EMV Smartcard Reader 0): 0x0 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: SCardBeginTransaction(0xea010000): 0x0 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 A4 04 0C 0C A0 00 00 01 77 .. 43 53 2D 31 35) 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: SCardBeginTransaction(0xea010000): 0x0 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(80 E4 00 00 1C) 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: SCardEndTransaction(0xea010000): 0x0 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: SCardEndTransaction(0xea010000): 0x0 2017-06-27 13:17:38 - 6792|1588 - cardlayer - INFO: Connected to BE eID card in reader Generic EMV Smartcard Reader 0 2017-06-27 13:17:38 - 6792|1588 - cardlayer - DEBUG: ReaderStatus(): card inserted 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardBeginTransaction(0xea010000): 0x0 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 2F 00) 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6A 82 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 3F 00) 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 2F 00) 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 FC) 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6C 25 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 25) 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:39 - 6792|1588 - cardlayer - INFO: Read file 3F002F00 (37 bytes) from card 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardEndTransaction(0xea010000): 0x0 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardBeginTransaction(0xea010000): 0x0 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 50 31) 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6A 82 2017-06-27 13:17:39 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 A4 04 0C 0C A0 00 00 01 77 .. 43 53 2D 31 35) 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 50 31) 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 FC) 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6C 24 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 24) 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:40 - 6792|1588 - cardlayer - INFO: Read file 3F00DF005031 (36 bytes) from card 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardEndTransaction(0xea010000): 0x0 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardBeginTransaction(0xea010000): 0x0 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 50 37) 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 FC) 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6C A3 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 A3) 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:40 - 6792|1588 - cardlayer - INFO: Read file 3F00DF005037 (163 bytes) from card 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardEndTransaction(0xea010000): 0x0 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardBeginTransaction(0xea010000): 0x0 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 50 35) 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:40 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 FC) 2017-06-27 13:17:41 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6C 77 2017-06-27 13:17:41 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 77) 2017-06-27 13:17:41 - 6792|1588 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:41 - 6792|1588 - cardlayer - INFO: Read file 3F00DF005035 (119 bytes) from card 2017-06-27 13:17:41 - 6792|1588 - cardlayer - DEBUG: SCardEndTransaction(0xea010000): 0x0 2017-06-27 13:17:41 - 6792|1588 - cardlayer - DEBUG: SCardListReaders(): 0x0 2017-06-27 13:17:41 - 6792|1588 - cardlayer - DEBUG: SCardStatus(0xea010000): 0x0 2017-06-27 13:17:41 - 6792|1588 - cardlayer - DEBUG: ReaderStatus(): card stil present 2017-06-27 13:17:41 - 6792|1588 - cardlayer - DEBUG: SCardStatus(0xea010000): 0x0 2017-06-27 13:17:41 - 6792|1588 - cardlayer - DEBUG: ReaderStatus(): card stil present 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: SCardStatus(0xea010000): 0x0 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: ReaderStatus(): card stil present 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: SCardStatus(0xea010000): 0x0 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: ReaderStatus(): card stil present 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: SCardStatus(0xea010000): 0x0 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: SCardBeginTransaction(0xea010000): 0x0 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 40 31) 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6A 82 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 3F 00) 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): 0x80100069 2017-06-27 13:17:41 - 6792|6428 - cardlayer - DEBUG: SCardEndTransaction(0xea010000): 0x80100069 2017-06-27 13:17:42 - 6792|6428 - cardlayer - DEBUG: SCardStatus(0xea010000): 0x80100069 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardDisconnect(0xea010000): 0x0 ; mode: 0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - INFO: Disconnected from card in reader Generic EMV Smartcard Reader 0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardConnect(Generic EMV Smartcard Reader 0): 0x0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardBeginTransaction(0xea020000): 0x0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 04 0C 0C A0 00 00 01 77 .. 43 53 2D 31 35) 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardBeginTransaction(0xea020000): 0x0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(80 E4 00 00 1C) 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardEndTransaction(0xea020000): 0x0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardEndTransaction(0xea020000): 0x0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - INFO: Connected to BE eID card in reader Generic EMV Smartcard Reader 0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardBeginTransaction(0xea020000): 0x0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 2F 00) 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6A 82 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 3F 00) 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 2F 00) 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 FC) 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6C 25 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 25) 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:43 - 6792|6428 - cardlayer - INFO: Read file 3F002F00 (37 bytes) from card 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardEndTransaction(0xea020000): 0x0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardBeginTransaction(0xea020000): 0x0 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 50 31) 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6A 82 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 04 0C 0C A0 00 00 01 77 .. 43 53 2D 31 35) 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:43 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 50 31) 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 FC) 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6C 24 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 24) 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:44 - 6792|6428 - cardlayer - INFO: Read file 3F00DF005031 (36 bytes) from card 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardEndTransaction(0xea020000): 0x0 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardBeginTransaction(0xea020000): 0x0 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 50 37) 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 FC) 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6C A3 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 A3) 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:44 - 6792|6428 - cardlayer - INFO: Read file 3F00DF005037 (163 bytes) from card 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardEndTransaction(0xea020000): 0x0 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardBeginTransaction(0xea020000): 0x0 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 A4 02 0C 02 50 35) 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 FC) 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 6C 77 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(00 B0 00 00 77) 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardTransmit(): SW12 = 90 00 2017-06-27 13:17:44 - 6792|6428 - cardlayer - INFO: Read file 3F00DF005035 (119 bytes) from card 2017-06-27 13:17:44 - 6792|6428 - cardlayer - DEBUG: SCardEndTransaction(0xea020000): 0x0

[Wannes123]

And in the log tab: D: CSCblogtest called Handling state transition for event SET_CALLBACKS D: CSCblogtest called Leaving state LIBOPEN D: CSCblogtest called Entering state CALLBACKS (target) D: CSCblogtest called Entering state NO_TOKEN (child) D: CSCbnewstate called STATE_NO_TOKEN D: CSCbNewSrc called EID_VWR_SRC_NONE D: Reader slotnr 0 D: Reader name \?PnP?\Notification D: CSCblogtest called Entering state NO_READER (child) D: CSCbnewstate called STATE_NO_READER D: CSCblogtest called State transition for SET_CALLBACKS complete D: CSCblogtest called Handling state transition for event READER_FOUND D: CSCblogtest called Leaving state NO_READER D: CSCblogtest called Entering state READY (target) D: CSCbnewstate called STATE_READY D: CSCblogtest called eID middleware outdated. Found version 2.0, whereas version 4.2 or higher is required for this version of the eID viewer D: CSCblogtest called State transition for READER_FOUND complete D: unknown language identifier found in registry: D: switching language to the system setting D: Reader slotnr 0 D: Reader name Generic EMV Smartcard Reader 0 D: Reader slotnr 1 D: Reader name \?PnP?\Notification D: CSCblogtest called Handling state transition for event TOKEN_INSERTED D: CSCblogtest called Leaving state READY D: CSCblogtest called Leaving state NO_TOKEN D: CSCblogtest called Entering state TOKEN (target) D: CSCbnewstate called STATE_TOKEN D: CSCbNewSrc called EID_VWR_SRC_CARD D: CSCblogtest called Entering state TOKEN_ID (child) D: CSCbnewstate called STATE_TOKEN_ID D: CSCblogtest called C_FindObjectsInit(session, &attr, 1) returned 0xe0 D: CSCblogtest called Handling state transition for event STATE_ERROR D: CSCblogtest called Leaving state TOKEN_ID D: CSCblogtest called C_FindObjectsFinal(session) returned 0x32 D: CSCblogtest called Entering state TOKEN_ERROR (target) D: CSCbnewstate called STATE_TOKEN_ERROR D: CSCblogtest called State transition for STATE_ERROR complete D: CSCblogtest called State transition detected, aborting handling of TOKEN_INSERTED

[Frederikus]

Closing this bugreport. The eID Viewer backend for windows has received many changes in version 4.4.5 regarding race-conditions of multiple threads using the pkcs11 slotlist. It might have fixed this issue, but we have not been able to reproduce it.

[shaochen]

The problem is, the latest inserted card is not read if inserted too quickly: you do not see any data in the eID viewer.

Thank you so much! You just brought an end to 30 minutes of frustration, slipping the ID card in slowly is the answer!