Redis went away

问题过程

输入法业务于12月12日上线词库推送业务，根据用户uuid（uuid平台校验）进行词库推送，在12月17日早上8点多开始出现大量的php报错（Redis went away），报错致使了大量的连接积累，瞬间服务器的80端口堆积到了2w多致使了接收计费日志的接口所有返回超时，丢失了1小时的结费数据。

报错内容以下：

[17-Dec-2018 01:32:51 UTC] PHP Fatal error:  Uncaught exception 'RedisException' with message 'Redis server went away' in /opt/case/update.pinyin.2345.com/UuidForRedis.php:75
Stack trace:
#0 /opt/case/update.pinyin.2345.com/UuidForRedis.php(75): Redis->auth('KangDuiShiWei')
#1 /opt/case/update.pinyin.2345.com/UuidForRedis.php(59): UuidForRedis->connectRedis()
#2 /opt/case/update.pinyin.2345.com/pinyin/cloud_switch.php(160): UuidForRedis->__construct()
#3 /opt/case/update.pinyin.2345.com/cloud_config_new.php(187): include('/opt/case/updat...')
#4 {main}
  thrown in /opt/case/update.pinyin.2345.com/UuidForRedis.php on line 75

排查过程：

收到服务器的80端口报警后，查看php错误是Redis连接超时，因Redis连接的时候设置的超时是10s，致使大量的80端口堆积，形成该机组其余业务接口所有都出现了5xx的错误。

线上解决：

连接Redis的时候增长超时设置，并设置为1秒，当Redis有连接问题的时候不会操做请求接口等待超时，上线后解决。

疑问：

那么如今你可能就有疑问了，redis为何会时不时的就出现了Redis went away的错误呢？而且在并发高的时候愈加明显，是否是redis并发扛不住了？

 

Redis排查过程

日志收集

一、 该Redis是一个公共uuid平台，确认线上全部连接是否都加了超时，没有所有加上并设置为1秒，并上线

二、挑选3个业务对Redis连接增长try catch捕获并将异常日志记录到文本一边后续分析

错误部分摘要：

2018-12-20 08:00:06 Redis server went away
2018-12-20 08:00:06 Redis server went away
2018-12-20 08:00:06 Redis server went away
2018-12-20 08:00:06 Redis server went away
2018-12-20 08:00:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:15:06 Redis server went away

 

排查过程

联系运维，先考虑从如下步骤依次排查问题的缘由：

• 内网网络问题

• redis错误日志

• redis的慢日志

• 防火墙的配置

• 系统错误日志

• 持久化配置

第一步：内网网络问题猜想

该问题实际很差测试重现，经过实际测试代码测试和业务日志状况分析，排除该问题

 

第二步：查看Redis错误日志

Redis错误日志在redis.conf中的logfile配置中，查看确认后无异常

 

第三步：查看redis的慢日志

经过连接redis-cli 输入slowlog get查看最近128条的慢日志信息，从慢日志上分析除了有keys的异常命令外其余都表现正常，能够再排除，继续往下排查

部分信息以下：
27.0.0.1:6379> SLOWLOG get
 1) 1) (integer) 52
   2) (integer) 1545183329
   3) (integer) 58086
   4) 1) "KEYS"
       2) ""
   5) "172.16.30.154:40135"
   6) ""
 2) 1) (integer) 51
   2) (integer) 1545182639
   3) (integer) 68437
   4) 1) "KEYS"
       2) ""
   5) "172.16.30.154:28131"
   6) ""

 

Redis的慢日志为啥会有keys命令，经过排查发现全部的请求是经过在线Redis平台过去的，由于Redis是单进程单线程的，通过评估以为该操做仍是有必定风险，因此咱们暂时关闭了全部在线redis平台的查看权限

第四步：查看防火墙的配置

当前这里所说的防火墙不是防火墙配置错了，那种错误是全部的连接都会被拒绝，如今的问题是时不时的会出现Redis went away错误，据某业务数据统计，1小时55万请求里约有300多请求出现了该问题。

检查iptables是否打开了nat转发模块，iptables在高并发链接时丢包，可能致使链接超时ip_conntrack: table full, dropping packet，与运维确认后未开启该模块，排查了该点。

具体参考该网页关于iptables的说明：https://zhangxugg-163-com.iteye.com/blog/2404170

第五步：查看系统错误日志

运维登陆该Redis机器，查看系统message里var/log/message是否有相关的错误信息，排查后错误信息正常。

第六步：redis的持久化配置

排查到这里还有一个重要的配置不能错过，redis的持久化配置rdb和aof都有可能致使阻塞给客户端连接操做了连接超时的状况。

先排查默认的持久化配置，经过命令和配置文件查看redis的rdb配置以下，aof未开启可忽略

save 900 1 // 900内,有1条写入,则产生快照
save 300 1000 // 若是300秒内有1000次写入,则产生快照
save 60 10000 // 若是60秒内有10000次写入,则产生快照

先关闭持久化配置，并观察线上的错误信息是否有变化

config set save ""

关闭后观察了1小时未有特别明显的变化，继续排查

第七步：排查是否phpredis扩展的版本

备注：php机器的版本是5.3，redis扩展的版本为xxx，线上Redis的版本是4.0

这个其实很差下定论，可是凑巧该业务还链接了另外一台Redis机器，该Redis的版本也是4.0版本，但从收集的错误日志来看未出现任何错误信息，因此反向推论能够得出Redis扩展的版本并没有问题。

 

继续思考，排查ing...

 

但从最近收集到的错误日志来看，有一个有规律的特征，每隔5分钟的05秒左右就会规律性的出现错误，这个点的数据应该引发警觉，有规律每隔5分钟出现一次，是否是有crontab再定时作持久化rdb呢？

联系运维再验证一下：

经过redis-cli monitor将最近5分钟的监控日志所有dump到文本文件中，而后对文本文件的命令进行分析，未发现异常的命令状况。

后续补充：redis的save和bgsave并不会在monitor监控列表里出现（4.x），但从其余方面验证了没有业务使用命令行进行了定时的save或bgsave操做

 

第八步：查看crontab配置

是否是crontab有5分钟一次的相关配置，的确找到了一条，这个你们一下就会比较熟悉，公司全部机器都会有定时同步时间的：

*/5 * * * *  /usr/sbin/ntpdate -s monitor.50bang.org || /usr/bin/rdate -s monitor.50bang.org; /sbin/hwclock -w

 

这个应该不会有问题了，可是该排查的都排查了，先去掉再看看状况：

5min

5min

5min

...

再查看3个业务线上的错误日志，日志所有变少了，从有规律的5分钟出错10来条，变成了1小时只有几条错误，另两个业务无错误了。

 

你可能也会一下就会联想就是这个问题了，可是为何更新时间会影响redis操做呢，这个理论上都关联不上了，咱们在反向验证一下，把crontab再打开再观察错误状况，若是错误又回来了那确定就是这玩意致使的了。

 

继续分析crontab的命令，把定时关掉，手动执行命令再观察业务机器是否有报错信息：

① 执行ntpdate命令，走的是udp协议，机房封了该协议，该命令返回是失败的，执行并没有影响排除

② 执行rdate命令，业务机器未发现错误，排除

③执行/sbin/hwclock -w命令，业务机器发现错误！！！发现错误！！！稳定重现！！！

 

看到这里，那么你关心的结果来了：

/sbin/hwclock -w在执行的过程当中会致使Redis的客户端连接出现Redis Went away现象。

但使用相同方法在测试环境未能重现现象

 

结论

/sbin/hwclock -w命令在执行的过程当中会致使php客户端链接Redis服务器出现必定机率的Redis Went away错误，该命令通常执行时间约1-2秒，因此就出现了以前每隔5分钟就定时出现一个错误信息。

后续为何该命令会影响Redis的服务呢，据与其余业务了解不少软件都依赖于时间服务，时间服务的变更都会影响到相关业务的服务提供。

 

后续优化

一、 全部业务连接第三方的api或服务，好比curl、redis、mysql等都须要设置超时

二、Redis设置超时时间建议最大为1秒，根据业务能够减小到毫秒，超时后须要有异常捕获