[
https://issues.apache.org/jira/browse/LOG4J2-485?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Remko Popma updated LOG4J2-485:
-------------------------------
Description:
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.
was:
Similar to LOG4J2-471, but for AsyncAppender.
See DeadlockDemo class in LOG4J2-471 comments.
> 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: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
