[logback-dev] [JIRA] Updates for LOGBACK-1741: AsyncAppender hangs intermittently

[logback developers list]

logback / LOGBACK-1741 [Open]
AsyncAppender hangs intermittently

==============================

Here's what changed in this issue in the last few minutes.

This issue has been created
This issue is now assigned to you.


View or comment on issue using this link
https://jira.qos.ch/browse/LOGBACK-1741

==============================
 Issue created
------------------------------

Jingfei Hu created this issue on 16/May/23 13:56

Summary:              AsyncAppender hangs intermittently
Issue Type:           Bug
Affects Versions:     1.3.1
Assignee:             Logback dev list
Components:           logback-classic, logback-core
Created:              16/May/23 13:56
Environment:
  openjdk version "1.8.0_332"
  OpenJDK Runtime Environment (build 1.8.0_332-b718)
  OpenJDK 64-Bit Server VM (build 25.332-b718, mixed mode)
Labels:               AsyncAppender
Priority:             Major
Reporter:             Jingfei Hu
Description:
  Hello team,
  
  Recently we leverage AsyncAppender to reduce latency as logging. It does help to reduce the latency in case of large amounts of logging events. However, we spot a hang issue. Though, for now, it occurs only once, we're afraid it's a bug of logback or JDK and it might happen again.
  
  Below is the thread stack, almost all threads of our process are blocked on this lock and we fail to locate the thread owning this lock(it's weird that jstack doesn't show which thread holds that lock, we guess the thread holding the lock might crash for somehow reason, but we have no way to prove that)
  {code:java}
  "msgWorkTP-582450565-6-thread-1" #642 prio=5 os_prio=0 tid=0x00007efec4094000 nid=0x4ca7 waiting on condition [0x00007efe841f9000]
     java.lang.Thread.State: WAITING (parking)
  	at sun.misc.Unsafe.park0(Native Method)
  	- parking to wait for  <0x00000007463ab208> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
  	at sun.misc.Unsafe.park(Unsafe.java:1038)
  	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:176)
  	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:842)
  	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:876)
  	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1207)
  	at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
  	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
  	at java.util.concurrent.ArrayBlockingQueue.remainingCapacity(ArrayBlockingQueue.java:468)
  	at ch.qos.logback.core.AsyncAppenderBase.isQueueBelowDiscardingThreshold(AsyncAppenderBase.java:170)
  	at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:162)
  	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
  	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
  	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
  	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
  	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:426)
  	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:386)
  	at ch.qos.logback.classic.Logger.info(Logger.java:584)
  {code}
  Our configuration is below
  {code:java}
  <!-- neverBlock true means possible loss of logging events in case of full queue -->
      <appender name="ASYNC_MODULE_APPENDER" class="ch.qos.logback.classic.AsyncAppender">
          <appender-ref ref="MODULE_APPENDER" />
          <queueSize>1024</queueSize>
          <discardingThreshold>0</discardingThreshold>
          <neverBlock>true</neverBlock>
      </appender>
  {code}
  And module configuration of MODULE_APPENDER is below
  {code:java}
  <appender name="MODULE_APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">
          <file>${user.home}/logs/sandbox/platform-test-support-sandbox-module.log</file>
          <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
              <FileNamePattern>${user.home}/logs/sandbox/platform-test-support-sandbox-module.log.%d{yyyy-MM-dd}.%i</FileNamePattern>
              <maxFileSize>100MB</maxFileSize>
              <MaxHistory>5</MaxHistory>
              <totalSizeCap>500MB</totalSizeCap>
          </rollingPolicy>
          <encoder>
              <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %msg%n</pattern>
              <charset>UTF-8</charset>
          </encoder>
          <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
              <level>INFO</level>
          </filter>
      </appender>
  {code}


==============================
 This message was sent by Atlassian Jira (v9.6.0#960000-sha1:a3ee8af)