Thanks so much Fraser for your reply.
Looking forward to your blog post!
All the best,
Guillermo
On Tue, Jul 23, 2019 at 8:22 PM Fraser Tweedale <ftweedal(a)redhat.com> wrote:
>
> On Tue, Jul 23, 2019 at 12:50:53AM -0400, Guillermo Fuentes via FreeIPA-users wrote:
> > Hi list,
> >
> > I'm having an issue where the CA subsystem certificates are failing to
renew.
> >
> > *** Environment:
> > 4 FreeIPA replica servers with CA.
> >
> > Currently CentOS 7 up-to-date.
> > Initially setup as FreeIPA 3 on CentOS 6 upgraded to CentOS 7 and kept
> > up-to-date with the latest stable release available:
> > ipa-server-4.6.4-10.el7.centos.3.x86_64
> > 389-ds-base-1.3.8.4-23.el7_6.x86_64
> > pki-ca-10.5.9-13.el7_6.noarch
> > pki-server-10.5.9-13.el7_6.noarch
> >
> > This past June third-party wildcard certificate was installed for both
> > the HTTPS and LDAP servers using the ipa-server-certinstall command.
> >
> > Trying to be proactive as the following CA subsystem certificates will
> > expire on August 12, 2019:
> > subject: CN=CA
Audit,O=EXAMPLE.COM
> > subject: CN=OCSP
Subsystem,O=EXAMPLE.COM
> > subject: CN=CA
Subsystem,O=EXAMPLE.COM
> > subject: CN=IPA
RA,O=EXAMPLE.COM
> >
> >
> > *** Issue:
> > Getting the following error when listing the certificate info for each
> > of them in the CA Renewal and CRL Master:
> > status: MONITORING
> > ca-error: Server at
> > "https://ipa1.example.com:8443/ca/agent/ca/profileProcess" replied:
1:
> > Server Internal Error
> > stuck: no
> > CA: dogtag-ipa-ca-renew-agent
> > issuer: CN=Certificate
Authority,O=EXAMPLE.COM
> > expires: 2019-08-12 ...
> > pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
> > post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert
> > "auditSigningCert cert-pki-ca"
> > track: yes
> > auto-renew: yes
> >
> > Getting the following error in the other CA replicas for the same
> > certificates (I'm assuming fixing it in the Master should take care of
> > the replicas):
> > ca-error: Invalid cookie: u''
> >
> >
> > Looking at the logs in the Master, the renewal seems to fail with an
> > LDAP error code 68 (Entry Already Exists) when adding serial 268304406
> > (when resubmitting it). Doesn't that serial suppose to exist as it's
> > being renewed?
> >
> > These are some relevant logs after resubmitting:
> > - certmonger journal shows:
> > ...
> > Jul 22 20:30:19
ipa1.example.com dogtag-ipa-renew-agent-submit[10116]:
> > GET
https://ipa1.example.com:8443/ca/agent/ca/profileProcess?requestId=998004...
> > Jul 22 20:30:19
ipa1.example.com
> > dogtag-ipa-ca-renew-agent-submit[10097]: dogtag-ipa-renew-agent
> > returned 2
> > Jul 22 20:30:19
ipa1.example.com certmonger[1288]: 2019-07-22 20:30:19
> > [1288] Server at
> > "https://ipa1.example.com:8443/ca/agent/ca/profileProcess" replied:
1:
> > Server Internal Error
> >
> > - /var/log/pki/pki-tomcat/ca/debug
> > ...
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: Repository: checkRange
> > mLastSerialNo=268304406
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: Repository:
> > getNextSerialNumber: returning retSerial 268304406
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: CAService:
> > issueX509Cert: setting issuerDN using exact CA signing cert subjectDN
> > encoding
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: About to ca.sign cert.
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: sign cert get algorithm
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: sign cert encoding cert
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: sign cert encoding algorithm
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: CA cert signing: signing cert
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: Getting algorithm
> > context for SHA256withRSA RSASignatureWithSHA256Digest
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: Signing Certificate
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: storeX509Cert 268304406
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: In storeX509Cert
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: In
> > LdapBoundConnFactory::getConn()
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: masterConn is connected: true
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: getConn: conn is connected true
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: getConn: mNumConns now 5
> > [22/Jul/2019:20:30:19][http-bio-8443-exec-16]: returnConn: mNumConns now 6
> > LDAP operation failure - cn=268304406,ou=certificateRepository, ou=ca,
> > o=ipaca: error result
> > at com.netscape.cmscore.dbs.DBSSession.add(DBSSession.java:125)
> > at
com.netscape.cmscore.dbs.CertificateRepository.addCertificateRecord(CertificateRepository.java:737)
> > at com.netscape.ca.CAService.storeX509Cert(CAService.java:893)
> > at com.netscape.ca.CAService.storeX509Cert(CAService.java:579)
> > at com.netscape.ca.CAService.issueX509Cert(CAService.java:564)
> > at
com.netscape.cms.profile.common.CAEnrollProfile.execute(CAEnrollProfile.java:203)
> > at
com.netscape.cms.servlet.cert.RequestProcessor.approveRequest(RequestProcessor.java:371)
> > at
com.netscape.cms.servlet.cert.RequestProcessor.processRequest(RequestProcessor.java:173)
> > ...
> >
> > - /var/log/dirsrv/slapd-EXAMPLE-COM/access
> > ...
> > [22/Jul/2019:20:30:18.703610909 +0000] conn=15 op=44 SRCH
> > base="cn=Certificate Manager Agents,ou=groups,o=ipaca" scope=0
> > filter="(uniqueMember=uid=ipara,ou=people,o=ipaca)"
attrs="cn"
> > [22/Jul/2019:20:30:18.703958648 +0000] conn=15 op=44 RESULT err=0
> > tag=101 nentries=1 etime=0.0002262912
> > [22/Jul/2019:20:30:18.706322783 +0000] conn=14 op=2439 SRCH
> > base="cn=9980043,ou=ca,ou=requests,o=ipaca" scope=0
> > filter="(objectClass=*)" attrs=ALL
> > [22/Jul/2019:20:30:18.706916435 +0000] conn=14 op=2439 RESULT err=0
> > tag=101 nentries=1 etime=0.0020648732
> > [22/Jul/2019:20:30:18.758736256 +0000] conn=14 op=2440 SRCH
> > base="cn=9980043,ou=ca,ou=requests,o=ipaca" scope=0
> > filter="(objectClass=*)" attrs=ALL
> > [22/Jul/2019:20:30:18.759537249 +0000] conn=14 op=2440 RESULT err=0
> > tag=101 nentries=1 etime=0.0051791092
> > [22/Jul/2019:20:30:18.984013755 +0000] conn=15 op=45 SRCH
> > base="ou=People,o=ipaca" scope=2
> > filter="(description=2;268304403;CN=Certificate
> > Authority,O=EXAMPLE.COM;CN=IPA RA,O=EXAMPLE.COM)" attrs=ALL
> > [22/Jul/2019:20:30:18.984630800 +0000] conn=15 op=45 RESULT err=0
> > tag=101 nentries=1 etime=0.1719630345
> > [22/Jul/2019:20:30:18.988077577 +0000] conn=15 op=46 SRCH
> > base="ou=Groups,o=ipaca" scope=2
> > filter="(&(objectClass=groupofuniquenames)(cn=*))" attrs=ALL
> > [22/Jul/2019:20:30:18.990404518 +0000] conn=15 op=46 RESULT err=0
> > tag=101 nentries=14 etime=0.0005432147
> > [22/Jul/2019:20:30:18.994230483 +0000] conn=15 op=47 SRCH
> > base="uid=ipara,ou=People,o=ipaca" scope=0
filter="(objectClass=*)"
> > attrs=ALL
> > [22/Jul/2019:20:30:18.994648102 +0000] conn=15 op=47 RESULT err=0
> > tag=101 nentries=1 etime=0.0004001393
> > [22/Jul/2019:20:30:18.996091715 +0000] conn=15 op=48 SRCH
> > base="cn=Certificate Manager Agents,ou=groups,o=ipaca" scope=0
> > filter="(uniqueMember=uid=ipara,ou=people,o=ipaca)"
attrs="cn"
> > [22/Jul/2019:20:30:18.996470330 +0000] conn=15 op=48 RESULT err=0
> > tag=101 nentries=1 etime=0.0001510753
> > [22/Jul/2019:20:30:19.023676890 +0000] conn=14 op=2441 ADD
> > dn="cn=268304406,ou=certificateRepository,ou=ca,o=ipaca"
> > [22/Jul/2019:20:30:19.024455023 +0000] conn=14 op=2441 RESULT err=68
> > tag=105 nentries=0 etime=0.1736683576
> > [22/Jul/2019:20:30:19.037339256 +0000] conn=28692 op=5 UNBIND
> > [22/Jul/2019:20:30:19.037387249 +0000] conn=28692 op=5 fd=162 closed - U1
> > ...
> >
> >
> > Can someone shed some light on what the problem could be and what to
> > try to fix it?
> >
> > Any help is really appreciated.
> >
> > Guillermo
> >
> Hi Guillermo,
>
> It looks like it could be CA replica range conflicts resulting in
> LDAP problems. i.e. two replicas trying to assign request IDs from
> the same range; an entry (probably created by a different replica)
> already exists, and that is why the add fails.
>
> We have been seeing more and more issues lately that seem to be
> related to replica ranges. I don't yet have a theory about why, but
> it could be related to replication problems (even transient ones).
> I will write a blog post in the next day or so explaining how
> replica range assignments work. That should give you enough info to
> continue analysis of the problem. Please prod me if I haven't
> followed up before end of week.
>
> Thanks,
> Fraser