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

Error when logging to new daily debuglog file: FileHandler is closed. No new debug logfile is created. #4907

Open
jmisset-cb opened this issue Dec 11, 2024 · 0 comments
Open

Error when logging to new daily debuglog file: FileHandler is closed. No new debug logfile is created. #4907

jmisset-cb opened this issue Dec 11, 2024 · 0 comments

Comments

@jmisset-cb
Copy link
Contributor

Description of problem:

Every day a debug logfile should be created in /var/log/pki/pki-tomcat/ca/
This only works on day 1 (after pki-tomcatd is started). As soon as the next day begins, no new debug logfile is created and logging stops until pki-tomcatd is restarted.

Version-Release number of selected component (if applicable):

rpm -qi dogtag-pki-ca
Name        : dogtag-pki-ca
Version     : 11.5.0
Release     : 3.fc40
Architecture: noarch
Install Date: Wed 11 Dec 2024 09:55:44 PM CET
Group       : Unspecified
Size        : 4014572
License     : GPL-2.0-only and LGPL-2.0-only
Signature   : RSA/SHA256, Mon 04 Mar 2024 10:05:34 PM CET, Key ID 0727707ea15b79cc
Source RPM  : dogtag-pki-11.5.0-3.fc40.src.rpm
Build Date  : Mon 04 Mar 2024 09:50:51 PM CET
Build Host  : buildhw-x86-04.iad2.fedoraproject.org
Packager    : Fedora Project
Vendor      : Fedora Project
URL         : https://www.dogtagpki.org
Bug URL     : https://bugz.fedoraproject.org/dogtag-pki
Summary     : Dogtag PKI CA Package

Steps to reproduce:

  1. Spawn CA with default settings
  2. Change date of system to just before midnight date -s "23:59:50"
  3. Wait until next day
  4. Generate some logs (e.g. connect to agent portal and list certificates)

Expected results:

The file /var/log/pki/pki-tomcat/ca/debug.YYYY-MM-DD.log is created and is being logged to.

Actual results:

A new debug log file is not created.
In journalctl, the following error is visible:

Dec 12 00:00:47 dogtagpkifedora.lan server[3867]: java.util.logging.ErrorManager: 1: FileHandler is closed or not yet initialized, unable to log [2024-12-12 00:00:47 [https-jsse-jss-nio-8443-exec-11] SEVERE: CAListRequests: access denied ("java.io.FilePermission" "/var/lib/pki/pki-tomcat/logs/ca" "read")
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]: java.security.AccessControlException: access denied ("java.io.FilePermission" "/var/lib/pki/pki-tomcat/logs/ca" "read")
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.security.AccessControlContext.checkPermission(AccessControlContext.java:488)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.security.AccessController.checkPermission(AccessController.java:1071)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.lang.SecurityManager.checkPermission(SecurityManager.java:411)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.lang.SecurityManager.checkRead(SecurityManager.java:742)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.io.File.exists(File.java:831)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.io.File.mkdirs(File.java:1405)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.juli.FileHandler.openWriter(FileHandler.java:428)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.juli.FileHandler.publish(FileHandler.java:220)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.logging/java.util.logging.Logger.log(Logger.java:983)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.slf4j.impl.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:582)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.slf4j.impl.JDK14LoggerAdapter.info(JDK14LoggerAdapter.java:277)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at com.netscape.cms.servlet.base.CMSServlet.getSSLClientCertificate(CMSServlet.java:842)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at com.netscape.cms.servlet.base.CMSServlet.getSSLClientCertificate(CMSServlet.java:835)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at com.netscape.cms.servlet.base.CMSServlet.authenticate(CMSServlet.java:1442)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at com.netscape.cms.servlet.base.CMSServlet.authenticate(CMSServlet.java:1386)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at com.netscape.cms.servlet.base.CMSServlet.authenticate(CMSServlet.java:1376)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at com.netscape.cms.servlet.base.DisplayHtmlServlet.process(DisplayHtmlServlet.java:65)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at com.netscape.cms.servlet.base.CMSServlet.service(CMSServlet.java:502)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at javax.servlet.http.HttpServlet.service(HttpServlet.java:623)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.lang.reflect.Method.invoke(Method.java:580)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.security.SecurityUtil.lambda$execute$0(SecurityUtil.java:222)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.security.AccessController.doPrivileged(AccessController.java:714)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/javax.security.auth.Subject.doAsPrivileged(Subject.java:670)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:250)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:142)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:197)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.core.ApplicationFilterChain.lambda$doFilter$0(ApplicationFilterChain.java:128)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.security.AccessController.doPrivileged(AccessController.java:571)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:127)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.lang.reflect.Method.invoke(Method.java:580)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.security.SecurityUtil.lambda$execute$0(SecurityUtil.java:222)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.security.AccessController.doPrivileged(AccessController.java:714)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/javax.security.auth.Subject.doAsPrivileged(Subject.java:670)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:250)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:202)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:166)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.core.ApplicationFilterChain.lambda$doFilter$0(ApplicationFilterChain.java:128)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.security.AccessController.doPrivileged(AccessController.java:571)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:127)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:168)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at com.netscape.cms.tomcat.ExternalAuthenticationValve.invoke(ExternalAuthenticationValve.java:83)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:130)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.valves.rewrite.RewriteValve.invoke(RewriteValve.java:543)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:660)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:346)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:383)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:937)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1791)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]:         at java.base/java.lang.Thread.run(Thread.java:1583)
Dec 12 00:00:47 dogtagpkifedora.lan server[3867]: ]

Workaround

Disable Java Security Manager
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
1 participant
@jmisset-cb