logback don’t log exception into file which throwed from an ThreadPoolTaskExecutor pool thread

I’ve got an wired problem, that seems like the logback only print my Exception stack trace on the console,rather than log it into an log file. The following is my experiment codes, I used an spring boot test with two thread pool,which simulating my production codes.Both thread print a log and throws an RuntimeException.But the exception info only print on the console, rather than log into an file. Here is my code:

@Autowired
  private ThreadPoolTaskExecutor goodsCommissionJobPool;
  @Autowired
  private ThreadPoolTaskExecutor goodsCommissionAlertPool;
  @Test
  public void test() {

    goodsCommissionJobPool.execute(() -> {
      log.info("first level..");
      goodsCommissionAlertPool.execute(() -> {
        log.info("second level..");
        throw new RuntimeException("funny error");
      });
      throw new RuntimeException("first error");
    });

    try {
      Thread.sleep(5000);
    } catch (InterruptedException e) {
      e.printStackTrace();
    }
  }

My ThreadPoolTaskExecutor configuration:

  @Bean
  public ThreadPoolTaskExecutor goodsCommissionJobPool() {
    ThreadPoolTaskExecutor pool = new ThreadPoolTaskExecutor();
    pool.setThreadNamePrefix("Goods_Commission_Job_");
    pool.setWaitForTasksToCompleteOnShutdown(true);
    pool.setAwaitTerminationSeconds(10);
    pool.setQueueCapacity(1000);
    pool.setMaxPoolSize(8);
    pool.setCorePoolSize(4);
    pool.setKeepAliveSeconds(60);
    return pool;
  }

  @Bean
  public ThreadPoolTaskExecutor goodsCommissionAlertPool() {
    ThreadPoolTaskExecutor pool = new ThreadPoolTaskExecutor();
    pool.setThreadNamePrefix("Goods_Commission_Alert_");
    pool.setQueueCapacity(10);
    pool.setMaxPoolSize(4);
    pool.setCorePoolSize(1);
    pool.setKeepAliveSeconds(60);
    pool.setRejectedExecutionHandler(new DiscardPolicy());
    return pool;
  }

the log on the console:

2021-06-03 11:02:59.594 +0800 [Goods_Commission_Job_1] INFO  [com.dada.inviter.logic.LocalTest] [LocalTest.java:35] - first level..
2021-06-03 11:02:59.595 +0800 [Goods_Commission_Alert_1] INFO  [com.dada.inviter.logic.LocalTest] [LocalTest.java:37] - second level..
Exception in thread "Goods_Commission_Job_1" java.lang.RuntimeException: first error
    at com.dada.inviter.logic.LocalTest.lambda$test$1(LocalTest.java:40)
    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)
Exception in thread "Goods_Commission_Alert_1" java.lang.RuntimeException: funny error
    at com.dada.inviter.logic.LocalTest.lambda$null$0(LocalTest.java:38)
    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)

The log in the file (only two info log):

2021-06-03 11:02:59.594 +0800 [Goods_Commission_Job_1] INFO  [com.dada.inviter.logic.LocalTest] [LocalTest.java:35] - first level..
2021-06-03 11:02:59.595 +0800 [Goods_Commission_Alert_1] INFO  [com.dada.inviter.logic.LocalTest] [LocalTest.java:37] - second level..

And my logback configuration :

<?xml version="1.0" encoding="UTF-8"?>

<configuration>

    <springProperty scope="context" name="appName" source="app.name"/>
    <springProperty scope="context" name="log.level" source="log.level" defaultValue="INFO" />

    <springProperty scope="context" name="envName" source="spring.profiles.active"/>

    <if condition='property("envName").equalsIgnoreCase("local")'>
        <then>
            <property name="log.filePath" value="logs/${appName}"/>
        </then>
        <else>
            <property name="log.filePath" value="/data/logs/java/${appName}"/>
        </else>
    </if>

    <property name="log.pattern"
              value="%date{yyyy-MM-dd HH:mm:ss.SSS Z} [%thread] %-5p [%c] [%F:%L] - %msg%n" />

    <property name="logName" value="inviter-settle" />

    <appender name="infoAppender"
        class="ch.qos.logback.core.FileAppender">
        <file>${log.filePath}/${logName}_info.log</file>
        <append>true</append>
        <encoder>
            <pattern>${log.pattern}</pattern>
        </encoder>
    </appender>

    <!-- ERROR -->
    <appender name="errorAppender"
        class="ch.qos.logback.core.FileAppender">
        <file>${log.filePath}/${logName}_error.log</file>
        <append>true</append>

        <encoder>
            <pattern>${log.pattern}</pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
        </filter>
    </appender>

    <!-- console -->
    <appender name="consoleAppender" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${log.pattern}</pattern>
        </encoder>
    </appender>

    <!-- rpc -->
    <appender name="rpcAppender"
              class="ch.qos.logback.core.FileAppender">
        <file>${log.filePath}/${logName}_rpcStats.log</file>
        <append>true</append>
        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
    </appender>

    <logger name="com.dada.base.registry.stats.RpcStatsUtil" level="INFO">
        <appender-ref ref="rpcAppender" />
    </logger>

    <root level="${log.level}">
        <appender-ref ref="infoAppender" />
        <appender-ref ref="errorAppender" />
        <appender-ref ref="consoleAppender" />
    </root>

</configuration>

Answer

I was inspired by this question : Log runtime Exceptions in Java using log4j In JDK Thread class, there is a field called UncaughtExceptionHandler;

private volatile UncaughtExceptionHandler uncaughtExceptionHandler;

All I need is to override the ThreadGroup method, to set an UncaughtExceptionHandler in every Thread of my pool, and then my ThreadPoolTaskExecutor configuration look like:

@Bean
  public ThreadPoolTaskExecutor goodsCommissionJobPool() {
    ThreadPoolTaskExecutor pool = new ThreadPoolTaskExecutor();
    pool.setThreadNamePrefix("Goods_Commission_Job_");
    pool.setWaitForTasksToCompleteOnShutdown(true);
    pool.setAwaitTerminationSeconds(10);
    pool.setQueueCapacity(1000);
    pool.setMaxPoolSize(8);
    pool.setCorePoolSize(4);
    pool.setKeepAliveSeconds(60);
    pool.setThreadFactory(new ThreadFactory() {
      private AtomicInteger threadCount = new AtomicInteger(0);
      @Override
      public Thread newThread(Runnable r) {
        Thread thread = new Thread(pool.getThreadGroup(), r,
            pool.getThreadNamePrefix() + threadCount.getAndIncrement());
        thread.setPriority(pool.getThreadPriority());
        thread.setDaemon(pool.isDaemon());
        thread.setUncaughtExceptionHandler((t, e) -> {
          log.error("", e);
        });
        return thread;
      }
    });
    return pool;
  }

  @Bean
  public ThreadPoolTaskExecutor goodsCommissionAlertPool() {
    ThreadPoolTaskExecutor pool = new ThreadPoolTaskExecutor();
    pool.setThreadNamePrefix("Goods_Commission_Alert_");
    pool.setQueueCapacity(10);
    pool.setMaxPoolSize(4);
    pool.setCorePoolSize(1);
    pool.setKeepAliveSeconds(60);
    pool.setRejectedExecutionHandler(new DiscardPolicy());
    pool.setThreadFactory(new ThreadFactory() {
      private AtomicInteger threadCount = new AtomicInteger(0);
      @Override
      public Thread newThread(Runnable r) {
        Thread thread = new Thread(pool.getThreadGroup(), r,
            pool.getThreadNamePrefix() + threadCount.getAndIncrement());
        thread.setPriority(pool.getThreadPriority());
        thread.setDaemon(pool.isDaemon());
        thread.setUncaughtExceptionHandler((t, e) -> {
          log.error("", e);
        });
        return thread;
      }
    });
    return pool;
  }