Consul server in a multiple server datacenter causes unexpected behaviour after changing hostname and gets restarted
- Dominant language
- Go
- Stars
- 30.1k
- Forks
- 4.6k
- Avg merge
- 1d 18h
- Merged PRs (30d)
- 39
Description
#### Overview of the Issue
When a follower gets restarted after changing the hostname it causes many errors messages in the leader log and its own log along the time and when there are new elections.
```
BDD description:
Given a boostrapped datacenter of 5 Consul servers
When one of the followers change the hostname
And gets restarted
Then both leader and that follower start misbehaving
```
#### Reproduction Steps
Steps to reproduce this issue:
1. Create 5 servers using Docker
```
docker run -d --name consul1 --cap-add SYS_ADMIN --network consul_net consul sleep 999999
...
docker run -d --name consul5 --cap-add SYS_ADMIN --network consul_net consul sleep 999999
```
2. Bootstrap the DC (do it for each container)
```
docker exec -it consul1 sh
consul agent -server -data-dir=/tmp/test -bootstrap-expect=5 -retry-join=consul1 -retry-join=consul2 -retry-join=consul3 -retry-join=consul4 -retry-join=consul5
...
docker exec -it consul5 sh
consul agent -server -data-dir=/tmp/test -bootstrap-expect=5 -retry-join=consul1 -retry-join=consul2 -retry-join=consul3 -retry-join=consul4 -retry-join=consul5
```
3. Find one follower (run in any container)
```
docker exec -it consul 1 sh
consul operator raft list-peers
```
4. Change hostname of the follower
```
docker exec -it consul4 sh
hostname consul4
```
5. Restart consul in that follower
```
docker exec -it consul4 sh
kill `pidof consul`; consul agent -server -data-dir=/tmp/test -bootstrap-expect=5 -retry-join=consul1 -retry-join=consul2 -retry-join=consul3 -retry-join=consul4 -retry-join=consul5
#or
consul leave; consul agent -server -data-dir=/tmp/test -bootstrap-expect=5 -retry-join=consul1 -retry-join=consul2 -retry-join=consul3 -retry-join=consul4 -retry-join=consul5
#or
consul operator raft remove-peer -address=172.19.0.3:8300; consul leave; consul leave; consul agent -server -data-dir=/tmp/test -bootstrap-expect=5 -retry-join=consul1 -retry-join=consul2 -retry-join=consul3 -retry-join=consul4 -retry-join=consul5
```
### Raft peers flapping
If you watch the list of peers in each node you can see that follower will flap between the old name and the name
```
docker exec -it consul${I} sh
watch -n1 consul operator raft list-peers
```
it will show one of this 2 outputs:
```
Node ID Address State Voter RaftProtocol
42ea2b3e105c 3b02d4c8-e506-bac6-016e-65b910410d1b 172.19.0.2:8300 leader true 3
0941995127df 471317bd-616e-f769-29b2-8aad6e3ed683 172.19.0.3:8300 follower true 3
0b1a425682a9 90ad140e-1105-ad55-c2d7-6c2cd405913e 172.19.0.4:8300 follower true 3
168162d91743 aa9c1a1f-b981-5a90-2ea6-c5b33a6287b9 172.19.0.6:8300 follower true 3
51de0e48625d 7bbc6c78-927d-1191-0ff1-c6010d0e78d8 172.19.0.5:8300 follower true 3
```
or
```
Node ID Address State Voter RaftProtocol
42ea2b3e105c 3b02d4c8-e506-bac6-016e-65b910410d1b 172.19.0.2:8300 leader true 3
0941995127df 471317bd-616e-f769-29b2-8aad6e3ed683 172.19.0.3:8300 follower true 3
0b1a425682a9 90ad140e-1105-ad55-c2d7-6c2cd405913e 172.19.0.4:8300 follower true 3
168162d91743 aa9c1a1f-b981-5a90-2ea6-c5b33a6287b9 172.19.0.6:8300 follower true 3
consul4 7bbc6c78-927d-1191-0ff1-c6010d0e78d8 172.19.0.5:8300 follower true 3
```
### Log Fragments
The server starts throwing many error logs similar to this one:
```
[WARN] raft: Unable to get address for server id 7bbc6c78-927d-1191-0ff1-c6010d0e78d8, using fallback address 172.19.0.5:8300: Could not find address for server id 7bbc6c78-927d-1191-0ff1-c6010d0e78d8
```
From time to time both leader and the changed hostname follower throw error messages like this:
Leader:
```
2019/08/23 09:52:29 [WARN] raft: Rejecting vote request from 172.19.0.5:8300 since we have a leader: 172.19.0.2:8300
2019/08/23 09:52:37 [WARN] raft: Rejecting vote request from 172.19.0.5:8300 since we have a leader: 172.19.0.2:8300
2019/08/23 09:52:39 [INFO] raft: Updating configuration with AddNonvoter (7bbc6c78-927d-1191-0ff1-c6010d0e78d8, 172.19.0.5:8300) to [{Suffrage:Voter ID:3b02d4c8-e506-bac6-016e-65b910410d1b Address:172.19.0.2:8300} {Suffrage:Voter ID:471317bd-616e-f769-29b2-8aad6e3ed683 Address:172.19.0.3:8300} {Suffrage:Voter ID:90ad140e-1105-ad55-c2d7-6c2cd405913e Address:172.19.0.4:8300} {Suffrage:Voter ID:aa9c1a1f-b981-5a90-2ea6-c5b33a6287b9 Address:172.19.0.6:8300} {Suffrage:Nonvoter ID:7bbc6c78-927d-1191-0ff1-c6010d0e78d8 Address:172.19.0.5:8300}]
2019/08/23 09:52:39 [INFO] raft: Added peer 7bbc6c78-927d-1191-0ff1-c6010d0e78d8, starting replication
2019/08/23 09:52:39 [WARN] raft: Unable to get address for server id 7bbc6c78-927d-1191-0ff1-c6010d0e78d8, using fallback address 172.19.0.5:8300: Could not find address for server id 7bbc6c78-927d-1191-0ff1-c6010d0e78d8
2019/08/23 09:52:39 [ERR] raft: peer {Nonvoter 7bbc6c78-927d-1191-0ff1-c6010d0e78d8 172.19.0.5:8300} has newer term, stopping replication
2019/08/23 09:52:39 [INFO] raft: Node at 172.19.0.2:8300 [Follower] entering Follower state (Leader: "")
2019/08/23 09:52:39 [INFO] raft: aborting pipeline replication to peer {Voter 471317bd-616e-f769-29b2-8aad6e3ed683 172.19.0.3:8300}
2019/08/23 09:52:39 [ERR] consul: failed to add raft peer: leadership lost while committing log
2019/08/23 09:52:39 [ERR] consul: failed to reconcile member: {consul4 172.19.0.5 8301 map[acls:0 build:1.5.1:40cec984 dc:dc1 expect:5 id:7bbc6c78-927d-1191-0ff1-c6010d0e78d8 port:8300 raft_vsn:3 role:consul segment: vsn:2 vsn_max:3 vsn_min:2 wan_join_port:8302] alive 1 5 2 2 5 4}: leadership lost while committing log
2019/08/23 09:52:39 [INFO] raft: aborting pipeline replication to peer {Voter 90ad140e-1105-ad55-c2d7-6c2cd405913e 172.19.0.4:8300}
2019/08/23 09:52:39 [INFO] consul: cluster leadership lost
2019/08/23 09:52:39 [INFO] raft: aborting pipeline replication to peer {Voter aa9c1a1f-b981-5a90-2ea6-c5b33a6287b9 172.19.0.6:8300}
2019/08/23 09:52:46 [WARN] raft: Rejecting vote request from 172.19.0.5:8300 since our last index is greater (289, 281)
2019/08/23 09:52:47 [ERR] http: Request GET /v1/operator/raft/configuration, error: No cluster leader from=127.0.0.1:41322
2019/08/23 09:52:49 [WARN] raft: Heartbeat timeout from "" reached, starting election
2019/08/23 09:52:49 [INFO] raft: Node at 172.19.0.2:8300 [Candidate] entering Candidate state in term 65
2019/08/23 09:52:49 [INFO] raft: Election won. Tally: 3
2019/08/23 09:52:49 [INFO] raft: Node at 172.19.0.2:8300 [Leader] entering Leader state
2019/08/23 09:52:49 [INFO] raft: Added peer 471317bd-616e-f769-29b2-8aad6e3ed683, starting replication
2019/08/23 09:52:49 [INFO] raft: Added peer 90ad140e-1105-ad55-c2d7-6c2cd405913e, starting replication
2019/08/23 09:52:49 [INFO] raft: Added peer aa9c1a1f-b981-5a90-2ea6-c5b33a6287b9, starting replication
2019/08/23 09:52:49 [INFO] consul: cluster leadership acquired
2019/08/23 09:52:49 [INFO] raft: Added peer 7bbc6c78-927d-1191-0ff1-c6010d0e78d8, starting replication
2019/08/23 09:52:49 [WARN] raft: Unable to get address for server id 7bbc6c78-927d-1191-0ff1-c6010d0e78d8, using fallback address 172.19.0.5:8300: Could not find address for server id 7bbc6c78-927d-1191-0ff1-c6010d0e78d8
2019/08/23 09:52:49 [INFO] consul: New leader elected: 42ea2b3e105c
2019/08/23 09:52:49 [INFO] raft: pipelining replication to peer {Voter aa9c1a1f-b981-5a90-2ea6-c5b33a6287b9 172.19.0.6:8300}
2019/08/23 09:52:49 [INFO] raft: pipelining replication to peer {Voter 471317bd-616e-f769-29b2-8aad6e3ed683 172.19.0.3:8300}
2019/08/23 09:52:49 [INFO] raft: pipelining replication to peer {Voter 90ad140e-1105-ad55-c2d7-6c2cd405913e 172.19.0.4:8300}
2019/08/23 09:52:49 [WARN] raft: AppendEntries to {Nonvoter 7bbc6c78-927d-1191-0ff1-c6010d0e78d8 172.19.0.5:8300} rejected, sending older logs (next: 282)
2019/08/23 09:52:49 [WARN] raft: Unable to get address for server id 7bbc6c78-927d-1191-0ff1-c6010d0e78d8, using fallback address 172.19.0.5:8300: Could not find address for server id 7bbc6c78-927d-1191-0ff1-c6010d0e78d8
```
The follower:
```
2019/08/23 09:38:14 [INFO] raft: Node at 172.19.0.5:8300 [Candidate] entering Candidate state in term 24
2019/08/23 09:38:17 [ERR] http: Request GET /v1/operator/raft/configuration, error: No cluster leader from=127.0.0.1:33972
2019/08/23 09:38:20 [WARN] raft: Election timeout reached, restarting election
2019/08/23 09:38:20 [INFO] raft: Node at 172.19.0.5:8300 [Candidate] entering Candidate state in term 25
2019/08/23 09:38:20 [WARN] raft: Failed to get previous log: 115 log not found (last: 107)
2019/08/23 09:38:20 [INFO] raft: Node at 172.19.0.5:8300 [Follower] entering Follower state (Leader: "172.19.0.2:8300")
2019/08/23 09:38:20 [ERR] raft-net: Failed to flush response: write tcp 172.19.0.5:8300->172.19.0.2:55180: write: broken pipe
2019/08/23 09:38:21 [INFO] consul: New leader elected: 42ea2b3e105c
2019/08/23 09:38:27 [INFO] serf: attempting reconnect to 51de0e48625d.dc1 172.19.0.5:8302
2019/08/23 09:38:29 [WARN] raft: Heartbeat timeout from "172.19.0.2:8300" reached, starting election
...
2019/08/23 09:43:19 [INFO] raft: Node at 172.19.0.5:8300 [Candidate] entering Candidate state in term 42
2019/08/23 09:43:20 [ERR] http: Request GET /v1/operator/raft/configuration, error: No cluster leader from=127.0.0.1:36772
2019/08/23 09:43:21 [ERR] agent: failed to sync remote state: No cluster leader
2019/08/23 09:43:24 [WARN] raft: Election timeout reached, restarting election
2019/08/23 09:43:24 [INFO] raft: Node at 172.19.0.5:8300 [Candidate] entering Candidate state in term 43
2019/08/23 09:43:28 [ERR] agent: Coordinate update error: No cluster leader
2019/08/23 09:43:29 [ERR] http: Request GET /v1/operator/raft/configuration, error: No cluster leader from=127.0.0.1:36846
2019/08/23 09:43:31 [WARN] raft: Election timeout reached, restarting election
2019/08/23 09:43:31 [INFO] raft: Node at 172.19.0.5:8300 [Candidate] entering Candidate state in term 44
2019/08/23 09:43:34 [WARN] raft: Failed to get previous log: 175 log not found (last: 165)
2019/08/23 09:43:34 [INFO] raft: Node at 172.19.0.5:8300 [Follower] entering Follower state (Leader: "172.19.0.2:8300")
2019/08/23 09:43:34 [ERR] raft-net: Failed to flush response: write tcp 172.19.0.5:8300->172.19.0.2:58056: write: broken pipe
2019/08/23 09:43:34 [WARN] raft: Failed to get previous log: 179 log not found (last: 178)
2019/08/23 09:43:34 [INFO] consul: New leader elected: 42ea2b3e105c
```
Contributor guide
Research direction
Reproduce the behavior with the five Docker containers and the consul agent, operator raft list-peers, and hostname commands described in the issue. Inspect the leader and follower logs around elections, peer flapping, and address lookup failures; done should mean that restarting a follower after its hostname changes does not destabilize the cluster or repeatedly produce these errors.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- distributed-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100