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

Wed Jul 20 15:09:31 UTC 2016

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

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