qos-ch / logback

The reliable, generic, fast and flexible logging framework for Java.
http://logback.qos.ch
Other
2.94k stars 1.27k forks source link

thread blocked in virtual thread envrionment with 1.4.14 version #767

Open walkertest opened 6 months ago

walkertest commented 6 months ago

Env

Problem

the request and response

The thread stack

"ts-reactor-0" #47 [693] prio=5 os_prio=0 cpu=195123.31ms elapsed=69926.73s tid=0x00007fbc7a0daf10 nid=693 waiting on condition  [0x00007fbc4cebf000]
   java.lang.Thread.State: WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
    - parking to wait for  <0x0000000759b899e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(java.base@21/LockSupport.java:371)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21/AbstractQueuedSynchronizer.java:519)
    at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21/ForkJoinPool.java:3780)
    at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21/ForkJoinPool.java:3725)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21/AbstractQueuedSynchronizer.java:1707)
    at java.util.concurrent.ArrayBlockingQueue.put(java.base@21/ArrayBlockingQueue.java:370)
    at ch.qos.logback.core.AsyncAppenderBase.putUninterruptibly(AsyncAppenderBase.java:186)
    at ch.qos.logback.core.AsyncAppenderBase.put(AsyncAppenderBase.java:177)
    at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:166)
    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.error(Logger.java:539)
    at com.huya.taf.net.core.nio.TCPSession.handleVtServer(TCPSession.java:218)
    at com.huya.taf.net.core.nio.TCPSession.readRequest(TCPSession.java:177)
    at com.huya.taf.net.core.nio.TCPSession.read(TCPSession.java:140)
    at com.huya.taf.net.core.nio.TCPAcceptor.handleReadEvent(TCPAcceptor.java:111)
    at com.huya.taf.net.core.nio.Reactor.dispatchEvent(Reactor.java:197)
    at com.huya.taf.net.core.nio.Reactor.run(Reactor.java:114)

"ts-reactor-1" #48 [694] prio=5 os_prio=0 cpu=223469.95ms elapsed=69926.73s tid=0x00007fbc7a0eda90 nid=694 waiting on condition  [0x00007fbc4ce7e000]
   java.lang.Thread.State: WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
    - parking to wait for  <0x0000000759b899e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(java.base@21/LockSupport.java:371)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21/AbstractQueuedSynchronizer.java:519)
    at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21/ForkJoinPool.java:3780)
    at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21/ForkJoinPool.java:3725)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21/AbstractQueuedSynchronizer.java:1707)
    at java.util.concurrent.ArrayBlockingQueue.put(java.base@21/ArrayBlockingQueue.java:370)
    at ch.qos.logback.core.AsyncAppenderBase.putUninterruptibly(AsyncAppenderBase.java:186)
    at ch.qos.logback.core.AsyncAppenderBase.put(AsyncAppenderBase.java:177)
    at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:166)
    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.error(Logger.java:539)
    at com.huya.taf.net.core.nio.Reactor.disConnectWithException(Reactor.java:144)
    at com.huya.taf.net.core.nio.Reactor.run(Reactor.java:117)

"ts-reactor-2" #49 [695] prio=5 os_prio=0 cpu=196075.69ms elapsed=69926.73s tid=0x00007fbc7a0eec00 nid=695 waiting on condition  [0x00007fbc4ce3d000]
   java.lang.Thread.State: WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
    - parking to wait for  <0x0000000759b895b8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(java.base@21/LockSupport.java:221)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@21/AbstractQueuedSynchronizer.java:754)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@21/AbstractQueuedSynchronizer.java:990)
    at java.util.concurrent.locks.ReentrantLock$Sync.lock(java.base@21/ReentrantLock.java:153)
    at java.util.concurrent.locks.ReentrantLock.lock(java.base@21/ReentrantLock.java:322)
    at java.util.concurrent.ArrayBlockingQueue.remainingCapacity(java.base@21/ArrayBlockingQueue.java:485)
    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_2(Logger.java:419)
    at ch.qos.logback.classic.Logger.info(Logger.java:592)
    at com.huya.taf.net.core.nio.TCPSession.handleVtServer(TCPSession.java:208)
    at com.huya.taf.net.core.nio.TCPSession.readRequest(TCPSession.java:177)
    at com.huya.taf.net.core.nio.TCPSession.read(TCPSession.java:140)
    at com.huya.taf.net.core.nio.TCPAcceptor.handleReadEvent(TCPAcceptor.java:111)
    at com.huya.taf.net.core.nio.Reactor.dispatchEvent(Reactor.java:197)
    at com.huya.taf.net.core.nio.Reactor.run(Reactor.java:114)

"ts-reactor-3" #50 [696] prio=5 os_prio=0 cpu=194924.27ms elapsed=69926.73s tid=0x00007fbc7a0f0020 nid=696 waiting on condition  [0x00007fbc4cdfc000]
   java.lang.Thread.State: WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
    - parking to wait for  <0x0000000759b899e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(java.base@21/LockSupport.java:371)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21/AbstractQueuedSynchronizer.java:519)
    at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21/ForkJoinPool.java:3780)
    at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21/ForkJoinPool.java:3725)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21/AbstractQueuedSynchronizer.java:1707)
    at java.util.concurrent.ArrayBlockingQueue.put(java.base@21/ArrayBlockingQueue.java:370)
    at ch.qos.logback.core.AsyncAppenderBase.putUninterruptibly(AsyncAppenderBase.java:186)
    at ch.qos.logback.core.AsyncAppenderBase.put(AsyncAppenderBase.java:177)
    at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:166)
    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.error(Logger.java:539)
    at com.huya.taf.net.core.nio.TCPSession.handleVtServer(TCPSession.java:218)
    at com.huya.taf.net.core.nio.TCPSession.readRequest(TCPSession.java:177)
    at com.huya.taf.net.core.nio.TCPSession.read(TCPSession.java:140)
    at com.huya.taf.net.core.nio.TCPAcceptor.handleReadEvent(TCPAcceptor.java:111)
    at com.huya.taf.net.core.nio.Reactor.dispatchEvent(Reactor.java:197)
    at com.huya.taf.net.core.nio.Reactor.run(Reactor.java:114)

"ts-reactor-4" #51 [697] prio=5 os_prio=0 cpu=194829.49ms elapsed=69926.73s tid=0x00007fbc7a0f15b0 nid=697 waiting on condition  [0x00007fbc4cdbb000]
   java.lang.Thread.State: WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
    - parking to wait for  <0x0000000759b899e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(java.base@21/LockSupport.java:371)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21/AbstractQueuedSynchronizer.java:519)
    at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21/ForkJoinPool.java:3780)
    at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21/ForkJoinPool.java:3725)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21/AbstractQueuedSynchronizer.java:1707)
    at java.util.concurrent.ArrayBlockingQueue.put(java.base@21/ArrayBlockingQueue.java:370)
    at ch.qos.logback.core.AsyncAppenderBase.putUninterruptibly(AsyncAppenderBase.java:186)
    at ch.qos.logback.core.AsyncAppenderBase.put(AsyncAppenderBase.java:177)
    at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:166)
    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_2(Logger.java:419)
    at ch.qos.logback.classic.Logger.info(Logger.java:592)
    at com.huya.taf.net.core.nio.TCPSession.handleVtServer(TCPSession.java:208)
    at com.huya.taf.net.core.nio.TCPSession.readRequest(TCPSession.java:177)
    at com.huya.taf.net.core.nio.TCPSession.read(TCPSession.java:140)
    at com.huya.taf.net.core.nio.TCPAcceptor.handleReadEvent(TCPAcceptor.java:111)
    at com.huya.taf.net.core.nio.Reactor.dispatchEvent(Reactor.java:197)
    at com.huya.taf.net.core.nio.Reactor.run(Reactor.java:114)
walkertest commented 6 months ago

jcmd Thread.dump_to_file info: The dump file is bigger than 26M(the github issue limit), so i split the file to two files.

thread_jcmdaa.txt thread_jcmdab.txt

ArtemiyVorobev commented 5 months ago

On your project we have the same problem. Waiting for fix

ArtemiyVorobev commented 5 months ago

@walkertest Have you found a work around ?

ceki commented 5 months ago

@walkertest Can you please provide the logback configuration file?

walkertest commented 1 month ago

@walkertest Have you found a work around ?

Not yet. Do you have solve this problem? My co-worker had meet this problem again

walkertest commented 1 month ago

@walkertest Can you please provide the logback configuration file?

${LOG_PATTERN} ${LOG_DIR}/udb_server_details/${springAppName}.log ${LOG_DIR}/udb_server_details/${springAppName}.%d{yyyy-MM-dd,Asia/Hong_Kong}.%i.log 800MB 60 20GB ${LOG_PATTERN} ${LOG_DIR}/taflog/${springAppName}.log ${LOG_DIR}/taflog/${springAppName}.%d{yyyy-MM-dd,Asia/Hong_Kong}.%i.log 800MB 60 20GB ${LOG_PATTERN}
apflieger commented 1 month ago

We have the same issue, it crashed our prod two times, then we rolled back the usage of virtual threads. Here's our config.

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
  <property name="TIMEZONE" value="Europe/Paris" />
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <!-- coloring the level without the brackets doesn't work -->
      <pattern>%date{ISO8601, ${TIMEZONE}} %highlight(%-7([%level])) %X{executionContext:-(no execution context)} - %logger - %message%n%xException</pattern>
    </encoder>
  </appender>
  <appender name="ASYNCSTDOUT" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="STDOUT" />
  </appender>
  <appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender">
    <smtpHost>${email.smtp.host}</smtpHost>
    <smtpPort>${email.smtp.port}</smtpPort>
    <SSL>${email.smtp.ssl}</SSL>
    <username>${email.smtp.user}</username>
    <password>${email.smtp.password}</password>
    <from>Logback ${app.env} &lt;${email.logback_recipient}&gt;</from><!-- So we can respond to it -->
    <to>${email.logback_recipient}</to>
    <subject>%logger{0} - %message</subject>
    <layout class="ch.qos.logback.classic.PatternLayout">
      <pattern>%date{ISO8601, ${TIMEZONE}} [%level] %X{executionContext:-(no execution context)} - %logger - %message%n%xException</pattern>
    </layout>
    <discriminator class="ch.qos.logback.classic.sift.MDCBasedDiscriminator">
      <key>executionContext</key>
      <defaultValue>default</defaultValue>
    </discriminator>
  </appender>
  <root level="WARN"> <!-- External libraries don't log that much interesting stuff -->
    <appender-ref ref="ASYNCSTDOUT" />
    <appender-ref ref="EMAIL" />
  </root>
  <logger name="com.zaxxer.hikari.pool.HikariPool" level="ERROR" /> <!-- Ignore clock leap warnings. This happens a lot when dev laptops are put to sleep. -->
  <logger name="org.apache.http.client.protocol.ResponseProcessCookies" level="ERROR" /> <!-- We get a lot of invalid cookies warnings from bots like this: Invalid cookie header: "Set-Cookie: AWSALBTGCORS=0hymVtXBvpvwanwaGglsFN0gnZp0XOtyI0Kyf5Muv57QcG09yKvyc7xBJpJ4SvWNwa++q7r4zxpSnYSPD0wTMTfoyeJifDU2V1dZsi19K73P+kmXKlHzGFNAiLXQcg4+vcx9K0F9kbU6QAfXYe2I3VB7kxd5TLfdeYAJOdXn3Bkv; Expires=Wed, 13 Apr 2022 11:03:00 GMT; Path=/; SameSite=None; Secure". Invalid 'expires' attribute: Wed, 13 Apr 2022 11:03:00 GMT -->
  <logger name="com.meetinclass" level="DEBUG" />
  <logger name="Javascript" level="DEBUG" />
  <!--
  <logger name="io.ebean" level="DEBUG"/>
  <logger name="io.ebeaninternal" level="DEBUG"/>
  <logger name="io.ebean.SQL" level="DEBUG"/>
  <logger name="io.ebean.SUM" level="DEBUG"/>
  -->
</configuration>