logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-471) toString methods that perform logging can deadlock AsyncLogger
Date Sat, 04 Jan 2014 09:10:50 GMT

    [ https://issues.apache.org/jira/browse/LOG4J2-471?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13862250#comment-13862250
] 

Remko Popma commented on LOG4J2-471:
------------------------------------

Anthony, thanks again for the patch!
I've applied it with some changes, and also applied a variant of the same idea to AsyncLoggerConfig
(for mixed sync and async loggers).

I have not been able to create JUnit tests for the deadlock scenario, but I've used the DeadLockDemo
class in the [comment above|https://issues.apache.org/jira/browse/LOG4J2-471?focusedCommentId=13855123&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-13855123]
to verify the solution. Without the patch this class reliably deadlocks, with the patch there
is no deadlock (both for AsyncLoggers and AsyncLoggerConfig).

To test *AsyncLoggers*, run the above {{demo.deadlock.DeadlockDemo}} with system properties
{code}
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
-DAsyncLogger.RingBufferSize=128
{code}
and configuration
{code}
<?xml version="1.0" encoding="UTF-8"?>
<configuration status="TRACE" name="deadlock-demo" packages="">
  <appenders>
      <Console name="STDOUT" target="SYSTEM_OUT">
        <PatternLayout pattern="%m%n"/>
      </Console>
  </appenders>
  <loggers>
    <root level="DEBUG">
      <appenderRef ref="STDOUT" />
    </root>
  </loggers>
</configuration>
{code}

To test *AsyncLoggerConfig* (mixed sync and async loggers), run the above {{demo.deadlock.DeadlockDemo}}
with system properties
{code}
-DAsyncLoggerConfig.RingBufferSize=128
{code}
and configuration
{code}
<?xml version="1.0" encoding="UTF-8"?>
<configuration status="TRACE" name="deadlock-demo" packages="">
  <appenders>
      <Console name="STDOUT" target="SYSTEM_OUT">
        <PatternLayout pattern="%m%n"/>
      </Console>
  </appenders>
  <loggers>
    <AsyncRoot level="DEBUG">
      <appenderRef ref="STDOUT" />
    </AsyncRoot>
  </loggers>
</configuration>
{code}

Fixed in revision 1555336.
Please verify and close.

> toString methods that perform logging can deadlock AsyncLogger
> --------------------------------------------------------------
>
>                 Key: LOG4J2-471
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-471
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Core
>    Affects Versions: 2.0-beta9
>         Environment: Debian Squeeze
> Java 7u25
>            Reporter: Anthony Baldocchi
>            Assignee: Remko Popma
>             Fix For: 2.0-rc1, 2.0
>
>         Attachments: LOG4J2-471.patch
>
>
> 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)



--
This message was sent by Atlassian JIRA
(v6.1.5#6160)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message