search

sofastack / sofa-jraft

A production-grade java implementation of RAFT consensus algorithm.
https://www.sofastack.tech/projects/sofa-jraft/
Apache License 2.0
3.56k stars 1.14k forks source link

压测过程中导致多数节点不可用，重启集群后数据不一致问题 #803

Closed yufan022 closed 2 years ago

yufan022 commented 2 years ago

问题： 压测过程中因overload发现多数节点不可用，重启集群后数据不一致问题

描述： 压测过程，因为抖动导致fsm disruptor ringbuffer被打满，jraft抛出overload异常节点变成不可用。此时关闭压测脚本，逐步重启每个节点，经过短暂等待读取快照与同步日志后，校验集群数据，发现数据不一致。（1.3.10增加了block模式，还可以增大ringbuffer size来解决overloa的问题，但是此处主要咨询节点重启后数据不一致的问题）

具体操作顺序：

  1. 清理状态机与raftLog数据
  2. 启动1，2，3节点
  3. 开启压测脚本
  4. 运行一段时间后，因为压力过大，3个节点逐步依次overload停止工作（节点不可用顺序：1，2，3）
  5. 此时手动依次重启节点
  6. 短暂等待（等待节点加载快照与同步日志）
  7. 启动工具分别对每个节点数据校验，经过以上操作多次模拟发现数据经常不一致

例如此时经过校验发现：2节点数据与1 3不一致，此时我手动删除2节点的状态机与raft数据，再次重启，观察日志发现2节点主动在1或3的Leader中通过installSnapshot与日志同步数据，完成后再次校验发现2的数据和1 3一致了。

想咨询一下数据不一致是因为我重启的操作有问题么？overload异常后正确的处理方式是怎样呢？是需要找到最后一任Leader的节点手动重启（从本地快照+log恢复），然后将其他两个节点的状态机与raft本地数据全部删除后再重启（从Leader远程恢复）么？不清理数据直接重启的操作是错误的么？

多次复现，偶尔就会出现有个别节点数据不一致的情况，检查日志发现在启动之后，新leader产生后，有检查到reject term_unmatched AppendEntriesRequest日志，不知道是否有影响

killme2008 commented 2 years ago

附上当时的节点日志，否则这样的描述提供不了太大帮助，无助于分析问题。

yufan022 commented 2 years ago

@killme2008 Hi，我刚刚复现了一下，截取了详细的三节点日志，具体流程：

  1. 启动1 2 3节点，此时1为leader
  2. 开启压测脚本（状态机维护一些kv，每次请求value自增+1）
  3. 运行几分钟后worker2首先overload，此时集群超过半数存活应该还可以工作，此时worker2 asset=2 [worker2.log 41 42行]
  4. 一分钟后worker3也overload，此时2 3都overload，超过半数节点故障，集群不可工作了。此时worker3 asset=3[worker3.log 51 52行]
  5. 重启worker2 [worker2.log 104行]
  6. 重启worker3 [worker3.log 114行]
  7. worker2 3重启加入集群后恢复正常
  8. 运行脚本校验三节点状态机中数据，发现worker3这台数据与1 2 不一致，worker3比1 2少了最新的几次变更

校验数据，此时以k1为例，发现三个节点数据不一致： worker1: asset=3 worker2: asset=3 worker3: asset=2

相关监控： 黄色worker1 leader 绿色worker2 follower 蓝色worker3 follower image

相关日志: worker3.log worker2.log worker1.log 触发onapply方法时会打印onapply update asset: asset[id=xxx,balance=xxx]

猜测: 在日志中发现worker2和3的区别是： worker2先加载本地快照 -> 再从leader加载快照 -> 加载完快照后没有还原log，猜测从远程加载的installSnapshot包含了最新变更所以没有重放log的日志，此时asset=3与leader一致。

而worker3从本地加载快照后没有从leader远程加载installSnapshot 接着重放了log 但是此时只重放到asset=2，没执行最新的asset=3。（但是奇怪的是，在worker3宕机前，已经执行了asset=1 asset=2 asset=3，这一点在日志中有体现[worker3.log 51行]，但重启后没只执行了asset=2 丢了asset=3[worker3.log 121行]）

此时我如果将worker3再次停止，然后将本地snapshot与raftlog全部删除，再重新启动，会用installSnapshot从远程拉取安装，启动后asset=3数据和1 2一致。

这种多数节点先后overload后，重启恢复之后发现三节点之间数据不一致的问题有很大概率可以复现，是我的操作流程有问题么？发生overload之后不能直接重启节点么

killme2008 commented 2 years ago

看了下，看起来没什么问题，最终日志都复制到了 1966588 这个 log index。

我猜测跟你的 state machine 实现或者 snapshot 实现有关系。

killme2008 commented 2 years ago

建议在 state machine 增加一些日志，可以在重启的时候开启，查看下 apply 的 log 信息是否正确（index，内容等）

yufan022 commented 2 years ago

好的，目前思路时我先把save/load snapshot和onApply时状态机的value都打印出来，先排除快照或onApply的问题，再缩小范围看到底缺了哪一条没执行。

yufan022 commented 2 years ago

添加了详细日志，复现了一次，发现save/load没有问题，符合预期，但是重启时确实有一部分Log没有再次执行：

2022-03-27 13:19:18 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=30006,balance=3,updateId=3092764]
...
2022-03-27 13:19:57 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=36,balance=4,updateId=3684338]
2022-03-27 13:20:02 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=3006,balance=11,updateId=3773166]
2022-03-27 13:20:09 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=306,balance=7,updateId=3888209]
2022-03-27 13:20:15 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=36,balance=5,updateId=3996983]
2022-03-27 13:20:16 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=306,balance=8,updateId=4023468]
2022-03-27 13:20:20 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=300006,balance=10,updateId=4095418]
2022-03-27 13:20:23 [JRaft-FSMCaller-Disruptor-0] INFO  AbstractStateSnapshotFile:49 - begin save snapshot updateId 4148143
2022-03-27 13:20:26 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=306,balance=9,updateId=4193443]
2022-03-27 13:20:41 [xx-snapshot-executor1] INFO  xxStorage:598 - Finish sst file /raft/test/raft_group_-1_8082/snapshot/temp/state_temp/default.sst with 9296166 keys.
2022-03-27 13:20:41 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=30006,balance=4,updateId=4419925]
2022-03-27 13:20:44 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=306,balance=10,updateId=4473126]
2022-03-27 13:20:46 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=306,balance=11,updateId=4503209]
2022-03-27 13:20:57 [JRaft-Closure-Executor-15] INFO  LocalSnapshotStorage:167 - Deleting snapshot /raft/test/raft_group_-1_8082/snapshot/snapshot_4648195.
2022-03-27 13:20:57 [JRaft-Closure-Executor-15] INFO  LocalSnapshotStorage:231 - Renaming /raft/test/raft_group_-1_8082/snapshot/temp to /raft/test/raft_group_-1_8082/snapshot/snapshot_4648195.
2022-03-27 13:20:57 [JRaft-Closure-Executor-15] INFO  LocalSnapshotStorage:167 - Deleting snapshot /raft/test/raft_group_-1_8082/snapshot/snapshot_3676298.
2022-03-27 13:21:04 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=306,balance=12,updateId=4805868]
2022-03-27 13:21:07 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=3006,balance=12,updateId=4862910]
2022-03-27 13:21:10 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=300006,balance=11,updateId=4897732]
2022-03-27 13:21:13 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=306,balance=13,updateId=4962692]
2022-03-27 13:21:15 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=36,balance=6,updateId=4993334]
2022-03-27 13:21:23 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=300006,balance=12,updateId=5098623]
2022-03-27 13:21:24 [JRaft-LogManager-Disruptor-0] ERROR StateMachineAdapter:72 - Encountered an error=Status[EBUSY<1009>: FSMCaller is overload.] on StateMachine xx.raftxx.raft.xxStateMachine,
 it's highly recommended to implement this method as raft stops working since some error occurs, you should figure out the cause and repair or remove this node.
com.alipay.sofa.jraft.error.RaftException: FSMCaller is overload.

可以从日志中看出，updateId=4148143时开始快照，此时快照中内容应该为: uid 300006 balance = 10 uid 30006 balance = 3 uid 3006 balance = 11 uid 306 balance = 8 uid 36 balance = 5 快照成功后节点overload

overload后重启日志：

2022-03-27 13:26:01 [main] INFO  JRaftServiceLoader:275 - SPI service [com.alipay.sofa.jraft.util.JRaftSignalHandler - com.alipay.sofa.jraft.ThreadPoolMetricsSignalHandler] loading.
2022-03-27 13:26:01 [main] INFO  JRaftServiceLoader:275 - SPI service [com.alipay.sofa.jraft.util.timer.RaftTimerFactory - com.alipay.sofa.jraft.util.timer.DefaultRaftTimerFactory] loading.
2022-03-27 13:26:01 [main] INFO  NodeImpl:555 - The number of active nodes increment to 1.
2022-03-27 13:26:03 [main] INFO  FSMCallerImpl:201 - Starts FSMCaller successfully.
2022-03-27 13:26:03 [main] INFO  SnapshotExecutorImpl:259 - Loading snapshot, meta=last_included_index: 4648195
last_included_term: 2
peers: "127.0.0.1:8081"
peers: "127.0.0.2:8082"
peers: "127.0.0.3:8083"
.
2022-03-27 13:26:03 [JRaft-FSMCaller-Disruptor-0] INFO  AbstractStateSnapshotFile:155 - load uid 4148143
2022-03-27 13:26:06 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:654 - Start ingest sst file /raft/test/raft_group_-1_8082/snapshot/snapshot_4648195/state/default.sst.
2022-03-27 13:26:07 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:660 - load asset account 300006 10
2022-03-27 13:26:07 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:665 - load asset account 30006 3
2022-03-27 13:26:07 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:670 - load asset account 3006 11
2022-03-27 13:26:07 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:675 - load asset account 306 8
2022-03-27 13:26:07 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:680 - load asset account 36 5
2022-03-27 13:26:07 [JRaft-FSMCaller-Disruptor-0] INFO  StateMachineAdapter:79 - onConfigurationCommitted: 127.0.0.1:8081,127.0.0.2:8082,127.0.0.3:8083.
2022-03-27 13:26:07 [JRaft-FSMCaller-Disruptor-0] INFO  SnapshotExecutorImpl:448 - Node <dev--1/127.0.0.2:8082> onSnapshotLoadDone, last_included_index: 4648195
last_included_term: 2
peers: "127.0.0.1:8081"
peers: "127.0.0.2:8082"
peers: "127.0.0.3:8083"2022-03-27 13:26:07 [main] INFO  NodeImpl:724 - Node <dev--1/127.0.0.2:8082> target priority value has changed from: 0, to: -1.
2022-03-27 13:26:07 [main] INFO  NodeImpl:1085 - Node <dev--1/127.0.0.2:8082> init, term=2, lastLogId=LogId [index=5653728, term=2], conf=127.0.0.1:8081,127.0.0.2:8082,127.0.0.3:8083, oldConf=.
2022-03-27 13:26:07 [main] INFO  RaftGroupService:136 - Start the RaftGroupService successfully.
2022-03-27 13:26:07 [main] INFO  GrpcReceiverServer:121 - Start the GrpcReceiverServer successfully, port:18082
2022-03-27 13:26:07 [main] INFO  log:170 - Logging initialized @6928ms to org.eclipse.jetty.util.log.Slf4jLog
2022-03-27 13:26:07 [Rpc-netty-server-worker-1-thread-1] WARN  BoltRaftRpcFactory:94 - JRaft SET bolt.rpc.dispatch-msg-list-in-default-executor to be false for replicator pipeline optimistic.
2022-03-27 13:26:07 [dev--1/PeerPair[127.0.0.2:8082 -> 127.0.0.3:8083]-AppendEntriesThread0] INFO  LocalRaftMetaStorage:132 - Save raft meta, path=/raft/test/raft_group_-1_8082/meta, term=3, votedFor=0.0.0.0:0, cost time=7 ms
2022-03-27 13:26:07 [dev--1/PeerPair[127.0.0.2:8082 -> 127.0.0.3:8083]-AppendEntriesThread0] WARN  NodeImpl:1953 - Node <dev--1/127.0.0.2:8082> reject term_unmatched AppendEntriesRequest from 127.0.0.3:8083, term=3, prevLogIndex=5655729, prevLogTerm=3, localPrevLogTerm=0, lastLogIndex=5653728, entriesSize=0.
2022-03-27 13:26:07 [JRaft-FSMCaller-Disruptor-0] INFO  StateMachineAdapter:89 - onStartFollowing: LeaderChangeContext [leaderId=127.0.0.3:8083, term=3, status=Status[ENEWLEADER<10011>: Raft node receives message from new leader with higher term.]].
2022-03-27 13:26:07 [dev--1/PeerPair[127.0.0.2:8082 -> 127.0.0.3:8083]-AppendEntriesThread0] INFO  Recyclers:52 - -Djraft.recyclers.maxCapacityPerThread: 4096.
2022-03-27 13:26:07 [main] INFO  Server:375 - jetty-9.4.45.v20220203; built: 2022-02-03T09:14:34.105Z;
2022-03-27 13:26:07 [main] INFO  ContextHandler:921 - Started o.e.j.s.ServletContextHandler@51b01550{/,null,AVAILABLE}
2022-03-27 13:26:07 [main] INFO  AbstractConnector:333 - Started ServerConnector@5de6cf3a{HTTP/1.1, (http/1.1)}{0.0.0.0:28081}
2022-03-27 13:26:07 [main] INFO  Server:415 - Started @7078ms
2022-03-27 13:26:20 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=36,balance=6,updateId=4993334]
2022-03-27 13:26:27 [JRaft-FSMCaller-Disruptor-0] INFO  xxStorage:324 - onapply: asset[uid=300006,balance=11,updateId=5098623]
2022-03-27 13:26:49 [JRaft-FSMCaller-Disruptor-0] INFO  AbstractStateSnapshotFile:49 - begin save snapshot uid 5155676
2022-03-27 13:27:14 [xx-snapshot-executor1] INFO  xxStorage:598 - Finish sst file /raft/test/raft_group_-1_8082/snapshot/temp/state_temp/default.sst with 11311338 keys.

可以看到重启时加载快照中updateId=4148143，并且快照中状态与save快照的日志相同，说明加载快照内容也是正确的： load asset account 300006 10 load asset account 30006 3 load asset account 3006 11 load asset account 306 8 load asset account 36 5

但时中间跳过了中间很多条（重启前 开始快照一直到overload发生），最后只执行了updateId=4993334和5098623的两条，此时中间很多条没执行，好像丢了。

虽然最终Index是最新的，但是中间updateId=4193443，4419925，4473126，4503209，4805868，4862910，4897732，4962692这几条都没有执行，所以造成这个节点数据不一致。

看情况似乎是发生overload前一批的log会有部分保存失败丢失？而且目前来看状态机和快照的实现暂时没发现问题，因为除了发生overload这种情况，数据一致性都是没问题的。

killme2008 commented 2 years ago

你要确认的是你所谓的丢失的日志，有没有传入 onApply，还是传入，因为你的逻辑忽略不执行了，等等。

killme2008 commented 2 years ago

在日志提交给 fsm caller 之前，日志都已经保存了的，所以你说的情况是不存在的(commit 的才会提交给 state machine)；并且每次都是从 snapshot 重放到最新的，重放过程中如果发现日志丢失也会报错，不会顺利重放到最新的，建议还是再看看你的 onApply 逻辑。

yufan022 commented 2 years ago

@killme2008 🙏感谢回复，这里再次验证后，如您描述是onApply前后不一致导致的问题，发现是某些场景重启读取快照时状态机RocksDB未清理干净 有脏数据，导致重启状态机时有部分log没有onApply成功导致数据不一致。

不过这里发现另外一个关于leader选举的问题： 描述：停止全部节点，重启后，似乎选举出了错误的leader，或者是cli获取到了错误的leader。

操作过程：

  1. shutdown worker1，worker2，worker3节点
  2. 重启1，2，3节点。
  3. 使用CLI routeTable.refreshLeader routeTable.selectLeader，发现获取的leader为worker3
  4. 此时check三节点数据，发现3节点还未追上最新进度，比1 2落后（追赶成功后会保持一致）

worker3节点中的快照比较旧，所以需要恢复时间较久，1 2节点快照时间较新 恢复时间较快。 此时在worker3追赶上最新进度之前，理论上应该只有1，2节点先追赶到最新index才能被选为主吧？

日志： worker2-leaderbug.log worker1-leaderbug.log worker3-leaderbug.log

image

描述： 14:30分使用cli调用selectLeader，发现获取到的leader为worker3（此时leader3还未onApply追赶最新进度，应该不能成为leader）。 同时观察三个节点的日志。 14:20:47 worker3 become leader of group， 但是没有onLeaderStart日志。 14:36:08 kill worker3，worker1会出现become leader of group和onLeaderStart日志。

此时check三节点内数据，1 2节点已还原最新index，并且一致。3节点还未还原到最新index，并且数据不一致。但是cli获取到的是worker3为leader。

killme2008 commented 2 years ago

这个是正常现象， refreshLeader 后，得到的leader 永远都只是瞬态的，一般都会建议你设计一个 redirect 重定向协议，服务端收到请求，发现不是 leader，可以把最新的leader 信息发给客户端，或者强制客户端重新刷新 route table，再获取。

yufan022 commented 2 years ago

这里就是用routetable refresh之后拿到的worker3，不过此时worker3还没还原到最新index，状态数据是旧的。

cli通过获取leader拿到的worker3，是真的成为leader了么？

看worker3的日志14:20:47 worker3 become leader of group似乎是成为leader了？

killme2008 commented 2 years ago

你看到那一刻的状态，可能是 worker 停止过程中， worker3 被选为 leader 的瞬间状态，而不是重启后的

killme2008 commented 2 years ago

log 的 commit 和 apply 是两个过程，并不需要等待 apply 追上才发起选举的。

yufan022 commented 2 years ago

就是说其实现在新的leader还没有产生，cli拿到的leader是类似于过期数据？等到新leader产生后才会拿到准确leader？

你看到那一刻的状态，可能是 worker 停止过程中， worker3 被选为 leader 的瞬间状态，而不是重启后的

这里每次停止我都是先shutdown worker3，发现leader转移到了1或2，此时cli获取到的也是1或2。再shutdown 1和2。

yufan022 commented 2 years ago

不过这里worker3确实好像成为了leader，因为有看到become leader of group日志，理论上此时worker3不能成为leader吧？因为状态机数据还没重放完毕。

worker3:

2022-03-30 14:20:47 [JRaft-RPC-Processor-2] INFO  NodeImpl:1222 - Node <dev--1/172.21.43.116:8083> become leader of group, term=11, conf=172.21.41.216:8081,172.21.42.61:8082,172.21.43.116:8083, oldConf=.

而且此时即使cli刷新route table拿到的leader也是worker3

killme2008 commented 2 years ago

前面都已经说完了，没有更多补充的，选举并不需要等 apply 追上，跟 state machine 状态也没有什么关系。 cli 看到的状态就是当时的状态， worker 3 最多可能就是因为 apply 追的慢，导致 onLeaderStart 通知延迟了。

从你的协议角度就是按照我给的建议来设计，不需要关心这些东西。

yufan022 commented 2 years ago

懂了，选举不用关心状态机是否应用到最新。

  1. 关于选举：所以当时CLI查询到的Leader是准确的，就是worker3是Leader。状态机落后并不影响选举，因为log是最新的，所以worker3可以当选leader，最新提交task的onApply最终会在未来时间点上执行。

  2. 关于业务：因为我的业务update请求的是通过RPC触发提交node.apply(task)，但是要等到状态机onApply到RocksDB中才执行Response。所以当这种情况的启动时，Leader当选了但是还未回放onApply到最新log，此时RPC请求都会超时，因为刚刚这次update请求的onApply还要等一段时间才能执行到，短时间不能执行Response，所以这次RPC会超时。但实际task是成功提交了的。只有当worker3追赶完毕，此时新的RPC才不会超时，因为追赶完毕后很快onApply到状态机了并且执行response延迟很短所以不会超时。

  3. 关于一致性：目前设计的查询RPC是没走node.apply(task)，直接查询状态机RocksDB。那这种情况当worker3当选Leader，在leader刚启动并且在回放历史log时接收到了RPC查询，此时通过Leader查询的数据相当于是历史数据，不能保证强一致性（因为选举不需要等statemachine追上）。需要让查询也走node.apply(task)，这样才能保证这种情况不会查询到历史数据。

不知道我的理解正确么？

killme2008 commented 2 years ago

1 和 2 是 ok 的。 2 的情况避免可以通过 onLeaderStart 来判断是否回放完成，可以看下 demo，会设置 term 作为 leader 是否就绪的标记。

3 可以走线性一致读 Node#readIndex ，具体阅读文档吧。

yufan022 commented 2 years ago

了解，通常情况新当选的leader应该不会有延迟log情况的。 除非是集群重启这种情况，这种情况如果当选的leader需要回放的log数量比较多，意味着最新RPC的onApply要等很久，RPC会超时。

这种情况能想到的方案是：

  1. 可以通过手动transferLeader转移leader至其他已经追赶index最新的节点（上边案例的worker1或2）。
  2. 结合term判断leader是否就绪，试过没有则直接拒绝提交task，返回失败（或者这里通过term判断leader就绪有其他的用法么）

这样正确么，或者有其他建议么？

问题3当前的设计可能有问题，这种情况不能保证一致性，我看一下Node#readIndex。

killme2008 commented 2 years ago

正常情况下，你的节点重启不是一批的吧？ 通过 transferLeader 保证集群可用，分批重启，那就不存在所谓追不上的问题。 apply 通常来讲都不应该延迟很多，可以监控这种情况。

yufan022 commented 2 years ago

是的，另外发现如果一些不需要等待状态机更新的RPC，也可以直接onCommit提高效率。

没有更多问题了，非常感谢您的帮助！issue我关闭了。