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…)
Florence Blanc-Renaud's technical spot 
This, and your reply at https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahosted.org/thread/ZZQKSZFHKCEY5ZVR7DOERJJQ7R7OGYB7/ helped me solve my ipa problem. Awesome! Thanks for posting your expertise!
LikeLiked by 1 person
I hit this issue today and thanks to you it has been solved.
What you did saved me a lot of time, may god bless you 🙂
LikeLiked by 1 person
Exactly the solution I needed, and I became more informed about the operations of the CA subsystem. Excellent post!
LikeLike
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!
LikeLike
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.
LikeLike
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.
LikeLike
Hi,
You can send me the ldif file you are using, along with the output of the command and I will check if there is any syntax error that could explain the failure.
LikeLiked by 1 person
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=
LikeLike
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.
LikeLike
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.
LikeLike
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
LikeLike
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.
LikeLike
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?
LikeLike
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.
LikeLike
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.
LikeLike
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.
LikeLike
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
LikeLike