Redis线上问题后续真正的原因

转载:https://www.cnblogs.com/devilwind/p/6865750.html
一、问题现象

redis服务端的sentinel模块存在大量的established状态的连接，并且这些连接一直不被释放，而客户端的连接数正常。

二、问题排查过程

1、根据连接状态进行推断

服务端存在大量的连接的状态为established，而客户端连接数正常，这说明客户端连接是被非正常的方式关闭的，因为根据TCP关闭连接的四次握手协议来看，只要客户端正常发起了关闭动作，服务端的状态只可能为CLOSE_WAIT/LAST_ACK/CLOSED中的一种。
非正常关闭连接的情况有断电、断网后服务器重启等等，但这些场景出现的次数较少，不会造成这么多连接，究竟是怎样被正常关闭，到这一步还无法判断，只能先从其它方面入手。

2、检查业务系统的redis配置和程序逻辑

检查redis配置，看是否有不规范的配置和不规范的使用redis的代码，经过排查，确定openapi有直接使用JedisSentinelPool类，但并未在spring中配置destroy-method=”destroy”，即在停止应用时释放连接。
排查其它系统，未发现有不正常使用redis的情况，JedisSentinelPool造成的连接数增长也是有限的，即只在启动时才创建sentinel连接，此处暂时排查是业务代码使用redis不规范的问题。

3、从网络寻找线索

通过百度搜索，找不到关于sentinel的该问题的文章。
查看redis、jedis、spring-data-redis官方网站的issues及releaseNotes，均未发现有提及该问题。

4、重新思考产生连接的根源

通过阅读jedis源码，发现连接sentinel的代码只有1处，即系统启动时会先建立一个短连接查询sentinel的主节点，然后开启3(业务系统配置了3个地址)个线程创建3个长连接与3个sentinel相连。短连接会立即释放，而长连接的创建放在循环中，问题可能出现在该处，以下是源码：

public void run() {
      running.set(true);
      while (running.get()) {
        j = new Jedis(host, port);
        try {
          j.subscribe(new JedisPubSub() {
            @Override
            public void onMessage(String channel, String message) {
              log.fine("Sentinel " + host + ":" + port + " published: " + message + ".");
              String[] switchMasterMsg = message.split(" ");
              if (switchMasterMsg.length > 3) {
                if (masterName.equals(switchMasterMsg[0])) {
                  initPool(toHostAndPort(Arrays.asList(switchMasterMsg[3], switchMasterMsg[4])));
                } else {
                  log.fine("Ignoring message on +switch-master for master name "
                     + switchMasterMsg[0] + ", our master name is " + masterName);
                }
              } else {
                log.severe("Invalid message received on Sentinel " + host + ":" + port
                    + " on channel +switch-master: " + message);
              }
            }
          }, "+switch-master");
        } catch (JedisConnectionException e) {
          if (running.get()) {
            log.severe("Lost connection to Sentinel at " + host + ":" + port
                + ". Sleeping 5000ms and retrying.");
            try {
              Thread.sleep(subscribeRetryWaitTimeMillis);
            } catch (InterruptedException e1) {
              e1.printStackTrace();
            }
          } else {
            log.fine("Unsubscribing from Sentinel at " + host + ":" + port);
          }
        }
      }
    }

正常情况下 j.subscribe会产生阻塞，而出现异常时会重新创建连接并且打印日志“Lost connection to Sentinel at……”

在业务系统搜索“Lost connection to Sentinel at”日志，把所有业务日志都搜索一遍，没有找到该日志，最后终于在nohub日志中找到了(nohub日志在weblogic启动时会被清理，也导致找了几次才找到该日志)，通过UltraEdit提取所有该内容的日志，发现了28条日志，将这些日志导出到excel比较，发现日志出现的时间间隔均为2小时11分15秒到2小时11分20秒左右，该日志出现的时间间隔非常有规律，这种规律一定与该问题存在某种联系。

一般在系统中设置时间间隔都会是个整数，2小时11分15秒显得有点怪异，然后将时间换算成秒，看是否为一个常用的或有规律的整数，2小时=7200秒，突然想到操作系统的keepalive设置中有一个7200秒，查一下操作系统默认的设置，参数如下：

net.ipv4.tcp_keepalive_time = 7200 默认 tcp空闲时间

net.ipv4.tcp_keepalive_intvl =75 默认心跳检测时间间隔

net.ipv4.tcp_keepalive_probes = 9 默认检测次数

如果完成9次心跳，仍然发现连接无效的时间为：7200+9*75=2小时11分15秒，由此，基本上可以判断，客户端的连接是被操作系统回收的，结合前面的分析，连接被回收时并未向服务端发送关闭的报文。

通过在网络上搜索，长连接被阻断的原因，看到了防火墙的字样，进一步了解，发现防火墙基本上都有该项功能，即给长连接设置默认的超时时间。

5、与运维进行沟通防火墙问题

刚开始问运行同事A时，同事A说防火墙用的是juniper，但绝对没有为长连接设置默认的超时时间。
进一步搜索juniper的资料，确定是有默认30分钟的超时时间。
与运维同事B沟通，确认有默认的超时时间。防火墙的策略是，当建立连接时，会在防火墙保存一条会话信息，记录了源IP、源端口、目的IP、目的端口。当在超时时间内，该会话代表的连接未有任何数据包时，就会清除该会话，此后若再有数据包过来，由于没有了会话，防火墙会直接丢弃该会话。
要同事B将sentinel的端口26379配置一条永不超时的策略。

6、持续观察测试环境的日志

发现在更改了防火墙超时策略后，仍然出现了一条“Lost connection to Sentinel at”日志，此后一直未出现，由此可见，防火墙确实对连接造成了影响。

7、初步结论

防火墙每30分钟将该连接的会话信息清除，从而导致客户端操作系统检测到心跳失败，随后操作系统清除了客户端连接，使得客户端的连接数能正常释放，由于报文被防火墙丢弃，close信息也不会到达服务端，导致服务端的连接未被及时关闭。

8、继续思考服务断连接不被释放的问题

按道理连接被防火墙阻断后，既然客户端的操作系统能正常回收连接，服务端应该也可以，但服务端的keepalive机制为什么没有发生作用？通过进一步阅读redis客户端-jedis的源码，发现jedis默认开启了keepalive，继续阅读redis的源码，发现redis默认关闭了keepalive，到此所有疑问已经解决。

以上因素使得防火墙每30分钟将该连接的会话信息清除，从而导致客户端操作系统检测到心跳失败，随后操作系统清除了客户端连接，使得客户端的连接数能正常释放，随后客户端的jedis收到异常后重新创建连接，而服务端的keepalive并未执行，以上过程不断循环，导致服务端established状态的连接不断增加并得不到释放。