You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2020/10/30 15:24:13 UTC

[Bug 64863] New: stderr logfile is corrupted when running as Windows service

https://bz.apache.org/bugzilla/show_bug.cgi?id=64863

            Bug ID: 64863
           Summary: stderr logfile is corrupted when running as Windows
                    service
           Product: Tomcat 8
           Version: 8.5.59
          Hardware: PC
            Status: NEW
          Severity: normal
          Priority: P2
         Component: Meta
          Assignee: dev@tomcat.apache.org
          Reporter: scholzb-hb@outlook.de
  Target Milestone: ----

Created attachment 37541
  --> https://bz.apache.org/bugzilla/attachment.cgi?id=37541&action=edit
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.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 64863] stderr logfile is corrupted when running as Windows service

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=64863

--- Comment #2 from scholzb-hb <sc...@outlook.de> ---
Thanks for the quick response. New issue:
https://issues.apache.org/jira/browse/DAEMON-424

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 64863] stderr logfile is corrupted when running as Windows service

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=64863

Mark Thomas <ma...@apache.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 OS|                            |All
         Resolution|---                         |INVALID
             Status|NEW                         |RESOLVED

--- Comment #1 from Mark Thomas <ma...@apache.org> ---
This bug needs to be raised against the Commons Daemon project.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org