[LOG4J2-1748] RollingFile appender prevents a stand alone application to terminate for as long as 60 sec

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.7
• Fix Version/s: 2.8
• Component/s: Appenders
• Labels: RollingFile bug

Environment

Java8, Windows

• Assignee: Mikael Ståldal
• Reporter: Daniele Demichelis
• Created: 22/Dec/16 22:03
• Updated: 25/Jan/17 09:42
• Resolved: 18/Jan/17 19:44

Description

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 my GitHub that demonstrates what I tried to explain here.

https://github.com/danidemi/bug-log4j2-hanging-up-before-shutdown

Issue Links

• is related to: LOG4J2-1623 Configurable JVM shutdown hook timeout
• links to: GitHub Pull Request #54
• links to: GitHub Pull Request #55