log-back and thirdparty writing to stdout. How to stop them getting interleaved.

Question

First some background. I have a batch-type java process run from a DOS batch script. All the java logging goes to stdout, and the batch script redirects the stdout to a file. (This is good for me because I can ECHO from the script and it gets into the log file, so I can see all the java JVM command line args, which is great for debugging.) I may not

I use slf4j API, and for the backend I used to use log4j, but recently switched to logback-classic.

Although all my application code uses slf4j, I have a third party library that does it's own logging (not using a standard API) which also gets written to stdout.

The problem is that sometimes log lines get mixed up and don't cleanly appear on separate lines. Here is an example of some messed up output:

2010-05-28 18:00:44.783 [thread-1       ] INFO  CreditCorrelationElementBuilderImpl - Bump parameters exist for scenario, now attempting bumping. [indexDisplayName=STANDARD_S1_v300]
2010-05-28 18:01:43.517 [thread-1       ] INFO  CreditCorrelationElementBuilderImpl - Found adjusted point in data, now applying bump. [point=0.144040000000000]
2010-05-28 18:01:58.642 [thread-1       ] DEBUG com.company.request.Request         - Generated request for [dealName=XXX_20050225_01[5],dealType=GENERIC_XXX,correlationType=2,copulaType=1] in 73.8 s, Simon Stopwatch: [sys1.batchpricer.reqgen.gen INHERIT] total 1049 s, counter 24, max 74.1 s, min 212 ms
2010-05-28 18:05/28/10 18:02:20.236 INFO: [ServiceEvent] SubmittedTask:BC-STRESS_04_FZBC-2010-05-21-545024448189310126-23
01:58.658 [req-writer-2b   ] INFO  .c.g.r.o.OptionalFileDocumentOutput - Writing request XML to \\filserver\dir\file1.xml - write time: 21.4 ms - Simon Stopwatch: [sys1.batchpricer.reqgen.writeinputfile INHERIT] total 905 ms, counter 24, max 109 ms, min 10.8 ms
2010-05-28 18:02:33.626 [ResponseCallbacks-1: DriverJobSpace$TakeJobRunner$1] ERROR c.c.s.s.D.CalculatorCallback        - Id:23 no deal found !!
2010-0505/28/10 18:02:50.267 INFO: [ServiceEvent] CompletedTask:BC-STRESS_04_FZBC-2010-05-21-545024448189310126-23:Total:24

Now comparing back to older log files, it seems the problem didn't occur when using log4j as the logging backend. So logback must be doing something different.

The problem seems to be that although PrintStream.write(byte buf[], int off, int len) is synchronized, however I can see in ch.qos.logback.core.joran.spi.ConsoleTarget that System.out.write(int b) is the only write method called.

So inbetween logback outputting each byte, the thirdparty library is managing to write a whole string to the stdout. (Not only is this cause me a problem, but it must also be a little inefficient?)

Is there any other fix to this interleaving problem than patching the code to ConsoleTarget so it implments the other write methods? Any nice work arounds. Or should I just file a bug report?

Here is my logback.xml:

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-16thread] %-5level %-35.35logger{30} - %msg%n</pattern>
        </encoder>
    </appender>
    <root level="DEBUG">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

I'm using logback 0.9.20 with java 1.6.0_07.

Answer 1

It looks like you have two different log configurations writing to the STDOUT. The pattern of these two seems to be very different when trying to decode the mess:

2010-05-28 18:01:58.658 [req-writer-2b   ] INFO  .c.g.r.o.OptionalFileDocumentOutput - Writing request XML to \\filserver\dir\file1.xml - write time: 21.4 ms - Simon Stopwatch: [sys1.batchpricer.reqgen.writeinputfile INHERIT] total 905 ms, counter 24, max 109 ms, min 10.8 ms
05/28/10 18:02:20.236 INFO: [ServiceEvent] SubmittedTask:BC-STRESS_04_FZBC-2010-05-21-545024448189310126-23

The second line seems to be using the default pattern in stead of your definition. Is there a logger loaded somewhere that uses the default configuration instead of your XML configuration?

Answer 2

In such case I would go through System.setOut(PrintStream out) for the given 3rd party lib that does not behave. Implement a thread that would read this stream of log split it it say by new line and spit it to the logging solution that you use. Just be careful not to start reading and writing to the same thread :-) this is what you do:

• You get the System.out stream save it aside
• You configure your logger to use this stream see OutputStreamAppender
• You create a thread that drains a stream that you assign as new System.out (your 3rd party lib will write there) and send well formatted output to the log

You got yourself a pretty log that in sync more or less with what happens in the system

Answer 3

In the end fixing the underlying issue was easier than any workaround.

Patch for fix: http://gist.github.com/434516

Bug raise in logback jira: http://jira.qos.ch/browse/LBCORE-158