logowanie i tworzenie stron trzecich na standardowe wyjście. Jak powstrzymać ich przed przeplotem?

Question

Najpierw trochę tła. Mam proces java typu wsadowego uruchamiany ze skryptu wsadowego DOS. Wszystkie dzienniki java przechodzą na standardowe wyjście, a skrypt wsadowy przekierowuje standardowe wyjście do pliku. (To jest dobre dla mnie, ponieważ mogę ECHO ze skryptu i dostaje się do pliku dziennika, więc widzę wszystkie argumenty JVM wiersza poleceń Javy, co jest świetne do debugowania.) Nie mogę

Używam slf4j API, a dla zaplecza użyłem log4j, ale ostatnio przełączyłem się na logback-classic.

Mimo że cały mój kod aplikacji używa slf4j, mam bibliotekę innej firmy, która wykonuje własne rejestrowanie (nie używając standardowego API), która również jest zapisywana na stdout.

Problem polega na tym, że czasami linie dzienników mieszają się i nie pojawiają się w osobnych wierszach. Oto przykład z jakiegoś zawiedli wyjścia:

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 

Teraz porównując z powrotem do starszych plików dziennika, wydaje się, że problemem nie występują podczas używania log4j jako backend rejestrowania. Więc logback musi być robiący coś innego.

Problem wydaje się, że chociaż PrintStream.write(byte buf[], int off, int len) jest zsynchronizowany, jednak widzę w ch.qos.logback.core.joran.spi.ConsoleTarget that System.out.write(int b) jest jedyną metodę zapisu o nazwie.

Tak więc pomiędzy raportowaniem logarytmicznym każdego bajtu, biblioteka trzeciej strony jest w stanie napisać cały ciąg do standardowego wyjścia. (Nie tylko jest to przyczyną problemu, ale również musi być trochę nieefektywna?)

Czy jest jakakolwiek inna poprawka do tego problemu przeplatania niż łatanie kodu do ConsoleTarget, aby implementował inne metody zapisu? Dobra robota wokół. Czy powinienem po prostu złożyć raport o błędzie?

Oto moja 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> 

Używam logback 0.9.20 z Java 1.6.0_07.

Answer 1

W ustalaniu końcowej podstawowy problem był łatwiejszy niż jakiekolwiek obejście tego problemu.

poprawki do poprawki: http://gist.github.com/434516

Bug podnieść w logback JIRA: http://jira.qos.ch/browse/LBCORE-158

Answer 2

Wygląda na to, że masz dwie różne konfiguracje dzienników, pisząc do STDOUT. Wzór tych dwóch wydaje się być bardzo różny, gdy próbuje dekodować bałagan:

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 

Druga linia wydaje się być przy użyciu domyślnego wzorca zamiast swojej definicji. Czy jest gdzieś ładowany program rejestrujący, który używa domyślnej konfiguracji zamiast konfiguracji XML?

Answer 3

W takim przypadku przechodzę przez System.setOut (PrintStream na zewnątrz) dla danej biblioteki, która nie zachowuje się. Zaimplementuj wątek, który odczytałby ten strumień dziennika, podziel go przez nową linię i wypluj go do używanego rozwiązania rejestrowania. Wystarczy być ostrożnym, aby nie rozpocząć czytania i pisania do tego samego wątku :-) to co robisz:

• uzyskać strumień System.out zapisać go na bok
• skonfigurować swój rejestrator aby skorzystać z tej stream zobacz OutputStreamAppender
• Tworzysz wątek, który wyczerpuje strumień, który przypisujesz jako nowy system.out (Twój 3rd party lib będzie tam pisać) i wysłać dobrze sformatowany wyjście do dziennika

Masz sobie ładną dziennik, który w synchronizacji mniej lub bardziej z tym, co się dzieje w systemie