Daniele Demichelis created LOG4J2-1748:
------------------------------------------
Summary: 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
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
