Bernhard Scholz created DAEMON-424:
--------------------------------------
Summary: 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
Attachments: 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 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
...
{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): 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.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
