PIV/OpenVPN/PKCS11 using libykcs11 results in PIN-entry loop

[ChrisTG742]

I managed to get the correct "pkcs11-id" and "providers" for using OpenVPN with the Yubikey, but still authentication stucks as passing through of the PIN seems to end in a loop.

When I enter the PIN, the modal dialog keeps popping up again and again:

(...) 2022-04-09 16:24:20 us=625000 PKCS#11: Calling pin_prompt hook for '' 2022-04-09 16:24:25 us=625000 MANAGEMENT: CMD 'password [...]' 2022-04-09 16:24:25 us=625000 PKCS#11: key_prompt/pin_prompt hook return rv=0 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_login_context C_Login rv=0-'CKR_OK' 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_login_context return rv=0-'CKR_OK' 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_login return rv=0-'CKR_OK' 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_getObjectById entry session=00000184D1C4F7F0, class=3, id=00000184D1B8C680, id_size=1, p_handle=00000184D1BA39C0 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_validate entry session=00000184D1C4F7F0 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1649514265 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK' 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_findObjects entry session=00000184D1C4F7F0, filter=0000004DD50FDDE0, filter_attrs=2, p_objects=0000004DD50FDE30, p_objects_found=0000004DD50FDE20 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_findObjects return rv=0-'CKR_OK', *p_objects_found=1 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_getObjectById return rv=0-'CKR_OK', *p_handle=00000056 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_certificate_resetSession return rv=0-'CKR_OK' 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_getObjectAttributes entry session=00000184D1C4F7F0, object=86, attrs=0000004DD50FDE50, count=6 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_getObjectAttributes return rv=0-'CKR_OK' 2022-04-09 16:24:25 us=640000 PKCS#11: Key attribute=00000005 always_authenticated=0 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_freeObjectAttributes entry attrs=0000004DD50FDE50, count=6 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_freeObjectAttributes return 2022-04-09 16:24:25 us=640000 PKCS#11: __pkcs11h_certificate_getKeyAttributes return rv=0-'CKR_OK' 2022-04-09 16:24:25 us=640000 PKCS#11: pkcs11h_certificate_sign_ex entry certificate=00000184D1BA39A0, mech_type=3, source=00000184D1BD2530, source_size=100, target=00000184D1BD2420, *p_target_size=100 2022-04-09 16:24:25 us=640000 PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=00000184D1BA39A0, op=0, mech_type=3, source=00000184D1BD2530, source_size=100, target=00000184D1BD2420, *p_target_size=100 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_certificate_validateSession entry certificate=00000184D1BA39A0 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_validate entry session=00000184D1C4F7F0 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1649514265 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK' 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_certificate_validateSession return rv=0-'CKR_OK' 2022-04-09 16:24:25 us=640000 PKCS#11: __pkcs11h_certificate_doPrivateOperation init rv=0 2022-04-09 16:24:25 us=640000 PKCS#11: __pkcs11h_certificate_doPrivateOperation op rv=48 2022-04-09 16:24:25 us=640000 PKCS#11: Private key operation failed rv=48-'CKR_DEVICE_ERROR' 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_certificate_resetSession entry certificate=00000184D1BA39A0, public_only=0, session_mutex_locked=1 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_login entry session=00000184D1C4F7F0, is_publicOnly=0, readonly=1, user_data=0000000000000000, mask_prompt=00000007 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_logout entry session=00000184D1C4F7F0 2022-04-09 16:24:25 us=640000 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=00000184D1BE3270, ptr=0000000000000000, ad=00000184D1BE32D8, idx=1, argl=0, argp=00007FF820F73C58 2022-04-09 16:24:25 us=640000 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=00000184D1BE3630, ptr=0000000000000000, ad=00000184D1BE3698, idx=1, argl=0, argp=00007FF820F73C58 2022-04-09 16:24:25 us=640000 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=00000184D1BE36F0, ptr=0000000000000000, ad=00000184D1BE3758, idx=1, argl=0, argp=00007FF820F73C58 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_logout return 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_reset entry session=00000184D1C4F7F0, user_data=0000000000000000, mask_prompt=00000007, p_slot=0000004DD50FDDD0 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_reset Expected token manufacturerID='Yubico (www.yubico.com)' model='YubiKey YK5', serialNumber='XXXXXXXXX', label='YubiKey PIV #XXXXXXXXX' 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_getSlotList entry provider=00000184D1BA2930, token_present=1, pSlotList=0000004DD50FDC50, pulCount=0000004DD50FDC44 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_getSlotList return rv=0-'CKR_OK' *pulCount=1 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_token_getTokenId entry p_token_id=0000004DD50FDC48 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0000004DD50FDC18 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=00000184D35706E0 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_token_getTokenId return rv=0-'CKR_OK', *p_token_id=00000184D35706E0 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_reset Found token manufacturerID='Yubico (www.yubico.com)' model='YubiKey YK5', serialNumber='XXXXXXXXX', label='YubiKey PIV #XXXXXXXXX' 2022-04-09 16:24:25 us=640000 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=00000184D35706E0 2022-04-09 16:24:25 us=640000 PKCS#11: pkcs11h_token_freeTokenId return 2022-04-09 16:24:25 us=640000 PKCS#11: _pkcs11h_session_reset return rv=0-'CKR_OK', *p_slot=0 2022-04-09 16:24:25 us=781000 PKCS#11: _pkcs11h_session_login_context entry session=00000184D1C4F7F0, user=1, label='(null)', user_data=0000000000000000, mask_prompt=00000007 2022-04-09 16:24:25 us=781000 PKCS#11: Calling pin_prompt hook for ''

From my uderstanding, the error seems to happen right above this line: 2022-04-09 16:24:25 us=640000 PKCS#11: Private key operation failed rv=48-'CKR_DEVICE_ERROR'

[ChrisTG742]

Could be connected to #290

[a-dma]

Hi,

could you try running the ykcs11 in debug mode (by setting the environment variable YKCS11_DBG) and/or running it through OpenSC's PKCS#11 spy?

[ChrisTG742]

I'll try that ASAP an report back here.

[qpernil]

Maybe try this https://github.com/Yubico/yubico-piv-tool/pull/377 ?

[ChrisTG742]

How do I do this? Is there a compiled binary of that branch anywere?

[qpernil]

#377 has now been merged, but we don't publish binaries other than releases. Maybe you could build it yourself ?

[qpernil]

Or just run the code you have with YKCS11_DBG set, we can likely deduce the problem from that.

[ChrisTG742]

Okay, I'll do so.

[qpernil]

Any feedback on this issue ? Thx.

[ChrisTG742]

Hi, sorry for the delay! We decided not to use this approach in my company meanwhile, so I can only do tests in my spare time. I'll try to test next weekend.

[qpernil]

I will close this issue now as there has been no activity. Please feel free to open a new issue if needed !