Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-2919

"AsyncAppender is not active" when logging with AsynAppender while the system is reconfigure concurrently

    XMLWordPrintableJSON

    Details

    • 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
    • Labels:
      None
    • Flags:
      Patch

      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

          Issue Links

            Activity

              People

              • Assignee:
                mattsicker Matt Sicker
                Reporter:
                gengyuanzhe Yuanzhe Geng
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: