[
https://issues.apache.org/jira/browse/LOG4J2-2816?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17272510#comment-17272510
]
Jacob Shields commented on LOG4J2-2816:
---------------------------------------
If {{RingBufferLogEventTranslator::translateTo}} throws an exception for _any_
reason, it looks like Disruptor's {{RingBuffer::translateAndPublish}} still
publishes the sequence in a {{finally}} block. In such a case, will the
"untranslated" event later be consumed by {{RingBufferLogEventHandler}}, since
its sequence was published? That would result in the exception we see here.
Also, if the translator throws any exception besides {{NullPointerException}},
it appears as if the exception will be propagated up to
{{AbstractLogger::handleLogMessageException}} and logged as a {{WARN}} via the
{{StatusLogger}}.
If the translator happens to throw a {{NullPointerException}}, then
{{AsyncLoggerDisruptor}} will catch it earlier. First in
{{AsyncLoggerDisruptor::tryPublish}}, then again in
{{AsyncLoggerDisruptor::enqueueLogMessageWhenQueueFull}}. In both cases it logs
it as a {{WARN}} via the {{StatusLogger}}.
By default, {{StatusLogger}}'s level is {{ERROR}}, so we may not be seeing
these exceptions in our logs if they are occurring.
Another observation I made while inspecting the code is that if you were to
call {{RingBufferLogEventTranslator::translateTo}} twice in a row, without
calling {{RingBufferLogEventTranslator::setBasicValues}} in between, then we
would call {{RingBufferLogEvent::setValues}} with {{asyncLogger == null}}.
Actually, in that case _all_ of the passed values would be {{null}}, and the
{{setValues}} call would hit an NPE when trying to access
{{clock.currentTimeMillis()}}. But as mentioned earlier, this exception would
be sent to the {{StatusLogger}} and Disruptor would still publish the sequence.
Is there anywhere in the code that could possibly call
{{RingBufferLogEventTranslator::translateTo}} twice in a row like that? The
only possible place I see is {{AsyncLogger::publish}}. If
{{RingBufferLogEventTranslator::translateTo}} threw a NPE for some reason, then
{{AsyncLoggerDisruptor::tryPublish}} would return {{false}}, and {{publish}}
could then call {{translateTo}} again with the same translator via
{{AsyncLogger::handleRingBufferFull}}. However, this hypothesis presupposes
that there's some other initial NPE being thrown from the translator.
> NullPointerException from AsyncLogger
> -------------------------------------
>
> Key: LOG4J2-2816
> URL: https://issues.apache.org/jira/browse/LOG4J2-2816
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.13.0
> Reporter: Denis
> Priority: Minor
>
> We've got several times following NullPointerException (example from our
> stdout.log):
>
> {code:java}
> 84449.232: [purging class loader data graph, 0.0000003 secs]
> AsyncLogger error handling event seq=1037012,
> value='org.apache.logging.log4j.core.async.RingBufferLogEvent@2a7b2d78':
> java.lang.NullPointerException: null
> java.lang.NullPointerException
> at
> org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:161)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:46)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
> at
> com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168)
> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
> at java.lang.Thread.run(Thread.java:748)
> AsyncLogger error handling event seq=1037022,
> value='org.apache.logging.log4j.core.async.RingBufferLogEvent@d5d330f':
> java.lang.NullPointerException: null
> java.lang.NullPointerException
> at
> org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:161)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:46)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
> at
> com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168)
> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
> at java.lang.Thread.run(Thread.java:748)
> 84450.232: [deflating idle monitors, 0.0000624 secs]
> {code}
>
> What is interesting this NPEs always preceeded by
> {code}
> 84449.232: [purging class loader data graph, 0.0000003 secs] vm message
> {code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
