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/09 06:45:00 UTC
[jira] [Commented] (LOG4J2-2919) "AsyncAppender is not active" when
logging with AsynAppender while the system is reconfigure concurrently
[ https://issues.apache.org/jira/browse/LOG4J2-2919?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17192671#comment-17192671 ]
Geng Yuanzhe commented on LOG4J2-2919:
--------------------------------------
Hi, [~rpopma] [~rgoers]
I found the LOG4J2-1121 is processed by you. Please help processing this issue. Thanks very much
> "AsyncAppender is not active" when logging with AsynAppender while the system is reconfigure concurrently
> ----------------------------------------------------------------------------------------------------------
>
> 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
> Attachments: reconfigure-and-asyncAppender-append.png
>
>
> 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.
> {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 {code}
> The following table describes the situation how the problem occurs. The row grows with time. The attachment *reconfigure-and-asyncAppender-append.png* does the same thing.
> ||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}| |
> *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 reproduce it in a unusual way.*
> *{color:#de350b}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}
> {color:#de350b}*unit test*{color}
> {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}
> {color:#de350b}*log4j2.properties* {color}
> {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)