[Freeipa-users] ipa upgrade failed

Thu Oct 1 15:28:35 UTC 2015

On Thu, Oct 01, 2015 at 05:09:23PM +0200, Martin Basti wrote:
> 
> 
> On 10/01/2015 05:03 PM, Andrew E. Bruno wrote:
> >Running CentOS 7.1.1503.
> >
> >Upgrading via yum update from:
> >
> >   ipa-server.x86_64 0:4.1.0-18.el7.centos.3
> >
> >   --to--
> >
> >   ipa-server.x86_64 0:4.1.0-18.el7.centos.4
> >
> >We have 3 replicates. Upgrading the first replicate (first-master) went
> >fine. Upgrading the second replicate failed.
> >
> >Got the following error during the update on the second replicate:
> >
> >Pre schema upgrade failed with [Errno 111] Connection refused
> >IPA upgrade failed.
> >
> >Where should I look for more info? Looked in the usual places and didn't
> >see anything out of the ordinary. How can I fix/verify the upgrade?
> >
> >Thanks!
> >
> >--Andrew
> >
> Hello,
> 
> can you check /var/log/ipaupgrade.log and /var/log/dirsrv/slapd-*/errors for
> more specific errors?

Here's the errors from /var/log/dirsrv/slapd-*/errors right around the time of the upgrade:

[01/Oct/2015:10:42:37 -0400] - slapd shutting down - signaling operation threads - op stack size 84 max work q size 59 max work q stack size 59
[01/Oct/2015:10:44:50 -0400] - Information: Non-Secure Port Disabled
[01/Oct/2015:10:44:50 -0400] - 389-Directory/1.3.3.1 B2015.218.023 starting up
[01/Oct/2015:10:44:50 -0400] - WARNING: changelog: entry cache size 512000B is less than db size 28639232B; We recommend to increase the entry cache size nsslapd-cachememsize.
[01/Oct/2015:10:44:50 -0400] - Detected Disorderly Shutdown last time Directory Server was running, recovering database.
...
tion.
[01/Oct/2015:10:45:03 -0400] NSMMReplicationPlugin - changelog program - _cl5NewDBFile: PR_DeleteSemaphore: /var/lib/dirsrv/slapd-INT-CCR-BUFFALO-EDU/cldb/9fc73292-2b0911e5-a53bd3a1-f3bbc58c.sema; NSPR error - -5943
[01/Oct/2015:10:45:08 -0400] NSMMReplicationPlugin - changelog program - _cl5NewDBFile: PR_DeleteSemaphore: /var/lib/dirsrv/slapd-INT-CCR-BUFFALO-EDU/cldb/d0a7671e-2b0911e5-a53bd3a1-f3bbc58c.sema; NSPR error - -5943
[01/Oct/2015:10:45:08 -0400] NSMMReplicationPlugin - replica_check_for_data_reload: Warning: disordely shutdown for replica o=ipaca. Check if DB RUV needs to be updated
[01/Oct/2015:10:45:08 -0400] set_krb5_creds - Could not get initial credentials for principal [ldap/srv-d13-39-02.int.ccr.buffalo.edu at INT.CCR.BUFFALO.EDU] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328324 (Generic error (see e-text))
[01/Oct/2015:10:45:08 -0400] NSMMReplicationPlugin - agmt="cn=cloneAgreement1-srv-d13-39-02.int.ccr.buffalo.edu-pki-tomcat" (srv-d13-38-02:389): Unable to acquire replica: the replica instructed us to go into backoff mode. Will retry later.
[01/Oct/2015:10:45:08 -0400] NSMMReplicationPlugin - replica_check_for_data_reload: Warning: disordely shutdown for replica dc=int,dc=ccr,dc=buffalo,dc=edu. Check if DB RUV needs to be updated
[01/Oct/2015:10:45:08 -0400] slapd_ldap_sasl_interactive_bind - Error: could not perform interactive bind for id [] mech [GSSAPI]: LDAP error -2 (Local error) (SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure.  Minor code may provide more information (No Kerberos credentials available)) errno 0 (Success)
...
[01/Oct/2015:10:45:09 -0400] DSRetroclPlugin - delete_changerecord: could not delete change record 22231 (rc: 32)
[01/Oct/2015:10:45:09 -0400] - slapd started.  Listening on /var/run/slapd-INT-CCR-BUFFALO-EDU.socket for LDAPI requests
[01/Oct/2015:10:45:09 -0400] DSRetroclPlugin - delete_changerecord: could not delete change record 22232 (rc: 32)
[01/Oct/2015:10:45:09 -0400] DSRetroclPlugin - delete_changerecord: could not delete change record 22233 (rc: 32)
[01/Oct/2015:10:45:09 -0400] DSRetroclPlugin - delete_changerecord: could not delete change record 22234 (rc: 32)
[01/Oct/2015:10:45:09 -0400] DSRetroclPlugin - delete_changerecord: could not delete change record 22235 (rc: 32)
[01/Oct/2015:10:45:09 -0400] DSRetroclPlugin - delete_changerecord: could not delete change record 22236 (rc: 32)
[01/Oct/2015:10:45:09 -0400] DSRetroclPlugin - delete_changerecord: could not delete change record 22237 (rc: 32)
[01/Oct/2015:10:45:09 -0400] DSRetroclPlugin - delete_changerecord: could not delete change record 22238 (rc: 32)
[01/Oct/2015:10:45:09 -0400] DSRetroclPlugin - delete_changerecord: could not delete change record 22239 (rc: 32)
[01/Oct/2015:10:45:09 -0400] DSRetroclPlugin - delete_changerecord: could not delete change record 22240 (rc: 32)
..

These delete_changerecord are repeated all the way to 321722.

Here's the errors from /var/log/ipaupgrade.log

2015-10-01T14:44:49Z DEBUG   [4/10]: starting directory server
2015-10-01T14:44:49Z DEBUG Starting external process
2015-10-01T14:44:49Z DEBUG args='/bin/systemctl' 'start' 'dirsrv at INT-CCR-BUFFALO-EDU.service'
2015-10-01T14:44:50Z DEBUG Process finished, return code=0
2015-10-01T14:44:50Z DEBUG stdout=
2015-10-01T14:44:50Z DEBUG stderr=
2015-10-01T14:44:50Z DEBUG   duration: 0 seconds
2015-10-01T14:44:50Z DEBUG   [5/10]: preparing server upgrade
2015-10-01T14:45:00Z ERROR Pre schema upgrade failed with [Errno 111] Connection refused
2015-10-01T14:45:00Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ipaserver/install/upgradeinstance.py", line 128, in __pre_schema_upgrade
    ld = ldapupdate.LDAPUpdate(dm_password='', ldapi=True, live_run=self.live_run, plugins=True)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ldapupdate.py", line 220, in __init__
    self.create_connection()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ldapupdate.py", line 783, in create_connection
    dm_password=self.dm_password, pw_name=self.pw_name)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ldapupdate.py", line 65, in connect
    conn.do_external_bind(pw_name)
  File "/usr/lib/python2.7/site-packages/ipapython/ipaldap.py", line 1761, in do_external_bind
    self.conn.sasl_interactive_bind_s, timeout, None, auth_tokens)
  File "/usr/lib/python2.7/site-packages/ipapython/ipaldap.py", line 1747, in __bind_with_wait
    self.__wait_for_connection(timeout)
  File "/usr/lib/python2.7/site-packages/ipapython/ipaldap.py", line 1733, in __wait_for_connection
    wait_for_open_socket(lurl.hostport, timeout)
  File "/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 1173, in wait_for_open_socket
    raise e
error: [Errno 111] Connection refused

2015-10-01T14:45:00Z DEBUG   duration: 10 seconds
2015-10-01T14:45:00Z DEBUG   [6/10]: updating schema

...

2015-10-01T14:45:43Z DEBUG   duration: 2 seconds
2015-10-01T14:45:43Z DEBUG   [9/10]: restoring configuration
2015-10-01T14:45:43Z DEBUG Saving StateFile to '/var/lib/ipa/sysrestore/sysrestore.state'
2015-10-01T14:45:43Z DEBUG Saving StateFile to '/var/lib/ipa/sysrestore/sysrestore.state'
2015-10-01T14:45:43Z DEBUG   duration: 0 seconds
2015-10-01T14:45:43Z DEBUG   [10/10]: starting directory server
2015-10-01T14:45:43Z DEBUG Starting external process
2015-10-01T14:45:43Z DEBUG args='/bin/systemctl' 'start' 'dirsrv at INT-CCR-BUFFALO-EDU.service'
2015-10-01T14:45:44Z DEBUG Process finished, return code=0
2015-10-01T14:45:44Z DEBUG stdout=
2015-10-01T14:45:44Z DEBUG stderr=
2015-10-01T14:45:44Z DEBUG Starting external process
2015-10-01T14:45:44Z DEBUG args='/bin/systemctl' 'is-active' 'dirsrv at INT-CCR-BUFFALO-EDU.service'
2015-10-01T14:45:44Z DEBUG Process finished, return code=0
2015-10-01T14:45:44Z DEBUG stdout=active

2015-10-01T14:45:44Z DEBUG stderr=
2015-10-01T14:45:44Z DEBUG wait_for_open_ports: localhost [389] timeout 300
2015-10-01T14:45:51Z DEBUG   duration: 7 seconds
2015-10-01T14:45:51Z DEBUG Done.
2015-10-01T14:45:51Z 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_ldap_updater.py", line 151, in run
    raise admintool.ScriptError('IPA upgrade failed.', 1)

2015-10-01T14:45:51Z DEBUG The ipa-ldap-updater command failed, exception: ScriptError: IPA upgrade failed.
2015-10-01T14:45:51Z ERROR IPA upgrade failed.
2015-10-01T14:45:51Z DEBUG /usr/sbin/ipa-upgradeconfig was invoked with options: {'debug': False, 'quiet': True}
2015-10-01T14:45:51Z DEBUG IPA version 4.1.0-18.el7.centos.4
2015-10-01T14:45:51Z DEBUG Loading Index file from '/var/lib/ipa/sysrestore/sysrestore.index'

...

2015-10-01T14:48:37Z DEBUG The CA status is: running
2015-10-01T14:48:37Z INFO The ipa-upgradeconfig command was successful

But from looking through the ipaupgrade.log it seems like the schema changes were in fact applied?