[Freeipa-users] KRA Cannot Authenticate with LDAP After Replication

Thu Apr 13 02:52:30 UTC 2017

Hi,

I’m wondering if anyone might be able to help me figure out why my KRA is failing after a fairly recent installation. It's throwing exceptions about LDAP authentication that look like the following (note, I’ve truncated some of the stacks for brevity:

Apr 12 21:14:22 server[7515]: Could not connect to LDAP server host ipa-1.mydomain.com port 636 Error netscape.ldap.LDAPException: error result (49)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.makeConnection(LdapBoundConnFactory.java:205)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.getConn(LdapBoundConnFactory.java:332)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.getConn(LdapBoundConnFactory.java:295)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.dbs.DBSubsystem.hasRangeConflict(DBSubsystem.java:475)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.dbs.Repository.checkRanges(Repository.java:500)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.dbs.KeyRepository.updateKeyStatus(KeyRepository.java:189)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.dbs.KeyStatusUpdateTask.run(KeyRepository.java:604)
Apr 12 21:14:22 server[7515]:         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
...
Apr 12 21:14:22 server[7515]: Could not connect to LDAP server host ipa-1.mydomain.com port 636 Error netscape.ldap.LDAPException: error result (49)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.makeConnection(LdapBoundConnFactory.java:205)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.getConn(LdapBoundConnFactory.java:332)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.getConn(LdapBoundConnFactory.java:295)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.dbs.DBSubsystem.hasRangeConflict(DBSubsystem.java:475)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.dbs.Repository.checkRanges(Repository.java:500)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.dbs.KeyRepository.updateKeyStatus(KeyRepository.java:193)
Apr 12 21:14:22 server[7515]:         at com.netscape.cmscore.dbs.KeyStatusUpdateTask.run(KeyRepository.java:604)
...

When I restart IPA, I get the following:

Apr 12 21:18:34 server[32159]: CA is started.
Apr 12 21:18:34 server[32159]: SSLAuthenticatorWithFallback: Creating SSL authenticator with fallback
Apr 12 21:18:34 server[32159]: SSLAuthenticatorWithFallback: Setting container
Apr 12 21:18:35 server[32159]: SSLAuthenticatorWithFallback: Initializing authenticators
Apr 12 21:18:35 server[32159]: SSLAuthenticatorWithFallback: Starting authenticators
Apr 12 21:18:35 server[32159]: CMSEngine.initializePasswordStore() begins
Apr 12 21:18:35 server[32159]: CMSEngine.initializePasswordStore(): tag=internaldb
Apr 12 21:18:35 server[32159]: testLDAPConnection connecting to ipa-1.mydomain.com:636
Apr 12 21:18:35 server[32159]: testLDAPConnection: Invalid Password
Apr 12 21:18:36 server[32159]: testLDAPConnection connecting to ipa-1.mydomain.com:636
Apr 12 21:18:36 server[32159]: testLDAPConnection: Invalid Password
Apr 12 21:18:36 server[32159]: testLDAPConnection connecting to ipa-1.mydomain.com:636
Apr 12 21:18:36 server[32159]: testLDAPConnection: Invalid Password
Apr 12 21:18:36 server[32159]: CMSEngine: init(): password test execution failed: 2
Apr 12 21:18:36 server[32159]: Password test execution failed. Is the database up?
Apr 12 21:18:36 server[32159]: Password test execution failed. Is the database up?
Apr 12 21:18:36 server[32159]:         at com.netscape.cmscore.apps.CMSEngine.initializePasswordStore(CMSEngine.java:469)
Apr 12 21:18:36 server[32159]:         at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:537)
Apr 12 21:18:36 server[32159]:         at com.netscape.certsrv.apps.CMS.init(CMS.java:188)
Apr 12 21:18:36 server[32159]:         at com.netscape.certsrv.apps.CMS.start(CMS.java:1621)
Apr 12 21:18:36 server[32159]:         at com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:114)
Apr 12 21:18:36 server[32159]:         at javax.servlet.GenericServlet.init(GenericServlet.java:158)
...

If I then try to add or delete a vault, I get the following:

Apr 12 22:19:08 server[32159]: SSLAuthenticatorWithFallback: Authenticate with client certificate authentication
Apr 12 22:19:08 server[32159]: java.lang.NullPointerException
Apr 12 22:19:08 server[32159]:         at com.netscape.cms.realm.PKIRealm.authenticate(PKIRealm.java:114)
Apr 12 22:19:08 server[32159]:         at com.netscape.cms.tomcat.ProxyRealm.authenticate(ProxyRealm.java:86)
Apr 12 22:19:08 server[32159]:         at org.apache.catalina.authenticator.SSLAuthenticator.authenticate(SSLAuthenticator.java:81)
Apr 12 22:19:08 server[32159]:         at com.netscape.cms.tomcat.SSLAuthenticatorWithFallback.doSubAuthenticate(SSLAuthenticatorWithFallback.java:37)
Apr 12 22:19:08 server[32159]:         at com.netscape.cms.tomcat.AbstractPKIAuthenticator.doAuthenticate(AbstractPKIAuthenticator.java:86)
Apr 12 22:19:08 server[32159]:         at com.netscape.cms.tomcat.SSLAuthenticatorWithFallback.authenticate(SSLAuthenticatorWithFallback.java:47)
...
Apr 12 22:19:08 server[32159]: SSLAuthenticatorWithFallback: Result: false

I’ve got the following in /var/log/pki/pki-tomcat/kra/debug:

[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: Starting request checkRanges
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: Serial numbers left in range: 10000
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: Last Serial Number: 9990000
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: Serial Numbers in next range: 10000000
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: Serial Numbers available: 10010000
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: Checking for a range conflict
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: In LdapBoundConnFactory::getConn()
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: masterConn is null.
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: makeConnection: errorIfDown true
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: TCP Keep-Alive: true
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: SSL handshake happened
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: Can't create master connection in LdapBoundConnFactory::getConn! Could not connect to LDAP server host ipa-1.mydomain.com port 636 Error netscape.ldap.LDAPException: error result (49)
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: DBSubsystem: hasRangeConflict. Error while checking next range.Could not connect to LDAP server host ipa-1.mydomain.com port 636 Error netscape.ldap.LDAPException: error result (49)
[12/Apr/2017:21:14:22][KeyStatusUpdateTask]: request checkRanges done

This is IPA 4.4.4-1.fc25, installed fairly recently. I’m not sure if this is relevant, but this was installed as a new master on new infrastructure based on an old Fedora 23, IPA 4.3 master that never had a KRA. I initially replicated to a new Fedora 23 host and upgraded that host to Fedora 25 (it may have still been connected to the 4.3 master during and after the upgrade). ipa-kra-install was then run on that Fedora 25 host which was again replicated to what is now presenting this problem. I believe the KRA started up fine at that point but I didn’t thoroughly test it. I then disconnected the old Fedora 25 host and shut down the old infrastructure. I’m now running on a single master IPA node with this broken KRA problem.

Note that everything else about this installation seems to work. I wouldn’t have even really noticed if not for trying to replicate again and failing due to KRA issues.

Thanks!
— Ilya Kogan

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20170412/98744097/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 801 bytes
Desc: Message signed with OpenPGP
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20170412/98744097/attachment.sig>