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.
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:
- dbs.beginRequestNumber=19970001 dbs.endRequestNumber=19980000
- dbs.beginRequestNumber=19980001 dbs.endRequestNumber=19990000
- dbs.beginRequestNumber=19990001 dbs.endRequestNumber=20000000
So my questions are:
- 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-replica...
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.
- 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.
- 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
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:
- dbs.beginRequestNumber=19970001 dbs.endRequestNumber=19980000
- dbs.beginRequestNumber=19980001 dbs.endRequestNumber=19990000
- dbs.beginRequestNumber=19990001 dbs.endRequestNumber=20000000
So my questions are:
- 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-replica...
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.
- 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.
- 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
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
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
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
Yes, I've already did this in https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste....
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.
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
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
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-cor...
Thanks, Fraser
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
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
freeipa-users@lists.fedorahosted.org
-
Boris Sukhinin -
Fraser Tweedale