[Freeipa-users] tomcatd - Could not connect to LDAP server host

[Jack Henschel]

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-tom...

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?