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

ECC and SHA-2 support in OpenSC.tokend #570

Closed
mouse07410 opened this issue Oct 2, 2015 · 143 comments
Closed

ECC and SHA-2 support in OpenSC.tokend #570

mouse07410 opened this issue Oct 2, 2015 · 143 comments

Comments

@mouse07410
Copy link
Contributor

Using the current/latest OpenSC.tokend from Github, and RSA-2048 keys/certs on the latest NEO (PIV applet 0.1.3). And a current-issue CAC.

All the OpenSC utilities seem to work fine, and as expected. The only problem is with OpenSC.tokend. It is unable to unlock the card, though

  1. when tokend sends the Unlock command (with the PIN), the card returns Success, and
  2. tokend seems to be able to retrieve certificates correctly, as evidenced by Keychain Access and Thunderbird applications that see those certificates.

I assume the successful unlock is not communicated because (a) Keychain Access does not change the card status from "locked" to "unlocked" upon receiving the correct PIN, and (b) Thunderbird keeps asking for the PIN over and over again - as if the unlock fails.

OpenSC.tokend also seems to fail to read the ATR to determine the correct card type, based on these entries in the opensc-debug.log (log shows both CAC on SCR3310 reader, and Yubikey NEO that is its own reader):

0x7fff7e07b300 14:31:32.140733193388825 [tokend] reader-pcsc.c:288:refresh_attributes: Yubico Yubikey NEO OTP+
U2F+CCID check
0x7fff7e07b300 14:31:32.140733193388826 [tokend] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x7fff7e07b300 14:31:32.140733193388827 [tokend] reader-pcsc.c:487:pcsc_connect: Initial protocol: T=1
0x7fff7e07b300 14:31:32.795 [tokend] card.c:965:match_atr_table: ATR : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
0x7fff7e07b300 14:31:32.795 [tokend] card.c:976:match_atr_table: ATR try : 3B:DD:18:00:81:31:FE:45:80:F9:A0:00:00:00:77:01:00:70:0A:90:00:8B
0x7fff7e07b300 14:31:32.795 [tokend] card.c:965:match_atr_table: ATR : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
0x7fff7e07b300 14:31:32.795 [tokend] card.c:976:match_atr_table: ATR try : 3B:7F:96:00:00:00:31:B9:64:40:70:14:10:73:94:01:80:82:90:00
0x7fff7e07b300 14:31:32.795 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:31:32.795 [tokend] card.c:976:match_atr_table: ATR try : 3B:7F:96:00:00:00:31:B8:64:40:70:14:10:73:94:01:80:82:90:00
0x7fff7e07b300 14:31:32.795 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:31:32.795 [tokend] card.c:976:match_atr_table: ATR try : 3B:DF:18:FF:81:91:FE:1F:C3:00:31:B8:64:0C:01:EC:C1:73:94:01:80:82:90:00:B3
0x7fff7e07b300 14:31:32.795 [tokend] card.c:979:match_atr_table: ignored - wrong length
........
0x7fff7e07b300 14:57:56.140733193388121 [tokend] card.c:976:match_atr_table: ATR try : 3B:DC:18:FF:81:91:FE:1F:C3:80:73:C8:21:13:66:01:0B:03:52:00:05:38
0x7fff7e07b300 14:57:56.140733193388121 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:57:56.140432545677401 [tokend] card.c:226:sc_connect_card: trying driver 'piv'
0x7fff7e07b300 14:57:56.140733193388121 [tokend] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:57:56.140733193388121 [tokend] card.c:976:match_atr_table: ATR try : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:57:56.140432545677401 [tokend] card.c:231:sc_connect_card: matched driver 'PIV-II  for multiple cards'
0x7fff7e07b300 14:57:56.089 [tokend] card-piv.c:2842:piv_match_card: called
0x7fff7e07b300 14:57:56.140733193388121 [tokend] card-piv.c:720:piv_find_aid: called
0x7fff7e07b300 14:57:56.4294967385 [tokend] card-piv.c:683:piv_select_aid: called
0x7fff7e07b300 14:57:56.4294967385 [tokend] card-piv.c:686:piv_select_aid: Got args: aid=23e5524, aidlen=9, response=5da90000, responselen=261
0x7fff7e07b300 14:57:56.140733193388121 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:57:56.089 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:57:56.317106025398361 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 14:57:56.4294967385 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:57:56.140733193388121 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:57:56.140733193388121 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(9) 0x1023e5524
0x7fff7e07b300 14:57:56.317106025398361 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:57:56.140733193388121 [tokend] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   14 bytes] =====================================
00 A4 04 00 09 A0 00 00 03 08 00 00 10 00 ..............
======================================================================
0x7fff7e07b300 14:57:56.140733193388121 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:57:56.4294967469 [tokend] apdu.c:187:sc_apdu_log: 
Incoming APDU data [    2 bytes] =====================================
61 18 a.
.......
0x7fff7e07b300 15:45:26.4294968133 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
6A 80 j.
======================================================================
0x7fff7e07b300 15:45:26.140733193388869 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 15:45:26.120259085125 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 15:45:26.-4294966459 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 15:45:26.140243567117125 [tokend] card-piv.c:496:piv_general_io: DEE r=0 apdu.resplen=0 sw1=6a sw2=80
0x7fff7e07b300 15:45:26.317106025399109 [tokend] iso7816.c:121:iso7816_check_sw: Incorrect parameters in the data field
0x7fff7e07b300 15:45:26.140243567117125 [tokend] card-piv.c:508:piv_general_io: Card returned error
0x7fff7e07b300 15:45:26.140733193388869 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 15:45:26.837 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 15:45:26.837 [tokend] card-piv.c:558:piv_general_io: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 15:45:26.4294968133 [tokend] card-piv.c:933:piv_get_data: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 15:45:26.4294968133 [tokend] card-piv.c:1014:piv_get_cached_data: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 15:45:26.140243567117125 [tokend] card-piv.c:2576:piv_process_discovery: returning with: 0 (Success)
0x7fff7e07b300 15:45:26.140243567117125 [tokend] card-piv.c:2919:piv_init: returning with: 0 (Success)
......

I have the entire log, but Github refuses to attach it. Will happily email or post anywhere you can use it.

Here are the keys:

$ pkcs15-tool -k
Using reader with a card: Yubico Yubikey NEO OTP+U2F+CCID
Private RSA Key [PIV AUTH key]
Object Flags : [0x1], private
Usage : [0x2E], decrypt, sign, signRecover, unwrap
Access Flags : [0x1D], sensitive, alwaysSensitive, neverExtract, local
ModLength : 2048
Key ref : 154 (0x9A)
Native : yes
Auth ID : 01
ID : 01
MD:guid : 0x'30...000000'
:cmap flags : 0x0
:sign : 0
:key-exchange: 0

Private RSA Key [SIGN key]
Object Flags : [0x1], private
Usage : [0x20E], decrypt, sign, signRecover, nonRepudiation
Access Flags : [0x1D], sensitive, alwaysSensitive, neverExtract, local
ModLength : 2048
Key ref : 156 (0x9C)
Native : yes
Auth ID : 01
ID : 02
MD:guid : 0x'30...000000'
:cmap flags : 0x0
:sign : 0
:key-exchange: 0

Private RSA Key [KEY MAN key]
Object Flags : [0x1], private
Usage : [0x22], decrypt, unwrap
Access Flags : [0x1D], sensitive, alwaysSensitive, neverExtract, local
ModLength : 2048
Key ref : 157 (0x9D)
Native : yes
Auth ID : 01
ID : 03
MD:guid : 0x'30...000000'
:cmap flags : 0x0
:sign : 0
:key-exchange: 0

Private RSA Key [CARD AUTH key]
Object Flags : [0x0]
Usage : [0xC], sign, signRecover
Access Flags : [0x1D], sensitive, alwaysSensitive, neverExtract, local
ModLength : 2048
Key ref : 158 (0x9E)
Native : yes
ID : 04
MD:guid : 0x'30...0000000'
:cmap flags : 0x0
:sign : 0
:key-exchange: 0
@frankmorgner
Copy link
Member

@mouse07410 you could use gist or pastebin for the log. Please use backticks when pasting code.

The Neo's card drivers have received some updates recently. Are you testing with the most recent version? What version is your OS?

@dengert
Copy link
Member

dengert commented Oct 2, 2015

A full log would help, can you post it somewhere, or send to me at deengert at gmail dot com.

This looks normal, but uits not teh full log. OpenSC tries to match a card by ATR then will try other drivers that do I/O to the card.
The PIV driver reads the AID for the PIV applet, not the ATR. It found the AID was a PIV card.

The 6A 80 is a little strange. it looked like the PIV driver was trying to read
the Discovery Object, which is optional and the NEO may be returning the wrong return code.
But its optional, and so
card-piv.c:2576:piv_process_discovery: returning with: 0 (Success)
card-piv.c:2919:piv_init: returning with: 0 (Success)

What version of the NEO do you have?

On 10/2/2015 9:00 AM, Mouse wrote:

Using the current/latest OpenSC.tokend from Github, and RSA-2048 keys/certs on the latest NEO (PIV applet 0.1.3). And a current-issue CAC.

All the OpenSC utilities seem to work fine, and as expected. The only problem is with OpenSC.tokend. It is unable to unlock the card, though

  1. when tokend sends the Unlock command (with the PIN), the card returns Success, and
  2. tokend seems to be able to retrieve certificates correctly, as evidenced by Keychain Access and Thunderbird applications that see those certificates.

I assume the successful unlock is not communicated because (a) Keychain Access does not change the card status from "locked" to "unlocked" upon receiving the correct PIN, and (b) Thunderbird keeps
asking for the PIN over and over again - as if the unlock fails.

OpenSC.tokend also seems to fail to read the ATR to determine the correct card type, based on these entries in the opensc-debug.log (log shows both CAC on SCR3310 reader, and Yubikey NEO that is its
own reader):

0x7fff7e07b300 14:31:32.140733193388825 [tokend] reader-pcsc.c:288:refresh_attributes: Yubico Yubikey NEO OTP+
U2F+CCID check
0x7fff7e07b300 14:31:32.140733193388826 [tokend] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x7fff7e07b300 14:31:32.140733193388827 [tokend] reader-pcsc.c:487:pcsc_connect: Initial protocol: T=1
0x7fff7e07b300 14:31:32.795 [tokend] card.c:965:match_atr_table: ATR : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
0x7fff7e07b300 14:31:32.795 [tokend] card.c:976:match_atr_table: ATR try : 3B:DD:18:00:81:31:FE:45:80:F9:A0:00:00:00:77:01:00:70:0A:90:00:8B
0x7fff7e07b300 14:31:32.795 [tokend] card.c:965:match_atr_table: ATR : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
0x7fff7e07b300 14:31:32.795 [tokend] card.c:976:match_atr_table: ATR try : 3B:7F:96:00:00:00:31:B9:64:40:70:14:10:73:94:01:80:82:90:00
0x7fff7e07b300 14:31:32.795 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:31:32.795 [tokend] card.c:976:match_atr_table: ATR try : 3B:7F:96:00:00:00:31:B8:64:40:70:14:10:73:94:01:80:82:90:00
0x7fff7e07b300 14:31:32.795 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:31:32.795 [tokend] card.c:976:match_atr_table: ATR try : 3B:DF:18:FF:81:91:FE:1F:C3:00:31:B8:64:0C:01:EC:C1:73:94:01:80:82:90:00:B3
0x7fff7e07b300 14:31:32.795 [tokend] card.c:979:match_atr_table: ignored - wrong length
........
0x7fff7e07b300 14:57:56.140733193388121 [tokend] card.c:976:match_atr_table: ATR try : 3B:DC:18:FF:81:91:FE:1F:C3:80:73:C8:21:13:66:01:0B:03:52:00:05:38
0x7fff7e07b300 14:57:56.140733193388121 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:57:56.140432545677401 [tokend] card.c:226:sc_connect_card: trying driver 'piv'
0x7fff7e07b300 14:57:56.140733193388121 [tokend] card.c:965:match_atr_table: ATR : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:57:56.140733193388121 [tokend] card.c:976:match_atr_table: ATR try : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:57:56.140432545677401 [tokend] card.c:231:sc_connect_card: matched driver 'PIV-II for multiple cards'
0x7fff7e07b300 14:57:56.089 [tokend] card-piv.c:2842:piv_match_card: called
0x7fff7e07b300 14:57:56.140733193388121 [tokend] card-piv.c:720:piv_find_aid: called
0x7fff7e07b300 14:57:56.4294967385 [tokend] card-piv.c:683:piv_select_aid: called
0x7fff7e07b300 14:57:56.4294967385 [tokend] card-piv.c:686:piv_select_aid: Got args: aid=23e5524, aidlen=9, response=5da90000, responselen=261
0x7fff7e07b300 14:57:56.140733193388121 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:57:56.089 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:57:56.317106025398361 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 14:57:56.4294967385 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:57:56.140733193388121 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:57:56.140733193388121 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(9) 0x1023e5524
0x7fff7e07b300 14:57:56.317106025398361 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:57:56.140733193388121 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [ 14 bytes] =====================================

00 A4 04 00 09 A0 00 00 03 08 00 00 10 00 ..............

0x7fff7e07b300 14:57:56.140733193388121 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:57:56.4294967469 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================
61 18 a.
.......
0x7fff7e07b300 15:45:26.4294968133 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================

6A 80 j.

0x7fff7e07b300 15:45:26.140733193388869 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 15:45:26.120259085125 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 15:45:26.-4294966459 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 15:45:26.140243567117125 [tokend] card-piv.c:496:piv_general_io: DEE r=0 apdu.resplen=0 sw1=6a sw2=80
0x7fff7e07b300 15:45:26.317106025399109 [tokend] iso7816.c:121:iso7816_check_sw: Incorrect parameters in the data field
0x7fff7e07b300 15:45:26.140243567117125 [tokend] card-piv.c:508:piv_general_io: Card returned error
0x7fff7e07b300 15:45:26.140733193388869 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 15:45:26.837 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 15:45:26.837 [tokend] card-piv.c:558:piv_general_io: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 15:45:26.4294968133 [tokend] card-piv.c:933:piv_get_data: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 15:45:26.4294968133 [tokend] card-piv.c:1014:piv_get_cached_data: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 15:45:26.140243567117125 [tokend] card-piv.c:2576:piv_process_discovery: returning with: 0 (Success)
0x7fff7e07b300 15:45:26.140243567117125 [tokend] card-piv.c:2919:piv_init: returning with: 0 (Success)
......

I have the entire log, but Github refuses to attach it. Will happily email or post anywhere you can use it.

Here are the keys:

$ pkcs15-tool -k
Using reader with a card: Yubico Yubikey NEO OTP+U2F+CCID
Private RSA Key [PIV AUTH key]
Object Flags : [0x1], private
Usage : [0x2E], decrypt, sign, signRecover, unwrap
Access Flags : [0x1D], sensitive, alwaysSensitive, neverExtract, local
ModLength : 2048
Key ref : 154 (0x9A)
Native : yes
Auth ID : 01
ID : 01
MD:guid : 0x'30...000000'
:cmap flags : 0x0
:sign : 0
:key-exchange: 0

Private RSA Key [SIGN key]
Object Flags : [0x1], private
Usage : [0x20E], decrypt, sign, signRecover, nonRepudiation
Access Flags : [0x1D], sensitive, alwaysSensitive, neverExtract, local
ModLength : 2048
Key ref : 156 (0x9C)
Native : yes
Auth ID : 01
ID : 02
MD:guid : 0x'30...000000'
:cmap flags : 0x0
:sign : 0
:key-exchange: 0

Private RSA Key [KEY MAN key]
Object Flags : [0x1], private
Usage : [0x22], decrypt, unwrap
Access Flags : [0x1D], sensitive, alwaysSensitive, neverExtract, local
ModLength : 2048
Key ref : 157 (0x9D)
Native : yes
Auth ID : 01
ID : 03
MD:guid : 0x'30...000000'
:cmap flags : 0x0
:sign : 0
:key-exchange: 0

Private RSA Key [CARD AUTH key]
Object Flags : [0x0]
Usage : [0xC], sign, signRecover
Access Flags : [0x1D], sensitive, alwaysSensitive, neverExtract, local
ModLength : 2048
Key ref : 158 (0x9E)
Native : yes
ID : 04
MD:guid : 0x'30...0000000'
:cmap flags : 0x0
:sign : 0
:key-exchange: 0


Reply to this email directly or view it on GitHub #570.

Douglas E. Engert [email protected]

@mouse07410
Copy link
Contributor Author

  1. Yes I'm testing on the latest/most recent version of what's in Github.
  2. This all is on Mac OS X Yosemite 10.10.5 with Xcode-7.0.
  3. No access to gist or pastebin from work. :-(

Will report more, and send a complete log to @dengert.

@mouse07410
Copy link
Contributor Author

Also, it looks like when opensc-pkcs11.so library is used as PKCS#11 interface for Thunderbird, something (Thunderbird probably) gets into infinite loop even before the user is prompted for a PIN, as indicated by application frozen and the log growing continuously with repeated records:

......
0x111aaf000 12:19:03.381 [opensc-pkcs11] card.c:394:sc_lock: called
0x111aaf000 12:19:03.140733193388413 [opensc-pkcs11] apdu.c:530:sc_transmit: called
0x111aaf000 12:19:03.140733193388413 [opensc-pkcs11] apdu.c:384:sc_single_transmit: called
0x111aaf000 12:19:03.140733193388413 [opensc-pkcs11] apdu.c:389:sc_single_transmit: CLA:0, INS:87, P1:0, P2:9B, data(4) 0x111aae9f0
0x111aaf000 12:19:03.317106025398653 [opensc-pkcs11] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x111aaf000 12:19:03.140733193388413 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   10 bytes] =====================================
00 87 00 9B 04 7C 02 81 00 00 .....|....
======================================================================
0x111aaf000 12:19:03.140733193388413 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x111aaf000 12:19:03.4294967696 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Incoming APDU data [   14 bytes] =====================================
7C 0A 81 08 9B E2 A6 03 F0 6F 44 76 90 00 |........oDv..
======================================================================
0x111aaf000 12:19:03.4294967696 [opensc-pkcs11] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x111aaf000 12:19:03.120259084688 [opensc-pkcs11] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x111aaf000 12:19:03.-4294966896 [opensc-pkcs11] card.c:434:sc_unlock: called
0x111aaf000 12:19:03.4294967696 [opensc-pkcs11] card-piv.c:496:piv_general_io: DEE r=0 apdu.resplen=12 sw1=90 sw2=00
0x111aaf000 12:19:03.4294967696 [opensc-pkcs11] card-piv.c:541:piv_general_io: DEE got buffer 0x127cb2660 len 12
0x111aaf000 12:19:03.140733193388432 [opensc-pkcs11] card.c:434:sc_unlock: called
0x111aaf000 12:19:03.4294967696 [opensc-pkcs11] card-piv.c:558:piv_general_io: returning with: 12
0x111aaf000 12:19:03.4294967696 [opensc-pkcs11] card-piv.c:447:piv_general_io: called
0x111aaf000 12:19:03.4294967696 [opensc-pkcs11] card-piv.c:450:piv_general_io: 87 00 9b 4 : 255 256
0x111aaf000 12:19:03.400 [opensc-pkcs11] card.c:394:sc_lock: called
0x111aaf000 12:19:03.400 [opensc-pkcs11] card-piv.c:490:piv_general_io: calling sc_transmit_apdu flags=1 le=256, resplen=4096, resp=0x111aad870
0x111aaf000 12:19:03.4294967696 [opensc-pkcs11] apdu.c:563:sc_transmit_apdu: called
0x111aaf000 12:19:03.400 [opensc-pkcs11] card.c:394:sc_lock: called
0x111aaf000 12:19:03.140733193388432 [opensc-pkcs11] apdu.c:530:sc_transmit: called
0x111aaf000 12:19:03.140733193388432 [opensc-pkcs11] apdu.c:384:sc_single_transmit: called
0x111aaf000 12:19:03.140733193388432 [opensc-pkcs11] apdu.c:389:sc_single_transmit: CLA:0, INS:87, P1:0, P2:9B, data(4) 0x111aae9f0
0x111aaf000 12:19:03.317106025398672 [opensc-pkcs11] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x111aaf000 12:19:03.140733193388432 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   10 bytes] =====================================
00 87 00 9B 04 7C 02 81 00 00 .....|....
======================================================================
0x111aaf000 12:19:03.140733193388432 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x111aaf000 12:19:03.140733193388441 [opensc-pkcs11] reader-pcsc.c:213:pcsc_internal_transmit: Yubico Yubikey NEO OTP+U2F+CCID:SCardTransmit/Control failed: 0x180100016
0x111aaf000 12:19:03.317106025398681 [opensc-pkcs11] reader-pcsc.c:378:pcsc_detect_card_presence: called
0x111aaf000 12:19:03.4294967705 [opensc-pkcs11] reader-pcsc.c:288:refresh_attributes: Yubico Yubikey NEO OTP+U2F+CCID check
0x111aaf000 12:19:03.4294967706 [opensc-pkcs11] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x111aaf000 12:19:03.4294967706 [opensc-pkcs11] reader-pcsc.c:383:pcsc_detect_card_presence: returning with: 5
0x111aaf000 12:19:03.4294967706 [opensc-pkcs11] reader-pcsc.c:378:pcsc_detect_card_presence: called
0x111aaf000 12:19:03.4294967706 [opensc-pkcs11] reader-pcsc.c:288:refresh_attributes: Yubico Yubikey NEO OTP+U2F+CCID check
0x111aaf000 12:19:03.4294967707 [opensc-pkcs11] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x111aaf000 12:19:03.4294967707 [opensc-pkcs11] reader-pcsc.c:383:pcsc_detect_card_presence: returning with: 5
0x111aaf000 12:19:03.4294967707 [opensc-pkcs11] reader-pcsc.c:261:pcsc_transmit: unable to transmit
0x111aaf000 12:19:03.411 [opensc-pkcs11] apdu.c:397:sc_single_transmit: unable to transmit APDU: -1107 (Transmit failed)
0x111aaf000 12:19:03.210453397915 [opensc-pkcs11] apdu.c:533:sc_transmit: transmit APDU failed: -1107 (Transmit failed)
0x111aaf000 12:19:03.-4294966885 [opensc-pkcs11] card.c:434:sc_unlock: called
0x111aaf000 12:19:03.4294967707 [opensc-pkcs11] card-piv.c:496:piv_general_io: DEE r=-1107 apdu.resplen=4096 sw1=00 sw2=00
0x111aaf000 12:19:03.4294967707 [opensc-pkcs11] card-piv.c:498:piv_general_io: Transmit failed
0x111aaf000 12:19:03.140733193388443 [opensc-pkcs11] card.c:434:sc_unlock: called
0x111aaf000 12:19:03.4294967707 [opensc-pkcs11] card-piv.c:558:piv_general_io: returning with: -1107 (Transmit failed)
0x111aaf000 12:19:03.4294967707 [opensc-pkcs11] card.c:434:sc_unlock: called
0x111aaf000 12:19:03.411 [opensc-pkcs11] reader-pcsc.c:566:pcsc_unlock: called
0x111aaf000 12:19:03.411 [opensc-pkcs11] card-piv.c:2186:piv_get_challenge: returning with: -1107 (Transmit failed)
0x111aaf000 12:19:03.2925134721581467 [opensc-pkcs11] card.c:760:sc_get_challenge: returning with: -1107 (Transmit failed)
0x111aaf000 12:19:03.140733193388443 [opensc-pkcs11] misc.c:61:sc_to_cryptoki_error_common: libopensc return value: -1107 (Transmit failed)
0x111aaf000 12:19:03.7453005947875623324 [opensc-pkcs11] pkcs11-object.c:336:C_FindObjectsInit: C_FindObjectsInit(slot = 1)
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] pkcs11-object.c:337:C_FindObjectsInit: C_FindObjectsInit(): CKA_CLASS = 0xce534354
0x111aaf000 12:19:03.412 [opensc-pkcs11] misc.c:139:session_start_operation: called
0x111aaf000 12:19:03.412 [opensc-pkcs11] misc.c:140:session_start_operation: Session 0x12b718b80, type 0
0x111aaf000 12:19:03.-4294966884 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10860f400
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3325:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x111aaf000 12:19:03.7163942970838745500 [opensc-pkcs11] pkcs11-object.c:366:C_FindObjectsInit: Object 1/140571648: Private object and not logged in.
0x111aaf000 12:19:03.7163942970838745500 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10860f940
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.7091324930813329820 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/140572992: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.7091324930813329820 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10b1144c0
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3228:pkcs15_cert_cmp_attribute: pkcs15_cert_cmp_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.-4294966884 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/185681088: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.-4294966884 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10860f580
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3325:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x111aaf000 12:19:03.7163942970838745500 [opensc-pkcs11] pkcs11-object.c:366:C_FindObjectsInit: Object 1/140572032: Private object and not logged in.
0x111aaf000 12:19:03.7163942970838745500 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10860fa00
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.7091324930813329820 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/140573184: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.7091324930813329820 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10b114820
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3228:pkcs15_cert_cmp_attribute: pkcs15_cert_cmp_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.-4294966884 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/185681952: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.-4294966884 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10860f640
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3325:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x111aaf000 12:19:03.7163942970838745500 [opensc-pkcs11] pkcs11-object.c:366:C_FindObjectsInit: Object 1/140572224: Private object and not logged in.
0x111aaf000 12:19:03.7163942970838745500 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10860fb20
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.7091324930813329820 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/140573472: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.7091324930813329820 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10b1b1340
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3228:pkcs15_cert_cmp_attribute: pkcs15_cert_cmp_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.-4294966884 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/186323776: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.-4294966884 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c2e0
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:366:C_FindObjectsInit: Object 1/216122080: Private object and not logged in.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c340
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:366:C_FindObjectsInit: Object 1/216122176: Private object and not logged in.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c3a0
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:366:C_FindObjectsInit: Object 1/216122272: Private object and not logged in.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10860f7c0
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3325:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3325:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3325:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x111aaf000 12:19:03.7163942970838745500 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/140572608: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.7163942970838745500 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10860fb80
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x111aaf000 12:19:03.7091324930813329820 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/140573568: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.7091324930813329820 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10b540fa0
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3228:pkcs15_cert_cmp_attribute: pkcs15_cert_cmp_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.412 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x111aaf000 12:19:03.-4294966884 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/190058400: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.-4294966884 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c0a0
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/216121504: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c100
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/216121600: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c160
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/216121696: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c1c0
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/216121792: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c400
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/216122368: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c460
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/216122464: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c520
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/216122656: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c580
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/216122752: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10ce1c6a0
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.140733193388444 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/216123040: Attribute 0x0 does NOT match.
0x111aaf000 12:19:03.4294967708 [opensc-pkcs11] pkcs11-object.c:406:C_FindObjectsInit: 0 matching objects
0x111aaf000 12:19:03.412 [opensc-pkcs11] misc.c:161:session_get_operation: called
0x111aaf000 12:19:03.4294967709 [opensc-pkcs11] misc.c:161:session_get_operation: called
0x111aaf000 12:19:03.317106025398685 [opensc-pkcs11] pkcs11-object.c:59:sc_find_release: freeing 0 handles used 0  at 0x0
0x111aaf000 12:19:03.6873740328524841375 [opensc-pkcs11] pkcs11-session.c:161:C_CloseAllSessions: C_CloseAllSessions(0xffffffffffffe44c)
0x111aaf000 12:19:03.4294967711 [opensc-pkcs11] slot.c:392:slot_get_token: Slot(id=0xFFFFFFFFFFFFE44C): get token
0x111aaf000 12:19:03.4294967711 [opensc-pkcs11] pkcs11-global.c:486:C_GetSlotInfo: C_GetSlotInfo(0xffffffffffffe44b)
0x111aaf000 12:19:03.4294967711 [opensc-pkcs11] pkcs11-global.c:489:C_GetSlotInfo: C_GetSlotInfo() get slot rv 0
0x111aaf000 12:19:03.4294967711 [opensc-pkcs11] pkcs11-global.c:516:C_GetSlotInfo: C_GetSlotInfo() flags 0x6
0x111aaf000 12:19:03.4294967711 [opensc-pkcs11] pkcs11-global.c:517:C_GetSlotInfo: C_GetSlotInfo(0xffffffffffffe44b) = CKR_OK
0x111aaf000 12:19:03.322122547615 [opensc-pkcs11] pkcs11-global.c:629:C_WaitForSlotEvent: C_WaitForSlotEvent(block=1)
0x111aaf000 12:19:03.415 [opensc-pkcs11] pkcs11-global.c:382:C_GetSlotList: C_GetSlotList(token=0, plug-n-play)
0x111aaf000 12:19:03.415 [opensc-pkcs11] reader-pcsc.c:1061:pcsc_detect_readers: called
0x111aaf000 12:19:03.415 [opensc-pkcs11] reader-pcsc.c:1075:pcsc_detect_readers: Probing PC/SC readers
0x111aaf000 12:19:03.415 [opensc-pkcs11] reader-pcsc.c:1227:pcsc_detect_readers: returning with: 0 (Success)
0x111aaf000 12:19:03.4294967711 [opensc-pkcs11] slot.c:333:card_detect_all: Detect all cards
0x111aaf000 12:19:03.140733193388447 [opensc-pkcs11] slot.c:197:card_detect: Yubico Yubikey NEO OTP+U2F+CCID: Detecting smart card
0x111aaf000 12:19:03.317106025398687 [opensc-pkcs11] sc.c:251:sc_detect_card_presence: called
0x111aaf000 12:19:03.317106025398687 [opensc-pkcs11] reader-pcsc.c:378:pcsc_detect_card_presence: called
0x111aaf000 12:19:03.4294967711 [opensc-pkcs11] reader-pcsc.c:288:refresh_attributes: Yubico Yubikey NEO OTP+U2F+CCID check
0x111aaf000 12:19:03.4294967712 [opensc-pkcs11] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x111aaf000 12:19:03.4294967712 [opensc-pkcs11] reader-pcsc.c:383:pcsc_detect_card_presence: returning with: 5
0x111aaf000 12:19:03.416 [opensc-pkcs11] sc.c:256:sc_detect_card_presence: returning with: 5
0x111aaf000 12:19:03.416 [opensc-pkcs11] slot.c:323:card_detect: Yubico Yubikey NEO OTP+U2F+CCID: Detection ended
0x111aaf000 12:19:03.4294967712 [opensc-pkcs11] slot.c:352:card_detect_all: All cards detected
0x111aaf000 12:19:03.-4294966880 [opensc-pkcs11] pkcs11-global.c:418:C_GetSlotList: was only a size inquiry (2)
0x111aaf000 12:19:03.-4294966880 [opensc-pkcs11] pkcs11-global.c:382:C_GetSlotList: C_GetSlotList(token=0, refresh)
0x111aaf000 12:19:03.140733193388448 [opensc-pkcs11] slot.c:333:card_detect_all: Detect all cards
0x111aaf000 12:19:03.140733193388448 [opensc-pkcs11] slot.c:197:card_detect: Yubico Yubikey NEO OTP+U2F+CCID: Detecting smart card
0x111aaf000 12:19:03.317106025398688 [opensc-pkcs11] sc.c:251:sc_detect_card_presence: called
0x111aaf000 12:19:03.317106025398688 [opensc-pkcs11] reader-pcsc.c:378:pcsc_detect_card_presence: called
0x111aaf000 12:19:03.4294967712 [opensc-pkcs11] reader-pcsc.c:288:refresh_attributes: Yubico Yubikey NEO OTP+U2F+CCID check
0x111aaf000 12:19:03.4294967713 [opensc-pkcs11] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x111aaf000 12:19:03.4294967713 [opensc-pkcs11] reader-pcsc.c:383:pcsc_detect_card_presence: returning with: 5
0x111aaf000 12:19:03.417 [opensc-pkcs11] sc.c:256:sc_detect_card_presence: returning with: 5
0x111aaf000 12:19:03.417 [opensc-pkcs11] slot.c:323:card_detect: Yubico Yubikey NEO OTP+U2F+CCID: Detection ended
0x111aaf000 12:19:03.4294967713 [opensc-pkcs11] slot.c:352:card_detect_all: All cards detected
0x111aaf000 12:19:03.-4294966879 [opensc-pkcs11] pkcs11-global.c:435:C_GetSlotList: returned 2 slots
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] pkcs11-global.c:486:C_GetSlotInfo: C_GetSlotInfo(0xffffffffffffe44a)
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] pkcs11-global.c:489:C_GetSlotInfo: C_GetSlotInfo() get slot rv 0
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] pkcs11-global.c:516:C_GetSlotInfo: C_GetSlotInfo() flags 0x6
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] pkcs11-global.c:517:C_GetSlotInfo: C_GetSlotInfo(0xffffffffffffe44a) = CKR_OK
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] pkcs11-global.c:486:C_GetSlotInfo: C_GetSlotInfo(0x1)
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] pkcs11-global.c:489:C_GetSlotInfo: C_GetSlotInfo() get slot rv 0
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] pkcs11-global.c:516:C_GetSlotInfo: C_GetSlotInfo() flags 0x7
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] pkcs11-global.c:517:C_GetSlotInfo: C_GetSlotInfo(0x1) = CKR_OK
0x111aaf000 12:19:03.4294967713 [opensc-pkcs11] framework-pkcs15.c:474:C_GetTokenInfo: C_GetTokenInfo(1)
0x111aaf000 12:19:03.417 [opensc-pkcs11] slot.c:392:slot_get_token: Slot(id=0x1): get token
0x111aaf000 12:19:03.417 [opensc-pkcs11] slot.c:410:slot_get_token: Slot-get-token returns OK
0x111aaf000 12:19:03.417 [opensc-pkcs11] framework-pkcs15.c:491:C_GetTokenInfo: C_GetTokenInfo() auth. object 0x1112ff000, token-info flags 0x40D
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] sec.c:159:sc_pin_cmd: called
0x111aaf000 12:19:03.417 [opensc-pkcs11] apdu.c:563:sc_transmit_apdu: called
0x111aaf000 12:19:03.417 [opensc-pkcs11] card.c:394:sc_lock: called
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] reader-pcsc.c:526:pcsc_lock: called
0x111aaf000 12:19:03.4294967713 [opensc-pkcs11] apdu.c:530:sc_transmit: called
0x111aaf000 12:19:03.140733193388449 [opensc-pkcs11] apdu.c:384:sc_single_transmit: called
0x111aaf000 12:19:03.140733193388449 [opensc-pkcs11] apdu.c:389:sc_single_transmit: CLA:0, INS:20, P1:0, P2:80, data(0) 0x111aac590
0x111aaf000 12:19:03.317106025398689 [opensc-pkcs11] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x111aaf000 12:19:03.140733193388449 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [    4 bytes] =====================================
00 20 00 80 . ..
======================================================================
0x111aaf000 12:19:03.140733193388449 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called

at this point I pulled the NEO out, and killed Thunderbird.

More report/log to follow

@dengert
Copy link
Member

dengert commented Oct 2, 2015

I was asking what version of the NEO.

You also say CAC card. I assume that you are then using a US DOD CAC card. The PIV driver will work with these if they are also PIV complaint.
All my testing have been done with non CAC, but PIV complaint cards.

The NEO has a PIV like application and has a number of known differences with the PIV specifications,
and the issue with 6A 80 may be one of these. But that may not be the locking issue you see.

If this is a MAC only issue, it is most likely with PCSC, as this is where the locking is implemented.

On 10/2/2015 11:06 AM, Mouse wrote:

Yes I'm testing on the latest/most recent version of what's in Github.
This all is on Mac OS X Yosemite 10.10.5 with Xcode-7.0.
No access to gist or pastebin from work. :-(

Will report more, and send a complete log to @dengert https://github.com/dengert.


Reply to this email directly or view it on GitHub #570 (comment).

Douglas E. Engert [email protected]

@dengert
Copy link
Member

dengert commented Oct 2, 2015

Thunderbird does polling using PKCS#11 to see if any change to cards or tokens being removed or inserted. It will use the C_GetSlotInfo then wait for a few seconds and try again. The log above is not large enough to see if this is the case or if thre is some other problem.

@dengert
Copy link
Member

dengert commented Oct 3, 2015

Can you have a look at #516 as it has information about locking problems on MacOS

@frankmorgner
Copy link
Member

I tested quite recent versions of OpenSC's tokend on Yosimete with cardos and an other type of card, which worked as expected. I think the tokend should work in general, but I have no specific information about neo or CAC.

@mouse07410
Copy link
Contributor Author

On Oct 3, 2015, at 21:54 , Frank Morgner <[email protected]mailto:[email protected]> wrote:
I tested quite recent versions of OpenSC's tokend on Yosimete with cardos and an other type of card, which worked as expected. I think the tokend should work in general, but I have no specific information about neo or CAC.

In my case, and based on what I’m observing from the application side (as a user - don’t have debugging info from, e.g. Keychain Access) OpenSC.tokend doesn’t seem to tell the calling application that the unlock succeeded.

This applies to both US DoD CAC and Yubikey NEO. The observable behavior is the same for both:

  • All the low-level OpenSC utilities appear to work fine (pkcs11-tool, pkcs15-tool, opensc-tool, etc).
  • OpenSC.tokend sees the card and correctly displays certificates present on it. However when I ask Keychain Access to unlock the card - it prompts me for the PIN, but the card stays locked - always (haven’t had one successful unlock with any OpenSC.tokend up to the current Github version, and with all the CAC cards I tried and all the NEO devices I tried - PIV applet 0.1.2 and 0.1.3). When I do the same with PKard.tokend, or PKCS11.tokend (from the latest CACKey package v0.7.4) - DoD CAC unlocks in 100% cases, while NEO PIV 0.1.3 unlocks always and 0.1.2 unlocks often but not always.

I would love to have this problem fixed, to be able to use OpenSC.tokend with CAC and NEO on Mac OS X (Yosemite, and later on El Capitan).

Please let me know how I can help - i.e. what tests I could run, what debug level I should set in opens.conf, and what debugging info I should provide you to make tracking this issue down possible.

Thanks!

P.S. Re. #516#516 and #487#487 (and #480#480) that if refers to - but cannot tell if it is related to the problem I’m describing. Also, please note that applications such as piv-tool and pkcs11-tool unlock the card (both CAC and NEO) just fine, so the problem doesn’t seem to manifest in the OpenSC “core”, only in its tokend. I don’t know what to make of it…

P.P.S. Here’s the output of
pkcs11-tool --module /Library/OpenSC/lib/opensc-pkcs11.so --login --test —pin xxxxxxxx
perhaps it could help figuring out what’s wrong with the NEO interface?

Using slot 1 with a present token (0x1)
C_SeedRandom() and C_GenerateRandom():
seeding (C_SeedRandom) not supported
seems to be OK
Digests:
all 4 digest functions seem to work
MD5: OK
SHA-1: OK
RIPEMD160: OK
Signatures (currently only RSA signatures)
testing key 0 (PIV AUTH key)
all 4 signature functions seem to work
testing signature mechanisms:
RSA-X-509: OK
RSA-PKCS: OK
SHA1-RSA-PKCS: OK
MD5-RSA-PKCS: OK
RIPEMD160-RSA-PKCS: OK
SHA256-RSA-PKCS: OK
testing key 1 (2048 bits, label=SIGN key) with 1 signature mechanism
MD5-RSA-PKCS: OK
testing key 2 (2048 bits, label=KEY MAN key) with 1 signature mechanism -- can't be used to sign/verify, skipping
testing key 3 (2048 bits, label=CARD AUTH key) with 1 signature mechanism
MD5-RSA-PKCS: OK
Verify (currently only for RSA):
testing key 0 (PIV AUTH key)
RSA-X-509: ERR: C_Verify() returned CKR_GENERAL_ERROR (0x5)
testing key 1 (SIGN key) with 1 mechanism
RSA-X-509: ERR: C_Verify() returned CKR_GENERAL_ERROR (0x5)
testing key 2 (KEY MAN key) with 1 mechanism
-- can't be used to sign/verify, skipping
testing key 3 (CARD AUTH key) with 1 mechanism
RSA-X-509: ERR: C_Verify() returned CKR_GENERAL_ERROR (0x5)
Unwrap: not implemented
Decryption (RSA)
testing key 0 (PIV AUTH key)
RSA-X-509: OK
RSA-PKCS: OK
testing key 1 (SIGN key)
error: PKCS11 function C_Decrypt failed: rv = CKR_USER_NOT_LOGGED_IN (0x101)

Aborting.

I verified that
pkcs11-tool -sign -m SHA384-RSA-PKCS -d 02 -i my_file.txt -o sig.out
produces signature that
openssl dgst -verify ${PUBKEY} -keyform DER -${HASH} -signature sig.out < my_file.txt

validates correctly.

Uri Blumenthal
[email protected]:[email protected]

@dengert
Copy link
Member

dengert commented Oct 4, 2015

When you say "unlock" are your referring to the PC/SC locking to prevent other processes to access the card,
or are your referring to entering the PIN to allow access to the protected objects and key?

For what you say in this note, it sounds like the verify is failing when the PIN is entered.

Can you send a OpenSC debug trace, Replace you PIN digits with 9s. I wan to see if they are digits,
and the PIN padding

I also want to see if there is a Discovery object on the card, and what the SWs from trying to read this are. The CAC may respond differently then a true PIV card.
The NEO may also have an issue with returning 6A 80.

Set debug = 9; in opensc.conf

Have you been able to use your CAC card with OpenSC on Linux? This would help eliminate tokend.

(You have still not sent the debug trace I asked about last week. You said you could not send it from work.)

On 10/4/2015 1:17 AM, Mouse wrote:

On Oct 3, 2015, at 21:54 , Frank Morgner <[email protected]mailto:[email protected]> wrote:
I tested quite recent versions of OpenSC's tokend on Yosimete with cardos and an other type of card, which worked as expected. I think the tokend should work in general, but I have no specific
information about neo or CAC.

In my case, and based on what I’m observing from the application side (as a user - don’t have debugging info from, e.g. Keychain Access) OpenSC.tokend doesn’t seem to tell the calling application that
the unlock succeeded.

This applies to both US DoD CAC and Yubikey NEO. The observable behavior is the same for both:

  • All the low-level OpenSC utilities appear to work fine (pkcs11-tool, pkcs15-tool, opensc-tool, etc).
  • OpenSC.tokend sees the card and correctly displays certificates present on it. However when I ask Keychain Access to unlock the card - it prompts me for the PIN, but the card stays locked - always
    (haven’t had one successful unlock with any OpenSC.tokend up to the current Github version, and with all the CAC cards I tried and all the NEO devices I tried - PIV applet 0.1.2 and 0.1.3). When I do
    the same with PKard.tokend, or PKCS11.tokend (from the latest CACKey package v0.7.4) - DoD CAC unlocks in 100% cases, while NEO PIV 0.1.3 unlocks always and 0.1.2 unlocks often but not always.

I would love to have this problem fixed, to be able to use OpenSC.tokend with CAC and NEO on Mac OS X (Yosemite, and later on El Capitan).

Please let me know how I can help - i.e. what tests I could run, what debug level I should set in opens.conf, and what debugging info I should provide you to make tracking this issue down possible.

Thanks!

P.S. Re. #516#516 and #487#487 (and #480#480) that if refers to - but cannot tell
if it is related to the problem I’m describing. Also, please note that applications such as piv-tool and pkcs11-tool unlock the card (both CAC and NEO) just fine, so the problem doesn’t seem to
manifest in the OpenSC “core”, only in its tokend. I don’t know what to make of it…

P.P.S. Here’s the output of
pkcs11-tool --module /Library/OpenSC/lib/opensc-pkcs11.so --login --test —pin xxxxxxxx
perhaps it could help figuring out what’s wrong with the NEO interface?

Using slot 1 with a present token (0x1)
C_SeedRandom() and C_GenerateRandom():
seeding (C_SeedRandom) not supported
seems to be OK
Digests:
all 4 digest functions seem to work
MD5: OK
SHA-1: OK
RIPEMD160: OK
Signatures (currently only RSA signatures)
testing key 0 (PIV AUTH key)
all 4 signature functions seem to work
testing signature mechanisms:
RSA-X-509: OK
RSA-PKCS: OK
SHA1-RSA-PKCS: OK
MD5-RSA-PKCS: OK
RIPEMD160-RSA-PKCS: OK
SHA256-RSA-PKCS: OK
testing key 1 (2048 bits, label=SIGN key) with 1 signature mechanism
MD5-RSA-PKCS: OK
testing key 2 (2048 bits, label=KEY MAN key) with 1 signature mechanism -- can't be used to sign/verify, skipping
testing key 3 (2048 bits, label=CARD AUTH key) with 1 signature mechanism
MD5-RSA-PKCS: OK
Verify (currently only for RSA):
testing key 0 (PIV AUTH key)
RSA-X-509: ERR: C_Verify() returned CKR_GENERAL_ERROR (0x5)
testing key 1 (SIGN key) with 1 mechanism
RSA-X-509: ERR: C_Verify() returned CKR_GENERAL_ERROR (0x5)
testing key 2 (KEY MAN key) with 1 mechanism
-- can't be used to sign/verify, skipping
testing key 3 (CARD AUTH key) with 1 mechanism
RSA-X-509: ERR: C_Verify() returned CKR_GENERAL_ERROR (0x5)
Unwrap: not implemented
Decryption (RSA)
testing key 0 (PIV AUTH key)
RSA-X-509: OK
RSA-PKCS: OK
testing key 1 (SIGN key)
error: PKCS11 function C_Decrypt failed: rv = CKR_USER_NOT_LOGGED_IN (0x101)

Aborting.

I verified that
pkcs11-tool -sign -m SHA384-RSA-PKCS -d 02 -i my_file.txt -o sig.out
produces signature that
openssl dgst -verify ${PUBKEY} -keyform DER -${HASH} -signature sig.out < my_file.txt

validates correctly.

Uri Blumenthal
[email protected]:[email protected]


Reply to this email directly or view it on GitHub #570 (comment).

Douglas E. Engert [email protected]

@dengert
Copy link
Member

dengert commented Oct 5, 2015

https://militarycac.com/cacdrivers.htm

reports upgrade available for SCR-3310 and SCR-331 readers and some problems on Mac with SCR readers. Could this be a problem? (But the NEO has its own reader, so there could be more then one problem.)

@dengert
Copy link
Member

dengert commented Oct 5, 2015

One other possible issue:
NIST 800-73-3 PART1
3.2.3 X.509 Certificate for Digital Signature
Says:
"The PKI cryptographic function is protected with a “PIN Always” access rule. In other
words, the PIN must be submitted every time immediately before a Digital Signatuire Key operation.
This ensures cardholder participation every time the private ley is used for digital signature
generation"

The card enforces this.

OpenSC id "02" is for the 9C key for this certificate. OpenSC PKCS#15 calls this user_consent. PKCS#11 has the private key attribute CKA_ALWAYS_AUTHENTICATE. C_Login with CKU_CONTEXT_SPECIFIC is used to send the PIN in again.

It could be tokend is not doing this, and thus the sign fails.
Thunderbird uses NSS calling PKCS#11 does have this code (or should be now, it has been years since this should have been fixed. Maybe it was not fixed in Mac versions.)

OpenSC has PIN caching, which my just send in the PIN again. (disregarding "ensures cardholder participation every time") OpenSC can also try and cache PINs, and may try and send the PIN in again without the user knowing.

So full OpenSC debug logs with debug = 9; and pkcs#11 spy logs would help show what is going on.

@mouse07410
Copy link
Contributor Author

Sorry, no it cannot because (a) my reader is upgraded, and (b) everything else (PKard, Centrify, CACKey PKCS11.tokend) successfully unlocks my CAC. My CAC reader is SCR-3310 v2.0.

Sent from my iPad

On Oct 4, 2015, at 22:36, Doug Engert <[email protected]mailto:[email protected]> wrote:

https://militarycac.com/cacdrivers.htm

reports upgrade available for SCR-3310 and SCR-331 readers and some problems on Mac with SCR readers. Could this be a problem? (But the NEO has its own reader, so there could be more then one problem.)


Reply to this email directly or view it on GitHubhttps://github.com//issues/570#issuecomment-145413536.

@mouse07410
Copy link
Contributor Author

I tried my CAC on Linux (running in a VM), and it worked perfectly, in all aspects - both with low-level tools from OpenSC (pkcs11-tool, etc), and with "normal" applications (accessed CAC-protected Web sites using Firefox, sent CAC_signed emails using Thunderbird - both were configured to use /usr/local/lib/opensc-pkcs11.so as PKCS#11 reader).

Must say that on Mac, CAC is handled by PKard.tokend. Apparently it passes everything correctly to invoking applications, including VMware Fusion - so my Linux VM was able to interact with CAC fine.

I tried with NEO. It used OpenSC.tokend (Github version). First observation - this tokend is unable to correctly pass the unlock information to the invoking applications, as seen in the log. I was also unable to access NEO from the Linux VM.

I cannot attach the log (Github doesn't accept it, though it's .TXT). The relevant lines are pasted in. They show that when the application (Keychain Access) requests to unlock the token, the request appears to reach down to the card, and unlock it successfully (returning Success). However that "Success" does not seem to be propagated to the invoking application - so it never learns that the operation in fact succeeded...

0x7fff7e07b300 13:11:59.969 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()0x7fff7e07b300 13:11:59.983 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()0x7fff7e07b300 13:12:10.421 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 13:12:10.434 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:330:getOwner: In OpenSCToken::getOwner()
0x7fff7e07b300 13:12:10.140733193388466 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 13:12:16.4294967499 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:149:verifyPIN: In OpenSCToken::verifyPIN(1)
0x7fff7e07b300 13:12:16.317106025398475 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:172:_verifyPIN: In OpenSCToken::_verifyPIN(), PIN num is: 1
0x7fff7e07b300 13:12:16.317106025398475 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:186:_verifyPIN:   sc_pkcs15_get_objects(pin_id=01): 2
0x7fff7e07b300 13:12:16.203 [tokend] pkcs15-pin.c:295:sc_pkcs15_verify_pin: called
0x7fff7e07b300 13:12:16.203 [tokend] pkcs15-pin.c:296:sc_pkcs15_verify_pin: PIN(type:0;method:1;len:)
0x7fff7e07b300 13:12:16.203 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:12:16.317106025398475 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 13:12:16.204 [tokend] sec.c:159:sc_pin_cmd: called
0x7fff7e07b300 13:12:16.204 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 13:12:16.204 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:12:16.140733193388236 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 13:12:16.140733193388236 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 13:12:16.140733193388236 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:20, P1:0, P2:80, data(8) 0x7......
0x7fff7e07b300 13:12:16.317106025398476 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:12:16.140733193388236 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [   13 bytes] =====================================
00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..
======================================================================
0x7fff7e07b300 13:12:16.140733193388236 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 13:12:16.4294967532 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
90 00 ..
======================================================================
0x7fff7e07b300 13:12:16.140733193388268 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:12:16.120259084524 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:12:16.-4294967060 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:12:16.236 [tokend] sec.c:206:sc_pin_cmd: returning with: 0 (Success)
0x7fff7e07b300 13:12:16.236 [tokend] pkcs15-pin.c:368:sc_pkcs15_verify_pin: PIN cmd result 0
0x7fff7e07b300 13:12:16.317106025398508 [tokend] pkcs15-pin.c:594:sc_pkcs15_pincache_add: called
0x7fff7e07b300 13:12:16.317106025398508 [tokend] pkcs15-pin.c:618:sc_pkcs15_pincache_add: caching refused (user consent)
0x7fff7e07b300 13:12:16.4294967532 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:12:16.236 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 13:12:16.237 [tokend] pkcs15-pin.c:373:sc_pkcs15_verify_pin: returning with: 0 (Success)
0x7fff7e07b300 13:12:16.237 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:192:_verifyPIN:   In OpenSCToken::verify returned 0 for pin 1
0x7fff7e07b300 13:12:16.5705853276663054573 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:158:verifyPIN:   About to call BEGIN()
0x7fff7e07b300 13:12:16.3617293440343081217 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 13:12:16.3617293440343081235 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 13:12:20.3617293440343081952 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 13:12:21.3617293440343080970 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()

Nothing more in the log file - just the repetition of that getAcl()...

And here's the attempt to unlock the token with the latest (of this morning) Github OpenSC.tokend, and with pin caching enforced (ignoring user consent):

0x7fff7e07b300 13:31:15.140733193388780 [tokend] ctx.c:742:sc_context_create: ===================================
0x7fff7e07b300 13:31:15.140733193388780 [tokend] ctx.c:743:sc_context_create: opensc version: 0.15.0
0x7fff7e07b300 13:31:15.3891300254905008878 [tokend] reader-pcsc.c:687:pcsc_init: PC/SC options: connect_exclusive=0 disconnect_action=1 transaction_end_action=0 reconnect_action=0 enable_pinpad=1 enable_pace=1
0x7fff7e07b300 13:31:15.4294968047 [tokend] ctx.c:454:load_card_drivers: Unable to load 'piv'.
0x7fff7e07b300 13:31:15.140733193388795 [tokend] reader-pcsc.c:1061:pcsc_detect_readers: called
0x7fff7e07b300 13:31:15.140733193388795 [tokend] reader-pcsc.c:1075:pcsc_detect_readers: Probing PC/SC readers
0x7fff7e07b300 13:31:15.140733193388795 [tokend] reader-pcsc.c:1104:pcsc_detect_readers: Establish PC/SC context
0x7fff7e07b300 13:31:15.140733193388795 [tokend] reader-pcsc.c:1152:pcsc_detect_readers: Found new PC/SC reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:31:15.140733193388795 [tokend] reader-pcsc.c:288:refresh_attributes: Yubico Yubikey NEO OTP+U2F+CCID check
0x7fff7e07b300 13:31:15.140733193388796 [tokend] reader-pcsc.c:315:refresh_attributes: current  state: 0x00000122
0x7fff7e07b300 13:31:15.140733193388796 [tokend] reader-pcsc.c:316:refresh_attributes: previous state: 0x00000000
0x7fff7e07b300 13:31:15.140733193388796 [tokend] reader-pcsc.c:370:refresh_attributes: card present, changed
0x7fff7e07b300 13:31:15.140733193388796 [tokend] reader-pcsc.c:1183:pcsc_detect_readers: Requesting reader features ... 
0x7fff7e07b300 13:31:15.140733193388798 [tokend] reader-pcsc.c:1197:pcsc_detect_readers: Yubico Yubikey NEO OTP+U2F+CCID:SCardConnect(SHARED): 0x7fa800000000
0x7fff7e07b300 13:31:15.766 [tokend] reader-pcsc.c:933:detect_reader_features: called
0x7fff7e07b300 13:31:15.766 [tokend] reader-pcsc.c:954:detect_reader_features: Reader feature 12 found
0x7fff7e07b300 13:31:15.4294968062 [tokend] reader-pcsc.c:913:part10_get_vendor_product: id_vendor=1050 id_product=0116
0x7fff7e07b300 13:31:15.140733193388799 [tokend] reader-pcsc.c:1152:pcsc_detect_readers: Found new PC/SC reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 13:31:15.140733193388799 [tokend] reader-pcsc.c:288:refresh_attributes: SCR3310 Smart Card Reader check
0x7fff7e07b300 13:31:15.140733193388799 [tokend] reader-pcsc.c:315:refresh_attributes: current  state: 0x00000012
0x7fff7e07b300 13:31:15.140733193388799 [tokend] reader-pcsc.c:316:refresh_attributes: previous state: 0x00000000
0x7fff7e07b300 13:31:15.140733193388799 [tokend] reader-pcsc.c:370:refresh_attributes: card absent
0x7fff7e07b300 13:31:15.140733193388799 [tokend] reader-pcsc.c:1183:pcsc_detect_readers: Requesting reader features ... 
0x7fff7e07b300 13:31:15.140733193388800 [tokend] reader-pcsc.c:1193:pcsc_detect_readers: SCR3310 Smart Card Reader:SCardConnect(DIRECT): 0x7fa800000000
0x7fff7e07b300 13:31:15.768 [tokend] reader-pcsc.c:933:detect_reader_features: called
0x7fff7e07b300 13:31:15.140733193388800 [tokend] reader-pcsc.c:1227:pcsc_detect_readers: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.140733193388801 [tokend] card.c:196:sc_connect_card: called
0x7fff7e07b300 13:31:15.317106025399041 [tokend] reader-pcsc.c:458:pcsc_connect: called
0x7fff7e07b300 13:31:15.140733193388801 [tokend] reader-pcsc.c:288:refresh_attributes: Yubico Yubikey NEO OTP+U2F+CCID check
0x7fff7e07b300 13:31:15.140733193388802 [tokend] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.140733193388803 [tokend] reader-pcsc.c:487:pcsc_connect: Initial protocol: T=1
0x7fff7e07b300 13:31:15.771 [tokend] card.c:965:match_atr_table: ATR     : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
0x7fff7e07b300 13:31:15.771 [tokend] card.c:976:match_atr_table: ATR try : 3B:DD:18:00:81:31:FE:45:80:F9:A0:00:00:00:77:01:00:70:0A:90:00:8B
0x7fff7e07b300 13:31:15.771 [tokend] card.c:965:match_atr_table: ATR     : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
0x7fff7e07b300 13:31:15.771 [tokend] card.c:976:match_atr_table: ATR try : 3B:7F:96:00:00:00:31:B9:64:40:70:14:10:73:94:01:80:82:90:00
0x7fff7e07b300 13:31:15.771 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 13:31:15.771 [tokend] card.c:976:match_atr_table: ATR try : 3B:7F:96:00:00:00:31:B8:64:40:70:14:10:73:94:01:80:82:90:00
0x7fff7e07b300 13:31:15.771 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 13:31:15.771 [tokend] card.c:976:match_atr_table: ATR try : 3B:DF:18:FF:81:91:FE:1F:C3:00:31:B8:64:0C:01:EC:C1:73:94:01:80:82:90:00:B3
0x7fff7e07b300 13:31:15.771 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 13:31:15.771 [tokend] card.c:976:match_atr_table: ATR try : 3B:DC:18:FF:81:91:FE:1F:C3:80:73:C8:21:13:66:01:0B:03:52:00:05:38
0x7fff7e07b300 13:31:15.771 [tokend] card.c:965:match_atr_table: ATR     : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
0x7fff7e07b300 13:31:15.771 [tokend] card.c:976:match_atr_table: ATR try : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 13:31:15.771 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 13:31:15.771 [tokend] card.c:976:match_atr_table: ATR try : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
0x7fff7e07b300 13:31:15.140733193388803 [tokend] reader-pcsc.c:407:check_forced_protocol: force_protocol: t1
0x7fff7e07b300 13:31:15.-4294966525 [tokend] reader-pcsc.c:499:pcsc_connect: Final protocol: T=1
0x7fff7e07b300 13:31:15.140359531234051 [tokend] card.c:217:sc_connect_card: matching configured ATRs
0x7fff7e07b300 13:31:15.140359531234051 [tokend] card.c:226:sc_connect_card: trying driver 'authentic'
0x7fff7e07b300 13:31:15.140733193388803 [tokend] card.c:965:match_atr_table: ATR     : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
.........
0x7fff7e07b300 13:31:15.140359531234051 [tokend] card.c:226:sc_connect_card: trying driver 'piv'
0x7fff7e07b300 13:31:15.140733193388803 [tokend] card.c:965:match_atr_table: ATR     : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
0x7fff7e07b300 13:31:15.140733193388803 [tokend] card.c:976:match_atr_table: ATR try : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 13:31:15.140733193388803 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 13:31:15.140733193388803 [tokend] card.c:976:match_atr_table: ATR try : 3b:fc:13:00:00:81:31:fe:15:59:75:62:69:6b:65:79:4e:45:4f:72:33:e1
0x7fff7e07b300 13:31:15.140359531234051 [tokend] card.c:231:sc_connect_card: matched driver 'PIV-II  for multiple cards'
0x7fff7e07b300 13:31:15.771 [tokend] card-piv.c:2842:piv_match_card: called
0x7fff7e07b300 13:31:15.140733193388804 [tokend] card-piv.c:720:piv_find_aid: called
0x7fff7e07b300 13:31:15.4294968068 [tokend] card-piv.c:683:piv_select_aid: called
0x7fff7e07b300 13:31:15.4294968068 [tokend] card-piv.c:686:piv_select_aid: Got args: aid=e94d524, aidlen=9, response=51523ff0, responselen=261
0x7fff7e07b300 13:31:15.140733193388804 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 13:31:15.772 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.317106025399044 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 13:31:15.4294968068 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 13:31:15.140733193388804 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 13:31:15.140733193388804 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(9) 0x10e94d524
0x7fff7e07b300 13:31:15.317106025399044 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:31:15.140733193388804 [tokend] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   15 bytes] =====================================
00 A4 04 00 09 A0 00 00 03 08 00 00 10 00 00 ...............
======================================================================
0x7fff7e07b300 13:31:15.140733193388804 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 13:31:15.4294968086 [tokend] apdu.c:187:sc_apdu_log: 
Incoming APDU data [   21 bytes] =====================================
61 11 4F 06 00 00 10 00 01 00 79 07 4F 05 A0 00 a.O.......y.O...
00 03 08 90 00                                  .....
======================================================================
0x7fff7e07b300 13:31:15.140733193388822 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.120259085078 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.-4294966506 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:31:15.790 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 13:31:15.3539882289829774102 [tokend] card-piv.c:701:piv_select_aid: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.3617015263901254423 [tokend] card-piv.c:735:piv_find_aid: found PIX
0x7fff7e07b300 13:31:15.3617015263901254423 [tokend] card-piv.c:749:piv_find_aid: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.791 [tokend] card-piv.c:2860:piv_init: called
0x7fff7e07b300 13:31:15.791 [tokend] card-piv.c:2876:piv_init: Max send = 0 recv = 0
0x7fff7e07b300 13:31:15.140733193388823 [tokend] card-piv.c:720:piv_find_aid: called
0x7fff7e07b300 13:31:15.4294968087 [tokend] card-piv.c:683:piv_select_aid: called
0x7fff7e07b300 13:31:15.4294968087 [tokend] card-piv.c:686:piv_select_aid: Got args: aid=e94d524, aidlen=9, response=51524140, responselen=261
0x7fff7e07b300 13:31:15.140733193388823 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 13:31:15.791 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.317106025399063 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 13:31:15.4294968087 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 13:31:15.140733193388823 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 13:31:15.140733193388823 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(9) 0x10e94d524
0x7fff7e07b300 13:31:15.317106025399063 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:31:15.140733193388823 [tokend] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   15 bytes] =====================================
00 A4 04 00 09 A0 00 00 03 08 00 00 10 00 00 ...............
======================================================================
0x7fff7e07b300 13:31:15.140733193388823 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 13:31:15.4294968103 [tokend] apdu.c:187:sc_apdu_log: 
Incoming APDU data [   21 bytes] =====================================
61 11 4F 06 00 00 10 00 01 00 79 07 4F 05 A0 00 a.O.......y.O...
00 03 08 90 00                                  .....
======================================================================
0x7fff7e07b300 13:31:15.140733193388839 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.120259085095 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.-4294966489 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:31:15.807 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 13:31:15.3539882289829774119 [tokend] card-piv.c:701:piv_select_aid: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.3617015263901254439 [tokend] card-piv.c:735:piv_find_aid: found PIX
0x7fff7e07b300 13:31:15.3617015263901254439 [tokend] card-piv.c:749:piv_find_aid: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.140733193388839 [tokend] card-piv.c:2617:piv_process_history: called
0x7fff7e07b300 13:31:15.317106025399079 [tokend] card-piv.c:945:piv_get_cached_data: called
0x7fff7e07b300 13:31:15.317106025399079 [tokend] card-piv.c:946:piv_get_cached_data: #11
0x7fff7e07b300 13:31:15.317106025399079 [tokend] card-piv.c:986:piv_get_cached_data: get #11
0x7fff7e07b300 13:31:15.140733193388839 [tokend] card-piv.c:879:piv_get_data: called
0x7fff7e07b300 13:31:15.140733193388839 [tokend] card-piv.c:880:piv_get_data: #11 
0x7fff7e07b300 13:31:15.140733193388839 [tokend] card-piv.c:899:piv_get_data: get len of #11
0x7fff7e07b300 13:31:15.807 [tokend] card-piv.c:447:piv_general_io: called
0x7fff7e07b300 13:31:15.807 [tokend] card-piv.c:450:piv_general_io: cb 3f ff 5 : 0 0
0x7fff7e07b300 13:31:15.807 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.317106025399079 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 13:31:15.808 [tokend] card-piv.c:490:piv_general_io: calling sc_transmit_apdu flags=3 le=8, resplen=8, resp=0x7fff51523c10
0x7fff7e07b300 13:31:15.140733193388840 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 13:31:15.808 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.140733193388840 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 13:31:15.140733193388840 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 13:31:15.140733193388840 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:CB, P1:3F, P2:FF, data(5) 0x7fff51523c18
0x7fff7e07b300 13:31:15.317106025399080 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:31:15.140733193388840 [tokend] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   11 bytes] =====================================
00 CB 3F FF 05 5C 03 5F C1 0C 08 ..?..\._...
======================================================================
0x7fff7e07b300 13:31:15.140733193388840 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 13:31:15.4294968114 [tokend] apdu.c:187:sc_apdu_log: 
Incoming APDU data [    2 bytes] =====================================
6A 82 j.
======================================================================
0x7fff7e07b300 13:31:15.140733193388850 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.120259085106 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.-4294966478 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:31:15.140359531234098 [tokend] card-piv.c:496:piv_general_io: DEE r=0 apdu.resplen=0 sw1=6a sw2=82
0x7fff7e07b300 13:31:15.317106025399090 [tokend] iso7816.c:121:iso7816_check_sw: File not found
0x7fff7e07b300 13:31:15.140359531234098 [tokend] card-piv.c:508:piv_general_io: Card returned error 
0x7fff7e07b300 13:31:15.140733193388850 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:31:15.818 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 13:31:15.819 [tokend] card-piv.c:558:piv_general_io: returning with: -1201 (File not found)
0x7fff7e07b300 13:31:15.4294968115 [tokend] card-piv.c:933:piv_get_data: returning with: -1201 (File not found)
0x7fff7e07b300 13:31:15.4294968115 [tokend] card-piv.c:1014:piv_get_cached_data: returning with: -1201 (File not found)
0x7fff7e07b300 13:31:15.140359531234099 [tokend] card-piv.c:2805:piv_process_history: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.3539882289829774131 [tokend] card-piv.c:945:piv_get_cached_data: called
0x7fff7e07b300 13:31:15.3539882289829774131 [tokend] card-piv.c:946:piv_get_cached_data: #10
0x7fff7e07b300 13:31:15.3539882289829774131 [tokend] card-piv.c:986:piv_get_cached_data: get #10
0x7fff7e07b300 13:31:15.140733193388851 [tokend] card-piv.c:879:piv_get_data: called
0x7fff7e07b300 13:31:15.140733193388851 [tokend] card-piv.c:880:piv_get_data: #10 
0x7fff7e07b300 13:31:15.140733193388851 [tokend] card-piv.c:899:piv_get_data: get len of #10
0x7fff7e07b300 13:31:15.140733193388851 [tokend] card-piv.c:447:piv_general_io: called
0x7fff7e07b300 13:31:15.140733193388851 [tokend] card-piv.c:450:piv_general_io: cb 3f ff 3 : 0 0
0x7fff7e07b300 13:31:15.819 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.317106025399091 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 13:31:15.819 [tokend] card-piv.c:490:piv_general_io: calling sc_transmit_apdu flags=3 le=8, resplen=8, resp=0x7fff51524140
0x7fff7e07b300 13:31:15.140733193388851 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 13:31:15.819 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.140733193388851 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 13:31:15.140733193388851 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 13:31:15.140733193388851 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:CB, P1:3F, P2:FF, data(3) 0x7fff51524148
0x7fff7e07b300 13:31:15.317106025399091 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:31:15.140733193388851 [tokend] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [    9 bytes] =====================================
00 CB 3F FF 03 5C 01 7E 08 ..?..\.~.
======================================================================
0x7fff7e07b300 13:31:15.140733193388851 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 13:31:15.4294968132 [tokend] apdu.c:187:sc_apdu_log: 
Incoming APDU data [   22 bytes] =====================================
7E 12 4F 0B A0 00 00 03 08 00 00 10 00 01 00 5F ~.O............_
2F 02 40 00 90 00                               /.@...
======================================================================
0x7fff7e07b300 13:31:15.140733193388868 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.120259085124 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
.........
0x7fff7e07b300 13:31:15.4294968158 [tokend] pkcs15-syn.c:184:sc_pkcs15_bind_synthetic: trying PIV-II
0x7fff7e07b300 13:31:15.4294968158 [tokend] pkcs15-piv.c:1028:sc_pkcs15emu_piv_init_ex: called
0x7fff7e07b300 13:31:15.140733193388894 [tokend] pkcs15-piv.c:234:piv_detect_card: called
0x7fff7e07b300 13:31:15.862 [tokend] pkcs15-piv.c:613:sc_pkcs15emu_piv_init: called
0x7fff7e07b300 13:31:15.317106025399134 [tokend] card.c:843:sc_card_ctl: called
0x7fff7e07b300 13:31:15.317106025399134 [tokend] card-piv.c:2116:piv_card_ctl: called
0x7fff7e07b300 13:31:15.317106025399134 [tokend] card-piv.c:2117:piv_card_ctl: cmd=5 ptr=0x7fff51524270
0x7fff7e07b300 13:31:15.140733193388894 [tokend] card-piv.c:2017:piv_get_serial_nr_from_CHUI: called
0x7fff7e07b300 13:31:15.4294968158 [tokend] card-piv.c:683:piv_select_aid: called
0x7fff7e07b300 13:31:15.4294968158 [tokend] card-piv.c:686:piv_select_aid: Got args: aid=e94d524, aidlen=9, response=5151f2c0, responselen=2000
0x7fff7e07b300 13:31:15.140733193388894 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 13:31:15.862 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.140733193388894 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 13:31:15.140733193388894 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 13:31:15.140733193388894 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(9) 0x10e94d524
0x7fff7e07b300 13:31:15.317106025399134 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:31:15.140733193388894 [tokend] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   15 bytes] =====================================
00 A4 04 00 09 A0 00 00 03 08 00 00 10 00 00 ...............
======================================================================
0x7fff7e07b300 13:31:15.140733193388894 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 13:31:15.4294968170 [tokend] apdu.c:187:sc_apdu_log: 
Incoming APDU data [   21 bytes] =====================================
61 11 4F 06 00 00 10 00 01 00 79 07 4F 05 A0 00 a.O.......y.O...
00 03 08 90 00                                  .....
======================================================================
0x7fff7e07b300 13:31:15.140733193388906 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.875 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.140733193388907 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 13:31:15.140733193388907 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 13:31:15.140733193388907 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:CB, P1:3F, P2:FF, data(5) 0x7fff5151f0e8
0x7fff7e07b300 13:31:15.317106025399147 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:31:15.140733193388907 [tokend] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   11 bytes] =====================================
00 CB 3F FF 05 5C 03 5F C1 02 08 ..?..\._...
======================================================================
0x7fff7e07b300 13:31:15.140733193388907 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 13:31:15.4294968186 [tokend] apdu.c:187:sc_apdu_log: 
Incoming APDU data [   63 bytes] =====================================
53 3B 30 19 D4 E7 39 DA 73 9C ED 39 CE 73 9D 83 S;0...9.s..9.s..
68 58 21 08 42 10 84 21 38 42 10 C3 F5 34 10 04 hX!.B..!8B...4..
16 C5 21 DC 5C 34 26 6C A1 5D DB D1 40 C6 A5 35 ..!.\4&l.][email protected]
08 32 30 33 30 30 31 30 31 3E 00 FE 00 90 00    .20300101>.....
======================================================================
0x7fff7e07b300 13:31:15.140733193388922 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.120259085178 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.-4294966406 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:31:15.140359531234170 [tokend] card-piv.c:496:piv_general_io: DEE r=0 apdu.resplen=8 sw1=90 sw2=00
0x7fff7e07b300 13:31:15.140733193388922 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:31:15.4294968186 [tokend] card-piv.c:558:piv_general_io: returning with: 61
0x7fff7e07b300 13:31:15.4294968186 [tokend] card-piv.c:919:piv_get_data: get buffer for #1 len 61
0x7fff7e07b300 13:31:15.4294968186 [tokend] card-piv.c:447:piv_general_io: called
0x7fff7e07b300 13:31:15.4294968186 [tokend] card-piv.c:450:piv_general_io: cb 3f ff 5 : 255 256
0x7fff7e07b300 13:31:15.890 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.890 [tokend] card-piv.c:490:piv_general_io: calling sc_transmit_apdu flags=1 le=61, resplen=61, resp=0x7fa893e0e240
0x7fff7e07b300 13:31:15.140733193388922 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 13:31:15.890 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.140733193388922 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 13:31:15.140733193388922 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 13:31:15.140733193388922 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:CB, P1:3F, P2:FF, data(5) 0x7fff5151f0e8
0x7fff7e07b300 13:31:15.317106025399162 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:31:15.140733193388922 [tokend] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   11 bytes] =====================================
00 CB 3F FF 05 5C 03 5F C1 02 3D ..?..\._..=
======================================================================
0x7fff7e07b300 13:31:15.140733193388922 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 13:31:15.4294968205 [tokend] apdu.c:187:sc_apdu_log: 
Incoming APDU data [   63 bytes] =====================================
53 3B 30 19 D4 E7 39 DA 73 9C ED 39 CE 73 9D 83 S;0...9.s..9.s..
68 58 21 08 42 10 84 21 38 42 10 C3 F5 34 10 04 hX!.B..!8B...4..
16 C5 21 DC 5C 34 26 6C A1 5D DB D1 40 C6 A5 35 ..!.\4&l.][email protected]
08 32 30 33 30 30 31 30 31 3E 00 FE 00 90 00    .20300101>.....
======================================================================
0x7fff7e07b300 13:31:15.140733193388941 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.120259085197 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
.........
0x7fff7e07b300 13:31:15.910 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:15.140733193388942 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 13:31:15.140733193388942 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 13:31:15.140733193388942 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:CB, P1:3F, P2:FF, data(5) 0x7fff5151f7d8
0x7fff7e07b300 13:31:15.317106025399182 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:31:15.140733193388942 [tokend] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   11 bytes] =====================================
00 CB 3F FF 05 5C 03 5F C1 05 08 ..?..\._...
======================================================================
0x7fff7e07b300 13:31:15.140733193388942 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 13:31:15.4294968258 [tokend] apdu.c:187:sc_apdu_log: 
Incoming APDU data [  255 bytes] =====================================
53 82 03 EB 70 82 03 E2 30 82 03 DE 30 82 02 46 S...p...0...0..F
A0 03 02 01 02 02 04 55 0A EB 26 30 0D 06 09 2A .......U..&0...*
86 48 86 F7 0D 01 01 0B 05 00 30 50 31 0B 30 09 .H........0P1.0.
06 03 55 04 06 13 02 55 53 31 13 30 11 06 03 55 ..U....US1.0...U
04 0A 0C 0A 54 68 65 20 42 75 72 72 6F 77 31 12 ....The Burrow1.
30 10 06 03 55 04 0B 0C 09 47 61 74 68 65 72 65 0...U....Gathere
72 73 31 18 30 16 06 03 55 04 03 0C 0F 46 6F 72 rs1.0...U....For
65 73 74 20 43 41 20 32 20 52 53 41 30 1E 17 0D est CA 2 RSA0...
31 35 30 33 31 39 31 35 32 38 35 35 5A 17 0D 31 150319152855Z..1
38 30 33 31 39 31 35 32 38 35 35 5A 30 18 31 16 80319152855Z0.1.
30 14 06 03 55 04 03 0C 0D 55 72 69 20 74 68 65 0...U....Uri the
20 47 72 65 61 74 30 82 01 22 30 0D 06 09 2A 86  Great0.."0...*.
48 86 F7 0D 01 01 01 05 00 03 82 01 0F 00 30 82 H.............0.
01 0A 02 82 01 01 00 AD 80 70 66 0A 9F 7A F1 BC .........pf..z..
E9 BD 78 05 AB 6F C2 32 E3 93 15 75 3B 19 94 FB ..x..o.2...u;...
54 8A F2 58 9F 64 C8 8B 73 FE 7D B9 72 61 FD    T..X.d..s.}.ra.
======================================================================
0x7fff7e07b300 13:31:15.140733193388994 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.120259085250 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:15.-4294966334 [tokend] card.c:434:sc_unlock: called
.........
0x7fff7e07b300 13:31:16.140359531233865 [tokend] pkcs15-piv.c:928:sc_pkcs15emu_piv_init: adding pubkey for 2 keyalg=0
0x7fff7e07b300 13:31:16.140733193388617 [tokend] pkcs15-pubkey.c:796:sc_pkcs15_encode_pubkey_as_spki: called
0x7fff7e07b300 13:31:16.140733193388617 [tokend] pkcs15-pubkey.c:800:sc_pkcs15_encode_pubkey_as_spki: Encoding public key with algorithm
 0
0x7fff7e07b300 13:31:16.140733193388617 [tokend] pkcs15-pubkey.c:593:sc_pkcs15_encode_pubkey_rsa: called
0x7fff7e07b300 13:31:16.140733193388617 [tokend] pkcs15-pubkey.c:604:sc_pkcs15_encode_pubkey_rsa: returning with: 0 (Success)
0x7fff7e07b300 13:31:16.140733193388617 [tokend] pkcs15-algo.c:530:sc_asn1_encode_algorithm_id: called
0x7fff7e07b300 13:31:16.140733193388617 [tokend] pkcs15-algo.c:531:sc_asn1_encode_algorithm_id: type of algorithm to encode: 0
0x7fff7e07b300 13:31:16.140733193388617 [tokend] pkcs15-algo.c:545:sc_asn1_encode_algorithm_id: encode algo 1.2.840.113549.1.1.1
0x7fff7e07b300 13:31:16.140733193388617 [tokend] pkcs15-algo.c:580:sc_asn1_encode_algorithm_id: return encoded algorithm ID: 06092A86488
6F70D0101010500
0x7fff7e07b300 13:31:16.140733193388617 [tokend] pkcs15-algo.c:581:sc_asn1_encode_algorithm_id: returning with: 0 (Success)
0x7fff7e07b300 13:31:16.140733193388617 [tokend] pkcs15-pubkey.c:866:sc_pkcs15_encode_pubkey_as_spki: returning with: 0 (Success)
0x7fff7e07b300 13:31:16.140359531233865 [tokend] pkcs15-piv.c:928:sc_pkcs15emu_piv_init: adding pubkey for 3 keyalg=0
0x7fff7e07b300 13:31:16.140359531233865 [tokend] pkcs15-piv.c:858:sc_pkcs15emu_piv_init: No cert for this pub key i=4
0x7fff7e07b300 13:31:16.140359531233865 [tokend] pkcs15-piv.c:870:sc_pkcs15emu_piv_init: DEE look for env NULL
0x7fff7e07b300 13:31:16.140359531233865 [tokend] pkcs15-piv.c:858:sc_pkcs15emu_piv_init: No cert for this pub key i=5
0x7fff7e07b300 13:31:16.140359531233865 [tokend] pkcs15-piv.c:870:sc_pkcs15emu_piv_init: DEE look for env NULL
0x7fff7e07b300 13:31:16.140359531233865 [tokend] pkcs15-piv.c:858:sc_pkcs15emu_piv_init: No cert for this pub key i=6
0x7fff7e07b300 13:31:16.140359531233865 [tokend] pkcs15-piv.c:870:sc_pkcs15emu_piv_init: DEE look for env NULL
.........
0x7fff7e07b300 13:31:16.585 [tokend] pkcs15-syn.c:218:sc_pkcs15_bind_synthetic: returning with: 0 (Success)
0x7fff7e07b300 13:31:16.463856468553 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:31:16.4294967881 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 13:31:16.586 [tokend] pkcs15.c:1251:sc_pkcs15_bind: returning with: 0 (Success)
0x7fff7e07b300 13:31:16.4294967882 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:254:probe:   sc_pkcs15_bind()
: 0
0x7fff7e07b300 13:31:16.4294967882 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:262:probe:   Get Score from c
onfig file: 300
0x7fff7e07b300 13:31:16.4294967882 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:283:probe:     score = 300, t
okenUid = "f8f005846711935bae20a0a0d89674a68a894b38"
0x7fff7e07b300 13:31:17.140733193388064 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:300:establish: In OpenSC
Token::establish() -> we had the highest score
0x7fff7e07b300 13:31:17.140733193388064 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:308:establish:   About t
o create schema
0x7fff7e07b300 13:31:17.140733193388064 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:312:establish:   Schema 
created, about to call populate()
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:401:populate: In OpenSCToken::popula
te()
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:424:populate:   sc_pkcs15_get_object
s(TYPE_CERT_X509): 4
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:431:populate:     - Certificate for 
PIV Authentication (ID=01)
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:431:populate:     - Certificate for Digital Signature (ID=02)
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:431:populate:     - Certificate for Key Management (ID=03)
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:431:populate:     - Certificate for Card Authentication (ID=04)
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:441:populate:   sc_pkcs15_get_objects(TYPE_PRKEY_RSA): 4
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:481:populate:     - PIV AUTH key (ID=01)
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:493:populate:         linked this key to cert "Certificate for PIV Authentication"
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:481:populate:     - SIGN key (ID=02)
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:493:populate:         linked this key to cert "Certificate for Digital Signature"
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:481:populate:     - KEY MAN key (ID=03)
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:493:populate:         linked this key to cert "Certificate for Key Management"
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:481:populate:     - CARD AUTH key (ID=04)
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:493:populate:         linked this key to cert "Certificate for Card Authentication"
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:505:populate:   sc_pkcs15_get_objects(TYPE_AUTH_PIN): 2
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:515:populate:     added pin with ID=01 to the pinmap
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:511:populate:     ignored non-user pin with ID=02
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:518:populate:   returning from OpenSCToken::populate()
0x7fff7e07b300 13:31:17.032 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:321:establish:   returning from OpenSCToken::establish()
0x7fff7e07b300 13:31:17.075 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 13:31:17.092 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 13:31:17.094 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
........ <tons more of the above getAcl() records> .........
0x7fff7e07b300 13:31:31.214 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 13:31:31.226 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:330:getOwner: In OpenSCToken::getOwn
er()
0x7fff7e07b300 13:31:31.140733193388258 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCTok
en::getAcl()
0x7fff7e07b300 13:31:36.4294967963 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:149:verifyPIN: In OpenSCToken
::verifyPIN(1)
0x7fff7e07b300 13:31:36.317106025398939 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:172:_verifyPIN: In OpenSCToken::_verifyPIN(), PIN num is: 1
0x7fff7e07b300 13:31:36.317106025398939 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:186:_verifyPIN:   sc_pkcs15_get_objects(pin_id=01): 2
0x7fff7e07b300 13:31:36.667 [tokend] pkcs15-pin.c:295:sc_pkcs15_verify_pin: called
0x7fff7e07b300 13:31:36.667 [tokend] pkcs15-pin.c:296:sc_pkcs15_verify_pin: PIN(type:0;method:1;len:)
0x7fff7e07b300 13:31:36.667 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:36.317106025398939 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 13:31:36.668 [tokend] sec.c:159:sc_pin_cmd: called
0x7fff7e07b300 13:31:36.668 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 13:31:36.668 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:36.317106025398939 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 13:31:36.668 [tokend] sec.c:159:sc_pin_cmd: called
0x7fff7e07b300 13:31:36.668 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 13:31:36.668 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 13:31:36.140733193388700 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 13:31:36.140733193388700 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 13:31:36.140733193388700 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:20, P1:0, P2:80, data(8) 0x7f........
0x7fff7e07b300 13:31:36.317106025398940 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff7e07b300 13:31:36.140733193388700 [tokend] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   13 bytes] =====================================
00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..
======================================================================
0x7......... 13:31:36.140733193388700 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7ff....... 13:31:36.4294967996 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [   13 bytes] =====================================
00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..
======================================================================
0x7fff7e07b300 13:31:36.140733193388700 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 13:31:36.4294967996 [tokend] apdu.c:187:sc_apdu_log: 
Incoming APDU data [    2 bytes] =====================================
90 00 ..
======================================================================
0x7fff7e07b300 13:31:36.140733193388732 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:36.120259084988 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 13:31:36.-4294966596 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:31:36.700 [tokend] sec.c:206:sc_pin_cmd: returning with: 0 (Success)
0x7fff7e07b300 13:31:36.700 [tokend] pkcs15-pin.c:368:sc_pkcs15_verify_pin: PIN cmd result 0
0x7fff7e07b300 13:31:36.317106025398972 [tokend] pkcs15-pin.c:594:sc_pkcs15_pincache_add: called
0x7fff7e07b300 13:31:36.317106025398972 [tokend] pkcs15-pin.c:634:sc_pkcs15_pincache_add: PIN(PIV Card Holder pin) cached
0x7fff7e07b300 13:31:36.4294967996 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 13:31:36.700 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 13:31:36.700 [tokend] pkcs15-pin.c:373:sc_pkcs15_verify_pin: returning with: 0 (Success)
0x7fff7e07b300 13:31:36.700 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:192:_verifyPIN:   In OpenSCToken::verify returned 0 for pin 1
0x7fff7e07b300 13:31:36.5705853276663055036 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:158:verifyPIN:   About to call BEGIN()
0x7fff7e07b300 13:31:36.3617293440343081679 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 13:31:36.3617293440343081697 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()

The above appears to say that OpenSC.tokend correctly determined what certs are on this token, received request to unlock the card, got the PIN, passed it to the token, got Success in return - but somehow failed to propagate that success to the invoker, because the invoking app still considered the token locked (as if the PIN was rejected).

P.S. I wanted to attach the above log excerpts, but Github interface did not let me. So my apologies for mailbox cluttering, but I saw no choice.

@mouse07410
Copy link
Contributor Author

Update. Trying to use OpenSC.tokend with CAC produces similar results to NEO: tokend is unable to unlock the card (though the log entries indicate a different problem?). The application instead is repeatedly prompting for a PIN.

Again, I have the log (6000 records :). And again, I cannot attach it. So again, the excerpts posted here:

0x1111af000 14:49:16.4121696572838773727 [opensc-pkcs11] pkcs11-global.c:513:C_GetSlotInfo: C_GetSlotInfo() card detect rv 0xE0
0x1111af000 14:49:16.4121696572838773727 [opensc-pkcs11] pkcs11-global.c:530:C_GetSlotInfo: C_GetSlotInfo() flags 0x6
0x1111af000 14:49:16.4121696572838773727 [opensc-pkcs11] pkcs11-global.c:531:C_GetSlotInfo: C_GetSlotInfo(0x1) = CKR_OK
0x7fff7e07b300 14:49:17.140733193388970 [tokend] ctx.c:742:sc_context_create: ===================================
0x7fff7e07b300 14:49:17.140733193388970 [tokend] ctx.c:743:sc_context_create: opensc version: 0.15.0
0x7fff7e07b300 14:49:17.-5908529313027718230 [tokend] reader-pcsc.c:687:pcsc_init: PC/SC options: connect_exclusive=0 disconnect_action=1 transaction_end_action=0 reconnect_action=0 enable_pinpad=1 enable_pace=1
0x7fff7e07b300 14:49:17.4294968234 [tokend] ctx.c:454:load_card_drivers: Unable to load 'piv'.
0x7fff7e07b300 14:49:17.140733193388970 [tokend] reader-pcsc.c:1061:pcsc_detect_readers: called
0x7fff7e07b300 14:49:17.140733193388971 [tokend] reader-pcsc.c:1075:pcsc_detect_readers: Probing PC/SC readers
0x7fff7e07b300 14:49:17.140733193388971 [tokend] reader-pcsc.c:1104:pcsc_detect_readers: Establish PC/SC context
0x7fff7e07b300 14:49:17.140733193388971 [tokend] reader-pcsc.c:1152:pcsc_detect_readers: Found new PC/SC reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:17.140733193388971 [tokend] reader-pcsc.c:288:refresh_attributes: SCR3310 Smart Card Reader check
0x7fff7e07b300 14:49:17.140733193388973 [tokend] reader-pcsc.c:315:refresh_attributes: current  state: 0x00000122
0x7fff7e07b300 14:49:17.140733193388973 [tokend] reader-pcsc.c:316:refresh_attributes: previous state: 0x00000000
0x7fff7e07b300 14:49:17.140733193388973 [tokend] reader-pcsc.c:370:refresh_attributes: card present, changed
0x7fff7e07b300 14:49:17.140733193388973 [tokend] reader-pcsc.c:1183:pcsc_detect_readers: Requesting reader features ...
0x7fff7e07b300 14:49:17.140733193388975 [tokend] reader-pcsc.c:1197:pcsc_detect_readers: SCR3310 Smart Card Reader:SCardConnect(SHARED): 0x7fb700000000
0x7fff7e07b300 14:49:17.943 [tokend] reader-pcsc.c:933:detect_reader_features: called
0x7fff7e07b300 14:49:17.140733193388976 [tokend] reader-pcsc.c:1227:pcsc_detect_readers: returning with: 0 (Success)
0x7fff7e07b300 14:49:17.140733193388976 [tokend] card.c:196:sc_connect_card: called
0x7fff7e07b300 14:49:17.317106025399216 [tokend] reader-pcsc.c:458:pcsc_connect: called
0x7fff7e07b300 14:49:17.140733193388976 [tokend] reader-pcsc.c:288:refresh_attributes: SCR3310 Smart Card Reader check
0x7fff7e07b300 14:49:17.140733193388977 [tokend] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x7fff7e07b300 14:49:17.140733193388978 [tokend] reader-pcsc.c:487:pcsc_connect: Initial protocol: T=0
0x7fff7e07b300 14:49:17.946 [tokend] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:17.140733193388978 [tokend] reader-pcsc.c:487:pcsc_connect: Initial protocol: T=0
0x7fff7e07b300 14:49:17.946 [tokend] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:17.946 [tokend] card.c:976:match_atr_table: ATR try : 3B:DD:18:00:81:31:FE:45:80:F9:A0:00:00:00:77:01:00:70:0A:90:00:8B
0x7fff7e07b300 14:49:17.946 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:49:17.946 [tokend] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:17.946 [tokend] card.c:976:match_atr_table: ATR try : 3B:7F:96:00:00:00:31:B9:64:40:70:14:10:73:94:01:80:82:90:00
0x7fff7e07b300 14:49:17.946 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:49:17.946 [tokend] card.c:976:match_atr_table: ATR try : 3B:7F:96:00:00:00:31:B8:64:40:70:14:10:73:94:01:80:82:90:00
0x7fff7e07b300 14:49:17.946 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:49:17.946 [tokend] card.c:976:match_atr_table: ATR try : 3B:DF:18:FF:81:91:FE:1F:C3:00:31:B8:64:0C:01:EC:C1:73:94:01:80:82:90:00:B3
0x7fff7e07b300 14:49:17.946 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:49:17.946 [tokend] card.c:976:match_atr_table: ATR try : 3B:DC:18:FF:81:91:FE:1F:C3:80:73:C8:21:13:66:01:0B:03:52:00:05:38
0x7fff7e07b300 14:49:17.946 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:49:17.946 [tokend] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:17.946 [tokend] card.c:976:match_atr_table: ATR try : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:17.140423955743666 [tokend] card.c:217:sc_connect_card: matching configured ATRs
0x7fff7e07b300 14:49:17.140423955743666 [tokend] card.c:226:sc_connect_card: trying driver 'authentic'
0x7fff7e07b300 14:49:17.140733193388978 [tokend] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:17.140733193388978 [tokend] card.c:976:match_atr_table: ATR try : 3B:DD:18:00:81:31:FE:45:80:F9:A0:00:00:00:77:01:00:70:0A:90:00:8B
0x7fff7e07b300 14:49:17.140733193388978 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:49:17.140423955743666 [tokend] card.c:226:sc_connect_card: trying driver 'iasecc'
0x7fff7e07b300 14:49:17.140733193388978 [tokend] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:17.140733193388978 [tokend] card.c:976:match_atr_table: ATR try : 3B:7F:96:00:00:00:31:B9:64:40:70:14:10:73:94:01:80:82:90:00
0x7fff7e07b300 14:49:17.140733193388978 [tokend] card.c:979:match_atr_table: ignored - wrong length
.........
0x7fff7e07b300 14:49:17.140733193388978 [tokend] card.c:979:match_atr_table: ignored - wrong length
0x7fff7e07b300 14:49:17.140423955743666 [tokend] card.c:226:sc_connect_card: trying driver 'piv'
0x7fff7e07b300 14:49:17.140733193388978 [tokend] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:17.140733193388978 [tokend] card.c:976:match_atr_table: ATR try : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:17.140423955743666 [tokend] card.c:231:sc_connect_card: matched driver 'PIV-II  for multiple cards'
0x7fff7e07b300 14:49:17.946 [tokend] card-piv.c:2842:piv_match_card: called
0x7fff7e07b300 14:49:17.140733193388978 [tokend] card-piv.c:720:piv_find_aid: called
0x7fff7e07b300 14:49:17.4294968242 [tokend] card-piv.c:683:piv_select_aid: called
0x7fff7e07b300 14:49:17.4294968242 [tokend] card-piv.c:686:piv_select_aid: Got args: aid=6509524, aidlen=9, response=5996f000, responselen=261
0x7fff7e07b300 14:49:17.140733193388978 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:49:17.946 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:17.317106025399218 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 14:49:17.4294968242 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:49:17.140733193388978 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:17.140733193388978 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(9) 0x106509524
0x7fff7e07b300 14:49:17.317106025399218 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:17.140733193388978 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [   14 bytes] =====================================
00 A4 04 00 09 A0 00 00 03 08 00 00 10 00 ..............
======================================================================
0x7fff7e07b300 14:49:17.140733193388979 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x1111af000 14:49:17.4294968290 [opensc-pkcs11] pkcs11-global.c:382:C_GetSlotList: C_GetSlotList(token=0, plug-n-play)
0x1111af000 14:49:17.994 [opensc-pkcs11] reader-pcsc.c:1061:pcsc_detect_readers: called
0x1111af000 14:49:17.994 [opensc-pkcs11] reader-pcsc.c:1075:pcsc_detect_readers: Probing PC/SC readers
0x1111af000 14:49:17.995 [opensc-pkcs11] reader-pcsc.c:1227:pcsc_detect_readers: returning with: 0 (Success)
0x1111af000 14:49:17.4294968291 [opensc-pkcs11] slot.c:333:card_detect_all: Detect all cards
0x1111af000 14:49:17.140733193389027 [opensc-pkcs11] slot.c:197:card_detect: SCR3310 Smart Card Reader: Detecting smart card
0x1111af000 14:49:17.317106025399267 [opensc-pkcs11] sc.c:251:sc_detect_card_presence: called
0x1111af000 14:49:17.317106025399267 [opensc-pkcs11] reader-pcsc.c:378:pcsc_detect_card_presence: called
0x1111af000 14:49:17.4294968291 [opensc-pkcs11] reader-pcsc.c:288:refresh_attributes: SCR3310 Smart Card Reader check
0x1111af000 14:49:17.4294968292 [opensc-pkcs11] reader-pcsc.c:315:refresh_attributes: current  state: 0x00000122
0x1111af000 14:49:17.4294968292 [opensc-pkcs11] reader-pcsc.c:316:refresh_attributes: previous state: 0x00000012
0x1111af000 14:49:17.4294968292 [opensc-pkcs11] reader-pcsc.c:370:refresh_attributes: card present, changed
0x1111af000 14:49:17.4294968292 [opensc-pkcs11] reader-pcsc.c:383:pcsc_detect_card_presence: returning with: 7
0x1111af000 14:49:17.996 [opensc-pkcs11] sc.c:256:sc_detect_card_presence: returning with: 7
0x1111af000 14:49:17.996 [opensc-pkcs11] slot.c:213:card_detect: SCR3310 Smart Card Reader: Card changed
0x1111af000 14:49:17.317106025399268 [opensc-pkcs11] slot.c:157:card_removed: SCR3310 Smart Card Reader: card removed
0x1111af000 14:49:17.140733193389028 [opensc-pkcs11] slot.c:420:slot_token_removed: slot_token_removed(0x1)
0x1111af000 14:49:17.317106025399268 [opensc-pkcs11] pkcs11-session.c:126:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x1) 0
0x1111af000 14:49:17.996 [opensc-pkcs11] slot.c:420:slot_token_removed: slot_token_removed(0x2)
0x1111af000 14:49:17.317106025399268 [opensc-pkcs11] pkcs11-session.c:126:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x2) 0
0x1111af000 14:49:17.996 [opensc-pkcs11] slot.c:420:slot_token_removed: slot_token_removed(0x3)
0x1111af000 14:49:17.317106025399268 [opensc-pkcs11] pkcs11-session.c:126:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x3) 0
0x1111af000 14:49:17.996 [opensc-pkcs11] slot.c:420:slot_token_removed: slot_token_removed(0x4)
0x1111af000 14:49:17.317106025399268 [opensc-pkcs11] pkcs11-session.c:126:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x4) 0
0x1111af000 14:49:17.4294968292 [opensc-pkcs11] sc.c:251:sc_detect_card_presence: called
0x1111af000 14:49:17.317106025399268 [opensc-pkcs11] reader-pcsc.c:378:pcsc_detect_card_presence: called
0x1111af000 14:49:17.4294968292 [opensc-pkcs11] reader-pcsc.c:288:refresh_attributes: SCR3310 Smart Card Reader check
0x1111af000 14:49:17.4294968293 [opensc-pkcs11] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x1111af000 14:49:17.4294968293 [opensc-pkcs11] reader-pcsc.c:383:pcsc_detect_card_presence: returning with: 5
0x1111af000 14:49:17.997 [opensc-pkcs11] sc.c:256:sc_detect_card_presence: returning with: 5
0x1111af000 14:49:17.997 [opensc-pkcs11] slot.c:234:card_detect: SCR3310 Smart Card Reader: First seen the card
0x1111af000 14:49:17.997 [opensc-pkcs11] slot.c:242:card_detect: SCR3310 Smart Card Reader: Connecting ...
0x1111af000 14:49:17.4294968293 [opensc-pkcs11] card.c:196:sc_connect_card: called
0x1111af000 14:49:17.317106025399269 [opensc-pkcs11] reader-pcsc.c:458:pcsc_connect: called
0x1111af000 14:49:17.4294968293 [opensc-pkcs11] reader-pcsc.c:288:refresh_attributes: SCR3310 Smart Card Reader check
0x1111af000 14:49:17.4294968293 [opensc-pkcs11] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.4294967326 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
61 18 a.
======================================================================
0x7fff7e07b300 14:49:18.140733193388062 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.140733193388062 [tokend] apdu.c:443:sc_get_response: called
0x7fff7e07b300 14:49:18.140733193388062 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:49:18.030 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:18.140733193388062 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:49:18.140733193388062 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:18.140733193388062 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:C0, P1:0, P2:0, data(0) 0x0
0x7fff7e07b300 14:49:18.317106025398302 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:18.140733193388062 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [    5 bytes] =====================================
00 C0 00 00 18 .....
======================================================================
0x7fff7e07b300 14:49:18.140733193388062 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:18.4294967331 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [   26 bytes] =====================================
61 16 4F 0B A0 00 00 03 08 00 00 10 00 01 00 79 a.O............y
07 4F 05 A0 00 00 03 08 90 00                   .O........
======================================================================
0x7fff7e07b300 14:49:18.140733193388067 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.120259084323 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.-4294967261 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 14:49:18.035 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 14:49:18.3539882289829773347 [tokend] card-piv.c:701:piv_select_aid: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.3617015263901253667 [tokend] card-piv.c:735:piv_find_aid: found PIX
0x7fff7e07b300 14:49:18.3617015263901253667 [tokend] card-piv.c:749:piv_find_aid: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.035 [tokend] card-piv.c:2860:piv_init: called
0x7fff7e07b300 14:49:18.035 [tokend] card-piv.c:2876:piv_init: Max send = 0 recv = 0
0x7fff7e07b300 14:49:18.140733193388067 [tokend] card-piv.c:720:piv_find_aid: called
0x7fff7e07b300 14:49:18.4294967331 [tokend] card-piv.c:683:piv_select_aid: called
0x7fff7e07b300 14:49:18.4294967331 [tokend] card-piv.c:686:piv_select_aid: Got args: aid=6509524, aidlen=9, response=5996f150, responselen=261
0x7fff7e07b300 14:49:18.140733193388067 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:49:18.035 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:18.317106025398307 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x1111af000 14:49:18.4294967332 [opensc-pkcs11] reader-pcsc.c:487:pcsc_connect: Initial protocol: T=0
0x1111af000 14:49:18.036 [opensc-pkcs11] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x1111af000 14:49:18.036 [opensc-pkcs11] card.c:976:match_atr_table: ATR try : 3B:DD:18:00:81:31:FE:45:80:F9:A0:00:00:00:77:01:00:70:0A:90:00:8B
0x1111af000 14:49:18.036 [opensc-pkcs11] card.c:979:match_atr_table: ignored - wrong length
.............
0x1111af000 14:49:18.036 [opensc-pkcs11] card.c:979:match_atr_table: ignored - wrong length
0x1111af000 14:49:18.4294967332 [opensc-pkcs11] card.c:226:sc_connect_card: trying driver 'piv'
0x1111af000 14:49:18.036 [opensc-pkcs11] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x1111af000 14:49:18.036 [opensc-pkcs11] card.c:976:match_atr_table: ATR try : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x1111af000 14:49:18.4294967332 [opensc-pkcs11] card.c:231:sc_connect_card: matched driver 'PIV-II  for multiple cards'
0x1111af000 14:49:18.036 [opensc-pkcs11] card-piv.c:2842:piv_match_card: called
0x1111af000 14:49:18.140733193388068 [opensc-pkcs11] card-piv.c:720:piv_find_aid: called
0x1111af000 14:49:18.4294967332 [opensc-pkcs11] card-piv.c:683:piv_select_aid: called
0x1111af000 14:49:18.4294967332 [opensc-pkcs11] card-piv.c:686:piv_select_aid: Got args: aid=10e47524, aidlen=9, response=111ae680, responselen=261
0x1111af000 14:49:18.4294967332 [opensc-pkcs11] apdu.c:563:sc_transmit_apdu: called
0x1111af000 14:49:18.036 [opensc-pkcs11] card.c:394:sc_lock: called
0x1111af000 14:49:18.317106025398308 [opensc-pkcs11] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 14:49:18.4294967332 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:49:18.140733193388068 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:18.140733193388068 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(9) 0x106509524
0x7fff7e07b300 14:49:18.317106025398308 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:18.140733193388068 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [   14 bytes] =====================================
00 A4 04 00 09 A0 00 00 03 08 00 00 10 00 ..............
======================================================================
0x7fff7e07b300 14:49:18.140733193388068 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:18.4294967370 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
61 18 a.
======================================================================
0x7fff7e07b300 14:49:18.140733193388106 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.140733193388106 [tokend] apdu.c:443:sc_get_response: called
0x7fff7e07b300 14:49:18.140733193388106 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:49:18.074 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:18.140733193388106 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:49:18.140733193388106 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:18.140733193388106 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:C0, P1:0, P2:0, data(0) 0x0
0x7fff7e07b300 14:49:18.317106025398346 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:18.140733193388106 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [    5 bytes] =====================================
00 C0 00 00 18 .....
======================================================================
0x7fff7e07b300 14:49:18.140733193388106 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:18.4294967375 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [   26 bytes] =====================================
61 16 4F 0B A0 00 00 03 08 00 00 10 00 01 00 79 a.O............y
07 4F 05 A0 00 00 03 08 90 00                   .O........
======================================================================
0x7fff7e07b300 14:49:18.140733193388111 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.120259084367 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.-4294967217 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 14:49:18.140733193388111 [tokend] apdu.c:514:sc_get_response: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.120259084367 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.-4294967217 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 14:49:18.079 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 14:49:18.3539882289829773391 [tokend] card-piv.c:701:piv_select_aid: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.3617015263901253711 [tokend] card-piv.c:735:piv_find_aid: found PIX
0x7fff7e07b300 14:49:18.3617015263901253711 [tokend] card-piv.c:749:piv_find_aid: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.140733193388111 [tokend] card-piv.c:2617:piv_process_history: called
0x7fff7e07b300 14:49:18.317106025398351 [tokend] card-piv.c:945:piv_get_cached_data: called
0x7fff7e07b300 14:49:18.317106025398351 [tokend] card-piv.c:946:piv_get_cached_data: #11
0x7fff7e07b300 14:49:18.317106025398351 [tokend] card-piv.c:986:piv_get_cached_data: get #11
0x7fff7e07b300 14:49:18.140733193388111 [tokend] card-piv.c:879:piv_get_data: called
0x7fff7e07b300 14:49:18.140733193388111 [tokend] card-piv.c:880:piv_get_data: #11
0x7fff7e07b300 14:49:18.140733193388111 [tokend] card-piv.c:899:piv_get_data: get len of #11
0x7fff7e07b300 14:49:18.140733193388112 [tokend] card-piv.c:447:piv_general_io: called
.........
0x7fff7e07b300 14:49:18.140733193388506 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.140733193388507 [tokend] apdu.c:443:sc_get_response: called
0x7fff7e07b300 14:49:18.140733193388507 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:49:18.475 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:18.140733193388507 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:49:18.140733193388507 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:18.140733193388507 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:C0, P1:0, P2:0, data(0) 0x0
0x7fff7e07b300 14:49:18.317106025398747 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:18.140733193388507 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [    5 bytes] =====================================
00 C0 00 00 00 .....
======================================================================
0x7fff7e07b300 14:49:18.140733193388507 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:18.4294967829 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [  258 bytes] =====================================
53 82 07 2D 30 19 D5 78 10 DA 10 CD 6C 12 71 10 S..-0..x....l.q.
................[CAC certificate]..........
61 00                                           a.
======================================================================
0x7fff7e07b300 14:49:18.140733193388565 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.120259084821 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.-4294966763 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 14:49:18.3544368301566067221 [tokend] apdu.c:514:sc_get_response: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.4412750542095254037 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.-4294966763 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 14:49:18.140423955743253 [tokend] card-piv.c:496:piv_general_io: DEE r=0 apdu.resplen=8 sw1=90 sw2=00
0x7fff7e07b300 14:49:18.140733193388565 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 14:49:18.4294967829 [tokend] card-piv.c:558:piv_general_io: returning with: 1841
0x7fff7e07b300 14:49:18.4294967829 [tokend] card-piv.c:919:piv_get_data: get buffer for #1 len 1841
0x7fff7e07b300 14:49:18.4294967829 [tokend] card-piv.c:447:piv_general_io: called
0x7fff7e07b300 14:49:18.4294967829 [tokend] card-piv.c:450:piv_general_io: cb 3f ff 5 : 255 256
0x7fff7e07b300 14:49:18.533 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:18.533 [tokend] card-piv.c:490:piv_general_io: calling sc_transmit_apdu flags=1 le=256, resplen=1841, resp=0x7fb7a4800000
0x7fff7e07b300 14:49:18.140733193388565 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:49:18.533 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:18.140733193388565 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:49:18.140733193388565 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:18.140733193388565 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:CB, P1:3F, P2:FF, data(5) 0x7fff5996a0f8
0x7fff7e07b300 14:49:18.317106025398805 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:18.140733193388565 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [   10 bytes] =====================================
00 CB 3F FF 05 5C 03 5F C1 02 ..?..\._..
======================================================================
0x7fff7e07b300 14:49:18.140733193388565 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:18.4294967946 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
61 00 a.
======================================================================
0x7fff7e07b300 14:49:18.140733193388682 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.140733193388682 [tokend] apdu.c:443:sc_get_response: called
0x7fff7e07b300 14:49:18.140733193388682 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:49:18.650 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:18.140733193388682 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:49:18.140733193388682 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:18.140733193388682 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:C0, P1:0, P2:0, data(0) 0x0
0x7fff7e07b300 14:49:18.317106025398922 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:18.140733193388682 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [    5 bytes] =====================================
00 C0 00 00 00 .....
======================================================================
0x7fff7e07b300 14:49:18.140733193388682 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:18.4294967978 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [  258 bytes] =====================================
53 82 07 2D 30 19 D5 78 10 DA 10 CD 6C 12 71 10 S..-0..x....l.q.
............[CAC certificate]............
61 00                                           a.
======================================================================
0x7fff7e07b300 14:49:18.140733193388714 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.120259084970 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.-4294966614 [tokend] card.c:434:sc_unlock: called
.........
0x1111af000 14:49:37.041 [opensc-pkcs11] slot.c:323:card_detect: SCR3310 Smart Card Reader: Detection ended
0x1111af000 14:49:37.4294967337 [opensc-pkcs11] slot.c:352:card_detect_all: All cards detected
0x1111af000 14:49:37.-4294967255 [opensc-pkcs11] pkcs11-global.c:503:C_GetSlotInfo: C_GetSlotInfo() get slot rv 0
0x1111af000 14:49:37.140733193388073 [opensc-pkcs11] slot.c:197:card_detect: SCR3310 Smart Card Reader: Detecting smart card
0x1111af000 14:49:37.317106025398313 [opensc-pkcs11] sc.c:251:sc_detect_card_presence: called
0x1111af000 14:49:37.317106025398313 [opensc-pkcs11] reader-pcsc.c:378:pcsc_detect_card_presence: called
0x1111af000 14:49:37.4294967337 [opensc-pkcs11] reader-pcsc.c:288:refresh_attributes: SCR3310 Smart Card Reader check
0x1111af000 14:49:37.4294967338 [opensc-pkcs11] reader-pcsc.c:307:refresh_attributes: returning with: 0 (Success)
0x1111af000 14:49:37.4294967338 [opensc-pkcs11] reader-pcsc.c:383:pcsc_detect_card_presence: returning with: 5
0x1111af000 14:49:37.042 [opensc-pkcs11] sc.c:256:sc_detect_card_presence: returning with: 5
0x1111af000 14:49:37.042 [opensc-pkcs11] slot.c:323:card_detect: SCR3310 Smart Card Reader: Detection ended
0x1111af000 14:49:37.4294967338 [opensc-pkcs11] pkcs11-global.c:513:C_GetSlotInfo: C_GetSlotInfo() card detect rv 0x0
0x1111af000 14:49:37.4294967338 [opensc-pkcs11] pkcs11-global.c:530:C_GetSlotInfo: C_GetSlotInfo() flags 0x7
0x1111af000 14:49:37.4294967338 [opensc-pkcs11] pkcs11-global.c:531:C_GetSlotInfo: C_GetSlotInfo(0x1) = CKR_OK
0x1111af000 14:49:37.4294967338 [opensc-pkcs11] pkcs11-session.c:187:C_GetSessionInfo: C_GetSessionInfo(hSession:0x10d0f9e80)
0x1111af000 14:49:37.4294967338 [opensc-pkcs11] pkcs11-session.c:195:C_GetSessionInfo: C_GetSessionInfo(slot:0x1)
0x1111af000 14:49:37.4294967338 [opensc-pkcs11] pkcs11-session.c:212:C_GetSessionInfo: C_GetSessionInfo(0x10d0f9e80) = CKR_OK
0x7fff7e07b300 14:49:37.4294968081 [opensc-pkcs11] pkcs11-session.c:259:C_Login: C_Login(0x10d0f9e80, 1)
0x7fff7e07b300 14:49:37.4294968081 [opensc-pkcs11] pkcs11-session.c:279:C_Login: C_Login() slot->login_user 8589934591
0x7fff7e07b300 14:49:37.4294968081 [opensc-pkcs11] pkcs11-session.c:288:C_Login: C_Login() userType 1
0x7fff7e07b300 14:49:37.4294968081 [opensc-pkcs11] framework-pkcs15.c:1414:pkcs15_login: pkcs15-login: userType 0x1, PIN length 7
0x7fff7e07b300 14:49:37.4294968081 [opensc-pkcs11] pkcs15-pin.c:295:sc_pkcs15_verify_pin: called
0x7fff7e07b300 14:49:37.4294968081 [opensc-pkcs11] pkcs15-pin.c:296:sc_pkcs15_verify_pin: PIN(type:0;method:1;len:)
0x7fff7e07b300 14:49:37.785 [opensc-pkcs11] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:37.317106025399057 [opensc-pkcs11] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 14:49:37.786 [opensc-pkcs11] sec.c:159:sc_pin_cmd: called
0x7fff7e07b300 14:49:37.786 [opensc-pkcs11] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:49:37.786 [opensc-pkcs11] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:37.140733193388818 [opensc-pkcs11] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:49:37.140733193388818 [opensc-pkcs11] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:37.140733193388818 [opensc-pkcs11] apdu.c:389:sc_single_transmit: CLA:0, INS:20, P1:0, P2:80, data(8) 0x.......
0x7fff7e07b300 14:49:37.317106025399058 [opensc-pkcs11] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:37.140733193388818 [opensc-pkcs11] apdu.c:187:sc_apdu_log:
Outgoing APDU data [   13 bytes] =====================================
00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..
======================================================================
0x7fff7e07b300 14:49:37.140733193388818 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:37.4294968114 [opensc-pkcs11] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
6A 86 j.
======================================================================
0x7fff7e07b300 14:49:37.140733193388850 [opensc-pkcs11] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:37.120259085106 [opensc-pkcs11] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:37.-4294966478 [opensc-pkcs11] card.c:434:sc_unlock: called
0x7fff7e07b300 14:49:37.-4294966478 [opensc-pkcs11] iso7816.c:121:iso7816_check_sw: Incorrect parameters P1-P2
0x7fff7e07b300 14:49:37.818 [opensc-pkcs11] sec.c:206:sc_pin_cmd: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 14:49:37.818 [opensc-pkcs11] pkcs15-pin.c:368:sc_pkcs15_verify_pin: PIN cmd result -1205
0x7fff7e07b300 14:49:37.140733193388850 [opensc-pkcs11] card.c:434:sc_unlock: called
0x7fff7e07b300 14:49:37.818 [opensc-pkcs11] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 14:49:37.818 [opensc-pkcs11] pkcs15-pin.c:373:sc_pkcs15_verify_pin: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 14:49:37.818 [opensc-pkcs11] framework-pkcs15.c:1518:pkcs15_login: PKCS15 verify PIN returned -1205
0x7fff7e07b300 14:49:37.140733193388850 [opensc-pkcs11] misc.c:61:sc_to_cryptoki_error_common: libopensc return value: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 14:49:37.7309464631855022898 [opensc-pkcs11] pkcs11-session.c:290:C_Login: fLogin() rv 32
0x7fff7e07b300 14:49:37.140733193388867 [opensc-pkcs11] pkcs11-session.c:187:C_GetSessionInfo: C_GetSessionInfo(hSession:0x10d0f9e80)
0x7fff7e07b300 14:49:37.140733193388867 [opensc-pkcs11] pkcs11-session.c:195:C_GetSessionInfo: C_GetSessionInfo(slot:0x1)
0x7fff7e07b300 14:49:37.140733193388867 [opensc-pkcs11] pkcs11-session.c:212:C_GetSessionInfo: C_GetSessionInfo(0x10d0f9e80) = CKR_OK
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] pkcs11-object.c:336:C_FindObjectsInit: C_FindObjectsInit(slot = 1)
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] pkcs11-object.c:337:C_FindObjectsInit: C_FindObjectsInit(): CKA_TOKEN = TRUE
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] pkcs11-object.c:337:C_FindObjectsInit: C_FindObjectsInit(): CKA_CLASS = CKO_CERTIFICATE
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] misc.c:139:session_start_operation: called
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] misc.c:140:session_start_operation: Session 0x10d0f9e80, type 0
0x7fff7e07b300 14:49:37.-4294966418 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10d0724c0
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:3325:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x7fff7e07b300 14:49:37.3270584670684709742 [opensc-pkcs11] pkcs11-object.c:366:C_FindObjectsInit: Object 1/218571968: Private object and not logged in.
0x7fff7e07b300 14:49:37.3270584670684709742 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10d072820
0x7fff7e07b300 14:49:37.4294968174 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x7fff7e07b300 14:49:37.8391439066347864942 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/218572832: Attribute 0x0 does NOT match.
0x7fff7e07b300 14:49:37.8391439066347864942 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10d072ac0
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] framework-pkcs15.c:3228:pkcs15_cert_cmp_attribute: pkcs15_cert_cmp_attribute() called
.........
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x7fff7e07b300 14:49:37.-4294966418 [opensc-pkcs11] pkcs11-object.c:389:C_FindObjectsInit: Object 1/218574080 matches
0x7fff7e07b300 14:49:37.-4294966418 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10d072760
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:3325:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x7fff7e07b300 14:49:37.3270584670684709742 [opensc-pkcs11] pkcs11-object.c:366:C_FindObjectsInit: Object 1/218572640: Private object and not logged in.
0x7fff7e07b300 14:49:37.3270584670684709742 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10d0728e0
0x7fff7e07b300 14:49:37.4294968174 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:3852:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x7fff7e07b300 14:49:37.8391439066347864942 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/218573024: Attribute 0x0 does NOT match.
0x7fff7e07b300 14:49:37.8391439066347864942 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10d072e20
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] framework-pkcs15.c:3228:pkcs15_cert_cmp_attribute: pkcs15_cert_cmp_attribute() called
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] framework-pkcs15.c:3228:pkcs15_cert_cmp_attribute: pkcs15_cert_cmp_attribute() called
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x7fff7e07b300 14:49:37.878 [opensc-pkcs11] framework-pkcs15.c:3130:pkcs15_cert_get_attribute: pkcs15_cert_get_attribute() called
0x7fff7e07b300 14:49:37.-4294966418 [opensc-pkcs11] pkcs11-object.c:389:C_FindObjectsInit: Object 1/218574368 matches
0x7fff7e07b300 14:49:37.-4294966418 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10d0b0d60
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] pkcs11-object.c:366:C_FindObjectsInit: Object 1/218828128: Private object and not logged in.
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10d0b0dc0
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] framework-pkcs15.c:4111:pkcs15_dobj_get_attribute: pkcs15_dobj_get_attribute() called
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] pkcs11-object.c:366:C_FindObjectsInit: Object 1/218828224: Private object and not logged in.
0x7fff7e07b300 14:49:37.140733193388910 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x10d0f9040
..........

Here's what pkcs11-tool has to say about this CAC (everything appears to function as expected):

$ pkcs11-tool --slot-index 2 --login --test
Using slot with index 2 (0x5)
Logging in to "PIV_II (PIV Card Holder pin)".
Please enter User PIN: 
C_SeedRandom() and C_GenerateRandom():
  seeding (C_SeedRandom) not supported
  ERR: C_GenerateRandom failed: CKR_DATA_INVALID (0x20)
Digests:
  all 4 digest functions seem to work
  MD5: OK
  SHA-1: OK
  RIPEMD160: OK
Signatures (currently only RSA signatures)
  testing key 0 (PIV AUTH key) 
  all 4 signature functions seem to work
  testing signature mechanisms:
    RSA-X-509: OK
    RSA-PKCS: OK
    SHA1-RSA-PKCS: OK
    MD5-RSA-PKCS: OK
    RIPEMD160-RSA-PKCS: OK
    SHA256-RSA-PKCS: OK
  testing key 1 (2048 bits, label=SIGN key) with 1 signature mechanism
Logging in to "PIV_II (PIV Card Holder pin)".
Please enter context specific PIN: 
    MD5-RSA-PKCS: OK
  testing key 2 (2048 bits, label=KEY MAN key) with 1 signature mechanism -- can't be used to sign/verify, skipping
Verify (currently only for RSA):
  testing key 0 (PIV AUTH key)
    RSA-X-509:   ERR: C_Verify() returned CKR_GENERAL_ERROR (0x5)
  testing key 1 (SIGN key) with 1 mechanism
    RSA-X-509: Logging in to "PIV_II (PIV Card Holder pin)".
Please enter context specific PIN: 
  ERR: C_Verify() returned CKR_GENERAL_ERROR (0x5)
  testing key 2 (KEY MAN key) with 1 mechanism
 -- can't be used to sign/verify, skipping
Unwrap: not implemented
Decryption (RSA)
  testing key 0 (PIV AUTH key) 
    RSA-X-509: OK
    RSA-PKCS: OK
  testing key 1 (SIGN key) 
    RSA-X-509: OK
    RSA-PKCS: OK
  testing key 2 (KEY MAN key) 
    RSA-X-509: OK
    RSA-PKCS: OK
3 errors

@dengert
Copy link
Member

dengert commented Oct 7, 2015

The VERIFY of the PIN command failed. (I realize you have replaced the numbers with xx.)

00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..

0x7fff7e07b300 14:49:37.140733193388818 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:37.4294968114 [opensc-pkcs11] apdu.c:187:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================
6A 86 j.

6A 86 is "Incorrect parameter in P1 or P2"

On PIV, P1 is always 00 P2 can be 00 for Global Pin, or or 80 for application PIN.

The choice of which PIN (i.e. the P2 parameter) is read from the Discovery object as defined in NIST 800-73-3 Part1
Section 3.2.6 Discovery Object

The reading of the discovery object is not shown in the debug log. It would be an outgoing APDU of:
00 CB 3F FF 03 5C 01 7E 14

If it fails what is the status bytes. If it reads it
the Incoming APDU data would look something like:

7E 12 4F 0B A0 00 00 03 08 00 00 10 00 01 00 5F ~.O............_
2F 02 40 00 90 00

Can you find this in the log?

It may be that the CAC card does not return a valid Discovery object
or the tokend is not making all the correct calls to setup the card.

Your PIN may be correct, but the CAC card may not like the P2=80.


Reply to this email directly or view it on GitHub #570 (comment).

Douglas E. Engert [email protected]

@mouse07410
Copy link
Contributor Author

On Oct 7, 2015, at 17:58 , Doug Engert [email protected] wrote:

The VERIFY of the PIN command failed. (I realize you have replaced the numbers with xx.)

00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..

0x7fff7e07b300 14:49:37.140733193388818 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:37.4294968114 [opensc-pkcs11] apdu.c:187:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================
6A 86 j.

6A 86 is "Incorrect parameter in P1 or P2”

And that’s weird. I’ll have to re-run this all.

The reading of the discovery object is not shown in the debug log. It would be an outgoing APDU of:
00 CB 3F FF 03 5C 01 7E 14

If it fails what is the status bytes. If it reads it
the Incoming APDU data would look something like:

7E 12 4F 0B A0 00 00 03 08 00 00 10 00 01 00 5F ~.O............_
2F 02 40 00 90 00

Can you find this in the log?

Will do my best.

It may be that the CAC card does not return a valid Discovery object
or the tokend is not making all the correct calls to setup the card.

This is the very standard current/fresh DoD CAC. The likelihood of it not being conformant to “de-facto standard” is negligible, not to mention that all the other token’s around (PKard, Centrify, CACKey) all successfully operate with in all the way (accessing web sites, and securing S/MIME email).

Your PIN may be correct, but the CAC card may not like the P2=80.

I’m pretty sure my PIN is correct - otherwise my CAC would have been locked/blocked by now. :-)

It appears that the problem is with P1, not P2. :-(

And since P1=00 is a valid code, the cause must lie elsewhere.

Uri Blumenthal
[email protected]

@dengert
Copy link
Member

dengert commented Oct 8, 2015

Issue may be that Discovery Object is not correct, or not parsed correctly,
and others like PKcard, Centrify, CACKey don't look at discovery object.

Could also be problem with opensc.tokend overwriting something.

On 10/7/2015 6:46 PM, Mouse wrote:

On Oct 7, 2015, at 17:58 , Doug Engert [email protected] wrote:

The VERIFY of the PIN command failed. (I realize you have replaced the numbers with xx.)

00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..

0x7fff7e07b300 14:49:37.140733193388818 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:37.4294968114 [opensc-pkcs11] apdu.c:187:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================
6A 86 j.

6A 86 is "Incorrect parameter in P1 or P2”

And that’s weird. I’ll have to re-run this all.

The reading of the discovery object is not shown in the debug log. It would be an outgoing APDU of:
00 CB 3F FF 03 5C 01 7E 14

If it fails what is the status bytes. If it reads it
the Incoming APDU data would look something like:

7E 12 4F 0B A0 00 00 03 08 00 00 10 00 01 00 5F ~.O............_
2F 02 40 00 90 00

Can you find this in the log?

Will do my best.

It may be that the CAC card does not return a valid Discovery object
or the tokend is not making all the correct calls to setup the card.

This is the very standard current/fresh DoD CAC. The likelihood of it not being conformant to “de-facto standard” is negligible, not to mention that all the other token’s around (PKard, Centrify,
CACKey) all successfully operate with in all the way (accessing web sites, and securing S/MIME email).

Your PIN may be correct, but the CAC card may not like the P2=80.

I’m pretty sure my PIN is correct - otherwise my CAC would have been locked/blocked by now. :-)

Whether the card likes P2=80, I’ve no idea. :-(

Uri Blumenthal
[email protected]


Reply to this email directly or view it on GitHub #570 (comment).

Douglas E. Engert [email protected]

@mouse07410
Copy link
Contributor Author

Another thing - file /tmp/opensc-debug.log grows rapidly even with “debug = 3;”, but file “/tmp/opensc-tokend.log” stays empty. Is it normal? Should anything get recorded in /tmp/opensc-tokend.log? Is it all getting dumped into /tmp/opensc-debug.log , or am I missing some setting that would provide tokend-specific logging?

On Oct 7, 2015, at 21:16 , Doug Engert <[email protected]mailto:[email protected]> wrote:
Issue may be that Discovery Object is not correct, or not parsed correctly,
and others like PKcard, Centrify, CACKey don't look at discovery object.

Could also be problem with opensc.tokend overwriting something.

On 10/7/2015 6:46 PM, Mouse wrote:

On Oct 7, 2015, at 17:58 , Doug Engert <[email protected]mailto:[email protected]> wrote:

The VERIFY of the PIN command failed. (I realize you have replaced the numbers with xx.)

00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..

0x7fff7e07b300 14:49:37.140733193388818 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:37.4294968114 [opensc-pkcs11] apdu.c:187:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================
6A 86 j.

6A 86 is "Incorrect parameter in P1 or P2”

And that’s weird. I’ll have to re-run this all.

The reading of the discovery object is not shown in the debug log. It would be an outgoing APDU of:
00 CB 3F FF 03 5C 01 7E 14

If it fails what is the status bytes. If it reads it
the Incoming APDU data would look something like:

7E 12 4F 0B A0 00 00 03 08 00 00 10 00 01 00 5F ~.O............_
2F 02 40 00 90 00

Can you find this in the log?

Will do my best.

It may be that the CAC card does not return a valid Discovery object
or the tokend is not making all the correct calls to setup the card.

This is the very standard current/fresh DoD CAC. The likelihood of it not being conformant to “de-facto standard” is negligible, not to mention that all the other token’s around (PKard, Centrify,
CACKey) all successfully operate with in all the way (accessing web sites, and securing S/MIME email).

Your PIN may be correct, but the CAC card may not like the P2=80.

I’m pretty sure my PIN is correct - otherwise my CAC would have been locked/blocked by now. :-)

Whether the card likes P2=80, I’ve no idea. :-(

Uri Blumenthal
[email protected]:[email protected]


Reply to this email directly or view it on GitHub #570 (comment).

Douglas E. Engert <[email protected]mailto:[email protected]>


Reply to this email directly or view it on GitHubhttps://github.com//issues/570#issuecomment-146387333.

Uri Blumenthal
[email protected]:[email protected]

@dengert
Copy link
Member

dengert commented Oct 8, 2015

The debug file is written by routines in libopensc. Did you find a reference to opensc-tokend.log in some code?

On 10/7/2015 9:36 PM, Mouse wrote:

Another thing - file /tmp/opensc-debug.log grows rapidly even with “debug = 3;”, but file “/tmp/opensc-tokend.log” stays empty. Is it normal? Should anything get recorded in /tmp/opensc-tokend.log? Is
it all getting dumped into /tmp/opensc-debug.log , or am I missing some setting that would provide tokend-specific logging?

On Oct 7, 2015, at 21:16 , Doug Engert <[email protected]mailto:[email protected]> wrote:
Issue may be that Discovery Object is not correct, or not parsed correctly,
and others like PKcard, Centrify, CACKey don't look at discovery object.

Could also be problem with opensc.tokend overwriting something.

On 10/7/2015 6:46 PM, Mouse wrote:

On Oct 7, 2015, at 17:58 , Doug Engert <[email protected]mailto:[email protected]> wrote:

The VERIFY of the PIN command failed. (I realize you have replaced the numbers with xx.)

00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..

0x7fff7e07b300 14:49:37.140733193388818 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:37.4294968114 [opensc-pkcs11] apdu.c:187:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================
6A 86 j.

6A 86 is "Incorrect parameter in P1 or P2”

And that’s weird. I’ll have to re-run this all.

The reading of the discovery object is not shown in the debug log. It would be an outgoing APDU of:
00 CB 3F FF 03 5C 01 7E 14

If it fails what is the status bytes. If it reads it
the Incoming APDU data would look something like:

7E 12 4F 0B A0 00 00 03 08 00 00 10 00 01 00 5F ~.O............_
2F 02 40 00 90 00

Can you find this in the log?

Will do my best.

It may be that the CAC card does not return a valid Discovery object
or the tokend is not making all the correct calls to setup the card.

This is the very standard current/fresh DoD CAC. The likelihood of it not being conformant to “de-facto standard” is negligible, not to mention that all the other token’s around (PKard, Centrify,
CACKey) all successfully operate with in all the way (accessing web sites, and securing S/MIME email).

Your PIN may be correct, but the CAC card may not like the P2=80.

I’m pretty sure my PIN is correct - otherwise my CAC would have been locked/blocked by now. :-)

Whether the card likes P2=80, I’ve no idea. :-(

Uri Blumenthal
[email protected]:[email protected]


Reply to this email directly or view it on GitHub #570 (comment).

Douglas E. Engert <[email protected]mailto:[email protected]>


Reply to this email directly or view it on GitHubhttps://github.com//issues/570#issuecomment-146387333.

Uri Blumenthal
[email protected]:[email protected]


Reply to this email directly or view it on GitHub #570 (comment).

Douglas E. Engert [email protected]

@mouse07410
Copy link
Contributor Author

The debug file is written by routines in libopensc. Did you find a reference to opensc-tokend.log in some code?

No, and I don't even know where to look. :-(

But the file /tmp/opensc-tokend.log is created regularly, i.e. if I delete it - it re-appears, albeit consistently empty.

@dengert
Copy link
Member

dengert commented Oct 8, 2015

OK, Don't know why. May be a minor bug.

Did you find any entries in the opensc-debug log with the CAC card reading the Discovery Object?

Grep for Discover
or a incoming APDU data 7E in first byte.

CAC cards have a long history, and the transition to PIV may cause problems.
In the CAC documents, what the card-piv.c suppots is referred to as "PIV EP".
card-piv.c does not look for any CAC specific files.

It might be the card you have was issued by DoD and the Discovery object used only by PIV is
not correct. Or there is a bug in OpenSC or tokend.

On 10/8/2015 9:28 AM, Mouse wrote:

The debug file is written by routines in libopensc. Did you find a reference to opensc-tokend.log in some code?

No, and I don't even know where to look. :-(

But the file /tmp/opensc-tokend.log is created regularly, i.e. if I delete it - it re-appears, albeit consistently empty.


Reply to this email directly or view it on GitHub #570 (comment).

Douglas E. Engert [email protected]

@mouse07410
Copy link
Contributor Author

I did not see any entry of "Discover". I see some for discovery (see below). I found no incoming APDU starting with 7E - I hope I haven't redacted it out :-( :-(

Apparently CAC does not have all the PIV containers - I wonder if some of those are optional...?

0x7fff7e07b300 14:49:18.140733193388229 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:18.140733193388229 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:CB, P1:3F, P2:FF, data(3) 0x7fff5996f158
0x7fff7e07b300 14:49:18.317106025398469 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:18.140733193388229 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [    8 bytes] =====================================
00 CB 3F FF 03 5C 01 7E ..?..\.~
======================================================================
0x7fff7e07b300 14:49:18.140733193388229 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:18.4294967503 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
6A 80 j.
======================================================================
0x7fff7e07b300 14:49:18.140733193388239 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.120259084495 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.-4294967089 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 14:49:18.140423955742927 [tokend] card-piv.c:496:piv_general_io: DEE r=0 apdu.resplen=0 sw1=6a sw2=80
0x7fff7e07b300 14:49:18.317106025398479 [tokend] iso7816.c:121:iso7816_check_sw: Incorrect parameters in the data field
0x7fff7e07b300 14:49:18.140423955742927 [tokend] card-piv.c:508:piv_general_io: Card returned error
0x7fff7e07b300 14:49:18.140733193388239 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 14:49:18.207 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 14:49:18.208 [tokend] card-piv.c:558:piv_general_io: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 14:49:18.4294967504 [tokend] card-piv.c:933:piv_get_data: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 14:49:18.4294967504 [tokend] card-piv.c:1014:piv_get_cached_data: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 14:49:18.140423955742928 [tokend] card-piv.c:2576:piv_process_discovery: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.140423955742928 [tokend] card-piv.c:2919:piv_init: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.208 [tokend] card.c:307:sc_connect_card: card info name:'PIV-II card', type:14001, flags:0x0, max_send/recv_size:255/256
0x7fff7e07b300 14:49:18.140733193388240 [tokend] card.c:1332:sc_card_sm_check: called
0x7fff7e07b300 14:49:18.140733193388240 [tokend] card.c:1333:sc_card_sm_check: card->sm_ctx.ops.open 0x0
0x7fff7e07b300 14:49:18.17141214478544 [tokend] card.c:965:match_atr_table: ATR     : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:18.17141214478544 [tokend] card.c:976:match_atr_table: ATR try : 3b:db:96:00:80:1f:03:00:31:c0:64:b0:f3:10:00:07:90:00:80
0x7fff7e07b300 14:49:18.140733193388240 [tokend] card.c:1341:sc_card_sm_check: returning with: 0 (Success)
.........
0x1111af000 14:49:18.4294967548 [opensc-pkcs11] card-piv.c:2805:piv_process_history: returning with: 0 (Success)
0x1111af000 14:49:18.3763377823679512828 [opensc-pkcs11] card-piv.c:945:piv_get_cached_data: called
0x1111af000 14:49:18.3763377823679512828 [opensc-pkcs11] card-piv.c:946:piv_get_cached_data: #10
0x1111af000 14:49:18.3763377823679512828 [opensc-pkcs11] card-piv.c:986:piv_get_cached_data: get #10
0x1111af000 14:49:18.140733193388284 [opensc-pkcs11] card-piv.c:879:piv_get_data: called
0x1111af000 14:49:18.140733193388284 [opensc-pkcs11] card-piv.c:880:piv_get_data: #10
0x1111af000 14:49:18.140733193388284 [opensc-pkcs11] card-piv.c:899:piv_get_data: get len of #10
0x1111af000 14:49:18.140733193388284 [opensc-pkcs11] card-piv.c:447:piv_general_io: called
0x1111af000 14:49:18.140733193388284 [opensc-pkcs11] card-piv.c:450:piv_general_io: cb 3f ff 3 : 0 0
0x1111af000 14:49:18.252 [opensc-pkcs11] card.c:394:sc_lock: called
0x1111af000 14:49:18.317106025398524 [opensc-pkcs11] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 14:49:18.252 [tokend] pkcs15.c:1223:sc_pkcs15_bind: PKCS#15 emulation enabled
0x7fff7e07b300 14:49:18.30064771324 [tokend] pkcs15.c:991:sc_pkcs15_bind_internal: called
0x7fff7e07b300 14:49:18.4294967548 [tokend] dir.c:143:sc_enum_apps: called
0x7fff7e07b300 14:49:18.253 [tokend] card.c:692:sc_select_file: called; type=2, path=3f002f00
0x7fff7e07b300 14:49:18.140733193388285 [tokend] card-piv.c:2440:piv_select_file: called
0x7fff7e07b300 14:49:18.140733193388285 [tokend] card-piv.c:368:piv_find_obj_by_containerid: called
0x7fff7e07b300 14:49:18.140733193388285 [tokend] card-piv.c:369:piv_find_obj_by_containerid: str=0x2F00
0x7fff7e07b300 14:49:18.140733193388285 [tokend] card-piv.c:376:piv_find_obj_by_containerid: returning with: -1 (Unknown error)
0x7fff7e07b300 14:49:18.253 [tokend] card-piv.c:2463:piv_select_file: returning with: -1201 (File not found)
0x7fff7e07b300 14:49:18.8387235362811937021 [tokend] card.c:714:sc_select_file: 'SELECT' error: -1201 (File not found)
0x7fff7e07b300 14:49:18.140423955742973 [tokend] dir.c:153:sc_enum_apps: Cannot select EF.DIR file: -1201 (File not found)
0x7fff7e07b300 14:49:18.30064771325 [tokend] pkcs15.c:996:sc_pkcs15_bind_internal: unable to enumerate apps: File not found
0x7fff7e07b300 14:49:18.30064771325 [tokend] pkcs15.c:1027:sc_pkcs15_bind_internal: application path '3f005015'
0x7fff7e07b300 14:49:18.253 [tokend] card.c:692:sc_select_file: called; type=2, path=3f005015
0x7fff7e07b300 14:49:18.140733193388285 [tokend] card-piv.c:2440:piv_select_file: called
0x7fff7e07b300 14:49:18.140733193388285 [tokend] card-piv.c:368:piv_find_obj_by_containerid: called
0x7fff7e07b300 14:49:18.140733193388285 [tokend] card-piv.c:369:piv_find_obj_by_containerid: str=0x5015
0x7fff7e07b300 14:49:18.140733193388285 [tokend] card-piv.c:376:piv_find_obj_by_containerid: returning with: -1 (Unknown error)
0x7fff7e07b300 14:49:18.253 [tokend] card-piv.c:2463:piv_select_file: returning with: -1201 (File not found)
0x7fff7e07b300 14:49:18.8387235362811937021 [tokend] card.c:714:sc_select_file: 'SELECT' error: -1201 (File not found)
0x7fff7e07b300 14:49:18.140423955742973 [tokend] pkcs15.c:1053:sc_pkcs15_bind_internal: absolute path to EF(ODF) 3f005031
0x7fff7e07b300 14:49:18.140733193388285 [tokend] card-piv.c:376:piv_find_obj_by_containerid: returning with: -1 (Unknown error)
0x7fff7e07b300 14:49:18.253 [tokend] card-piv.c:2463:piv_select_file: returning with: -1201 (File not found)
0x7fff7e07b300 14:49:18.8387235362811937021 [tokend] card.c:714:sc_select_file: 'SELECT' error: -1201 (File not found)
0x7fff7e07b300 14:49:18.140423955742973 [tokend] pkcs15.c:1064:sc_pkcs15_bind_internal: EF(ODF) not found in '3f005031'
0x7fff7e07b300 14:49:18.140423955742973 [tokend] pkcs15.c:1171:sc_pkcs15_bind_internal: returning with: -1413 (Unsupported card)
0x7fff7e07b300 14:49:18.140733193388285 [tokend] pkcs15-syn.c:141:sc_pkcs15_bind_synthetic: called
0x7fff7e07b300 14:49:18.140733193388285 [tokend] pkcs15-syn.c:182:sc_pkcs15_bind_synthetic: no emulator list in config file, trying all builtin emulators
0x7fff7e07b300 14:49:18.140733193388285 [tokend] pkcs15-syn.c:184:sc_pkcs15_bind_synthetic: trying westcos
0x7fff7e07b300 14:49:18.4294967549 [tokend] pkcs15-westcos.c:260:sc_pkcs15emu_westcos_init_ex: sc_pkcs15_init_func_ex westcos
0x7fff7e07b300 14:49:18.140733193388285 [tokend] pkcs15-westcos.c:247:westcos_detect_card: westcos_detect_card (PIV-II card)
.........
0x7fff7e07b300 14:49:18.4294967549 [tokend] pkcs15-syn.c:184:sc_pkcs15_bind_synthetic: trying postecert
0x7fff7e07b300 14:49:18.4294967549 [tokend] pkcs15-syn.c:184:sc_pkcs15_bind_synthetic: trying PIV-II
0x7fff7e07b300 14:49:18.4294967549 [tokend] pkcs15-piv.c:1028:sc_pkcs15emu_piv_init_ex: called
0x7fff7e07b300 14:49:18.140733193388285 [tokend] pkcs15-piv.c:234:piv_detect_card: called
0x7fff7e07b300 14:49:18.253 [tokend] pkcs15-piv.c:613:sc_pkcs15emu_piv_init: called
0x7fff7e07b300 14:49:18.317106025398525 [tokend] card.c:843:sc_card_ctl: called
0x7fff7e07b300 14:49:18.317106025398525 [tokend] card-piv.c:2116:piv_card_ctl: called
0x7fff7e07b300 14:49:18.317106025398525 [tokend] card-piv.c:2117:piv_card_ctl: cmd=5 ptr=0x7fff5996f280
0x7fff7e07b300 14:49:18.140733193388285 [tokend] card-piv.c:2017:piv_get_serial_nr_from_CHUI: called
0x7fff7e07b300 14:49:18.4294967549 [tokend] card-piv.c:683:piv_select_aid: called
0x7fff7e07b300 14:49:18.4294967549 [tokend] card-piv.c:686:piv_select_aid: Got args: aid=6509524, aidlen=9, response=5996a2d0, responselen=2000
0x7fff7e07b300 14:49:18.140733193388285 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:49:18.253 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:18.140733193388285 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:49:18.140733193388285 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:18.140733193388285 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(9) 0x106509524
0x7fff7e07b300 14:49:18.317106025398525 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:18.140733193388285 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [   14 bytes] =====================================
00 A4 04 00 09 A0 00 00 03 08 00 00 10 00 ..............
======================================================================
0x7fff7e07b300 14:49:18.140733193388285 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:18.4294967574 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
61 18 a.
======================================================================
0x7fff7e07b300 14:49:18.140733193388310 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.140733193388310 [tokend] apdu.c:443:sc_get_response: called
0x7fff7e07b300 14:49:18.140733193388310 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 14:49:18.278 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 14:49:18.140733193388310 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 14:49:18.140733193388310 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 14:49:18.140733193388310 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:C0, P1:0, P2:0, data(0) 0x0
0x7fff7e07b300 14:49:18.317106025398550 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 14:49:18.140733193388310 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [    5 bytes] =====================================
00 C0 00 00 18 .....
======================================================================
0x7fff7e07b300 14:49:18.140733193388310 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 14:49:18.4294967578 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [   26 bytes] =====================================
61 16 4F 0B A0 00 00 03 08 00 00 10 00 01 00 79 a.O............y
07 4F 05 A0 00 00 03 08 90 00                   .O........
======================================================================
0x7fff7e07b300 14:49:18.140733193388314 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.120259084570 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 14:49:18.-4294967014 [tokend] card.c:434:sc_unlock: called

@mouse07410
Copy link
Contributor Author

I re-did the OpenSC.tokend experiment with CAC. There is no "Discover" in the log, nor is there any APDU starting with 7E.

Indeed it appears that OpenSC.tokend fails to correctly pass the PIN to unlock the card. The error returned in Incoming APDU says "Incorrect parameter in P1". Needless to say, before redacting the PIN out, I carefully verified it, and made sure it was the correct PIN that was in the Outgoing APDU.

Here's what NIST 800-73 got to say about this returned APDU:
'6A' '86' Incorrect parameter in P1

If the PIN was wrong, the card would have responded with

'63' '00' Verification failed
or
'63' 'CX' Verification failed, X indicates the number of further allowed retries

I must add, that it seems to me that cards tend to reply with 6a 86 when they think something in general is wrong...

0x7fff7e07b300 12:27:43.140733193388135 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:20, P1:0, P2:80, data(8) 0xyyyyyyyyyyyyyyyy
0x7fff7e07b300 12:27:43.317106025398375 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 12:27:43.140733193388135 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [   13 bytes] =====================================
00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..
======================================================================
0x7fff7e07b300 12:27:43.140733193388135 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 12:27:43.4294967413 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
6A 86 j.
======================================================================
0x7fff7e07b300 12:27:43.140733193388149 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 12:27:43.120259084405 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 12:27:43.-4294967179 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 12:27:43.-4294967179 [tokend] iso7816.c:121:iso7816_check_sw: Incorrect parameters P1-P2
0x7fff7e07b300 12:27:43.117 [tokend] sec.c:206:sc_pin_cmd: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 12:27:43.117 [tokend] pkcs15-pin.c:368:sc_pkcs15_verify_pin: PIN cmd result -1205
0x7fff7e07b300 12:27:43.140733193388149 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 12:27:43.117 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 12:27:43.118 [tokend] pkcs15-pin.c:373:sc_pkcs15_verify_pin: returning with: -1205 (Incorrect parameters in APDU)
0x7fff7e07b300 12:27:43.118 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:192:_verifyPIN:   In OpenSCToken::verify returned -1205 for pin 1

For the fun of it, I tried to pass the PIN to the CAC manually using opensc-explorer. The same command that OpenSC.tokend failed on, was accepted:

$ opensc-explorer
OpenSC Explorer version 0.15.0
Using reader with a card: SCR3310 Smart Card Reader
OpenSC [3F00]> apdu 00 20 00 80 08 xx xx xx xx xx xx ff ff
Sending: 00 20 00 80 08 xx xx xx xx xx xx FF FF
Received (SW1=0x90, SW2=0x00)
Success!

@dengert
Copy link
Member

dengert commented Oct 8, 2015

Well the get data should not fail like that with invalid parameters.

First the log which you just sent part of to me for the output of:
727 SC_FUNC_RETURN(card->ctx, SC_LOG_DEBUG_NORMAL, 0);
That would look like:
card-piv.c:727:piv_find_aid: returning with: 0

If it is returning 0 then it is not falling through.
Then can you rebuild opensc with these two lines removed from card_piv.c:

726 if (card->type == SC_CARD_TYPE_PIV_II_GENERIC)
727 SC_FUNC_RETURN(card->ctx, SC_LOG_DEBUG_NORMAL, 0);

Then send "ALL" the log up and including the verify of the pin and its return status?
It looks like the card may not have the default AID being the PIV AID, it may be a CAC AID.
which will causes some APDUs to fail.
Removing the above two lines should cause line:

729 r = piv_select_aid(card, piv_aids[0].value, piv_aids[0].len_short, rbuf, &resplen);

to sselect the AID on the card.

THIS IS NOT A FIX, BUT A DEBUGING TEST.


Reply to this email directly or view it on GitHub #570 (comment).

Douglas E. Engert [email protected]

@dengert
Copy link
Member

dengert commented Oct 9, 2015

Here is a simple test to see if the card can process a verify PIN command:

To test if the pin reference of 80 (PIV specs say is the application pin) works:

opensc-tool -s 00:20:00:80:08:31:32:33:34:35:36:FF:FF

To test if the pin reference of 00 (PIV specs call the global pin) works:

opensc-tool -s 00:20:00:00:08:31:32:33:34::35:36:FF:FF

In both of the above replace the 31:32:33:34::35:36:FF:FF with hex version of the digits of your PIN padded to 8 bytes with FF.

I can not find CAC document that says id 80 or 00 should work.
PIV Discovery object says if piv application pin or global pin will work for PIV PIV application.

It 00 works, AS A TEST, change card-piv.c line 2867
priv->pin_preference = 0x80; /* 800-73-3 part 1, table 3 /
to
priv->pin_preference = 0x00; /
800-73-3 part 1, table 3 */

and see if tokend get any further.

Douglas E. Engert [email protected]

@mouse07410
Copy link
Contributor Author

The test you suggested shows that CAC prefers P2=80 replying with OK, and rejects P2=00 replying with "Key reference not found". So something else must be wrong with how OpenSC.tokend tries to unlock the card (be it CAC or NEO).
Obviously, in the log below the PIN has been redacted out with FF.

$ opensc-tool -s 00:20:00:80:08:FF:FF:FF:FF:FF:FF:FF:FF
Using reader with a card: SCR3310 Smart Card Reader
Sending: 00 20 00 80 08 FF FF FF FF FF FF FF FF 
Received (SW1=0x90, SW2=0x00)
$ opensc-tool -s 00:20:00:00:08:FF:FF:FF:FF:FF:FF:FF:FF
Using reader with a card: SCR3310 Smart Card Reader
Sending: 00 20 00 00 08 FF FF FF FF FF FF FF FF 
Received (SW1=0x6A, SW2=0x88)

@mouse07410
Copy link
Contributor Author

Then can you rebuild opensc with these two lines removed from card_piv.c:

726 if (card->type == SC_CARD_TYPE_PIV_II_GENERIC)
727 SC_FUNC_RETURN(card->ctx, SC_LOG_DEBUG_NORMAL, 0);

Then send "ALL" the log up and including the verify of the pin and its return status?
It looks like the card may not have the default AID being the PIV AID, it may be a CAC AID.
which will causes some APDUs to fail.

With the above change:

........
0x7fff7e07b300 12:18:34.140733193388466 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 12:18:40.4294967583 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:149:verifyPIN: In OpenSCToken::verifyPIN(1)
0x7fff7e07b300 12:18:40.317106025398559 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:172:_verifyPIN: In OpenSCToken::_verifyPIN(), PIN num is: 1
0x7fff7e07b300 12:18:40.317106025398559 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:186:_verifyPIN:   sc_pkcs15_get_objects(pin_id=01): 2
0x7fff7e07b300 12:18:40.289 [tokend] pkcs15-pin.c:295:sc_pkcs15_verify_pin: called
0x7fff7e07b300 12:18:40.289 [tokend] pkcs15-pin.c:296:sc_pkcs15_verify_pin: PIN(type:0;method:1;len:)
0x7fff7e07b300 12:18:40.289 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 12:18:40.317106025398561 [tokend] reader-pcsc.c:526:pcsc_lock: called
0x7fff7e07b300 12:18:40.289 [tokend] sec.c:159:sc_pin_cmd: called
0x7fff7e07b300 12:18:40.290 [tokend] apdu.c:563:sc_transmit_apdu: called
0x7fff7e07b300 12:18:40.290 [tokend] card.c:394:sc_lock: called
0x7fff7e07b300 12:18:40.140733193388322 [tokend] apdu.c:530:sc_transmit: called
0x7fff7e07b300 12:18:40.140733193388322 [tokend] apdu.c:384:sc_single_transmit: called
0x7fff7e07b300 12:18:40.140733193388322 [tokend] apdu.c:389:sc_single_transmit: CLA:0, INS:20, P1:0, P2:80, data(8) 0x7f........
0x7fff7e07b300 12:18:40.317106025398562 [tokend] reader-pcsc.c:254:pcsc_transmit: reader 'SCR3310 Smart Card Reader'
0x7fff7e07b300 12:18:40.140733193388322 [tokend] apdu.c:187:sc_apdu_log:
Outgoing APDU data [   13 bytes] =====================================
00 20 00 80 08 xx xx xx xx xx xx FF FF . ...yyyyyy..
======================================================================
0x7fff7e07b300 12:18:40.140733193388322 [tokend] reader-pcsc.c:184:pcsc_internal_transmit: called
0x7fff7e07b300 12:18:40.4294967667 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
90 00 ..
======================================================================
0x7fff7e07b300 12:18:40.140733193388403 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff7e07b300 12:18:40.120259084660 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff7e07b300 12:18:40.-4294966924 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 12:18:40.372 [tokend] sec.c:206:sc_pin_cmd: returning with: 0 (Success)
0x7fff7e07b300 12:18:40.372 [tokend] pkcs15-pin.c:368:sc_pkcs15_verify_pin: PIN cmd result 0
0x7fff7e07b300 12:18:40.317106025398644 [tokend] pkcs15-pin.c:594:sc_pkcs15_pincache_add: called
0x7fff7e07b300 12:18:40.317106025398644 [tokend] pkcs15-pin.c:634:sc_pkcs15_pincache_add: PIN(PIV Card Holder pin) cached
0x7fff7e07b300 12:18:40.4294967668 [tokend] card.c:434:sc_unlock: called
0x7fff7e07b300 12:18:40.372 [tokend] reader-pcsc.c:566:pcsc_unlock: called
0x7fff7e07b300 12:18:40.372 [tokend] pkcs15-pin.c:373:sc_pkcs15_verify_pin: returning with: 0 (Success)
0x7fff7e07b300 12:18:40.372 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:192:_verifyPIN:   In OpenSCToken::verify returned 0 for pin 1
0x7fff7e07b300 12:18:40.5705853276663054708 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:158:verifyPIN:   About to call BEGIN()
0x7fff7e07b300 12:18:40.3617293440343081352 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()
0x7fff7e07b300 12:18:40.3617293440343081372 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:342:getAcl: In OpenSCToken::getAcl()

Now we’re back to square one with the main OpenSC.tokend problem – OpenSC.tokend successfully passes the PIN to the card (be it CAC or NEO) and unlocks it, but does not propagate this knowledge to the invoking application(s); so as far as they’re concerned the CAC stays locked and unable to perform private key operations.

P.S. The entire log been emailed to you.

@dengert
Copy link
Member

dengert commented Oct 9, 2015

The problem with the pin for the CAC card looks more like a tokend problem. (Any tokend developers want to look at this?)

The partial opensc-debug log created by tokend you sent me shows the verify being sent as:
00 20 00 80 08 xx xx xx xx xx xx FF FF (with actual digits)
and it returned 6A 86

But when opensc-tool sends the SAME command it works and returns 90 00.

Are are some possibilities:

One of you snapshots or emails said something about a GemSafe tokend.
Could this be a CAC tokend that is also sending commands to the card at the same time,
and causing the CAC applet to be selected? This could interfere with the OpenSC
drivers, as the default application could be reset.
(Note that different applications can define different APDUs and different p1 and p2 parameters for the same APDU.
so CAC applet may not accept 00 20 00 80, but PIV applet does.)
Thus both OpenSC and the GenSafe (or other tokend) are selecting different applications and stepping
on each other. The opensc debug log will only show the OpenSC commands.)

A USB trace to the reader could show this...

It could also be PC/SC is powering down the reader and thus resetting the security status on the card,
and resetting the default application. You said in one note that the CAC always failed and the NEO failed some of the time.

There could be a problem with how tokend calls the sc_pkcs15 routines.

There could be a different opensc.conf file that causes some driver is being called
that does some I/O to the CAC card during that causes it to
select a different application, or does not select the PIV application.

Only a FULL opensc-debug log showing "ALL" the log entries is needed to see what is different.

Or tokend is not picking up the same shared libraries that the opensc tools or opensc_pkcs11.so do,
thus causing some thing to be done to the card to cause it to reject the verifiy.
LDD could show what libs will be loaded.

There is still the additional problem that tokend with the NEO (where the opensc-debug shows the PIN was verified
and a number of decrypt operations also worked) did not unlock the Key Chain. (You said it kept asking for the pin?)
This points to the card being reset or that tokend does not run on Yosemite correctly.

On 10/9/2015 10:55 AM, Mouse wrote:

The test you suggested shows that CAC prefers P2=80 replying with OK, and rejects P2=00 replying with "Key reference not found". So something else must be wrong with how OpenSC.tokend tries to unlock
the card (be it CAC or NEO).
/Obviously, in the log below the PIN has been redacted out with FF./

|$ opensc-tool -s 00:20:00:80:08:FF:FF:FF:FF:FF:FF:FF:FF Using reader with a card: SCR3310 Smart Card Reader Sending: 00 20 00 80 08 FF FF FF FF FF FF FF FF Received (SW1=0x90, SW2=0x00) $ opensc-tool
-s 00:20:00:00:08:FF:FF:FF:FF:FF:FF:FF:FF Using reader with a card: SCR3310 Smart Card Reader Sending: 00 20 00 00 08 FF FF FF FF FF FF FF FF Received (SW1=0x6A, SW2=0x88) |


Reply to this email directly or view it on GitHub #570 (comment).

Douglas E. Engert [email protected]

@dengert
Copy link
Member

dengert commented Oct 9, 2015

Yes this looks at the full debug log you sent, this looks like the first bug. The default application is not the PIV and the code following
lines 726 and 727 removed lines the would have done more checking and done a piv_select_aid to tell the card to select the PIV applet.

I need to look closer, but I thing that a piv_select_aid is done when other opensc routines request the serial number
but tokend does not request the serial number, thus the piv_select_aid is not done and verify command is different
for the default application on the card cause it to fail.

I will submit a real patch early next week.

Douglas E. Engert [email protected]

@mouse07410
Copy link
Contributor Author

I am having problems keeping up with you. You ask for guidance, then a few hours
later you have something working and asking for something else.

Sorry! ;) Being at the bottom of the food-chain, have to move fast! :-)

Are you using git? Can you do PR?

Yes and yes. :-)

If you want to get Outlook working with ECDSA save that as the next request,

OK. In fact, I'm not sure if it is even possible. The problem as I see it is - Outlook requests for an RSA signature, so whatever the Context has to say about the algorithm and such - will be RSA. So for me to switch it to ECDSA - I need to somehow preempt the entire Context, and (a) I don't know how (and don't want to remove "const" from the input parameter), and (b) not sure we really want this kind of hack/fix...

Open to suggestions.

but lets get the SHA 256 and ECDSA stuff into a PR. Please do what @frankmorgner is asking.

Done. Just updated my PR frankmorgner/OpenSC.tokend#1 with the latest changes.

@dengert and @frankmorgner I'd appreciate if you could review that PR and (if agreeable) merge it soonest. It also includes README.md changes - that I do not consider a necessary part of the PR, so if you have means to ignore it, please feel free to.

I disagree with your comment: "Regardless, with this patch ECDH support isn't any worse
than without it." It is worse off. Someone next year will be looking at this code and thinking,
"Someone added this last year, it must have worked or the would not have added it. Why
can't I get it to work." and they will be spending time and effort and asking why was this code added.

OK, I agree. Now the code detects ECDH decrypt attempt, and throws exception upon it.

What the tokend presents as a name is up to tokend.

This is exactly the point. I would like tokend to present a different name that would be based not on the driver used for this token, but the CN of a first discovered certificate.

@mouse07410
Copy link
Contributor Author

As @frankmorgner wanted a rebase against what I think is his "sha2" branch, see PR frankmorgner/OpenSC.tokend#3.

@frankmorgner frankmorgner changed the title OpenSC.tokend does not unlock smartcard (PIV, Mac OS X Yosemite) ECC and SHA-2 support in OpenSC.tokend Dec 8, 2015
mouse07410 pushed a commit to mouse07410/OpenSC.tokend that referenced this issue Jan 22, 2016
Fixes OpenSC/OpenSC#570
an at least 7 year old bug...
@ansnunez
Copy link

Something's still wrong with how the signature is generated. Thunderbird generates consistently good signatures using opensc-pkcs11.so (see the Thunderbird log in one of my previous posts to compare), and Apple Mail generates consistently bad

Hi @mouse07410, I'm working on something similar and found you guys here. May I know if you got the answer to that Apple Mail signing problem?

@mouse07410
Copy link
Contributor Author

mouse07410 commented May 24, 2016

@ansnunez First of all, https://github.com/mouse07410OpenSC.tokend appears to produce correct ECDSA signatures, as tested with MS Outlook and Blackberry-10.The complaint you quoted is really old. That problem was taken care of long time ago.

Regarding your question (as there still is an issue :-( ), I think I got the answer. What (IMHO) is missing just got added to the current Tokend is the ability to tell and set the correct type (CSSM_ALGID_RSA vs CSSM_ALGID_ECC) in line 46 of OpenSC/OpenSCSchema.cpp.

The problem is that in order to do so one needs to determine what kind of keys this token has before instantiating OpenSCSchema(). That's what I'm working on now - feel free to give a hand if you can.

Thanks to @dengert's guidance, that part is now fixed:
ecc_key_in_keychain
MS Outlook accepted the signature, and approved of the certificate:
outlook_view_of_signing_cert

The one thing I'm still missing is the ability to extract Common Name from the retrieved certificate, so the token can display it instead of "PIV_II".

@ansnunez
Copy link

Thanks @mouse07410 I'll try to process this info and see if I've got anything to add. That common name problem's on my list too.

@mouse07410
Copy link
Contributor Author

mouse07410 commented May 27, 2016

@ansnunez thanks, but don't bother - already finished. ;)
See here: OpenSC/OpenSC.tokend#23 (comment)

@dengert if Apple Mail proves up to snuff, it might be the time to revisit EC_DERIVE :-) :-)
Because now the token representation seems complete and consistent, including Tokend properly reporting type of the private keys. So maybe Apple Mail would issue a key_derive() call after all.

@ansnunez
Copy link

@mouse07410 wow thanks a lot! Good thing I found this thread 👍

@ansnunez
Copy link

ansnunez commented Jun 3, 2016

@mouse07410 got another question I hope you or anyone here can help me with.
Posting it here as this concerns SHA-2.

I've got an RSA2k SHA256 certificate that, when imported directly into Keychain Access, is successfully being used by Apple Mail or Adobe Reader XI to sign a mail/document.

But when I use tokend, the inputs to generateSignature() are always signOnly = SHA1 and input size = 20 bytes. I don't know why the request isn't for SHA256.

Any thoughts why the behavior is different in the two cases?

@mouse07410
Copy link
Contributor Author

mouse07410 commented Jun 3, 2016

I've got an RSA2k SHA256 certificate

No, you got an RSA 2k certificate that its issuer signed using SHA256. It has nothing to do with what hash would this certificate be used with. You can use it to sign with hashes from MD5 to SHA512, and everything in between (and SHA3 if your code supports it).

when I use tokend, the inputs to generateSignature() are always signOnly = SHA1 and input size = 20 bytes. I don't know why the request isn't for SHA256.

A snarky remark would be "try without Tokend and see if the results are different". :)
Show me a log of Apple Mail generating RSA signature using SHA256 with any certificate (not necessarily on a hardware token).

Seriously though - no Apple-provided application can access tokens without Tokend (OpenSSL and Firefox/Thunderbird can because they are designed differently, and are not Apple-specific).

What you observe is the evidence of the fact that Apple does not allow users to configure what hash (and what encryption algorithm, and even what certificate) to use for S/MIME. Apple knows better. Apple decided that SHA1 should be used as hash for signatures, so Apple Mail performs SHA1. Case closed, no appeal.

On the other hand, since we do want to know that Tokend passes the correct data, here's a log excerpt just made with MS Outlook 2011 (with all the MS shortcomings, they still allow you to choose the certificates you want for this account, and to specify what hash and encryption algorithms to use) configured to use SHA256 for signatures:

. . . . .
0x7fff78711000 09:30:40.406 [tokend] pkcs15-pin.c:373:sc_pkcs15_verify_pin: returning with: 0 (Success)
0x7fff78711000 09:30:40.406 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:243:_verifyPIN:   In OpenSCToken::verify returned 0 for pin 1
0x7fff78711000 09:30:40.406 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:208:verifyPIN:   PIN verified
0x7fff78711000 09:30:40.406 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCKeyHandle.cpp:77:generateSignature: In OpenSCKeyHandle::generateSignature()
0x7fff78711000 09:30:40.406 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCKeyHandle.cpp:80:generateSignature:   type == CSSM_ALGCLASS_SIGNATURE
0x7fff78711000 09:30:40.406 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCKeyHandle.cpp:88:generateSignature:   algorithm == CSSM_ALGID_RSA
0x7fff78711000 09:30:40.406 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCKeyHandle.cpp:115:generateSignature:   Using SHA256, length is 32 bytes
0x7fff78711000 09:30:40.406 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCKeyHandle.cpp:169:generateSignature:   PKCS#1 padding
0x7fff78711000 09:30:40.406 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCKeyHandle.cpp:193:generateSignature:   Signing buffers: inlen=32, outlen=256
0x7fff78711000 09:30:40.406 [tokend] pkcs15-sec.c:314:sc_pkcs15_compute_signature: called
0x7fff78711000 09:30:40.406 [tokend] pkcs15-sec.c:362:sc_pkcs15_compute_signature: supported algorithm flags 0x1, private key usage 0x20E
0x7fff78711000 09:30:40.406 [tokend] padding.c:283:sc_get_encoding_flags: called
0x7fff78711000 09:30:40.406 [tokend] padding.c:287:sc_get_encoding_flags: iFlags 0x202, card capabilities 0x1
0x7fff78711000 09:30:40.406 [tokend] padding.c:316:sc_get_encoding_flags: pad flags 0x202, secure algorithm flags 0x0
0x7fff78711000 09:30:40.406 [tokend] padding.c:317:sc_get_encoding_flags: returning with: 0 (Success)
0x7fff78711000 09:30:40.406 [tokend] pkcs15-sec.c:413:sc_pkcs15_compute_signature: DEE flags:0x00000202 alg_info->flags:0x00000001 pad:0x00000202 sec:0x00000000
. . . . .
0x7fff78711000 09:30:40.407 [tokend] sec.c:68:sc_set_security_env: called
0x7fff78711000 09:30:40.407 [tokend] card-piv.c:2221:piv_set_security_env: called
0x7fff78711000 09:30:40.407 [tokend] card-piv.c:2225:piv_set_security_env: flags=00000014 op=2 alg=0 algf=00000000 algr=00000000 kr0=9c, krfl=1
. . . . .
0x7fff78711000 09:30:41.082 [tokend] pkcs15-sec.c:441:sc_pkcs15_compute_signature: returning with: 256
0x7fff78711000 09:30:41.082 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCKeyHandle.cpp:201:generateSignature:   sc_pkcs15_compute_signature(): rv = 256
0x7fff78711000 09:30:41.082 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCKeyHandle.cpp:213:generateSignature:   Completed RSA signature, len=256
. . . . .

You can see from the above that the confusion is on the user's side, and the problem - on the side of Apple Mail. ;)

I must also add that Apple Mail seems to have no problem verifying signatures made using SHA256, it merely refuses to create such signatures.

@ansnunez
Copy link

ansnunez commented Jun 6, 2016

@mouse07410 Thanks for the explanation. It's crystal clear for Apple Mail.

I guess Adobe Reader suffers from a similar but not completely explained issue:

  1. Importing the key/certificate directly into Keychain Access (i.e., no TokenD involvement), then signing a PDF file, I get the following information on the signature (sorry I'm on a different machine so taking screens isn't quick):

    Advanced Signature Properties
    Signature Details
    Signature was created using Adobe Reader 11.0.4.
    Hash Algorithm: SHA256

    (This would be the "try without tokend" way that you mentioned)

  2. Using TokenD for signing with the same key/certificate, I get this info:

    Advanced Signature Properties
    Signature Details
    Signature was created using Adobe Reader 11.0.4.
    Hash Algorithm: SHA1

There are some discussions in the Adobe forums of people getting the same kind of problem (e.g., https://forums.adobe.com/thread/1045769). In any case, I think it might be a problem with the application itself.

Finally, I tried Outlook 2011 too just now, and my SHA2 code in TokenD works fine :-)

@mouse07410
Copy link
Contributor Author

mouse07410 commented Jun 6, 2016

@ansnunez thank you for exploring this - it turned out to be most interesting! I did not realize Acrobat exhibited a similar problem, and the way Adobe staff tried to explain it on their forum was priceless (aka ridiculous).

The problem must be with what/how the application requests from the underlying services. One reason - because we know that other applications are able to successfully obtain SHA256 from the same underlying services.

Update
@ansnunez, I found that no matter what I try to do to a PDF file, or no matter how I try to create a new PDF using Adobe Acrobat X or XI, it always reports PDF 1.6 or at best PDF 1.7. I have never (so far) managed to create PDF 1.7 Extension level 5 or such that would be compatible with Acrobat 9.1 or later. I believe this is related to Acrobat forcing SHA1 (and no, I've no idea why this doesn't manifest for files signed with Keychain-residing keys). This is what I mean:
acrobat pdf-1 6

@ansnunez
Copy link

ansnunez commented Jun 9, 2016

@mouse07410 Thanks for the info. I've put Adobe testing on hold for now since Outlook confirms the SHA2 signing works. If I find a definitive answer somewhere about Adobe SHA2 support for TokenD I'll let you guys know.

@mouse07410
Copy link
Contributor Author

I still had the same SHA1 problem with Acrobat Pro DC (2015). I guess Adobe is doomed. ;)

P.S. Tokend just became a bit better. ;)

@martinpaljak
Copy link
Member

A looong thread to read through. Did this lead to anything? Seeing no changes in OpenSC.tokend master, I'd guess not?

@mouse07410
Copy link
Contributor Author

Did this lead to anything?

@martinpaljak it led to creation of the OpenSC.tokend fork that supports ECC and SHA-2.

I needed that functionality, and wasn't able to reach an agreement on the merge. So the only path left was maintaining my own fork, which I did. That's probably what people use if they need a working SHA-2 capable tokend.

I guess you can say that for the main repo it did not lead anywhere - it's still broken wrt. SHA-2, and still does not support ECC tokens.

Caveat: there are no applications that I know of that can use ECDH, so ECDH support is not done (nothing to test against). ECDSA is fully functional.

P.S. Regarding "I still had the same SHA1 problem with Acrobat Pro DC (2015)" - it's fixed by the Mac OS X update to 10.11.6. Now Acrobat uses SHA-256 when requested for signing with hardware tokens.

P.P.S. MacOS Sierra includes a working tokend that was shown to support RSA tokens. So hopefully (depending on their ECC support) I won't need to maintain my fork for much longer.

@martinpaljak
Copy link
Member

I am not able to pinpoint the actual problem that did now allow for the merge?

@mouse07410
Copy link
Contributor Author

mouse07410 commented Oct 4, 2016

I am not able to pinpoint the actual problem that did now allow for the merge?

I personally saw/see no technical problem either.

The maintainer did not want to merge. Basically, he wanted me to re-write the code in a different way. That would make the code look nicer, but it did not work (his re-write in that style did not work either). I had neither time nor skills (nor help) to get to the bottom of that. So I left the code the way it was - working.

My fork contains enhancements and fixes that @frankmorgner made, plus enhancements and fixes on top of those. As you can see from the above posts (#570 (comment)), it appears that people find my fork useful (at least those who are able to find it :).

I've made another PR against the main master: OpenSC/OpenSC.tokend#28.
It would bring the master to the level of my fork (that includes Frank's fixes and all of my enhancements).

Please feel free to merge it, or close - as you see fit.

At this point I'm just maintaining my fork for bug fixes, until Apple native tokend includes all of these capabilities (or until this fork is merged into the main repo, which at this time I don't hope for very much). The only possible/missing enhancement would be full support for ECDH - and that is highly unlikely in the absence of applications that use it.

Update
I estimate that my fork would remain useful for another year or so. Then Apple is likely to catch up with their code, and we won't need another tokend. This fork was tested on Sierra in legacy mode (worked OK).

@martinpaljak
Copy link
Member

@dengert what about setting the token label based on the certificate common name in pkcs15-piv.c ?

See OpenSC/OpenSC.tokend#28 (comment) for a reasoning.

@dengert
Copy link
Member

dengert commented Oct 6, 2016

Backward compatibility.
Also with multiple certificates on a card, may all have the same CN. For example my old US gov issued card had 4 certificates, 3 have CN=DOUGLAS ENGERT (Affiliate) and the 4th is for the card and has no CN.

PKCS#11 says:
"The CKA_LABEL attribute is intended to assist users in browsing." It does not say in searching.
There is so much libp11 messages these days based on RFC 7512 that any changes should consider how RFC 7512 uses the label. It maps the CKA_LABEL to "object" Using the CNwould produce duplicate object names.

Tokend can always get all the certificates, and parse them for the CN.

@martinpaljak
Copy link
Member

Well, I believe there's a sensible default between good user experience and backward compatibility. The card driver is in the best position to decide which card to use for the token label (PKCS#15 sense) and it makes sense for the Tokend driver only to relay that to the OSX UI, instead of

Most drivers in OpenSC don't make use of it, only have the token label as a generic "card type" name, rather than for the end user to understand and associate with the inserted card. And once you have two cards of the same type.... Things go hairy.

Anyway, I'd not be including the certificate based naming into tokend, but would suggest to implement in PIV driver.

@dengert
Copy link
Member

dengert commented Oct 6, 2016

I have been referring to the Label of an object on a token. Sounds like you are referring to the label in the PKCS#11 tokenInfo. Since tokend does not use PKCS#11, RFC 7412 does not apply.

Can you look and see if sc_pkcs15_get_name_from_dn which was added recently would met you needs?

See commit: e4f5f84

@mouse07410
Copy link
Contributor Author

sc_pkcs15_get_name_from_dn() would probably meet his needs - but he'd have to get the DN first (unless OpenSC PIV driver already has it as a part of its routine processing?).

@martinpaljak
Copy link
Member

@dengert I'm referring to the label set here: https://github.com/OpenSC/OpenSC/blob/master/src/libopensc/pkcs15-piv.c#L620

@mouse07410 wants to use the CN from a certificate for this label (makes sense). The same is done in https://github.com/OpenSC/OpenSC/blob/master/src/libopensc/pkcs15-esteid.c#L120

I don't know what would be the best, CN seems meaningful. Anyway, setting this label is NOT the job of Tokend, for the sake of meaningful layering.

@dengert
Copy link
Member

dengert commented Oct 7, 2016

I would be very reluctant to change the p15card->tokeninfo->label. There are 58 uses of "tokeninfo*.label" in src/libopensc Most of the pkcs15-.c set this to a constant to represent the card or application on the card, using strdup or set_string from a constant.

p15card->tokeninfo->label is also used in pkcs11/framework-pkcs15.c So if p15card->tokeninfo->label is changed, it will impact PKCS#11 too, and cause a backward compatibility issue for current users.

If you want change p15card->tokeninfo->label for the PIV, I would suggest that all the cards do the same. And get the libp11 URI advocates involved too.

As I see the problem, @mouse07410 wants a name the user can relate too. Microsoft addressed the problem in the Certificate Store by showing "Issued To", "Issued By" and allowing the user to set "Friendly Name" and "Description" for a certificate. Internet Options->Content->Certificates. Click on a certificate->View->Details->Edit Properties->General

What I was suggesting that tokend could take the same approach, and retrieve whatever info it wanted from the certificate, and the new sc_pkcs15_get_name_from_dn() could be used.

@mouse07410
Copy link
Contributor Author

@mouse07410 wants a name the user can relate to.

Every commercial tokend presents such a name that is based on a certificate found on the token.

What I was suggesting that tokend could take the same approach, and retrieve whatever info it wanted from the certificate

That's exactly what my tokend fork is doing.

and the new sc_pkcs15_get_name_from_dn() could be used

Sure. I don't remember if I use it or not - it depends on when that function was introduced relative to when I released this capability...

@frankmorgner
Copy link
Member

Implementation and discussion is continued here OpenSC/OpenSC.tokend#28

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

5 participants