Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-1748

RollingFile appender prevents a stand alone application to terminate for as long as 60 sec

    Details

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

      Java8, Windows

      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

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                mikaelstaldal Mikael Ståldal
                Reporter:
                danidemi Daniele Demichelis
              • Votes:
                0 Vote for this issue
                Watchers:
                6 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: