最近遇到一次生产环境 redis sentinel 故障切换失败的问题，以此记录给自己敲响警钟。

背景

生产环境有一组当作数据源使用的 redis ，考虑到数据不可用将影响业务，即 P1 级应用， 需要保障较严格的高可用。 鉴于原先业务使用单台 redis 时使用我们自己封装的客户端。使用 sentinel 方式进行故障 的检测与转移，而客户端改从 sentinel 获取可用节点，都使用 master 节点。

我们的生产环境是部署在阿里云的VPC中， 

        AZ-A        |   AZ-B
+------+  +------+  | +------+
|  R1  |  |  R2  |  | |  R3  |
+------+  +------+  | +------+
                    |
                    |
+------+  +------+  | +------+
|  S1  |  |  S2  |  | |  S3  |
+------+  +------+  | +------+
                    |

  • R 为 redis 实例， S 为 sentinel 实例

  • R3 为 master ，R1 与 R2 为 slave

  • 网络带宽 1Gbps

  • 数据量限制在 4 GiB

  • R1与R2所在的系统上安装了 k8s (且 redis 没有部署在 k8s 中)

  • 业务应用在可用区A，与大部分主机在一起

问题描述

出现问题是在 2019-10-17 15:00:04 由 Python 与 Java 应用同时 报出 Connection Refused ，检查 R3:6379 端口无法访问，检查没有进程监听， 没有 redis 进程，首先想到的是是否因内存小号太多被 OOM Killer 杀掉了，翻日志 果不其然 

[Thu Oct 17 14:18:36 2019] lowmem_reserve[]: 0 2976 16031 16031 16031
[Thu Oct 17 14:18:36 2019] Node 0 DMA32 free:66352kB min:12412kB low:15512kB high:18616kB active_anon:2933712kB inactive_anon:432kB active_file:2000kB inactive_file:2916kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3129216kB managed:3048440kB mlocked:0kB dirty:0kB writeback:8kB mapped:3124kB shmem:572kB slab_reclaimable:6088kB slab_unreclaimable:9308kB kernel_stack:1680kB pagetables:14452kB unstable:0kB bounce:0kB free_pcp:1136kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:31252 all_unreclaimable? yes
[Thu Oct 17 14:18:36 2019] lowmem_reserve[]: 0 0 13054 13054 13054
[Thu Oct 17 14:18:36 2019] Node 0 Normal free:70440kB min:55104kB low:68880kB high:82656kB active_anon:13064876kB inactive_anon:2476kB active_file:116kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):128kB present:13631488kB managed:13367460kB mlocked:0kB dirty:0kB writeback:4kB mapped:688kB shmem:3456kB slab_reclaimable:32776kB slab_unreclaimable:49288kB kernel_stack:9168kB pagetables:68696kB unstable:0kB bounce:0kB free_pcp:1636kB local_pcp:48kB free_cma:0kB writeback_tmp:0kB pages_scanned:1076 all_unreclaimable? yes
[Thu Oct 17 14:18:36 2019] lowmem_reserve[]: 0 0 0 0 0
[Thu Oct 17 14:18:36 2019] Node 0 DMA: 0*4kB 0*8kB 0*16kB 1*32kB (U) 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15904kB
[Thu Oct 17 14:18:36 2019] Node 0 DMA32: 514*4kB (UME) 422*8kB (UME) 431*16kB (UME) 324*32kB (UME) 153*64kB (E) 91*128kB (UME) 33*256kB (UME) 10*512kB (UM) 6*1024kB (UME) 1*2048kB (H) 0*4096kB = 65896kB
[Thu Oct 17 14:18:36 2019] Node 0 Normal: 2452*4kB (UMEH) 1082*8kB (UMEH) 1536*16kB (UMEH) 444*32kB (UME) 168*64kB (UMEH) 17*128kB (UME) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 70176kB
[Thu Oct 17 14:18:36 2019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[Thu Oct 17 14:18:36 2019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[Thu Oct 17 14:18:36 2019] 2644 total pagecache pages
[Thu Oct 17 14:18:36 2019] 0 pages in swap cache
[Thu Oct 17 14:18:36 2019] Swap cache stats: add 0, delete 0, find 0/0
[Thu Oct 17 14:18:36 2019] Free swap  = 0kB
[Thu Oct 17 14:18:36 2019] Total swap = 0kB
[Thu Oct 17 14:18:36 2019] 4194174 pages RAM
[Thu Oct 17 14:18:36 2019] 0 pages HighMem/MovableOnly
[Thu Oct 17 14:18:36 2019] 86223 pages reserved
[Thu Oct 17 14:18:36 2019] 0 pages cma reserved
[Thu Oct 17 14:18:36 2019] 0 pages hwpoisoned
[Thu Oct 17 14:18:36 2019] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
[Thu Oct 17 14:18:36 2019] [17611]     0 17611    12555      106      29       3        0             0 cron
[Thu Oct 17 14:18:36 2019] [17612]   999 17612     1126       18       8       3        0             0 sh

# ... 中间省略进程表较多

[Thu Oct 17 14:18:36 2019] [17621]   999 17621    48661    10416      98       3        0             0 python
[Thu Oct 17 14:18:36 2019] [17622]   999 17622    48661    10358     101       3        0             0 python
[Thu Oct 17 14:18:36 2019] Out of memory: Kill process 21370 (redis-server) score 461 or sacrifice child
[Thu Oct 17 14:18:36 2019] Killed process 21370 (redis-server) total-vm:7624292kB, anon-rss:7571104kB, file-rss:0kB

不过这个时间点 14:18:36 就比较神奇，有超过40分钟没杀成功？并且检查主机的内存监控的确 是在15:00才释放出来的。

然后是 sentinel 检测出 master 宕机 ，并且很快就满足 quorum 要求 

22719:X 17 Oct 15:00:38.423 # +sdown master idfa_check 10.111.5.143 6379
22719:X 17 Oct 15:00:38.516 # +odown master idfa_check 10.111.5.143 6379 #quorum 3/2

开始 sentinel 的 leader 选举，可以说很真实，3台 sentinel 都选自己， 所以第一次没有选出 master ；并且故障转移的延迟要等6分钟（！）。 

22719:X 17 Oct 15:00:38.516 # +new-epoch 9
22719:X 17 Oct 15:00:38.516 # +try-failover master idfa_check 10.111.5.143 6379
22719:X 17 Oct 15:00:38.532 # +vote-for-leader bee639a324755c111c238557b244bf3628418629 9
22719:X 17 Oct 15:00:38.533 # 27eb1f1e055b94c91b988d0191640f21946edb9e voted for 27eb1f1e055b94c91b988d0191640f21946edb9e 9
22719:X 17 Oct 15:00:38.555 # 485cb1b8e708517b929aa4036639a9b5be5503ec voted for 485cb1b8e708517b929aa4036639a9b5be5503ec 9
22719:X 17 Oct 15:00:49.008 # -failover-abort-not-elected master idfa_check 10.111.5.143 6379
22719:X 17 Oct 15:00:49.086 # Next failover delay: I will not start a failover before Thu Oct 17 15:06:38 2019

6分钟后，可以看到顺利选举出 sentinel leader 后，看到进行故障转移的过程有异常 

22719:X 17 Oct 15:06:38.943 # +new-epoch 10
22719:X 17 Oct 15:06:38.943 # +try-failover master idfa_check 10.111.5.143 6379
22719:X 17 Oct 15:06:38.947 # +vote-for-leader bee639a324755c111c238557b244bf3628418629 10
22719:X 17 Oct 15:06:38.953 # 485cb1b8e708517b929aa4036639a9b5be5503ec voted for bee639a324755c111c238557b244bf3628418629 10
22719:X 17 Oct 15:06:38.954 # 27eb1f1e055b94c91b988d0191640f21946edb9e voted for bee639a324755c111c238557b244bf3628418629 10
22719:X 17 Oct 15:06:39.013 # +elected-leader master idfa_check 10.111.5.143 6379
22719:X 17 Oct 15:06:39.013 # +failover-state-select-slave master idfa_check 10.111.5.143 6379
22719:X 17 Oct 15:06:39.104 # -failover-abort-no-good-slave master idfa_check 10.111.5.143 6379
22719:X 17 Oct 15:06:39.175 # Next failover delay: I will not start a failover before Thu Oct 17 15:12:39 2019

-failover-abort-no-good-slave 状态显示这组主从中没有可用的 slave 实例？

尝试在 sentinel 命令行手工故障转移得到的是一样的结果 

(error) NOGOODSLAVE No suitable slave to promote

从两台 slave 实例的日子可以看到，实际上远在这之前，主从复制的连接就有问题了 

3847:S 17 Oct 12:43:04.846 * Connecting to MASTER 10.111.5.143:6379
3847:S 17 Oct 12:43:04.846 * MASTER <-> SLAVE sync started
3847:S 17 Oct 12:44:05.940 # Timeout connecting to the MASTER...

最后采取了，手工将其中一台 slave (R1) 切换成 master ，才顺利解决 

$ redis-cli slaveof no one

看到故障转移顺利执行 

22719:X 17 Oct 15:10:43.524 # +new-epoch 11
22719:X 17 Oct 15:10:43.528 # +vote-for-leader 485cb1b8e708517b929aa4036639a9b5be5503ec 11
22719:X 17 Oct 15:10:43.531 # Next failover delay: I will not start a failover before Thu Oct 17 15:16:43 2019
22719:X 17 Oct 15:10:43.618 # +config-update-from sentinel 485cb1b8e708517b929aa4036639a9b5be5503ec 10.111.5.153 26379 @ idfa_check 10.111.5.143 6379

最后整个故障过程约10分钟后业务恢复， 于是这个月4个9的 SLA 是不要想了，已经完蛋了 XDDD

分析

追溯日志，实际上远在3周前，这个主从复制就已经出现故障，而这个时间点又与该主机上安装 k8s 符合。业务都使用 master 节点故不受影响。

进一步研究主从连接为何会超时，发现 

redis-ser 3704 root   13u     IPv4 241658807      0t0       TCP 127.0.0.1:46189->10.111.5.110:6379 (SYN_SENT)

建立 TCP 连接的源地址是 127.0.0.1 这个理解起来有点不符合一般情况，我们知道 如果 connect(2) 调用的发起 socket fd 没有指定地址或者网卡的话，内核会帮我们 选择，一般是符合路由的那张网卡地址。同时，在没有特殊设置的情况下，即使使用 127.0.0.1 源地址发起连接也是可以连接上的。于是这里就有两个可疑的地方

  • 为何源地址是 127.0.0.1

  • 为何发起连接连不上？

解答第一个问题比较简单，我们的 redis 实例配置文件中有这么一行 

bind 127.0.0.1 <internal_ip>

这是我们早期在阿里云使用经典网络的教训，不配置内网地址的话，甚至可能被其他 阿里云租户访问到，问题就在这里 127.0.0.1 写在第一个，那么 redis 是如何发起主从 同步连接的呢？

可以看到1 ， 还真就是拿配置中第一个地址作为源地址 ，好吧。 但是这应该不影响连接。

于是怀疑到是否因为 netfilter 的若干规则影响到呢？注意到前面介绍背景时， R1 与 R2 上都安装了 k8s 环境，我们知道 k8s 的网络是通过 kube-proxy 设置 netfilter 规则来实现 集群内网络走向控制的。

这个调试原理与过程想以后详细再讲，这里先丢一张图2， 理解一下 iptables 的处理流程。

然后，要知道 k8s 还在跑应用，并不方便将某台主机的 kubelet kube-proxy 以及网络插件停掉，进而清理 iptables 规则来验证。所以这里采取将 redis 的配置 修改，将内网地址放到第一个，重开后 顺利开启 R2 从 R1 同步的复制 。

可以吸取的教训

  • 重要的数据类服务与业务应用隔离分开部署， 减少因不可控造成资源的抢占导致服务不可用。 事后分析，R3 (原 master) 所在主机因业务增加部署进程导致内存开销吃紧， 而 OOM Killer 计算分数3的时候，粗略认为占用比例越大分数越高， 意味着更有可能被杀死。

  • 缺乏最基础的监控，实例、端口存活情况应当是非常需要重视的基础。

  • 网络因素尤其是 netfilter 相关的细节是许多开发人员并不会注意的细节，在做出调整前 应该仔细评估做测试。

此外特别值得一提的是 sentinel 有一项设置 failover-timeout4 同时在故障切换过程中被多次使用且含义不同，默认 3 分钟 

# - The time needed to re-start a failover after a previous failover was
#   already tried against the same master by a given Sentinel, is two
#   times the failover timeout.

故障转移失败后需要 2倍 这个超时，所以上面情景是 6 分钟， 即这个值不宜过大 。

并且 

# - The time needed for a slave replicating to a wrong master according
#   to a Sentinel current configuration, to be forced to replicate
#   with the right master, is exactly the failover timeout (counting since
#   the moment a Sentinel detected the misconfiguration).
#
# - The time needed to cancel a failover that is already in progress but
#   did not produced any configuration change (SLAVEOF NO ONE yet not
#   acknowledged by the promoted slave).
#
# - The maximum time a failover in progress waits for all the slaves to be
#   reconfigured as slaves of the new master. However even after this time
#   the slaves will be reconfigured by the Sentinels anyway, but not with
#   the exact parallel-syncs progression as specified.

  • 旧 master (新 slave) 强制改正同步对象的时间

  • 取消目前已经在同步，但尚未生成配置 slave 的时间

  • 整个故障转移过程中等待所有 slave 都完成到新 master 配置的时间

根据上面日志查看选举成功、修改配置等实际消耗的时间， 这个值可能并不需要 3 分钟那么大 。

目前已经采取的改进措施有：

  • 增加 redis_exporter 5部署，对所有 redis 实例的存活 ( redis_up ) 进行监控

  • 增加 redis_master_link_up 的监控， master 实例没有这一项，所以检测出来 0 的 即是有问题的 slave

顺便，有找到好几个 sentinel_expoter 的实现，例如这个6 ， 不过目前尚未想好需要监控哪些内容，主从同步的延迟等等似乎也应该考虑加入。

可以进一步深入研究的细节

  • k8s 哪条 netfilter 规则导致了从 127.0.0.1 发起向外的连接无法正常建立

  • iptables 处理顺序，以及如何让调试规则更便利

  • sentinel 做故障切换时，还有哪些值得注意的 异常 情况

结语

现在回顾对 redis 的主从复制、故障转移的原理没有吃透；同时作为 DevOps 人员， 应对生产环境的一切保有敬畏心，警钟长鸣 。

__END__

1

https://github.com/antirez/redis/blob/4.0.11/src/replication.c#L1859

2

https://stuffphilwrites.com/2014/09/iptables-processing-flowchart/

3

https://unix.stackexchange.com/questions/153585/how-does-the-oom-killer-decide-which-process-to-kill-first

4

https://github.com/antirez/redis/blob/4.0.11/sentinel.conf#L108

5

https://github.com/oliver006/redis_exporter

6

https://github.com/9maf4you/sentinel_exporter