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

Attachment: signature.asc
Description: Message signed with OpenPGP

-- 
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

Reply via email to