All threads blocked - Githubissues

koszta5 commented 5 months ago

Logback version :1.2.11 Springboot version: 2.7.4

Apparently in some cases all locks are lost and logback is just "stuck" - only restart helps. Thread dump is attached StuckLogback.threads.txt

All threads remain in this state WAITING for lock endlessly `"http-nio-8184-exec-1" #139 daemon prio=5 os_prio=0 cpu=53544.34ms elapsed=232090.85s tid=0x00002af5d1b77800 nid=0x15fe7 waiting on condition [0x00002af676207000] java.lang.Thread.State: WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@11.0.19/Native Method)

parking to wait for <0x00000000e0c37af0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) at java.util.concurrent.locks.LockSupport.park(java.base@11.0.19/LockSupport.java:194) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.19/AbstractQueuedSynchronizer.java:885) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base@11.0.19/AbstractQueuedSynchronizer.java:917) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@11.0.19/AbstractQueuedSynchronizer.java:1240) at java.util.concurrent.locks.ReentrantLock.lock(java.base@11.0.19/ReentrantLock.java:267) at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:197) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:398) at ch.qos.logback.classic.Logger.debug(Logger.java:486) at com.ourcomapany.integration.distribution.v2.delivery.TokenService.addToCache(TokenService.java:233)`

This bug is very closely related to issue originally reported here: https://jira.qos.ch/projects/LOGBACK/issues/LOGBACK-1406?filter=allopenissues (same thing really). It is also similar to this: https://github.com/qos-ch/logback/issues/767

sunl888 commented 4 months ago

I also encountered this issue, it will be resolved after restarting jstack.txt

koszta5 commented 4 months ago

well that is not resolving this problem :(

ceki commented 4 months ago

@koszta5 Under which JDK version is this occurring?

koszta5 commented 4 months ago

openjdk version "11.0.19" 2023-04-18 OpenJDK Runtime Environment Temurin-11.0.19+7 (build 11.0.19+7) OpenJDK 64-Bit Server VM Temurin-11.0.19+7 (build 11.0.19+7, mixed mode)

jinshuai86 commented 4 months ago

@koszta5 Under which JDK version is this occurring?

Can you take a look at the problem in the link? https://jira.qos.ch/browse/LOGBACK-1406

It's very similar to this issue, I've also encountered this problem. only one thread(Thread 507 belows) BLOCKED in FileOutputStream.writeBytes() , other threads(Thread 402 belows) BLOCKED in OutputStreamAppender.subAppend()

Thread 507: (state = BLOCKED)

java.io.FileOutputStream.writeBytes(byte[], int, int, boolean) @bci=0 (Compiled frame; information may be imprecise)
java.io.FileOutputStream.write(byte[], int, int) @bci=8, line=326 (Compiled frame)
java.io.BufferedOutputStream.write(byte[], int, int) @bci=20, line=122 (Compiled frame)
java.io.PrintStream.write(byte[], int, int) @bci=16, line=480 (Compiled frame)
java.io.FilterOutputStream.write(byte[]) @bci=5, line=97 (Compiled frame)
ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(byte[]) @bci=4, line=37 (Compiled frame)
ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(java.lang.Object) @bci=20, line=131 (Compiled frame)
ch.qos.logback.core.OutputStreamAppender.writeOut(java.lang.Object) @bci=5, line=187 (Compiled frame)
ch.qos.logback.core.OutputStreamAppender.subAppend(java.lang.Object) @bci=33, line=212 (Compiled frame)
ch.qos.logback.core.OutputStreamAppender.append(java.lang.Object) @bci=10, line=100 (Compiled frame)
ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(java.lang.Object) @bci=123, line=84 (Compiled frame)
ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(java.lang.Object) @bci=32, line=51 (Compiled frame)
ch.qos.logback.classic.Logger.appendLoopOnAppenders(ch.qos.logback.classic.spi.ILoggingEvent) @bci=12, line=270 (Compiled frame)
ch.qos.logback.classic.Logger.callAppenders(ch.qos.logback.classic.spi.ILoggingEvent) @bci=10, line=257 (Compiled frame)
ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(java.lang.String, org.slf4j.Marker, ch.qos.logback.classic.Level, java.lang.String, java.lang.Object[], java.lang.Throwable) @bci=27, line=421 (Compiled frame)
ch.qos.logback.classic.Logger.filterAndLog_1(java.lang.String, org.slf4j.Marker, ch.qos.logback.classic.Level, java.lang.String, java.lang.Object, java.lang.Throwable) @bci=64, line=398 (Compiled frame)
ch.qos.logback.classic.Logger.info(java.lang.String, java.lang.Object) @bci=11, line=583 (Compiled frame)

Thread 402: (state = BLOCKED)

sun.misc.Unsafe.park(boolean, long) @bci=0 (Compiled frame; information may be imprecise)
java.util.concurrent.locks.LockSupport.park(java.lang.Object) @bci=14, line=175 (Compiled frame)
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt() @bci=1, line=836 (Compiled frame)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.util.concurrent.locks.AbstractQueuedSynchronizer$Node, int) @bci=67, line=870 (Compiled frame)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(int) @bci=17, line=1199 (Compiled frame)
java.util.concurrent.locks.ReentrantLock$NonfairSync.lock() @bci=21, line=209 (Compiled frame)
java.util.concurrent.locks.ReentrantLock.lock() @bci=4, line=285 (Compiled frame)
ch.qos.logback.core.OutputStreamAppender.subAppend(java.lang.Object) @bci=28, line=210 (Compiled frame)
ch.qos.logback.core.OutputStreamAppender.append(java.lang.Object) @bci=10, line=100 (Compiled frame)
ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(java.lang.Object) @bci=123, line=84 (Compiled frame)
ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(java.lang.Object) @bci=32, line=51 (Compiled frame)

koszta5 commented 3 months ago

Sorry, but no - if you examine e.g. my very recent thread dump here: https://jstack.review/

You will find out that all my threads are simply WAITING for a lock that is now lost (no other thread is holding it) stuckLogback.threads.txt

Lock 0x0000000701dc5ff0 is completely lost to the JVM :( Causing the whole app to get stuck

ceki commented 2 weeks ago

@koszta5 The 1.2 branch is about 8 years old now. Would it be possible for your to upgrade to logback 1.5?

apflieger commented 2 weeks ago

I had this problem on 1.4.11 and rollbacked our virtual thread migration. We couldn't reproduce the crash so while I can upgrade to 1.5, I can't test virtual threads again blindly

qos-ch / logback

All threads blocked #786