[logback-dev] [JIRA] (LOGBACK-1422) Deadlock with logging

[QOS.CH (JIRA)]

MJ created LOGBACK-1422:
---------------------------

             Summary: Deadlock with logging
                 Key: LOGBACK-1422
                 URL: https://jira.qos.ch/browse/LOGBACK-1422
             Project: logback
          Issue Type: Bug
    Affects Versions: 1.2.3
         Environment: jdk8
            Reporter: MJ
            Assignee: Logback dev list


Multithreaded java service

Threadpool with each thread doing logging

high request rate 

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)

        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)

 

   Locked ownable synchronizers:

        - <0x00000003c0658e90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

        - <0x00000003c11c30e8> (a java.util.concurrent.ThreadPoolExecutor$Worker)



--
This message was sent by Atlassian JIRA
(v7.3.1#73012)