前言

在開始這篇文章之前想先說一句：如果一套系統暫時沒問題，那只是因為它的并發量不夠而已。

上周在查看系統日志時，發現了一條與眾不同的日志。日志中有一半內容是正常的報文數據，而另一半內容是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(recvLen == -1){
    break;
   }
   // 改造點2
   recvLen += currentLen;
  }
  System.out.println(new String(body, "GBK"));
}

上述改造只改動了兩處，將read方法的返回值用新變量接收，然后讓recvLen每次累加read讀取的字節數。

改造是不是非常簡單?正應了那句話：改bug很容易，難的是如何找到bug。

小結

有時候我們對自己寫的代碼很自信，有時候總以為代碼之前能夠正常運行，以后也能夠正常運行。但往往事與愿違，誰能想到一直“運行良好”的代碼中深藏著這樣的Bug?所以，還是那句話，如果你覺得你的代碼沒問題，那只是因為系統的并發量還不夠而已。代碼不僅要實現功能，還要滿足性能和健壯性。