[
https://issues.apache.org/jira/browse/LOG4J2-1748?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15819620#comment-15819620
]
Remko Popma edited comment on LOG4J2-1748 at 1/12/17 12:52 AM:
---------------------------------------------------------------
If rollover compression is to take place in daemon threads with the shutdown
hook being aware of rollover actions that are in flight and holding off
shutdown until such actions complete, then it would be nice if the shutdown
hook would be able to print a message like "Log4j2 shutdown hook is waiting for
compress action <absolute path to log file > to complete".
The current solution to use non-daemon threads for compression is a lot simpler
though.
To clarify, my solution to the problem this JIRA was raised for was to limit
the timeout to 1 sec. We can also decide not to try reusing these threads at
all and compress in an ad hoc non-daemon thread.
was (Author: rem...@yahoo.com):
If rollover compression is to take place in daemon threads with the shutdown
hook being aware of rollover actions that are in flight and holding off
shutdown until such actions complete, then it would be nice if the shutdown
hook would be able to print a message like "Log4j2 shutdown hook is waiting for
compress action <absolute path to log file > to complete".
The current solution to use non-daemon threads for compression is a lot simpler
though.
> 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-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
