CA subsystem fails to start when using HSM and Nuxwdog

[jmisset-cb]

Description of problem:

CA subsystem fails to start on nuxwdog-enabled CA instance that uses an HSM.
To be more specific, it is the pki-server upgrade PreTask from the systemd service file, that fails.

Version-Release number of selected component (if applicable):

rpm -qi dogtag-pki-ca
Name        : dogtag-pki-ca
Version     : 11.5.0
Release     : 3.fc40
Architecture: noarch
Install Date: Wed 06 Nov 2024 01:25:27 PM CET
Group       : Unspecified
Size        : 4014572
License     : GPL-2.0-only and LGPL-2.0-only
Signature   : RSA/SHA256, Mon 04 Mar 2024 10:05:34 PM CET, Key ID 0727707ea15b79cc
Source RPM  : dogtag-pki-11.5.0-3.fc40.src.rpm
Build Date  : Mon 04 Mar 2024 09:50:51 PM CET
Build Host  : buildhw-x86-04.iad2.fedoraproject.org
Packager    : Fedora Project
Vendor      : Fedora Project
URL         : https://www.dogtagpki.org
Bug URL     : https://bugz.fedoraproject.org/dogtag-pki
Summary     : Dogtag PKI CA Package

Steps to reproduce:

1. Spawn a CA subsystem with HSM enabled (for example using softhsm, but most probably not HSM-module related)
2. Stop the CA subsystem and enable nuxwdog pki-server instance-nuxwdog-enable pki-tomcat
3. Add cms.tokenList=<token> to CS.cfg
4. Remove /etc/pki/pki-tomcat/password.conf
5. Start the CA subsystem systemctl start [email protected]
6. Supply the passwords

Expected results:

CA starts up succesfully

Actual results:

CA startup fails with:

Nov  6 14:38:32 localhost pki-server[7386]: ERROR: 'hardware-dogtagpki'
Nov  6 14:38:32 localhost pki-server[7386]: Traceback (most recent call last):
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/server/pkiserver.py", line 41, in <module>
Nov  6 14:38:32 localhost pki-server[7386]:    cli.execute(sys.argv)
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/server/cli/__init__.py", line 144, in execute
Nov  6 14:38:32 localhost pki-server[7386]:    super().execute(args)
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/cli/__init__.py", line 217, in execute
Nov  6 14:38:32 localhost pki-server[7386]:    module.execute(module_args)
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/server/cli/upgrade.py", line 144, in execute
Nov  6 14:38:32 localhost pki-server[7386]:    self.upgrade(
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/server/cli/upgrade.py", line 178, in upgrade
Nov  6 14:38:32 localhost pki-server[7386]:    upgrader.upgrade()
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/upgrade.py", line 485, in upgrade
Nov  6 14:38:32 localhost pki-server[7386]:    self.upgrade_version(version)
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/upgrade.py", line 460, in upgrade_version
Nov  6 14:38:32 localhost pki-server[7386]:    self.run_scriptlet(scriptlet)
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/server/upgrade.py", line 106, in run_scriptlet
Nov  6 14:38:32 localhost pki-server[7386]:    scriptlet.upgrade_subsystem(self.instance, subsystem)
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/share/pki/server/upgrade/11.5.0/04-RemoveCertCSRfromConfig.py", line 28, in upgrade_subsystem
Nov  6 14:38:32 localhost pki-server[7386]:    for cert in certs:
Nov  6 14:38:32 localhost pki-server[7386]:                ^^^^^
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/server/subsystem.py", line 333, in find_system_certs
Nov  6 14:38:32 localhost pki-server[7386]:    yield self.get_subsystem_cert(cert_id)
Nov  6 14:38:32 localhost pki-server[7386]:          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/server/subsystem.py", line 357, in get_subsystem_cert
Nov  6 14:38:32 localhost pki-server[7386]:    cert_info = self.get_nssdb_cert_info(tag)
Nov  6 14:38:32 localhost pki-server[7386]:                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/server/subsystem.py", line 386, in get_nssdb_cert_info
Nov  6 14:38:32 localhost pki-server[7386]:    return nssdb.get_cert_info(nickname, token=token)
Nov  6 14:38:32 localhost pki-server[7386]:           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/nssdb.py", line 2052, in get_cert_info
Nov  6 14:38:32 localhost pki-server[7386]:    cert_pem = self.get_cert(nickname=nickname, token=token)
Nov  6 14:38:32 localhost pki-server[7386]:               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/nssdb.py", line 1991, in get_cert
Nov  6 14:38:32 localhost pki-server[7386]:    password_file = self.get_password_file(tmpdir, token)
Nov  6 14:38:32 localhost pki-server[7386]:                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov  6 14:38:32 localhost pki-server[7386]:  File "/usr/lib/python3.12/site-packages/pki/nssdb.py", line 422, in get_password_file
Nov  6 14:38:32 localhost pki-server[7386]:    password = self.passwords[token]
Nov  6 14:38:32 localhost pki-server[7386]:               ~~~~~~~~~~~~~~^^^^^^^
Nov  6 14:38:32 localhost pki-server[7386]: KeyError: 'hardware-dogtagpki'

Workaround and possible solution

• This problem does not occur when commenting out ExecStartPre=/usr/sbin/pki-server upgrade %i in /usr/lib/systemd/system/[email protected]
• This problem can also be worked around by changing:
  nssdb = self.instance.open_nssdb()
  to nssdb = self.instance.open_nssdb(token=token) in:
  https://github.com/dogtagpki/pki/blob/master/base/server/python/pki/server/subsystem.py#L413

It seems like the problem is that self.instance.open_nssdb() loads the nssdb, without a tokenname, so that it defaults to token internal.
Consequently, the get_nssdb_cert_info function tries to lookup certificate info on the HSM tokenname, but this is not present in the pki.nssdb.NSSDatabase object.

I am not sure how good of a solution it is to use nssdb = self.instance.open_nssdb(token=token) for this specific case. I've seen other parts of the code where the token is also not specified when opening an instance of nssdb.