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

Question

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>

score 0 · Accepted Answer · answered Jun 03 '21 at 06:54

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

score 0 · Answer 2 · answered Jun 03 '21 at 22:37

e.printStackTrace(); is printed to standard error only, namely the console. It's considered a security bug since you might not have control over stderr thus leaking information about your system. To write exception to file you can use

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

score 0 · Answer 3 · answered Jun 20 '22 at 19:21

If this behavior is wanted for all threads, Thread#setDefaultUncaughtExceptionHandler can also be used. Its javadoc:

Set the default handler invoked when a thread abruptly terminates due to an uncaught exception, and no other handler has been defined for that thread.

Uncaught exception handling is controlled first by the thread, then by the thread's ThreadGroup object and finally by the default uncaught exception handler. If the thread does not have an explicit uncaught exception handler set, and the thread's thread group (including parent thread groups) does not specialize its uncaughtException method, then the default handler's uncaughtException method will be invoked.

By setting the default uncaught exception handler, an application can change the way in which uncaught exceptions are handled (such as logging to a specific device, or file) for those threads that would already accept whatever "default" behavior the system provided.

Note that the default uncaught exception handler should not usually defer to the thread's ThreadGroup object, as that could cause infinite recursion.

For example:

public class LoggingUncaughtExceptionHandler implements Thread.UncaughtExceptionHandler {
    private static final Logger log = LoggerFactory.getLogger(LoggingUncaughtExceptionHandler.class);

    @Override
    public void uncaughtException(Thread thread, Throwable throwable) {
        log.error("", throwable);
    }
}

And then set it to be the default handler for all threads:

public class Main {
    public static void main(String[] args) {
        Thread.setDefaultUncaughtExceptionHandler(new LoggingUncaughtExceptionHandler());
        SpringApplication.run(Main.class, args);
    }
}

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

3 Answers3