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

        Andre Bogus created issue -
        Remko Popma made changes -
        Field Original Value New Value
        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">
        &nbsp;<appenders>
        &nbsp;&nbsp;<Console name="console" target="SYSTEM_OUT">
        &nbsp;&nbsp;&nbsp;<PatternLayout pattern="%d\{ABSOLUTE\} %6p %c %x - %m%n"/>
        &nbsp;&nbsp;</Console>
        &nbsp;</appenders>
        &nbsp;<loggers>
        &nbsp;&nbsp;<asyncroot level="WARN">
        &nbsp;&nbsp;&nbsp;<appender-ref ref="console" />
        &nbsp;&nbsp;</asyncroot>
        &nbsp;</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 {
        &nbsp;&nbsp;private static final Logger log = LogManager.getLogger(Log4jAsyncReconfTest.class);
        &nbsp;&nbsp;public static void main(String[] args) throws InterruptedException \{
        &nbsp;&nbsp;&nbsp;&nbsp;System.out.println("test");
        &nbsp;&nbsp;&nbsp;&nbsp;LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
        &nbsp;&nbsp;&nbsp;&nbsp;ctx.reconfigure();
        &nbsp;&nbsp;&nbsp;&nbsp;ctx.reconfigure();
        &nbsp;&nbsp;&nbsp;&nbsp;log.warn("Danger!");
        &nbsp;&nbsp;\}
        }

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

        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:

        {code}
        <?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>
        {code}

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

        {code}
        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!");
            }
        }
        {code}

        ----
        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)
        Remko Popma made changes -
        Assignee Remko Popma [ remkop@yahoo.com ]
        Remko Popma made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Fix Version/s 2.0-beta9 [ 12324756 ]
        Resolution Fixed [ 1 ]

          People

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

            Dates

            • Created:
              Updated:
              Resolved:

              Development