Member Add Failure #11554

daniel-keeney · 2020-01-22T19:23:32Z

We are trying to set up a 3-node cluster of etcd. The first two nodes start up fine, but the third one experiences trouble approximately 80% of the time. The steps that the nodes take to join the cluster are to:

join the cluster via etcdctl member add ...
start up the etcd server with the relevant initial cluster data from step 1

This is failing at step 1, and so the etcd server ends up not running on the third node.

Version: 3.3.17

Script:
ETCDCTL_API=3 etcdctl member add <memberName> --peer-urls "https://master-2.internal:2380"

(master-2.internal is itself)

Expected Output:

Member ec15b94869b0fca7 added to cluster 6d938e3be5102340

ETCD_NAME="memberName"
ETCD_INITIAL_CLUSTER="2846f720-4ec2-4794-af5e-2261f3d047ea=https://master-0.internal:2380,7b915602-0b4b-473c-8d92-1afdc1d03c58=https://master-1.internal:2380,2e51e8ec-8c1d-493a-9b2a-a8bb07f9f630=https://master-2.internal:2380"
ETCD_INITIAL_ADVERTISE_PEER_URLS="https://master-2.internal:2380"
ETCD_INITIAL_CLUSTER_STATE="existing"

Actual Output:

Member db14cc7363e1acfb added to cluster 6d938e3be5102340
{"level":"warn","ts":"2020-01-22T19:16:35.617Z","caller":"clientv3/retry_interceptor.go:61","msg":"retrying of unary invoker failed","target":"endpoint://client-ef3acb95-0e80-4a52-97ba-b3c2ff99f703/master-0.internal:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
Error: context deadline exceeded

Output of etcdctl endpoint health:

{"level":"warn","ts":"2020-01-22T19:19:53.005Z","caller":"clientv3/retry_interceptor.go:61","msg":"retrying of unary invoker failed","target":"endpoint://client-e6eec11d-f769-41e4-8c4d-b5d262987894/master-2.internal:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest connection error: connection error: desc = \"transport: Error while dialing dial tcp 10.0.10.4:2379: connect: connection refused\""}
https://master-1.internal:2379 is healthy: successfully committed proposal: took = 17.114338ms
https://master-0.internal:2379 is healthy: successfully committed proposal: took = 17.410487ms
https://master-2.internal:2379 is unhealthy: failed to commit proposal: context deadline exceeded
Error: unhealthy cluster

We are able to dig the relevant host names from all 3 nodes (master-0|1|2.internal), and we tried adding the --command-timeout=30s flag to etcdctl member add which did not help. We are able to manually remove the member and retry, which works about 20% of the time. How can we go about diagnosing this problem further?

EDIT: Markdown formatting

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

daniel-keeney · 2020-01-23T00:44:00Z

To reproduce this, it will help to run 3 instances of etcd inside a single etcd docker container. You might want to use 3 separate terminal windows to make this easy to follow. Steps to reproduce:

Window 1

docker run \
  --name=experiment \
  -it \
  gcr.io/etcd-development/etcd:v3.3.12 \
  sh

/usr/local/bin/etcd \
  --name "node-0" \
  --data-dir /etcd-data1 \
  --listen-client-urls http://0.0.0.0:12379 \
  --advertise-client-urls http://0.0.0.0:12380 \
  --listen-peer-urls http://0.0.0.0:12380 \
  --initial-advertise-peer-urls http://0.0.0.0:12380 \
  --initial-cluster node-0=http://0.0.0.0:12380 \
  --initial-cluster-state new

Window 2

docker exec -it $(docker ps -f name=experiment -q) sh
export ETCDCTL_API=3
MEMBER_ADD_OUTPUT="$(etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379,http://0.0.0.0:32379" member add node-1 --peer-urls "http://0.0.0.0:22380")"
echo "MEMBER_ADD_OUTPUT = $MEMBER_ADD_OUTPUT"
CLUSTER="$(echo "${MEMBER_ADD_OUTPUT}" | grep "ETCD_INITIAL_CLUSTER=" | cut -d'=' -f2- | tr -d '"')"
echo "CLUSTER = $CLUSTER"

/usr/local/bin/etcd \
  --name="node-1" \
  --data-dir="/etcd-data2" \
  --listen-peer-urls="http://0.0.0.0:22380" \
  --initial-advertise-peer-urls="http://0.0.0.0:22380" \
  --listen-client-urls="http://0.0.0.0:22379" \
  --advertise-client-urls="http://0.0.0.0:22380" \
  --initial-cluster="${CLUSTER}" \
  --initial-cluster-state="existing"

Window 3

docker exec -it $(docker ps -f name=experiment -q) sh
export ETCDCTL_API=3
etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379,http://0.0.0.0:32379" member add node-2 --peer-urls "http://0.0.0.0:32380"
etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379,http://0.0.0.0:32379" member remove $(etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379,http://0.0.0.0:32379" member list | grep unstarted | cut -d',' -f1)

Repeat the last two steps in Window 3 repeatedly to see how consistently it passes or fails. Then you can start over and change the version of the docker image you run with in step 1 of Window 1. Our results:

v3.3.12
passed 10x

v3.3.13
passed 10x

v3.3.14
failed 2x
passed 2x
failed 2x
passed 1x
failed 3x

v3.3.15
failed 2x
passed 2x
failed 2x
passed 1x
failed 3x

v3.3.17
passed 2x
failed 1x
passed 3x
failed 3x
passed 1x

daniel-keeney · 2020-01-23T00:44:27Z

To summarize, it looks like this was a regression introduced in v3.3.14

YoyinZyc · 2020-01-25T00:33:54Z

It looks like similar to #11186. It should have been fixed in 3.3.17 with PR #11194. @jingyih could you please have a look?

jingyih · 2020-01-27T09:38:31Z

etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379,http://0.0.0.0:32379" member add node-2 --peer-urls "http://0.0.0.0:32380"

@daniel-keeney
When you run this command, is endpoint http://0.0.0.0:32379 available? Or is it the endpoint that is going to be served by the 3rd member?

jfmyers9 · 2020-01-27T17:23:39Z

We are running this command from the third node that is being added. The process looks like:

Have a running closer of N nodes on N machines.
Spin up a new machine
Run etcdctl member add from the new machine
Extract the cluster information from the output of etcdctl member add
Start up the new ETCD process on the new machine.

Therefore there will be nothing listening on any interfaces at the time of running etcdctl member add.

jfmyers9 · 2020-01-27T18:45:28Z

If it helps, I grabbed a goroutine dump of the etcdctl process when it fails to fetch the cluster information. I've attached it the full contents but it appears to be hanging on this line in the member add command.

goroutines.txt

swalner-pivotal · 2020-01-28T17:20:57Z

@jingyih (answering for @daniel-keeney since he's out): http://0.0.0.:32379 is the endpoint that is going to be served by the 3rd member.

jingyih · 2020-01-30T07:52:04Z

@swalner-pivotal Thanks! Given that http://0.0.0.:32379 is not yet available at the time of command execution. Could you remove it from the "--endpoints" flag and see if it helps?

swalner-pivotal · 2020-01-30T16:45:25Z

Hi @jingyih, we also tried that, but it's important to note that this exact configuration works when run with 3.3.12 (and 3.3.13).
We are using a work-around of combining etcdctl 3.3.12 with etcd server 3.3.17, and (for our limited purposes) this seems to work well.

jingyih · 2020-01-31T01:07:09Z

In 3.3.14, the etcd client balancer was rewritten to fix a major bug. It is a breaking change [1]. That might explain the different behavior you observed.

[1] https://github.com/etcd-io/etcd/blob/master/CHANGELOG-3.3.md#v3314-2019-08-16

daniel-keeney · 2020-01-31T18:19:00Z

@jingyih Thanks for your responsiveness! We took your advice and tried replacing Window 3's step 3, which was originally:
etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379,http://0.0.0.0:32379" member add node-2 --peer-urls "http://0.0.0.0:32380"
with this:
etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379" member add node-2 --peer-urls "http://0.0.0.0:32380"
(note that http://0.0.0.0:32379 is missing from the endpoints), and we still had a failure rate higher than 50% in version 3.3.17. Thanks for the pointer about the changelog, you may be right that the load balancer rewrite is the source of the problem.

Please advise us if there is something else we should try, we appreciate your help.

jingyih · 2020-02-03T09:02:41Z

Could you paste the error message of the following command you tried?

etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379" member add node-2 --peer-urls "http://0.0.0.0:32380"

daniel-keeney · 2020-02-03T23:22:58Z

Sorry for leaving out that detail. It was the same as in the initial report:

Member db14cc7363e1acfb added to cluster 6d938e3be5102340
{"level":"warn","ts":"2020-01-22T19:16:35.617Z","caller":"clientv3/retry_interceptor.go:61","msg":"retrying of unary invoker failed","target":"endpoint://client-ef3acb95-0e80-4a52-97ba-b3c2ff99f703/master-0.internal:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
Error: context deadline exceeded

jingyih · 2020-02-04T07:05:43Z

But "endpoint://client-ef3acb95-0e80-4a52-97ba-b3c2ff99f703/master-0.internal:2379", which is part of the error message, is not included in the command flag --endpoints? I am asking because I cannot reproduce this issue. Could you reproduce this issue using the following command?

etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379" member add node-2 --peer-urls "http://0.0.0.0:32380"

daniel-keeney · 2020-02-04T20:13:30Z

Sorry about that, I was trying to indicate that it was the same "DeadlineExceeded" error as before. Here is the combined shell prompt, command, and output:

/ # etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379" member add node-2 --peer-urls "http://0.0.0.0:
32380"
Member ced8f1ec7181d330 added to cluster 3cc7a70a26c80530
{"level":"warn","ts":"2020-02-04T20:12:56.757Z","caller":"clientv3/retry_interceptor.go:61","msg":"retrying of unary invoker failed","target":"endpoint://client-338a57d6-68c2-4933-b74d-bfc48410cc20/0.0.0.0:12379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
Error: <nil>

If you are not able to reproduce it on the first try, then run:

etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379" member remove $(etcdctl --endpoints "http://0.0.0.0:12379,http://0.0.0.0:22379" member list | grep unstarted | cut -d',' -f1)

to reset the cluster back to 2 members and try member add again, it will fail around 50% or more of the time.

jingyih · 2020-02-05T04:12:55Z

Thanks @daniel-keeney, I was able to reproduce this. I will take a closer look.

daniel-keeney · 2020-02-06T23:33:48Z

Great, thank you!

eselvam · 2020-07-15T05:07:51Z

{"level":"warn","ts":"2020-07-15T05:45:40.089+0100","caller":"clientv3/retry_interceptor.go:61","msg":"retrying of unary invoker failed","target":"passthrough:///https://ipmasked:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}

It is happening when we add stacked kubernetes masters based on instruction at kubernetes.io. It is a second master node.

The etcdctl member status and list are showing correctly with node 1 as master and node 2 as false however when we down the master 1, the entire cluster is going done.

Kubernetes version 1.18.5 and etcd version: 3.4.3

+------------------+------------------+---------+---------+-----------+------------+-----------+------------+--------------------+--------+
| ENDPOINT | ID | VERSION | DB SIZE | IS LEADER | IS LEARNER | RAFT TERM | RAFT INDEX | RAFT APPLIED INDEX | ERRORS |
+------------------+------------------+---------+---------+-----------+------------+-----------+------------+--------------------+--------+
| master1:2379 | 16cf629ee72c2590 | 3.4.3 | 3.2 MB | false | false | 6 | 3637096 | 3637096 | |
| master2:2379 | 448a38484560a13c | 3.4.3 | 3.2 MB | true | false | 6 | 3637096 | 3637096 | |
+------------------+------------------+---------+---------+-----------+------------+-----------+------------+--------------------+--------+

jingyih added the type/bug label Feb 5, 2020

jingyih mentioned this issue Feb 19, 2020

etcdctl: fix member add (again...) #11638

Merged

jingyih closed this as completed in #11638 Feb 29, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Member Add Failure #11554

Member Add Failure #11554

daniel-keeney commented Jan 22, 2020 •

edited

Loading

daniel-keeney commented Jan 23, 2020 •

edited

Loading

daniel-keeney commented Jan 23, 2020

YoyinZyc commented Jan 25, 2020

jingyih commented Jan 27, 2020 •

edited

Loading

jfmyers9 commented Jan 27, 2020

jfmyers9 commented Jan 27, 2020

swalner-pivotal commented Jan 28, 2020

jingyih commented Jan 30, 2020

swalner-pivotal commented Jan 30, 2020

jingyih commented Jan 31, 2020 •

edited

Loading

daniel-keeney commented Jan 31, 2020 •

edited

Loading

jingyih commented Feb 3, 2020

daniel-keeney commented Feb 3, 2020

jingyih commented Feb 4, 2020

daniel-keeney commented Feb 4, 2020 •

edited

Loading

jingyih commented Feb 5, 2020

daniel-keeney commented Feb 6, 2020

eselvam commented Jul 15, 2020

Member Add Failure #11554

Member Add Failure #11554

Comments

daniel-keeney commented Jan 22, 2020 • edited Loading

daniel-keeney commented Jan 23, 2020 • edited Loading

daniel-keeney commented Jan 23, 2020

YoyinZyc commented Jan 25, 2020

jingyih commented Jan 27, 2020 • edited Loading

jfmyers9 commented Jan 27, 2020

jfmyers9 commented Jan 27, 2020

swalner-pivotal commented Jan 28, 2020

jingyih commented Jan 30, 2020

swalner-pivotal commented Jan 30, 2020

jingyih commented Jan 31, 2020 • edited Loading

daniel-keeney commented Jan 31, 2020 • edited Loading

jingyih commented Feb 3, 2020

daniel-keeney commented Feb 3, 2020

jingyih commented Feb 4, 2020

daniel-keeney commented Feb 4, 2020 • edited Loading

jingyih commented Feb 5, 2020

daniel-keeney commented Feb 6, 2020

eselvam commented Jul 15, 2020

daniel-keeney commented Jan 22, 2020 •

edited

Loading

daniel-keeney commented Jan 23, 2020 •

edited

Loading

jingyih commented Jan 27, 2020 •

edited

Loading

jingyih commented Jan 31, 2020 •

edited

Loading

daniel-keeney commented Jan 31, 2020 •

edited

Loading

daniel-keeney commented Feb 4, 2020 •

edited

Loading