[ https://issues.apache.org/jira/browse/LOG4J2-1748?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15828495#comment-15828495 ]
ASF GitHub Bot commented on LOG4J2-1748: ---------------------------------------- Github user rgoers commented on the issue: https://github.com/apache/logging-log4j2/pull/55 I manually approved it. > RollingFile appender prevents a stand alone application to terminate for as > long as 60 sec > ------------------------------------------------------------------------------------------ > > Key: LOG4J2-1748 > URL: https://issues.apache.org/jira/browse/LOG4J2-1748 > Project: Log4j 2 > Issue Type: Bug > Components: Appenders > Affects Versions: 2.7 > Environment: Java8, Windows > Reporter: Daniele Demichelis > Assignee: Mikael Ståldal > Labels: RollingFile, bug > Fix For: 2.8 > > > 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. > {code:java} > 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); > } > } > > } > {code} > Here's the `log4j2.xml` configuration file. > {code:xml} > <?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> > {code} > What is strange is that when the application is launched you will see this > logs in the console. > {code} > 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]... > {code} > What is strange is that the last log is issued at a certain time... > {code} > 2016-12-22 22:12:36 INFO This is log message #1999. > {code} > but the shutdown of log4j2 starts __exactly__ one minute after the last > "business" log message. > {code} > 2016-12-22 22:13:36,380 pool-1-thread-1 DEBUG Stopping > LoggerContext[name=60199c81, > org.apache.logging.log4j.core.LoggerContext@4597ec68] > {code} > *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... > {code:xml} > <Policies> > <OnStartupTriggeringPolicy/> > <SizeBasedTriggeringPolicy size="5 KB"/> > </Policies> > {code} > to 5Mb... > {code:xml} > <Policies> > <OnStartupTriggeringPolicy/> > <SizeBasedTriggeringPolicy size="5 MB"/> > </Policies> > {code} > ... 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 -- This message was sent by Atlassian JIRA (v6.3.4#6332) --------------------------------------------------------------------- To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-dev-h...@logging.apache.org