为什么日志使用logback包含空字符(空洞)

Question

我在我的应用程序中使用logback(SiftingAppender和RollingFileAppender)。当请求进入时，它们将根据url查询中的id被记录到不同的文件中。

这真的很好用，我得到了预期的结果。然而，我偶尔注意到，在日志中间有一些空字符。我不确定为什么会发生这种情况，以及如何减少这种情况。

我做了一些研究，我发现最接近的东西是https://serverfault.com/questions/71341/why-do-jboss-and-logrotate-create-log-files-full-of-nul-characters

他们将logrotate与log4j一起使用，这会导致空字符。但是，在我的例子中，整个日志轮换和生命周期都由logback处理。

这是我的logback xml配置的一部分：

<appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
<discriminator>
  <key>id</key>
  <defaultValue>main</defaultValue>
</discriminator>
<sift>
  <appender name="${id}Rolling" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>${logRoot}/${id}.%d{"yyyy-MM-dd-HH", UTC}.%i.json</fileNamePattern>
      <maxFileSize>${logSizeLimit}</maxFileSize>
      <maxHistory>100</maxHistory>
      <totalSizeCap>20GB</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%msg%n</pattern>
    </encoder>
  </appender>
</sift>

​

在java代码中：

String jsonOutput = gson.toJson(ping);

MDC.put("id", id));
logger.info(jsonOutput);
MDC.remove("id");

输出日志如下所示：

{"timestamp":{"seconds":1557048143，"nanos":028000000}，“httpRequest”：{“status”：028000000，"remoteIp":"111.11.111.111"，"requestMethod":"GET"，"requestUrl":"https://my.example.com/?id=testid"，“Mozilla”：“Mozilla/5.0 "}} ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@{“时间戳”：{“秒”：1557041043，"nanos":318000000}，"httpRequest":{"status":200，"remoteIp":"111.11.111.111"，"requestMethod":"GET"，"requestUrl":"https://my.example.com/?id=testid"，"userAgent":"Mozilla/5.0 "}}

我使用vim打开它，所以它将空字符显示为^@。这些空字符被附加在真实日志消息的开头。我还没有找到什么时候会发生这种情况的模式。我期望没有这些空字符的普通日志。

Answer 1

虽然日志轮换可能会导致某些问题，但我想为您所看到的影响提供另一种原因(和解决方案)。我在log4j2上也遇到过类似的问题。

我怀疑日志文件中的乱码输出(空字符)与线程安全有关。而低级POSIX例程(例如printf)是线程安全的，不能声明为直接文件脚本访问，有时出于性能考虑首选。这一切都是关于附加器实现的。使用日志记录器已经提供了所需的线程安全性和异步操作保证，因此，如果使用单一日志记录机制，则低级线程安全性不是问题。但是，当使用多个日志记录机制时，这可能会导致问题。

由于传递依赖(库)，在应用程序中很容易最终使用多个日志记录机制。因此，虽然您的目标可能是logback或log4j，但您的一些依赖项可能会尝试使用commons-logging。这种情况下的解决方案非常简单:只需向commons-logging或导入的库使用的其他日志机制添加一个桥实现即可。