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 [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
