Search code examples
javalogbackasyncappender

What happens to queued messages when Logback's AsyncAppender crashes?

When using Logback's AsyncAppender, messages get queued before they are written to their final destination (depending on which Appender you wrapped with the AsyncAppender). So far so good.

Is it possible those queued messages get lost when my program or logback itself crash?

Solution

  • Yes, I think queued messages will be lost when JVM crashed and even normal program shutdown.

    I was doing an investigation on how much time is improved when using AsyncAppender.

    Sample logback.xml:
    I have a normal FILE_LOG and ASYNC_FILE_LOG.

    <appender name="FILE0" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>./file.log</file>
    ... (not relevant)
</appender>

<appender name="FILE1" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>./async_file.log</file>
    ... (not relevant)
</appender>
<appender name="ASYNC_FILE1" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="FILE1" />
    <discardingThreshold>0</discardingThreshold>
</appender>

<logger name="FILE_LOG" additivity="false">
    <appender-ref ref="FILE0" />
</logger>

<logger name="ASYNC_FILE_LOG" additivity="false">
    <appender-ref ref="ASYNC_FILE1" />
</logger>

    Sample MultiThreadsExecutor tester program, it should generate 1010 lines of log messages:

    import java.util.concurrent.CountDownLatch;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class MultiThreadsExecutor {
    private static final Logger asyncLOGGER = LoggerFactory.getLogger("ASYNC_FILE_LOG");
    private static final Logger normaLOGGER = LoggerFactory.getLogger("FILE_LOG");
    static CountDownLatch latch = null; // Java7 feature to ensure all threads ended execution.

    public MultiThreadsExecutor() {
    }

    public void someMethod(String who, String loggerName) {
        Thread backgroundThread = new Thread(new Runnable() {
            public void run() {
                getLogger(loggerName).warn(Thread.currentThread().getName() +": is Running in the background");
                for (int i=0; i<100; i++) {
                    getLogger(loggerName).info(Thread.currentThread().getName() +" counting: " + i);
                }
                latch.countDown();
            }
        },"Background " + who + " Thread");
        backgroundThread.start();
    }

    private Logger getLogger(String name) {
        if (name.equals("ASYNC_FILE_LOG")) {
            return asyncLOGGER;
        } else if (name.equals("FILE_LOG")) {
            return normaLOGGER;
        } else {
            System.out.println("Logger Undefined");
            return null;
        }
    }

    public static void main(String[] args) {
        long start;
        MultiThreadsExecutor mte = new MultiThreadsExecutor();

        latch = new CountDownLatch(10);
        start = System.currentTimeMillis();
        for (int i=0; i<10; i++) {
            mte.someMethod(Integer.toString(i)," FILE_LOG");
        }
        try {
            latch.await();
            System.out.println("FILE_LOG ended - " + (System.currentTimeMillis() - start));
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        latch = new CountDownLatch(10);
        start = System.currentTimeMillis();
        for (int i=0; i<10; i++) {
            mte.someMethod(Integer.toString(i)," ASYNC_FILE_LOG");
        }
        try {
            latch.await();
            System.out.println("ASYNC_FILE_LOG ended - " + (System.currentTimeMillis() - start));
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        // Remove below to enable Testcase(2)
        // try { Thread.sleep(1000); } catch (InterruptedException e) { e.printStackTrace(); }
        System.out.println("END");
   }
}

    Test Case (1) Normal execution.

    FILE_LOG ended - 46
    ASYNC_FILE_LOG ended - 16
    END

    ASYNC_FILE_LOG indeed is much faster. However...

    File.log recorded 1010 line of messages correctly:

    line1 Background 1 Thread: is Running in the background
line2 Background 3 Thread: is Running in the background
line3 Background 6 Thread: is Running in the background
line4 Background 8 Thread: is Running in the background
...
line1009 Background 0 Thread counting: 99
line1010 Background 8 Thread counting: 99

    Async_File.log records up to 800+ messages only!

    line1 Background 0 Thread: is Running in the background
line2 Background 1 Thread: is Running in the background
line3 Background 1 Thread counting: 0
line4 Background 1 Thread counting: 1
line5 Background 1 Thread counting: 2
....
line811 Background 2 Thread counting: 95
line812 Background 4 Thread counting: 66
line813 Background 8 Thread counting: 46

    Test Case (2) , Tester sleeps 1 second before END in case AsyncAppender needs time to clear queue...

    FILE_LOG ended - 47
    ASYNC_FILE_LOG ended - 16
    END

    ASYNC_FILE_LOG is still faster. This time, ASYNC_FILE_LOG recorded 1010 lines correctly.

    line1 Background 0 Thread: is Running in the background
line2 Background 2 Thread: is Running in the background
line3 Background 2 Thread counting: 0
line4 Background 2 Thread counting: 1
line5 Background 2 Thread counting: 2
....
line1008 Background 5 Thread counting: 97
line1009 Background 5 Thread counting: 98
line1010 Background 5 Thread counting: 99

    Conclusion

    The above test proves that, when Java program shutdown, AsyncAppender does not have enough time to clear log queue. Not to mention JVM crashes, Java program exit is immediate.