[
https://issues.apache.org/jira/browse/LOG4J2-485?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Remko Popma closed LOG4J2-485.
------------------------------
> toString methods that perform logging can deadlock AsyncAppender
> ----------------------------------------------------------------
>
> Key: LOG4J2-485
> URL: https://issues.apache.org/jira/browse/LOG4J2-485
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.0-beta9
> Reporter: Remko Popma
> Assignee: Remko Popma
> Fix For: 2.0-rc1, 2.0
>
>
> During analysis of LOG4J2-471, I found the same issue can happen with
> AsyncAppender. Summary of the problem:
> Application thread A calls {{Logger.log()}}, which puts LogEvents in a queue.
> Appender thread B takes LogEvents off the queue, converts them to a byte[]
> array and saves this byte array to disk. The conversion from a LogEvent to a
> byte[] array may itself result in calls to {{Logger.log()}} (particularly if
> logging is done from the {{toString()}} method of an object that is being
> logged).
> Here is where the problem occurs: if the Appender thread calls
> {{Logger.log()}} when processing LogEvents from the queue, and it happens
> that the queue is full, then in blocking mode, the Appender thread will block
> until space is available in the queue. Unfortunately space will only become
> available if the Appender consumes LogEvents, but the Appender thread is
> blocked... resulting in deadlock.
> It is possible to configure {{AsyncAppender}} with {{blocking="false"}},
> which will log to an errorAppender when the queue is full, but a better
> solution would be to prevent deadlock in the above scenario.
> The problem can be reproduced with this program:
> {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...");
> sLog.info("Done. Completed without deadlock.");
> }
>
> 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}
> ... and this 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.
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
