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.
