Deadlock

[vemv]

I hit this deadlock while using cider-log-mode. I'm using logback-classic. This let the repl and local websever stuck indefinitely.

Last thing I was trying to do is to play with the filters.

These are the two stacktraces (separated by waiting to lock lines)

Stacks

+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|                                                                                 Name                                                                                  |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|  +---qtp2043949759-134  Blocked waiting to lock logjam.framework.logback.proxy$ch.qos.logback.core.AppenderBase$ff19274a@5a5c59ee which is held by qtp2043949759-139  |
|  | |                                                                                                                                                                  |
|  | +---ch.qos.logback.core.AppenderBase.doAppend AppenderBase.java:64                                                                                                 |
|  | |                                                                                                                                                                  |
|  | +---logjam.framework.logback.proxy$ch.qos.logback.core.AppenderBase$ff19274a.doAppend                                                                              |
|  | |                                                                                                                                                                  |
|  | +---ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders AppenderAttachableImpl.java:51                                                            |
|  | |                                                                                                                                                                  |
|  | +---ch.qos.logback.classic.Logger.appendLoopOnAppenders Logger.java:272                                                                                            |
|  | |                                                                                                                                                                  |
|  | +---ch.qos.logback.classic.Logger.callAppenders Logger.java:259                                                                                                    |
|  | |                                                                                                                                                                  |
|  | +---ch.qos.logback.classic.Logger.buildLoggingEventAndAppend Logger.java:426                                                                                       |
|  | |                                                                                                                                                                  |
|  | +---ch.qos.logback.classic.Logger.filterAndLog_2 Logger.java:419                                                                                                   |
|  | |                                                                                                                                                                  |
|  | +---ch.qos.logback.classic.Logger.debug Logger.java:495                                                                                                            |
|  | |                                                                                                                                                                  |
|  | +---org.eclipse.jetty.util.thread.ReservedThreadExecutor.startReservedThread ReservedThreadExecutor.java:256                                                       |
|  | |                                                                                                                                                                  |
|  | +---org.eclipse.jetty.util.thread.ReservedThreadExecutor.tryExecute ReservedThreadExecutor.java:236                                                                |
|  | |                                                                                                                                                                  |
|  | +---org.eclipse.jetty.util.thread.QueuedThreadPool.tryExecute QueuedThreadPool.java:809                                                                            |
|  | |                                                                                                                                                                  |
|  | +---org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.selectSubStrategy AdaptiveExecutionStrategy.java:340                                          |
|  | |                                                                                                                                                                  |
|  | +---org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce AdaptiveExecutionStrategy.java:277                                                 |
|  | |                                                                                                                                                                  |
|  | +---org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce AdaptiveExecutionStrategy.java:193                                                    |
|  | |                                                                                                                                                                  |
|  | +---org.eclipse.jetty.io.ManagedSelector$$Lambda/0x0000000803dee978.run                                                                                            |
|  | |                                                                                                                                                                  |
|  | +---org.eclipse.jetty.util.thread.QueuedThreadPool.runJob QueuedThreadPool.java:969                                                                                |
|  | |                                                                                                                                                                  |
|  | +---org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob QueuedThreadPool.java:1194                                                                      |
|  | |                                                                                                                                                                  |
|  | +---org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run QueuedThreadPool.java:1149                                                                           |
|  | |                                                                                                                                                                  |
|  | +---java.lang.Thread.runWith Thread.java:1596                                                                                                                      |
|  | |                                                                                                                                                                  |
|  | +---java.lang.Thread.run Thread.java:1583                                                                                                                          |
|  |                                                                                                                                                                    |
|  +---qtp2043949759-139  Waiting waiting to lock java.util.concurrent.locks.ReentrantLock$NonfairSync@6d05fd22 which is held by qtp2043949759-134                      |
|    |                                                                                                                                                                  |
|    +---jdk.internal.misc.Unsafe.park Unsafe.java (native)                                                                                                             |
|    |                                                                                                                                                                  |
|    +---java.util.concurrent.locks.LockSupport.park LockSupport.java:221                                                                                               |
|    |                                                                                                                                                                  |
|    +---java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire AbstractQueuedSynchronizer.java:754                                                              |
|    |                                                                                                                                                                  |
|    +---java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire AbstractQueuedSynchronizer.java:990                                                              |
|    |                                                                                                                                                                  |
|    +---java.util.concurrent.locks.ReentrantLock$Sync.lock ReentrantLock.java:153                                                                                      |
|    |                                                                                                                                                                  |
|    +---java.util.concurrent.locks.ReentrantLock.lock ReentrantLock.java:322                                                                                           |
|    |                                                                                                                                                                  |
|    +---org.eclipse.jetty.util.thread.AutoLock.lock AutoLock.java:44                                                                                                   |
|    |                                                                                                                                                                  |
|    +---org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.toString AdaptiveExecutionStrategy.java:542                                                   |
|    |                                                                                                                                                                  |
|    +---org.slf4j.helpers.MessageFormatter.safeObjectAppend MessageFormatter.java:291                                                                                  |
|    |                                                                                                                                                                  |
|    +---org.slf4j.helpers.MessageFormatter.deeplyAppendParameter MessageFormatter.java:263                                                                             |
|    |                                                                                                                                                                  |
|    +---org.slf4j.helpers.MessageFormatter.arrayFormat MessageFormatter.java:225                                                                                       |
|    |                                                                                                                                                                  |
|    +---org.slf4j.helpers.MessageFormatter.arrayFormat MessageFormatter.java:160                                                                                       |
|    |                                                                                                                                                                  |
|    +---ch.qos.logback.classic.spi.LoggingEvent.getFormattedMessage LoggingEvent.java:396                                                                              |
|    |                                                                                                                                                                  |
|    +---logjam.framework.logback$event_data.invokeStatic logback.clj:58                                                                                                |
|    |                                                                                                                                                                  |
|    +---logjam.framework.logback$event_data.invoke logback.clj:51                                                                                                      |
|    |                                                                                                                                                                  |
|    +---logjam.framework.logback$add_appender$fn__1486127.invoke logback.clj:68                                                                                        |
|    |                                                                                                                                                                  |
|    +---logjam.framework.logback.proxy$ch.qos.logback.core.AppenderBase$ff19274a.append                                                                                |
|    |                                                                                                                                                                  |
|    +---ch.qos.logback.core.AppenderBase.doAppend AppenderBase.java:83                                                                                                 |
|    |                                                                                                                                                                  |
|    +---logjam.framework.logback.proxy$ch.qos.logback.core.AppenderBase$ff19274a.doAppend                                                                              |
|    |                                                                                                                                                                  |
|    +---ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders AppenderAttachableImpl.java:51                                                            |
|    |                                                                                                                                                                  |
|    +---ch.qos.logback.classic.Logger.appendLoopOnAppenders Logger.java:272                                                                                            |
|    |                                                                                                                                                                  |
|    +---ch.qos.logback.classic.Logger.callAppenders Logger.java:259                                                                                                    |
|    |                                                                                                                                                                  |
|    +---ch.qos.logback.classic.Logger.buildLoggingEventAndAppend Logger.java:426                                                                                       |
|    |                                                                                                                                                                  |
|    +---ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus Logger.java:386                                                                                           |
|    |                                                                                                                                                                  |
|    +---ch.qos.logback.classic.Logger.debug Logger.java:499                                                                                                            |
|    |                                                                                                                                                                  |
|    +---org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.reservedWait ReservedThreadExecutor.java:327                                               |
|    |                                                                                                                                                                  |
|    +---org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run ReservedThreadExecutor.java:401                                                        |
|    |                                                                                                                                                                  |
|    +---org.eclipse.jetty.util.thread.QueuedThreadPool.runJob QueuedThreadPool.java:969                                                                                |
|    |                                                                                                                                                                  |
|    +---org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob QueuedThreadPool.java:1194                                                                      |
|    |                                                                                                                                                                  |
|    +---org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run QueuedThreadPool.java:1149                                                                           |
|    |                                                                                                                                                                  |
|    +---java.lang.Thread.runWith Thread.java:1596                                                                                                                      |
|    |                                                                                                                                                                  |
|    +---java.lang.Thread.run Thread.java:1583                                                                                                                          |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+

Generated by YourKit Java Profiler 2023.9-b101 January 12, 2024 07:59:24 AM

I'm using:

• ch.qos.logback/logback-classic 1.4.14
• org.slf4j/slf4j-api 2.0.10
• org.clojure/tools.logging 1.2.4
• org.eclipse.jetty/jetty-server 11.0.18

[vemv]

@r0man feel free to eye this one. I will too!

[r0man]

@vemv How did you notice this and what was the effect? Did CIDER/Emacs "hang"?
I haven't seen/noticed this so far.

[r0man]

And is there a way to reproduce this?

[vemv]

How did you notice this and what was the effect? Did CIDER/Emacs "hang"?

The repl started working (although thankfully nothing was frozen Emacs side) - it would not respond with anything.

And the webserver would stop responding as well.

And is there a way to reproduce this?

I was playing with the filters, Elisp side, so it might have to do.

My preliminary plan is to:

• check the code per the stacktrace
• learn about the underlying lock(s) being used
• try to use the lock better (if there's any documented way to do so), or perhaps some lockless code path is offered.

I'll do that tomorrow-ish but in any case, if you'd like to do something like that too, the more eyes the better!