From oasisnejeb at gmail.com Mon Nov 25 14:48:09 2019 Content-Type: multipart/mixed; boundary="===============1226415600457776417==" MIME-Version: 1.0 From: Alexander Skobeltsin To: freeipa-users at lists.fedorahosted.org Subject: [Freeipa-users] freeipa communication to dogtag broken after certificates expired and ipa-cert-fix run Date: Mon, 25 Nov 2019 14:47:46 +0000 Message-ID: <20191125144746.6471.46801@mailman01.phx2.fedoraproject.org> --===============1226415600457776417== Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable Several days ago my freeipa (4.4) server was broken due to expiration of a= ll 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 Googl= e were using it, I decided to upgrade my broken freeipa to 4.5 ( by package= s upgrade). Packages were installed succesfully, but automatic ipa-server-u= pgrade script after installation failed ( because of certificates, obviousl= y). Then, I ran ipa-cert-fix and almost all freeipa certificates were succe= sfully resubmited and updated. Then, I tried to manually run ipa-server-upg= rade, 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=3D"Certificate Authority" Content-Type: text/html;charset=3Dutf-8 Content-Language: en Content-Length: 951 Date: Mon, 25 Nov 2019 14:44:35 GMT 2019-11-25T14:44:35Z DEBUG response body 'Apache Tomcat/= 7.0.76 - Error report

HTTP Status 401 -

type Status report

= message

description This request requires HTTP = authentication.


Apache Tomcat= /7.0.76

' 2019-11-25T14:44:35Z ERROR IPA server upgrade failed: Inspect /var/log/ipau= pgrade.log and run command ipa-server-upgrade manually. 2019-11-25T14:44:35Z DEBUG File "/usr/lib/python2.7/site-packages/ipapyth= on/admintool.py", line 178, in execute return_value =3D self.run() File "/usr/lib/python2.7/site-packages/ipaserver/install/ipa_server_upgra= de.py", line 54, in run server.upgrade() File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.p= y", line 2146, in upgrade upgrade_configuration() File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.p= y", line 2018, in upgrade_configuration ca_enable_ldap_profile_subsystem(ca) File "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.p= y", 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=3DFalse) 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=3D_('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 incomp= atibility of newly generated ra-agent certificate in location "/var/lib/ipa= /ra-agent.pem" and LDAP database in location "uid=3Dipara,ou=3Dpeople,o=3Di= paca"(userCertificate,SeeAlso,description fields), and really, there was ol= d certificates data there. I modified these 3 fields with corresponding new= values from new certificate, including correct serial number in descriptio= n. Here how it looks like now: dn: uid=3Dipara,ou=3Dpeople,o=3Dipaca userCertificate: MIIDXD...NX7U3S description: 2;16;CN=3DCertificate Authority,O=3DTIS.RK;CN=3DIPA RA,O=3DTIS= .RK pkidbuser LDAP entry contained old "CA Subsystem" also, so I modified it to= o with new "CA Subsystem" certificate data. dn: uid=3Dpkidbuser,ou=3Dpeople,o=3Dipaca userCertificate:: MIIDYj...+M7J8bmRc description: 2;14;CN=3DCertificate Authority,O=3DTIS.RK;CN=3DCA Subsystem,O= =3DTIS.RK But none helped. Here what I see in /var/log/pki/pki-tomcat/ca/debug, when trying to show ce= rtificate detail in freeipa's ui: [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet:service()= uri =3D /ca/agent/ca/displayBySerial [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet::service(= ) param name=3D'xml' value=3D'true' [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet::service(= ) param name=3D'serialNumber' value=3D'20' [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: caDispla= yBySerial 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: certUse= rDBAuthMgr [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: retrievi= ng SSL certificate [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: certUID= =3DCN=3DIPA RA,O=3DTIS.RK [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CertUserDBAuth: star= ted [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CertUserDBAuth: Retr= ieving 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 LdapBoundConnFact= ory::getConn() [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connec= ted: true [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is con= nected true [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns n= ow 4 [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConn= s now 5 [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: Authentication: clie= nt certificate found [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFact= ory::getConn() [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connec= ted: true [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is con= nected true [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns n= ow 5 [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConn= s now 6 [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CertUserDBAuthentica= tion: cannot map certificate to any userServer Internal Error [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: SignedAuditLogger: e= vent AUTH [25/Nov/2019:17:24:38][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet.java: ren= derTemplate [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=3D40148 fd=3D206 slot=3D206 con= nection from 172.19.4.2 to 172.19.4.2 [25/Nov/2019:17:29:41.098585286 +0300] conn=3D40148 op=3D0 BIND dn=3D"" met= hod=3Dsasl version=3D3 mech=3DGSS-SPNEGO [25/Nov/2019:17:29:41.103760424 +0300] conn=3D40148 op=3D0 RESULT err=3D0 t= ag=3D97 nentries=3D0 etime=3D0.0005409737 dn=3D"uid=3Dadmin,cn=3Dusers,cn= =3Daccounts,dc=3Dtis,dc=3Drk" [25/Nov/2019:17:29:41.105906742 +0300] conn=3D40148 op=3D1 SRCH base=3D"cn= =3Dipaconfig,cn=3Detc,dc=3Dtis,dc=3Drk" scope=3D0 filter=3D"(objectClass=3D= *)" attrs=3DALL [25/Nov/2019:17:29:41.106795977 +0300] conn=3D40148 op=3D1 RESULT err=3D0 t= ag=3D101 nentries=3D1 etime=3D0.0000976075 [25/Nov/2019:17:29:41.108348488 +0300] conn=3D40148 op=3D2 SRCH base=3D"cn= =3Dmasters,cn=3Dipa,cn=3Detc,dc=3Dtis,dc=3Drk" scope=3D2 filter=3D"(&(objec= tClass=3DipaConfigObject)(cn=3DCA))" attrs=3DALL [25/Nov/2019:17:29:41.108921046 +0300] conn=3D40148 op=3D2 RESULT err=3D0 t= ag=3D101 nentries=3D1 etime=3D0.0000658341 [25/Nov/2019:17:29:41.135945117 +0300] conn=3D27 op=3D13 SRCH base=3D"ou=3D= People,o=3Dipaca" scope=3D2 filter=3D"(description=3D2;16;CN=3DCertificate = Authority,O=3DTIS.RK;CN=3DIPA RA,O=3DTIS.RK)" attrs=3DALL [25/Nov/2019:17:29:41.136203891 +0300] conn=3D27 op=3D13 RESULT err=3D0 tag= =3D101 nentries=3D1 etime=3D0.0000356148 [25/Nov/2019:17:29:41.142786310 +0300] conn=3D40148 op=3D3 UNBIND [25/Nov/2019:17:29:41.142807994 +0300] conn=3D40148 op=3D3 fd=3D206 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,=20 --===============1226415600457776417==--