[logback-dev] [JIRA] (LOGBACK-1406) Seems all threads blocked
Title: Message Title Duarte commented on LOGBACK-1406 Re: Seems all threads blocked @Joshua, your problem appears to be a deadlock, which would be unrelated to this ticket. You have a PrintStream (that holds a lock) writing to logback in one thread, and logback writing to the same PrintStream in another thread. The original problem are not the threads waiting for the lock. It's the thread that is holding the lock indefinitely. Using things like tryLock with a timeout would just cause all other threads to temporarily block and fail when trying to log - it's not a solution. I would try understand why the native method "writeBytes" is blocked. It could be a I/O issue, like full disk, writing to a pipe without a reader, etc. You can use lsof, for example, to investigate. Add Comment This message was sent by Atlassian Jira (v8.8.0#808000-sha1:e2c7e59) ___ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
[logback-dev] [JIRA] (LOGBACK-1406) Seems all threads blocked
Title: Message Title Joshua Carter commented on LOGBACK-1406 Re: Seems all threads blocked @Alvin, my solution was to merely stop logging so much stuff Luckily for me, there was a significant amount of non-useful DEBUG logging coming from a single class that I simply changed to INFO in my config. Also, I suspect this is related to logging coming from a large number of separate threads concurrently (this was my test case at least), so if there is no way to reduce the amount of logging, perhaps there is some way of reducing the number of concurrent threads. Add Comment This message was sent by Atlassian JIRA (v7.3.1#73012-sha1:68837e3) ___ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
[logback-dev] [JIRA] (LOGBACK-1406) Seems all threads blocked
Title: Message Title Alvin commented on LOGBACK-1406 Re: Seems all threads blocked I just curious if this blocker issue was already resolved or is there any walk-around available to avoid this. Since it is identified as a blocker and had opened for more than a year, i wonder how other managed to get around it! I have similar issue encountered by Joshua and it can happen few times a day as our load is extreme high. Any help will be appreciated. Below is what the thread is waiting for: java.lang.Thread.State: WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@11.0.5/Native Method) - parking to wait for <0x7f739e995d50> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) at java.util.concurrent.locks.LockSupport.park(java.base@11.0.5/LockSupport.java:194) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.5/AbstractQueuedSynchronizer.java:885) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base@11.0.5/AbstractQueuedSynchronizer.java:917) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@11.0.5/AbstractQueuedSynchronizer.java:1240) at java.util.concurrent.locks.ReentrantLock.lock(java.base@11.0.5/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_0_Or3Plus(Logger.java:383) at ch.qos.logback.classic.Logger.debug(Logger.java:482) Add Comment
[logback-dev] [JIRA] (LOGBACK-1406) Seems all threads blocked
Title: Message Title Joshua Carter commented on LOGBACK-1406 Re: Seems all threads blocked Just wanted to jump in and say that I am also experiencing this issue with logback-classic:1.2.3. I am able to reliably reproduce this issue with an application we are working on. I have attached a debug log which demonstrates the issue. You can see that the application starts logging a larger and larger amount of log messages per unit of time until eventually the application hangs (stop responding to all input) indefinitely: debug-LOGBACK-1406.log. Add Comment This message was sent by Atlassian JIRA (v7.3.1#73012-sha1:68837e3) ___ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
[logback-dev] [JIRA] (LOGBACK-1406) Seems all threads blocked
Title: Message Title Ala Schneider commented on LOGBACK-1406 Re: Seems all threads blocked Yes. In the worst case a single message will be discarded. It is much better then stagnation. You can also define a buffer of such lost messages and show them in status or something like this. But in general case waiting for a while just solves the conflict and messages will not be lost at all. Add Comment This message was sent by Atlassian JIRA (v7.3.1#73012-sha1:68837e3) ___ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
[logback-dev] [JIRA] (LOGBACK-1406) Seems all threads blocked
Title: Message Title Ralph Goers commented on LOGBACK-1406 Re: Seems all threads blocked Let me see if I understand. You would like to have tryLock used instead and if the lock cannot be obtained then the log event would be discarded? Add Comment This message was sent by Atlassian JIRA (v7.3.1#73012-sha1:68837e3) ___ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
[logback-dev] [JIRA] (LOGBACK-1406) Seems all threads blocked
Title: Message Title Ala Schneider commented on LOGBACK-1406 Re: Seems all threads blocked OutputStreamAppender.java method writeBytes makes infinite lock of ReentrantLock lock. This is the reason of stagnation. Only process restart may help. At least this is the problem of logback-core version 1.2.3. Using of tryLock with some reasonable timeout is better - the current message will be lost, but the whole thread will not stuck. I hope this is fixed in the next version. Add Comment This message was sent by Atlassian JIRA (v7.3.1#73012-sha1:68837e3) ___ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
[logback-dev] [JIRA] (LOGBACK-1406) Seems all threads blocked
Title: Message Title Mirit commented on LOGBACK-1406 Re: Seems all threads blocked Any solution or workaround for this issue? Add Comment This message was sent by Atlassian JIRA (v7.3.1#73012-sha1:68837e3) ___ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
[logback-dev] [JIRA] (LOGBACK-1406) Seems all threads blocked
Title: Message Title Nadav Yeheskel commented on LOGBACK-1406 Re: Seems all threads blocked Guys, do you have an estimation for this one? This is a blocker for us too. Add Comment This message was sent by Atlassian JIRA (v7.3.1#73012-sha1:68837e3) ___ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
[logback-dev] [JIRA] (LOGBACK-1406) Seems all threads blocked
Tony Zeng created LOGBACK-1406:
--
Summary: Seems all threads blocked
Key: LOGBACK-1406
URL: https://jira.qos.ch/browse/LOGBACK-1406
Project: logback
Issue Type: Bug
Components: logback-core
Environment: Linux ubuntu-100 4.4.0-116-generic #140-Ubuntu SMP Mon
Feb 12 21:23:04 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
java version "1.8.0_161"
Java(TM) SE Runtime Environment (build 1.8.0_161-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.161-b12, mixed mode)
Reporter: Tony Zeng
Assignee: Logback dev list
Attachments: dump
We are using `logback-core-1.1.11` as our logging framework, and recently we
found sometimes our web application is blocked and no response. After thread
dump, we found that most of web threads (and many, around 150) are waiting for
a lock in `OutputStreamAppender` as following stacktrace show:
{code:java}
"qtp956480812-17384" #17384 prio=5 os_prio=0 tid=0x7f667400e800 nid=0x43f3
waiting on condition [0x7f652d4d]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x843211e8> (a
java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at
java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at
ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)
at
ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
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_2(Logger.java:414)
at ch.qos.logback.classic.Logger.info(Logger.java:587)
at cn.superid.auth.utils.PermissionUtil.hasPermission(PermissionUtil.java:31)
{code}
And following is the only thread which has the lock
{code:java}
"qtp956480812-17230" #17230 prio=5 os_prio=0 tid=0x7f65c0017800 nid=0x4359
runnable [0x7f65e5fe9000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:326)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122)
- locked <0x830542d0> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(PrintStream.java:480)
- locked <0x830542b0> (a java.io.PrintStream)
at java.io.FilterOutputStream.write(FilterOutputStream.java:97)
at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:37)
at
ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:131)
at
ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:187)
at
ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212)
at
ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
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_2(Logger.java:414)
at ch.qos.logback.classic.Logger.info(Logger.java:587)
{code}
From the stacktrace, it seems no deadlock and application should not be
blocked. But the actual phenomenon is no log, no response. So, what's the
problem?
If you need more info, let me know. Thanks.
--
This message was sent by Atlassian JIRA
(v7.3.1#73012)
___
logback-dev mailing list
logback-dev@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-dev
