解 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 之类的手段把收发状态重新调整为一致也是可以的,这无疑增加了很高的复杂度。所以废弃连接重建是最简单有效的方法。

公众号

关注笔者公众号，获取更多干货文章: