线上Redis偶发性链接失败排查记
问题过程
输入法业务于12月12日上线了词库接受业务，对部分用户根据用户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/xxx/uuidforredis.php:75
stack trace:
#0 /opt/case/xxx/uuidforredis.php(75): redis->auth('kangduishiwei')
#1 /opt/case/xxx/uuidforredis.php(59): uuidforredis->connectredis()
#2 /opt/case/xxx/pinyin/cloud_switch.php(160): uuidforredis->__construct()
#3 /opt/case/xxx/cloud_config_new.php(187): include('/opt/case/updat...')
#4 {main}
thrown in /opt/case/xxx/uuidforredis.php on line 75
排查过程：
收到服务器的80端口报警后，查看php错误是redis链接超时，因redis链接的时候设置的超时是10s，所以导致了大量的80端口堆积，造成了该机组的所有业务都其他接口全部都出现了5xx的超时错误。
线上解决：
链接redis的时候增加超时设置，并设置为1秒，当redis有链接问题的时候不会操作请求接口等待超时，上线后解决。
疑问：
那么现在你可能就有疑问了，redis为什么会时不时的就出现了redis went away的错误呢？并且在并发高的时候越发明显，是不是redis并发扛不住了？
redis排查过程
日志收集
1、 该redis是一个公共uuid平台，确认线上所有链接是否都加了超时，没有全部加上并设置为1秒，并上线
2、挑选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的说明：
第五步：查看系统错误日志
运维登录该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监控列表里出现，但从其他方面验证了没有业务使用命令行进行了定时的save或bgsave操作
第八步：查看crontab配置
是不是crontab有5分钟一次的相关配置，的确找到了一条，这个大家一下就会比较熟悉，公司所有机器都会有定时同步时间的：
*/5 * * * * /usr/sbin/ntpdate -s xxx || /usr/bin/rdate -s xxx; /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服务器出现一定几率的redid went away错误，该命令一般执行时间约1-2秒，所以就出现了之前每隔5分钟就定时出现一个错误信息。
后续为什么该命令会影响redis的服务呢，据与其他业务了解很多软件都依赖于时间服务，时间服务的变动都会影响到相关业务的服务提供。
后续优化
1、 所有业务链接第三方的api或服务，比如curl、redis、mysql等都需要设置超时
2、redis设置超时时间建议最大为1秒，根据业务可以减少到毫秒，超时后需要有异常捕获