[LOG4J2-1221] Dead lock observed in BlockingWaitStrategy in Log4J

• Type: Bug
• Status: Closed
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 2.2
• Fix Version/s: 2.6
• Component/s: Core
• Labels: patch

Environment

log4J Version : 2.2 Disruptor Version : 3.3.2
Ring Buffer Size : 128
OS Version :
cat /etc/release
Oracle Solaris 11.2 X86
Java Version
java version "1.7.0_45"
Java(TM) SE Runtime Environment (build 1.7.0_45-b18)
Java HotSpot(TM) Server VM (build 24.45-b08, mixed mode)

• Flags: Patch, Important
• External issue URL: https://github.com/LMAX-Exchange/disruptor/issues/138
• External issue ID: 138
• Assignee: Unassigned
• Reporter: Sampath Kumar
• Created: 11/Dec/15 16:43
• Updated: 08/Apr/16 08:11
• Resolved: 23/Dec/15 14:14

Description

We have seen this behavior in during high load. Where Logging Got Stropped and Application Went to not responsive state.
log4J Version : 2.2 Disruptor Version : 3.3.2
Ring Buffer Size : 128
Producer(Multiples Threads) and Consumer Threads(Single Thread As per Log 4J Configuration) Started Waiting on each other.

Here is the one of the Trace from Thread Dump:

Producer :
"[ACTIVE] ExecuteThread: '7' for queue: 'weblogic.kernel.Default (self-tuning)'" TIMED_WAITING
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:349)
com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:444)
com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:256)
org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:285)
org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:722)
org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:693)
org.apache.logging.log4j.jcl.Log4jLog.debug(Log4jLog.java:81)

Consumer Thread :

"AsyncLogger-1" waiting for lock java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@5d972983 WAITING
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
com.lmax.disruptor.BlockingWaitStrategy.waitFor(BlockingWaitStrategy.java:45)
com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:55)
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:123)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:744)

Is this is known issue which got already fixed in recent build ?

Issue Links

• is related to: LOG4J2-1080 Drop events when the RingBuffer is full
• relates to: LOG4J2-1350 Circuit Breaker for log system to avoid DOS by recursion