一次异常艰难的bug排查之旅
下午终于解决了困扰了我好几天的一个bug,这个bug的排查之旅十分艰辛,最后的解决方式出乎意料的简单.简单分析一下.
前提
这是一个新项目,从老项目移植而来,框架上从 spring boot 1.x升级到了2.x ,相关的依赖也都升级了.大家一起解决了升级过程中遇到的一堆坑,然后对老项目中的各个痛点进行改进..之后就是按部就班的移植业务逻辑,提测,事情进展到这一步是相当顺利的,前提是,没有这个bug!
测试提了几个bug,类似于 消息推送了两次,弹框出现两次,系统消息重复,主流程错误 等.
排查之旅
事情要分个轻重缓急,弹框出现两次,和系统消息重复这种问题不影响大局,而且看起来很像是前端的问题,因此这些bug先放到一边,先看主流程错误
没有什么是加log不能解决的,如果有,那就多加点
由于是移植的代码,逻辑我也不是特别清楚,上万行代码要是等全部理清了再处理黄花菜都凉了,首先想把这块逻辑和老代码比对一下,看下是不是移植的时候疏忽了,完全没问题! 怎么办? 加log,对和这块逻辑相关的代码的每一个关键步骤添加log,记录关键变量的变化,记录的时候一定要有一个统一的字段将他们关联起来,这样查看日志的时候可以观察到完整的流程,例如
...
logger.info("userId [{}] xxxxxxxxxxxxx",userId);
...
logger.info("userId [{}] xxxxxxxxxxxxx",userId);
...
logger.info("userId [{}] xxxxxxxxxxxxx",userId);
初现端倪
通过观察日志,比对代码中的关键步骤,发现是一个状态被错误的更新了两次,正常情况下它应该只被更新一次的,检查对应的dao层代码,看下是不是又copy的时候搞混了,检查下来没问题,再看更新状态对应的这个dao层方法的调用情况,和老项目做下对比,也没问题.
既然这里查不到问题,那么就查下出现问题这段时候的所有日志,经过艰难的过滤和查找,终于找到了一个关键信息: 这个逻辑的入口方法被调用了两次,因此状态才会被更新两次.
假象
进行到这里,我以为已经找到了问题的关键,这个时候我对这个bug出现原因的假设是: 有些逻辑会调用这个入口方法,那么应该是移植的时候这些逻辑copy错了,导致这个入口方法被调用了两次.那么下面的重点就是找出哪些地方调用了这个入口方法.
经过检查,这个方法分为内部调用和外部调用,外部调用会制定一个定时任务(定时任务这个模块有两个实例运行),间接传递给顶层模块,顶层模块会在计时到达时调用这个入口方法,内部调用则是其他逻辑中直接调用. 查看日志,根据其中一次调用对应的UUID,成功找到顶层模块中对应的调用日志.那么另外一个肯定是内部调用了,然后查找内部调用的逻辑,有牵扯出一大堆关联逻辑,一层调一层, 没办法,再次祭出log大法.一大堆log看的头皮发麻,这样边查边加log,苦苦挣扎了大半天,一无所获,此时心态爆炸,已经想要放弃,求教大佬了,然而根据现在查出来的数据,无法提供有意义的参考,自己的锅还是自己背吧,继续查.
转机出现
第二天早上,抱着死马当成活马医的想法,再次查看日志,发现两次都是外部调用,纳尼! 顺着这个思路,去查找制定定时任务的地方,看下是不是这里的逻辑有问题,经过艰难的log&查找,看到定时任务只制定了一次.再次陷入僵局.时间又过去了半天...离验收时间又近了,头疼.
换一个视角
再次查看日志,发现两次入口方法的调用时间十分接近.难道是顶层模块除了问题.首先解释一下定时任务制定的逻辑: 底层模块制定定时任务就是redis中存入一个key,顶层模块会轮询同一个redis,然后解析key进行调用. 这整个模块也是直接copy过来,基本没有改动,这次是真的无计可施了.只能求教大佬
柳暗花明又一村
将我调查出的所有线索告知大佬,大佬查找之后发现有很多定时任务都是很相近的时间被重复调用,大佬给出了指导,看下顶层轮询那里,加点日志看一下.这一查,果真查出了问题. 由于有多个(请注意,两个!!!)顶层模块实例存在,因此使用redis事务保证定时任务只被执行一次.之前的代码是这样判断事务是否执行成功的
List result=redisOperations.exec();
if(result!=null){
// 事务执行成功操作
}else{
//事务执行失败操作
}
问题就出在这里,由于spring boot升级了2.x,对应的spring data redis也升级了.而升级之后,当事务执行失败后,exec()返回的不再是null,而是空List.修改为以下代码后顺利解决
List result=redisOperations.exec();
if(!CollectionUtils.isEmpty(result)){
// 事务执行成功操作
}else{
//事务执行失败操作
}
反思
exec的变化之前是看到过相关文章的,由于其他地方代码也用到过这个事务,而且那些部分也经过了测试,所以从来没有向这块联想.没想过会是这里出问题
有哪些征兆没能意识到?
系统消息重复,两次弹框,消息推送了两次,从这些是能看出一些征兆的,结合顶层模块有两个实例,这些特征都被无意识的忽略了.导致在无意义的方向浪费了很多精力.
思维差异
时候问大佬为什么他第一印象是顶层模块有问题? 大佬说:
业务逻辑是移植过去的,如果有问题,早就乱套了
而我的第一印象是业务逻辑移植的时候出了问题,细想一下,这个印象站不住脚,移植业务逻辑,顶多出现遗落了一个分支代码或者错误删除一些代码.不可能出现张冠李戴这种问题.
总结
最终是大佬找到了bug的关键,是不是就意味着我做了几天的无用功? 不不不,在我看来,之前收集到的那些线索,很有用处,首先排除了很多不可能的判断.然后以我的视角给出问题的表现,再将收集到的证据展示出来,才能最终这么快速的解决问题. (如果在没有搜集到足够的证据之前就甩锅给别人,是不道德的,只会将一个人的痛苦变为两个人的痛苦)
代码不规范,同事两行泪, 在这个bug上的体现就是: 集合判空一定要用工具类,不要只是 list==null
