After postponing the my home network FreeIPA server upgrade (FreeIPA 4.7.x/Fedora 29 -> FreeIPA 4.8.x/Fedora 30) due previously running into this error already, I am running into the same error again but now want to fix it. On FreeIPA 4.7.x/Fedora 29 my set-up was judged healthy by ipa-healthcheck.
However, `ipa-server-upgrade` fails with the message "Failed to authenticate to CA REST API".
The pki-tomcatd@pki-tomcat.service log (during the upgrade) looks as follows:
``` Dec 11 21:17:16 ipa.my.domain systemd[1]: Starting PKI Tomcat Server pki-tomcat... Dec 11 21:17:16 ipa.my.domain pki-server[2405]: ---------------------------- Dec 11 21:17:16 ipa.my.domain pki-server[2405]: pki-tomcat instance migrated Dec 11 21:17:16 ipa.my.domain pki-server[2405]: ---------------------------- Dec 11 21:17:17 ipa.my.domain systemd[1]: Started PKI Tomcat Server pki-tomcat. Dec 11 21:17:17 ipa.my.domain server[2514]: Java virtual machine used: /usr/lib/jvm/jre-1.8.0-openjdk/bin/java Dec 11 21:17:17 ipa.my.domain server[2514]: classpath used: /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/lib/java/commons-daemon.jar Dec 11 21:17:17 ipa.my.domain server[2514]: main class used: org.apache.catalina.startup.Bootstrap Dec 11 21:17:17 ipa.my.domain server[2514]: flags used: -Djava.library.path=/usr/lib64/nuxwdog-jni Dec 11 21:17:17 ipa.my.domain server[2514]: options used: -Dcatalina.base=/var/lib/pki/pki-tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp -Djava.util.logging.config.file=/var/lib/pki/pki-tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.security.manager -Djava.security.policy==/var/lib/pki/pki-tomcat/conf/catalina.policy Dec 11 21:17:17 ipa.my.domain server[2514]: arguments used: start Dec 11 21:17:22 ipa.my.domain server[2514]: main: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to closed log file 0.main - [11/Dec/2022:21:17:22 CET] [14] [6] [AuditEvent=AUDIT_LOG_SHUTDOWN][SubjectID=$System$][Outcome=Success] audit function shutdown Dec 11 21:17:22 ipa.my.domain server[2514]: main: Failed to write in file: "AUDIT_LOG_SHUTDOWN", entry: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to closed log file 0.main - [11/Dec/2022:21:17:22 CET] [14] [6] [AuditEvent=AUDIT_LOG_SHUTDOWN][SubjectID=$System$][Outcome=Success] audit function shutdown, error: Audit Event Failure! Dec 11 21:17:22 ipa.my.domain server[2514]: main: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to closed log file 0.main - [11/Dec/2022:21:17:22 CET] [14] [6] [AuditEvent=AUDIT_LOG_SHUTDOWN][SubjectID=$System$][Outcome=Success] audit function shutdown Dec 11 21:17:22 ipa.my.domain server[2514]: main: Failed to write in file: "AUDIT_LOG_SHUTDOWN", entry: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to closed log file 0.main - [11/Dec/2022:21:17:22 CET] [14] [6] [AuditEvent=AUDIT_LOG_SHUTDOWN][SubjectID=$System$][Outcome=Success] audit function shutdown, error: Audit Event Failure! Dec 11 21:17:28 ipa.my.domain server[2514]: SEVERE: CA subsystem unavailable. Check CA debug log. Dec 11 21:17:33 ipa.my.domain server[2514]: SEVERE: CA subsystem unavailable. Check CA debug log. ``` after which pki-tomcatd@pki-tomcat crashes.
the pki-tomcat CA debug log has the following SEVERE exceptions:
/var/log/pki/pki-tomcat/ca/debug.2022-12-11.log ``` [...] 2022-12-11 21:17:22 [main] FINE: LdapBoundConnection: Connecting to ipa.my.domain:636 with client cert auth 2022-12-11 21:17:22 [main] FINE: ldapconn/PKISocketFactory.makeSSLSocket: begins 2022-12-11 21:17:22 [main] FINE: SignedAuditLogger: event CLIENT_ACCESS_SESSION_ESTABLISH 2022-12-11 21:17:22 [main] FINE: LogFile: event type not selected: CLIENT_ACCESS_SESSION_ESTABLISH 2022-12-11 21:17:22 [main] SEVERE: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) java.net.ConnectException: Connection refused (Connection refused) [...traceback...] 2022-12-11 21:17:22 [main] SEVERE: LdapBoundConnFactory: Unable to connect to LDAP server: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) [...traceback...] 2022-12-11 21:17:22 [main] SEVERE: DBSubsystem: initialization failed: Unable to connect to LDAP server: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) [...traceback...] 2022-12-11 21:17:22 [main] SEVERE: Unable to start CMS engine: Internal Database Error encountered: Unable to connect to LDAP serve r: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) [...traceback...] 2022-12-11 21:17:22 [main] SEVERE: Shutting down. 2022-12-11 21:17:22 [main] INFO: Shutting down CA subsystem [...] ```
Looking at the `journalctl` log, it seems the dirsrv@MY-DOMAIN.service receives a stop command during the ipa-server-upgrade script just before this error occurs.
Dec 11 21:17:19 ipa.my.domain systemd[1]: Stopping 389 Directory Server MY-DOMAIN.... Dec 11 21:17:19 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:19.575684141 +0100] - INFO - op_thread_cleanup - slapd shutting d> Dec 11 21:17:19 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:19.581818694 +0100] - INFO - slapd_daemon - slapd shutting down -> Dec 11 21:17:19 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:19.595175102 +0100] - INFO - slapd_daemon - slapd shutting down -> Dec 11 21:17:20 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:20.597957402 +0100] - INFO - dblayer_pre_close - Waiting for 4 da> Dec 11 21:17:22 ipa.my.domain server[2514]: main: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to> Dec 11 21:17:22 ipa.my.domain server[2514]: main: Failed to write in file: "AUDIT_LOG_SHUTDOWN", entry: Attempt to log message "/v> Dec 11 21:17:22 ipa.my.domain server[2514]: main: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to> Dec 11 21:17:22 ipa.my.domain server[2514]: main: Failed to write in file: "AUDIT_LOG_SHUTDOWN", entry: Attempt to log message "/v> Dec 11 21:17:22 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:22.815909751 +0100] - INFO - dblayer_pre_close - All database thr> Dec 11 21:17:22 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:22.831586103 +0100] - INFO - ldbm_back_instance_set_destructor - > Dec 11 21:17:22 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:22.851949498 +0100] - INFO - connection_post_shutdown_cleanup - s> Dec 11 21:17:22 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:22.864268380 +0100] - INFO - main - slapd stopped. Dec 11 21:17:23 ipa.my.domain systemd[1]: dirsrv@MY-DOMAIN.service: Succeeded. Dec 11 21:17:23 ipa.my.domain systemd[1]: Stopped 389 Directory Server MY-DOMAIN.. Dec 11 21:17:23 ipa.my.domain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 m> Dec 11 21:17:23 ipa.my.domain systemd[1]: Starting 389 Directory Server MY-DOMAIN....
I'm not sure how the LDAP connection is supposed to work if the LDAP server gets shut down, but since this is all handled/managed by ipa-server-upgrade, I assume this is correct...? Or is this some bug in the ipa-server-upgrade script?
Does anyone have a clue what the root cause of this error might be or how to figure it out?
Johannes Falke via FreeIPA-users wrote:
After postponing the my home network FreeIPA server upgrade (FreeIPA 4.7.x/Fedora 29 -> FreeIPA 4.8.x/Fedora 30) due previously running into this error already, I am running into the same error again but now want to fix it. On FreeIPA 4.7.x/Fedora 29 my set-up was judged healthy by ipa-healthcheck.
However, `ipa-server-upgrade` fails with the message "Failed to authenticate to CA REST API".
Seeing the upgrade debug log would be useful to see where exactly it failed.
rob
The pki-tomcatd@pki-tomcat.service log (during the upgrade) looks as follows:
Dec 11 21:17:16 ipa.my.domain systemd[1]: Starting PKI Tomcat Server pki-tomcat... Dec 11 21:17:16 ipa.my.domain pki-server[2405]: ---------------------------- Dec 11 21:17:16 ipa.my.domain pki-server[2405]: pki-tomcat instance migrated Dec 11 21:17:16 ipa.my.domain pki-server[2405]: ---------------------------- Dec 11 21:17:17 ipa.my.domain systemd[1]: Started PKI Tomcat Server pki-tomcat. Dec 11 21:17:17 ipa.my.domain server[2514]: Java virtual machine used: /usr/lib/jvm/jre-1.8.0-openjdk/bin/java Dec 11 21:17:17 ipa.my.domain server[2514]: classpath used: /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/lib/java/commons-daemon.jar Dec 11 21:17:17 ipa.my.domain server[2514]: main class used: org.apache.catalina.startup.Bootstrap Dec 11 21:17:17 ipa.my.domain server[2514]: flags used: -Djava.library.path=/usr/lib64/nuxwdog-jni Dec 11 21:17:17 ipa.my.domain server[2514]: options used: -Dcatalina.base=/var/lib/pki/pki-tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp -Djava.util.logging.config.file=/var/lib/pki/pki-tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.security.manager -Djava.security.policy==/var/lib/pki/pki-tomcat/conf/catalina.policy Dec 11 21:17:17 ipa.my.domain server[2514]: arguments used: start Dec 11 21:17:22 ipa.my.domain server[2514]: main: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to closed log file 0.main - [11/Dec/2022:21:17:22 CET] [14] [6] [AuditEvent=AUDIT_LOG_SHUTDOWN][SubjectID=$System$][Outcome=Success] audit function shutdown Dec 11 21:17:22 ipa.my.domain server[2514]: main: Failed to write in file: "AUDIT_LOG_SHUTDOWN", entry: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to closed log file 0.main - [11/Dec/2022:21:17:22 CET] [14] [6] [AuditEvent=AUDIT_LOG_SHUTDOWN][SubjectID=$System$][Outcome=Success] audit function shutdown, error: Audit Event Failure! Dec 11 21:17:22 ipa.my.domain server[2514]: main: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to closed log file 0.main - [11/Dec/2022:21:17:22 CET] [14] [6] [AuditEvent=AUDIT_LOG_SHUTDOWN][SubjectID=$System$][Outcome=Success] audit function shutdown Dec 11 21:17:22 ipa.my.domain server[2514]: main: Failed to write in file: "AUDIT_LOG_SHUTDOWN", entry: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to closed log file 0.main - [11/Dec/2022:21:17:22 CET] [14] [6] [AuditEvent=AUDIT_LOG_SHUTDOWN][SubjectID=$System$][Outcome=Success] audit function shutdown, error: Audit Event Failure! Dec 11 21:17:28 ipa.my.domain server[2514]: SEVERE: CA subsystem unavailable. Check CA debug log. Dec 11 21:17:33 ipa.my.domain server[2514]: SEVERE: CA subsystem unavailable. Check CA debug log.after which pki-tomcatd@pki-tomcat crashes.
the pki-tomcat CA debug log has the following SEVERE exceptions:
/var/log/pki/pki-tomcat/ca/debug.2022-12-11.log
[...] 2022-12-11 21:17:22 [main] FINE: LdapBoundConnection: Connecting to ipa.my.domain:636 with client cert auth 2022-12-11 21:17:22 [main] FINE: ldapconn/PKISocketFactory.makeSSLSocket: begins 2022-12-11 21:17:22 [main] FINE: SignedAuditLogger: event CLIENT_ACCESS_SESSION_ESTABLISH 2022-12-11 21:17:22 [main] FINE: LogFile: event type not selected: CLIENT_ACCESS_SESSION_ESTABLISH 2022-12-11 21:17:22 [main] SEVERE: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) java.net.ConnectException: Connection refused (Connection refused) [...traceback...] 2022-12-11 21:17:22 [main] SEVERE: LdapBoundConnFactory: Unable to connect to LDAP server: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) [...traceback...] 2022-12-11 21:17:22 [main] SEVERE: DBSubsystem: initialization failed: Unable to connect to LDAP server: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) [...traceback...] 2022-12-11 21:17:22 [main] SEVERE: Unable to start CMS engine: Internal Database Error encountered: Unable to connect to LDAP serve r: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) [...traceback...] 2022-12-11 21:17:22 [main] SEVERE: Shutting down. 2022-12-11 21:17:22 [main] INFO: Shutting down CA subsystem [...]Looking at the `journalctl` log, it seems the dirsrv@MY-DOMAIN.service receives a stop command during the ipa-server-upgrade script just before this error occurs.
Dec 11 21:17:19 ipa.my.domain systemd[1]: Stopping 389 Directory Server MY-DOMAIN.... Dec 11 21:17:19 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:19.575684141 +0100] - INFO - op_thread_cleanup - slapd shutting d> Dec 11 21:17:19 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:19.581818694 +0100] - INFO - slapd_daemon - slapd shutting down -> Dec 11 21:17:19 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:19.595175102 +0100] - INFO - slapd_daemon - slapd shutting down -> Dec 11 21:17:20 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:20.597957402 +0100] - INFO - dblayer_pre_close - Waiting for 4 da> Dec 11 21:17:22 ipa.my.domain server[2514]: main: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to> Dec 11 21:17:22 ipa.my.domain server[2514]: main: Failed to write in file: "AUDIT_LOG_SHUTDOWN", entry: Attempt to log message "/v> Dec 11 21:17:22 ipa.my.domain server[2514]: main: Attempt to log message "/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit" to> Dec 11 21:17:22 ipa.my.domain server[2514]: main: Failed to write in file: "AUDIT_LOG_SHUTDOWN", entry: Attempt to log message "/v> Dec 11 21:17:22 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:22.815909751 +0100] - INFO - dblayer_pre_close - All database thr> Dec 11 21:17:22 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:22.831586103 +0100] - INFO - ldbm_back_instance_set_destructor - > Dec 11 21:17:22 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:22.851949498 +0100] - INFO - connection_post_shutdown_cleanup - s> Dec 11 21:17:22 ipa.my.domain ns-slapd[2338]: [11/Dec/2022:21:17:22.864268380 +0100] - INFO - main - slapd stopped. Dec 11 21:17:23 ipa.my.domain systemd[1]: dirsrv@MY-DOMAIN.service: Succeeded. Dec 11 21:17:23 ipa.my.domain systemd[1]: Stopped 389 Directory Server MY-DOMAIN.. Dec 11 21:17:23 ipa.my.domain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 m> Dec 11 21:17:23 ipa.my.domain systemd[1]: Starting 389 Directory Server MY-DOMAIN....
I'm not sure how the LDAP connection is supposed to work if the LDAP server gets shut down, but since this is all handled/managed by ipa-server-upgrade, I assume this is correct...? Or is this some bug in the ipa-server-upgrade script?
Does anyone have a clue what the root cause of this error might be or how to figure it out?
Ok, thanks for being my rubber duck. I solved it while preparing an anonymized ipaupgrade.log for you.
I noticed that the failure I was looking at was actually a secondary failure after a first failed upgrade. The primary error was a result of a missing caECAdminCert.cfg (https://bugzilla.redhat.com/show_bug.cgi?id=1836806) which was apparently never patched for Fedora 29/30. Since I never saw the error message from the first failed automatic ipa-server-upgrade during/after Fedora release upgrade), I reran ipa-server-upgrade which then gave me a different error (the one I was trying to debug above).
At some point when previously trying to fix the installation after the failed upgrade, I did see the caECAdminCert.cfg message, but I had tried adding the file and re-running ipa-server-upgrade and it did not fix it. It turns out that a failed ipa-server-upgrade is not rolled back and irreparably damages the existing configuration - maybe this should be explicitly noted?
After noticing what was happening today, I rolled back to my pre-upgrade Fedora 29 snapshot, copied /usr/share/pki/ca/profiles/ca/caECAdminCert.cfg to /var/lib/pki/pki-tomcat/ca/profiles/ca/ and then ran the Fedora 29 -> 30 upgrade - something I now recall I had planned to do when I first saw that error but forgot (since I was busy excluding a real PKI/certificate error).
Best wishes, Johannes
Johannes Falke via FreeIPA-users wrote:
Ok, thanks for being my rubber duck. I solved it while preparing an anonymized ipaupgrade.log for you.
I noticed that the failure I was looking at was actually a secondary failure after a first failed upgrade. The primary error was a result of a missing caECAdminCert.cfg (https://bugzilla.redhat.com/show_bug.cgi?id=1836806) which was apparently never patched for Fedora 29/30. Since I never saw the error message from the first failed automatic ipa-server-upgrade during/after Fedora release upgrade), I reran ipa-server-upgrade which then gave me a different error (the one I was trying to debug above).
At some point when previously trying to fix the installation after the failed upgrade, I did see the caECAdminCert.cfg message, but I had tried adding the file and re-running ipa-server-upgrade and it did not fix it. It turns out that a failed ipa-server-upgrade is not rolled back and irreparably damages the existing configuration - maybe this should be explicitly noted?
After noticing what was happening today, I rolled back to my pre-upgrade Fedora 29 snapshot, copied /usr/share/pki/ca/profiles/ca/caECAdminCert.cfg to /var/lib/pki/pki-tomcat/ca/profiles/ca/ and then ran the Fedora 29 -> 30 upgrade - something I now recall I had planned to do when I first saw that error but forgot (since I was busy excluding a real PKI/certificate error).
That's great, I'm glad you got it fixed. Thanks for following up with the solution.
rob
freeipa-users@lists.fedorahosted.org
-
Johannes Falke -
Rob Crittenden