Log4j 2
  1. Log4j 2
  2. LOG4J2-669

NPE when combining AsyncLoggerConfig with AsyncLogger

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-rc1
    • Fix Version/s: 2.0-rc2
    • Component/s: Core
    • Labels:
      None

      Description

      When all loggers are made asynchronous by setting Log4jContextSelector to org.apache.logging.log4j.core.async.AsyncLoggerContextSelector, they produce RingBufferLogEvent instances. These RingBufferLogEvents are mutable by design. They are used as follows:

      1. Application calls logger.log("msg").
      2. The AsyncLogger claims a RingBufferLogEvent and populates its fields (level, timestamp, message, etc).
      3. The AsyncLogger then "publishes" the RingBufferLogEvent, to pass it to the event handler thread.
      4. The event handler thread passes the RingBufferLogEvent to all appenders.
      5. Finally, the event handler thread calls RingBufferLogEvent.clear() to allow the log message to be garbage collected (LOG4J2-304)

      This last step causes problems if the log event is still being processed.

      To reproduce this issue, configure all loggers to be asynchronous (with the Log4jContextSelector system property), and in the configuration, have a normal (non-async) Root logger, and an AsyncLogger.
      Be sure not to keep the default additivity="true", to ensure both the Root logger and the AsyncLogger process the events. (There may be other ways to reproduce this, but they all have to do with combining AsyncLogger with AsyncLoggerConfig.)

      This give the error below:

      2014-06-14 17:57:55,547 ERROR An exception occurred processing Appender File java.lang.NullPointerException
      	at java.lang.StringBuilder.<init>(StringBuilder.java:92)
      	at org.apache.logging.log4j.core.pattern.NameAbbreviator$PatternAbbreviator.abbreviate(NameAbbreviator.java:286)
      	at org.apache.logging.log4j.core.pattern.NamePatternConverter.abbreviate(NamePatternConverter.java:53)
      	at org.apache.logging.log4j.core.pattern.LoggerPatternConverter.format(LoggerPatternConverter.java:64)
      	at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
      	at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:214)
      	at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:54)
      	at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:46)
      	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
      	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
      	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:426)
      	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:118)
      	at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:222)
      	at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:207)
      	at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
      	at java.lang.Thread.run(Thread.java:662)
      

      By the time the AsyncLoggerConfigHelper$Log4jEventWrapperHandler handles the event, the original AsyncLogger has already called clear() on the event, so the logger name has been set to null, causing the NPE above.

        Issue Links

          Activity

          Remko Popma created issue -
          Remko Popma made changes -
          Field Original Value New Value
          Description When all loggers are made asynchronous by setting Log4jContextSelector to {{org.apache.logging.log4j.core.async.AsyncLoggerContextSelector}}, they produce {{RingBufferLogEvent}} instances. These RingBufferLogEvents are mutable by design. They are used as follows:

          # Application calls logger.log("msg").
          # The AsyncLogger claims a RingBufferLogEvent and populates its fields (level, timestamp, message, etc).
          # The AsyncLogger then "publishes" the RingBufferLogEvent, to pass it to the event handler thread.
          # The event handler thread passes the RingBufferLogEvent to all appenders.
          # Finally, the event handler thread calls {{RingBufferLogEvent.clear()}} to allow the log message to be garbage collected (LOG4J2-304)

          This last step causes problems if the log event is still being processed.

          To reproduce this issue, configure all loggers to be asynchronous (with the Log4jContextSelector system property), and in the configuration, have a normal (non-async) Root logger, and an AsyncLogger.
          Be sure not to keep the default additivity="true", to ensure both the Root logger and the AsyncLogger process the events.

          This give the error below:
          {code}
          2014-06-14 17:57:55,547 ERROR An exception occurred processing Appender File java.lang.NullPointerException
          at java.lang.StringBuilder.<init>(StringBuilder.java:92)
          at org.apache.logging.log4j.core.pattern.NameAbbreviator$PatternAbbreviator.abbreviate(NameAbbreviator.java:286)
          at org.apache.logging.log4j.core.pattern.NamePatternConverter.abbreviate(NamePatternConverter.java:53)
          at org.apache.logging.log4j.core.pattern.LoggerPatternConverter.format(LoggerPatternConverter.java:64)
          at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
          at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:214)
          at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:54)
          at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:46)
          at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
          at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
          at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:426)
          at org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:118)
          at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:222)
          at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:207)
          at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133)
          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
          at java.lang.Thread.run(Thread.java:662)
          {code}
          By the time the {{AsyncLoggerConfigHelper$Log4jEventWrapperHandler}} handles the event, the original AsyncLogger has already called {{clear()}} on the event, so the logger name has been set to null, causing the NPE above.
          When all loggers are made asynchronous by setting Log4jContextSelector to {{org.apache.logging.log4j.core.async.AsyncLoggerContextSelector}}, they produce {{RingBufferLogEvent}} instances. These RingBufferLogEvents are mutable by design. They are used as follows:

          # Application calls logger.log("msg").
          # The AsyncLogger claims a RingBufferLogEvent and populates its fields (level, timestamp, message, etc).
          # The AsyncLogger then "publishes" the RingBufferLogEvent, to pass it to the event handler thread.
          # The event handler thread passes the RingBufferLogEvent to all appenders.
          # Finally, the event handler thread calls {{RingBufferLogEvent.clear()}} to allow the log message to be garbage collected (LOG4J2-304)

          This last step causes problems if the log event is still being processed.

          To reproduce this issue, configure all loggers to be asynchronous (with the Log4jContextSelector system property), and in the configuration, have a normal (non-async) Root logger, and an AsyncLogger.
          Be sure not to keep the default additivity="true", to ensure both the Root logger and the AsyncLogger process the events. (There may be other ways to reproduce this, but they all have to do with combining AsyncLogger with AsyncLoggerConfig.)

          This give the error below:
          {code}
          2014-06-14 17:57:55,547 ERROR An exception occurred processing Appender File java.lang.NullPointerException
          at java.lang.StringBuilder.<init>(StringBuilder.java:92)
          at org.apache.logging.log4j.core.pattern.NameAbbreviator$PatternAbbreviator.abbreviate(NameAbbreviator.java:286)
          at org.apache.logging.log4j.core.pattern.NamePatternConverter.abbreviate(NamePatternConverter.java:53)
          at org.apache.logging.log4j.core.pattern.LoggerPatternConverter.format(LoggerPatternConverter.java:64)
          at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
          at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:214)
          at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:54)
          at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:46)
          at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
          at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
          at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:426)
          at org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:118)
          at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:222)
          at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:207)
          at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133)
          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
          at java.lang.Thread.run(Thread.java:662)
          {code}
          By the time the {{AsyncLoggerConfigHelper$Log4jEventWrapperHandler}} handles the event, the original AsyncLogger has already called {{clear()}} on the event, so the logger name has been set to null, causing the NPE above.
          Hide
          Remko Popma added a comment -

          Fixed in revision 1602578.

          Show
          Remko Popma added a comment - Fixed in revision 1602578.
          Remko Popma made changes -
          Status Open [ 1 ] Resolved [ 5 ]
          Fix Version/s 2.0-rc2 [ 12326292 ]
          Resolution Fixed [ 1 ]
          Remko Popma made changes -
          Status Resolved [ 5 ] Closed [ 6 ]
          Remko Popma made changes -
          Link This issue relates to LOG4J2-668 [ LOG4J2-668 ]
          Transition Time In Source Status Execution Times Last Executer Last Execution Date
          Open Open Resolved Resolved
          2h 31m 1 Remko Popma 14/Jun/14 11:35
          Resolved Resolved Closed Closed
          18s 1 Remko Popma 14/Jun/14 11:35

            People

            • Assignee:
              Remko Popma
              Reporter:
              Remko Popma
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development