Header Shadow Image


DEBUG The ipa-server-upgrade command failed, exception: ScriptError: CA did not start in 300.0s

Getting this?

/var/log/ipaupgrade.log
2020-05-23T23:32:58Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
2020-05-23T23:32:58Z 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 56, in run
    raise admintool.ScriptError(str(e))

?2020-05-23T23:16:22Z DEBUG The ipa-server-upgrade command failed, exception: ScriptError: CA did not start in 300.0s
2020-05-23T23:16:22Z ERROR CA did not start in 300.0s
2020-05-23T23:16:22Z ERROR The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information

/var/log/pki/pki-tomcat/ca/debug
Could not connect to LDAP server host idmipa04.mws.mds.xyz port 636 Error netscape.ldap.LDAPException: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) (-1)

It's likely because you have the following set:

[root@idmipa04 ca]# grep -Ei "nsslapd-port|nsslapd-security" /etc/dirsrv/slapd-MWS-MDS-XYZ/dse.ldif
nsslapd-port: 0
nsslapd-security: off
[root@idmipa04 ca]#

These need to be set to:

nsslapd-port: 389
nsslapd-security: on

But this did not work.  Checking certs expiration all shows dates in the future:

[root@idmipa04 ~]# getcert list|grep expires
        expires: 2021-02-05 07:37:13 UTC
        expires: 2021-02-05 07:37:42 UTC
        expires: 2021-01-25 03:22:30 UTC
        expires: 2021-01-25 03:21:37 UTC
        expires: 2021-01-25 03:21:36 UTC
        expires: 2021-01-25 03:21:37 UTC
        expires: 2039-02-05 03:21:36 UTC
        expires: 2021-01-25 07:40:56 UTC
        expires: 2021-02-05 07:42:11 UTC
[root@idmipa04 ~]#

Lastly, check for port 636 and 389 through netstat:

[root@idmipa04 pki-tomcat]# netstat -pnltu
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      1069/sshd
tcp        0      0 0.0.0.0:88              0.0.0.0:*               LISTEN      1089/krb5kdc
tcp        0      0 127.0.0.1:25            0.0.0.0:*               LISTEN      1537/master
tcp6       0      0 :::22                   :::*                    LISTEN      1069/sshd
tcp6       0      0 :::88                   :::*                    LISTEN      1089/krb5kdc
tcp6       0      0 ::1:25                  :::*                    LISTEN      1537/master
tcp6       0      0 :::8443                 :::*                    LISTEN      16371/java
tcp6       0      0 :::443                  :::*                    LISTEN      15941/httpd
tcp6       0      0 127.0.0.1:8005          :::*                    LISTEN      16371/java
tcp6       0      0 127.0.0.1:8009          :::*                    LISTEN      16371/java
tcp6       0      0 :::8080                 :::*                    LISTEN      16371/java
tcp6       0      0 :::80                   :::*                    LISTEN      15941/httpd
udp        0      0 0.0.0.0:88              0.0.0.0:*                           1089/krb5kdc
udp6       0      0 :::88                   :::*                                1089/krb5kdc

If missing, start the directory server:

[root@idmipa04 pki-tomcat]# systemctl start dirsrv@MWS-MDS-XYZ.service

Check for the IP once started:

[root@idmipa04 pki-tomcat]# systemctl status dirsrv@MWS-MDS-XYZ.service
? dirsrv@MWS-MDS-XYZ.service – 389 Directory Server MWS-MDS-XYZ.
   Loaded: loaded (/usr/lib/systemd/system/dirsrv@.service; enabled; vendor preset: disabled)
   Active: active (running) since Sun 2020-05-24 01:44:55 EDT; 10s ago
  Process: 18618 ExecStartPre=/usr/sbin/ds_systemd_ask_password_acl /etc/dirsrv/slapd-%i/dse.ldif (code=exited, status=0/SUCCESS)
 Main PID: 18625 (ns-slapd)
   Status: "slapd started: Ready to process requests"
   CGroup: /system.slice/system-dirsrv.slice/dirsrv@MWS-MDS-XYZ.service
           ??18625 /usr/sbin/ns-slapd -D /etc/dirsrv/slapd-MWS-MDS-XYZ -i /var/run/dirsrv/slapd-MWS-…

May 24 01:44:55 idmipa04.mws.mds.xyz ns-slapd[18625]: GSSAPI client step 1
May 24 01:44:56 idmipa04.mws.mds.xyz ns-slapd[18625]: GSSAPI client step 1
May 24 01:44:56 idmipa04.mws.mds.xyz ns-slapd[18625]: GSSAPI client step 1
May 24 01:44:56 idmipa04.mws.mds.xyz ns-slapd[18625]: GSSAPI client step 2
May 24 01:44:57 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:44:57.329920836 -0400] – ERR…d.
May 24 01:44:57 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:44:57.331112434 -0400] – ERR…d.
May 24 01:45:00 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:45:00.339593970 -0400] – ERR…d.
May 24 01:45:00 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:45:00.340490104 -0400] – ERR…d.
May 24 01:45:03 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:45:03.348216609 -0400] – ERR…d.
May 24 01:45:03 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:45:03.354849567 -0400] – ERR…d.
Hint: Some lines were ellipsized, use -l to show in full.
[root@idmipa04 pki-tomcat]#

Check the ports are listening:

[root@idmipa04 pki-tomcat]# netstat -pnltu|grep 18625
tcp6       0      0 :::636                  :::*                    LISTEN      18625/ns-slapd
tcp6       0      0 :::389                  :::*                    LISTEN      18625/ns-slapd

Check the error logs for the service:

[root@idmipa04 pki-tomcat]# systemctl status dirsrv@MWS-MDS-XYZ.service -l
? dirsrv@MWS-MDS-XYZ.service – 389 Directory Server MWS-MDS-XYZ.
   Loaded: loaded (/usr/lib/systemd/system/dirsrv@.service; enabled; vendor preset: disabled)
   Active: active (running) since Sun 2020-05-24 01:44:55 EDT; 28s ago
  Process: 18618 ExecStartPre=/usr/sbin/ds_systemd_ask_password_acl /etc/dirsrv/slapd-%i/dse.ldif (code=exited, status=0/SUCCESS)
 Main PID: 18625 (ns-slapd)
   Status: "slapd started: Ready to process requests"
   CGroup: /system.slice/system-dirsrv.slice/dirsrv@MWS-MDS-XYZ.service
           ??18625 /usr/sbin/ns-slapd -D /etc/dirsrv/slapd-MWS-MDS-XYZ -i /var/run/dirsrv/slapd-MWS-MDS-XYZ.pid

May 24 01:45:09 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:45:09.372741696 -0400] – ERR – agmt="cn=caToidmipa03.mws.mds.xyz" (idmipa03:389) – clcache_load_buffer – Can't locate CSN 5c7bc2730000ffffffff in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized.
May 24 01:45:09 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:45:09.373677051 -0400] – ERR – NSMMReplicationPlugin – send_updates – agmt="cn=caToidmipa03.mws.mds.xyz" (idmipa03:389): Missing data encountered. If the error persists the replica must be reinitialized.
[root@idmipa04 pki-tomcat]#

If you see the above, reinitialize the system:

[root@idmipa04 pki-tomcat]# ipa-csreplica-manage re-initialize –from idmipa03.mws.mds.xyz
Directory Manager password:

Update in progress, 3 seconds elapsed
Update succeeded

[root@idmipa04 pki-tomcat]# systemctl status dirsrv@MWS-MDS-XYZ.service -l
? dirsrv@MWS-MDS-XYZ.service – 389 Directory Server MWS-MDS-XYZ.
   Loaded: loaded (/usr/lib/systemd/system/dirsrv@.service; enabled; vendor preset: disabled)
   Active: active (running) since Sun 2020-05-24 01:44:55 EDT; 4min 29s ago
  Process: 18618 ExecStartPre=/usr/sbin/ds_systemd_ask_password_acl /etc/dirsrv/slapd-%i/dse.ldif (code=exited, status=0/SUCCESS)
 Main PID: 18625 (ns-slapd)
   Status: "slapd started: Ready to process requests"
   CGroup: /system.slice/system-dirsrv.slice/dirsrv@MWS-MDS-XYZ.service
           ??18625 /usr/sbin/ns-slapd -D /etc/dirsrv/slapd-MWS-MDS-XYZ -i /var/run/dirsrv/slapd-MWS-MDS-XYZ.pid

May 24 01:49:15 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:49:15.687759236 -0400] – WARN – NSMMReplicationPlugin – replica_reload_ruv – New data for replica o=ipaca does not match the data in the changelog.
May 24 01:49:15 idmipa04.mws.mds.xyz ns-slapd[18625]: Recreating the changelog file. This could affect replication with replica's  consumers in which case the consumers should be reinitialized.
May 24 01:49:15 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:49:15.721328728 -0400] – ERR – cos-plugin – cos_dn_defs_cb – Skipping CoS Definition cn=Password Policy,cn=accounts,dc=mws,dc=mds,dc=xyz–no CoS Templates found, which should be added before the CoS Definition.
May 24 01:49:15 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:49:15.727578549 -0400] – NOTICE – NSMMReplicationPlugin – changelog program – _cl5ConstructRUV – Rebuilding the replication changelog RUV, this may take several minutes…
May 24 01:49:15 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:49:15.728113208 -0400] – NOTICE – NSMMReplicationPlugin – changelog program – _cl5ConstructRUV – Rebuilding replication changelog RUV complete.  Result 0 (Success)
May 24 01:49:15 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:49:15.728579987 -0400] – NOTICE – NSMMReplicationPlugin – changelog program – _cl5ConstructRUV – Rebuilding the replication changelog RUV, this may take several minutes…
May 24 01:49:15 idmipa04.mws.mds.xyz ns-slapd[18625]: [24/May/2020:01:49:15.728985312 -0400] – NOTICE – NSMMReplicationPlugin – changelog program – _cl5ConstructRUV – Rebuilding replication changelog RUV complete.  Result 0 (Success)
May 24 01:49:15 idmipa04.mws.mds.xyz ns-slapd[18625]: GSSAPI server step 1
May 24 01:49:15 idmipa04.mws.mds.xyz ns-slapd[18625]: GSSAPI server step 2
May 24 01:49:15 idmipa04.mws.mds.xyz ns-slapd[18625]: GSSAPI server step 3

[root@idmipa04 pki-tomcat]#

Your FreeIPA server should now be back up?  Let's try that and see what happens.

/var/log/ipaupgrade.log
2020-05-24T06:00:06Z DEBUG request POST http://idmipa04.mws.mds.xyz:8080/ca/admin/ca/getStatus
2020-05-24T06:00:06Z DEBUG request body ''
2020-05-24T06:00:06Z DEBUG response status 200
2020-05-24T06:00:06Z DEBUG response headers Server: Apache-Coyote/1.1
Content-Type: application/xml
Content-Length: 168
Date: Sun, 24 May 2020 06:00:06 GMT

2020-05-24T06:00:06Z DEBUG response body '<?xml version="1.0" encoding="UTF-8" standalone="no"?><XMLResponse><State>1</State><Type>CA</Type><Status>running</Status><Version>10.5.17-6.el7</Version></XMLResponse>'
2020-05-24T06:00:06Z INFO The IPA services were upgraded
2020-05-24T06:00:06Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2020-05-24T06:00:06Z DEBUG Saving StateFile to '/var/lib/ipa/sysupgrade/sysupgrade.state'
2020-05-24T06:00:06Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2020-05-24T06:00:06Z DEBUG Saving StateFile to '/var/lib/ipa/sysupgrade/sysupgrade.state'
2020-05-24T06:00:06Z INFO The ipa-server-upgrade command was successful

Confirming the command now succeeded as expected:

[root@idmipa04 pki-tomcat]# ipactl start
IPA version error: data needs to be upgraded (expected version '4.6.6-11.el7.centos', current version '4.6.4-10.el7.centos.2')
Automatically running upgrade, for details see /var/log/ipaupgrade.log
Be patient, this may take a few minutes.
Existing service file detected!
Assuming stale, cleaning and proceeding
Starting Directory Service
Starting krb5kdc Service
Starting kadmin Service
Starting named Service
Starting httpd Service
Starting ipa-custodia Service
Starting ntpd Service
Starting pki-tomcatd Service
Starting ipa-otpd Service
Starting ipa-dnskeysyncd Service
ipa: INFO: The ipactl command was successful
[root@idmipa04 pki-tomcat]#

RELATED ERRORS:

The following errors were seen alongside the above-mentioned entries.

/var/log/ipaupgrade.log
2020-05-02T12:50:40Z DEBUG The ipa-server-upgrade command failed, exception: CalledProcessError: Command '/bin/systemctl start dirsrv@MWS-MDS-XYZ.service' returned non-zero exit status 1

2020-05-23T21:07:50Z DEBUG The CA status is: check interrupted due to error: Retrieving CA status failed with status 500

/var/log/pki/pki-tomcat/localhost.2020-05-24.log
SEVERE: Exception Processing /ca/admin/ca/getStatus
javax.ws.rs.ServiceUnavailableException: Subsystem unavailable

SEVERE: Servlet.service() for servlet [Resteasy] in context with path [/ca] threw exception
org.jboss.resteasy.spi.UnhandledException: org.jboss.resteasy.core.NoMessageBodyWriterFoundFailure: Could not find MessageBodyWriter for response object of type: com.netscape.certsrv.base.PKIException$Data of media type: application/x-www-form-urlencoded

/var/log/pki/pki-tomcat/ca/debug
Could not connect to LDAP server host idmipa04.mws.mds.xyz port 636 Error netscape.ldap.LDAPException: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) (-1)

/var/log/dirsrv/slapd-MWS-MDS-XYZ/errors
[24/May/2020:01:02:41.912364232 -0400] – ERR – NSMMReplicationPlugin – send_updates – agmt="cn=caToidmipa03.mws.mds.xyz" (idmipa03:389): Missing data encountered. If the error persists the replica must be reinitialized.

[23/May/2020:00:40:23.025920441 -0400] – ERR – set_krb5_creds – Could not get initial credentials for principal [ldap/idmipa04.mws.mds.xyz@MWS.MDS.XYZ] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm)

Cheers,
TK
 


     
  Copyright © 2003 - 2013 Tom Kacperski (microdevsys.com). All rights reserved.

Creative Commons License
This work is licensed under a Creative Commons Attribution 3.0 Unported License