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

libykcs11 breaks when ED25519 or X25519 key is present on the Yubikey #510

Open
davidmatson opened this issue Sep 8, 2024 · 17 comments
Open

Comments

@davidmatson
Copy link

I'm using the latest yubico-piv-tool release (2.6.0) and YubiKey 5C NFC with firmware 5.7.1.

When using libykcs11.dll, it fails to be able to find any key on the YubiKey if any key, in any normal slot, exists using either the ED25519 or X25519 algorithms.

For example, using OpenSSL:

openssl.exe pkeyutl -decrypt -in encrypted.txt -inkey "pkcs11:object=Private key for Key Management;type=private" -keyform ENGINE -engine pkcs11

This command works just fine when only a single RSA4096 key exists in the appropriate slot.

But if I then generate a new key using ED25519 or X25519 in a different slot, the command above starts failing with:

The private key was not found at: pkcs11:object=Private key for Key Management;type=private
PKCS11_get_private_key returned NULL
Could not find private key from org.openssl.engine:pkcs11:pkcs11:object=Private key for Key Management;type=private

If I delete the new ED25519 or X25519 key in the other slot, the exact same command starts working again.

@aveenismail
Copy link
Member

While the latest release does contain a bug related to handling of ED keys in YKCS11 (a patch release with a fix is scheduled soon), it should not effect RSA key functions. I am also unable to re-produce the issue using pkcs11-tool.

Can you please set the environment variable YKCS11_DBG to any positive value and run your command again, then post the debug log here? Make sure that the log does not contain sensitive data.

@davidmatson
Copy link
Author

PS C:\> & "C:\Program Files\OpenSSL-Win64\bin\openssl.exe" pkeyutl -decrypt -in encrypted.txt -inkey "pkcs11:object=Private key for Key Management;type=private" -keyform ENGINE -engine pkcs11
Engine "pkcs11" set.
DBG ykcs11.c:415 (C_GetSlotList): Initializing slot 0 for '<NFC reader name>'
DBG ykcs11.c:428 (C_GetSlotList): Failed to validate <NFC reader name>: Argument error
DBG ykpiv.c:544 (ykpiv_connect): Connect reader '<NFC reader name>'.
DBG ykpiv.c:560 (ykpiv_connect): SCardConnect succeeded for '<NFC reader name>', protocol=2
DBG ykpiv.c:781 (ykpiv_translate_sw_ex): _ykpiv_verify: SW_63c3
DBG ykcs11.c:438 (C_GetSlotList): Connected slot 0 to '<NFC reader name>'
DBG ykcs11.c:500 (C_GetSlotList): token present is 0
DBG ykcs11.c:501 (C_GetSlotList): number of slots is 1
DBG ykcs11.c:505 (C_GetSlotList): Out
DBG ykcs11.c:343 (C_GetSlotList): In
DBG ykpiv.c:493 (ykpiv_validate): Validate reader '<NFC reader name>'.
DBG ykcs11.c:500 (C_GetSlotList): token present is 0
DBG ykcs11.c:501 (C_GetSlotList): number of slots is 1
DBG ykcs11.c:505 (C_GetSlotList): Out
DBG ykcs11.c:514 (C_GetSlotInfo): In
DBG ykcs11.c:544 (C_GetSlotInfo): Out
DBG ykcs11.c:553 (C_GetTokenInfo): In
DBG ykcs11.c:618 (C_GetTokenInfo): Out
DBG ykcs11.c:927 (C_OpenSession): In
DBG ykcs11.c:1000 (C_OpenSession): Created attestation for object 86 slot 9a
DBG util.c:1448 (ykpiv_util_get_certdata): Unknown cert tag 0x30
DBG util.c:1457 (ykpiv_util_get_certdata): Invalid TLV encoding, treating as a raw certificate
DBG objects.c:1488 (add_object): Added object 62, slot contains 1 objects
DBG objects.c:1488 (add_object): Added object 86, slot contains 2 objects
DBG objects.c:1488 (add_object): Added object 111, slot contains 3 objects
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc105
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 0 slot 5fc105: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 87 slot 9c: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 87 slot 9c: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc10a
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 1 slot 5fc10a: Invalid object
DBG ykcs11.c:1000 (C_OpenSession): Created attestation for object 88 slot 9d
DBG util.c:1448 (ykpiv_util_get_certdata): Unknown cert tag 0x30
DBG util.c:1457 (ykpiv_util_get_certdata): Invalid TLV encoding, treating as a raw certificate
DBG objects.c:1488 (add_object): Added object 64, slot contains 4 objects
DBG objects.c:1488 (add_object): Added object 88, slot contains 5 objects
DBG objects.c:1488 (add_object): Added object 113, slot contains 6 objects
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc10b
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 2 slot 5fc10b: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 89 slot 9e: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 89 slot 9e: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc101
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 3 slot 5fc101: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 90 slot 82: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 90 slot 82: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc10d
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 4 slot 5fc10d: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 91 slot 83: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 91 slot 83: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc10e
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 5 slot 5fc10e: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 92 slot 84: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 92 slot 84: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc10f
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 6 slot 5fc10f: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 93 slot 85: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 93 slot 85: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc110
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 7 slot 5fc110: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 94 slot 86: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 94 slot 86: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc111
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 8 slot 5fc111: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 95 slot 87: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 95 slot 87: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc112
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 9 slot 5fc112: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 96 slot 88: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 96 slot 88: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc113
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 10 slot 5fc113: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 97 slot 89: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 97 slot 89: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc114
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 11 slot 5fc114: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 98 slot 8a: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 98 slot 8a: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc115
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 12 slot 5fc115: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 99 slot 8b: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 99 slot 8b: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc116
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 13 slot 5fc116: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 100 slot 8c: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 100 slot 8c: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc117
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 14 slot 5fc117: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 101 slot 8d: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 101 slot 8d: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc118
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 15 slot 5fc118: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 102 slot 8e: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 102 slot 8e: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc119
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 16 slot 5fc119: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 103 slot 8f: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 103 slot 8f: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc11a
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 17 slot 5fc11a: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 104 slot 90: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 104 slot 90: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc11b
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 18 slot 5fc11b: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 105 slot 91: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 105 slot 91: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc11c
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 19 slot 5fc11c: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 106 slot 92: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 106 slot 92: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc11d
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 20 slot 5fc11d: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 107 slot 93: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 107 slot 93: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc11e
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 21 slot 5fc11e: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 108 slot 94: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 108 slot 94: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc11f
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 22 slot 5fc11f: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 109 slot 95: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1038 (C_OpenSession): Failed to fetch metadata for object 109 slot 95: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc120
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 23 slot 5fc120: Invalid object
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1017 (C_OpenSession): Failed to create attestation for object 110 slot f9: Argument error
DBG ykcs11.c:1020 (C_OpenSession): Fetched 279 bytes metadata for object 110 slot f9
DBG objects.c:1488 (add_object): Added object 110, slot contains 7 objects
DBG objects.c:1488 (add_object): Added object 135, slot contains 8 objects
DBG ykcs11.c:1048 (C_OpenSession): Fetched 770 bytes for object 24 slot 5fff01
DBG objects.c:1488 (add_object): Added object 24, slot contains 9 objects
DBG util.c:1432 (ykpiv_util_get_certdata): Found TAG_CERT with length 766
DBG objects.c:1488 (add_object): Added object 61, slot contains 10 objects
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc107
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 25 slot 5fc107: Invalid object
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc102
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 26 slot 5fc102: Invalid object
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc106
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 28 slot 5fc106: Invalid object
DBG ykcs11.c:1048 (C_OpenSession): Fetched 18 bytes for object 31 slot 7e
DBG objects.c:1488 (add_object): Added object 31, slot contains 11 objects
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc10c
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 32 slot 5fc10c: Invalid object
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc122
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 35 slot 5fc122: Invalid object
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1868 (_ykpiv_fetch_object): Failed to get data for object 5fc123
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch object 36 slot 5fc123: Invalid object
DBG ykcs11.c:1077 (C_OpenSession): Out
DBG ykcs11.c:1903 (C_FindObjectsInit): In
DBG ykcs11.c:1936 (C_FindObjectsInit): Initialized search with 1 parameters
DBG objects.c:307 (get_doa): For data object 24, get
DBG objects.c:311 (get_doa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 24
DBG objects.c:307 (get_doa): For data object 31, get
DBG objects.c:311 (get_doa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 31
DBG objects.c:411 (_get_coa): For certificate object 61, get
DBG objects.c:415 (_get_coa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 61
DBG objects.c:411 (_get_coa): For certificate object 62, get
DBG objects.c:415 (_get_coa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 62
DBG objects.c:411 (_get_coa): For certificate object 64, get
DBG objects.c:415 (_get_coa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 64
DBG ykcs11.c:1946 (C_FindObjectsInit): Removing private object 86
DBG ykcs11.c:1946 (C_FindObjectsInit): Removing private object 88
DBG ykcs11.c:1946 (C_FindObjectsInit): Removing private object 110
DBG objects.c:842 (get_puoa): For public key object 111, get
DBG objects.c:846 (get_puoa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 111
DBG objects.c:842 (get_puoa): For public key object 113, get
DBG objects.c:846 (get_puoa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 113
DBG objects.c:842 (get_puoa): For public key object 135, get
DBG objects.c:846 (get_puoa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 135
DBG ykcs11.c:1968 (C_FindObjectsInit): 0 object(s) left after attribute matching
DBG ykcs11.c:1972 (C_FindObjectsInit): Out
DBG ykcs11.c:1983 (C_FindObjects): In
DBG ykcs11.c:2012 (C_FindObjects): Can return 1 object(s), 0 remaining
DBG ykcs11.c:2021 (C_FindObjects): Returning 0 objects, 0 remaining
DBG ykcs11.c:2025 (C_FindObjects): Out
DBG ykcs11.c:2033 (C_FindObjectsFinal): In
DBG ykcs11.c:2059 (C_FindObjectsFinal): Out
Enter PKCS#11 token PIN for YubiKey PIV #<serial omitted>:

DBG ykcs11.c:1262 (C_Login): In
DBG ykcs11.c:1278 (C_Login): userType 1, pinLen <omitted>
DBG ykcs11.c:1370 (C_Login): Successfully logged in
DBG ykcs11.c:1374 (C_Login): Out
DBG ykcs11.c:1903 (C_FindObjectsInit): In
DBG ykcs11.c:1936 (C_FindObjectsInit): Initialized search with 1 parameters
DBG objects.c:307 (get_doa): For data object 24, get
DBG objects.c:311 (get_doa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 24
DBG objects.c:307 (get_doa): For data object 31, get
DBG objects.c:311 (get_doa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 31
DBG objects.c:411 (_get_coa): For certificate object 61, get
DBG objects.c:415 (_get_coa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 61
DBG objects.c:411 (_get_coa): For certificate object 62, get
DBG objects.c:415 (_get_coa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 62
DBG objects.c:411 (_get_coa): For certificate object 64, get
DBG objects.c:415 (_get_coa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 64
DBG objects.c:551 (get_proa): For private key object 86, get
DBG objects.c:555 (get_proa): CLASS
DBG ykcs11.c:1961 (C_FindObjectsInit): Keeping object 86
DBG objects.c:551 (get_proa): For private key object 88, get
DBG objects.c:555 (get_proa): CLASS
DBG ykcs11.c:1961 (C_FindObjectsInit): Keeping object 88
DBG objects.c:551 (get_proa): For private key object 110, get
DBG objects.c:555 (get_proa): CLASS
DBG ykcs11.c:1961 (C_FindObjectsInit): Keeping object 110
DBG objects.c:842 (get_puoa): For public key object 111, get
DBG objects.c:846 (get_puoa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 111
DBG objects.c:842 (get_puoa): For public key object 113, get
DBG objects.c:846 (get_puoa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 113
DBG objects.c:842 (get_puoa): For public key object 135, get
DBG objects.c:846 (get_puoa): CLASS
DBG ykcs11.c:1954 (C_FindObjectsInit): Removing object 135
DBG ykcs11.c:1968 (C_FindObjectsInit): 3 object(s) left after attribute matching
DBG ykcs11.c:1972 (C_FindObjectsInit): Out
DBG ykcs11.c:1983 (C_FindObjects): In
DBG ykcs11.c:2012 (C_FindObjects): Can return 1 object(s), 3 remaining
DBG ykcs11.c:2021 (C_FindObjects): Returning 1 objects, 2 remaining
DBG ykcs11.c:2025 (C_FindObjects): Out
DBG ykcs11.c:1834 (C_GetAttributeValue): In
DBG objects.c:551 (get_proa): For private key object 86, get
DBG objects.c:555 (get_proa): CLASS
DBG ykcs11.c:1880 (C_GetAttributeValue): Out
DBG ykcs11.c:1834 (C_GetAttributeValue): In
DBG objects.c:551 (get_proa): For private key object 86, get
DBG objects.c:582 (get_proa): KEY TYPE
DBG ykcs11.c:1880 (C_GetAttributeValue): Out
DBG ykcs11.c:2033 (C_FindObjectsFinal): In
DBG ykcs11.c:2059 (C_FindObjectsFinal): Out
Unable to enumerate private keys
The private key was not found at: pkcs11:object=Private key for Key Management;type=private
PKCS11_get_private_key returned NULL
Could not find private key from org.openssl.engine:pkcs11:pkcs11:object=Private key for Key Management;type=private
3C1D0000:error:40000065:pkcs11 engine:ERR_ENG_error:object not found:eng_back.c:887:
3C1D0000:error:13000080:engine routines:ENGINE_load_private_key:failed loading private key:crypto\engine\eng_pkey.c:79:
pkeyutl: Error initializing context
PS C:\>

@aveenismail
Copy link
Member

aveenismail commented Sep 11, 2024

I have now set up OpenSSL with PKCS11 engine. I generated RSA4096 keys on slot 9d, done both signing and decryption using the following commands:

$ openssl pkeyutl -sign -in data.txt -inkey "pkcs11:object=Private key for Key Management;type=private" -keyform ENGINE -engine pkcs11
$ openssl pkeyutl -decrypt -in data.enc -inkey "pkcs11:object=Private key for Key Management;type=private" -keyform ENGINE -engine pkcs11

As expected, that worked fine.

I then generated an ED25519 on slot 9c and repeated the same commands above with the RSA key in 9d. They still worked fine without any issues. I then repeated the same tests with an RSA4096 key imported into slot 9a both with slot 9c empty and occupied with an ED25519 key. Everything still worked as it should. So as of now, I am unable to re-produce the error you are getting. And I also don't see anything in the debug log you posted that jumps out as wrong.

What YubiKey version do you have? How did you create the keys (I created them using the yubico-piv-tool command line tool)?

Do you have the possibility to build yubico-piv-tool from source? If yes, can you build it from the branch called ed_ykcs11 (https://github.com/Yubico/yubico-piv-tool/tree/ed_ykcs11) and try the OpenSSL command again? This branch contains the fix for the reported bug related to ED25519 keys. I don't actually see how either the bug or the fix would effect RSA key operations but maybe it's worth the try?

@davidmatson
Copy link
Author

What YubiKey version do you have?

I'm using the latest yubico-piv-tool release (2.6.0) and YubiKey 5C NFC with firmware 5.7.1.

How did you create the keys (I created them using the yubico-piv-tool command line tool)?

I used ykman piv keys generate.

Do you have the possibility to build yubico-piv-tool from source?

I don't have a compiler on the machine I'm using to test. I suspect OpenSSL enumerates all as part of locating the PKCS11 object and gets an error when it encounters the ED25519 key before the fix. Could you see if this bug reproduces on the release version (yubico-piv-tool 2.6.0)?

Thanks,

David

@aveenismail
Copy link
Member

aveenismail commented Sep 12, 2024

Sorry I didn't make that clear but I am actually testing on the released version (reproduce first then see if the patch solves the issue :) ). I realized though that I'm testing with OpenSSL 1.1 but you are most likely running OpenSSL 3. Now I have finally gotten a configuration running with OpenSSL 3 and ran the same tests again, and I am still able to do both signing and decryption with both RSA and ED keys present on the same key. I don't have YubiKey 5.7.1 at hands at the moment but I tested with both 5.7.0 and 5.7.2 and I'm not encountering any issues.

Can you try generating/importing the keys using the yubico-piv-tool command line tool and see if that makes any difference? (https://developers.yubico.com/yubico-piv-tool/Actions/key_generation.html and https://developers.yubico.com/yubico-piv-tool/Actions/key_import.html). On my end, I'll try generating them with ykman and see if I can reproduce that way. By the way, are the keys generated on the YubiKey or imported? If imported, how were they created?

A patch release (yubico-piv-tool 2.6.1) should be coming out before the end of the week, so you can test that soon too.

@davidmatson
Copy link
Author

davidmatson commented Sep 12, 2024

Thanks for looking, @aveenismail.

I just tried using yubico-piv-tool to generate the keys, and the same problem repro'd for me - it can decrypt the RSA-encrypted file if and only if a previous slot does not contain an ED25519 key.

Yes, I am using OpenSSL 3.

Some other details, in case they're relevant:
When testing, I've been putting the RSA key in slot 9D and the ED/X25519 key in slot 9A.
For the runtime openssl.exe, I'm using version 3.3.1 from https://slproweb.com/products/Win32OpenSSL.html (though they've since updated to 3.3.2).
I had to compile libp11.dll myself on another box, which I believe used the headers from https://www.firedaemon.com/get-openssl.
I'm connecting to the YubiKey using an NFC reader rather than plugging into a USB C port.
EDIT: I tried the entire process while connected to a USB C port, and it produced the same results, so it's not specific to NFC.

@davidmatson
Copy link
Author

@aveenismail - I tried with the 2.6.1 release of yubico-piv-tool, and this bug still repros. I also tried putting the X25519/ED25519 key a later slot (9E), and that didn't change the behavior either.

Note, however, that this problem does not reproduce with ECCP256 or ECCP384; it is specific to X25519 and ED25519.

Have you been able to reproduce this problem with OpenSSL 3 and YubiKey 5.7.1?

@aveenismail
Copy link
Member

@davidmatson I am still unable to re-produce. I have, however, added some more debug output that can hopefully point us in the right direction. Are you able to download github artifact from https://github.com/Yubico/yubico-piv-tool/actions/runs/11128165948? You are running on Windows, correct? There should be an MSI installer there with binaries that produces more debug output. Can you run that with debug turned on and paste the output here?

@davidmatson
Copy link
Author

Engine "pkcs11" set.
DBG ykcs11.c:415 (C_GetSlotList): Initializing slot 0 for '<reader>'
DBG ykcs11.c:428 (C_GetSlotList): Failed to validate <reader>: Argument error
DBG ykpiv.c:544 (ykpiv_connect): Connect reader '<reader>'.
DBG ykpiv.c:560 (ykpiv_connect): SCardConnect succeeded for '<reader>', protocol=2
DBG ykpiv.c:781 (ykpiv_translate_sw_ex): _ykpiv_verify: SW_63c3
DBG ykcs11.c:438 (C_GetSlotList): Connected slot 0 to '<reader>'
DBG ykcs11.c:500 (C_GetSlotList): token present is 0
DBG ykcs11.c:501 (C_GetSlotList): number of slots is 1
DBG ykcs11.c:505 (C_GetSlotList): Out
DBG ykcs11.c:343 (C_GetSlotList): In
DBG ykpiv.c:493 (ykpiv_validate): Validate reader '<reader>'.
DBG ykcs11.c:500 (C_GetSlotList): token present is 0
DBG ykcs11.c:501 (C_GetSlotList): number of slots is 1
DBG ykcs11.c:505 (C_GetSlotList): Out
DBG ykcs11.c:514 (C_GetSlotInfo): In
DBG ykcs11.c:544 (C_GetSlotInfo): Out
DBG ykcs11.c:553 (C_GetTokenInfo): In
DBG ykcs11.c:618 (C_GetTokenInfo): Out
DBG ykcs11.c:927 (C_OpenSession): In
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 0    sub_id: 1
DBG ykcs11.c:1003 (C_OpenSession): Created attestation for object 86 slot 9a
DBG util.c:1448 (ykpiv_util_get_certdata): Unknown cert tag 0x30
DBG util.c:1457 (ykpiv_util_get_certdata): Invalid TLV encoding, treating as a raw certificate
DBG objects.c:1503 (add_object): Added object 62, slot contains 1 objects
DBG ykcs11.c:1010 (C_OpenSession): -------- Added attestation. Key type 80000000
DBG objects.c:1503 (add_object): Added object 86, slot contains 2 objects
DBG objects.c:1503 (add_object): Added object 111, slot contains 3 objects
DBG ykcs11.c:1015 (C_OpenSession): -------- Added privkey and pubkey. Key type 41
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc105
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 0 slot 5fc105: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 1    sub_id: 2
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 87 slot 9c: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 87 slot 9c: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10a
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 1 slot 5fc10a: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 2    sub_id: 3
DBG ykcs11.c:1003 (C_OpenSession): Created attestation for object 88 slot 9d
DBG util.c:1448 (ykpiv_util_get_certdata): Unknown cert tag 0x30
DBG util.c:1457 (ykpiv_util_get_certdata): Invalid TLV encoding, treating as a raw certificate
DBG objects.c:1503 (add_object): Added object 64, slot contains 4 objects
DBG ykcs11.c:1010 (C_OpenSession): -------- Added attestation. Key type 80000000
DBG objects.c:1503 (add_object): Added object 88, slot contains 5 objects
DBG objects.c:1503 (add_object): Added object 113, slot contains 6 objects
DBG ykcs11.c:1015 (C_OpenSession): -------- Added privkey and pubkey. Key type 0
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10b
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 2 slot 5fc10b: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 3    sub_id: 4
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 89 slot 9e: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 89 slot 9e: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc101
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 3 slot 5fc101: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 4    sub_id: 5
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 90 slot 82: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 90 slot 82: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10d
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 4 slot 5fc10d: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 5    sub_id: 6
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 91 slot 83: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 91 slot 83: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10e
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 5 slot 5fc10e: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 6    sub_id: 7
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 92 slot 84: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 92 slot 84: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10f
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 6 slot 5fc10f: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 7    sub_id: 8
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 93 slot 85: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 93 slot 85: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc110
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 7 slot 5fc110: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 8    sub_id: 9
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 94 slot 86: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 94 slot 86: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc111
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 8 slot 5fc111: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 9    sub_id: 10
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 95 slot 87: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 95 slot 87: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc112
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 9 slot 5fc112: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 10    sub_id: 11
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 96 slot 88: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 96 slot 88: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc113
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 10 slot 5fc113: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 11    sub_id: 12
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 97 slot 89: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 97 slot 89: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc114
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 11 slot 5fc114: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 12    sub_id: 13
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 98 slot 8a: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 98 slot 8a: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc115
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 12 slot 5fc115: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 13    sub_id: 14
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 99 slot 8b: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 99 slot 8b: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc116
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 13 slot 5fc116: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 14    sub_id: 15
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 100 slot 8c: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 100 slot 8c: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc117
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 14 slot 5fc117: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 15    sub_id: 16
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 101 slot 8d: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 101 slot 8d: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc118
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 15 slot 5fc118: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 16    sub_id: 17
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 102 slot 8e: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 102 slot 8e: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc119
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 16 slot 5fc119: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 17    sub_id: 18
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 103 slot 8f: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 103 slot 8f: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11a
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 17 slot 5fc11a: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 18    sub_id: 19
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 104 slot 90: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 104 slot 90: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11b
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 18 slot 5fc11b: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 19    sub_id: 20
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 105 slot 91: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 105 slot 91: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11c
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 19 slot 5fc11c: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 20    sub_id: 21
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 106 slot 92: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 106 slot 92: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11d
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 20 slot 5fc11d: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 21    sub_id: 22
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 107 slot 93: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 107 slot 93: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11e
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 21 slot 5fc11e: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 22    sub_id: 23
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 108 slot 94: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 108 slot 94: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11f
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 22 slot 5fc11f: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 23    sub_id: 24
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 109 slot 95: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 109 slot 95: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc120
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 23 slot 5fc120: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 24    sub_id: 25
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 110 slot f9: Argument error
DBG ykcs11.c:1026 (C_OpenSession): Fetched 279 bytes metadata for object 110 slot f9
DBG objects.c:1503 (add_object): Added object 110, slot contains 7 objects
DBG objects.c:1503 (add_object): Added object 135, slot contains 8 objects
DBG ykcs11.c:1036 (C_OpenSession): -------- Added privkey and pubkey through metadata. Key type 0
DBG ykcs11.c:1055 (C_OpenSession): Fetched 770 bytes for object 24 slot 5fff01
DBG objects.c:1503 (add_object): Added object 24, slot contains 9 objects
DBG util.c:1432 (ykpiv_util_get_certdata): Found TAG_CERT with length 766
DBG objects.c:1503 (add_object): Added object 61, slot contains 10 objects
DBG ykcs11.c:1069 (C_OpenSession): -------- Added cert. Key type 0
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 25    sub_id: 26
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc107
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 25 slot 5fc107: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 26    sub_id: 27
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc102
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 26 slot 5fc102: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 28    sub_id: 29
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc106
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 28 slot 5fc106: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 31    sub_id: 32
DBG ykcs11.c:1055 (C_OpenSession): Fetched 18 bytes for object 31 slot 7e
DBG objects.c:1503 (add_object): Added object 31, slot contains 11 objects
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 32    sub_id: 33
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10c
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 32 slot 5fc10c: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 35    sub_id: 36
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc122
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 35 slot 5fc122: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 36    sub_id: 37
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc123
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 36 slot 5fc123: Invalid object
DBG ykcs11.c:1079 (C_OpenSession): ------ number of objects in slot: 11
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 24
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 25
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 770
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 31
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 61
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 25
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 770
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 62
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 1
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 41
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 0
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 64
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 3
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 0
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 86
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 1
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 41
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 0
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 88
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 3
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 0
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 110
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 25
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 770
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 111
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 1
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 41
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 0
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 113
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 3
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 0
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 135
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 25
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 770
DBG ykcs11.c:1102 (C_OpenSession): Out
DBG ykcs11.c:1928 (C_FindObjectsInit): In
DBG ykcs11.c:1961 (C_FindObjectsInit): Initialized search with 1 parameters
DBG objects.c:308 (get_doa): For data object 24, get
DBG objects.c:312 (get_doa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 24
DBG objects.c:308 (get_doa): For data object 31, get
DBG objects.c:312 (get_doa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 31
DBG objects.c:412 (_get_coa): For certificate object 61, get
DBG objects.c:416 (_get_coa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 61
DBG objects.c:412 (_get_coa): For certificate object 62, get
DBG objects.c:416 (_get_coa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 62
DBG objects.c:412 (_get_coa): For certificate object 64, get
DBG objects.c:416 (_get_coa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 64
DBG ykcs11.c:1971 (C_FindObjectsInit): Removing private object 86
DBG ykcs11.c:1971 (C_FindObjectsInit): Removing private object 88
DBG ykcs11.c:1971 (C_FindObjectsInit): Removing private object 110
DBG objects.c:850 (get_puoa): For public key object 111, get
DBG objects.c:854 (get_puoa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 111
DBG objects.c:850 (get_puoa): For public key object 113, get
DBG objects.c:854 (get_puoa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 113
DBG objects.c:850 (get_puoa): For public key object 135, get
DBG objects.c:854 (get_puoa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 135
DBG ykcs11.c:1993 (C_FindObjectsInit): 0 object(s) left after attribute matching
DBG ykcs11.c:1997 (C_FindObjectsInit): Out
DBG ykcs11.c:2008 (C_FindObjects): In
DBG ykcs11.c:2037 (C_FindObjects): Can return 1 object(s), 0 remaining
DBG ykcs11.c:2046 (C_FindObjects): Returning 0 objects, 0 remaining
DBG ykcs11.c:2050 (C_FindObjects): Out
DBG ykcs11.c:2058 (C_FindObjectsFinal): In
DBG ykcs11.c:2084 (C_FindObjectsFinal): Out
Enter PKCS#11 token PIN for YubiKey PIV #<serial>:

DBG ykcs11.c:1287 (C_Login): In
DBG ykcs11.c:1303 (C_Login): userType 1, pinLen <omitted>
DBG ykcs11.c:1395 (C_Login): Successfully logged in
DBG ykcs11.c:1399 (C_Login): Out
DBG ykcs11.c:1928 (C_FindObjectsInit): In
DBG ykcs11.c:1961 (C_FindObjectsInit): Initialized search with 1 parameters
DBG objects.c:308 (get_doa): For data object 24, get
DBG objects.c:312 (get_doa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 24
DBG objects.c:308 (get_doa): For data object 31, get
DBG objects.c:312 (get_doa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 31
DBG objects.c:412 (_get_coa): For certificate object 61, get
DBG objects.c:416 (_get_coa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 61
DBG objects.c:412 (_get_coa): For certificate object 62, get
DBG objects.c:416 (_get_coa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 62
DBG objects.c:412 (_get_coa): For certificate object 64, get
DBG objects.c:416 (_get_coa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 64
DBG objects.c:552 (get_proa): For private key object 86, get
DBG objects.c:556 (get_proa): CLASS
DBG ykcs11.c:1986 (C_FindObjectsInit): Keeping object 86
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:556 (get_proa): CLASS
DBG ykcs11.c:1986 (C_FindObjectsInit): Keeping object 88
DBG objects.c:552 (get_proa): For private key object 110, get
DBG objects.c:556 (get_proa): CLASS
DBG ykcs11.c:1986 (C_FindObjectsInit): Keeping object 110
DBG objects.c:850 (get_puoa): For public key object 111, get
DBG objects.c:854 (get_puoa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 111
DBG objects.c:850 (get_puoa): For public key object 113, get
DBG objects.c:854 (get_puoa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 113
DBG objects.c:850 (get_puoa): For public key object 135, get
DBG objects.c:854 (get_puoa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 135
DBG ykcs11.c:1993 (C_FindObjectsInit): 3 object(s) left after attribute matching
DBG ykcs11.c:1997 (C_FindObjectsInit): Out
DBG ykcs11.c:2008 (C_FindObjects): In
DBG ykcs11.c:2037 (C_FindObjects): Can return 1 object(s), 3 remaining
DBG ykcs11.c:2046 (C_FindObjects): Returning 1 objects, 2 remaining
DBG ykcs11.c:2050 (C_FindObjects): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 86, get
DBG objects.c:556 (get_proa): CLASS
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 86, get
DBG objects.c:583 (get_proa): KEY TYPE
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:2058 (C_FindObjectsFinal): In
DBG ykcs11.c:2084 (C_FindObjectsFinal): Out
Unable to enumerate private keys
The private key was not found at: pkcs11:object=Private key for Key Management;type=private
PKCS11_get_private_key returned NULL
Could not find private key from org.openssl.engine:pkcs11:pkcs11:object=Private key for Key Management;type=private
C4130000:error:40000065:pkcs11 engine:ERR_ENG_error:object not found:eng_back.c:887:
C4130000:error:13000080:engine routines:ENGINE_load_private_key:failed loading private key:crypto\engine\eng_pkey.c:79:
pkeyutl: Error initializing context

@aveenismail
Copy link
Member

Thank you.

To make sure, you have an RSA key in slot 9d and ED25519 key in slot 9a, correct?

@aveenismail
Copy link
Member

OK, I see that you have an RSA key in 9d and X25519 in 9a. YKCS11 reads all objects when it opens a PKCS11 session as expected. The weird thing is that it can clearly see that there is something in these slots because it does read the right key type, but it returns 0 as the length of the key.

Can you paste an debug output where the X25519 keys is not there (aka, when it works) so we can compare?

@davidmatson
Copy link
Author

Yes, here's the config (ykman piv info):

PIV version:              5.7.1
PIN tries remaining:      <not blocked>
PUK tries remaining:      <not blocked>
Management key algorithm: AES192
Management key is stored on the YubiKey, protected by PIN.
CHUID: No data available
CCC:   No data available
Slot 9A (AUTHENTICATION):
  Private key type: X25519

Slot 9D (KEY_MANAGEMENT):
  Private key type: RSA4096

If I delete the key in 9A, here's the debug output:

Engine "pkcs11" set.
DBG ykcs11.c:415 (C_GetSlotList): Initializing slot 0 for '<reader>'
DBG ykcs11.c:428 (C_GetSlotList): Failed to validate <reader>: Argument error
DBG ykpiv.c:544 (ykpiv_connect): Connect reader '<reader>'.
DBG ykpiv.c:560 (ykpiv_connect): SCardConnect succeeded for '<reader>', protocol=2
DBG ykpiv.c:781 (ykpiv_translate_sw_ex): _ykpiv_verify: SW_63c3
DBG ykcs11.c:438 (C_GetSlotList): Connected slot 0 to '<reader>'
DBG ykcs11.c:500 (C_GetSlotList): token present is 0
DBG ykcs11.c:501 (C_GetSlotList): number of slots is 1
DBG ykcs11.c:505 (C_GetSlotList): Out
DBG ykcs11.c:343 (C_GetSlotList): In
DBG ykpiv.c:493 (ykpiv_validate): Validate reader '<reader>'.
DBG ykcs11.c:500 (C_GetSlotList): token present is 0
DBG ykcs11.c:501 (C_GetSlotList): number of slots is 1
DBG ykcs11.c:505 (C_GetSlotList): Out
DBG ykcs11.c:514 (C_GetSlotInfo): In
DBG ykcs11.c:544 (C_GetSlotInfo): Out
DBG ykcs11.c:553 (C_GetTokenInfo): In
DBG ykcs11.c:618 (C_GetTokenInfo): Out
DBG ykcs11.c:927 (C_OpenSession): In
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 0    sub_id: 1
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 86 slot 9a: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 86 slot 9a: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc105
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 0 slot 5fc105: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 1    sub_id: 2
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 87 slot 9c: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 87 slot 9c: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10a
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 1 slot 5fc10a: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 2    sub_id: 3
DBG ykcs11.c:1003 (C_OpenSession): Created attestation for object 88 slot 9d
DBG util.c:1448 (ykpiv_util_get_certdata): Unknown cert tag 0x30
DBG util.c:1457 (ykpiv_util_get_certdata): Invalid TLV encoding, treating as a raw certificate
DBG objects.c:1503 (add_object): Added object 64, slot contains 1 objects
DBG ykcs11.c:1010 (C_OpenSession): -------- Added attestation. Key type 80000000
DBG objects.c:1503 (add_object): Added object 88, slot contains 2 objects
DBG objects.c:1503 (add_object): Added object 113, slot contains 3 objects
DBG ykcs11.c:1015 (C_OpenSession): -------- Added privkey and pubkey. Key type 0
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10b
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 2 slot 5fc10b: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 3    sub_id: 4
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 89 slot 9e: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 89 slot 9e: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc101
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 3 slot 5fc101: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 4    sub_id: 5
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 90 slot 82: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 90 slot 82: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10d
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 4 slot 5fc10d: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 5    sub_id: 6
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 91 slot 83: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 91 slot 83: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10e
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 5 slot 5fc10e: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 6    sub_id: 7
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 92 slot 84: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 92 slot 84: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10f
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 6 slot 5fc10f: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 7    sub_id: 8
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 93 slot 85: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 93 slot 85: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc110
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 7 slot 5fc110: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 8    sub_id: 9
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 94 slot 86: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 94 slot 86: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc111
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 8 slot 5fc111: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 9    sub_id: 10
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 95 slot 87: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 95 slot 87: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc112
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 9 slot 5fc112: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 10    sub_id: 11
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 96 slot 88: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 96 slot 88: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc113
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 10 slot 5fc113: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 11    sub_id: 12
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 97 slot 89: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 97 slot 89: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc114
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 11 slot 5fc114: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 12    sub_id: 13
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 98 slot 8a: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 98 slot 8a: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc115
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 12 slot 5fc115: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 13    sub_id: 14
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 99 slot 8b: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 99 slot 8b: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc116
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 13 slot 5fc116: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 14    sub_id: 15
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 100 slot 8c: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 100 slot 8c: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc117
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 14 slot 5fc117: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 15    sub_id: 16
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 101 slot 8d: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 101 slot 8d: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc118
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 15 slot 5fc118: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 16    sub_id: 17
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 102 slot 8e: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 102 slot 8e: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc119
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 16 slot 5fc119: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 17    sub_id: 18
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 103 slot 8f: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 103 slot 8f: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11a
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 17 slot 5fc11a: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 18    sub_id: 19
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 104 slot 90: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 104 slot 90: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11b
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 18 slot 5fc11b: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 19    sub_id: 20
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 105 slot 91: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 105 slot 91: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11c
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 19 slot 5fc11c: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 20    sub_id: 21
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 106 slot 92: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 106 slot 92: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11d
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 20 slot 5fc11d: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 21    sub_id: 22
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 107 slot 93: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 107 slot 93: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11e
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 21 slot 5fc11e: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 22    sub_id: 23
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 108 slot 94: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 108 slot 94: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc11f
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 22 slot 5fc11f: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 23    sub_id: 24
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 109 slot 95: Argument error
DBG ykpiv.c:769 (ykpiv_translate_sw_ex): _ykpiv_get_metadata: SW_ERR_REFERENCE_NOT_FOUND
DBG ykcs11.c:1045 (C_OpenSession): Failed to fetch metadata for object 109 slot 95: Key error
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc120
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 23 slot 5fc120: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 24    sub_id: 25
DBG ykpiv.c:763 (ykpiv_translate_sw_ex): ykpiv_attest: SW_ERR_INCORRECT_PARAM
DBG ykcs11.c:1023 (C_OpenSession): Failed to create attestation for object 110 slot f9: Argument error
DBG ykcs11.c:1026 (C_OpenSession): Fetched 279 bytes metadata for object 110 slot f9
DBG objects.c:1503 (add_object): Added object 110, slot contains 4 objects
DBG objects.c:1503 (add_object): Added object 135, slot contains 5 objects
DBG ykcs11.c:1036 (C_OpenSession): -------- Added privkey and pubkey through metadata. Key type 0
DBG ykcs11.c:1055 (C_OpenSession): Fetched 770 bytes for object 24 slot 5fff01
DBG objects.c:1503 (add_object): Added object 24, slot contains 6 objects
DBG util.c:1432 (ykpiv_util_get_certdata): Found TAG_CERT with length 766
DBG objects.c:1503 (add_object): Added object 61, slot contains 7 objects
DBG ykcs11.c:1069 (C_OpenSession): -------- Added cert. Key type 0
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 25    sub_id: 26
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc107
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 25 slot 5fc107: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 26    sub_id: 27
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc102
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 26 slot 5fc102: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 28    sub_id: 29
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc106
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 28 slot 5fc106: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 31    sub_id: 32
DBG ykcs11.c:1055 (C_OpenSession): Fetched 18 bytes for object 31 slot 7e
DBG objects.c:1503 (add_object): Added object 31, slot contains 8 objects
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 32    sub_id: 33
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc10c
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 32 slot 5fc10c: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 35    sub_id: 36
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc122
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 35 slot 5fc122: Invalid object
DBG ykcs11.c:987 (C_OpenSession): ------ object_id: 36    sub_id: 37
DBG ykpiv.c:766 (ykpiv_translate_sw_ex): _ykpiv_fetch_object: SW_ERR_FILE_NOT_FOUND
DBG ykpiv.c:1909 (_ykpiv_fetch_object): Failed to get data for object 5fc123
DBG ykcs11.c:1052 (C_OpenSession): Failed to fetch object 36 slot 5fc123: Invalid object
DBG ykcs11.c:1079 (C_OpenSession): ------ number of objects in slot: 8
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 24
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 25
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 770
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 31
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 61
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 25
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 770
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 64
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 3
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 0
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 88
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 3
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 0
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 110
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 25
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 770
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 113
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 3
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 0
DBG ykcs11.c:1081 (C_OpenSession): -------- object id: 135
DBG ykcs11.c:1086 (C_OpenSession): -------- subid: 25
DBG ykcs11.c:1091 (C_OpenSession): -------- key type: 0
DBG ykcs11.c:1092 (C_OpenSession): -------- object len: 770
DBG ykcs11.c:1102 (C_OpenSession): Out
DBG ykcs11.c:1928 (C_FindObjectsInit): In
DBG ykcs11.c:1961 (C_FindObjectsInit): Initialized search with 1 parameters
DBG objects.c:308 (get_doa): For data object 24, get
DBG objects.c:312 (get_doa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 24
DBG objects.c:308 (get_doa): For data object 31, get
DBG objects.c:312 (get_doa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 31
DBG objects.c:412 (_get_coa): For certificate object 61, get
DBG objects.c:416 (_get_coa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 61
DBG objects.c:412 (_get_coa): For certificate object 64, get
DBG objects.c:416 (_get_coa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 64
DBG ykcs11.c:1971 (C_FindObjectsInit): Removing private object 88
DBG ykcs11.c:1971 (C_FindObjectsInit): Removing private object 110
DBG objects.c:850 (get_puoa): For public key object 113, get
DBG objects.c:854 (get_puoa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 113
DBG objects.c:850 (get_puoa): For public key object 135, get
DBG objects.c:854 (get_puoa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 135
DBG ykcs11.c:1993 (C_FindObjectsInit): 0 object(s) left after attribute matching
DBG ykcs11.c:1997 (C_FindObjectsInit): Out
DBG ykcs11.c:2008 (C_FindObjects): In
DBG ykcs11.c:2037 (C_FindObjects): Can return 1 object(s), 0 remaining
DBG ykcs11.c:2046 (C_FindObjects): Returning 0 objects, 0 remaining
DBG ykcs11.c:2050 (C_FindObjects): Out
DBG ykcs11.c:2058 (C_FindObjectsFinal): In
DBG ykcs11.c:2084 (C_FindObjectsFinal): Out
Enter PKCS#11 token PIN for YubiKey PIV #<serial>:

DBG ykcs11.c:1287 (C_Login): In
DBG ykcs11.c:1303 (C_Login): userType 1, pinLen <omitted>
DBG ykcs11.c:1395 (C_Login): Successfully logged in
DBG ykcs11.c:1399 (C_Login): Out
DBG ykcs11.c:1928 (C_FindObjectsInit): In
DBG ykcs11.c:1961 (C_FindObjectsInit): Initialized search with 1 parameters
DBG objects.c:308 (get_doa): For data object 24, get
DBG objects.c:312 (get_doa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 24
DBG objects.c:308 (get_doa): For data object 31, get
DBG objects.c:312 (get_doa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 31
DBG objects.c:412 (_get_coa): For certificate object 61, get
DBG objects.c:416 (_get_coa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 61
DBG objects.c:412 (_get_coa): For certificate object 64, get
DBG objects.c:416 (_get_coa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 64
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:556 (get_proa): CLASS
DBG ykcs11.c:1986 (C_FindObjectsInit): Keeping object 88
DBG objects.c:552 (get_proa): For private key object 110, get
DBG objects.c:556 (get_proa): CLASS
DBG ykcs11.c:1986 (C_FindObjectsInit): Keeping object 110
DBG objects.c:850 (get_puoa): For public key object 113, get
DBG objects.c:854 (get_puoa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 113
DBG objects.c:850 (get_puoa): For public key object 135, get
DBG objects.c:854 (get_puoa): CLASS
DBG ykcs11.c:1979 (C_FindObjectsInit): Removing object 135
DBG ykcs11.c:1993 (C_FindObjectsInit): 2 object(s) left after attribute matching
DBG ykcs11.c:1997 (C_FindObjectsInit): Out
DBG ykcs11.c:2008 (C_FindObjects): In
DBG ykcs11.c:2037 (C_FindObjects): Can return 1 object(s), 2 remaining
DBG ykcs11.c:2046 (C_FindObjects): Returning 1 objects, 1 remaining
DBG ykcs11.c:2050 (C_FindObjects): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:556 (get_proa): CLASS
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:583 (get_proa): KEY TYPE
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:592 (get_proa): ID
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:577 (get_proa): LABEL
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:577 (get_proa): LABEL
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:777 (get_proa): ALWAYS AUTHENTICATE
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:2008 (C_FindObjects): In
DBG ykcs11.c:2037 (C_FindObjects): Can return 1 object(s), 1 remaining
DBG ykcs11.c:2046 (C_FindObjects): Returning 1 objects, 0 remaining
DBG ykcs11.c:2050 (C_FindObjects): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 110, get
DBG objects.c:556 (get_proa): CLASS
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 110, get
DBG objects.c:583 (get_proa): KEY TYPE
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 110, get
DBG objects.c:592 (get_proa): ID
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 110, get
DBG objects.c:577 (get_proa): LABEL
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 110, get
DBG objects.c:577 (get_proa): LABEL
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 110, get
DBG objects.c:777 (get_proa): ALWAYS AUTHENTICATE
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:2008 (C_FindObjects): In
DBG ykcs11.c:2037 (C_FindObjects): Can return 1 object(s), 0 remaining
DBG ykcs11.c:2046 (C_FindObjects): Returning 0 objects, 0 remaining
DBG ykcs11.c:2050 (C_FindObjects): Out
DBG ykcs11.c:2058 (C_FindObjectsFinal): In
DBG ykcs11.c:2084 (C_FindObjectsFinal): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:711 (get_proa): MODULUS
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:711 (get_proa): MODULUS
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:768 (get_proa): PUBLIC EXPONENT
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 88, get
DBG objects.c:768 (get_proa): PUBLIC EXPONENT
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:2343 (C_DecryptInit): In
DBG ykcs11.c:2412 (C_DecryptInit): Out
DBG ykcs11.c:2424 (C_Decrypt): In
DBG ykcs11.c:2460 (C_Decrypt): The maximum size of the data will be 501
DBG ykcs11.c:2470 (C_Decrypt): Using slot 9d to decrypt 512 bytes
DBG ykcs11.c:2495 (C_Decrypt): Got 51 bytes back
DBG ykcs11.c:2499 (C_Decrypt): Out
<decrypted text here>

@aveenismail
Copy link
Member

Thank you.

OK, so it returns object length 0 even when everything works, so this is apparently not the issue.

It looks like ykcs11 accurately reads the content of the key when it opens a PKCS11 session. Also ykman output lists the correct keys so it is not a hardware issue.

Let me make new binaries with more debug log when searching for the key and get back to you.

@aveenismail
Copy link
Member

aveenismail commented Oct 2, 2024

Suddenly, I am able to re-produce!! I did not do anything different!!!

I see, however, that my OpenSSL version is upgraded from 3.0.2 to 3.0.13. Tested it again now and yes, everything works fine with OpenSSL 3.0.2 but breaks with 3.0.13. I see now in the comments above that you are running OpenSSL 3.3.1. I must have misread that because I was convinced you were running 3.0.1 and thought that one patch version cannot account for this.

At least now I can dig properly on my end. Hopefully I'll be able to provide you with a binaries to test very soon

@davidmatson
Copy link
Author

That sounds great. Thanks, @aveenismail!

@aveenismail
Copy link
Member

aveenismail commented Oct 2, 2024

Here is what I got so far: I am fairly sure that ykcs11 is behaving the way it's suppose to.

When I have an EC key in 9a and RSA key in 9d, here's the debug output (I added more for clarity) from when it tries to find the RSA key:

DBG ykcs11.c:1993 (C_FindObjectsInit): 3 object(s) left after attribute matching ===> It was looking for private key object and it found 3 of them as expected: my EC key in 9a, RSA key in 9d and the attestation RSA key in slot 25
DBG ykcs11.c:1995 (C_FindObjectsInit): ------ Found objects:
DBG ykcs11.c:1997 (C_FindObjectsInit): -------- object id: 86  ===> hard coded internal object ID for private keys stored in slot 9a
DBG ykcs11.c:2002 (C_FindObjectsInit): -------- subid: 1 ===> This mean slot 9a
DBG ykcs11.c:2003 (C_FindObjectsInit): -------- key type: 3 ===> The type of the key it finds there is an EC key
DBG ykcs11.c:1997 (C_FindObjectsInit): -------- object id: 88 ===> hard coded internal object ID for private keys stored in slot 9d
DBG ykcs11.c:2002 (C_FindObjectsInit): -------- subid: 3  ===> This mean slot 9d
DBG ykcs11.c:2003 (C_FindObjectsInit): -------- key type: 0   ===> The type of the key it finds there is an RSA key
DBG ykcs11.c:1997 (C_FindObjectsInit): -------- object id: 110  ===> hard coded internal object ID for private keys stored in slot 25
DBG ykcs11.c:2002 (C_FindObjectsInit): -------- subid: 25 ===> This mean slot 25
DBG ykcs11.c:2003 (C_FindObjectsInit): -------- key type: 0 ===> The type of the key it finds there is an RSA key
DBG ykcs11.c:2009 (C_FindObjectsInit): Out
DBG ykcs11.c:2020 (C_FindObjects): In
DBG ykcs11.c:2049 (C_FindObjects): Can return 1 object(s), 3 remaining
DBG ykcs11.c:2058 (C_FindObjects): Returning 1 objects, 2 remaining  ===> Here OpenSSL is fetching the first key it found, aka, the one in slot 9a
DBG ykcs11.c:2062 (C_FindObjects): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In ===> Between (C_GetAttributeValue): In and (C_GetAttributeValue): Out, it tries to get the CKA_CLASS attribute value of the key in 9a and gets the value 3, which translates to CKO_PRIVATE_KEY
DBG objects.c:552 (get_proa): For private key object 86, get
DBG objects.c:556 (get_proa): CLASS
DBG objects.c:560 (get_proa): ----------- class: 3
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In ===> Between (C_GetAttributeValue): In and (C_GetAttributeValue): Out, it tries to get the CKA_KEY_TYPE attribute value of the key in 9a and gets the value 3, which translates to CKK_EC
DBG objects.c:552 (get_proa): For private key object 86, get 
DBG objects.c:584 (get_proa): KEY TYPE
DBG objects.c:590 (get_proa): -------------- key_type: 3
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In ===> Between (C_GetAttributeValue): In and (C_GetAttributeValue): Out, it tries to get the CKA_ID attribute value of the key in 9a and gets a value
DBG objects.c:552 (get_proa): For private key object 86, get 
DBG objects.c:594 (get_proa): ID
DBG ykcs11.c:1905 (C_GetAttributeValue): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In ===> Between (C_GetAttributeValue): In and (C_GetAttributeValue): Out, it tries to get the CKA_LABEL attribute value of the key in 9a and gets a value
DBG objects.c:552 (get_proa): For private key object 86, get 
DBG objects.c:578 (get_proa): LABEL
DBG ykcs11.c:1905 (C_GetAttributeValue): Out

It continues to get more attribute values for this key, then fetchs the next key (in slot 9d) and proceeds to fetch its attribute values and so on. In the end, it matches the label to the one stated in the command line, picks the key with the right label and uses it to perform the private key operation.

When I replace the EC key in 9a with an X25519, this becomes the debug output (which matches the debug output from your command):

DBG ykcs11.c:1993 (C_FindObjectsInit): 3 object(s) left after attribute matching 
DBG ykcs11.c:1995 (C_FindObjectsInit): ------ Found objects:   ===> Here it clearly finds the same objects as before except the key type of the key in slot 9a is now 41, which translates to CKK_EC_MONTGOMERY (aka X25519 key)
DBG ykcs11.c:1997 (C_FindObjectsInit): -------- object id: 86
DBG ykcs11.c:2002 (C_FindObjectsInit): -------- subid: 1
DBG ykcs11.c:2003 (C_FindObjectsInit): -------- key type: 41
DBG ykcs11.c:1997 (C_FindObjectsInit): -------- object id: 88
DBG ykcs11.c:2002 (C_FindObjectsInit): -------- subid: 3
DBG ykcs11.c:2003 (C_FindObjectsInit): -------- key type: 0
DBG ykcs11.c:1997 (C_FindObjectsInit): -------- object id: 110
DBG ykcs11.c:2002 (C_FindObjectsInit): -------- subid: 25
DBG ykcs11.c:2003 (C_FindObjectsInit): -------- key type: 0
DBG ykcs11.c:2009 (C_FindObjectsInit): Out
DBG ykcs11.c:2020 (C_FindObjects): In
DBG ykcs11.c:2049 (C_FindObjects): Can return 1 object(s), 3 remaining
DBG ykcs11.c:2058 (C_FindObjects): Returning 1 objects, 2 remaining
DBG ykcs11.c:2062 (C_FindObjects): Out
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 86, get 
DBG objects.c:556 (get_proa): CLASS
DBG objects.c:560 (get_proa): ----------- class: 3 ===> Getting the right class type here (aka CKO_PRIVATE_KEY), so this is correct
DBG ykcs11.c:1905 (C_GetAttributeValue): Out  
DBG ykcs11.c:1859 (C_GetAttributeValue): In
DBG objects.c:552 (get_proa): For private key object 86, get 
DBG objects.c:584 (get_proa): KEY TYPE
DBG objects.c:590 (get_proa): -------------- key_type: 41 ===> Getting the right key type here (aka CKK_EC_MONTGOMERY), so this too is correct
DBG ykcs11.c:1905 (C_GetAttributeValue): Out 
DBG ykcs11.c:2070 (C_FindObjectsFinal): In ===> After getting the key type, it stops trying to get more attribute values, jumps the the end of the Find operation and deems that there are no keys it can use.
DBG ykcs11.c:2096 (C_FindObjectsFinal): Out
Unable to enumerate private keys
The private key was not found at: pkcs11:object=Private key for Key Management;type=private
PKCS11_get_private_key returned NULL
Could not read private key from org.openssl.engine:pkcs11:pkcs11:object=Private key for Key Management;type=private

The only possible scenario for how this happens is that when OpenSSL gets the key_type value CKK_EC_MONTGOMERY, it considers that an error and interrupts the operation without trying to check the other keys it found.

I started digging into the OpenSSL side of this to try and figure out what is happening. I still haven't managed to find the right piece of code but I do find it strange that the 25519 keys were supported in a previous version but not a later one, which leads me to think it could be a configuration issue. I checked the OpenSSL Changelog to see if this is mentioned and it wasn't, however, I found mention of a configuration option no-ecx that should disable support for ED25519 and X25519 keys. However, I see no indication that this option is turned on by default, on the contrary, but I'm also still looking for where it's defined or when it was introduced so I'm not very sure.

I have actually no reason to believe that support for the 25519 is turned off by default in your installation (or mine for that matter), but this is the most promissing lead I got to why later OpenSSL versions are behaving this way.

I'll keep digging and hopefully figure this out, but this is how far I've gotten for now.

@davidmatson
Copy link
Author

Thanks, @aveenismail!

I wonder if the problem is in libp11.

From a quick skim of their code, I think they have RSA and ECC support but not ED255119/X25519:
https://github.com/OpenSC/libp11/blob/4ad2d25fb4afea34e85a260383155e6413ce54a8/src/pkcs11.h#L711

It looks like there's a related open issue:
OpenSC/libp11#363

So maybe older versions of OpenSSL skipped unknown key types altogether, and when recent versions added support for this key type but libp11 didn't have them, that's when things started going wrong?

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

No branches or pull requests

2 participants