9:20 a.m.
I try to add a new replica to a cluster of 3 freeipa servers. 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.
/var/log/pki/pki-tomcat/ca/debug gives more info:
[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)
<...long stacktrace...>
LDAP access logs on existing server show that certificate request ID was reused. ADD
queries for request as well as for certificate have failed, but nevertheless the request
was overwritten with a third query:
[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
I can confirm that each server has its own request ID range configured in
/etc/pki/pki-tomcat/ca/CS.cfg:
1. dbs.beginRequestNumber=19970001
dbs.endRequestNumber=19980000
2. dbs.beginRequestNumber=19980001
dbs.endRequestNumber=19990000
3. dbs.beginRequestNumber=19990001
dbs.endRequestNumber=20000000
So my questions are:
1. How does PKI track request IDs and prevent their reuse?
2. Does overwriting certificate request in LDAP affect certificate renewal or have any
other negative consequences?
3. What's the best way to fix this problem? LDAP backups are available and restoring
o=ipaca is an option. Domain database rollback is not an option though.
8:29 p.m.
On Tue, Sep 15, 2020 at 02:20:49PM -0000, Boris Sukhinin via FreeIPA-users wrote:
I try to add a new replica to a cluster of 3 freeipa servers.
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.
/var/log/pki/pki-tomcat/ca/debug gives more info:
[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)
<...long stacktrace...>
LDAP access logs on existing server show that certificate request ID was reused. ADD
queries for request as well as for certificate have failed, but nevertheless the request
was overwritten with a third query:
[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
I can confirm that each server has its own request ID range configured in
/etc/pki/pki-tomcat/ca/CS.cfg:
1. dbs.beginRequestNumber=19970001
dbs.endRequestNumber=19980000
2. dbs.beginRequestNumber=19980001
dbs.endRequestNumber=19990000
3. dbs.beginRequestNumber=19990001
dbs.endRequestNumber=20000000
So my questions are:
1. How does PKI track request IDs and prevent their reuse?
There are two aspects to this. One is replica range management.
You have already checked the replica ranges so that seems OK. More
details about replica range management in this blog post[1], if you
are interested.
[1]
https://frasertweedale.github.io/blog-redhat/posts/2019-07-26-dogtag-repl...
The other aspect is VLV indices. During startup, Dogtag uses a VLV
search to find the next unused identifier in its active range. If
VLV indicies are corrupt or incomplete, it can result in this
behaviour.
2. Does overwriting certificate request in LDAP affect certificate
renewal or have any other negative consequences?
It depends on the verison of FreeIPA. Older versions used
serial-based renewal for system certificates. This can cause big
problems if there are conflicts or old requests have been
overwritten. Since freeipa-4.8.1 we perform a "fresh enrolment"
when renewing system certificates, to avoid such problems.
3. What's the best way to fix this problem? LDAP backups are
available and restoring o=ipaca is an option. Domain database
rollback is not an option though.
Next step is to stop Dogtag, rebuild VLV indices, restart Dogtag and
see if the problem went away. I'm not quite sure how to do this.
I'll reply again when I work it out - or maybe someone familiar with
DS can advise.
Thanks,
Fraser
9:37 p.m.
On Wed, Sep 16, 2020 at 11:29:05AM +1000, Fraser Tweedale via FreeIPA-users wrote:
On Tue, Sep 15, 2020 at 02:20:49PM -0000, Boris Sukhinin via
FreeIPA-users wrote:
> I try to add a new replica to a cluster of 3 freeipa servers. 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.
>
> /var/log/pki/pki-tomcat/ca/debug gives more info:
> [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)
> <...long stacktrace...>
>
> LDAP access logs on existing server show that certificate request ID was reused. ADD
queries for request as well as for certificate have failed, but nevertheless the request
was overwritten with a third query:
> [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
>
> I can confirm that each server has its own request ID range configured in
/etc/pki/pki-tomcat/ca/CS.cfg:
> 1. dbs.beginRequestNumber=19970001
> dbs.endRequestNumber=19980000
> 2. dbs.beginRequestNumber=19980001
> dbs.endRequestNumber=19990000
> 3. dbs.beginRequestNumber=19990001
> dbs.endRequestNumber=20000000
>
> So my questions are:
>
> 1. How does PKI track request IDs and prevent their reuse?
>
There are two aspects to this. One is replica range management.
You have already checked the replica ranges so that seems OK. More
details about replica range management in this blog post[1], if you
are interested.
[1]
https://frasertweedale.github.io/blog-redhat/posts/2019-07-26-dogtag-repl...
The other aspect is VLV indices. During startup, Dogtag uses a VLV
search to find the next unused identifier in its active range. If
VLV indicies are corrupt or incomplete, it can result in this
behaviour.
> 2. Does overwriting certificate request in LDAP affect certificate
> renewal or have any other negative consequences?
>
It depends on the verison of FreeIPA. Older versions used
serial-based renewal for system certificates. This can cause big
problems if there are conflicts or old requests have been
overwritten. Since freeipa-4.8.1 we perform a "fresh enrolment"
when renewing system certificates, to avoid such problems.
> 3. What's the best way to fix this problem? LDAP backups are
> available and restoring o=ipaca is an option. Domain database
> rollback is not an option though.
>
Next step is to stop Dogtag, rebuild VLV indices, restart Dogtag and
see if the problem went away. I'm not quite sure how to do this.
I'll reply again when I work it out - or maybe someone familiar with
DS can advise.
You can use the following script to reindex the VLV indices:
$ /bin/cp /usr/share/pki/ca/conf/vlvtasks.ldif .
$ sed -i "s/{instanceId}/pki-tomcat/g" vlvtasks.ldif
$ sed -i "s/{database}/ipaca/g" vlvtasks.ldif
$ ldapadd -x -D "cn=Directory Manager" -w $DM_PASS -f vlvtasks.ldif
Then wait for the task to complete successfully; check the progress
with this search:
$ ldapsearch -x -D "cn=Directory Manager" -w $DM_PASS \
-b "cn=index1160589769,cn=index,cn=tasks,cn=config"
Note that the task object is only retained for 10 seconds after the
task finishes. If you want to keep it a longer time, change the
`ttl' attribute in vlvtasks.ldif before creating the object.
After reindexing is complete, restart Dogtag.
Cheers,
Fraser
12:26 a.m.
It seems the problem is with a single replica only. Is was assigned request id range
19990001-20000000. Requests 19990001-19990008 were submitted some time ago, and requests
19990001-19990005 were overwritten in my recent attempts to install another replica. Note
that CA doesn't always overwrite the first request, it actually increments request
number, but still reusing already assigned ids.
Trying to install a replica one or two more times will solve the problem as CA will
naturally start using previously unused request ids (I'm planning to restore
overwritten requests from backup after that). But I don't like this solution because
it doesn't tell us what exactly happened, why did it happen and how to avoid it in the
future.
That being said, is there a way to verify the problem is actually with VLV indices without
submitting new requests? Running ldapsearch -LLL -x -b
"ou=ca,ou=requests,o=ipaca" -D "cn=Directory Manager" -W
"(requeststate=*)" on every replica shows all the requests 19990001-19990008.
Maybe you could point me to the exact mechanism / query / source code snippet used to
select the next request id?
Regards,
Boris
2:14 a.m.
That being said, is there a way to verify the problem is actually
with VLV indices without
submitting new requests? Running ldapsearch -LLL -x -b
"ou=ca,ou=requests,o=ipaca" -D "cn=Directory Manager" -W
"(requeststate=*)" on every replica shows all the requests 19990001-19990008.
Maybe you could point me to the exact mechanism / query / source code snippet used to
select the next request id?
I've tried to reproduce CA behaviour (as much as I could understand from source code)
with the following command:
ldapsearch -LLL -x -b "ou=ca,ou=requests,o=ipaca" -D "cn=Directory
Manager" -W -E '!vlv=5/0:0820000000' -E '!sss=requestId'
"(requeststate=*)" dn
Results are the same for every replica, 19990008 is the last submitted request id, and 81
is the actual number of certificate requests in ou=ca,ou=requests,o=ipaca:
dn: cn=19990003,ou=ca,ou=requests,o=ipaca
dn: cn=19990004,ou=ca,ou=requests,o=ipaca
dn: cn=19990005,ou=ca,ou=requests,o=ipaca
dn: cn=19990006,ou=ca,ou=requests,o=ipaca
dn: cn=19990007,ou=ca,ou=requests,o=ipaca
dn: cn=19990008,ou=ca,ou=requests,o=ipaca
# sortResult: (0) Success
# vlvResultpos=81 count=81 context= (0) Success
It seems VLV indices are fine. I'll still try to repair them in case there are no
other feasible explainations for request id reuse.
Regards,
Boris
2:52 a.m.
On Wed, Sep 16, 2020 at 05:26:14AM -0000, Boris Sukhinin via FreeIPA-users wrote:
It seems the problem is with a single replica only. Is was
assigned request id range 19990001-20000000. Requests
19990001-19990008 were submitted some time ago, and requests
19990001-19990005 were overwritten in my recent attempts to
install another replica. Note that CA doesn't always overwrite the
first request, it actually increments request number, but still
reusing already assigned ids.
Trying to install a replica one or two more times will solve the
problem as CA will naturally start using previously unused request
ids (I'm planning to restore overwritten requests from backup
after that). But I don't like this solution because it doesn't
tell us what exactly happened, why did it happen and how to avoid
it in the future.
That being said, is there a way to verify the problem is actually
with VLV indices without submitting new requests? Running
ldapsearch -LLL -x -b "ou=ca,ou=requests,o=ipaca" -D "cn=Directory
Manager" -W "(requeststate=*)" on every replica shows all the
requests 19990001-19990008. Maybe you could point me to the exact
mechanism / query / source code snippet used to select the next
request id?
Regards, Boris
Hi Boris,
Yes, performing a VLV search is a bit fiddly but you can do it like
this:
$ ldapsearch -LLL -D "cn=Directory Manager" -w $PASS -s one \
-b ou=ca,ou=requests,o=ipaca '(requeststate=*)' \
-E sss=requestId -E vlv=1/0:0820000000 requestId
This should show what, according to the VLV index, is the highest
number in the range that has been used so far. The next number to
be used will be one greater than that. (Note that there may be
an entry greater than 20000000 in the result - it can be ignored).
I would be interested to see the exact command output if you are
willing to share it. Maybe I didn't get the command or the VLV
inputs exactly correct...
Cheers,
Fraser
3 a.m.
Yes, I've already did this in
https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedoraho....
I can re-run it and share more output. What attributes are you interested in? We usually
try to not disclose hostnames, usernames, etc., but sharing other information is
completely fine.
3:14 a.m.
Yes, performing a VLV search is a bit fiddly but you can do it like
this:
$ ldapsearch -LLL -D "cn=Directory Manager" -w $PASS -s one \
-b ou=ca,ou=requests,o=ipaca '(requeststate=*)' \
-E sss=requestId -E vlv=1/0:0820000000 requestId
Yes, you were right, the problem is with VLV indices.
On two nodes query returns:
$ ldapsearch -LLL -D "cn=Directory Manager" -W -s one -b
ou=ca,ou=requests,o=ipaca '(requeststate=*)' -E sss=requestId -E
vlv=1/0:0820000000 requestId
Enter LDAP Password:
dn: cn=19990007,ou=ca,ou=requests,o=ipaca
requestId: 0819990007
dn: cn=19990008,ou=ca,ou=requests,o=ipaca
requestId: 0819990008
# sortResult: (0) Success
# vlvResultpos=81 count=81 context= (0) Success
Press [before/after(/offset/count|:value)] Enter for the next window.
^C
And on the third node it's broken:
$ ldapsearch -LLL -D "cn=Directory Manager" -W -s one -b
ou=ca,ou=requests,o=ipaca '(requeststate=*)' -E sss=requestId -E
vlv=1/0:0820000000 requestId
Enter LDAP Password:
dn: cn=19990004,ou=ca,ou=requests,o=ipaca
requestId: 0819990004
dn: cn=19990005,ou=ca,ou=requests,o=ipaca
requestId: 0819990005
# sortResult: (0) Success
# vlvResultpos=13 count=13 context= (0) Success
Press [before/after(/offset/count|:value)] Enter for the next window.
^C
I'm going to rebuild indices, then restore overwritten requests from LDAP backup, and
then try to add a new replica to the FreeIPA cluster.
Thank you very much!
Regards,
Boris
7:41 a.m.
I can confirm that rebuilding VLV solved the issue. After restoring overwritten
certificate requests from backup we were able to add new replicas to the FreeIPA cluster
without any problems.
Fraser, thank you very much, your help was extremely valuable.
Best regards,
Boris
7:33 p.m.
On Thu, Sep 17, 2020 at 12:41:37PM -0000, Boris Sukhinin via FreeIPA-users wrote:
I can confirm that rebuilding VLV solved the issue. After restoring
overwritten certificate requests from backup we were able to add new replicas to the
FreeIPA cluster without any problems.
Fraser, thank you very much, your help was extremely valuable.
Best regards,
Boris
You are welcome, Boris. I'm glad the issue is resolved.
Would you mind having a look through the DS error and access logs on
the affected system, to see if there are any clues about why the VLV
index became inconsistent?
I also wrote a blog post about this scenario:
https://frasertweedale.github.io/blog-redhat/posts/2020-09-17-dogtag-vlv-...
Thanks,
Fraser
12:02 p.m.
Would you mind having a look through the DS error and access logs on
the affected system, to see if there are any clues about why the VLV
index became inconsistent?
It seems there are no records of VLV-related errors in DS logs.
The only messages in error log that contain 'vlv' term are either
backup-related (dblayer_copyfile, dblayer_copy_directory) or about
building VLV index (ldbm_back_ldbm2index) that I initiated myself.
Didn't find any clues in access logs either, records look like regular
LDAP queries to me:
conn=130 op=11 SRCH base="ou=ca,ou=requests,o=ipaca" scope=1
filter="(requestState=*)" attrs=ALL
conn=130 op=11 SORT requestId
conn=130 op=11 VLV 5:0:0819990000 2:2 (0)
conn=130 op=11 RESULT err=0 tag=101 nentries=2 etime=0.0001728512
My only guess is that VLV index was damaged some time ago when BDB ran out
of file descriptors and panicked (which was caused by default value of
nsslapd-maxdescriptors=1024 in cn=config being too low for our setup):
ERR - libdb - BDB2520 /var/lib/dirsrv/slapd-LOCAL-DOMAIN/db/log.0000000242: log file
unreadable: Too many open files
ERR - libdb - BDB0061 PANIC: Too many open files
ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
ERR - idl_new_fetch - idl_new.c (1); server stopping as database recovery needed.
I've restored domain database from another replica but didn't do anything about
CA database which probebly was a mistake.
It feels a little worrying that logs show no signs of inconsistent VLV because
that means we're unable to monitor and fix the issue before it becomes a problem
as it happened in our case.
I also wrote a blog post about this scenario:
https://frasertweedale.github.io/blog-redhat/posts/2020-09-17-dogtag-vlv-...
That's a great post, thank you!
Regards,
Boris
1:44 a.m.
On Fri, Sep 18, 2020 at 05:02:39PM -0000, Boris Sukhinin via FreeIPA-users wrote:
> Would you mind having a look through the DS error and access
logs on
> the affected system, to see if there are any clues about why the VLV
> index became inconsistent?
It seems there are no records of VLV-related errors in DS logs.
The only messages in error log that contain 'vlv' term are either
backup-related (dblayer_copyfile, dblayer_copy_directory) or about
building VLV index (ldbm_back_ldbm2index) that I initiated myself.
Didn't find any clues in access logs either, records look like regular
LDAP queries to me:
conn=130 op=11 SRCH base="ou=ca,ou=requests,o=ipaca" scope=1
filter="(requestState=*)" attrs=ALL
conn=130 op=11 SORT requestId
conn=130 op=11 VLV 5:0:0819990000 2:2 (0)
conn=130 op=11 RESULT err=0 tag=101 nentries=2 etime=0.0001728512
My only guess is that VLV index was damaged some time ago when BDB ran out
of file descriptors and panicked (which was caused by default value of
nsslapd-maxdescriptors=1024 in cn=config being too low for our setup):
ERR - libdb - BDB2520 /var/lib/dirsrv/slapd-LOCAL-DOMAIN/db/log.0000000242: log file
unreadable: Too many open files
ERR - libdb - BDB0061 PANIC: Too many open files
ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
ERR - idl_new_fetch - idl_new.c (1); server stopping as database recovery needed.
Boris, thank you for the info. Adding Thierry (DS engineer) -
do you think it could be related?
Cheers,
Fraser
I've restored domain database from another replica but didn't
do anything about
CA database which probebly was a mistake.
It feels a little worrying that logs show no signs of inconsistent VLV because
that means we're unable to monitor and fix the issue before it becomes a problem
as it happened in our case.
> I also wrote a blog post about this scenario:
> https://frasertweedale.github.io/blog-redhat/posts/2020-09-17-dogtag-vlv-...
That's a great post, thank you!
Regards,
Boris
1298
days inactive
1311
days old
freeipa-users@lists.fedorahosted.org
11 comments
2 participants
participants (2)
-
Boris Sukhinin -
Fraser Tweedale