记一次 bug 定位

《代码简洁之道》中说:读与写花费时间的比例是10:1,写新代码时,我们一直在读旧代码！尤其在定位 bug 的时候,我们在一遍一遍的阅读代码。

今天遇到有同事遇到下面的异常信息,我帮其定位并解决了问题,特记录一下定位 bug 的历程。

当看到上面哪行日志的的时候,我也是蒙的,为啥？因为堆栈信息太少了,前前后后总共才13行,而且出现了我们程序猿最不愿意看到的情况,异常堆栈打印的全是源码中的信息。这样的情况要么凭经验一眼看出是哪个类问题,要么就得单步调试了。一般我们打印出来的日志总是定位到我们自己写的代码的 xxx行。

那么针对上面这种情况怎么办呢? 我们要抓住第3行的 这几个字,很明显这是自定义的一个异常信息,那么在程序中大概率这句话是写死的,拿这句话在全局中搜索一下,如果你很幸运你会只定位到一处,如果不幸那就得根据前后请求的 RUL 来定位了。

因此我们定位到如下的代码

很明显 result 的异常被 recover 住了,说明第6 行的 result 这个 Future 中发生了异常,由于日志中没有打印第7行的 ,所以可以断定函数没有进入 flatMap 中,那异常一定出在 add 这个函数中.但是我们追踪函数发现

这是一个 trait ,那么我们去找他的实现

发现运用了反射、泛型等知识,遇到这里有可能有人就看不下去了,因为一行有用的代码有没有,还要去理解框架的意图,那简直太坑了。但是没办法,你就得去理解他的意图,猜测这个的意图是找到一个 AuthInfoDAO 的实例类去执行 add 方法,所以无论如何也找找到自己的实现,因为框架出问题的概率很小,一定要找到自己写的代码。

我们来看看这个 add 的实现,结果发现,妈蛋,又是一个接口

继续找实现吧

终于守得云开见月明了,终于找到了自己写的代码。

我们看看这个 addAction 做了什么动作

好！！终于看到一个有可能报Invoker.first的地方了,Invoker.first是说去一个空的对象取第一个元素,因为这个对象是空,那自然没有办法取第一个元素啊！！

这说明你传的参数去数据库里面查找的时候没有查到数据！！！

问题定位到了,那事情就这么简单么,当然不是!,我们应该想到为什么之前业务没有出问题,而现在业务却出了问题,这个时候就要从业务的实现流程以及这期代码改动了什么内容着手了。

经过询问,发现有同事给这个方法添加了事务控制,于是我很敏锐的觉察到可能是事务的控制没有做好,好了再看一遍代码吧,哎呀,原来他在一个系统里面调用了另一个系统,而另一个系统依赖非事务的数据。下面详细描述一下。

这个业务功能是新增一个员工,那么在 A 系统中开始操作数据库,先添加到员工表员工信息,在添加到员工公司的关联表,然后在登录表中添加一条信息,最后要添加到密码表中生成一个初始密码,但这个生成的密码必须由 B系统生成,也即是在 A的这个添加员工的方法中需要调用 B 的生成密码的方法,但是但是,B 系统添加密码的前提是登录表中有 A 中添加的那个数据也就是代码中 Login_info 表中必须有值得,但是由于 A中的方法是事务的,只有在方法执行完毕的时候才能 commit 信息到数据库中去,也就是说掐面 A添加信息到登录表中的的操作在 B中查数据库的时候是看到添加的数据的,于是 B 中生成密码的方法率先报异常了,导致 A 中所有的数据库操作回滚！！！

哈哈,真相大白了！！

彩蛋

那么怎么解决这个问题呢?且听下回分解