CODEWITHSUNDEEP
javaasynchronousloggingconfigurationlog4j2
benji
benji

Reputation: 2451

How to flush Asynchronous loggers in Log4J2 (with disruptor)

I'm using Log4J2 "Making All Loggers Asynchronous" section by setting:

-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector.

https://logging.apache.org/log4j/2.x/manual/async.html

I process a lot of logs and then stop the appenders before exiting:

org.apache.logging.log4j.core.Logger coreLogger = (org.apache.logging.log4j.core.Logger) logger;
org.apache.logging.log4j.core.LoggerContext context = (org.apache.logging.log4j.core.LoggerContext) coreLogger.getContext();
Map<String, Appender> appenders = context.getConfiguration().getAppenders();
for (Appender appender : appenders.values()) {
  appender.stop();
}

By doing so I'm hoping that it will flush the async appender(s) and write to the disk the remaining logs before I exit the program.

But here is what happens:

2015-05-19 14:09:58,540 ERROR Attempted to append to non-started appender myFileAppender
Exception in thread "AsyncLogger-1" java.lang.RuntimeException: org.apache.logging.log4j.core.appender.AppenderLoggingException: Attempted to append to non-started appender myFileAppender
    at com.lmax.disruptor.FatalExceptionHandler.handleEventException(FatalExceptionHandler.java:45)
    at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:147)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.apache.logging.log4j.core.appender.AppenderLoggingException: Attempted to append to non-started appender myFileAppender
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:430)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:409)
    at org.apache.logging.log4j.core.Logger$PrivateConfig.logEvent(Logger.java:288)
    at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:305)
    at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:100)
    at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:43)
    at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:28)
    at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:128)
    ... 3 more

So the close doesn't look like it's actually flushing and the logger ends up failing.

My conf:

<Configuration>
  <Appenders>
    <RollingFile name="myFileAppender" fileName="/tmp/test.log" ignoreExceptions="false" immediateFlush="false">
      <PatternLayout><Pattern>%m%n</Pattern></PatternLayout>
      <Policies>
        <TimeBasedTriggeringPolicy />
      </Policies>
    </RollingFile>
    <Console name="STDOUT">
      <PatternLayout pattern="%C{1.} %m %level MDC%X%n"/>
    </Console>
  </Appenders>

  <Loggers>
    <Logger name="myLogger" level="info" additivity="false">
      <AppenderRef ref="myFileAppender" />
    </Logger>
    <Root level="fatal">
      <AppenderRef ref="STDOUT"/>
    </Root>
  </Loggers>
</Configuration>

How can I flush / synchronize log4j2?

Upvotes: 8

Views: 10341

Answers (1)

Remko Popma
Remko Popma

Reputation: 36754

Log4j2 has a shutdown hook (for non-web applications) that takes care of waiting for the background thread to process any events still in the queue. So the best thing to do is to not stop the appenders when they are still being used. Let log4j2 take care of the cleanup.

Log4j versions earlier than 2.5

To cleanly stop the async logger, you can call org.apache.logging.log4j.core.async.AsyncLogger.stop().

Log4j 2.5 and later

To cleanly stop the async logger, get a reference to its LoggerContext and stop it:

void stopAsyncLogger() {
    // you might need different arguments to getContext() to find the right one
    LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
    ctx.stop();
}

For all versions this blocks until all messages are flushed. Be aware:

  • This only works when "Making All Loggers Asynchronous" section by setting: -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector.
  • Are you sure you want to measure this? The disk I/O will dominate your measurements. If you want to include I/O, it may simpler to switch off async logging and measure synchronous logging (which includes the I/O). Most people are interested in the impact of logging on their application, so they only measure how long the calls to the logger take, and don't include the background thread work in their measurements.

Upvotes: 6

Related Questions