Troubleshooting FreeIPA: pki-tomcatd fails to start

When performing the upgrade of FreeIPA, you may encounter an issue with pki-tomcatd failing to start. At first this issue looks related to the upgrade, but often reveals a latent problem and gets detected only because the upgrade triggers a restart of pki-tomcatd.

So how to troubleshoot this type of issue?

 

Upgrade logs

The upgrade is using /var/log/ipaupgrade.log and may contain a lot of useful information. In this specific case, I could see:

[...] DEBUG The ipa-server-upgrade command failed,
exception: ScriptError: CA did not start in 300.0s
[...] ERROR CA did not start in 300.0s
[...] ERROR The ipa-server-upgrade command failed. See
/var/log/ipaupgrade.log for more information

 

CA debug logs

The first step is to understand why pki-tomcatd refuses to start. This process is launched inside Tomcat and corresponds to the CA component of FreeIPA. It is logging into /var/log/pki/pki-tomcat/ca/debug:

[...][localhost-startStop-2]: ============================================
[...][localhost-startStop-2]: ===== DEBUG SUBSYSTEM INITIALIZED =======
[...][localhost-startStop-2]: ============================================
[...][localhost-startStop-2]: CMSEngine: restart at autoShutdown? false
[...][localhost-startStop-2]: CMSEngine: autoShutdown crumb file path? /var/lib/pki/pki-tomcat/logs/autoShutdown.crumb
[...][localhost-startStop-2]: CMSEngine: about to look for cert for auto-shutdown support:auditSigningCert cert-pki-ca
[...][localhost-startStop-2]: CMSEngine: found cert:auditSigningCert cert-pki-ca
[...][localhost-startStop-2]: CMSEngine: done init id=debug
[...][localhost-startStop-2]: CMSEngine: initialized debug
[...][localhost-startStop-2]: CMSEngine: initSubsystem id=log
[...][localhost-startStop-2]: CMSEngine: ready to init id=log
[...][localhost-startStop-2]: Creating RollingLogFile(/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit)
[...][localhost-startStop-2]: Creating RollingLogFile(/var/lib/pki/pki-tomcat/logs/ca/system)
[...][localhost-startStop-2]: Creating RollingLogFile(/var/lib/pki/pki-tomcat/logs/ca/transactions)
[...][localhost-startStop-2]: CMSEngine: restart at autoShutdown? false
[...][localhost-startStop-2]: CMSEngine: autoShutdown crumb file path? /var/lib/pki/pki-tomcat/logs/autoShutdown.crumb
[...][localhost-startStop-2]: CMSEngine: about to look for cert for auto-shutdown support:auditSigningCert cert-pki-ca
[...][localhost-startStop-2]: CMSEngine: found cert:auditSigningCert cert-pki-ca
[...][localhost-startStop-2]: CMSEngine: done init id=log
[...][localhost-startStop-2]: CMSEngine: initialized log
[...][localhost-startStop-2]: CMSEngine: initSubsystem id=jss
[...][localhost-startStop-2]: CMSEngine: ready to init id=jss
[...][localhost-startStop-2]: CMSEngine: restart at autoShutdown? false
[...][localhost-startStop-2]: CMSEngine: autoShutdown crumb file path? /var/lib/pki/pki-tomcat/logs/autoShutdown.crumb
[...][localhost-startStop-2]: CMSEngine: about to look for cert for auto-shutdown support:auditSigningCert cert-pki-ca
[...][localhost-startStop-2]: CMSEngine: found cert:auditSigningCert cert-pki-ca
[...][localhost-startStop-2]: CMSEngine: done init id=jss
[...][localhost-startStop-2]: CMSEngine: initialized jss
[...][localhost-startStop-2]: CMSEngine: initSubsystem id=dbs
[...][localhost-startStop-2]: CMSEngine: ready to init id=dbs
[...][localhost-startStop-2]: DBSubsystem: init() mEnableSerialMgmt=true
[...][localhost-startStop-2]: Creating LdapBoundConnFactor(DBSubsystem)
[...][localhost-startStop-2]: LdapBoundConnFactory: init
[...][localhost-startStop-2]: LdapBoundConnFactory:doCloning true
[...][localhost-startStop-2]: LdapAuthInfo: init()
[...][localhost-startStop-2]: LdapAuthInfo: init begins
[...][localhost-startStop-2]: LdapAuthInfo: init ends
[...][localhost-startStop-2]: init: before makeConnection errorIfDown is true
[...][localhost-startStop-2]: makeConnection: errorIfDown true
[...][localhost-startStop-2]: TCP Keep-Alive: true
[...][localhost-startStop-2]: SSLClientCertificateSelectionCB: Setting desired cert nickname to: subsystemCert cert-pki-ca
[...][localhost-startStop-2]: LdapJssSSLSocket: set client auth cert nickname subsystemCert cert-pki-ca
[...][localhost-startStop-2]: SSL handshake happened
Could not connect to LDAP server host ipaserver.ipadomain.com port 636 Error netscape.ldap.LDAPException: Authentication failed (49)
 at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.makeConnection(LdapBoundConnFactory.java:205)
 at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:166)
 at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:130)
 at com.netscape.cmscore.dbs.DBSubsystem.init(DBSubsystem.java:654)
 at com.netscape.cmscore.apps.CMSEngine.initSubsystem(CMSEngine.java:1172)
 at com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:1078)
 at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:570)
 at com.netscape.certsrv.apps.CMS.init(CMS.java:188)
 at com.netscape.certsrv.apps.CMS.start(CMS.java:1621)
 at com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:114)
 at javax.servlet.GenericServlet.init(GenericServlet.java:158)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:498)
 at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:288)
 at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
 at java.security.AccessController.doPrivileged(Native Method)
 at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
 at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:320)
 at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:175)
 at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:124)
 at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1270)
 at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1195)
 at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1085)
 at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5318)
 at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5610)
 at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:147)
 at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:899)
 at org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:133)
 at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:156)

The exception shows that LDAP authentication failed with return code 49: invalid credentials.

 

Communication between pki-tomcatd and the LDAP server

We can see that pki-tomcatd is trying to open a LDAP connection through SSL but fails to authenticate. Within FreeIPA, pki-tomcat is storing data in the 389-ds LDAP server and needs to communicate through LDAP with this server.

The configuration of this communication channel can be read in /etc/pki/pki-tomcat/ca/CS.cfg:

internaldb.ldapauth.authtype=SslClientAuth
internaldb.ldapauth.bindDN=cn=Directory Manager
internaldb.ldapauth.bindPWPrompt=internaldb
internaldb.ldapauth.clientCertNickname=subsystemCert cert-pki-ca
internaldb.ldapconn.host=ipaserver.ipadomain.com
internaldb.ldapconn.port=636
internaldb.ldapconn.secureConn

The connection is using port 636 (SSL port) with SSL Client authentication (authtype=SslClientAuth). This means that pki-tomcatd provides a user certificate to the LDAP server, and the LDAP server maps a user to this certificate in order to authenticate the communications.

Note: Authtype can either be SslClientAuth or BasicAuth (authentication with username and password).

In this case, the SSL client authentication is done with the certificate named ‘subsystemCert cert-pki-ca‘ that is stored in /etc/pki/pki-tomcat/alias. So what could be causing the authentication to fail? We need to check that the certificate is available in /etc/pki/pki-tomcat/alias and that pki-tomcat is able to use the associated private key, and that the LDAP server is able to map this certificate to a user.

 

Check the subsystemCert cert-pki-ca

The first step consists in making sure that this certificate is present in /etc/pki/pki-tomcat/alias:

$ sudo certutil -L -d /etc/pki/pki-tomcat/alias -n 'subsystemCert cert-pki-ca'
Certificate:
 Data:
 Version: 3 (0x2)
...

 

Then make sure that the private key can be read using the password found in /var/lib/pki/pki-tomcat/conf/password.conf (with the tag internal=…)

$ sudo grep internal /var/lib/pki/pki-tomcat/conf/password.conf | cut -d= -f2 > /tmp/pwdfile.txt
$ sudo certutil -K -d /etc/pki/pki-tomcat/alias -f /tmp/pwdfile.txt -n 'subsystemCert cert-pki-ca'
certutil: Checking token "NSS Certificate DB" in slot "NSS User Private Key and Certificate Services"
< 0> rsa 86a7fe00cc2a01ad085f35d4ed3e84e7b82ab4f5 subsystemCert cert-pki-ca

At this point we know that pki-tomcat is able to access the certificate and the private key. So the issue is likely to be on the LDAP server side.

 

LDAP server configuration

The LDAP configuration describes how a certificate can be mapped to a user in /etc/dirsrv/slapd-IPADOMAIN-COM/certmap.conf:

$ sudo cat /etc/dirsrv/slapd-IPADOMAIN-COM/certmap.conf 
[...]
certmap default default
[...]
default:DNComps
default:FilterComps uid
certmap ipaca CN=Certificate Authority,O=IPADOMAIN.COM
ipaca:CmapLdapAttr seeAlso
ipaca:verifycert on

This means that when the LDAP server receives an authentication request with a certificate issued by the CA CN=Certificate Authority,O=IPADOMAIN.COM, it will look for users that contain a seeAlso attribute equal to the subject of the certificate, and the user entry must contain the certificate in the usercertificate attribute (verifycert: on).

With a default config, the ‘subsystemCert cert-pki-ca‘ is mapped to the user uid=pkidbuser,ou=people,o=ipaca. So let’s compare the user entry and the certificate:

$ ldapsearch -LLL -D 'cn=directory manager' -W -b uid=pkidbuser,ou=people,o=ipaca userCertificate description seeAlso
Enter LDAP Password: 
dn: uid=pkidbuser,ou=people,o=ipaca
userCertificate:: MIID...uwab3
description: 2;4;CN=Certificate Authority,O=IPADOMAIN.COM;CN=CA Subsystem,O=IPADOMAIN.COM
seeAlso: CN=CA Subsystem,O=IPADOMAIN.COM


$ sudo certutil -L -d /etc/pki/pki-tomcat/alias -n 'subsystemCert cert-pki-ca' -a
-----BEGIN CERTIFICATE-----
MIID...e5QAR
-----END CERTIFICATE-----

The certificate in the userCertificate attribute is different from the one in the NSS database! This can also be seen by comparing the serial number with the value from the ldap entry (in description: 2;<serial>;<issuer>;<subject>):

$ sudo certutil -L -d /etc/pki/pki-tomcat/alias -n 'subsystemCert cert-pki-ca' | grep Serial
 Serial Number: 1341718541 (0x4ff9000d

This explains why pki-tomcat could not authenticate to the LDAP server. The fix consists in updating the LDAP entry with the right certificate (and do not forget to update the description attribute with the right serial number!)

But we still do not know the root cause for the inconsistency between the NSS database /etc/pki/pki-tomcat/alias and the user entry for uid=pkidbuser. This could be described in another blog post (for the impatients, the automatic renewal of the certificate failed to update the LDAP server entry…)

Advertisements