[jira] [Resolved] (DAEMON-424) stderr logfile is corrupted when running Tomcat 8.5 as Windows service

["Mark Thomas (Jira)" <ji...@apache.org>]

     [ 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)