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