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