[LOG4J2-471] toString methods that perform logging can deadlock AsyncLogger

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.0-beta9
• Fix Version/s: 2.0-rc1, 2.0
• Component/s: Core

Environment

Debian Squeeze
Java 7u25

• Assignee: Remko Popma
• Reporter: Anthony Baldocchi
• Created: 21/Dec/13 00:03
• Updated: 10/Sep/17 12:54
• Resolved: 04/Jan/14 09:10

Description

The AsyncLogger thread is the only consumer of a Disruptor RingBuffer which contains log events ostensibly produced by a number of other threads. However, when AsyncLogger generates a log message, it has to call toString() on objects which can potentially also perform logging internally. This results in a situation when the RingBuffer is nearly full whereby AsyncLogger has pulled an event from the RingBuffer, calls toString() on the associated objects, which call AsyncLogger.log which attempts to publish an event into a full buffer, which will park repeatedly without hope of ever leaving the loop. Relevant stack trace is:
"AsyncLogger-1" daemon prio=10 tid=0x00007f7a705a8000 nid=0x3d73 runnable [0x00007f7a740d1000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:349)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:133)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:102)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:391)
at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:219)
at org.apache.logging.log4j.core.async.AsyncLogger.log(AsyncLogger.java:214)
at org.apache.logging.log4j.spi.AbstractLoggerWrapper.log(AbstractLoggerWrapper.java:55)
at org.slf4j.impl.SLF4JLogger.debug(SLF4JLogger.java:138)
at org.somepackage.SomeException.toString (SomeException.java:32)
at java.lang.String.valueOf(String.java:2854)
at java.io.PrintWriter.println(PrintWriter.java:754)
at java.lang.Throwable$WrappedPrintWriter.println(Throwable.java:763)
at java.lang.Throwable.printStackTrace(Throwable.java:654)

• locked <0x00000000cb2f6380> (a java.io.PrintWriter)
  at java.lang.Throwable.printStackTrace(Throwable.java:720)
  at org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.formatOption(ThrowablePatternConverter.java:138)
  at org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.format(ThrowablePatternConverter.java:80)
  at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:69)
  at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
  at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:167)
  at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:52)
  at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:45)
  at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:111)
  at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
  at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
  at org.apache.logging.log4j.core.Logger$PrivateConfig.logEvent(Logger.java:273)
  at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:230)
  at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:98)
  at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:43)
  at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:28)
  at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
  at java.lang.Thread.run(Thread.java:724)

Issue Links

• is related to: LOG4J2-2031 Messages appear out of order in log file (was: Log4j2 log file not reflecting application log function calls)
• is related to: LOG4J2-485 toString methods that perform logging can deadlock AsyncAppender