Open flo-renaud opened 8 months ago
@flo-renaud Since we're in exception phase, could you open a RHEL Jira ticket for this and provide the justification?
Hi @edewata I opened https://issues.redhat.com/browse/RHEL-27181
Thanks. I've added some tests for this (PR #4679) and ran it multiple times but so far the ipa ca-add
command never fails. Are you using a replica to run the test?
Also, the SEVERE: Object certificate not found
message and the stack trace above are not actually an error as explained in the PR. The actual error is actually happening in the key retriever implementation which is provided by IPA:
2024-02-28 05:14:31 [KeyRetriever-269d9c22-fa4e-411e-aa82-2e3ba236a6f0] INFO: ExternalProcessKeyRetriever: Retrieving caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0 key
2024-02-28 05:14:40 [KeyRetriever-269d9c22-fa4e-411e-aa82-2e3ba236a6f0] WARNING: Unable to retrieve caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0 key from master.testrelm.test: RC=1
2024-02-28 05:14:40 [KeyRetriever-269d9c22-fa4e-411e-aa82-2e3ba236a6f0] SEVERE: Unable to retrieve caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0 key
2024-02-28 05:14:40 [KeyRetriever-269d9c22-fa4e-411e-aa82-2e3ba236a6f0] WARNING: KeyRetriever did not return a result.
2024-02-28 05:14:55 [KeyRetriever-269d9c22-fa4e-411e-aa82-2e3ba236a6f0] INFO: ExternalProcessKeyRetriever: Retrieving caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0 key
2024-02-28 05:15:03 [KeyRetriever-269d9c22-fa4e-411e-aa82-2e3ba236a6f0] WARNING: Unable to retrieve caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0 key from master.testrelm.test: RC=1
2024-02-28 05:15:03 [KeyRetriever-269d9c22-fa4e-411e-aa82-2e3ba236a6f0] SEVERE: Unable to retrieve caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0 key
2024-02-28 05:15:03 [KeyRetriever-269d9c22-fa4e-411e-aa82-2e3ba236a6f0] WARNING: KeyRetriever did not return a result.
Could you check PKI's systemd journal to see if there are any log messages from the key retriever?
I've invited you to dogtagpki so you can review the PR.
With your PR, the issue is also reproducible. It happened on iteration 62. /var/log/httpd/error_log:
[Thu Feb 29 03:28:05.156029 2024] [proxy_ajp:error] [pid 9229:tid 9331] (70007)The timeout specified has expired: AH01030: ajp_ilink_receive() can't receive header
[Thu Feb 29 03:28:05.156082 2024] [proxy_ajp:error] [pid 9229:tid 9331] [client 2620:52:0:bb:f816:3eff:fe9a:4d4b:36568] AH00992: ajp_read_header: ajp_ilink_receive failed
[Thu Feb 29 03:28:05.156088 2024] [proxy_ajp:error] [pid 9229:tid 9331] (70007)The timeout specified has expired: [client 2620:52:0:bb:f816:3eff:fe9a:4d4b:36568] AH00893: dialog to [::1]:8009 (localhost:8009) failed
[Thu Feb 29 03:28:05.167721 2024] [wsgi:error] [pid 9222:tid 9587] [remote 2620:52:0:bb:f816:3eff:fe9a:4d4b:36546] ipa: INFO: [jsonserver_session] admin@IPA.TEST: ca_add/1('test_subca_62', description='subca', ipacasubjectdn='cn=test_subca_62', version='2.253'): HTTPRequestError
The journal shows custodia failure to obtain the key:
Feb 29 03:27:09 vm-10-0-185-239.xxx.redhat.com ipa-custodia[11929]: Error retrieving key "keys/ca_wrapped/caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694/2.16.840.1.101.3.4.1.2": CalledProcessError(Command ['/usr/libexec/ipa/custodia/ipa-custodia-pki-tomcat-wrapped', '--nickname', 'caSign
ingCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694', '--algorithm', '2.16.840.1.101.3.4.1.2', '--export', '-'] returned non-zero exit status 1: 'Traceback (most recent call last):\n File "/usr/libexec/ipa/custodia/ipa-custodia-pki-tomcat-wrapped", line 8, in <module>\n main(pki_tomcat_parser())\n File "/usr/
lib/python3.12/site-packages/ipaserver/secrets/handlers/nsswrappedcert.py", line 122, in main\n common.main(parser, export_key, None)\n File "/usr/lib/python3.12/site-packages/ipaserver/secrets/handlers/common.py", line 73, in main\n func(args, tmpdir, **kwargs)\n File "/usr/lib/python3.12/site-packages/ipaserv
er/secrets/handlers/nsswrappedcert.py", line 22, in export_key\n ipautil.run([\n File "/usr/lib/python3.12/site-packages/ipapython/ipautil.py", line 599, in run\n raise CalledProcessError(\nipapython.ipautil.CalledProcessError: CalledProcessError(Command [\'/usr/bin/pki\', \'-d\', \'/etc/pki/pki-tomcat/alias\',
\'-C\', \'/etc/pki/pki-tomcat/alias/pwdfile.txt\', \'ca-authority-key-export\', \'--wrap-nickname\', \'caSigningCert cert-pki-ca\', \'--target-nickname\', \'caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694\', \'--algorithm\', \'2.16.840.1.101.3.4.1.2\', \'-o\', \'/tmp/tmpv8epcu3q/wrapped_key\'] returned n
on-zero exit status 255: \'java.lang.SecurityException: Unable to initialize security library: (-8025) A PKCS #11 module returned CKR_GENERAL_ERROR, indicating that an unrecoverable error has occurred.\\n\\tat org.mozilla.jss.CryptoManager.initializeAllNative2(Native Method)\\n\\tat org.mozilla.jss.CryptoManager.initia
lize(CryptoManager.java:594)\\n\\tat org.mozilla.jss.CryptoManager.initialize(CryptoManager.java:504)\\n\\tat com.netscape.cmstools.cli.MainCLI.init(MainCLI.java:508)\\n\\tat com.netscape.cmstools.cli.SubsystemCLI.execute(SubsystemCLI.java:71)\\n\\tat org.dogtagpki.cli.CLI.execute(CLI.java:353)\\n\\tat com.netscape.cms
tools.cli.MainCLI.execute(MainCLI.java:659)\\n\\tat com.netscape.cmstools.cli.MainCLI.main(MainCLI.java:698)\\n\')\n')
Feb 29 03:27:09 vm-10-0-185-239.xxx.redhat.com ipa-custodia[11929]: 2024-02-29 03:27:09 - Secrets-[/keys] - DENIED: '(null)' requested key 'ca_wrapped/caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694/2.16.840.1.101.3.4.1.2'
Feb 29 03:27:09 vm-10-0-185-239.xxx.redhat.com ipa-custodia[11929]: 2024-02-29 03:27:09 - server - code 404, message Not Found
Feb 29 03:27:09 vm-10-0-185-239.xxx.redhat.com ipa-custodia[11929]: 127.0.0.1 - - [29/Feb/2024 03:27:09] "GET /keys/ca_wrapped/caSigningCert%20cert-pki-ca%205bece6da-efbd-40fa-a999-c9d887b1d694/2.16.840.1.101.3.4.1.2?type=kem&value=eyJhbGciOiJSU0EtT0FFUCIsImVuYyI6IkEyNTZDQkMtSFM1MTIiLCJraWQiOm51bGx9.YVw
pWqv7mk-Fc_fKfzQM7ohcxReYmnCN-C0BVUyxmJt_jsdTPY-8kpp1bghhUKcqKtQWgB2WbIHyW70XzntbdRXyq67PZ0ums3bAB7GyF7S02gJVlQl7mAL32n86ZIDTmtMRnUXDewgiVWocGbNARzp-P0INp2VDQkeCfzN4SmrrQjb31lxRpnMbWKCyns1XHs1P3hWKZ3NnSEBMkfAXZVCDq_IWD-nIX5V2-qjB8lzGLS9IacIF4z0iLM_OAA6SSR00QnS2jCSDiMrJL95W_OZ13SmOOD4isLt6Y-Th3y2FrXMmY-l5RgCjqsZbqZ6gfeL
YwgTvwQ1rRy9v1Z4jsw.eRPIa5-inU48JgtXEk83hA.9i7oiB3YgP-sKSvodDTEZbmQUwUrhoeV0rDwWGoVZHbka0ucfYZdXhysYnzdviCpFRhz8ERvXk8EMXj5gZO5tiIfMbPXXSeKWPibG_KOhfh4VSRFikgSg7t0BcwC5fjM0tqUHd8BzQ3fD7YJjFHt-d18f8aN6PWUUokq1HJSrIi5OJ83Ad-4t6QcDinEW9VcLaRur1LLnnT9_GgxLZRsJF-gfKSwNxWDDElYifyLZ8iot1jM1VxfTgS6PNyv7pCUECknTgFuauTSXimXP0ura
HTm_WhA5MwH2cfJ3lOxNfkLZfvoFSAgBD_jAOi4kqjSvOAO2M1rV5RXCU6oJKpsxQz2hD5OUjvKfjuTPamXHCcyslQNnwCk4ZsUay1cwjuVpCh2EFOTI1BuUTefAWXuoTln3dAHTwa6wmUPIDUfJ-UTpvZcg4v10pJicXUYYQDl-lWQ4tFfdzjVn5oUEptwwSpl7MTtJtZc1ZarUIMGggTCYDnWIuM-5ZG0dS_MG-iFVRSD0uSLz95TmaToT485Rnd07dERDBdDzl5yWqtVcDQFd0R3NB9oFAP6nc9-mk1eCewevgP9Mr47hUejmw_uH
JHm6ur7D1FohaAWMAHm78UhbyXAL_5cMAQE1HGvuv-xN1ljRl7jsYvIUi_h0Zp9KW6B_BQ9EeN7D-etMULchtNPYH5KzfwB3smVQIA_bzB775B0ZAOUHKIO7YBX9zNPXKL1H8tWdZPczF1yRCu1fy4GGEevG4x_so7v-B7h5CMHylOk-8YPmPGdOZxDU9gz-lMFhLgaDrqVFdIk2Y8d0YpwAntEjdBpf8gHWF5GH0U9.oaIhQ-eM4fLXxlqbnNSb3yFrtW94VGQY1m5LWXgeIB0 HTTP/1.1" 404 -
It shows a call to /usr/bin/pki -d /etc/pki/pki-tomcat/alias -C /etc/pki/pki-tomcat/alias/pwdfile.txt ca-authority-key-export --wrap-nickname 'caSigningCert cert-pki-ca' --target-nickname 'caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694' --algorithm 2.16.840.1.101.3.4.1.2 -o /tmp/tmpv8epcu3q/wrapped_key
which fails.
pki-tomcat/ca/debug:
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: AuthorityService: Creating authority cn=test_subca_62
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: CAEngine: Creating cn=5bece6da-efbd-40fa-a999-c9d887b1d694,ou=authorities,ou=ca,o=ipaca
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: CAEngine: - authority ID: 5bece6da-efbd-40fa-a999-c9d887b1d694
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: CAEngine: - authority DN: CN=test_subca_62
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: CAEngine: - parent ID: f7af9ce4-35fe-4048-b0e6-c0274bd551af
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: CAEngine: - parent DN: CN=Certificate Authority,O=IPA.TEST
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: CAEngine: - enabled: null
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: CAEngine: - key nickname: caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: CAEngine: - key hosts: [vm-10-0-185-239.xxx.redhat.com:443]
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: CAEngine: Generating signing certificate
2024-02-29 03:27:05 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-8] INFO: CertificateAuthority: generating RSA key
2024-02-29 03:27:05 [AuthorityMonitor] INFO: AuthorityMonitor: Loading authority record cn=5bece6da-efbd-40fa-a999-c9d887b1d694,ou=authorities,ou=ca,o=ipaca
2024-02-29 03:27:05 [AuthorityMonitor] INFO: CAEngine: Loading cn=5bece6da-efbd-40fa-a999-c9d887b1d694,ou=authorities,ou=ca,o=ipaca
2024-02-29 03:27:05 [AuthorityMonitor] INFO: CAEngine: Initializing authority 5bece6da-efbd-40fa-a999-c9d887b1d694
2024-02-29 03:27:05 [AuthorityMonitor] INFO: CAEngine: Initializing cert signing unit
2024-02-29 03:27:05 [AuthorityMonitor] INFO: CASigningUnit: Loading cert caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694
2024-02-29 03:27:05 [AuthorityMonitor] WARNING: CAEngine: CA signing key and cert not (yet) present in NSS database
2024-02-29 03:27:05 [AuthorityMonitor] INFO: CertificateAuthority: Starting KeyRetriever for authority 5bece6da-efbd-40fa-a999-c9d887b1d694
2024-02-29 03:27:05 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] INFO: ExternalProcessKeyRetriever: Retrieving caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694 key
2024-02-29 03:27:05 [AuthorityMonitor] INFO: CAEngine: Checking for newer CA cert
2024-02-29 03:27:05 [AuthorityMonitor] INFO: CAEngine: - serial number: null
2024-02-29 03:27:12 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] WARNING: Unable to retrieve caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694 key from vm-10-0-185-239.hosted.upshift.rdu2.redhat.com: RC=1
2024-02-29 03:27:12 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] SEVERE: Unable to retrieve caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694 key
2024-02-29 03:27:12 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] WARNING: KeyRetriever did not return a result.
2024-02-29 03:27:22 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] INFO: ExternalProcessKeyRetriever: Retrieving caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694 key
2024-02-29 03:27:30 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] WARNING: Unable to retrieve caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694 key from vm-10-0-185-239.hosted.upshift.rdu2.redhat.com: RC=1
2024-02-29 03:27:30 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] SEVERE: Unable to retrieve caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694 key
2024-02-29 03:27:30 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] WARNING: KeyRetriever did not return a result.
2024-02-29 03:27:45 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] INFO: ExternalProcessKeyRetriever: Retrieving caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694 key
2024-02-29 03:27:52 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] WARNING: Unable to retrieve caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694 key from vm-10-0-185-239.hosted.upshift.rdu2.redhat.com: RC=1
2024-02-29 03:27:52 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] SEVERE: Unable to retrieve caSigningCert cert-pki-ca 5bece6da-efbd-40fa-a999-c9d887b1d694 key
2024-02-29 03:27:52 [KeyRetriever-5bece6da-efbd-40fa-a999-c9d887b1d694] WARNING: KeyRetriever did not return a result.
With the PKI version provided in the copr repo @pki/master, freeipa fails to add subcas in loops. After a few iterations, ipa ca-add fails with:
Reproducer: Enable pki copr repo:
dnf copr enable -y @pki/master
Enable freeipa copr repo:dnf copr enable -y @freeipa/freeipa-master-nightly
Upgrade and install freeipa:dnf update -y; dnf install -y freeipa-server-dns
Install IPA server:ipa-server-install --domain ipa.test --realm IPA.TEST --setup-dns --auto-forwarders -a Secret123 -p Secret123 -U
Create multiple subcas:In the provided logs, the command failed for iterations 16,17,18,19,20:
debug.2024-02-23.log