Server node cannot rejoin the cluster after host power loss #2080
Description
- What version of Dgraph are you using?
Dgraph version : v1.0.2-dev
Commit SHA-1 : 5e47b20d
Commit timestamp : 2018-02-01 15:59:32 +1100
Branch : HEAD
- Have you tried reproducing the issue with latest release?
Yes, this is the latest version.
- What is the hardware spec (RAM, OS)?
Three kvm machines joined in docker swarm, centos 7, 4 gigabytes of RAM each.
- Steps to reproduce the issue (command/config used to run Dgraph).
Deploy dgraph in docker swarm using the following configuration (3 server nodes, 3 zero nodes, one zero and server per host, restricted from moving by specifying the hostname).
docker-compose.yml:
version: "3.4"
services:
zero-1:
image: dgraph/dgraph:master
hostname: "zero-1"
command: dgraph zero --my=zero-1:5080 --replicas 3 --idx 1
volumes:
- data:/dgraph
networks:
- dgraph
ports:
- 6080:6080
deploy:
placement:
constraints:
- node.hostname == swarm-manager-1
zero-2:
image: dgraph/dgraph:master
hostname: "zero-2"
command: dgraph zero --my=zero-2:5080 --replicas 3 --idx 2 --peer zero-1:5080
volumes:
- data:/dgraph
networks:
- dgraph
deploy:
placement:
constraints:
- node.hostname == swarm-manager-2
zero-3:
image: dgraph/dgraph:master
hostname: "zero-3"
command: dgraph zero --my=zero-3:5080 --replicas 3 --idx 3 --peer zero-1:5080
volumes:
- data:/dgraph
networks:
- dgraph
deploy:
placement:
constraints:
- node.hostname == swarm-manager-3
server-1:
image: dgraph/dgraph:master
hostname: "server-1"
command: dgraph server --my=server-1:7080 --memory_mb=1568 --zero=zero-1:5080 --export=/dgraph/export
volumes:
- data:/dgraph
networks:
- dgraph
ports:
- 8080:8080
deploy:
replicas: 1
placement:
constraints:
- node.hostname == swarm-manager-1
server-2:
image: dgraph/dgraph:master
hostname: "server-2"
command: dgraph server --my=server-2:7080 --memory_mb=1568 --zero=zero-1:5080 --export=/dgraph/export
volumes:
- data:/dgraph
networks:
- dgraph
ports:
- 8081:8080
deploy:
replicas: 1
placement:
constraints:
- node.hostname == swarm-manager-2
server-3:
image: dgraph/dgraph:master
hostname: "server-3"
command: dgraph server --my=server-3:7080 --memory_mb=1568 --zero=zero-1:5080 --export=/dgraph/export
volumes:
- data:/dgraph
ports:
- 8082:8080
networks:
- dgraph
deploy:
replicas: 1
placement:
constraints:
- node.hostname == swarm-manager-3
ratel:
image: dgraph/dgraph:master
command: dgraph-ratel
networks:
- dgraph
ports:
- 18049:8081
networks:
dgraph:
external: true
volumes:
data:
Hard reboot any host (via virsh destroy, reset the virtual box's machine or just pull the plug from physical server), wait for services to start, check the logs. In my case I rebooted node swarm-manager-3 with services dgraph_server-3 and dgraph_zero-3.
Logs from zero-3:
dgraph_zero-3.1.l203rs6nlr7x@swarm-manager-3 | 2018/02/02 09:01:38 raft.go:749: INFO: 3 is starting a new election at term 80
dgraph_zero-3.1.l203rs6nlr7x@swarm-manager-3 | 2018/02/02 09:01:38 raft.go:580: INFO: 3 became candidate at term 81
dgraph_zero-3.1.l203rs6nlr7x@swarm-manager-3 | 2018/02/02 09:01:38 raft.go:664: INFO: 3 received MsgVoteResp from 3 at term 81
dgraph_zero-3.1.l203rs6nlr7x@swarm-manager-3 | 2018/02/02 09:01:38 raft.go:651: INFO: 3 [logterm: 5, index: 178] sent MsgVote request to 1 at term 81
...
dgraph_zero-3.1.l203rs6nlr7x@swarm-manager-3 | 2018/02/02 09:13:03 raft.go:708: INFO: 3 [term: 303] received a MsgVote message with higher term from 1 [term: 304]
dgraph_zero-3.1.l203rs6nlr7x@swarm-manager-3 | 2018/02/02 09:13:03 raft.go:567: INFO: 3 became follower at term 304
dgraph_zero-3.1.l203rs6nlr7x@swarm-manager-3 | 2018/02/02 09:13:03 raft.go:763: INFO: 3 [logterm: 5, index: 178, vote: 0] cast MsgVote for 1 [logterm: 5, index: 179] at term 304
dgraph_zero-3.1.l203rs6nlr7x@swarm-manager-3 | 2018/02/02 09:13:03 node.go:301: INFO: raft.node: 3 elected leader 1 at term 304
Logs from server-3:
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:01:55 raft.go:749: INFO: 1 is starting a new election at term 80
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:01:55 raft.go:580: INFO: 1 became candidate at term 81
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:01:55 raft.go:664: INFO: 1 received MsgVoteResp from 1 at term 81
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:01:55 raft.go:651: INFO: 1 [logterm: 2, index: 26] sent MsgVote request to 3 at term 81
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:01:55 raft.go:651: INFO: 1 [logterm: 2, index: 26] sent MsgVote request to 2 at term 81
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:01:59 raft.go:749: INFO: 1 is starting a new election at term 81
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:01:59 raft.go:580: INFO: 1 became candidate at term 82
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:01:59 raft.go:664: INFO: 1 received MsgVoteResp from 1 at term 82
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:01:59 raft.go:651: INFO: 1 [logterm: 2, index: 26] sent MsgVote request to 2 at term 82
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:01:59 raft.go:651: INFO: 1 [logterm: 2, index: 26] sent MsgVote request to 3 at term 82
...
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:13:12 raft.go:708: INFO: 1 [term: 300] received a MsgVote message with higher term from 2 [term: 301]
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:13:12 raft.go:567: INFO: 1 became follower at term 301
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:13:12 raft.go:763: INFO: 1 [logterm: 2, index: 26, vote: 0] cast MsgVote for 2 [logterm: 3, index: 27] at term 301
dgraph_server-3.1.ot5rm9gltmze@swarm-manager-3 | 2018/02/02 09:13:12 node.go:301: INFO: raft.node: 1 elected leader 2 at term 301
Logs from zero-1:
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 08:59:41 raft.go:692: INFO: 1 [logterm: 5, index: 179, vote: 1] ignored MsgVote from 3 [logterm: 5, index: 178] at term 5: lease is not expired (remaining ticks: 28)
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 08:59:44 raft.go:692: INFO: 1 [logterm: 5, index: 179, vote: 1] ignored MsgVote from 3 [logterm: 5, index: 178] at term 5: lease is not expired (remaining ticks: 73)
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 08:59:47 raft.go:692: INFO: 1 [logterm: 5, index: 179, vote: 1] ignored MsgVote from 3 [logterm: 5, index: 178] at term 5: lease is not expired (remaining ticks: 14)
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 08:59:50 raft.go:692: INFO: 1 [logterm: 5, index: 179, vote: 1] ignored MsgVote from 3 [logterm: 5, index: 178] at term 5: lease is not expired (remaining ticks: 54)
...
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 09:13:03 raft.go:651: INFO: 1 [logterm: 5, index: 179] sent MsgVote request to 2 at term 304
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 09:13:03 node.go:307: INFO: raft.node: 1 lost leader 3 at term 304
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 09:13:03 raft.go:664: INFO: 1 received MsgVoteResp from 3 at term 304
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 09:13:03 raft.go:1013: INFO: 1 [quorum:2] has received 2 MsgVoteResp votes and 0 vote rejections
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 09:13:03 raft.go:621: INFO: 1 became leader at term 304
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 09:13:03 node.go:301: INFO: raft.node: 1 elected leader 1 at term 304
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 09:13:07 pool.go:168: Echo error from server-3:7080. Err: rpc error: code = Unavailable desc = transport is closing
dgraph_zero-1.1.60oyk2lrh7jn@swarm-manager-1 | 2018/02/02 09:13:07 pool.go:168: Echo error from server-3:7080. Err: rpc error: code = Unavailable desc = transport is closing
Output of /state endpoint:
{
"counter": "179",
"groups": {
"1": {
"members": {
"1": {
"id": "1",
"groupId": 1,
"addr": "server-3:7080",
"lastUpdate": "1517558484"
},
"2": {
"id": "2",
"groupId": 1,
"addr": "server-2:7080"
},
"3": {
"id": "3",
"groupId": 1,
"addr": "server-1:7080",
"leader": true,
"lastUpdate": "1517561855"
}
},
"tablets": {
"_predicate_": {
"groupId": 1,
"predicate": "_predicate_",
"space": "6737282"
},
"actor.film": {
"groupId": 1,
"predicate": "actor.film",
"space": "154599"
},
...
}
}
},
"zeros": {
"1": {
"id": "1",
"addr": "zero-1:5080",
"leader": true
},
"2": {
"id": "2",
"addr": "zero-2:5080"
},
"3": {
"id": "3",
"addr": "zero-3:5080"
}
},
"maxLeaseId": "1010000",
"maxTxnTs": "10000",
"maxRaftId": "3"
}
- Expected behaviour and actual result.
I expect the node to get back into the cluster in about 20 seconds after the start of corresponding services (like in soft reboot case, when you gracefully reboot the host). The result - node rejoins in about 15 minutes. Looks like a RAFT problem to me.
I also expect the output of /state to reflect the actual status of the rebooted node - see #2069