search

dogtagpki / pki

The Dogtag Certificate System is an enterprise-class Certificate Authority (CA) which supports all aspects of certificate lifecycle management, including key archival, OCSP and smartcard management.
https://www.dogtagpki.org
GNU General Public License v2.0
349 stars 133 forks source link

Log rotation can break ipa-kra-install #4703

Open flo-renaud opened 4 months ago

flo-renaud commented 4 months ago

In FreeIPA nightly tests we can see random failures installing the KRA, for instance if the installation happens around the same time that PKI logs rotation is done. Example of issue: report.html, with the logs in this dir

/var/log/ipaserver-kra-install.log shows an error calling securityDomain/domainInfo:

2024-03-21T00:00:41Z DEBUG https://master.ipa.test:8443 "GET /ca/rest/securityDomain/domainInfo HTTP/1.1" 500 195
2024-03-21T00:00:41Z DEBUG   File "/usr/lib/python3.12/site-packages/ipapython/admintool.py", line 180, in execute
    return_value = self.run()
                   ^^^^^^^^^^
  File "/usr/lib/python3.12/site-packages/ipaserver/install/ipa_kra_install.py", line 161, in run
    self.installing_replica = dogtaginstance.is_installing_replica("KRA")
                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/site-packages/ipaserver/install/dogtaginstance.py", line 100, in is_installing_replica
    info = get_security_domain()
           ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/site-packages/ipaserver/install/dogtaginstance.py", line 89, in get_security_domain
    info = domain_client.get_domain_info()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/site-packages/pki/system.py", line 275, in get_domain_info
    response = self.connection.get(self.domain_info_url, headers=headers)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/site-packages/pki/client.py", line 55, in wrapper
    return func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/site-packages/pki/client.py", line 264, in get
    r.raise_for_status()
  File "/usr/lib/python3.12/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)

2024-03-21T00:00:41Z DEBUG The ipa-kra-install command failed, exception: HTTPError: 500 Server Error:  for url: https://master.ipa.test:8443/ca/rest/securityDomain/domainInfo
2024-03-21T00:00:41Z ERROR 500 Server Error:  for url: https://master.ipa.test:8443/ca/rest/securityDomain/domainInfo
2024-03-21T00:00:41Z ERROR The ipa-kra-install command failed. See /var/log/ipaserver-kra-install.log for more information

Around the same time, the journal shows an Exception in PKI:

Mar 21 00:00:41 master.ipa.test server[10374]: java.util.logging.ErrorManager: 1: FileHandler is closed or not yet initialized, unable to log [2024-03-21 00:00:41 [https-jsse-nio-8443-exec-11] SEVERE: SecurityDomainProcessor: Failed to read domain info from ldap access denied ("java.io.FilePermission" "/var/lib/pki/pki-tomcat/logs/ca" "read")
Mar 21 00:00:41 master.ipa.test server[10374]: java.security.AccessControlException: access denied ("java.io.FilePermission" "/var/lib/pki/pki-tomcat/logs/ca" "read")
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.security.AccessControlContext.checkPermission(AccessControlContext.java:485)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.security.AccessController.checkPermission(AccessController.java:1068)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.lang.SecurityManager.checkPermission(SecurityManager.java:416)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.lang.SecurityManager.checkRead(SecurityManager.java:756)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.io.File.exists(File.java:829)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.io.File.mkdirs(File.java:1403)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.juli.FileHandler.openWriter(FileHandler.java:428)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.juli.FileHandler.publish(FileHandler.java:220)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.logging/java.util.logging.Logger.log(Logger.java:980)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:582)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:277)
Mar 21 00:00:41 master.ipa.test server[10374]:         at com.netscape.cmscore.ldapconn.PKISocketFactory.init(PKISocketFactory.java:128)
Mar 21 00:00:41 master.ipa.test server[10374]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.makeNewConnection(LdapBoundConnFactory.java:304)
Mar 21 00:00:41 master.ipa.test server[10374]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.makeConnection(LdapBoundConnFactory.java:278)
Mar 21 00:00:41 master.ipa.test server[10374]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:262)
Mar 21 00:00:41 master.ipa.test server[10374]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:224)
Mar 21 00:00:41 master.ipa.test server[10374]:         at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:193)
Mar 21 00:00:41 master.ipa.test server[10374]:         at com.netscape.cms.servlet.csadmin.SecurityDomainProcessor.getDomainInfo(SecurityDomainProcessor.java:180)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.dogtagpki.server.rest.SecurityDomainService.getDomainInfo(SecurityDomainService.java:92)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.lang.reflect.Method.invoke(Method.java:568)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:236)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:406)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:213)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:228)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
Mar 21 00:00:41 master.ipa.test server[10374]:         at javax.servlet.http.HttpServlet.service(HttpServlet.java:623)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.lang.reflect.Method.invoke(Method.java:568)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.security.SecurityUtil.lambda$execute$0(SecurityUtil.java:222)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.security.AccessController.doPrivileged(AccessController.java:712)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/javax.security.auth.Subject.doAsPrivileged(Subject.java:584)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:250)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:142)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:207)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.core.ApplicationFilterChain.lambda$doFilter$0(ApplicationFilterChain.java:137)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.security.AccessController.doPrivileged(AccessController.java:569)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:136)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.lang.reflect.Method.invoke(Method.java:568)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.security.SecurityUtil.lambda$execute$0(SecurityUtil.java:222)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.security.AccessController.doPrivileged(AccessController.java:712)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/javax.security.auth.Subject.doAsPrivileged(Subject.java:584)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:250)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:202)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:176)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.core.ApplicationFilterChain.lambda$doFilter$0(ApplicationFilterChain.java:137)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.security.AccessController.doPrivileged(AccessController.java:569)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:136)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:168)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:481)
Mar 21 00:00:41 master.ipa.test server[10374]:         at com.netscape.cms.tomcat.ExternalAuthenticationValve.invoke(ExternalAuthenticationValve.java:83)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:130)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.valves.rewrite.RewriteValve.invoke(RewriteValve.java:545)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:670)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:390)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:928)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1794)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
Mar 21 00:00:41 master.ipa.test server[10374]:         at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
Mar 21 00:00:41 master.ipa.test server[10374]:         at java.base/java.lang.Thread.run(Thread.java:833)
Mar 21 00:00:41 master.ipa.test server[10374]: ]

The list of installed packages: dogtag-pki-server-11.4.3-2.fc39.1.noarch dogtag-jss-5.4.2-1.fc39.1.x86_64

opoplawski commented 3 months ago

Perhaps related - after rotation there was now more logging from pki tomcat on an EL9 IPA server:

-rw-r--r--. 1 pkiuser pkiuser 118080 Apr 23 23:58 debug.2024-04-23.log
2024-04-23 23:53:22 [Timer-0] INFO: SessionTimer: checking security domain sessions
2024-04-23 23:53:24 [SerialNumberUpdateTask] INFO: SerialNumberUpdateTask: Updating serial number counter
2024-04-23 23:53:24 [SerialNumberUpdateTask] INFO: SerialNumberUpdateTask: Checking serial number ranges
2024-04-23 23:53:24 [SerialNumberUpdateTask] INFO: Repository: Searching for conflicting entries
2024-04-23 23:53:24 [SerialNumberUpdateTask] INFO: SerialNumberUpdateTask: Checking request ID ranges
2024-04-23 23:53:24 [SerialNumberUpdateTask] INFO: Repository: Searching for conflicting entries
2024-04-23 23:58:22 [Timer-0] INFO: SessionTimer: checking security domain sessions

Requests for CRL started timing out.

[Thu Apr 25 04:01:01.617837 2024] [proxy_ajp:error] [pid 110419:tid 110426] (70007)The timeout specified has expired: AH01030: ajp_ilink_receive() can't receive header
[Thu Apr 25 04:01:01.617977 2024] [proxy_ajp:error] [pid 110419:tid 110426] [client 10.20.0.37:53184] AH00992: ajp_read_header: ajp_ilink_receive failed
[Thu Apr 25 04:01:01.618003 2024] [proxy_ajp:error] [pid 110419:tid 110426] (70007)The timeout specified has expired: [client 10.20.0.37:53184] AH00878: read response failed from [::1]:8009 (localhost:8009)