記一次 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 中所有的資料庫操作回滾！！！

哈哈,真相大白了！！

彩蛋

那麼怎麼解決這個問題呢?且聽下回分解

喜歡這篇文章嗎？立刻分享出去讓更多人知道吧！