解 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。示意圖如下:

我們發現此情況時,聯繫 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 的姿勢上。
於是筆者找到了下面一段代碼:

當時我就覺得很奇怪,筆者自己寫的,閱讀過的連接池的代碼都沒有將拋異常的連接放回池裏。就以 Druid 爲例,如果是網絡 IO 等 fatal 級別的異常,直接拋棄連接。這裏把 jedisClient 連接返回去感覺就是出問題的關鍵。

Bug 推理

筆者意識到,之所以串包可能是由於 jedisClient 裏面可能有殘餘的數據,導致讀取的時候讀取到此數據,從而造成串包的現象。

串包原因

正常情況下的 redis 交互

先上 Jedis 源碼

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 相比較, 如下代碼所示:

總結

至少在筆者遇到的場景中,出現 IO 異常的連接都必須被拋掉廢棄,因爲你永遠不知道在你複用的那一刻,socket 或者 inputstream 的 buffer 中到底有沒有上一次命令遺留的數據。
當然如果刻意的去構造協議,能夠通過 packetId 之類的手段把收發狀態重新調整爲一致也是可以的, 這無疑增加了很高的複雜度。所以廢棄連接重建是最簡單有效的方法。

本文由 Readfog 進行 AMP 轉碼,版權歸原作者所有。
來源https://mp.weixin.qq.com/s/Td-3EzHQBes9bgxZOebAEg