Why Log4j2's RollingFile appender prevents a stand alone application to terminate for 60 sec?

Question

This code reproduces what I think is a bug of Log4j2. It's a simple loop that logs 2000 messages with two appenders: a console appender and a rolling file appender that rolls the file every 5Kb. This limit is intentionally low to reproduce what I think is a bug.

Here's the code.

package bug;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class Example {

    private static final Logger logger = LogManager.getLogger(Example.class);

    public static void main(String[] args) throws InterruptedException {
        for(int i = 0; i<2000; i++){
            logger.info("This is log message #{}.", i);
            Thread.sleep(0);
        }
    }

}

Here's the log4j2.xml configuration file.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="TRACE">
    <Appenders>
        <Console name="stdout" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss} %p %m%n"/>
        </Console>
        <RollingFile name="roll-by-size"
                     fileName="target/log4j2/roll-by-size/app.log"
                     filePattern="target/log4j2/roll-by-size/app.%i.log.gz"
                     ignoreExceptions="false"
                     append="false">
            <PatternLayout>
                <Pattern>%d{yyyy-MM-dd HH:mm:ss} %p %m%n</Pattern>
            </PatternLayout>
            <Policies>
                <OnStartupTriggeringPolicy/>
                <SizeBasedTriggeringPolicy
                        size="5 KB"/>
            </Policies>
        </RollingFile>
    </Appenders>
    <Loggers>
        <Logger name="bug" level="TRACE">
            <AppenderRef ref="roll-by-size"/>
        </Logger>
        <Root level="DEBUG">
            <AppenderRef ref="stdout"/>
        </Root>
    </Loggers>
</Configuration>

What is strange is that when the application is launched you will see this logs in the console.

2016-12-22 22:12:36 INFO This is log message #1993.
2016-12-22 22:12:36 INFO This is log message #1994.
2016-12-22 22:12:36 INFO This is log message #1995.
2016-12-22 22:12:36 INFO This is log message #1996.
2016-12-22 22:12:36 INFO This is log message #1997.
2016-12-22 22:12:36 INFO This is log message #1998.
2016-12-22 22:12:36 INFO This is log message #1999.
2016-12-22 22:13:36,380 pool-1-thread-1 DEBUG Stopping LoggerContext[name=60199c81, org.apache.logging.log4j.core.LoggerContext@4597ec68]
2016-12-22 22:13:36,380 pool-1-thread-1 DEBUG Stopping LoggerContext[name=60199c81, org.apache.logging.log4j.core.LoggerContext@4597ec68]...
2016-12-22 22:13:36,381 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=60199c81]
2016-12-22 22:13:36,381 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=60199c81,component=StatusLogger]
2016-12-22 22:13:36,381 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=60199c81,component=ContextSelector]
2016-12-22 22:13:36,381 pool-1-thread-1 TRACE Unregistering 2 MBeans: [org.apache.logging.log4j2:type=60199c81,component=Loggers,name=bug, org.apache.logging.log4j2:type=60199c81,component=Lo
ggers,name=]
2016-12-22 22:13:36,381 pool-1-thread-1 TRACE Unregistering 2 MBeans: [org.apache.logging.log4j2:type=60199c81,component=Appenders,name=roll-by-size, org.apache.logging.log4j2:type=60199c81,c
omponent=Appenders,name=stdout]
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=60199c81,component=AsyncAppenders,name=*'
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=60199c81,component=AsyncLoggerRingBuffer'
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=60199c81,component=Loggers,name=*,subtype=RingBuffer'
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE Stopping XmlConfiguration[location=C:\Users\danidemi\workspace\bug-log4j2-hanging-up-before-shutdown\target\classes\log4j2.xml]...
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE XmlConfiguration notified 3 ReliabilityStrategies that config will be stopped.
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE XmlConfiguration stopping 2 LoggerConfigs.
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE XmlConfiguration stopping root LoggerConfig.
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE XmlConfiguration notifying ReliabilityStrategies that appenders will be stopped.
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE XmlConfiguration stopping remaining Appenders.
2016-12-22 22:13:36,383 pool-1-thread-1 DEBUG Shutting down RollingFileManager target/log4j2/roll-by-size/app.log
2016-12-22 22:13:36,383 pool-1-thread-1 DEBUG Shut down RollingFileManager target/log4j2/roll-by-size/app.log, all resources released: true
2016-12-22 22:13:36,383 pool-1-thread-1 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false
2016-12-22 22:13:36,383 pool-1-thread-1 DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false, all resources released: true
2016-12-22 22:13:36,384 pool-1-thread-1 TRACE XmlConfiguration stopped 2 remaining Appenders.
2016-12-22 22:13:36,384 pool-1-thread-1 TRACE XmlConfiguration cleaning Appenders from 3 LoggerConfigs.
2016-12-22 22:13:36,384 pool-1-thread-1 DEBUG Stopped XmlConfiguration[location=C:\Users\danidemi\workspace\bug-log4j2-hanging-up-before-shutdown\target\classes\log4j2.xml] OK
2016-12-22 22:13:36,385 pool-1-thread-1 DEBUG Stopped LoggerContext[name=60199c81, org.apache.logging.log4j.core.LoggerContext@4597ec68]...

What is strange is that the last log is issued at a certain time...

2016-12-22 22:12:36 INFO This is log message #1999.

but the shutdown of log4j2 starts exactly one minute after the last "business" log message.

2016-12-22 22:13:36,380 pool-1-thread-1 DEBUG Stopping LoggerContext[name=60199c81, org.apache.logging.log4j.core.LoggerContext@4597ec68]

This is the problem! The business logic terminates, but log4j2 waits for one minute before allow the app to stop! Why that ? I would prefer the application to stop immediately as one would probably expect.

I investigated a little... this 60 sec delay seems more or less independent from the number of messages being logged.

However, if you change the log4j2.xml incrementing the size from 5Kb...

<Policies>
    <OnStartupTriggeringPolicy/>
    <SizeBasedTriggeringPolicy size="5 KB"/>
</Policies>

to 5Mb...

<Policies>
    <OnStartupTriggeringPolicy/>
    <SizeBasedTriggeringPolicy size="5 MB"/>
</Policies>

... that makes the application to stop immediately right after the last log message. 5Mb is a limit big enough not to require the rolling to actually take place. So I think that is the rolling itself that in some way make this delay to occur. I think it's a bug but... what do you think?

I've set up a small Maven project on GitHub that demonstrates what I tried to explain here.

Answer 1

Thank you for raising this issue to the Log4j2 community.

The underlying cause is that Log4j creates two ThreadPoolExecutors, one daemon and one non-daemon. These executors are created with the default settings, which sets the thread keepAliveTime to one minute.

In the example, the application shuts down immediately after triggering a rollover. The rollover compresses the old file in a background thread in the non-daemon executor. Because the executor keeps this thread alive for one minute, and this is a non-daemon thread, the application as a whole is kept alive for one minute.

This will only impact applications that exit immediately after a rollover.

Update 2016-12-26: This has been fixed. From 2.8, non-daemon threads will have a shorter (one second) keepAliveTime by default.

Answer 2

You can try using LogManager.shutdown() as the very last command of your program.