Home / server / Questions / 103293
Accepted
Chris
Asked: 2010-01-16 17:30:55 +0800 CST

Why is Windows Tomcat handling stdout differently if it's from webapp vs from JVM?

  • 772

I'm running Tomcat 6 under Windows, using the bundled Windows service runner. I seem to have the following behavior:

  • If one of my webapps writes to stdout (via, say, System.out.println), then this output shows up verbatim in logs titled like stdout_xxx.log.
  • If the jvm itself writes to stdout (as it does if you enable -XX:+PrintCompilation), then this output shows up in logs titled like jakarta_service_xxx.log.

Also, jakarta_service_xxx.log is not a direct dump of stdout; rather, something seems to be intercepting stdout and redirecting that through java logging. Thus whereas the JVM, running free of Tomcat, would normally print

283 s java.lang.StringBuffer::length (5 bytes)

what shows up in jakarta_service_xxx.log is this:

[2010-01-15 17:07:15] [info] 283
[2010-01-15 17:07:15] [info]  s    
[2010-01-15 17:07:15] [info]  java.lang.StringBuffer::
[2010-01-15 17:07:15] [info] l
[2010-01-15 17:07:15] [info] e
[2010-01-15 17:07:15] [info] n
[2010-01-15 17:07:15] [info] g
[2010-01-15 17:07:15] [info] t
[2010-01-15 17:07:15] [info] h
[2010-01-15 17:07:15] [info]  (5 bytes)

Can you clarify why stdout would be getting treated differently in the two cases? Alternatively, any hints on how to get the JVM output from -XX:+PrintCompilation to show up in stdout.log, instead of as the above craziness?

windows tomcat java logging

2 Answers

  1. Best Answer

    Without digging into the guts of Tomcat to be sure, I think that the sequence will be something like this.

    1. A new process for the JVM is launched, passing 'stdin', 'stdout' and 'stderr' file descriptors. These will typically be set up by the calling shell and passed to the JVM across the fork/exec syscalls. (Or whatever the Windows equivalent is ...) But in this case, there is some wrapper script or native application that redirects 'stdout' to "jakarta_service_xxx.log" before the JVM is launched.

    2. The JVM creates some internal logging system (implemented in native code) that will be used by the GC and other JVM services for JVM logging. This will use the 'stdout' or 'stderr' file descriptors.

    3. The JVM creates PrintStream(OutputStream) objects that wrap 'stdout' and 'stderr' file descriptors and sets java.lang.System.out and java.lang.System.err to these objects respectively.

    4. The JVM calls the Tomcat main method to start Tomcat.

    5. Tomcat opens a new FileOutputStream to "stdout_xxx.log" and uses java.lang.System.setOut() to update java.lang.System.out. If there are different "stdout_xxx.log" files for each webapp, then it is likely that Tomcat has implemented a clever output stream proxy that demuxes output to different log files based on thread groups or something ...

    I suspect that the JVM logging is not using java.util.Logging ... or any Java code at all. It just looks like it is. I say this because I think the JVM would get into knots if it tried to call into Java code at certain points; for example at critical points in the GC. But I might be wrong about this ...

    As to WHY this is happening, I think it is happening because it is generally a good idea to separate "System.out/err" output coming from the webapps and from the jvm / tomcat core. There are probably configuration files etc that allow you to change this ... if you want to.

    • 1

  2. You generally want to have log output separated by webapp, and also separated from container-internal messages (such as JVM diagnostic messages).

    In addition to supporting the various logging frameworks, Tomcat also captures System.out and System.err and redirects them to the appropriate log file.

    You should be able to configure the exact behaviour and formatting in Tomcat's configuration files (more on that over on Serverfault...)

    • 0