[logback-dev] [JIRA] (LOGBACK-891) Deadlock in RollingFileAppender

Title: Message Title

MJ commented on

I am seeing a similar issue with logback.

Under heavy load my service deadlocks in the logback logger calls.

A number of threads like the one below waiting for 0x00000003c0658e90

"pool-6-thread-110" #155 prio=5 os_prio=0 tid=0x00007f90c80b1000 nid=0xd7 waiting on condition [0x00007f8fd59d8000]

java.lang.Thread.State: WAITING (parking)

at sun.misc.Unsafe.park(Native Method)

- parking to wait for <0x00000003c0658e90> (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.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.info(Logger.java:579)

at com.k2io.validator.repository.ValidationRepository.constructPmapWithTrail(ValidationRepository.java:555)

at com.k2io.validator.ValidationService$ValidationCallable.getAgrePmap(ValidationService.java:329)

at com.k2io.validator.ValidationService$ValidationCallable.call(ValidationService.java:167)

at com.k2io.validator.ValidationService$ValidationCallable.call(ValidationService.java:70)

at java.util.concurrent.FutureTask.run(FutureTask.java:266)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

at java.lang.Thread.run(Thread.java:748)

And 0x00000003c0658e90 is held by – why is this not releasing the lock

"pool-6-thread-87" #129 prio=5 os_prio=0 tid=0x00007f90d405d000 nid=0xb6 runnable [0x00007f8fd73f2000]

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 <0x00000003c06e8890> (a java.io.BufferedOutputStream)

at java.io.PrintStream.write(PrintStream.java:480)

- locked <0x00000003c06e8870> (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.OutputStreamAppender.writeBytes(OutputStreamAppender.java:199)