failed to read raft message (unexpected EOF) - when replacing member in etcd v2.2.1

[Robin Percy]

Hi All,

Apologies if this seems more like a user-level question, but I seem to have stumped all other support channels - and at this point could use developer insight. 

A few days ago, we lost a member of our 3 node etcd2 cluster. We issued an `etcdctl member remove` and then tried to add a new member with `etcdctl member add`.  The add completed without error, but when we tried to start the new member we're seeing the following (gist: https://gist.github.com/robinpercy/8d6b70eb83f4d5e9625aa4f4540d7d82)

2017-09-07 21:27:51.591021 I | flags: recognized and used environment variable ETCD_ADVERTISE_CLIENT_URLS=http://etcd-us-east-1b.internal.apps-qa-green.us-east-1.core.mycompany.com:4001

2017-09-07 21:27:51.591079 I | flags: recognized and used environment variable ETCD_DATA_DIR=/var/etcd/data

2017-09-07 21:27:51.591092 I | flags: recognized and used environment variable ETCD_DEBUG=true

2017-09-07 21:27:51.591119 I | flags: recognized and used environment variable ETCD_INITIAL_ADVERTISE_PEER_URLS=http://etcd-us-east-1b.internal.apps-qa-green.us-east-1.core.mycompany.com:2380

2017-09-07 21:27:51.591138 I | flags: recognized and used environment variable ETCD_INITIAL_CLUSTER=etcd-us-east-1b=http://etcd-us-east-1b.internal.apps-qa-green.us-east-1.core.mycompany.com:2380,etcd-us-east-1c=http://etcd-us-east-1c.internal.apps-qa-green.us-east-1.core.mycompany.com:2380,etcd-us-east-1a=http://etcd-us-east-1a.internal.apps-qa-green.us-east-1.core.mycompany.com:2380

2017-09-07 21:27:51.591160 I | flags: recognized and used environment variable ETCD_INITIAL_CLUSTER_STATE=existing

2017-09-07 21:27:51.591171 I | flags: recognized and used environment variable ETCD_INITIAL_CLUSTER_TOKEN=etcd-mycluster-token

2017-09-07 21:27:51.591185 I | flags: recognized and used environment variable ETCD_LISTEN_CLIENT_URLS=http://0.0.0.0:4001

2017-09-07 21:27:51.591201 I | flags: recognized and used environment variable ETCD_LISTEN_PEER_URLS=http://0.0.0.0:2380

2017-09-07 21:27:51.591218 I | flags: recognized and used environment variable ETCD_NAME=etcd-us-east-1b

2017-09-07 21:27:51.591352 I | etcdmain: etcd Version: 2.2.1

2017-09-07 21:27:51.591363 I | etcdmain: Git SHA: 75f8282

2017-09-07 21:27:51.591370 I | etcdmain: Go Version: go1.5.1

2017-09-07 21:27:51.591377 I | etcdmain: Go OS/Arch: linux/amd64

2017-09-07 21:27:51.591388 I | etcdmain: setting maximum number of CPUs to 4, total number of available CPUs is 4

2017-09-07 21:27:51.591488 I | etcdmain: listening for peers on http://0.0.0.0:2380

2017-09-07 21:27:51.591518 I | etcdmain: listening for client requests on http://0.0.0.0:4001

2017-09-07 21:27:51.594257 I | netutil: resolving etcd-us-east-1a.internal.apps-qa-green.us-east-1.core.mycompany.com:2380 to 10.141.7.175:2380

2017-09-07 21:27:51.594847 I | netutil: resolving etcd-us-east-1a.internal.apps-qa-green.us-east-1.core.mycompany.com:2380 to 10.141.7.175:2380

2017-09-07 21:27:51.595397 I | netutil: resolving etcd-us-east-1b.internal.apps-qa-green.us-east-1.core.mycompany.com:2380 to 10.141.8.72:2380

2017-09-07 21:27:51.595909 I | netutil: resolving etcd-us-east-1b.internal.apps-qa-green.us-east-1.core.mycompany.com:2380 to 10.141.8.72:2380

2017-09-07 21:27:51.596484 I | netutil: resolving etcd-us-east-1c.internal.apps-qa-green.us-east-1.core.mycompany.com:2380 to 10.141.9.41:2380

2017-09-07 21:27:51.596992 I | netutil: resolving etcd-us-east-1c.internal.apps-qa-green.us-east-1.core.mycompany.com:2380 to 10.141.9.41:2380

2017-09-07 21:27:51.602034 I | etcdserver: name = etcd-us-east-1b

2017-09-07 21:27:51.602058 I | etcdserver: data dir = /var/etcd/data

2017-09-07 21:27:51.602074 I | etcdserver: member dir = /var/etcd/data/member

2017-09-07 21:27:51.602082 I | etcdserver: heartbeat = 100ms

2017-09-07 21:27:51.602090 I | etcdserver: election = 1000ms

2017-09-07 21:27:51.602096 I | etcdserver: snapshot count = 10000

2017-09-07 21:27:51.602110 I | etcdserver: advertise client URLs = http://etcd-us-east-1b.internal.apps-qa-green.us-east-1.core.mycompany.com:4001

2017-09-07 21:27:51.605161 I | etcdserver: starting member ad955e1348f4aa89 in cluster 58d26b168f47d0e7

2017-09-07 21:27:51.605202 I | raft: ad955e1348f4aa89 became follower at term 0

2017-09-07 21:27:51.605212 I | raft: newRaft ad955e1348f4aa89 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]

2017-09-07 21:27:51.605217 I | raft: ad955e1348f4aa89 became follower at term 1

2017-09-07 21:27:51.612717 I | rafthttp: the connection with 9705a6cab44e97e8 became active

2017-09-07 21:27:51.617389 I | etcdserver: starting server... [version: 2.2.1, cluster version: to_be_decided]

2017-09-07 21:27:51.620916 I | rafthttp: the connection with c2233199ea681cfc became active

2017-09-07 21:27:51.689181 I | raft: ad955e1348f4aa89 [term: 1] received a MsgHeartbeat message with higher term from c2233199ea681cfc [term: 804]

2017-09-07 21:27:51.689200 I | raft: ad955e1348f4aa89 became follower at term 804

2017-09-07 21:27:51.689213 I | raft: raft.node: ad955e1348f4aa89 elected leader c2233199ea681cfc at term 804

2017-09-07 21:27:56.803734 E | rafthttp: failed to read raft message (unexpected EOF)

2017-09-07 21:27:58.617893 E | etcdserver: publish error: etcdserver: request timed out, possibly due to previous leader failure

2017-09-07 21:28:01.907742 E | rafthttp: failed to read raft message (unexpected EOF)

2017-09-07 21:28:05.618080 E | etcdserver: publish error: etcdserver: request timed out

2017-09-07 21:28:07.007743 E | rafthttp: failed to read raft message (unexpected EOF)

2017-09-07 21:28:12.135761 E | rafthttp: failed to read raft message (unexpected EOF)

2017-09-07 21:28:12.618271 E | etcdserver: publish error: etcdserver: request timed out

2017-09-07 21:28:17.207743 E | rafthttp: failed to read raft message (unexpected EOF)

Dumping RAFT traffic on the new member, I see "POST /raft" messages are being truncated (gist: https://gist.github.com/robinpercy/95a5ea57848740bfd6e7b82288e3139a). Note etcd-us-east-1b.internal.apps-qa-green.mycompany.com is the new member.

POST /raft HTTP/1.1

Host: etcd-us-east-1b.internal.apps-qa-green.mycompany.com:2380

User-Agent: Go-http-client/1.1

Content-Length: 25384951

Content-Type: application/protobuf

X-Etcd-Cluster-Id: 58d26b168f47d0e7

X-Min-Cluster-Version: 2.1.0

X-Server-From: 9705a6cab44e97e8

X-Server-Version: 2.2.1

Accept-Encoding: gzip

........................ ..(.0.@.J....

....{"Root":{"Path":"/","CreatedIndex":0,"ModifiedIndex":0,"ExpireTime":"0001-01-01T00:00:00Z","Value":"","Children":{"0":{"Path":"/0","CreatedIndex":0,"ModifiedIndex":0,"ExpireTime":"0001-01-01T00:00:00Z","Value":"","Children":{"members":{"Path":"/0/members","CreatedIndex":1,"ModifiedIndex":1,"ExpireTime":"0001-01-01T00:00:00Z","Value":"","Children":{"9705a6cab44e97e8":

~2MB of data omitted

[\"secrets\",\"configmaps\"]},{\"verbs\":[\"get\"],\"attributeRestrictions\":null,\"apiGroups\":[\"\"],\"resources\":[\"persistentvolumeclaims\",\"persistentvolumes\"]},{\"verbs\":[\"get\

HTTP/1.1 400 Bad Request

Content-Type: text/plain; charset=utf-8

X-Content-Type-Options: nosniff

X-Etcd-Cluster-Id: 58d26b168f47d0e7

Date: Wed, 06 Sep 2017 23:07:44 GMT

Content-Length: 27

Connection: close




error reading raft message

So I'm now trying to determine likely causes of this truncation.  

Some additional info: this cluster is used as the data store for our Kubernetes cluster on AWS, and the procs themselves are run as docker containers with host networking. It's the standard setup that the Kops provisioner creates. 

Thanks,

Robin

[Robin Percy]

A bit more info about the truncation we're seeing. When the leader POSTs the snapshot, we see the initial set of packets being sent, then a 200ms period of no packets, then a FIN from the leader.  

Any further insight on this would be appreciated.

[anthony...@coreos.com]

Do the etcd peers communicate through a proxy/firewall/load balancer?  Do large POSTs work between similarly configured containers running ordinary http servers?

[Robin Percy]

Hi Anthony,

Large POSTs do work, I tested by setting up a simple web server with similar networking to etcd, and POSTed the 25MB snapshot from a container in a different AZ. The full message got through.

Is there a timeout we should be aware of on the  RAFT POST from the leader? Once difference we noticed is that the etcd message truncation happens after ~5s but our test completes within 3s.  

Cheers,

Robin