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.

Sign up for GitHub

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

Jump to bottom

Using OpenPGP applet - fails to login...? #205

Closed
mouse07410 opened this issue Feb 1, 2018 · 4 comments
Closed

Using OpenPGP applet - fails to login...? #205

mouse07410 opened this issue Feb 1, 2018 · 4 comments

Comments

@mouse07410
Copy link
Contributor

OpenSSL+libp11 debug log:

0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] pkcs11-session.c:276:C_Login: C_Login(0x7fa118432ec0, 1)
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] pkcs11-session.c:298:C_Login: C_Login() slot->login_user -1
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] pkcs11-session.c:309:C_Login: C_Login() userType 1
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] framework-pkcs15.c:1520:pkcs15_login: pkcs15-login: userType 0x1, PIN length 7
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] pkcs15-pin.c:302:sc_pkcs15_verify_pin: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] pkcs15-pin.c:357:sc_pkcs15_verify_pin_with_session_pin: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] pkcs15-pin.c:361:sc_pkcs15_verify_pin_with_session_pin: PIN(type:0; method:1; value(0x7fa118432d00:7)
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] card.c:407:sc_lock: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] reader-pcsc.c:612:pcsc_lock: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] card.c:449:sc_lock: returning with: 0 (Success)
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] card.c:748:sc_select_file: called; type=2, path=3f00
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] card-openpgp.c:1101:pgp_select_file: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] card-openpgp.c:1165:pgp_select_file: returning with: 0 (Success)
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] card.c:783:sc_select_file: returning with: 0 (Success)
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] sec.c:170:sc_pin_cmd: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] card-openpgp.c:1570:pgp_pin_cmd: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] apdu.c:554:sc_transmit_apdu: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] card.c:407:sc_lock: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] card.c:449:sc_lock: returning with: 0 (Success)
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] apdu.c:521:sc_transmit: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] apdu.c:371:sc_single_transmit: called
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] apdu.c:378:sc_single_transmit: CLA:0, INS:20, P1:0, P2:81, data(7) 0x7fff59da5950
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] reader-pcsc.c:283:pcsc_transmit: reader 'Yubico Yubikey 4 OTP+U2F+CCID'
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] reader-pcsc.c:284:pcsc_transmit:
Outgoing APDU (12 bytes):
00 20 00 81 07 31 32 33 34 35 36 37 . ...1234567
0x7ffff13513c0 11:40:38.127 [opensc-pkcs11] reader-pcsc.c:212:pcsc_internal_transmit: called
0x7ffff13513c0 11:40:38.129 [opensc-pkcs11] reader-pcsc.c:293:pcsc_transmit:
Incoming APDU (2 bytes):
6D 00 m.

Same token, pkcs11-tool debug excerpt:

0x7ffff13513c0 11:56:13.727 [opensc-pkcs11] pkcs11-session.c:276:C_Login: C_Login(0x7f803fc25de0, 1)
0x7ffff13513c0 11:56:13.727 [opensc-pkcs11] pkcs11-session.c:298:C_Login: C_Login() slot->login_user -1
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] pkcs11-session.c:309:C_Login: C_Login() userType 1
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] framework-pkcs15.c:1520:pkcs15_login: pkcs15-login: userType 0x1, PIN length 7
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] pkcs15-pin.c:302:sc_pkcs15_verify_pin: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] pkcs15-pin.c:357:sc_pkcs15_verify_pin_with_session_pin: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] pkcs15-pin.c:361:sc_pkcs15_verify_pin_with_session_pin: PIN(type:0; method:1; value(0x7f8040807870:7)
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] card.c:407:sc_lock: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] reader-pcsc.c:612:pcsc_lock: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] card.c:449:sc_lock: returning with: 0 (Success)
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] card.c:748:sc_select_file: called; type=2, path=3f00
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] card-openpgp.c:1101:pgp_select_file: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] card-openpgp.c:1165:pgp_select_file: returning with: 0 (Success)
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] card.c:783:sc_select_file: returning with: 0 (Success)
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] sec.c:170:sc_pin_cmd: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] card-openpgp.c:1570:pgp_pin_cmd: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] apdu.c:554:sc_transmit_apdu: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] card.c:407:sc_lock: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] card.c:449:sc_lock: returning with: 0 (Success)
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] apdu.c:521:sc_transmit: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] apdu.c:371:sc_single_transmit: called
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] apdu.c:378:sc_single_transmit: CLA:0, INS:20, P1:0, P2:81, data(7) 0x7fff5240b840
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] reader-pcsc.c:283:pcsc_transmit: reader 'Yubico Yubikey 4 OTP+U2F+CCID'
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] reader-pcsc.c:284:pcsc_transmit:
Outgoing APDU (12 bytes):
00 20 00 81 07 31 32 33 34 35 36 37 . ...1234567
0x7ffff13513c0 11:56:13.728 [opensc-pkcs11] reader-pcsc.c:212:pcsc_internal_transmit: called
0x7ffff13513c0 11:56:13.738 [opensc-pkcs11] reader-pcsc.c:293:pcsc_transmit:
Incoming APDU (2 bytes):
90 00 ..

Somehow, when login is requested not via pkcs11-tool, the token responds with CKR_GENERAL_ERROR:

$ OPENSC_DEBUG=9 OPENSC_DRIVER=openpgp p11tool --list-privkeys "pkcs11:token=User%20PIN%20%28OpenPGP%20card%29" --login


*************** OpenSC PKCS#11 spy *****************
Loaded: "/Library/OpenSC/lib/opensc-pkcs11.dylib"

0: C_GetFunctionList
2018-02-01 12:18:17.995
Returned:  0 CKR_OK

1: C_Initialize
2018-02-01 12:18:17.997
[in] pInitArgs = 0x7fc6b342e850
     flags: 2
       CKF_OS_LOCKING_OK
Returned:  0 CKR_OK

2: C_GetInfo
2018-02-01 12:18:18.256
[out] pInfo: 
      cryptokiVersion:         2.20
      manufacturerID:         'OpenSC Project                  '
      flags:                   0
      libraryDescription:     'OpenSC smartcard framework      '
      libraryVersion:          0.17
Returned:  0 CKR_OK

3: C_GetSlotList
2018-02-01 12:18:18.256
[in] tokenPresent = 0x1
[out] pSlotList: 
Slot 4
Slot 5
[out] *pulCount = 0x2
Returned:  0 CKR_OK

4: C_GetTokenInfo
2018-02-01 12:18:18.258
[in] slotID = 0x4
[out] pInfo: 
      label:                  'User PIN (OpenPGP card)         '
      manufacturerID:         'Yubico                          '
      model:                  'PKCS#15 emulated'
      serialNumber:           '000602222222    '
      ulMaxSessionCount:       0
      ulSessionCount:          0
      ulMaxRwSessionCount:     0
      ulRwSessionCount:        0
      ulMaxPinLen:             127
      ulMinPinLen:             6
      ulTotalPublicMemory:     -1
      ulFreePublicMemory:      -1
      ulTotalPrivateMemory:    -1
      ulFreePrivateMemory:     -1
      hardwareVersion:         2.1
      firmwareVersion:         2.1
      time:                   '                '
      flags:                   40c
        CKF_LOGIN_REQUIRED               
        CKF_USER_PIN_INITIALIZED         
        CKF_TOKEN_INITIALIZED            
Returned:  0 CKR_OK

5: C_GetSlotInfo
2018-02-01 12:18:18.260
[in] slotID = 0x4
[out] pInfo: 
      slotDescription:        'Yubico Yubikey 4 OTP+U2F+CCID   '
                              '                                '
      manufacturerID:         'Yubico                          '
      hardwareVersion:         4.55
      firmwareVersion:         0.0
      flags:                   7
        CKF_TOKEN_PRESENT                
        CKF_REMOVABLE_DEVICE             
        CKF_HW_SLOT                      
Returned:  0 CKR_OK

6: C_OpenSession
2018-02-01 12:18:18.263
[in] slotID = 0x4
[in] flags = 0x4
pApplication=0x0
Notify=0x0
[out] *phSession = 0x7fc6b3600a10
Returned:  0 CKR_OK

7: C_CloseSession
2018-02-01 12:18:18.263
[in] hSession = 0x7fc6b3600a10
Returned:  0 CKR_OK

8: C_GetSlotList
2018-02-01 12:18:18.263
[in] tokenPresent = 0x1
[out] pSlotList: 
Slot 4
Slot 5
[out] *pulCount = 0x2
Returned:  0 CKR_OK

9: C_GetTokenInfo
2018-02-01 12:18:18.264
[in] slotID = 0x4
[out] pInfo: 
      label:                  'User PIN (OpenPGP card)         '
      manufacturerID:         'Yubico                          '
      model:                  'PKCS#15 emulated'
      serialNumber:           '000602222222    '
      ulMaxSessionCount:       0
      ulSessionCount:          0
      ulMaxRwSessionCount:     0
      ulRwSessionCount:        0
      ulMaxPinLen:             127
      ulMinPinLen:             6
      ulTotalPublicMemory:     -1
      ulFreePublicMemory:      -1
      ulTotalPrivateMemory:    -1
      ulFreePrivateMemory:     -1
      hardwareVersion:         2.1
      firmwareVersion:         2.1
      time:                   '                '
      flags:                   40c
        CKF_LOGIN_REQUIRED               
        CKF_USER_PIN_INITIALIZED         
        CKF_TOKEN_INITIALIZED            
Returned:  0 CKR_OK

10: C_GetSlotInfo
2018-02-01 12:18:18.265
[in] slotID = 0x4
[out] pInfo: 
      slotDescription:        'Yubico Yubikey 4 OTP+U2F+CCID   '
                              '                                '
      manufacturerID:         'Yubico                          '
      hardwareVersion:         4.55
      firmwareVersion:         0.0
      flags:                   7
        CKF_TOKEN_PRESENT                
        CKF_REMOVABLE_DEVICE             
        CKF_HW_SLOT                      
Returned:  0 CKR_OK

11: C_OpenSession
2018-02-01 12:18:18.266
[in] slotID = 0x4
[in] flags = 0x4
pApplication=0x0
Notify=0x0
[out] *phSession = 0x7fc6b3515fc0
Returned:  0 CKR_OK

12: C_GetSessionInfo
2018-02-01 12:18:18.266
[in] hSession = 0x7fc6b3515fc0
[out] pInfo: 
      slotID:                  4
      state:                  '           CKS_RO_PUBLIC_SESSION'
      flags:                   4
        CKF_SERIAL_SESSION               
      ulDeviceError:           0
Returned:  0 CKR_OK
Token 'User PIN (OpenPGP card)' with URL 'pkcs11:model=PKCS%2315%20emulated;manufacturer=Yubico;serial=000602222222;token=User%20PIN%20%28OpenPGP%20card%29' requires user PIN
Enter PIN: 

13: C_Login
2018-02-01 12:18:21.142
[in] hSession = 0x7fc6b3515fc0
[in] userType = CKU_USER
[in] pPin[ulPinLen] 00007fc6b3645230 / 7
    00000000  31 32 33 34 35 36 37                             1234567         
Returned:  5 CKR_GENERAL_ERROR
Error in crt_list_import (1): PKCS #11 error.
$

Here's the OPENSC_DEBUG=9 log:
pgp-opensc-bad.txt

But doing OPENSC_DEBUG=9 OPENSC_DRIVER=openpgp pkcs11-tool --slot 4 -O --login is successful:

$ OPENSC_DEBUG=9 OPENSC_DRIVER=openpgp pkcs11-tool --module /Library/OpenSC/lib/pkcs11-spy.dylib --slot 4 -O --login


*************** OpenSC PKCS#11 spy *****************
Loaded: "/Library/OpenSC/lib/opensc-pkcs11.dylib"

0: C_GetFunctionList
2018-02-01 12:29:04.934
Returned:  0 CKR_OK

1: C_Initialize
2018-02-01 12:29:04.934
[in] pInitArgs = 0x0
Returned:  0 CKR_OK

2: C_GetSlotList
2018-02-01 12:29:05.042
[in] tokenPresent = 0x0
[out] pSlotList: 
Count is 4
[out] *pulCount = 0x4
Returned:  0 CKR_OK

3: C_GetSlotList
2018-02-01 12:29:05.044
[in] tokenPresent = 0x0
[out] pSlotList: 
Slot 0
Slot 4
Slot 5
Slot 8
[out] *pulCount = 0x4
Returned:  0 CKR_OK

4: C_OpenSession
2018-02-01 12:29:05.045
[in] slotID = 0x4
[in] flags = 0x6
pApplication=0x0
Notify=0x0
[out] *phSession = 0x7f9a96522ef0
Returned:  0 CKR_OK

5: C_GetTokenInfo
2018-02-01 12:29:05.045
. . . . .
Returned:  0 CKR_OK
Logging in to "User PIN (OpenPGP card)".
Please enter User PIN: 

6: C_Login
2018-02-01 12:29:07.467
[in] hSession = 0x7f9a96522ef0
[in] userType = CKU_USER
[in] pPin[ulPinLen] 00007f9a966120a0 / 7
    00000000  31 32 33 34 35 36 37                             1234567         
Returned:  0 CKR_OK

7: C_FindObjectsInit
2018-02-01 12:29:07.478
[in] hSession = 0x7f9a96522ef0
[in] pTemplate[0]: 
Returned:  0 CKR_OK
. . . . .

Complete console SPY log (good result):
pgp-full-spy-good.txt
Complete debug log (good result):
pgp-opensc-debug-good.txt

I confess to having no clue as to what's wrong. Would appreciate any help.
This was referenced Feb 1, 2018
Closed
Closed
@mouse07410
Copy link
Contributor Author

@dengert perhaps you can see what the problem is?

@mouse07410
Copy link
Contributor Author

mouse07410 commented Feb 1, 2018 •
edited

Turns out (@dengert, thanks for diagnosing it) the problem was that p11-kit also invoked another module, which did SCARD_W_RESET_CARD that wasn't followed by an appropriate SELECT AID. That in turn caused CKR_GENERAL_ERROR when C_Login showed up at the token with no applet currently selected.

Hopefully OpenSC/OpenSC#1243 + OpenSC/OpenSC#1256 will take care of this problem. But it's not a libp11 issue.

@dengert
Copy link
Member

dengert commented Feb 2, 2018

Yes, #1243 will handle the OpenPGP application. #1256 will handle the PIV application. When either driver needs to do something to the card, it will get a reader lock, "SCardBeginTransaction" then detect if its application is active. If not it will do a SELECT AID to make it active. They also take actions if the card was reset too.

Since the reader lock, "SCardBeginTransaction" is done in PCSC, any other middleware even in other processes will be locked out during the transaction.

@mouse07410
Copy link
Contributor Author

Perfect. Thanks!!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@dengert @mouse07410