一个线程中断引发Bug的“爆肝”排查经历

秒速五厘米 2022-11-20 05:53 153阅读 0赞

![0e1f450d2341d28214f412f0800416ca.png][]

## 背景 ##

在之前的版本上线了一个接收大数据推送交易数据文件的接口，这个接口要做的逻辑就是解析文件，分批入库。 当然为了数据的可靠性，以及支持重推，最终的流程大概就是这样：

![715282dd3eb20a097fdca6b1c9aee89b.png][]

上面的流程就是每日增量文件的处理流程，除此之外，还有一个历史交易数据的全量文件也需要推送过来，这个文件由于只推送一次，而且无法按照日期来支持重推，所以就约定只推一次（现在看来这里的处理方法是有点粗糙了。。），下个版本我将初始化接口对应的代码干掉。

版本上线后，业务在验证时发现不对劲，开始在开发业务验证群爆出问题：交易数据对不上！ 既然不对，那就直接看看数据库，很明显的发现，数据重复了，没错就是约定只推一次的数据现在推了多次，因为初始化的全量数据并不支持多次推送。

果然还是应了那句话，需要人为介入的事情，总是会有风险，关联方的推送开关不知道怎么滴被打开了，导致了上线后每天都推送了一遍，没有等到我方系统下线对应的接口。

![5e08de1e252f5d300a94c370675bba21.png][]

同时这也证明了，**墨菲定律**。如果你还不知道什么是墨菲定律，那我这里补充下：**如果一件事有发生的可能，那么不管几率多少，总是会发生的**，也可以理解为怕什么，来什么。

这也告诉大家，在平时开发相关逻辑接口时，一定要考虑各种出错场景，假设关联系统都是不可信的，确保自己的系统可以应对更多的异常场景。

对策：因为处于上线后验证期间，客户端没有上线，只有业务人员在验证使用，对应数据库表因为重推了好几份全量的数据导致数据量比较大，和运维讨论后决定删表重建后，在推一遍数据。 同时对推送文件的处理接口做防重逻辑：**如果重复推送则直接异常告警**。

## 问题出现 ##

再提交了重建表的脚本和初始化防重的代码后，当天下午移交给测试做功能测试和回归验证，准备第二天发布版本。 结果意外发生了，在执行解析入库的DB操作时报了获取不到连接异常：

![8936a8707b48f4575417823ec438452a.png][]

看到这个异常信息后：

### Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection;

想当然的以为是数据库的问题，然后考虑到有同事在复现 **数据库重启后应用实例无法重新连接** 的问题，第一时间重启了应用实例，结果发现依然不行，同样的错误。

既然是获取不到数据库连接，那应该整个应用实例都获取不到才对，所以去看下Myabtis的操作日志，发现其他DAO操作都是正常的。 没办法只能去看下代码，到底是哪里的问题。定位后发现是在解析数据入库这个环节报错了，具体一点就是在解析数据成功后，执行插入语句时，报了这个获取不到连接的异常。

## 排查过程 ##

因为这次修复我并没有改解析入库这块的代码，只是删表重建，然后在 `清理数据库（支持重推）`这个环节增加了如果数据已存在则直接抛出异常的代码。

@Override
    public void clearHistoryData(BigDataFileLogicParam param,String fileName) throws Exception { 
        if (!preCheckFilePass(fileName, 8)) { 
            OpLogUtil.logOpStep("文件预校验", "异常", param.getBizSeq(), param.getDate(), param.getFileId());
            throw new Exception("data receive has exists!");
        }
    }

既然已经走到了解析入库那肯定是没有啥问题了。

那么自然而然的认为，变动点就是删表重建的sql。难道是我的建表语句写错了导致Mybatis中的字段映射不对么？ 还是我使用的数据库用户新建的表,应用实例数据库连接串使用的用户没有访问权限？

带着这些猜想一个个排查吧。

经过检查，建表语句时一模一样，数据库用户也是同一个，这就奇了怪了。

![056e0f75e5e7c692f394fcc62d6e714d.png][]

这个时候我发现被我删除重建的这个表的查询语句是没有问题。 而这个时候测试都在等着验证，因为第二天下午要发版本。 当时只觉得一顿着急，实在看不出来啥问题了。

既然通过代码和日志不能直接解决问题，那就曲线排查吧。最原始的方法，一个一个排除，直接将这条sql语句改为操作其他表，排除是因为我删表重建导致出现这个问题。

改完代码打包部署上去。

if (CollectionUtils.isNotEmpty(acctDealTypeInfoEntities)) { 
        // 将原来的插入操作替换为一个任意表的操作
        // appAcctDealTypeInfoDao.batchInsert(acctDealTypeInfoEntities);
    	testDao.test();
        count += acctDealTypeInfoEntities.size();
    }

发请求再测试一下。。

结果，同样的错误，获取连接异常。

\[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-4eYTXOFN-1604449927783)(https://cdn.jsdelivr.net/gh/coderluojust/speed-image/img/20201103222611.png)\]

我真的要懵了，无论哪个表的DAO操作，放到这块都会报错，可是这块确实没有啥逻辑，为什么就只有在这块获取不到数据库连接呢，已经这么晚了，测试环境压根没有人再用了，也不可能是因为连接不够呀，实在解释不通。

士可杀，不可辱呀，不知不觉已经快10点了，测试同学可能是等累了，他们先回去，第二天早上测。 期间我还找了同事一起帮看，结果反复排查还是想不明白原因。

![bee7ed04f335f176c2143dfd2aa5e1f5.png][]

不过这个问题，当晚必须要解决，不能拖团队后腿呀（太菜了不好意思承认^^）。

## 灵光乍现 ##

这个时候组内老板突然来到了我身边，这可是请教的好机会呀！（拖他下水。。）

老板平时已经不怎么写业务代码了，见我搞不定，只能一起帮我看看（当时已经晚上10点多了，整层楼没几个人了）。

我在本地又直接连接测试环境对应的数据库，执行了对应的批量插入语句是没有问题的。无奈的加了些日志，期间打包部署了两次。

老板review了下相关代码发现没有问题，就看了下错误异常堆栈信息，提出了一个关键性的信息，那就是异常堆栈中打印的是获取数据库连接中断异常：

![7130a5316b7af66f5ffbb6c4bd9f9326.png][]

我好想瞬间想起了点什么，一晚上之前应该是排查错了方向，一看获取不到数据库连接，就以为是数据库相关的问题，忽略了堆栈中打印的中断信息。

既然这样，业务代码很简单也看不出来问题，就顺着堆栈追源码吧，当时已经午夜12点左右了，老板家里还有俩儿子，就先回去了，临走时安慰我说搞不定的话，就先回去明天再找专家指导下。可是我这么有责任心（菜的忧心）能安心的回去。

我们数据库连接池使用的是 Druid，`CannotgetJdbcConnectionException` 就是从 `DruidDataSource.getConnectionInternal()` 方法如下代码中抛出来的。

private DruidPooledConnection getConnectionInternal(long maxWait) throws SQLException { 
       // 省略
        try { 
            lock.lockInterruptibly();
        } catch (InterruptedException e) { 
            connectErrorCountUpdater.incrementAndGet(this);
            throw new SQLException("interrupt", e);
        }
        // 省略，数据库连接池配置的大小参数等检查 
      
    }

看到这里，可以发现，在DruidDataSource 从连接池中获取数据库连接时，这块调用了 `lock.lockInterruptibly()` 获取锁，来控制并发从连接池中获取数据库连接，因为要对连接池中连接的个数等进行检查。

而 `lock.lockInterruptibly()` 是响应中断的，如果当前线程中断就会被这里的catch代码块捕获，进而抛出我们前面看到的 SQLException:

![6a7cbcf2a3adbc8e13d558dc33e9bff4.png][]

但是线程好端端的，抛出中断异常，这怎么解释呢？

思考的时候口中默念了几遍 “Interrupt”，突然（此处应该有一道划破黑暗的灵光），我想起了在Java多线程开发中，经常有的线程阻塞、失眠等线程方法，都是会抛出 `Interruptexception`,而要模拟这种异常异常，最简单的就是调用线程实例对象的 `interrupt()` 方法，他会标记线程的中断位位true，而 `lock.lockInterruptibly()` 又是可响应中断的锁，具体实现是调用了AQS（`AbstractQueuedSynchronizer`）提供的方法:

public final void acquireInterruptibly(int arg)
            throws InterruptedException { 
        // 判断线程的中断标志位是否为true，如果是则抛出中断异常 
        if (Thread.interrupted())
            throw new InterruptedException();
        if (!tryAcquire(arg))
            doAcquireInterruptibly(arg);
    }

分析到这里，请求每次处理到解析数据落库这块就会失败，那么极有可能是这个流程中前面的步骤调用了线程的 interrupt() 方法，然后在落库时候获取数据库连接 `DruidDataSource.getConnectionInternal()` 中调用中断锁，导致抛出来异常。

业务的处理流程我们再来看下：

![715282dd3eb20a097fdca6b1c9aee89b.png][]

按照上面的猜想应该是解析数据入库之前的流程中出现了问题，照个这个思路去看业务代码，发现了一丝端倪：

/** * 直接清空上一批次的历史数据 */
    private void clearHistoryData(BigDataFileLogicParam param, String fileName){ 
        Collection<ReportFileParseService> reportFileParseServiceList = reportBaseService.getReportFileParseServiceList();
        for(ReportFileParseService reportFileParseService : reportFileParseServiceList) { 
            if(reportFileParseService.supportReportFileAndInsertHandle(param.getBizType())) { 
                try { 
                    reportFileParseService.clearHistoryData(param,fileName);
                } catch (Exception e) { 
                    OpLogUtil.onError("清空历史数据","异常",e.getMessage());
                    Thread.currentThread().interrupt();
                }
                break;
            }
        }
    }

上面的代码，在清理历史数据的公共方法中，如果实现类清理出现了异常就会调用 `Thread.currentThread().interrupt();` 导致线程中断标志位被设为true，进而在后面的解析入库逻辑中 调用 `DruidDataSource.getConnectionInternal()` 获取连接时抛出中断异常。

为了验证这个推断，我将这块代码改成下面这样，在清空数据实现类抛出异常时，不再调用 `Thread.currentThread().interrupt();` 改成仅打印错误日志，重新部署后，只要搜索日志关键字 “清空历史数据，异常”，并且插入数据正常落库就能验证这个问题了。

/** * 直接清空上一批次的历史数据 */
    private void clearHistoryData(BigDataFileLogicParam param, String fileName){ 
        Collection<ReportFileParseService> reportFileParseServiceList = reportBaseService.getReportFileParseServiceList();
        for(ReportFileParseService reportFileParseService : reportFileParseServiceList) { 
            if(reportFileParseService.supportReportFileAndInsertHandle(param.getBizType())) { 
                try { 
                    reportFileParseService.clearHistoryData(param,fileName);
                } catch (Exception e) { 
                    OpLogUtil.onError("清空历史数据","异常",e.getMessage());
                    // Thread.currentThread().interrupt();
                }
                break;
            }
        }
    }

改动后重新部署，再次调用接口，果然收到了 “清空历史数据，异常”的日志，并且之前的获取数据库连接异常：

![6a7cbcf2a3adbc8e13d558dc33e9bff4.png][]

终于不再出现了。

## 寻找上游问题 ##

之前这段代码是已经上线过了，其他有好几个实现类都走的这套逻辑，为什么就我这个接口出现问题了呢？ 这里根据代码逻辑继续追踪，肯定是我的清理历史数据的实现类出现了问题，而我这次确实改动了清空历史数据的实现代码，就是如果数据已经回传，则直接报错：

@Override
    public void clearHistoryData(BigDataFileLogicParam param,String fileName) throws Exception { 
        if (!preCheckFilePass(fileName, 8)) { 
            OpLogUtil.logOpStep("文件预校验", "异常", param.getBizSeq(),param.getDate(), param.getFileId());
            throw new Exception("data receive has exists!");
        }
    }

检查数据库中对应日期的数据是否已经回传，果然，对应的测试环境的数据库已经有很多脏数据存在，终于前因后果都对上了；

此时已经凌晨1点了，我赶紧将问题已经排查解决的结果告诉组内老板，因为他回家路上还给我打了好几个电话指导思路，肯定也很担心这个问题（我可不是想表现什么的，认真脸）

![a0bcb0743e09c8c9f844b4253c47c347.png][]

## 小结 ##

至此，耗时5小时的获取不到连接异常终于搞定了，我来做下小结：

**对事方面的小结：**

问题综述：

1.  测试环境存在人为插入导致数据日期冲突的脏数据；
2.  在清理历史数据的实现方法中增加了抛出异常操作，导致外层公共代码执行了线程中断操作；
3.  调用清理历史数据的公共方法在异常处理中调用了 线程的 interrupt() 方法；
4.  调用了线程 interrupt() 方法，导致解析插入数据，获取数据库连接时抛出中断异常；

解决方案：

1.  将接口流程中所有调用 `Thread.currentThread().interrupt();` 方法改为抛出异常，让调用方感知到错误；

**需要明确注意的是：**

`Thread.currentThread().interrupt();` 方法不能使线程立刻中断退出，而只是设置了线程的中断属性为true，在线程调用可以响应中断的方法时，才会将异常抛出，将控制权交给捕获中断异常的代码块。 比如当调用 线程的 `sleep()` 方法，`wait()`方法， `lock.lockInterruptibly()` 方法时，都是必须强制捕获中断异常的， 这些情况才会响应线程的中断状态。

这也是为什么在清理数据的时候调用了 interrupt 方法，但是线程还一直运行到了解析入库的流程中，在获取数据库连接的代码中有调用 `lock.lockInterruptibly()` 这才抛出了中断异常，因为从清理数据到解析落库这个过程中没有调用任何可以相应中断的方法，所以这中断的状态一直没有发挥作用，相当于埋了一颗定时炸弹，不知道他啥时候会爆炸，导致出现离奇错误。

**对人方面的总结：**

1.  编码时要谨慎，改动点再小也要仔细评估审阅上下文代码；
2.  一般编写业务代码捕获异常后不要再使用 `Thread.currentThread().interrupt();` ，线程中断等线程api用法要牢牢掌握；
3.  想当然的坏习惯，使我一开始看到`CannotGetConnection`错误就以为是数据库问题,错过了宝贵的线索，今后的问题要避免主观因素，掌握套路，分析异常堆栈展示出的详细信息；

## 群策群力，消灭BUG ##

踩坑踩得心累，如果本文内容你觉得有所收获，请帮忙点个**三连**

**同时不要忘了关注我呀，让七哥做你成长路上的同行者！**

[0e1f450d2341d28214f412f0800416ca.png]: /images/20221120/2b249fbe047048e9890e7b7ea9cc9b20.png
[715282dd3eb20a097fdca6b1c9aee89b.png]: /images/20221120/7ab72b61ac4548009971c48f48344c57.png
[5e08de1e252f5d300a94c370675bba21.png]: /images/20221120/a09b2b3258a14e27bfe829e736f3f85c.png
[8936a8707b48f4575417823ec438452a.png]: /images/20221120/3ec9ab250c9a4397b8e5675bd9cc61c7.png
[056e0f75e5e7c692f394fcc62d6e714d.png]: /images/20221120/e0995f9d102a4cb39094d16270fe70a0.png
[bee7ed04f335f176c2143dfd2aa5e1f5.png]: /images/20221120/df10341a280846e395bc5669c623bfee.png
[7130a5316b7af66f5ffbb6c4bd9f9326.png]: /images/20221120/dce4b9e76e2e4e09bd792ecf46ab5e17.png
[6a7cbcf2a3adbc8e13d558dc33e9bff4.png]: /images/20221120/83db51e5ccd9448296e8364cbb4d9338.png
[a0bcb0743e09c8c9f844b4253c47c347.png]: https://img-blog.csdnimg.cn/img_convert/a0bcb0743e09c8c9f844b4253c47c347.png