Bug 2029834

Summary: Tighten up debug logging / Wrong certificate returned if multiple certs have same label but different ID
Product: Red Hat Enterprise Linux 9 Reporter: Graham Leggett <minfrin>
Component: openssl-pkcs11Assignee: Jakub Jelen <jjelen>
Status: CLOSED ERRATA QA Contact: Miluse Bezo Konecna <mbezokon>
Severity: unspecified Docs Contact:
Priority: low    
Version: 9.4CC: ansasaki, mbezokon
Target Milestone: rcKeywords: Triaged
Target Release: 9.4Flags: pm-rhel: mirror+
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: openssl-pkcs11-0.4.11-8.el9 Doc Type: No Doc Update
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2024-04-30 10:11:59 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Graham Leggett 2021-12-07 12:12:24 UTC
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

Comment 1 Jakub Jelen 2021-12-07 15:25:15 UTC
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.

Comment 2 Graham Leggett 2021-12-09 14:23:42 UTC
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

Comment 3 Graham Leggett 2022-03-08 15:15:59 UTC
Patch is approved upstream.

Reminder that certificate selection after a certificate renewal is broken until this patch is applied.

Comment 5 Jakub Jelen 2023-05-18 11:25:39 UTC
Moving to RHEL 9 as we do not plan to do any other non-critical bugfixes in RHEL8.

Comment 8 Jakub Jelen 2023-08-30 17:08:21 UTC
The change is ready for testing in the following centos stream MR:

https://gitlab.com/redhat/centos-stream/rpms/openssl-pkcs11/-/merge_requests/4

Comment 13 errata-xmlrpc 2024-04-30 10:11:59 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (openssl-pkcs11 bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2024:2398