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.

Note: depending on your version, the nickname of the certificate may also be prefixed with ‘NSS Certificate DB:’. In this case, run the following command:

$ sudo certutil -K -d /etc/pki/pki-tomcat/alias -f /tmp/pwdfile.txt -n 'NSS Certificate DB: subsystemCert cert-pki-ca'

 

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!):

$ cat updatecert.ldif
dn: uid=pkidbuser,ou=people,o=ipaca
changetype: modify
replace: usercertificate
usercertificate::MII... <here put the new cert in a single line. The double colon :: is important as the format is binary>
-
replace: description
description: 2;<here put the new serial number>;CN=Certificate Authority,O=IPADOMAIN.COM;CN=CA Subsystem,O=IPADOMAIN.COM


$ ldapmodify -D "cn=directory manager" -W -f updatecert.ldif

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…)

Advertisement

19 thoughts on “Troubleshooting FreeIPA: pki-tomcatd fails to start”

  1. Thank you so much for this! It is exactly what I needed.

    Are there plans for the blog post on how to get automatic renewal to update the LDAP entry properly? Unless I am mistaken, without that part, we will face the same problem again in the future.

    Thanks!

    Like

    1. Hi,
      the issue has been fixed in selinux-policy. The problem was that certmonger pre-save and post-save command were trying to stop and start pki-tomcatd but SElinux prevented this operation. As a consequence, the end of the post-save command was not executed and this was the place where the LDAP entry update should happen.

      Like

  2. Hello,

    I’ve come across an issue where I can see some of the same symptoms above on some of our freeipa servers.

    However when trying to update the certificate blob in the LDAP to match the what is in /etc/pki/pki-tomcat/alias/ it doesn’t seem to work for unknown reason.

    I’m using a ldif file to apply the change to the userCertificate and the description sections BUT it updates the description field! I’ve tried many different combinations without any improvement.

    Any suggestions are appreciated.

    Like

      1. This is the command output followed by the .ldif file content.

        # ldapmodify -x -h localhost -p 389 -D “cn=directory manager” -w -f updatecert.ldif -v
        ldap_initializer( ldap://localhost:389 )
        replace usercertificate:
        NOT ASCII (894 bytes)
        replace description:
        2;32;CN=Certificate Authority,O=;CN=CA Subsystem,O=
        modifying entry “uid=pkidbuser,ou=people,o=ipaca”
        modify complete

        # cat updatecert.ldif
        dn: uid=pkidbuser,ou=people,o=ipaca
        changetype: modify
        replace: usercertificate
        usercertificate::MII..

        replace: description
        description: 2;32;CN=Certificate Authority,O=;CN=CA Subsystem,O=

        Like

      2. Below is some background in case I’m doing something that’s obviously isn’t going to work.

        1. I’m performing these commands in a clone that’s disconnected from the network until I establish set of steps to fix the broken servers (and avoid impacting other freeipa servers if that’s a possibility).
        2. The server clone I’m working on is not our CA renewal master, but just another master.
        3. In the actual environment we have 6 freeipa servers and 3 of them are having some issue or another preventing pki-tomcatd service starting up, including the CA renewal master.
        4. All three servers show “Could not connect to LDAP server host servername.our.domain port 636 Error netscape.ldap.LDAPException: Authentication failed (49)”
        5. Two of them have a newer certificate in LDAP but an expired cert in /etc/pki/pki-tomcat/alias
        6. CA renewal master doesn’t seem to suffer from this #5 even though the pki-tomcatd is not coming up

        What I’ve attempted so far :
        1. I’ve used below method to verify the certificate stored in /etc/pki/pki-tomcat/alias and LDAP
        # certutil -L -d /etc/pki/pki-tomcat/alias/ -n “subsystemCert cert-pki-ca” -a
        # certutil -L -d /etc/pki/pki-tomcat/alias/ -n “subsystemCert cert-pki-ca” | grep -i serial
        # ldapsearch -D “cn=directory manager” -W -b “uid=pkidbuser,ou=People,o=ipaca”

        2. Reset the time on the box to a time where /etc/pki/pki-tomcat/alias certificate is still valid.
        3. Run “ipactl start –ignore-service-failure” otherwise I can’t interact with LDAP as that service also doesn’t come up.
        4. This is the point where I’ve performed the below command to update the LDAP cert to match the older certificate in /etc/pki..
        description field gets updated but not the certificate blob.

        Like

      3. Hi,
        if you’re doing the ldapmodify operation on a disconnected replica, then the changes won’t get replicated to the other servers and it won’t fix them.
        It’s extra important to work first on the CA renewal master in order to repair him.

        What is the exact status of the CA renewal master? Are there other expired certificates (you can check with getcert list)?
        Which version of IPA is installed (if you have a recent enough version, the utility ipa-cert-fix can definitely help)?
        We can continue this investigation on freeipa-users@lists.fedorahosted.org, the community is always helpful there.

        Like

  3. Hi , I may be late in the game but when i perform the following command I get the reply
    [root@hq-idm-lxd-01 ipa]#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”
    certutil: problem listing keys: SEC_ERROR_INVALID_ARGS: security library: invalid arguments.

    Thank you for your advice
    ZS

    Like

    1. Hi,

      as written in the post, sometimes the nickname of the certificate is prefixed with ‘NSS Certificate DB:’. In this case, run the following command: $ sudo certutil -K -d /etc/pki/pki-tomcat/alias -f /tmp/pwdfile.txt -n ‘NSS Certificate DB: subsystemCert cert-pki-ca’

      HTH.

      Like

  4. Thanks , I even tried that but did not work, one thing that I noticed was that in the command.
    “ldapsearch -LLL -D ‘cn=directory manager’ -W -b uid=pkidbuser,ou=people,o=ipaca userCertificate description seeAlso” I get 3 userCertificates instead of one. but serial number is same. Do I need to delete the other 2 certs which does not match the one in the /etc/pki/pki-tomcat/alias database?

    Like

  5. Thanks you for this inciteful post. I very much appreciate the organized way it validates each step and the clarity in which it is written. We have an environment with two servers. This exact issue (pki-tomcatd service fails to start) has been occurring in our environment. and I have followed the steps to update the NSS database with the correct certificate and serial number from the ‘subsystemCert cert-pki-ca’ Cert alias, which allows the pki-tomcatd service to start, however each time I do this, the pki-tomcatd service breaks with the same issue on the other server.

    Like

  6. I have an updated to my earlier reply. I figured out the issues I was having.

    After looking at the certificate and serial numbers on each server for the “subsystemCert cert-pki-ca’ alias, I believe the key piece of information is that if you have two servers with master replicas, then there should be two userCertificate enteries in the NSS DB for uid=pkidbuser,ou=people,o=ipaca. Both entries should match what is on each server. But the Serial number in the NSS DB should match the only the ‘subsystemCert cert-pki-ca’ alias on the server that is the IPA CA renewal master.

    # certutil -d /etc/pki/pki-tomcat/alias/ -L -n ‘subsystemCert cert-pki-ca’ -a ### get cert from both servers
    # certutil -d /etc/pki/pki-tomcat/alias/ -L -n ‘subsystemCert cert-pki-ca’ | grep -i serial ### only matters for the IPA CA Renewal master server
    # ldapsearch -LLL -D ‘cn=directory manager’ -W -b uid=pkidbuser,ou=people,o=ipaca userCertificate description seeAlso ### should see 2 userCertificate entries which should match the entries from each server, the serial number should match the serial from the IPA CA Renewal master server.

    Like

    1. Hi,
      the “subsystemCert cert-pki-ca” is one of the shared certificates: it must be identical on all the IPA servers that provide the CA role. When it is renewed on one server, it normally gets automatically updated on the other servers.
      If the entry “uid=pkidbuser,ou=people,o=ipaca” contains multiple values for the userCertificate attributes, it simply means that the “subsystemCert cert-pki-ca” has been renewed and the entry contains both the first one (issued during IPA installation) and the renewed one.
      Hope this clarifies.

      Like

  7. Hi,
    if there are multiple userCertificate values in the LDAP entry uid=pkidbuser,ou=people,o=ipaca, it means that the certificate has been renewed already twice. The additional values should not cause any issue.
    What does the following command return in your case?
    $ sudo certutil -K -d /etc/pki/pki-tomcat/alias -f /tmp/pwdfile.txt

    Like

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s