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:12:00 UTC
[jira] [Updated] (LOG4J2-2919) "AsyncAppender is not active" when
logging with AsynAppender while the system is reconfigure
[ https://issues.apache.org/jira/browse/LOG4J2-2919?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Geng Yuanzhe updated LOG4J2-2919:
---------------------------------
Summary: "AsyncAppender is not active" when logging with AsynAppender while the system is reconfigure (was: logging with AsynAppender while the system is reconfigure )
> "AsyncAppender is not active" when 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.4, 2.4.1, 2.5, 2.6, 2.6.1, 2.6.2, 2.7, 2.8, 2.8.1, 2.8.2, 2.9.0, 2.9.1, 2.10.0, 2.11.0, 2.11.1, 2.11.2, 2.12.0, 2.12.1, 2.13.0, 2.13.1, 2.13.2, 2.13.3
> Reporter: Geng Yuanzhe
> Priority: Major
>
> 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
> {color:#172b4d}*org.apache.logging.log4j.core.appender.AsyncAppender*{color}
> {code:java}
> @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}
> *unit 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)