Log4j 2
  1. Log4j 2
  2. LOG4J2-336

AsyncLogger.log fail with NullPointerException after double reconfigure

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta8
    • Fix Version/s: 2.0-beta9
    • Component/s: Core
    • Labels:
      None
    • Environment:

      LUbuntu 13.04, OpenJDK 7

      Description

      Using reconfigure() to select log files at runtime.
      After the second reconfigure, the next log fails with a NullPointerException in org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper:253

      It appears that the disruptor has been nulled and not been brought back up by the second reconfigure().

      Trying to get a minimal test case I came up with the following log4j2.xml:

      <?xml version="1.0" encoding="UTF-8" ?>
      <configuration status="debug">
        <appenders>
          <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d\{ABSOLUTE\} %6p %c %x - %m%n"/>
          </Console>
        </appenders>
        <loggers>
          <asyncroot level="WARN">
            <appender-ref ref="console" />
          </asyncroot>
        </loggers>
      </configuration>
      

      The following Java class did NOT bring up the error, instead it threw a different exception (stack trace below):

      import org.apache.logging.log4j.LogManager;
      import org.apache.logging.log4j.Logger;
      import org.apache.logging.log4j.core.LoggerContext;
      
      public class Log4jAsyncReconfTest {
          private static final Logger log = LogManager.getLogger(Log4jAsyncReconfTest.class);
          public static void main(String[] args) throws InterruptedException {
              System.out.println("test");
              LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
              ctx.reconfigure();
              ctx.reconfigure();
              log.warn("Danger!");
          }
      }
      

      throws:

      java.util.concurrent.RejectedExecutionException: Task com.lmax.disruptor.BatchEventProcessor@7ea4461e rejected from java.util.concurrent.ThreadPoolExecutor@52f79c86[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 1]
      at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2048)
      at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821)
      at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1372)
      at java.util.concurrent.Executors$DelegatedExecutorService.execute(Executors.java:628)
      at com.lmax.disruptor.dsl.EventProcessorInfo.start(EventProcessorInfo.java:77)
      at com.lmax.disruptor.dsl.Disruptor.start(Disruptor.java:263)
      at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper.initDisruptor(AsyncLoggerConfigHelper.java:119)

        Activity

        Hide
        Remko Popma added a comment -

        Thanks for finding this.

        On reconfiguration, a new Disruptor instance is created, but no new thread pool is created. The new Disruptor instances references the old thread pool, which has been shut down (or is in the middle of shutting down), resulting in various errors. The solution is to create a new thread pool object every time a new Disruptor instance is created.

        Show
        Remko Popma added a comment - Thanks for finding this. On reconfiguration, a new Disruptor instance is created, but no new thread pool is created. The new Disruptor instances references the old thread pool, which has been shut down (or is in the middle of shutting down), resulting in various errors. The solution is to create a new thread pool object every time a new Disruptor instance is created.
        Hide
        Andre Bogus added a comment -

        You're very welcome. Thanks for working on this. So I presume this will be fixed with 2.0beta9? If so, when can we expect it to be available?

        Show
        Andre Bogus added a comment - You're very welcome. Thanks for working on this. So I presume this will be fixed with 2.0beta9? If so, when can we expect it to be available?
        Hide
        Remko Popma added a comment -

        Yes, this will be fixed with beta9. Not sure when that will be, community decision. Perhaps a few weeks from now?

        BTW, sorry I haven't had time to run your test case, but I assume you see the same issue (or worse) when making all loggers Async Loggers? (by setting -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector)?

        Show
        Remko Popma added a comment - Yes, this will be fixed with beta9. Not sure when that will be, community decision. Perhaps a few weeks from now? BTW, sorry I haven't had time to run your test case, but I assume you see the same issue (or worse) when making all loggers Async Loggers? (by setting -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector)?
        Hide
        Remko Popma added a comment -

        I was finally able to track this down to an unbalanced number of calls to LoggerConfig#startFilter and #stopFilter. In o.a.l.l.c.c.BaseConfiguration, the #stop() method explicitly calls the #stopFilter() method on the root logger, but there is no equivalent call to root#startFilter in the BaseConfiguration#start() method.

        This means that the reference count (used to determine when to shut down or create new Disruptor instances) is incorrect when the configuration contains a <asyncRoot> element.

        Proposed solution:

        // o.a.l.l.c.c.BaseConfiguration
        public void start() {
            setup();
            doConfigure();
            for (final LoggerConfig logger : loggers.values()) {
                logger.startFilter();
            }
            for (final Appender appender : appenders.values()) {
                appender.start();
            }
            root.startFilter(); // add this line
            startFilter();
        }
        

        Note that the #startFilter and #stopFilter methods may be called twice for the root logger. Not ideal, but better than stopping twice for every start. Based on current usage I don't see any problems. FYI, currently AsyncLoggerConfig is the only LoggerConfig that overrides the default #startFilter and #stopFilter implementation.

        Show
        Remko Popma added a comment - I was finally able to track this down to an unbalanced number of calls to LoggerConfig#startFilter and #stopFilter. In o.a.l.l.c.c.BaseConfiguration, the #stop() method explicitly calls the #stopFilter() method on the root logger, but there is no equivalent call to root#startFilter in the BaseConfiguration#start() method. This means that the reference count (used to determine when to shut down or create new Disruptor instances) is incorrect when the configuration contains a <asyncRoot> element. Proposed solution: // o.a.l.l.c.c.BaseConfiguration public void start() { setup(); doConfigure(); for ( final LoggerConfig logger : loggers.values()) { logger.startFilter(); } for ( final Appender appender : appenders.values()) { appender.start(); } root.startFilter(); // add this line startFilter(); } Note that the #startFilter and #stopFilter methods may be called twice for the root logger. Not ideal, but better than stopping twice for every start. Based on current usage I don't see any problems. FYI, currently AsyncLoggerConfig is the only LoggerConfig that overrides the default #startFilter and #stopFilter implementation.
        Hide
        Andre Bogus added a comment -

        Hi again. Good job on finding this. If I may ask a stupid question, why does log4j need to explicitly stop the root filter?

        Show
        Andre Bogus added a comment - Hi again. Good job on finding this. If I may ask a stupid question, why does log4j need to explicitly stop the root filter?
        Hide
        Remko Popma added a comment -

        Andre, during a reconfigure, new Appenders and LoggerConfig objects are created and started, and the old ones are all stopped, including the old root LoggerConfig.

        Show
        Remko Popma added a comment - Andre, during a reconfigure, new Appenders and LoggerConfig objects are created and started, and the old ones are all stopped, including the old root LoggerConfig.
        Hide
        Andre Bogus added a comment - - edited

        Allow me to rephrase my question: Why is the root LoggerConfig not part of the loggers Map by default?

        Show
        Andre Bogus added a comment - - edited Allow me to rephrase my question: Why is the root LoggerConfig not part of the loggers Map by default?
        Hide
        Remko Popma added a comment -

        Fixed in revision 1513832.
        Please verify and close.

        Show
        Remko Popma added a comment - Fixed in revision 1513832. Please verify and close.
        Hide
        Remko Popma added a comment -

        Andre, one reason I can see is that it is possible to create a configuration without a root element. In that case a default root element is created automatically (with a console Appender, ERROR level and a default layout). In this scenario the root logger is not part of the loggers Map.

        As far as I can tell, the root logger would be part of the loggers Map if a <root> (or <asyncRoot>) logger is configured in the configuration file.

        Show
        Remko Popma added a comment - Andre, one reason I can see is that it is possible to create a configuration without a root element. In that case a default root element is created automatically (with a console Appender, ERROR level and a default layout). In this scenario the root logger is not part of the loggers Map. As far as I can tell, the root logger would be part of the loggers Map if a <root> (or <asyncRoot> ) logger is configured in the configuration file.
        Hide
        Andre Bogus added a comment - - edited

        Wouldn't adding a default root logger into the loggers Map even if one isn't configured be a more general solution? Edit: I've just checked out the trunk, will compile, verify and hopefully close this issue shortly.

        Show
        Andre Bogus added a comment - - edited Wouldn't adding a default root logger into the loggers Map even if one isn't configured be a more general solution? Edit: I've just checked out the trunk, will compile, verify and hopefully close this issue shortly.

          People

          • Assignee:
            Remko Popma
            Reporter:
            Andre Bogus
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development