背景###
事情是這樣滴:
有個發貨服務化工程 D,依賴於數據訪問服務 S 提供的若干個 dubbo 接口,還有一個服務接口自動化測試工程 T , 可以直接調用 D 和 S 的 dubbo / httpRestful 接口來自動化回歸測試這兩個工程暴漏的服務接口。當改動 S 或 D 的代碼后,運行 T 里的可重復執行的發貨自動測試用例,若全部通過,則可驗證 S 或 D 改動是有效的。
發貨的核心邏輯是: 在前置條件校驗通過后,D 需要調用 S 的 insertExpress dubbo 接口來插入發貨的數據記錄。一個單商品無退款訂單,應該分別只插入一條 oe(簡稱 X), oe_detail (簡稱 Y)記錄。
問題###
當同步升級 D , S 依賴的 common-model 包的版本后(差別僅在於 BaseResult 的 code 類型由字符串變成整型),之前一直執行成功的發貨自動測試用例現在失敗了。
開始以為是多個訂單號的發貨測試用例之間存在隱性的依賴,導致連續運行的時候失敗了;於是,我注釋掉其他的訂單號,只針對一個最普通的訂單號運行單次發貨用例;然而,即使是單次調用針對最普通訂單的發貨服務的 Restful 接口,也會失敗。
使用Debug模式單步調試了下,發現是一個 assert 語句未通過;而這個語句未通過的原因,是針對這個單商品訂單號插入了幾乎完全相同(除ID值不同)的數據庫記錄 X(id1) ,X(id2), Y(xid=id1), Y(xid=id2)。
運行 insertExpress 的數據庫DAO單元測試是沒有問題的,說明DAO的數據插入方法應該是沒有問題的;也不存在並發訪問數據庫的情況。
由於QA環境有問題,我就部署到預發環境,看看是否有問題,能不能找到線索;結果預發沒有問題;推測QA環境可能哪里有問題,但是又想不出是什么。
排查###
迷惑因素-jar包升級####
由於此問題碰巧是在 common-model JAR包升級 1.0.1之后出現的,一度以為是這個升級導致。對比實驗也似乎非常確鑿地支持這一點。當我把工程 D 切回到升級前的分支后,用例就執行成功了,切到升級后的分支,用例又失敗了。可是,這個升級中工程 D 只改了一行跟發貨毫無干系的代碼,就是把 String 類型的 errorCode 解析成 int 類型返回給調用方而已,幾乎不可能是導致用例失敗的原因。不管怎么說,這個Jar包的升級是必須的,必須在升級的基礎上進行排查。
運行多次-概率性出現####
不信邪的我多次執行這個單次調用服務接口的測試,時而換個訂單號執行下,發現有的時候成功,有的時候失敗。這下可奇怪了,同樣的代碼,為什么有時成功,有時失敗呢?接連運行的測試之間有依賴? 不大可能啊!
於是我編寫了一個通用方法,可以多次執行同一個測試,並統計失敗次數。發現這個測試確實是概率性成功,且成功的概率還是很小的。失敗都是因為單次調用卻插入了兩條完全相同的數據庫記錄。這究竟是怎么回事呢? 難道是事務代碼編寫有問題,導致實際調用了兩次SQL?
聚焦核心接口####
由於 D 調用 S 的 insertExpress 方法是實現發貨的核心邏輯(除了這個就是各種校驗了),因此可以聚焦 S 的這個方法。既然多次調用D的發貨服務接口概率性失敗,那么多次調用 S 的 insertExpress 會怎樣呢?在 T 中多次執行 S 的 insertExpress 的測試用例,幾乎都是成功的。很難相信這個結果:只有這個方法會插入數據庫記錄,如果調用 D 的發貨測試用例多次失敗,那么幾乎可以肯定是 S insertExpress 多次失敗了。然而 調用 D 的發貨測試用例的失敗概率 與 調用 S 的 insertExpress 的失敗概率是成反比的。
代碼細審####
從代碼入手吧,仔細讀讀代碼,看看是否有因為馬虎寫錯的地方,或者在某個細微的地方犯了錯誤。果然,發現事務代碼似乎有點問題:
會不會因為 transactionStatus 取不同的值多次執行了后面的插入呢?會不會因為 T 調用 D 的接口超時重試,導致這個方法被多次執行了呢? defaultTxTemplate ? 這個不是引用非分庫的數據源嗎? 可是 X, Y 記錄是在分庫的數據源里啊,為什么引用非分庫數據源的事務管理器可以訪問分庫的數據源的數據呢? 如果不可以,為什么發布到預發和線上都沒有問題呢?如果可以,又是什么緣故呢?此外,還發現了一個問題:工程 D 的 OrderExpressService 的 Bean 名稱在 Spring配置文件里寫成了 orderExpressDetailService , 但代碼里引用的卻是
@Resource private OrderExpressService orderExpressService
這代碼是怎么跑起來的?真是一波未平,一波又起。
打印日志-排除可能####
於是,我在 S 的事務代碼中加了日志,部署到QA環境再執行。
令人驚訝的是,日志清清楚楚地顯示,事務代碼只執行了一次,SQL執行中也顯示只插入了一條記錄,但是查詢 order_express_detail 的時候,卻查到了兩條! 實在令人百思不得其解!
ngrep抓包-疑竇叢生####
早會上說了這事,工作伙伴奎哥建議使用 ngrep 抓包試試。其實一直對抓包這個詞感到神秘,這會正好學學怎么玩。在部署了 S 和 D 的 centos 機器上使用 sudo yum install ngrep 安裝 ngrep 后,就開始抓包行動了:
(1) 在 D 上使用 sudo ngrep -W byline -d eth0 port 8025 打印本機到 D 的網絡調用請求及數據;
(2) 在 S 上使用 sudo ngrep -W byline -d eth0 port 20881 打印 D 到 S 的dubbo服務請求及數據;
(3) 在 S 上使用 sudo ngrep -W byline -d eth0 port 3007 打印 S 到 mysql 的請求及數據。
然而,請求和插入SQL依然只執行了一次,但是查詢的時候卻有兩條。這條額外的插入語句究竟是怎么來的呢?我還對比了下成功和失敗情況下抓包數據有什么差異;開始捕獲了一點似乎有用的線索,比如SQL的設置等,但后來發現成功的時候也會有這些設置。
一語驚醒夢中人####
中午吃飯的時候又跟奎哥說了下這些奇怪的事情,奎哥說可以讓數據庫同學抓包看看,插入SQL的來源IP是什么。這句話點醒了我: 不同的IP?不同的機器同時插入數據庫? 突然我記起前不久QA在搭建集成環境,當時測試同學還找我協助解決搭建 D, S 的問題。會不會兩個機器都接到了dubbo服務請求去插入了數據庫呢?想到這里,我馬上登陸到那台QA集成環境的機器上,使用 sudo ngrep -W byline -d eth0 port 3007 進行抓包。真相大白了! 果然這台機器也執行了dubbo服務請求,插入了數據庫記錄!
可是疑惑還未完全消散: 為什么發送一個請求到注冊中心,多個提供服務的應用都會執行呢?按照負載均衡原理,這些服務器不是只有一台才會去執行請求嗎?線上不是也部署了多台提供相同服務的應用服務器么?它們也會同時插入數據庫記錄嗎?后來問了下中間件同學,確定是 QA 集成環境和 QA測試環境都注冊到同一個 etcd 環境,導致同一個dubbo 請求被分別執行了一次。
多工程聯調####
那么,那個引用錯誤的數據源的事務管理器又能插入到正確的分庫數據庫是什么緣故呢? 找RDS同學幫忙看了下,沒發現數據庫這邊的線索;於是在本地啟動 D , S 工程, 臨時修改 S 的 dubbo 端口配置為 20886 避免與 D 的沖突,並修改 D 的配置直連 S 的接口進行調試。感謝奎哥的工作!通過單步調試發現, DAO 配置的是分庫的數據源;盡管從事務管理進入時引用的是非分庫的數據源,但是到達DAO Session 層執行SQL 的時候就轉變成分庫的數據源,從而能夠正確執行SQL了。就好比函數里的局部同名變量覆蓋了全局同名變量。不過這里到底是有問題的,后面需要修復。
另外,Spring bean 聲明的名稱與代碼里引用的不一致,卻能正常工作,是因為 @Resource 在找不到與名稱一致的 bean 時會自動創建類型相同的 bean ; 這些都是細小的問題,但隱藏着風險。
AllPassed####
明白了原因所在,解決就好辦了。我征求了QA 同學的意見,將QA集成環境的那台機器的 S 應用停掉了,測試用例立即就全部通過了。
小結###
排查疑難問題總是讓人絞盡腦汁百思不得其解,可是解開謎底的過程,又是個痛並充實着的過程,也會很好滴提高解決問題的綜合能力。就拿這次問題排查來說,綜合使用了“排除迷惑因素、對比實驗、多次執行、聚焦核心代碼、代碼細審、日志打印、單步調試、多工程聯調、網絡抓包、數據對比、環境部署、與工作伙伴交流探討”等技能。
當出現問題時,或許我們應該更善於從整體上找原因和解決方案。針對這個問題,如果從單個應用的角度去考慮,就會考察代碼寫得是不是有問題(當然確實有點問題,但不是真正原因);如果從環境去考慮,就會思考是不是有多台機器同時插入了數據庫。比如手機充不上電是因為電源芯片燒壞了,解決方案是換個電源芯片。但實際上由於使用了兩年,可能電池或其它部件也老化了,從整體來說換個手機更划算。再比如ide報第75行語法錯誤,很可能是第73行少了個分號引起的連鎖出錯反應。
單步調試依然是調試細微問題的最簡單的武器。任何問題都逃不過單步調試的眼睛。排查“引用錯誤的數據源的事務管理器能插入到正確的分庫數據庫”這個問題,正是使用單步調試,發現數據源又被偷偷換回來了。
排查問題的手段也要靈活多樣。既要縱向深入,也要學會橫向對比,多角度探查。
與工作伙伴交流也是非常重要的。如果不是奎哥的兩次重要提醒,估計還要花更多時間在雲里霧里不得其解。
在解決問題的過程中,順便還發現了兩個隱蔽的小問題,在大規模線上服務分流之前,簡直是天意!