Deadlock in aQute.junit.Tee

[amichair]

The project is currently using 6.4.0, but it looks like this class hasn't been changed in years, so might be still relevant.

Tee extends PrintStream which extends FilterOutputStream which as an OutputStream out field.
Tee uses the grandparent's out field as a monitor, it's parent PrintStream uses itself as a monitor, and presumably the OutputStream may also use itself as a monitor. Some methods in Tee grab its monitor first, but some (like flush) are not implemented so are handled by the parent that grabs the second monitor first. Two monitors need to be held by println and flush, but in different order, hence the deadlock.

From thread dump:

Found one Java-level deadlock:
=============================
"main":
  waiting to lock monitor 0x00007ea640005100 (object 0x00000000fa9b3550, a java.io.PrintStream),
  which is held by "TcpConnection-Reader-org.apache.aries.rsa.discovery.tcp.TcpConnection@6350c49"
"TcpConnection-Reader-org.apache.aries.rsa.discovery.tcp.TcpConnection@6350c49":
  waiting to lock monitor 0x00007ea52c003380 (object 0x00000000fed4ebe0, a aQute.junit.Tee),
  which is held by "main"

Java stack information for the threads listed above:
===================================================
"main":
        at java.io.PrintStream.flush(java.base@11.0.30/PrintStream.java:414)
        - waiting to lock <0x00000000fa9b3550> (a java.io.PrintStream)
        at java.io.PrintStream.flush(java.base@11.0.30/PrintStream.java:417)
        - locked <0x00000000fed4ebe0> (a aQute.junit.Tee)
        at org.apache.logging.log4j.core.util.CloseShieldOutputStream.flush(CloseShieldOutputStream.java:43)
        at org.apache.logging.log4j.core.appender.OutputStreamManager.flushDestination(OutputStreamManager.java:277)
        - locked <0x00000000fc3190e8> (a org.apache.logging.log4j.core.appender.OutputStreamManager)
        at org.apache.logging.log4j.core.appender.OutputStreamManager.flush(OutputStreamManager.java:308)
        - locked <0x00000000fc3190e8> (a org.apache.logging.log4j.core.appender.OutputStreamManager)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:229)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:220)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:211)
        at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:160)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:133)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:124)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
        at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:705)
        at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:663)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:639)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:540)
        at org.apache.logging.log4j.core.config.DefaultReliabilityStrategy.log(DefaultReliabilityStrategy.java:53)
        at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:155)
        at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog0(PaxLoggerImpl.java:1129)
        at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog(PaxLoggerImpl.java:1099)
        at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.debug(PaxLoggerImpl.java:253)
        at org.apache.felix.scr.impl.logger.ScrLogManager$ScrLoggerFacade.log0(ScrLogManager.java:195)
        at org.apache.felix.scr.impl.logger.ScrLogManager$ScrLoggerFacade.log(ScrLogManager.java:154)
        at org.apache.felix.scr.impl.Activator.debug(Activator.java:689)
        at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:195)
        at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169)
        at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49)
        at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:490)
        at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:1)
        at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:233)
        at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:452)
        at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:987)
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
        at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151)
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:237)
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:136)
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:128)
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:232)
        at org.eclipse.osgi.container.Module.publishEvent(Module.java:534)
        at org.eclipse.osgi.container.Module.start(Module.java:518)
        at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:471)
        at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:490)
        at org.osgi.test.cases.remoteserviceadmin.junit.DiscoveryTest.testDiscoveryBasicEndpointEvents_122_6_3(DiscoveryTest.java:398)
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.30/Native Method)
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.30/NativeMethodAccessorImpl.java:62)
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.30/DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(java.base@11.0.30/Method.java:566)
        at junit.framework.TestCase.runTest(TestCase.java:177)
        at junit.framework.TestCase.runBare(TestCase.java:142)
        at junit.framework.TestResult$1.protect(TestResult.java:122)
        at junit.framework.TestResult.runProtected(TestResult.java:142)
        at junit.framework.TestResult.run(TestResult.java:125)
        at junit.framework.TestCase.run(TestCase.java:130)
        at junit.framework.TestSuite.runTest(TestSuite.java:241)
        at junit.framework.TestSuite.run(TestSuite.java:236)
        at junit.framework.TestSuite.runTest(TestSuite.java:241)
        at junit.framework.TestSuite.run(TestSuite.java:236)
        at aQute.junit.Activator.test(Activator.java:354)
        at aQute.junit.Activator.automatic(Activator.java:266)
        at aQute.junit.Activator.run(Activator.java:188)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.30/Executors.java:515)
        at aQute.launcher.Launcher.handleMainCallable(Launcher.java:465)
        at aQute.launcher.Launcher.launch(Launcher.java:438)
        at aQute.launcher.Launcher.run(Launcher.java:186)
        at aQute.launcher.Launcher.main(Launcher.java:162)
        at java.lang.invoke.LambdaForm$DMH/0x0000000840062c40.invokeStaticInit(java.base@11.0.30/LambdaForm$DMH)
        at java.lang.invoke.LambdaForm$MH/0x0000000840067c40.invoke(java.base@11.0.30/LambdaForm$MH)
        at java.lang.invoke.LambdaForm$MH/0x0000000840067840.invoke_MT(java.base@11.0.30/LambdaForm$MH)
        at aQute.launcher.pre.EmbeddedLauncher.executeWithRunPath(EmbeddedLauncher.java:170)
        at aQute.launcher.pre.EmbeddedLauncher.findAndExecute(EmbeddedLauncher.java:135)
        at aQute.launcher.pre.EmbeddedLauncher.main(EmbeddedLauncher.java:52)
"TcpConnection-Reader-org.apache.aries.rsa.discovery.tcp.TcpConnection@6350c49":
        at java.io.PrintStream.println(java.base@11.0.30/PrintStream.java:881)
        - waiting to lock <0x00000000fed4ebe0> (a aQute.junit.Tee)
        at aQute.junit.Tee.println(Tee.java:204)
        - locked <0x00000000fa9b3550> (a java.io.PrintStream)
        at org.osgi.test.cases.remoteserviceadmin.junit.DiscoveryTest$EndpointEventListenerImpl.endpointChanged(DiscoveryTest.java:873)
        at org.apache.aries.rsa.discovery.tcp.Interest.lambda$notifyListener$0(Interest.java:57)
        at org.apache.aries.rsa.discovery.tcp.Interest$$Lambda$335/0x000000084045fc40.accept(Unknown Source)
        at java.util.Optional.ifPresent(java.base@11.0.30/Optional.java:183)
        at org.apache.aries.rsa.discovery.tcp.Interest.notifyListener(Interest.java:54)
        at org.apache.aries.rsa.discovery.tcp.InterestManager.lambda$notifyAllListeners$2(InterestManager.java:62)
        at org.apache.aries.rsa.discovery.tcp.InterestManager$$Lambda$333/0x000000084045f040.accept(Unknown Source)
        at java.util.concurrent.ConcurrentHashMap$ValuesView.forEach(java.base@11.0.30/ConcurrentHashMap.java:4770)
        at org.apache.aries.rsa.discovery.tcp.InterestManager.notifyAllListeners(InterestManager.java:62)
        at org.apache.aries.rsa.discovery.tcp.InterestManager.addEndpoint(InterestManager.java:69)
        at org.apache.aries.rsa.discovery.tcp.TcpConnectionManager.onMessage(TcpConnectionManager.java:212)
        at org.apache.aries.rsa.discovery.tcp.TcpConnectionManager$$Lambda$257/0x0000000840381c40.accept(Unknown Source)
        at org.apache.aries.rsa.discovery.tcp.TcpConnection.readLoop(TcpConnection.java:111)
        at org.apache.aries.rsa.discovery.tcp.TcpConnection$$Lambda$263/0x000000084039f840.run(Unknown Source)
        at java.lang.Thread.run(java.base@11.0.30/Thread.java:829)

Found 1 deadlock.

[peterkir]

Copilot Analysis of the issue.
https://github.com/peterkir/bnd/tasks/69801f02-6b2c-44ba-bd3d-7789dbf6c67d?author=peterkir

[amichair]

I'm getting a 404 on that link, maybe it's not public or somehow deleted?

[chrisrueger]

From that Copilot link:

short Summary:

The bug is that Tee's method overrides invent a lock (lock() returning out) that is inconsistent with the lock used by PrintStream's own synchronized methods (this), and they are acquired in opposite order in different methods.

Change lock() to return this instead of out:

protected Object lock() {
return this; // was: return out;
}

It's also worth adding an explicit flush() override in Tee for clarity and to make the locking intent explicit:

@OverRide
public void flush() {
synchronized (lock()) {
super.flush();
}
}
This makes it clear that flush() participates in the same lock protocol as all other methods. (With lock() returning this, super.flush() also does synchronized(this) which is reentrant — OK.)