三年之久的 etcd 3 数据不一致 bug 分析

遇事不决问 Google

强一致性的存储突然数据不一致了，这么严重的问题，想必日志里肯定会有所体现。然而，可能是 etcd 开发者担心日志太多会影响性能的缘故，etcd 的日志打印的比较少，以至于我们排查了 etcd 各个节点的日志，也没有发现有用的报错日志。甚至是在我们调高日志级别之后，仍没有发现异常信息。

作为一个21世纪的程序员，遇到这种诡异且暂时没头绪的问题，第一反应当然是先 Google 一下啦，毕竟不会 StackOverFlow 的 程序员 不是好运维！Google 输入“etcd data inconsistent” 搜索发现，并不是只有我们遇到过该问题，之前也有其他人向 etcd 社区反馈过类似问题，只是苦于没有提供稳定的复现方式，最后都不了了之。如 issue：

1. https://github.com/etcd-io/etcd/issues/9630

2. https://github.com/etcd-io/etcd/issues/10407

3. https://github.com/etcd-io/etcd/issues/10594

4. https://github.com/etcd-io/etcd/issues/11643

由于这个问题比较严重，会影响到数据的一致性，而我们生产环境中当前使用了数百套 etcd 集群，为了避免出现类似问题，我们决定深入定位一番。

etcd 工作原理和术语简介

在开始之前，为方便读者理解，这里先简单介绍下 etcd 的常用术语和基本读写原理。

术语表：

etcd 是一个强一致性的分布式 KV 存储，所谓强一致性，简单来说就是一个写操作成功后，从任何一个节点读出来的数据都是最新值，而不会出现写数据成功后读不出来或者读到旧数据的情况。etcd 通过 Raft 协议来实现 leader 选举、配置变更以及保证数据读写的一致性。下面简单介绍下 etcd 的读写流程：

写数据流程（以 leader 节点为例，见上图）：

1. etcd 任一节点的 etcd server 模块收到 Client 写请求（如果是 follower 节点，会先通过 Raft 模块将请求转发至 leader 节点处理）。

2. etcd server 将请求封装为 Raft 请求，然后提交给 Raft 模块处理。

3. leader 通过 Raft 协议与集群中 follower 节点进行交互，将消息复制到follower 节点，于此同时，并行将日志持久化到 WAL。

4. follower 节点对该请求进行响应，回复自己是否同意该请求。

5. 当集群中超过半数节点（(n/2)+1 members ）同意接收这条日志数据时，表示该请求可以被Commit，Raft 模块通知 etcd server 该日志数据已经 Commit，可以进行 Apply。

6. 各个节点的 etcd server 的 applierV3 模块异步进行 Apply 操作，并通过 MVCC 模块写入后端存储 BoltDB。

7. 当 client 所连接的节点数据 apply 成功后，会返回给客户端 apply 的结果。

读数据流程：

1. etcd 任一节点的 etcd server 模块收到客户端读请求（Range 请求） 判断读请求类型，如果是串行化读（serializable）则直接进入 Apply 流程

2. 如果是线性一致性读（linearizable），则进入 Raft 模块

3. Raft 模块向 leader 发出 ReadIndex 请求，获取当前集群已经提交的最新数据 Index

4. 等待本地 AppliedIndex 大于或等于 ReadIndex 获取的 CommittedIndex 时，进入 Apply 流程

5. Apply 流程：通过 Key 名从 KV Index 模块获取 Key 最新的 Revision，再通过 Revision 从 BoltDB 获取对应的 Key 和 Value。

初步验证

通常集群正常运行情况下，如果没有外部变更的话，一般不会出现这么严重的问题。我们查询故障 etcd 集群近几天的发布记录时发现，故障前一天对该集群进行的一次发布中，由于之前 dbsize 配置不合理，导致 db 被写满，集群无法写入新的数据，为此运维人员更新了集群 dbsize 和 compaction 相关配置，并重启了 etcd。重启后，运维同学继续对 etcd 手动执行了 compact 和 defrag 操作，来压缩 db 空间。

通过上述场景，我们可以初步判断出以下几个可疑的触发条件：

1. dbsize 满

2. dbsize 和 compaction 配置更新

3. compaction 操作和 defrag 操作

4. 重启 etcd

出了问题肯定要能够复现才更有利于解决问题，正所谓能够复现的 bug 就不叫 bug。复现问题之前，我们通过分析 etcd 社区之前的相关 issue 发现，触发该 bug 的共同条件都包含执行过 compaction 和 defrag 操作，同时重启过 etcd 节点。因此，我们计划首先尝试同时模拟这几个操作，观察是否能够在新的环境中复现。为此我们新建了一个集群，然后通过编写脚本向集群中不停的写入和删除数据，直到 dbsize 达到一定程度后，对节点依次进行配置更新和重启，并触发 compaction 和 defrag 操作。然而经过多次尝试，我们并没有复现出类似于上述数据不一致的场景。

抽丝剥茧，初现端倪

紧接着，在之后的测试中无意发现，client 指定不同的 endpoint 写数据，能够查到数据的节点也不同。比如，endpoint 指定为 node1 进行写数据，3个节点都可以查到数据；endpoint 指定为 node2 进行写数据，node2 和 node3 可以查到；endpoint 指定为 node3 写数据，只有 node3 自己能够查到。具体情况如下表：

于是我们做出了初步的猜测，有以下几种可能：

1. 集群可能分裂了，leader 未将消息发送给 follower 节点。

2. leader 给 follower 节点发送了消息，但是 log 异常，没有对应的 command。

3. leader 给 follower 节点发送了消息，有对应的 command，但是 apply 异常，操作还未到 KV Index 和 boltdb 就异常了。

4. leader 给 follower 节点发送了消息, 有对应的 command，但是 apply 异常，KV Index 出现了问题。

5. leader 给 follower 节点发送了消息, 有对应的 command，但是 apply 异常，boltdb 出现了问题。

为了验证我们的猜测，我们进行了一系列测试来缩小问题范围：

首先，我们通过 endpoint status 查看集群信息，发现 3 个节点的 clusterId，leader，raftTerm，raftIndex 信息均一致，而 dbSize 大小和 revision 信息不一致。clusterId 和 leader 一致，基本排除了集群分裂的猜测，而 raftTerm 和 raftIndex 一致，说明 leader 是有向 follower 同步消息的，也进一步排除了第一个猜测，但是 WAL落盘有没有异常还不确定。dbSize 和 revision 不一致则进一步说明了 3 个节点数据已经发生不一致了。

其次，由于 etcd 本身提供了一些 dump 工具，例如 etcd-dump-log 和 etcd-dump-db。我们可以像下图一样，使用 etcd-dump-log dump 出指定 WAL 文件的内容，使用 etcd-dump-db dump 出 db 文件的数据，方便对 WAL 和 db 数据进行分析。

于是，我们向 node3 写了一条便于区分的数据，然后通过 etcd-dump-log 来分析 3 个节点的 WAL，按照刚才的测试，endpoint 指定为 node3 写入的数据，通过其他两个节点应该查不到的。但是我们发现 3 个节点都收到了 WAL log，也就是说 WAL 并没有丢，因此排除了第二个猜测。

接下来我们 dump 了 db 的数据进行分析，发现 endpoint 指定为 node3 写入的数据，在其他两个节点的 db 文件里找不到，也就是说数据确实没有落到 db，而不是写进去了查不出来。

既然 WAL 里有而 db 里没有，因此很大可能是 apply 流程异常了，数据可能在 apply 时被丢弃了。

由于现有日志无法提供更有效的信息，我们打算在 etcd 里新加一些日志来更好地帮助我们定位问题。etcd 在做 apply 操作时，trace 日志会打印超过每个超过 100ms 的请求，我们首先把 100ms 这个阈值调低，调整到 1ns，这样每个 apply 的请求都能够记录下来，可以更好的帮助我们定位问题。

编译好新版本之后，我们替换了其中一个 etcd 节点，然后向不同 node 发起写请求测试。果然，我们发现了一条不同寻常的错误日志："error":"auth:revision in header is old"，因此我们断定问题很可能是因为——发出这条错误日志的节点，对应的 key 刚好没有写进去。

搜索代码后，我们发现 etcd 在进行 apply 操作时，如果开启了鉴权，在鉴权时会判断 raft 请求 header 中的 AuthRevision，如果请求中的 AuthRevision 小于当前 node 的AuthRevision，则会认为 AuthRevision 太老而导致 Apply失败。

那么，既然 3 个节点的 AuthRevision 不一致，会不会是因为某些节点写权限相关的操作丢失了，从而没有写入 db ？如果该猜测成立，3 个节点的 db 里 authUser 和 authRole 的 bucket 内容应该有所不同才对。于是为进一步验证，我们继续修改了下 etcd-dump-db 这个工具，加入了对比不同 db 文件 bucket 内容的功能。遗憾的是，通过对比发现，3 个节点之间的 authUser 和 authRole bucket 的内容并没有什么不同。

既然节点写权限相关的操作没有丢，那会不会是命令重复执行了呢？查看异常时间段内日志时发现，其中包含了较多的 auth 操作；进一步分别比对 3 个节点的 auth 操作相关的日志又发现，部分节点日志较多，而部分节点日志较少，看起来像是存在命令重复执行现象。由于日志压缩，虽然暂时还不能确定是重复执行还是操作丢失，但是这些信息能够为我们后续的排查带来很大启发。

我们继续观察发现，不同节点之间的 AuthRevison虽有差异，但是差异较小，而且差异值在我们压测期间没有变过。既然不同节点之间的 AuthRevision 差异值没有进一步放大，那么通过新增的日志基本上也看不出什么问题，因为不一致现象的出现很可能是在过去的某个时间点瞬时造成的。这就造成我们如果想要发现问题根因，还是要能够复现 AuthRevison 不一致或者数据不一致问题才行，并且要能够抓到复现瞬间的现场。

问题似乎又回到了原点，但好在我们目前已经排除了很多干扰信息，将目标聚焦在了 auth 操作上。

混沌工程，成功复现

鉴于之前多次手动模拟各种场景都没能成功复现，我们打算搞一套自动化的压测方案来复现这个问题，方案制定时主要考虑的点有以下几个：

• 如何增大复现的概率？根据之前的排查结果，很有可能是 auth 操作导致的数据不一致，因此我们实现了一个 monkey 脚本，每隔一段时间，会向集群写入随机的用户、角色，并向角色授权，同时进行写数据操作，以及随机的重启集群中的节点，详细记录每次一操作的时间点和执行日志。

• 怎样保证在复现的情况下，能够尽可能的定位到问题的根因？根据之前的分析得出，问题根因大概率是 apply 过程中出了问题，于是我们在 apply 的流程里加入了详细的日志，并打印了每次 apply 操作committedIndex、appliedIndex、consistentIndex 等信息。

• 如果复现成功，如何能够在第一时间发现？由于日志量太大，只有第一时间发现问题，才能够更精确的缩小问题范围，才能更利于我们定位问题。于是我们实现了一个简单的 metric-server，每隔一分钟拉取各个节点的 key 数量，并进行对比，将差异值暴露为 metric，通过 Prometheus 进行拉取，并用 Grafana 进行展示，一旦差异值超过一定阈值（写入数据量大的情况下，就算并发统计各个节点的 key 数量，也可能会有少量的差异，所以这里有一个容忍误差），则立刻通过统一告警平台向我们推送告警，以便于及时发现。

方案搞好后，我们新建了一套 etcd 集群，部署了我们的压测方案，打算进行长期观察。结果第二天中午，我们就收到了微信告警——集群中存在数据不一致现象。

于是，我们立刻登录压测机器进行分析，首先停掉了压测脚本，然后查看了集群中各个节点的 AuthRevision，发现 3 个节点的 AuthRevision 果然不一样！根据 Grafana 监控面板上的监控数据，我们将数据不一致出现的时间范围缩小到了 10 分钟内，然后重点分析了下这 10 分钟的日志，发现在某个节点重启后，consistentIndex 的值比重启前要小。然而 etcd 的所有 apply 操作，幂等性都依赖 consistentIndex 来保证，当进行 apply 操作时，会判断当前要 apply 的 Entry 的 Index 是否大于 consistentIndex，如果 Index 大于 consistentIndex，则会将 consistentIndex 设为 Index，并允许该条记录被 apply。否则，则认为该请求被重复执行了，不会进行实际的 apply 操作。

该问题从 2016 年引入，所有开启鉴权的 etcd3 集群都会受到影响，在特定场景下，会导致 etcd 集群多个节点之间的数据不一致，并且 etcd 对外表现还可以正常读写，日志无明显报错。

触发条件：

1. 使用的为 etcd3 集群，并且开启了鉴权。

2. etcd 集群中节点发生重启。

3. 节点重启之前，有 grant-permission 操作（或短时间内对同一个权限操作连续多次增删），且操作之后重启之前无其他数据写入。

4. 通过非重启节点向集群发起写数据请求。

导致该问题的直接原因，是由于 consistentIndex 在进行权限相关操作时未持久化，从而导致 auth 相关的操作不幂等，造成了数据的不一致。

而造成 auth 模块未持久化 consistentIndex 的一个因素，是因为 consistentIndex 目前是在 mvcc 模块实现的，并未对外暴露持久化接口，只能通过间接的方式来调用，很容易漏掉。为了优化这个问题，我们重构了 consistentIndex 相关操作，将它独立为一个单独的模块，其他依赖它的模块可以直接调用，一定程度上可以避免将来再出现类似问题，具体见 PR #11699[4]。

另一方面，etcd 的 apply 操作本身是个异步流程，而且失败之后没有打印任何错误日志，很大程度上增加了排障的难度，因此我们后边也向社区提交了相关 PR #11670[5]，来优化 apply 失败时的日志打印，便于定位问题。

造成问题定位困难的另一个原因，是 auth revision 目前没有对外暴露 metric 或者 api，每次查询只能通过 etcd-dump-db 工具来直接从 db 获取，为方便 debug，我们也增加了相关的 metric[6] 和 status api[7]，增强了 auth revision 的可观测性和可测试性。

相关链接：

1. https://github.com/etcd-io/etcd/pull/11652

2. https://github.com/etcd-io/etcd/issues/11689

3. https://github.com/etcd-io/etcd/pull/11691

4. https://github.com/etcd-io/etcd/pull/11699

5. https://github.com/etcd-io/etcd/pull/11670

6. https://github.com/etcd-io/etcd/pull/11652/commits/f14d2a087f7b0fd6f7980b95b5e0b945109c95f3

7. https://github.com/etcd-io/etcd/pull/11659

文章来源： 腾讯云容器团队，点击查看原文 。