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@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
Zarko D via FreeIPA-users wrote:
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
Nov 6 15:55:03 ca-ldap04 server: SelfTestSubsystem: Disabling "ca" subsystem due to selftest failure.
Check out the selftest log for details.
rob
The /var/lib/pki/pki-tomcat/logs/ca/selftests.log reads:
0.localhost-startStop-2 - [06/Nov/2018:15:55:02 PST] [20] [1] SelfTestSubsystem: Initializing self test plugins: 0.localhost-startStop-2 - [06/Nov/2018:15:55:02 PST] [20] [1] SelfTestSubsystem: loading all self test plugin logger parameters 0.localhost-startStop-2 - [06/Nov/2018:15:55:02 PST] [20] [1] SelfTestSubsystem: loading all self test plugin instances 0.localhost-startStop-2 - [06/Nov/2018:15:55:02 PST] [20] [1] SelfTestSubsystem: loading all self test plugin instance parameters 0.localhost-startStop-2 - [06/Nov/2018:15:55:02 PST] [20] [1] SelfTestSubsystem: loading self test plugins in on-demand order 0.localhost-startStop-2 - [06/Nov/2018:15:55:02 PST] [20] [1] SelfTestSubsystem: loading self test plugins in startup order 0.localhost-startStop-2 - [06/Nov/2018:15:55:02 PST] [20] [1] SelfTestSubsystem: Self test plugins have been successfully loaded! 0.localhost-startStop-2 - [06/Nov/2018:15:55:03 PST] [20] [1] SelfTestSubsystem: Running self test plugins specified to be executed at startup: 0.localhost-startStop-2 - [06/Nov/2018:15:55:03 PST] [20] [1] CAPresence: CA is present 0.localhost-startStop-2 - [06/Nov/2018:15:55:03 PST] [20] [1] SystemCertsVerification: system certs verification failure: Certificate Server-Cert cert-pki-ca is invalid: Invalid certificate: (-8181) Peer's Certificate has expired. 0.localhost-startStop-2 - [06/Nov/2018:15:55:03 PST] [20] [1] SelfTestSubsystem: The CRITICAL self test plugin called selftests.container.instance.SystemCertsVerification running at startup FAILED! 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] SelfTestSubsystem: Initializing self test plugins: 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] SelfTestSubsystem: loading all self test plugin logger parameters 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] SelfTestSubsystem: loading all self test plugin instances 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] SelfTestSubsystem: loading all self test plugin instance parameters 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] SelfTestSubsystem: loading self test plugins in on-demand order 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] SelfTestSubsystem: loading self test plugins in startup order 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] SelfTestSubsystem: Self test plugins have been successfully loaded! 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] SelfTestSubsystem: Running self test plugins specified to be executed at startup: 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] CAPresence: CA is present 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] SystemCertsVerification: system certs verification failure: Certificate Server-Cert cert-pki-ca is invalid: Invalid certificate: (-8181) Peer's Certificate has expired. 0.localhost-startStop-3 - [06/Nov/2018:15:55:17 PST] [20] [1] SelfTestSubsystem: The CRITICAL self test plugin called selftests.container.instance.SystemCertsVerification running at startup FAILED!
Okay, we know cert has expired, but I am configuring basic auth for PKI, so why is this relevant now?
On Wed, Nov 07, 2018 at 06:27:51PM -0000, Zarko D via FreeIPA-users wrote:
Okay, we know cert has expired, but I am configuring basic auth for PKI, so why is this relevant now?
The basic/cert auth is related to how Dogtag authenticates to the the database.
The self-test checks the validity of all Dogtag system certificates, including its HTTPS certificate ("Server-Cert cert-pki-ca").
Check all the certificates in the /etc/pki/pki-tomcat/alias/ NSSDB, as well as /etc/dirsrv/slapd-YOUR-REALM/, and set the system clock to a time when all the certificates are valid. Then Dogtag's selftest should pass, it should come up, and you should be able to renew the certificates (or at least, we can help you solve the next issue ^_^).
Cheers, Fraser
Thank you Fraser for the support. 'REALM.COM IPA CA' or caSigningCert is valid for 20 years, should be no problem here. But I am afraid I can't find common date for remaining four certs. As per bellow data:
[1] There is common date for auditSigningCert, subsystemCert and Server-Cert [2] There is common date for Server-Cert and ocspSigningCert [3] ocspSigningCert CANNOT have common date with auditSigningCert and subsystemCert
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'auditSigningCert cert-pki-ca' Not Before: Wed Aug 24 20:49:38 2016 Not After : Tue Aug 14 20:49:38 2018
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'caSigningCert cert-pki-ca' Not Before: Wed Aug 24 20:49:35 2016 Not After : Sun Aug 24 20:49:35 2036
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'subsystemCert cert-pki-ca' Not Before: Wed Aug 24 20:49:36 2016 Not After : Tue Aug 14 20:49:36 2018
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'Server-Cert cert-pki-ca' Not Before: Sat Nov 12 16:21:33 2016 Not After : Fri Nov 02 15:21:33 2018
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'ocspSigningCert cert-pki-ca' Not Before: Mon Oct 22 20:15:53 2018 Not After : Sun Oct 11 20:15:53 2020
# certutil -L -d /etc/dirsrv/slapd-REALM-COM -n 'REALM.COM IPA CA' Not Before: Wed Aug 24 20:49:35 2016 Not After : Sun Aug 24 20:49:35 2036
What would you suggest now ?
On Thu, Nov 08, 2018 at 06:03:27AM -0000, Zarko D via FreeIPA-users wrote:
Thank you Fraser for the support. 'REALM.COM IPA CA' or caSigningCert is valid for 20 years, should be no problem here. But I am afraid I can't find common date for remaining four certs. As per bellow data:
[1] There is common date for auditSigningCert, subsystemCert and Server-Cert [2] There is common date for Server-Cert and ocspSigningCert [3] ocspSigningCert CANNOT have common date with auditSigningCert and subsystemCert
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'auditSigningCert cert-pki-ca' Not Before: Wed Aug 24 20:49:38 2016 Not After : Tue Aug 14 20:49:38 2018
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'caSigningCert cert-pki-ca' Not Before: Wed Aug 24 20:49:35 2016 Not After : Sun Aug 24 20:49:35 2036
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'subsystemCert cert-pki-ca' Not Before: Wed Aug 24 20:49:36 2016 Not After : Tue Aug 14 20:49:36 2018
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'Server-Cert cert-pki-ca' Not Before: Sat Nov 12 16:21:33 2016 Not After : Fri Nov 02 15:21:33 2018
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'ocspSigningCert cert-pki-ca' Not Before: Mon Oct 22 20:15:53 2018 Not After : Sun Oct 11 20:15:53 2020
# certutil -L -d /etc/dirsrv/slapd-REALM-COM -n 'REALM.COM IPA CA' Not Before: Wed Aug 24 20:49:35 2016 Not After : Sun Aug 24 20:49:35 2036
What would you suggest now ?
I'm not 100% sure on the procedure but it will be something like:
1. Find an older version of the ocspSigningCert under 'ou=certificateRepository,ou=ca,o=ipaca', that is valid at the same time as all the other certs. Copy the certificate data to a file.
2. Back up the ocspSigningCert from the /etc/pki/pki-tomcat/alias NSSDB, via pk12util.
3. Delete the ocspSigningCert from the /etc/pki/pki-tomcat/alias NSSDB, i.e.:
certutil -d /etc/pki/pki-tomcat/alias \ -f /etc/pki/pki-tomcat/alias/pwdfile.txt \ -D -n "ocspSigningCert cert-pki-ca"
4. IIRC, (3) should only delete the "most recent" version of the OCSP cert, and expose the earlier version. But if this is not the case, then import the certificate you saved at (1) via `certutil -A`.
Once you have coerced to the NSSDB to have a set of certificates that are all valid at some point in time, set the system clock to that time, restart Dogtag, and initiate renewals.
Cheers, Fraser
Hi Fraser, I am making some progress. Let's please continue.
[1] I was able to follow your info and find common date in past for all certs to be valid. Note, in case this is important, I have four IPA servers and I do this on CA renewal master.
[2] Then system clock was set to past time (about 2 weeks before expire time) , stop ntp, restart krb5kdc, dirsrv, httpd, CA. The I verify that CA is running, with command :
SSL_DIR=/etc/httpd/alias/ curl -v -o /dev/null --cacert /etc/ipa/ca.crt https://%60hostname%60:8443/ca/agent/ca/profileReview
* Initializing NSS with certpath: sql:/etc/httpd/alias/ * CAfile: /etc/ipa/ca.crt CApath: none * NSS: client certificate not found (nickname not specified) * SSL connection using TLS_RSA_WITH_AES_256_CBC_SHA * Server certificate: * subject: CN=ca-ldap04,O=REALM.COM * start date: Aug 01 17:18:06 2018 GMT * expire date: Jul 21 17:18:06 2020 GMT * common name: ca-ldap04 * issuer: CN=Certificate Authority,O=US.ORACLE.COM
GET /ca/agent/ca/profileReview HTTP/1.1 User-Agent: curl/7.29.0 Host: ca-ldap04:8443 Accept: */*
* NSS: client certificate not found (nickname not specified) < HTTP/1.1 200 OK < Server: Apache-Coyote/1.1 < Content-Type: text/html;charset=UTF-8 < Transfer-Encoding: chunked < Date: Wed, 01 Aug 2018 18:28:04 GMT < { [data not shown] 100 17641 0 17641 0 0 230k 0 --:--:-- --:--:-- --:--:-- 232k * Connection #0 to host ca-ldap04.realm.com left intact
[3] Restart certmonger, and ONLY ONE cert is renewed, it's "Server-Cert cert-pki-ca".
status: CA_UNREACHABLE certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-ca',token='NSS Certificate DB' expires: 2018-08-14 20:49:38 UTC status: CA_UNREACHABLE certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='ocspSigningCert cert-pki-ca',token='NSS Certificate DB' expires: 2018-08-14 20:49:35 UTC status: CA_UNREACHABLE certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='subsystemCert cert-pki-ca',token='NSS Certificate DB' expires: 2018-08-14 20:49:36 UTC status: MONITORING certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='caSigningCert cert-pki-ca',token='NSS Certificate DB' expires: 2036-08-24 20:49:35 UTC status: MONITORING certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='Server-Cert cert-pki-ca',token='NSS Certificate DB' expires: 2020-07-21 17:18:06 UTC status: CA_UNREACHABLE certificate: type=NSSDB,location='/etc/httpd/alias',nickname='ipaCert',token='NSS Certificate DB' expires: 2018-08-14 20:50:00 UTC
[4] From "journalctl -fu certmonger --full " basically there is " Insufficient access: Invalid credentials"
Aug 01 11:04:45 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:45 [7447] Will revisit CA6('dogtag-ipa-ca-renew-agent').default_profile now. Aug 01 11:04:45 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:45 [7447] CA6('dogtag-ipa-ca-renew-agent').default_profile moved to state 'DISABLED' Aug 01 11:04:45 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:45 [7447] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').default_profile. Aug 01 11:04:45 ca-ldap04.realm.com dogtag-ipa-ca-renew-agent-submit[7526]: Traceback (most recent call last): File "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit", line 511, in <module> sys.exit(main()) File "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit", line 497, in main if ca.is_renewal_master(): File "/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line 1188, in is_renewal_master self.ldap_connect() File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 177, in ldap_connect conn.do_bind(self.dm_password, autobind=self.autobind) File "/usr/lib/python2.7/site-packages/ipapython/ipaldap.py", line 1690, in do_bind self.do_sasl_gssapi_bind(timeout=timeout) File "/usr/lib/python2.7/site-packages/ipapython/ipaldap.py", line 1668, in do_sasl_gssapi_bind self.__bind_with_wait(self.gssapi_bind, timeout) File "/usr/lib/python2.7/site-packages/ipapython/ipaldap.py", line 1650, in __bind_with_wait bind_func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/ipapython/ipaldap.py", line 1108, in gssapi_bind '', auth_tokens, server_controls, client_controls) File "/usr/lib64/python2.7/contextlib.py", line 35, in __exit__ self.gen.throw(type, value, traceback) File "/usr/lib/python2.7/site-packages/ipapython/ipaldap.py", line 973, in error_handler raise errors.ACIError(info="%s %s" % (info, desc)) ACIError: Insufficient access: Invalid credentials Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Certificate submission still ongoing. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Will revisit Request1('20161112162146') on traffic from 92. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').profiles retrieval unsupported Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').profiles moved to state 'DISABLED' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Will revisit CA6('dogtag-ipa-ca-renew-agent').profiles now. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').profiles moved to state 'DISABLED' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').profiles. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').capabilities retrieval unsupported Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').capabilities moved to state 'DISABLED' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Will revisit CA6('dogtag-ipa-ca-renew-agent').capabilities now. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').capabilities moved to state 'DISABLED' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').capabilities. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').renewal_reqs retrieval unsupported Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').renewal_reqs moved to state 'DISABLED' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Will revisit CA6('dogtag-ipa-ca-renew-agent').renewal_reqs now. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').renewal_reqs moved to state 'DISABLED' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').renewal_reqs. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs retrieval unsupported Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs moved to state 'DISABLED' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Will revisit CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs now. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs moved to state 'DISABLED' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs. Aug 01 11:04:46 ca-ldap04.realm.com python2[7533]: GSSAPI client step 1 Aug 01 11:04:46 ca-ldap04.realm.com python2[7533]: GSSAPI client step 1 Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').encryption_certs retrieval unsupported Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').encryption_certs moved to state 'DISABLED' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Will revisit CA6('dogtag-ipa-ca-renew-agent').encryption_certs now. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] CA6('dogtag-ipa-ca-renew-agent').encryption_certs moved to state 'DISABLED' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').encryption_certs. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Certificate submission attempt complete. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Child status = 3. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Child output: Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: "Internal error Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: " Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Internal error Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Certificate not (yet?) issued. Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Request1('20161112162146') moved to state 'CA_UNREACHABLE' Aug 01 11:04:46 ca-ldap04.realm.com certmonger[7447]: 2018-08-01 11:04:46 [7447] Will revisit Request1('20161112162146') in 566546 seconds.
I've also reset nss trust flag, as per
https://rcritten.wordpress.com/2017/09/20/peer-certificate-cannot-be-authent...
and still getting " Insufficient access: Invalid credentials", from the previous post.
Once again, I am back in time when all certs are valid. , for example : # date Fri Aug 3 01:47:18 PDT 2018
Yet, CA cannot start and /var/log/pki/pki-tomcat/ca/selftests.log reads:
0.localhost-startStop-2 - [03/Aug/2018:01:03:17 PDT] [20] [1] CAPresence: CA is present 0.localhost-startStop-2 - [03/Aug/2018:01:03:17 PDT] [20] [1] SystemCertsVerification: system certs verification failure: Certificate auditSigningCert cert-pki-ca is invalid: Invalid certificate: (-8181) Peer's Certificate has expired. 0.localhost-startStop-2 - [03/Aug/2018:01:03:17 PDT] [20] [1] SelfTestSubsystem: The CRITICAL self test plugin called selftests.container.instance.SystemCertsVerification running at startup FAILED!
This cannot be true !? Aug 03 2018 should be valid date.
# certutil -L -d /etc/pki/pki-tomcat/alias/ -n 'auditSigningCert cert-pki-ca' | grep Not Not Before: Wed Aug 24 20:49:38 2016 Not After : Tue Aug 14 20:49:38 2018
Have you experience such case before?
freeipa-users@lists.fedorahosted.org
-
Fraser Tweedale -
Rob Crittenden -
Zarko D