一次奇怪的的bug排查过程
- 2021 年 11 月 30 日
- 筆記
- architecture&framework, BUG, golang, golang debug, PostgreSQL
公司对底层基础库进行了重构，线上稳定跑了几天，在查看订单系统的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在兴风作浪，或者是两个 (￣^￣)
