Mahoney
commented
10 years ago I'm really sorry, for some reason Github had stopped emailing notifications to me so I've only just seen this. I'll look into it.
Open Javaru opened 11 years ago
Mahoney
commented
10 years ago I'm really sorry, for some reason Github had stopped emailing notifications to me so I've only just seen this. I'll look into it.
Mahoney
commented
10 years ago Yes, this is a genuine issue - OnConsoleStatusListener is being redirected by sysout-over-slf4j back to Logback and that's causing the deadlock. I'll think about a solution.
edpike109
commented
9 years ago First thanks for writing this. However, I am having the same problem. Took me forever to figure it out because it is somewhat intermittent and apparently I'm not heavy enough to do a thread dump. When the roll fails, the tmp file is created, the original file is deleted and logback says that it is about to zip the file, then hangs. If it fails on root logger, the deadlock is hard and the server has to be rebooted. I am running this in Tomcat 7 as windows service, Java 7 SDK, Windows 7, sysout-overslf4j-1.0.2.jar, slf4j 1.7.7.jar, logback 1.1.2. If I turn off zip compression, it seems to be working fine. If I remove the lidalia listener from server/conf/web.xml, i can use zip compression. All testing is using a size based policy of 3kb and loading a page that populates that logger. I say "seems" because I might just be getting a string of good luck.
JWood48
commented
7 years ago From the logback documentation setting debug=true when configuring logback will send output to system.out (specifically when rolling) using the OnConsoleStatusListener. This causes the deadlock in my case.
Setting debug=false should use the NopStatusListener
We recently introduced sysout-over-slf4j into an application that has been running steadily for a couple of years. No other code changes were made other than adding the sysout-over-slf4j dependency and the one line of code to initialize it. We immediately started seeing nightly deadlocks when Logback went to roll log files. It occurred most nights. Upon removing sysout-over-slf4j, the deadlocks stopped.
We've used sysout-over-slf4j in past projects without this issue. A primary difference is that this application does a lot of very rapid logging across numerous threads. Below is a thread dump.
Found one Java-level deadlock:
"pool-19-thread-1": waiting to lock monitor 0x00007fd5381c2718 (object 0x000000043eb38cd0, a ch.qos.logback.core.rolling.TimeBasedRollingPolicy), which is held by "ipl-doc-processing-pool-0" "ipl-doc-processing-pool-0": waiting to lock monitor 0x000000000085ce50 (object 0x000000043eaf0178, a ch.qos.logback.core.spi.LogbackLock), which is held by "pool-19-thread-1" Java stack information for the threads listed above:
"pool-19-thread-1": at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:170)
Found 1 deadlock.
Heap par new generation total 231680K, used 174203K [0x00000003fae00000, 0x000000040a960000, 0x000000043e790000) eden space 205952K, 80% used [0x00000003fae00000, 0x000000040508c3b8, 0x0000000407720000) from space 25728K, 30% used [0x0000000409040000, 0x00000004097d2a18, 0x000000040a960000) to space 25728K, 0% used [0x0000000407720000, 0x0000000407720000, 0x0000000409040000) concurrent mark-sweep generation total 2706712K, used 2318580K [0x000000043e790000, 0x00000004e3ad6000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 83968K, used 53433K [0x00000007fae00000, 0x0000000800000000, 0x0000000800000000)