Hi,


On Thu, Jul 1, 2021 at 6:19 PM Tiemen Ruiten via FreeIPA-users <freeipa-users@lists.fedorahosted.org> wrote:
Hello,

On a newly installed CentOS 8 IPA master (a few days ago), the pki-tomcatd@pki-tomcat service fails to start and logs LDAP authentication failed (48) in /var/log/pki/pki-tomcat/ca/debug.2021-07-01.log. See below. This happened after I dnf upgraded the master and replica at the same time, my mistake. 

I've gone through the troubleshooting steps described here: https://floblanc.wordpress.com/2017/09/11/troubleshooting-freeipa-pki-tomcatd-fails-to-start/ but all certificates appear to be correct. 

What else can I do?

RPM versions:
[root@ipa-01 ca]# rpm -qa | grep ipa
ipa-healthcheck-0.7-3.module_el8.5.0+750+c59b186b.noarch
python3-libipa_hbac-2.4.0-9.el8_4.1.x86_64
sssd-ipa-2.4.0-9.el8_4.1.x86_64
python3-ipalib-4.9.2-4.module_el8.4.0+846+96522ed7.noarch
ipa-server-trust-ad-4.9.2-4.module_el8.4.0+846+96522ed7.x86_64
centos-logos-ipa-85.8-1.el8.noarch
ipa-healthcheck-core-0.7-3.module_el8.5.0+750+c59b186b.noarch
ipa-client-common-4.9.2-4.module_el8.4.0+846+96522ed7.noarch
ipa-selinux-4.9.2-4.module_el8.4.0+846+96522ed7.noarch
ipa-server-4.9.2-4.module_el8.4.0+846+96522ed7.x86_64
python3-ipaclient-4.9.2-4.module_el8.4.0+846+96522ed7.noarch
python3-ipaserver-4.9.2-4.module_el8.4.0+846+96522ed7.noarch
ipa-server-common-4.9.2-4.module_el8.4.0+846+96522ed7.noarch
libipa_hbac-2.4.0-9.el8_4.1.x86_64
ipa-common-4.9.2-4.module_el8.4.0+846+96522ed7.noarch
ipa-server-dns-4.9.2-4.module_el8.4.0+846+96522ed7.noarch
ipa-client-4.9.2-4.module_el8.4.0+846+96522ed7.x86_64


<...>
2021-07-01 17:28:20 [main] INFO: CMSEngine: initializing password store
2021-07-01 17:28:20 [main] INFO: CMSEngine: initializing password store for internaldb
2021-07-01 17:28:20 [main] INFO: CMSEngine: initializing password store for replicationdb
2021-07-01 17:28:20 [main] INFO: CMSEngine: Java version: 1.8.0_292
2021-07-01 17:28:20 [main] INFO: CMSEngine: security providers:
2021-07-01 17:28:20 [main] INFO: PluginRegistry: Loading plugin registry from /var/lib/pki/pki-tomcat/conf/ca/registry.cfg
2021-07-01 17:28:21 [main] SEVERE: LdapBoundConnFactory: Unable to connect to LDAP server: Authentication failed
netscape.ldap.LDAPException: Authentication failed (48)
        at netscape.ldap.LDAPSaslBind.checkForSASLBindCompletion(Unknown Source)
        at netscape.ldap.LDAPSaslBind.bind(Unknown Source)
        at netscape.ldap.LDAPSaslBind.bind(Unknown Source)
        at netscape.ldap.LDAPConnection.authenticate(Unknown Source)
        at netscape.ldap.LDAPConnection.authenticate(Unknown Source)
        at netscape.ldap.LDAPConnection.checkClientAuth(Unknown Source)
        at netscape.ldap.LDAPConnection.connect(Unknown Source)
        at netscape.ldap.LDAPConnection.connect(Unknown Source)
        at netscape.ldap.LDAPConnection.connect(Unknown Source)
        at com.netscape.cmscore.ldapconn.LdapBoundConnection.<init>(LdapBoundConnection.java:105)
        at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.makeConnection(LdapBoundConnFactory.java:284)
        at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:260)
        at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:223)
        at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:192)
        at org.dogtagpki.server.ca.CAEngine.initDatabase(CAEngine.java:186)
        at com.netscape.cmscore.apps.CMSEngine.start(CMSEngine.java:1002)
        at com.netscape.cmscore.apps.CMSEngine.contextInitialized(CMSEngine.java:1643)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4685)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5146)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:717)
        at org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:129)
        at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:150)
        at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:140)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:688)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:705)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:631)
        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1831)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
        at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:526)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:425)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1576)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:309)
        at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
        at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:423)
        at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:366)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:936)
        at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:841)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1384)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1374)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:909)
        at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:262)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.StandardService.startInternal(StandardService.java:421)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:930)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:633)
        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.startup.Bootstrap.start(Bootstrap.java:343)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:474)
<...>

I reproduced the issue you're seeing.
In the access log of 389-ds-base I see the following:
[02/Jul/2021:10:35:17.492672461 +0000] conn=14 fd=67 slot=67 SSL connection from 192.168.122.134 to 192.168.122.134
[02/Jul/2021:10:35:18.067123102 +0000] conn=14 SSL failed to obtain channel info; Netscape Portable Runtime error -8187 (security library: invalid arguments.)
[02/Jul/2021:10:35:18.067184174 +0000] conn=14 op=1 BIND dn="" method=sasl version=3 mech=EXTERNAL
[02/Jul/2021:10:35:18.068421909 +0000] conn=14 op=1 RESULT err=48 tag=97 nentries=0 wtime=0.089133960 optime=0.001244217 etime=0.090376268

Turns out 389-ds-base-1.4.3.16-16 was built against nss-3.67.0-2.el8_4 [1], while the latest available version in CentOS repos is nss-3.53.1-17.el8_3. I don't know why the latest nss is not tagged with dist-c8-compose though.
Once the newer nss build lands in the repos, it should fix the issue. 

HTH

[1] https://koji.mbox.centos.org/pkgs/packages/389-ds-base/1.4.3.16/16.module_el8.4.0+845+0c39e1b7/data/logs/x86_64/root.log

--
Tiemen Ruiten
Infrastructure Engineer
_______________________________________________
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org
To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org
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/freeipa-users@lists.fedorahosted.org
Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure


--
Viktor