Search code examples
javalog4j2logrotate

Async Log4J2 and logrotate not working correctly (truncate is broken)

I am using Log4J2 async logger to log my Java application and I'm using logrotate to store the old logs everyday.

Previously, I was using Log4J2 synchronously and everything worked fine; since I switched to async logging logrotate stopped working correctly.

I think I am experiencing the same issue explained here: since I am using the copytruncate option, the old log file gets truncated after being copied, but the logger doesn't know it, so it continues writing starting from the "old" index, thus filling all the previous space in the file with NUL values, which is exactly what I'm seeing.

This is the command I am launching my application with:

java -Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -Dlog4j2.asyncQueueFullPolicy=Discard -Dlog4j2.asyncLoggerRingBufferSize=6553600 -Djava.library.path=my_libs -cp MyApplication.jar:my_libs/* com.gscaparrotti.Main >> logs/other.log

This is an excerpt from my log4j2.xml file:

<Configuration status="debug">
    <Appenders>
        <RandomAccessFile name="LogToFile" fileName="logs/standalone.log" append="true" ImmediateFlush="false">
            <PatternLayout>
                <Pattern>[MyApp - %t - %d{DATE}] %5p %c{1} - %m%n</Pattern>
            </PatternLayout>
        </RandomAccessFile>
        <RandomAccessFile name="LogAnalyzer" fileName="logs/analyzer.txt" append="true" ImmediateFlush="false">
            <PatternLayout>
                <Pattern>[%d{DATE}] %5p %c{1} - %m%n</Pattern>
            </PatternLayout>
        </RandomAccessFile>
    </Appenders>
    <Loggers>
        <Root level="warn">
            <AppenderRef ref="LogToFile"/>
        </Root>
        <Logger name="analyzer" level="debug" additivity="false">
            <AppenderRef ref="LogAnalyzer"/>
        </Logger>
    </Loggers>
</Configuration>

This is the logrotate configuration I'm using (it's the same for all the log files):

/root/logs/analyzer.txt {
  copytruncate
  daily
  rotate 4
  compress
  missingok
  create 640 root root
}

A sort-of solution would be to stop my application before logrotateing it, but this is hardly a good solution, since I'd like to have it running.

What else could I do to fix this issue?

Solution

  • You should replace the RandomAccessFileAppender with a simple FileAppender.

    Your issue is not caused by the use of asynchronous loggers, but by the appender you use:

    • Java's RandomAccessFile, which is used by the RandomAccessFileAppender opens files in read/write mode without the O_APPEND option (cf. open(2)),
    • FileOutputStream, which is used by the usual FileAppender, opens files in write only mode with the O_APPEND option.

    The presence or the absence of this option influences how writes are performed:

    O_APPEND The file is opened in append mode. Before each write(2), the file offset is positioned at the end of the file, as if with lseek(2). The modification of the file offset and the write operation are performed as a single atomic step.

    (from man open(2)).

    When you truncate your log file a FileAppenders offset will be reset to 0, while a RandomAccessFileAppender will continue writing at the previous position.

    Remark: Log4j also provides a RollingFileAppender, which will remove the need to use logrotate at all.

    Edit: the exact options used to create the objects used by the managers can be found: