来源 | 程序新视界（ID：ershixiong_see_world）
在开始这篇文章之前想先说一句：
如果一套系统暂时没问题，那只是因为它的并发量不够而已。
上周在查看系统日志时，发现了一条与众不同的日志。
日志中有一半内容是正常的报文数据，而另一半内容是0x00这样的空数据。
虽然系统没抛出任何异常，但这些日志肯定是反常的。
多年的经验告诉我，这其中一定有什么不对的地方，加上好奇心的驱使，终于揭开了一个隐藏非常深的Bug。
有时候找到Bug，解决Bug很容易，难的是如何发现Bug，并推理出哪里出问题解决。
下面就带大家来剖析一下这个Bug。
奇怪的日志输出
一个调用外部接口的基础类，打印出类似如下的日志：
abcdabcdabcdabcdabcdabcdabcd<0x00><0x00><0x00><0x00><0x00>
其中前面的abcd是正常的业务数据，后面莫名其妙的多出了很多
<0x00>
。
那么，这个基础工具类有多基础？
多处使用该方法，每天大约被调用几十万次吧，而上面的情况一天只会出现几次。
就是那么巧，恰好被看到了。
查看代码，初步推断，可能是byte数组转String时，byte数组后半部分为空或存在一些无法转换的数据导致的。
旧代码分析
这里先把业务代码脱敏，写成一个demo展示给大家看看：
public static void oldCode() throws IOException { InputStream in = new ByteArrayInputStream("abc".getBytes()); 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 { InputStream in = new ByteArrayInputStream("abc".getBytes()); int bodyLen = "abc".getBytes().length; System.out.println(bodyLen); byte[] body = new byte[6]; int recvLen = 0; while (recvLen < bodyLen) { int currentLen = in.read(body, recvLen, bodyLen - recvLen); if(currentLen == -1){ break; } recvLen += currentLen; } System.out.println(new String(body, "GBK"));}
上述改造只改动了两处，将read方法的返回值用新变量接收，然后让recvLen每次累加read读取的字节数。
改造是不是非常简单？
正应了那句话：
改bug很容易，难的是如何找到bug。
小结
