Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Log rotation can break ipa-kra-install #4703

Open
flo-renaud opened this issue Mar 21, 2024 · 2 comments
Open

Log rotation can break ipa-kra-install #4703

flo-renaud opened this issue Mar 21, 2024 · 2 comments

Comments

@flo-renaud
Copy link

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
Copy link

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)

@flo-renaud flo-renaud mentioned this issue May 28, 2024
Closed
@flo-renaud flo-renaud mentioned this issue Jul 16, 2024
Closed
@flo-renaud flo-renaud mentioned this issue Jul 30, 2024
Closed
This was referenced Aug 9, 2024
Closed
Closed
@amore17 amore17 mentioned this issue Aug 21, 2024
Closed
@flo-renaud flo-renaud mentioned this issue Aug 28, 2024
Closed
@amore17 amore17 mentioned this issue Sep 2, 2024
Closed
@flo-renaud flo-renaud mentioned this issue Sep 18, 2024
Closed
@jsf9k
Copy link

jsf9k commented Sep 24, 2024

See also:

@amore17 amore17 mentioned this issue Sep 25, 2024
Closed
@miskopo miskopo mentioned this issue Oct 3, 2024
Closed
@amore17 amore17 mentioned this issue Oct 7, 2024
Closed
This was referenced Oct 10, 2024
Closed
Closed
This was referenced Oct 18, 2024
Closed
Closed
This was referenced Oct 24, 2024
Closed
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@opoplawski @jsf9k @flo-renaud