[Freeipa-users] Fails to start CA with Basic Auth (and/or SSL)

[Zarko D]

Hi, this is the part of troubleshooting expired certificates (it's in another post). I
can't successfully renew certs after going back in time and I believe the reason is
that CA is not starting. Some of posts and Bugzilla bugs suggest using PKI basic
authentication, that I try without success, so I'd like to see if I do something
wrong. 

ipa-server is 4.4.0 and pki-server is 10.3.3


[1] "internaldb" added to /etc/pki/pki-tomcat/password.conf hence it reads:

internal=264530051944
replicationdb=-1979518752
internaldb=directory-manager-password

[2] Edited /etc/pki/pki-tomcat/ca/CS.cfg so diff is:

61c61
< authz.instance.DirAclAuthz.ldap.ldapauth.authtype=BasicAuth
---
>  authz.instance.DirAclAuthz.ldap.ldapauth.authtype=SslClientAuth
63,64c63,64
< authz.instance.DirAclAuthz.ldap.ldapconn.port=389
< authz.instance.DirAclAuthz.ldap.ldapconn.secureConn=false
---
>  authz.instance.DirAclAuthz.ldap.ldapconn.port=636
>  authz.instance.DirAclAuthz.ldap.ldapconn.secureConn=true 
784,786c784,785
< internaldb.ldapauth.authtype=BasicAuth
< internaldb.ldapauth.bindDN=cn=Directory Manager
< internaldb.ldapauth.bindPWPrompt=internaldb
---
>  internaldb.ldapauth.authtype=SslClientAuth
>  internaldb.ldapauth.bindDN=uid=pkidbuser,ou=people,o=ipaca 
791c790
< internaldb.ldapconn.port=389
---
>  internaldb.ldapconn.port=636 
793c792

< internaldb.ldapconn.secureConn=false
---
>  internaldb.ldapconn.secureConn=true 

[3] Restart pki-tomcatd(a)pki-tomcat.service


Please let me know if you need some additional logs, these are the ones I believe can help
and are relevant.  

[4] /var/log/pki/pki-tomcat/catalina.2018-11-06.log

WARNING: Problem with JAR file [/usr/share/pki/server/common/lib/symkey.jar], exists:
[false], canRead: [false]
Nov 06, 2018 3:54:35 PM org.apache.catalina.startup.SetAllPropertiesRule begin
WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property
'enableOCSP' to 'false' did not find a matching property.
Nov 06, 2018 3:54:35 PM org.apache.catalina.startup.SetAllPropertiesRule begin
WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property
'ocspResponderURL' to 'http://ca-ldap04.internal.com:9080/ca/ocsp' did not
find a matching property.
Nov 06, 2018 3:54:35 PM org.apache.catalina.startup.SetAllPropertiesRule begin
WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property
'ocspResponderCertNickname' to 'ocspSigningCert cert-pki-ca' did not find
a matching property.
Nov 06, 2018 3:54:35 PM org.apache.catalina.startup.SetAllPropertiesRule begin
WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property
'ocspCacheSize' to '1000' did not find a matching property.
Nov 06, 2018 3:54:35 PM org.apache.catalina.startup.SetAllPropertiesRule begin
WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property
'ocspMinCacheEntryDuration' to '60' did not find a matching property.
Nov 06, 2018 3:54:35 PM org.apache.catalina.startup.SetAllPropertiesRule begin
WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property
'ocspMaxCacheEntryDuration' to '120' did not find a matching property.
Nov 06, 2018 3:54:35 PM org.apache.catalina.startup.SetAllPropertiesRule begin
WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property
'ocspTimeout' to '10' did not find a matching property.
Nov 06, 2018 3:54:35 PM org.apache.catalina.startup.SetAllPropertiesRule begin
WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property
'strictCiphers' to 'true' did not find a matching property.
Nov 06, 2018 3:54:35 PM org.apache.catalina.startup.SetAllPropertiesRule begin
WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property
'sslOptions' to 'ssl2=false,ssl3=false,tls=true' did not find a matching
property.
... shortened INFO messages ... 
Nov 06, 2018 3:55:13 PM org.apache.catalina.loader.WebappClassLoaderBase
clearReferencesThreads
SEVERE: The web application [/ca] appears to have started a thread named [LDAPConnThread-9
ldap://ca-ldap04.internal.com:389] but has failed to stop it. This is very likely to
create a memory leak.
Nov 06, 2018 3:55:13 PM org.apache.catalina.loader.WebappClassLoaderBase
clearReferencesThreads
SEVERE: The web application [/ca] appears to have started a thread named
[profileChangeMonitor] but has failed to stop it. This is very likely to create a memory
leak.



[5] /var/log/pki/pki-tomcat/ca/debug


[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]:
CMSEngine.shutdown()
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying
LdapBoundConnFactory(CrossCertPairSubsystem)
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying
RollingLogFile(/var/lib/pki/pki-tomcat/logs/ca/selftests.log)
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying
LogFile(/var/lib/pki/pki-tomcat/logs/ca/selftests.log)
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]:
SignedAuditEventFactory: create() message created for eventType=AUDIT_LOG_SHUTDOWN
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: In
LdapBoundConnFactory::getConn()
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: masterConn
is null.
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]:
makeConnection: errorIfDown true
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]:
Established LDAP connection using basic authentication to host ca-ldap04.internal.com port
389 as cn=Directory Manager
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: increasing
minimum connections by 3
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: new total
available connections 3
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: new number
of connections 3
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: getConn:
conn is connected true
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: getConn:
mNumConns now 2
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]:
returnConn: mNumConns now 3
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Shuting
down publishing.
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying
LdapBoundConnFactory(CertificateAuthority)
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Cannot
reset factory: connections not all returned
[06/Nov/2018:15:55:28][ContainerBackgroundProcessor[StandardEngine[Catalina]]]:
CertificateAuthority.shutdown: failed to reset dbFactory: Cannot reset LDAP connection
factory because some connections are still outstanding.



[6] /var/log/messages


Nov  6 15:54:34 ca-ldap04 server: INFO: Pausing ProtocolHandler
["http-bio-8080"]
Nov  6 15:54:34 ca-ldap04 systemd: Starting PKI Tomcat Server pki-tomcat...
Nov  6 15:54:34 ca-ldap04 systemd: Started PKI Tomcat Server pki-tomcat.
Nov  6 15:54:34 ca-ldap04 server: Java virtual machine used:
/usr/lib/jvm/jre-1.8.0-openjdk/bin/java
Nov  6 15:54:34 ca-ldap04 server: classpath used:
/usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/commons-daemon.jar
Nov  6 15:54:34 ca-ldap04 server: main class used: org.apache.catalina.startup.Bootstrap
Nov  6 15:54:34 ca-ldap04 server: flags used: -DRESTEASY_LIB=/usr/share/java/resteasy-base
-Djava.library.path=/usr/lib64/nuxwdog-jni
Nov  6 15:54:34 ca-ldap04 server: 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
Nov  6 15:54:34 ca-ldap04 server: arguments used: start
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.ClassLoaderFactory validateFile
Nov  6 15:54:35 ca-ldap04 server: WARNING: Problem with JAR file
[/usr/share/pki/server/common/lib/symkey.jar], exists: [false], canRead: [false]
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
Nov  6 15:54:35 ca-ldap04 server: WARNING:
[SetAllPropertiesRule]{Server/Service/Connector} Setting property 'enableOCSP' to
'false' did not find a matching property.
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
Nov  6 15:54:35 ca-ldap04 server: WARNING:
[SetAllPropertiesRule]{Server/Service/Connector} Setting property
'ocspResponderURL' to 'http://ca-ldap04.internal.com:9080/ca/ocsp' did not
find a matching property.
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
Nov  6 15:54:35 ca-ldap04 server: WARNING:
[SetAllPropertiesRule]{Server/Service/Connector} Setting property
'ocspResponderCertNickname' to 'ocspSigningCert cert-pki-ca' did not find
a matching property.
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
Nov  6 15:54:35 ca-ldap04 server: WARNING:
[SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ocspCacheSize'
to '1000' did not find a matching property.
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
Nov  6 15:54:35 ca-ldap04 server: WARNING:
[SetAllPropertiesRule]{Server/Service/Connector} Setting property
'ocspMinCacheEntryDuration' to '60' did not find a matching property.
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
Nov  6 15:54:35 ca-ldap04 server: WARNING:
[SetAllPropertiesRule]{Server/Service/Connector} Setting property
'ocspMaxCacheEntryDuration' to '120' did not find a matching property.
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
Nov  6 15:54:35 ca-ldap04 server: WARNING:
[SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ocspTimeout' to
'10' did not find a matching property.
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
Nov  6 15:54:35 ca-ldap04 server: WARNING:
[SetAllPropertiesRule]{Server/Service/Connector} Setting property 'strictCiphers'
to 'true' did not find a matching property.
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
Nov  6 15:54:35 ca-ldap04 server: WARNING:
[SetAllPropertiesRule]{Server/Service/Connector} Setting property 'sslOptions' to
'ssl2=false,ssl3=false,tls=true' did not find a matching property.
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
Nov  6 15:54:35 ca-ldap04 server: WARNING:
[SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ssl2Ciphers' to
'-
SSL2_RC4_128_WITH_MD5,-SSL2_RC4_128_EXPORT40_WITH_MD5,-SSL2_RC2_128_CBC_WITH_MD5,-SSL2_RC2_128_CBC_EXPORT40_WITH_MD5,-SSL2_DES_64_CBC_WITH_MD5,-
SSL2_DES_192_EDE3_CBC_WITH_MD5' did not find a matching property.
Nov  6 15:54:35 ca-ldap04 server: Nov 06, 2018 3:54:35 PM
org.apache.catalina.startup.SetAllPropertiesRule begin
...
Nov  6 15:54:58 ca-ldap04 server: Nov 06, 2018 3:54:58 PM
org.apache.catalina.startup.HostConfig deployDescriptor
Nov  6 15:54:58 ca-ldap04 server: INFO: Deploying configuration descriptor
/etc/pki/pki-tomcat/Catalina/localhost/ca.xml
Nov  6 15:54:58 ca-ldap04 server: SSLAuthenticatorWithFallback: Creating SSL authenticator
with fallback
Nov  6 15:54:58 ca-ldap04 server: SSLAuthenticatorWithFallback: Setting container
Nov  6 15:55:00 ca-ldap04 server: Nov 06, 2018 3:55:00 PM
org.apache.catalina.startup.TldConfig execute
Nov  6 15:55:00 ca-ldap04 server: INFO: At least one JAR was scanned for TLDs yet
contained no TLDs. Enable debug logging for this logger for a complete list of JARs that
were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can
improve startup time and JSP compilation time.
Nov  6 15:55:00 ca-ldap04 server: SSLAuthenticatorWithFallback: Initializing
authenticators
Nov  6 15:55:00 ca-ldap04 server: SSLAuthenticatorWithFallback: Starting authenticators
Nov  6 15:55:00 ca-ldap04 server: CMSEngine.initializePasswordStore() begins
Nov  6 15:55:00 ca-ldap04 server: CMSEngine.initializePasswordStore(): tag=internaldb
Nov  6 15:55:01 ca-ldap04 server: testLDAPConnection connecting to
ca-ldap04.internal.com:389
Nov  6 15:55:01 ca-ldap04 server: CMSEngine.initializePasswordStore(): tag=replicationdb
Nov  6 15:55:01 ca-ldap04 server: testLDAPConnection connecting to
ca-ldap04.internal.com:389
Nov  6 15:55:01 ca-ldap04 server: testLDAPConnection: The specified user cn=Replication
Manager masterAgreement1-ca-ldap04.internal.com-pki-tomcat,cn=config does not exist
Nov  6 15:55:02 ca-ldap04 server: CMSEngine: init(): password test execution failed for
replicationdbwith NO_SUCH_USER.  This may not be a latest instance.  Ignoring ..
Nov  6 15:55:03 ca-ldap04 server: SelfTestSubsystem: Disabling "ca" subsystem
due to selftest failure.
Nov  6 15:55:03 ca-ldap04 server: -----------------------
Nov  6 15:55:03 ca-ldap04 server: Disabled "ca" subsystem
Nov  6 15:55:03 ca-ldap04 server: -----------------------
Nov  6 15:55:03 ca-ldap04 server: Subsystem ID: ca
Nov  6 15:55:03 ca-ldap04 server: Instance ID: pki-tomcat
Nov  6 15:55:03 ca-ldap04 server: Enabled: False
Nov  6 15:55:03 ca-ldap04 server: Invalid class name repositorytop
Nov  6 15:55:03 ca-ldap04 server: Invalid class name repositorytop
..
Nov  6 15:55:03 ca-ldap04 server: Nov 06, 2018 3:55:03 PM
org.apache.catalina.startup.HostConfig deployDescriptor
Nov  6 15:55:03 ca-ldap04 server: INFO: Deployment of configuration descriptor
/etc/pki/pki-tomcat/Catalina/localhost/ca.xml has finished in4,815 ms
Nov  6 15:55:13 ca-ldap04 server: Nov 06, 2018 3:55:13 PM
org.apache.catalina.startup.HostConfig undeploy
Nov  6 15:55:13 ca-ldap04 server: INFO: Undeploying context [/ca]
Nov  6 15:55:13 ca-ldap04 server: SSLAuthenticatorWithFallback: Stopping authenticators
Nov  6 15:55:13 ca-ldap04 server: Nov 06, 2018 3:55:13 PM
org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
Nov  6 15:55:13 ca-ldap04 server: SEVERE: The web application [/ca] appears to have
started a thread named [LDAPConnThread-3 ldap://ca-ldap04.internal.com:389] but has failed
to stop it. This is very likely to create a memory leak.
Nov  6 15:55:13 ca-ldap04 server: Nov 06, 2018 3:55:13 PM
org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
Nov  6 15:55:13 ca-ldap04 server: SEVERE: The web application [/ca] appears to have
started a thread named [LDAPConnThread-7 ldap://ca-dap04.internal.com:389] but has failed
to stop it. This is very likely to create a memory leak.
Nov  6 15:55:13 ca-ldap04 server: Nov 06, 2018 3:55:13 PM
org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
Nov  6 15:55:13 ca-ldap04 server: SEVERE: The web application [/ca] appears to have
started a thread named [authorityMonitor] but has failed to stop it. This is very likely
to create a memory leak.
Nov  6 15:55:13 ca-ldap04 server: Nov 06, 2018 3:55:13 PM
org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
Nov  6 15:55:13 ca-ldap04 server: SEVERE: The web application [/ca] appears to have
started a thread named [LDAPConnThread-9 ldap://ca-ldap04.internal.com:389] but has failed
to stop it. This is very likely to create a memory leak.
Nov  6 15:55:13 ca-ldap04 server: Nov 06, 2018 3:55:13 PM
org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
Nov  6 15:55:13 ca-ldap04 server: SEVERE: The web application [/ca] appears to have
started a thread named [profileChangeMonitor] but has failed to stop it. This is very
likely to create a memory leak.
Nov  6 15:55:13 ca-ldap04 server: SSLAuthenticatorWithFallback: Setting container
Nov  6 15:55:13 ca-ldap04 server: Nov 06, 2018 3:55:13 PM
org.apache.catalina.startup.HostConfig deployDescriptor
Nov  6 15:55:13 ca-ldap04 server: INFO: Deploying configuration descriptor
/etc/pki/pki-tomcat/Catalina/localhost/ca.xml
Nov  6 15:55:13 ca-ldap04 server: SSLAuthenticatorWithFallback: Creating SSL authenticator
with fallback
Nov  6 15:55:13 ca-ldap04 server: SSLAuthenticatorWithFallback: Setting container
Nov  6 15:55:14 ca-ldap04 server: Nov 06, 2018 3:55:14 PM
org.apache.catalina.startup.TldConfig execute
Nov  6 15:55:14 ca-ldap04 server: INFO: At least one JAR was scanned for TLDs yet
contained no TLDs. Enable debug logging for this logger for a complete list of JARs that
were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can
improve startup time and JSP compilation time.
Nov  6 15:55:14 ca-ldap04 server: SSLAuthenticatorWithFallback: Initializing
authenticators
Nov  6 15:55:15 ca-ldap04 server: SSLAuthenticatorWithFallback: Starting authenticators
Nov  6 15:55:15 ca-ldap04 server: CMSEngine.initializePasswordStore() begins
Nov  6 15:55:15 ca-ldap04 server: CMSEngine.initializePasswordStore(): tag=internaldb
Nov  6 15:55:15 ca-ldap04 server: testLDAPConnection connecting to
ca-ldap04.internal.com:389
Nov  6 15:55:15 ca-ldap04 server: CMSEngine.initializePasswordStore(): tag=replicationdb
Nov  6 15:55:15 ca-ldap04 server: testLDAPConnection connecting to
ca-ldap04.internal.com:389
Nov  6 15:55:15 ca-ldap04 server: testLDAPConnection: The specified user cn=Replication
Manager masterAgreement1-ca-ldap04.internal.com-pki-tomcat,cn=config does not exist