search

OpenSC / OpenSC

Open source smart card tools and middleware. PKCS#11/MiniDriver/Tokend
https://github.com/OpenSC/OpenSC/wiki
GNU Lesser General Public License v2.1
2.57k stars 733 forks source link

Tokend unable to reconnect to PIV card after private key operation #786

Closed mouse07410 closed 8 years ago

mouse07410 commented 8 years ago

Expected behaviour

Mac OS X native applications (Apple Mail, Keychain Access) should be able to use the token after OpenSC command line tool completes its work and releases the token.

Actual behaviour

If the operation performed involved private key (signature, decryption, or on-token key derivation), subsequent attempts by Tokend to unlock the token fail. Observed with Yubikey and CAC.

Steps to reproduce

  1. Build and install the current master of OpenSC.
  2. Insert a token (RSA or ECC, doesn't matter).
  3. Perform a private key operation using, e.g., pkcs11-tool or openssl -engine pkcs11 <whatever>
  4. Attempt to unlock the token using Keychain Access (or Apple Mail). Observe failure to unlock the token.

    Logs

Good log, showing that after public key was accessed, the token stays operational, and Keychain Access has no difficulty unlocking it. This log was obtain by running openssl pkeyutl -engine pkcs11 -derive -keyform PEM -inkey e256.priv.pem -peerform engine -peerkey "pkcs11:object=KEY%20MAN%20pubkey;object-type=public" -hexdump, followed by Keychain "Unlock" command: opensc-derive-good.txt

Bad log, showing that after private key operation was performed on the token, Keychain Access fails to unlock it. This log was obtained by running pkcs11-tool -l --derive -m ECDH1-COFACTOR-DERIVE -d 03 -i e256.pub.der, followed by Keychain "Unlock" command: opensc-derive-bad.txt

Excerpt from the good log:

. . . . . 
0x7fff78711000 23:48:35.722 [opensc-pkcs11] pkcs15-pubkey.c:757:sc_pkcs15_encode_pubkey_ec: returning with: 0 (Success)
0x7fff78711000 23:48:35.722 [opensc-pkcs11] pkcs11-object.c:237:C_GetAttributeValue: Object 140436191600000: CKA_EC_POINT = 044104A5E2B8F6763FCA7C4018CDF6135AB2EBDD45979D06B8BD1B186F3CD97C
0x7fff78711000 23:48:35.722 [opensc-pkcs11] pkcs11-object.c:259:C_GetAttributeValue: C_GetAttributeValue(hSession=0x7fb9d94336d0, hObject=0x7fb9d9505d80) = CKR_OK
0x7fff78711000 23:48:41.026 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:502:getAcl: In OpenSCToken::getAcl()
0x7fff78711000 23:48:41.026 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:154:pinStatus: In OpenSCToken::pinStatus for pinNum (1)
0x7fff78711000 23:48:41.026 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:161:pinStatus: In OpenSCToken::pinStatus blocked
0x7fff78711000 23:48:41.030 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:490:getOwner: In OpenSCToken::getOwner()
0x7fff78711000 23:48:41.030 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:502:getAcl: In OpenSCToken::getAcl()
0x7fff78711000 23:48:44.056 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:177:verifyPIN: In OpenSCToken::verifyPIN(1)
0x7fff78711000 23:48:44.056 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:223:_verifyPIN: In OpenSCToken::_verifyPIN(), PIN num is: 1
0x7fff78711000 23:48:44.056 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:237:_verifyPIN:   sc_pkcs15_get_objects(pin_id=01): 2
0x7fff78711000 23:48:44.056 [tokend] pkcs15-pin.c:295:sc_pkcs15_verify_pin: called
0x7fff78711000 23:48:44.056 [tokend] pkcs15-pin.c:296:sc_pkcs15_verify_pin: PIN(type:0;method:1;len:)
0x7fff78711000 23:48:44.056 [tokend] card.c:394:sc_lock: called
0x7fff78711000 23:48:44.056 [tokend] reader-pcsc.c:547:pcsc_lock: called
0x7fff78711000 23:48:44.057 [tokend] sec.c:159:sc_pin_cmd: called
0x7fff78711000 23:48:44.057 [tokend] apdu.c:550:sc_transmit_apdu: called
0x7fff78711000 23:48:44.057 [tokend] card.c:394:sc_lock: called
0x7fff78711000 23:48:44.057 [tokend] apdu.c:517:sc_transmit: called
0x7fff78711000 23:48:44.057 [tokend] apdu.c:371:sc_single_transmit: called
0x7fff78711000 23:48:44.057 [tokend] apdu.c:376:sc_single_transmit: CLA:0, INS:20, P1:0, P2:80, data(8) 0x7fff5e5c1010
0x7fff78711000 23:48:44.057 [tokend] reader-pcsc.c:269:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff78711000 23:48:44.057 [tokend] reader-pcsc.c:270:pcsc_transmit:
Outgoing APDU (13 bytes):
00 20 00 80 08 31 32 33 34 35 36 37 38 . ...12345678
0x7fff78711000 23:48:44.057 [tokend] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7fff78711000 23:48:44.089 [tokend] reader-pcsc.c:279:pcsc_transmit:
Incoming APDU (2 bytes):
90 00 ..
. . . . .
0x7fff78711000 23:48:44.090 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:243:_verifyPIN:   In OpenSCToken::verify returned 0 for pin 1
0x7fff78711000 23:48:44.090 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:208:verifyPIN:   PIN verified
. . . . .

Excerpt from the bad log:

. . . . .
0x7fff78711000 23:56:07.618 [opensc-pkcs11] framework-pkcs15.c:3719:pkcs15_prkey_derive: Derivation complete. Result 32.
. . . . .
0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs11-session.c:147:C_CloseSession: C_CloseSession(0x7ffeb0502130)
0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs11-session.c:98:sc_pkcs11_close_session: real C_CloseSession(0x7ffeb0502130)
0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs15-pin.c:690:sc_pkcs15_pincache_clear: called
0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs11-global.c:304:C_Finalize: C_Finalize()
0x7fff78711000 23:56:07.619 [opensc-pkcs11] ctx.c:819:sc_cancel: called
0x7fff78711000 23:56:07.619 [opensc-pkcs11] reader-pcsc.c:637:pcsc_cancel: called
0x7fff78711000 23:56:07.619 [opensc-pkcs11] slot.c:163:card_removed: Yubico Yubikey NEO OTP+U2F+CCID: card removed
0x7fff78711000 23:56:07.619 [opensc-pkcs11] slot.c:425:slot_token_removed: slot_token_removed(0x0)
0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs11-session.c:129:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x0) 0
0x7fff78711000 23:56:07.619 [opensc-pkcs11] framework-pkcs15.c:1364:pkcs15_release_token: pkcs15_release_token() not implemented
0x7fff78711000 23:56:07.619 [opensc-pkcs11] slot.c:425:slot_token_removed: slot_token_removed(0x1)
0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs11-session.c:129:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x1) 0
0x7fff78711000 23:56:07.619 [opensc-pkcs11] slot.c:425:slot_token_removed: slot_token_removed(0x2)
. . . . .
0x7fff78711000 23:56:07.619 [opensc-pkcs11] reader-pcsc.c:533:pcsc_disconnect: called
0x7fff78711000 23:56:07.628 [opensc-pkcs11] card.c:357:sc_disconnect_card: returning with: 0 (Success)
0x7fff78711000 23:56:07.628 [opensc-pkcs11] ctx.c:842:sc_release_context: called
0x7fff78711000 23:56:07.628 [opensc-pkcs11] reader-pcsc.c:794:pcsc_finish: called
0x7fff78711000 23:56:12.460 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:502:getAcl: In OpenSCToken::getAcl()
0x7fff78711000 23:56:12.460 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:154:pinStatus: In OpenSCToken::pinStatus for pinNum (1)
0x7fff78711000 23:56:12.460 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:161:pinStatus: In OpenSCToken::pinStatus blocked
0x7fff78711000 23:56:15.034 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:177:verifyPIN: In OpenSCToken::verifyPIN(1)
0x7fff78711000 23:56:15.034 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:223:_verifyPIN: In OpenSCToken::_verifyPIN(), PIN num is: 1
0x7fff78711000 23:56:15.034 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:237:_verifyPIN:   sc_pkcs15_get_objects(pin_id=01): 2
0x7fff78711000 23:56:15.034 [tokend] pkcs15-pin.c:295:sc_pkcs15_verify_pin: called
0x7fff78711000 23:56:15.034 [tokend] pkcs15-pin.c:296:sc_pkcs15_verify_pin: PIN(type:0;method:1;len:)
0x7fff78711000 23:56:15.034 [tokend] card.c:394:sc_lock: called
0x7fff78711000 23:56:15.034 [tokend] reader-pcsc.c:547:pcsc_lock: called
0x7fff78711000 23:56:15.034 [tokend] reader-pcsc.c:440:pcsc_reconnect: Reconnecting to the card...
0x7fff78711000 23:56:15.034 [tokend] reader-pcsc.c:303:refresh_attributes: Yubico Yubikey NEO OTP+U2F+CCID check
0x7fff78711000 23:56:15.035 [tokend] reader-pcsc.c:323:refresh_attributes: returning with: 0 (Success)
0x7fff78711000 23:56:15.036 [tokend] reader-pcsc.c:547:pcsc_lock: called
0x7fff78711000 23:56:15.036 [tokend] sec.c:159:sc_pin_cmd: called
0x7fff78711000 23:56:15.036 [tokend] apdu.c:550:sc_transmit_apdu: called
0x7fff78711000 23:56:15.036 [tokend] card.c:394:sc_lock: called
0x7fff78711000 23:56:15.036 [tokend] apdu.c:517:sc_transmit: called
0x7fff78711000 23:56:15.036 [tokend] apdu.c:371:sc_single_transmit: called
0x7fff78711000 23:56:15.036 [tokend] apdu.c:376:sc_single_transmit: CLA:0, INS:20, P1:0, P2:80, data(8) 0x7fff53ab8010
0x7fff78711000 23:56:15.036 [tokend] reader-pcsc.c:269:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID'
0x7fff78711000 23:56:15.036 [tokend] reader-pcsc.c:270:pcsc_transmit:
Outgoing APDU (13 bytes):
00 20 00 80 08 31 32 33 34 35 36 37 38 . ...12345678
0x7fff78711000 23:56:15.036 [tokend] reader-pcsc.c:199:pcsc_internal_transmit: called
0x7fff78711000 23:56:15.049 [tokend] reader-pcsc.c:279:pcsc_transmit:
Incoming APDU (2 bytes):
6D 00 m.
0x7fff78711000 23:56:15.050 [tokend] apdu.c:386:sc_single_transmit: returning with: 0 (Success)
0x7fff78711000 23:56:15.050 [tokend] apdu.c:539:sc_transmit: returning with: 0 (Success)
0x7fff78711000 23:56:15.050 [tokend] card.c:434:sc_unlock: called
0x7fff78711000 23:56:15.050 [tokend] iso7816.c:121:iso7816_check_sw: Instruction code not supported or invalid
0x7fff78711000 23:56:15.050 [tokend] sec.c:206:sc_pin_cmd: returning with: -1204 (Unsupported INS byte in APDU)
0x7fff78711000 23:56:15.050 [tokend] pkcs15-pin.c:368:sc_pkcs15_verify_pin: PIN cmd result -1204
. . . . .

Update Specifying disconnect_action = leave (instead of default reset) in opensc.conf seems to alleviate this problem, but I don't know what (other) consequences that setting has (I wonder whether these settings and what they do is documented anywhere?). And reconnect() is still broken. So would still like somebody more knowledgable than myself to go over this.

dengert commented 8 years ago 
Looks like when the opensc-pkcs11 process ends, pcscd may be
powering down the reader. You need a pcscd trace to see what is
going on with the reader. Also look at the opensc.conf to see what
reader-pcsc.c  will do with the reader on disconect. 

A higher opensc debug level  might show the calls to pcscd, and
might show if the opensc-pkcs11 process still has a lock set. 

It is also not clear why the openssl pkeyutl -engine pkcs11
  never cleaned up the pkcs11 sessions. 
  It should have also done  C_CloseSession,
  C_Finalize, leading to pcsc_finish which should have
  then produced the same problem as the bad log. 
   
On 6/4/2016 11:27 PM, Mouse wrote:

  Expected behaviour
  Mac OS X native applications (Apple Mail, Keychain Access)
    should be able to use the token after OpenSC command line tool
    completes its work and releases the token.
  Actual behaviour
  If the operation performed involved private key (signature,
    decryption, or on-token key derivation), subsequent attempts by
    Tokend to unlock the token fail. Observed with Yubikey and CAC.
  Steps to reproduce

    Build and install the current master of OpenSC.
    Insert a token (RSA or ECC, doesn't matter).
    Perform a private key operation using, e.g., pkcs11-tool
      or openssl -engine pkcs11 <whatever>

    Attempt to unlock the token using Keychain Access (or Apple
      Mail). Observe failure to unlock the token.

  Logs
  Good log, showing that after public key was accessed, the token
    stays operational, and Keychain Access has no difficulty
    unlocking it. This log was obtain by running openssl
      pkeyutl -engine pkcs11 -derive -keyform PEM -inkey
      e256.priv.pem -peerform engine -peerkey
      "pkcs11:object=KEY%20MAN%20pubkey;object-type=public" -hexdump,
    followed by Keychain "Unlock" command:
    opensc-derive-good.txt
  Bad log, showing that after private key operation was performed
    on the token, Keychain Access fails to unlock it. This log was
    obtained by running pkcs11-tool -l --derive -m
      ECDH1-COFACTOR-DERIVE -d 03 -i e256.pub.der, followed
    by Keychain "Unlock" command:
    opensc-derive-bad.txt
  Excerpt from the good log:
  . . . . .

0x7fff78711000 23:48:35.722 [opensc-pkcs11] pkcs15-pubkey.c:757:sc_pkcs15_encode_pubkey_ec: returning with: 0 (Success) 0x7fff78711000 23:48:35.722 [opensc-pkcs11] pkcs11-object.c:237:C_GetAttributeValue: Object 140436191600000: CKA_EC_POINT = 044104A5E2B8F6763FCA7C4018CDF6135AB2EBDD45979D06B8BD1B186F3CD97C 0x7fff78711000 23:48:35.722 [opensc-pkcs11] pkcs11-object.c:259:C_GetAttributeValue: C_GetAttributeValue(hSession=0x7fb9d94336d0, hObject=0x7fb9d9505d80) = CKR_OK 0x7fff78711000 23:48:41.026 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:502:getAcl: In OpenSCToken::getAcl() 0x7fff78711000 23:48:41.026 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:154:pinStatus: In OpenSCToken::pinStatus for pinNum (1) 0x7fff78711000 23:48:41.026 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:161:pinStatus: In OpenSCToken::pinStatus blocked 0x7fff78711000 23:48:41.030 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:490:getOwner: In OpenSCToken::getOwner() 0x7fff78711000 23:48:41.030 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:502:getAcl: In OpenSCToken::getAcl() 0x7fff78711000 23:48:44.056 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:177:verifyPIN: In OpenSCToken::verifyPIN(1) 0x7fff78711000 23:48:44.056 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:223:_verifyPIN: In OpenSCToken::_verifyPIN(), PIN num is: 1 0x7fff78711000 23:48:44.056 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:237:_verifyPIN: sc_pkcs15_get_objects(pin_id=01): 2 0x7fff78711000 23:48:44.056 [tokend] pkcs15-pin.c:295:sc_pkcs15_verify_pin: called 0x7fff78711000 23:48:44.056 [tokend] pkcs15-pin.c:296:sc_pkcs15_verify_pin: PIN(type:0;method:1;len:) 0x7fff78711000 23:48:44.056 [tokend] card.c:394:sc_lock: called 0x7fff78711000 23:48:44.056 [tokend] reader-pcsc.c:547:pcsc_lock: called 0x7fff78711000 23:48:44.057 [tokend] sec.c:159:sc_pin_cmd: called 0x7fff78711000 23:48:44.057 [tokend] apdu.c:550:sc_transmit_apdu: called 0x7fff78711000 23:48:44.057 [tokend] card.c:394:sc_lock: called 0x7fff78711000 23:48:44.057 [tokend] apdu.c:517:sc_transmit: called 0x7fff78711000 23:48:44.057 [tokend] apdu.c:371:sc_single_transmit: called 0x7fff78711000 23:48:44.057 [tokend] apdu.c:376:sc_single_transmit: CLA:0, INS:20, P1:0, P2:80, data(8) 0x7fff5e5c1010 0x7fff78711000 23:48:44.057 [tokend] reader-pcsc.c:269:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID' 0x7fff78711000 23:48:44.057 [tokend] reader-pcsc.c:270:pcsc_transmit: Outgoing APDU (13 bytes): 00 20 00 80 08 31 32 33 34 35 36 37 38 . ...12345678 0x7fff78711000 23:48:44.057 [tokend] reader-pcsc.c:199:pcsc_internal_transmit: called 0x7fff78711000 23:48:44.089 [tokend] reader-pcsc.c:279:pcsc_transmit: Incoming APDU (2 bytes): 90 00 .. . . . . . 0x7fff78711000 23:48:44.090 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:243:_verifyPIN: In OpenSCToken::verify returned 0 for pin 1 0x7fff78711000 23:48:44.090 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:208:verifyPIN: PIN verified . . . . .

  Excerpt from the bad log:
  . . . . .

0x7fff78711000 23:56:07.618 [opensc-pkcs11] framework-pkcs15.c:3719:pkcs15_prkey_derive: Derivation complete. Result 32. . . . . . 0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs11-session.c:147:C_CloseSession: C_CloseSession(0x7ffeb0502130) 0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs11-session.c:98:sc_pkcs11_close_session: real C_CloseSession(0x7ffeb0502130) 0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs15-pin.c:690:sc_pkcs15_pincache_clear: called 0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs11-global.c:304:C_Finalize: C_Finalize() 0x7fff78711000 23:56:07.619 [opensc-pkcs11] ctx.c:819:sc_cancel: called 0x7fff78711000 23:56:07.619 [opensc-pkcs11] reader-pcsc.c:637:pcsc_cancel: called 0x7fff78711000 23:56:07.619 [opensc-pkcs11] slot.c:163:card_removed: Yubico Yubikey NEO OTP+U2F+CCID: card removed 0x7fff78711000 23:56:07.619 [opensc-pkcs11] slot.c:425:slot_token_removed: slot_token_removed(0x0) 0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs11-session.c:129:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x0) 0 0x7fff78711000 23:56:07.619 [opensc-pkcs11] framework-pkcs15.c:1364:pkcs15_release_token: pkcs15_release_token() not implemented 0x7fff78711000 23:56:07.619 [opensc-pkcs11] slot.c:425:slot_token_removed: slot_token_removed(0x1) 0x7fff78711000 23:56:07.619 [opensc-pkcs11] pkcs11-session.c:129:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x1) 0 0x7fff78711000 23:56:07.619 [opensc-pkcs11] slot.c:425:slot_token_removed: slot_token_removed(0x2) . . . . . 0x7fff78711000 23:56:07.619 [opensc-pkcs11] reader-pcsc.c:533:pcsc_disconnect: called 0x7fff78711000 23:56:07.628 [opensc-pkcs11] card.c:357:sc_disconnect_card: returning with: 0 (Success) 0x7fff78711000 23:56:07.628 [opensc-pkcs11] ctx.c:842:sc_release_context: called 0x7fff78711000 23:56:07.628 [opensc-pkcs11] reader-pcsc.c:794:pcsc_finish: called 0x7fff78711000 23:56:12.460 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:502:getAcl: In OpenSCToken::getAcl() 0x7fff78711000 23:56:12.460 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:154:pinStatus: In OpenSCToken::pinStatus for pinNum (1) 0x7fff78711000 23:56:12.460 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:161:pinStatus: In OpenSCToken::pinStatus blocked 0x7fff78711000 23:56:15.034 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:177:verifyPIN: In OpenSCToken::verifyPIN(1) 0x7fff78711000 23:56:15.034 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:223:_verifyPIN: In OpenSCToken::_verifyPIN(), PIN num is: 1 0x7fff78711000 23:56:15.034 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:237:_verifyPIN: sc_pkcs15_get_objects(pin_id=01): 2 0x7fff78711000 23:56:15.034 [tokend] pkcs15-pin.c:295:sc_pkcs15_verify_pin: called 0x7fff78711000 23:56:15.034 [tokend] pkcs15-pin.c:296:sc_pkcs15_verify_pin: PIN(type:0;method:1;len:) 0x7fff78711000 23:56:15.034 [tokend] card.c:394:sc_lock: called 0x7fff78711000 23:56:15.034 [tokend] reader-pcsc.c:547:pcsc_lock: called 0x7fff78711000 23:56:15.034 [tokend] reader-pcsc.c:440:pcsc_reconnect: Reconnecting to the card... 0x7fff78711000 23:56:15.034 [tokend] reader-pcsc.c:303:refresh_attributes: Yubico Yubikey NEO OTP+U2F+CCID check 0x7fff78711000 23:56:15.035 [tokend] reader-pcsc.c:323:refresh_attributes: returning with: 0 (Success) 0x7fff78711000 23:56:15.036 [tokend] reader-pcsc.c:547:pcsc_lock: called 0x7fff78711000 23:56:15.036 [tokend] sec.c:159:sc_pin_cmd: called 0x7fff78711000 23:56:15.036 [tokend] apdu.c:550:sc_transmit_apdu: called 0x7fff78711000 23:56:15.036 [tokend] card.c:394:sc_lock: called 0x7fff78711000 23:56:15.036 [tokend] apdu.c:517:sc_transmit: called 0x7fff78711000 23:56:15.036 [tokend] apdu.c:371:sc_single_transmit: called 0x7fff78711000 23:56:15.036 [tokend] apdu.c:376:sc_single_transmit: CLA:0, INS:20, P1:0, P2:80, data(8) 0x7fff53ab8010 0x7fff78711000 23:56:15.036 [tokend] reader-pcsc.c:269:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+U2F+CCID' 0x7fff78711000 23:56:15.036 [tokend] reader-pcsc.c:270:pcsc_transmit: Outgoing APDU (13 bytes): 00 20 00 80 08 31 32 33 34 35 36 37 38 . ...12345678 0x7fff78711000 23:56:15.036 [tokend] reader-pcsc.c:199:pcsc_internal_transmit: called 0x7fff78711000 23:56:15.049 [tokend] reader-pcsc.c:279:pcsc_transmit: Incoming APDU (2 bytes): 6D 00 m. 0x7fff78711000 23:56:15.050 [tokend] apdu.c:386:sc_single_transmit: returning with: 0 (Success) 0x7fff78711000 23:56:15.050 [tokend] apdu.c:539:sc_transmit: returning with: 0 (Success) 0x7fff78711000 23:56:15.050 [tokend] card.c:434:sc_unlock: called 0x7fff78711000 23:56:15.050 [tokend] iso7816.c:121:iso7816_check_sw: Instruction code not supported or invalid 0x7fff78711000 23:56:15.050 [tokend] sec.c:206:sc_pin_cmd: returning with: -1204 (Unsupported INS byte in APDU) 0x7fff78711000 23:56:15.050 [tokend] pkcs15-pin.c:368:sc_pkcs15_verify_pin: PIN cmd result -1204 . . . . .

  —
    You are receiving this because you are subscribed to this
    thread.
    Reply to this email directly, view it on
      GitHub, or mute
      the thread.

--

Douglas E. Engert DEEngert@gmail.com

mouse07410 commented 8 years ago

Looks like when the opensc-pkcs11 process ends, pcscd may be powering down the reader.

I do not observe this, as the LED indicator does not turn off.

You need a pcscd trace to see what is going on with the reader.

Oy... That's difficult.

Also look at the opensc.conf to see what reader-pcsc.c will do with the reader on disconnect.

Already did. The default action of disconnect is to reset. When that is set, reconnect is broken. I changed it to leave, and reconnect started working correctly.

P.S. Changing disconnect default to unpower causes the token/reader to turn off. Keychain Access seems unable to turn it back on. But OpenSC command line utilities appear to be able to do that in the process of normal operations, i.e.:

  1. Edit opensc.conf and set disconnect_action = unpower.
  2. Perform pkcs11-tool -l --derive -m ECDH1-COFACTOR-DERIVE -d 03 -i e256.pub.der -o /dev/null. After completion the token/reader is powered off.
  3. Try Keychain Access - it is unable to turn the reader back on.
  4. Edit opensc.conf and set disconnect_action = leave.
  5. Perform (2) again. It runs and completes fine. The reader stays on after completion, as indicated by its LED.
  6. Now try Keychain Access, and observe that it can unlock the token correctly.
dengert commented 8 years ago 
On 6/5/2016 8:16 AM, Mouse wrote:

    Looks like when the opensc-pkcs11 process ends, pcscd may be
      powering down the reader. 

  I do not observe this, as the LED indicator does not turn off.

    You need a pcscd trace to see what is going on with the
      reader. 

  Oy... That's difficult.

    Also look at the opensc.conf to see what reader-pcsc.c
      will do with the reader on disconnect.

  Already did. The default action of disconnect
    is to reset. When that is set, reconnect is
    broken. I changed it to leave, and reconnect
    started working correctly.

Sounds like tokend is calling some of the sc_pkcs15 routines, but
not any that can check the state of the card, and cause cause a
recconect to the card to be done. 

Look at https://github.com/OpenSC/OpenSC/pull/624 from last year
that has not bee accepted. https://github.com/frankmorgner had other
ideas so the PR  was never implemented.  Tokend is more like the
minidriver, in that both have long running sessions with cards, were
other processes can also access the card. Both need to handle a
condition where some other process may access the card while the
sessions are open.

Sounds like you have a circumvention to use "leave". 

  P.S. Changing disconnect default to unpower
    causes the token/reader to turn off. Keychain Access seems
    unable to turn it back on. But OpenSC command line utilities
    appear to be able to do that in the process of normal
    operations, i.e.:

    Edit opensc.conf and set disconnect_action
        = unpower.
    Perform pkcs11-tool -l --derive -m
        ECDH1-COFACTOR-DERIVE -d 03 -i e256.pub.der -o /dev/null.
      After completion the token/reader is powered off.
    Try Keychain Access - it is unable to turn the reader back
      on.
    Edit opensc.conf and set disconnect_action
        = leave.
    Perform (2) again. The reader stays on after completion, as
      indicated by its LED.
    Now try Keychain Access, and observe that it can unlock the
      token correctly.

  —
    You are receiving this because you commented.
    Reply to this email directly, view
      it on GitHub, or mute
      the thread.

--

Douglas E. Engert DEEngert@gmail.com

mouse07410 commented 8 years ago

@frankmorgner and @viktorTarasov in view of the above, are you willing to reconsider #624 ?

frankmorgner commented 8 years ago

yes, two processes changing each other's state is worth reconsidering #624.

mouse07410 commented 8 years ago

@frankmorgner thank you! (I think more than one process accessing smartcard is the inevitable reality, and GnuPG has made a huge mistake sacrificing a lot of usability for "exclusive access". At least I find that I very rarely use GPG signature - it interferes with the workflow, while S/MIME fits right in - all you need is to keep your smartcard inserted.)

@dengert, does #624 need to be updated to match the current state of the master?

dengert commented 8 years ago 
I am not saying #624 is the answer. I am saying tokend is not doing
enough using sc_pkcs15 calls to detect a possible situation. I don't
hear complaints about the minidriver, of Mozilla NSS. Look at how
PKCS#11 calls the framework-pkcs11.c routines that intern call the
sc_pkcs15  routines to detect if the card needs to be reconnected. 

On 6/6/2016 1:24 PM, Mouse wrote:

  @frankmorgner
    and @viktorTarasov
    in view of the above, are you willing to reconsider #624
    ?
  —
    You are receiving this because you commented.
    Reply to this email directly, view
      it on GitHub, or mute
      the thread.

--

Douglas E. Engert DEEngert@gmail.com

mouse07410 commented 8 years ago

Update

I am not saying #624 is the answer. I am saying tokend is not doing enough using sc_pkcs15 calls to detect a possible situation.

Ah, so you're saying Tokend should call sc_pkcs15_xxx to learn the status?

I don't hear complaints about the minidriver, of Mozilla NSS.

That may not mean much - because unless the user accesses the token by multiple applications, some of which do not use Tokend, the problem would not manifest itself. And Firefox uses opensc-pkcs11.so PKCS#11 shim library - it does not go through Tokend. I don't know how it works on Windows, but presumably all the applications go through the minidriver rather than use OpenSC libraries directly...?

So the only conclusive test would be to try an app that definitely uses minidriver, and an app that definitely does not use one. It would probably be more productive to just figure out whether additional code proposed in #624 is still needed (and augment OpenSC itself), and where the extra code/checks need to go in Tokend (and add it to Tokend, which I volunteer myself for :).

frankmorgner commented 8 years ago

Tokend could get the status by doing this https://github.com/OpenSC/OpenSC/blob/master/src/pkcs11/framework-pkcs15.c#L501-522

mouse07410 commented 8 years ago

Thank you! Where in your opinion would be a good place (method, function) in Tokend to add that code?

dengert commented 8 years ago 
The point I would make, is the code in C_GetTokenInfo to get the PIN
status  should be in a sc_pkcs15_* functions called at this point.
The function could  then be used by tokend for example. 

#624 defined sc_check_state,  sc_pkcs15_check_state, 
pkcs15_check_state (in framework-pkcs11.c) and check_state (in
struct sc_card_driver) so each card-*.c could have one. Additional
pcscd debug messages for locking were also added. 

#624 also tried to keep track if the user was logged in or not.  

The mods were never completed, and only the card-piv.c was changed
to use this code. 
If there is more interest, then lets talk. 

On 6/6/2016 4:16 PM, Mouse wrote:

  Thank you! Where in your opinion would be a good place (method,
    function) in Tokend to add that code?
  —
    You are receiving this because you were mentioned.
    Reply to this email directly, view
      it on GitHub, or mute
      the thread.

--

Douglas E. Engert DEEngert@gmail.com

mouse07410 commented 8 years ago

If I understand @dengert correctly, it may not be sufficient to call sc_pin_cmd() from Tokend, and more underlying support in OpenSC libraries would be needed.

I think adding xxx_check_state() may add some complexity, but the ability of Tokend to correctly determine the exact/complete status of the card seems well-worth that. I remember that people on several mailing lists complained about inability of (more than one!) Tokend to keep track of the card status, and the need to close an app (usually, Apple Mail), re-insert the card, and re-start the app in order for it to work. If we can fix this status discovery issue - I think many of those problems would go away, as they appear to be related to Tokend-using applications (and therefore, Tokend) being confused about the correct/current state of the card...

So yes, there is more interest!

mouse07410 commented 8 years ago

(Copying from https://github.com/OpenSC/OpenSC/issues/786)

I have to confess my confusion. The log in #786 seems to show that Tokend does prompt for the PIN (as I observed myself) and tries to unlock the token. But the token somehow is in a state (after reset) where it does not accept that request, and returns 6D 00 instead. Do we need to do more than ask for the token state here? Why after leave Tokend's request to unlock succeeds, and after reset it fails? Is any (re-)initialization (that must be performed after reset) missing here, and is the new code you've written going to provide that?

mouse07410 commented 8 years ago

This problem seems to have been solved by @dengert's #624. I recommend that is is merged (and have already merged it into my fork, of course). When that PR is merged, I'll close this issue.

P.S. Tokend (my fork) has been adjusted to make use of sc_pkcs15_check_state().

mouse07410 commented 8 years ago

Update Unfortunately, solution is partial. Still working on it.

Update2 Everything works, except for one thing: if you unlock the token with Keychain system tray (actually, top system menubar) icon, and then open Keychain Access and try to work with the token - synchronization will be lost and you'd have to remove and re-insert the token. As far as I can tell, everything else works fine. I'm still waiting for #624 to be merged to close this issue.

mouse07410 commented 8 years ago

Update3 To properly work with Firefox and Thunderbird (and other apps relying on opensc-pkcs11.so) without losing Tokend support, one needs https://github.com/OpenSC/OpenSC/pull/624#issuecomment-228240193 on top of #624.

mouse07410 commented 8 years ago

Update4 Current work merging #797, #816, and df62b35 on top of it looks promising (passed all the tests so far, there's a couple more to run), and appears to be better that the solution I was referring above https://github.com/OpenSC/OpenSC/issues/786#issuecomment-228792527.

Update. Current #816 subsumes df62b35.

mouse07410 commented 8 years ago

For all practical purposes, #797 and the latest #816 address this problem. If the current master correctly merged #816 - the problem is fixed.