вход в систему и запись третьей стороной в стандартный вывод. Как остановить их чередование

Question

Сначала немного фона. У меня есть Java-процесс пакетного типа, запускаемый из пакетного сценария DOS. Все журналы Java отправляются на стандартный вывод, а пакетный скрипт перенаправляет стандартный вывод в файл. (Это хорошо для меня, потому что я могу ECHO из сценария, и он попадает в файл журнала, поэтому я могу видеть все аргументы командной строки java JVM, что отлично подходит для отладки.) Я не могу

Я использую slf4j API, а для бэкэнда я использовал log4j, но недавно переключился на logback-classic.

Хотя весь код моего приложения использует slf4j, у меня есть сторонняя библиотека, которая ведет свою собственную регистрацию (не использует стандартный API), которая также записывается в стандартный вывод.

Проблема в том, что иногда строки журнала перепутываются и не отображаются чисто в отдельных строках. Вот пример некоторого испорченного вывода:

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

Теперь, сравнивая со старыми файлами журналов, кажется, что проблема не возникла при использовании log4j в качестве бэкэнда ведения журнала. Так что logback должен делать что-то другое.

Проблема, похоже, заключается в том, что хотя PrintStream.write(byte buf[], int off, int len) синхронизирован, я вижу в ch.qos.logback.core.joran.spi.ConsoleTarget that System.out.write(int b) единственный вызываемый метод записи.

Таким образом, между logback, выводящим каждый байт, сторонней библиотеке удается записать целую строку в стандартный вывод. (Это не только вызывает у меня проблемы, но и должно быть немного неэффективно?)

Есть ли другое решение этой проблемы чередования, кроме исправления кода в ConsoleTarget, чтобы оно влияло на другие методы записи? Любая хорошая работа вокруг. Или я должен просто подать отчет об ошибке?

Вот мой 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>

Я использую logback 0.9.20 с Java 1.6.0_07.

Answer 1

В таком случае я бы прошел System.setOut (PrintStream out) для данной сторонней библиотеки, которая не ведет себя. Реализуйте поток, который будет читать этот поток журнала, разделить его, скажем, на новую строку и плюнуть на используемое вами решение для ведения журнала. Только будьте осторожны, чтобы не начать читать и писать в одной теме :-) это то, что вы делаете:

• Вы получаете поток System.out и сохраняете его в стороне
• Вы настроили свой регистратор для использования этого потока, см. OutputStreamAppender
• Вы создаете поток, который сливает поток, который вы назначаете как новый System.out (ваша сторонняя библиотека будет писать там), и отправляете хорошо отформатированный вывод в журнал

У вас есть симпатичный журнал, который более или менее синхронизируется с тем, что происходит в системе

Answer 2

В конце концов, исправить основную проблему оказалось проще, чем любой обходной путь.

Патч для исправления: http://gist.github.com/434516

Ошибка поднятия в logback jira: http://jira.qos.ch/browse/LBCORE-158

Answer 3

Похоже, у вас есть две разные конфигурации журнала, записывающие в STDOUT.Кажется, что эти два шаблона очень сильно различаются при попытке декодировать беспорядок:

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

Вторая строка, похоже, использует шаблон по умолчанию вместо вашего определения.Есть ли загруженный регистратор, который использует конфигурацию по умолчанию вместо вашей конфигурации XML?