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

Current master breaks key access on the token via reader #109

Closed
mouse07410 opened this issue Sep 28, 2016 · 23 comments
Closed

Current master breaks key access on the token via reader #109

mouse07410 opened this issue Sep 28, 2016 · 23 comments

Comments

@mouse07410
Copy link
Contributor

It now refuses to retrieve public keys when the token is not logged on - exactly the problem we've solved a few months ago:

$ echo 879dec92bd3559f8bdf99ca698b9739156ea1025b3bae59b335fb6f19ec41489 | xxd -r -p -c 200 | openssl rsautl -engine pkcs11 -keyform engine -encrypt -pubin -inkey "pkcs11:object=KEY%20MAN%20pubkey;object-type=public" -pkcs -out /tmp/derive.87882.key.enc
engine "pkcs11" set.
No public keys found.
PKCS11_load_public_key returned NULL
unable to load Public Key

The relevant (IMHO) excerpt from the log:

Outgoing APDU (4 bytes):
00 20 00 80 . ..
0x7fff75470000 14:31:35.383 [tokend] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7fff75470000 14:31:35.388 [tokend] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (2 bytes):
63 C5 c.
0x7fff75470000 14:31:35.388 [tokend] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7fff75470000 14:31:35.388 [tokend] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7fff75470000 14:31:35.388 [tokend] card.c:449:sc_unlock: called
0x7fff75470000 14:31:35.388 [tokend] iso7816.c:116:iso7816_check_sw: Verification failed (remaining tries: 5)
0x7fff75470000 14:31:35.388 [tokend] card-piv.c:3138:piv_check_protected_objects: called
0x7fff75470000 14:31:35.388 [tokend] card-piv.c:908:piv_get_data: called
0x7fff75470000 14:31:35.388 [tokend] card-piv.c:909:piv_get_data: #4
0x7fff75470000 14:31:35.388 [tokend] card-piv.c:948:piv_get_data: buffer for #4 *buf=0x0x7fff53ba0328 len=8
0x7fff75470000 14:31:35.388 [tokend] card-piv.c:484:piv_general_io: called
0x7fff75470000 14:31:35.388 [tokend] card-piv.c:487:piv_general_io: cb 3f ff 5 : 255 256
0x7fff75470000 14:31:35.388 [tokend] card.c:397:sc_lock: called
0x7fff75470000 14:31:35.388 [tokend] card.c:439:sc_lock: returning with: 0 (Success)
0x7fff75470000 14:31:35.388 [tokend] card-piv.c:527:piv_general_io: calling sc_transmit_apdu flags=3 le=8, resplen=8, resp=0x7fff53ba0328
0x7fff75470000 14:31:35.388 [tokend] apdu.c:550:sc_transmit_apdu: called
0x7fff75470000 14:31:35.388 [tokend] card.c:397:sc_lock: called
0x7fff75470000 14:31:35.388 [tokend] card.c:439:sc_lock: returning with: 0 (Success)
0x7fff75470000 14:31:35.388 [tokend] apdu.c:517:sc_transmit: called
0x7fff75470000 14:31:35.388 [tokend] apdu.c:371:sc_single_transmit: called
0x7fff75470000 14:31:35.388 [tokend] apdu.c:376:sc_single_transmit: CLA:0, INS:CB, P1:3F, P2:FF, data(5) 0x7fff53ba02a8
0x7fff75470000 14:31:35.388 [tokend] reader-pcsc.c:269:pcsc_transmit: reader 'Gemalto Prox Dual USB PC Link Reader(1)'
0x7fff75470000 14:31:35.388 [tokend] reader-pcsc.c:270:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 CB 3F FF 05 5C 03 5F C1 09 08 ..?..\._...
0x7fff75470000 14:31:35.388 [tokend] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7fff75470000 14:31:35.395 [tokend] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (2 bytes):
69 82 i.
0x7fff75470000 14:31:35.395 [tokend] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7fff75470000 14:31:35.395 [tokend] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7fff75470000 14:31:35.395 [tokend] card.c:449:sc_unlock: called
0x7fff75470000 14:31:35.395 [tokend] card-piv.c:533:piv_general_io: DEE r=0 apdu.resplen=0 sw1=69 sw2=82
0x7fff75470000 14:31:35.395 [tokend] iso7816.c:121:iso7816_check_sw: Security status not satisfied
0x7fff75470000 14:31:35.395 [tokend] card-piv.c:544:piv_general_io: Card returned error 
0x7fff75470000 14:31:35.395 [tokend] card.c:449:sc_unlock: called
0x7fff75470000 14:31:35.395 [tokend] card-piv.c:595:piv_general_io: returning with: -1211 (Security status not satisfied)
0x7fff75470000 14:31:35.395 [tokend] card-piv.c:960:piv_get_data: returning with: -1211 (Security status not satisfied)
0x7fff75470000 14:31:35.395 [tokend] card-piv.c:3196:piv_check_protected_objects: object_test_verify=4, card_issues = 0x00020313
0x7fff75470000 14:31:35.395 [tokend] card-piv.c:3197:piv_check_protected_objects: returning with: -1214 (PIN code or key incorrect)
0x7fff75470000 14:31:35.395 [tokend] card-piv.c:3286:piv_pin_cmd: piv_pin_cmd tries_left=5, logged_in=0
0x7fff75470000 14:31:35.395 [tokend] card-piv.c:3287:piv_pin_cmd: returning with: 0 (Success)
0x7fff75470000 14:31:35.395 [tokend] sec.c:206:sc_pin_cmd: returning with: 0 (Success)
0x7fff75470000 14:31:35.395 [tokend] card.c:449:sc_unlock: called
0x7fff75470000 14:31:35.395 [tokend] reader-pcsc.c:627:pcsc_unlock: called
0x7fff75470000 14:31:35.395 [tokend] pkcs15-pin.c:638:sc_pkcs15_get_pin_info: returning with: 0 (Success)
0x7fff75470000 14:31:35.395 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:212:pinStatus:   In OpenSCToken::sc_pkcs15_get_pin_info returned 0 for pin 1
0x7fff75470000 14:31:35.395 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:217:pinStatus:   In OpenSCToken::pinStatus() pin_info->logged_in = 0
0x7fff75470000 14:31:35.395 [tokend] /Users/ur20980/Src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:353:unverifyPIN: In OpenSCToken::unverifyPIN(-1)
@dwmw2
Copy link
Contributor

dwmw2 commented Sep 28, 2016

Does that object have CKA_PRIVATE?

@mouse07410
Copy link
Contributor Author

mouse07410 commented Sep 28, 2016

Certainly not. It's a public key (on a properly initialized token):

Card has 4 public key(s).

Public RSA Key [PIV AUTH pubkey]
    Object Flags   : [0x0]
    Usage          : [0xD1], encrypt, wrap, verify, verifyRecover
    Access Flags   : [0x2], extract
    ModLength      : 2048
    Key ref        : 154 (0x9A)
    Native         : yes
    ID             : 01
    DirectValue    : <absent>

Public RSA Key [SIGN pubkey]
    Object Flags   : [0x0]
    Usage          : [0x2C1], encrypt, verify, verifyRecover, nonRepudiation
    Access Flags   : [0x2], extract
    ModLength      : 2048
    Key ref        : 156 (0x9C)
    Native         : yes
    ID             : 02
    DirectValue    : <absent>

Public RSA Key [KEY MAN pubkey]
    Object Flags   : [0x0]
    Usage          : [0x11], encrypt, wrap
    Access Flags   : [0x2], extract
    ModLength      : 2048
    Key ref        : 157 (0x9D)
    Native         : yes
    ID             : 03
    DirectValue    : <absent>

Public RSA Key [CARD AUTH pubkey]
    Object Flags   : [0x0]
    Usage          : [0xC0], verify, verifyRecover
    Access Flags   : [0x2], extract
    ModLength      : 2048
    Key ref        : 158 (0x9E)
    Native         : yes
    ID             : 04
    DirectValue    : <absent>

And private keys:

Card has 4 private key(s).

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'30316.....'

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'3032.....'

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'30336.....'

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'3034.....'

And using pkcs11-tool:

Private Key Object; RSA 
  label:      PIV AUTH key
  ID:         01
  Usage:      decrypt, sign, unwrap
Public Key Object; RSA 2048 bits
  label:      PIV AUTH pubkey
  ID:         01
  Usage:      encrypt, verify, wrap
Certificate Object, type = X.509 cert
  label:      Certificate for PIV Authentication
  ID:         01
Private Key Object; RSA 
  label:      SIGN key
  ID:         02
  Usage:      decrypt, sign, non-repudiation
  Access:     always authenticate
Public Key Object; RSA 2048 bits
  label:      SIGN pubkey
  ID:         02
  Usage:      encrypt, verify
Certificate Object, type = X.509 cert
  label:      Certificate for Digital Signature
  ID:         02
Private Key Object; RSA 
  label:      KEY MAN key
  ID:         03
  Usage:      decrypt, unwrap
Public Key Object; RSA 2048 bits
  label:      KEY MAN pubkey
  ID:         03
  Usage:      encrypt, wrap
Certificate Object, type = X.509 cert
  label:      Certificate for Key Management
  ID:         03
. . . . .

Funny thing - the above works when the token is connected directly (not via reader)...

I'm trying to determine whether this is a libp11 fault, or the OpenSC screw-up.

The problem seems to have something to do with the presence of multiple readers...

@dengert
Copy link
Member

dengert commented Sep 28, 2016

The excerpts look OK to me.

The device must be a Yubico device that does not handle VERIFY with Lc=0,
The piv_get_data: #4 is for the PIV_OBJ_PI Printed Info that is a protected object.
It is being use to test the state of the card. see commit edf24d0e2ebcc50263cb4afcf7652080655e108f

The rest of the debug log may show something.

@dwmw2
Copy link
Contributor

dwmw2 commented Sep 28, 2016

Hm, can you show output of p11tool --list-tokens ? Does it help if you make your object ID actually specify the token uniquely?

@mouse07410
Copy link
Contributor Author

mouse07410 commented Sep 28, 2016

The device must be a Yubico device that does not handle VERIFY with Lc=0

Correct. But I've been having the same problem with CAC (that handles VERIFY quite well). Not to mention that VERIFY doesn't seem to belong with the public key access/retrieval (and no, I'm not mad to ever provision the card in such a way that a public key gets CKA_PRIVATE set).

Providing the entire log of the original event (excerpt from the log is in the original posting):
opensc-20160927-broken.txt

Hm, can you show output of p11tool --list-tokens ?

This is the setup when everything works (Gemalto reader is disconnected):

$ p11tool --list-tokens
Token 0:
    URL: pkcs11:model=p11-kit-trust;manufacturer=PKCS%2311%20Kit;serial=1;token=Default%20Trust
    Label: Default Trust
    Type: Trust module
    Manufacturer: PKCS#11 Kit
    Model: p11-kit-trust
    Serial: 1
    Module: p11-kit-trust.so


Token 1:
    URL: pkcs11:model=p11-kit-trust;manufacturer=PKCS%2311%20Kit;serial=1;token=System%20Trust
    Label: System Trust
    Type: Trust module
    Manufacturer: PKCS#11 Kit
    Model: p11-kit-trust
    Serial: 1
    Module: p11-kit-trust.so

Plugging in Gemalto reader did not change the above output - still the same. Putting Yubikey NEO on that reader did not change the above output either.

Keychain Access (on Mac OS X) is able to lock and unlock the Yubikey token when it's on Gemalto reader - but does not show any certificates on it (which is does fine when the Yubikey is inserted directly into a USB port).

CAC inserted into a different reader (SCM Microsystems Inc. SCR 3310, with Gemalto reader still plugged in) does show its certificates in the Keychain Access, and requests for certificates or private key operations work.

CAC inserted into Gemalto reader also worked fine (certificates shown, keys accessible).

The failure appears to be with the NFC part of the Gemalto reader... (??? it used to work fine ???)

Here's the complete log of the above test:
opensc-nfc-broken.txt.zip

Update
After configuring GnuTLS properly (I don't use it, so it was a bit neglected), here's the output of p11tool --list-all with Yubikey plugged into a USB port, and CAC - into the Gemalto reader"

$ p11tool --list-all
warning: no token URL was provided for this operation; the available tokens are:

pkcs11:model=p11-kit-trust;manufacturer=PKCS%2311%20Kit;serial=1;token=Default%20Trust
pkcs11:model=p11-kit-trust;manufacturer=PKCS%2311%20Kit;serial=1;token=System%20Trust
pkcs11:model=PKCS%2315%20emulated;manufacturer=piv_II;serial=d104xxxxxxxxxxx;token=PIV%20Card%20Holder%20pin%20%28PIV_II%29
pkcs11:model=PKCS%2315%20emulated;manufacturer=piv_II;serial=646xxxxxxxx;token=PIV%20Card%20Holder%20pin%20%28PIV_II%29
$ 
$ p11tool --list-tokens
Token 0:
    URL: pkcs11:model=p11-kit-trust;manufacturer=PKCS%2311%20Kit;serial=1;token=Default%20Trust
    Label: Default Trust
    Type: Trust module
    Manufacturer: PKCS#11 Kit
    Model: p11-kit-trust
    Serial: 1
    Module: p11-kit-trust.so


Token 1:
    URL: pkcs11:model=p11-kit-trust;manufacturer=PKCS%2311%20Kit;serial=1;token=System%20Trust
    Label: System Trust
    Type: Trust module
    Manufacturer: PKCS#11 Kit
    Model: p11-kit-trust
    Serial: 1
    Module: p11-kit-trust.so


Token 2:
    URL: pkcs11:model=PKCS%2315%20emulated;manufacturer=piv_II;serial=d104xxxxxxxx;token=PIV%20Card%20Holder%20pin%20%28PIV_II%29
    Label: PIV Card Holder pin (PIV_II)
    Type: Hardware token
    Manufacturer: piv_II
    Model: PKCS#15 emulated
    Serial: d104xxxxxxxxxxxxxx
    Module: /Library/OpenSC/lib/opensc-pkcs11.so


Token 3:
    URL: pkcs11:model=PKCS%2315%20emulated;manufacturer=piv_II;serial=646xxxxxxxxxxxx;token=PIV%20Card%20Holder%20pin%20%28PIV_II%29
    Label: PIV Card Holder pin (PIV_II)
    Type: Hardware token
    Manufacturer: piv_II
    Model: PKCS#15 emulated
    Serial: 646xxxxxxxxxxxx
    Module: /Library/OpenSC/lib/opensc-pkcs11.so

Does it help if you make your object ID actually specify the token uniquely?

I don't know... Reason I suspect it wouldn't is because I see the LEDs blinking when the request goes to the token, so the system appears to know what device to ask for the certs/pubkeys...

How would I do that (a) with OpenSC command line tools, and (b) with pkcs11 URI that I feed to OpenSSL and libp11? I'd love to try it.

@dwmw2
Copy link
Contributor

dwmw2 commented Sep 28, 2016

Just specify more details — e.g. pkcs11:serial=1234567890;object=foo.

I asked about that because I was wondering it was a problem in the code which iterates over all the tokens, and searches in the one(s) which match the search criteria. And if your URI matches more than one token then it won't log in.

@mouse07410
Copy link
Contributor Author

mouse07410 commented Sep 28, 2016

  1. Having the above data (I've updated my previous post with more output that became available after GnuTLS was configured properly), could you provide the exact command line? Frankly, I'm still confused where I'd put that pkcs11 URI...
  2. I hear what you're saying about the login - but it shouldn't even try to login to retrieve the public key.

Update
This is the output of p11tool --list-tokens when I put Yubikey on Gemalto:

. . . . .
Token 2:
    URL: pkcs11:model=PKCS%2315%20emulated;manufacturer=piv_II;serial=00000000;token=PIV%20Card%20Holder%20pin%20%28PIV_II%29
    Label: PIV Card Holder pin (PIV_II)
    Type: Hardware token
    Manufacturer: piv_II
    Model: PKCS#15 emulated
    Serial: 00000000
    Module: /Library/OpenSC/lib/opensc-pkcs11.so

You can see that it did not get the serial number, for example.

@dengert
Copy link
Member

dengert commented Sep 28, 2016

in opensc-20160927-broken.txt line 1018-1020 an attempt to read the remaining 0xFC bytes of the second certificate
is failing with PCSC returning SCardTransmit/Control failed: 0x80100016
This appears to be SCARD_E_NOT_TRANSACTED (You can google for it) This should not happen.

It would appear it is caused by some other process, PCSC, the USB or causing some issue maybe power with the reader and PCSC has lost the lock on the card. Things fall apart quickly here. Could be hardware or power issues or It could have also been caused by some memory overwrite.
But it is in the middle of a loop to read the certificate in 0xFC byte chunks from the card, a very common operation.

Don't know what else to say.

@dwmw2
Copy link
Contributor

dwmw2 commented Sep 28, 2016

Your original command line included -inkey "pkcs11:object=KEY%20MAN%20pubkey;object-type=public"

That is the PKCS#11 URI. If you actually have two tokens in the system which each have an object with CKA_LABEL of KEY MAN pubkey, then you didn't actually disambiguate between the two. Hence my initial suspicion that you might be talking to the wrong token somehow?

But it doesn't look like that's the case now?

@mouse07410
Copy link
Contributor Author

Your original command line included -inkey "pkcs11:object=KEY%20MAN%20pubkey;object-type=public"

Ah, so I just add "serial=xxxxx;" to that pkcs11 URI. Understood, thank you very much!

@dwmw2 in my setup there (almost) always is only one token actually inserted and in use. So, I could understand a confusion between the readers - but only one of them would actually have a working card. From that I conclude that specifying token serial number isn't likely to help, correct?

@dengert I hear you (Dr. Google says "an attempt was made to end a non-existing transaction"). Would you recommend anything to remedy or diagnose further?

@dengert
Copy link
Member

dengert commented Sep 28, 2016

No ideas. Its Tokend on MacOS with Apple's pcsc and using that dual reader.

@mouse07410
Copy link
Contributor Author

Its Tokend on MacOS with Apple's pcsc and using that dual reader.

Actually, it is not - the same situation happens after I kill tokend, thus ensuring that nothing interferes with the command line operations (I do the same when I need to access OpenPGP applet).

Regarding the dual reader - yes, but I've no idea what to make of it. The contact part seems to be working with CAC. The contactless used to work fine with NEO, a couple of weeks ago it stopped working for no obvious reasons. I've been tracking OpenSC updates to the master, but even trying to install OpenSC.pkg built around end of July (which I know worked OK) did not help. And the problem is manifested by the very basic OpenSC tools (this is with tokend killed):

$ OPENSC_DEBUG=9 pkcs15-tool --read-certificate 03
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(2)
Certificate with ID '03' not found.
$ 

But trying (thanks, @dwmw2) p11-tool, I'm getting:

$ p11tool --info "pkcs11:object=PIV%20AUTH%20pubkey;object-type=public"
Object 0:
    URL: pkcs11:model=PKCS%2315%20emulated;manufacturer=piv_II;serial=646xxxx;token=PIV%20Card%20Holder%20pin%20%28PIV_II%29;id=%01;object=PIV%20AUTH%20pubkey;type=public
    Type: Public key
    Label: PIV AUTH pubkey
    Flags: CKA_WRAP/UNWRAP; 
    ID: 01

$ p11tool --info "pkcs11:object=SIGN%20pubkey;object-type=public"
No matching objects found
$ p11tool --info "pkcs11:object=Certificate%20for%20Digital%20Signature;object-type=public"
No matching objects found
$

@mtrojnar
Copy link
Member

mtrojnar commented Sep 30, 2016

Did one of the commits break the functionality that previously worked? Which commit?

@mouse07410
Copy link
Contributor Author

It appears so, but I've been unable to pinpoint it. I went back to a commit made in August (and I remember than it worked then), but couldn't get it to work any more. :-(

@mtrojnar
Copy link
Member

We have a CI test for accessing public keys without logging in:

/* get public keys */
rc = PKCS11_enumerate_public_keys(slot->token, &keys, &nkeys);
error_queue("PKCS11_enumerate_public_keys");
CHECK_ERR(rc < 0, "PKCS11_enumerate_public_keys failed", 4);
CHECK_ERR(nkeys == 0, "No public keys found", 5);
list_keys("Public keys", keys, nkeys);

libp11/tests/Makefile.am

Lines 14 to 16 in b7e39db

listkeys_SOURCES = ../examples/listkeys.c
check_PROGRAMS = auth fork-test rawrsasign listkeys

Something is broken in your environment, but not libp11.

@mouse07410
Copy link
Contributor Author

mouse07410 commented Sep 30, 2016

Something is broken in your environment, but not libp11.

@mtrojnar two facts to support your point: OpenSC command line tool also fails to access public keys (libp11 not involved there), and there was an OS update between when things worked and when they stopped working. :-(

Question: does GnuTLS and p11tool use libp11, or OpenSC only/directly?

@dwmw2
Copy link
Contributor

dwmw2 commented Sep 30, 2016

GnuTLS and p11tool will use OpenSC via p11-kit. Definitely not via libp11 (which is only for OpenSSL).

@dengert
Copy link
Member

dengert commented Sep 30, 2016

@mouse07410 You said "OpenSC command line tool also fails to access public keys"

Do you mean pkcs15-tool?
In which case a opensc-debug log would be helpful.

Or do you mean pkcs11-tool?
In which case a opensc-spy and opensc-debug logs would be helpful.

Some change in OpenSC might have changes this.

OR it could be the "SCardTransmit/Control failed: 0x80100016"
issue related to hardware with the dual reader or software changes in the OS or PCSC
You said: "there was an OS update between when things worked and when they stopped working."
Anyway to use a Mac that has not been upgraded?

Do you have more then one reader? That could pin down a hardware problem.

Do you have or can get a Linux system to try your reader and cards to see if you can reproduce the problems?

@mouse07410
Copy link
Contributor Author

mouse07410 commented Sep 30, 2016

Do you mean pkcs15-tool? In which case a opensc-debug log would be helpful.
Or do you mean pkcs11-tool? In which case a opensc-spy and opensc-debug logs would be helpful.

Actually I meant both. Regarding the logs: noted.

$ OPENSC_DEBUG=9 pkcs15-tool -vvvv --read-certificate 03
0x7fff75470000 12:01:17.238 [pkcs15-tool] sc.c:264:sc_detect_card_presence: called
0x7fff75470000 12:01:17.238 [pkcs15-tool] reader-pcsc.c:397:pcsc_detect_card_presence: called
0x7fff75470000 12:01:17.238 [pkcs15-tool] reader-pcsc.c:303:refresh_attributes: SCM Microsystems Inc. SCR 3310 check
0x7fff75470000 12:01:17.239 [pkcs15-tool] reader-pcsc.c:323:refresh_attributes: returning with: 0 (Success)
0x7fff75470000 12:01:17.239 [pkcs15-tool] reader-pcsc.c:402:pcsc_detect_card_presence: returning with: 0 (Success)
0x7fff75470000 12:01:17.239 [pkcs15-tool] sc.c:269:sc_detect_card_presence: returning with: 0 (Success)
0x7fff75470000 12:01:17.239 [pkcs15-tool] sc.c:264:sc_detect_card_presence: called
0x7fff75470000 12:01:17.239 [pkcs15-tool] reader-pcsc.c:397:pcsc_detect_card_presence: called
0x7fff75470000 12:01:17.239 [pkcs15-tool] reader-pcsc.c:303:refresh_attributes: Gemalto Prox Dual USB PC Link Reader(2) check
0x7fff75470000 12:01:17.240 [pkcs15-tool] reader-pcsc.c:323:refresh_attributes: returning with: 0 (Success)
0x7fff75470000 12:01:17.240 [pkcs15-tool] reader-pcsc.c:402:pcsc_detect_card_presence: returning with: 5
0x7fff75470000 12:01:17.240 [pkcs15-tool] sc.c:269:sc_detect_card_presence: returning with: 5
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(2)
0x7fff75470000 12:01:17.240 [pkcs15-tool] sc.c:264:sc_detect_card_presence: called
0x7fff75470000 12:01:17.240 [pkcs15-tool] reader-pcsc.c:397:pcsc_detect_card_presence: called
0x7fff75470000 12:01:17.240 [pkcs15-tool] reader-pcsc.c:303:refresh_attributes: Gemalto Prox Dual USB PC Link Reader(2) check
0x7fff75470000 12:01:17.240 [pkcs15-tool] reader-pcsc.c:323:refresh_attributes: returning with: 0 (Success)
0x7fff75470000 12:01:17.240 [pkcs15-tool] reader-pcsc.c:402:pcsc_detect_card_presence: returning with: 5
0x7fff75470000 12:01:17.240 [pkcs15-tool] sc.c:269:sc_detect_card_presence: returning with: 5
Connecting to card in reader Gemalto Prox Dual USB PC Link Reader(2)...
0x7fff75470000 12:01:17.240 [pkcs15-tool] card.c:196:sc_connect_card: called
0x7fff75470000 12:01:17.240 [pkcs15-tool] reader-pcsc.c:509:pcsc_connect: called
0x7fff75470000 12:01:17.240 [pkcs15-tool] reader-pcsc.c:303:refresh_attributes: Gemalto Prox Dual USB PC Link Reader(2) check
0x7fff75470000 12:01:17.241 [pkcs15-tool] reader-pcsc.c:323:refresh_attributes: returning with: 0 (Success)
0x7fff75470000 12:01:17.242 [pkcs15-tool] reader-pcsc.c:538:pcsc_connect: Initial protocol: T=1
0x7fff75470000 12:01:17.242 [pkcs15-tool] reader-pcsc.c:269:pcsc_transmit: reader 'Gemalto Prox Dual USB PC Link Reader(2)'
0x7fff75470000 12:01:17.242 [pkcs15-tool] reader-pcsc.c:270:pcsc_transmit: 
Outgoing APDU (5 bytes):
FF CA 00 00 00 .....
0x7fff75470000 12:01:17.242 [pkcs15-tool] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7fff75470000 12:01:17.243 [pkcs15-tool] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (9 bytes):
04 16 2C 1B 6B 24 80 90 00 ..,.k$...
0x7fff75470000 12:01:17.243 [pkcs15-tool] reader-pcsc.c:495:initialize_uid: 
UID (7 bytes):
04 16 2C 1B 6B 24 80 ..,.k$.
0x7fff75470000 12:01:17.243 [pkcs15-tool] card.c:218:sc_connect_card: matching configured ATRs
0x7fff75470000 12:01:17.243 [pkcs15-tool] card.c:261:sc_connect_card: matching built-in ATRs
0x7fff75470000 12:01:17.243 [pkcs15-tool] card.c:266:sc_connect_card: trying driver 'PIV-II'
0x7fff75470000 12:01:17.243 [pkcs15-tool] card-piv.c:2877:piv_match_card: called
0x7fff75470000 12:01:17.243 [pkcs15-tool] card-piv.c:757:piv_find_aid: called
0x7fff75470000 12:01:17.243 [pkcs15-tool] card-piv.c:720:piv_select_aid: called
0x7fff75470000 12:01:17.243 [pkcs15-tool] card-piv.c:722:piv_select_aid: Got args: aid=f998940, aidlen=9, response=503a5030, responselen=261
0x7fff75470000 12:01:17.243 [pkcs15-tool] apdu.c:550:sc_transmit_apdu: called
0x7fff75470000 12:01:17.243 [pkcs15-tool] card.c:397:sc_lock: called
0x7fff75470000 12:01:17.243 [pkcs15-tool] reader-pcsc.c:582:pcsc_lock: called
0x7fff75470000 12:01:17.243 [pkcs15-tool] card-piv.c:3311:piv_card_reader_lock_obtained: called
0x7fff75470000 12:01:17.243 [pkcs15-tool] card-piv.c:3319:piv_card_reader_lock_obtained: returning with: 0 (Success)
0x7fff75470000 12:01:17.243 [pkcs15-tool] card.c:439:sc_lock: returning with: 0 (Success)
0x7fff75470000 12:01:17.243 [pkcs15-tool] apdu.c:517:sc_transmit: called
0x7fff75470000 12:01:17.243 [pkcs15-tool] apdu.c:371:sc_single_transmit: called
0x7fff75470000 12:01:17.243 [pkcs15-tool] apdu.c:376:sc_single_transmit: CLA:0, INS:A4, P1:4, P2:0, data(9) 0x10f998940
0x7fff75470000 12:01:17.243 [pkcs15-tool] reader-pcsc.c:269:pcsc_transmit: reader 'Gemalto Prox Dual USB PC Link Reader(2)'
0x7fff75470000 12:01:17.244 [pkcs15-tool] reader-pcsc.c:270:pcsc_transmit: 
Outgoing APDU (15 bytes):
00 A4 04 00 09 A0 00 00 03 08 00 00 10 00 00 ...............
0x7fff75470000 12:01:17.244 [pkcs15-tool] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7fff75470000 12:01:17.250 [pkcs15-tool] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (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                                  .....
0x7fff75470000 12:01:17.250 [pkcs15-tool] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7fff75470000 12:01:17.250 [pkcs15-tool] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7fff75470000 12:01:17.250 [pkcs15-tool] card.c:449:sc_unlock: called
0x7fff75470000 12:01:17.250 [pkcs15-tool] reader-pcsc.c:627:pcsc_unlock: called
0x7fff75470000 12:01:17.251 [pkcs15-tool] card-piv.c:738:piv_select_aid: returning with: 0 (Success)
0x7fff75470000 12:01:17.251 [pkcs15-tool] card-piv.c:769:piv_find_aid: found PIX
0x7fff75470000 12:01:17.251 [pkcs15-tool] card-piv.c:783:piv_find_aid: returning with: 0 (Success)
0x7fff75470000 12:01:17.251 [pkcs15-tool] card.c:280:sc_connect_card: matched: PIV-II  for multiple cards
0x7fff75470000 12:01:17.251 [pkcs15-tool] card-piv.c:2979:piv_init: called
0x7fff75470000 12:01:17.251 [pkcs15-tool] card-piv.c:2987:piv_init: Max send = 0 recv = 0 card->type = 14003
0x7fff75470000 12:01:17.251 [pkcs15-tool] apdu.c:550:sc_transmit_apdu: called
0x7fff75470000 12:01:17.251 [pkcs15-tool] card.c:397:sc_lock: called
0x7fff75470000 12:01:17.251 [pkcs15-tool] reader-pcsc.c:582:pcsc_lock: called
0x7fff75470000 12:01:17.251 [pkcs15-tool] card-piv.c:3311:piv_card_reader_lock_obtained: called
0x7fff75470000 12:01:17.251 [pkcs15-tool] card-piv.c:3319:piv_card_reader_lock_obtained: returning with: 0 (Success)
0x7fff75470000 12:01:17.251 [pkcs15-tool] card.c:439:sc_lock: returning with: 0 (Success)
0x7fff75470000 12:01:17.251 [pkcs15-tool] apdu.c:517:sc_transmit: called
0x7fff75470000 12:01:17.251 [pkcs15-tool] apdu.c:371:sc_single_transmit: called
0x7fff75470000 12:01:17.251 [pkcs15-tool] apdu.c:376:sc_single_transmit: CLA:0, INS:FD, P1:0, P2:0, data(0) 0x0
0x7fff75470000 12:01:17.251 [pkcs15-tool] reader-pcsc.c:269:pcsc_transmit: reader 'Gemalto Prox Dual USB PC Link Reader(2)'
0x7fff75470000 12:01:17.251 [pkcs15-tool] reader-pcsc.c:270:pcsc_transmit: 
Outgoing APDU (5 bytes):
00 FD 00 00 03 .....
0x7fff75470000 12:01:17.251 [pkcs15-tool] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7fff75470000 12:01:17.256 [pkcs15-tool] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (5 bytes):
01 00 04 90 00 .....
0x7fff75470000 12:01:17.256 [pkcs15-tool] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7fff75470000 12:01:17.256 [pkcs15-tool] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7fff75470000 12:01:17.256 [pkcs15-tool] card.c:449:sc_unlock: called
0x7fff75470000 12:01:17.256 [pkcs15-tool] reader-pcsc.c:627:pcsc_unlock: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:3008:piv_init: NEO card->type=14003, r=0x00000000 version=0x00010004
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:3052:piv_init: PIV card-type=14003 card_issues=0x00020313
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:2649:piv_process_history: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:973:piv_get_cached_data: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:974:piv_get_cached_data: #11
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:1013:piv_get_cached_data: get #11
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:908:piv_get_data: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:909:piv_get_data: #11
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:928:piv_get_data: get len of #11
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:484:piv_general_io: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:487:piv_general_io: cb 3f ff 5 : 0 0
0x7fff75470000 12:01:17.257 [pkcs15-tool] card.c:397:sc_lock: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] reader-pcsc.c:582:pcsc_lock: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:3311:piv_card_reader_lock_obtained: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:3319:piv_card_reader_lock_obtained: returning with: 0 (Success)
0x7fff75470000 12:01:17.257 [pkcs15-tool] card.c:439:sc_lock: returning with: 0 (Success)
0x7fff75470000 12:01:17.257 [pkcs15-tool] card-piv.c:527:piv_general_io: calling sc_transmit_apdu flags=3 le=8, resplen=8, resp=0x7fff503a4d70
0x7fff75470000 12:01:17.257 [pkcs15-tool] apdu.c:550:sc_transmit_apdu: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] card.c:397:sc_lock: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] card.c:439:sc_lock: returning with: 0 (Success)
0x7fff75470000 12:01:17.257 [pkcs15-tool] apdu.c:517:sc_transmit: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] apdu.c:371:sc_single_transmit: called
0x7fff75470000 12:01:17.257 [pkcs15-tool] apdu.c:376:sc_single_transmit: CLA:0, INS:CB, P1:3F, P2:FF, data(5) 0x7fff503a4d78
0x7fff75470000 12:01:17.257 [pkcs15-tool] reader-pcsc.c:269:pcsc_transmit: reader 'Gemalto Prox Dual USB PC Link Reader(2)'
0x7fff75470000 12:01:17.257 [pkcs15-tool] reader-pcsc.c:270:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 CB 3F FF 05 5C 03 5F C1 0C 08 ..?..\._...
0x7fff75470000 12:01:17.257 [pkcs15-tool] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7fff75470000 12:01:17.263 [pkcs15-tool] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (2 bytes):
6A 82 j.
0x7fff75470000 12:01:17.263 [pkcs15-tool] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7fff75470000 12:01:17.264 [pkcs15-tool] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7fff75470000 12:01:17.264 [pkcs15-tool] card.c:449:sc_unlock: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:533:piv_general_io: DEE r=0 apdu.resplen=0 sw1=6a sw2=82
0x7fff75470000 12:01:17.264 [pkcs15-tool] iso7816.c:121:iso7816_check_sw: File not found
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:544:piv_general_io: Card returned error 
0x7fff75470000 12:01:17.264 [pkcs15-tool] card.c:449:sc_unlock: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] reader-pcsc.c:627:pcsc_unlock: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:595:piv_general_io: returning with: -1201 (File not found)
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:960:piv_get_data: returning with: -1201 (File not found)
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:1040:piv_get_cached_data: returning with: -1201 (File not found)
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:2834:piv_process_history: returning with: 0 (Success)
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:973:piv_get_cached_data: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:974:piv_get_cached_data: #10
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:1013:piv_get_cached_data: get #10
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:908:piv_get_data: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:909:piv_get_data: #10
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:928:piv_get_data: get len of #10
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:484:piv_general_io: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:487:piv_general_io: cb 3f ff 3 : 0 0
0x7fff75470000 12:01:17.264 [pkcs15-tool] card.c:397:sc_lock: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] reader-pcsc.c:582:pcsc_lock: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:3311:piv_card_reader_lock_obtained: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:3319:piv_card_reader_lock_obtained: returning with: 0 (Success)
0x7fff75470000 12:01:17.264 [pkcs15-tool] card.c:439:sc_lock: returning with: 0 (Success)
0x7fff75470000 12:01:17.264 [pkcs15-tool] card-piv.c:527:piv_general_io: calling sc_transmit_apdu flags=3 le=8, resplen=8, resp=0x7fff503a4d70
0x7fff75470000 12:01:17.264 [pkcs15-tool] apdu.c:550:sc_transmit_apdu: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] card.c:397:sc_lock: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] card.c:439:sc_lock: returning with: 0 (Success)
0x7fff75470000 12:01:17.264 [pkcs15-tool] apdu.c:517:sc_transmit: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] apdu.c:371:sc_single_transmit: called
0x7fff75470000 12:01:17.264 [pkcs15-tool] apdu.c:376:sc_single_transmit: CLA:0, INS:CB, P1:3F, P2:FF, data(3) 0x7fff503a4d78
0x7fff75470000 12:01:17.264 [pkcs15-tool] reader-pcsc.c:269:pcsc_transmit: reader 'Gemalto Prox Dual USB PC Link Reader(2)'
0x7fff75470000 12:01:17.264 [pkcs15-tool] reader-pcsc.c:270:pcsc_transmit: 
Outgoing APDU (9 bytes):
00 CB 3F FF 03 5C 01 7E 08 ..?..\.~.
0x7fff75470000 12:01:17.264 [pkcs15-tool] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7fff75470000 12:01:17.271 [pkcs15-tool] reader-pcsc.c:279:pcsc_transmit: 
Incoming APDU (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                               /.@...
0x7fff75470000 12:01:17.271 [pkcs15-tool] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7fff75470000 12:01:17.271 [pkcs15-tool] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7fff75470000 12:01:17.271 [pkcs15-tool] card.c:449:sc_unlock: called
0x7fff75470000 12:01:17.271 [pkcs15-tool] card-piv.c:533:piv_general_io: DEE r=0 apdu.resplen=8 sw1=90 sw2=00
0x7fff75470000 12:01:17.271 [pkcs15-tool] card.c:449:sc_unlock: called
0x7fff75470000 12:01:17.271 [pkcs15-tool] reader-pcsc.c:627:pcsc_unlock: called
0x7fff75470000 12:01:17.272 [pkcs15-tool] card-piv.c:595:piv_general_io: returning with: 20
0x7fff75470000 12:01:17.272 [pkcs15-tool] card-piv.c:948:piv_get_data: buffer for #10 *buf=0x0x0 len=20
0x7fff75470000 12:01:17.272 [pkcs15-tool] card-piv.c:484:piv_general_io: called
0x7fff75470000 12:01:17.272 [pkcs15-tool] card-piv.c:487:piv_general_io: cb 3f ff 3 : 0 0
0x7fff75470000 12:01:17.272 [pkcs15-tool] card.c:397:sc_lock: called
0x7fff75470000 12:01:17.272 [pkcs15-tool] reader-pcsc.c:582:pcsc_lock: called
0x7fff75470000 12:01:17.272 [pkcs15-tool] card-piv.c:3311:piv_card_reader_lock_obtained: called
0x7fff75470000 12:01:17.272 [pkcs15-tool] card-piv.c:3319:piv_card_reader_lock_obtained: returning with: 0 (Success)
0x7fff75470000 12:01:17.272 [pkcs15-tool] card.c:439:sc_lock: returning with: 0 (Success)
. . . . .
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:403:piv_find_obj_by_containerid: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:404:piv_find_obj_by_containerid: str=0x1012
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:408:piv_find_obj_by_containerid: returning with: 29
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:2127:piv_is_object_present: returning with: 1
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-piv.c:726:sc_pkcs15emu_piv_init: Cert can not be present,i=21
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:2148:piv_card_ctl: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:2149:piv_card_ctl: cmd=1346983428 ptr=0x7fff503a4e28
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:403:piv_find_obj_by_containerid: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:404:piv_find_obj_by_containerid: str=0x1013
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:408:piv_find_obj_by_containerid: returning with: 30
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:2127:piv_is_object_present: returning with: 1
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-piv.c:726:sc_pkcs15emu_piv_init: Cert can not be present,i=22
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:2148:piv_card_ctl: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:2149:piv_card_ctl: cmd=1346983428 ptr=0x7fff503a4e28
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:403:piv_find_obj_by_containerid: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:404:piv_find_obj_by_containerid: str=0x1014
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:408:piv_find_obj_by_containerid: returning with: 31
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:2127:piv_is_object_present: returning with: 1
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-piv.c:726:sc_pkcs15emu_piv_init: Cert can not be present,i=23
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-piv.c:778:sc_pkcs15emu_piv_init: PIV-II adding pins...
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:2148:piv_card_ctl: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:2149:piv_card_ctl: cmd=1346983427 ptr=0x7fff503a4238
0x7fff75470000 12:01:19.585 [pkcs15-tool] card-piv.c:2140:piv_get_pin_preference: returning with: 0 (Success)
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-piv.c:809:sc_pkcs15emu_piv_init: DEE Adding pin 0 label=PIV Card Holder pin
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-piv.c:809:sc_pkcs15emu_piv_init: DEE Adding pin 1 label=PIV PUK
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-piv.c:825:sc_pkcs15emu_piv_init: PIV-II adding pub keys...
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-pubkey.c:802:sc_pkcs15_encode_pubkey_as_spki: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-pubkey.c:806:sc_pkcs15_encode_pubkey_as_spki: Encoding public key with algorithm 0
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-pubkey.c:599:sc_pkcs15_encode_pubkey_rsa: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-pubkey.c:610:sc_pkcs15_encode_pubkey_rsa: returning with: 0 (Success)
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-algo.c:530:sc_asn1_encode_algorithm_id: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-algo.c:531:sc_asn1_encode_algorithm_id: type of algorithm to encode: 0
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-algo.c:545:sc_asn1_encode_algorithm_id: encode algo 1.2.840.113549.1.1.1
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-algo.c:580:sc_asn1_encode_algorithm_id: return encoded algorithm ID: 06092A864886F70D0101010500
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-algo.c:581:sc_asn1_encode_algorithm_id: returning with: 0 (Success)
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-pubkey.c:872:sc_pkcs15_encode_pubkey_as_spki: returning with: 0 (Success)
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-piv.c:928:sc_pkcs15emu_piv_init: adding pubkey for 0 keyalg=0
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-pubkey.c:802:sc_pkcs15_encode_pubkey_as_spki: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-pubkey.c:806:sc_pkcs15_encode_pubkey_as_spki: Encoding public key with algorithm 0
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-pubkey.c:599:sc_pkcs15_encode_pubkey_rsa: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-pubkey.c:610:sc_pkcs15_encode_pubkey_rsa: returning with: 0 (Success)
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-algo.c:530:sc_asn1_encode_algorithm_id: called
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-algo.c:531:sc_asn1_encode_algorithm_id: type of algorithm to encode: 0
0x7fff75470000 12:01:19.585 [pkcs15-tool] pkcs15-algo.c:545:sc_asn1_encode_algorithm_id: encode algo 1.2.840.113549.1.1.1
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-algo.c:580:sc_asn1_encode_algorithm_id: return encoded algorithm ID: 06092A864886F70D0101010500
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-algo.c:581:sc_asn1_encode_algorithm_id: returning with: 0 (Success)
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-pubkey.c:872:sc_pkcs15_encode_pubkey_as_spki: returning with: 0 (Success)
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:928:sc_pkcs15emu_piv_init: adding pubkey for 1 keyalg=0
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:858:sc_pkcs15emu_piv_init: No cert for this pub key i=2
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:870:sc_pkcs15emu_piv_init: DEE look for env PIV_9D_KEY
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:876:sc_pkcs15emu_piv_init: DEE look for file NULL
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:858:sc_pkcs15emu_piv_init: No cert for this pub key i=3
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:870:sc_pkcs15emu_piv_init: DEE look for env PIV_9E_KEY
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:876:sc_pkcs15emu_piv_init: DEE look for file NULL
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:858:sc_pkcs15emu_piv_init: No cert for this pub key i=4
. . . . .
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:870:sc_pkcs15emu_piv_init: DEE look for env NULL
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:959:sc_pkcs15emu_piv_init: PIV-II adding private keys...
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-piv.c:1019:sc_pkcs15emu_piv_init: returning with: 0 (Success)
0x7fff75470000 12:01:19.586 [pkcs15-tool] pkcs15-syn.c:181:sc_pkcs15_bind_synthetic: returning with: 0 (Success)
0x7fff75470000 12:01:19.586 [pkcs15-tool] card.c:449:sc_unlock: called
0x7fff75470000 12:01:19.586 [pkcs15-tool] reader-pcsc.c:627:pcsc_unlock: called
0x7fff75470000 12:01:19.587 [pkcs15-tool] pkcs15.c:1275:sc_pkcs15_bind: returning with: 0 (Success)
Found PIV_II!
Certificate with ID '03' not found.
0x7fff75470000 12:01:19.587 [pkcs15-tool] pkcs15.c:1288:sc_pkcs15_unbind: called
0x7fff75470000 12:01:19.587 [pkcs15-tool] pkcs15-pin.c:758:sc_pkcs15_pincache_clear: called
0x7fff75470000 12:01:19.587 [pkcs15-tool] card.c:449:sc_unlock: called
0x7fff75470000 12:01:19.587 [pkcs15-tool] card.c:337:sc_disconnect_card: called
0x7fff75470000 12:01:19.587 [pkcs15-tool] card-piv.c:2844:piv_finish: called
0x7fff75470000 12:01:19.587 [pkcs15-tool] card-piv.c:2856:piv_finish: DEE freeing #0, 0x00 0x0:0 0x0:0
0x7fff75470000 12:01:19.587 [pkcs15-tool] card-piv.c:2856:piv_finish: DEE freeing #1, 0x01 0x7ff6a2500330:61 0x0:0
0x7fff75470000 12:01:19.587 [pkcs15-tool] card-piv.c:2856:piv_finish: DEE freeing #2, 0x01 0x7ff6a2402ac0:945 0x7ff6a2702b90:932
0x7fff75470000 12:01:19.587 [pkcs15-tool] card-piv.c:2856:piv_finish: DEE freeing #3, 0x00 0x0:0 0x0:0
. . . . .
0x7fff75470000 12:01:19.587 [pkcs15-tool] card-piv.c:2856:piv_finish: DEE freeing #54, 0x00 0x0:0 0x0:0
0x7fff75470000 12:01:19.587 [pkcs15-tool] card-piv.c:2856:piv_finish: DEE freeing #55, 0x00 0x0:0 0x0:0
0x7fff75470000 12:01:19.587 [pkcs15-tool] card-piv.c:2856:piv_finish: DEE freeing #56, 0x00 0x0:0 0x0:0
0x7fff75470000 12:01:19.587 [pkcs15-tool] reader-pcsc.c:566:pcsc_disconnect: called
0x7fff75470000 12:01:19.587 [pkcs15-tool] reader-pcsc.c:570:pcsc_disconnect: Gemalto Prox Dual USB PC Link Reader(2):SCardDisconnect returned: 0x00000000
0x7fff75470000 12:01:19.587 [pkcs15-tool] card.c:358:sc_disconnect_card: returning with: 0 (Success)
0x7fff75470000 12:01:19.587 [pkcs15-tool] ctx.c:843:sc_release_context: called
0x7fff75470000 12:01:19.587 [pkcs15-tool] reader-pcsc.c:834:pcsc_finish: called
$ 

Complete log:
opensc-pkcs15-nfc-bad.txt

Do you have more than one reader? That could pin down a hardware problem.

Yes. And only one type of the reader appeared to misbehave.

Also, it seemed to misbehave only with command line tools (OpenSSL + libp11, and OpenSC). Unlocking the screen using OpenSC.tokend succeeded several times.

Also:

$ pkcs15-tool --read-ssh-key 01
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(2)
ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQCdeKK/Bv0gGRsU8fZ6vhsBsZ/n74Jk1uE9fZTphleC99w. . . . .b1aF1dNkv0Rv3OnuUcIrVT8iYDQEN+0p3aLQl2ic4+RKPyVcb6k40vsfj4gkWY/7GZ PIV AUTH pubkey
$ pkcs15-tool --read-public-key 01
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(2)
-----BEGIN PUBLIC KEY-----
MIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAnXiivwb9IBkbFPH2er4b
AbGf5++CZNbhPX2U6YZXgvfcJNap40xRySv4twYPy6j1JcEPL3T5yslAu44gw1TI
. . . . .
9WhdXTZL9Eb9zp7lHCK1U/ImA0BDftKd2i0JdonOPkSj8lXG+pONL7H4+IJFmP+x
mQIDAQAB
-----END PUBLIC KEY-----
$ pkcs15-tool --read-certificate 01
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(2)
-----BEGIN CERTIFICATE-----
MIIDoDCCAgigAwIBAgIEV6nftjANBgkqhkiG9w0BAQsFADAaMRgwFgYDVQQDDA9G
b3Jlc3QgQ0EgUlNBIDQwHhcNMTYwODA5MTM1MjA5WhcNMTkwODA5MTM1MjA5WjAY
. . . . .
FdIJBNU3dH0aC0TLoNi2JbQCICUFDUHTMDAsfbz9m+irN83YjxJar+qHelgNWT2S
9Y28jZ75DybSf4H2Og4iwAaj37I=
-----END CERTIFICATE-----
$ pkcs15-tool --read-certificate 02
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(2)
-----BEGIN CERTIFICATE-----
MIIDqzCCAhOgAwIBAgIEV46RqTANBgkqhkiG9w0BAQsFADAaMRgwFgYDVQQDDA9G
b3Jlc3QgQ0EgUlNBIDQwHhcNMTYwNzE5MjA0NzM0WhcNMTkwNzE5MjA0NzM0WjAY
. . . . .
QKiwihRS0Dr4bWEsASjoDEhCJjzgZfSqfWKMF6yOefTGywbocOIfNE3mtB1kYlWz
K2Wh5Tk25AhmQbjp2Kzltp2/VDwiVHdbZ+yeNOAL8d0g+uZbjncoDDW3tJzb7IT6
DQHSV1Vn8fPqMQlOjVzzTpNv8v1YUm3Eb3sqK6p+t+NRpnbm3Jo4zrEdTGoMnd64
9lnXP/fUuTGc9tRH95FnsuKUDFriJQM1w7o1jZUcNRRSs6wrxXiC1ti5F9TKa4BP
TfDejJX9+3guJ0sha8z38T4MJRE+Trsyw0VFHBScM0qoXUyigSfpyPnVjWTQ8XsA
yYzpLYxz4FPl6lTASEHbEll4JDy3xP6srZfpx4PwyQ==
-----END CERTIFICATE-----
$ pkcs15-tool --read-certificate 03
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(2)
Certificate with ID '03' not found.
$ pkcs15-tool --read-certificate 03
Using reader with a card: Yubico Yubikey NEO OTP+U2F+CCID
-----BEGIN CERTIFICATE-----
MIIDrjCCAhagAwIBAgIEV46SEjANBgkqhkiG9w0BAQsFADAaMRgwFgYDVQQDDA9G
b3Jlc3QgQ0EgUlNBIDQwHhcNMTYwNzE5MjA0ODUzWhcNMTkwNzE5MjA0ODUzWjAY
. . . . .
N5fYCtl5Q8XTMzu4qLdJNMXMHAC2p8Nhjd5is1d90AHjcNVsU+qejmbwpDi9gzWg
aKzjzarM9DtJwpT58TktTE8M5dp23QQo/oJVFfW3s5fCyw==
-----END CERTIFICATE-----
$ pkcs15-tool --read-certificate 02
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(1)
Certificate with ID '02' not found.
$ pkcs15-tool --read-certificate 03
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(1)
Certificate with ID '03' not found.
$ pkcs15-tool --read-certificate 01
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(1)
Certificate with ID '01' not found.
$ pkcs15-tool --read-certificate 02
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(1)
Certificate with ID '02' not found.
$ pkcs15-tool --read-certificate 02
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(1)
-----BEGIN CERTIFICATE-----
MIIDqzCCAhOgAwIBAgIEV46RqTANBgkqhkiG9w0BAQsFADAaMRgwFgYDVQQDDA9G
. . . . .
TfDejJX9+3guJ0sha8z38T4MJRE+Trsyw0VFHBScM0qoXUyigSfpyPnVjWTQ8XsA
yYzpLYxz4FPl6lTASEHbEll4JDy3xP6srZfpx4PwyQ==
-----END CERTIFICATE-----
$ 

I don't understand. When the token is inserted in a USB port - all the certificates and keys are perfectly accessible. When it is accessed via NFC through Gemalto reader - sometimes all the certificates are not accessible, KEY MAN certificate and key is not accessible, others usually are... What seems to be broken? Mac OS X? The hardware reader (I have three Gemalto DU Prox readers, they all behave the same)? OpenSC? All of the above?

@dengert
Copy link
Member

dengert commented Sep 30, 2016

@mouse07410
Looking closer at opensc-20160927-broken.txt There are 6 failures were PCSC returns 0x80100016. The failures com on different commands, but looking at the times from "pcsc_internal_transmit: called" till the next line with the failure, they all appear to be a multiple of about .72 seconds.

This looks like some timer or timeout going on. Maybe it could be retried.

This spreed sheet does not format well view it in the write mode:

Line Start End Diff periods diff/period
1020 31.569 30.841 0.728 1 0.728
7745 38.864 36.758 2.106 3 0.702
8459 49.978 49.253 0.725 1 0.725
9632 50.897 50.159 0.738 1 0.738
11485 51.861 51.125 0.736 1 0.736
12305 54.035 51.929 2.106 3 0.702

@mouse07410
Copy link
Contributor Author

Very impressive, thanks!

This looks like some timer or timeout going on. Maybe it could be retried.

Yeah... Excellent to at least have an idea what to look for. Now the question is - is it a timer within PCSC (handled by Mac OS X), or with OpenSC (that we might be able to affect)?

@dengert
Copy link
Member

dengert commented Oct 2, 2016

@mouse07410
You has said there was an OS upgrade, and the failures were all wth contactless portion of the dual reader.

A contacless reader is really a NFC reader. There are programs/drivers besides PCSC that can use the USB device. On Debian based systems at least to get PCSC to work with the contactless device required
/etc/modprobe.d/blacklist-libnfc.conf contain:
blacklist pn533
blacklist nfc

Did MacOS add some new drivers or apps that may be accessing the contactless reader while PCSC is still trying to use it for the smart card?

Depending on how the duel reader works, interference of one could be caused by use of the other.

@mouse07410
Copy link
Contributor Author

Did MacOS add some new drivers or apps that may be accessing the contactless reader while PCSC is still trying to use it for the smart card?

I don't know - unfortunately Apple doesn't tell much about what their updates actually change. But the failures on the contactless side became almost regular - much more frequent than successes.

Depending on how the dual reader works, interference of one could be caused by use of the other

I never put two cards in this reader, and when one is used the other one appears disabled (a few months ago I experimented with that)...

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

No branches or pull requests

4 participants