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.

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

OpenSC fails to detect card when inserted after the library initialization (C_WaitForSlotEvent() does not return) #943

Closed
Jakuje opened this issue Jan 16, 2017 · 29 comments

Comments

@Jakuje
Copy link
Member

Jakuje commented Jan 16, 2017

Expected behaviour

Initializing pkcs11 library and then waiting for slot events (card insertion) should work.

Actual behaviour

Trying interactive tests depending on the C_WaitForSlotEvent() fails to detect the Coolkey card (or CAC -- from #841), because the card is detected in the card-mcrd driver and its initialization fails.

Steps to reproduce

  1. Remove the card from the reader
  2. Start the interactive testsuite (init library and call C_WaitForSlotEvent), for example using pkcs11-tool --test-hotplug or ./p11test -p pin -i -s 0
  3. Insert the card
  4. Watch nothing happen.

Logs

With OPENSC_DEBUG=999 we can observe these logs behavior (with comments):

start detection in mcrd:

0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:266:sc_connect_card: trying driver 'mcrd'
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:993:match_atr_table: ATR     : 3b:ff:14:00:ff:81:31:fe:45:80:25:a0:00:00:00:56:57:53:43:36:35:30:03:03:38
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3B:FF:94:00:FF:80:B1:FE:45:1F:03:00:68:D2:76:00:00:28:FF:05:1E:31:80:00:90:00:23
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:6f:00:ff:00:68:d2:76:00:00:28:ff:05:1e:31:80:00:90:00
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:ff:11:00:ff:80:b1:fe:45:1f:03:00:68:d2:76:00:00:28:ff:05:1e:31:80:00:90:00:a6
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3B:FE:94:00:FF:80:B1:FA:45:1F:03:45:73:74:45:49:44:20
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:fe:94:00:ff:80:b1:fa:45:1f:03:45:73:74:45:49:44:20:76:65:72:20:31:2e:30:43
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:6e:00:ff:45:73:74:45:49:44:20:76:65:72:20:31:2e:30
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:de:18:ff:c0:80:b1:fe:45:1f:03:45:73:74:45:49:44:20:76:65:72:20:31:2e:30:2b
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:5e:11:ff:45:73:74:45:49:44:20:76:65:72:20:31:2e:30
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:6e:00:00:45:73:74:45:49:44:20:76:65:72:20:31:2e:30
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3B:FE:18:00:00:80:31:FE:45:45:73:74:45:49:44:20:76:65:72:20:31:2E:30:A8
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3B:FE:18:00:00:80:31:FE:45:80:31:80:66:40:90:A4:56:1B:16:83:01:90:00:86
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:fe:18:00:00:80:31:fe:45:80:31:80:66:40:90:a4:16:2a:00:83:01:90:00:e1
0x7f336f056980 13:03:02.486 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.487 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:fe:18:00:00:80:31:fe:45:80:31:80:66:40:90:a4:16:2a:00:83:0f:90:00:ef
0x7f336f056980 13:03:02.487 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.487 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:fa:18:00:00:80:31:fe:45:fe:65:49:44:20:2f:20:50:4b:49:03
0x7f336f056980 13:03:02.487 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.487 [opensc-pkcs11] card.c:1004:match_atr_table: ATR try : 3b:f8:18:00:00:80:31:fe:45:fe:41:5a:45:20:44:49:54:33
0x7f336f056980 13:03:02.487 [opensc-pkcs11] card.c:1007:match_atr_table: ignored - wrong length
0x7f336f056980 13:03:02.487 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
0x7f336f056980 13:03:02.490 [opensc-pkcs11] card.c:397:sc_lock: called
0x7f336f056980 13:03:02.490 [opensc-pkcs11] reader-pcsc.c:582:pcsc_lock: called
0x7f336f056980 13:03:02.690 [opensc-pkcs11] card.c:439:sc_lock: returning with: 0 (Success)
0x7f336f056980 13:03:02.690 [opensc-pkcs11] apdu.c:517:sc_transmit: called
0x7f336f056980 13:03:02.690 [opensc-pkcs11] apdu.c:371:sc_single_transmit: called
0x7f336f056980 13:03:02.690 [opensc-pkcs11] apdu.c:376:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(15) 0x7f336c30df40
0x7f336f056980 13:03:02.690 [opensc-pkcs11] reader-pcsc.c:269:pcsc_transmit: reader 'OMNIKEY AG CardMan 3121 00 00'
0x7f336f056980 13:03:02.690 [opensc-pkcs11] reader-pcsc.c:270:pcsc_transmit: 
Outgoing APDU (20 bytes):
00 A4 04 00 0F D2 33 00 00 00 45 73 74 45 49 44 ......3...EstEID
20 76 33 35                                      v35
0x7f336f056980 13:03:02.690 [opensc-pkcs11] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7f336f056980 13:03:02.703 [opensc-pkcs11] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..
0x7f336f056980 13:03:02.703 [opensc-pkcs11] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7f336f056980 13:03:02.703 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7f336f056980 13:03:02.703 [opensc-pkcs11] card.c:449:sc_unlock: called
0x7f336f056980 13:03:02.703 [opensc-pkcs11] reader-pcsc.c:627:pcsc_unlock: called
0x7f336f056980 13:03:02.712 [opensc-pkcs11] card-mcrd.c:296:mcrd_match_card: SELECT AID: 9000
0x7f336f056980 13:03:02.712 [opensc-pkcs11] card-mcrd.c:298:mcrd_match_card: AID found
0x7f336f056980 13:03:02.712 [opensc-pkcs11] card.c:280:sc_connect_card: matched: MICARDO 2.1 / EstEID 1.0 - 3.0

we just matched completely mcrd card

0x7f336f056980 13:03:02.712 [opensc-pkcs11] reader-pcsc.c:440:pcsc_reconnect: Reconnecting to the card...
0x7f336f056980 13:03:02.712 [opensc-pkcs11] reader-pcsc.c:303:refresh_attributes: OMNIKEY AG CardMan 3121 00 00 check
0x7f336f056980 13:03:02.712 [opensc-pkcs11] reader-pcsc.c:323:refresh_attributes: returning with: 0 (Success)
0x7f336f056980 13:03:04.563 [opensc-pkcs11] reader-pcsc.c:463:pcsc_reconnect: OMNIKEY AG CardMan 3121 00 00:SCardReconnect returned: 0x00000000
0x7f336f056980 13:03:04.563 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
0x7f336f056980 13:03:04.563 [opensc-pkcs11] card.c:397:sc_lock: called
0x7f336f056980 13:03:04.563 [opensc-pkcs11] reader-pcsc.c:582:pcsc_lock: called
0x7f336f056980 13:03:04.563 [opensc-pkcs11] card.c:439:sc_lock: returning with: 0 (Success)
0x7f336f056980 13:03:04.563 [opensc-pkcs11] apdu.c:517:sc_transmit: called
0x7f336f056980 13:03:04.563 [opensc-pkcs11] apdu.c:371:sc_single_transmit: called
0x7f336f056980 13:03:04.563 [opensc-pkcs11] apdu.c:376:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(15) 0x7f336c30df30
0x7f336f056980 13:03:04.563 [opensc-pkcs11] reader-pcsc.c:269:pcsc_transmit: reader 'OMNIKEY AG CardMan 3121 00 00'
0x7f336f056980 13:03:04.563 [opensc-pkcs11] reader-pcsc.c:270:pcsc_transmit: 
Outgoing APDU (20 bytes):
00 A4 04 00 0F F0 45 73 74 45 49 44 20 76 65 72 ......EstEID ver
20 31 2E 30                                      1.0
0x7f336f056980 13:03:04.563 [opensc-pkcs11] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7f336f056980 13:03:06.741 [opensc-pkcs11] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (2 bytes):
6A 82 j.
0x7f336f056980 13:03:06.741 [opensc-pkcs11] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7f336f056980 13:03:06.741 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7f336f056980 13:03:06.741 [opensc-pkcs11] card.c:449:sc_unlock: called
0x7f336f056980 13:03:06.741 [opensc-pkcs11] reader-pcsc.c:627:pcsc_unlock: called
0x7f336f056980 13:03:06.746 [opensc-pkcs11] card-mcrd.c:342:mcrd_init: SELECT AID: 6A82

the card driver tries to initialize the card

0x7f336f056980 13:03:06.746 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
0x7f336f056980 13:03:06.746 [opensc-pkcs11] card.c:397:sc_lock: called
0x7f336f056980 13:03:06.746 [opensc-pkcs11] reader-pcsc.c:582:pcsc_lock: called
0x7f336f056980 13:03:06.746 [opensc-pkcs11] card.c:439:sc_lock: returning with: 0 (Success)
0x7f336f056980 13:03:06.746 [opensc-pkcs11] apdu.c:517:sc_transmit: called
0x7f336f056980 13:03:06.746 [opensc-pkcs11] apdu.c:371:sc_single_transmit: called
0x7f336f056980 13:03:06.746 [opensc-pkcs11] apdu.c:376:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(15) 0x7f336c30df40
0x7f336f056980 13:03:06.746 [opensc-pkcs11] reader-pcsc.c:269:pcsc_transmit: reader 'OMNIKEY AG CardMan 3121 00 00'
0x7f336f056980 13:03:06.746 [opensc-pkcs11] reader-pcsc.c:270:pcsc_transmit: 
Outgoing APDU (20 bytes):
00 A4 04 00 0F D2 33 00 00 00 45 73 74 45 49 44 ......3...EstEID
20 76 33 35                                      v35
0x7f336f056980 13:03:06.746 [opensc-pkcs11] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7f336f056980 13:03:06.753 [opensc-pkcs11] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (2 bytes):
6A 82 j.
0x7f336f056980 13:03:06.753 [opensc-pkcs11] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7f336f056980 13:03:06.753 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7f336f056980 13:03:06.753 [opensc-pkcs11] card.c:449:sc_unlock: called
0x7f336f056980 13:03:06.753 [opensc-pkcs11] reader-pcsc.c:627:pcsc_unlock: called
0x7f336f056980 13:03:06.761 [opensc-pkcs11] card-mcrd.c:353:mcrd_init: SELECT AID: 6A82
0x7f336f056980 13:03:06.761 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
0x7f336f056980 13:03:06.761 [opensc-pkcs11] card.c:397:sc_lock: called
0x7f336f056980 13:03:06.761 [opensc-pkcs11] reader-pcsc.c:582:pcsc_lock: called
0x7f336f056980 13:03:06.761 [opensc-pkcs11] card.c:439:sc_lock: returning with: 0 (Success)
0x7f336f056980 13:03:06.761 [opensc-pkcs11] apdu.c:517:sc_transmit: called
0x7f336f056980 13:03:06.761 [opensc-pkcs11] apdu.c:371:sc_single_transmit: called
0x7f336f056980 13:03:06.762 [opensc-pkcs11] apdu.c:376:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(11) 0x7f336c30df50
0x7f336f056980 13:03:06.762 [opensc-pkcs11] reader-pcsc.c:269:pcsc_transmit: reader 'OMNIKEY AG CardMan 3121 00 00'
0x7f336f056980 13:03:06.762 [opensc-pkcs11] reader-pcsc.c:270:pcsc_transmit: 
Outgoing APDU (16 bytes):
00 A4 04 00 0B D0 31 00 00 00 44 69 67 69 49 44 ......1...DigiID
0x7f336f056980 13:03:06.762 [opensc-pkcs11] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7f336f056980 13:03:06.768 [opensc-pkcs11] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (2 bytes):
6A 82 j.
0x7f336f056980 13:03:06.768 [opensc-pkcs11] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7f336f056980 13:03:06.768 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7f336f056980 13:03:06.768 [opensc-pkcs11] card.c:449:sc_unlock: called
0x7f336f056980 13:03:06.768 [opensc-pkcs11] reader-pcsc.c:627:pcsc_unlock: called
0x7f336f056980 13:03:06.776 [opensc-pkcs11] card-mcrd.c:363:mcrd_init: SELECT AID: 6A82
0x7f336f056980 13:03:06.776 [opensc-pkcs11] card-mcrd.c:365:mcrd_init: returning with: -1200 (Card command failed)
0x7f336f056980 13:03:06.776 [opensc-pkcs11] card.c:285:sc_connect_card: driver 'MICARDO 2.1 / EstEID 1.0 - 3.0' init() failed: Card command failed
0x7f336f056980 13:03:06.776 [opensc-pkcs11] reader-pcsc.c:566:pcsc_disconnect: called
0x7f336f056980 13:03:08.618 [opensc-pkcs11] reader-pcsc.c:570:pcsc_disconnect: OMNIKEY AG CardMan 3121 00 00:SCardDisconnect returned: 0x00000000
0x7f336f056980 13:03:08.618 [opensc-pkcs11] card.c:326:sc_connect_card: returning with: -1200 (Card command failed)
0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:272:card_detect: OMNIKEY AG CardMan 3121 00 00: SC connect card error -1200
0x7f336f056980 13:03:08.618 [opensc-pkcs11] misc.c:61:sc_to_cryptoki_error_common: libopensc return value: -1200 (Card command failed)

which finally fails

0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:378:card_detect_all: All cards detected

but does not fail back to the detection of using different drivers

0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:493:slot_find_changed: slot 0x0 token: 0 events: 0x00
0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:499:slot_find_changed: mask: 0x0F events: 0x00 result: 0
0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:493:slot_find_changed: slot 0x1 token: 0 events: 0x00
0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:499:slot_find_changed: mask: 0x0F events: 0x00 result: 0
0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:493:slot_find_changed: slot 0x2 token: 0 events: 0x00
0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:499:slot_find_changed: mask: 0x0F events: 0x00 result: 0
0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:493:slot_find_changed: slot 0x3 token: 0 events: 0x00
0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:499:slot_find_changed: mask: 0x0F events: 0x00 result: 0
0x7f336f056980 13:03:08.618 [opensc-pkcs11] slot.c:507:slot_find_changed: returning with: 8
0x7f336f056980 13:03:08.618 [opensc-pkcs11] pkcs11-global.c:664:C_WaitForSlotEvent: C_WaitForSlotEvent() reader_states:0xd700b0
0x7f336f056980 13:03:08.618 [opensc-pkcs11] ctx.c:855:sc_wait_for_event: called
0x7f336f056980 13:03:08.618 [opensc-pkcs11] reader-pcsc.c:1354:pcsc_wait_for_event: called
0x7f336f056980 13:03:08.618 [opensc-pkcs11] reader-pcsc.c:1388:pcsc_wait_for_event: re-use reader 'OMNIKEY AG CardMan 3121 00 00'
0x7f336f056980 13:03:08.618 [opensc-pkcs11] reader-pcsc.c:1388:pcsc_wait_for_event: re-use reader '\\?PnP?\Notification'
0x7f336f056980 13:03:08.619 [opensc-pkcs11] reader-pcsc.c:1429:pcsc_wait_for_event: Looping...
0x7f336f056980 13:03:08.619 [opensc-pkcs11] reader-pcsc.c:1437:pcsc_wait_for_event: 'OMNIKEY AG CardMan 3121 00 00' before=0x001D0022 now=0x001D0020
0x7f336f056980 13:03:08.619 [opensc-pkcs11] reader-pcsc.c:1437:pcsc_wait_for_event: '\\?PnP?\Notification' before=0x00000000 now=0x00000000

and the insertion event is lost.

Commenting out mcrd from ctx.c will make the same match and fail in the muscle card driver. Commenting all of them (except Coolkey) works as expected. I didn't test that further. This looks like a problem with very similar cards (eg answering successfully to the same APDU). This does NOT happen when the card is inserted during the library initialization (the weird part), which is probably handled i bit differently.

Can somebody with better architecture overview have a look in these logs and confirm that my theory and probably propose what can be done about that?

@dengert
Copy link
Member

dengert commented Jan 16, 2017

Are you saying that your card is not a mcrd card but it was selected?

The APDU 00 A4 04 00 0F D2 33 00 00 00 45 73 74 45 49 44 20 76 33 35
is a select file command, that is also used to select an AID. But it does not look like it is registered. internationally registered AID start with A0

Could it be that your CAC card returns 90 00 to this command? Is the card from the same vendor as the mcrd card?

As you suggest it could be the code should have detected a card was removed, (but I don't see in your trace where the card was removed.) shold not try a reconnect, but stat over as if it is a new card.

@Jakuje
Copy link
Member Author

Jakuje commented Jan 16, 2017

Are you saying that your card is not a mcrd card but it was selected?

Yes. This is a log with CoolKey applet. I can provide more information about the card manufacturer tomorrow, but the applet itself should be open source.

Could it be that your CAC card returns 90 00 to this command? Is the card from the same vendor as the mcrd card?

It looks like we are getting 90 00, but only once. The second answer is already 6A 82 ... but I might be missing something.

As you suggest it could be the code should have detected a card was removed, (but I don't see in your trace where the card was removed.) shold not try a reconnect, but stat over as if it is a new card.

The card was removed before I started the test. It is not part of the log. This is par of the log, when the card is inserted into the empty slot.

@frankmorgner
Copy link
Member

First, the mcrd ATR clashes with your cards ATR, which is bad. Maybe the ATR mask is not properly set somewhere...

If you change mcrd_init() to return SC_ERROR_INVALID_CARD instead of SC_ERROR_CARD_CMD_FAILED, the program will continue the card detection and finally get to your driver.

However, you need to step through the program to find out why that only happens when there is no card inserted...

@frankmorgner
Copy link
Member

It feels strange that your card succeeeds to select the EstEIDv35 AID. Are there additional applets on the card or does your applet not handle SELECT AIDs correctly?

@dengert
Copy link
Member

dengert commented Jan 16, 2017

This sounds like the card wil accept some AIDS when it does not have that applet on the card.
https://github.com/OpenSC/OpenSC/wiki/Estonian-eID-(EstEID)
says: "1.1 card answers with 0×9000 to any AID selection, even if the application is not present on the card. This causes problems for software that detects cards by trying to select the AID of the expected application."

It sounds like to problem is with the Java card. You said the applet was opens source.
https://svn.fedorahosted.org/svn/coolkey/trunk/applet/README says this is from 2002, 15 years old.

as @frankmorgner said the ATRs may be the same as it is the ATR for a javacard, and selecting the AID does not work as expected because the javacard will return 9000 for any AID. the same problem as the EstEID card. The PIV driver might also fail, as it tries to select the AID.

So any driver that tries to select the AID may fail. May be the same issue with the muscle driver?

Where did you get the card?
How old is it?

I would be interested in a trace of having just the PIV and the driver you expect to work in the opensc.conf.

Who installed the applet?

@Jakuje
Copy link
Member Author

Jakuje commented Jan 16, 2017

It feels strange that your card succeeeds to select the EstEIDv35 AID. Are there additional applets on the card or does your applet not handle SELECT AIDs correctly?

As far as I know, there are no other applets. When the card is available during the library initialization it is detected correctly.

How old is it?

The card should be new and was provisioned recently (~months). The applet is not any new. There are some updates in github repo, but the logic is probably still the same:

Who installed the applet?

The card was provisioned (applet installed, key generated) by Enterprise Security Client (ESC), part of Red Hat Certificate System. ESC is using the CoolKey PKCS#11 module to read/write which basically supports only the CoolKey applet (in addition to CAC and PIV).

I will attach the traces tomorrow.

@Jakuje
Copy link
Member Author

Jakuje commented Jan 17, 2017

I would be interested in a trace of having just the PIV and the driver you expect to work in the opensc.conf.

@dengert I added a

     card_drivers = piv, coolkey;

to the /etc/opensc.conf and this is the log of the call to WaitForSlotEvent from the library:

https://gist.github.com/Jakuje/877eb2ab0ecca843962dd479d68867fb

The detection and the initialization works as expected in this case.

The card with CoolKey applet should be Gemalto/SafeNet will SC650.

@dengert
Copy link
Member

dengert commented Jan 17, 2017

Somewhere between 0.15.0 and master, the name to use for the PIV driver changed from piv to PIV-II
as internally PIV-II was always displayed.
Use opensc-tool --list-drivers to see the names in your version.
The trace does not show any use of card-piv.c to match a card. I suspect it because the driver name is wrong. (The pkcs15-piv.c was called, but that is much later after a driver is selected.)

Looking at the internal list in ctx.c you will note that the drivers are in order, and starting with the mcrd driver are the drivers that do some APDU command to the card to test if it matches. In your first post it showed the mcrd driver did a SELECT command that responded 90 00, so the driver assumed it matched. . When you removed mcrd, you said the muscle driver did the same thing, but you did not provide a trace to show why the muscle driver though it matched. ( The same trace would also show why the setcos driver did not match.) There are 10 drivers before the coolkey driver that could also cause a false match. It would be nice to see if they also have a false match, and why.

If you remove the mcrd driver (we know how it matched, but not why) from ctx.c can you get a debug log?

Pleae send the whole log. The last log started at the C_WaitForSlotEvent, and there is a lot of other stuff before this. This would show what the setcos and muscle drivers are doing, and why the muscle driver got a match.

@Jakuje
Copy link
Member Author

Jakuje commented Jan 17, 2017

Thanks for the reminder. I knew about that, but obviously forgot. Adding a new log with both PIV and Coolkey. Now, the reports look good:

$ opensc-tool --list-drivers
Configured card drivers:
PIV-II PIV-II for multiple cards
coolkey COOLKEY

I posted only the C_WaitForSlotEvent part, because in the whole log, there is a lot of things around that, which would cause a lot of unnecessary output. Now I put together simple program to wait for the event and end.

The whole logs

The fail means I killed the program, because the C_WaitForSlotEvent never returned for Coolkey.

@dengert
Copy link
Member

dengert commented Jan 17, 2017

mcrd, coolkey
The card responded 90 00 to 00 A4 00 0F D2 33 00 00 00 45 73 74 45 49 44 20 76 33 35 issued by card-mcrd.c so driver assumed a match.

muscle, coolkey
The card responded 90 00 to: 00 A4 04 00 06 A0 00 00 00 01 01 issued by card-muscle.c
Driver then sent B0 3C 00 00 40 with response 01 01 01 04 00 00 13 88 00 00 0B BC 01 04 00 00 90 00
and said it matched. card.c:276:sc_connect_card: matched: MuscleApplet
but card-muscle.c:482:muscle_init: returning with: -1408 (Not supported) which I think maybe too late. @frankmorgner is it too late?

piv, coolkey
The card responded 90 00 to 00 A4 04 00 09 A0 00 00 03 08 00 00 10 00 00 issued by card-piv.c but piv_find_aid() expects the card to return the template with the correct data in the template. There was no template returned, just 90 00, so the SC_ERROR_NO_CARD_SUPPORT is returned and the card did not match, so the next driver coolkey driver was tried and works.

00 A4 04 00 is really a SELECT FILE with (P1=A4) Direct selection by DF name (data field=DF name) and
(P2=00)Return FCI, optional template.

http://www.cardwerk.com/smartcards/smartcard_standard_ISO7816-4_9_application-independent_card_services.aspx#ISO7816-4_9_3

also uses the SELECT FILE in section "9.3 Application selection service"

Now it maybe that your card does not support "9.3" but even if it is only supporting a select file,
and the DF is not present I would expect it should return 62XX or 6Axx to indicate an error or file not found.

What we don't have is a trace of starting with all the drivers without using C_WaitForSlotEvent.
You said coolkey works in this situation. So there could be something that is set differently if not card is in the slot, for example T=0 vs T=1 is not reset correctly, or something in the sc_card structure is not reset correctly. It is not clear why the other drivers would not fine the card in the normal situation, but not after waiting for the slot event.

Can you get a dump with all the drivers, but have card in the slot, and don't use C_WaitForSlotEvent?
opensc-tool --serial should work for this.

@Jakuje
Copy link
Member Author

Jakuje commented Jan 18, 2017

Thanks for having a look into that. The opensc-tool --serial with Coolkey is segfaulting, because of uninitialized serial.len (it somehow slipped through, but probably not related to the actual issue above). This patch makes it work:

diff --git a/src/libopensc/card-coolkey.c b/src/libopensc/card-coolkey.c
index 8a70102..fb7c721 100644
--- a/src/libopensc/card-coolkey.c
+++ b/src/libopensc/card-coolkey.c
@@ -1347,6 +1347,7 @@ static int coolkey_get_serial_nr_from_CUID(sc_card_t* card, sc_serial_number_t*
 
 	SC_FUNC_CALLED(card->ctx, SC_LOG_DEBUG_NORMAL);
 	memcpy(serial->value, &priv->cuid, sizeof(priv->cuid));
+	serial->len = sizeof(priv->cuid);
 	SC_FUNC_RETURN(card->ctx, SC_LOG_DEBUG_NORMAL, SC_SUCCESS);
 }

The logs with all drivers enabled, muscle and mcrd (all passes):
https://gist.github.com/Jakuje/4240dfd3ec829321efc3bf02ee723a91

Interesting is that in these cases, the card returns 6A82 for the same APDU from mcrd instead of the 9000, which basically points out the problem will be in the card somehow. Could that be some timing issue, that the card answers 9000 before it is properly initialized, but OpenSC starts querying it in the meantime?

The note about the card is that it is low power 1.8V card so we had to fix pcsc-lite in Fedora to get it even recognized (pcsc-lite was ignorring the cards below 3V).

@dengert
Copy link
Member

dengert commented Jan 18, 2017

Good to see @LudovicRousseau is involved in this problem.

Have you tried using a different readers? Say for example the SCM 3500: https://www.amazon.com/Micro-Systems-SmartFold-Reader-SCR3500/dp/B004RL6QUQ

Some differences between having card inserted before starting pkcs11 application or opensc-tool
and having them wait for card insertion, could be timing issues, with the reader, card or pcsc.

Inserting the card may require the card's OS to "boot" and get the default applet setup. If it gets a SELECT command before it is ready it might responds with the wrong response.

Try adding a sleep(1) in reader-pcsc.c after sc_log(ctx, "card inserted event"); This is for debugging,
but should give the card and reader plenty of time to get ready. If that works, we cold find a better place to put this.

You could start pcscd with debugging to see timing and commands and responses.

You could get a USB trace to see if the APDU and response from the card match what OpenSC is seeing.
This would point at pcsc or OpenSC code doing something, like handling an unknown response and converting to 90 00.

There are also ways to look at the card to reader interface to see what is going on. I have never tried this.

There may be some timing problem
Do you have an other reader to try?

@Jakuje
Copy link
Member Author

Jakuje commented Jan 18, 2017

I have got also "SCM Microsystems Inc. SCR 3310", but it reports "Unresponsive card" for Coolkey card (works fine with PIV Test cards).

Try adding a sleep(1) in reader-pcsc.c after sc_log(ctx, "card inserted event"); This is for debugging,
but should give the card and reader plenty of time to get ready. If that works, we cold find a better place to put this.

Yes, this "solves" the problem and I am getting the events correctly. The card obviously needs some time. Now there is the question how to solve that generally in OpenSC. I will dig in the pcscd and post the logs, if there will be something suspicious.

@Jakuje
Copy link
Member Author

Jakuje commented Jan 18, 2017

pcsc in debug mode shows the same APDU being send and received (mcrd):

00000002 winscard_svc.c:559:ContextThread() BEGIN_TRANSACTION rv=0x0 for client 16
00000119 winscard_svc.c:359:ContextThread() Received command: TRANSMIT from client 16
00000009 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
00000002 winscard.c:1605:SCardTransmit() Send Protocol: T=1
00000005 APDU: 00 A4 04 00 0F D2 33 00 00 00 45 73 74 45 49 44 20 76 33 35 
00000003 ifdhandler.c:1303:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/002/034 (lun: 0)
00012623 SW: 90 00 
00000015 winscard.c:1650:SCardTransmit() UnrefReader() count was: 2
00000004 winscard_svc.c:672:ContextThread() TRANSMIT rv=0x0 for client 16
00000078 winscard_svc.c:359:ContextThread() Received command: END_TRANSACTION from client 16
00000010 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
00000005 winscard.c:1244:SCardEndTransaction() Status: 0x00000000
00000002 winscard.c:1247:SCardEndTransaction() UnrefReader() count was: 2
00000003 winscard_svc.c:575:ContextThread() END_TRANSACTION rv=0x0 for client 16
00000002 winscard_svc.c:559:ContextThread() BEGIN_TRANSACTION rv=0x0 for client 16
00000035 winscard_svc.c:359:ContextThread() Received command: TRANSMIT from client 16
00000009 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
00000002 winscard.c:1605:SCardTransmit() Send Protocol: T=1
00000005 APDU: 00 A4 04 00 0F D2 33 00 00 00 45 73 74 45 49 44 20 76 33 35 
00000003 ifdhandler.c:1303:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/002/034 (lun: 0)
00006469 SW: 6A 82 
00000012 winscard.c:1650:SCardTransmit() UnrefReader() count was: 2
00000003 winscard_svc.c:672:ContextThread() TRANSMIT rv=0x0 for client 16
00000062 winscard_svc.c:359:ContextThread() Received command: END_TRANSACTION from client 16
00000007 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
00000003 winscard.c:1244:SCardEndTransaction() Status: 0x00000000
00000001 winscard.c:1247:SCardEndTransaction() UnrefReader() count was: 2
00000002 winscard_svc.c:575:ContextThread() END_TRANSACTION rv=0x0 for client 16

Not sure about the USB trace and how to get that. Is it still needed?

@dengert
Copy link
Member

dengert commented Jan 18, 2017

Probably not, but keep it in mind.

Is this a new card? Since it runs at 3V and required changes to pcsc it appears to be newer then any of the other cards supported by OpenSC.

Are you working with the manufacture of the card?
Do they have any insight in to this problem?

Do you have any manual on the card?
Is it a GlobalPlatform or Java Card?
These might give some insight into the problem.

What version of the coolkey applet is loaded on the card?
Could it have a bug to not respond correctly while starting up?

@dengert
Copy link
Member

dengert commented Jan 18, 2017

Any developers have a muscle card that could test with the C_WaitForEvent?
It may have the same problem as in this issue.

While looking for source code for the coolkey applet, I found this. It reports it is from Redhat
and the code is based on the muscle card applet:
http://github.com/elmarco/coolkey
In: applet/src/com/redhat/ckey/applet/CardEdge.java

3010 // **** Most processing starts here!!
3011 //
3012 public void process(APDU apdu)
3013 {
3014 if (selectingApplet())
3015 ISOException.throwIt(ISO7816.SW_NO_ERROR);
3016

The way I read this, if a command is received before the applet is selected , 90 00 is returned
This is exactly what we are seeing.

@dengert
Copy link
Member

dengert commented Jan 18, 2017

Looking further, selectingApplet ():
"This method is used by the applet process() method to distinguish the SELECT APDU command that selected this applet from all other SELECT APDU APDU commands that may relate to file or internal applet state selection."
So the above is not the issue. But if a Muscle card also has the same issue, it may still be in the applet or timing problem wit the card.

@frankmorgner
Copy link
Member

Ignoring the crappy implementation of hardware and software that we build on, could you try solving the problem in software? Above I suggested to return SC_ERROR_INVALID_CARD to continue the card detection. Did you try that?

diff --git a/src/libopensc/card-mcrd.c b/src/libopensc/card-mcrd.c
index dd456cef..746a79aa 100644
--- a/src/libopensc/card-mcrd.c
+++ b/src/libopensc/card-mcrd.c
@@ -362,7 +362,7 @@ static int mcrd_init(sc_card_t * card)
                                        SC_TEST_RET(card->ctx, SC_LOG_DEBUG_NORMAL, r, "APDU transmit failed");
                                        sc_debug(card->ctx, SC_LOG_DEBUG_VERBOSE, "SELECT AID: %02X%02X", apdu.sw1, apdu.sw2);
                                        if (apdu.sw1 != 0x90 && apdu.sw2 != 0x00)
-                                               SC_FUNC_RETURN(card->ctx, SC_LOG_DEBUG_VERBOSE,  SC_ERROR_CARD_CMD_FAILED);
+                                               SC_FUNC_RETURN(card->ctx, SC_LOG_DEBUG_VERBOSE,  SC_ERROR_INVALID_CARD);
                                }
                        }
                } else {

@Jakuje
Copy link
Member Author

Jakuje commented Jan 19, 2017

@frankmorgner sorry, I somehow missed your comment earlier. Such change was something I had in my mind since the start and it is certainly solving the problem (at least when tested with card_drivers = mcrd, coolkey;). Would this change could break anything/make a difference somewhere else?

@Jakuje
Copy link
Member Author

Jakuje commented Jan 19, 2017

hmm ... weird. Just build OpenSC again and I am not getting the matches of mcrd with the same card, driver, USB port, computer everything even with the old OpenSC without further modifications even though it was perfectly reproducible yesterday (per logs above). No idea what settled down and made it working (restarting pcscd?). I will give it some more testing tomorrow.

@dengert
Copy link
Member

dengert commented Jan 19, 2017

It could still be a timing problem. You referred to changes to the CCID to get the below 3V card to work. Pcscd loads CCID, so restarting pcscd it could make a difference. What version of each are you using?

Based on the comments above, if Redhat is issuing cards, there may be a lot of them and this could become a big problem.

@frankmorgner returning SC_ERROR_CARD_CMD_FAILED from ops->init would work, but ops->init() can allocate and change card structure expecting ops->finish to be called to clean up. (Unlike ops->match_card which is expected to do its own cleanup.)

We need to address memory leaks. One way is to make sure every card's init cleans up on error, or
We should also add a call to ops->finish in card.c after test for SC_ERROR_INVALID_CARD and check if their finish routine can handle being called after a failed init.

We should also look at every card driver that may fail in init to see if they should return SC_ERROR_INVALID_CARD.

The mcrd was the first card that had this problem, muscle (and others) may also fail with this problem and may even make it through init without failing! So we really need to find out why his environment or his card or reader are failing.

@dengert
Copy link
Member

dengert commented Jan 19, 2017

@Jakuje "weird. Just build OpenSC again" was that with the sleep(1) test or not?

@Jakuje
Copy link
Member Author

Jakuje commented Jan 20, 2017

What version of each are you using?

These should be latest Fedora 25 versions:

pcsc-lite-1.8.20-1.fc25.x86_64
pcsc-lite-ccid-1.4.26-1.fc25.x86_64

Today I can reproduce the issue again so back to the questions:

@frankmorgner As @dengert pointed out, returning SC_ERROR_INVALID_CARD from MCRD creates inconsistent state and coolkey segfaults because of this.

Sorry for the noise. Now it looks like even the sleep(5) does not change it and fails the same way.

To the CoolKey code, the part is the same as in the Muscle and it is considered as a good practice to do something like that (also most of the Java cards I saw look like do something like this):

if (selectingApplet())
    ISOException.throwIt(ISO7816.SW_NO_ERROR);

It is probably answering 9000 to all select APDU, which quite prevents to distinguish them by this call (if I got that right). But how does it happen it returns 6A 82 (SW_FILE_NOT_FOUND), when used from opensc-tool --serial and without the C_WaitForSlotEvent?

@frankmorgner
Copy link
Member

I don't see mcrd_match_card or mcrd_init exiting with an inconsistent state, nor do I see it exiting with dangeling pointers. If I was you, I'd still try to continue card detaction and fix this within OpenSC by tracking down the segfault, but I can't reproduce the problem.

@Jakuje
Copy link
Member Author

Jakuje commented Jan 20, 2017

Well ... I was running with all the drivers, but when there is mcrd it leaves behind allocated card->drv_data which makes coolkey skip initialization (maybe not correctly) of this structure and therefore accessing NULL pointers for SCLists and so. Adding before the return from mcrd card makes it working again:

free(card->drv_data);
card->drv_data = NULL;

@dengert
Copy link
Member

dengert commented Jan 20, 2017

I misinterpreted the selectingApplet in my first comment. It is true when Java tells the applet it has been selected based on the registered AID the applet provided. So that is not the real problem which could still could be a problem with the card/reader or pcscd.

mcrd should clean up, but that is only caused because the card/reader/pcscd returned 90 00 to a request to select the mcrd AID. So the real problem is why was 90 00 returned.

I can not reproduce the problem. Do you have some non Redhat system to try this on?
I. e. eliminate the Redhat environment and its version of pcsc and any other libs involved.

Do you have some other card that does not fail? I believe you said you have PIV and mcrd does not fail it does not fail. So this points at the card or pcsc when using the card.

Any other reader to try?

Jakuje added a commit to Jakuje/OpenSC that referenced this issue Jan 23, 2017
@Jakuje
Copy link
Member Author

Jakuje commented Jan 23, 2017

Just tested with my Ubuntu 16.10, but it has ancient pcscd-1.8.14-1ubuntu1 and libccid-1.4.24-1, and does not recognize the card.

Manual change in /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist (as described in previously mentioned bug) makes the detection working and also the C_WaitForSlotEvent works as expected with OpenSC master, the same card and same reader.

I don't have any other reader around here to try. I created PR #945 with the changes we came with so far.

@LudovicRousseau do you have overview what could have changed in pcsc-lite* since Ubuntu versions? Fedora have pcsc-lite-ccid-1.4.26-1.fc25.x86_64 and pcsc-lite-1.8.20-1.fc25.x86_64. I will try to downgrade on my Fedora to see if it is really related to these new versions.

@LudovicRousseau
Copy link
Member

CCID version 1.4.26 changed the voltage used to power a card.
See https://ludovicrousseau.blogspot.fr/2017/01/new-version-of-libccid-1426.html

RedHat had issues with voltage and Coolkey cards and had already their own patch.

@Jakuje
Copy link
Member Author

Jakuje commented Jan 23, 2017

The downgrade to "Ubuntu" versions didn't change anything (nor the change of ifdDriverOptions to 0x0020. If I see right, we don't have any downstream patches in the above two packages, so the versions should not matter, but the problem will be somewhere else ...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants