TestRestartMember: context deadline exceeded #7595

mitake · 2017-03-24T05:04:56Z

via https://jenkins-etcd-public.prod.coreos.systems/job/etcd-proxy/1084/consoleFull in the PR #7569

--- FAIL: TestRestartMember (163.14s)
	cluster_test.go:521: #2: watch on unix://127.0.0.1:2193617511 error: context deadline exceeded

Possibly related to #7258 and #7379 ?

The text was updated successfully, but these errors were encountered:

heyitsanthony · 2017-03-24T22:38:54Z

Might be a raft bug, the logs are getting spammed with leadership change messages:

2017-03-24 02:14:23.820073 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.823444 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.830189 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.832424 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.840226 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.842899 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.850610 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.852937 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.862708 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.862990 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.870388 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.872647 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.880820 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.883083 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.890079 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.892419 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.900274 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.902754 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.913205 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.916137 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.921303 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.923624 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.930672 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.935528 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.941130 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.945300 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.950502 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.953071 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.960465 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.963414 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.971261 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.973549 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.980855 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.985781 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:23.990174 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8
2017-03-24 02:14:23.993201 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3554539849c8e8e to 3626c71ed93b52c4 at term 8
2017-03-24 02:14:24.000691 I | raft: raft.node: b4501d80aad6ac80 changed leader from 3626c71ed93b52c4 to 3554539849c8e8e at term 8

/cc @xiang90

gyuho · 2017-03-27T19:05:11Z

test-restart-member.txt

# current leader 3554539849c8e8e at term 7
2017-03-24 02:14:18.460429 I | raft: raft.node: b4501d80aad6ac80 elected leader 3554539849c8e8e at term 7

# current leader 3554539849c8e8e is stepping down
2017-03-24 02:14:18.661534 I | raft: raft.node: 3626c71ed93b52c4 lost leader 3554539849c8e8e at term 8

# new leader 3626c71ed93b52c4 at term 8
2017-03-24 02:14:18.670565 I | raft: raft.node: 3626c71ed93b52c4 elected leader 3626c71ed93b52c4 at term 8
2017-03-24 02:14:18.671246 E | rafthttp: failed to dial 3554539849c8e8e on stream MsgApp v2 (dial unix 127.0.0.1:2193517511: connect: no such file or directory)
2017-03-24 02:14:18.671475 I | rafthttp: peer 3554539849c8e8e became inactive
2017-03-24 02:14:18.673701 I | raft: raft.node: b4501d80aad6ac80 elected leader 3626c71ed93b52c4 at term 8

# old leader 3554539849c8e8e comes back
2017-03-24 02:14:18.754261 I | integration: restarting 8862439040227607551 ()
2017-03-24 02:14:18.754783 I | integration: launching 8862439040227607551 ()
2017-03-24 02:14:18.764399 I | etcdserver: name = 8862439040227607551
2017-03-24 02:14:18.764486 I | etcdserver: data dir = /tmp/etcd943149656
2017-03-24 02:14:18.764537 I | etcdserver: member dir = /tmp/etcd943149656/member
2017-03-24 02:14:18.764579 I | etcdserver: heartbeat = 10ms
2017-03-24 02:14:18.764626 I | etcdserver: election = 100ms
2017-03-24 02:14:18.764668 I | etcdserver: snapshot count = 0
2017-03-24 02:14:18.764723 I | etcdserver: advertise client URLs = unix://127.0.0.1:2193617511
2017-03-24 02:14:18.767013 I | etcdserver: restarting member 3554539849c8e8e in cluster 8a55663c7afccf2 at commit index 17
2017-03-24 02:14:18.767254 I | raft: 3554539849c8e8e became follower at term 7
2017-03-24 02:14:18.767351 I | raft: newRaft 3554539849c8e8e [peers: [], term: 7, commit: 17, applied: 0, lastindex: 17, lastterm: 7]
2017-03-24 02:14:18.777681 W | auth: simple token is not cryptographically signed
2017-03-24 02:14:18.782006 I | etcdserver: set snapshot count to default 100000
2017-03-24 02:14:18.782103 I | etcdserver: starting server... [version: 3.2.0+git, cluster version: to_be_decided]
2017-03-24 02:14:18.792854 I | rafthttp: started HTTP pipelining with peer 3626c71ed93b52c4

# indicates progress on peer is missing
2017-03-24 02:14:18.793183 E | rafthttp: failed to find member 3626c71ed93b52c4 in cluster 8a55663c7afccf2

# old leader 3554539849c8e8e becomes the leader in single-node cluster? 
2017-03-24 02:14:18.767351 I | raft: newRaft 3554539849c8e8e [peers: [], term: 7, commit: 17, applied: 0, lastindex: 17, lastterm: 7]
2017-03-24 02:14:18.794536 I | raft: 3554539849c8e8e is starting a new election at term 7
2017-03-24 02:14:18.794759 I | raft: 3554539849c8e8e became candidate at term 8
2017-03-24 02:14:18.794852 I | raft: 3554539849c8e8e received MsgVoteResp from 3554539849c8e8e at term 8
2017-03-24 02:14:18.794960 I | raft: 3554539849c8e8e became leader at term 8
2017-03-24 02:14:18.795042 I | raft: raft.node: 3554539849c8e8e elected leader 3554539849c8e8e at term 8
2017-03-24 02:14:18.795894 I | integration: launched 8862439040227607551 ()
2017-03-24 02:14:18.795963 I | integration: restarted 8862439040227607551 ()

Somehow old leader comes back as a leader with a single-node cluster

Old leader should have added member first like

2017-04-06 15:29:31.427536 I | raft: ==========newRaft 326abdccb20359fe [peers: [], term: 2, commit: 11, applied: 0, lastindex: 11, lastterm: 2]
2017-04-06 15:29:31.429147 W | auth: simple token is not cryptographically signed
2017-04-06 15:29:31.429583 I | etcdserver: set snapshot count to default 100000
2017-04-06 15:29:31.429594 I | etcdserver: starting server... [version: 3.1.3+git, cluster version: to_be_decided]
2017-04-06 15:29:31.429644 E | etcdserver: cannot monitor file descriptor usage (cannot get FDUsage on darwin)
============== ConfChangeAdd: 326abdccb20359fe for 326abdccb20359fe
============ setProgress: 326abdccb20359fe for 326abdccb20359fe
2017-04-06 15:29:31.429813 I | etcdserver/membership: added member 326abdccb20359fe [unix://127.0.0.1:2100512917] to cluster 5cd30f62cc099194
2017-04-06 15:29:31.429824 I | integration: launched 686597568185812930 ()
============== ConfChangeAdd: 326abdccb20359fe for 429095cd84e8e85b
============ setProgress: 326abdccb20359fe for 429095cd84e8e85b
2017-04-06 15:29:31.466193 I | integration: restarted 686597568185812930 ()
2017-04-06 15:29:31.466216 I | raft: 326abdccb20359fe [term: 2] received a MsgHeartbeat message with higher term from c120463ca22bf51d [term: 10]
2017-04-06 15:29:31.466235 I | raft: 326abdccb20359fe became follower at term 10
2017-04-06 15:29:31.466244 I | raft: raft.node: 326abdccb20359fe elected leader c120463ca22bf51d at term 10
2017-04-06 15:29:31.466337 I | etcdserver/membership: added member 429095cd84e8e85b [unix://127.0.0.1:2100312917] to cluster 5cd30f62cc099194
2017-04-06 15:29:31.466392 I | rafthttp: starting peer 429095cd84e8e85b...
2017-04-06 15:29:31.466697 I | rafthttp: started HTTP pipelining with peer 429095cd84e8e85b
2017-04-06 15:29:31.466778 I | rafthttp: peer 326abdccb20359fe became active
2017-04-06 15:29:31.467146 I | rafthttp: started streaming with peer 429095cd84e8e85b (writer)
2017-04-06 15:29:31.467576 I | rafthttp: started streaming with peer 429095cd84e8e85b (writer)
2017-04-06 15:29:31.468328 I | rafthttp: started peer 429095cd84e8e85b
2017-04-06 15:29:31.468425 I | rafthttp: added peer 429095cd84e8e85b
2017-04-06 15:29:31.468499 I | rafthttp: started streaming with peer 429095cd84e8e85b (stream Message reader)
2017-04-06 15:29:31.468566 I | rafthttp: started streaming with peer 429095cd84e8e85b (stream MsgApp v2 reader)
============== ConfChangeAdd: 326abdccb20359fe for c120463ca22bf51d
============ setProgress: 326abdccb20359fe for c120463ca22bf51d

Could be similar to #7280.

gyuho · 2017-04-06T23:04:13Z

@xiang90 @heyitsanthony I think it is also possible that follower misses the raftpb.ConfChangeAddNode proposal apply in the beginning.

Failure logs show that old leader comes back as if it had been the single node cluster.

Here https://github.com/coreos/etcd/blob/master/raft/raft.go#L637

r.quorum() possibly returned 1. No progress is populated yet from applied ConfChangeAddNode entries (it expects to return 2, instead of 1 in 3-node cluster). The log rafthttp: failed to find member 3626c71ed93b52c4 in cluster 8a55663c7afccf2 also indicates the Progress had not been populated yet.

func (r *raft) campaign(t CampaignType) {
	...
	if r.quorum() == r.poll(r.id, voteRespMsgType(voteMsg), true) {
		if t == campaignPreElection {
			r.campaign(campaignElection)
		} else {
			r.becomeLeader()
	...

Problem is etcd server-side apply layer does not wait on raftpb.EntryConfChange apply finish. In slow machine, it might take awhile to apply this initial add-node proposal. Meanwhile, follower advances before the entry is applied, and then elapses the election timeout, and then becomes the candidate, then the single-node cluster.

etcdserver should not proceed until the initial ConfChangeAddNode entry is applied. We could add another check, if the node is follower and the committed entries contain raftpb.EntryConfChange, then wait for apply.

Edits

We do wait for conf change entry apply with configure https://github.com/coreos/etcd/blob/master/etcdserver/server.go#L1162, and that configure is not even in the related code path... So it's still possible apply-layer calls raft.Advance before applying the raftpb.EntryConfChange entry.

When apply-layer sees configuration change entry in raft.Ready.CommittedEntries, the server should not proceed until such entry is applied. Otherwise, follower's raft layer advances, possibly election-timeout, and becomes single-node cluster, before add-node conf changes are applied. Fix etcd-io#7595. Signed-off-by: Gyu-Ho Lee <gyuhox@gmail.com>

When apply-layer sees configuration change entry in raft.Ready.CommittedEntries, the server should not proceed until that entry is applied. Otherwise, follower's raft layer advances, possibly election-timeouts, and becomes the leader in single-node cluster, before add-node conf change of other nodes is applied. Fix etcd-io#7595. Signed-off-by: Gyu-Ho Lee <gyuhox@gmail.com>

Problem is: `Step1`: `etcdserver/raft.go`'s `Ready` process routine sends config-change entries via `r.applyc <- ap` (https://github.com/coreos/etcd/blob/master/etcdserver/raft.go#L193-L203) `Step2`: `etcdserver/server.go`s `*EtcdServer.run` routine receives this via `ap := <-s.r.apply()` (https://github.com/coreos/etcd/blob/master/etcdserver/server.go#L735-L738) `StepA`: `Step1` proceeds without sync, right after sending `r.applyc <- ap`. `StepB`: `Step2` proceeds without sync, right after `sched.Schedule(s.applyAll(&ep,&ap))`. `StepC`: `etcdserver` tries to sync with `s.applyAll(&ep,&ap)` by calling `rh.waitForApply()`. `rh.waitForApply()` waits for all pending jobs to finish in `pkg/schedule` side. However, the order of `StepA`,`StepB`,`StepC` is not guaranteed. It is possible that `StepC` happens first, and proceeds without waiting on apply. And the restarting member comes back as a leader in single-node cluster, when there is no synchronization between apply-layer and config-change Raft entry apply. Confirmed with more debugging lines below, only reproducible with slow CPU VM (~2 vCPU). ``` ~:24.005397 I | etcdserver: starting server... [version: 3.2.0+git, cluster version: to_be_decided] ~:24.011136 I | etcdserver: [DEBUG] 29b2d24047a277df waitForApply before ~:24.011194 I | etcdserver: [DEBUG] 29b2d24047a277df starts wait for 0 pending jobs ~:24.011234 I | etcdserver: [DEBUG] 29b2d24047a277df finished wait for 0 pending jobs (current pending 0) ~:24.011268 I | etcdserver: [DEBUG] 29b2d24047a277df waitForApply after ~:24.011348 I | etcdserver: [DEBUG] [0] 29b2d24047a277df is scheduling conf change on 29b2d24047a277df ~:24.011396 I | etcdserver: [DEBUG] [1] 29b2d24047a277df is scheduling conf change on 5edf80e32a334cf0 ~:24.011437 I | etcdserver: [DEBUG] [2] 29b2d24047a277df is scheduling conf change on e32e31e76c8d2678 ~:24.011477 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on 29b2d24047a277df ~:24.011509 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on 5edf80e32a334cf0 ~:24.011545 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on e32e31e76c8d2678 ~:24.012500 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df before ~:24.013014 I | etcdserver/membership: added member 29b2d24047a277df [unix://127.0.0.1:2100515039] to cluster 9250d4ae34216949 ~:24.013066 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df after ~:24.013113 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df after trigger ~:24.013158 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 5edf80e32a334cf0 before ~:24.013666 W | etcdserver: failed to send out heartbeat on time (exceeded the 10ms timeout for 11.964739ms) ~:24.013709 W | etcdserver: server is likely overloaded ~:24.013750 W | etcdserver: failed to send out heartbeat on time (exceeded the 10ms timeout for 12.057265ms) ~:24.013775 W | etcdserver: server is likely overloaded ~:24.013950 I | raft: 29b2d24047a277df is starting a new election at term 4 ~:24.014012 I | raft: 29b2d24047a277df became candidate at term 5 ~:24.014051 I | raft: 29b2d24047a277df received MsgVoteResp from 29b2d24047a277df at term 5 ~:24.014107 I | raft: 29b2d24047a277df became leader at term 5 ~:24.014146 I | raft: raft.node: 29b2d24047a277df elected leader 29b2d24047a277df at term 5 ``` I am printing out the number of pending jobs before we call `sched.WaitFinish(0)`, and there was no pending jobs, so it returned immediately (before we schedule `applyAll`). This is the root cause to: - etcd-io#7595 - etcd-io#7739 - etcd-io#7802 `sched.WaitFinish(0)` doesn't work when `len(f.pendings)==0` and `f.finished==0`. Config-change is the first job to apply, so `f.finished` is 0 in this case. `f.finished` monotonically increases, so we need `WaitFinish(finished+1)`. And `finished` must be the one before calling `Schedule`. This is safe because `Schedule(applyAll)` is the only place adding jobs to `sched`. This patch ensures scheduler waits on the single job of `applyAll`, by getting the current number of finished jobs before sending `Schedule`. Confirmed that it fixes the issue, as below: ``` ~:43.198354 I | rafthttp: started streaming with peer 36cda5222aba364b (stream MsgApp v2 reader) ~:43.198740 I | etcdserver: [DEBUG] 3988bc20c2b2e40c waitForApply before ~:43.198836 I | etcdserver: [DEBUG] 3988bc20c2b2e40c starts wait for 0 pending jobs, 1 finished jobs ~:43.200696 I | integration: launched 3169361310155633349 () ~:43.201784 I | etcdserver: [DEBUG] [0] 3988bc20c2b2e40c is scheduling conf change on 36cda5222aba364b ~:43.201884 I | etcdserver: [DEBUG] [1] 3988bc20c2b2e40c is scheduling conf change on 3988bc20c2b2e40c ~:43.201965 I | etcdserver: [DEBUG] [2] 3988bc20c2b2e40c is scheduling conf change on cf5d6cbc2a121727 ~:43.202070 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on 36cda5222aba364b ~:43.202139 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on 3988bc20c2b2e40c ~:43.202204 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on cf5d6cbc2a121727 ~:43.202444 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) before ~:43.204486 I | etcdserver/membership: added member 36cda5222aba364b [unix://127.0.0.1:2100913646] to cluster 425d73f1b7b01674 ~:43.204588 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) after ~:43.204703 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) after trigger ~:43.204791 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) before ~:43.205689 I | etcdserver/membership: added member 3988bc20c2b2e40c [unix://127.0.0.1:2101113646] to cluster 425d73f1b7b01674 ~:43.205783 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) after ~:43.205929 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) after trigger ~:43.206056 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) before ~:43.207353 I | etcdserver/membership: added member cf5d6cbc2a121727 [unix://127.0.0.1:2100713646] to cluster 425d73f1b7b01674 ~:43.207516 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) after ~:43.207619 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) after trigger ~:43.207710 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on 36cda5222aba364b ~:43.207781 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on 3988bc20c2b2e40c ~:43.207843 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on cf5d6cbc2a121727 ~:43.207951 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished wait for 0 pending jobs (current pending 0, finished 1) ~:43.208029 I | rafthttp: started HTTP pipelining with peer cf5d6cbc2a121727 ~:43.210339 I | rafthttp: peer 3988bc20c2b2e40c became active ~:43.210435 I | rafthttp: established a TCP streaming connection with peer 3988bc20c2b2e40c (stream MsgApp v2 reader) ~:43.210861 I | rafthttp: started streaming with peer 3988bc20c2b2e40c (writer) ~:43.211732 I | etcdserver: [DEBUG] 3988bc20c2b2e40c waitForApply after ``` Signed-off-by: Gyu-Ho Lee <gyuhox@gmail.com>

Problem is: `Step1`: `etcdserver/raft.go`'s `Ready` process routine sends config-change entries via `r.applyc <- ap` (https://github.com/coreos/etcd/blob/master/etcdserver/raft.go#L193-L203) `Step2`: `etcdserver/server.go`'s `*EtcdServer.run` routine receives this via `ap := <-s.r.apply()` (https://github.com/coreos/etcd/blob/master/etcdserver/server.go#L735-L738) `StepA`: `Step1` proceeds without sync, right after sending `r.applyc <- ap`. `StepB`: `Step2` proceeds without sync, right after `sched.Schedule(s.applyAll(&ep,&ap))`. `StepC`: `etcdserver` tries to sync with `s.applyAll(&ep,&ap)` by calling `rh.waitForApply()`. `rh.waitForApply()` waits for all pending jobs to finish in `pkg/schedule` side. However, the order of `StepA`,`StepB`,`StepC` is not guaranteed. It is possible that `StepC` happens first, and proceeds without waiting on apply. And the restarting member comes back as a leader in single-node cluster, when there is no synchronization between apply-layer and config-change Raft entry apply. Confirmed with more debugging lines below, only reproducible with slow CPU VM (~2 vCPU). ``` ~:24.005397 I | etcdserver: starting server... [version: 3.2.0+git, cluster version: to_be_decided] ~:24.011136 I | etcdserver: [DEBUG] 29b2d24047a277df waitForApply before ~:24.011194 I | etcdserver: [DEBUG] 29b2d24047a277df starts wait for 0 pending jobs ~:24.011234 I | etcdserver: [DEBUG] 29b2d24047a277df finished wait for 0 pending jobs (current pending 0) ~:24.011268 I | etcdserver: [DEBUG] 29b2d24047a277df waitForApply after ~:24.011348 I | etcdserver: [DEBUG] [0] 29b2d24047a277df is scheduling conf change on 29b2d24047a277df ~:24.011396 I | etcdserver: [DEBUG] [1] 29b2d24047a277df is scheduling conf change on 5edf80e32a334cf0 ~:24.011437 I | etcdserver: [DEBUG] [2] 29b2d24047a277df is scheduling conf change on e32e31e76c8d2678 ~:24.011477 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on 29b2d24047a277df ~:24.011509 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on 5edf80e32a334cf0 ~:24.011545 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on e32e31e76c8d2678 ~:24.012500 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df before ~:24.013014 I | etcdserver/membership: added member 29b2d24047a277df [unix://127.0.0.1:2100515039] to cluster 9250d4ae34216949 ~:24.013066 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df after ~:24.013113 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df after trigger ~:24.013158 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 5edf80e32a334cf0 before ~:24.013666 W | etcdserver: failed to send out heartbeat on time (exceeded the 10ms timeout for 11.964739ms) ~:24.013709 W | etcdserver: server is likely overloaded ~:24.013750 W | etcdserver: failed to send out heartbeat on time (exceeded the 10ms timeout for 12.057265ms) ~:24.013775 W | etcdserver: server is likely overloaded ~:24.013950 I | raft: 29b2d24047a277df is starting a new election at term 4 ~:24.014012 I | raft: 29b2d24047a277df became candidate at term 5 ~:24.014051 I | raft: 29b2d24047a277df received MsgVoteResp from 29b2d24047a277df at term 5 ~:24.014107 I | raft: 29b2d24047a277df became leader at term 5 ~:24.014146 I | raft: raft.node: 29b2d24047a277df elected leader 29b2d24047a277df at term 5 ``` I am printing out the number of pending jobs before we call `sched.WaitFinish(0)`, and there was no pending jobs, so it returned immediately (before we schedule `applyAll`). This is the root cause to: - etcd-io#7595 - etcd-io#7739 - etcd-io#7802 `sched.WaitFinish(0)` doesn't work when `len(f.pendings)==0` and `f.finished==0`. Config-change is the first job to apply, so `f.finished` is 0 in this case. `f.finished` monotonically increases, so we need `WaitFinish(finished+1)`. And `finished` must be the one before calling `Schedule`. This is safe because `Schedule(applyAll)` is the only place adding jobs to `sched`. This patch ensures scheduler waits on the single job of `applyAll`, by getting the current number of finished jobs before sending `Schedule`. Confirmed that it fixes the issue, as below: ``` ~:43.198354 I | rafthttp: started streaming with peer 36cda5222aba364b (stream MsgApp v2 reader) ~:43.198740 I | etcdserver: [DEBUG] 3988bc20c2b2e40c waitForApply before ~:43.198836 I | etcdserver: [DEBUG] 3988bc20c2b2e40c starts wait for 0 pending jobs, 1 finished jobs ~:43.200696 I | integration: launched 3169361310155633349 () ~:43.201784 I | etcdserver: [DEBUG] [0] 3988bc20c2b2e40c is scheduling conf change on 36cda5222aba364b ~:43.201884 I | etcdserver: [DEBUG] [1] 3988bc20c2b2e40c is scheduling conf change on 3988bc20c2b2e40c ~:43.201965 I | etcdserver: [DEBUG] [2] 3988bc20c2b2e40c is scheduling conf change on cf5d6cbc2a121727 ~:43.202070 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on 36cda5222aba364b ~:43.202139 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on 3988bc20c2b2e40c ~:43.202204 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on cf5d6cbc2a121727 ~:43.202444 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) before ~:43.204486 I | etcdserver/membership: added member 36cda5222aba364b [unix://127.0.0.1:2100913646] to cluster 425d73f1b7b01674 ~:43.204588 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) after ~:43.204703 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) after trigger ~:43.204791 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) before ~:43.205689 I | etcdserver/membership: added member 3988bc20c2b2e40c [unix://127.0.0.1:2101113646] to cluster 425d73f1b7b01674 ~:43.205783 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) after ~:43.205929 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) after trigger ~:43.206056 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) before ~:43.207353 I | etcdserver/membership: added member cf5d6cbc2a121727 [unix://127.0.0.1:2100713646] to cluster 425d73f1b7b01674 ~:43.207516 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) after ~:43.207619 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) after trigger ~:43.207710 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on 36cda5222aba364b ~:43.207781 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on 3988bc20c2b2e40c ~:43.207843 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on cf5d6cbc2a121727 ~:43.207951 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished wait for 0 pending jobs (current pending 0, finished 1) ~:43.208029 I | rafthttp: started HTTP pipelining with peer cf5d6cbc2a121727 ~:43.210339 I | rafthttp: peer 3988bc20c2b2e40c became active ~:43.210435 I | rafthttp: established a TCP streaming connection with peer 3988bc20c2b2e40c (stream MsgApp v2 reader) ~:43.210861 I | rafthttp: started streaming with peer 3988bc20c2b2e40c (writer) ~:43.211732 I | etcdserver: [DEBUG] 3988bc20c2b2e40c waitForApply after ``` Signed-off-by: Gyu-Ho Lee <gyuhox@gmail.com>

Problem is: `Step1`: `etcdserver/raft.go`'s `Ready` process routine sends config-change entries via `r.applyc <- ap` (https://github.com/coreos/etcd/blob/master/etcdserver/raft.go#L193-L203) `Step2`: `etcdserver/server.go`'s `*EtcdServer.run` routine receives this via `ap := <-s.r.apply()` (https://github.com/coreos/etcd/blob/master/etcdserver/server.go#L735-L738) `StepA`: `Step1` proceeds without sync, right after sending `r.applyc <- ap`. `StepB`: `Step2` proceeds without sync, right after `sched.Schedule(s.applyAll(&ep,&ap))`. `StepC`: `etcdserver` tries to sync with `s.applyAll(&ep,&ap)` by calling `rh.waitForApply()`. `rh.waitForApply()` waits for all pending jobs to finish in `pkg/schedule` side. However, the order of `StepA`,`StepB`,`StepC` is not guaranteed. It is possible that `StepC` happens first, and proceeds without waiting on apply. And the restarting member comes back as a leader in single-node cluster, when there is no synchronization between apply-layer and config-change Raft entry apply. Confirmed with more debugging lines below, only reproducible with slow CPU VM (~2 vCPU). ``` ~:24.005397 I | etcdserver: starting server... [version: 3.2.0+git, cluster version: to_be_decided] ~:24.011136 I | etcdserver: [DEBUG] 29b2d24047a277df waitForApply before ~:24.011194 I | etcdserver: [DEBUG] 29b2d24047a277df starts wait for 0 pending jobs ~:24.011234 I | etcdserver: [DEBUG] 29b2d24047a277df finished wait for 0 pending jobs (current pending 0) ~:24.011268 I | etcdserver: [DEBUG] 29b2d24047a277df waitForApply after ~:24.011348 I | etcdserver: [DEBUG] [0] 29b2d24047a277df is scheduling conf change on 29b2d24047a277df ~:24.011396 I | etcdserver: [DEBUG] [1] 29b2d24047a277df is scheduling conf change on 5edf80e32a334cf0 ~:24.011437 I | etcdserver: [DEBUG] [2] 29b2d24047a277df is scheduling conf change on e32e31e76c8d2678 ~:24.011477 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on 29b2d24047a277df ~:24.011509 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on 5edf80e32a334cf0 ~:24.011545 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on e32e31e76c8d2678 ~:24.012500 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df before ~:24.013014 I | etcdserver/membership: added member 29b2d24047a277df [unix://127.0.0.1:2100515039] to cluster 9250d4ae34216949 ~:24.013066 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df after ~:24.013113 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df after trigger ~:24.013158 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 5edf80e32a334cf0 before ~:24.013666 W | etcdserver: failed to send out heartbeat on time (exceeded the 10ms timeout for 11.964739ms) ~:24.013709 W | etcdserver: server is likely overloaded ~:24.013750 W | etcdserver: failed to send out heartbeat on time (exceeded the 10ms timeout for 12.057265ms) ~:24.013775 W | etcdserver: server is likely overloaded ~:24.013950 I | raft: 29b2d24047a277df is starting a new election at term 4 ~:24.014012 I | raft: 29b2d24047a277df became candidate at term 5 ~:24.014051 I | raft: 29b2d24047a277df received MsgVoteResp from 29b2d24047a277df at term 5 ~:24.014107 I | raft: 29b2d24047a277df became leader at term 5 ~:24.014146 I | raft: raft.node: 29b2d24047a277df elected leader 29b2d24047a277df at term 5 ``` I am printing out the number of pending jobs before we call `sched.WaitFinish(0)`, and there was no pending jobs, so it returned immediately (before we schedule `applyAll`). This is the root cause to: - etcd-io#7595 - etcd-io#7739 - etcd-io#7802 `sched.WaitFinish(0)` doesn't work when `len(f.pendings)==0` and `f.finished==0`. Config-change is the first job to apply, so `f.finished` is 0 in this case. `f.finished` monotonically increases, so we need `WaitFinish(finished+1)`. And `finished` must be the one before calling `Schedule`. This is safe because `Schedule(applyAll)` is the only place adding jobs to `sched`. Then scheduler waits on the single job of `applyAll`, by getting the current number of finished jobs before sending `Schedule`. Or just make it be blocked until 'applyAll' routine triggers on the config-change job. This patch just removes 'waitForApply', and signal 'raftDone' to wait until applyAll finishes applying entries. Confirmed that it fixes the issue, as below: ``` ~:43.198354 I | rafthttp: started streaming with peer 36cda5222aba364b (stream MsgApp v2 reader) ~:43.198740 I | etcdserver: [DEBUG] 3988bc20c2b2e40c waitForApply before ~:43.198836 I | etcdserver: [DEBUG] 3988bc20c2b2e40c starts wait for 0 pending jobs, 1 finished jobs ~:43.200696 I | integration: launched 3169361310155633349 () ~:43.201784 I | etcdserver: [DEBUG] [0] 3988bc20c2b2e40c is scheduling conf change on 36cda5222aba364b ~:43.201884 I | etcdserver: [DEBUG] [1] 3988bc20c2b2e40c is scheduling conf change on 3988bc20c2b2e40c ~:43.201965 I | etcdserver: [DEBUG] [2] 3988bc20c2b2e40c is scheduling conf change on cf5d6cbc2a121727 ~:43.202070 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on 36cda5222aba364b ~:43.202139 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on 3988bc20c2b2e40c ~:43.202204 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on cf5d6cbc2a121727 ~:43.202444 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) before ~:43.204486 I | etcdserver/membership: added member 36cda5222aba364b [unix://127.0.0.1:2100913646] to cluster 425d73f1b7b01674 ~:43.204588 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) after ~:43.204703 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) after trigger ~:43.204791 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) before ~:43.205689 I | etcdserver/membership: added member 3988bc20c2b2e40c [unix://127.0.0.1:2101113646] to cluster 425d73f1b7b01674 ~:43.205783 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) after ~:43.205929 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) after trigger ~:43.206056 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) before ~:43.207353 I | etcdserver/membership: added member cf5d6cbc2a121727 [unix://127.0.0.1:2100713646] to cluster 425d73f1b7b01674 ~:43.207516 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) after ~:43.207619 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) after trigger ~:43.207710 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on 36cda5222aba364b ~:43.207781 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on 3988bc20c2b2e40c ~:43.207843 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on cf5d6cbc2a121727 ~:43.207951 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished wait for 0 pending jobs (current pending 0, finished 1) ~:43.208029 I | rafthttp: started HTTP pipelining with peer cf5d6cbc2a121727 ~:43.210339 I | rafthttp: peer 3988bc20c2b2e40c became active ~:43.210435 I | rafthttp: established a TCP streaming connection with peer 3988bc20c2b2e40c (stream MsgApp v2 reader) ~:43.210861 I | rafthttp: started streaming with peer 3988bc20c2b2e40c (writer) ~:43.211732 I | etcdserver: [DEBUG] 3988bc20c2b2e40c waitForApply after ``` Signed-off-by: Gyu-Ho Lee <gyuhox@gmail.com>

Problem is: `Step1`: `etcdserver/raft.go`'s `Ready` process routine sends config-change entries via `r.applyc <- ap` (https://github.com/coreos/etcd/blob/master/etcdserver/raft.go#L193-L203) `Step2`: `etcdserver/server.go`'s `*EtcdServer.run` routine receives this via `ap := <-s.r.apply()` (https://github.com/coreos/etcd/blob/master/etcdserver/server.go#L735-L738) `StepA`: `Step1` proceeds without sync, right after sending `r.applyc <- ap`. `StepB`: `Step2` proceeds without sync, right after `sched.Schedule(s.applyAll(&ep,&ap))`. `StepC`: `etcdserver` tries to sync with `s.applyAll(&ep,&ap)` by calling `rh.waitForApply()`. `rh.waitForApply()` waits for all pending jobs to finish in `pkg/schedule` side. However, the order of `StepA`,`StepB`,`StepC` is not guaranteed. It is possible that `StepC` happens first, and proceeds without waiting on apply. And the restarting member comes back as a leader in single-node cluster, when there is no synchronization between apply-layer and config-change Raft entry apply. Confirmed with more debugging lines below, only reproducible with slow CPU VM (~2 vCPU). ``` ~:24.005397 I | etcdserver: starting server... [version: 3.2.0+git, cluster version: to_be_decided] ~:24.011136 I | etcdserver: [DEBUG] 29b2d24047a277df waitForApply before ~:24.011194 I | etcdserver: [DEBUG] 29b2d24047a277df starts wait for 0 pending jobs ~:24.011234 I | etcdserver: [DEBUG] 29b2d24047a277df finished wait for 0 pending jobs (current pending 0) ~:24.011268 I | etcdserver: [DEBUG] 29b2d24047a277df waitForApply after ~:24.011348 I | etcdserver: [DEBUG] [0] 29b2d24047a277df is scheduling conf change on 29b2d24047a277df ~:24.011396 I | etcdserver: [DEBUG] [1] 29b2d24047a277df is scheduling conf change on 5edf80e32a334cf0 ~:24.011437 I | etcdserver: [DEBUG] [2] 29b2d24047a277df is scheduling conf change on e32e31e76c8d2678 ~:24.011477 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on 29b2d24047a277df ~:24.011509 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on 5edf80e32a334cf0 ~:24.011545 I | etcdserver: [DEBUG] 29b2d24047a277df scheduled conf change on e32e31e76c8d2678 ~:24.012500 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df before ~:24.013014 I | etcdserver/membership: added member 29b2d24047a277df [unix://127.0.0.1:2100515039] to cluster 9250d4ae34216949 ~:24.013066 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df after ~:24.013113 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 29b2d24047a277df after trigger ~:24.013158 I | etcdserver: [DEBUG] 29b2d24047a277df applyConfChange on 5edf80e32a334cf0 before ~:24.013666 W | etcdserver: failed to send out heartbeat on time (exceeded the 10ms timeout for 11.964739ms) ~:24.013709 W | etcdserver: server is likely overloaded ~:24.013750 W | etcdserver: failed to send out heartbeat on time (exceeded the 10ms timeout for 12.057265ms) ~:24.013775 W | etcdserver: server is likely overloaded ~:24.013950 I | raft: 29b2d24047a277df is starting a new election at term 4 ~:24.014012 I | raft: 29b2d24047a277df became candidate at term 5 ~:24.014051 I | raft: 29b2d24047a277df received MsgVoteResp from 29b2d24047a277df at term 5 ~:24.014107 I | raft: 29b2d24047a277df became leader at term 5 ~:24.014146 I | raft: raft.node: 29b2d24047a277df elected leader 29b2d24047a277df at term 5 ``` I am printing out the number of pending jobs before we call `sched.WaitFinish(0)`, and there was no pending jobs, so it returned immediately (before we schedule `applyAll`). This is the root cause to: - etcd-io#7595 - etcd-io#7739 - etcd-io#7802 `sched.WaitFinish(0)` doesn't work when `len(f.pendings)==0` and `f.finished==0`. Config-change is the first job to apply, so `f.finished` is 0 in this case. `f.finished` monotonically increases, so we need `WaitFinish(finished+1)`. And `finished` must be the one before calling `Schedule`. This is safe because `Schedule(applyAll)` is the only place adding jobs to `sched`. Then scheduler waits on the single job of `applyAll`, by getting the current number of finished jobs before sending `Schedule`. Or just make it be blocked until `applyAll` routine triggers on the config-change job. This patch just removes `waitForApply`, and signal `raftDone` to wait until `applyAll` finishes applying entries. Confirmed that it fixes the issue, as below: ``` ~:43.198354 I | rafthttp: started streaming with peer 36cda5222aba364b (stream MsgApp v2 reader) ~:43.198740 I | etcdserver: [DEBUG] 3988bc20c2b2e40c waitForApply before ~:43.198836 I | etcdserver: [DEBUG] 3988bc20c2b2e40c starts wait for 0 pending jobs, 1 finished jobs ~:43.200696 I | integration: launched 3169361310155633349 () ~:43.201784 I | etcdserver: [DEBUG] [0] 3988bc20c2b2e40c is scheduling conf change on 36cda5222aba364b ~:43.201884 I | etcdserver: [DEBUG] [1] 3988bc20c2b2e40c is scheduling conf change on 3988bc20c2b2e40c ~:43.201965 I | etcdserver: [DEBUG] [2] 3988bc20c2b2e40c is scheduling conf change on cf5d6cbc2a121727 ~:43.202070 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on 36cda5222aba364b ~:43.202139 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on 3988bc20c2b2e40c ~:43.202204 I | etcdserver: [DEBUG] 3988bc20c2b2e40c scheduled conf change on cf5d6cbc2a121727 ~:43.202444 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) before ~:43.204486 I | etcdserver/membership: added member 36cda5222aba364b [unix://127.0.0.1:2100913646] to cluster 425d73f1b7b01674 ~:43.204588 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) after ~:43.204703 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 36cda5222aba364b (request ID: 0) after trigger ~:43.204791 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) before ~:43.205689 I | etcdserver/membership: added member 3988bc20c2b2e40c [unix://127.0.0.1:2101113646] to cluster 425d73f1b7b01674 ~:43.205783 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) after ~:43.205929 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on 3988bc20c2b2e40c (request ID: 0) after trigger ~:43.206056 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) before ~:43.207353 I | etcdserver/membership: added member cf5d6cbc2a121727 [unix://127.0.0.1:2100713646] to cluster 425d73f1b7b01674 ~:43.207516 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) after ~:43.207619 I | etcdserver: [DEBUG] 3988bc20c2b2e40c applyConfChange on cf5d6cbc2a121727 (request ID: 0) after trigger ~:43.207710 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on 36cda5222aba364b ~:43.207781 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on 3988bc20c2b2e40c ~:43.207843 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished scheduled conf change on cf5d6cbc2a121727 ~:43.207951 I | etcdserver: [DEBUG] 3988bc20c2b2e40c finished wait for 0 pending jobs (current pending 0, finished 1) ~:43.208029 I | rafthttp: started HTTP pipelining with peer cf5d6cbc2a121727 ~:43.210339 I | rafthttp: peer 3988bc20c2b2e40c became active ~:43.210435 I | rafthttp: established a TCP streaming connection with peer 3988bc20c2b2e40c (stream MsgApp v2 reader) ~:43.210861 I | rafthttp: started streaming with peer 3988bc20c2b2e40c (writer) ~:43.211732 I | etcdserver: [DEBUG] 3988bc20c2b2e40c waitForApply after ``` Signed-off-by: Gyu-Ho Lee <gyuhox@gmail.com>

Update raftexample to apply conf changes before send raft.Ready.Messages. Candidate or follower needs to wait for all pending conf changes. Otherwise there might be incorrectly count votes. This PR introduces the fix from etcd-io#7595 and pr num 7706. Signed-off-by: Kee-Hyun Kum <kbzjung359@gmail.com>

Update raftexample to apply conf changes before send raft.Ready.Messages. Candidate or follower needs to wait for all pending conf changes. Otherwise there might be incorrectly count votes. This PR introduces the fix from etcd-io#7595 and pr num 7706. Signed-off-by: Kee-Hyun Kum <kbzjung359@gmail.com> Signed-off-by: KumKeeHyun <kbzjung359@gmail.com>

mitake mentioned this issue Mar 24, 2017

auth: store cached permission information in a form of interval tree #7569

Merged

gyuho added the area/raft label Mar 27, 2017

heyitsanthony assigned gyuho Mar 28, 2017

heyitsanthony added this to the v3.2.0 milestone Mar 28, 2017

gyuho mentioned this issue Apr 11, 2017

etcdserver: wait apply on conf change Raft entry #7706

Merged

gyuho closed this as completed in #7706 Apr 13, 2017

This was referenced Apr 19, 2017

TestRejectUnhealthyRemove: should reject quorum breaking remove #7609

Closed

TestNetworkPartition5MembersLeaderInMinority: context deadline exceeded #7802

Closed

gyuho mentioned this issue Apr 25, 2017

etcdserver: ensure waitForApply sync with applyAll #7810

Merged

KumKeeHyun mentioned this issue Mar 13, 2023

raftexample: apply conf change entries before send message #15450

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

TestRestartMember: context deadline exceeded #7595

TestRestartMember: context deadline exceeded #7595

mitake commented Mar 24, 2017

heyitsanthony commented Mar 24, 2017

gyuho commented Mar 27, 2017 •

edited

Loading

gyuho commented Apr 6, 2017 •

edited

Loading

TestRestartMember: context deadline exceeded #7595

TestRestartMember: context deadline exceeded #7595

Comments

mitake commented Mar 24, 2017

heyitsanthony commented Mar 24, 2017

gyuho commented Mar 27, 2017 • edited Loading

gyuho commented Apr 6, 2017 • edited Loading

Edits

gyuho commented Mar 27, 2017 •

edited

Loading

gyuho commented Apr 6, 2017 •

edited

Loading