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

Posted 2023-03-15

【中文标题】logback 不会将异常记录到从 ThreadPoolTask​​Executor 池线程抛出的文件中

【英文标题】：logback don't log exception into file which throwed from an ThreadPoolTaskExecutor pool thread

【发布时间】：2021-08-21 04:35:36

【问题描述】：

我遇到了一个有线问题，似乎 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="%dateyyyy-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>

【参考方案1】：

我受到这个问题的启发：Log runtime Exceptions in Java using log4j 在JDK的Thread类中，有一个字段叫UncaughtExceptionHandler；

private volatile UncaughtExceptionHandler uncaughtExceptionHandler;

我只需要重写 ThreadGroup 方法，在我的池的每个线程中设置一个 UncaughtExceptionHandler，然后我的 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);
    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;
  

【参考方案2】：

e.printStackTrace(); 仅打印到标准错误，即控制台。 它被认为是一个安全错误，因为您可能无法控制 stderr 从而泄露有关您的系统的信息。 要将异常写入文件，您可以使用

 catch (InterruptedException e) 
    log.error("Some error message: ",e);