New subject: freeipa communication to dogtag broken after certificates expired and ipa-cert-fix run

25 Nov 2019


      Several days ago  my freeipa (4.4) server was broken due to expiration of all certificates ( except ca of course). Because of in 4.4 was no such handy tool, as ipa-cert-fix, but lots of recovery methods, that I found in Google were using it, I decided to upgrade my broken freeipa to 4.5 ( by packages upgrade). Packages were installed succesfully, but automatic ipa-server-upgrade script after installation failed ( because of certificates, obviously). Then, I ran ipa-cert-fix and almost all freeipa certificates were succesfully resubmited and updated. Then, I tried to manually run ipa-server-upgrade, but it failed in the same place, as before updating certificates - on trying to communicate with dogtag. As well as I can't just start ipa (via "ipactl start"), but it works with "--force" option, and works well, except those part of ui, that shows certificates.
There is part of ipaupgrade.log, where upgrade fails:
2019-11-25T14:44:35Z DEBUG request GET https://ipa-vis.tis.rk:8443/ca/rest/account/login
2019-11-25T14:44:35Z DEBUG request body ''
2019-11-25T14:44:35Z DEBUG response status 401
2019-11-25T14:44:35Z DEBUG response headers Server: Apache-Coyote/1.1
Cache-Control: private
Expires: Thu, 01 Jan 1970 03:00:00 MSK
WWW-Authenticate: Basic realm="Certificate Authority"
Content-Type: text/html;charset=utf-8
Content-Language: en
Content-Length: 951
Date: Mon, 25 Nov 2019 14:44:35 GMT
2019-11-25T14:44:35Z DEBUG response body '<html><head><title>Apache Tomcat/7.0.76 - Error report</title><style><!--H1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} H2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} H3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} BODY {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} B {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} P {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;}A {color : black;}A.name {color : black;}HR {color : #525D76;}--></style> </head><body><h1>HTTP Status 401 - </h1><HR size="1" noshade="noshade"><p><b>type</b> Status report</p><p><b>message</b> <u></u></p><p><b>description</b> <u>This request requires HTTP authentication.</u></p><HR size="1" noshade="noshade"><h3>Apache Tomcat/7.0.76</h3></body></html>'
2019-11-25T14:44:35Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
2019-11-25T14:44:35Z DEBUG   File "/usr/lib/python2.7/site-packages/ipapython/admintool.py", line 178, in execute
    return_value = self.run()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ipa_server_upgrade.py", line 54, in run
    server.upgrade()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py", line 2146, in upgrade
    upgrade_configuration()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py", line 2018, in upgrade_configuration
    ca_enable_ldap_profile_subsystem(ca)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py", line 406, in ca_enable_ldap_profile_subsystem
    cainstance.migrate_profiles_to_ldap()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line 2027, in migrate_profiles_to_ldap
    _create_dogtag_profile(profile_id, profile_data, overwrite=False)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line 2033, in _create_dogtag_profile
    with api.Backend.ra_certprofile as profile_api:
  File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 1315, in __enter__
    raise errors.RemoteRetrieveError(reason=_('Failed to authenticate to CA REST API'))
2019-11-25T14:44:35Z DEBUG The ipa-server-upgrade command failed, exception: RemoteRetrieveError: Failed to authenticate to CA REST API
After some searching, I found that such behaviour could be caused by incompatibility of newly generated ra-agent certificate in location "/var/lib/ipa/ra-agent.pem" and LDAP database in location "uid=ipara,ou=people,o=ipaca"(userCertificate,SeeAlso,description fields), and really, there was old certificates data there. I modified these 3 fields with corresponding new values from new certificate, including correct serial number in description. Here how it looks like now:
dn: uid=ipara,ou=people,o=ipaca
userCertificate: MIIDXD...NX7U3S
description: 2;16;CN=Certificate Authority,O=TIS.RK;CN=IPA RA,O=TIS.RK
pkidbuser LDAP entry contained old "CA Subsystem" also, so I modified it too with new "CA Subsystem" certificate data.
dn: uid=pkidbuser,ou=people,o=ipaca
userCertificate:: MIIDYj...+M7J8bmRc
description: 2;14;CN=Certificate Authority,O=TIS.RK;CN=CA Subsystem,O=TIS.RK
But none helped.
Here what I see in /var/log/pki/pki-tomcat/ca/debug, when trying to show certificate detail in freeipa's ui:
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet:service() uri = /ca/agent/ca/displayBySerial
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet::service() param name='xml' value='true'
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet::service() param name='serialNumber' value='20'
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: caDisplayBySerial start to service.
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: IP: 172.19.4.2
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: AuthMgrName: certUserDBAuthMgr
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: retrieving SSL certificate
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: certUID=CN=IPA RA,O=TIS.RK
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CertUserDBAuth: started
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CertUserDBAuth: Retrieving client certificate
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CertUserDBAuth: Got client certificate
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 4
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 5
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: Authentication: client certificate found
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 5
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 6
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CertUserDBAuthentication: cannot map certificate to any userServer Internal Error
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: SignedAuditLogger: event AUTH
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet.java: renderTemplate
[25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet.java: xml parameter detected, returning xml
Before I Updated IPA RA LDAP Entry, it showed "User not found" instead of "Server Internal Error".
And in dirsrv log I see such entries, when navigating to certificate detail page:
[25/Nov/2019:17:29:41.095869943 +0300] conn=40148 fd=206 slot=206 connection from 172.19.4.2 to 172.19.4.2
[25/Nov/2019:17:29:41.098585286 +0300] conn=40148 op=0 BIND dn="" method=sasl version=3 mech=GSS-SPNEGO
[25/Nov/2019:17:29:41.103760424 +0300] conn=40148 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0005409737 dn="uid=admin,cn=users,cn=accounts,dc=tis,dc=rk"
[25/Nov/2019:17:29:41.105906742 +0300] conn=40148 op=1 SRCH base="cn=ipaconfig,cn=etc,dc=tis,dc=rk" scope=0 filter="(objectClass=*)" attrs=ALL
[25/Nov/2019:17:29:41.106795977 +0300] conn=40148 op=1 RESULT err=0 tag=101 nentries=1 etime=0.0000976075
[25/Nov/2019:17:29:41.108348488 +0300] conn=40148 op=2 SRCH base="cn=masters,cn=ipa,cn=etc,dc=tis,dc=rk" scope=2 filter="(&(objectClass=ipaConfigObject)(cn=CA))" attrs=ALL
[25/Nov/2019:17:29:41.108921046 +0300] conn=40148 op=2 RESULT err=0 tag=101 nentries=1 etime=0.0000658341
[25/Nov/2019:17:29:41.135945117 +0300] conn=27 op=13 SRCH base="ou=People,o=ipaca" scope=2 filter="(description=2;16;CN=Certificate Authority,O=TIS.RK;CN=IPA RA,O=TIS.RK)" attrs=ALL
[25/Nov/2019:17:29:41.136203891 +0300] conn=27 op=13 RESULT err=0 tag=101 nentries=1 etime=0.0000356148
[25/Nov/2019:17:29:41.142786310 +0300] conn=40148 op=3 UNBIND
[25/Nov/2019:17:29:41.142807994 +0300] conn=40148 op=3 fd=206 closed - U1
Now I am stuck at this point. I don't understand, what is wrong with dogtag, is it LDAP entry trouble or dogtags itself.
There are some errors in "getcert list" output,