[
https://issues.apache.org/jira/browse/LOG4J2-1748?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15826799#comment-15826799
]
ASF GitHub Bot commented on LOG4J2-1748:
----------------------------------------
GitHub user mikaelstaldal opened a pull request:
https://github.com/apache/logging-log4j2/pull/55
LOG4J2-1748 and LOG4J2-1780
Remove executor service from LoggerContext.
You can merge this pull request into a Git repository by running:
$ git pull https://github.com/apache/logging-log4j2
LOG4J2-1748and1780-remove-ExecutorService-from-LoggerContext
Alternatively you can review and apply these changes as the patch at:
https://github.com/apache/logging-log4j2/pull/55.patch
To close this pull request, make a commit to your master/trunk branch
with (at least) the following in the commit message:
This closes #55
----
commit 162a5e33ace3f1b4adf0726502083d0efb1e799a
Author: Mikael Ståldal <mikael.stal...@magine.com>
Date: 2017-01-12T11:14:18Z
LOG4J2-1748 and LOG4J2-1780 Remove ExecutorServices from LoggerContext
commit 9f2b0984682f708adb0359646127043b4f1561ae
Author: Mikael Ståldal <mikael.stal...@magine.com>
Date: 2017-01-12T21:36:25Z
LOG4J2-1748 and LOG4J2-1780 Remove non-relevant documentation
commit d3e04250d2e314aa33a51247698b3ed46503afd5
Author: Mikael Ståldal <mikael.stal...@magine.com>
Date: 2017-01-12T21:36:58Z
LOG4J2-1748 and LOG4J2-1780 Fix changelog
commit bd649ed99069add1a2b46b9e8e1079803d9507ad
Author: Mikael Ståldal <mik...@staldal.nu>
Date: 2017-01-15T14:51:17Z
Merge branch 'master' into
LOG4J2-1748and1780-remove-ExecutorService-from-LoggerContext
# Conflicts:
#
log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java
# src/changes/changes.xml
commit 80879c7dd6c76700a575c4dfe4e42bfde205faef
Author: Mikael Ståldal <mik...@staldal.nu>
Date: 2017-01-15T14:56:42Z
LOG4J2-1748 fix changelog
commit e21a07e353a748e3a7dbefce20bf414aa425e1c7
Author: Mikael Ståldal <mik...@staldal.nu>
Date: 2017-01-15T15:13:41Z
LOG4J2-1748 revert some changes
commit e390ad368f5549c2415856d9176a0cf32c2ced40
Author: Mikael Ståldal <mik...@staldal.nu>
Date: 2017-01-15T15:29:31Z
LOG4J2-1748 revert some changes
commit 4fb38c620aaf62b37642387237da2a06c58b4d8c
Author: Mikael Ståldal <mik...@staldal.nu>
Date: 2017-01-15T15:32:50Z
LOG4J2-1748 fix
commit f6341ad505c298fcf66c9b3183873cc5f6c4e844
Author: Mikael Ståldal <mik...@staldal.nu>
Date: 2017-01-15T16:14:12Z
LOG4J2-1748 fix
commit 527b125c31e3ce654657bf7df5a9b2fc27d8ffd4
Author: Mikael Ståldal <mik...@staldal.nu>
Date: 2017-01-15T16:18:39Z
LOG4J2-1748 revert some changes
commit 1974c8202eed10d0c971f493ca2c09a05bfc6cbb
Author: Mikael Ståldal <mik...@staldal.nu>
Date: 2017-01-17T20:53:39Z
Merge branch 'master' into
LOG4J2-1748and1780-remove-ExecutorService-from-LoggerContext
# Conflicts:
#
log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java
# src/changes/changes.xml
commit 3917b66ec79cc8fe103a6eb49badf934d6e64182
Author: Mikael Ståldal <mik...@staldal.nu>
Date: 2017-01-17T20:57:26Z
LOG4J2-1748 fix merge issue
----
> 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: Mikael Ståldal
> 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
