前言:由于最近找工作战况严峻,不得以只能再掏个去年的项目,顺便温故一下之前学习分布式知识,commit就是最好的证明~PS:找工作的风气…,希望写这个Lab的不要太功利,bug才是真正提高自己水平的~

那段时光也是最能静下心来,算是研究生生涯中相对美好的时光,感谢这个实验陪我度过生命中至暗的时刻~~~

image-20240914110620319

写这篇文章的时候,发生了一件很不愉快的事情,有点让我觉得生命中认识某些人是我的悲哀。

真正厉害的人,是在避开车马喧嚣后,还可以在心中修篱种菊;是在面对不如意时,还可以戒掉抱怨,学会自愈。

很多事情就像风吹过一样,随风散去ba~

img

实验说明

地址:http://nil.csail.mit.edu/6.824/2022/labs/lab-raft.html

任务要求

  • 实现leader和follower追加新日志条目的代码
  • 运行go test -run 2B来测试

任务提示

  • 你的首要目标应该是通过TestBasicAgree2B()。从实现Start()开始,然后根据Figure2写通过AppendEntries RPCs发送和接收新日志条目的代码。
  • 你需要实现论文5.4.1节提到的选举限制.
  • 在lab 2B的早期测试中无法达成协议的一种可能是,即使leader还活着也在反复举行选举。寻找选举计时器管理中的错误,或者在赢得选举后不立即发送心跳。
  • 你的代码可能具有重复检查某些事件的循环。不要让这些循环连续执行而不暂停,因为这会拖慢实现,导致测试失败。使用Go的条件变量,或者在每个循环迭代中插入一个time.Sleep(10 * time.Millisecond)
  • 为了将来的实验,请编写或重写干净而清晰的代码,思路可以参考raft-structure、raft-locking和guide文档。

如果你的代码运行太慢,接下来的测试可能会失败。你可以使用time命令检查你的解决方案使用了多少实时时间和CPU时间。下面是典型的输出示例:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
$ time go test -run 2B
Test (2B): basic agreement ...
... Passed -- 1.6 3 18 5158 3
Test (2B): RPC byte count ...
... Passed -- 3.3 3 50 115122 11
Test (2B): agreement despite follower disconnection ...
... Passed -- 6.3 3 64 17489 7
Test (2B): no agreement if too many followers disconnect ...
... Passed -- 4.9 5 116 27838 3
Test (2B): concurrent Start()s ...
... Passed -- 2.1 3 16 4648 6
Test (2B): rejoin of partitioned leader ...
... Passed -- 8.1 3 111 26996 4
Test (2B): leader backs up quickly over incorrect follower logs ...
... Passed -- 28.6 5 1342 953354 102
Test (2B): RPC counts aren't too high ...
... Passed -- 3.4 3 30 9050 12
PASS
ok raft 58.142s

real 0m58.475s
user 0m2.477s
sys 0m1.406s
$
  • "ok raft 58.142s"意味着Go测量Part 2B花费的实际时间为58.142秒。

  • “user 0m2.477s”意味着代码消耗了2.477秒的CPU时间,即实际执行指令所花费的时间(而不是等待或休眠的时间)。

  • 如果你的解决方案在Part 2B测试中使用的实时时间远远超过一分钟,或者CPU时间远远超过5秒,那么你之后可能会遇到麻烦。

    查看花费在睡眠或等待RPC超时上的时间、在没有睡眠或等待条件或通道消息的情况下运行的循环,或者大量的RPC发送。

原理说明

FAQ

Q:为什么要日志复制?

A:当一个节点成为领导人后,他需要将自己的日志,复制到其他的跟随者节点,而这,正是复制状态机的实现关键,只要领导人将自己的日志都正确,安全地复制到了跟随者节点,这样可以保证,不管我们外部向任意一个集群发起指令请求,他都会帮助我们找到领导人,而领导人会帮我们将该请求的日志信息都复制到所有的节点,并执行日志的请求,所以无论我们向集群的任意的节点发起输入,最终得到的输出都是一致的。

Q:raft集群怎么得以保障各个机器上的数据的一致性?

A:prevLogIndex和prevLogTerm保证。

image-20240914144119304

描述:

在这个场景中,S1 是当前任期4的领导者,而 S2 在先前崩溃后刚刚恢复,因此 S2 的日志缺失了一些任期4的内容,导致集群中的日志不一致。

作为领导者,S1 在发送心跳信号(也就是 AppendEntries RPC)时,会附带上它自己最后一条日志的任期号和索引号。而跟随者 S2 收到这个心跳信号后,会对比 S1 发送过来的上一个日志的任期号和索引号与它自己本地日志中的相应值。如果 S1 和 S2 的这些值一致,说明在这个索引号之前,两者的日志是完全一致的,S2 就可以安全地复制 S1 的日志到自己的日志序列中。

但是,如果 S1 和 S2 的任期号或日志索引号不一致,说明 S2 缺失了一些日志或日志有冲突。在这种情况下,S1 会通过回溯,逐步减少发送的索引号,直到找到两者日志序列一致的位置。

具体而言,S1 会先发送包含索引 6 和对应任期号的日志条目,但 S2 检查发现其本地日志在该索引处的任期号不一致,接着 S1 会发送索引 5 处的日志,继续回溯,直到找到两者日志完全一致的索引位置。找到了双方日志的最后一致位置后,S2 就可以从该位置继续接受并复制 S1 的最新日志。

这一过程可以被看作是领导者逐步“回退”日志索引,直到找到双方日志的同步点,然后再继续日志复制,确保集群中所有节点的日志最终保持一致。

根据上述日志idx和任期号,无法保证一致性

来看下论文中举出经典的例子:

image-20240914145808506

解释:

  • 现在集群中已经有过半数节点(a、b、c、d)复制并提交了索引4到9的日志,因此这些日志应该已经正确提交。
  • 如果此时节点 f 当选为新的领导者,情况会非常危险。节点 f 的日志与其他节点的最后一致日志是索引3,它的索引4到9的日志是任期2和3的旧日志。
  • 节点 f 当选后,会将自己未提交的旧日志从索引4到9覆盖到其他节点上,导致已经提交的日志(任期4、5、6的日志)被覆盖,破坏了系统的一致性。

Q:上面说到,根据上述日志idx和任期号,无法保证一致性,那raft如何解决的呢?

A:

在 Raft 共识算法中,候选者在发起选举投票的 RPC 时,会携带其最后一项日志的任期号(lastLogTerm)和索引号(lastLogIndex)。每个收到 RPC 的跟随者都会将其与自己的最后一项日志的任期号和索引号进行比较,以确定候选者的日志是否过期。具体规则如下:

  1. 任期号比较
    • 如果候选者的 lastLogTerm 小于跟随者的 lastLogTerm,则跟随者会拒绝投票。
    • 如果候选者的 lastLogTerm 大于或等于跟随者的 lastLogTerm,则继续进行下一步比较。
  2. 索引号比较
    • 如果任期号相同(即 lastLogTerm 相等),则比较索引号。
    • 如果候选者的 lastLogIndex 小于跟随者的 lastLogIndex,则跟随者会拒绝投票。
    • 如果候选者的 lastLogIndex 大于或等于跟随者的 lastLogIndex,则跟随者会投票给候选者。

image-20240914202007154

Q:领导人将一项日志复制到过半的节点后,就可以执行提交了吗?

A:

image-20240914202111140

【崩掉之后 新leader的节点必须在日志复制过半的节点】

假设场景

  1. S1 在任期 2 当选领导人,写入了日志条目 2,但还未完成复制或提交就崩溃了。
  2. S5 在任期 3 当选领导人,并写入了自己的日志条目 2(任期 3),但也未完成复制或提交,随后 S5 崩溃。
  3. S1 在任期 4 再次当选领导人,并试图将它在任期 2 写的日志条目 2(任期 2)复制到其他节点上。

现在的问题

  • 当 S1 再次成为领导人后,它是否可以提交自己在任期 2 时写的日志条目 2?
  • 如果 S1 提交了日志条目 2,之后又崩溃了,S5 成为新领导人后会发生什么?

1.S1 在任期 4 是否可以提交日志条目 2?

根据 Raft 的规则,日志条目只有在当前领导者的任期内被复制到过半数节点后才可以提交。即使 S1 是在任期 4 当选领导人,它也不能直接提交它在任期 2 写入的日志条目 2,原因如下:

  • Raft 的安全性要求:只有当一个日志条目被当前领导者(在它的任期内)复制到大多数节点时,才能被提交。
  • 虽然 S1 是在任期 4 当选的领导人,但它试图提交的是任期 2 的日志条目。根据 Raft 的规则,S1 必须在任期 4 重新将该日志复制到大多数节点上,并且这些节点确认该日志在当前任期内(即任期 4)是最新的,S1 才能提交。

因此,在 S1 成为任期 4 的领导人后,它需要重新将任期 4 的日志条目复制到大多数节点上,才能安全地提交这些日志条目。如果它只复制了任期 2 的日志条目,而没有在任期 4 中将这些条目重新复制到大多数节点上,它是不能立即提交的。

2. 如果 S1 在任期 4 提交了日志条目 2,之后崩溃了会发生什么?

假设 S1 在没有符合 Raft 安全性要求的情况下错误地提交了任期 2 的日志条目 2,然后它崩溃了,S5 在任期 5 成为领导人。此时,S5 必须遵循 Raft 的日志复制和冲突解决规则。

  • S5 的日志条目 2(任期 3)会覆盖 S1 的日志条目 2(任期 2)

    。这是因为 Raft 的日志冲突解决机制规定:

    • 如果某个节点的日志条目与领导者的日志不一致(即索引相同但任期不同),领导者会用自己的日志条目覆盖追随者的条目。
    • 因为 S5 在任期 3 中写的日志条目 2(任期 3)比 S1 的日志条目 2(任期 2)更新,S5 会将它的日志条目 2(任期 3)复制到其他节点,覆盖掉之前的任期 2 的日志条目 2。

3. 如果在此时提交了日志 2,会发生什么?

如果 S1 在任期 4 中提交了日志条目 2(任期 2),即便它提交了该日志条目,后续如果 S5 成为领导人并覆盖了日志条目 2,那么系统的一致性可能会被破坏。

  • 提交并不意味着日志条目永远不可更改。Raft 的日志一致性是基于领导者的日志,如果后续有新任期的领导者出现,并且它的日志条目比之前的日志更新,那么即使之前的日志条目已经提交,新领导者仍然可以通过覆盖的方式引入新的日志条目。
  • 因此,如果 S1 提交了任期 2 的日志条目 2,但之后 S5 覆盖了它的日志条目,系统最终会采用 S5 的版本,S1 的日志条目将被认为是无效的。这可能导致已经执行的操作被“撤销”或“覆盖”,从而违反了系统的一致性要求。

Q:在 Raft 共识算法中,领导者提交日志后,存在一个时间间隔,这段时间内,虽然领导者已经将提交结果返回给了客户端,但还没有通知所有的跟随者节点成功提交。如果在这段时间内领导者崩溃了,确实会出现这样一种情况:领导者已经成功提交了日志,但其他节点还没有同步提交。这个看似“单点提交”的情况会不会影响整个集群的一致性呢?

A:

在 Raft 算法中,日志的提交和复制遵循严格的多数决规则。领导者在提交日志之前,必须确保该日志已经复制到了大多数节点上。即使领导者在提交日志后崩溃,但只要日志已经复制到了大多数节点,Raft 的一致性机制依然能够保证整个集群最终能正确提交该日志。

场景分析:

假设在某个领导者(比如 S1)提交了日志后,但在通知所有跟随者节点成功提交之前,S1 崩溃了。此时,像 S2 和 S3 等跟随者节点并没有接收到通知,日志还没有被这些节点正式提交。

但由于 Raft 的机制,日志已经被复制到过半节点(即至少有大多数节点保存了该日志)。这意味着,只要有大多数节点存活,新的领导者在选举时,必须从拥有最新日志的节点中产生。因此,当 S1 崩溃后,只有那些已经接收到该日志并保存了该日志的节点能够当选为新的领导者。

新的领导者如何处理:

当新领导者(例如 S2 或 S3)被选举出来后,它会继续同步和提交之前的未完成日志。由于该日志已经复制到了大多数节点,新领导者会确认该日志的提交状态,并将其提交给那些尚未完成提交的节点。

总结:

因此,单点提交并不会导致日志一致性问题。一旦有一个领导者成功提交了日志,并且该日志已经复制到了大多数节点,即使领导者崩溃,新的领导者也能够接续处理并完成日志的提交。Raft 的多数决复制机制确保了只要有大多数节点存活,集群就能够保证一致性。

换句话说,单点提交意味着集群整体最终会成功提交,因为新的领导者会从大多数节点中继承并完成未完成的提交操作。

理清一个概念:日志复制过半和提交

复制过半:当领导者将一条日志条目发送给跟随者,并且超过半数的节点(包括领导者自己)已经成功保存了这条日志,我们称这条日志复制过半。此时,日志条目只是被大多数节点持有,但并不意味着立即提交。
日志提交:为了确保一致性,Raft 要求日志条目在当前领导者的任期内,且已经被复制到过半节点,才能被正式提交。提交意味着该日志条目是已达成共识的,并且可以被应用到状态机,影响系统的状态。

实验思路

对于lab2中去看2b的test其实可以可以发现,其实是调用raft中的start函数,对leader节点写入log,然后检测log是否成功其实就是通过applyChan协程一直检测。

image-20240914141946975

raft 数据结构新增维护日志数据变量:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
type Raft struct {
mu sync.Mutex // Lock to protect shared access to this peer's state
peers []*labrpc.ClientEnd // RPC end points of all peers
persister *Persister // Object to hold this peer's persisted state
me int // this peer's index into peers[]
dead int32 // set by Kill()

// Your data here (2A, 2B, 2C).
// Look at the paper's Figure 2 for a description of what
// state a Raft server must maintain.
// 根据论文的要求定义
// 2A
currentTerm int // Server当前的term
voteFor int // Server在选举阶段的投票给了谁
voteGrantedNum int // 收集到的投票数量
state int // 当前状态
heartbeatTimer *time.Timer // 心跳超时时间
electionTimeout *time.Timer // 随机选举时间
// 2B
logs []Entry
commitIndex int // 已提交日志序号
lastApplied int // 已应用日志序号
nextIndex []int // 下一个待发送日志序号,leader 特有
matchIndex []int // 已同步日志序号,leader 特有
applyChan chan ApplyMsg // 日志都是存在这里client取(2B)
}

Entry数据结构

1
2
3
4
5
6
// 定义日志具体细节
type Entry struct {
Index int // 日志索引,也就是第几行
Term int // 任期
Command interface{} // 具体命令内容
}

ApplyMsg 结构体用于在 Raft 集群中传递应用消息。它包含两种类型的消息:命令消息和快照消息。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
type ApplyMsg struct {
// 指示该消息是否包含有效的命令
CommandValid bool
// 如果 CommandValid 为 true,则 Command 包含要应用的命令
Command interface{}
// 如果 CommandValid 为 true,则 CommandIndex 包含命令的索引
CommandIndex int
// 以下字段用于快照(2D 部分)
// 指示该消息是否包含有效的快照
SnapshotValid bool
// 如果 SnapshotValid 为 true,则 Snapshot 包含快照数据
Snapshot []byte
// 如果 SnapshotValid 为 true,则 SnapshotTerm 包含快照对应的任期
SnapshotTerm int
// 如果 SnapshotValid 为 true,则 SnapshotIndex 包含快照对应的索引
SnapshotIndex int
}

Start方法:测试代码是通过Start方法给Leader节点添加日志条目。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
// Start 方法用于启动 Raft 协议中的日志追加过程。
// 如果当前服务器不是领导者,则返回 false。
// 否则,启动日志追加过程并立即返回。
// 返回值包括:
// 1. 命令将被提交的索引
// 2. 当前任期
// 3. 当前服务器是否为领导者
func (rf *Raft) Start(command interface{}) (int, int, bool) {
index := -1 // 初始化索引为 -1
term := -1 // 初始化任期为 -1
isLeader := true // 假设当前服务器是领导者
// 加锁,确保线程安全
rf.mu.Lock()
// 如果 Raft 实例已被终止,则返回 false
if rf.killed() {
rf.mu.Unlock()
fmt.Println("Start false1")
return index, term, false
}
// 获取当前任期
term = rf.currentTerm
// 如果当前服务器是领导者,则处理命令
if rf.state == StateLeader {
PrettyDebug(dInfo, "S%dcommand%d[ReceiveLog]", rf.me, command)
// 定义新的日志条目
PrettyDebug(dInfo, "S%d:%d[Start-Before]", rf.me, rf.logs)
tlog := Entry{}
tlog.Index = len(rf.logs) + 1 // 设置日志条目的索引
tlog.Term = term // 设置日志条目的任期
tlog.Command = command // 设置日志条目的命令

// 将新的日志条目追加到日志中
rf.logs = append(rf.logs, tlog)

// 设置返回值
index = len(rf.logs)
isLeader = true

// 解锁
rf.mu.Unlock()

PrettyDebug(dInfo, "S%d:%d[Start-After]", rf.me, rf.logs)

// 广播心跳消息,通知其他服务器更新日志
rf.BroadcastHeartbeat() // 之后看看怎么加
} else {
// 如果当前服务器不是领导者,则返回 false
fmt.Println("Start false2")
isLeader = false
rf.mu.Unlock()
}
// 返回结果
return index, term, isLeader
}

理清一下逻辑:

1.初始化

对于初始化的话的操作,对于lab2a没太大的差别。主要在于多了初始化日志下标数组。

2.go rf.ticker()

这部分代码和lab2a没太大的差别,直接复用

3.选举超时的处理

改变自身状态,从跟随者变成候选者。之后开始请求投票。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
func (rf *Raft) startElection() {

// 向所有除了自己以外的sever的请求投票
rf.mu.Lock()
Len_Peers := len(rf.peers)
numID := rf.me

rf.mu.Unlock()
for i := 0; i < Len_Peers; i++ {
if i == numID {
continue
}
go func(peer int) {
// 首先先对服务器上锁
// rf.mu.Lock()
// defer rf.mu.Unlock()
// 定义rpc参数
rf.mu.Lock()
args := RequestVoteArgs{}
args.Term = rf.currentTerm
args.CandidateId = rf.me
args.LastLogIndex = len(rf.logs)
args.LastLogTerm = 0
if len(rf.logs) > 0 {
args.LastLogTerm = rf.logs[len(rf.logs)-1].Term
}
rf.mu.Unlock()
reply := RequestVoteReply{}
reply.VoteGranted = false

// 发送rpc请求
// 处理请求服务器返回的结果
// PrettyDebug(dInfo, "S%d-term:%d-state:%d => %d[RPC-Vote]", rf.me, rf.currentTerm, rf.state, peer)
if rf.sendRequestVote(peer, &args, &reply) {
// PrettyDebug(dInfo, "S%d-term:%d-state:%d => %d[RPC-Vote-Over]", rf.me, rf.currentTerm, rf.state, peer)
rf.mu.Lock()
// 任期号
if rf.currentTerm == args.Term && rf.state == StateCandidate {
// 计算投票数量
if reply.VoteGranted {
PrettyDebug(dTimer, "S%dVote<--%d[Vote]", rf.me, peer)
rf.voteGrantedNum++
if rf.voteGrantedNum > len(rf.peers)/2 {
PrettyDebug(dInfo, "S%d:state:%d-changeTo-state:%d[BecomeLeader]", rf.me, rf.state, StateLeader)
// 当选leader
rf.state = StateLeader
// 初始化nextIndex和matchIndex数组
// rf.nextIndex = make([]int, len(rf.peers))
for i := 0; i < len(rf.peers); i++ {
rf.nextIndex[i] = len(rf.logs) + 1
rf.matchIndex[i] = 0
}
// PrettyDebug(dLeader, "S%d-term:%d-state:%d[BecomeLeader]", rf.me, rf.currentTerm, rf.state)
// rf.heartbeatTimer.Reset(StableHeartbeatTimeout())
rf.mu.Unlock()
// 发送心跳给各个server
rf.BroadcastHeartbeat() // with lock
return
} else {
rf.mu.Unlock()
}
} else {
if rf.currentTerm < reply.Term {
// PrettyDebug(dError, "S%d[VoteFail1]", rf.me)
rf.currentTerm = reply.Term
rf.voteFor = -1
rf.voteGrantedNum = 0
// PrettyDebug(dInfo, "S%d:state:%d:term:%d-changeTo-state:%d:term:%d[BecomeLeader]", rf.me, rf.state, rf.currentTerm, StateFollower, reply.Term)
rf.state = StateFollower
rf.electionTimeout.Reset(RandomizedElectionTimeout())
rf.mu.Unlock()
} else {
rf.mu.Unlock()
}
}
} else {
rf.mu.Unlock()
}
}
}(i)
}
}

sendRequestVote函数简单来说就是在原先投票的基础上加上日志索引的判断。

广播心跳

两种情况下会广播心跳,leader不断发送心跳包维护,成为leader的时候发送,让其他节点知道谁是Leader。

这里给出代码逻辑,实现的话自行根据逻辑实现。

BroadcastHeartbeat函数逻辑

1.发送心跳或日志同步的准备

  • 该函数是 Raft 领导者(Leader)向其他节点发送心跳或日志同步请求的逻辑。在 Raft 中,领导者需要定期向跟随者(Follower)发送心跳维持领导地位,并同步日志。
  • 在函数开始时,打印调试信息,标识当前领导者的任期、节点 ID 和状态。

2. 遍历所有的跟随者

  • 通过遍历集群中的所有节点(除了自己),向每个节点发送心跳或日志条目。
  • 对每个节点,构造 AppendEntriesArgs请求参数,这个参数包括:
    • 当前领导者的任期 (Term)。
    • 当前领导者的 ID (LeaderId)。
    • 当前已提交的日志索引 (LeaderCommit)。
    • 上一个日志条目的索引 (PrevLogIndex) 和任期 (PrevLogTerm),用于日志一致性检查。
    • 如果有新的日志条目需要同步,包含需要发送的日志条目 (Entries),如果没有则 Entries 为空。

3. 日志索引的设置

  • PrevLogIndexPrevLogTerm 【在代码层面是PRC的参数,是由nextIdx和matchIdx设置值的】是 Raft 中日志一致性检查的关键。它们指示领导者要发送的日志条目的前一个条目的索引和任期,确保跟随者的日志与领导者一致。
  • 如果跟随者的日志落后,领导者会根据 nextIndex 确定从哪一条日志开始同步。
  • 如果 nextIndex 指定的日志条目存在,领导者将从该索引开始同步日志条目。

4. 并发发送心跳和日志同步请求

  • 使用 Goroutine 并发地向每个跟随者发送 AppendEntries 请求,减少等待时间,提高效率。
  • 发送请求后,等待跟随者的响应,并处理不同的响应结果。

5. 处理响应结果

  • 如果发送成功,领导者会根据跟随者的响应进行相应的处理:
    • 日志不同步:如果跟随者的日志不同步(日志冲突),会根据返回的索引调整 nextIndex,从而重新发送早期的日志条目。
    • 日志复制成功:如果日志复制成功,更新 nextIndexmatchIndex,表示该跟随者已经同步到的最新日志条目。
    • 任期过期:如果领导者发现跟随者的任期比自己高,则降级为跟随者(Follower)状态,放弃领导地位。

6. 提交日志

  • 在成功复制日志后,领导者会检查是否有新的日志条目可以提交。
  • 通过遍历 matchIndex,领导者检查是否有某个日志条目已经被大多数节点复制(超过半数)。
  • 如果某个日志条目已经被大多数节点复制,并且该日志条目是当前任期的日志,领导者将其提交,并更新 commitIndex
  • 将提交的日志条目应用到状态机,并通过 applyChan 通知状态机执行相应的命令。

7. 日志应用到状态机

  • 提交的日志条目会被封装成 ApplyMsg,通过通道 applyChan 传递给状态机。
  • 领导者不断更新 lastApplied,确保每个已提交的日志条目都被按顺序应用。

AppendEntries函数逻辑

  1. 基本检查
  • 开始时,获取锁以确保对 rf 对象的安全访问(避免并发冲突)。
  • 检查当前节点是否被杀死(rf.killed())。如果是,直接返回失败状态并标记为已终止(Killed)。
  1. 任期检查
  • 如果领导者的任期(args.Term)小于当前节点的任期(rf.currentTerm),则拒绝该请求,返回当前节点的任期,并设置响应状态为过期(OutData)。
  • 如果领导者的任期比当前节点高,更新当前节点的任期为领导者的任期,并将当前节点状态切换为跟随者(Follower)。
  1. 日志一致性检查
  • 检查日志的一致性:
    • 如果领导者发送的 PrevLogIndex 大于当前节点的日志长度,或者 PrevLogTerm 与当前节点日志的对应位置不匹配,说明日志存在冲突。此时,返回失败状态(FailMatch),并告知领导者下次可以同步的日志索引(UpNextIndex)。
    • 如果当前节点的已提交索引(lastApplied)比领导者的 PrevLogIndex 更高,说明当前节点的日志已经超前,返回失败状态(AppCommitted),并告知领导者应从哪个索引重新同步。
  1. 日志追加
  • 如果领导者有新的日志条目需要同步(args.Entries不为空):
    • 当前节点将裁剪掉从 PrevLogIndex 之后的所有日志(如果有日志冲突)。
    • 然后,追加领导者发送的日志条目到当前节点的日志中。
  1. 日志提交
  • 当前节点会根据领导者的LeaderCommit更新自己的commitIndex:
    • 如果领导者已经提交的日志比当前节点多,逐条提交日志,直到达到领导者的 LeaderCommit
    • 每次提交日志时,将日志条目封装成 ApplyMsg,通过 applyChan 传递给状态机进行应用。
  1. 更新状态
  • 将当前节点的状态设置为 Follower,并重置选举超时(electionTimeout.Reset),确保节点不会立即发起新的选举。
  • 最后,返回成功的响应,指示日志追加成功,并告知领导者下次可以从哪个索引继续同步(UpNextIndex)。

测试调试

测试样例

  • TestBasicAgree2B:最基础的追加日志测试。先使用nCommitted()检查有多少的server认为日志已经提交(在执行Start()函数之前,所有的服务器都不应该提交日志),若满足条件则调用cfg.one(),其通过调用rf.Start(cmd)来追加日志。rf.Start(cmd)用于模拟Raft实例从Client接收实例的情况。

  • TestRPCBytes2B:基于RPC的字节数检查保证每个cmd都只对每个peer发送一次。OR。校验RPC发送的字节数,确保每个log只对peer发送一次,发送10条log,校验log command字节总数与抓包捕获的字节总数是否一致.

  • For2023TestFollowerFailure2B:校验Follow丢失连接之后是否正常工作

  • For2023TestLeaderFailure2B:校验Leader丢失连接之后是否正常工作

    • 发送一条log
    • 断开leader连接,剩下两个peer选出一个leader,再发送两条log
    • 断开leader连接,现在客户端只能连接一个peer
    • 遍历peer调用start() 测试是否有peer提交了日志
  • (G - √)TestFailAgree2B:断连小部分,不影响整体Raft集群的情况检测追加日志。

  • (G - √)TestFailNoAgree2B:断连过半数节点,保证无日志可以正常追加。然后又重新恢复节点,检测追加日志情况。

  • TestConcurrentStarts2B:模拟客户端并发发送多个命令

  • (g)TestRejoin2B:Leader 1断连,再让旧leader 1接受日志,再给新Leader 2发送日志,2断连,再重连旧Leader 1,提交日志,再让2重连,再提交日志。

  • (G)TestBackup2B:先给Leader 1发送日志,然后断连3个Follower(总共1Ledaer 4Follower),网络分区。提交大量命令给1。然后让leader 1和其Follower下线,之前的3个Follower上线,向它们发送日志。然后在对剩下的仅有3个节点的Raft集群重复上面网络分区的过程。

  • TestCount2B:检查无效的RPC个数,不能过多。

整体代码:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
func TestBasicAgree2B(t *testing.T) {
servers := 3
cfg := make_config(t, servers, false, false)
defer cfg.cleanup()
cfg.begin("Test (2B): basic agreement")
iters := 3
for index := 1; index < iters+1; index++ {
nd, _ := cfg.nCommitted(index)
if nd > 0 {
t.Fatalf("some have committed before Start()")
}
xindex := cfg.one(index*100, servers, false)
if xindex != index {
t.Fatalf("got index %v but expected %v", xindex, index)
}
}
cfg.end()
}

建议自己根据代码进行分析

  1. 配置初始化【make_config】
  2. 有多少服务器认为一条log已经提交 【nCommitted】
  3. 找到leader,调用start()方法提交命令,如果当前server不是leader,则更换目标重新提交提交成功后,等待一段时间,检查cmd是否真的提交成功【one】

TestFailAgree2B测试样例分析

分析下列程序

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
func TestFailNoAgree2B(t *testing.T) {
servers := 5
cfg := make_config(t, servers, false, false)
defer cfg.cleanup()
cfg.begin("Test (2B): no agreement if too many followers disconnect")
cfg.one(10, servers, false)
// 3 of 5 followers disconnect
leader := cfg.checkOneLeader()
cfg.disconnect((leader + 1) % servers)
cfg.disconnect((leader + 2) % servers)
cfg.disconnect((leader + 3) % servers)
index, _, ok := cfg.rafts[leader].Start(20)
if ok != true {
t.Fatalf("leader rejected Start()")
}
if index != 2 {
t.Fatalf("expected index 2, got %v", index)
}
time.Sleep(2 * RaftElectionTimeout)
n, _ := cfg.nCommitted(index)
if n > 0 {
t.Fatalf("%v committed but no majority", n)
}
// repair
cfg.connect((leader + 1) % servers)
cfg.connect((leader + 2) % servers)
cfg.connect((leader + 3) % servers)
// the disconnected majority may have chosen a leader from
// among their own ranks, forgetting index 2.
leader2 := cfg.checkOneLeader()
index2, _, ok2 := cfg.rafts[leader2].Start(30)
if ok2 == false {
t.Fatalf("leader2 rejected Start()")
}
if index2 < 2 || index2 > 3 {
t.Fatalf("unexpected index %v", index2)
}
cfg.one(1000, servers, true)
cfg.end()
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
5个peers,断连3个后重连,测试是否正常

TERM 1: 5个peer都写入 msg 10

S2 S3 S4 断线 超时

S1 写入 msg 20 index 2

转TERM 2 开始选举 恢复连接

S3 成为 TERM 3的 leader

写入msg 30 msg 1000

这时候S1的log index=2 为msg20,prelog 1 的index和term都匹配,直接把msg 30 1000插入了,应该要把msg20删除的

分析程序发现判断符号写错了

TestRejoin2B测试程序分析

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
func TestRejoin2B(t *testing.T) {
servers := 3
cfg := make_config(t, servers, false, false)
defer cfg.cleanup()

cfg.begin("Test (2B): rejoin of partitioned leader")

cfg.one(101, servers, true)

// leader network failure
leader1 := cfg.checkOneLeader()
cfg.disconnect(leader1)

// make old leader try to agree on some entries
cfg.rafts[leader1].Start(102)
cfg.rafts[leader1].Start(103)
cfg.rafts[leader1].Start(104)

// new leader commits, also for index=2
cfg.one(103, 2, true)

// new leader network failure
leader2 := cfg.checkOneLeader()
cfg.disconnect(leader2)

// old leader connected again
cfg.connect(leader1)

cfg.one(104, 2, true)

// all together now
cfg.connect(leader2)

cfg.one(105, servers, true)

cfg.end()
}

解释:

  1. 写入msg 101 leader1断开连接
  2. leader1写入102 103 104
  3. leader2写入103 然后断开连接
  4. leader1重连
  5. 请求写入104
  6. eader2重连
  7. 写入105

报错这个错误

outlog.log文件

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
Test (2B): rejoin of partitioned leader ...
002647 INFO S0term:1=state:1=[StartElect]
002648 INFO S0-term:1-state:1 => 2[RPC-Vote]
002648 INFO S0-term:1-state:1 => 1[RPC-Vote]
002650 INFO S2:term:0 ==> S0-term:1[Enter-RequestVote]
002650 INFO S2 ==> S0-term:1[RequestVote]
002650 INFO S2:state:0:term:0-changeTo-state:0:term:1[RequestVote1]
002650 INFO S2:state:0-changeTo-state:0[RequestVote2]
002650 INFO S0-term:1-state:1 => 2[RPC-Vote-Over]
002651 TIMR S0Vote<--2[Vote]
002651 INFO S0:state:1-changeTo-state:2[BecomeLeader]
002651 LEAD S0-term:1-state:2[BecomeLeader]
002651 LEAD S0-term:1-state:2[BeginHeart]
002652 INFO S1:term:0 ==> S0-term:1[Enter-RequestVote]
002652 INFO S1 ==> S0-term:1[RequestVote]
002652 INFO S1:state:0:term:0-changeTo-state:0:term:1[RequestVote1]
002652 INFO S1:state:0-changeTo-state:0[RequestVote2]
002652 INFO S0-term:1-state:2 => 1[RPC-Vote-Over]
003024 LEAD S0-term:1-state:2[BeginHeart]
003048 INFO S0term[ReceiveLog]
003048 LEAD S0-term:1-state:2[BeginHeart]
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
003051 INFO S2:state:0:term:1-ReceiveFrom-S0[AppendEntries]
003052 INFO S0[Heartbeat]
cnt,len(rf.peers) 2 3
003052 INFO S1:state:0:term:1-ReceiveFrom-S0[AppendEntries]
cmdi,ok: 101 true
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: 101 true
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: 101 true
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: 101 true
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: 101 true
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: 101 true
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: 101 true
cmdi,ok: <nil> false
cmdi,ok: <nil> false
004530 LEAD S0-term:1-state:2[BeginHeart]
cmdi,ok: 101 true
cmdi,ok: 101 true
cmdi,ok: 101 true
006039 LEAD S0-term:1-state:2[BeginHeart]
007542 LEAD S0-term:1-state:2[BeginHeart]
009051 LEAD S0-term:1-state:2[BeginHeart]
Pass==checkOneLeader()
009483 INFO S0term[ReceiveLog]
009483 LEAD S0-term:1-state:2[BeginHeart]
009483 INFO S0term[ReceiveLog]
009483 LEAD S0-term:1-state:2[BeginHeart]
009483 INFO S0term[ReceiveLog]
009483 LEAD S0-term:1-state:2[BeginHeart]
010555 LEAD S0-term:1-state:2[BeginHeart]
011512 INFO S2term:2=state:1=[StartElect]
011512 INFO S2-term:2-state:1 => 1[RPC-Vote]
011513 INFO S2-term:2-state:1 => 0[RPC-Vote]
011514 INFO S1:term:1 ==> S2-term:2[Enter-RequestVote]
011514 INFO S1 ==> S2-term:2[RequestVote]
011514 INFO S1:state:0:term:1-changeTo-state:0:term:2[RequestVote1]
011514 INFO S1:state:0-changeTo-state:0[RequestVote2]
011514 INFO S2-term:2-state:1 => 1[RPC-Vote-Over]
011514 TIMR S2Vote<--1[Vote]
011514 INFO S2:state:1-changeTo-state:2[BecomeLeader]
011514 LEAD S2-term:2-state:2[BecomeLeader]
011514 LEAD S2-term:2-state:2[BeginHeart]
011675 INFO S2term[ReceiveLog]
011676 LEAD S2-term:2-state:2[BeginHeart]
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
011677 INFO S1:state:0:term:2-ReceiveFrom-S2[AppendEntries]
011678 INFO S2[Heartbeat]
cnt,len(rf.peers) 2 3
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: 103 true
012058 LEAD S2-term:2-state:2[BeginHeart]
012058 LEAD S0-term:1-state:2[BeginHeart]
cmdi,ok: <nil> false
cmdi,ok: 103 true
cmdi,ok: 103 true
013566 LEAD S0-term:1-state:2[BeginHeart]
013567 LEAD S2-term:2-state:2[BeginHeart]
015074 LEAD S2-term:2-state:2[BeginHeart]
015074 LEAD S0-term:1-state:2[BeginHeart]
Pass==checkOneLeader()
016924 INFO S0term[ReceiveLog]
016925 LEAD S2-term:2-state:2[BeginHeart]
016926 LEAD S0-term:1-state:2[BeginHeart]
016926 LEAD S0-term:1-state:2[BeginHeart]
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
016929 INFO S1:state:0:term:2-ReceiveFrom-S0[AppendEntries]
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
018429 LEAD S2-term:2-state:2[BeginHeart]
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
019936 LEAD S2-term:2-state:2[BeginHeart]
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
cmdi,ok: <nil> false
020620 INFO S1term:3=state:1=[StartElect]
020621 INFO S1-term:3-state:1 => 2[RPC-Vote]
020622 INFO S1-term:3-state:1 => 0[RPC-Vote]
020624 INFO S0:term:2 ==> S1-term:3[Enter-RequestVote]
020624 INFO S0 ==> S1-term:3[RequestVote]
020624 INFO S0:state:0:term:2-changeTo-state:0:term:3[RequestVote1]
020624 INFO S0:state:0-changeTo-state:0[RequestVote2]
020624 INFO S1-term:3-state:1 => 0[RPC-Vote-Over]
020624 TIMR S1Vote<--0[Vote]
020624 INFO S1:state:1-changeTo-state:2[BecomeLeader]
020624 LEAD S1-term:3-state:2[BecomeLeader]
020624 LEAD S1-term:3-state:2[BeginHeart]
0: log map[1:101]; server map[1:101 2:103]
0: log map[1:101]; server map[1:101 2:103]
apply error: commit index=2 server=0 102 != server=2 103
exit status 1
FAIL 6.824/raft 2.064s

TestBackup2B测试程序

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
func TestBackup2B(t *testing.T) {
servers := 5
cfg := make_config(t, servers, false, false)
defer cfg.cleanup()

cfg.begin("Test (2B): leader backs up quickly over incorrect follower logs")

cfg.one(rand.Int(), servers, true)

// put leader and one follower in a partition
leader1 := cfg.checkOneLeader()
cfg.disconnect((leader1 + 2) % servers)
cfg.disconnect((leader1 + 3) % servers)
cfg.disconnect((leader1 + 4) % servers)

// submit lots of commands that won't commit
for i := 0; i < 50; i++ {
cfg.rafts[leader1].Start(rand.Int())
}

time.Sleep(RaftElectionTimeout / 2)

cfg.disconnect((leader1 + 0) % servers)
cfg.disconnect((leader1 + 1) % servers)

// allow other partition to recover
cfg.connect((leader1 + 2) % servers)
cfg.connect((leader1 + 3) % servers)
cfg.connect((leader1 + 4) % servers)

// lots of successful commands to new group.
for i := 0; i < 50; i++ {
cfg.one(rand.Int(), 3, true)
}

// now another partitioned leader and one follower
leader2 := cfg.checkOneLeader()
other := (leader1 + 2) % servers
if leader2 == other {
other = (leader2 + 1) % servers
}
cfg.disconnect(other)

// lots more commands that won't commit
for i := 0; i < 50; i++ {
cfg.rafts[leader2].Start(rand.Int())
}

time.Sleep(RaftElectionTimeout / 2)

// bring original leader back to life,
for i := 0; i < servers; i++ {
cfg.disconnect(i)
}
cfg.connect((leader1 + 0) % servers)
cfg.connect((leader1 + 1) % servers)
cfg.connect(other)

// lots of successful commands to new group.
for i := 0; i < 50; i++ {
cfg.one(rand.Int(), 3, true)
}

// now everyone
for i := 0; i < servers; i++ {
cfg.connect(i)
}
cfg.one(rand.Int(), servers, true)

cfg.end()
}

error_Log

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
Test (2B): leader backs up quickly over incorrect follower logs ...
003590 INFO S1term:1=state:1=[StartElect]
003592 INFO S1-term:1-state:1 => 4[RPC-Vote]
003592 INFO S1-term:1-state:1 => 2[RPC-Vote]
003594 INFO S1-term:1-state:1 => 3[RPC-Vote]
003608 INFO S1-term:1-state:1 => 0[RPC-Vote]
003611 INFO S2:term:0 ==> S1-term:1[Enter-RequestVote]
003612 INFO S2 ==> S1-term:1[RequestVote]
003612 INFO S2:state:0:term:0-changeTo-state:0:term:1[RequestVote1]
003612 INFO S2:state:0-changeTo-state:0[RequestVote2]
003612 INFO S0:term:0 ==> S1-term:1[Enter-RequestVote]
003612 INFO S0 ==> S1-term:1[RequestVote]
003612 INFO S0:state:0:term:0-changeTo-state:0:term:1[RequestVote1]
003612 INFO S0:state:0-changeTo-state:0[RequestVote2]
003613 INFO S1-term:1-state:1 => 0[RPC-Vote-Over]
003613 TIMR S1Vote<--0[Vote]
003613 INFO S1-term:1-state:1 => 2[RPC-Vote-Over]
003613 TIMR S1Vote<--2[Vote]
003613 INFO S1:state:1-changeTo-state:2[BecomeLeader]
003613 INFO S3:term:0 ==> S1-term:1[Enter-RequestVote]
003613 INFO S3 ==> S1-term:1[RequestVote]
003613 INFO S3:state:0:term:0-changeTo-state:0:term:1[RequestVote1]
003613 INFO S3:state:0-changeTo-state:0[RequestVote2]
003614 INFO S1-term:1-state:2 => 3[RPC-Vote-Over]
003613 LEAD S1-term:1-state:2[BecomeLeader]
003614 LEAD S1-term:1-state:2[BeginHeart]
003612 INFO S4:term:0 ==> S1-term:1[Enter-RequestVote]
003616 INFO S4 ==> S1-term:1[RequestVote]
003616 INFO S4:state:0-changeTo-state:0[RequestVote2]
003617 INFO S1-term:1-state:2 => 4[RPC-Vote-Over]
004110 INFO S1command1[ReceiveLog]
004110 INFO S1:[][Start-Before]
004110 INFO S1:[{1 1 1}][Start-After]
004111 LEAD S1-term:1-state:2[BeginHeart]
004113 INFO S3:state:0:term:1-ReceiveFrom-S1[AppendEntries]
004113 INFO S4:state:0:term:1-ReceiveFrom-S1[AppendEntries]
004113 INFO S4:term:[][Add-Before]
004113 INFO S4FromS1:[{1 1 1}][Adding]
004113 INFO S4FromS1:[{1 1 1}][Add-After]
004113 INFO S0:state:0:term:1-ReceiveFrom-S1[AppendEntries]
004113 INFO S0:term:[][Add-Before]
004113 INFO S0FromS1:[{1 1 1}][Adding]
004113 INFO S0FromS1:[{1 1 1}][Add-After]
004113 INFO S2:state:0:term:1-ReceiveFrom-S1[AppendEntries]
004114 INFO S2:term:[][Add-Before]
004114 INFO S2FromS1:[{1 1 1}][Adding]
004114 INFO S2FromS1:[{1 1 1}][Add-After]
004114 INFO S1[Heartbeat]
cnt,len(rf.peers) 3 5
004113 INFO S3:term:[][Add-Before]
004114 INFO S3FromS1:[{1 1 1}][Adding]
004114 INFO S3FromS1:[{1 1 1}][Add-After]
004524 LEAD S1-term:1-state:2[BeginHeart]
[TestBackup2B]==pass1
006030 LEAD S1-term:1-state:2[BeginHeart]
007537 LEAD S1-term:1-state:2[BeginHeart]
009045 LEAD S1-term:1-state:2[BeginHeart]
Pass==checkOneLeader()
leader1: 1
[TestBackup2B]==pass2
009661 INFO S1command2[ReceiveLog]
009662 INFO S1:[{1 1 1}][Start-Before]
009662 INFO S1:[{1 1 1} {2 1 2}][Start-After]
009662 LEAD S1-term:1-state:2[BeginHeart]
009662 INFO S1command3[ReceiveLog]
009662 INFO S1:[{1 1 1} {2 1 2}][Start-Before]
009662 INFO S1:[{1 1 1} {2 1 2} {3 1 3}][Start-After]
009662 LEAD S1-term:1-state:2[BeginHeart]
[TestBackup2B]==pass3
009664 INFO S2:state:0:term:1-ReceiveFrom-S1[AppendEntries]
009664 INFO S2:term:[{1 1 1}][Add-Before]
009664 INFO S2FromS1:[{2 1 2}][Adding]
009664 INFO S2FromS1:[{1 1 1} {2 1 2}][Add-After]
009664 INFO S2:state:0:term:1-ReceiveFrom-S1[AppendEntries]
009664 INFO S2:term:[{1 1 1}][Add-Before]
009664 INFO S2FromS1:[{2 1 2} {3 1 3}][Adding]
009664 INFO S2FromS1:[{1 1 1} {2 1 2} {3 1 3}][Add-After]
010557 LEAD S1-term:1-state:2[BeginHeart]
011250 INFO S3term:2=state:1=[StartElect]
011250 INFO S3-term:2-state:1 => 4[RPC-Vote]
011251 INFO S3-term:2-state:1 => 1[RPC-Vote]
011251 INFO S3-term:2-state:1 => 2[RPC-Vote]
011251 INFO S3-term:2-state:1 => 0[RPC-Vote]
012070 LEAD S1-term:1-state:2[BeginHeart]
012669 INFO S4term:2=state:1=[StartElect]
012671 INFO S4-term:2-state:1 => 3[RPC-Vote]
012671 INFO S4-term:2-state:1 => 1[RPC-Vote]
012672 INFO S4-term:2-state:1 => 0[RPC-Vote]
012673 INFO S4-term:2-state:1 => 2[RPC-Vote]
013574 LEAD S1-term:1-state:2[BeginHeart]
[TestBackup2B]==pass4
014850 INFO S0term:2=state:1=[StartElect]
014850 INFO S0-term:2-state:1 => 4[RPC-Vote]
014851 INFO S0-term:2-state:1 => 2[RPC-Vote]
014851 INFO S4:term:2 ==> S0-term:2[Enter-RequestVote]
014851 INFO S4 ==> S0-term:2[RequestVote]
014851 INFO S4:state:1:term:2-requestOther[RequestVote2]%!(EXTRA int=0, int=2)
014851 INFO S0-term:2-state:1 => 1[RPC-Vote]
014852 INFO S0-term:2-state:1 => 4[RPC-Vote-Over]
014852 INFO S0-term:2-state:1 => 3[RPC-Vote]
014853 INFO S3:term:2 ==> S0-term:2[Enter-RequestVote]
014853 INFO S3 ==> S0-term:2[RequestVote]
014853 INFO S3:state:1:term:2-requestOther[RequestVote2]%!(EXTRA int=0, int=2)
014853 INFO S0-term:2-state:1 => 3[RPC-Vote-Over]
015077 LEAD S1-term:1-state:2[BeginHeart]
016561 INFO S3term:3=state:1=[StartElect]
016561 INFO S3-term:3-state:1 => 0[RPC-Vote]
016562 INFO S3-term:3-state:1 => 4[RPC-Vote]
016562 INFO S3-term:3-state:1 => 1[RPC-Vote]
016562 INFO S3-term:3-state:1 => 2[RPC-Vote]
016562 INFO S0:term:2 ==> S3-term:3[Enter-RequestVote]
016562 INFO S0 ==> S3-term:3[RequestVote]
016563 INFO S0:state:1:term:2-changeTo-state:0:term:3[RequestVote1]
016563 INFO S0:state:0-changeTo-state:0[RequestVote2]
016563 INFO S4:term:2 ==> S3-term:3[Enter-RequestVote]
016563 INFO S4 ==> S3-term:3[RequestVote]
016563 INFO S3-term:3-state:1 => 0[RPC-Vote-Over]
016563 INFO S4:state:1:term:2-changeTo-state:0:term:3[RequestVote1]
016563 TIMR S3Vote<--0[Vote]
016563 INFO S4:state:0-changeTo-state:0[RequestVote2]
016563 INFO S3-term:3-state:1 => 4[RPC-Vote-Over]
016563 TIMR S3Vote<--4[Vote]
016563 INFO S3:state:1-changeTo-state:2[BecomeLeader]
016563 LEAD S3-term:3-state:2[BecomeLeader]
016563 LEAD S3-term:3-state:2[BeginHeart]
016588 LEAD S3-term:3-state:2[BeginHeart]
016589 LEAD S1-term:1-state:2[BeginHeart]
016815 INFO S3command4[ReceiveLog]
016815 INFO S3:[{1 1 1}][Start-Before]
016815 INFO S3:[{1 1 1} {2 3 4}][Start-After]
016815 LEAD S3-term:3-state:2[BeginHeart]
016817 INFO S4:state:0:term:3-ReceiveFrom-S3[AppendEntries]
016817 INFO S4:term:[{1 1 1}][Add-Before]
016817 INFO S4FromS3:[{2 3 4}][Adding]
016817 INFO S4FromS3:[{1 1 1} {2 3 4}][Add-After]
016817 INFO S0:state:0:term:3-ReceiveFrom-S3[AppendEntries]
016817 INFO S0:term:[{1 1 1}][Add-Before]
016817 INFO S0FromS3:[{2 3 4}][Adding]
016817 INFO S0FromS3:[{1 1 1} {2 3 4}][Add-After]
016818 INFO S3[Heartbeat]
cnt,len(rf.peers) 3 5
018025 INFO S2term:2=state:1=[StartElect]
018030 INFO S2-term:2-state:1 => 4[RPC-Vote]
018031 INFO S2-term:2-state:1 => 1[RPC-Vote]
018032 INFO S2-term:2-state:1 => 0[RPC-Vote]
018032 INFO S2-term:2-state:1 => 3[RPC-Vote]
018106 LEAD S3-term:3-state:2[BeginHeart]
018106 LEAD S1-term:1-state:2[BeginHeart]
018234 INFO S3command5[ReceiveLog]
018234 INFO S3:[{1 1 1} {2 3 4}][Start-Before]
018235 INFO S3:[{1 1 1} {2 3 4} {3 3 5}][Start-After]
018235 LEAD S3-term:3-state:2[BeginHeart]
018237 INFO S0:state:0:term:3-ReceiveFrom-S3[AppendEntries]
018237 INFO S0:term:[{1 1 1} {2 3 4}][Add-Before]
018237 INFO S0FromS3:[{3 3 5}][Adding]
018237 INFO S0FromS3:[{1 1 1} {2 3 4} {3 3 5}][Add-After]
018237 INFO S4:state:0:term:3-ReceiveFrom-S3[AppendEntries]
018237 INFO S4:term:[{1 1 1} {2 3 4}][Add-Before]
018237 INFO S4FromS3:[{3 3 5}][Adding]
018237 INFO S4FromS3:[{1 1 1} {2 3 4} {3 3 5}][Add-After]
018238 INFO S3[Heartbeat]
cnt,len(rf.peers) 3 5
019618 LEAD S3-term:3-state:2[BeginHeart]
019618 LEAD S1-term:1-state:2[BeginHeart]
[TestBackup2B]==pass6
020674 INFO S0:term:3 ==> S3-term:2[Enter-RequestVote]
020675 INFO S0 ==> S3-term:2[RequestVote]
020678 INFO S3-term:3-state:2 => 0[RPC-Vote-Over]
020796 INFO S2term:3=state:1=[StartElect]
020805 INFO S2-term:3-state:1 => 4[RPC-Vote]
020809 INFO S2-term:3-state:1 => 0[RPC-Vote]
020811 INFO S2-term:3-state:1 => 3[RPC-Vote]
020811 INFO S2-term:3-state:1 => 1[RPC-Vote]
021126 LEAD S1-term:1-state:2[BeginHeart]
021126 LEAD S3-term:3-state:2[BeginHeart]
022630 LEAD S3-term:3-state:2[BeginHeart]
022632 LEAD S1-term:1-state:2[BeginHeart]
024076 INFO S2term:4=state:1=[StartElect]
024077 INFO S2-term:4-state:1 => 4[RPC-Vote]
024078 INFO S2-term:4-state:1 => 3[RPC-Vote]
024078 INFO S2-term:4-state:1 => 0[RPC-Vote]
024078 INFO S2-term:4-state:1 => 1[RPC-Vote]
024141 LEAD S1-term:1-state:2[BeginHeart]
024145 LEAD S3-term:3-state:2[BeginHeart]
Pass==checkOneLeader()
leader2: 3
other: 4
[TestBackup2B]==pass7
024386 INFO S3command6[ReceiveLog]
024386 INFO S3:[{1 1 1} {2 3 4} {3 3 5}][Start-Before]
024386 INFO S3:[{1 1 1} {2 3 4} {3 3 5} {4 3 6}][Start-After]
024386 LEAD S3-term:3-state:2[BeginHeart]
024386 INFO S3command7[ReceiveLog]
024386 INFO S3:[{1 1 1} {2 3 4} {3 3 5} {4 3 6}][Start-Before]
024386 INFO S3:[{1 1 1} {2 3 4} {3 3 5} {4 3 6} {5 3 7}][Start-After]
024387 LEAD S3-term:3-state:2[BeginHeart]
[TestBackup2B]==pass8
024389 INFO S0:state:0:term:3-ReceiveFrom-S3[AppendEntries]
024389 INFO S0:term:[{1 1 1} {2 3 4} {3 3 5}][Add-Before]
024389 INFO S0FromS3:[{4 3 6}][Adding]
024389 INFO S0FromS3:[{1 1 1} {2 3 4} {3 3 5} {4 3 6}][Add-After]
024390 INFO S0:state:0:term:3-ReceiveFrom-S3[AppendEntries]
024390 INFO S0:term:[{1 1 1} {2 3 4} {3 3 5}][Add-Before]
024390 INFO S0FromS3:[{4 3 6} {5 3 7}][Adding]
024390 INFO S0FromS3:[{1 1 1} {2 3 4} {3 3 5} {4 3 6} {5 3 7}][Add-After]
025647 LEAD S1-term:1-state:2[BeginHeart]
025653 LEAD S3-term:3-state:2[BeginHeart]
026405 INFO S2term:5=state:1=[StartElect]
026405 INFO S2-term:5-state:1 => 4[RPC-Vote]
026406 INFO S2-term:5-state:1 => 3[RPC-Vote]
026406 INFO S2-term:5-state:1 => 1[RPC-Vote]
026406 INFO S2-term:5-state:1 => 0[RPC-Vote]
027406 LEAD S1-term:1-state:2[BeginHeart]
027408 LEAD S3-term:3-state:2[BeginHeart]
028572 INFO S2term:6=state:1=[StartElect]
028573 INFO S2-term:6-state:1 => 4[RPC-Vote]
028573 INFO S2-term:6-state:1 => 1[RPC-Vote]
028573 INFO S2-term:6-state:1 => 3[RPC-Vote]
028573 INFO S2-term:6-state:1 => 0[RPC-Vote]
028907 LEAD S1-term:1-state:2[BeginHeart]
028918 LEAD S3-term:3-state:2[BeginHeart]
[TestBackup2B]==pass9
029388 INFO S1command8[ReceiveLog]
029388 INFO S1:[{1 1 1} {2 1 2} {3 1 3}][Start-Before]
029388 INFO S1:[{1 1 1} {2 1 2} {3 1 3} {4 1 8}][Start-After]
029388 LEAD S1-term:1-state:2[BeginHeart]
029997 INFO S4term:4=state:1=[StartElect]
029998 INFO S4-term:4-state:1 => 3[RPC-Vote]
029998 INFO S4-term:4-state:1 => 0[RPC-Vote]
029998 INFO S4-term:4-state:1 => 1[RPC-Vote]
029998 INFO S4-term:4-state:1 => 2[RPC-Vote]
030000 INFO S2:term:6 ==> S4-term:4[Enter-RequestVote]
030000 INFO S2 ==> S4-term:4[RequestVote]
030000 INFO S4-term:4-state:1 => 2[RPC-Vote-Over]
030000 INFO S1:term:3 ==> S4-term:4[Enter-RequestVote]
030000 INFO S1 ==> S4-term:4[RequestVote]
030001 INFO S1:state:0:term:3-changeTo-state:0:term:4[RequestVote1]
030001 INFO S1:state:0-changeTo-state:0[RequestVote2]
030001 INFO S4-term:6-state:0 => 1[RPC-Vote-Over]
030422 LEAD S3-term:3-state:2[BeginHeart]
031050 INFO S2term:7=state:1=[StartElect]
031051 INFO S2-term:7-state:1 => 4[RPC-Vote]
031051 INFO S2-term:7-state:1 => 1[RPC-Vote]
031052 INFO S2-term:7-state:1 => 3[RPC-Vote]
031052 INFO S2-term:7-state:1 => 0[RPC-Vote]
031052 INFO S4:term:6 ==> S2-term:7[Enter-RequestVote]
031053 INFO S4 ==> S2-term:7[RequestVote]
031053 INFO S4:state:0:term:6-changeTo-state:0:term:7[RequestVote1]
031053 INFO S4:state:0:term:7-LogFailOK[RequestVote3]%!(EXTRA int=0, int=7)
031055 INFO S1:term:4 ==> S2-term:7[Enter-RequestVote]
031055 INFO S1 ==> S2-term:7[RequestVote]
031055 INFO S1:state:0:term:4-changeTo-state:0:term:7[RequestVote1]
031055 INFO S1:state:0:term:7-LogFailOK[RequestVote3]%!(EXTRA int=0, int=7)
031056 INFO S2-term:7-state:1 => 1[RPC-Vote-Over]
031055 INFO S2-term:7-state:1 => 4[RPC-Vote-Over]
031879 INFO S0term:4=state:1=[StartElect]
031880 INFO S0-term:4-state:1 => 4[RPC-Vote]
031880 INFO S0-term:4-state:1 => 2[RPC-Vote]
031880 INFO S0-term:4-state:1 => 3[RPC-Vote]
031880 INFO S0-term:4-state:1 => 1[RPC-Vote]
031927 LEAD S3-term:3-state:2[BeginHeart]
033440 LEAD S3-term:3-state:2[BeginHeart]
033468 INFO S4term:8=state:1=[StartElect]
033469 INFO S4-term:8-state:1 => 3[RPC-Vote]
033469 INFO S4-term:8-state:1 => 0[RPC-Vote]
033470 INFO S4-term:8-state:1 => 2[RPC-Vote]
033471 INFO S4-term:8-state:1 => 1[RPC-Vote]
033471 INFO S2:term:7 ==> S4-term:8[Enter-RequestVote]
033472 INFO S2 ==> S4-term:8[RequestVote]
033472 INFO S2:state:1:term:7-changeTo-state:0:term:8[RequestVote1]
033472 INFO S2:state:0-changeTo-state:0[RequestVote2]
033472 INFO S1:term:7 ==> S4-term:8[Enter-RequestVote]
033472 INFO S1 ==> S4-term:8[RequestVote]
033472 INFO S1:state:0:term:7-changeTo-state:0:term:8[RequestVote1]
033472 INFO S1:state:0-changeTo-state:0[RequestVote2]
033472 INFO S4-term:8-state:1 => 2[RPC-Vote-Over]
033472 TIMR S4Vote<--2[Vote]
033473 INFO S4-term:8-state:1 => 1[RPC-Vote-Over]
033473 TIMR S4Vote<--1[Vote]
033473 INFO S4:state:1-changeTo-state:2[BecomeLeader]
033473 LEAD S4-term:8-state:2[BecomeLeader]
033473 LEAD S4-term:8-state:2[BeginHeart]
034551 INFO S0term:5=state:1=[StartElect]
034552 INFO S0-term:5-state:1 => 4[RPC-Vote]
034552 INFO S0-term:5-state:1 => 2[RPC-Vote]
034552 INFO S0-term:5-state:1 => 3[RPC-Vote]
034552 INFO S0-term:5-state:1 => 1[RPC-Vote]
034951 LEAD S3-term:3-state:2[BeginHeart]
034952 LEAD S4-term:8-state:2[BeginHeart]
034954 INFO S1:state:0:term:8-ReceiveFrom-S4[AppendEntries]
034954 INFO S1:term:[{1 1 1}][Add-Before]
034954 INFO S1FromS4:[{2 3 4} {3 3 5}][Adding]
034954 INFO S1FromS4:[{1 1 1} {2 3 4} {3 3 5}][Add-After]
034955 INFO S2:state:0:term:8-ReceiveFrom-S4[AppendEntries]
034955 INFO S2:term:[{1 1 1}][Add-Before]
034955 INFO S2FromS4:[{2 3 4} {3 3 5}][Adding]
034955 INFO S2FromS4:[{1 1 1} {2 3 4} {3 3 5}][Add-After]
037185 LEAD S3-term:3-state:2[BeginHeart]
037185 LEAD S4-term:8-state:2[BeginHeart]
037201 INFO S1:term:8 ==> S2-term:6[Enter-RequestVote]
037201 INFO S1 ==> S2-term:6[RequestVote]
037201 INFO S2-term:8-state:0 => 1[RPC-Vote-Over]
037740 INFO S1:term:8 ==> S2-term:3[Enter-RequestVote]
037740 INFO S1 ==> S2-term:3[RequestVote]
037741 INFO S2-term:8-state:0 => 1[RPC-Vote-Over]
037938 INFO S1:term:8 ==> S2-term:4[Enter-RequestVote]
037939 INFO S1 ==> S2-term:4[RequestVote]
037939 INFO S2-term:8-state:0 => 1[RPC-Vote-Over]
038691 LEAD S4-term:8-state:2[BeginHeart]
038693 INFO S4:term:8 ==> S2-term:2[Enter-RequestVote]
038694 INFO S4 ==> S2-term:2[RequestVote]
038692 LEAD S3-term:3-state:2[BeginHeart]
038694 INFO S2-term:8-state:0 => 4[RPC-Vote-Over]
039984 INFO S0term:6=state:1=[StartElect]
039985 INFO S0-term:6-state:1 => 4[RPC-Vote]
039985 INFO S0-term:6-state:1 => 2[RPC-Vote]
039986 INFO S0-term:6-state:1 => 1[RPC-Vote]
039986 INFO S0-term:6-state:1 => 3[RPC-Vote]
040203 LEAD S3-term:3-state:2[BeginHeart]
040204 LEAD S4-term:8-state:2[BeginHeart]
041708 LEAD S4-term:8-state:2[BeginHeart]
041709 LEAD S3-term:3-state:2[BeginHeart]
043219 LEAD S3-term:3-state:2[BeginHeart]
043220 LEAD S4-term:8-state:2[BeginHeart]
043885 INFO S0term:7=state:1=[StartElect]
043886 INFO S0-term:7-state:1 => 4[RPC-Vote]
043886 INFO S0-term:7-state:1 => 2[RPC-Vote]
043887 INFO S0-term:7-state:1 => 1[RPC-Vote]
043887 INFO S0-term:7-state:1 => 3[RPC-Vote]
044733 LEAD S4-term:8-state:2[BeginHeart]
044733 LEAD S3-term:3-state:2[BeginHeart]
045684 INFO S4:term:8 ==> S2-term:5[Enter-RequestVote]
045684 INFO S4 ==> S2-term:5[RequestVote]
045685 INFO S2-term:8-state:0 => 4[RPC-Vote-Over]
046235 LEAD S4-term:8-state:2[BeginHeart]
046235 LEAD S3-term:3-state:2[BeginHeart]
047741 LEAD S4-term:8-state:2[BeginHeart]
047747 LEAD S3-term:3-state:2[BeginHeart]
048161 INFO S0term:8=state:1=[StartElect]
048162 INFO S0-term:8-state:1 => 4[RPC-Vote]
048162 INFO S0-term:8-state:1 => 2[RPC-Vote]
048162 INFO S0-term:8-state:1 => 1[RPC-Vote]
048163 INFO S0-term:8-state:1 => 3[RPC-Vote]
049254 LEAD S3-term:3-state:2[BeginHeart]
049255 LEAD S4-term:8-state:2[BeginHeart]
049426 INFO S4command8[ReceiveLog]
049427 INFO S4:[{1 1 1} {2 3 4} {3 3 5}][Start-Before]
049427 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8}][Start-After]
049427 LEAD S4-term:8-state:2[BeginHeart]
049430 INFO S1:state:0:term:8-ReceiveFrom-S4[AppendEntries]
049430 INFO S1:term:[{1 1 1} {2 3 4} {3 3 5}][Add-Before]
049430 INFO S1FromS4:[{4 8 8}][Adding]
049430 INFO S1FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8}][Add-After]
049430 INFO S2:state:0:term:8-ReceiveFrom-S4[AppendEntries]
049430 INFO S2:term:[{1 1 1} {2 3 4} {3 3 5}][Add-Before]
049430 INFO S2FromS4:[{4 8 8}][Adding]
049431 INFO S2FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8}][Add-After]
049432 INFO S4[Heartbeat]
cnt,len(rf.peers) 3 5
050729 INFO S0term:9=state:1=[StartElect]
050730 INFO S0-term:9-state:1 => 4[RPC-Vote]
050730 INFO S0-term:9-state:1 => 1[RPC-Vote]
050731 INFO S0-term:9-state:1 => 2[RPC-Vote]
050731 INFO S0-term:9-state:1 => 3[RPC-Vote]
050763 LEAD S3-term:3-state:2[BeginHeart]
050763 LEAD S4-term:8-state:2[BeginHeart]
050935 INFO S4command9[ReceiveLog]
050935 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8}][Start-Before]
050936 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9}][Start-After]
050936 LEAD S4-term:8-state:2[BeginHeart]
050937 INFO S1:state:0:term:8-ReceiveFrom-S4[AppendEntries]
050937 INFO S1:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8}][Add-Before]
050937 INFO S1FromS4:[{5 8 9}][Adding]
050937 INFO S1FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9}][Add-After]
050937 INFO S2:state:0:term:8-ReceiveFrom-S4[AppendEntries]
050937 INFO S2:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8}][Add-Before]
050937 INFO S2FromS4:[{5 8 9}][Adding]
050937 INFO S2FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9}][Add-After]
050938 INFO S4[Heartbeat]
cnt,len(rf.peers) 3 5
052268 LEAD S4-term:8-state:2[BeginHeart]
052268 LEAD S3-term:3-state:2[BeginHeart]
[TestBackup2B]==pass10
[TestBackup2B]==pass11
052400 INFO S3command10[ReceiveLog]
052400 INFO S3:[{1 1 1} {2 3 4} {3 3 5} {4 3 6} {5 3 7}][Start-Before]
052400 INFO S3:[{1 1 1} {2 3 4} {3 3 5} {4 3 6} {5 3 7} {6 3 10}][Start-After]
052400 LEAD S3-term:3-state:2[BeginHeart]
052574 INFO S1:term:8 ==> S2-term:5[Enter-RequestVote]
052574 INFO S1 ==> S2-term:5[RequestVote]
052575 INFO S2-term:8-state:0 => 1[RPC-Vote-Over]
053522 INFO S3:state:0:term:8-ReceiveFrom-S4[AppendEntries]
053522 INFO S3:term:[{1 1 1} {2 3 4} {3 3 5}][Add-Before]
053522 INFO S3FromS4:[{4 8 8} {5 8 9}][Adding]
053522 INFO S3FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9}][Add-After]
053523 INFO S4:term:8 ==> S2-term:3[Enter-RequestVote]
053524 INFO S4 ==> S2-term:3[RequestVote]
053524 INFO S2-term:8-state:0 => 4[RPC-Vote-Over]
053777 LEAD S4-term:8-state:2[BeginHeart]
054829 INFO S3:state:0:term:8-ReceiveFrom-S4[AppendEntries]
054829 INFO S3:term:[{1 1 1} {2 3 4} {3 3 5}][Add-Before]
054829 INFO S3FromS4:[{4 8 8}][Adding]
054829 INFO S3FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8}][Add-After]
055130 INFO S0term:10=state:1=[StartElect]
055131 INFO S0-term:10-state:1 => 4[RPC-Vote]
055131 INFO S0-term:10-state:1 => 2[RPC-Vote]
055131 INFO S0-term:10-state:1 => 1[RPC-Vote]
055131 INFO S0-term:10-state:1 => 3[RPC-Vote]
055132 INFO S1:term:8 ==> S0-term:10[Enter-RequestVote]
055132 INFO S1 ==> S0-term:10[RequestVote]
055132 INFO S2:term:8 ==> S0-term:10[Enter-RequestVote]
055132 INFO S1:state:0:term:8-changeTo-state:0:term:10[RequestVote1]
055132 INFO S2 ==> S0-term:10[RequestVote]
055132 INFO S2:state:0:term:8-changeTo-state:0:term:10[RequestVote1]
055132 INFO S1:state:0:term:10-LogFailOK[RequestVote3]%!(EXTRA int=0, int=10)
055132 INFO S2:state:0:term:10-LogFailOK[RequestVote3]%!(EXTRA int=0, int=10)
055132 INFO S3:term:8 ==> S0-term:10[Enter-RequestVote]
055132 INFO S3 ==> S0-term:10[RequestVote]
055132 INFO S3:state:0:term:8-changeTo-state:0:term:10[RequestVote1]
055132 INFO S3:state:0:term:10-LogFailOK[RequestVote3]%!(EXTRA int=0, int=10)
055132 INFO S4:term:9 ==> S0-term:10[Enter-RequestVote]
055132 INFO S0-term:10-state:1 => 1[RPC-Vote-Over]
055133 INFO S4 ==> S0-term:10[RequestVote]
055133 INFO S4:state:0:term:9-changeTo-state:0:term:10[RequestVote1]
055133 INFO S4:state:0:term:10-LogFailOK[RequestVote3]%!(EXTRA int=0, int=10)
055133 INFO S0-term:10-state:1 => 3[RPC-Vote-Over]
055133 INFO S0-term:10-state:1 => 2[RPC-Vote-Over]
055133 INFO S0-term:10-state:1 => 4[RPC-Vote-Over]
055467 INFO S1:term:10 ==> S0-term:5[Enter-RequestVote]
055468 INFO S1 ==> S0-term:5[RequestVote]
055468 INFO S0-term:10-state:1 => 1[RPC-Vote-Over]
055890 INFO S4term:11=state:1=[StartElect]
055890 INFO S4-term:11-state:1 => 3[RPC-Vote]
055891 INFO S4-term:11-state:1 => 1[RPC-Vote]
055891 INFO S4-term:11-state:1 => 2[RPC-Vote]
055891 INFO S4-term:11-state:1 => 0[RPC-Vote]
055891 INFO S3:term:10 ==> S4-term:11[Enter-RequestVote]
055891 INFO S3 ==> S4-term:11[RequestVote]
055892 INFO S1:term:10 ==> S4-term:11[Enter-RequestVote]
055892 INFO S2:term:10 ==> S4-term:11[Enter-RequestVote]
055892 INFO S2 ==> S4-term:11[RequestVote]
055892 INFO S1 ==> S4-term:11[RequestVote]
055892 INFO S1:state:0:term:10-changeTo-state:0:term:11[RequestVote1]
055892 INFO S1:state:0-changeTo-state:0[RequestVote2]
055892 INFO S2:state:0:term:10-changeTo-state:0:term:11[RequestVote1]
055892 INFO S0:term:10 ==> S4-term:11[Enter-RequestVote]
055892 INFO S0 ==> S4-term:11[RequestVote]
055892 INFO S0:state:1:term:10-changeTo-state:0:term:11[RequestVote1]
055892 INFO S0:state:0-changeTo-state:0[RequestVote2]
055892 INFO S3:state:0:term:10-changeTo-state:0:term:11[RequestVote1]
055892 INFO S3:state:0-changeTo-state:0[RequestVote2]
055892 INFO S2:state:0-changeTo-state:0[RequestVote2]
055892 INFO S4-term:11-state:1 => 1[RPC-Vote-Over]
055892 TIMR S4Vote<--1[Vote]
055892 INFO S4-term:11-state:1 => 0[RPC-Vote-Over]
055892 TIMR S4Vote<--0[Vote]
055892 INFO S4:state:1-changeTo-state:2[BecomeLeader]
055892 LEAD S4-term:11-state:2[BecomeLeader]
055892 LEAD S4-term:11-state:2[BeginHeart]
055892 INFO S4-term:11-state:1 => 3[RPC-Vote-Over]
055892 INFO S4-term:11-state:2 => 2[RPC-Vote-Over]
056796 LEAD S4-term:11-state:2[BeginHeart]
056801 INFO S0:state:0:term:11-ReceiveFrom-S4[AppendEntries]
056802 INFO S0:term:[{1 1 1} {2 3 4} {3 3 5}][Add-Before]
056803 INFO S0FromS4:[{4 8 8} {5 8 9}][Adding]
056803 INFO S0FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9}][Add-After]
057735 INFO S3:term:11 ==> S0-term:9[Enter-RequestVote]
057736 INFO S3 ==> S0-term:9[RequestVote]
057737 INFO S0-term:11-state:0 => 3[RPC-Vote-Over]
058299 LEAD S4-term:11-state:2[BeginHeart]
059264 INFO S1:term:11 ==> S3-term:2[Enter-RequestVote]
059264 INFO S1 ==> S3-term:2[RequestVote]
059265 INFO S3-term:11-state:0 => 1[RPC-Vote-Over]
059439 INFO S1:term:11 ==> S0-term:8[Enter-RequestVote]
059439 INFO S1 ==> S0-term:8[RequestVote]
059440 INFO S0-term:11-state:0 => 1[RPC-Vote-Over]
059806 LEAD S4-term:11-state:2[BeginHeart]
060177 INFO S1:term:11 ==> S2-term:2[Enter-RequestVote]
060177 INFO S1 ==> S2-term:2[RequestVote]
060178 INFO S2-term:11-state:0 => 1[RPC-Vote-Over]
060980 INFO S3:term:11 ==> S2-term:7[Enter-RequestVote]
060980 INFO S3 ==> S2-term:7[RequestVote]
060980 INFO S2-term:11-state:0 => 3[RPC-Vote-Over]
061020 INFO S4:term:11 ==> S0-term:4[Enter-RequestVote]
061020 INFO S4 ==> S0-term:4[RequestVote]
061020 INFO S0-term:11-state:0 => 4[RPC-Vote-Over]
061308 LEAD S4-term:11-state:2[BeginHeart]
062475 INFO S3:term:11 ==> S2-term:4[Enter-RequestVote]
062476 INFO S3 ==> S2-term:4[RequestVote]
062476 INFO S2-term:11-state:0 => 3[RPC-Vote-Over]
063105 LEAD S4-term:11-state:2[BeginHeart]
063114 INFO S1:term:11 ==> S4-term:2[Enter-RequestVote]
063114 INFO S1 ==> S4-term:2[RequestVote]
063114 INFO S4-term:11-state:2 => 1[RPC-Vote-Over]
064020 INFO S0:term:11 ==> S4-term:4[Enter-RequestVote]
064020 INFO S0 ==> S4-term:4[RequestVote]
064020 INFO S4-term:11-state:2 => 0[RPC-Vote-Over]
064560 INFO S3:term:11 ==> S4-term:2[Enter-RequestVote]
064560 INFO S3 ==> S4-term:2[RequestVote]
064561 INFO S4-term:11-state:2 => 3[RPC-Vote-Over]
064620 LEAD S4-term:11-state:2[BeginHeart]
065309 INFO S3:term:11 ==> S0-term:5[Enter-RequestVote]
065314 INFO S3 ==> S0-term:5[RequestVote]
065315 INFO S0-term:11-state:0 => 3[RPC-Vote-Over]
065345 INFO S0:term:11 ==> S2-term:6[Enter-RequestVote]
065345 INFO S0 ==> S2-term:6[RequestVote]
065345 INFO S2-term:11-state:0 => 0[RPC-Vote-Over]
065898 INFO S4:term:11 ==> S0-term:7[Enter-RequestVote]
065898 INFO S4 ==> S0-term:7[RequestVote]
065898 INFO S0-term:11-state:0 => 4[RPC-Vote-Over]
066130 LEAD S4-term:11-state:2[BeginHeart]
067640 LEAD S4-term:11-state:2[BeginHeart]
068029 INFO S0:term:11 ==> S4-term:2[Enter-RequestVote]
068029 INFO S0 ==> S4-term:2[RequestVote]
068030 INFO S4-term:11-state:2 => 0[RPC-Vote-Over]
069037 INFO S2:term:11 ==> S4-term:2[Enter-RequestVote]
069038 INFO S2 ==> S4-term:2[RequestVote]
069038 INFO S4-term:11-state:2 => 2[RPC-Vote-Over]
069151 LEAD S4-term:11-state:2[BeginHeart]
069334 INFO S0:term:11 ==> S4-term:8[Enter-RequestVote]
069335 INFO S0 ==> S4-term:8[RequestVote]
069335 INFO S4-term:11-state:2 => 0[RPC-Vote-Over]
069613 INFO S4:term:11 ==> S3-term:2[Enter-RequestVote]
069613 INFO S4 ==> S3-term:2[RequestVote]
069613 INFO S3-term:11-state:0 => 4[RPC-Vote-Over]
070473 INFO S0:term:11 ==> S2-term:4[Enter-RequestVote]
070474 INFO S0 ==> S2-term:4[RequestVote]
070475 INFO S2-term:11-state:0 => 0[RPC-Vote-Over]
070665 LEAD S4-term:11-state:2[BeginHeart]
071747 INFO S2:term:11 ==> S3-term:2[Enter-RequestVote]
071748 INFO S2 ==> S3-term:2[RequestVote]
071749 INFO S3-term:11-state:0 => 2[RPC-Vote-Over]
072169 LEAD S4-term:11-state:2[BeginHeart]
073000 INFO S4command10[ReceiveLog]
073001 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9}][Start-Before]
073001 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10}][Start-After]
073001 LEAD S4-term:11-state:2[BeginHeart]
073002 INFO S0:state:0:term:11-ReceiveFrom-S4[AppendEntries]
073002 INFO S0:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9}][Add-Before]
073005 INFO S0FromS4:[{6 11 10}][Adding]
073005 INFO S0FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10}][Add-After]
073006 INFO S1:state:0:term:11-ReceiveFrom-S4[AppendEntries]
073006 INFO S1:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9}][Add-Before]
073006 INFO S1FromS4:[{6 11 10}][Adding]
073006 INFO S1FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10}][Add-After]
073007 INFO S4[Heartbeat]
cnt,len(rf.peers) 3 5
073022 INFO S2:state:0:term:11-ReceiveFrom-S4[AppendEntries]
073022 INFO S2:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9}][Add-Before]
073022 INFO S2FromS4:[{6 11 10}][Adding]
073022 INFO S2FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10}][Add-After]
073678 LEAD S4-term:11-state:2[BeginHeart]
073815 INFO S4:term:11 ==> S0-term:8[Enter-RequestVote]
073815 INFO S4 ==> S0-term:8[RequestVote]
073816 INFO S0-term:11-state:0 => 4[RPC-Vote-Over]
074216 INFO S3:term:11 ==> S4-term:4[Enter-RequestVote]
074217 INFO S3 ==> S4-term:4[RequestVote]
074217 INFO S4-term:11-state:2 => 3[RPC-Vote-Over]
074328 INFO S4:term:11 ==> S2-term:4[Enter-RequestVote]
074328 INFO S4 ==> S2-term:4[RequestVote]
074329 INFO S2-term:11-state:0 => 4[RPC-Vote-Over]
074448 INFO S2:term:11 ==> S0-term:2[Enter-RequestVote]
074448 INFO S2 ==> S0-term:2[RequestVote]
074448 INFO S0-term:11-state:0 => 2[RPC-Vote-Over]
074986 INFO S3:term:11 ==> S2-term:6[Enter-RequestVote]
074986 INFO S3 ==> S2-term:6[RequestVote]
074987 INFO S2-term:11-state:0 => 3[RPC-Vote-Over]
075181 LEAD S4-term:11-state:2[BeginHeart]
075327 INFO S2:term:11 ==> S0-term:8[Enter-RequestVote]
075327 INFO S2 ==> S0-term:8[RequestVote]
075328 INFO S0-term:11-state:0 => 2[RPC-Vote-Over]
075845 INFO S1:term:11 ==> S0-term:2[Enter-RequestVote]
075845 INFO S1 ==> S0-term:2[RequestVote]
075848 INFO S0-term:11-state:0 => 1[RPC-Vote-Over]
076691 LEAD S4-term:11-state:2[BeginHeart]
078192 LEAD S4-term:11-state:2[BeginHeart]
078750 INFO S3:term:11 ==> S0-term:4[Enter-RequestVote]
078750 INFO S3 ==> S0-term:4[RequestVote]
078750 INFO S0-term:11-state:0 => 3[RPC-Vote-Over]
079696 LEAD S4-term:11-state:2[BeginHeart]
079874 INFO S2:term:11 ==> S3-term:3[Enter-RequestVote]
079875 INFO S2 ==> S3-term:3[RequestVote]
079876 INFO S3-term:11-state:0 => 2[RPC-Vote-Over]
081197 LEAD S4-term:11-state:2[BeginHeart]
081264 INFO S1:term:11 ==> S3-term:3[Enter-RequestVote]
081264 INFO S1 ==> S3-term:3[RequestVote]
081265 INFO S3-term:11-state:0 => 1[RPC-Vote-Over]
081375 INFO S4:term:11 ==> S0-term:6[Enter-RequestVote]
081375 INFO S4 ==> S0-term:6[RequestVote]
081376 INFO S0-term:11-state:0 => 4[RPC-Vote-Over]
082017 INFO S4:term:11 ==> S2-term:6[Enter-RequestVote]
082017 INFO S4 ==> S2-term:6[RequestVote]
082018 INFO S2-term:11-state:0 => 4[RPC-Vote-Over]
082051 INFO S0:term:11 ==> S2-term:5[Enter-RequestVote]
082051 INFO S0 ==> S2-term:5[RequestVote]
082052 INFO S2-term:11-state:0 => 0[RPC-Vote-Over]
082887 LEAD S4-term:11-state:2[BeginHeart]
084393 LEAD S4-term:11-state:2[BeginHeart]
085900 LEAD S4-term:11-state:2[BeginHeart]
087402 LEAD S4-term:11-state:2[BeginHeart]
087655 INFO S1:term:11 ==> S0-term:6[Enter-RequestVote]
087656 INFO S1 ==> S0-term:6[RequestVote]
087657 INFO S0-term:11-state:0 => 1[RPC-Vote-Over]
088928 LEAD S4-term:11-state:2[BeginHeart]
089334 INFO S3:term:11 ==> S2-term:5[Enter-RequestVote]
089335 INFO S3 ==> S2-term:5[RequestVote]
089335 INFO S2-term:11-state:0 => 3[RPC-Vote-Over]
089791 INFO S0:term:11 ==> S2-term:7[Enter-RequestVote]
089791 INFO S0 ==> S2-term:7[RequestVote]
089792 INFO S2-term:11-state:0 => 0[RPC-Vote-Over]
090443 LEAD S4-term:11-state:2[BeginHeart]
091273 INFO S2:term:11 ==> S0-term:9[Enter-RequestVote]
091274 INFO S2 ==> S0-term:9[RequestVote]
091274 INFO S0-term:11-state:0 => 2[RPC-Vote-Over]
091532 INFO S0:term:11 ==> S2-term:3[Enter-RequestVote]
091532 INFO S0 ==> S2-term:3[RequestVote]
091532 INFO S2-term:11-state:0 => 0[RPC-Vote-Over]
091651 INFO S3:term:11 ==> S2-term:3[Enter-RequestVote]
091652 INFO S3 ==> S2-term:3[RequestVote]
091652 INFO S2-term:11-state:0 => 3[RPC-Vote-Over]
092029 LEAD S4-term:11-state:2[BeginHeart]
093068 INFO S4command10[ReceiveLog]
093068 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10}][Start-Before]
093068 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10}][Start-After]
093068 LEAD S4-term:11-state:2[BeginHeart]
093070 INFO S0:state:0:term:11-ReceiveFrom-S4[AppendEntries]
093070 INFO S0:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10}][Add-Before]
093070 INFO S0FromS4:[{7 11 10}][Adding]
093070 INFO S0FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10}][Add-After]
093070 INFO S1:state:0:term:11-ReceiveFrom-S4[AppendEntries]
093071 INFO S1:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10}][Add-Before]
093071 INFO S1FromS4:[{7 11 10}][Adding]
093071 INFO S1FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10}][Add-After]
093071 INFO S4[Heartbeat]
cnt,len(rf.peers) 3 5
093071 INFO S2:state:0:term:11-ReceiveFrom-S4[AppendEntries]
093071 INFO S2:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10}][Add-Before]
093071 INFO S2FromS4:[{7 11 10}][Adding]
093071 INFO S2FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10}][Add-After]
093341 INFO S4:term:11 ==> S0-term:5[Enter-RequestVote]
093341 INFO S4 ==> S0-term:5[RequestVote]
093341 INFO S0-term:11-state:0 => 4[RPC-Vote-Over]
093532 LEAD S4-term:11-state:2[BeginHeart]
093665 INFO S4:term:11 ==> S0-term:9[Enter-RequestVote]
093665 INFO S4 ==> S0-term:9[RequestVote]
093666 INFO S0-term:11-state:0 => 4[RPC-Vote-Over]
095038 LEAD S4-term:11-state:2[BeginHeart]
095039 INFO S1:term:11 ==> S0-term:9[Enter-RequestVote]
095039 INFO S1 ==> S0-term:9[RequestVote]
095039 INFO S0-term:11-state:0 => 1[RPC-Vote-Over]
096159 INFO S3:term:11 ==> S4-term:8[Enter-RequestVote]
096160 INFO S3 ==> S4-term:8[RequestVote]
096161 INFO S4-term:11-state:2 => 3[RPC-Vote-Over]
096549 LEAD S4-term:11-state:2[BeginHeart]
097435 INFO S2:term:11 ==> S0-term:5[Enter-RequestVote]
097435 INFO S2 ==> S0-term:5[RequestVote]
097436 INFO S0-term:11-state:0 => 2[RPC-Vote-Over]
097546 INFO S1:term:11 ==> S0-term:4[Enter-RequestVote]
097547 INFO S1 ==> S0-term:4[RequestVote]
097547 INFO S0-term:11-state:0 => 1[RPC-Vote-Over]
097991 INFO S0:term:11 ==> S2-term:2[Enter-RequestVote]
097992 INFO S0 ==> S2-term:2[RequestVote]
097992 INFO S2-term:11-state:0 => 0[RPC-Vote-Over]
098062 LEAD S4-term:11-state:2[BeginHeart]
098086 INFO S2:term:11 ==> S0-term:4[Enter-RequestVote]
098087 INFO S2 ==> S0-term:4[RequestVote]
098087 INFO S0-term:11-state:0 => 2[RPC-Vote-Over]
099568 LEAD S4-term:11-state:2[BeginHeart]
101084 LEAD S4-term:11-state:2[BeginHeart]
101391 INFO S3:term:11 ==> S0-term:8[Enter-RequestVote]
101391 INFO S3 ==> S0-term:8[RequestVote]
101392 INFO S0-term:11-state:0 => 3[RPC-Vote-Over]
102594 LEAD S4-term:11-state:2[BeginHeart]
104103 LEAD S4-term:11-state:2[BeginHeart]
105058 INFO S2:term:11 ==> S0-term:7[Enter-RequestVote]
105058 INFO S2 ==> S0-term:7[RequestVote]
105059 INFO S0-term:11-state:0 => 2[RPC-Vote-Over]
105621 LEAD S4-term:11-state:2[BeginHeart]
106396 INFO S3:term:11 ==> S0-term:7[Enter-RequestVote]
106397 INFO S3 ==> S0-term:7[RequestVote]
106398 INFO S0-term:11-state:0 => 3[RPC-Vote-Over]
107135 LEAD S4-term:11-state:2[BeginHeart]
107547 INFO S2:term:11 ==> S0-term:6[Enter-RequestVote]
107548 INFO S2 ==> S0-term:6[RequestVote]
107550 INFO S0-term:11-state:0 => 2[RPC-Vote-Over]
108036 INFO S3:term:11 ==> S0-term:6[Enter-RequestVote]
108036 INFO S3 ==> S0-term:6[RequestVote]
108037 INFO S0-term:11-state:0 => 3[RPC-Vote-Over]
108644 LEAD S4-term:11-state:2[BeginHeart]
110156 LEAD S4-term:11-state:2[BeginHeart]
110392 INFO S3:term:11 ==> S2-term:2[Enter-RequestVote]
110392 INFO S3 ==> S2-term:2[RequestVote]
110393 INFO S2-term:11-state:0 => 3[RPC-Vote-Over]
111658 LEAD S4-term:11-state:2[BeginHeart]
112401 INFO S1:term:11 ==> S0-term:7[Enter-RequestVote]
112401 INFO S1 ==> S0-term:7[RequestVote]
112401 INFO S0-term:11-state:0 => 1[RPC-Vote-Over]
113164 LEAD S4-term:11-state:2[BeginHeart]
113229 INFO S4command10[ReceiveLog]
113229 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10}][Start-Before]
113229 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10}][Start-After]
113230 LEAD S4-term:11-state:2[BeginHeart]
113231 INFO S0:state:0:term:11-ReceiveFrom-S4[AppendEntries]
113231 INFO S0:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10}][Add-Before]
113231 INFO S0FromS4:[{8 11 10}][Adding]
113231 INFO S0FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10}][Add-After]
113232 INFO S1:state:0:term:11-ReceiveFrom-S4[AppendEntries]
113232 INFO S1:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10}][Add-Before]
113232 INFO S1FromS4:[{8 11 10}][Adding]
113232 INFO S1FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10}][Add-After]
113232 INFO S4[Heartbeat]
cnt,len(rf.peers) 3 5
113232 INFO S2:state:0:term:11-ReceiveFrom-S4[AppendEntries]
113232 INFO S2:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10}][Add-Before]
113232 INFO S2FromS4:[{8 11 10}][Adding]
113232 INFO S2FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10}][Add-After]
114675 LEAD S4-term:11-state:2[BeginHeart]
116176 LEAD S4-term:11-state:2[BeginHeart]
117684 LEAD S4-term:11-state:2[BeginHeart]
119194 LEAD S4-term:11-state:2[BeginHeart]
120697 LEAD S4-term:11-state:2[BeginHeart]
122202 LEAD S4-term:11-state:2[BeginHeart]
123704 LEAD S4-term:11-state:2[BeginHeart]
125206 LEAD S4-term:11-state:2[BeginHeart]
126716 LEAD S4-term:11-state:2[BeginHeart]
128226 LEAD S4-term:11-state:2[BeginHeart]
129728 LEAD S4-term:11-state:2[BeginHeart]
131244 LEAD S4-term:11-state:2[BeginHeart]
132747 LEAD S4-term:11-state:2[BeginHeart]
133387 INFO S4command10[ReceiveLog]
133388 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10}][Start-Before]
133389 INFO S4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10} {9 11 10}][Start-After]
133389 LEAD S4-term:11-state:2[BeginHeart]
133396 INFO S1:state:0:term:11-ReceiveFrom-S4[AppendEntries]
133402 INFO S1:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10}][Add-Before]
133403 INFO S1FromS4:[{9 11 10}][Adding]
133403 INFO S1FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10} {9 11 10}][Add-After]
133398 INFO S2:state:0:term:11-ReceiveFrom-S4[AppendEntries]
133406 INFO S2:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10}][Add-Before]
133406 INFO S2FromS4:[{9 11 10}][Adding]
133406 INFO S2FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10} {9 11 10}][Add-After]
133407 INFO S4[Heartbeat]
cnt,len(rf.peers) 3 5
133401 INFO S0:state:0:term:11-ReceiveFrom-S4[AppendEntries]
133408 INFO S0:term:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10}][Add-Before]
133408 INFO S0FromS4:[{9 11 10}][Adding]
133408 INFO S0FromS4:[{1 1 1} {2 3 4} {3 3 5} {4 8 8} {5 8 9} {6 11 10} {7 11 10} {8 11 10} {9 11 10}][Add-After]
134252 LEAD S4-term:11-state:2[BeginHeart]
135771 LEAD S4-term:11-state:2[BeginHeart]
137283 LEAD S4-term:11-state:2[BeginHeart]
138796 LEAD S4-term:11-state:2[BeginHeart]
140300 LEAD S4-term:11-state:2[BeginHeart]
141808 LEAD S4-term:11-state:2[BeginHeart]
143324 LEAD S4-term:11-state:2[BeginHeart]
144839 LEAD S4-term:11-state:2[BeginHeart]
146339 LEAD S4-term:11-state:2[BeginHeart]
147845 LEAD S4-term:11-state:2[BeginHeart]
149381 LEAD S4-term:11-state:2[BeginHeart]
150890 LEAD S4-term:11-state:2[BeginHeart]
152401 LEAD S4-term:11-state:2[BeginHeart]
--- FAIL: TestBackupCopy2B (15.35s)
config.go:616: [point2]one(10) failed to reach agreement
FAIL
exit status 1
FAIL 6.824/raft 15.356s

image-20240915145024791

由于代码中少考虑了一个情况:如果当前节点提交的Index比传过来的还高,说明当前节点的日志已经超前,需返回过去

image-20240915144939007
跑100echo

image-20240915144958097

跑200echo

image-20240915145006201

网络分区情况: