解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 User123456NameJedis.return:OK
	orJedis.sendCommand:get User123456NameJedis.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之類的手段把收發狀態從新調整爲一致也是能夠的,這無疑增長了很高的複雜度。因此廢棄鏈接重建是最簡單有效的方法。