Deadlocks with DEBUG logging enabled in jetty-server testing

[joakime]

Jetty version(s)
12.0.6-SNAPSHOT

Jetty Environment
Any

Java version/vendor (use: java -version)
OpenJDK 17 (but could happen in any JDK)

OS type/version
Any

Description
When running the jetty-server tests in DEBUG a deadlock was discovered.

Thread Dump of pid 50408 showing 2 deadlocks.

To copy/paste the first deadlock seen from the attached thread dump ...

Found one Java-level deadlock:
=============================
"ForkJoinPool-1-worker-1":
  waiting for ownable synchronizer 0x00000006a7000070, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
  which is held by "qtp1985660841-12081"

"qtp1985660841-12081":
  waiting for ownable synchronizer 0x00000006a7095a80, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
  which is held by "ForkJoinPool-1-worker-1"

Java stack information for the threads listed above:
===================================================
"ForkJoinPool-1-worker-1":
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x00000006a7000070> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:211)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire([email protected]/AbstractQueuedSynchronizer.java:715)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire([email protected]/AbstractQueuedSynchronizer.java:938)
	at java.util.concurrent.locks.ReentrantLock$Sync.lock([email protected]/ReentrantLock.java:153)
	at java.util.concurrent.locks.ReentrantLock.lock([email protected]/ReentrantLock.java:322)
	at org.eclipse.jetty.util.thread.AutoLock.lock([email protected]/AutoLock.java:44)
	at org.eclipse.jetty.server.internal.HttpChannelState.toString([email protected]/HttpChannelState.java:527)
	at java.util.Formatter$FormatSpecifier.printString([email protected]/Formatter.java:3056)
	at java.util.Formatter$FormatSpecifier.print([email protected]/Formatter.java:2933)
	at java.util.Formatter.format([email protected]/Formatter.java:2689)
	at java.util.Formatter.format([email protected]/Formatter.java:2625)
	at java.lang.String.format([email protected]/String.java:4141)
	at org.eclipse.jetty.server.internal.HttpConnection.toConnectionString([email protected]/HttpConnection.java:660)
	at org.eclipse.jetty.io.AbstractEndPoint.toConnectionString([email protected]/AbstractEndPoint.java:462)
	at org.eclipse.jetty.io.AbstractEndPoint.toString([email protected]/AbstractEndPoint.java:441)
	at org.eclipse.jetty.io.ByteArrayEndPoint.toString([email protected]/ByteArrayEndPoint.java:503)
	at org.slf4j.helpers.MessageFormatter.safeObjectAppend([email protected]/MessageFormatter.java:291)
	at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter([email protected]/MessageFormatter.java:263)
	at org.slf4j.helpers.MessageFormatter.arrayFormat([email protected]/MessageFormatter.java:225)
	at org.slf4j.helpers.MessageFormatter.arrayFormat([email protected]/MessageFormatter.java:160)
	at org.eclipse.jetty.logging.StdErrAppender.format([email protected]/StdErrAppender.java:162)
	at org.eclipse.jetty.logging.StdErrAppender.emit([email protected]/StdErrAppender.java:93)
	at org.eclipse.jetty.logging.JettyLogger.emit([email protected]/JettyLogger.java:640)
	at org.eclipse.jetty.logging.JettyLogger.debug([email protected]/JettyLogger.java:181)
	at org.eclipse.jetty.io.ByteArrayEndPoint.addInput([email protected]/ByteArrayEndPoint.java:203)
	at org.eclipse.jetty.server.handler.gzip.GzipHandlerTest.testHEADThenGETPersistent([email protected]/GzipHandlerTest.java:338)

"qtp1985660841-12081":
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x00000006a7095a80> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:211)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire([email protected]/AbstractQueuedSynchronizer.java:715)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire([email protected]/AbstractQueuedSynchronizer.java:938)
	at java.util.concurrent.locks.ReentrantLock$Sync.lock([email protected]/ReentrantLock.java:153)
	at java.util.concurrent.locks.ReentrantLock.lock([email protected]/ReentrantLock.java:322)
	at org.eclipse.jetty.util.thread.AutoLock.lock([email protected]/AutoLock.java:44)
	at org.eclipse.jetty.io.ByteArrayEndPoint.toString([email protected]/ByteArrayEndPoint.java:497)
	at java.util.Formatter$FormatSpecifier.printString([email protected]/Formatter.java:3056)
	at java.util.Formatter$FormatSpecifier.print([email protected]/Formatter.java:2933)
	at java.util.Formatter.format([email protected]/Formatter.java:2689)
	at java.util.Formatter.format([email protected]/Formatter.java:2625)
	at java.lang.String.format([email protected]/String.java:4141)
	at org.eclipse.jetty.io.AbstractConnection.toString([email protected]/AbstractConnection.java:309)
	at org.slf4j.helpers.MessageFormatter.safeObjectAppend([email protected]/MessageFormatter.java:291)
	at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter([email protected]/MessageFormatter.java:263)
	at org.slf4j.helpers.MessageFormatter.arrayFormat([email protected]/MessageFormatter.java:225)
	at org.slf4j.helpers.MessageFormatter.arrayFormat([email protected]/MessageFormatter.java:160)
	at org.eclipse.jetty.logging.StdErrAppender.format([email protected]/StdErrAppender.java:162)
	at org.eclipse.jetty.logging.StdErrAppender.emit([email protected]/StdErrAppender.java:93)
	at org.eclipse.jetty.logging.JettyLogger.emit([email protected]/JettyLogger.java:640)
	at org.eclipse.jetty.logging.JettyLogger.debug([email protected]/JettyLogger.java:181)
	at org.eclipse.jetty.server.internal.HttpConnection.parseRequestBuffer([email protected]/HttpConnection.java:569)
	at org.eclipse.jetty.server.internal.HttpConnection.parseAndFillForContent([email protected]/HttpConnection.java:492)
	at org.eclipse.jetty.server.internal.HttpConnection$HttpStreamOverHTTP1.read([email protected]/HttpConnection.java:1349)
	at org.eclipse.jetty.server.HttpStream.consumeAvailable([email protected]/HttpStream.java:117)
	at org.eclipse.jetty.server.internal.HttpConnection$HttpStreamOverHTTP1.consumeAvailable([email protected]/HttpConnection.java:1112)
	at org.eclipse.jetty.server.internal.HttpChannelState$ChannelCallback.succeeded([email protected]/HttpChannelState.java:1448)
	at org.eclipse.jetty.server.handler.ContextResponse$1$$Lambda$1028/0x00000007c0484a00.run([email protected]/Unknown Source)
	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run([email protected]/ContextHandler.java:1202)
	at org.eclipse.jetty.server.handler.ContextResponse$1.succeeded([email protected]/ContextResponse.java:41)
	at org.eclipse.jetty.server.internal.HttpChannelState$ChannelResponse$$Lambda$772/0x00000007c0380540.run([email protected]/Unknown Source)
	at org.eclipse.jetty.util.thread.SerializedInvoker$NamedRunnable.run([email protected]/SerializedInvoker.java:219)
	at org.eclipse.jetty.util.thread.SerializedInvoker$Link.run([email protected]/SerializedInvoker.java:191)
	at org.eclipse.jetty.util.thread.SerializedInvoker.run([email protected]/SerializedInvoker.java:117)
	at org.eclipse.jetty.server.internal.HttpChannelState$ChannelResponse.succeeded([email protected]/HttpChannelState.java:1242)
	at org.eclipse.jetty.server.internal.HttpConnection$SendCallback.onCompleteSuccess([email protected]/HttpConnection.java:906)
	at org.eclipse.jetty.util.IteratingCallback.processing([email protected]/IteratingCallback.java:333)
	at org.eclipse.jetty.util.IteratingCallback.iterate([email protected]/IteratingCallback.java:231)
	at org.eclipse.jetty.server.internal.HttpConnection$HttpStreamOverHTTP1.send([email protected]/HttpConnection.java:1423)
	at org.eclipse.jetty.server.internal.HttpChannelState$ChannelResponse.write([email protected]/HttpChannelState.java:1217)
	at org.eclipse.jetty.server.Response$Wrapper.write([email protected]/Response.java:757)
	at org.eclipse.jetty.server.handler.ContextResponse.write([email protected]/ContextResponse.java:56)
	at org.eclipse.jetty.server.handler.gzip.GzipHandlerTest$SingleWriteHandler.handle([email protected]/GzipHandlerTest.java:2000)
	at org.eclipse.jetty.server.handler.ContextHandler.handle([email protected]/ContextHandler.java:761)
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle([email protected]/GzipHandler.java:594)
	at org.eclipse.jetty.server.Handler$Wrapper.handle([email protected]/Handler.java:716)
	at org.eclipse.jetty.server.handler.gzip.GzipHandlerTest$CheckHandler.handle([email protected]/GzipHandlerTest.java:2052)
	at org.eclipse.jetty.server.Server.handle([email protected]/Server.java:221)
	at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run([email protected]/HttpChannelState.java:596)
	at org.eclipse.jetty.server.internal.HttpConnection.onFillable([email protected]/HttpConnection.java:410)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded([email protected]/AbstractConnection.java:322)
	at org.eclipse.jetty.io.FillInterest.fillable([email protected]/FillInterest.java:99)
	at org.eclipse.jetty.io.ByteArrayEndPoint.lambda$new$0([email protected]/ByteArrayEndPoint.java:58)
	at org.eclipse.jetty.io.ByteArrayEndPoint$$Lambda$1004/0x00000007c04373f8.run([email protected]/Unknown Source)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob([email protected]/QueuedThreadPool.java:971)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob([email protected]/QueuedThreadPool.java:1201)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run([email protected]/QueuedThreadPool.java:1156)
	at java.lang.Thread.run([email protected]/Thread.java:833)

[joakime]

Once PR #11225 is merged, this deadlock can be triggered with the following.

Turn on DEBUG for all of jetty-server, run StopTest.testCommittedResponsesAreClosed()

[joakime]

Attaching latest deadlock jstack dumps.

debug-deadlock.log
debug-deadlock-2.log

[sbordet]

The problem is as follows:

In the example above, T1 grabs the ByteArrayEndPoint lock, then logs the ByteArrayEndPoint, which logs the associated Connection, which calls HttpChannelState.toString(), that tries to grab the HttpChannelState lock.
Thread T2 grabs the HttpChannelState lock, calls HttpStream.consumeAvailable(), which eventually logs the Connection, which tries to log the associated ByteArrayEndPoint, which tries to grab the ByteArrayEndPoint lock, resulting in the deadlock.

The fact that EndPoint and Connection are double-linked is important, but this can happen in general on any class that as a double-link, for example Handler and Server.

It is going to be hard to find and modify the toString() of the double-linked pairs, so while breaking the link in toString() would solve the problem, it seems a fragile solution (the link may be re-instated by mistake, or other pairs may be introduced).

The log debug statement are going to occur anyway, if not explicitly within the lock, in a method called from within the lock that does not know that it is being called with a lock held.

After discussion, the solution has been to introduce AutoLock.tryLock() in relevant toString() implementations, so that the deadlock does not happen, at the cost of -- in case of potential deadlock -- performing a reduced version of the log.

[sbordet]

A related, but different, issue: #8354.