#8499 ipa-replica-install fails because certificate already exists in LDAP
Closed: invalid by ftweedal. Opened by sukhinin.

Issue

We have an installation of 3 freeipa masters. IPA Certificate authority is configured as a subordinate CA. When we try to add one more replica, ipa-replica-install --setup-ca fails with an error:

  [5/28]: configuring certificate server instance
ipaserver.install.dogtaginstance: CRITICAL Failed to configure CA instance: Command '/usr/sbin/pkispawn -s CA -f /tmp/tmp_3KfOZ' returned non-zero exit status 1
ipaserver.install.dogtaginstance: CRITICAL See the installation logs and the following files/directories for more information:
ipaserver.install.dogtaginstance: CRITICAL   /var/log/pki/pki-tomcat
  [error] RuntimeError: CA configuration failed.

It seems the error is because certificate requestId was somehow used more than once.

Actual behavior

RequestId is reused when requesting certificate from FreeIPA CA. Certificate cannot be saved to LDAP because an entry with the same DN already exists.

Expected behavior

RequestId is unique for each request.

Version/Release/Distribution

$ rpm -q freeipa-server freeipa-client ipa-server ipa-client 389-ds-base pki-ca krb5-server
package freeipa-server is not installed
package freeipa-client is not installed
ipa-server-4.6.4-10.el7.centos.x86_64
ipa-client-4.6.4-10.el7.centos.x86_64
389-ds-base-1.3.8.4-18.el7_6.x86_64
pki-ca-10.5.9-6.el7.noarch
krb5-server-1.15.1-34.el7.x86_64

Additional info:

/var/log/pki/pki-tomcat/ca/debug with a detailed error message:

[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: === Processing signing cert ===
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: === Processing ocsp_signing cert ===
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: === Processing sslserver cert ===
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: SystemConfigService.processKeyPair(sslserver)
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: SystemConfigService: san_server_cert not found
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: SystemConfigService: loading existing key pair from NSS database
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: ConfigurationUtils: loadKeyPair(Server-Cert cert-pki-ca, )
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: SystemConfigService: storing key pair into CS.cfg
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: ConfigurationUtils: storeKeyPair(sslserver)
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: SystemConfigService.processCert(sslserver)
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: SystemConfigService: checking sslserver cert in NSS database
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: configCert: caType is local
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: configCert: caType is remote (revised)
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: ConfigurationUtils: updateConfig() for certTag sslserver
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: updateConfig() done
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: configCert: remote CA
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: confgCert: tag: sslserver
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: CertRequestPanel: got public key
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: CertRequestPanel: got private key
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: ConfigurationUtils: For this Cloned CA, always use its Master CA to generate the 'sslserver' certificate to avoid any changes which may have been made to the X500Name directory string encoding order.
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: ConfigurationUtils: injectSAN: false
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: configRemoteCert: tag: sslserver : setting profileId to: caInternalAuthServerCert
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: configRemoteCert: tag: sslserver calculated profileId: caInternalAuthServerCert
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: CertUtil: content: {xmlOutput=[true], cert_request_type=[pkcs10], profileId=[caInternalAuthServerCert], cert_request=[...cut...], requestor_name=[CA-srvXXX.local.domain-8443], sessionID=[6184760106499759096]}
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: ConfigurationUtils: POST https://srvYYY.local.domain:443/ca/ee/ca/profileSubmit
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: CertUtil: status: 1
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: CertUtil: error: Request 19990005 - Server Internal Error
java.io.IOException: Request 19990005 - Server Internal Error
    at com.netscape.cms.servlet.csadmin.CertUtil.createRemoteCert(CertUtil.java:103)
    at com.netscape.cms.servlet.csadmin.ConfigurationUtils.configRemoteCert(ConfigurationUtils.java:2737)
    at com.netscape.cms.servlet.csadmin.ConfigurationUtils.configCert(ConfigurationUtils.java:2593)
    at org.dogtagpki.server.rest.SystemConfigService.processCert(SystemConfigService.java:484)
    at org.dogtagpki.server.rest.SystemConfigService.processCerts(SystemConfigService.java:303)
    at org.dogtagpki.server.rest.SystemConfigService.configure(SystemConfigService.java:166)
    at org.dogtagpki.server.rest.SystemConfigService.configure(SystemConfigService.java:101)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:280)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:234)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:221)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:288)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
    at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:320)
    at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:175)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:297)
    at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:55)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:191)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:187)
    at java.security.AccessController.doPrivileged(Native Method)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:186)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:288)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
    at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:320)
    at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:260)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
    at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:55)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:191)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:187)
    at java.security.AccessController.doPrivileged(Native Method)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:186)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:218)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:110)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:506)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:962)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:445)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1087)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:637)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:748)
[15/Sep/2020:15:42:06][http-bio-8443-exec-3]: SignedAuditLogger: event ACCESS_SESSION_TERMINATED

LDAP access logs /var/log/dirsrv/slapd-LOCAL-DOMAIN/access from one of the existing replicas (srvYYY.local.domain):

[15/Sep/2020:15:42:06.259655845 +0300] conn=2608 op=1804 ADD dn="cn=19990005,ou=ca,ou=requests,o=ipaca"
[15/Sep/2020:15:42:06.260525381 +0300] conn=2608 op=1804 RESULT err=68 tag=105 nentries=0 etime=0.0001251547
[15/Sep/2020:15:42:06.295774388 +0300] conn=2608 op=1805 ADD dn="cn=536805381,ou=certificateRepository,ou=ca,o=ipaca"
[15/Sep/2020:15:42:06.296210847 +0300] conn=2608 op=1805 RESULT err=68 tag=105 nentries=0 etime=0.0000755866
[15/Sep/2020:15:42:06.301651990 +0300] conn=2608 op=1806 MOD dn="cn=19990005,ou=ca,ou=requests,o=ipaca"
[15/Sep/2020:15:42:06.315983780 +0300] conn=2608 op=1806 RESULT err=0 tag=103 nentries=0 etime=0.0014827998 csn=5f60b69f000000110000

@edewata @cipherboy can you take a look since it's a PKI issue?

@rcritten @edewata @cipherboy related mailing list discussion: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahosted.org/thread/RUZEILNVXW7SDNZ3TA5NSZOVYLIXBBKF/ .

My current theory is that it is caused by incomplete/corrupted VLV index, otherwise somehow a range conflict arose.

Problem was confirmed as corrupt/inconsistent VLV index: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahosted.org/message/SPTWIG4BER25PE2G332MLLOWSVFUJ4DR/ .

Closing this ticket. If we ever find out what is causing the problems with the VLV index, we can address that in a separate ticket (probably a problem with 389ds or Dogtag, not IPA).

Metadata Update from @ftweedal:
- Issue close_status updated to: invalid
- Issue status updated to: Closed (was: Open)

Metadata