Details
Major Description
Note: This issue has originally been reported under https://bz.apache.org/bugzilla/show_bug.cgi?id=64863 for the Tomcat 8 project.
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.
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
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 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 ...
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:
- 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)));
- Log file is opened again and System.err is adjusted, via reflection (Java code):
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.
Attachments
Attachments
Issue Links
- links to