[2.2.4] etcd/controlplane master not registering on new clusters

[superxor]

Fresh custom cluster. Rancher 2.2.4
k8s 1.13, flannel

steps: create new cluster, add master node

Master node can't register, one of the pods endlessly loops:

• docker start kubelet
  Error response from daemon: {"message":"No such container: kubelet"}
  Error: failed to start containers: kubelet
• sleep 2

etcd pod shows:

WARNING: 2019/07/13 10:19:35 Failed to dial 0.0.0.0:2379: connection error: desc = "transport: authentication handshake failed: remote error: tls: bad certificate"; please retry.

[slamdev]

when k8s 1.14 is used, this error appears in etcd logs:

2019-07-13 11:14:24.030026 I | embed: rejected connection from "10.3.1.20:40787" (error "EOF", ServerName "")
2019-07-13 11:14:32.866684 I | embed: rejected connection from "10.3.1.20:58550" (error "tls: failed to verify client's certificate: x509: certificate signed by unknown authority (possibly because of \"crypto/rsa: verification error\" while trying to verify candidate authority certificate \"kube-ca\")", ServerName "")
2019-07-13 11:14:37.882558 I | embed: rejected connection from "10.3.1.20:58552" (error "tls: failed to verify client's certificate: x509: certificate signed by unknown authority (possibly because of \"crypto/rsa: verification error\" while trying to verify candidate authority certificate \"kube-ca\")", ServerName "")
2019-07-13 11:14:42.905844 I | embed: rejected connection from "10.3.1.20:58554" (error "tls: failed to verify client's certificate: x509: certificate signed by unknown authority (possibly because of \"crypto/rsa: verification error\" while trying to verify candidate authority certificate \"kube-ca\")", ServerName "")

[superxor]

can someone please check this? its a show-stopper

its clearly an issue with rancher: tls: bad certificate
I can reproduce it every time

[superxor]

related #20909

[superseb]

The error shown usually indicates nodes being re-used and data is left behind which clashes with the newly generated data.

If its reproducible every time, please provide exact steps that you've taken so I can use that to reproduce on my end (see https://rancher.com/docs/rancher/v2.x/en/contributing/#bugs-issues-or-questions. Adding a etcd + controlplane node in a custom cluster (1.13 + flannel) does not reproduce.

[superxor]

@superseb I suspect the issue lies with the rancher-master. The etcd node is a brand new fresh VM with fresh hostname (because of the famous hostname issue...when is that ever going to be fixed?).

I tried this 4-5 times now, making sure its always a new VM with new disk and new different hostname

steps:

1. Create new cluster
2. spawn new VM/node
3. run docker command...
4. see etcd pod error about tls cert failure

Ubuntu 18.04 LTS
docker version
Client:
Version: 18.09.7
API version: 1.39
Go version: go1.10.8
Git commit: 2d0083d
Built: Thu Jun 27 17:56:23 2019
OS/Arch: linux/amd64
Experimental: false

[superseb]

When did it start to happen (as it doesnt happen on a fresh 2.2.4 Rancher)? What is in the log of the rancher container (possible leads to why its failing)

[superxor]

Since the upgrade to 2.2.4.

I dont see anything on the rancher master, nor in the other pods

2019/07/24 09:12:29 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.60:44214: i/o timeout
2019/07/24 09:12:29 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.72:49762: i/o timeout
2019/07/24 09:12:30 [INFO] Handling backend connection request [c-q89w5:m-4c0602df0d65]
2019/07/24 09:12:30 [INFO] Handling backend connection request [c-q89w5:m-e5f8240f1893]
2019/07/24 09:12:30 [INFO] Handling backend connection request [c-5q2fz:m-623b23917cdf]
2019/07/24 09:12:30 [INFO] Handling backend connection request [c-5q2fz:m-f48ee2daad85]
2019/07/24 09:12:32 [INFO] Handling backend connection request [c-q89w5:m-b0676695ae93]
2019/07/24 09:12:32 [INFO] Handling backend connection request [c-5q2fz:m-25bd4ee7511c]
2019/07/24 09:12:33 [INFO] Handling backend connection request [c-5q2fz:m-a885899d4c85]
2019/07/24 09:12:34 [INFO] Handling backend connection request [c-5q2fz:m-2b5b7779d339]
2019/07/24 09:12:36 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.26:39580: i/o timeout
2019/07/24 09:12:36 [INFO] Handling backend connection request [c-5q2fz:m-e81840c53f86]

same time on the etcd pod:

2019-07-24 09:12:22.726490 W | auth: simple token is not cryptographically signed
2019-07-24 09:12:22.730662 I | etcdserver: starting server... [version: 3.2.24, cluster version: to_be_decided]
2019-07-24 09:12:22.731466 I | etcdserver/membership: added member fd1bb75040a79e2d [https://10.3.1.20:2380] to cluster 3bf383ae9c8f9b68
2019-07-24 09:12:22.731580 N | etcdserver/membership: set the initial cluster version to 3.2
2019-07-24 09:12:22.731638 I | etcdserver/api: enabled capabilities for version 3.2
2019-07-24 09:12:22.732407 I | embed: ClientTLS: cert = /etc/kubernetes/ssl/kube-etcd-10-3-1-20.pem, key = /etc/kubernetes/ssl/kube-etcd-10-3-1-20-key.pem, ca = , trusted-ca = /etc/kubernetes/ssl/kube-ca.pem, client-cert-auth = true
2019-07-24 09:12:30.221083 I | raft: fd1bb75040a79e2d is starting a new election at term 2
2019-07-24 09:12:30.221215 I | raft: fd1bb75040a79e2d became candidate at term 3
2019-07-24 09:12:30.221258 I | raft: fd1bb75040a79e2d received MsgVoteResp from fd1bb75040a79e2d at term 3
2019-07-24 09:12:30.221306 I | raft: fd1bb75040a79e2d became leader at term 3
2019-07-24 09:12:30.221323 I | raft: raft.node: fd1bb75040a79e2d elected leader fd1bb75040a79e2d at term 3
2019-07-24 09:12:30.221963 I | etcdserver: published {Name:etcd-slamdev-master-t13-20 ClientURLs:[https://10.3.1.20:2379 https://10.3.1.20:4001]} to cluster 3bf383ae9c8f9b68
2019-07-24 09:12:30.222173 I | embed: ready to serve client requests
2019-07-24 09:12:30.223095 I | embed: serving client requests on [::]:2379
WARNING: 2019/07/24 09:12:30 Failed to dial 0.0.0.0:2379: connection error: desc = "transport: authentication handshake failed: remote error: tls: bad certificate"; please retry.

[superxor]

@superseb Where are the certs coming from? I assume the issue is the certs provided by the rancher master? Maybe because we started out with 2.1 or something and upgrades did not fix some issue with them. Would explain why a fresh 2.4 setup does not have this problem.

[superseb]

When you create a new cluster and add the node, rancher starts provisioning the cluster. Logging from this would be helpful as it will show what part of the provisioning process succeeds and where it fails.

Also agent logs would help as I see connections to Rancher dropping (from the new node in the new cluster and possibly from other nodes in other clusters)

[superxor]

rancher master logs during cluster creation and node adding (I removed a few i/o timeout and warning lines that are unrelated, was too much log spam)

2019/07/24 11:45:32 [INFO] Provisioning cluster [c-8gf44]
2019/07/24 11:45:32 [INFO] Creating cluster [c-8gf44]
2019/07/24 11:45:35 [INFO] Handling backend connection request [c-8gf44:m-91f491207258]
2019/07/24 11:45:35 [INFO] Handling backend connection request [c-5q2fz:m-3057e8ce2de9]
2019/07/24 11:45:36 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.86:37826: i/o timeout
2019/07/24 11:45:37 [INFO] Handling backend connection request [c-5q2fz:m-4b59508bd6b8]
2019/07/24 11:45:37 [INFO] kontainerdriver rancherkubernetesengine listening on address 127.0.0.1:10800
2019/07/24 11:45:37 [INFO] cluster [c-8gf44] provisioning: Initiating Kubernetes cluster
2019/07/24 11:45:37 [INFO] cluster [c-8gf44] provisioning: [dialer] Setup tunnel for host [10.3.1.20]
2019/07/24 11:45:37 [INFO] cluster [c-8gf44] provisioning: [state] Pulling image [rancher/rke-tools:v0.1.28] on host [10.3.1.20]
2019/07/24 11:45:42 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.37:43978: i/o timeout
2019/07/24 11:45:42 [INFO] Handling backend connection request [c-5q2fz:m-daaf4c2d51eb]
2019/07/24 11:45:42 [INFO] cluster [c-8gf44] provisioning: [state] Successfully pulled image [rancher/rke-tools:v0.1.28] on host [10.3.1.20]
2019/07/24 11:45:43 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.63:41068: i/o timeout
2019/07/24 11:45:43 [INFO] Handling backend connection request [c-5q2fz:m-41c1a245fd95]
2019/07/24 11:45:44 [INFO] cluster [c-8gf44] provisioning: [state] Successfully started [cluster-state-deployer] container on host [10.3.1.20]
2019/07/24 11:45:44 [INFO] Handling backend connection request [c-5q2fz:m-1afe65447b6f]
2019/07/24 11:45:44 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.60:51806: i/o timeout
2019/07/24 11:45:44 [INFO] cluster [c-8gf44] provisioning: [certificates] Generating CA kubernetes certificates
2019/07/24 11:45:44 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.42:37558: i/o timeout
2019/07/24 11:45:44 [INFO] cluster [c-8gf44] provisioning: [certificates] Generating Kubernetes API server aggregation layer requestheader client CA certificates
2019/07/24 11:45:44 [INFO] Handling backend connection request [c-5q2fz:m-30da5bbfa251]
2019/07/24 11:45:45 [INFO] cluster [c-8gf44] provisioning: [certificates] Generating Kube Scheduler certificates
2019/07/24 11:45:45 [INFO] cluster [c-8gf44] provisioning: [certificates] Generating Kube Proxy certificates
2019/07/24 11:45:45 [INFO] Handling backend connection request [c-5q2fz:m-5fa522286aa8]
2019/07/24 11:45:45 [INFO] cluster [c-8gf44] provisioning: [certificates] Generating Node certificate
2019/07/24 11:45:45 [INFO] cluster [c-8gf44] provisioning: [certificates] Generating Kubernetes API server certificates
2019/07/24 11:45:45 [INFO] Handling backend connection request [c-5q2fz:m-fa0b42cd127d]
2019/07/24 11:45:45 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.119:34756: i/o timeout
2019/07/24 11:45:46 [INFO] cluster [c-8gf44] provisioning: [certificates] Generating admin certificates and kubeconfig
2019/07/24 11:45:46 [INFO] cluster [c-8gf44] provisioning: [certificates] Generating Kubernetes API server proxy client certificates
2019/07/24 11:45:47 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.83:60424: i/o timeout
2019/07/24 11:45:47 [INFO] cluster [c-8gf44] provisioning: [certificates] Generating etcd-10.3.1.20 certificate and key
2019/07/24 11:45:47 [INFO] cluster [c-8gf44] provisioning: [certificates] Generating Kube Controller certificates
2019/07/24 11:45:47 [INFO] Handling backend connection request [c-q89w5:m-ad044186556d]
2019/07/24 11:45:47 [INFO] cluster [c-8gf44] provisioning: Successfully Deployed state file at [management-state/rke/rke-119787230/cluster.rkestate]
2019/07/24 11:45:48 [INFO] cluster [c-8gf44] provisioning: Building Kubernetes cluster
2019/07/24 11:45:48 [INFO] cluster [c-8gf44] provisioning: [dialer] Setup tunnel for host [10.3.1.20]
2019/07/24 11:45:48 [INFO] cluster [c-8gf44] provisioning: [network] Deploying port listener containers
2019/07/24 11:45:48 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.62:43140: i/o timeout
2019/07/24 11:45:48 [INFO] cluster [c-8gf44] provisioning: [network] Successfully started [rke-etcd-port-listener] container on host [10.3.1.20]
2019/07/24 11:45:49 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.88:49832: i/o timeout
2019/07/24 11:45:49 [INFO] cluster [c-8gf44] provisioning: [network] Successfully started [rke-cp-port-listener] container on host [10.3.1.20]
2019/07/24 11:45:49 [INFO] cluster [c-8gf44] provisioning: [network] Port listener containers deployed successfully
2019/07/24 11:45:49 [INFO] cluster [c-8gf44] provisioning: [network] Running control plane -> etcd port checks
2019/07/24 11:45:50 [INFO] Handling backend connection request [c-5q2fz:m-132e9f7d86bc]
2019/07/24 11:45:50 [INFO] Handling backend connection request [c-q89w5:m-b0676695ae93]
2019/07/24 11:45:50 [INFO] Handling backend connection request [c-5q2fz:m-623b23917cdf]
2019/07/24 11:45:50 [INFO] cluster [c-8gf44] provisioning: [network] Successfully started [rke-port-checker] container on host [10.3.1.20]
2019/07/24 11:45:50 [INFO] cluster [c-8gf44] provisioning: [network] Running control plane -> worker port checks
2019/07/24 11:45:51 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.91:44942: i/o timeout
2019/07/24 11:45:51 [INFO] cluster [c-8gf44] provisioning: [network] Successfully started [rke-port-checker] container on host [10.3.1.20]
2019-07-24 11:45:51.343530 I | mvcc: store.index: compact 34577767
2019/07/24 11:45:51 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.38:35090: i/o timeout
2019/07/24 11:45:51 [INFO] cluster [c-8gf44] provisioning: [network] Running workers -> control plane port checks
2019-07-24 11:45:51.490473 I | mvcc: finished scheduled compaction at 34577767 (took 136.99168ms)
2019/07/24 11:45:51 [INFO] cluster [c-8gf44] provisioning: [network] Skipping kubeapi port check
2019/07/24 11:45:51 [INFO] cluster [c-8gf44] provisioning: [network] Removing port listener containers
2019/07/24 11:45:51 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.58:57148: i/o timeout
2019/07/24 11:45:51 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.24:37620: i/o timeout
2019/07/24 11:45:51 [INFO] cluster [c-8gf44] provisioning: [remove/rke-etcd-port-listener] Successfully removed container on host [10.3.1.20]
2019/07/24 11:45:52 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.98:57630: i/o timeout
2019/07/24 11:45:52 [INFO] cluster [c-8gf44] provisioning: [remove/rke-cp-port-listener] Successfully removed container on host [10.3.1.20]
2019/07/24 11:45:52 [INFO] cluster [c-8gf44] provisioning: [network] Port listener containers removed successfully
2019/07/24 11:45:52 [INFO] cluster [c-8gf44] provisioning: [certificates] Deploying kubernetes certificates to Cluster nodes

2019/07/24 11:45:58 [INFO] cluster [c-8gf44] provisioning: [reconcile] Rebuilding and updating local kube config
I0724 11:45:58.076641 7 http.go:110] HTTP2 has been explicitly disabled
2019/07/24 11:45:58 [INFO] cluster [c-8gf44] provisioning: Successfully Deployed local admin kubeconfig at [management-state/rke/rke-119787230/kube_config_cluster.yml]
2019/07/24 11:45:58 [INFO] Handling backend connection request [c-5q2fz:m-471f71f8e09b]
2019/07/24 11:45:58 [INFO] cluster [c-8gf44] provisioning: [certificates] Successfully deployed kubernetes certificates to Cluster nodes
2019/07/24 11:45:58 [INFO] cluster [c-8gf44] provisioning: [file-deploy] Deploying file [/etc/kubernetes/kube-api-authn-webhook.yaml] to node [10.3.1.20]
2019/07/24 11:45:59 [INFO] cluster [c-8gf44] provisioning: Successfully started [file-deployer] container on host [10.3.1.20]
2019/07/24 11:45:59 [INFO] cluster [c-8gf44] provisioning: Waiting for [file-deployer] container to exit on host [10.3.1.20]
2019/07/24 11:45:59 [INFO] cluster [c-8gf44] provisioning: Waiting for [file-deployer] container to exit on host [10.3.1.20]
2019/07/24 11:45:59 [INFO] cluster [c-8gf44] provisioning: Container [file-deployer] is still running on host [10.3.1.20]
2019/07/24 11:45:59 [INFO] Handling backend connection request [c-q89w5:m-4c0602df0d65]
2019/07/24 11:46:00 [INFO] cluster [c-8gf44] provisioning: Waiting for [file-deployer] container to exit on host [10.3.1.20]
2019/07/24 11:46:00 [INFO] cluster [c-8gf44] provisioning: [remove/file-deployer] Successfully removed container on host [10.3.1.20]
2019/07/24 11:46:00 [INFO] cluster [c-8gf44] provisioning: [/etc/kubernetes/kube-api-authn-webhook.yaml] Successfully deployed authentication webhook config Cluster nodes
2019/07/24 11:46:00 [INFO] cluster [c-8gf44] provisioning: [reconcile] Reconciling cluster state
2019/07/24 11:46:00 [INFO] cluster [c-8gf44] provisioning: [reconcile] This is newly generated cluster
2019/07/24 11:46:00 [INFO] cluster [c-8gf44] provisioning: Pre-pulling kubernetes images
2019/07/24 11:46:00 [INFO] cluster [c-8gf44] provisioning: [pre-deploy] Pulling image [rancher/hyperkube:v1.13.5-rancher1] on host [10.3.1.20]

2019/07/24 11:46:20 [INFO] cluster [c-8gf44] provisioning: [pre-deploy] Successfully pulled image [rancher/hyperkube:v1.13.5-rancher1] on host [10.3.1.20]
2019/07/24 11:46:20 [INFO] cluster [c-8gf44] provisioning: Kubernetes images pulled successfully
2019/07/24 11:46:20 [INFO] cluster [c-8gf44] provisioning: [etcd] Building up etcd plane..
2019/07/24 11:46:20 [INFO] cluster [c-8gf44] provisioning: [etcd] Pulling image [rancher/coreos-etcd:v3.2.24-rancher1] on host [10.3.1.20]
2019/07/24 11:46:20 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.122:41248: i/o timeout
2019/07/24 11:46:20 [INFO] Handling backend connection request [c-5q2fz:m-f48ee2daad85]
2019/07/24 11:46:23 [INFO] cluster [c-8gf44] provisioning: [etcd] Successfully pulled image [rancher/coreos-etcd:v3.2.24-rancher1] on host [10.3.1.20]
2019/07/24 11:46:24 [INFO] Handling backend connection request [c-5q2fz:m-471f71f8e09b]
2019/07/24 11:46:25 [INFO] Handling backend connection request [c-5q2fz:m-132e9f7d86bc]
2019/07/24 11:46:25 [INFO] Handling backend connection request [c-q89w5:m-4c0602df0d65]
2019/07/24 11:46:26 [INFO] cluster [c-8gf44] provisioning: [etcd] Successfully started [etcd] container on host [10.3.1.20]
2019/07/24 11:46:26 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.124:57546: i/o timeout
2019/07/24 11:46:26 [INFO] cluster [c-8gf44] provisioning: [etcd] Successfully started [rke-log-linker] container on host [10.3.1.20]
2019/07/24 11:46:26 [INFO] Handling backend connection request [c-q89w5:m-10f33b2daa15]
2019/07/24 11:46:26 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.43:56516: i/o timeout
2019/07/24 11:46:27 [INFO] cluster [c-8gf44] provisioning: [remove/rke-log-linker] Successfully removed container on host [10.3.1.20]
2019/07/24 11:46:27 [INFO] cluster [c-8gf44] provisioning: [etcd] Successfully started etcd plane.. Checking etcd cluster health

2019/07/24 11:46:40 [INFO] error in remotedialer server [400]: read tcp 172.17.0.3:443->10.3.1.119:37006: i/o timeout
2019/07/24 11:46:41 [INFO] Handling backend connection request [c-5q2fz:m-623b23917cdf]
2019/07/24 11:46:42 [ERROR] cluster [c-8gf44] provisioning: [etcd] Failed to bring up Etcd Plane: [etcd] Etcd Cluster is not healthy
2019/07/24 11:46:42 [INFO] kontainerdriver rancherkubernetesengine stopped
2019/07/24 11:46:42 [ERROR] ClusterController c-8gf44 [cluster-provisioner-controller] failed with : [etcd] Failed to bring up Etcd Plane: [etcd] Etcd Cluster is not healthy

Agent pods only show this:

INFO: Using resolv.conf: nameserver 10.3.3.254
INFO: https://rxxxxx/ping is accessible
INFO: rxxxx resolves to 10.3.1.1
time="2019-07-24T11:45:34Z" level=info msg="Rancher agent version v2.2.4 is starting"
time="2019-07-24T11:45:34Z" level=info msg="Option customConfig=map[address:10.3.1.20 internalAddress: roles:[] label:map[]]"
time="2019-07-24T11:45:34Z" level=info msg="Option etcd=false"
time="2019-07-24T11:45:34Z" level=info msg="Option controlPlane=false"
time="2019-07-24T11:45:34Z" level=info msg="Option worker=false"
time="2019-07-24T11:45:34Z" level=info msg="Option requestedHostname=slamdev-master-t14-20"
time="2019-07-24T11:45:34Z" level=info msg="Listening on /tmp/log.sock"
time="2019-07-24T11:45:34Z" level=info msg="Connecting to wss://rancher.adnz.co/v3/connect with token h9vt6wmf6kwv6s7m9qm257gwx8bv5wv5b8zq5qfs984mvmtk976lhw"
time="2019-07-24T11:45:34Z" level=info msg="Connecting to proxy" url="wss://rxxxxxxo/v3/connect"
time="2019-07-24T11:45:34Z" level=info msg="Starting plan monitor"

[superxor]

@superseb same issue on 2.2.6 master and 2.2.6 agent. This is 100% related to rancher upgrades from 2.1 or 2.2

2019-07-25 09:11:20.258357 N | etcdserver/membership: set the initial cluster version to 3.2
2019-07-25 09:11:20.258443 I | etcdserver/api: enabled capabilities for version 3.2
WARNING: 2019/07/25 09:11:20 Failed to dial 0.0.0.0:2379: connection error: desc = "transport: authentication handshake failed: remote error: tls: bad certificate"; please retry.

[superseb]

Can you share the output of:

openssl x509 -in /etc/kubernetes/ssl/kube-etcd-10-3-1-20.pem -text -noout
openssl x509 -in /etc/kubernetes/ssl/kube-ca.pem -text -noout
ls -la /etc/kubernetes/ssl