Hello,

we ran into an issue after an upgrade to FreeIPA 4.6.4, API_VERSION: 2.229 (using the current Docker Image Fedora 27)

The ipa-upgrade ran without issues, but pki-tomcatd is causing trouble after the upgrade.

The tomcatd system log:

0.localhost-startStop-1 - [05/Nov/2018:08:44:41 UTC] [8] [3] In Ldap (bound) connection pool to host ipa port 636, Cannot connect to LDAP server. Error: netscape.ldap.LDAPException: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) (-1)

Tomcat Debug log:

java.net.ConnectException: Connection refused (Connection refused)     at java.net.PlainSocketImpl.socketConnect(Native Method)     Could not connect to LDAP server host ipa port 636 Error netscape.ldap.LDAPException: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) (-1)     at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.makeConnection(LdapBoundConnFactory.java:205)     Internal Database Error encountered: Could not connect to LDAP server host ipa port 636 Error netscape.ldap.LDAPException: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) (-1)     at com.netscape.cmscore.dbs.DBSubsystem.init(DBSubsystem.java:689)

However, the dirsrv starts just seconds afterwards:

Nov 05 08:44:45 ipa ns-slapd[90]: [05/Nov/2018:08:44:45.159306972 +0000] - INFO - slapd_daemon - slapd started. Listening on All Interfaces port 389 for LDAP requests     Nov 05 08:44:45 ipa ns-slapd[90]: [05/Nov/2018:08:44:45.162543716 +0000] - INFO - slapd_daemon - Listening on All Interfaces port 636 for LDAPS requests     Nov 05 08:44:45 ipa systemd[1]: Started 389 Directory Server

Then, certmonger fails to start (probably trying to reach tomcatd, I assume):

Nov 05 08:45:41 ipa systemd[1]: certmonger.service: Start-post operation timed out. Stopping.     Nov 05 08:45:50 ipa server[231]: WARNING: Exception processing realm com.netscape.cms.tomcat.ProxyRealm@3b86a3a1 background process     Nov 05 08:45:50 ipa server[231]: javax.ws.rs.ServiceUnavailableException: Subsystem unavailable     Nov 05 08:45:50 ipa server[231]: at com.netscape.cms.tomcat.ProxyRealm.backgroundProcess(ProxyRealm.java:130)     Nov 05 08:45:50 ipa server[231]: at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1156)     Nov 05 08:45:50 ipa server[231]: at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5740)     Nov 05 08:45:50 ipa server[231]: at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java: 1379)     Nov 05 08:45:50 ipa server[231]: at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java: 1383)     Nov 05 08:45:50 ipa server[231]: at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1351)     Nov 05 08:45:50 ipa server[231]: at java.lang.Thread.run(Thread.java:748)     Nov 05 08:45:56 ipa systemd[1]: Failed to start Certificate monitoring and PKI enrollment.     Nov 05 08:45:56 ipa systemd[1]: certmonger.service: Unit entered failed state.     Nov 05 08:45:56 ipa systemd[1]: certmonger.service: Failed with result 'timeout'.

After that, IPA shuts down after 300 sec.

Nov 05 08:50:01 ipa systemd[1]: Stopping Kerberos 5 KDC...     Nov 05 08:50:01 ipa systemd[1]: Stopped Kerberos 5 KDC.     Nov 05 08:50:01 ipa systemd[1]: Stopping Kerberos 5 Password-changing and Administration...     Nov 05 08:50:01 ipa systemd[1]: kadmin.service: Main process exited, code=exited, status=2/INVALIDARGUMENT     Nov 05 08:50:01 ipa systemd[1]: Stopped Kerberos 5 Password-changing and Administration.     Nov 05 08:50:01 ipa systemd[1]: kadmin.service: Unit entered failed state.     Nov 05 08:50:01 ipa systemd[1]: kadmin.service: Failed with result 'exit-code'.     Nov 05 08:50:02 ipa systemd[1]: Stopping The Apache HTTP Server...     Nov 05 08:50:03 ipa systemd[1]: Stopped The Apache HTTP Server.     Nov 05 08:50:03 ipa systemd[1]: Stopping IPA Custodia Service...     Nov 05 08:50:03 ipa systemd[1]: Stopped IPA Custodia Service.     Nov 05 08:50:03 ipa ntpd[73]: ntpd exiting on signal 15 (Terminated)     Nov 05 08:50:03 ipa ntpd[73]: 127.127.1.0 local addr 127.0.0.1 ->     Nov 05 08:50:03 ipa systemd[1]: Stopping Network Time Service...     Nov 05 08:50:03 ipa systemd[1]: Stopped Network Time Service.     Nov 05 08:50:03 ipa systemd[1]: Stopped target PKI Tomcat Server.     Nov 05 08:50:03 ipa systemd[1]: Stopping PKI Tomcat Server pki-tomcat...

The error is consistent enough, it seems LDAP only comes up seconds after tomcat tries to reach it.

Nov 05 09:34:57 ipa server[231]: Internal Database Error encountered: Could not connect to LDAP server host ipa port 636 E rror netscape.ldap.LDAPException: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) (-1)     Nov 05 09:34:59 ipa ns-slapd[83]: [05/Nov/2018:09:34:59.793590657 +0000] - INFO - slapd_daemon - slapd started. Listening on All Interfaces port 389 for LDAP requests     Nov 05 09:34:59 ipa ns-slapd[83]: [05/Nov/2018:09:34:59.812565603 +0000] - INFO - slapd_daemon - Listening on All Interfaces port 636 for LDAPS requests     Nov 05 09:34:59 ipa ns-slapd[83]: [05/Nov/2018:09:34:59.814451330 +0000] - INFO - slapd_daemon - Listening on /var/run/slapd-VISION-FHG-DE.socket for LDAPI requests

Since it's not an Authentication Error, as described here: https://floblanc.wordpress.com/2017/09/11/troubleshooting-freeipa-pki-tomcat... I don't think this is an issue with the certificates. Nonetheless, I checked them and it seems fine.

When starting FreeIPA via ipactl start, however, the system starts - certmonger remains failed though. The system isn't fully functional though.

This is how we start the Container:

/usr/bin/docker run \   -h 'ipa' --net bridge -m 0b -e IPA_SERVER_IP=192.168.2.15 \  -e IPA_SERVER_HOSTNAME=ipa \  -p 80:80 \  -p 443:443 \  -p 88:88/tcp \  -p 88:88/udp \  -p 389:389 \  -p 636:636 \  -p 7389:7389 \  -p 464:464/tcp \  -p 464:464/udp \  -p 123:123 \  -p 9443:9443 \  -p 9444:9444 \  -p 9445:9445 \  -v /data/ipa:/data:Z \  -v /sys/fs/cgroup:/sys/fs/cgroup:ro \  --tmpfs /tmp --tmpfs /run --sysctl net.ipv6.conf.all.disable_ipv6=0 --cap-add=SYS_ADMIN --cap-add SYS_TIME \         --name freeipa \         freeipa/freeipa-server:fedora-27 \

Any idea what might cause this, or how we can futher debug it?