记一次PHP偶现获取不到Redis数据排查过程

问题描述

  3月25号早晨8点左右线上回归时，发现getTestInfos接口部分请求返回空数据。kibana查询异常请求日志，输入参数正常；梳理接口业务逻辑，是根据输入参数从Redis查询数据返回空导致。

  进一步确认：1）Redis查询数据时未抛异常；2）Redis中确实存在该数据；3）只有偶尔部分请求无法从Redis获取数据。

  10点25左右，重启业务进程与confd，恢复正常。

  两个疑问：1）为什么部分请求会获取不到Redis的数据；2）为什么重启服务可以恢复

现状梳理

  已知：服务并不是直连Redis，中间经过代理Twemproxy转发（简称tw），tw后端存在多个Redis实例，tw通过key-hash将请求分发到具体的Redis实例。架构如下：

  etcd作为注册中心，tw将自身信息ip:port:weight注册到etcd；业务机器都部署有confd进程，从etcd拉取tw配置，并同步配置到业务进程。

  进一步了解：24号晚11点14分，一台tw实例曾出现"故障"，并在2分钟左右恢复。kibana查询日志验证，晚11点14分访问Redis出现短暂的异常"read error on connection"，后续再没有捕获到任何异常。

  查看confd日志，晚11点14分（剔除一台tw），晚11点16分（tw恢复），早10点25分（confd重启），拉取tw配置正确，切同步配置到业务进程配置文件正确，如下：

DEBUG Got the following map from store xxxx

DEBUG Target config /home/www/xxxx/conf/redis.php in sync

  等等，上面说重启业务进程与confd恢复正常，业务进程为什么需要重启？原来，业务服务并不是运行在php-fpm模式下，是基于Swoole的，常驻进程。那么业务进程是如何感知到配置文件的变化并重新加载的。查看confd模板配置：

[template]
src="xxxx/config.tmpl"
dest="/home/www/xxxx/conf/redis.php"
keys=[
    "xxxx",
]
check_cmd="/usr/local/php7/bin/php -l {
  {.src}}"
reload_com="/usr/local/php7/bin/php /home/www/xxxx/daemon/baseserver/start.php kill && /usr/local/php7/bin/php /home/www/xxxx/daemon/baseserver/start.php start"

  原来业务进程是想通过confd提供的"reload_cmd"实现的（配置改变时，重启命令），只是书写错误导致业务进程没有重启。

  另外，业务代码中与tw是通过长连接通信的。

  有点眉目了，tw故障以及恢复时，业务进程没有重启，从而没有成功更新配置以及重新连接tw，导致业务进程与这台tw的连接是异常的，因此无法获取数据。

  进一步思考，如果tw是挂掉并重启，那业务进程之前与tw建立的连接全部异常（如果没有重连机制）；而我们只有2个tw实例，并且请求是平均分摊到2个tw实例，那么理论上应该有大概50%的请求无法无法获取数据。kibana统计异常请求与正常请求比例，只有2%左右。

  经咨询，原来晚11点14分，tw是由于所在机器网络线路故障，才导致的短暂失联，tw进程并没有重启。

  猜测：在tw失联期间，业务进程执行查询请求，phpredis扩展由于连接异常导致读写数据错误，并抛出异常"read error o