David Woodhouse
2014-11-06 20:52:41 UTC
I'm using a Yubikey NEO with OpenSC, from the OpenConnect VPN client.
It starts off by doing a test signature to validate that I've given it a
matching certificate and key, which works fine. PKCS#11 Spy output at
http://forum.yubico.com/viewtopic.php?f=26&t=1586
Then it connects to the HTTPS server and is required to do client
certificate authentication, so it tries another signature. Which fails
thus:
22: C_SignInit
2014-11-06 16:32:39.499
[in] hSession = 0x28a1560
pMechanism->type=CKM_RSA_PKCS
[in] hKey = 0x2a3b950
Returned: 0 CKR_OK
23: C_Sign
2014-11-06 16:32:39.499
[in] hSession = 0x28a1560
[in] pData[ulDataLen] 00007fff6dbbf6b0 / 36
00000000 42 B1 2E A0 4B A2 D6 C0 AD C0 CA 28 AD 0F 5D 34 B...K......(..]4
00000010 09 AD 6C 8C 2C A1 31 1E 13 FF 91 65 59 A3 9D D9 ..l.,.1....eY...
00000020 24 89 88 9D $...
[out] pSignature[*pulSignatureLen] NULL [size : 0x100 (256)]
Returned: 0 CKR_OK
24: C_Sign
2014-11-06 16:32:39.499
[in] hSession = 0x28a1560
[in] pData[ulDataLen] 00007fff6dbbf6b0 / 36
00000000 42 B1 2E A0 4B A2 D6 C0 AD C0 CA 28 AD 0F 5D 34 B...K......(..]4
00000010 09 AD 6C 8C 2C A1 31 1E 13 FF 91 65 59 A3 9D D9 ..l.,.1....eY...
00000020 24 89 88 9D $...
Returned: 257 CKR_USER_NOT_LOGGED_IN
I believe that's a violation of the PKCS#11 spec because
CKR_USER_NOT_LOGGED_IN isn't a valid return value from C_Sign(). You're
supposed to return that from C_SignInit() if it's the case.
We modified GnuTLS to attempt to re-login when a key had the
CKA_ALWAYS_AUTHENTICATE attribute set:
https://gitorious.org/gnutls/gnutls/commit/e1a0af191
The GnuTLS pkcs11_login() function, however, does this first:
25: C_GetSessionInfo
2014-11-06 19:56:41.534
[in] hSession = 0xed7620
[out] pInfo:
slotID: 1
state: ' CKS_RO_USER_FUNCTIONS'
flags: 4
CKF_SERIAL_SESSION
ulDeviceError: 0
Returned: 0 CKR_OK
It sees the CKS_RO_USER_FUNCTIONS and decides that it didn't need to log
in again after all. And then the C_Sign still fails.
So I hacked it not to do that, and to call C_Login unconditionally. Now
I get this...
28: C_Login
2014-11-06 20:02:11.599
[in] hSession = 0x2c089a0
[in] userType = CKU_USER
[in] pPin[ulPinLen] 000000000293d9c0 / 6
00000000 31 32 33 34 35 36 123456
Returned: 256 CKR_USER_ALREADY_LOGGED_IN
p11: Login result = 256
29: C_SignInit
2014-11-06 20:02:11.599
[in] hSession = 0x2c089a0
pMechanism->type=CKM_RSA_PKCS
[in] hKey = 0x269da90
Returned: 0 CKR_OK
30: C_Sign
2014-11-06 20:02:11.599
[in] hSession = 0x2c089a0
[in] pData[ulDataLen] 00007fff4449d3d0 / 36
00000000 E9 44 15 2E 2F 04 6F 66 78 9B F1 9F 35 20 1D
EB .D../.ofx...5 ..
00000010 A7 8B A1 B9 70 99 36 1B 9E 75 73 2D 4D 8F 7A
A6 ....p.6..us-M.z.
00000020 7D DE 54 B7 }.T.
[out] pSignature[*pulSignatureLen] NULL [size : 0x100 (256)]
Returned: 0 CKR_OK
31: C_Sign
2014-11-06 20:02:11.599
[in] hSession = 0x2c089a0
[in] pData[ulDataLen] 00007fff4449d3d0 / 36
00000000 E9 44 15 2E 2F 04 6F 66 78 9B F1 9F 35 20 1D
EB .D../.ofx...5 ..
00000010 A7 8B A1 B9 70 99 36 1B 9E 75 73 2D 4D 8F 7A
A6 ....p.6..us-M.z.
00000020 7D DE 54 B7 }.T.
Returned: 257 CKR_USER_NOT_LOGGED_IN
Full log including OPENSC_DEBUG=9 output at
http://david.woodhou.se/opensc-debug.txt â that final failing C_Sign()
call looks like this (not the same run, so don't be surprised that the
data we're signing are different):
0x7f6d5bc2a840 20:44:36.827 [opensc-pkcs11] reader-pcsc.c:249:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+CCID 00 00'
0x7f6d5bc2a840 20:44:36.827 [opensc-pkcs11] apdu.c:185:sc_apdu_log:
Outgoing APDU data [ 260 bytes] =====================================
10 87 07 9C FF 7C 82 01 06 82 00 81 82 01 00 00 .....|..........
01 FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF 00 84 0A 81 DA 22 ..............."
F5 48 AA 5F 12 18 9C 93 DF 99 D2 B5 A4 BA 7F 20 .H._...........
81 09 FF 51 ...Q
======================================================================
0x7f6d5bc2a840 20:44:36.827 [opensc-pkcs11] reader-pcsc.c:182:pcsc_internal_transmit: called
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:185:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================
90 00 ..
======================================================================
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:395:sc_single_transmit: returning with: 0 (Success)
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:548:sc_transmit: returning with: 0 (Success)
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:526:sc_transmit: called
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:380:sc_single_transmit: called
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:385:sc_single_transmit: CLA:0, INS:87, P1:7, P2:9C, data(11) 0x7fffe321f54f
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] reader-pcsc.c:249:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+CCID 00 00'
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:185:sc_apdu_log:
Outgoing APDU data [ 17 bytes] =====================================
00 87 07 9C 0B 9F C1 10 C1 2F 5D 66 C2 E1 54 28 ........./]f..T(
00 .
======================================================================
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] reader-pcsc.c:182:pcsc_internal_transmit: called
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] apdu.c:185:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================
69 82 i.
======================================================================
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] apdu.c:395:sc_single_transmit: returning with: 0 (Success)
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] apdu.c:548:sc_transmit: returning with: 0 (Success)
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] card.c:361:sc_unlock: called
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] card-piv.c:493:piv_general_io: DEE r=0 apdu.resplen=0 sw1=69 sw2=82
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] iso7816.c:102:iso7816_check_sw: Security status not satisfied
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] card-piv.c:503:piv_general_io: Card returned error
Is this simply a card error, and/or is it something that OpenSC should
be able to deal with?
It starts off by doing a test signature to validate that I've given it a
matching certificate and key, which works fine. PKCS#11 Spy output at
http://forum.yubico.com/viewtopic.php?f=26&t=1586
Then it connects to the HTTPS server and is required to do client
certificate authentication, so it tries another signature. Which fails
thus:
22: C_SignInit
2014-11-06 16:32:39.499
[in] hSession = 0x28a1560
pMechanism->type=CKM_RSA_PKCS
[in] hKey = 0x2a3b950
Returned: 0 CKR_OK
23: C_Sign
2014-11-06 16:32:39.499
[in] hSession = 0x28a1560
[in] pData[ulDataLen] 00007fff6dbbf6b0 / 36
00000000 42 B1 2E A0 4B A2 D6 C0 AD C0 CA 28 AD 0F 5D 34 B...K......(..]4
00000010 09 AD 6C 8C 2C A1 31 1E 13 FF 91 65 59 A3 9D D9 ..l.,.1....eY...
00000020 24 89 88 9D $...
[out] pSignature[*pulSignatureLen] NULL [size : 0x100 (256)]
Returned: 0 CKR_OK
24: C_Sign
2014-11-06 16:32:39.499
[in] hSession = 0x28a1560
[in] pData[ulDataLen] 00007fff6dbbf6b0 / 36
00000000 42 B1 2E A0 4B A2 D6 C0 AD C0 CA 28 AD 0F 5D 34 B...K......(..]4
00000010 09 AD 6C 8C 2C A1 31 1E 13 FF 91 65 59 A3 9D D9 ..l.,.1....eY...
00000020 24 89 88 9D $...
Returned: 257 CKR_USER_NOT_LOGGED_IN
I believe that's a violation of the PKCS#11 spec because
CKR_USER_NOT_LOGGED_IN isn't a valid return value from C_Sign(). You're
supposed to return that from C_SignInit() if it's the case.
We modified GnuTLS to attempt to re-login when a key had the
CKA_ALWAYS_AUTHENTICATE attribute set:
https://gitorious.org/gnutls/gnutls/commit/e1a0af191
The GnuTLS pkcs11_login() function, however, does this first:
25: C_GetSessionInfo
2014-11-06 19:56:41.534
[in] hSession = 0xed7620
[out] pInfo:
slotID: 1
state: ' CKS_RO_USER_FUNCTIONS'
flags: 4
CKF_SERIAL_SESSION
ulDeviceError: 0
Returned: 0 CKR_OK
It sees the CKS_RO_USER_FUNCTIONS and decides that it didn't need to log
in again after all. And then the C_Sign still fails.
So I hacked it not to do that, and to call C_Login unconditionally. Now
I get this...
28: C_Login
2014-11-06 20:02:11.599
[in] hSession = 0x2c089a0
[in] userType = CKU_USER
[in] pPin[ulPinLen] 000000000293d9c0 / 6
00000000 31 32 33 34 35 36 123456
Returned: 256 CKR_USER_ALREADY_LOGGED_IN
p11: Login result = 256
29: C_SignInit
2014-11-06 20:02:11.599
[in] hSession = 0x2c089a0
pMechanism->type=CKM_RSA_PKCS
[in] hKey = 0x269da90
Returned: 0 CKR_OK
30: C_Sign
2014-11-06 20:02:11.599
[in] hSession = 0x2c089a0
[in] pData[ulDataLen] 00007fff4449d3d0 / 36
00000000 E9 44 15 2E 2F 04 6F 66 78 9B F1 9F 35 20 1D
EB .D../.ofx...5 ..
00000010 A7 8B A1 B9 70 99 36 1B 9E 75 73 2D 4D 8F 7A
A6 ....p.6..us-M.z.
00000020 7D DE 54 B7 }.T.
[out] pSignature[*pulSignatureLen] NULL [size : 0x100 (256)]
Returned: 0 CKR_OK
31: C_Sign
2014-11-06 20:02:11.599
[in] hSession = 0x2c089a0
[in] pData[ulDataLen] 00007fff4449d3d0 / 36
00000000 E9 44 15 2E 2F 04 6F 66 78 9B F1 9F 35 20 1D
EB .D../.ofx...5 ..
00000010 A7 8B A1 B9 70 99 36 1B 9E 75 73 2D 4D 8F 7A
A6 ....p.6..us-M.z.
00000020 7D DE 54 B7 }.T.
Returned: 257 CKR_USER_NOT_LOGGED_IN
Full log including OPENSC_DEBUG=9 output at
http://david.woodhou.se/opensc-debug.txt â that final failing C_Sign()
call looks like this (not the same run, so don't be surprised that the
data we're signing are different):
0x7f6d5bc2a840 20:44:36.827 [opensc-pkcs11] reader-pcsc.c:249:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+CCID 00 00'
0x7f6d5bc2a840 20:44:36.827 [opensc-pkcs11] apdu.c:185:sc_apdu_log:
Outgoing APDU data [ 260 bytes] =====================================
10 87 07 9C FF 7C 82 01 06 82 00 81 82 01 00 00 .....|..........
01 FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
FF FF FF FF FF FF FF FF FF FF 00 84 0A 81 DA 22 ..............."
F5 48 AA 5F 12 18 9C 93 DF 99 D2 B5 A4 BA 7F 20 .H._...........
81 09 FF 51 ...Q
======================================================================
0x7f6d5bc2a840 20:44:36.827 [opensc-pkcs11] reader-pcsc.c:182:pcsc_internal_transmit: called
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:185:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================
90 00 ..
======================================================================
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:395:sc_single_transmit: returning with: 0 (Success)
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:548:sc_transmit: returning with: 0 (Success)
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:526:sc_transmit: called
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:380:sc_single_transmit: called
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:385:sc_single_transmit: CLA:0, INS:87, P1:7, P2:9C, data(11) 0x7fffe321f54f
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] reader-pcsc.c:249:pcsc_transmit: reader 'Yubico Yubikey NEO OTP+CCID 00 00'
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] apdu.c:185:sc_apdu_log:
Outgoing APDU data [ 17 bytes] =====================================
00 87 07 9C 0B 9F C1 10 C1 2F 5D 66 C2 E1 54 28 ........./]f..T(
00 .
======================================================================
0x7f6d5bc2a840 20:44:36.857 [opensc-pkcs11] reader-pcsc.c:182:pcsc_internal_transmit: called
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] apdu.c:185:sc_apdu_log:
Incoming APDU data [ 2 bytes] =====================================
69 82 i.
======================================================================
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] apdu.c:395:sc_single_transmit: returning with: 0 (Success)
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] apdu.c:548:sc_transmit: returning with: 0 (Success)
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] card.c:361:sc_unlock: called
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] card-piv.c:493:piv_general_io: DEE r=0 apdu.resplen=0 sw1=69 sw2=82
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] iso7816.c:102:iso7816_check_sw: Security status not satisfied
0x7f6d5bc2a840 20:44:36.869 [opensc-pkcs11] card-piv.c:503:piv_general_io: Card returned error
Is this simply a card error, and/or is it something that OpenSC should
be able to deal with?
--
dwmw2
dwmw2