java - 为什么日志包含使用 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":200,"remoteIp":"111.11.111.111","re​​questMethod":"GET","re​​questUrl ":" https://my.example.com/?id=testid ","userAgent":"Mozilla/5.0"}}
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ {"timestamp":{"seconds":1557041043,"nanos":318000000},"httpRequest":{"status":200,"remoteIp":"111.11.111.111","re​​questMethod":"GET","re​​questUrl ":" https://my.example.com/?id=testid ","userAgent":"Mozilla/5.0"}}

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

Answer 1

虽然日志轮换可能会导致某些问题，但我想为您所看到的影响提供替代原因(和解决方案)。我在使用 log4j2 时遇到了类似的问题。
我怀疑日志文件中的乱码输出(空字符)与线程安全有关。虽然低级 POSIX 例程(例如 printf)是线程安全的，但有时出于性能考虑，不能声称直接访问文件描述符。这都是关于 appender 实现的。使用记录器已经提供了所需的线程安全和异步操作保证，因此如果使用单个日志记录机制，低级线程安全不是问题。但是，当使用多个日志记录机制时，这可能会导致问题。
由于传递依赖(库)，在应用程序中很容易最终使用多种日志记录机制。因此，虽然您可能以 logback 或 log4j 为目标，但您的某些依赖项可能会尝试使用 commons-logging。在这种情况下的解决方案非常简单:只需向 commons-logging 或导入库使用的其他一些日志记录机制添加一个桥接实现。