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

Seems all threads blocked

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Priority: Blocker
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: logback-core
    • Labels:
      None
    • Environment:

      Description

      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:

      "qtp956480812-17384" #17384 prio=5 os_prio=0 tid=0x00007f667400e800 nid=0x43f3 waiting on condition [0x00007f652d4d0000]
      java.lang.Thread.State: WAITING (parking)
      at sun.misc.Unsafe.park(Native Method)
      - parking to wait for <0x00000000843211e8> (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)
      

      And following is the only thread which has the lock

      "qtp956480812-17230" #17230 prio=5 os_prio=0 tid=0x00007f65c0017800 nid=0x4359 runnable [0x00007f65e5fe9000]
      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 <0x00000000830542d0> (a java.io.BufferedOutputStream)
      at java.io.PrintStream.write(PrintStream.java:480)
      - locked <0x00000000830542b0> (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)
      

      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.

        Attachments

        1. debug-LOGBACK-1406.log
          768 kB
        2. dump
          1.77 MB

          Activity

            People

            Assignee:
            logback-dev Logback dev list
            Reporter:
            tony Tony Zeng
            Votes:
            2 Vote for this issue
            Watchers:
            8 Start watching this issue

              Dates

              Created:
              Updated: