[
https://issues.apache.org/jira/browse/DAEMON-424?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Mark Thomas resolved DAEMON-424.
--------------------------------
Fix Version/s: 1.2.4
Resolution: Fixed
Thanks for the analysis and for the patch. The fix will be in the next release.
> stderr logfile is corrupted when running Tomcat 8.5 as Windows service
> ----------------------------------------------------------------------
>
> Key: DAEMON-424
> URL: https://issues.apache.org/jira/browse/DAEMON-424
> Project: Commons Daemon
> Issue Type: Bug
> Components: prunsrv
> Affects Versions: 1.2.3
> Environment: * Windows 10 Version 1909
> * Apache Tomcat 8.5.59
> * Adopt OpenJDK 1.8.0_222
> Reporter: Bernhard Scholz
> Priority: Major
> Fix For: 1.2.4
>
> Attachments: DAEMON-424_scholzb-hb.patch,
> uncaught-exception-sample.zip
>
>
> _Note: This issue has originally been reported under
> https://bz.apache.org/bugzilla/show_bug.cgi?id=64863 for the Tomcat 8
> project._
> h3. Description
> When Tomcat is running as a Windows Service, output written to System.err may
> be overwritten again in the tomcat8-stderr*.log file.
> This includes messages about uncaught exceptions. As a consequence, the
> occurrence of an uncaught exception may remain undetected since it appears in
> no log file.
> h3. Steps to reproduce
> # Install Tomcat as a Windows Service with default settings
> # Build attached Maven project [^uncaught-exception-sample.zip] and deploy
> WAR file into Tomcat
> # Restart Tomcat
> # Inspect file logs/tomcat8-stderr-<date>.log every few seconds
> h3. Expected behavior
> When startup is finished, the file should contain:
> {noformat}
> 30-Oct-2020 14:46:12.669 INFORMATION [main]
> org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
> Engine: Apache Tomcat/8.5.59
> 30-Oct-2020 14:46:12.810 INFORMATION [localhost-startStop-1]
> org.apache.catalina.startup.HostConfig.deployWAR Deploying web application
> archive [C:\Program Files\Apache Software Foundation\Tomcat
> 8.5\webapps\uncaught-exception-sample-1.0-SNAPSHOT.war]
> Message 0 from localhost-start-stop thread
> Message 1 from localhost-start-stop thread
> Message 2 from localhost-start-stop thread
> Message 3 from localhost-start-stop thread
> Message 4 from localhost-start-stop thread
> Message 5 from localhost-start-stop thread
> Message 6 from localhost-start-stop thread
> Message 7 from localhost-start-stop thread
> Message 8 from localhost-start-stop thread
> Message 9 from localhost-start-stop thread
> Exception in thread "Thread-4" java.lang.RuntimeException: exception thrown
> from temporary thread
> at
> org.example.ContextLoaderListener.lambda$contextInitialized$0(ContextLoaderListener.java:17)
> at java.lang.Thread.run(Thread.java:748)
> Message 10 from localhost-start-stop thread
> Message 11 from localhost-start-stop thread
> Message 12 from localhost-start-stop thread
> Message 13 from localhost-start-stop thread
> Message 14 from localhost-start-stop thread
> Message 15 from localhost-start-stop thread
> Message 16 from localhost-start-stop thread
> Message 17 from localhost-start-stop thread
> Message 18 from localhost-start-stop thread
> Message 19 from localhost-start-stop thread
> 30-Oct-2020 14:47:01.449 INFORMATION [localhost-startStop-1]
> org.apache.catalina.startup.HostConfig.deployWAR Deployment of web
> application archive [C:\Program Files\Apache Software Foundation\Tomcat
> 8.5\webapps\uncaught-exception-sample-1.0-SNAPSHOT.war] has finished in
> [48.637] ms
> ...
> {noformat}
> h3. Actual behavior
> The custom messages and the uncaught exception message are written to the
> file and remain there for five seconds, then they are overwritten by
> subsequent log messages. When startup is finished, the file contains:
> {noformat}
> 30-Oct-2020 14:46:12.669 INFORMATION [main]
> org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
> Engine: Apache Tomcat/8.5.59
> 30-Oct-2020 14:46:12.810 INFORMATION [localhost-startStop-1]
> org.apache.catalina.startup.HostConfig.deployWAR Deploying web application
> archive [C:\Program Files\Apache Software Foundation\Tomcat
> 8.5\webapps\uncaught-exception-sample-1.0-SNAPSHOT.war]
> 30-Oct-2020 14:47:01.449 INFORMATION [localhost-startStop-1]
> org.apache.catalina.startup.HostConfig.deployWAR Deployment of web
> application archive [C:\Program Files\Apache Software Foundation\Tomcat
> 8.5\webapps\uncaught-exception-sample-1.0-SNAPSHOT.war] has finished in
> [48.637] ms
> ...
> {noformat}
> The message about the uncaught exception is gone.
> h3. Root Cause
> _(as far as I can tell)_
> The file is opened twice during startup (by the prunsrv), and both file
> descriptors are being used in the Java application.
> Startup sequence:
> # In prunsrv.c, redirectStdStreams():
> -- Log file is opened using _wfsopen() with sharing mode _SH_DENYNO (Permits
> read and write access)
> -- then _dup2() to reassign the existing stderr file descriptor
> # In javajni.c, __apxJavaWorkerThread():
> -- the main class org.apache.catalina.startup.Bootstrap is loaded
> # In javajni.c, apxJavaSetOut():
> -- Log file is opened again and System.err is adjusted, via reflection (Java
> code):
> {noformat}
> System.setErr(new PrintStream(new FileOutputStream(filename, true)));
> {noformat}
> Problem: When the main class is loaded in step 2, it initializes the
> java.util.logging.ConsoleHandler. This class remembers the current System.err
> (from step 1) in a private field.
> Result:
> - ConsoleHandler uses file descriptor from step 1 (via FileOutputStream with
> append == false)
> - System.err uses file descriptor from step 3 (via FileOutputStream with
> append == true)
> Therefore messages written to System.err appear at the end of the log file,
> but are overwritten by subsequent messages written by ConsoleHandler.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
