On 2022-09-25 12:38 a.m., TomK via FreeIPA-users wrote:
Hey Everyone!
Wondering if anyone could help nudge me along in the right direction
on this one. Getting the following on my FreeIPA master and replica:
Internal Database Error encountered: Could not connect to LDAP server
host idmipa01.nix.mds.xyz port 636 Error netscape.ldap.LDAPException:
Authentication failed (48)
Internal Database Error encountered: Could not connect to LDAP server
host idmipa02.nix.mds.xyz port 636 Error netscape.ldap.LDAPException:
Authentication failed (48)
These appeared after some power outages occurred 2-3 times and both
hosts were affected. Went over a few pages online to try to get to
the bottom of these errors on these VM's however no luck so far:
https://access.redhat.com/solutions/3081821
https://floblanc.wordpress.com/2017/09/11/troubleshooting-freeipa-pki-tomcatd-fails-to-start/
and about a dozen other pages with little luck.
Here's what I tried. First, wanted to and did kick off the following
on idmipa02:
ipa-cacert-manage renew
I've read on a few posts that command will cause the running server
to become the renewal master, so was cautious to check first:
[idmipa01]
# ipa config-show | grep 'IPA CA renewal master'
IPA CA renewal master: idmipa02.nix.mds.xyz
[idmipa02]
# ipa config-show | grep 'IPA CA renewal master'
IPA CA renewal master: idmipa02.nix.mds.xyz
Checked the certs and indeed the serial was different:
# ldapsearch -D 'cn=directory manager' -W -b
uid=pkidbuser,ou=people,o=ipaca
Enter LDAP Password:
# extended LDIF
#
# LDAPv3
# base <uid=pkidbuser,ou=people,o=ipaca> with scope subtree
# filter: (objectclass=*)
# requesting: ALL
#
# pkidbuser, people, ipaca
dn: uid=pkidbuser,ou=people,o=ipaca
userPassword:: e1NTSEE1MTJ9NUs3N......................................g4
description: 2;26;CN=Certificate Authority,O=NIX.MDS.XYZ;CN=CA
Subsystem,O=NIX
.MDS.XYZ
seeAlso: CN=CA Subsystem,O=NIX.MDS.XYZ
userCertificate:: MIIDdjCCAl6............................IYL9mJQXhHIxpc=
userCertificate:: MIIDcTCCAlmgAwIBAg.........Mdr8SvD9uWfMPwUE4Tf2csf0z+Z
userCertificate:: MIIDcTCCAlmgA..............yShSmujM9PJrJPBBjLmTCIle9Xl
userCertificate:: MIIDdDCCAlygAwIBAg......................cgDVlPYm3LmKk+
userstate: 1
usertype: agentType
mail:
cn: pkidbuser
sn: pkidbuser
uid: pkidbuser
objectClass: top
objectClass: person
objectClass: organizationalPerson
objectClass: inetOrgPerson
objectClass: cmsuser
# search result
search: 2
result: 0 Success
# numResponses: 2
# numEntries: 1
# certutil -d /etc/pki/pki-tomcat/alias/ -L -n 'subsystemCert
cert-pki-ca' -a
-----BEGIN CERTIFICATE-----
MIIDdDC..........................................dJmcMKreZ7cgDVlPYm3LmKk+
-----END CERTIFICATE-----
# certutil -d /etc/pki/pki-tomcat/alias/ -L -n 'subsystemCert
cert-pki-ca' |grep -i serial
Serial Number: 268369925 (0xfff0005)
So updated it using:
ldapmodify -x -h localhost -p 389 -D "cn=Directory Manager" -W << EOF
dn:uid=pkidbuser,ou=people,o=ipaca
changetype: modify
replace: description
description: 2;268369925;CN=Certificate Authority,O=NIX.MDS.XYZ;CN=CA
Subsystem,O=NIX.MDS.XYZ
EOF
Then verified that only the serial changed (the cert was already in
the list anyway so did not need to change) by comparing the before
and after:
# diff 1.txt 2.txt
11a12,13
> description: 2;268369925;CN=Certificate
Authority,O=NIX.MDS.XYZ;CN=CA Subsyste
> m,O=NIX.MDS.XYZ
14,15d15
< description: 2;26;CN=Certificate Authority,O=NIX.MDS.XYZ;CN=CA
Subsystem,O=NIX
< .MDS.XYZ
Confirmed trust attributes are fine:
certutil -d /etc/dirsrv/slapd-NIX-MDS-XYZ/ -L
Certificate Nickname Trust Attributes
SSL,S/MIME,JAR/XPI
Server-Cert u,u,u
NIX.MDS.XYZ IPA CA CT,C,C
Yet on restart on idmipa02, still the same issue:
# ipactl restart
Restarting Directory Service
Restarting krb5kdc Service
Restarting kadmin Service
Restarting named Service
Restarting httpd Service
Restarting ipa-custodia Service
Restarting ntpd Service
Restarting pki-tomcatd Service
Failed to restart pki-tomcatd Service
Shutting down
Hint: You can use --ignore-service-failure option for forced start in
case that a non-critical service failed
Aborting ipactl
I have dated snapshots of both servers however, they both are with
the above mentioned issue. These hosts were also offline for a
couple of months meaning cert expiration could be an issue. Likewise,
I could have caused a slight mess myself trying various online
solutions that don't always match 100%.
In regards to the certificate expiration, below are the expiration
dates for various certs though admittedly, I can't be sure of how
impacting any of these dates are since I don't yet understand the
usage of each of these certs as much as I would like to, which the
exception of the subsystemCert:
# getcert list|grep -Ei "expires|status|key pair storage"
status: CA_UNREACHABLE
key pair storage:
type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert
cert-pki-ca',token='NSS Certificate DB',pin set
expires: 2022-09-10 22:14:56 UTC
status: CA_UNREACHABLE
key pair storage:
type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='ocspSigningCert
cert-pki-ca',token='NSS Certificate DB',pin set
expires: 2022-09-10 22:13:56 UTC
status: CA_UNREACHABLE
key pair storage:
type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='subsystemCert
cert-pki-ca',token='NSS Certificate DB',pin set
expires: 2022-09-10 22:13:54 UTC
status: MONITORING
key pair storage:
type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='caSigningCert
cert-pki-ca',token='NSS Certificate DB',pin set
expires: 2036-11-21 07:32:02 UTC
status: CA_UNREACHABLE
key pair storage: type=FILE,location='/var/lib/ipa/ra-agent.key'
expires: 2022-09-21 22:13:57 UTC
status: CA_UNREACHABLE
key pair storage:
type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='Server-Cert
cert-pki-ca',token='NSS Certificate DB',pin set
expires: 2022-08-27 17:23:10 UTC
status: CA_UNREACHABLE
key pair storage:
type=NSSDB,location='/etc/dirsrv/slapd-NIX-MDS-XYZ',nickname='Server-Cert',token='NSS
Certificate DB',pinfile='/etc/dirsrv/slapd-NIX-MDS-XYZ/pwdfile.txt'
expires: 2022-09-29 17:22:58 UTC
status: CA_UNREACHABLE
key pair storage:
type=NSSDB,location='/etc/httpd/alias',nickname='Server-Cert',token='NSS
Certificate DB',pinfile='/etc/httpd/alias/pwdfile.txt'
expires: 2022-09-29 17:22:45 UTC
status: MONITORING
key pair storage:
type=FILE,location='/var/kerberos/krb5kdc/kdc.key'
expires: 2023-09-25 02:17:17 UTC
Both hosts are reachable from each other. Verified a couple of ports
to be sure. F/W is off on both, for the moment and both hosts exist
on the same VLAN.
FreeIPA Version:
# ipa --version
VERSION: 4.6.6, API_VERSION: 2.231
Plus the pki-tomcat debug log entry on restart:
# tail -f /var/log/pki/pki-tomcat/ca/debug -n 100
[25/Sep/2022:00:05:28][localhost-startStop-1]:
============================================
[25/Sep/2022:00:05:28][localhost-startStop-1]: ===== DEBUG SUBSYSTEM
INITIALIZED =======
[25/Sep/2022:00:05:28][localhost-startStop-1]:
============================================
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: restart at
autoShutdown? false
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: autoShutdown
crumb file path? /var/lib/pki/pki-tomcat/logs/autoShutdown.crumb
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: about to
look for cert for auto-shutdown support:auditSigningCert cert-pki-ca
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: found
cert:auditSigningCert cert-pki-ca
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: done init
id=debug
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: initialized
debug
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine:
initSubsystem id=log
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: ready to
init id=log
[25/Sep/2022:00:05:28][localhost-startStop-1]: Event filters:
[25/Sep/2022:00:05:28][localhost-startStop-1]: Creating
RollingLogFile(/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit)
[25/Sep/2022:00:05:28][localhost-startStop-1]: Event filters:
[25/Sep/2022:00:05:28][localhost-startStop-1]: Creating
RollingLogFile(/var/lib/pki/pki-tomcat/logs/ca/system)
[25/Sep/2022:00:05:28][localhost-startStop-1]: Event filters:
[25/Sep/2022:00:05:28][localhost-startStop-1]: Creating
RollingLogFile(/var/lib/pki/pki-tomcat/logs/ca/transactions)
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: restart at
autoShutdown? false
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: autoShutdown
crumb file path? /var/lib/pki/pki-tomcat/logs/autoShutdown.crumb
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: about to
look for cert for auto-shutdown support:auditSigningCert cert-pki-ca
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: found
cert:auditSigningCert cert-pki-ca
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: done init
id=log
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: initialized log
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine:
initSubsystem id=jss
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: ready to
init id=jss
[25/Sep/2022:00:05:28][localhost-startStop-1]: JssSubsystem:
initializing JSS subsystem
[25/Sep/2022:00:05:28][localhost-startStop-1]: JssSubsystem: enabled:
true
[25/Sep/2022:00:05:28][localhost-startStop-1]: JssSubsystem: NSS
database: /var/lib/pki/pki-tomcat/alias/
[25/Sep/2022:00:05:28][localhost-startStop-1]: JssSubsystem:
initializing CryptoManager
[25/Sep/2022:00:05:28][localhost-startStop-1]: JssSubsystem:
initializing SSL
[25/Sep/2022:00:05:28][localhost-startStop-1]: JssSubsystem: random:
[25/Sep/2022:00:05:28][localhost-startStop-1]: JssSubsystem: -
algorithm: pkcs11prng
[25/Sep/2022:00:05:28][localhost-startStop-1]: JssSubsystem: -
provider: Mozilla-JSS
[25/Sep/2022:00:05:28][localhost-startStop-1]: JssSubsystem:
initialization complete
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: restart at
autoShutdown? false
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: autoShutdown
crumb file path? /var/lib/pki/pki-tomcat/logs/autoShutdown.crumb
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: about to
look for cert for auto-shutdown support:auditSigningCert cert-pki-ca
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: found
cert:auditSigningCert cert-pki-ca
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: done init
id=jss
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: initialized jss
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine:
initSubsystem id=dbs
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine: ready to
init id=dbs
[25/Sep/2022:00:05:28][localhost-startStop-1]: DBSubsystem: init()
mEnableSerialMgmt=true
[25/Sep/2022:00:05:28][localhost-startStop-1]: Creating
LdapBoundConnFactor(DBSubsystem)
[25/Sep/2022:00:05:28][localhost-startStop-1]: LdapBoundConnFactory: init
[25/Sep/2022:00:05:28][localhost-startStop-1]:
LdapBoundConnFactory:doCloning true
[25/Sep/2022:00:05:28][localhost-startStop-1]: LdapAuthInfo: init()
[25/Sep/2022:00:05:28][localhost-startStop-1]: LdapAuthInfo: init begins
[25/Sep/2022:00:05:28][localhost-startStop-1]: LdapAuthInfo: init ends
[25/Sep/2022:00:05:28][localhost-startStop-1]: init: before
makeConnection errorIfDown is true
[25/Sep/2022:00:05:28][localhost-startStop-1]: makeConnection:
errorIfDown true
[25/Sep/2022:00:05:28][localhost-startStop-1]: TCP Keep-Alive: true
[25/Sep/2022:00:05:28][localhost-startStop-1]:
ldapconn/PKISocketFactory.makeSocket: begins
[25/Sep/2022:00:05:28][localhost-startStop-1]:
ldapconn/PKISocketFactory.makeSSLSocket: begins
[25/Sep/2022:00:05:28][localhost-startStop-1]:
SSLClientCertificateSelectionCB: Setting desired cert nickname to:
subsystemCert cert-pki-ca
[25/Sep/2022:00:05:28][localhost-startStop-1]:
ldapconn/PKISocketFactory.makeSSLSocket: set client auth cert
nickname subsystemCert cert-pki-ca
[25/Sep/2022:00:05:28][localhost-startStop-1]:
SSLClientCertificatSelectionCB: Entering!
[25/Sep/2022:00:05:28][localhost-startStop-1]: Candidate cert:
caSigningCert cert-pki-ca
[25/Sep/2022:00:05:28][localhost-startStop-1]:
SSLClientCertificateSelectionCB: returning: null
[25/Sep/2022:00:05:28][localhost-startStop-1]:
PKIClientSocketListener.handshakeCompleted: begins
[25/Sep/2022:00:05:28][localhost-startStop-1]: SignedAuditLogger:
event CLIENT_ACCESS_SESSION_ESTABLISH
[25/Sep/2022:00:05:28][localhost-startStop-1]: LogFile: event type not
selected: CLIENT_ACCESS_SESSION_ESTABLISH
[25/Sep/2022:00:05:28][localhost-startStop-1]:
PKIClientSocketListener.handshakeCompleted:
CS_CLIENT_ACCESS_SESSION_ESTABLISH_SUCCESS
[25/Sep/2022:00:05:28][localhost-startStop-1]:
PKIClientSocketListener.handshakeCompleted: clientIP=192.168.0.45
serverIP=192.168.0.45 serverPort=31746
[25/Sep/2022:00:05:28][localhost-startStop-1]: SSL handshake happened
Could not connect to LDAP server host idmipa02.nix.mds.xyz port 636
Error netscape.ldap.LDAPException: Authentication failed (48)
at
com.netscape.cmscore.ldapconn.LdapBoundConnFactory.makeConnection(LdapBoundConnFactory.java:205)
at
com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:166)
at
com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:130)
at
com.netscape.cmscore.dbs.DBSubsystem.init(DBSubsystem.java:667)
at
com.netscape.cmscore.apps.CMSEngine.initSubsystem(CMSEngine.java:1056)
at
com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:962)
at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:568)
at com.netscape.certsrv.apps.CMS.init(CMS.java:191)
at com.netscape.certsrv.apps.CMS.start(CMS.java:1458)
at
com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:117)
at javax.servlet.GenericServlet.init(GenericServlet.java:158)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:288)
at
org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
at
org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:320)
at
org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:175)
at
org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:124)
at
org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1218)
at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1174)
at
org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1066)
at
org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5377)
at
org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5669)
at
org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
at
org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:899)
at
org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:133)
at
org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:156)
at
org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:145)
at java.security.AccessController.doPrivileged(Native Method)
at
org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:873)
at
org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
at
org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:679)
at
org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1966)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Internal Database Error encountered: Could not connect to LDAP server
host idmipa02.nix.mds.xyz port 636 Error netscape.ldap.LDAPException:
Authentication failed (48)
at
com.netscape.cmscore.dbs.DBSubsystem.init(DBSubsystem.java:689)
at
com.netscape.cmscore.apps.CMSEngine.initSubsystem(CMSEngine.java:1056)
at
com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:962)
at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:568)
at com.netscape.certsrv.apps.CMS.init(CMS.java:191)
at com.netscape.certsrv.apps.CMS.start(CMS.java:1458)
at
com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:117)
at javax.servlet.GenericServlet.init(GenericServlet.java:158)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:288)
at
org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
at
org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:320)
at
org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:175)
at
org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:124)
at
org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1218)
at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1174)
at
org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1066)
at
org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5377)
at
org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5669)
at
org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
at
org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:899)
at
org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:133)
at
org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:156)
at
org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:145)
at java.security.AccessController.doPrivileged(Native Method)
at
org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:873)
at
org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
at
org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:679)
at
org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1966)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMS.start(): shutdown
server
[25/Sep/2022:00:05:28][localhost-startStop-1]: CMSEngine.shutdown()
