Hi folks. PKI-related commands have started to fail on my setup:
$ ipa cert-find ipa: ERROR: Certificate operation cannot be completed: Unable to communicate with CMS (403)
$ ipa vaultconfig-show ipa: ERROR: an internal error has occurred
In /var/log/httpd/error_log I can see, respectively (stripping out the dates, pids, ip addresses etc):
ipa: ERROR: ra.find(): Unable to communicate with CMS (403) ipa: INFO: [jsonserver_session] admin@IPA.EXAMPLE.COM: cert_find/1(None, version='2.245'): CertificateOperationError
and:
ipa: ERROR: non-public: HTTPError: 403 Client Error: 403 for url: https://ipa3.ipa.example.com:443/kra/rest/config/cert/transport Traceback (most recent call last): File "/usr/lib/python3.6/site-packages/pki/__init__.py", line 437, in handler json = exc_val.response.json() File "/usr/lib/python3.6/site-packages/requests/models.py", line 897, in json return complexjson.loads(self.text, **kwargs) File "/usr/lib64/python3.6/json/__init__.py", line 354, in loads return _default_decoder.decode(s) File "/usr/lib64/python3.6/json/decoder.py", line 339, in decode obj, end = self.raw_decode(s, idx=_w(s, 0).end()) File "/usr/lib64/python3.6/json/decoder.py", line 357, in raw_decode raise JSONDecodeError("Expecting value", s, err.value) from None json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
During handling of the above exception, another exception occurred:
Traceback (most recent call last): File "/usr/lib/python3.6/site-packages/ipaserver/rpcserver.py", line 407, in wsgi_execute result = command(*args, **options) File "/usr/lib/python3.6/site-packages/ipalib/frontend.py", line 471, in __call__ return self.__do_call(*args, **options) File "/usr/lib/python3.6/site-packages/ipalib/frontend.py", line 499, in __do_call ret = self.run(*args, **options) File "/usr/lib/python3.6/site-packages/ipalib/frontend.py", line 821, in run return self.execute(*args, **options) File "/usr/lib/python3.6/site-packages/ipaserver/plugins/vault.py", line 1003, in execute transport_cert = kra_client.system_certs.get_transport_cert() File "/usr/lib/python3.6/site-packages/pki/__init__.py", line 442, in handler six.reraise(exc_type, exc_val, exc_tb) File "/usr/lib/python3.6/site-packages/six.py", line 693, in reraise raise value File "/usr/lib/python3.6/site-packages/pki/__init__.py", line 431, in handler return fn_call(inst, *args, **kwargs) File "/usr/lib/python3.6/site-packages/pki/systemcert.py", line 62, in get_transport_cert response = self.connection.get(url, self.headers) File "/usr/lib/python3.6/site-packages/pki/client.py", line 55, in wrapper return func(self, *args, **kwargs) File "/usr/lib/python3.6/site-packages/pki/client.py", line 261, in get r.raise_for_status() File "/usr/lib/python3.6/site-packages/requests/models.py", line 940, in raise_for_status raise HTTPError(http_error_msg, response=self) requests.exceptions.HTTPError: 403 Client Error: 403 for url: https://ipa3.example.com:443/kra/rest/config/cert/transport
ipa: INFO: [jsonserver_session] admin@IPA.EXAMPLE.COM: vaultconfig_show/1(version='2.245'): InternalError
The only messages I can find on the PKI server side are in </var/log/pki/pki-tomcat/localhost_access_log.2022-04-27.txt>:
2001:db8::1 - - [27/Apr/2022:11:59:14 +0000] "POST /ca/rest/certs/search?size=2147483647 HTTP/1.1" 403 618 2001:db8::1 - - [27/Apr/2022:11:59:17 +0000] "GET /kra/rest/config/cert/transport HTTP/1.1" 403 618
So I'm guessing that whatever certificate the IPA API uses to communicate with the PKI server has expired.
ipa-healthcheck has been telling me about certificates with mismatches between their NSS databases and their copies within CS.cfg for a while. I reported these at https://github.com/dogtagpki/pki/issues/3877 in the hope that it would lead somewhere, before the warning actually started causing problems. And then forgot all about it, naturally. :)
Here are the failed checks from ipa-healtcheck, followed by certmonger's status for each tracking request, and the details of the certificate in the NSS database and its copy within CS.cfg:
{ "source": "pki.server.healthcheck.meta.csconfig", "check": "KRADogtagCertsConfigCheck", "result": "ERROR", "uuid": "38ada44b-ded5-4ae9-9365-6d171bc5b0fa", "when": "20220427040032Z", "duration": "0.193909", "kw": { "key": "kra_transport", "nickname": "transportCert cert-pki-kra", "directive": "kra.transport.cert", "configfile": "/var/lib/pki/pki-tomcat/kra/conf/CS.cfg", "msg": "Certificate 'transportCert cert-pki-kra' does not match the value of kra.transport.cert in /var/lib/pki/pki-tomcat/kra/conf/CS.cfg" } } { "source": "ipahealthcheck.dogtag.ca", "check": "DogtagCertsConfigCheck", "result": "ERROR", "uuid": "24b190a9-e445-47d8-9664-742ec413f18e", "when": "20220427040033Z", "duration": "0.471634", "kw": { "key": "transportCert cert-pki-kra", "directive": "ca.connector.KRA.transportCert", "configfile": "/var/lib/pki/pki-tomcat/conf/ca/CS.cfg", "msg": "Certificate 'transportCert cert-pki-kra' does not match the value of ca.connector.KRA.transportCert in /var/lib/pki/pki-tomcat/conf/ca/CS.cfg" } }
# getcert list -d /etc/pki/pki-tomcat/alias -n 'transportCert cert-pki-kra' Number of certificates and requests being tracked: 12. Request ID '20210518174640': status: MONITORING stuck: no key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='transportCert cert-pki-kra',token='NSS Certificate DB',pin set certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='transportCert cert-pki-kra',token='NSS Certificate DB' CA: dogtag-ipa-ca-renew-agent issuer: CN=Certificate Authority,O=IPA.EXAMPLE.COM subject: CN=KRA Transport Certificate,O=IPA.EXAMPLE.COM expires: 2023-03-31 21:42:06 UTC key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment eku: id-kp-clientAuth profile: caTransportCert pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "transportCert cert-pki-kra" track: yes auto-renew: yes
# certutil -d /etc/pki/pki-tomcat/alias -L -n 'transportCert cert-pki-kra' -a | openssl x509 -noout -issuer -serial -subject -dates issuer=O = IPA.EXAMPLE.COM, CN = Certificate Authority serial=2FFF000B subject=O = IPA.EXAMPLE.COM, CN = KRA Transport Certificate notBefore=Apr 10 21:42:06 2021 GMT notAfter=Mar 31 21:42:06 2023 GMT
# crudini --get /etc/pki/pki-tomcat/kra/CS.cfg '' kra.transport.cert | base64 -d | openssl x509 -inform der -noout -issuer -serial -subject -dates issuer=O = IPA.EXAMPLE.COM, CN = Certificate Authority serial=0B subject=O = IPA.EXAMPLE.COM, CN = KRA Transport Certificate notBefore=Mar 18 00:15:01 2019 GMT notAfter=Mar 7 00:15:01 2021 GMT
# crudini --get /var/lib/pki/pki-tomcat/conf/ca/CS.cfg '' ca.connector.KRA.transportCert | base64 -d | openssl x509 -inform der -noout -issuer -serial -subject -dates issuer=O = IPA.EXAMPLE.COM, CN = Certificate Authority serial=0B subject=O = IPA.EXAMPLE.COM, CN = KRA Transport Certificate notBefore=Mar 18 00:15:01 2019 GMT notAfter=Mar 7 00:15:01 2021 GMT
{ "source": "pki.server.healthcheck.meta.csconfig", "check": "KRADogtagCertsConfigCheck", "result": "ERROR", "uuid": "c90d8174-bf9d-4efe-a24c-4e4ece90d7f9", "when": "20220427040032Z", "duration": "0.256320", "kw": { "key": "kra_storage", "nickname": "storageCert cert-pki-kra", "directive": "kra.storage.cert", "configfile": "/var/lib/pki/pki-tomcat/kra/conf/CS.cfg", "msg": "Certificate 'storageCert cert-pki-kra' does not match the value of kra.storage.cert in /var/lib/pki/pki-tomcat/kra/conf/CS.cfg" } }
# getcert list -d /etc/pki/pki-tomcat/alias -n 'storageCert cert-pki-kra' Number of certificates and requests being tracked: 12. Request ID '20210518174641': status: MONITORING stuck: no key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB',pin set certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB' CA: dogtag-ipa-ca-renew-agent issuer: CN=Certificate Authority,O=IPA.EXAMPLE.COM subject: CN=KRA Storage Certificate,O=IPA.EXAMPLE.COM expires: 2023-03-31 21:42:23 UTC key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment eku: id-kp-clientAuth profile: caStorageCert pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "storageCert cert-pki-kra" track: yes auto-renew: yes
# certutil -d /etc/pki/pki-tomcat/alias -L -n 'storageCert cert-pki-kra' -a | openssl x509 -noout -issuer -serial -subject -dates issuer=O = IPA.EXAMPLE.COM, CN = Certificate Authority serial=2FFF000D subject=O = IPA.EXAMPLE.COM, CN = KRA Storage Certificate notBefore=Apr 10 21:42:23 2021 GMT notAfter=Mar 31 21:42:23 2023 GMT
# crudini --get /etc/pki/pki-tomcat/kra/CS.cfg '' kra.storage.cert | base64 -d | openssl x509 -inform der -noout -issuer -serial -subject -dates issuer=O = IPA.EXAMPLE.COM, CN = Certificate Authority serial=0C subject=O = IPA.EXAMPLE.COM, CN = KRA Storage Certificate notBefore=Mar 18 00:15:01 2019 GMT notAfter=Mar 7 00:15:01 2021 GMT
{ "source": "pki.server.healthcheck.meta.csconfig", "check": "KRADogtagCertsConfigCheck", "result": "ERROR", "uuid": "95187b54-782d-455f-8dae-39d6eaee71e5", "when": "20220427040033Z", "duration": "0.319186", "kw": { "key": "kra_audit_signing", "nickname": "auditSigningCert cert-pki-kra", "directive": "kra.audit_signing.cert", "configfile": "/var/lib/pki/pki-tomcat/kra/conf/CS.cfg", "msg": "Certificate 'auditSigningCert cert-pki-kra' does not match the value of kra.audit_signing.cert in /var/lib/pki/pki-tomcat/kra/conf/CS.cfg" } }
# getcert list -d /etc/pki/pki-tomcat/alias -n 'auditSigningCert cert-pki-kra' Number of certificates and requests being tracked: 12. Request ID '20210518174639': status: MONITORING stuck: no key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-kra',token='NSS Certificate DB',pin set certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-kra',token='NSS Certificate DB' CA: dogtag-ipa-ca-renew-agent issuer: CN=Certificate Authority,O=IPA.EXAMPLE.COM subject: CN=KRA Audit,O=IPA.EXAMPLE.COM expires: 2023-03-31 21:42:08 UTC key usage: digitalSignature,nonRepudiation profile: caAuditSigningCert pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "auditSigningCert cert-pki-kra" track: yes auto-renew: yes
# certutil -d /etc/pki/pki-tomcat/alias -L -n 'auditSigningCert cert-pki-kra' -a | openssl x509 -noout -issuer -serial -subject -dates issuer=O = IPA.EXAMPLE.COM, CN = Certificate Authority serial=2FFF000C subject=O = IPA.EXAMPLE.COM, CN = KRA Audit notBefore=Apr 10 21:42:08 2021 GMT notAfter=Mar 31 21:42:08 2023 GMT
# crudini --get /etc/pki/pki-tomcat/kra/CS.cfg '' kra.audit_signing.cert | base64 -d | openssl x509 -inform der -noout -issuer -serial -subject -dates issuer=O = IPA.EXAMPLE.COM, CN = Certificate Authority serial=0D subject=O = IPA.EXAMPLE.COM, CN = KRA Audit notBefore=Mar 18 00:15:02 2019 GMT notAfter=Mar 7 00:15:02 2021 GMT
I'm really not clear exactly what is supposed to be taking the certificates from the NSS database and updating CS.cfg. At first I thought it was the renew_ca_cert script, but looking into the code, it only seems to update CS.cfg for 'caSigningCert cert-pki-ca'.
(Regarding that, there's maybe another issue to solve here. The CA's CS.cfg file has subsystem.select=Clone; it looks like that will cause renew_ca_cert to not update CS.cfg when the CA certificate renews in the distant future. Should I edit CS.cfg by hand, or maybe promote another server to be the CA renewal master, and see if subsystem.select is set properly on that server once it's promoted?)
Anyway. The funny thing about all this is that all these certificates expired last year. And I am pretty sure I used the ipa vault commands a couple of weeks ago. So perhaps the problem is actually elsewhere, and I don't know how to debug the PKI server any further, so...
1. Are the expired certs in CS.cfg causing the problem? 2. Which bit of FreeIPA updates the certificate copies in CS.cfg? 3. Where do I look to debug the PKI server further?
As always, I'm grateful for any assistance, thanks :)