+++ 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').