Multiple leader election (Multiple increases in term)

[jopemachine]

In the 3-node example, after setting the election_tick to 10 and the heartbeat_tick to 3, multiple leader elections are occurring due to network failures when electing a new leader.

Is this issue happening simply because I have set the heartbeat_tick and election_tick too low? I am wondering if it is expected behavior for a new leader election could occur while in the process of electing a leader.

This issue occurs only when continuous put requests are sent and a network failure happens. (This means that requests continue to come in even during the leader election process.)

In contrast, in the simple 3-node example, when the leader quitted forcely, only one leader election occurs normally (with the term increasing to 2)

 Nov 23 02:40:59.899 INFO starting a new election, term: 8
 Nov 23 02:40:59.899 DEBG reset election timeout 12 -> 14 at 0, election_elapsed: 0, timeout: 14, prev_timeout: 12
 Nov 23 02:40:59.899 INFO became candidate at term 9, term: 9
 Nov 23 02:40:59.899 DEBG Sending from 3 to 1, msg: Message { msg_type: MsgRequestVote, to: 1, from: 0, term: 9, log_term: 8, index: 3612, entries: [], commit: 3611, commit_term: 8, snapshot: Snapshot { data: "None", metadata: None }, request_snapshot: 0, reject: false, reject_hint: 0, context: "None", deprecated_priority: 0, priority: 0 }, to: 1, from: 3
 Nov 23 02:40:59.900 DEBG Sending from 3 to 2, msg: Message { msg_type: MsgRequestVote, to: 2, from: 0, term: 9, log_term: 8, index: 3612, entries: [], commit: 3611, commit_term: 8, snapshot: Snapshot { data: "None", metadata: None }, request_snapshot: 0, reject: false, reject_hint: 0, context: "None", deprecated_priority: 0, priority: 0 }, to: 2, from: 3
 Nov 23 02:40:59.900 INFO broadcasting vote request, to: [1, 2], log_index: 3612, log_term: 8, term: 9, type: MsgRequestVote
2023-11-23 11:40:59,914 - WARNING  - Failed to connect to node 1 elapsed from first failure: 1.2223s. Err message: <AioRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60061: Can't assign requested address"
        debug_error_string = "UNKNOWN:failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60061: Can't assign requested address {created_time:"2023-11-23T11:40:59.911426+09:00", grpc_status:14}"
>
2023-11-23 11:40:59,915 - WARNING  - Failed to connect to node 2 elapsed from first failure: 0.0000s. Err message: <AioRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60062: Can't assign requested address"
        debug_error_string = "UNKNOWN:failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60062: Can't assign requested address {grpc_status:14, created_time:"2023-11-23T11:40:59.913889+09:00"}"
>
 Nov 23 02:41:01.320 INFO starting a new election, term: 9
 Nov 23 02:41:01.321 DEBG reset election timeout 14 -> 10 at 0, election_elapsed: 0, timeout: 10, prev_timeout: 14
 Nov 23 02:41:01.321 INFO became candidate at term 10, term: 10
 Nov 23 02:41:01.321 DEBG Sending from 3 to 1, msg: Message { msg_type: MsgRequestVote, to: 1, from: 0, term: 10, log_term: 8, index: 3612, entries: [], commit: 3611, commit_term: 8, snapshot: Snapshot { data: "None", metadata: None }, request_snapshot: 0, reject: false, reject_hint: 0, context: "None", deprecated_priority: 0, priority: 0 }, to: 1, from: 3
 Nov 23 02:41:01.321 DEBG Sending from 3 to 2, msg: Message { msg_type: MsgRequestVote, to: 2, from: 0, term: 10, log_term: 8, index: 3612, entries: [], commit: 3611, commit_term: 8, snapshot: Snapshot { data: "None", metadata: None }, request_snapshot: 0, reject: false, reject_hint: 0, context: "None", deprecated_priority: 0, priority: 0 }, to: 2, from: 3
 Nov 23 02:41:01.322 INFO broadcasting vote request, to: [1, 2], log_index: 3612, log_term: 8, term: 10, type: MsgRequestVote
2023-11-23 11:41:01,340 - WARNING  - Failed to connect to node 1 elapsed from first failure: 2.6481s. Err message: <AioRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60061: Can't assign requested address"
        debug_error_string = "UNKNOWN:failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60061: Can't assign requested address {grpc_status:14, created_time:"2023-11-23T11:41:01.337358+09:00"}"
>
2023-11-23 11:41:01,340 - WARNING  - Failed to connect to node 2 elapsed from first failure: 1.4257s. Err message: <AioRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60062: Can't assign requested address"
        debug_error_string = "UNKNOWN:failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60062: Can't assign requested address {grpc_status:14, created_time:"2023-11-23T11:41:01.340115+09:00"}"
>
 Nov 23 02:41:02.338 INFO starting a new election, term: 10
 Nov 23 02:41:02.338 DEBG reset election timeout 10 -> 14 at 0, election_elapsed: 0, timeout: 14, prev_timeout: 10
 Nov 23 02:41:02.338 INFO became candidate at term 11, term: 11
 Nov 23 02:41:02.339 DEBG Sending from 3 to 1, msg: Message { msg_type: MsgRequestVote, to: 1, from: 0, term: 11, log_term: 8, index: 3612, entries: [], commit: 3611, commit_term: 8, snapshot: Snapshot { data: "None", metadata: None }, request_snapshot: 0, reject: false, reject_hint: 0, context: "None", deprecated_priority: 0, priority: 0 }, to: 1, from: 3
 Nov 23 02:41:02.339 DEBG Sending from 3 to 2, msg: Message { msg_type: MsgRequestVote, to: 2, from: 0, term: 11, log_term: 8, index: 3612, entries: [], commit: 3611, commit_term: 8, snapshot: Snapshot { data: "None", metadata: None }, request_snapshot: 0, reject: false, reject_hint: 0, context: "None", deprecated_priority: 0, priority: 0 }, to: 2, from: 3
 Nov 23 02:41:02.339 INFO broadcasting vote request, to: [1, 2], log_index: 3612, log_term: 8, term: 11, type: MsgRequestVote
2023-11-23 11:41:02,357 - WARNING  - Failed to connect to node 1 elapsed from first failure: 3.6649s. Err message: <AioRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60061: Can't assign requested address"
        debug_error_string = "UNKNOWN:failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60061: Can't assign requested address {grpc_status:14, created_time:"2023-11-23T11:41:02.353028+09:00"}"
>
2023-11-23 11:41:02,358 - WARNING  - Failed to connect to node 2 elapsed from first failure: 2.4432s. Err message: <AioRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60062: Can't assign requested address"
        debug_error_string = "UNKNOWN:failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60062: Can't assign requested address {created_time:"2023-11-23T11:41:02.356241+09:00", grpc_status:14}"
>
2023-11-23 11:41:03,710 - WARNING  - Failed to connect to node 1 elapsed from first failure: 5.0182s. Err message: <AioRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60061: Can't assign requested address"
        debug_error_string = "UNKNOWN:failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60061: Can't assign requested address {created_time:"2023-11-23T11:41:03.704304+09:00", grpc_status:14}"
>
 Nov 23 02:41:03.768 INFO starting a new election, term: 11
 Nov 23 02:41:03.768 DEBG reset election timeout 14 -> 15 at 0, election_elapsed: 0, timeout: 15, prev_timeout: 14
 Nov 23 02:41:03.769 INFO became candidate at term 12, term: 12
 Nov 23 02:41:03.769 DEBG Sending from 3 to 1, msg: Message { msg_type: MsgRequestVote, to: 1, from: 0, term: 12, log_term: 8, index: 3612, entries: [], commit: 3611, commit_term: 8, snapshot: Snapshot { data: "None", metadata: None }, request_snapshot: 0, reject: false, reject_hint: 0, context: "None", deprecated_priority: 0, priority: 0 }, to: 1, from: 3
 Nov 23 02:41:03.769 DEBG Sending from 3 to 2, msg: Message { msg_type: MsgRequestVote, to: 2, from: 0, term: 12, log_term: 8, index: 3612, entries: [], commit: 3611, commit_term: 8, snapshot: Snapshot { data: "None", metadata: None }, request_snapshot: 0, reject: false, reject_hint: 0, context: "None", deprecated_priority: 0, priority: 0 }, to: 2, from: 3
 Nov 23 02:41:03.770 INFO broadcasting vote request, to: [1, 2], log_index: 3612, log_term: 8, term: 12, type: MsgRequestVote
2023-11-23 11:41:03,786 - WARNING  - Failed to connect to node 1 elapsed from first failure: 5.0941s. Err message: <AioRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60061: Can't assign requested address"
        debug_error_string = "UNKNOWN:failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60061: Can't assign requested address {grpc_status:14, created_time:"2023-11-23T11:41:03.783181+09:00"}"
>
2023-11-23 11:41:03,787 - WARNING  - Failed to connect to node 2 elapsed from first failure: 3.8718s. Err message: <AioRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60062: Can't assign requested address"
        debug_error_string = "UNKNOWN:failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:60062: Can't assign requested address {created_time:"2023-11-23T11:41:03.785907+09:00", grpc_status:14}"