apache / apache/iotdb

Would raft-related request get the correct term in the situation?

Ouverte
#4,320 0 commentaires 0 réactions 0 personnes assignées Voir sur GitHub
Langage dominant
Java
Étoiles
6.4k
Forks
1.2k
Merge moyen
1 j 23 h
PR mergées (30 j)
115

Description

Let's consider the below scenarios.

## Scenario1
3 replica, 3 nodes
```
t0 - term=1, node1: leader, node1, node2: follower
t1 - node3 timeout when checking heartbeat, start election for term=2 and get vote from node1,
t2 - node2 timeout when checking heartbeat, going to start election, thread is hang by system, term=1
t3 - node2 receive election request for term=2, accept the election, vote for node3, update term=2 and became follower
t4 - node2 continue the election, get lock of `term`, construct an election request with term=3 and send out
```
In the scenario, we can see that node2 timeout in term=1 but started an election for term=3. I think this should be a bug although it won't make system run into some wrong status.

If the bug in scenario1 is benign, then I think the next one is very serious.
## Senario2
3 replica, 3 nodes
```
t0 - term=1, node1: leader, node1, node2: follower
t1 - node1 is going to appendLog() to node2, thread is scheduled out by system before construct the AppendEntryRequest.
t2 - network partition happens between node1 and node2, node3. node2 and node3 can communication with each other.
t3 - node3 becomes the leader in term=2 after election
t4 - network partition recover
t5 - node1 receives the election request from node3, and accept the election, vote for node3, updates term=2
t6 - node1 continue the appendLog() thread and send appendLog() for term=2
```
In the scenario, node1 has become follower in term=2 but still send out log to node2 with term=2. This will cause node2 run into mess and then ruin the whole raft group.

## Summary
No matter scenario1 or scenario2, the bugs happen because we don't sync term well. IMHO, if we want to solve the bugs by sync on term, it's really very hard and may make everything into serialization. Maybe a better way is isolating between terms in some way. (Ratis makes term final and create new instance for each term).

After reviewing code, I think both scenarios would happen in the latest code. Correct me if anything is wrong and welcome to discuss.

Actually the scenarios come from our test environment(making the build from rel/0.12 branch). As our server run into wired status because too many inodes, it run slowly at that time and we found the scenarios from log. Below are the log after organization. Please send email to me for raw logs if you want to analysis.

### meta group log for scenario1
```
// Node09 received election request from Node08
2021-10-28 20:55:45,812 [MetaHeartbeatClientThread-3] INFO o.a.i.c.s.m.RaftMember:1550 - Meta has update it's term to 4
2021-10-28 20:55:45,872 [MetaHeartbeatClientThread-3] INFO o.a.i.c.s.m.RaftMember:1592 - Meta has update it's voteFor to null
2021-10-28 20:55:45,872 [MetaHeartbeatClientThread-3] INFO o.a.i.c.s.m.RaftMember:654 - Meta has been set to null in term 4

// Node 09 heartbeat timeout, going to start election by set character to ELECTOR, at the time, term should be 3
2021-10-28 20:55:45,873 [Meta-HeartbeatThread@1634546688149] INFO o.a.i.c.s.h.HeartbeatThread:97 - Meta: The leader Node(internalIp:10.0.0.10, metaPort:9003, nodeIdentifier:-1501659200, dataPort:40010, clientPort:6667, clientIp:10.0.0.10) timed out

// Node09 agreed to vote for Node08,change character to follower, term=4
2021-10-28 20:55:45,873 [MetaHeartbeatClientThread-3] INFO o.a.i.c.s.m.RaftMember:656 - Meta has become a follower of Node(internalIp:10.0.0.8, metaPort:9003, nodeIdentifier:-1501774531, dataPort:40010, clientPort:6667, clientIp:10.0.0.8) in term 4

// Node09 election thread continue execution
2021-10-28 20:55:45,873 [Meta-HeartbeatThread@1634546688149] INFO o.a.i.c.s.m.RaftMember:634 - Meta has become a ELECTOR
2021-10-28 20:55:45,873 [Meta-HeartbeatThread@1634546688149] INFO o.a.i.c.s.m.RaftMember:654 - Meta has been set to null in term 4
2021-10-28 20:55:45,886 [Meta-HeartbeatThread@1634546688149] INFO o.a.i.c.s.h.HeartbeatThread:128 - Meta: Start elections

// Node09 received an duplicated election request from Node08, term=4
2021-10-28 20:55:45,886 [MetaHeartbeatClientThread-4] INFO o.a.i.c.s.m.RaftMember:1193 - Meta accepted an election request, term:4/4, logIndex:792/792, logTerm:2/2
2021-10-28 20:55:45,886 [MetaHeartbeatClientThread-4] INFO o.a.i.c.s.m.RaftMember:634 - Meta has become a FOLLOWER
2021-10-28 20:55:45,887 [MetaHeartbeatClientThread-4] INFO o.a.i.c.s.m.RaftMember:1592 - Meta has update it's voteFor to Node(internalIp:10.0.0.8, metaPort:9003, nodeIdentifier:-1501774531, dataPort:40010, clientPort:6667, clientIp:10.0.0.8)
2021-10-28 20:55:45,887 [MetaHeartbeatClientThread-4] INFO o.a.i.c.s.m.RaftMember:468 - Meta sending response -1 to the elector Node(internalIp:10.0.0.8, metaPort:9003, nodeIdentifier:-1501774531, dataPort:40010, clientPort:6667, clientIp:10.0.0.8)
2021-10-28 20:55:45,887 [MetaHeartbeatClientThread-2] INFO o.a.i.c.s.m.RaftMember:656 - Meta has become a follower of Node(internalIp:10.0.0.8, metaPort:9003, nodeIdentifier:-1501774531, dataPort:40010, clientPort:6667, clientIp:10.0.0.8) in term 4

// Node09 election thread continue execution, start a election in term=5
2021-10-28 20:55:45,887 [Meta-HeartbeatThread@1634546688149] INFO o.a.i.c.s.m.RaftMember:1592 - Meta has update it's voteFor to Node(internalIp:10.0.0.9, metaPort:9003, nodeIdentifier:-1501660166, dataPort:40010, clientPort:6667, clientIp:10.0.0.9)
2021-10-28 20:55:45,888 [Meta-HeartbeatThread@1634546688149] INFO o.a.i.c.s.h.HeartbeatThread:282 - Meta: Election 5 starts, quorum: 1
2021-10-28 20:55:45,888 [Meta-HeartbeatThread@1634546688149] INFO o.a.i.c.s.h.HeartbeatThread:314 - Meta: Wait for 20000ms until election time out
....
```

### log of Data(10.0.0.10) group for scenario2
```
// Node09 heartbeat timeout in term=1, update term=2 and start election request
2021-10-28 20:54:44,005 [Data(10.0.0.10:9003)-HeartbeatThread@1634546693722] INFO o.a.i.c.s.h.HeartbeatThread:97 - Data(10.0.0.10:9003): The leader Node(internalIp:10.0.0.10, metaPort:9003, nodeIdentifier:-1501659200, dataPort:40010, clientPort:6667, clientIp:10.0.0.10) timed out
2021-10-28 20:54:44,005 [Data(10.0.0.10:9003)-HeartbeatThread@1634546693722] INFO o.a.i.c.s.m.RaftMember:634 - Data(10.0.0.10:9003) has become a ELECTOR
2021-10-28 20:54:44,005 [Data(10.0.0.10:9003)-HeartbeatThread@1634546693722] INFO o.a.i.c.s.m.RaftMember:654 - Data(10.0.0.10:9003) has been set to null in term 1
2021-10-28 20:54:44,006 [Data(10.0.0.10:9003)-HeartbeatThread@1634546693722] INFO o.a.i.c.s.h.HeartbeatThread:128 - Data(10.0.0.10:9003): Start elections
2021-10-28 20:54:44,006 [Data(10.0.0.10:9003)-HeartbeatThread@1634546693722] INFO o.a.i.c.s.m.RaftMember:1592 - Data(10.0.0.10:9003) has update it's voteFor to Node(internalIp:10.0.0.9, metaPort:9003, nodeIdentifier:-1501660166, dataPort:40010, clientPort:6667, clientIp:10.0.0.9)
2021-10-28 20:54:44,006 [Data(10.0.0.10:9003)-HeartbeatThread@1634546693722] INFO o.a.i.c.s.h.HeartbeatThread:282 - Data(10.0.0.10:9003): Election 2 starts, quorum: 1
2021-10-28 20:54:44,006 [Data(10.0.0.10:9003)-HeartbeatThread@1634546693722] INFO o.a.i.c.s.h.HeartbeatThread:314 - Data(10.0.0.10:9003): Wait for 20000ms until election time out

//Node09 get vote from Node08, became leader in term=2
2021-10-28 20:54:44,009 [Data(10.0.0.10:9003)-SerialToParallel1] INFO o.a.i.c.s.h.c.ElectionHandler:89 - Data(10.0.0.10:9003): Received a grant vote from Node(internalIp:10.0.0.8, metaPort:9003, nodeIdentifier:-1501774531, dataPort:40010, clientPort:6667, clientIp:10.0.0.8), remaining votes to succeed: 0
2021-10-28 20:54:44,009 [Data(10.0.0.10:9003)-SerialToParallel1] INFO o.a.i.c.s.h.c.ElectionHandler:100 - Data(10.0.0.10:9003): Election 2 is won
2021-10-28 20:54:44,009 [Data(10.0.0.10:9003)-HeartbeatThread@1634546693722] INFO o.a.i.c.s.h.HeartbeatThread:330 - Data(10.0.0.10:9003): Election 2 accepted
2021-10-28 20:54:44,009 [Data(10.0.0.10:9003)-HeartbeatThread@1634546693722] INFO o.a.i.c.s.m.RaftMember:634 - Data(10.0.0.10:9003) has become a LEADER
2021-10-28 20:54:44,009 [Data(10.0.0.10:9003)-HeartbeatThread@1634546693722] INFO o.a.i.c.s.h.HeartbeatThread:132 - Data(10.0.0.10:9003): End elections

// Node08 received election request from Node09 for term=2,Node08 accept the election and vote for Node09, became follower
2021-10-28 20:54:44,014 [DataHeartbeatClientThread-7] INFO o.a.i.c.s.m.RaftMember:498 - Data(10.0.0.10:9003) received an election from elector Node(internalIp:10.0.0.9, metaPort:9003, nodeIdentifier:-1501660166, dataPort:40010, clientPort:6667, clientIp:10.0.0.9) which has bigger term 2 than localTerm 1, raftMember should step down first and then continue to decide whether to grant it's vote by log status.
2021-10-28 20:54:44,014 [DataHeartbeatClientThread-7] INFO o.a.i.c.s.m.RaftMember:1550 - Data(10.0.0.10:9003) has update it's term to 2
2021-10-28 20:54:44,014 [DataHeartbeatClientThread-7] INFO o.a.i.c.s.m.RaftMember:1592 - Data(10.0.0.10:9003) has update it's voteFor to null
2021-10-28 20:54:44,014 [DataHeartbeatClientThread-7] INFO o.a.i.c.s.m.RaftMember:654 - Data(10.0.0.10:9003) has been set to null in term 2
2021-10-28 20:54:44,015 [DataHeartbeatClientThread-7] INFO o.a.i.c.s.m.DataGroupMember:358 - Data(10.0.0.10:9003) received an dataGroup election request, term:2, metaLastLogIndex:792, metaLastLogTerm:2, dataLastLogIndex:7828302, dataLastLogTerm:1
2021-10-28 20:54:44,015 [DataHeartbeatClientThread-7] INFO o.a.i.c.s.m.DataGroupMember:377 - Data(10.0.0.10:9003) accepted an dataGroup election request, term:2/2, dataLogIndex:7828302/7828302, dataLogTerm:1/1, metaLogIndex:792/792,metaLogTerm:2/2
2021-10-28 20:54:44,015 [DataHeartbeatClientThread-7] INFO o.a.i.c.s.m.RaftMember:1592 - Data(10.0.0.10:9003) has update it's voteFor to Node(internalIp:10.0.0.9, metaPort:9003, nodeIdentifier:-1501660166, dataPort:40010, clientPort:6667, clientIp:10.0.0.9)
2021-10-28 20:54:44,015 [DataHeartbeatClientThread-7] INFO o.a.i.c.s.m.RaftMember:468 - Data(10.0.0.10:9003) sending response -1 to the elector Node(internalIp:10.0.0.9, metaPort:9003, nodeIdentifier:-1501660166, dataPort:40010, clientPort:6667, clientIp:10.0.0.9)
2021-10-28 20:54:44,016 [DataHeartbeatClientThread-7] INFO o.a.i.c.s.m.RaftMember:656 - Data(10.0.0.10:9003) has become a follower of Node(internalIp:10.0.0.9, metaPort:9003, nodeIdentifier:-1501660166, dataPort:40010, clientPort:6667, clientIp:10.0.0.9) in term 2

// As some log should be lost, I guess:
// Node10 received heartbeat from Node09 in term=2, Node 10 update its term=2 and became follower
2021-10-28 20:54:49,133 [DataHeartbeatClientThread-12] INFO o.a.i.c.s.m.RaftMember:1550 - Data(10.0.0.10:9003) has update it's term to 2
2021-10-28 20:54:49,133 [DataHeartbeatClientThread-12] INFO o.a.i.c.s.m.RaftMember:1592 - Data(10.0.0.10:9003) has update it's voteFor to null
2021-10-28 20:54:49,133 [DataHeartbeatClientThread-12] INFO o.a.i.c.s.m.RaftMember:654 - Data(10.0.0.10:9003) has been set to null in term 2
2021-10-28 20:54:49,134 [DataHeartbeatClientThread-12] INFO o.a.i.c.s.m.RaftMember:634 - Data(10.0.0.10:9003) has become a FOLLOWER
2021-10-28 20:54:49,134 [DataHeartbeatClientThread-12] INFO o.a.i.c.s.m.RaftMember:656 - Data(10.0.0.10:9003) has become a follower of Node(internalIp:10.0.0.9, metaPort:9003, nodeIdentifier:-1501660166, dataPort:40010, clientPort:6667, clientIp:10.0.0.9) in term 2

// Node09 received raft request like appendLog from Node10 in term = 2,Node09 set character to follower
2021-10-28 20:54:49,134 [DataClientThread-349] INFO o.a.i.c.s.m.RaftMember:656 - Data(10.0.0.10:9003) has become a follower of Node(internalIp:10.0.0.10, metaPort:9003, nodeIdentifier:-1501659200, dataPort:40010, clientPort:6667, clientIp:10.0.0.10) in term 2

// Node10 received election request from Node09 in term=2, it rejected the election as log mismatch
2021-10-28 20:54:49,151 [DataHeartbeatClientThread-11] INFO o.a.i.c.s.m.DataGroupMember:358 - Data(10.0.0.10:9003) received an dataGroup election request, term:2, metaLastLogIndex:792, metaLastLogTerm:2, dataLastLogIndex:7828302, dataLastLogTerm:1
2021-10-28 20:54:49,162 [DataHeartbeatClientThread-11] INFO o.a.i.c.s.m.DataGroupMember:395 - Data(10.0.0.10:9003) rejected an dataGroup election request, term:2/2, dataLogIndex:7828302/7828313, dataLogTerm:1/2, metaLogIndex:792/792,metaLogTerm:2/2
2021-10-28 20:54:49,162 [DataHeartbeatClientThread-11] INFO o.a.i.c.s.m.RaftMember:468 - Data(10.0.0.10:9003) sending response -2 to the elector Node(internalIp:10.0.0.9, metaPort:9003, nodeIdentifier:-1501660166, dataPort:40010, clientPort:6667, clientIp:10.0.0.9)

// Node09 received election for term=2 response from Node10
2021-10-28 20:54:49,162 [Data(10.0.0.10:9003)-SerialToParallel0] INFO o.a.i.c.s.h.c.ElectionHandler:79 - Data(10.0.0.10:9003): Terminated election received a election response -2 from Node(internalIp:10.0.0.10, metaPort:9003, nodeIdentifier:-1501659200, dataPort:40010, clientPort:6667, clientIp:10.0.0.10)

// Node08 became follower as received appendLog request from Node10, set leader to 10, term=2
2021-10-28 20:54:49,141 [DataClientThread-300] INFO o.a.i.c.s.m.RaftMember:656 - Data(10.0.0.10:9003) has become a follower of Node(internalIp:10.0.0.10, metaPort:9003, nodeIdentifier:-1501659200, dataPort:40010, clientPort:6667, clientIp:10.0.0.10) in term 2

// Node08 became follower as received appendLog request from Node10, set leader to 09, term=2
2021-10-28 20:54:49,158 [DataHeartbeatClientThread-7] INFO o.a.i.c.s.m.RaftMember:656 - Data(10.0.0.10:9003) has become a follower of Node(internalIp:10.0.0.9, metaPort:9003, nodeIdentifier:-1501660166, dataPort:40010, clientPort:6667, clientIp:10.0.0.9) in term 2
```

Guide de contribution

Ouvrir le guide de contribution

Piste de recherche

Commencez par lire les chemins de RaftMember, HeartbeatThread, ElectionHandler et DataGroupMember référencés dans les logs, puis suivez la manière dont les changements de term interagissent avec l’élection et le traitement de append-log. Reproduisez les deux scénarios de timing signalés et ajoutez une couverture de régression montrant que les requêtes provenant d’un rôle ou d’un term précédent sont traitées de manière sûre.

Rédigé par le modèle d'indexation à partir du texte de l'issue.

Évaluation

Stack technique
java
Domaine
databases, distributed-systems
Type d'issue
Bug
Difficulté
5/5
Temps estimé
Plus d'une semaine
Activité
À l'abandon
Clarté
Plutôt claire
Accessibilité débutants
25/100

Recevez les nouvelles issues par e-mail

Un résumé court des issues GitHub adaptées aux débutants.