Leader election bug on leader disconnection (?)

[Arie Abramovici]

We are testing environment for network disconnect with 3 consul servers (0.6.3), and encountered the following issue:

1. The leader loses network connectivity
2. A new server is promoted to be leader
1. It seems the server didn't have the latest Term
3. The other connected server recognizes the new leader, but as it receives append entries requests with a stale term, it drops them and claims to not have a leader
4. Upon re-connection of the original leader, the new leader recognizes it's term wan't the latest, and steps down

I believe the root cause is here: https://github.com/hashicorp/raft/blob/master/raft.go#L1321

The server (not the new leader) drops the appendEntries request, without notifying the leader on the stale term.

Logs:

Original leader (disconnencted from network):

    2016/02/28 11:11:23 [INFO] memberlist: Suspect stratonode15159 has failed, no acks received
    2016/02/28 11:11:23 [WARN] raft: Heartbeat timeout reached, starting election
    2016/02/28 11:11:23 [INFO] raft: Node at 1.104.195.175:8300 [Candidate] entering Candidate state
    2016/02/28 11:11:24 [INFO] memberlist: Suspect stratonode6577 has failed, no acks received
    2016/02/28 11:11:24 [WARN] raft: Election timeout reached, restarting election

...

    2016/02/28 11:21:29 [ERR] dns: rpc error: No cluster leader
    2016/02/28 11:21:29 [INFO] raft: Node at 1.104.195.175:8300 [Follower] entering Follower state
    2016/02/28 11:21:29 [WARN] raft: Failed to get previous log: 2303 log not found (last: 1629)
    2016/02/28 11:21:29 [WARN] raft: Previous log term mis-match: ours: 1 remote: 3
    2016/02/28 11:21:30 [WARN] raft: Clearing log suffix from 1629 to 1629

New leader:

    2016/02/28 11:11:23 [INFO] memberlist: Suspect stratonode0 has failed, no acks received
    2016/02/28 11:11:23 [WARN] raft: Heartbeat timeout reached, starting election
    2016/02/28 11:11:23 [INFO] raft: Node at 1.104.217.177:8300 [Candidate] entering Candidate state
    2016/02/28 11:11:23 [INFO] raft: Duplicate RequestVote for same term: 2
    2016/02/28 11:11:24 [WARN] raft: Election timeout reached, restarting election
    2016/02/28 11:11:24 [INFO] raft: Node at 1.104.217.177:8300 [Candidate] entering Candidate state
    2016/02/28 11:11:25 [INFO] raft: Election won. Tally: 2
    2016/02/28 11:11:25 [INFO] raft: Node at 1.104.217.177:8300 [Leader] entering Leader state
    2016/02/28 11:11:25 [INFO] consul: cluster leadership acquired
    2016/02/28 11:11:25 [INFO] consul: New leader elected: stratonode6577
    2016/02/28 11:11:25 [INFO] raft: pipelining replication to peer 1.104.251.55:8300
    2016/02/28 11:11:25 [WARN] raft: Failed to contact 1.104.195.175:8300 in 509.819706ms
    2016/02/28 11:11:25 [WARN] raft: Failed to contact 1.104.195.175:8300 in 977.860525ms
    2016/02/28 11:11:26 [INFO] memberlist: Suspect stratonode0 has failed, no acks received
    2016/02/28 11:11:26 [WARN] raft: Failed to contact 1.104.195.175:8300 in 1.435647139s
    2016/02/28 11:11:28 [INFO] memberlist: Marking stratonode0 as failed, suspect timeout reached
    2016/02/28 11:11:28 [INFO] serf: EventMemberFailed: stratonode0 1.104.195.175
    2016/02/28 11:11:28 [INFO] consul: removing LAN server stratonode0 (Addr: 1.104.195.175:8300) (DC: stratocluster-18381067762067666372__1_2_1_0_025225eb)
    2016/02/28 11:11:28 [INFO] consul: member 'stratonode0' failed, marking health critical

    2016/02/28 11:11:29 [INFO] memberlist: Suspect stratonode0 has failed, no acks received
    2016/02/28 11:11:33 [ERR] raft: Failed to make RequestVote RPC to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: i/o timeout
    2016/02/28 11:11:34 [ERR] raft: Failed to make RequestVote RPC to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: i/o timeout
    2016/02/28 11:11:35 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: i/o timeout
    2016/02/28 11:11:35 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: i/o timeout
    2016/02/28 11:11:45 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: i/o timeout
    2016/02/28 11:11:45 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: i/o timeout    

...

    2016/02/28 11:19:18 [INFO] serf: attempting reconnect to stratonode0 1.104.195.175:8301
    2016/02/28 11:19:28 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:19:31 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:19:41 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:19:44 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:19:55 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:19:58 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:20:08 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:20:11 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:20:18 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:20:24 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:20:31 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:20:38 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:20:45 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:20:51 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:20:58 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:21:04 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:21:11 [ERR] raft: Failed to AppendEntries to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:21:18 [ERR] raft: Failed to heartbeat to 1.104.195.175:8300: dial tcp 1.104.195.175:8300: getsockopt: no route to host
    2016/02/28 11:21:28 [WARN] raft: Rejecting vote from 1.104.195.175:8300 since we have a leader: 1.104.217.177:8300
    2016/02/28 11:21:28 [ERR] raft: peer 1.104.195.175:8300 has newer term, stopping replication
    2016/02/28 11:21:28 [INFO] raft: Node at 1.104.217.177:8300 [Follower] entering Follower state
    2016/02/28 11:21:28 [INFO] raft: aborting pipeline replication to peer 1.104.251.55:8300

    2016/02/28 11:21:28 [INFO] consul: cluster leadership lost
    2016/02/28 11:21:29 [WARN] raft: Heartbeat timeout reached, starting election
    2016/02/28 11:21:29 [INFO] raft: Node at 1.104.217.177:8300 [Candidate] entering Candidate state
    2016/02/28 11:21:29 [INFO] raft: Election won. Tally: 2
    2016/02/28 11:21:29 [INFO] raft: Node at 1.104.217.177:8300 [Leader] entering Leader state
    2016/02/28 11:21:29 [INFO] consul: cluster leadership acquired
    2016/02/28 11:21:29 [INFO] consul: New leader elected: stratonode6577
    2016/02/28 11:21:29 [WARN] raft: AppendEntries to 1.104.195.175:8300 rejected, sending older logs (next: 1630)
    2016/02/28 11:21:29 [INFO] raft: pipelining replication to peer 1.104.251.55:8300
    2016/02/28 11:21:29 [WARN] raft: AppendEntries to 1.104.195.175:8300 rejected, sending older logs (next: 1629)
    2016/02/28 11:21:30 [INFO] raft: pipelining replication to peer 1.104.195.175:8300
 

And the third server:

    2016/02/28 11:11:23 [WARN] raft: Rejecting vote from 1.104.217.177:8300 since we have a leader: 1.104.195.175:8300
    2016/02/28 11:11:24 [WARN] raft: Heartbeat timeout reached, starting election
    2016/02/28 11:11:24 [INFO] raft: Node at 1.104.251.55:8300 [Candidate] entering Candidate state
    2016/02/28 11:11:24 [INFO] memberlist: Suspect stratonode0 has failed, no acks received
    2016/02/28 11:11:25 [INFO] raft: Node at 1.104.251.55:8300 [Follower] entering Follower state
    2016/02/28 11:11:25 [INFO] consul: New leader elected: stratonode6577
    2016/02/28 11:11:25 [ERR] http: Request GET /v1/kv/cluster/nodestates?recurse, error: No cluster leader from=127.0.0.1:60137
    2016/02/28 11:11:26 [INFO] memberlist: Suspect stratonode0 has failed, no acks received
    2016/02/28 11:11:27 [ERR] http: Request GET /v1/kv/cluster/nodestates?recurse, error: No cluster leader from=127.0.0.1:60137
    2016/02/28 11:11:28 [ERR] http: Request GET /v1/session/info/f56286a4-ea02-8a9b-d3cd-b51e4c968900, error: No cluster leader from=127.0.0.1:60120
    2016/02/28 11:11:28 [INFO] memberlist: Marking stratonode0 as failed, suspect timeout reached
    2016/02/28 11:11:28 [INFO] serf: EventMemberFailed: stratonode0 1.104.195.175
    2016/02/28 11:11:28 [INFO] consul: removing LAN server stratonode0 (Addr: 1.104.195.175:8300) (DC: stratocluster-18381067762067666372__1_2_1_0_025225eb)
    2016/02/28 11:11:28 [INFO] memberlist: Suspect stratonode0 has failed, no acks received
    2016/02/28 11:11:29 [ERR] http: Request GET /v1/session/info/f56286a4-ea02-8a9b-d3cd-b51e4c968900, error: No cluster leader from=127.0.0.1:60120
    2016/02/28 11:11:30 [ERR] http: Request GET /v1/kv/cluster/nodestates?recurse, error: No cluster leader from=127.0.0.1:60137
    2016/02/28 11:11:31 [ERR] http: Request GET /v1/session/info/f56286a4-ea02-8a9b-d3cd-b51e4c968900, error: No cluster leader from=127.0.0.1:60120
    2016/02/28 11:11:32 [ERR] agent: coordinate update error: No cluster leader
...
    2016/02/28 11:21:28 [WARN] raft: Rejecting vote from 1.104.195.175:8300 since we have a leader: 1.104.217.177:8300
    2016/02/28 11:21:28 [ERR] http: Request GET /v1/kv/cluster/nodestates?recurse&wait&index=822, error: No cluster leader from=127.0.0.1:61869
    2016/02/28 11:21:29 [WARN] raft: Rejecting vote from 1.104.195.175:8300 since we have a leader: 1.104.217.177:8300
    2016/02/28 11:21:29 [ERR] http: Request GET /v1/kv/cluster/nodestates?recurse, error: No cluster leader from=127.0.0.1:60137
    2016/02/28 11:21:30 [WARN] raft: Rejecting vote from 1.104.217.177:8300 since we have a leader: 1.104.217.177:8300
    2016/02/28 11:21:30 [INFO] consul: New leader elected: stratonode6577


Am I correct in understanding the issue?

[Иван Присяжный]

Seems like we ran into the very same issue according to your logs with a big cluster of Consul 0.5.2 in Windows R2012 env. But your assumption about having an issue in https://github.com/hashicorp/raft/blob/master/raft.go#L1321 does not explain why the new leader observes i/o timeouts? (from the code, ignoring old term follows immediate response)

вторник, 1 марта 2016 г., 9:50:00 UTC+2 пользователь Arie Abramovici написал:

[Armon Dadgar]

Arie,

Looking through the logs here, it doesn’t look like there is a particular issue.

It seems like the servers elected a new leader and operations continued as

expected. Please let me know if I’ve misunderstood.

The line you’ve linked to the Raft source is correct, if you look further up on

line 1309 the follower is attaching its current term to the response as well.

Best Regards,

Armon Dadgar

--
This mailing list is governed under the HashiCorp Community Guidelines - https://www.hashicorp.com/community-guidelines.html. Behavior in violation of those guidelines may result in your removal from this mailing list.
 
GitHub Issues: https://github.com/hashicorp/consul/issues
IRC: #consul on Freenode
---
You received this message because you are subscribed to the Google Groups "Consul" group.
To unsubscribe from this group and stop receiving emails from it, send an email to consul-tool...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/consul-tool/a2aa805a-c909-492c-8937-ac3ddaef9030%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.