[logback-dev] Why my logs contain null characters(holes)

[Tianjiao Liu]

Hi all,

I am using logback(SiftingAppender and RollingFileAppender) in my
application. Whenever requests come in, they will be logged to different
files according to the id from url query.

This is working really well and I get the expected result. However, I
noticed occasionally, there are some null characters in the middle of logs.
I am not sure why this happens and how to reduce it.

I did some research and the closest thing I found is
https://serverfault.com/questions/71341/why-do-jboss-and-logrotate-create-log-files-full-of-nul-characters

They are using logrotate with log4j and that results in the null character.
However, in my case, the whole log rotate and lifecycle is handled by
logback.

This is partial of my logback xml configuration:

<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>

And in the java code:

String jsonOutput = gson.toJson(ping);

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

The output log looks like :

{"timestamp":{"seconds":1557048143,"nanos":028000000},"httpRequest":{"status":200,"remoteIp":"111.11.111.111","requestMethod":"GET","requestUrl":"
https://my.example.com/?id=testid","userAgent":"Mozilla/5.0 "}}
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@{"timestamp":{"seconds":1557041043,"nanos":318000000},"httpRequest":{"status":200,"remoteIp":"111.11.111.111","requestMethod":"GET","requestUrl":"
https://my.example.com/?id=testid","userAgent":"Mozilla/5.0 "}}

I am using vim to open it, so it displays null character as ^@. These null
characters are appended at the beginning of a real log message. I haven't
found a pattern when this will happen.


Does anyone have any idea why this happens?

Best regards,

TJ Liu
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-dev/attachments/20190515/aed804fc/attachment-0001.html>