Deadlock - Githubissues

vemv commented 8 months ago

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 commented 8 months ago

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

r0man commented 8 months ago

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

r0man commented 8 months ago

And is there a way to reproduce this?

vemv commented 8 months ago

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!

clojure-emacs / logjam

Deadlock #12