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,