发现关于这个问题的文章很多都没有解释清楚地,找到个大佬解释的挺详细的。转载一波记录下。
作者:哈密朵
链接:https://www.jianshu.com/p/b2e03ff2eb6e

【发现问题】
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的连接,也能轻易的判断出这一点。

在这里插入图片描述

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分钟)。

Logo

为开发者提供学习成长、分享交流、生态实践、资源工具等服务,帮助开发者快速成长。

更多推荐