k3s: After a complete power off: the server is currently unable to handle the request

Environmental Info: K3s Version: k3s version v1.19.1-rc1+k3s1 (041f18f6)

Node(s) CPU architecture, OS, and Version: Linux cluster01 5.4.0-1018-raspi #20-Ubuntu SMP Sun Sep 6 05:11:16 UTC 2020 aarch64 aarch64 aarch64 GNU/Linux

Cluster Configuration: 3 masters

Describe the bug: After a fresh install, all nodes were up correctly. After complete power off of all nodes, when devices come up, nodes are not able to reconnect.

Steps To Reproduce: Installation of K3s on first master node:

curl -sfL https://get.k3s.io | K3S_CLUSTER_INIT=true INSTALL_K3S_CHANNEL=testing sh -

On 2 others masters, installation of K3s

curl -sfL https://get.k3s.io | K3S_URL=${k3s_url} K3S_TOKEN=${k3s_token} INSTALL_K3S_CHANNEL=testing bash -s server

with the correct first node URL and token

Installed K3s: Before the shutdown, all nodes are Ready

$ sudo kubectl get nodes
NAME        STATUS   ROLES         AGE     VERSION
cluster01   Ready    etcd,master   4h47m   v1.19.1-rc1+k3s1
cluster02   Ready    etcd,master   4h46m   v1.19.1-rc1+k3s1
cluster03   Ready    etcd,master   4h46m   v1.19.1-rc1+k3s1

After the power off, here is the error on first created master node

Error from server (ServiceUnavailable): the server is currently unable to handle the request

And on other master nodes

The connection to the server 127.0.0.1:6443 was refused - did you specify the right host or port?

Expected behavior: After a shutdown, all clusters should reconnect. At least, one of then should start correctly

Actual behavior: Connection error to nodes

Additional context / logs: On first master, here are cyclic messages

Sep 15 00:03:16 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.14:49416: remote error: tls: bad certificate
Sep 15 00:03:16 cluster01 k3s[1706]: raft2020/09/15 00:03:16 INFO: 6571fb7574e87dba is starting a new election at term 1287
Sep 15 00:03:16 cluster01 k3s[1706]: raft2020/09/15 00:03:16 INFO: 6571fb7574e87dba became candidate at term 1288
Sep 15 00:03:16 cluster01 k3s[1706]: raft2020/09/15 00:03:16 INFO: 6571fb7574e87dba received MsgVoteResp from 6571fb7574e87dba at term 1288
Sep 15 00:03:16 cluster01 k3s[1706]: raft2020/09/15 00:03:16 INFO: 6571fb7574e87dba [logterm: 3, index: 4142] sent MsgVote request to 5b9648b5cb0fc41a at term 1288
Sep 15 00:03:16 cluster01 k3s[1706]: raft2020/09/15 00:03:16 INFO: 6571fb7574e87dba [logterm: 3, index: 4142] sent MsgVote request to 7e3172f2dd9d22d5 at term 1288
Sep 15 00:03:18 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.13:39492: remote error: tls: bad certificate
Sep 15 00:03:18 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.14:49424: remote error: tls: bad certificate
Sep 15 00:03:19 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.12:55948: remote error: tls: bad certificate
Sep 15 00:03:19 cluster01 k3s[1706]: health check for peer 5b9648b5cb0fc41a could not connect: dial tcp 192.168.10.13:2380: connect: connection refused
Sep 15 00:03:19 cluster01 k3s[1706]: health check for peer 7e3172f2dd9d22d5 could not connect: dial tcp 192.168.10.12:2380: connect: connection refused
Sep 15 00:03:19 cluster01 k3s[1706]: health check for peer 5b9648b5cb0fc41a could not connect: dial tcp 192.168.10.13:2380: connect: connection refused
Sep 15 00:03:19 cluster01 k3s[1706]: health check for peer 7e3172f2dd9d22d5 could not connect: dial tcp 192.168.10.12:2380: connect: connection refused
Sep 15 00:03:20 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.14:49432: remote error: tls: bad certificate
Sep 15 00:03:22 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.14:49440: remote error: tls: bad certificate
Sep 15 00:03:24 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.13:39496: remote error: tls: bad certificate
Sep 15 00:03:24 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.14:49448: remote error: tls: bad certificate
Sep 15 00:03:24 cluster01 k3s[1706]: {"level":"warn","ts":"2020-09-15T00:03:24.661Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://127.0.0.1:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
Sep 15 00:03:24 cluster01 k3s[1706]: time="2020-09-15T00:03:24.661907139Z" level=info msg="Failed to test data store connection: context deadline exceeded"
Sep 15 00:03:24 cluster01 k3s[1706]: WARNING: 2020/09/15 00:03:24 grpc: addrConn.createTransport failed to connect to {https://127.0.0.1:2379  <nil> 0 <nil>}. Err :connection error: desc = "transport: authentication handshake failed: context canceled". Reconnecting...
Sep 15 00:03:24 cluster01 k3s[1706]: WARNING: 2020/09/15 00:03:24 grpc: addrConn.createTransport failed to connect to {https://127.0.0.1:2379  <nil> 0 <nil>}. Err :connection error: desc = "transport: authentication handshake failed: context deadline exceeded". Reconnecting...
Sep 15 00:03:24 cluster01 k3s[1706]: health check for peer 7e3172f2dd9d22d5 could not connect: dial tcp 192.168.10.12:2380: connect: connection refused
Sep 15 00:03:24 cluster01 k3s[1706]: health check for peer 5b9648b5cb0fc41a could not connect: dial tcp 192.168.10.13:2380: connect: connection refused
Sep 15 00:03:24 cluster01 k3s[1706]: health check for peer 5b9648b5cb0fc41a could not connect: dial tcp 192.168.10.13:2380: connect: connection refused
Sep 15 00:03:24 cluster01 k3s[1706]: health check for peer 7e3172f2dd9d22d5 could not connect: dial tcp 192.168.10.12:2380: connect: connection refused
Sep 15 00:03:25 cluster01 k3s[1706]: raft2020/09/15 00:03:25 INFO: 6571fb7574e87dba is starting a new election at term 1288
Sep 15 00:03:25 cluster01 k3s[1706]: raft2020/09/15 00:03:25 INFO: 6571fb7574e87dba became candidate at term 1289
Sep 15 00:03:25 cluster01 k3s[1706]: raft2020/09/15 00:03:25 INFO: 6571fb7574e87dba received MsgVoteResp from 6571fb7574e87dba at term 1289
Sep 15 00:03:25 cluster01 k3s[1706]: raft2020/09/15 00:03:25 INFO: 6571fb7574e87dba [logterm: 3, index: 4142] sent MsgVote request to 5b9648b5cb0fc41a at term 1289
Sep 15 00:03:25 cluster01 k3s[1706]: raft2020/09/15 00:03:25 INFO: 6571fb7574e87dba [logterm: 3, index: 4142] sent MsgVote request to 7e3172f2dd9d22d5 at term 1289
Sep 15 00:03:25 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.12:55952: remote error: tls: bad certificate
Sep 15 00:03:26 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.14:49456: remote error: tls: bad certificate
Sep 15 00:03:28 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.14:49464: remote error: tls: bad certificate
Sep 15 00:03:29 cluster01 k3s[1706]: publish error: etcdserver: request timed out
Sep 15 00:03:29 cluster01 k3s[1706]: health check for peer 5b9648b5cb0fc41a could not connect: dial tcp 192.168.10.13:2380: connect: connection refused
Sep 15 00:03:29 cluster01 k3s[1706]: health check for peer 7e3172f2dd9d22d5 could not connect: dial tcp 192.168.10.12:2380: connect: connection refused
Sep 15 00:03:29 cluster01 k3s[1706]: health check for peer 7e3172f2dd9d22d5 could not connect: dial tcp 192.168.10.12:2380: connect: connection refused
Sep 15 00:03:29 cluster01 k3s[1706]: health check for peer 5b9648b5cb0fc41a could not connect: dial tcp 192.168.10.13:2380: connect: connection refused
Sep 15 00:03:30 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.13:39500: remote error: tls: bad certificate
Sep 15 00:03:30 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.14:49472: remote error: tls: bad certificate
Sep 15 00:03:31 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.12:55956: remote error: tls: bad certificate
Sep 15 00:03:32 cluster01 k3s[1706]: http: TLS handshake error from 192.168.10.14:49480: remote error: tls: bad certificate

On other masters, cyclic messages

Sep 15 00:05:19 cluster02 k3s[41498]: time="2020-09-15T00:05:19.655182251Z" level=fatal msg="starting kubernetes: preparing server: failed to get CA certs at https://cluster01:6443/cacerts: https://cluster01:6443/cacerts: 503 Service Unavailable"
Sep 15 00:05:19 cluster02 systemd[1]: k3s.service: Main process exited, code=exited, status=1/FAILURE
Sep 15 00:05:19 cluster02 systemd[1]: k3s.service: Failed with result 'exit-code'.
Sep 15 00:05:19 cluster02 systemd[1]: Failed to start Lightweight Kubernetes.
Sep 15 00:05:24 cluster02 systemd[1]: k3s.service: Scheduled restart job, restart counter is at 1579.
Sep 15 00:05:24 cluster02 systemd[1]: Stopped Lightweight Kubernetes.
Sep 15 00:05:24 cluster02 systemd[1]: Starting Lightweight Kubernetes...
Sep 15 00:05:25 cluster02 k3s[41527]: time="2020-09-15T00:05:25.507939367Z" level=info msg="Starting k3s v1.19.1-rc1+k3s1 (041f18f6)"
Sep 15 00:05:25 cluster02 k3s[41527]: time="2020-09-15T00:05:25.666961273Z" level=fatal msg="starting kubernetes: preparing server: failed to get CA certs at https://cluster01:6443/cacerts: https://cluster01:6443/cacerts: 503 Service Unavailable"
Sep 15 00:05:25 cluster02 systemd[1]: k3s.service: Main process exited, code=exited, status=1/FAILURE
Sep 15 00:05:25 cluster02 systemd[1]: k3s.service: Failed with result 'exit-code'.
Sep 15 00:05:25 cluster02 systemd[1]: Failed to start Lightweight Kubernetes.
Sep 15 00:05:30 cluster02 systemd[1]: k3s.service: Scheduled restart job, restart counter is at 1580.
Sep 15 00:05:30 cluster02 systemd[1]: Stopped Lightweight Kubernetes.
Sep 15 00:05:30 cluster02 systemd[1]: Starting Lightweight Kubernetes...
Sep 15 00:05:31 cluster02 k3s[41549]: time="2020-09-15T00:05:31.512641858Z" level=info msg="Starting k3s v1.19.1-rc1+k3s1 (041f18f6)"
Sep 15 00:05:31 cluster02 k3s[41549]: time="2020-09-15T00:05:31.671164367Z" level=fatal msg="starting kubernetes: preparing server: failed to get CA certs at https://cluster01:6443/cacerts: https://cluster01:6443/cacerts: 503 Service Unavailable"
Sep 15 00:05:31 cluster02 systemd[1]: k3s.service: Main process exited, code=exited, status=1/FAILURE
Sep 15 00:05:31 cluster02 systemd[1]: k3s.service: Failed with result 'exit-code'.
Sep 15 00:05:31 cluster02 systemd[1]: Failed to start Lightweight Kubernetes.

About this issue

Original URL
State: closed
Created 4 years ago
Reactions: 2
Comments: 33 (24 by maintainers)

Commits related to this issue

Fix managed etcd cold startup deadlock issue #2249 * Add code to handle join URL server returning 503, and continue with startup if the manaaged database is already initialized to avoid deadlock ... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 * Add code to handle join URL server returning 503, and continue with startup if the manaaged database is already initialized to avoid deadlock ... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 * Add code to handle join URL server returning 503, and continue with startup if the manaaged database is already initialized to avoid deadlock ... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 * Add code to handle join URL server returning 503, and continue with startup if the managed database is already initialized to avoid deadlock w... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 * Add code to handle join URL server returning 503, and continue with startup if the managed database is already initialized to avoid deadlock w... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 * Add code to handle join URL server returning 503, and continue with startup if the managed database is already initialized to avoid deadlock w... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 Add code to handle join URL server returning 503, and continue with startup if the managed database is already initialized to avoid deadlock when et... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 Add code to handle join URL server returning 503, and continue with startup if the managed database is already initialized to avoid deadlock when et... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 We should ignore --token and --server if the managed database is initialized, just like we ignore --cluster-init. If the user wants to join a new cl... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 We should ignore --token and --server if the managed database is initialized, just like we ignore --cluster-init. If the user wants to join a new cl... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 We should ignore --token and --server if the managed database is initialized, just like we ignore --cluster-init. If the user wants to join a new cl... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 We should ignore --token and --server if the managed database is initialized, just like we ignore --cluster-init. If the user wants to join a new cl... — committed to brandond/k3s by brandond 4 years ago
Merge pull request #2300 from brandond/fix_2249 Fix managed etcd cold startup deadlock issue #2249 — committed to k3s-io/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 We should ignore --token and --server if the managed database is initialized, just like we ignore --cluster-init. If the user wants to join a new cl... — committed to brandond/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 We should ignore --token and --server if the managed database is initialized, just like we ignore --cluster-init. If the user wants to join a new cl... — committed to k3s-io/k3s by brandond 4 years ago
Fix managed etcd cold startup deadlock issue #2249 We should ignore --token and --server if the managed database is initialized, just like we ignore --cluster-init. If the user wants to join a new cl... — committed to briandowns/k3s by brandond 4 years ago

Most upvoted comments

On the primary server, this happens because we block starting the http listener until the datastore finishes starting. Obviously the datastore can’t come up until quorum is reached, which requires additional servers.

On the secondary servers this happens because we try to validate the client token here: https://github.com/rancher/k3s/blob/master/pkg/cluster/bootstrap.go#L43 before checking to see if we’ve already bootstrapped here: https://github.com/rancher/k3s/blob/master/pkg/cluster/bootstrap.go#L56 all of which have to complete before we start the datastore (etcd).

The workaround is to remove K3S_TOKEN and K3S_URL from /etc/systemd/system/k3s.service.env on the secondary servers after the first startup so it doesn’t try to bootstrap again.

The real fix is to either correct the check order, or start up the http listener earlier so that it can respond to bootstrap requests before etcd is up. The first option is probably simpler, assuming we can handle any side effects of switching the checks.

brandond on Sep 19, 2020

Not everything makes the planned milestone. The upstream release had several CVEs, so we wanted to turn it around quickly. We’ve got another release planned soon (independent of upstream patches) that will include backported fixes from the master branch.

brandond on Oct 17, 2020

I tried the workaround and it works fine. Thanks! Do you think the real fix will be done in the next release?

PPCM on Sep 20, 2020

@brandond just in the last few minutes I have been analyzing the problem further and it seems to be the operating system. When I issue a “reboot” command, everything runs fine until “Stopping Restore / save the current clock…”. Whatever that means…

So everything is good with k3s 😉 Even more than good I have to say! The 1.19 etcd performance compared to 1.18 sqlite is amazing. I observe only half of the base load on the cpu.

Postscript: There were kernel, bootloader and eeporm updates pending. After I installed them all, the problem seems to have disappeared as suddenly as it appeared.

cubed-it on Sep 23, 2020

@cubed-it that doesn’t sound like a k3s issue. It sounds like something is timing out on boot and delaying network startup. Have you checked your system logs?

brandond on Sep 23, 2020

This is definitely a blocker for GAing etcd support. We’ll figure it out

cjellick on Sep 19, 2020

That depends on what the root cause is. Different OS distribution and different hardware merit a new issue.

brandond on Sep 18, 2020

Thanks for the feedback y’all! We’ll investigate this as soon as possible. We expected there might be a few corner cases with the embedded etcd cluster which is why it’s still experimental, but it should stabilize soon.

brandond on Sep 18, 2020