[
https://issues.apache.org/jira/browse/LOG4J2-2816?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17273172#comment-17273172
]
Jacob Shields commented on LOG4J2-2816:
---------------------------------------
We were able to reproduce this bug and find the root cause (in our case).
Thanks to my colleague Dan Vinegrad for helping out with the debugging effort.
Hibernate is logging a message using a {{StringFormattedMessage}}. One of the
format argument objects is one of our domain classes. Our domain class's
{{toString}} method has a bug that throws an exception.
Then what happens is {{RingBufferLogEventTranslator#translateTo}} indirectly
triggers that {{toString}} method, which triggers the exception and interrupts
the translator. However, as previously mentioned, Disruptor still publishes the
sequence, even though all the log event fields are missing. Then, the event is
picked up by {{RingBufferLogEventHandler}}, and a NPE is thrown because the
fields are missing.
I created a minimal reproducible example here:
https://github.com/jshields-squarespace/log4j2-async-npe-example
I think that Log4j needs to handle the scenario where an exception is thrown in
{{translateTo}} and the log event is published with missing data.
> 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)
