[Freeipa-users] RPM Update fails on some replicas in ipa-server-upgrade

Wed Aug 3 13:39:37 UTC 2016

On 20.07.2016 17:09, Patrick Hurrelmann wrote:
> Hi all,
>
> today I updated all of our IPA servers (CentOS 7.2) with some minor RPM
> updates, but one of the replicas failed with:
>
> RemoteRetrieveError: Gettext('Failed to authenticate to CA REST API',
> domain='ipa', localedir=None)
>
> Log excerpt (ipaupgrade.log) from this host:
> (Also available as https://paste.fedoraproject.org/392759/90042561/)
>
> 2016-07-20T08:39:10Z INFO [Migrating certificate profiles to LDAP]
> 2016-07-20T08:39:10Z DEBUG Created connection context.ldap2_79620048
> 2016-07-20T08:39:10Z DEBUG flushing
> ldapi://%2fvar%2frun%2fslapd-EXAMPLE-COM.socket from SchemaCache
> 2016-07-20T08:39:10Z DEBUG retrieving schema for SchemaCache
> url=ldapi://%2fvar%2frun%2fslapd-EXAMPLE-COM.socket
> conn=<ldap.ldapobject.SimpleLDAPObject instance at 0x6b1bcb0>
> 2016-07-20T08:39:10Z DEBUG Destroyed connection context.ldap2_79620048
> 2016-07-20T08:39:10Z DEBUG request GET
> https://ipa1.loc1.example.com:8443/ca/rest/account/login
> 2016-07-20T08:39:10Z DEBUG request body ''
> 2016-07-20T08:39:10Z DEBUG NSSConnection init ipa1.loc1.example.com
> 2016-07-20T08:39:11Z DEBUG Connecting: 1.2.3.210:0
> 2016-07-20T08:39:11Z DEBUG approved_usage = SSL Server intended_usage =
> SSL Server
> 2016-07-20T08:39:11Z DEBUG cert valid True for
> "CN=ipa1.loc1.example.com,O=Example Org,OU=CA,L=City,ST=State,C=DE"
> 2016-07-20T08:39:11Z DEBUG handshake complete, peer = 1.2.3.210:8443
> 2016-07-20T08:39:11Z DEBUG Protocol: TLS1.2
> 2016-07-20T08:39:11Z DEBUG Cipher: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
> 2016-07-20T08:39:11Z DEBUG response status 401
> 2016-07-20T08:39:11Z DEBUG response headers {'content-length': '951',
> 'content-language': 'en', 'expires': 'Thu, 01 Jan 1970 01:00:00 CET',
> 'server': 'Apache-Coyote/1.1', 'cache-control': 'private', 'date': 'Wed,
> 20 Jul 2016 08:39:11 GMT', 'content-type': 'text/html;charset=utf-8',
> 'www-authenticate': 'Basic realm="Certificate Authority"'}
> 2016-07-20T08:39:11Z DEBUG response body '<html><head><title>Apache
> Tomcat/7.0.54 - 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.54</h3></body></html>'
> 2016-07-20T08:39:11Z ERROR IPA server upgrade failed: Inspect
> /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
> 2016-07-20T08:39:11Z DEBUG   File
> "/usr/lib/python2.7/site-packages/ipapython/admintool.py", line 171, in
> execute
>     return_value = self.run()
>   File
> "/usr/lib/python2.7/site-packages/ipaserver/install/ipa_server_upgrade.py",
> line 48, in run
>     server.upgrade()
>   File
> "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py",
> line 1618, in upgrade
>     upgrade_configuration()
>   File
> "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py",
> line 1548, in upgrade_configuration
>     ca_enable_ldap_profile_subsystem(ca)
>   File
> "/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py",
> line 341, in ca_enable_ldap_profile_subsystem
>     cainstance.migrate_profiles_to_ldap(caconfig)
>   File
> "/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line
> 1868, 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
> 1874, in _create_dogtag_profile
>     with api.Backend.ra_certprofile as profile_api:
>   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py",
> line 2038, in __enter__
>     raise errors.RemoteRetrieveError(reason=_('Failed to authenticate to
> CA REST API'))
>
> 2016-07-20T08:39:11Z DEBUG The ipa-server-upgrade command failed,
> exception: RemoteRetrieveError: Gettext('Failed to authenticate to CA
> REST API', domain='ipa', localedir=None)
> 2016-07-20T08:39:11Z ERROR Unexpected error - see
> /var/log/ipaupgrade.log for details:
> RemoteRetrieveError: Gettext('Failed to authenticate to CA REST API',
> domain='ipa', localedir=None)
>
>
> And with further help from mbaste on IRC, I found the following error in
> ca debug log:
> (Also available as https://paste.fedoraproject.org/392897/02195914/)
>
> [20/Jul/2016:10:39:04][profileChangeMonitor]: BasicProfile: done init
> [20/Jul/2016:10:39:04][profileChangeMonitor]: Done Profile Creation -
> IECUserRoles
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: PKIRealm.logDebug:
> Authenticating certificate chain:
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]:
> PKIRealm.getAuditUserfromCert: certUID=CN=IPA RA, O=Example Org, OU
> =CA, L=City, ST=State, C=DE
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: PKIRealm.logDebug:  
> CN=IPA RA, O=Example Org, OU=CA, L=City,
> ST=State, C=DE
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: CertUserDBAuth: started
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: CertUserDBAuth: Retrieving
> client certificate
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: CertUserDBAuth: Got client
> certificate
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: In
> LdapBoundConnFactory::getConn()
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: masterConn is connected: false
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: makeConnection:
> errorIfDown true
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: LdapJssSSLSocket set
> client auth cert nicknamesubsystemCert cert-pki-ca
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: SSL handshake happened
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: Established LDAP
> connection with SSL client auth to ipa1.loc1.example.com:636
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: getConn: conn is connected
> false
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: Attempt to bring back down
> connection.
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: Re-animated connection:
> LDAPConnection {ldaps://ipa1.loc1.example.com:636 (2) ldapVersion:3
> bindDN:""}
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: getConn: mNumConns now 2
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: returnConn: mNumConns now 3
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: Authentication: client
> certificate found
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: In
> LdapBoundConnFactory::getConn()
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: masterConn is connected: false
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: makeConnection:
> errorIfDown true
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: LdapJssSSLSocket set
> client auth cert nicknamesubsystemCert cert-pki-ca
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: SSL handshake happened
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: Established LDAP
> connection with SSL client auth to ipa1.loc1.example.com:636
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: getConn: conn is connected
> false
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: Attempt to bring back down
> connection.
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: Re-animated connection:
> LDAPConnection {ldaps://ipa1.loc1.example.com:636 (2) ldapVersion:3
> bindDN:""}
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: getConn: mNumConns now 2
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: returnConn: mNumConns now 3
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: CertUserDBAuthentication:
> cannot map certificate to any user
> [20/Jul/2016:10:39:11][http-bio-8443-exec-4]: SignedAuditEventFactory:
> create() message=[AuditEvent=AUTH_FAIL][SubjectID=CN=IPA RA, O=Example
> Org, OU=CA, L=City, ST=State,
> C=DE][Outcome=Failure][AuthMgr=certUserDBAuthMgr][AttemptedCred=CN=IPA
> RA, O=Example Org, OU=CA, L=City, ST=State, C=DE] authentication failure
>
>
> I'm totally lost with this and cannot explain, why some replicas
> successfully updated and some failed.
> Does anyone have some ideas for further debugging and/or maybe even some
> solution or pointers to fix?
>
> Thank you very much.
>
> Kind regards
> Patrick

Update: This one got fixed. The main reason was, that certmonger somehow
lost
track of the certificates on 2 replicas and as these certificates were
automatically
renewed on the working replicas, the other 2 kept using the old/expired
certs and
broke. Fortunately the fix was quite easy. The missing ca config had to
be added
back to certmonger and the tracking for all internal certificates had to
be re-enabled:

getcert add-ca -v -c dogtag-ipa-ca-renew-agent -e
/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit

getcert start-tracking -d '/etc/pki/pki-tomcat/alias' -n
'auditSigningCert cert-pki-ca' \
  -t 'NSS Certificate DB' -P XXXX -r -c dogtag-ipa-ca-renew-agent -B
/usr/lib64/ipa/certmonger/stop_pkicad \
  -C '/usr/lib64/ipa/certmonger/renew_ca_cert "auditSigningCert
cert-pki-ca"' -v

getcert start-tracking -d '/etc/pki/pki-tomcat/alias' -n
'ocspSigningCert cert-pki-ca' \
  -t 'NSS Certificate DB' -P XXXX -r -c dogtag-ipa-ca-renew-agent -B
/usr/lib64/ipa/certmonger/stop_pkicad \
  -C '/usr/lib64/ipa/certmonger/renew_ca_cert "ocspSigningCert
cert-pki-ca"' -v

getcert start-tracking -d '/etc/pki/pki-tomcat/alias' -n 'subsystemCert
cert-pki-ca' \
  -t 'NSS Certificate DB' -P XXXX -r -c dogtag-ipa-ca-renew-agent -B
/usr/lib64/ipa/certmonger/stop_pkicad \
  -C '/usr/lib64/ipa/certmonger/renew_ca_cert "subsystemCert
cert-pki-ca"' -v

getcert start-tracking -d '/etc/pki/pki-tomcat/alias' -n 'caSigningCert
cert-pki-ca' \
  -t 'NSS Certificate DB' -P XXXX -r -c dogtag-ipa-ca-renew-agent -B
/usr/lib64/ipa/certmonger/stop_pkicad \
  -C '/usr/lib64/ipa/certmonger/renew_ca_cert "caSigningCert
cert-pki-ca"' -v

getcert start-tracking -d '/etc/httpd/alias' -n 'ipaCert' -t 'NSS
Certificate DB' \
  -p '/etc/httpd/alias/pwdfile.txt' -r -c dogtag-ipa-ca-renew-agent -B
/usr/lib64/ipa/certmonger/renew_ra_cert_pre \
  -C /usr/lib64/ipa/certmonger/renew_ra_cert -v

getcert start-tracking -d '/etc/pki/pki-tomcat/alias' -n 'Server-Cert
cert-pki-ca' \
  -t 'NSS Certificate DB' -P XXXX -r -c dogtag-ipa-renew-agent -B
/usr/lib64/ipa/certmonger/stop_pkicad \
  -C '/usr/lib64/ipa/certmonger/renew_ca_cert "Server-Cert cert-pki-ca"' -v

Maybe this is helpful for anyone facing a similar problem.

Again thx to rcrit and Crys on IRC for their support in debugging and
resolving this issue.

Kind regards
Patrick

-- 
Lobster SCM GmbH, Hindenburgstraße 15, D-82343 Pöcking
HRB 178831, Amtsgericht München
Geschäftsführer: Dr. Martin Fischer, Rolf Henrich