[logback-dev] [JIRA] (LOGBACK-1492) AppenderBase is deadlock prone
QOS.CH (JIRA)
noreply-jira at qos.ch
Tue Nov 19 10:56:00 CET 2019
Christoffer Eide created LOGBACK-1492:
-----------------------------------------
Summary: AppenderBase is deadlock prone
Key: LOGBACK-1492
URL: https://jira.qos.ch/browse/LOGBACK-1492
Project: logback
Issue Type: Bug
Environment: {noformat}
java version "1.8.0_192"
Java(TM) SE Runtime Environment (build 1.8.0_192-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.192-b12, mixed mode)
{noformat}
Tested in HEAD ({{cc0d7394faf2525a43f967f8960d54ebefe30b2c}})
Reporter: Christoffer Eide
Assignee: Logback dev list
We encountered a deadlock with a subclass of {{ch.qos.logback.core.AppenderBase}}.
The implementation of {{append()}} is:
{code:java}
@Override
protected void append(ILoggingEvent event) {
event.prepareForDeferredProcessing();
try {
queue.put(event);
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
}
}
{code}
{{AppenderBase#doAppend}} has the signature:
{code:java}
public synchronized void doAppend(E eventObject)
{code}
And it calls the subclass {{append()}}.
The deadlock occurred because the subclass of {{AppenderBase}} called {{toString()}} on an object (via {{ILoggingEvent#prepareForDeferredProcessing()}}) while holding a lock in {{AppenderBase#doAppend}}. The objects {{toString()}} method grabbed a second lock, leading to a deadlock.
One might argue that an implementation of {{toString()}} should _not_ grab a lock, but it's also bad practice to call an alien method while holding a lock.
>From JCIP 10.1.3:
??Invoking an alien method with a lock held is asking for liveness trouble. The alien method might acquire other locks (risking deadlock) or block for an unexpectedly long time, stalling other threads that need the lock you hold??
The test below demonstrates the problem we encountered:
{code:java}
package ch.qos.logback.core;
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.spi.ILoggingEvent;
import org.junit.Before;
import org.junit.Test;
import java.lang.management.ManagementFactory;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
import static java.util.concurrent.Executors.newFixedThreadPool;
import static org.junit.Assert.assertNull;
public class AppenderBaseDeadlockTest {
static CountDownLatch inReload = new CountDownLatch(1);
Logger logger;
ExecutorService executor;
@Before
public void setUp() throws Exception {
LoggerContext context = new LoggerContext();
logger = context.getLogger(Logger.ROOT_LOGGER_NAME);
logger.detachAndStopAllAppenders();
logger.setLevel(Level.TRACE);
logger.addAppender(new AppenderBase<ILoggingEvent>() {
{
start();
}
@Override
protected void append(ILoggingEvent eventObject) {
inReload.countDown();
eventObject.prepareForDeferredProcessing();
}
});
executor = newFixedThreadPool(2, runnable -> {
Thread thread = Executors.defaultThreadFactory().newThread(runnable);
thread.setDaemon(true);
return thread;
});
}
@Test
public void testDeadlock() throws Exception {
ClassWithLockOnToString classWithLockOnToString = new ClassWithLockOnToString(logger);
CountDownLatch start = new CountDownLatch(1);
executor.submit(() -> {
start.await();
logger.debug("{}", classWithLockOnToString);
return null;
});
executor.submit(() -> {
start.await();
classWithLockOnToString.reload();
return null;
});
start.countDown();
executor.shutdown();
if(!executor.awaitTermination(1, TimeUnit.SECONDS)){
assertNull(ManagementFactory.getThreadMXBean().findDeadlockedThreads());
}
}
static class ClassWithLockOnToString {
private final Logger logger;
ClassWithLockOnToString(Logger logger) {
this.logger = logger;
}
void reload(){
synchronized (this){
try {
inReload.await();
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
}
logger.debug("ClassWithLockOnToString#toStringwreload()");
}
}
@Override
public String toString() {
reload();
return "ClassWithLockOnToString#toString()";
}
}
}
{code}
A simplified stack track trace of the stack:
{noformat}
ThreadA
-> logger#debug
-> AppenderBase#doAppend <-- Grabs Lock A
-> LoggingEvent#prepareForDeferredProcessing
-> ClassWithLockOnToString#toString
-> ClassWithLockOnToString#reload <-- Grabs Lock B
ThreadB
-> ClassWithLockOnToString#reload <-- Grabs Lock B
-> logger#debug
-> AppenderBase#doAppend <-- Grabs Lock A
{noformat}
Full stacktraces of the deadlocked threads
{noformat}
"pool-1-thread-1 at 1038" daemon prio=5 tid=0xd nid=NA waiting for monitor entry
java.lang.Thread.State: BLOCKED
blocks pool-2-thread-1 at 1043
waiting for pool-2-thread-1 at 1043 to release lock on <0x42d> (a ch.qos.logback.core.AppenderBaseDeadlockTest$ClassWithLockOnToString)
at ch.qos.logback.core.AppenderBaseDeadlockTest$ClassWithLockOnToString.reload(AppenderBaseDeadlockTest.java:95)
at ch.qos.logback.core.AppenderBaseDeadlockTest$ClassWithLockOnToString.toString(AppenderBaseDeadlockTest.java:105)
at org.slf4j.helpers.MessageFormatter.safeObjectAppend(MessageFormatter.java:292)
at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(MessageFormatter.java:264)
at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:226)
at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:161)
at ch.qos.logback.classic.spi.LoggingEvent.getFormattedMessage(LoggingEvent.java:314)
at ch.qos.logback.classic.spi.LoggingEvent.prepareForDeferredProcessing(LoggingEvent.java:218)
at ch.qos.logback.core.AppenderBaseDeadlockTest$1.append(AppenderBaseDeadlockTest.java:42)
at ch.qos.logback.core.AppenderBaseDeadlockTest$1.append(AppenderBaseDeadlockTest.java:34)
at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:82)
- locked <0x438> (a ch.qos.logback.core.AppenderBaseDeadlockTest$1)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:423)
at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:400)
at ch.qos.logback.classic.Logger.debug(Logger.java:488)
at ch.qos.logback.core.AppenderBaseDeadlockTest.lambda$testDeadlock$1(AppenderBaseDeadlockTest.java:60)
at ch.qos.logback.core.AppenderBaseDeadlockTest$$Lambda$2.171497379.call(Unknown Source:-1)
at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266)
at java.util.concurrent.FutureTask.run(FutureTask.java:-1)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
{noformat}
{noformat}
"pool-2-thread-1 at 1043" daemon prio=5 tid=0xe nid=NA waiting for monitor entry
java.lang.Thread.State: BLOCKED
blocks pool-1-thread-1 at 1038
blocks main at 1
waiting for pool-1-thread-1 at 1038 to release lock on <0x438> (a ch.qos.logback.core.AppenderBaseDeadlockTest$1)
at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:63)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:423)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:385)
at ch.qos.logback.classic.Logger.debug(Logger.java:484)
at ch.qos.logback.core.AppenderBaseDeadlockTest$ClassWithLockOnToString.reload(AppenderBaseDeadlockTest.java:99)
- locked <0x42d> (a ch.qos.logback.core.AppenderBaseDeadlockTest$ClassWithLockOnToString)
at ch.qos.logback.core.AppenderBaseDeadlockTest.lambda$testDeadlock$2(AppenderBaseDeadlockTest.java:66)
at ch.qos.logback.core.AppenderBaseDeadlockTest$$Lambda$3.415186196.call(Unknown Source:-1)
at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266)
at java.util.concurrent.FutureTask.run(FutureTask.java:-1)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
{noformat}
--
This message was sent by Atlassian JIRA
(v7.3.1#73012)
More information about the logback-dev
mailing list