Java编程中如何精准定位bug？

前言在开始这篇文章之前想先说一句如果一套系统暂时没问题那只是因为它的并发量不够而已。上周在查看系统日志时发现了一条与众不同的日志。日志中有一半内容是正常的报文数据而另一半内容是0x00这样的空数据。虽然系统没抛出任何异常但这些日志肯定是反常的。多年的经验告诉我这其中一定有什么不对的地方加上好奇心的驱使终于揭开了一个隐藏非常深的Bug。有时候找到Bug解决Bug很容易难的是如何发现Bug并推理出哪里出问题解决。下面就带大家来剖析一下这个Bug。奇怪的日志输出一个调用外部接口的基础类打印出类似如下的日志abcdabcdabcdabcdabcdabcdabcd0x000x000x000x000x00其中前面的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长度为10read一次性读完。在这种情况中先进入while循环read一次性读完返回值为10此时recvLen赋值为10不再满足循环条件recvLen bodyLen退出循环继续执行。此时代码没问题。这种情况可能占到99.9%-99.99%取决于请求频次和报文大小。情况二假设bodyLen长度为10read 2次读完发生粘包拆包现象。第一次循环read读取6个字节长度返回值为6recvLen赋值为6。第二次循环off参数取recvLen的值为6读取剩余4个字节10 - 6。完成第二次读取循环本应该结束的但你会发现此时recvLen被赋值为4依旧满足while循环的判断条件recvLen bodyLen进行下一轮读取。下一轮读取时off变为4len变为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所以还是那句话如果你觉得你的代码没问题那只是因为系统的并发量还不够而已。代码不仅要实现功能还要满足性能和健壮性。