[
https://issues.apache.org/jira/browse/LOG4J2-2816?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17272510#comment-17272510
]
Jacob Shields edited comment on LOG4J2-2816 at 1/27/21, 2:32 AM:
-----------------------------------------------------------------
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 still published? That would result in the exception we see
here.
This discussion looks related:
https://github.com/LMAX-Exchange/disruptor/issues/244#issuecomment-437814712
There the suggestion was to detect events that weren't completely translated in
the {{EventHandler}}, and ignore their data.
/
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}}.
Whereas 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}}.
It appears that {{StatusLogger}}'s default level is {{ERROR}}, so we may not be
seeing these exceptions in our logs if they are occurring. Perhaps we should
change this to {{WARN}} in our configurations and check for exceptions from the
translator.
was (Author: jshields-squarespace):
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 still published? That would result in the exception we see
here.
This discussion looks related:
https://github.com/LMAX-Exchange/disruptor/issues/244#issuecomment-437814712
There the suggestion was to detect events that weren't completely translated in
the {{EventHandler}}, and ignore their data.
/
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}}.
Whereas 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}}.
It appears that {{StatusLogger}}'s default level is {{ERROR}}, so we may not be
seeing these exceptions in our logs if they are occurring. Perhaps we should
change this to {{WARN}} in our configurations and check for exceptions from the
translator.
/
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)
