Bug 64863 - stderr logfile is corrupted when running as Windows service
Summary: stderr logfile is corrupted when running as Windows service
Status: RESOLVED INVALID
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: Meta (show other bugs)
Version: 8.5.59
Hardware: PC All
: P2 normal (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-10-30 15:24 UTC by scholzb-hb
Modified: 2020-10-31 14:20 UTC (History)
0 users



Attachments
Example Maven project to reproduce the issue (2.59 KB, application/x-zip-compressed)
2020-10-30 15:24 UTC, scholzb-hb
Details

Note You need to log in before you can comment on or make changes to this bug.
Description scholzb-hb 2020-10-30 15:24:13 UTC
Created attachment 37541 [details]
Example Maven project to reproduce the issue

== 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 consequences, the occurrence of an uncaught exception may remain undetected since it appears in no log file.

== Steps to reproduce ==
1. Install Tomcat as a Windows Service with default settings
2. Build attached Maven project uncaught-exception-sample and deploy WAR file into Tomcat
3. Restart Tomcat
4. Inspect file logs/tomcat8-stderr-<date>.log every few seconds

== Expected behavior ==
When startup is finished, the file should contain:

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 main thread
Message 1 from main thread
Message 2 from main thread
Message 3 from main thread
Message 4 from main thread
Message 5 from main thread
Message 6 from main thread
Message 7 from main thread
Message 8 from main thread
Message 9 from main thread
Exception in thread "Thread-4" java.lang.RuntimeException: exception thrown from thread
	at org.example.ContextLoaderListener.lambda$contextInitialized$0(ContextLoaderListener.java:17)
	at java.lang.Thread.run(Thread.java:748)
Message 10 from main thread
Message 11 from main thread
Message 12 from main thread
Message 13 from main thread
Message 14 from main thread
Message 15 from main thread
Message 16 from main thread
Message 17 from main thread
Message 18 from main thread
Message 19 from main 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
...

== 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:

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
...

The message about the uncaught exception is gone.

== 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:
1. 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
2. In javajni.c, __apxJavaWorkerThread():
- the main class org.apache.catalina.startup.Bootstrap is loaded
3. In javajni.c, apxJavaSetOut():
- Log file is opened again and System.err is adjusted, via reflection (Java code): System.setErr(new PrintStream(new FileOutputStream(filename), true));

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.
Comment 1 Mark Thomas 2020-10-30 15:46:07 UTC
This bug needs to be raised against the Commons Daemon project.
Comment 2 scholzb-hb 2020-10-31 14:20:53 UTC
Thanks for the quick response. New issue: https://issues.apache.org/jira/browse/DAEMON-424