You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2016/12/26 16:44:58 UTC
[jira] [Resolved] (LOG4J2-1748) RollingFile appender prevents a
stand alone application to terminate for as long as 60 sec
[ https://issues.apache.org/jira/browse/LOG4J2-1748?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Remko Popma resolved LOG4J2-1748.
---------------------------------
Resolution: Fixed
Assignee: Remko Popma
Fix Version/s: 2.8
Fixed in commit d003404.
Shortened the default keep-alive time for non-daemon threads from 60 seconds to 1 second. Users can configure this with system property {{log4j.nondaemon.threads.keepAliveSeconds}}.
Please verify and close.
> 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: Remko Popma
> 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-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org