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@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) {noformat} {noformat} "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) {noformat} -- This message was sent by Atlassian JIRA (v7.3.1#73012)