[
https://issues.apache.org/jira/browse/LOG4J2-1518?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Leon Finker updated LOG4J2-1518:
--------------------------------
Attachment: 10511.jstack
Full thread dump attached. I can see that the async logger processor thread is
not doing anything and waiting for events:
{noformat}
"Log4j2-AsyncLogger[AsyncContext@18b4aac2]1" #24 daemon prio=5 os_prio=64
tid=0x0000000002278000 nid=0x2b runnable [0xfffffd7e695fe000]
java.lang.Thread.State: RUNNABLE
at
com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:56)
at
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:124)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
Yet all the other threads are blocked on
{noformat}
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
at
com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
at
com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
at
org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
at
org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:169)
{noformat}
And the only out of ordinary thread stack that is nested with double log calls
is:
{noformat}
"102469:c:japan" #171 prio=5 os_prio=64 tid=0x00000000052be000 nid=0xba
runnable [0xfffffd7e5d1e7000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
at
com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
at
com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
at
org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
at
org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:169)
at
org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:161)
at
org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:156)
at
org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:126)
at
org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2005)
at
org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1876)
at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:124)
...
at x.share.biz.instrument.Instrument.toString(Instrument.java:290)
at
org.apache.logging.log4j.message.ParameterFormatter.tryObjectToString(ParameterFormatter.java:611)
at
org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(ParameterFormatter.java:431)
at
org.apache.logging.log4j.message.ParameterFormatter.formatMessage2(ParameterFormatter.java:189)
at
org.apache.logging.log4j.message.ReusableParameterizedMessage.formatTo(ReusableParameterizedMessage.java:307)
at
org.apache.logging.log4j.core.async.RingBufferLogEvent.setMessage(RingBufferLogEvent.java:118)
at
org.apache.logging.log4j.core.async.RingBufferLogEvent.setValues(RingBufferLogEvent.java:104)
at
org.apache.logging.log4j.core.async.RingBufferLogEventTranslator.translateTo(RingBufferLogEventTranslator.java:56)
at
org.apache.logging.log4j.core.async.RingBufferLogEventTranslator.translateTo(RingBufferLogEventTranslator.java:34)
at
com.lmax.disruptor.RingBuffer.translateAndPublish(RingBuffer.java:947)
at com.lmax.disruptor.RingBuffer.tryPublishEvent(RingBuffer.java:463)
at
org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.tryPublish(AsyncLoggerDisruptor.java:190)
at
org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:160)
at
org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:156)
at
org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:126)
at
org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2005)
at
org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1876)
at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:124)
...
{noformat}
> Deadlock when using pure async and toString logs another message
> ----------------------------------------------------------------
>
> Key: LOG4J2-1518
> URL: https://issues.apache.org/jira/browse/LOG4J2-1518
> Project: Log4j 2
> Issue Type: Bug
> Affects Versions: 2.6.2
> Environment: Linux/WIndows/Solaris
> Reporter: Leon Finker
> Attachments: 10511.jstack, async_deadlock.txt
>
>
> Hi,
> It looks like this was reported before in: LOG4J2-471
> We've encountered similar issue with one of the libraries where it's toString
> was indirectly also logging. This caused a deadlock when RingBuffer was full.
> Please see attached stack snippet.
> According to the following docs, it's possible to set sync policy to
> synchronously log the event if buffer is full. I don't see it documented.
> What's the policy option?
> https://issues.apache.org/jira/plugins/servlet/mobile#issue/LOG4J2-1080
> https://logging.apache.org/log4j/2.x/log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicyFactory.html
> Thank you
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
