Log4j 2
  1. Log4j 2
  2. LOG4J2-471

toString methods that perform logging can deadlock AsyncLogger

    Details

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

      Debian Squeeze
      Java 7u25

      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)
      1. LOG4J2-471.patch
        4 kB
        Anthony Baldocchi

        Issue Links

          Activity

          Anthony Baldocchi created issue -
          Remko Popma made changes -
          Field Original Value New Value
          Assignee Remko Popma [ remkop@yahoo.com ]
          Anthony Baldocchi made changes -
          Attachment LOG4J2-471.patch [ 12620074 ]
          Remko Popma made changes -
          Status Open [ 1 ] In Progress [ 3 ]
          Remko Popma made changes -
          Fix Version/s 2.0 [ 12324757 ]
          Remko Popma made changes -
          Status In Progress [ 3 ] Resolved [ 5 ]
          Fix Version/s 2.0-rc1 [ 12325011 ]
          Resolution Fixed [ 1 ]
          Remko Popma made changes -
          Link This issue is related to LOG4J2-485 [ LOG4J2-485 ]
          Anthony Baldocchi made changes -
          Status Resolved [ 5 ] Closed [ 6 ]

            People

            • Assignee:
              Remko Popma
              Reporter:
              Anthony Baldocchi
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development