解Bug之路-串包Bug
筆者很熱衷于解決Bug,同時比較擅長(網絡/協定)部分，是以經常被喚去解決一些網絡IO方面的Bug。現在就挑一個案例出來，寫出分析思路，以飨讀者，希望讀者在以後的工作中能夠少踩點坑。
串包Bug現場
前置故障Redis逾時
由于某個系統大量的hget、hset操作将Redis拖垮，通過監控發現Redis的CPU和IO有大量的尖刺,CPU示意圖下圖所示:
CPU達到了100%,導緻很多Redis請求處理不及時，其它業務系統都頻繁爆出readTimeOut。此時，緊急将這個做大量hget、hset的系統kill,過了一段時間，Redis的CPU恢複平穩。
一波未平，一波又起
就在我們以為事件平息的時候，線上爆出登入後的使用者名稱不正确。同時錯誤日志裡面也有大量的Redis傳回不正确的報錯。尤為奇葩的是，系統擷取一個已經存在的key,例如get User123456Name,傳回的竟然是redis的成功傳回OK。示意圖如下:
Jedis.sendCommand:get User123456Name
Jedis.return:OK
or
Jedis.sendCommand:get User123456Name
Jedis.return:user789 我們發現此情況時，聯系op将Redis叢集的所有Key緊急delete,當時監控示意圖:
當重新開機後，我們再去線上觀察的時候，發現錯誤依然存在，神奇的是，這種錯誤發生的頻率會随着時間的增加而遞減。到最後刷個10分鐘頁面才會出現這種錯,示意圖如下所示:
既然如此，那隻能祭出重新開機大法，把出錯的業務系統全部重新開機了一遍。
重新開機之後，線上恢複正常，一切Okay。
Bug複盤
此次Bug是由Redis本身Server負載太高逾時引起的。Bug的現象是通過Jedis去取對應的Key值，得不到預期的結果，簡而言之包亂了，串包了。
縮小Bug範圍
首先:Redis是全球久經考驗的系統，這樣的串包不應該是Redis的問題。
第二:Redis重新整理了key後Bug依然存在，而業務系統重新開機了之後Okay。
第三:筆者在錯誤日志中發現一個現象，A系統隻可能列印出屬于A系統的json串結構(redis存的是json)。
很明顯，是業務系統的問題，如果是Redis本身的問題，那麼在很大機率上A系統會接收到B系統的json串結構。
業務系統問題定位
業務系統用的是Jedis,這同樣也是一個久經考驗的庫，出現此問題的可能性不大。那麼問題肯定是出在運用Jedis的姿勢上。
于是筆者找到了下面一段代碼:
public Object invoke(Object proxy,Method method,Object[] args) throws Throwable{
JedisClient jedisClient = jedisPool.getResource();
try{
return method.invoke(jedisClient,args);
} catch(Exception e){
logger.error("invoke redis error",e);
throw e;
}finally {
if(jedisClient != null){
// 問題處在下面這句
jedisPool.returnResource(jedisClient);
}
}
} 當時我就覺得很奇怪，筆者自己寫的，閱讀過的連接配接池的代碼都沒有将抛異常的連接配接放回池裡。就以Druid為例，如果是網絡IO等fatal級别的異常，直接抛棄連接配接。這裡把jedisClient連接配接傳回去感覺就是出問題的關鍵。
Bug推理
筆者意識到，之是以串包可能是由于jedisClient裡面可能有殘餘的資料，導緻讀取的時候讀取到此資料，進而造成串包的現象。
串包原因
正常情況下的redis互動
先上Jedis源碼
public String get(final String key) {
checkIsInMulti();
client.sendCommand(Protocol.Command.GET, key);
return client.getBulkReply();
} Jedis本身用的是Bio,上述源碼的過程示意圖如下:
出錯的業務系統的redis互動
由于Redis本身在高負載狀态，導緻沒能及時相應command請求，進而導緻readTimeOut異常。
複用這個出錯連結導緻出錯
在Redis響應了上一個command後，把資料傳到了對應command的socket，進而被inputream給buffer起來。而這個command由于逾時失敗了。
這樣，inputStream裡面就有個上個指令留下來的資料。
下一次業務操作在此拿到這個連接配接的時候，就會出現下面的情況。
再下面的指令get user789Key會拿到get user456Key的結果，依次類推，則出現串包的現象。
串包過程圖
上圖中相同顔色的矩形對應的資料是一緻的。但是由于Redis逾時，導緻資料串了。
為什麼get操作傳回OK
上圖很明顯的解釋了為什麼一個get操作會傳回OK的現象。因為其上一個操作是set操作，它傳回的OK被get操作讀取到，于是就有了這種現象。
為什麼會随着時間的收斂而頻率降低
因為在調用Redis出錯後，業務系統有一層攔截器會攔截到業務層的出錯，同時給這個JedisClient的錯誤個數+1,當錯誤個數>3的時候，會将其從池中踢掉。這樣這種串了的連接配接會越來越少，導緻Bug原來越難以出現。
在每次調用之前清理下inputstream可行否
不行，因為Redis可能在你清理inputstream後，你下次讀取前把資料給傳回來。
怎麼避免這種現象?
抛出這種IO異常的連接配接直接給扔掉，不要放到池子裡面。
怎麼從協定層面避免這種現象
對每次發送的指令都加一個随機的packetId,然後結果傳回回來的時候将這個packetId帶回來。在用戶端每次接收到資料的時候，擷取包中的packetId和之前發出的packetId相比較,如下代碼所示:
if(oldPacketId != packetIdFromData){
throw new RuntimeException("串包");
} 總結
至少在筆者遇到的場景中，出現IO異常的連接配接都必須被抛掉廢棄，因為你永遠不知道在你複用的那一刻，socket或者inputstream的buffer中到底有沒有上一次指令遺留的資料。
當然如果刻意的去構造協定，能夠通過packetId之類的手段把收發狀态重新調整為一緻也是可以的,這無疑增加了很高的複雜度。是以廢棄連接配接重建是最簡單有效的方法。
公衆号
關注筆者公衆号，擷取更多幹貨文章: