日志返回和第三方写入标准输出。如何阻止它们交错

发布于 2024-09-04 05:22:49 字数 2572 浏览 4 评论 0原文

首先是一些背景知识。我有一个从 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 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。

原文

First some background. I have a batch-type java process run from a DOS batch script. All the java logging goes to stdout, and the batch script redirects the stdout to a file. (This is good for me because I can ECHO from the script and it gets into the log file, so I can see all the java JVM command line args, which is great for debugging.) I may not

I use slf4j API, and for the backend I used to use log4j, but recently switched to logback-classic.

Although all my application code uses slf4j, I have a third party library that does it's own logging (not using a standard API) which also gets written to stdout.

The problem is that sometimes log lines get mixed up and don't cleanly appear on separate lines. Here is an example of some messed up output:

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

Now comparing back to older log files, it seems the problem didn't occur when using log4j as the logging backend. So logback must be doing something different.

The problem seems to be that although PrintStream.write(byte buf[], int off, int len) is synchronized, however I can see in ch.qos.logback.core.joran.spi.ConsoleTarget that System.out.write(int b) is the only write method called.

So inbetween logback outputting each byte, the thirdparty library is managing to write a whole string to the stdout. (Not only is this cause me a problem, but it must also be a little inefficient?)

Is there any other fix to this interleaving problem than patching the code to ConsoleTarget so it implments the other write methods? Any nice work arounds. Or should I just file a bug report?

Here is my 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>

I'm using logback 0.9.20 with java 1.6.0_07.

分享到QQ

分享到微博

如果你对这篇内容有疑问，欢迎到本站社区发帖提问参与讨论，获取更多帮助，或者扫码二维码加入 Web 技术交流群。

发布评论

需要登录才能够评论，你可以免费注册一个本站的账号。

英雄似剑 2024-09-11 05:22:49

在这种情况下，我将通过 System.setOut(PrintStream out) 查找不正常行为的给定第 3 方库。实现一个线程，该线程将读取此日志流，将其按换行符分割，并将其吐出到您使用的日志记录解决方案。
只是要小心不要开始读取和写入同一线程:-)
这就是您要做的：

您获取 System.out 流，将其保存在一边
您配置记录器以使用此流，请参阅 OutputStreamAppender
您创建一个线程，用于排出您指定为新 System.out 的流（您的第 3 方库将写入其中）并将格式良好的输出发送到日志

您为自己准备一个漂亮的日志，或多或少与系统中发生的情况同步

回复收藏 0 原文

懵少女 2024-09-11 05:22:49

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

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

logback jira 中引发的错误：< a href="http://jira.qos.ch/browse/LBCORE-158" rel="nofollow noreferrer">http://jira.qos.ch/browse/LBCORE-158

回复收藏 0 原文

调妓 2024-09-11 05:22:49

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

It looks like you have two different log configurations writing to the STDOUT. The pattern of these two seems to be very different when trying to decode the mess:

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

The second line seems to be using the default pattern in stead of your definition. Is there a logger loaded somewhere that uses the default configuration instead of your XML configuration?

回复收藏 0 原文

~没有更多了~