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

Authentication with a SmartCard may fail when the SmartCard certificate is not linked to any IdM user, or to a user different from the one specified on the console.

In order to find which user is associated to a given SmartCard certificate, you can run the following command:

ipaclient$ ipa certmap-match cert.pem
--------------
1 user matched
--------------
 Domain: IPADOMAIN.COM
 User logins: demosc1
----------------------------
Number of entries returned 1
----------------------------

If the result is not what you were expecting, you need first to check how certificates are mapped to users.

By default, a certificate is associated to a user when the user entry contains the full certificate in its usercertificate attribute. But this behavior can be modified by defining certificate mapping rules:

ipaclient$ ipa certmaprule-find
-------------------------------------------
1 Certificate Identity Mapping Rule matched
-------------------------------------------
 Rule name: rulesmartcard
 Mapping rule: (ipacertmapdata=X509:<I>{issuer_dn}<S>{subject_dn})
 Matching rule: <ISSUER>CN=Smart Card CA,O=EXAMPLE.ORG
 Enabled: FALSE
----------------------------
Number of entries returned 1
----------------------------

Mapping with full certificate content

When the mapping is based on the full certificate content, you can check if the user entry contains the certificate:

root@ipaclient$ ipa user-show demosc1
 User login: demosc1
[...]
Certificate: MIIC...

If it is not the case, associate the certificate with the user entry using:

ipaclient$ CERT=`cat cert.pem | tail -n +2 | head -n -1 | tr -d '\r\n'`
ipaclient$ ipa user-add-cert demosc1 --certificate $CERT

Once this is done, you may need to clear sssd cache to force SSSD to reload the entries before retrying ipa certmap-match:

ipaclient$ sudo sss_cache -E

Flexible mapping with certificate identity mapping rule

When the mapping is based on certificate mapping rules, the same tool ipa certmap-match can be used to check which user entry is associated to a certificate. When the result is not what you expect, you can enable sssd domain logs by adding the following in /etc/sssd/sssd.conf on IdM master:

[domain/ipadomain.com]
...
debug_level = 9

then restart sssd with

root@ipaserver$ systemctl restart sssd

The logs will be located in /var/log/sssd/sssd_ipadomain.log.

Check that the certificate identity mapping rules are properly loaded

When sssd is restarted, it reads the mapping rules and should print the following in /var/log/sssd/sssd_ipadomain.log:

[sssd[be[ipadomain.com]]] [sss_certmap_init] (0x0040): sss_certmap initialized.
[sssd[be[ipadomain.com]]] [ipa_certmap_parse_results] (0x4000): Trying to add rule [rulesmartcard][-1][<ISSUER>CN=Smart Card CA,O=EXAMPLE.ORG][(ipacertmapdata=X509:<I>{issuer_dn!nss_x500}<S>{subject_dn!nss_x500})].

If the rule has an invalid syntax, you will see instead:

[sssd[be[ipadomain.com]]] [sss_certmap_init] (0x0040): sss_certmap initialized.
[sssd[be[ipadomain.com]]] [ipa_certmap_parse_results] (0x4000): Trying to add rule [rulesmartcard][-1][<ISSUER>CN=Smart Card CA,O=EXAMPLE.ORG][(ipacertmapdata=X509:<I>{issuer_dn!x509}<S>{subject_dn})].
[sssd[be[ipadomain.com]]] [parse_template] (0x0040): Parse template invalid.
[sssd[be[ipadomain.com]]] [parse_ldap_mapping_rule] (0x0040): Failed to add template.
[sssd[be[ipadomain.com]]] [parse_mapping_rule] (0x0040): Failed to parse LDAP mapping rule.
[sssd[be[ipadomain.com]]] [ipa_certmap_parse_results] (0x0020): sss_certmap_add_rule failed for rule [rulesmartcard], skipping. Please check for typos and if rule syntax is supported.
[sssd[be[ipadomain.com]]] [ipa_subdomains_certmap_done] (0x0040): Unable to parse certmap results [22]: Invalid argument
[sssd[be[ipadomain.com]]] [ipa_subdomains_refresh_certmap_done] (0x0020): Failed to read certificate mapping rules [22]: Invalid argument

The log shows that the rule named rulesmartcard is invalid. Check the rule (see man page for sss-certmap for the supported syntax) and fix if needed:

ipaclient$ ipa certmaprule-show rulesmartcard
 Rule name: rulesmartcard
 Mapping rule: (ipacertmapdata=X509:<I>{issuer_dn!x509}<S>{subject_dn})
 Matching rule: <ISSUER>CN=Smart Card CA,O=EXAMPLE.ORG
 Enabled: TRUE
ipaclient$ ipa certmaprule-mod rulesmartcard --maprule '(ipacertmapdata=X509:<I>{issuer_dn}<S>{subject_dn})'

Check that the matching rule corresponds to the certificate

When SSSD tries to associate the certificate to a user, it starts by finding which rule can be applied based on the matching rule (for instance rulesmartcard applies to all certificates issued by CN=Smart Card CA,O=EXAMPLE.ORG because its matching rule is <ISSUER>CN=Smart Card CA,O=EXAMPLE.ORG).

If no matching rule applies to the certificate, SSSD will not be able to associate the certificate with a user, and will display the following in /var/log/sssd/sssd_ipadomain.log:

[sssd[be[ipadomain.com]]] [sss_cert_derb64_to_ldap_filter] (0x0040): Certificate does not match matching-rules.

In this case, you need to create or modify an identity mapping rule, so that the match rule applies to your certificate. See sss-certmap man page for the supported syntax of the –matchrule option of ipa certmaprule-add command.

Check that the expected certificate identity mapping rule is used

When SSSD tries to find the user associated to the certificate, you will see the following logs in /var/log/sssd/sssd_ipadomain.log:

[sssd[be[ipadomain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x14][BE_REQ_BY_CERT][cert=MII..]
...
[sssd[be[ipadomain.com]]] [sdap_search_user_next_base] (0x0400): Searching for users with base [cn=accounts,dc=ipadomain,dc=com]
[sssd[be[ipadomain.com]]] [sdap_print_server] (0x2000): Searching 10.34.58.20:389
[sssd[be[ipadomain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(ipacertmapdata=X509:<I>O=EXAMPLE.ORG,CN=Smart Card CA<S>CN=test,O=EXAMPLE.ORG)(objectclass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=ipadomain,dc=com].
...
[sssd[be[ipadomain.com]]] [sdap_search_user_process] (0x0400): Search for users, returned 0 results.

The logs show the LDAP search performed by SSSD: IP address of the LDAP server, base and search filter. Carefully review this information and compare with what you would expect.

Check that the mapping rule defines a valid search filter

If the rule cannot be transformed to a valid search filter, you will see in /var/log/sssd/sssd_ipadomain.log:

[sssd[be[ipadomain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(ipacertmapdata=X509:<I>O=EXAMPLE.ORG,CN=Smart Card CA<S>CN=test,O=EXAMPLE.ORG(objectclass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=ipadomain,dc=com].
[...]
[sssd[be[ipadomain.com]]] [sdap_get_generic_ext_step] (0x0080): ldap_search_ext failed: Bad search filter

If it is the case, you need to fix the certmap rule using

ipaclient$ ipa certmaprule-mod rulesmartcard –maprule …

RHEL 7.4 beta is now available, delivering a new version of IPA which contains the support for Smart Card authentication. This feature allows to use a certificate contained in a SmartCard in order to login to IdM WebUI, to ssh to an IdM-enrolled host, or to login to the console or Gnome Desktop Manager of an IdM-enrolled host.

This feature is really powerful but may also seem difficult to troubleshoot. I will explain where to look for additional information when authentication fails, and how to fix the most common issues.

The information is split into posts specific to each authentication method:

• authentication to IdM WebGUI with a SmartCard
• ssh to an IdM host with a SmartCard
• authentication to the system console or Gnome Desktop Manager of an IdM host with a SmartCard
• mapping between a SmartCard certificate and an IdM user