short lived leader election reported when starting a raft cluster

[freddyrios]

The issue can be reproduced with the example project, by building it locally and adding a cluster.bat to the output folder that has the following lines:

START /B .\RaftNode.exe tcp 3262 node2 > node2.log
START /B .\RaftNode.exe tcp 3263 node3 > node3.log
START /B .\RaftNode.exe tcp 3264 node4 > node4.log

Run: del -r node* && .\cluster.bat

I can reproduce it with 2-6 attempts in a windows x64 machine. The issue was originally found in a raspberry pi (arm - linux).

The leader prints this its log:

New cluster leader is elected. Leader address is 127.0.0.1:3260
Term of local cluster member is 1. Election timeout 00:00:00.1590000
Consensus cannot be reached
Term of local cluster member is 1. Election timeout 00:00:00.1590000
New cluster leader is elected. Leader address is 127.0.0.1:3267
Term of local cluster member is 2. Election timeout 00:00:00.1590000
Accepting value 500
Accepting value 1000
Accepting value 1500
Accepting value 2000
...

Other nodes print (+ the leader prints the save messages)

New cluster leader is elected. Leader address is 127.0.0.1:3267
Term of local cluster member is 2. Election timeout 00:00:00.1700000
Accepting value 500
Accepting value 1000
Accepting value 1500
Accepting value 2000
...

When done with the run, the RaftNode processes need to be killed via task manager since they are running in the background.

Originally posted by @freddyrios in #167 (reply in thread)

[sakno]

Leader address is 127.0.0.1:3260

How is it possible if there are only 3262, 3263, 3264 nodes?

[freddyrios]

@sakno sorry for the noise, I used the log messages of the 10 nodes test run because they looked the same and forgot about it. Here are the actual entries for the 3 nodes run:

New cluster leader is elected. Leader address is 127.0.0.1:3264
Term of local cluster member is 2. Election timeout 00:00:00.2510000
Accepting value 500
Accepting value 1000
Accepting value 1500
Accepting value 2000

---

New cluster leader is elected. Leader address is 127.0.0.1:3263
Term of local cluster member is 1. Election timeout 00:00:00.1820000
Consensus cannot be reached
Term of local cluster member is 1. Election timeout 00:00:00.1820000
New cluster leader is elected. Leader address is 127.0.0.1:3264
Term of local cluster member is 2. Election timeout 00:00:00.1820000
Accepting value 500
Accepting value 1000
Accepting value 1500
Accepting value 2000

---

New cluster leader is elected. Leader address is 127.0.0.1:3264
Term of local cluster member is 2. Election timeout 00:00:00.2560000
Saving value 500 generated by the leader node
Accepting value 500
Saving value 1000 generated by the leader node
Accepting value 1000
Saving value 1500 generated by the leader node
Accepting value 1500
Saving value 2000 generated by the leader node
Accepting value 2000

[sakno]

So the problem with 3263 node, right? It was elected as a leader, and that fact was not reflected by other nodes.

[freddyrios]

Yes, that is the issue.

…

On Sat, Jun 3, 2023, 09:20 SRV ***@***.***> wrote: So the problem with 3263 node, right? It was elected as a leader, and that fact was not reflected by other nodes. — Reply to this email directly, view it on GitHub <#168 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AQ42ZDNUD5QTQOCO2YD5623XJLQVPANCNFSM6AAAAAAYYAJOR4> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[sakno]

In theory, it's possible (and correct from Raft perspective). But it should be very rare situation. I'll take a look.

[sakno]

Maybe related PR #170

[sakno]

Can you turn on Debug severity and attach logs for each node separately?

[freddyrios]

switched to file logging that also shows times + added an extra log message just before calling StartAsync.
node4.log
node2.log
node3.log

[freddyrios]

forgot to add that I set logging to trace and did not get anything extra

[sakno]

Example code uses Console.WriteLine instead of logging infrastructure. It seems like logs were not written at all (or written to another source, such as file instead of stdio).

[freddyrios]

Turned out a lot of the logging is only enabled for http.

Here are the details of one of the runs after enabling it for tcp.

node2.log
node3.log
node4.log

Some things that I found interesting:

1. term 0 is skipped, as nodes transitioning to leader change to term 1
2. at 41.8886 node 3 logs that, in term 1, node 2 rejected the vote but node 4 approved it
3. node 2 accepts the loss by downgrading to follower at 41.9006, while node 3 says it became a leader at 41.9008
4. node 4 first raft log is at 41.8900 which is .0014 after it suppodsely voted for node 3.
5. at 41.8900 node 4 says twice it downgrades to follower in term1 and that "Election timeout is refreshed". But then incorrectly inmediately transitions to candidate.
6. later node 4 starts and wins a vote in term 2 as normal.
7. there are still some funny artifacts at this point though, for example:
   1. node 4 reports node 3 rejection 29ms after node 2 approved the vote
   2. (maybe expected) node 3 reports a leader change without a leader with term 1 / when we have already entered term 2 election
   3. node 3 reports "Leader state reverted with error" ... a task was canceled.

[sakno]

term 0 is skipped, as nodes transitioning to leader change to term 1

This is fine. Term 0 is an initial term for every fresh node. Transition to Candidate increases the term.

[freddyrios]

5. at 41.8900 node 4 says twice it downgrades to follower in term1 and that "Election timeout is refreshed". But then incorrectly inmediately transitions to candidate.

I missed it says Member is downgrading vs. Member is downgraded / so its not double message of that. The timeout message does show twice though.