2:52 p.m.
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(a)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(a)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(a)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?