在開始這篇文章之前想先說一句:如果一套系統暫時沒問題,那只是因為它的并發量不夠而已。
上周在查看系統日志時,發現了一條與眾不同的日志。日志中有一半內容是正常的報文數據,而另一半內容是0x00這樣的空數據。
雖然系統沒拋出任何異常,但這些日志肯定是反常的。多年的經驗告訴我,這其中一定有什么不對的地方,加上好奇心的驅使,終于揭開了一個隱藏非常深的Bug。
有時候找到Bug,解決Bug很容易,難的是如何發現Bug,并推理出哪里出問題解決。下面就帶大家來剖析一下這個Bug。
奇怪的日志輸出
一個調用外部接口的基礎類,打印出類似如下的日志:
abcdabcdabcdabcdabcdabcdabcd《0x00》《0x00》《0x00》《0x00》《0x00》
其中前面的abcd是正常的業務數據,后面莫名其妙的多出了很多《0x00》。
那么,這個基礎工具類有多基礎?多處使用該方法,每天大約被調用幾十萬次吧,而上面的情況一天只會出現幾次。就是那么巧,恰好被看到了。
查看代碼,初步推斷,可能是byte數組轉String時,byte數組后半部分為空或存在一些無法轉換的數據導致的。
舊代碼分析
這里先把業務代碼脫敏,寫成一個demo展示給大家看看:
public static void oldCode() throws IOException
{
// 通過HttpURLConnection讀取的外部系統返回的流
InputStream in = new ByteArrayInputStream(“abc”.getBytes());
// 明確知道的報文長度(解析Header獲得)
int bodyLen = 2048;
byte[] body = new byte[bodyLen];
int recvLen = 0; while (recvLen 《 bodyLen)
{
recvLen = in.read(body, recvLen, bodyLen - recvLen);
if(recvLen == -1){
break;
}
}
System.out.println(new String(body, “GBK”));}
上述代碼進行了業務脫敏處理,僅為還原基本的使用過程。
業務場景的大概使用流程是:第一,通過HTTP調用遠程接口;第二,讀取接口返回的字節流,Inputstream;第三,解析字節流,存入字節數組;第四,將字節數組轉換為String。
而日志中看到的異常內容,便是打印String時出現的。前面我們已經推斷,出現《0x00》的可能性是字節數組有一部分為空導致或數據錯誤導致的。
上述代碼有一個明顯的錯誤,你是否能夠看出來?根據代碼原始的寫法,推測之所以出現這個錯誤是因為使用者對InputStream的read方法并不熟悉導致的。
這里讀者先自行閱讀看看上述代碼的Bug在哪里,下面我們來介紹一下InputStream的read方法。
InputStream的read方法
InputStream這個抽象類是表示字節輸入流的所有類的超類,它提供了3個經常被使用的read()方法:
read(),無參方法。該方法從輸入流中讀取數據的下一個字節。返回0到255范圍內的int字節值。如果因為已經到達流末尾而沒有可用的字節,則返回值 -1 。該方法會處于阻塞狀態,等待數據的到達,直到返回值為-1或拋出異常。
read(byte b[], int off, int len):將輸入流中最多len個數據字節讀入byte數組。嘗試讀取len個字節,但讀取的字節也可能小于該值。以整數形式返回實際讀取的字節數。
read (byte[] b):從輸入流中讀取一定數量的字節,并將其存儲在緩沖區數組b中。以整數形式返回實際讀取的字節數。
分析一下上面的三個方法。
其中第一個方法,本質上來說后兩個方法都是調用第一個方法來實現的,但第一個方法直接使用缺點很明顯,就是處理效率低下,一個字節一個字節的讀。而后兩個方法都加入了byte數組,用來作為緩存區。
而第三個方法又相當于第二個方法被如下方式調用:
read(b, 0, b.length)
而有Bug的代碼中使用的是第二個方法。
Bug分析
看了read方法的API說明,你是不是已經找到Bug了?對的,當初寫這段代碼的人把read方法返回值理解錯了。
recvLen = in.read(body, recvLen, bodyLen - recvLen);
最初寫代碼的人可能把read方法的返回值當中參數off經過讀取之后新的位置了。這樣在調用read方法之后,獲得了填充的位置,然后拿總長度減去已經填充的位置,再繼續讀取后面的內容,繼續填充。
但實際上read方法的返回結果是:以整數形式返回實際讀取的字節數,可能與off的位置值相同,但并不是off的位置。
下面來分析一下while循環中的邏輯處理情況:
while (recvLen 《 bodyLen)
{
recvLen = in.read(body, recvLen,
bodyLen - recvLen);
if(recvLen == -1){
break;
}}
我們舉個例子來推演一下2種情況(為了方便推算,暫且用比較小的數來舉例)。
情況一:假設bodyLen長度為10,read一次性讀完。
在這種情況中,先進入while循環,read一次性讀完,返回值為10,此時recvLen賦值為10,不再滿足循環條件(recvLen 《 bodyLen),退出循環,繼續執行。此時,代碼沒問題。這種情況可能占到99.9%-99.99%(取決于請求頻次和報文大?。?。
情況二:假設bodyLen長度為10,read 2次讀完(發生粘包拆包現象)。
第一次循環,read讀取6個字節長度,返回值為6,recvLen賦值為6。第二次循環,off參數取recvLen的值為6,讀取剩余4個字節(10 - 6)。完成第二次讀取,循環本應該結束的,但你會發現此時recvLen被賦值為4,依舊滿足while循環的判斷條件(recvLen 《 bodyLen),進行下一輪讀取。
下一輪讀取時,off變為4,len變為(10 - 4)。本來經過第二輪循環off已經讀取到10了,現在又指定為4,又去流中讀取。這就造成了日志中出現很多《0x00》。
Bug原因
經過上述分析,我們已經找到Bug,并獲得了Bug原因。
首先,Bug之所以沒有大面積爆發,那是因為大多數請求都是一次性讀完流中的數據,循環直接結束,當不會進入第二次循環時,這個Bug就被隱藏了。
其次,Bug之所以發生除了使用者對API的返回值不了解,更重要的原因是對于read方法可能會將結果分多次返回(粘包拆包現象)不了解。
Bug改造
找到原因,改造起來就非常容易了。針對demo我們重新改造一下:
public static void oldCode()
throws IOException
{
// 通過HttpURLConnection讀取的外部系統返回的流
InputStream in = new ByteArrayInputStream(“abc”.getBytes());
// 明確知道的報文長度(解析Header獲得)
int bodyLen = “abc”.getBytes().length;
System.out.println(bodyLen);
byte[] body = new byte[6];
int recvLen = 0; while (recvLen 《 bodyLen)
{
// 改造點1
int currentLen = in.read(body, recvLen, bodyLen - recvLen);
if(currentLen == -1){
break;
}
// 改造點2
recvLen += currentLen;
}
System.out.println(new String(body, “GBK”));}
上述改造只改動了兩處,將read方法的返回值用新變量接收,然后讓recvLen每次累加read讀取的字節數。
改造是不是非常簡單?正應了那句話:改bug很容易,難的是如何找到bug。
小結
有時候我們對自己寫的代碼很自信,有時候總以為代碼之前能夠正常運行,以后也能夠正常運行。但往往事與愿違,誰能想到一直“運行良好”的代碼中深藏著這樣的Bug?所以,還是那句話,如果你覺得你的代碼沒問題,那只是因為系統的并發量還不夠而已。代碼不僅要實現功能,還要滿足性能和健壯性。
審核編輯 :李倩
-
數組
+關注
關注
1文章
416瀏覽量
25912 -
BUG
+關注
關注
0文章
155瀏覽量
15653
原文標題:捕獲了一只發生概率小于萬分之一的Bug
文章出處:【微信號:coder_life,微信公眾號:程序人生】歡迎添加關注!文章轉載請注明出處。
發布評論請先 登錄
相關推薦
評論