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: onBut 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
