Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-1422

Deadlock with logging

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Major Major
    • None
    • 1.2.3
    • None
    • None
    • jdk8

    Description

      Multithreaded java service in a docker container

      Threadpool with each thread doing logging

      high request rate 

       

      Logging policy is

      <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
      
      <encoder>
       <pattern>%d\{HH:mm:ss.SSS} [%thread] %-5level %logger\{5} - %msg%n</pattern>
       </encoder>
       </appender>
      
      <appender name="FILE"
       class="ch.qos.logback.core.rolling.RollingFileAppender">
       <file>logs/kafkaconsumer.log</file>
       <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
       <Pattern>
       %d\{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger\{5} - %msg%n
       </Pattern>
       </encoder>
      
      <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
       <!-- rollover daily -->
       <fileNamePattern>logs/kafkaconsumer.%d\{yyyy-MM-dd}.%i.log
       </fileNamePattern>
       <timeBasedFileNamingAndTriggeringPolicy
       class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
       <maxFileSize>10MB</maxFileSize>
       </timeBasedFileNamingAndTriggeringPolicy>
       </rollingPolicy>
      
      </appender>
      
      <logger name="com.k2io" level="INFO" additivity="false">
       <appender-ref ref="STDOUT" />
       <appender-ref ref="FILE" />
       </logger>
      

       

      Deadlock occurs after running for several hours

      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 the following thread

      "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)
      

      Attachments

        Activity

          People

            ceki Ceki Gülcü
            mjk2io MJ
            Votes:
            1 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated: