заставить slf4j печатать логи в последовательности - PullRequest
Новая
       16

заставить slf4j печатать логи в последовательности

5 голосов
/ 21 февраля 2012

Я использую slf4j для выхода из системы.Иногда журналы не распечатываются в порядке (отметка времени).Можем ли мы заставить его регистрироваться в том же порядке, в котором выполняется код?

Обновление 1 : это происходит при запуске модульных тестов на Jenkins через maven.Это происходит последовательно.Сначала поступают операторы журнала из кода, а затем поступают операторы журнала из модульного теста.

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

  <appender name="STDOUT"
            class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">

Обновление 2 : фрагменты журнала похожи на это (я редактировал имя файла и т. д.).Во время выполнения test1 мы вызываем код для отмены транзакции, которая не удалась из-за какой-то ошибки.Но странно то, что сначала печатается исключение, а затем печатаются операторы журнала из методов тестирования.Кроме того, временные метки операторов журнала соответствуют ожидаемым, но порядок их в файле отличается (14: 33: 34. 718 предшествует 14: 33: 34. 449 ) 

14:33:34.667 [869082978@qtp-1587505558-0] [] WARN  org.hibernate.ejb.Ejb3Configuration - hibernate.connection.autocommit = false break the EJB3 specification
14:33:34.718 [869082978@qtp-1587505558-0] [] WARN  o.h.impl.SessionFactoryObjectFactory - InitialContext did not implement EventContext
14:33:34.843 [869082978@qtp-1587505558-0] [] DEBUG c.r.a.exception.ExceptionMapper - <3003> can't reverse transaction. [id=10000000100120014]
.
.
.
.
.
14:33:34.158 [main] [] DEBUG c.r.a.test - ========================= test0: finished.
14:33:34.158 [main] [] DEBUG c.r.a.test - ========================= test1: started.
.
.
.
.
14:33:34.449 [main] [] DEBUG c.r.a.test - reversing transaction, id=10000000100120014
14:33:34.856 [main] [] DEBUG c.r.a.test - ========================= test2: started.

Обновление 3 : в нашем проекте используется maven и имеется несколько модулей.У нас есть logback-test.xml в папке src/test/resources.

Структура проекта выглядит следующим образом
codemodule/src/test/resources/logback-test.xml - этот модуль будет упакован в файл jar.В тестовом примере вызывается код этого модуля.
parent/src/test/resources/logback-test.xml - это родительский модуль, который упаковывает jar-файлы и пакеты всех других модулей в войну.Здесь у меня запущен тестовый пример, и он вызывает код выше модуля.

У меня есть записи журнала как в коде тестового примера, так и в реальном коде.Я проверил, что и тестовый пример, и код используют шаблон из файла журнала родителя (шаблон в кодовом модуле отличается).Он последовательно печатает операторские записи кода перед печатью журналов тестовых примеров.

Также мы не проводим параллельные тесты.
Concurrency config is parallel='none', perCoreThreadCount=true, threadCount=2, useUnlimitedThreads=false

Обновление 4 : я понимаюэта проблема.Мы делаем запрос http, а не прямой вызов метода.Таким образом, тестовые случаи выполняются в потоке main, а реальный код выполняется в другом потоке (спасибо Sebbe).

Я понимаю, что принудительная последовательность ведения журнала может привести к снижению производительности, но для полноты вопроса я задам еще одинвопрос.

Поскольку оба журнала отправляются одному приложению (STDOUT), могу ли я заставить его регистрироваться в порядке отметки времени?

1 Ответ

2 голосов
/ 28 февраля 2012

В самом журнале видно, что у вас запущено как минимум 2 потока: 869082978@qtp-1587505558-0 и main.

Вы не можете контролировать порядок, в котором отдельные потоки записывают свои события на один и тот же вывод (вы, вероятно, можете, но это было бы плохой идеей).

Из вашей ветки журнала 869082978@qtp-1587505558-0 сначала получает доступ на запись к вашей консоли.Во время записи события регистрируются с main.Как только 869082978@qtp-1587505558-0 снимает блокировку, main получает ее и может сбрасывать свои журналы в файл.

...