log-back和第三方向标准输出写入的问题。如何防止它们交错。

Question

首先介绍一下背景。我有一个从DOS批处理脚本运行的Java批处理程序，所有的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输出每个字节之间，第三方库成功将整个字符串写入stdout。（这不仅是给我带来了问题，而且可能也有点低效吧？）

除了修补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>

我正在使用Java 1.6.0_07和logback 0.9.20。

- David Roussel

---

嗯，我的预格式化代码块在传输时变成了一行，但在预览中是正常的！唔！ - David Roussel

David，你可以再次编辑这个问题，必要时使用逐字逐句的方式。 - Hamish Grubijan

你有verbatim的参考或示例吗？你是指使用非代码块吗？ - David Roussel

这是一个多线程问题 - 参见线程名称 - 除非您可以同步实际的写入语句，否则您很可能无法修复它，只要您写入到标准输出。考虑将事物分离成单独的文件，或者勇敢地修复日志记录。如果您可以让所有组件桥接到slf4j，则问题得以解决。 - Thorbjørn Ravn Andersen

是的，这是一个多线程问题，但我已经解决了它。请参见下面的补丁。它现在已合并到Logback的发布版本中。 - David Roussel

Answer 1

在这种情况下，我会通过System.setOut(PrintStream out)来处理那些无法正常工作的第三方库。实现一个线程，读取日志流并将其按照换行符进行分割，然后将其发送到您使用的日志记录解决方案中。但是要小心不要开始读写同一个线程:-)

具体步骤如下：

• 获取System.out流并保存
• 配置您的日志记录器以使用此流，参见OutputStreamAppender
• 创建一个线程，将一个新的System.out流（您的第三方库将在其中写入）分配给该线程，并将格式化输出发送到日志记录器中

这样，您就可以拥有一个与系统事件更或多或少同步的漂亮日志了。

- Boris Daich

---

谢谢Boris，你的想法很好，但是它比修复代码问题更费力。我已经点赞了，但没有接受你的答案。 - David Roussel

Answer 2

最终修复根本问题比任何解决方法都更容易。

修复补丁：http://gist.github.com/434516 在logback jira中提出的错误：http://jira.qos.ch/browse/LBCORE-158

- David Roussel

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 配置？

- Marc

---

另一个模式来自第三方库。但困扰我的不是这个模式，而是混乱的行。没关系，我现在已经修补了logback以解决这个问题。谢谢。 - David Roussel