【发现问题】
2019年3月20日某个项目组报告称A机房的应用日志，每隔一段时间报出一次丢失Sentinel连接的异常。
[00:38:55.256] {Thread-11}Lost connection to Sentinel at xx.xx.xx.40:26379. Sleeping 5000ms and retrying.
[00:38:55.256] {Thread-12}Lost connection to Sentinel at xx.xx.xx.39:26379. Sleeping 5000ms and retrying.
[00:38:55.256] {Thread-10}Lost connection to Sentinel at xx.xx.xx.41:26379. Sleeping 5000ms and retrying.
。。。。。。
[02:50:32.344] {Thread-11}Lost connection to Sentinel at xx.xx.xx.40:26379. Sleeping 5000ms and retrying.
[02:50:32.344] {Thread-10}Lost connection to Sentinel at xx.xx.xx.41:26379. Sleeping 5000ms and retrying.
[02:50:32.345] {Thread-12}Lost connection to Sentinel at xx.xx.xx.39:26379. Sleeping 5000ms and retrying.
。。。。。。
[05:02:09.432] {Thread-12}Lost connection to Sentinel at xx.xx.xx.39:26379. Sleeping 5000ms and retrying.
[05:02:09.432] {Thread-11}Lost connection to Sentinel at xx.xx.xx.40:26379. Sleeping 5000ms and retrying.
[05:02:09.432] {Thread-10}Lost connection to Sentinel at xx.xx.xx.41:26379. Sleeping 5000ms and retrying.
。。。。。。
【分析问题】
Sentinel是redis的监察节点，三个IP地址正是A机房redis的一套Sentinel地址。该项目组刚接入kafka并启用了自研的托管offset到redis的功能，所以会出现跟redis的连接。
查询该异常可知客户端跟Sentinel的连接属于长连接，结合两次异常之间的间隔都是2小时11分27秒，联想到linux的默认keepalive为7500即2小时，猜测长连接已被意外断开，在每2小时的keepalive时检查到连接不可达所以抛出异常。
登录A机房Sentinel所在机器，查询26379端口的连接情况如下，共有980个客户端连接，且都处于ESTABLISHED状态，而且客户端几乎都落在xx.xx.xx.149，xx.xx.xx.150，xx.xx.xx.153上。
netstat -anp | grep 26379
tcp 0 0 xx.xx.xx.39:26379 xx.xx.xx.153:47914 ESTABLISHED 9752/./src/redis-se
tcp 0 0 xx.xx.xx.39:26379 xx.xx.xx.150:55064 ESTABLISHED 9752/./src/redis-se
tcp 0 0 xx.xx.xx.39:26379 xx.xx.xx.153:59528 ESTABLISHED 9752/./src/redis-se
tcp 0 0 xx.xx.xx.39:26379 xx.xx.xx.150:48246 ESTABLISHED 9752/./src/redis-se
tcp 0 0 xx.xx.xx.39:26379 xx.xx.xx.150:43686 ESTABLISHED 9752/./src/redis-se
tcp 0 0 xx.xx.xx.39:26379 xx.xx.xx.150:55588 ESTABLISHED 9752/./src/redis-se
tcp 0 0 xx.xx.xx.39:26379 xx.xx.xx.153:58350 ESTABLISHED 9752/./src/redis-se
tcp 0 0 xx.xx.xx.39:26379 xx.xx.xx.150:59076 ESTABLISHED 9752/./src/redis-se
。。。。。。
登录客户端所在机器xx.xx.xx.149，查询26379端口的连接情况如下，只有3个Sentinel的一套连接。
netstat -anp | grep 26379
tcp 0 0 xx.xx.xx.149:53610 xx.xx.xx.39:26379 ESTABLISHED 28548/java
tcp 0 0 xx.xx.xx.149:42184 xx.xx.xx.40:26379 ESTABLISHED 28548/java
tcp 0 0 xx.xx.xx.149:53520 xx.xx.xx.41:26379 ESTABLISHED 28548/java
经运维查询证实客户端机器xx.xx.xx.149的keepalive为7500， probes为9， intvl为75，即在 7500 + 75 * 9 = 2小时11分15秒时能探知连接不可达并多次尝试后决定连接失效然后清理，这和日志表达出来的连接失效的间隔时间几乎一致。
【初步结论】
所以可以断定长连接被意外断开后，客户端已通过keepalive清理掉失效长连接，并重建新的一轮长连接。但服务端无感知，保持失效长连接处于ESTABLISHED状态。
接下来要查找长连接被意外断开的原因，登录另一个机房B的Sentinel所在机器查询26379端口的连接情况，总共只有130个客户端连接，说明A机房的redis长连接断开是个例。这里的reids处于xx.xx.19网段，客户端处于xx.xx.32网段，所以我们猜测redis长连接被断开同样是因为A机房子网间的网关防火墙造成。
经运维查询证实，xx.xx.19网段和xx.xx.32网段之间的防火墙，设置有限定超时时间1小时，任何连接在1小时内没有任意的数据报文通过，即会被防火墙断开。客户端该业务使用频次较低，很可能几个小时没有请求，而客户端的keepalive使用的是默认值2小时，超过了防火墙设置的1小时。
所以每1小时防火墙发现没有报文通过就断开连接，客户端和服务端此时都无感知。每2小时客户端的keepalive发送心跳包时，探知到连接不可用所以就抛出异常。
【思考】
1）为什么能够确定客户端发现连接不可用抛出异常后，重建了新的一轮连接？
通过源码得知，catch异常打印丢失连接的日志后，方法并没有退出，而是在while循环里重头再来，新建Jedis发起长连接订阅“switch-master”事件。
从现象上来看，客户端间隔性的打印丢失连接的日志后，登录客户端所在机器xx.xx.xx.149，查询26379端口，依然能看到一整套Sentinel的连接，也能轻易的判断出这一点。
图片.png
2）为什么服务端redis没有清理无效的长连接？
# A reasonable value for this option is 60 seconds.
tcp-keepalive 0
因为redis默认没有开启keepalive，所以防火墙断开连接后，客户端通过keepalive检测清理失效连接并进行重建，服务端没有做出任何措施所以会造成连接堆积。
【解决问题】
有三种思路可以解决这个问题：
1）调整防火墙策略，上调或者放过部分端口的超时设置。但这会增加运维对全机房的维护负担。
2）调整客户端的keepalive间隔，但这需要每一台机器都要配一次，如果新机器有遗漏，问题还会重现。
3）调整服务端，打开keepalive并设置一个合理值，这样可以不用在意客户端的keepalive配置。因为对防火墙来说，业务数据包，客户端发起的来回的keepalive包，服务端发起的来回的keepalive包，都是有效的。
最终选择的是3）设置redis的tcp-keepalive=600（10分钟）。
网友评论