Etcd: "Error: context deadline exceeded"

[dchambon]

Summary

I am trying to build a simple etcd cluster using coreos from scratch.

Environment

To set up my VM, I am using the github script with the following command
$ sudo ./coreos-install -d /dev/sda -i ignition.json -o vmware_raw
My ignition file is valid and the associated configuration is:

# This config is meant to be consumed by the config transpiler, which will
# generate the corresponding Ignition config. Do not pass this config directly
# to instances of Container Linux.

passwd:
  users:
    - name: core
      password_hash: "<pwd_hash>"
      ssh_authorized_keys:
        - "<ssh_key>"

storage:
  files:
    - filesystem: "root"
      path: "/etc/hostname"
      mode: 0644
      contents:
        inline: coreos0
    - filesystem: root
      path: /etc/profile.env
      mode: 0644
      contents:
        inline: |
          alias ll='ls -al'
          export ETCDCTL_API=3

etcd:
  name: "etcd0"
  initial_advertise_peer_urls: http://192.168.12.50:2380
  listen_peer_urls: http://192.168.12.50:2380
  listen_client_urls: http://192.168.12.50:2379,http://127.0.0.1:2379
  advertise_client_urls: http://192.168.12.50:2379
  initial_cluster_token: etcd-cluster-1
  initial_cluster: etcd0=http://192.168.12.50:2380,etcd1=http://192.168.12.51:2380,etcd2=http://192.168.12.52:2380,etcd3=http://192.168.12.53:2380
  initial_cluster_state: new

systemd:
  units:
    - name: docker-tcp.socket
      enable: true
      contents: |
        [Unit]
        Description=Docker Socket for the API

        [Socket]
        ListenStream=127.0.0.1:2375
        BindIPv6Only=both
        Service=docker.service

        [Install]
        WantedBy=sockets.target

docker:
  flags:
    - --insecure-registry=artifacts.corp.skysoft-atm.com:5000
    - --insecure-registry=devserver2.corp.skysoft-atm.com:5000

update:
  group: "stable"
locksmith:
  reboot_strategy: "etcd-lock"
  window_start: "Sun 1:00"
  window_length: "2h"

networkd:
  units:
    - name: 00-ens0.network
      contents: |
        [Match]
        Name=ens*

        [Network]
        DHCP=no
        DNS=192.168.100.81
        Address=192.168.12.50/16
        Gateway=192.168.100.1

Once my env is up and running, I have the following:

```
$ systemctl cat etcd-member.service

/usr/lib/systemd/system/etcd-member.service

[Unit]
Description=etcd (System Application Container)
Documentation=https://github.com/coreos/etcd
Wants=network.target
Conflicts=etcd.service
Conflicts=etcd2.service

[Service]
Type=notify
Restart=on-failure
RestartSec=10s
TimeoutStartSec=0
LimitNOFILE=40000

Environment="ETCD_IMAGE_TAG=v3.1.10"
Environment="ETCD_NAME=%m"
Environment="ETCD_USER=etcd"
Environment="ETCD_DATA_DIR=/var/lib/etcd"
Environment="RKT_RUN_ARGS=--uuid-file-save=/var/lib/coreos/etcd-member-wrapper.uuid"

ExecStartPre=/usr/bin/mkdir --parents /var/lib/coreos
ExecStartPre=-/usr/bin/rkt rm --uuid-file=/var/lib/coreos/etcd-member-wrapper.uuid
ExecStart=/usr/lib/coreos/etcd-wrapper $ETCD_OPTS
ExecStop=-/usr/bin/rkt stop --uuid-file=/var/lib/coreos/etcd-member-wrapper.uuid

[Install]
WantedBy=multi-user.target

/etc/systemd/system/etcd-member.service.d/20-clct-etcd-member.conf

[Service]
ExecStart=
ExecStart=/usr/lib/coreos/etcd-wrapper $ETCD_OPTS \
--name="etcd0" \
--listen-peer-urls="http://192.168.12.50:2380" \
--listen-client-urls="http://192.168.12.50:2379,http://127.0.0.1:2379" \
--initial-advertise-peer-urls="http://192.168.12.50:2380" \
--initial-cluster="etcd0=http://192.168.12.50:2380,etcd1=http://192.168.12.51:2380,etcd2=http://192.168.12.52:2380,etcd3=http://192.168.12.53:2380" \
--initial-cluster-state="new" \
--initial-cluster-token="etcd-cluster-1" \
--advertise-client-urls="http://192.168.12.50:2379"

# Issue
If I try to execute a simple etcdctl command. I have the following exception:

$ etcdctl member list
Error: context deadline exceeded

Log shows:

$ systemctl status etcd-member.service
● etcd-member.service - etcd (System Application Container)
Loaded: loaded (/usr/lib/systemd/system/etcd-member.service; enabled; vendor preset: enabled)
Drop-In: /etc/systemd/system/etcd-member.service.d
└─20-clct-etcd-member.conf
Active: activating (start) since Tue 2017-10-31 07:30:25 UTC; 3min 50s ago
Docs: https://github.com/coreos/etcd
Process: 762 ExecStartPre=/usr/bin/rkt rm --uuid-file=/var/lib/coreos/etcd-member-wrapper.uuid (code=exited, status=254)
Process: 756 ExecStartPre=/usr/bin/mkdir --parents /var/lib/coreos (code=exited, status=0/SUCCESS)
Main PID: 849 (etcd)
Tasks: 8 (limit: 32768)
Memory: 137.5M
CPU: 3.443s
CGroup: /system.slice/etcd-member.service
└─849 /usr/local/bin/etcd --name=etcd0 --listen-peer-urls=http://192.168.12.50:2380 --listen-client-urls=http://192.168.12.50:2379,http://127.0.0.1:2379 --initial-advertise-pee

Oct 31 07:34:13 coreos0 etcd-wrapper[849]: 2017-10-31 07:34:13.673270 I | raft: 7931e79c0d8b47c5 received MsgVoteResp from 7931e79c0d8b47c5 at term 131
Oct 31 07:34:13 coreos0 etcd-wrapper[849]: 2017-10-31 07:34:13.673922 I | raft: 7931e79c0d8b47c5 [logterm: 1, index: 4] sent MsgVote request to 987146e8925f10e5 at term 131
Oct 31 07:34:13 coreos0 etcd-wrapper[849]: 2017-10-31 07:34:13.674503 I | raft: 7931e79c0d8b47c5 [logterm: 1, index: 4] sent MsgVote request to 3fcf5cf9cea1739d at term 131
Oct 31 07:34:13 coreos0 etcd-wrapper[849]: 2017-10-31 07:34:13.675129 I | raft: 7931e79c0d8b47c5 [logterm: 1, index: 4] sent MsgVote request to 5ae3067007f7fb85 at term 131
Oct 31 07:34:15 coreos0 etcd-wrapper[849]: 2017-10-31 07:34:15.371772 I | raft: 7931e79c0d8b47c5 is starting a new election at term 131
Oct 31 07:34:15 coreos0 etcd-wrapper[849]: 2017-10-31 07:34:15.372609 I | raft: 7931e79c0d8b47c5 became candidate at term 132
Oct 31 07:34:15 coreos0 etcd-wrapper[849]: 2017-10-31 07:34:15.373320 I | raft: 7931e79c0d8b47c5 received MsgVoteResp from 7931e79c0d8b47c5 at term 132
Oct 31 07:34:15 coreos0 etcd-wrapper[849]: 2017-10-31 07:34:15.373968 I | raft: 7931e79c0d8b47c5 [logterm: 1, index: 4] sent MsgVote request to 987146e8925f10e5 at term 132
Oct 31 07:34:15 coreos0 etcd-wrapper[849]: 2017-10-31 07:34:15.374548 I | raft: 7931e79c0d8b47c5 [logterm: 1, index: 4] sent MsgVote request to 3fcf5cf9cea1739d at term 132
Oct 31 07:34:15 coreos0 etcd-wrapper[849]: 2017-10-31 07:34:15.375165 I | raft: 7931e79c0d8b47c5 [logterm: 1, index: 4] sent MsgVote request to 5ae3067007f7fb85 at term 132

and journalctl:

journalctl -u etcd-member.service
-- Logs begin at Tue 2017-10-31 07:30:00 UTC, end at Tue 2017-10-31 07:45:43 UTC. --
Oct 31 07:30:25 coreos0 systemd[1]: Starting etcd (System Application Container)...
Oct 31 07:30:33 coreos0 rkt[762]: rm: unable to resolve UUID from file: open /var/lib/coreos/etcd-member-wrapper.uuid: no such file or directory
Oct 31 07:30:33 coreos0 rkt[762]: rm: failed to remove one or more pods
Oct 31 07:30:33 coreos0 etcd-wrapper[849]: ++ id -u etcd
Oct 31 07:30:33 coreos0 etcd-wrapper[849]: + exec /usr/bin/rkt run --uuid-file-save=/var/lib/coreos/etcd-member-wrapper.uuid --trust-keys-from-https --mount volume=coreos-systemd-dir,targ
Oct 31 07:30:37 coreos0 etcd-wrapper[849]: pubkey: prefix: "quay.io/coreos/etcd"
Oct 31 07:30:37 coreos0 etcd-wrapper[849]: key: "https://quay.io/aci-signing-key"
Oct 31 07:30:37 coreos0 etcd-wrapper[849]: gpg key fingerprint is: BFF3 13CD AA56 0B16 A898 7B8F 72AB F5F6 799D 33BC
Oct 31 07:30:37 coreos0 etcd-wrapper[849]: Quay.io ACI Converter (ACI conversion signing key) [e-mail]
Oct 31 07:30:37 coreos0 etcd-wrapper[849]: Trusting "https://quay.io/aci-signing-key" for prefix "quay.io/coreos/etcd" without fingerprint review.
Oct 31 07:30:37 coreos0 etcd-wrapper[849]: Added key for prefix "quay.io/coreos/etcd" at "/etc/rkt/trustedkeys/prefix.d/quay.io/coreos/etcd/bff313cdaa560b16a8987b8f72abf5f6799d33bc"
Oct 31 07:30:37 coreos0 etcd-wrapper[849]: Downloading signature: 0 B/473 B
Oct 31 07:30:37 coreos0 etcd-wrapper[849]: Downloading signature: 473 B/473 B
Oct 31 07:30:37 coreos0 etcd-wrapper[849]: Downloading signature: 473 B/473 B
Oct 31 07:30:39 coreos0 etcd-wrapper[849]: Downloading ACI: 0 B/12.9 MB
Oct 31 07:30:39 coreos0 etcd-wrapper[849]: Downloading ACI: 17 KB/12.9 MB
Oct 31 07:30:40 coreos0 etcd-wrapper[849]: Downloading ACI: 405 KB/12.9 MB
Oct 31 07:30:41 coreos0 etcd-wrapper[849]: Downloading ACI: 941 KB/12.9 MB
Oct 31 07:30:42 coreos0 etcd-wrapper[849]: Downloading ACI: 1.42 MB/12.9 MB
Oct 31 07:30:43 coreos0 etcd-wrapper[849]: Downloading ACI: 2.29 MB/12.9 MB
Oct 31 07:30:44 coreos0 etcd-wrapper[849]: Downloading ACI: 3.23 MB/12.9 MB
Oct 31 07:30:45 coreos0 etcd-wrapper[849]: Downloading ACI: 4.98 MB/12.9 MB
Oct 31 07:30:46 coreos0 etcd-wrapper[849]: Downloading ACI: 5.98 MB/12.9 MB
Oct 31 07:30:47 coreos0 etcd-wrapper[849]: Downloading ACI: 6.56 MB/12.9 MB
Oct 31 07:30:48 coreos0 etcd-wrapper[849]: Downloading ACI: 7.01 MB/12.9 MB
Oct 31 07:30:49 coreos0 etcd-wrapper[849]: Downloading ACI: 7.54 MB/12.9 MB
Oct 31 07:30:50 coreos0 etcd-wrapper[849]: Downloading ACI: 8.06 MB/12.9 MB
Oct 31 07:30:51 coreos0 etcd-wrapper[849]: Downloading ACI: 8.67 MB/12.9 MB
Oct 31 07:30:52 coreos0 etcd-wrapper[849]: Downloading ACI: 9.5 MB/12.9 MB
Oct 31 07:30:53 coreos0 etcd-wrapper[849]: Downloading ACI: 10.5 MB/12.9 MB
Oct 31 07:30:54 coreos0 etcd-wrapper[849]: Downloading ACI: 11.4 MB/12.9 MB
Oct 31 07:30:55 coreos0 etcd-wrapper[849]: Downloading ACI: 12.4 MB/12.9 MB
Oct 31 07:30:56 coreos0 etcd-wrapper[849]: Downloading ACI: 12.9 MB/12.9 MB
Oct 31 07:30:56 coreos0 etcd-wrapper[849]: image: signature verified:
Oct 31 07:30:56 coreos0 etcd-wrapper[849]: Quay.io ACI Converter (ACI conversion signing key) [e-mail]
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.849095 I | pkg/flags: recognized and used environment variable ETCD_DATA_DIR=/var/lib/etcd
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.849416 I | pkg/flags: recognized environment variable ETCD_NAME, but unused: shadowed by corresponding flag
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.849569 W | pkg/flags: unrecognized environment variable ETCD_USER=etcd
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.849713 W | pkg/flags: unrecognized environment variable ETCD_IMAGE_TAG=v3.1.10
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.849849 I | etcdmain: etcd Version: 3.1.10
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.849975 I | etcdmain: Git SHA: 0520cb9
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.850100 I | etcdmain: Go Version: go1.8.3
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.850219 I | etcdmain: Go OS/Arch: linux/amd64
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.850339 I | etcdmain: setting maximum number of CPUs to 2, total number of available CPUs is 2
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.850545 I | embed: listening for peers on http://192.168.12.50:2380
Oct 31 07:30:58 coreos0 etcd-wrapper[849]: 2017-10-31 07:30:58.850703 I | embed: listening for client requests on 127.0.0.1:2379

So no explicit exceptions in the console. I tried to change the ETCDCTL_API but still an error is raised when I try to use etcd:

core@coreos0 ~ $ export ETCDCTL_API=2
core@coreos0 ~ $ etcdctl member list
client: etcd cluster is unavailable or misconfigured; error #0: dial tcp 127.0.0.1:4001: getsockopt: connection refused
; error #1: client: endpoint http://127.0.0.1:2379 exceeded header timeout
```

I guess I am doing something wrong with my configuration but I can't find out...

Thanks in advance for your help.

[gyuho]

etcd cluster is unavailable or misconfigured;

Did you check 3 other nodes in your cluster? Server logs should have some warnings?

[gyuho]

@dchambon Ping?

[dchambon]

Hi @gyuho ,

Sorry for the late reply. I manage to have my ETCD v3 cluster working. I actually changed the configuration to use the discovery mecanism and then it works.
I close the issue, thanks !

[gemfield]

For etcd v3, if you didn't provide ca, key, cert for the client, then you would met the errors. (ref: https://zhuanlan.zhihu.com/p/47228920)

[steaksauce-]

For etcd v3, if you didn't provide ca, key, cert for the client, then you would met the errors. (ref: https://zhuanlan.zhihu.com/p/47228920)

@gemfield I cannot tell you how much this helped me running an etcdctl snapshot. I was getting the same error and added my endpoint and ca, cert, and key and it worked great.

[liukaii]

@steaksauce-
Could you please show me how to provide ca,key,cert in go code?Thank you!

[steaksauce-]

@steaksauce-
Could you please show me how to provide ca,key,cert in go code?Thank you!

I'm not a developer (and do not know Go). I use the CLI options to pass in these options. Here is the example from the article that @gemfield provided: ETCDCTL_API=3 etcdctl --cacert /etc/kubernetes/pki/etcd/ca.crt --cert /etc/kubernetes/pki/etcd/peer.crt --key /etc/kubernetes/pki/etcd/peer.key get --prefix /calico/bgp/v1

If I recall, I had to modify the options slightly because the CLI changed, but you should be able to run man etcdctl and figure out the correct option names.

[attila123]

I needed to use etcdctl with etcd installed on CoreOS (Container Linux). In my case the following worked (executed from CoreOS shell prompt):

$ sudo ETCDCTL_API=3 etcdctl --cacert /etc/ssl/etcd/etcd/peer-ca.crt --cert /etc/ssl/etcd/etcd/peer.crt --key /etc/ssl/etcd/etcd/peer.key get --prefix / --keys-only

I used sudo as a quick solution to the permission problem "Error: open /etc/ssl/etcd/etcd/peer.crt: permission denied".

[paulcaskey]

Just to repeat and emphasize, this "context deadline exceeded" also happens (3.3.13) when using --auto-tls unless you specify _some_ cert and key on the client side, i.e. etcdctl --key=blah.key --cert=blah.crt. You don't actually need the --cacert.

This is true even with ETCDCTL_INSECURE_SKIP_TLS_VERIFY=true.
The server log shows nothing when this happens, even with etcd --debug.

This is unexpected because --auto-tls seems like a feature that "should just work" and there is no corresponding --auto-tls option for etcdctl.

Overall etcd needs better error reporting for all TLS issues. "context deadline exceeded" is a meaningless error message, making troubleshooting difficult.

[jobin-AT]

if you are running on openstack or any cloud please make sure to allow the ports in security groups
in my case this was the error