[
https://issues.apache.org/jira/browse/LOG4J2-669?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Remko Popma updated LOG4J2-669:
-------------------------------
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. (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.
was:
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.
> NPE when combining AsyncLoggerConfig with AsyncLogger
> -----------------------------------------------------
>
> Key: LOG4J2-669
> URL: https://issues.apache.org/jira/browse/LOG4J2-669
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0-rc1
> Reporter: Remko Popma
> Assignee: Remko Popma
>
> 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.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
