一个多线程问题引发的思考：论规范使用日志的重要性

1. 问题描述

问题来源于某开源项目，在程序运行过程中，如果连接的数据库停掉，会导致程序卡死，问题简化后的代码如下：

@Test
public void testThreadPoolSubmitBlocked() {
    ExecutorService workerExecutor = Util.newSingleThreadExecutor(5000L);
    ((ThreadPoolExecutor) workerExecutor).setThreadFactory(new ThreadFactoryBuilder().setNameFormat("workerExecutor-pool-%d").build());

    ExecutorService groupInnerExecutorService = Util.newFixedThreadPool(1, 5000L);
    ((ThreadPoolExecutor) groupInnerExecutorService).setThreadFactory(new ThreadFactoryBuilder().setNameFormat("group-inner-pool-%d").build());

    for (int i = 0; i < 5; i++) {
        log.info("committing new task");
        Future<Boolean> workerExecutorFuture = workerExecutor.submit(() -> {
            Future<Boolean> groupInnerFuture = groupInnerExecutorService.submit(new Callable<Boolean>() {
                @Override
                public Boolean call() throws Exception {
                    try {
                        Thread.sleep(10000); //6s正常运行，10s时好时坏，20s卡死
                    } catch (InterruptedException e) {
                        log.info("interrupted");
                        throw new RuntimeException("child thread was interrupted!");
                    }
                    return true;
                }
            });

            try {
                groupInnerFuture.get();
            } catch (Exception e) {
                throw new RuntimeException(e);
            }
            return true;
        });

        log.info("task committed");

        try {
            Boolean aBoolean = workerExecutorFuture.get(5, TimeUnit.SECONDS);
            if (aBoolean != null && aBoolean) {
                break;
            }
        } catch (Exception e) {
            workerExecutorFuture.cancel(true);
        }
    }
}

Util.java:

public static ThreadPoolExecutor newFixedThreadPool(int nThreads, long keepAliveTime) {
    return new ThreadPoolExecutor(nThreads,
        nThreads,
        keepAliveTime,
        TimeUnit.MILLISECONDS,
        new SynchronousQueue<>(),
        (r, exe) -> {
            if (!exe.isShutdown()) {
                try {
                    exe.getQueue().put(r);
                } catch (InterruptedException e) {
                    // ignore
                }
            }
        });
}

因为Util类被在较多地方引用，为降低影响没有修改Util类来设置线程池名称。
运行上面的测试代码，输出日志内容大致如下：

09:22:48.206 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - committing new task
09:22:48.212 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - task committed
09:22:53.228 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - committing new task
09:22:53.229 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - task committed
09:22:58.243 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - committing new task
09:22:58.244 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - task committed
09:23:03.248 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - committing new task

然后线程一直阻塞。

2. 原因分析

上面的多线程问题，原因如下：

workerExecutorFuture.cancel(true)方法会导致内部任务线程中断；

而内部线程恰好阻塞在groupInnerExecutorService.submit()方法处，更精确一点，是在Util类中exe.getQueue().put(r)处；

当中断发生时，内部线程会抛出InterruptedException异常，然后进入到catch块，然而catch块中什么也没做；

这样就导致groupInnerExecutorService.submit()方法返回了一个Future实例，但这个实例对应的任务永远不会被线程池执行；

groupInnerFuture.get()会一直阻塞。

3. 问题思考

上面的问题症结在于这一处代码：

try {
    exe.getQueue().put(r);
} catch (InterruptedException e) {
    // ignore
}

这里进入到异常分支却什么也没做，导致出现问题却没有任何提示，对排查问题造成了不少障碍，如果打印一行错误日志，将会使问题更容易定位。而如果改成下面这样，阻塞的问题将不会出现：

try {
    exe.getQueue().put(r);
} catch (InterruptedException e) {
    // ignore
    logger.error("put runnable to queue failed");
    throw new RuntimeException("put runnable to queue failed, caused by: ", e);
}

原因是抛出异常会使groupInnerExecutorService.submit()方法不返回结果，而是直接将异常继续上抛导致线程终止。如果将workerExecutor.submit(()->{ ... }) 内部代码块用try catch进行异常的捕获并打印日志，那么异常信息将会被打印。

上面的问题是项目中的问题被复现后再简化得到的，实际项目中的源码比上面复杂得多。事实上将项目中的问题简化成上面的代码就花了好几天。事后总结了一下，认为如果先对日志进行优化，也许问题会解决地快一点。

4. 不规范使用日志示例

上面的问题只暴露出项目中日志使用不规范的一些，还有其它不规范的做法也导致问题定位的困难，这里总结如下：

4.1 不打印异常

如前所述，捕捉到异常后不做任何事，一旦异常真的发生，且导致问题出现，在复杂项目中可能会极难定位。除非真的确定异常发生不会有影响，否则至少还是打印一下日志吧。

4.2 线程池任务异常不捕获

如前所述，workerExecutor.submit(()->{ ... }) 内部代码块最好用 try catch 包围，然后打印一下日志，如果有必要的话，可以再次抛出异常。

4.3 logger对象定义为protected

protected final Logger logger = LoggerFactory.getLogger(this.getClass());

上面定义Logger对象的方式的有问题的，this.getClass()获取的是实例的Class, 而不是类的Class, 这样父类中打印日志时，显示的类名可能为子类（实例为子类对象）。

显然this.getClass()改成 Test.class 也是有问题的，这会导致子类打印日志显示父类的类名。事实上，logger对象不应该在父类和子类间共享，所以定义为protected 是不合适的。

一般还是应采用如下写法：

private static final Logger logger = LoggerFactory.getLogger(Test.class);

如果嫌麻烦，就用lombok或者IDEA自动生成代码吧。

4.4 异常日志没有说明

logger.error(e.getMessage(), e);

当捕捉到异常时，打印日志采用上面写法虽然省事，但却不便于根据日志快速定位至代码位置，一般应简单说明错误内容。如：

logger.error("send message error!", e);

4.5 线程池没有设置名称

在遇到较复杂的多线程问题时，没有命名的线程池会使问题更难定位。

4.6 异常日志不打印堆栈

logger.error(e.getMessage() + " send message error!");

这种写法不打印堆栈信息，仅通过e.getMessage()可能根本无法推断出异常的具体来源。

5. 总结

上面这些示例都是本次在定位问题过程中发现的，为解决问题不得不一点点优化日志打印，直至最后问题解决。
回过头来想一想，在定位问题前，若一开始就把日志优化好，再来定位问题，也许效率会更高。