公司对底层基础库进行了重构,线上稳定跑了几天,在查看订单系统的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
到数据库pg_stat_activity
里观察执行情况
发现一个更奇怪的现象,无论我执行插入还是执行修改操作query
字段里一直都是BEGIN READ WRITE
,sql
没有在事务里执行?再一步的深入查看代码,一直到基础库的代码终于发现了问题的原因,公司的数据库基础库封装的有问题,在创建创建事务的时候正确创建了tx
但在执行具体的sql时没有使用tx
因为sql
没有在事务里执行,我们的行锁也没锁住,为了验证我是正确的,写gotest
创建两个事务,第一个事务,不提交也不回滚,正常情况下,第二个事务,会一直等待第一个事务。
果然,直接就打印出来两个结果,没有锁住,再结合CDC
数据中看到的状态也就能说通了,代码被重入了,哪怕有问题 rollback
也不能把已经执行的sql回滚。
终于找到原因了,没白浪费这么长时间,修改代码
再执行代码观察事务
query
里有正常的数据了。基础库的问题,在业务代码的各种测试时都是按正常流程进行的,所以也测试不出一来,盲目的相信业务代码,虽然业务代码确实没有问题,如果能早一点进行锁的测试就能更快的定位到基础库的问题。提交MR
修改引用的项目,等低峰上线。
不起眼的错误log
信息,一定要重视,说不定就是个超级大bug在兴风作浪,或者是两个 ( ̄^ ̄)