Description of problem: Debug logging produced by openssl-pkcs11 is insufficiently detailed and difficult to follow. Version-Release number of selected component (if applicable): openssl-pkcs11-0.4.10-2.el8.x86_64 How reproducible: Always Steps to Reproduce: 1. Install softhsm2 and opencryptoki, configure tokens. 2. Neither softhsm nor opencryptoki work when accessed from httpd (not the bug in this case, this shows the underlying problem). 3. Try to configure a pkcs11 URL in httpd. Actual results: Debug logging as follows: PKCS#11: Initializing the engine Found 3 slots Loading private key "pkcs11:token=softtok;id=%B0%90%5A%36%1A%E0%2F%DA%13%14%81%FC%E1%DE%9D%86%9E%30%8F%AE;object=;type=private?pin-value=1111" Loading private key "pkcs11:token=softtok;id=%B0%90%5A%36%1A%E0%2F%DA%13%14%81%FC%E1%DE%9D%86%9E%30%8F%AE;object=;type=private?pin-value=1111" Looking in slot -1 for key: id=b0905a361ae02fda131481fce1de9d869e308fae label= [17] Linux uninitialized, login (softtok) Found uninitialized token [18] SoftHSM slot ID 0x6be9cd2 login (SoftHSM Token) [19] SoftHSM slot ID 0x1 uninitialized, login (no label) Specified object not found PKCS11_get_private_key returned NULL - No idea which module is being used. - "Loading private key" done twice, not clear why (turns out first is without login, second is with). - "Looking in slot -1 for key". This message is wrong, we're actually looking at a PKCS11 URL for the key, -1 means "not a specific slot". - "Found uninitialized token". This appears once even though two slots are uninitialised. Confusing. - "Specified object not found". What kind of object? Where did we look? Is this the private key mentioned above or some other object? Expected results: Debug logging as follows: PKCS#11: Initializing the engine: /usr/lib64/p11-kit-proxy.so Found 3 slots Looking in slots for private key without login: id=b0905a361ae02fda131481fce1de9d869e308fae label= - [17] Linux uninitialized, login (softtok) - [18] SoftHSM slot ID 0x6be9cd2 login (SoftHSM Token) - [19] SoftHSM slot ID 0x1 uninitialized, login (no label) No matching initialized token was found for private key Looking in slots for private key with login: id=b0905a361ae02fda131481fce1de9d869e308fae label= - [17] Linux uninitialized, login (softtok) - [18] SoftHSM slot ID 0x6be9cd2 login (SoftHSM Token) - [19] SoftHSM slot ID 0x1 uninitialized, login (no label) No matching initialized token was found for private key The private key was not found at: pkcs11:token=softtok;id=%B0%90%5A%36%1A%E0%2F%DA%13%14%81%FC%E1%DE%9D%86%9E%30%8F%AE;object=;type=private?pin-value=1111 PKCS11_get_private_key returned NULL Additional info: PR proposed here: https://github.com/OpenSC/libp11/pull/433
Thank you for the PR. It looks good to me. As a side note, I can recommend using the "log-calls" configuration option in the softhsm2 pkcs11 configuration in p11-kit, which will log all the pkcs11 calls and can give you some more ideas what is going on in there. I can not promise this will be available in RHEL any time soon. If you have a business need for this, please open a customer ticket with your Red Hat support.
Due to Github's inability to handle layered patches, the debug fixes and the fix to the underlying problem are included in the same PR. Underlying problem is: When ID and label are specified, both need to match, not either. To fix this id-match OR label-match was replaced with id-match AND label-match. A tiebreak was added when multiple matching certificates could be returned. The certificate with the latest expiry wins, and if we still have a tie we deterministically choose a certificate using X509_cmp(). If we do not specify a certificate id or label, we return the first certificate (or first certificate with an ID) as before. Debug logging showing broken certificate selection decision: Looking in slots for certificate without login: id=b0905a361ae02fda131481fce1de9d869e308fae label= - [17] Linux login (Local Tokens) - [18] SoftHSM slot ID 0x6be9cd2 login (SoftHSM Token) - [19] SoftHSM slot ID 0x1 uninitialized, login (no label) Found slot: Linux Found token: Local Tokens Found 2 certificates: 1 id=b0905a361ae02fda131481fce1de9d869e308fae label= 2 id=8d8c5ec454ad8ae177e99bf99b05e1b8018d61e1 label= Returning last matching certificate: id=8d8c5ec454ad8ae177e99bf99b05e1b8018d61e1 label= (The id returned does not match id requested, this is because match was done on label equals empty string only) Debug logging showing correct cert selected after fix applied: Looking in slots for certificate without login: id=b0905a361ae02fda131481fce1de9d869e308fae label= - [17] Linux login (Local Tokens) - [18] SoftHSM slot ID 0x6be9cd2 login (SoftHSM Token) - [19] SoftHSM slot ID 0x1 uninitialized, login (no label) Found slot: Linux Found token: Local Tokens Found 5 certificates: 1 id=b0905a361ae02fda131481fce1de9d869e308fae label= expiry=Oct 10 23:59:59 2022 GMT 2 id=8d8c5ec454ad8ae177e99bf99b05e1b8018d61e1 label= expiry=Dec 31 23:59:59 2030 GMT 3 id=db37d5e37791d66591a0ee77704a80db4234fea1 label= expiry=Oct 16 12:00:00 2019 GMT 4 id=db37d5e37791d66591a0ee77704a80db4234fea1 label= expiry=Oct 9 23:59:59 2021 GMT 5 id=b5c303e570ff60a6d794a120d43a32fd88b2dc3f label= expiry=Sep 20 12:00:00 2017 GMT Returning longest expiry matching certificate: id=b0905a361ae02fda131481fce1de9d869e308fae label= expiry=Oct 10 23:59:59 2022 GMT
Patch is approved upstream. Reminder that certificate selection after a certificate renewal is broken until this patch is applied.
Moving to RHEL 9 as we do not plan to do any other non-critical bugfixes in RHEL8.