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

Сначала немного предыстории. У меня есть процесс java пакетного типа, запущенный из пакетного сценария DOS. Все журналы Java отправляются на стандартный вывод, а пакетный скрипт перенаправляет стандартный вывод в файл. (Это хорошо для меня, потому что я могу ЭХО из сценария, и он попадает в файл журнала, поэтому я могу видеть все аргументы командной строки 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) вызывается единственный метод записи.

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

Есть ли какое-либо другое решение этой проблемы чередования, кроме исправления кода для 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.


person David Roussel    schedule 04.06.2010    source источник
comment
Хм, мои предварительно отформатированные блоки кода отображаются одной строкой, но в предварительном просмотре все было в порядке! Хамф!   -  person David Roussel    schedule 04.06.2010
comment
Дэвид, вы можете снова отредактировать этот вопрос, используя дословно, если необходимо.   -  person Hamish Grubijan    schedule 04.06.2010
comment
Есть ссылка или пример дословно? Вы имеете в виду использование некодового блока?   -  person David Roussel    schedule 04.06.2010
comment
Это проблема многопоточности — см. имена потоков — и вы, скорее всего, не сможете ее исправить, пока будете писать в стандартный вывод, если только вы не можете синхронизировать фактические операторы записи. Подумайте о том, чтобы разделить вещи на отдельные файлы или стиснуть зубы и исправить ведение журнала. Если вы можете подключить все компоненты к slf4j, ваша проблема решена.   -  person Thorbjørn Ravn Andersen    schedule 05.03.2014
comment
Да, это была проблема с многопоточностью, но я ее исправил. Смотрите мой патч ниже. Теперь он объединен с релизной версией logback.   -  person David Roussel    schedule 12.03.2014


Ответы (3)


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

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

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

person Boris Daich    schedule 06.06.2010
comment
Спасибо, Борис, у вас была хорошая идея, к сожалению, это было больше работы, чем исправление проблемы с кодом. Я проголосовал, но не принял ваш ответ. - person David Roussel; 11.06.2010

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

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

Исправление ошибки в журнале jira: http://jira.qos.ch/browse/LBCORE-158< /а>

person David Roussel    schedule 11.06.2010

Похоже, у вас есть две разные конфигурации журнала, записывающие в файл 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?

person Marc    schedule 06.06.2010
comment
Другой шаблон исходит из сторонней библиотеки. Но меня смущает не узор, а перепутанные линии. Неважно, я пропатчил logback, чтобы исправить проблему сейчас. Спасибо. - person David Roussel; 11.06.2010