Bug 1746545

Summary: Certmonger fails to read token in HSM
Product: [Fedora] Fedora Reporter: Rob Crittenden <rcritten>
Component: certmongerAssignee: Rob Crittenden <rcritten>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 30CC: ipa-qe, mharmsen, nalin, rcritten
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: certmonger-0.79.9-1 certmonger-0.79.9-1.fc31 certmonger-0.79.9-1.fc30 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1746543 Environment:
Last Closed: 2020-02-10 01:42:13 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1746543    
Bug Blocks:    

Description Rob Crittenden 2019-08-28 18:04:21 UTC 
+++ This bug was initially created as a clone of Bug #1746543 +++

This bug is created as a clone of upstream ticket:
https://pagure.io/certmonger/issue/125

I'm helping to add HSM support for FreeIPA.

I have disabled p11-kit https://pagure.io/freeipa/issue/7810
$ rm -f /etc/crypto-policies/local.d/nss-p11-kit.config && update-crypto-policies
$ reboot

Modified the FreeIPA python scripts so that internal (mostly dogtag) certificate is stored in HSM (I'm using SoftHSM for development)

$ modutil -dbdir /etc/pki/pki-tomcat/alias -list

Listing of PKCS 11 Modules

  1. NSS Internal PKCS 11 Module
	   uri: pkcs11:library-manufacturer=Mozilla%20Foundation;library-description=NSS%20Internal%20Crypto%20Services;library-version=3.44
	 slots: 2 slots attached
	status: loaded

	 slot: NSS Internal Cryptographic Services
	token: NSS Generic Crypto Services
	  uri: pkcs11:token=NSS%20Generic%20Crypto%20Services;manufacturer=Mozilla%20Foundation;serial=0000000000000000;model=NSS%203

	 slot: NSS User Private Key and Certificate Services
	token: NSS Certificate DB
	  uri: pkcs11:token=NSS%20Certificate%20DB;manufacturer=Mozilla%20Foundation;serial=0000000000000000;model=NSS%203

  2. softhsm
	library name: /usr/lib64/pkcs11/libsofthsm2.so
	   uri: pkcs11:library-manufacturer=SoftHSM;library-description=Implementation%20of%20PKCS11;library-version=2.5
	 slots: 2 slots attached
	status: loaded

	 slot: SoftHSM slot ID 0x1e204b1f
	token: Dogtag
	  uri: pkcs11:token=Dogtag;manufacturer=SoftHSM%20project;serial=2e2e45569e204b1f;model=SoftHSM%20v2

	 slot: SoftHSM slot ID 0x1
	token: 
	  uri: pkcs11:manufacturer=SoftHSM%20project;model=SoftHSM%20v2


$ certutil -L -d /etc/pki/pki-tomcat/alias -h all

Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

Enter Password or Pin for "Dogtag":
Server-Cert cert-pki-ca                                      u,u,u
auditSigningCert cert-pki-ca                                 u,u,Pu
caSigningCert cert-pki-ca                                    CTu,Cu,Cu
Dogtag:caSigningCert cert-pki-ca                             CTu,Cu,Cu
Dogtag:auditSigningCert cert-pki-ca                          u,u,Pu
Dogtag:ocspSigningCert cert-pki-ca                           u,u,u
Dogtag:subsystemCert cert-pki-ca                             u,u,u

$ certutil -K -d /etc/pki/pki-tomcat/alias -h all
certutil: Checking token "NSS Generic Crypto Services" in slot "NSS Internal Cryptographic Services"
certutil: no keys found
certutil: Checking token "NSS Certificate DB" in slot "NSS User Private Key and Certificate Services"
Enter Password or Pin for "NSS Certificate DB":
< 0> rsa      a6793d9d3d8333c7c0de32d8ed8fe974b109f137   NSS Certificate DB:Server-Cert cert-pki-ca
certutil: Checking token "Dogtag" in slot "SoftHSM slot ID 0x1e204b1f"
Enter Password or Pin for "Dogtag":
< 0> rsa      87f899a34660a00bc8db2df813200d80254bb8cd   ocspSigningCert cert-pki-ca
< 1> rsa      a15e8133b16a6a194225274283c95f90b2edfebf   auditSigningCert cert-pki-ca
< 2> rsa      d722c8de0c89b73fd7adbc9329ede583e7c5428a   caSigningCert cert-pki-ca
< 3> rsa      f9d9e20d507d236f762a4a4102bc6b55cc6fedb3   subsystemCert cert-pki-ca

But ran into problem that certmonger will not found above token 'Dogtag'

Stop dogtag, so that certmonger can get read/write lock on nss db
$ systemctl stop pki-tomcatd

Manually add certmonger tracking (which is the same that is done in freeipa python script)
$ getcert start-tracking -d /etc/pki/pki-tomcat/alias -n 'ocspSigningCert cert-pki-ca' -t 'Dogtag' -P redhat123 -r -c dogtag-ipa-ca-renew-agent -S -B /usr/libexec/ipa/certmonger/stop_pkicad -C "/usr/libexec/ipa/certmonger/renew_ca_cert 'ocspSigningCert cert-pki-ca'"

But the token 'Dogtag' is never found
$ journalctl -f -t certmonger
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Pending GetConnectionUnixUser serial 5804
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Pending GetConnectionUnixProcessID serial 5805
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Queuing FD 7 for Read for 0x5598c2efcd30:0x5598c2f1ed30.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Dequeuing FD 7 for Read for 0x5598c2efcd30:0x5598c2f1ed30.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Handling D-Bus traffic (Read) on FD 7 for 0x5598c2efcd30.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] message 0x5598c2efcd30(method_return)->5804->4294967295
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] message 0x5598c2efcd30(method_return)->5805->4294967295
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] User ID 0 PID 8390 called /org/fedorahosted/certmonger:org.fedorahosted.certmonger.add_request.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8391] Read value "0" from "/proc/sys/crypto/fips_enabled".
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8391] Not attempting to set NSS FIPS mode.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8391] Skipping NSS internal slot (NSS Generic Crypto Services).
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8391] Found token 'NSS Certificate DB'.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8391] Token is named "NSS Certificate DB", not "Dogtag", skipping.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8391] Error locating a key.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8392] Read value "0" from "/proc/sys/crypto/fips_enabled".
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8392] Not attempting to set NSS FIPS mode.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8392] Found token 'NSS Generic Crypto Services'.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8392] Token is named "NSS Generic Crypto Services", not "Dogtag", skipping.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8392] Found token 'NSS Certificate DB'.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8392] Token is named "NSS Certificate DB", not "Dogtag", skipping.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8392] Error locating certificate.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Request11('20190822103540') starts in state 'NEWLY_ADDED'
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Request11('20190822103540') taking writing lock
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Request11('20190822103540') moved to state 'NEWLY_ADDED_START_READING_KEYINFO'
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Will revisit Request11('20190822103540') now.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Started Request11('20190822103540').
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Queuing FD 7 for Read for 0x5598c2efcd30:0x5598c2f0a420.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Request11('20190822103540') moved to state 'NEWLY_ADDED_READING_KEYINFO'
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Will revisit Request11('20190822103540') on traffic from 11.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Dequeuing FD 7 for Read for 0x5598c2efcd30:0x5598c2f0a420.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Handling D-Bus traffic (Read) on FD 7 for 0x5598c2efcd30.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] message 0x5598c2efcd30(method_call)->org.fedorahosted.certmonger:/org/fedorahosted/certmonger/requests/Request11:org.fedorahosted.certmonger.request.get_nickname
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Pending GetConnectionUnixUser serial 5809
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Pending GetConnectionUnixProcessID serial 5810
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Queuing FD 7 for Read for 0x5598c2efcd30:0x5598c2f1bd90.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Dequeuing FD 7 for Read for 0x5598c2efcd30:0x5598c2f1bd90.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Handling D-Bus traffic (Read) on FD 7 for 0x5598c2efcd30.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] message 0x5598c2efcd30(method_return)->5809->4294967295
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] message 0x5598c2efcd30(method_return)->5810->4294967295
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] User ID 0 PID 8390 called /org/fedorahosted/certmonger/requests/Request11:org.fedorahosted.certmonger.request.get_nickname.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Queuing FD 7 for Read for 0x5598c2efcd30:0x5598c2f0a420.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8393] Read value "0" from "/proc/sys/crypto/fips_enabled".
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8393] Not attempting to set NSS FIPS mode.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8393] Skipping NSS internal slot (NSS Generic Crypto Services).
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8393] Found token 'NSS Certificate DB'.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8393] Token is named "NSS Certificate DB", not "Dogtag", skipping.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [8393] Error locating a key.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Request11('20190822103540') releasing writing lock
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Request11('20190822103540') moved to state 'NEWLY_ADDED_NEED_KEYINFO_READ_TOKEN'
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Will revisit Request11('20190822103540') now.
Aug 22 12:35:40 freeipa-fedora30-master-hsm.magnuskkarlsson.local certmonger[7909]: 2019-08-22 12:35:40 [7909] Waiting for instructions for Request11('20190822103540').
Comment 1 Rob Crittenden 2019-09-06 17:41:36 UTC 
master:
34c120f0259750ff2228def2955de9ad985340e6
59df833ca5fb80c596df621a24dc461a550dba71
Comment 2 Fedora Update System 2020-02-01 01:04:10 UTC 
FEDORA-2020-773d9d9103 has been submitted as an update to Fedora 30. https://bodhi.fedoraproject.org/updates/FEDORA-2020-773d9d9103
Comment 3 Fedora Update System 2020-02-02 01:15:14 UTC 
certmonger-0.79.9-1.fc31 has been pushed to the Fedora 31 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-319545c382
Comment 4 Fedora Update System 2020-02-02 02:36:59 UTC 
certmonger-0.79.9-1.fc30 has been pushed to the Fedora 30 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-773d9d9103
Comment 5 Fedora Update System 2020-02-10 01:42:13 UTC 
certmonger-0.79.9-1.fc31 has been pushed to the Fedora 31 stable repository. If problems still persist, please make note of it in this bug report.
Comment 6 Fedora Update System 2020-02-10 02:38:18 UTC 
certmonger-0.79.9-1.fc30 has been pushed to the Fedora 30 stable repository. If problems still persist, please make note of it in this bug report.