RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 2029834 - Tighten up debug logging / Wrong certificate returned if multiple certs have same label but different ID
Summary: Tighten up debug logging / Wrong certificate returned if multiple certs have ...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 9
Classification: Red Hat
Component: openssl-pkcs11
Version: 9.4
Hardware: Unspecified
OS: Unspecified
low
unspecified
Target Milestone: rc
: 9.4
Assignee: Jakub Jelen
QA Contact: Miluse Bezo Konecna
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-12-07 12:12 UTC by Graham Leggett
Modified: 2024-04-30 10:14 UTC (History)
2 users (show)

Fixed In Version: openssl-pkcs11-0.4.11-8.el9
Doc Type: No Doc Update
Doc Text:
Clone Of:
Environment:
Last Closed: 2024-04-30 10:11:59 UTC
Type: Bug
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker CRYPTO-10583 0 None None None 2023-05-08 07:29:59 UTC
Red Hat Issue Tracker RHELPLAN-104974 0 None None None 2021-12-07 12:13:39 UTC
Red Hat Product Errata RHBA-2024:2398 0 None None None 2024-04-30 10:12:00 UTC

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
Note You need to log in before you can comment on or make changes to this bug.