Details
Major Description
We encountered a deadlock with a subclass of ch.qos.logback.core.AppenderBase.
The implementation of append() is:
@Override protected void append(ILoggingEvent event) { event.prepareForDeferredProcessing(); try { queue.put(event); } catch (InterruptedException e) { Thread.currentThread().interrupt(); } }
AppenderBase#doAppend has the signature:
public synchronized void doAppend(E eventObject)
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:
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()"; } } }
A simplified stacktrace:
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
Full stacktraces of the deadlocked threads
"pool-1-thread-1@1038" daemon prio=5 tid=0xd nid=NA waiting for monitor entry java.lang.Thread.State: BLOCKED blocks pool-2-thread-1@1043 waiting for pool-2-thread-1@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)
"pool-2-thread-1@1043" daemon prio=5 tid=0xe nid=NA waiting for monitor entry java.lang.Thread.State: BLOCKED blocks pool-1-thread-1@1038 blocks main@1 waiting for pool-1-thread-1@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)