[
https://issues.apache.org/jira/browse/LOG4J2-471?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13855123#comment-13855123
]
Remko Popma commented on LOG4J2-471:
------------------------------------
Anthony, from the stacktrace, I agree with your analysis. I'm still thinking
about how to solve this.
Did you use the default ring buffer size?
Btw, it looks like this issue can also happen with {{AsyncAppender}}. (See demo
code below).
The saving grace with {{AsyncAppender}} is that it can be configured to
{{blocking="false"}}, which will log to an errorAppender when the queue is
full. AsyncLoggers currently don't have any such mechanism.
{code}
package demo.deadlock;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public class DeadlockDemo {
static Logger sLog = LogManager.getLogger(DeadlockDemo.class);
public static void main(String[] args) throws Exception {
try {
System.out.println("(Sysout) Before throwing ex...");
sLog.info("(Log) Before throwing ex...");
Thread.sleep(1000);
throw new LoggingEx();
} catch (Exception ex) {
sLog.warn("Caught a {} problem", ex, ex);
sLog.error(ex, ex);
}
System.out.println("(Sysout) After catching ex");
sLog.info("(Log) After catching ex");
Thread.sleep(1000);
System.out.println("(Sysout) After 1 sec..."); // I still see this
sLog.info("(Log) After 1 sec..."); // causes deadlock on my laptop
Thread.sleep(1000);
System.out.println("(Sysout) After 2 sec..."); // I don't see this
output
sLog.info("(Log) After 2 sec...");
}
public static class LoggingEx extends Exception {
static final Logger exLog = LogManager.getLogger(LoggingEx.class);
@Override
public String toString() {
System.out.println("(Sysout) Before LoggingEx calling logger.debug
300 times...");
// fill up AsyncAppender queue (128 slots)
for(int i = 0; i < 300; i++) {
exLog.debug("(Log) in LoggingEx.toString() {}...", i);
}
System.out.println("(Sysout) After LoggingEx called logger.debug
300 times...");
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
return "oops";
}
}
}
{code}
log4j2.xml config:
{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>
<Async name="Async" bufferSize="128" errorRef="STDOUT">
<appenderRef ref="STDOUT" />
</Async>
</appenders>
<loggers>
<root level="DEBUG">
<appenderRef ref="Async" />
</root>
</loggers>
</configuration>
{code}
Output:
{code}
(Sysout) Before throwing ex...
(Log) Before throwing ex...
(Sysout) Before LoggingEx calling logger.debug 300 times...
(Log) in LoggingEx.toString() 0...
(Log) in LoggingEx.toString() 1...
(Log) in LoggingEx.toString() 2...
...(omitted)
(Log) in LoggingEx.toString() 169...
(Log) in LoggingEx.toString() 170...
(Sysout) After LoggingEx called logger.debug 300 times...
(Log) in LoggingEx.toString() 171...
(Log) in LoggingEx.toString() 172...
...(omitted)
(Log) in LoggingEx.toString() 298...
(Log) in LoggingEx.toString() 299...
Caught a oops problem
demo.deadlock.DeadlockDemo$LoggingEx
at demo.deadlock.DeadlockDemo.main(DeadlockDemo.java:32) [bin/:?]
(Sysout) After catching ex
(Sysout) Before LoggingEx calling logger.debug 300 times...
(Sysout) After 1 sec...
{code}
... and the application hangs.
> 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
>
> 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-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
