0. 问题
2022-07-18 07:39:30 xxoo-im-connector 业务方收到了一条宕机报警，经查实际没有宕机，而是网络出现了异常。
07:47 之后网络恢复稳定了，业务流量也正常了，但是调依赖的 MOA 服务还是有报错，仔细看错误日志发现是调用的地址不对。
2022.07.18 08:50:48.883 ERROR MoaMessageSender.lambda$sendMessage$0:94 - Failed to invoke business msg.java.lang.RuntimeException: Error code [501], error message [Error code: 501, message: Service not found: /service/xxoo-[c]-service., targetUri: moa://xx.xx.134.243:13515?timeout=2000&version=2&protocol=redis&start=1654175538&warmup=60&weight=100&zone=sg-aws&group=default].
复制代码
这是地址列表错乱了！
1. 排查
MOA 框架中打印了详细的地址变更日志，但是业务方通过 log4j 配置给屏蔽了，以此同时有一些关键的异常日志也没有了，这对根因定位造成了很大障碍。
好在还有一个 aft 的日志可以看一下地址列表的信息：
/service/im-[a]-service
本地地址列表：["xx.xx.156.11:13510","xx.xx.152.26:13511","xx.xx.150.69:13510","xx.xx.147.195:13511","xx.xx.146.162:13511","xx.xx.128.209:13511","xx.xx.153.29:13511","xx.xx.131.236:13511"]实际地址列表：["xx.xx.156.11:13510","xx.xx.150.69:13510"]
复制代码
/service/xxoo-im-[b]-service
本地地址列表：["xx.xx.146.162:13511","xx.xx.147.195:13511","xx.xx.128.209:13511","xx.xx.128.209:13511","xx.xx.156.11:13510","xx.xx.130.248:13511","xx.xx.152.26:13511","xx.xx.150.69:13510","xx.xx.141.194:13511","xx.xx.131.236:13511","xx.xx.153.29:13511"]实际地址列表：["xx.xx.146.162:13511","xx.xx.147.195:13511","xx.xx.128.209:13511","xx.xx.128.209:13511","xx.xx.130.248:13511","xx.xx.152.26:13511","xx.xx.141.194:13511","xx.xx.131.236:13511","xx.xx.153.29:13511"]
复制代码
异常的地址并不是无效的地址，也不是已下线遗留的脏信息，而是来自当前依赖的其它服务的在线地址，im-[a]-service 的地址出现在了 xxoo-im-[b]-service，同时 xxoo-im-[b]-service 的地址出现在了 im-[a]-service，也就是说两个服务的地址列表“混合”了。
这个现象很特殊。
这个服务使用的 MOA 版本较旧，是 1.10.0-alpha.1，向本地地址列表添加地址的地方有三个：
从 momokeeper 订阅的地址变更事件
地址都不可以用时，调 lookup 获取（在 2.7.2-alpha.8 版本后去掉了该逻辑）
从黑名单到中恢复之前 PING 不通的实例（在 2.4.0-alpha.1 版本后去掉了该逻辑，这里可能添加已下线的脏实例）
从维护地址列表的代码逻辑来看是不会出现上述的地址列表异常现象。由于当时网络出现了异常，难道是从外部获取的地址就错了？上述 1 和 2 是从外部获取的信息。
首先看 1 过程，使用的是 redis pub/sub 机制，从协议 message 的格式来看，每次的数据（地址列表）都有对应的 channel（服务）信息，所以这里数据错误的可能性很低，即便有未知异常也会重新建立连接，再 subscribe 相关的 channel。
// subscribe message 格式*3$7message${m}{channel}${n}{value}
复制代码
剩下的就是 2 过程了，这里是 jedis get 的标准用法：
public String get(String key) { Jedis jedis = null; try { jedis = getJedisResource(); return jedis.get(key); } catch (Exception e) { throw new RuntimeException("get(" + key + ")", e); } finally { if (jedis != null) { jedis.close(); } }}
复制代码
正常来说不会有问题，理论上是有个可能的异常场景：发送服务 A 的查询请求，响应返回了，但是由于某种异常，程序没有读取数据，而是将 Jedis 连接归还了连接池，那么再次从池中拿到该 Jedis 连接，发送服务 B 的查询请求，就有可能拿到之前的服务 A 的响应。
如果真的出现上述可能的异常场景，产生的结果就跟上述现象一致了。
但是我们使用 iptables 模拟随机丢包和端口耗尽都没有复现，排查进入了死胡同。
2. 类似问题梳理
现有的信息无法进一步排查了，我们搜索了 wiki 中类似的问题记录，发现之前 php 服务使用 phpredis 也出现过类似现象。
现象
发送 req-1 后读取 resp-1 超时
发送 req-2 后读取 resp-2 协议错误
发送 req-3 后读取 resp-3 时，实际读取到的是 resp-2
原理分析
问题的核心就是，对于异常的连接没有及时弃用关闭。 redis 协议比较简单，请求和响应没有 id 进行关联，所以一旦顺序错误就会导致数据混乱。
3. jedis 2.9.0 逻辑梳理
jedis 2.9.0 版本对于上述问题处理已经设计的挺完善了。
@Overridepublic void close() { if (dataSource != null) { if (client.isBroken()) { this.dataSource.returnBrokenResource(this); } else { this.dataSource.returnResource(this); } } else { client.close(); }}
复制代码
对于标记为 broken 的连接将会直接丢弃关闭，标记 broken 的地方都在 Connection 类中，总共有 7 处，我们跟一下 get 命令的相关处理流程：
public String get(final String key) { checkIsInMultiOrPipeline(); client.sendCommand(Protocol.Command.GET, key); return client.getBulkReply();}
复制代码
整理来看分两个子流程：发送命令和读取请求。发送命令：
protected Connection sendCommand(final Command cmd, final byte[]... args) { try { connect(); Protocol.sendCommand(outputStream, cmd, args); pipelinedCommands++; return this; } catch (JedisConnectionException ex) { /* * When client send request which formed by invalid protocol, Redis send back error message * before close connection. We try to read it to provide reason of failure. */ try { String errorMessage = Protocol.readErrorLineIfPossible(inputStream); if (errorMessage != null && errorMessage.length() > 0) { ex = new JedisConnectionException(errorMessage, ex.getCause()); } } catch (Exception e) { /* * Catch any IOException or JedisConnectionException occurred from InputStream#read and just * ignore. This approach is safe because reading error message is optional and connection * will eventually be closed. */ } // Any other exceptions related to connection? broken = true; throw ex; }}
复制代码
读取请求：
public byte[] getBinaryBulkReply() { flush(); pipelinedCommands--; return (byte[]) readProtocolWithCheckingBroken();}//...protected void flush() { try { outputStream.flush(); } catch (IOException ex) { broken = true; throw new JedisConnectionException(ex); }}//...protected Object readProtocolWithCheckingBroken() { try { return Protocol.read(inputStream); } catch (JedisConnectionException exc) { broken = true; throw exc; }}
复制代码
可见 jedis 对网络异常都做了相应的处理，可以保障异常的连接不会重用，造成不确定的后果。
4. 可能的问题分析与模拟
jedis 基本把所有网络异常的情况都处理了，但是在实际使用中 catch 的异常范围可能有点儿小，比如说在某些位置抛出 Error，很可能会影响 broken 这个关键字段的标记。
例如我们魔改一下源码，抛出一个 StackOverflowError:
public byte[] getBinaryBulkReply() { flush(); pipelinedCommands--; //------------------ // 模拟调 readProtocolWithCheckingBroken 栈溢出 i++; if (i == 1) { throw new StackOverflowError("mock error"); } //----------------- return (byte[]) readProtocolWithCheckingBroken();}
复制代码
这样就很容易模拟出数据错乱的现象，但是实际要触发的条件很苛刻，这只是分析一种可能性。
为了防止类似的情况发生，我们在 Jedis 外部将异常的处理范畴扩大到了 Throwable：
public String get(String key) { Jedis jedis = null; boolean isBroken = false; try { jedis = getJedisResource(); return jedis.get(key); } catch (Exception e) { throw new RuntimeException("get(" + key + ")", e); } catch (Throwable t) { isBroken = true; // 处理 JVM Error 的情况 throw t; } finally { if (jedis != null) { if (isBroken) { jedisPool.returnBrokenResource(jedis); } else { jedis.close(); } } }}
复制代码
5. 总结
xxoo-im-connector 业务的问题由于缺失关键日志可能无法提供决定性的证据，但是根据现象我们对各种可能性进行了推断分析，最终定位可能是 Jedis 对异常处理不完善导致的。
最后在总结一下，由于 redis 协议比较简单，在协议层面没有设计唯一的 id 来关联请求和响应，所以请求和响应的关联完全依赖“顺序”，对于连接和处理逻辑正常的情况下，根据“顺序”关联是没有问题的，但是一旦出现异常情况，“顺序”就无法保证了，对于应用层面就会出现请求和响应错乱的情况。
Jedis 自身设计已经很完善，但是主要处理的是网络异常的情况，也就是对于网络异常的连接进行了弃用关闭，但是对于 JVM 异常 并没有做很完善的处理，在处理流程中抛出的 Error 等可能会影响请求和响应的关联。但是要求 Jedis 库中处理 Error 可能也不太合适（对于一些不好处理的 Error，实际上进程 crash 可能是最好的选择），所以这里没有给 Jedis 提 issue，主要还是在使用的时候进行处理，如果捕获到 Error 那么强制弃用关闭当前的连接。
评论