logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Gary Gregory (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-1748) RollingFile appender prevents a stand alone application to terminate for as long as 60 sec
Date Thu, 22 Dec 2016 22:39:58 GMT

    [ https://issues.apache.org/jira/browse/LOG4J2-1748?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15771292#comment-15771292
] 

Gary Gregory commented on LOG4J2-1748:
--------------------------------------

I think the rollover happens on a separate thread. When log4j shutdown, it cleans up after
itself and waits for threads to finish and files to be closed. You might be seeing a delay
because of this.

> 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
>              Labels: RollingFile, bug
>
> 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


Mime
View raw message