案例：一行日志导致的线上事故。

清疚 2022-02-16 12:51 242阅读 0赞

本文解决一个由于增加一行日志导致的线上事故，以提醒我们在程序开发的过程中一定要精心记录每一行日志。

该案例为一个线上运行良好的服务，在一次上线的过程中增加了一行日志，导致这个服务的数据库连接池的连接出现用光的情况：

private void doSomething(..., Map param) {
        log.debug("....." + param);
        ...
    }

从表面上看，这样增加日志没有任何问题，也不会导致数据库连接池被用光。

现在我们开始排查。首先，观察线上日志，发现线上服务开始偶发的报NullPointerException，通过查看线程的调用堆栈，发现他是在一个领域模型的toString()方法里报出来的。

public class DomainObject {
        DomainObject1 do1;
    
        @Override
        public String toString() {
            return "domainObject1：" + do1.getId();
        }
    
        public void setDo1(DomainObject1 domainObject1) {
            this.do1 = domainObject1;
        }
    }

这时可以想到，报NullPointerException是因为增加了日志，在日志中打印Map的内容，Map的内容里面包含这个对象，那么打印日志时就需要把这个对象转换成字符串，这时会调用对象的toString()方法。

可是toString()方法为什么会产生NullPointerException呢？产生问题的toString()方法本身很复杂，有很多字符串串联，我们对上面的代码进行了简化，但是通过分析，发现只有domainObject1为空时会产生NullPointerException。

至此，我们还有两个问题。

*  为什么字段domainObject1会是空的呢？
 *  为什么会引起数据库连接池里面的连接用光呢？

要想弄明白第1个问题，我们需要先知道数据的来源，通过查看代码，我们发现外层的domainObject对象本身是从缓存里面拿到的，这样就比较合理了。

其原因可能是缓存数据的生产方在取数据时只取了外层的domainObject，而没有取domainObject1字段，然后就放进了缓存，这时toString()就产生了NullPointerException。

可是为什么只有一部分请求量会产生NullPointerException呢？原因可能是生产domainObject对象的缓存数据有多个提供者，有些提供者既提供了domainObject，也提供了domainObjeect1字段，而有些提供者只提供了外层的domainObject，于是有些请求发生了NullPointerException。

现在我们来看第2个问题，虽然产生了NullPointerException，但为什么数据库连接池会用光呢？因为这个应用还存在一个Bug，在上层处理业务逻辑的过程中，我们手工拿到了数据库连接，遇到了NullPointerException后并没有释放数据库连接，因此多个数据库连接被占用，最后数据库连接逐渐被用光，就无法提供正常的服务了。  
那么，我们在开发程序时应该注意什么呢？

*  toString()方法的实现需要考虑连接字符串是否可能产生NullPointerException，对可能为空的字段先判空后再进行打印。
 *  如果对象不大并且不是一个集合类，则在toString()中可以考虑使用JSON序列化工具把对象转化成JSON字符串。
 *  如果没有对使用的变量判空，则在toString()方法中也要抓住异常。
 *  在增加打印日志时要考虑到toString()方法是否有传导性，避免可能引起不可预测的NullPointerException问题。
 *  一定要在try...finally语句里面对申请的资源进行释放。
 *  使用缓存存储数据的时候，要确保存入的数据一定是准确的和完整的。