Details
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
Attachments
Attachments
Issue Links
- is caused by
-
LOG4J2-1121 LoggerConfig performance improvement: remove waitForCompletion and associated fields
- Resolved
- relates to
-
LOG4J2-323 ThreadLocal-leak on tomcat shutdown when using async logging
- Resolved
-
LOG4J2-392 Intermittent errors with appenders
- Resolved
-
LOG4J2-511 Referenced appenders on async appender are shutdown prematurely
- Closed
- links to