解Bug之路-串包Bug
阿新 • • 發佈:2020-09-14
# 解Bug之路-串包Bug
筆者很熱衷於解決Bug,同時比較擅長(網路/協議)部分,所以經常被喚去解決一些網路IO方面的Bug。現在就挑一個案例出來,寫出分析思路,以饗讀者,希望讀者在以後的工作中能夠少踩點坑。
# 串包Bug現場
## 前置故障Redis超時
由於某個系統大量的hget、hset操作將Redis拖垮,通過監控發現Redis的CPU和IO有大量的尖刺,CPU示意圖下圖所示:
![輸入圖片說明](https://static.oschina.net/uploads/img/201704/27101220_ckSF.png "在這裡輸入圖片標題")
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,當時監控示意圖:
![輸入圖片說明](https://static.oschina.net/uploads/img/201704/27101242_UZNd.png "在這裡輸入圖片標題")
當重啟後,我們再去線上觀察的時候,發現錯誤依然存在,神奇的是,這種錯誤發生的頻率會隨著時間的增加而遞減。到最後刷個10分鐘頁面才會出現這種錯,示意圖如下所示:
![輸入圖片說明](https://static.oschina.net/uploads/img/201704/27101304_KtWN.png "在這裡輸入圖片標題")
既然如此,那隻能祭出重啟大法,把出錯的業務系統全部重啟了一遍。
重啟之後,線上恢復正常,一切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,上述原始碼的過程示意圖如下:
![輸入圖片說明](https://static.oschina.net/uploads/img/201704/27101351_ATMc.png "在這裡輸入圖片標題")
#### 出錯的業務系統的redis互動
![輸入圖片說明](https://static.oschina.net/uploads/img/201704/27101403_xhqa.png "在這裡輸入圖片標題")
由於Redis本身在高負載狀態,導致沒能及時相應command請求,從而導致readTimeOut異常。
#### 複用這個出錯連結導致出錯
在Redis響應了上一個command後,把資料傳到了對應command的socket,進而被inputream給buffer起來。而這個command由於超時失敗了。
![輸入圖片說明](https://static.oschina.net/uploads/img/201704/27101418_6WKS.png "在這裡輸入圖片標題")
這樣,inputStream裡面就有個上個命令留下來的資料。
下一次業務操作在此拿到這個連線的時候,就會出現下面的情況。
![輸入圖片說明](https://static.oschina.net/uploads/img/201704/27101434_7uCm.png "在這裡輸入圖片標題")
再下面的命令get user789Key會拿到get user456Key的結果,依次類推,則出現串包的現象。
#### 串包過程圖
![輸入圖片說明](https://static.oschina.net/uploads/img/201704/27104801_Zv4G.png "在這裡輸入圖片標題")
上圖中相同顏色的矩形對應的資料是一致的。但是由於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之類的手段把收發狀態重新調整為一致也是可以的,這無疑增加了很高的複雜度。所以廢棄連線重建是最簡單有效的方法。
## 公眾號
關注筆者公眾號,獲取更多幹貨文章:
![](https://oscimg.oschina.net/oscnet/up-03e8bdd592b3eb9dec0a50fa5ff56192df0.JPEG)