一次奇怪的的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在興風作浪，或者是兩個 (￣^￣)
