8

首先是一些背景。我有一个从 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 输出每个字节之间，第三方库正在设法将整个字符串写入标准输出。（这不仅给我带来了问题，而且它一定也有点低效？）

除了将代码修补到 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 一起使用。

4

3 回答 3

2

在这种情况下，我将通过 System.setOut(PrintStream out) 为给定的不行为的第 3 方库。实现一个线程，该线程将读取此日志流，将其拆分为新行并将其吐出到您使用的日志记录解决方案中。请注意不要开始读取和写入同一个线程 :-) 这就是你要做的：

  • 你得到 System.out 流，把它放在一边
  • 您将记录器配置为使用此流，请参阅OutputStreamAppender
  • 您创建一个线程来排出您分配为新 System.out 的流（您的第 3 方库将在那里写入）并将格式正确的输出发送到日志

你得到了一个漂亮的日志，它或多或少与系统中发生的事情同步

于 2010-06-06T22:54:59.733 回答
2

最后，解决根本问题比任何解决方法都容易。

修复补丁： http: //gist.github.com/434516

logback jira 中的错误提升：http: //jira.qos.ch/browse/LBCORE-158

于 2010-06-11T14:22:59.680 回答
0

看起来您有两种不同的日志配置写入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 配置的记录器？

于 2010-06-06T12:41:32.460 回答