logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (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 Sat, 07 Jan 2017 23:44:58 GMT

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

Remko Popma commented on LOG4J2-1748:
-------------------------------------

Good point. Unfortunately, that JIRA doesn't document the name of the system property that
was introduced. I would have to go and look at the code to see what that property is called
in order to judge whether it makes sense for both use cases. Not sure when I'll have time
for that. 

Conversations like this would go faster if we document more detail on our changes in JIRA.
That would also be useful for users. 

> 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


Mime
View raw message