Log-back und ThirdParty Schreiben auf stdout. Wie man sie stoppt, verschachtelt zu erhalten

Question

Zuerst etwas Hintergrund. Ich habe einen Batch-Java-Prozess von einem DOS-Batch-Skript ausgeführt. Die gesamte Java-Protokollierung wird auf "stdout" gesetzt und das Stapel-Skript leitet die stdout-Datei in eine Datei um. (Dies ist gut für mich, weil ich ECHO aus dem Skript kann und es in die Protokolldatei, so dass ich alle Java JVM Befehlszeilenargumente sehen kann, die für das Debuggen ist.) Ich kann nicht

Ich benutze slf4j API, und für das Backend verwendete ich log4j, aber vor kurzem zu Logback-Classic gewechselt.

Obwohl alle meine Anwendung Code slf4j verwendet, habe ich eine Drittanbieter-Bibliothek, die ihre eigene Protokollierung (nicht mit einer Standard-API), die auch in stdout geschrieben wird.

Das Problem ist, dass manchmal Protokollzeilen durcheinander geraten und nicht sauber in separaten Zeilen angezeigt werden. Hier ist ein Beispiel von etwas verkorksten Ausgabe:

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 

Nun zurück zu älteren Protokolldateien zu vergleichen, wie es scheint das Problem nicht auftreten, wenn log4j als Logging-Backend verwenden. Logback muss also etwas anderes machen.

Das Problem scheint zu sein, dass zwar PrintStream.write(byte buf[], int off, int len) synchronisiert ist, aber ich kann in ch.qos.logback.core.joran.spi.ConsoleTarget that System.out.write(int b) sehen ist die einzige Schreibmethode genannt.

Da zwischen logback Logging jedes Byte ausgibt, verwaltet die ThirdParty-Bibliothek eine ganze Zeichenfolge in den Stdout. (Das ist nicht nur ein Problem, sondern auch ein wenig ineffizient?)

Gibt es eine andere Lösung für dieses Interleaving-Problem, als den Code an ConsoleTarget zu patchen, damit er die anderen Schreibmethoden unterstützt? Irgendwelche netten Arbeitsumgebungen. Oder sollte ich einfach einen Fehlerbericht einreichen?

Hier ist meine 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> 

Ich verwende logback 0.9.20 mit Java 1.6.0_07.

Answer 1

Am Ende Befestigungs Das zugrunde liegende Problem war einfacher als jede Umgehungslösung.

Patch für fix: http://gist.github.com/434516

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

Answer 2

Es sieht so aus, als hätten Sie zwei verschiedene Protokollkonfigurationen, die an die STDOUT schreiben. Das Muster dieser beiden scheint sehr unterschiedlich zu sein, wenn sie versuchen, das Chaos zu entschlüsseln:

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 

Die zweite Zeile scheint anstelle von Ihrer Definition die Standardmuster zu verwenden. Wird irgendwo ein Logger geladen, der anstelle der XML-Konfiguration die Standardkonfiguration verwendet?

Answer 3

In diesem Fall würde ich System.setOut (PrintStream out) für die angegebene 3rd Party Lib gehen, die sich nicht verhält. Implementieren Sie einen Thread, der diesen Protokollstrom lesen würde, teilen Sie ihn mit einer neuen Zeile und spucken Sie ihn in die Protokollierungslösung, die Sie verwenden. Nur vorsichtig sein, nicht zu starten Lesen und Schreiben auf dem gleichen Thread :-) das ist, was Sie tun können:

• Sie die System.out Strom erhalten, speichern Sie es beiseite
• konfigurieren Sie Ihren Logger dies zu nutzen Stream siehe OutputStreamAppender
• Sie erstellen einen Thread, der einen Stream ableitet, den Sie als neues System zuweisen.aus (Ihr 3rd-Party-lib dort schreiben wird) und

Sie haben selbst ein ziemlich lügen gut formatierte Ausgabe in das Protokoll senden, dass synchron mehr oder weniger mit dem, was im System passiert