etcd3: etcdserver: publish error: etcdserver: request timed out
My etcd cluster has 3 peers. After bootstrapping, the peers got joined but then they are stuck in a loop to choose a leader.
etcd config:
etcd:
version: 3.2.0
name: "s1"
discovery: http://discovery.com:2379/v2/keys/discovery/01
advertise_client_urls: https://10.123.16.102:2379
initial_advertise_peer_urls: https://10.123.16.102:2380
listen_client_urls: https://0.0.0.0:2379
listen_peer_urls: https://0.0.0.0:2380
heartbeat_interval: 500
election_timeout: 5000
peer_cert_file: /etc/ssl/certs/etcd-peer-cert.pem
peer_key_file: /etc/ssl/certs/etcd-peer-key.pem
peer_trusted_ca_file: /etc/ssl/certs/etcd-peer-ca.pem
cert_file: /etc/ssl/certs/etcd-cert.pem
key_file: /etc/ssl/certs/etcd-key.pem
trusted_ca_file: /etc/ssl/certs/etcd-ca.pem
client_cert_auth: true
peer_client_cert_auth: true
log
etcd-wrapper[6659]: 2018-04-26 15:54:33.719433 W | rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:33.719839 W | rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:38.719873 W | rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:38.720595 W | rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:42.345264 I | raft: b28fc32f73213db4 is starting a new election at term 268
etcd-wrapper[6659]: 2018-04-26 15:54:42.346040 I | raft: b28fc32f73213db4 became candidate at term 269
etcd-wrapper[6659]: 2018-04-26 15:54:42.346246 I | raft: b28fc32f73213db4 received MsgVoteResp from b28fc32f73213db4 at term 269
etcd-wrapper[6659]: 2018-04-26 15:54:42.346401 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to 3c8a859ede12a0ca at term 269
etcd-wrapper[6659]: 2018-04-26 15:54:42.346548 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to c98dfd5f27177c78 at term 269
etcd-wrapper[6659]: 2018-04-26 15:54:43.514940 E | etcdserver: publish error: etcdserver: request timed out
etcd-wrapper[6659]: 2018-04-26 15:54:43.720972 W | rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:43.721242 W | rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:48.721568 W | rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:48.722261 W | rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:50.344602 I | raft: b28fc32f73213db4 is starting a new election at term 269
etcd-wrapper[6659]: 2018-04-26 15:54:50.345429 I | raft: b28fc32f73213db4 became candidate at term 270
etcd-wrapper[6659]: 2018-04-26 15:54:50.345539 I | raft: b28fc32f73213db4 received MsgVoteResp from b28fc32f73213db4 at term 270
etcd-wrapper[6659]: 2018-04-26 15:54:50.345680 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to c98dfd5f27177c78 at term 270
etcd-wrapper[6659]: 2018-04-26 15:54:50.345784 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to 3c8a859ede12a0ca at term 270
etcd-wrapper[6659]: 2018-04-26 15:54:53.722403 W | rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:53.723334 W | rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:57.344596 I | raft: b28fc32f73213db4 is starting a new election at term 270
etcd-wrapper[6659]: 2018-04-26 15:54:57.345259 I | raft: b28fc32f73213db4 became candidate at term 271
etcd-wrapper[6659]: 2018-04-26 15:54:57.345367 I | raft: b28fc32f73213db4 received MsgVoteResp from b28fc32f73213db4 at term 271
etcd-wrapper[6659]: 2018-04-26 15:54:57.345493 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to c98dfd5f27177c78 at term 271
etcd-wrapper[6659]: 2018-04-26 15:54:57.345604 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to 3c8a859ede12a0ca at term 271
etcd-wrapper[6659]: 2018-04-26 15:54:58.515748 E | etcdserver: publish error: etcdserver: request timed out
etcd-wrapper[6659]: 2018-04-26 15:54:58.723382 W | rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:54:58.723866 W | rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:55:03.723805 W | rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:55:03.724676 W | rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:55:03.844607 I | raft: b28fc32f73213db4 is starting a new election at term 271
etcd-wrapper[6659]: 2018-04-26 15:55:03.844847 I | raft: b28fc32f73213db4 became candidate at term 272
etcd-wrapper[6659]: 2018-04-26 15:55:03.844957 I | raft: b28fc32f73213db4 received MsgVoteResp from b28fc32f73213db4 at term 272
etcd-wrapper[6659]: 2018-04-26 15:55:03.845071 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to c98dfd5f27177c78 at term 272
etcd-wrapper[6659]: 2018-04-26 15:55:03.845192 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to 3c8a859ede12a0ca at term 272
etcd-wrapper[6659]: 2018-04-26 15:55:08.724779 W | rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:55:08.725523 W | rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:55:09.344619 I | raft: b28fc32f73213db4 is starting a new election at term 272
etcd-wrapper[6659]: 2018-04-26 15:55:09.344891 I | raft: b28fc32f73213db4 became candidate at term 273
etcd-wrapper[6659]: 2018-04-26 15:55:09.344989 I | raft: b28fc32f73213db4 received MsgVoteResp from b28fc32f73213db4 at term 273
etcd-wrapper[6659]: 2018-04-26 15:55:09.345091 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to 3c8a859ede12a0ca at term 273
etcd-wrapper[6659]: 2018-04-26 15:55:09.345225 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to c98dfd5f27177c78 at term 273
etcd-wrapper[6659]: 2018-04-26 15:55:13.516733 E | etcdserver: publish error: etcdserver: request timed out
etcd-wrapper[6659]: 2018-04-26 15:55:13.725672 W | rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:55:13.725992 W | rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:55:15.344601 I | raft: b28fc32f73213db4 is starting a new election at term 273
etcd-wrapper[6659]: 2018-04-26 15:55:15.345262 I | raft: b28fc32f73213db4 became candidate at term 274
etcd-wrapper[6659]: 2018-04-26 15:55:15.345403 I | raft: b28fc32f73213db4 received MsgVoteResp from b28fc32f73213db4 at term 274
etcd-wrapper[6659]: 2018-04-26 15:55:15.345523 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to 3c8a859ede12a0ca at term 274
etcd-wrapper[6659]: 2018-04-26 15:55:15.345622 I | raft: b28fc32f73213db4 [logterm: 1, index: 3] sent MsgVote request to c98dfd5f27177c78 at term 274
etcd-wrapper[6659]: 2018-04-26 15:55:18.726132 W | rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
etcd-wrapper[6659]: 2018-04-26 15:55:18.726762 W | rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbidden
any idea?
Thanks
encodeflush
All 13 comments
rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbidden
I think this is where you need to look. What is causing this?
hexfusion
on 26 Apr 2018
@hexfusion I just enabled debugging flag.
rafthttp: health check for peer 3c8a859ede12a0ca could not connect: Tunnel or SSL Forbi
rafthttp: health check for peer c98dfd5f27177c78 could not connect: Tunnel or SSL Forbi
rafthttp: failed to dial c98dfd5f27177c78 on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial c98dfd5f27177c78 on stream MsgApp v2 (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream Message (Tunnel or SSL Forbidden)
rafthttp: failed to dial 3c8a859ede12a0ca on stream MsgApp v2 (Tunnel or SSL Forbidden)
do you think something is wrong with etcd certs?
encodeflush
on 26 Apr 2018
Fairly certain that message is not coming from etcd directly so you need to see what is causing it. Maybe try connecting to the health endpoint directly with curl -v or similar and see what it returns? IMO this is a networking vs TLS issue.
hexfusion
on 26 Apr 2018
@hexfusion Just to clarify if there is networking issue, I disabled TLS and restarted etcd service.
```
2018-04-26 15:18:24.126341 I | pkg/flags: recognized and used environment variable ETCD_DATA_DIR=/var/lib/etcd
2018-04-26 15:18:24.127082 I | pkg/flags: recognized environment variable ETCD_NAME, but unused: shadowed by corresponding flag
2018-04-26 15:18:24.130207 W | pkg/flags: unrecognized environment variable ETCD_USER=etcd
2018-04-26 15:18:24.130295 W | pkg/flags: unrecognized environment variable ETCD_IMAGE_TAG=v3.2.0
2018-04-26 15:18:24.130407 I | etcdmain: etcd Version: 3.2.0
2018-04-26 15:18:24.130483 I | etcdmain: Git SHA: 66722b1
2018-04-26 15:18:24.130554 I | etcdmain: Go Version: go1.8.3
2018-04-26 15:18:24.130624 I | etcdmain: Go OS/Arch: linux/amd64
2018-04-26 15:18:24.130696 I | etcdmain: setting maximum number of CPUs to 1, total number of available CPUs is 1
2018-04-26 15:18:24.133618 I | embed: peerTLS: cert = /etc/ssl/certs/etcd-peer-cert.pem, key = /etc/ssl/certs/etcd-peer-key.pem, ca = , trusted-ca = /etc/ssl/ce
2018-04-26 15:18:24.143319 I | embed: listening for peers on https://0.0.0.0:2380
2018-04-26 15:18:24.143480 I | embed: listening for client requests on 0.0.0.0:2379
2018-04-26 15:18:24.164824 N | discovery: found self b28fc32f73213db4 in the cluster
2018-04-26 15:18:24.164975 N | discovery: found 1 peer(s), waiting for 2 more
2018-04-26 15:20:30.894323 N | discovery: found peer 3c8a859ede12a0ca in the cluster
2018-04-26 15:20:30.895373 N | discovery: found 2 peer(s), waiting for 1 more
2018-04-26 15:21:58.328590 N | discovery: found peer c98dfd5f27177c78 in the cluster
2018-04-26 15:21:58.329346 N | discovery: found 3 needed peer(s)
2018-04-26 15:21:58.329945 I | etcdserver: data dir = /var/lib/etcd
2018-04-26 15:21:58.330063 I | etcdserver: member dir = /var/lib/etcd/member
2018-04-26 15:21:58.330179 I | etcdserver: heartbeat = 500ms
2018-04-26 15:21:58.330314 I | etcdserver: election = 5000ms
2018-04-26 15:21:58.330414 I | etcdserver: snapshot count = 100000
2018-04-26 15:21:58.330636 I | etcdserver: advertise client URLs = https://10.123.16.102:2379
2018-04-26 15:21:58.330748 I | etcdserver: initial advertise peer URLs = https://10.123.16.102:2380
2018-04-26 15:21:58.343793 I | etcdserver: starting member b28fc32f73213db4 in cluster 801557806bb42a8b
2018-04-26 15:21:58.343955 I | raft: b28fc32f73213db4 became follower at term 0
2018-04-26 15:21:58.344078 I | raft: newRaft b28fc32f73213db4 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
2018-04-26 15:21:58.344197 I | raft: b28fc32f73213db4 became follower at term 1
2018-04-26 15:21:58.371231 W | auth: simple token is not cryptographically signed
2018-04-26 15:21:58.378440 I | rafthttp: starting peer 3c8a859ede12a0ca...
2018-04-26 15:21:58.378666 I | rafthttp: started HTTP pipelining with peer 3c8a859ede12a0ca
2018-04-26 15:21:58.384213 I | rafthttp: started peer 3c8a859ede12a0ca
2018-04-26 15:21:58.384377 I | rafthttp: added peer 3c8a859ede12a0ca
2018-04-26 15:21:58.384518 I | rafthttp: starting peer c98dfd5f27177c78...
2018-04-26 15:21:58.384806 I | rafthttp: started HTTP pipelining with peer c98dfd5f27177c78
2018-04-26 15:21:58.389396 I | rafthttp: started peer c98dfd5f27177c78
2018-04-26 15:21:58.389543 I | rafthttp: added peer c98dfd5f27177c78
2018-04-26 15:21:58.389699 I | etcdserver: starting server... [version: 3.2.0, cluster version: to_be_decided]
2018-04-26 15:21:58.389870 I | embed: ClientTLS: cert = /etc/ssl/certs/etcd-cert.pem, key = /etc/ssl/certs/etcd-key.pem, ca = , trusted-ca = /etc/ssl/certs/etcd
2018-04-26 15:21:58.396521 I | rafthttp: started streaming with peer 3c8a859ede12a0ca (writer)
etcdctl member list:
23d53ba91af96343: name= peerURLs=http://10.123.16.102:2380 clientURLs=http://10.123.16.102:2379 isLeader=false
588807ab4aa53f36: name= peerURLs=http://10.123.16.104:2380 clientURLs=http://10.123.16.104:2379 isLeader=true
78b971dd29f11488: name= peerURLs=http://10.123.16.101:2380 clientURLs=http://10.123.16.101:2379 isLeader=false
```
I'll check TLS key pairs.
encodeflush
on 26 Apr 2018
@arasmax Have you checked your TLS configurations? etcd doesn't seem related here.
gyuho
on 26 Apr 2018
@hexfusion Just to clarify if there is networking issue, I disabled TLS and restarted etcd service.
I am confused why do logs still reference https?
2018-04-26 15:21:58.330636 I | etcdserver: advertise client URLs = https://10.123.16.102:2379
2018-04-26 15:21:58.330748 I | etcdserver: initial advertise peer URLs = https://10.123.16.102:2380
hexfusion
on 27 Apr 2018
@hexfusion I double checked etcd config. Both '--initial-advertise-peer-urls' and '--advertise-client-urls' are set to http. However, later https does not appear.
encodeflush
on 27 Apr 2018
@gyuho I'm trying clarify it. Thanks.
encodeflush
on 27 Apr 2018
hi @arasmax any update?
hexfusion
on 3 May 2018
@hexfusion I checked all TLS keys and they're fine. However, it took me a while to figure out the root of the problem. I set corp proxy as https_proxy and also no_proxy environment variables in etcd-wrapper service to be able to fetch etcd rkt image. But later I verified that etcd-wrapper continues to use the https_proxy to communicate to with the other members. It seems etcd-wrapper ignores the no_proxy env variable and goes directly to the proxy server.
I did a workaround which includes a systemd service which fetches etcd rkt image (with https_proxy) and later starts etcd-wrapper without any proxy. After that etcd starts on all nodes without any problem.
encodeflush
on 3 May 2018
@gyuho Are any of CoreOS developers are here in KubeCon in Copenhagen?
encodeflush
on 3 May 2018
@arasmax great to hear that you have this resolved can we close this issue now? Enjoy KubeCon, I am very jealous :).
hexfusion
on 3 May 2018
Thanks @hexfusion
I am closing this.
gyuho
on 18 May 2018
Related issues
primeroz
路
3Comments
govine
路
3Comments
zhousoft
路
3Comments
kghost
路
4Comments
el10savio
路
4Comments
Most helpful comment
Thanks @hexfusion
I am closing this.