java - logback 不会将异常记录到从 ThreadPoolTask​​Executor 池线程抛出的文件中

Question

我遇到了一个有线问题，似乎 logback 只在控制台上打印我的异常堆栈跟踪，而不是将其记录到日志文件中。以下是我的实验代码，我使用了一个带有两个线程池的 spring boot 测试，它模拟了我的生产代码。两个线程都打印日志并抛出 RuntimeException。但是异常信息只打印在控制台上，而不是登录到文件中. 这是我的代码：

@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();
    }
  }

我的 ThreadPoolTask​​Executor 配置：

  @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;
  }

控制台上的日志：

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)

文件中的日志（只有两个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..

还有我的 logback 配置：

<?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>

标签： javaspringspring-bootthreadpoollogback

Answer 1

我受到这个问题的启发：Log runtime Exceptions in Java using log4j 在 JDK Thread 类中，有一个名为 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;
  }