You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Geng Yuanzhe (Jira)" <ji...@apache.org> on 2020/09/07 18:07:00 UTC
[jira] [Created] (LOG4J2-2919) logging with AsynAppender while the
system is reconfigure
Geng Yuanzhe created LOG4J2-2919:
------------------------------------
Summary: logging with AsynAppender while the system is reconfigure
Key: LOG4J2-2919
URL: https://issues.apache.org/jira/browse/LOG4J2-2919
Project: Log4j 2
Issue Type: Bug
Components: Core
Affects Versions: 2.13.3, 2.13.2, 2.13.1, 2.13.0, 2.12.1, 2.12.0, 2.11.2, 2.11.1, 2.11.0, 2.10.0, 2.9.1, 2.9.0, 2.8.2, 2.8.1, 2.8, 2.7, 2.6.2, 2.6.1, 2.6, 2.5, 2.4.1, 2.4
Reporter: Geng Yuanzhe
Hi Team,
I found a concurrent bug when reading the source code of log4j2-core. When logging with AsyncAppender, and at the same time reconfigure() is invoked, the following error may occurs
{code:java}
2020-09-08 01:16:06,145 main ERROR An exception occurred processing Appender async-console java.lang.IllegalStateException: AsyncAppender async-console is not active2020-09-08 01:16:06,145 main ERROR An exception occurred processing Appender async-console java.lang.IllegalStateException: AsyncAppender async-console is not active at org.apache.logging.log4j.core.appender.AsyncAppender.append(AsyncAppender.java:168) at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156) at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129) at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120) at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84) at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:508) at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:468) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:451) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:426) at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82) at org.apache.logging.log4j.core.Logger.log(Logger.java:158) at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2135) at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2089) at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2072) at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1948) at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1920) at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1257) at ReconfigureTest.testLoggingWhenReconfigure(ReconfigureTest.java:27) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63) at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) at org.junit.runners.ParentRunner.run(ParentRunner.java:413) at org.junit.runner.JUnitCore.run(JUnitCore.java:137) at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68) at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33) at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:230) at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:58){code}
The following table describes the situation where the problem occurs. The row grows with time.
||thread 1(logger.info(...))||thread 2(reconfigure())||
|org.apache.logging.log4j.core.config.AppenderControl#tryCallAppender| |
| |new config start()|
| |updateLoggers()|
| |prev.stop()|
| |org.apache.logging.log4j.core.config.AbstractConfiguration#stop|
| |AsyncAppenders stop|
|org.apache.logging.log4j.core.appender.AsyncAppender#append
{color:#de350b}(throw new IllegalStateException("AsyncAppender " + getName() + " is not active");){color}| |
To test this case, I modify class *org.apache.logging.log4j.core.appender.AsyncAppender* and write a unit test to get the above error
{code:java}
// org.apache.logging.log4j.core.appender.AsyncAppender
@Override
public void append(final LogEvent logEvent) {
// ---------sleep to wait reconfigre() stop this appender----
try {
System.out.println("AsyncAppender append, sleep 10s");
Thread.sleep(10000);
System.out.println("AsyncAppender append, awake");
}catch (InterruptedException e){
e.printStackTrace();
}
// ----------------------------------------------------------
if (!isStarted()) {
throw new IllegalStateException("AsyncAppender " + getName() + " is not active");
}
final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);
InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage());
if (!transfer(memento)) {
if (blocking) {
if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
// If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
AsyncQueueFullMessageUtil.logWarningToStatusLogger();
logMessageInCurrentThread(logEvent);
} else {
// delegate to the event router (which may discard, enqueue and block, or log in current thread)
final EventRoute route = asyncQueueFullPolicy.getRoute(thread.getId(), memento.getLevel());
route.logMessage(this, memento);
}
} else {
error("Appender " + getName() + " is unable to write primary appenders. queue is full");
logToErrorAppenderIfNecessary(false, memento);
}
}
}{code}
and make test
{code:java}
// unit test
@Test
public void testLoggingWhenReconfigure(){
Logger logger = LogManager.getLogger("logger");
new Thread(new Runnable() {
@Override
public void run() {
try {
// make logger.info execute first
Thread.sleep(2000);
} catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println("reconfiguring ...");
LoggerContext.getContext(false).reconfigure();
System.out.println("reconfiguring done...");
}
}).start();
logger.info("info");
}
{code}
log4j2.properties
{code:java}
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="ERROR">
<Appenders>
<Console name="console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
</Console>
<Async name="async-console">
<AppenderRef ref="console"/>
</Async>
</Appenders>
<Loggers>
<logger name="logger" level="info" additivity="false">
<AppenderRef ref="async-console" />
</logger>
</Loggers>
</Configuration>
{code}
I has solve this problem by calling ReliabilityStrategy's beforeStopAppenders() method before stopping AsyncAppender with the pull request [https://github.com/apache/logging-log4j2/pull/416]
Please help me review my code.
Thanks.
Yuanzhe Geng
--
This message was sent by Atlassian Jira
(v8.3.4#803005)