【问题标题】:force slf4j to print logs in sequence强制 slf4j 依次打印日志
【发布时间】:2012-03-11 17:58:34
【问题描述】:

我在 log-back 上使用 slf4j。有时日志没有按顺序打印(时间戳)。 我们可以强制它以与代码运行相同的顺序登录吗?

更新 1:通过 maven 在 Jenkins 上运行单元测试时会发生这种情况。它一直在发生。来自代码的第一个日志语句即将到来,然后来自单元测试的日志语句即将到来。

所有的 logback 文件看起来都很正常,如下所示。

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

Update 2:log sn-ps 是这样的(我已经编辑了文件名等)。在 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,有多个模块。我们在src/test/resources 文件夹中有logback-test.xml

项目结构是这样的
codemodule/src/test/resources/logback-test.xml - 这个模块会被打包成jar文件。测试用例调用此模块的代码。
parent/src/test/resources/logback-test.xml - 这是将所有其他模块的 jar 文件和包包装成战争的父模块。这是我运行测试用例的地方,它调用上面的模块代码。

我在测试用例代码和实际代码中都有日志语句。我已经检查过测试用例和代码都使用父级 logback 文件中的模式(代码模块中的模式不同)。 它在打印测试用例的日志之前始终打印代码的日志语句。

另外,我们没有并行运行测试。
Concurrency config is parallel='none', perCoreThreadCount=true, threadCount=2, useUnlimitedThreads=false

更新 4:我了解问题所在。我们正在发出一个 http 请求,而不是直接的方法调用。所以测试用例在 main 线程中运行,实际代码在另一个线程中运行(感谢 Sebbe)。

我知道强制记录顺序可能会影响性能,但为了问题的完整性,我会再问一个问题。

由于两个日志都将转到单个附加程序(STDOUT),我可以强制它按时间戳顺序登录吗?

【问题讨论】:

  • 你是说在你的日志中你看到消息混合时间戳(没有增长?)从未见过这样的现象。您使用的是哪个附加程序?
  • @TomaszNurkiewicz 是的,我正在使用 ch.qos.logback.core.ConsoleAppender
  • 你使用并发吗?这可能是一个原因。另外,你能提供一个日志摘录
  • @Fixpoint,不,我们不使用 junit/surefire 的并行执行。我可以提供日志摘录,但我不确定它有什么帮助。
  • 我会帮助您了解“代码中的日志语句”和“测试中的日志语句”的确切含义。 :)

标签: java maven junit slf4j logback


【解决方案1】:

从您的日志本身中,您可以看到至少有 2 个线程在运行: 869082978@qtp-1587505558-0main

您无法控制不同线程将其事件记录到同一输出的顺序(您可能可以,但这是个坏主意)。

从您的日志线程869082978@qtp-1587505558-0 首先获得对您的控制台的写入权限。在写入时,事件会从main 记录下来。一旦869082978@qtp-1587505558-0 释放它的锁,main 就会得到它,它可以将它的日志刷新到文件中。

【讨论】:

  • 谢谢 Sebbe,这可能是问题所在。但我仍然需要检查为什么它会持续发生以及869082978@qtp-1587505558-0 的来源。
  • 我遇到了这个问题,但是还有另一个问题。更新 (#4) 问题。
猜你喜欢
  • 2013-01-21
  • 1970-01-01
  • 2017-06-20
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 2015-07-08
  • 1970-01-01
相关资源
最近更新 更多