Uploaded image for project: 'RHEL'
  1. RHEL
  2. RHEL-27181

IdM: adding subca in loop fails with Non-2xx response from CA REST API: 500

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Normal Normal
    • None
    • rhel-9.4
    • pki-core
    • None
    • None
    • None
    • sst_idm_cs
    • ssg_idm
    • None
    • False
    • Hide

      None

      Show
      None
    • None
    • None
    • None
    • None
    • None

      What were you trying to do that didn't work?

      On an IdM server, adding subca in loops fails with the error 
       

      ipa: ERROR: Request failed with status 500: Non-2xx response from CA REST API: 500

      Please provide the package NVR for which bug is seen:

      idm-pki-ca-11.5.0-1.el9.noarch

      How reproducible:

      Always

      Steps to reproduce

      Install ipa packages and configure the IdM server:

      # dnf install -y ipa-server
# ipa-server-install --domain ipa.test --realm IPA.TEST -a Secret123 -p Secret123 -U

      In a loop, add subcas:

      # echo Secret123 | kinit admin
# for i in {1..30}; do ipa ca-add test_subca_${i} --subject "cn=test_subca_${i}" --desc subca; done

      Expected results

      The ipa ca-add command should succeed and create subca.

      Actual results

      After a few iterations, the command fails:

      # ipa ca-add test_subca_master_6 --subject cn=test_subca_master_6 --desc subca
ipa: ERROR: Request failed with status 500: Non-2xx response from CA REST API: 500. 

      The log file /var/log/httpd/error_log shows:

      [Wed Feb 28 05:15:13.214199 2024] [proxy_ajp:error] [pid 38370:tid 38419] (70007)The timeout specified has expired: AH01030: ajp_ilink_receive() can't receive header
[Wed Feb 28 05:15:13.214280 2024] [proxy_ajp:error] [pid 38370:tid 38419] [client 10.0.203.129:50714] AH00992: ajp_read_header: ajp_ilink_receive failed
[Wed Feb 28 05:15:13.214286 2024] [proxy_ajp:error] [pid 38370:tid 38419] (70007)The timeout specified has expired: [client 10.0.203.129:50714] AH00878: read response failed from [::1]:8009 (localhost:8009)
[Wed Feb 28 05:15:13.244548 2024] [wsgi:error] [pid 37118:tid 37429] [remote 10.0.203.129:50700] ipa: INFO: [jsonserver_session] admin@TESTRELM.TEST: ca_add/1('test_subca_master_6', description='subca', ipacasubjectdn='cn=test_subca_master_6', version='2.253'): HTTPRequestError

      The /var/log/pki/pki-tomcat/ca/debug.$DATE.log file contains the following:

      2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: AuthorityService: Creating authority cn=test_subca_master_6
2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: CAEngine: Creating cn=269d9c22-fa4e-411e-aa82-2e3ba236a6f0,ou=authorities,ou=ca,o=ipaca
2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: CAEngine: - authority ID: 269d9c22-fa4e-411e-aa82-2e3ba236a6f0
2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: CAEngine: - authority DN: CN=test_subca_master_6
2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: CAEngine: - parent ID: 40b038b3-928c-4460-808a-7fc49f4ab4f6
2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: CAEngine: - parent DN: CN=Certificate Authority,O=TESTRELM.TEST
2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: CAEngine: - enabled: null
2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: CAEngine: - key nickname: caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0
2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: CAEngine: - key hosts: [master.testrelm.test:443]
2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: CAEngine: Generating signing certificate
2024-02-28 05:14:13 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-6] INFO: CertificateAuthority: generating RSA key
2024-02-28 05:14:13 [AuthorityMonitor] INFO: AuthorityMonitor: Loading authority record cn=269d9c22-fa4e-411e-aa82-2e3ba236a6f0,ou=authorities,ou=ca,o=ipaca
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: Loading cn=269d9c22-fa4e-411e-aa82-2e3ba236a6f0,ou=authorities,ou=ca,o=ipaca
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: Initializing authority 269d9c22-fa4e-411e-aa82-2e3ba236a6f0
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: Initializing cert signing unit
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CASigningUnit: Loading cert caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0
2024-02-28 05:14:13 [AuthorityMonitor] SEVERE: Object certificate not found. Error Certificate not found: caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0: Certificate not found: caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0
Certificate not found: caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0: Certificate not found: caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0
	at com.netscape.ca.CASigningUnit.init(CASigningUnit.java:108)
	at org.dogtagpki.server.ca.CAEngine.initCertSigningUnit(CAEngine.java:1907)
	at org.dogtagpki.server.ca.CAEngine.initCA(CAEngine.java:2016)
	at org.dogtagpki.server.ca.CAEngine.createCA(CAEngine.java:1556)
	at com.netscape.ca.AuthorityMonitor.readAuthority(AuthorityMonitor.java:360)
	at com.netscape.ca.AuthorityMonitor.run(AuthorityMonitor.java:166)
	at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: org.mozilla.jss.crypto.ObjectNotFoundException: Certificate not found: caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0
	at org.mozilla.jss.CryptoManager.findCertByNicknameNative(Native Method)
	at org.mozilla.jss.CryptoManager.findCertByNickname(CryptoManager.java:998)
	at com.netscape.ca.CASigningUnit.init(CASigningUnit.java:104)
	... 6 more

2024-02-28 05:14:13 [AuthorityMonitor] WARNING: CAEngine: CA signing key and cert not (yet) present in NSS database
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CertificateAuthority: Starting KeyRetriever for authority 269d9c22-fa4e-411e-aa82-2e3ba236a6f0
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: Checking for newer CA cert
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: - serial number: null
2024-02-28 05:14:13 [KeyRetriever-269d9c22-fa4e-411e-aa82-2e3ba236a6f0] INFO: ExternalProcessKeyRetriever: Retrieving caSigningCert cert-pki-ca 269d9c22-fa4e-411e-aa82-2e3ba236a6f0 key
2024-02-28 05:14:13 [AuthorityMonitor] INFO: AuthorityMonitor: Loading authority record cn=2fcd83b7-07fb-4652-b0a9-f0f219223579,ou=authorities,ou=ca,o=ipaca
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: Loading cn=2fcd83b7-07fb-4652-b0a9-f0f219223579,ou=authorities,ou=ca,o=ipaca
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: Initializing authority 2fcd83b7-07fb-4652-b0a9-f0f219223579
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: Initializing cert signing unit
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CASigningUnit: Loading cert caSigningCert cert-pki-ca 2fcd83b7-07fb-4652-b0a9-f0f219223579
2024-02-28 05:14:13 [AuthorityMonitor] INFO: SigningUnit: cert chain:
2024-02-28 05:14:13 [AuthorityMonitor] INFO: SigningUnit: - CN=test_subca_master_5
2024-02-28 05:14:13 [AuthorityMonitor] INFO: SigningUnit: - CN=Certificate Authority,O=TESTRELM.TEST
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CASigningUnit: Loading private key
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: - nickname: caSigningCert cert-pki-ca 2fcd83b7-07fb-4652-b0a9-f0f219223579
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: Initializing CRL signing unit
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: - nickname: caSigningCert cert-pki-ca 2fcd83b7-07fb-4652-b0a9-f0f219223579
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: Initializing OCSP signing unit
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: - nickname: caSigningCert cert-pki-ca 2fcd83b7-07fb-4652-b0a9-f0f219223579
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: Checking for newer CA cert
2024-02-28 05:14:13 [AuthorityMonitor] INFO: CAEngine: - serial number: 21
2024-02-28 05:14:21 [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:21 [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:21 [KeyRetriever-269d9c22-fa4e-411e-aa82-2e3ba236a6f0] WARNING: KeyRetriever did not return a result.
2024-02-28 05:14:22 [CertStatusUpdateTask] INFO: CertStatusUpdateTask: Updating cert status
2024-02-28 05:14:22 [CertStatusUpdateTask] INFO: CertStatusUpdateTask: Updating invalid certs to valid
2024-02-28 05:14:22 [CertStatusUpdateTask] INFO: LDAPVirtualList: Searching ou=certificateRepository, ou=ca,o=ipaca
2024-02-28 05:14:22 [CertStatusUpdateTask] INFO: LDAPVirtualList: filter: (certStatus=INVALID)
2024-02-28 05:14:23 [CertStatusUpdateTask] INFO: CertStatusUpdateTask: Updating valid certs to expired
2024-02-28 05:14:23 [CertStatusUpdateTask] INFO: LDAPVirtualList: Searching ou=certificateRepository, ou=ca,o=ipaca
2024-02-28 05:14:23 [CertStatusUpdateTask] INFO: LDAPVirtualList: filter: (certStatus=VALID)
2024-02-28 05:14:23 [CertStatusUpdateTask] INFO: LDAPVirtualList: dn: cn=2,ou=certificateRepository,ou=ca,o=ipaca
2024-02-28 05:14:23 [CertStatusUpdateTask] INFO: CertStatusUpdateTask: Updating revoked certs to expired
2024-02-28 05:14:23 [CertStatusUpdateTask] INFO: LDAPVirtualList: Searching ou=certificateRepository, ou=ca,o=ipaca
2024-02-28 05:14:23 [CertStatusUpdateTask] INFO: LDAPVirtualList: filter: (certStatus=REVOKED)
2024-02-28 05:14:23 [CertStatusUpdateTask] INFO: LDAPVirtualList: dn: cn=15,ou=certificateRepository,ou=ca,o=ipaca
2024-02-28 05:14:23 [SerialNumberUpdateTask] INFO: SerialNumberUpdateTask: Updating serial number counter
2024-02-28 05:14:23 [SerialNumberUpdateTask] INFO: CertificateRepository: Storing config into /var/lib/pki/pki-tomcat/conf/ca/CS.cfg
2024-02-28 05:14:23 [SerialNumberUpdateTask] INFO: SerialNumberUpdateTask: Checking serial number ranges
2024-02-28 05:14:23 [SerialNumberUpdateTask] INFO: SerialNumberUpdateTask: Checking request ID ranges
2024-02-28 05:14:23 [Timer-0] INFO: SessionTimer: checking security domain sessions
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.

        1. debug.2024-02-28.log
          970 kB
          Florence Renaud
        2. localhost_access_log.2024-02-28.txt
          14 kB
          Florence Renaud

            Unassigned Unassigned
            frenaud@redhat.com Florence Renaud
            RHCS Maintenance RHCS Maintenance
            IdM CS QE IdM CS QE
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated: