一次奇怪的的bug排查过程
公司对底层基础库进行了重构,线上稳定跑了几天,在查看订单系统的log
时,有几条error
信息非常的奇怪,
orderID:80320180 statemachine error: no event [Revoked] at current state [Paid]orderID:81983045 statemachine error: no event [Refund] at current state [Revoked]
订单有状态机进行维护
- 已经被撤消的订单不能再进行有其他操作,和状态更改。
- 已经支付的订单,不能被撤消,只能退款或者部分退款。
log
虽然没有太大问题,关键问题在于,正常情况下,这条log就不应该被执行,所有对订单进行操作的接口,都会判断订单的状态,如果订单已经支付,撤消就会直接当做错误的操作,返回给客户端error,这条log
所在的地方是不会被执行到的,总结和排查问题- 这个错误不是每天都有,偶尔会被报出来
- 有旧的镜像在跑旧的业务代码导致的?查看
k8s
镜像信息,没有问题。 - 并发问题导致的?规定在操作订单的时候都是行级锁,再判断订单状态的,但需要排查一下业务代码,是不是有哪里有没进行锁行操作,导致代码被重入了?好在
Log
也有链路id
可以根据trace-id
来确定是哪个接口调用,就能很快定位到问题所在的地方,
文章图片
trace-id
追踪发现了一个新问题,查不到数据,只有那一条错误log
,查看代码,这个系统的trace
在初始化的时候不知道什么时候被改错了。先修复
trace-id
的问题,但对当前的问题也没啥用了,等上线后,还不知道这个问题啥时候能复现呢。只能用最笨的办法一点点的排查代码了,对所有操作订单的地方进行检查,代码没有问题,又检查了一遍还是没有问题,突然脑子里冒出个段子:难道是神密力量导致电缆里的几个
bit
出了问题,导致我们的代码运行异常了?哈哈。又检查完一遍业务代码还是木有问题。数据库的问题?那还不如是系统的bug呢。
这时候同事导出一份
CDC
数据,根据这些数据查看订单支付状态,从2->3->2 变回去了,正常流程下不可能有这样的情况发生,100%确定就是系统的问题,但业务代码中没有看出问题来哇!文章图片
再
debug
看一下数据库(postgresql)里事务的执行情况,找一个事务的
pid
文章图片
【一次奇怪的的bug排查过程】到数据库
pg_stat_activity
里观察执行情况文章图片
发现一个更奇怪的现象,无论我执行插入还是执行修改操作
query
字段里一直都是BEGIN READ WRITE
,sql
没有在事务里执行?再一步的深入查看代码,一直到基础库的代码终于发现了问题的原因,公司的数据库基础库封装的有问题,在创建创建事务的时候正确创建了tx
文章图片
但在执行具体的sql时没有使用
tx
文章图片
因为
sql
没有在事务里执行,我们的行锁也没锁住,为了验证我是正确的,写gotest
创建两个事务,第一个事务,不提交也不回滚,正常情况下,第二个事务,会一直等待第一个事务。文章图片
果然,直接就打印出来两个结果,没有锁住,再结合
CDC
数据中看到的状态也就能说通了,代码被重入了,哪怕有问题 rollback
也不能把已经执行的sql回滚。终于找到原因了,没白浪费这么长时间,修改代码
文章图片
再执行代码观察事务
文章图片
query
里有正常的数据了。基础库的问题,在业务代码的各种测试时都是按正常流程进行的,所以也测试不出一来,盲目的相信业务代码,虽然业务代码确实没有问题,如果能早一点进行锁的测试就能更快的定位到基础库的问题。提交MR
修改引用的项目,等低峰上线。不起眼的错误
log
信息,一定要重视,说不定就是个超级大bug在兴风作浪,或者是两个 ( ̄^ ̄)推荐阅读
- 【故障公告】周五下午的一次突发故障
- 我要我们在一起(二)
- 洱海不是海,,人群没有你
- 我的拖延症如何控制了我,又一次
- 跟身体谈恋爱
- 心情的样子
- 记一次赛课失利
- 秋已动夏未走
- 第一次组织同学们乘车
- 恩|恩 有点喜欢你