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 [email protected] 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 [email protected] 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]: [email protected]: 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? _______________________________________________ FreeIPA-users mailing list -- [email protected] To unsubscribe send an email to [email protected] Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/[email protected] Do not reply to spam, report it: https://pagure.io/fedora-infrastructure/new_issue
