[LOG4J2-2919] "AsyncAppender is not active" when logging with AsynAppender while the system is reconfigure concurrently

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 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
• Fix Version/s: 2.14.0
• Component/s: Core
• Flags: Patch
• Assignee: Matt Sicker
• Reporter: Yuanzhe Geng
• Created: 07/Sep/20 18:06
• Updated: 13/Sep/20 16:40
• Resolved: 12/Sep/20 17:34

Description

Hi Team, 

I found a problem where LOG4J2-1121 try to fix, but left the scenario for AsyncAppender. In org.apache.logging.log4j.core.config.AbstractConfiguration#stop(), loggerConfig.getReliabilityStrategy().beforeStopAppenders() is invoked after the AsyncAppender.stop(), so the reliablity strategy can't protect losing log events for AsyncAppender.

So when logging with AsyncAppender, and at the same time reconfigure() is invoked, if the prev config stop before the AsyncAppender finish log(),  the following error may occurs.

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 

 The following pic describes the situation how the problem occurs. 

It's really hard to reproduce this case, and I can't write a standard unit test for It.

But by modifying class org.apache.logging.log4j.core.appender.AsyncAppender with adding a sleep in the append() method, I can reproduce it in a unusual way.

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);
        }
    }
}

unit test

// 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");
}

log4j2.properties 

<?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>

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

 

Issue Links

• is caused by: LOG4J2-1121 LoggerConfig performance improvement: remove waitForCompletion and associated fields
• relates to: LOG4J2-323 ThreadLocal-leak on tomcat shutdown when using async logging
• relates to: LOG4J2-392 Intermittent errors with appenders
• relates to: LOG4J2-511 Referenced appenders on async appender are shutdown prematurely
• links to: GitHub Pull Request #416