[
https://issues.apache.org/jira/browse/LOG4J2-1748?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15819271#comment-15819271
]
Ralph Goers commented on LOG4J2-1748:
-------------------------------------
I don't know why those two ThreadPoolExecutors were added. The
ConfigurationScheduler was added to be the single place that Log4j schedules
work to be executed. I plan on modifying the RollingFileManager to use the
ConfigurationScheduler to perform the rollover. The only other thing using
those ExecutorServices is the configuration file Watcher. What is interesting
is that the WatchManager uses the ConfigurationScheduler to periodically check
for events - so naturally the check happens on a Thread owned by the
ConfigurationScheduler. When a file modification is found
ConfigurationFileWatcher schedules another Thread to run to perform the
reconfiguration. This used to be done by creating a Thread and running it. I
guess Gary decided it was better to have an ExecutorService for this.
Personally, I think this is wrong. The reconfiguration shouldn't happen in a
Thread owned by the ConfigurationScheduler because that will be stopped and
restarted during reconfiguration. But I see no point in creating an
ExecutorService to perform just this one task as it is overkill.
I don't think this problem would exist if these ExecutorServices weren't
present.
> 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
