etcd
etcd copied to clipboard
Inconsistent reading, two leaders appear one after another at the same term
Hi, we meet an Inconsistent reading issue. the key can read from the leader but not from one follower, and found two leaders appear one after another at the same term.
The log details:
node 620d71aa28ed3b63, the term became 4 firstly and then changed to 3 again, and finaly became leader in term 4:
{"level":"info","ts":1531181998.7567253,"caller":"raft/raft.go:797","msg":"620d71aa28ed3b63 [term: 3] received a MsgVote message with higher term from 4e49bc5f2b3d67c6 [term: 4]"}
{"level":"info","ts":1531181998.7567725,"caller":"raft/raft.go:656","msg":"620d71aa28ed3b63 became follower at term 4"}
{"level":"info","ts":1531181998.7568014,"caller":"raft/raft.go:882","msg":"620d71aa28ed3b63 [logterm: 3, index: 132071, vote: 0] cast MsgVote for 4e49bc5f2b3d67c6 [logterm: 3, index: 132071] at term 4"}
{"level":"info","ts":1531181998.771561,"caller":"raft/node.go:306","msg":"raft.node: 620d71aa28ed3b63 elected leader 4e49bc5f2b3d67c6 at term 4"}
// restart node, start new election, reject from 4e49bc5f2b3d67c6,
{"level":"info","ts":1531193320.3799624,"caller":"raft/raft.go:656","msg":"620d71aa28ed3b63 became follower at term 3"}
{"level":"info","ts":1531193320.3856823,"caller":"raft/raft.go:364","msg":"newRaft 620d71aa28ed3b63 [peers: [4e49bc5f2b3d67c6,620d71aa28ed3b63,b5c9c099610a418c], term: 3, commit: 132069, applied: 100001, lastindex: 132070, lastterm: 3]"}
{"level":"info","ts":1531193321.386299,"caller":"raft/raft.go:857","msg":"620d71aa28ed3b63 is starting a new election at term 3"}
{"level":"info","ts":1531193321.3863857,"caller":"raft/raft.go:684","msg":"620d71aa28ed3b63 became pre-candidate at term 3"}
{"level":"info","ts":1531193321.3864245,"caller":"raft/raft.go:755","msg":"620d71aa28ed3b63 received MsgPreVoteResp from 620d71aa28ed3b63 at term 3"}
{"level":"info","ts":1531193321.386452,"caller":"raft/raft.go:742","msg":"620d71aa28ed3b63 [logterm: 3, index: 132070] sent MsgPreVote request to 4e49bc5f2b3d67c6 at term 3"}
{"level":"info","ts":1531193321.3864691,"caller":"raft/raft.go:742","msg":"620d71aa28ed3b63 [logterm: 3, index: 132070] sent MsgPreVote request to b5c9c099610a418c at term 3"}
{"level":"info","ts":1531193321.3872113,"caller":"raft/raft.go:755","msg":"620d71aa28ed3b63 received MsgPreVoteResp from b5c9c099610a418c at term 3"}
{"level":"info","ts":1531193321.3872662,"caller":"raft/raft.go:1148","msg":"620d71aa28ed3b63 [quorum:2] has received 2 MsgPreVoteResp votes and 0 vote rejections"}
{"level":"info","ts":1531193321.3873036,"caller":"raft/raft.go:669","msg":"620d71aa28ed3b63 became candidate at term 4"}
{"level":"info","ts":1531193321.3873124,"caller":"raft/raft.go:755","msg":"620d71aa28ed3b63 received MsgVoteResp from 620d71aa28ed3b63 at term 4"}
{"level":"info","ts":1531193321.38733,"caller":"raft/raft.go:742","msg":"620d71aa28ed3b63 [logterm: 3, index: 132070] sent MsgVote request to 4e49bc5f2b3d67c6 at term 4"}
{"level":"info","ts":1531193321.3873405,"caller":"raft/raft.go:742","msg":"620d71aa28ed3b63 [logterm: 3, index: 132070] sent MsgVote request to b5c9c099610a418c at term 4"}
{"level":"info","ts":1531193321.387938,"caller":"raft/raft.go:757","msg":"620d71aa28ed3b63 received MsgVoteResp rejection from 4e49bc5f2b3d67c6 at term 4"}
{"level":"info","ts":1531193321.3879704,"caller":"raft/raft.go:1148","msg":"620d71aa28ed3b63 [quorum:2] has received 1 MsgVoteResp votes and 1 vote rejections"}
{"level":"info","ts":1531193321.388202,"caller":"raft/raft.go:755","msg":"620d71aa28ed3b63 received MsgVoteResp from b5c9c099610a418c at term 4"}
{"level":"info","ts":1531193321.3882232,"caller":"raft/raft.go:1148","msg":"620d71aa28ed3b63 [quorum:2] has received 2 MsgVoteResp votes and 1 vote rejections"}
{"level":"info","ts":1531193321.3882663,"caller":"raft/raft.go:712","msg":"620d71aa28ed3b63 became leader at term 4"}
{"level":"info","ts":1531193321.3882892,"caller":"raft/node.go:306","msg":"raft.node: 620d71aa28ed3b63 elected leader 620d71aa28ed3b63 at term 4"}
node 4e49bc5f2b3d67c6, became leader in term 4 and then meet some network problem.
{"level":"info","ts":1531181998.753459,"caller":"raft/raft.go:755","msg":"4e49bc5f2b3d67c6 received MsgVoteResp from 4e49bc5f2b3d67c6 at term 4"}
{"level":"info","ts":1531181998.7534702,"caller":"raft/raft.go:742","msg":"4e49bc5f2b3d67c6 [logterm: 3, index: 132071] sent MsgVote request to 620d71aa28ed3b63 at term 4"}
{"level":"info","ts":1531181998.7534807,"caller":"raft/raft.go:742","msg":"4e49bc5f2b3d67c6 [logterm: 3, index: 132071] sent MsgVote request to b5c9c099610a418c at term 4"}
{"level":"info","ts":1531181998.7534912,"caller":"raft/node.go:312","msg":"raft.node: 4e49bc5f2b3d67c6 lost leader 620d71aa28ed3b63 at term 4"}
{"level":"info","ts":1531181998.7683225,"caller":"raft/raft.go:755","msg":"4e49bc5f2b3d67c6 received MsgVoteResp from 620d71aa28ed3b63 at term 4"}
{"level":"info","ts":1531181998.7683463,"caller":"raft/raft.go:1148","msg":"4e49bc5f2b3d67c6 [quorum:2] has received 2 MsgVoteResp votes and 0 vote rejections"}
{"level":"info","ts":1531181998.7683868,"caller":"raft/raft.go:712","msg":"4e49bc5f2b3d67c6 became leader at term 4"}
{"level":"info","ts":1531181998.7684014,"caller":"raft/node.go:306","msg":"raft.node: 4e49bc5f2b3d67c6 elected leader 4e49bc5f2b3d67c6 at term 4"}
WARNING: 2018/07/10 08:19:58 grpc: addrConn.createTransport failed to connect to {172.16.9.5:2379 0 <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 172.16.9.5:2379: connect: cannot assign requested address". Reconnecting...
WARNING: 2018/07/10 08:19:59 Failed to dial 172.16.9.5:2379: context canceled; please retry.
WARNING: 2018/07/10 08:19:59 grpc: addrConn.createTransport failed to connect to {172.16.9.5:2379 0 <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 172.16.9.5:2379: connect: cannot assign requested address". Reconnecting...
WARNING: 2018/07/10 08:20:00 grpc: addrConn.createTransport failed to connect to {172.16.9.5:2379 0 <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 172.16.9.5:2379: connect: cannot assign requested address". Reconnecting...
WARNING: 2018/07/10 08:20:01 grpc: addrConn.createTransport failed to connect to {172.16.9.5:2379 0 <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 172.16.9.5:2379: connect: cannot assign requested address". Reconnecting...
WARNING: 2018/07/10 08:20:02 Failed to dial 172.16.9.5:2379: context canceled; please retry.
WARNING: 2018/07/10 08:20:02 grpc: addrConn.createTransport failed to connect to {172.16.9.5:2379 0 <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 172.16.9.5:2379: connect: cannot assign requested address". Reconnecting...
// drop leader for a long time, and restart new election, the index is 132085.
{"level":"warn","ts":1531186954.7412045,"caller":"raft/raft.go:924","msg":"4e49bc5f2b3d67c6 stepped down to follower since quorum is not active"}
{"level":"info","ts":1531186954.7413478,"caller":"raft/raft.go:656","msg":"4e49bc5f2b3d67c6 became follower at term 4"}
{"level":"info","ts":1531186954.741363,"caller":"raft/node.go:312","msg":"raft.node: 4e49bc5f2b3d67c6 lost leader 4e49bc5f2b3d67c6 at term 4"}
WARNING: 2018/07/10 09:42:35 grpc: addrConn.createTransport failed to connect to {172.16.9.5:2379 0 <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 172.16.9.5:2379: connect: cannot assign requested address". Reconnecting...
WARNING: 2018/07/10 09:42:35 Failed to dial 172.16.9.5:2379: context canceled; please retry.
WARNING: 2018/07/10 09:42:35 grpc: addrConn.createTransport failed to connect to {172.16.9.5:2379 0 <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 172.16.9.5:2379: connect: cannot assign requested address". Reconnecting...
WARNING: 2018/07/10 09:42:36 grpc: addrConn.createTransport failed to connect to {172.16.9.5:2379 0 <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 172.16.9.5:2379: connect: cannot assign requested address". Reconnecting...
WARNING: 2018/07/10 09:42:38 grpc: addrConn.createTransport failed to connect to {172.16.9.5:2379 0 <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 172.16.9.5:2379: connect: cannot assign requested address". Reconnecting...
{"level":"info","ts":1531186958.7412286,"caller":"raft/raft.go:857","msg":"4e49bc5f2b3d67c6 is starting a new election at term 4"}
{"level":"info","ts":1531186958.741318,"caller":"raft/raft.go:684","msg":"4e49bc5f2b3d67c6 became pre-candidate at term 4"}
{"level":"info","ts":1531186958.7413387,"caller":"raft/raft.go:755","msg":"4e49bc5f2b3d67c6 received MsgPreVoteResp from 4e49bc5f2b3d67c6 at term 4"}
{"level":"info","ts":1531186958.7413552,"caller":"raft/raft.go:742","msg":"4e49bc5f2b3d67c6 [logterm: 4, index: 132085] sent MsgPreVote request to 620d71aa28ed3b63 at term 4"}
{"level":"info","ts":1531186958.7413685,"caller":"raft/raft.go:742","msg":"4e49bc5f2b3d67c6 [logterm: 4, index: 132085] sent MsgPreVote request to b5c9c099610a418c at term 4"}
//restart node , commit index is 132085
{"level":"info","ts":1531193319.9247162,"caller":"raft/raft.go:656","msg":"4e49bc5f2b3d67c6 became follower at term 4"}
{"level":"info","ts":1531193319.9248278,"caller":"raft/raft.go:364","msg":"newRaft 4e49bc5f2b3d67c6 [peers: [4e49bc5f2b3d67c6,620d71aa28ed3b63,b5c9c099610a418c], term: 4, commit: 132085, applied: 100001, lastindex: 132085, lastterm: 4]"}
{"level":"info","ts":1531193321.4336638,"caller":"raft/raft.go:900","msg":"4e49bc5f2b3d67c6 [logterm: 4, index: 132085, vote: 4e49bc5f2b3d67c6] rejected MsgPreVote from 620d71aa28ed3b63 [logterm: 3, index: 132070] at term 4"}
{"level":"info","ts":1531193321.434485,"caller":"raft/raft.go:900","msg":"4e49bc5f2b3d67c6 [logterm: 4, index: 132085, vote: 4e49bc5f2b3d67c6] rejected MsgVote from 620d71aa28ed3b63 [logterm: 3, index: 132070] at term 4"}
{"level":"info","ts":1531193321.4353561,"caller":"raft/node.go:306","msg":"raft.node: 4e49bc5f2b3d67c6 elected leader 620d71aa28ed3b63 at term 4"}
node b5c9c099610a418c.
{"level":"info","ts":1530759023.700201,"caller":"raft/node.go:306","msg":"raft.node: b5c9c099610a418c elected leader b5c9c099610a418c at term 2"}
// restart node
{"level":"info","ts":1531193320.4605248,"caller":"raft/raft.go:656","msg":"b5c9c099610a418c became follower at term 3"}
{"level":"info","ts":1531193320.470015,"caller":"raft/raft.go:364","msg":"newRaft b5c9c099610a418c [peers: [], term: 3, commit: 16067, applied: 0, lastindex: 16073, lastterm: 3]"}
{"level":"info","ts":1531193321.429727,"caller":"raft/raft.go:882","msg":"b5c9c099610a418c [logterm: 3, index: 16073, vote: 0] cast MsgPreVote for 620d71aa28ed3b63 [logterm: 3, index: 132070] at term 3"}
{"level":"info","ts":1531193321.4304776,"caller":"raft/raft.go:797","msg":"b5c9c099610a418c [term: 3] received a MsgVote message with higher term from 620d71aa28ed3b63 [term: 4]"}
{"level":"info","ts":1531193321.430521,"caller":"raft/raft.go:656","msg":"b5c9c099610a418c became follower at term 4"}
{"level":"info","ts":1531193321.4305408,"caller":"raft/raft.go:882","msg":"b5c9c099610a418c [logterm: 3, index: 16073, vote: 0] cast MsgVote for 620d71aa28ed3b63 [logterm: 3, index: 132070] at term 4"}
{"level":"info","ts":1531193321.4313545,"caller":"raft/node.go:306","msg":"raft.node: b5c9c099610a418c elected leader 620d71aa28ed3b63 at term 4"}
{"level":"info","ts":1531193321.4366477,"caller":"raft/raft.go:1282","msg":"b5c9c099610a418c [commit: 16067, lastindex: 16073, lastterm: 3] starts to restore snapshot [index: 132069, term: 3]"}
{"level":"info","ts":1531193321.4366844,"caller":"raft/log.go:288","msg":"log [committed=16067, applied=16067, unstable.offset=16074, len(unstable.Entries)=0] starts to restore snapshot [index: 132069, term: 3]"}
{"level":"info","ts":1531193321.4367511,"caller":"raft/raft.go:1301","msg":"b5c9c099610a418c restored progress of 4e49bc5f2b3d67c6 [next = 132070, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]"}
{"level":"info","ts":1531193321.4367745,"caller":"raft/raft.go:1301","msg":"b5c9c099610a418c restored progress of 620d71aa28ed3b63 [next = 132070, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]"}
{"level":"info","ts":1531193321.4367905,"caller":"raft/raft.go:1301","msg":"b5c9c099610a418c restored progress of b5c9c099610a418c [next = 132070, match = 132069, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]"}
{"level":"info","ts":1531193321.436805,"caller":"raft/raft.go:1249","msg":"b5c9c099610a418c [commit: 132069] restored snapshot [index: 132069, term: 3]"}
and the wal of this node b5c9c099610a418c is broken:
2018/07/10 11:28:40.220 log.go:84: [info] wal: [repairing /home/tidb/deploy/data.pd/member/wal/0000000000000000-0000000000000000.wal]
2018/07/10 11:28:40.430 log.go:86: [info] etcdserver: [repaired WAL error (unexpected EOF)]
2018/07/10 11:28:40.430 log.go:82: [warning] wal: [ignored file 0000000000000000-0000000000000000.wal.broken in wal]
2018/07/10 11:28:40.457 log.go:86: [info] etcdserver: [restarting member b5c9c099610a418c in cluster 27367556bc53fbb4 at commit index 16067]
2018/07/10 11:28:40.470 log.go:86: [info] mvcc: [restore compact to 14829]
2018/07/10 11:28:40.472 log.go:82: [warning] auth: [simple token is not cryptographically signed]
2018/07/10 11:28:40.472 log.go:86: [info] embed: [b5c9c099610a418c starting with cors ["*"]]
2018/07/10 11:28:40.472 log.go:86: [info] embed: [b5c9c099610a418c starting with host whitelist ["*"]]
2018/07/10 11:28:40.473 log.go:86: [info] etcdserver: [starting server... [version: 3.3.0+git, cluster version: to_be_decided]]
2018/07/10 11:28:40.473 log.go:86: [info] etcdserver/membership: [added member 4e49bc5f2b3d67c6 [http://172.16.9.5:2380] to cluster 27367556bc53fbb4]
2018/07/10 11:28:40.473 log.go:86: [info] rafthttp: [starting peer 4e49bc5f2b3d67c6...]
2018/07/10 11:28:40.473 log.go:86: [info] rafthttp: [started HTTP pipelining with peer 4e49bc5f2b3d67c6]
2018/07/10 11:28:40.475 log.go:86: [info] rafthttp: [started streaming with peer 4e49bc5f2b3d67c6 (writer)]
2018/07/10 11:28:40.475 log.go:86: [info] rafthttp: [started streaming with peer 4e49bc5f2b3d67c6 (writer)]
2018/07/10 11:28:40.477 log.go:86: [info] embed: [listening for peers on 172.16.9.9:2380]
2018
log entries:
I dump the wal and found node 620d71aa28ed3b63 different with node 4e49bc5f2b3d67c6 in the beginning of this term:
node 620d71aa28ed3b63:
3 132070 norm header:<ID:4279374470265339902 > txn:<compare:<target:VALUE key:"/pd/6574559945929147219/leader" value:"\n\003pd3\020\343\366\264\307\242\265\334\206b\032\027http://172.16.9.16:2380\"\027http://172.16.9.16:2379" > success:<request_put:<key:"/pd/6574559945929147219/timestamp" value:"\025?\263\211X\242\374\021" > > >
4 132071 norm
4 132072 norm method=PUT path="/0/members/620d71aa28ed3b63/attributes" val="{\"name\":\"pd3\",\"clientURLs\":[\"http://172.16.9.16:2379\"]}"
4 132073 norm method=PUT path="/0/members/b5c9c099610a418c/attributes" val="{\"name\":\"pd2\",\"clientURLs\":[\"http://172.16.9.9:2379\"]}"
4 132074 norm method=PUT path="/0/members/4e49bc5f2b3d67c6/attributes" val="{\"name\":\"pd1\",\"clientURLs\":[\"http://172.16.9.5:2379\"]}"
4 132075 norm header:<ID:4279374581445411335 > lease_grant:<TTL:3 ID:4279374581445411334 >
4 132076 norm method=PUT path="/0/members/4e49bc5f2b3d67c6/attributes" val="{\"name\":\"pd1\",\"clientURLs\":[\"http://172.16.9.5:2379\"]}"
4 132077 norm header:<ID:4279374581445411347 > lease_grant:<TTL:3 ID:4279374581445411346 >
4 132078 norm header:<ID:4279374581445411360 > lease_grant:<TTL:3 ID:4279374581445411359 >
4 132079 norm method=PUT path="/0/members/4e49bc5f2b3d67c6/attributes" val="{\"name\":\"pd1\",\"clientURLs\":[\"http://172.16.9.5:2379\"]}"
4 132080 norm header:<ID:4279374581445411373 > lease_grant:<TTL:3 ID:4279374581445411372 >
4 132081 norm method=PUT path="/0/members/4e49bc5f2b3d67c6/attributes" val="{\"name\":\"pd1\",\"clientURLs\":[\"http://172.16.9.5:2379\"]}"
4 132082 norm header:<ID:4279374581445411386 > lease_grant:<TTL:3 ID:4279374581445411385 >
4 132083 norm method=PUT path="/0/members/4e49bc5f2b3d67c6/attributes" val="{\"name\":\"pd1\",\"clientURLs\":[\"http://172.16.9.5:2379\"]}"
4 132084 norm header:<ID:4279374581445411399 > lease_grant:<TTL:3 ID:4279374581445411398 >
4 132085 norm header:<ID:4279374581445411400 > txn:<compare:<target:CREATE key:"/pd/6574559945929147219/leader" create_revision:0 > success:<request_put:<key:"/pd/6574559945929147219/leader" value:"\n\003pd3\020\343\366\264\307\242\265\334\206b\032\027http://172.16.9.16:2380\"\027http://172.16.9.16:2379" lease:4279374581445411398 > > >
node 4e49bc5f2b3d67c6:
3 132071 norm header:<ID:4279374470265339903 > txn:<compare:<target:VALUE key:"/pd/6574559945929147219/leader" value:"\n\003pd3\020\343\366\264\307\242\265\334\206b\032\027http://172.16.9.16:2380\"\027http://172.16.9.16:2379" > success:<request_put:<key:"/pd/6574559945929147219/timestamp" value:"\025?\263\212\016n.d" > > >
4 132072 norm
4 132073 norm method=PUT path="/0/members/620d71aa28ed3b63/attributes" val="{\"name\":\"pd3\",\"clientURLs\":[\"http://172.16.9.16:2379\"]}"
4 132074 norm header:<ID:7477774630629500142 > lease_grant:<TTL:60 ID:7477774630629500141 >
4 132075 norm header:<ID:7477774630629500144 > lease_grant:<TTL:600 ID:7477774630629500143 >
4 132076 norm header:<ID:7477774630629500146 > lease_grant:<TTL:60 ID:7477774630629500145 >
4 132077 norm header:<ID:7477774630629500147 > txn:<compare:<target:CREATE key:"/tidb/ddl/fg/owner/67c66468591964ed" create_revision:0 > success:<request_put:<key:"/tidb/ddl/fg/owner/67c66468591964ed" value:"90a17182-598b-43d3-80ef-03f26e9b3c83" lease:7477774630629500141 > > failure:<request_range:<key:"/tidb/ddl/fg/owner/67c66468591964ed" > > >
4 132078 norm header:<ID:7477774630629500148 > txn:<compare:<target:CREATE key:"/tidb/stats/owner/67c66468591964f1" create_revision:0 > success:<request_put:<key:"/tidb/stats/owner/67c66468591964f1" value:"90a17182-598b-43d3-80ef-03f26e9b3c83" lease:7477774630629500145 > > failure:<request_range:<key:"/tidb/stats/owner/67c66468591964f1" > > >
4 132079 norm header:<ID:7477774630629500149 > put:<key:"/tidb/ddl/all_schema_versions/90a17182-598b-43d3-80ef-03f26e9b3c83" value:"0" lease:7477774630629500143 >
4 132080 norm header:<ID:7477774630629500152 > lease_revoke:<ID:4279374470265225426 >
4 132081 norm header:<ID:7477774630629500153 > compaction:<revision:131926 >
4 132082 norm header:<ID:7477774630629500154 > lease_revoke:<ID:7477774630628398434 >
4 132083 norm header:<ID:7477774630629500155 > lease_revoke:<ID:7477774630628398425 >
4 132084 norm header:<ID:7477774630629500160 > lease_revoke:<ID:7477774630628398429 >
4 132085 norm header:<ID:7477774630629500161 > compaction:<revision:131926 >
and node 620d71aa28ed3b63 can read the key /pd/6574559945929147219/leader, the 4e49bc5f2b3d67c6 can not read it.
etcd version:
master + commit: 2b3aa7e1d49dd8484138c95ac9ab7dfc8e1e7dc0
config:
enable PreVote and CheckQuorum
@nolouch How often do you see this? Can you help reproduce with current master?
@gyuho after restarting all node, the service seems to go well, but I pointed out that the reading of the keys is inconsistent. and I still try to reproduce it.
is it Network Partitions ?
@aleafboat I'm not sure, it only appears once in production, and the environment is gone.
This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 21 days if no further activity occurs. Thank you for your contributions.