年年出妖事,一例由JSON解析導致的"薛定諤BUG"排查過程記錄

鉑賽東發表於2022-05-07

前言

做開發這麼多年,也碰到無數的bug了。不過再複雜的bug,只要仔細去研讀程式碼,加上debug,總能找到原因。

但是最近公司內碰到的這一個bug,這個bug初看很簡單,但是非常妖孽,在一段時間內我甚至是百思不得其解。在長達幾天的時間內,復現的概率非常低。幾乎難以抓住任何蹤跡。

所以這篇文章就非常寫實的來記錄一下此Bug的發現和排查整個過程。

起因

同事之前做了個需求,提交測試。測試同事在測的一半的時候。發現了後臺的一個報錯

com.alibaba.fastjson.JSONException: can not cast to String, value : {"code":"00","msg":"成功","data":{這裡是正確的資料}}
	at com.alibaba.fastjson.util.TypeUtils.castToInt(TypeUtils.java:564) ~[fastjson-1.2.29.jar:na]
	at com.alibaba.fastjson.serializer.IntegerCodec.deserialze(IntegerCodec.java:89) ~[fastjson-1.2.29.jar:na]

一看就知道這錯很簡單,就是一個fastjson的轉換型別的報錯。接受的json和要轉化的型別不匹配造成的。基本上檢查下程式碼,一眼就能解決的。

結果同事看了好一會兒,都沒發現哪有問題。

然後遠端在測試環境debug執行,打上斷點準備除錯,測試同事操作下來,卻又好了。

然後釋放斷點,正常執行。操作一會,又出現了相同報錯。

繼續打上斷點,還是正常。

這個現象把同事整的有點懵,我在群裡看到這個,覺得這個現象很有趣,結果竟然依賴於是否觀測,這什麼鬼。。

我接過手看了下程式碼,我初步看下來也是完全沒問題的。

程式碼我經過了精簡和一些虛擬碼處理,如下所示:

public <T> T executeLua(String luaName, Class<T> c, Object... args){
	String json = 執行器.執行(luaName,args);
  log.info("執行結果為:{}",json);
  T resut = JSON.parseObject(json, c);
  return result;
}

呼叫的時候如此呼叫:

LuaResult result = executeLua("xxxx", LuaResult.class, args);

而返回物件的泛型T則是一個LuaResult物件,其結構也很簡單:

public class LuaResult<T> {

	protected String code;

	protected String msg;

	protected T data;
  
  ...
}

根據列印出來的json結果來看,返回的資料是正確的結果,並且是完全匹配LuaResult物件這個結構的。雖然在呼叫的時候沒加泛型,但是由於前面程式碼並用不到LuaResult裡的data,所以解析出來依舊保留了JsonObject的型別。從執行的角度上來說,是完全沒問題的。我也用本地的main方法用相同的資料跑了下,是完全能正常解析的。甚至於我在本地試了迴圈解析多次,多執行緒去解析,都是沒問題的。

那為什麼一到伺服器環境就偶發性的報錯呢。

我也決定遠端debug下,我不相信會有薛定諤的bug這麼一說。

我遠端打上斷點,測試同事開始做業務,一切完全正常。

於是我去掉斷點,在沒過多久後,測試同事給我發來了報錯的截圖。一切還真的和之前的同事如出一轍。。。

這下我也凌亂了,這麼簡單的報錯,看不出問題也就罷了,還沒法除錯??而打出的日誌返回的json字串,又都完全是正常的業務返回資料。

太妖孽。

排查(一)

首先可以肯定的是返回資料是完全正確的,這點在日誌列印的時候就可以看到。不存在低階失誤,json不匹配返回型別這一說。

那問題很明顯了,就是fastjson的解析問題,而專案使用的fastjson的版本相對較老,為1.2.29版本。

但是問題究竟在哪,本來很簡單的錯,但是在資料和結構都完全正確的情況下偶發性的報出,就顯得很詭異了。

而且我根本就不相信在debug的時候恢復正常,在正常執行時就會有問題這種事實。

而且在接下來這個bug就像消失了一樣,無論是debug啟動還是正常啟動,都不再出現了。

看到這,肯定會有人說,這還不簡單。換個json解析框架,或是升級fastjson不就行了。

對於換框架來說,私下有和同事聊過換成jackson。首先系統內多處要改,其次即便換了,問題不再復現了。但對於問題而言,等於是繞過去了,而沒有真正意義上正面去解決。而我本身對這個bug的根源非常感興趣。所以不打算換,正面剛。

對於升級fastjson,其實有猜測過是因為fastjson的某些bug導致。但是得拿出證據,否則升級之後就算不復發,也不能證明是因為升級了fastjson而修復的,因為這個bug是極其偶發的。也就是說,還是得找到確定的根源問題。不能只依靠長時間的觀測而去證明是否修復。

終於在一個偶然的機會,我在debug中終於斷點捕捉到了一次。

這也就說明了,不存在薛定諤bug這麼一說,至少我在觀測時能捕捉到。

斷點的地方在以下這個位置(部分業務資料做了一些改動)

//json為:{"code":"00","msg":"成功","data":{"xxx":21,"yyy":5}}
//c為LuaResult.class
T resut = JSON.parseObject(json, c);

用IDEA的Evaluate工具進行了檢視執行結果

然後繼續反覆執行,大概在按幾十次回車之後,終於出現了一個報錯:

這就很詭異了有沒有,同樣的資料,同樣的程式碼。執行幾十次就出錯了。

但是問題肯定是在fastjson這邊了。接下去就是要破解這個問題的根源了。為了抓住這個原因,我還真捨不得馬上升級。

排查(二)

之前說到過呼叫的時候並沒有加泛型,於是我抱著試一試的想法,給這個呼叫加上了泛型,引數換成了TypeReference

LuaResult<Map<String,Object>> result = executeLua("xxxx", new TypeReference<LuaResult<Map<String,Object>>>(){}, args);

再去斷點,通過Evaluate工具去診斷,點了有上百次,都沒出現那個錯。

那這樣就確定應該是泛型引起的了。通過搜尋相關關鍵字,找到了一篇關於fastjson關於對於泛型解析的文章。大致意思就是:fastjson對於那些沒有定義明確泛型型別的相同物件,會預設使用上一次泛型的型別。也就是說,fastjson會對相同物件的前一次的泛型定義進行快取。

這樣,我就能大致理解這個妖孽bug的偶發原因了。

為此,我特地在本地寫了一段程式碼來模擬這個bug的產生。

大家也可以複製到本地來執行下,fastjson版本要為1.2.29。

public static void main(String... args) throws Exception {
    try {
        String json = "{\"code\":\"00\",\"msg\":\"成功\",\"data\":{\"xxx\":21,\"yyy\":5}}";
        LuaResult result = JSON.parseObject(json, LuaResult.class);
        System.out.println(result);
    }catch (Exception e){
        log.error("出錯了", e);
    }

    try {
        String json1 = "{\"msg\":\"成功\",\"data\":\"31\",\"code\":\"00\"}";
        LuaResult<Integer> result = JSON.parseObject(json1, new TypeReference<LuaResult<Integer>>(){});
        System.out.println(result);
    }catch (Exception e){
        log.error("出錯了", e);
    }

 		//上面2個沒問題,到執行第三段的時候,就會必現
    try {
        String json = "{\"code\":\"00\",\"msg\":\"成功\",\"data\":{\"xxx\":21,\"yyy\":5}}";
        LuaResult result = JSON.parseObject(json, LuaResult.class);
        System.out.println(result);
    }catch (Exception e){
        log.error("出錯了", e);
    }
}

執行後出現報錯:

有意思的是,只有三段程式碼是這個順序的時候,才出錯,把三段程式碼換個順序,又正常了。

這下是一個必現的bug了。原形畢露!

由於專案使用的fastjson是1.2.29版本,我逐個版本升級,想知道到底是哪個版本會修復這個bug。在試到1.2.33版本時,這個bug終於沒了。去github上找1.2.33這個版本的release資訊,發現了作者修復了不使用引數泛型解析錯誤的issue。

結論

所以結論就是:這個薛定諤的bug就是因為fastjson在早期的版本中存在著對泛型解析的不嚴謹bug產生的。

既然都到這個程度了,那繼續再深入研究發現,fastjson在1.2.33版本以下,對同一個物件的泛型存在著快取現象。之前如果一直執行帶泛型定義的LuaResult這是沒問題的,如果前幾個是帶泛型的,後一個執行到不帶泛型的,這就出現問題了。會按照上次快取的泛型進行解析,由於前一次的泛型是Integer,所以不管這次json是什麼資料,都會按照Integer型別去進行轉換,所以就導致了can not cast to int這個錯誤。

至於為什麼一開始,會出現類似於薛定諤的幻覺,現在也有了定論,這是因為測試同學的測試的順序。正好debug的時候,沒按照這個順序執行,而正常執行的時候,是按照這個順序執行的。我猜想這可能就是一個巧合。

知道了根源原因,修復起來只要升級到最新版本即可。

有人會覺得我繞了一大圈,直接升級就完事了。何必去究其原因。

一方面我覺得在技術上要嚴謹點,知其所以,更要知其所以然。二者我對這個如何產生的,抱有很大的興趣(執念)。所以即便升級一個版本號就能解決,也要弄清楚來龍去脈。

如果大家喜歡類似的bug尋找過程的文章,也請在留言評論告訴我,我以後多安排一些。

我是鉑賽東,一個有趣且有深度的開發,希望你關注我,在我的公號裡,會分享技術以及開源相關的內容。也會分享點生活觀。

相關文章