Cluster cannot be created because of (second) server node's issue

Original problem: I tried to create a cluster with multiple nodes in a single physical machine, this is the command
k3d cluster create -a3 -s3 test3 --trace
and the process stuck forever at this point, when the cluster was firing up the second server node:
DEBU[0005] Waiting for node k3d-test3-server-0 to get ready (Log: 'Running kube-apiserver')
TRAC[0005] NodeWaitForLogMessage: Node 'k3d-test3-server-0' waiting for log message 'Running kube-apiserver' since '2021-06-02 12:45:02.516841645 +0000 UTC'
DEBU[0006] Finished waiting for log message 'Running kube-apiserver' from node 'k3d-test3-server-0'
....
DEBU[0007] Waiting for node k3d-test3-server-1 to get ready (Log: 'k3s is up and running')
TRAC[0007] NodeWaitForLogMessage: Node 'k3d-test3-server-1' waiting for log message 'k3s is up and running' since '2021-06-02 12:45:04.23375296 +0000 UTC

It took a while for k3d-test3-server-1 (the second server node) to start (it kept restarting several times before that). This resulted in other nodes (including servers and agents) could not start up. You can see the "created" status in docker ps output

I have tried to purge everything from docker packages and reinstall them (I tried both docker-ce and apt package). Nothing worked so far. It stuck there forever. The weird thing is my other Ubuntu servers did not have the problem. Therefore I suspect this is a local issue - BUT i have tried to reinstall docker and even switch to other linux user just to make sure there is nothing in between k3d and docker. Any suggestions for debugging are really appreciated.
k3d version
k3d version v4.4.4
k3s version v1.20.6-k3s1 (default)

OS version
LSB Version:	core-9.20170808ubuntu1-noarch:security-9.20170808ubuntu1-noarch
Distributor ID:	Ubuntu
Description:	Ubuntu 18.04.3 LTS
Release:	18.04
Codename:	bionic

Docker Info:
Client:
 Context:    default
 Debug Mode: false

Server:
 Containers: 11
  Running: 2
  Paused: 0
  Stopped: 9
 Images: 2
 Server Version: 20.10.2
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: runc io.containerd.runc.v2 io.containerd.runtime.v1.linux
 Default Runtime: runc
 Init Binary: docker-init
 containerd version:
 runc version:
 init version:
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 5.4.0-66-generic
 Operating System: Ubuntu 18.04.3 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 16
 Total Memory: 31.26GiB
 Name: AMC_Test
 ID: HTTK:CWTG:YLKI:Q2AH:5MXF:MVOE:XHFV:V6BF:ZXDX:ZGZ2:EDWM:ZIIE
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  <IP_ADDRESS>/8
 Live Restore Enabled: false

WARNING: No swap limit support
WARNING: No blkio weight support
WARNING: No blkio weight_device support

Additional logs
longnv@AMC_Test  ~  docker logs 0faef53a27b0
time="2021-06-02T12:45:04.467620702Z" level=info msg="Starting k3s v1.20.6+k3s1 (8d043282)"
time="2021-06-02T12:45:04.517018890Z" level=fatal msg="starting kubernetes: preparing server: failed to get CA certs: https://k3d-test3-server-0:6443/cacerts: 503 Service Unavailable"
time="2021-06-02T12:45:05.755968864Z" level=info msg="Starting k3s v1.20.6+k3s1 (8d043282)"
time="2021-06-02T12:45:05.801646534Z" level=fatal msg="starting kubernetes: preparing server: failed to get CA certs: https://k3d-test3-server-0:6443/cacerts: 503 Service Unavailable"
time="2021-06-02T12:45:06.947352136Z" level=info msg="Starting k3s v1.20.6+k3s1 (8d043282)"
time="2021-06-02T12:45:06.993416610Z" level=fatal msg="starting kubernetes: preparing server: failed to get CA certs: https://k3d-test3-server-0:6443/cacerts: 503 Service Unavailable"
time="2021-06-02T12:45:08.305266405Z" level=info msg="Starting k3s v1.20.6+k3s1 (8d043282)"
time="2021-06-02T12:45:08.347054640Z" level=fatal msg="starting kubernetes: preparing server: failed to get CA certs: https://k3d-test3-server-0:6443/cacerts: 503 Service Unavailable"
time="2021-06-02T12:45:10.095231184Z" level=info msg="Starting k3s v1.20.6+k3s1 (8d043282)"
time="2021-06-02T12:45:10.144121231Z" level=warning msg="Cluster CA certificate is not trusted by the host CA bundle, but the token does not include a CA hash. Use the full token from the server's node-token file to enable Cluster CA validation."
time="2021-06-02T12:45:10.144182981Z" level=info msg="Managed etcd cluster not yet initialized"
time="2021-06-02T12:45:10.148323728Z" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.148965934Z" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.149625481Z" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.150251560Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-client-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.150885419Z" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.151474780Z" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.152189659Z" level=info msg="certificate CN=cloud-controller-manager signed by CN=k3s-client-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.152901356Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.153597948Z" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.154228404Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.154830831Z" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.155457319Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.157501228Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1622637902: notBefore=2021-06-02 12:45:02 +0000 UTC notAfter=2022-06-02 12:45:10 +0000 UTC"
time="2021-06-02T12:45:10.158114939Z" level=info msg="Active TLS secret  (ver=) (count 8): map[listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-localhost:localhost listener.cattle.io/fingerprint:SHA1=8E02A6749D1D91B3184B0B5B3517BD3A59F159D6]"
time="2021-06-02T12:45:10.166925515Z" level=info msg="Adding https://<IP_ADDRESS>:2380 to etcd cluster [k3d-test3-server-0-673cddf7=https://<IP_ADDRESS>:2380]"
time="2021-06-02T12:45:10.171117654Z" level=info msg="Starting etcd for cluster [k3d-test3-server-0-673cddf7=https://<IP_ADDRESS>:2380 k3d-test3-server-1-d28439f8=https://<IP_ADDRESS>:2380]"
{"level":"info","ts":"2021-06-02T12:45:10.173Z","caller":"embed/etcd.go:117","msg":"configuring peer listeners","listen-peer-urls":["https://<IP_ADDRESS>:2380"]}
{"level":"info","ts":"2021-06-02T12:45:10.173Z","caller":"embed/etcd.go:468","msg":"starting with peer TLS","tls-info":"cert = /var/lib/rancher/k3s/server/tls/etcd/peer-server-client.crt, key = /var/lib/rancher/k3s/server/tls/etcd/peer-server-client.key, trusted-ca = /var/lib/rancher/k3s/server/tls/etcd/peer-ca.crt, client-cert-auth = true, crl-file = ","cipher-suites":[]}
{"level":"info","ts":"2021-06-02T12:45:10.174Z","caller":"embed/etcd.go:127","msg":"configuring client listeners","listen-client-urls":["https://<IP_ADDRESS>:2379","https://<IP_ADDRESS>:2379"]}
{"level":"info","ts":"2021-06-02T12:45:10.174Z","caller":"embed/etcd.go:302","msg":"starting an etcd server","etcd-version":"3.4.13","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.15.10","go-os":"linux","go-arch":"amd64","max-cpu-set":16,"max-cpu-available":16,"member-initialized":false,"name":"k3d-test3-server-1-d28439f8","data-dir":"/var/lib/rancher/k3s/server/db/etcd","wal-dir":"","wal-dir-dedicated":"","member-dir":"/var/lib/rancher/k3s/server/db/etcd/member","force-new-cluster":false,"heartbeat-interval":"500ms","election-timeout":"5s","initial-election-tick-advance":true,"snapshot-count":100000,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["http://localhost:2380"],"listen-peer-urls":["https://<IP_ADDRESS>:2380"],"advertise-client-urls":["https://<IP_ADDRESS>:2379"],"listen-client-urls":["https://<IP_ADDRESS>:2379","https://<IP_ADDRESS>:2379"],"listen-metrics-urls":["http://<IP_ADDRESS>:2381"],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"k3d-test3-server-0-673cddf7=https://<IP_ADDRESS>:2380,k3d-test3-server-1-d28439f8=https://<IP_ADDRESS>:2380","initial-cluster-state":"existing","initial-cluster-token":"etcd-cluster","quota-size-bytes":2147483648,"pre-vote":false,"initial-corrupt-check":false,"corrupt-check-time-interval":"0s","auto-compaction-mode":"","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":""}
{"level":"info","ts":"2021-06-02T12:45:10.177Z","caller":"etcdserver/backend.go:80","msg":"opened backend db","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","took":"2.328973ms"}
{"level":"warn","ts":"2021-06-02T12:45:10.245Z","caller":"etcdserver/cluster_util.go:76","msg":"failed to get cluster response","address":"https://<IP_ADDRESS>:2380/members","error":"Get \"https://<IP_ADDRESS>:2380/members\": EOF"}
{"level":"info","ts":"2021-06-02T12:45:10.246Z","caller":"embed/etcd.go:363","msg":"closing etcd server","name":"k3d-test3-server-1-d28439f8","data-dir":"/var/lib/rancher/k3s/server/db/etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["https://<IP_ADDRESS>:2379"]}
{"level":"info","ts":"2021-06-02T12:45:10.247Z","caller":"embed/etcd.go:367","msg":"closed etcd server","name":"k3d-test3-server-1-d28439f8","data-dir":"/var/lib/rancher/k3s/server/db/etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["https://<IP_ADDRESS>:2379"]}
time="2021-06-02T12:45:10.247410008Z" level=info msg="Running kube-apiserver --advertise-port=6443 --allow-privileged=true --anonymous-auth=false --api-audiences=https://kubernetes.default.svc.cluster.local,k3s --authorization-mode=Node,RBAC --bind-address=<IP_ADDRESS> --cert-dir=/var/lib/rancher/k3s/server/tls/temporary-certs --client-ca-file=/var/lib/rancher/k3s/server/tls/client-ca.crt --enable-admission-plugins=NodeRestriction --etcd-cafile=/var/lib/rancher/k3s/server/tls/etcd/server-ca.crt --etcd-certfile=/var/lib/rancher/k3s/server/tls/etcd/client.crt --etcd-keyfile=/var/lib/rancher/k3s/server/tls/etcd/client.key --etcd-servers=https://<IP_ADDRESS>:2379 --feature-gates=ServiceAccountIssuerDiscovery=false --insecure-port=0 --kubelet-certificate-authority=/var/lib/rancher/k3s/server/tls/server-ca.crt --kubelet-client-certificate=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.crt --kubelet-client-key=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.key --profiling=false --proxy-client-cert-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt --proxy-client-key-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.key --requestheader-allowed-names=system:auth-proxy --requestheader-client-ca-file=/var/lib/rancher/k3s/server/tls/request-header-ca.crt --requestheader-extra-headers-prefix=X-Remote-Extra- --requestheader-group-headers=X-Remote-Group --requestheader-username-headers=X-Remote-User --secure-port=6444 --service-account-issuer=https://kubernetes.default.svc.cluster.local --service-account-key-file=/var/lib/rancher/k3s/server/tls/service.key --service-account-signing-key-file=/var/lib/rancher/k3s/server/tls/service.key --service-cluster-ip-range=<IP_ADDRESS>/16 --service-node-port-range=30000-32767 --storage-backend=etcd3 --tls-cert-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt --tls-private-key-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key"
{"level":"warn","ts":"2021-06-02T12:45:10.247Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-02T12:45:20.247Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://<IP_ADDRESS>:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\""}
time="2021-06-02T12:45:20.247501638Z" level=info msg="Failed to test data store connection: context deadline exceeded"
{"level":"warn","ts":"2021-06-02T12:45:25.157Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}

{"level":"warn","ts":"2021-06-02T12:45:35.247Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://<IP_ADDRESS>:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\""}
time="2021-06-02T12:45:35.247878656Z" level=info msg="Failed to test data store connection: context deadline exceeded"
{"level":"warn","ts":"2021-06-02T12:45:35.985Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}

the second server node's creation was unstable (up and then restarting and up again and turned off)

tested with other versions (v4.4.0 and v3.4.0), same problem happened. It always stopped at second server node.

Similar issue(s) - i'll keep updating this.
https://github.com/rancher/k3d/issues/592

Hi @nguyenvulong , thanks for opening this issue!
On first sight, I cannot find any obvious issue :thinking:
However, recently there were quite some changes upstream in k3s to fix various issues with OS-Level stuff (kernel changes that broke things, upstream k8s changes that had to be fixed, etc.).
Maybe you can use the --image flag to test one of the newer k3s releases?

Thanks a lot for your time
trying with newest image:

 longnv@AMC_Test þó ~ þó docker logs k3d-test2-server-1
time="2021-06-04T07:03:33.522531537Z" level=info msg="Starting k3s v1.21.1+k3s1 (75dba57f)"
time="2021-06-04T07:03:33.563937545Z" level=fatal msg="starting kubernetes: preparing server: failed to get CA certs: https://k3d-test2-server-0:6443/cacerts: 503 Service Unavailable"
time="2021-06-04T07:03:34.785640367Z" level=info msg="Starting k3s v1.21.1+k3s1 (75dba57f)"
time="2021-06-04T07:03:34.823346580Z" level=fatal msg="starting kubernetes: preparing server: failed to get CA certs: https://k3d-test2-server-0:6443/cacerts: 503 Service Unavailable"
time="2021-06-04T07:03:36.081897728Z" level=info msg="Starting k3s v1.21.1+k3s1 (75dba57f)"
time="2021-06-04T07:03:36.124776263Z" level=fatal msg="starting kubernetes: preparing server: failed to get CA certs: https://k3d-test2-server-0:6443/cacerts: 503 Service Unavailable"
time="2021-06-04T07:03:37.659059818Z" level=info msg="Starting k3s v1.21.1+k3s1 (75dba57f)"
time="2021-06-04T07:03:37.698283670Z" level=warning msg="Cluster CA certificate is not trusted by the host CA bundle, but the token does not include a CA hash. Use the full token from the server's node-token file to enable Cluster CA validation."
time="2021-06-04T07:03:37.698336126Z" level=info msg="Managed etcd cluster not yet initialized"
time="2021-06-04T07:03:37.707032806Z" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.708497737Z" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.709813492Z" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.711070592Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.712364332Z" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.713179657Z" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.713947195Z" level=info msg="certificate CN=cloud-controller-manager signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.714748844Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.715517869Z" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.716472707Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.717202779Z" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.717962686Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.720206173Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.720721054Z" level=info msg="Active TLS secret  (ver=) (count 8): map[listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-localhost:localhost listener.cattle.io/fingerprint:SHA1=CB3CCA6866090E93037DEBBB2F0CB31CCDB90149]"
time="2021-06-04T07:03:37.729505209Z" level=info msg="Adding https://<IP_ADDRESS>:2380 to etcd cluster [k3d-test2-server-0-2de3a935=https://<IP_ADDRESS>:2380]"
time="2021-06-04T07:03:37.731660953Z" level=info msg="Starting etcd for cluster [k3d-test2-server-0-2de3a935=https://<IP_ADDRESS>:2380 k3d-test2-server-1-8337dbce=https://<IP_ADDRESS>:2380]"
{"level":"info","ts":"2021-06-04T07:03:37.733Z","caller":"embed/etcd.go:117","msg":"configuring peer listeners","listen-peer-urls":["https://<IP_ADDRESS>:2380"]}
{"level":"info","ts":"2021-06-04T07:03:37.733Z","caller":"embed/etcd.go:468","msg":"starting with peer TLS","tls-info":"cert = /var/lib/rancher/k3s/server/tls/etcd/peer-server-client.crt, key = /var/lib/rancher/k3s/server/tls/etcd/peer-server-client.key, trusted-ca = /var/lib/rancher/k3s/server/tls/etcd/peer-ca.crt, client-cert-auth = true, crl-file = ","cipher-suites":[]}
{"level":"info","ts":"2021-06-04T07:03:37.734Z","caller":"embed/etcd.go:127","msg":"configuring client listeners","listen-client-urls":["https://<IP_ADDRESS>:2379","https://<IP_ADDRESS>:2379"]}
{"level":"info","ts":"2021-06-04T07:03:37.734Z","caller":"embed/etcd.go:302","msg":"starting an etcd server","etcd-version":"3.4.13","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.16.4","go-os":"linux","go-arch":"amd64","max-cpu-set":16,"max-cpu-available":16,"member-initialized":false,"name":"k3d-test2-server-1-8337dbce","data-dir":"/var/lib/rancher/k3s/server/db/etcd","wal-dir":"","wal-dir-dedicated":"","member-dir":"/var/lib/rancher/k3s/server/db/etcd/member","force-new-cluster":false,"heartbeat-interval":"500ms","election-timeout":"5s","initial-election-tick-advance":true,"snapshot-count":100000,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["http://localhost:2380"],"listen-peer-urls":["https://<IP_ADDRESS>:2380"],"advertise-client-urls":["https://<IP_ADDRESS>:2379"],"listen-client-urls":["https://<IP_ADDRESS>:2379","https://<IP_ADDRESS>:2379"],"listen-metrics-urls":["http://<IP_ADDRESS>:2381"],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"k3d-test2-server-0-2de3a935=https://<IP_ADDRESS>:2380,k3d-test2-server-1-8337dbce=https://<IP_ADDRESS>:2380","initial-cluster-state":"existing","initial-cluster-token":"etcd-cluster","quota-size-bytes":2147483648,"pre-vote":false,"initial-corrupt-check":false,"corrupt-check-time-interval":"0s","auto-compaction-mode":"","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":""}
{"level":"info","ts":"2021-06-04T07:03:37.737Z","caller":"etcdserver/backend.go:80","msg":"opened backend db","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","took":"2.963843ms"}
{"level":"warn","ts":"2021-06-04T07:03:37.776Z","caller":"etcdserver/cluster_util.go:76","msg":"failed to get cluster response","address":"https://<IP_ADDRESS>:2380/members","error":"Get \"https://<IP_ADDRESS>:2380/members\": EOF"}
{"level":"info","ts":"2021-06-04T07:03:37.779Z","caller":"embed/etcd.go:363","msg":"closing etcd server","name":"k3d-test2-server-1-8337dbce","data-dir":"/var/lib/rancher/k3s/server/db/etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["https://<IP_ADDRESS>:2379"]}
{"level":"info","ts":"2021-06-04T07:03:37.779Z","caller":"embed/etcd.go:367","msg":"closed etcd server","name":"k3d-test2-server-1-8337dbce","data-dir":"/var/lib/rancher/k3s/server/db/etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["https://<IP_ADDRESS>:2379"]}
time="2021-06-04T07:03:37.780070743Z" level=info msg="Running kube-apiserver --advertise-port=6443 --allow-privileged=true --anonymous-auth=false --api-audiences=https://kubernetes.default.svc.cluster.local,k3s --authorization-mode=Node,RBAC --bind-address=<IP_ADDRESS> --cert-dir=/var/lib/rancher/k3s/server/tls/temporary-certs --client-ca-file=/var/lib/rancher/k3s/server/tls/client-ca.crt --enable-admission-plugins=NodeRestriction --etcd-cafile=/var/lib/rancher/k3s/server/tls/etcd/server-ca.crt --etcd-certfile=/var/lib/rancher/k3s/server/tls/etcd/client.crt --etcd-keyfile=/var/lib/rancher/k3s/server/tls/etcd/client.key --etcd-servers=https://<IP_ADDRESS>:2379 --insecure-port=0 --kubelet-certificate-authority=/var/lib/rancher/k3s/server/tls/server-ca.crt --kubelet-client-certificate=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.crt --kubelet-client-key=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.key --profiling=false --proxy-client-cert-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt --proxy-client-key-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.key --requestheader-allowed-names=system:auth-proxy --requestheader-client-ca-file=/var/lib/rancher/k3s/server/tls/request-header-ca.crt --requestheader-extra-headers-prefix=X-Remote-Extra- --requestheader-group-headers=X-Remote-Group --requestheader-username-headers=X-Remote-User --secure-port=6444 --service-account-issuer=https://kubernetes.default.svc.cluster.local --service-account-key-file=/var/lib/rancher/k3s/server/tls/service.key --service-account-signing-key-file=/var/lib/rancher/k3s/server/tls/service.key --service-cluster-ip-range=<IP_ADDRESS>/16 --service-node-port-range=30000-32767 --storage-backend=etcd3 --tls-cert-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt --tls-private-key-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key"
{"level":"warn","ts":"2021-06-04T07:03:37.780Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:38.719Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:38.780Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:40.349Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:40.458Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:42.963Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:43.247Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:47.466Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:47.769Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:47.780Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://<IP_ADDRESS>:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\""}
time="2021-06-04T07:03:47.780294528Z" level=info msg="Failed to test data store connection: context deadline exceeded"
{"level":"warn","ts":"2021-06-04T07:03:52.720Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:52.781Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:52.916Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:53.721Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:53.781Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:55.135Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:55.156Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:57.370Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:03:58.191Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:00.916Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:01.514Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:01.674Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:02.721Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://<IP_ADDRESS>:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\""}
time="2021-06-04T07:04:02.721175671Z" level=error msg="Failed to check local etcd status for learner management: context deadline exceeded"
{"level":"warn","ts":"2021-06-04T07:04:02.781Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://<IP_ADDRESS>:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\""}
time="2021-06-04T07:04:02.781558215Z" level=info msg="Failed to test data store connection: context deadline exceeded"
{"level":"warn","ts":"2021-06-04T07:04:07.720Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:07.782Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:08.721Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:08.784Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:10.024Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:10.586Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:12.867Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:12.903Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:16.382Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:16.864Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:17.719Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://<IP_ADDRESS>:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\""}
time="2021-06-04T07:04:17.719914154Z" level=error msg="Failed to check local etcd status for learner management: context deadline exceeded"
{"level":"warn","ts":"2021-06-04T07:04:17.777Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:17.782Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://<IP_ADDRESS>:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\""}
time="2021-06-04T07:04:17.782607624Z" level=info msg="Failed to test data store connection: context deadline exceeded"
{"level":"warn","ts":"2021-06-04T07:04:22.719Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:22.783Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:23.720Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:23.784Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:25.069Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:25.343Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:27.463Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:28.167Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:31.125Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:32.052Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:32.719Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://<IP_ADDRESS>:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\""}
time="2021-06-04T07:04:32.719771843Z" level=error msg="Failed to check local etcd status for learner management: context deadline exceeded"
{"level":"warn","ts":"2021-06-04T07:04:32.784Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"passthrough:///https://<IP_ADDRESS>:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\""}
time="2021-06-04T07:04:32.784136575Z" level=info msg="Failed to test data store connection: context deadline exceeded"
{"level":"warn","ts":"2021-06-04T07:04:37.720Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:37.784Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:38.720Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:38.786Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:40.256Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}
{"level":"warn","ts":"2021-06-04T07:04:40.591Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {https://<IP_ADDRESS>:2379  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp <IP_ADDRESS>:2379: connect: connection refused\". Reconnecting..."}

 longnv@AMC_Test  ~  docker logs k3d-test2-server-0
time="2021-06-04T07:03:31.639407541Z" level=info msg="Starting k3s v1.21.1+k3s1 (75dba57f)"
time="2021-06-04T07:03:31.639906447Z" level=info msg="Managed etcd cluster initializing"
time="2021-06-04T07:03:31.660940408Z" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.662973979Z" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.664439743Z" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.665878197Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.667212026Z" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.668506868Z" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.669895803Z" level=info msg="certificate CN=cloud-controller-manager signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.672204883Z" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.673589430Z" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.674793128Z" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.675446317Z" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
time="2021-06-04T07:03:31.676681558Z" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:31 +0000 UTC"
{"level":"info","ts":"2021-06-04T07:03:32.080Z","caller":"embed/etcd.go:117","msg":"configuring peer listeners","listen-peer-urls":["https://<IP_ADDRESS>:2380"]}
{"level":"info","ts":"2021-06-04T07:03:32.080Z","caller":"embed/etcd.go:468","msg":"starting with peer TLS","tls-info":"cert = /var/lib/rancher/k3s/server/tls/etcd/peer-server-client.crt, key = /var/lib/rancher/k3s/server/tls/etcd/peer-server-client.key, trusted-ca = /var/lib/rancher/k3s/server/tls/etcd/peer-ca.crt, client-cert-auth = true, crl-file = ","cipher-suites":[]}
time="2021-06-04T07:03:32.080376449Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:32 +0000 UTC"
{"level":"info","ts":"2021-06-04T07:03:32.080Z","caller":"embed/etcd.go:127","msg":"configuring client listeners","listen-client-urls":["https://<IP_ADDRESS>:2379","https://<IP_ADDRESS>:2379"]}
{"level":"info","ts":"2021-06-04T07:03:32.080Z","caller":"embed/etcd.go:302","msg":"starting an etcd server","etcd-version":"3.4.13","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.16.4","go-os":"linux","go-arch":"amd64","max-cpu-set":16,"max-cpu-available":16,"member-initialized":false,"name":"k3d-test2-server-0-2de3a935","data-dir":"/var/lib/rancher/k3s/server/db/etcd","wal-dir":"","wal-dir-dedicated":"","member-dir":"/var/lib/rancher/k3s/server/db/etcd/member","force-new-cluster":false,"heartbeat-interval":"500ms","election-timeout":"5s","initial-election-tick-advance":true,"snapshot-count":100000,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["https://<IP_ADDRESS>:2380"],"listen-peer-urls":["https://<IP_ADDRESS>:2380"],"advertise-client-urls":["https://<IP_ADDRESS>:2379"],"listen-client-urls":["https://<IP_ADDRESS>:2379","https://<IP_ADDRESS>:2379"],"listen-metrics-urls":["http://<IP_ADDRESS>:2381"],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"k3d-test2-server-0-2de3a935=https://<IP_ADDRESS>:2380","initial-cluster-state":"new","initial-cluster-token":"etcd-cluster","quota-size-bytes":2147483648,"pre-vote":false,"initial-corrupt-check":false,"corrupt-check-time-interval":"0s","auto-compaction-mode":"","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":""}
time="2021-06-04T07:03:32.080903418Z" level=info msg="Active TLS secret  (ver=) (count 8): map[listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-localhost:localhost listener.cattle.io/fingerprint:SHA1=4DA54AB8CCFD99FE5EF7A622E18650E5B1DA2C2C]"
{"level":"info","ts":"2021-06-04T07:03:32.083Z","caller":"etcdserver/backend.go:80","msg":"opened backend db","path":"/var/lib/rancher/k3s/server/db/etcd/member/snap/db","took":"2.183796ms"}
{"level":"info","ts":"2021-06-04T07:03:32.087Z","caller":"etcdserver/raft.go:486","msg":"starting local member","local-member-id":"c2ed0eb8fc7bc4fc","cluster-id":"d94dd8791a0b7a16"}
{"level":"info","ts":"2021-06-04T07:03:32.087Z","caller":"raft/raft.go:1530","msg":"c2ed0eb8fc7bc4fc switched to configuration voters=()"}
{"level":"info","ts":"2021-06-04T07:03:32.087Z","caller":"raft/raft.go:700","msg":"c2ed0eb8fc7bc4fc became follower at term 0"}
{"level":"info","ts":"2021-06-04T07:03:32.087Z","caller":"raft/raft.go:383","msg":"newRaft c2ed0eb8fc7bc4fc [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"}
{"level":"info","ts":"2021-06-04T07:03:32.087Z","caller":"raft/raft.go:700","msg":"c2ed0eb8fc7bc4fc became follower at term 1"}
{"level":"info","ts":"2021-06-04T07:03:32.087Z","caller":"raft/raft.go:1530","msg":"c2ed0eb8fc7bc4fc switched to configuration voters=(14045899000511186172)"}
{"level":"warn","ts":"2021-06-04T07:03:32.090Z","caller":"auth/store.go:1366","msg":"simple token is not cryptographically signed"}
{"level":"info","ts":"2021-06-04T07:03:32.094Z","caller":"etcdserver/quota.go:98","msg":"enabled backend quota with default value","quota-name":"v3-applier","quota-size-bytes":2147483648,"quota-size":"2.1 GB"}
{"level":"info","ts":"2021-06-04T07:03:32.096Z","caller":"etcdserver/server.go:803","msg":"starting etcd server","local-member-id":"c2ed0eb8fc7bc4fc","local-server-version":"3.4.13","cluster-version":"to_be_decided"}
{"level":"info","ts":"2021-06-04T07:03:32.096Z","caller":"etcdserver/server.go:669","msg":"started as single-node; fast-forwarding election ticks","local-member-id":"c2ed0eb8fc7bc4fc","forward-ticks":9,"forward-duration":"4.5s","election-ticks":10,"election-timeout":"5s"}
{"level":"info","ts":"2021-06-04T07:03:32.097Z","caller":"raft/raft.go:1530","msg":"c2ed0eb8fc7bc4fc switched to configuration voters=(14045899000511186172)"}
{"level":"info","ts":"2021-06-04T07:03:32.097Z","caller":"membership/cluster.go:392","msg":"added member","cluster-id":"d94dd8791a0b7a16","local-member-id":"c2ed0eb8fc7bc4fc","added-peer-id":"c2ed0eb8fc7bc4fc","added-peer-peer-urls":["https://<IP_ADDRESS>:2380"]}
{"level":"info","ts":"2021-06-04T07:03:32.099Z","caller":"embed/etcd.go:711","msg":"starting with client TLS","tls-info":"cert = /var/lib/rancher/k3s/server/tls/etcd/server-client.crt, key = /var/lib/rancher/k3s/server/tls/etcd/server-client.key, trusted-ca = /var/lib/rancher/k3s/server/tls/etcd/server-ca.crt, client-cert-auth = true, crl-file = ","cipher-suites":[]}
{"level":"info","ts":"2021-06-04T07:03:32.099Z","caller":"embed/etcd.go:579","msg":"serving peer traffic","address":"<IP_ADDRESS>:2380"}
{"level":"info","ts":"2021-06-04T07:03:32.099Z","caller":"embed/etcd.go:244","msg":"now serving peer/client/metrics","local-member-id":"c2ed0eb8fc7bc4fc","initial-advertise-peer-urls":["https://<IP_ADDRESS>:2380"],"listen-peer-urls":["https://<IP_ADDRESS>:2380"],"advertise-client-urls":["https://<IP_ADDRESS>:2379"],"listen-client-urls":["https://<IP_ADDRESS>:2379","https://<IP_ADDRESS>:2379"],"listen-metrics-urls":["http://<IP_ADDRESS>:2381"]}
{"level":"info","ts":"2021-06-04T07:03:32.099Z","caller":"embed/etcd.go:781","msg":"serving metrics","address":"http://<IP_ADDRESS>:2381"}
time="2021-06-04T07:03:32.099688032Z" level=info msg="Running kube-apiserver --advertise-port=6443 --allow-privileged=true --anonymous-auth=false --api-audiences=https://kubernetes.default.svc.cluster.local,k3s --authorization-mode=Node,RBAC --bind-address=<IP_ADDRESS> --cert-dir=/var/lib/rancher/k3s/server/tls/temporary-certs --client-ca-file=/var/lib/rancher/k3s/server/tls/client-ca.crt --enable-admission-plugins=NodeRestriction --etcd-cafile=/var/lib/rancher/k3s/server/tls/etcd/server-ca.crt --etcd-certfile=/var/lib/rancher/k3s/server/tls/etcd/client.crt --etcd-keyfile=/var/lib/rancher/k3s/server/tls/etcd/client.key --etcd-servers=https://<IP_ADDRESS>:2379 --insecure-port=0 --kubelet-certificate-authority=/var/lib/rancher/k3s/server/tls/server-ca.crt --kubelet-client-certificate=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.crt --kubelet-client-key=/var/lib/rancher/k3s/server/tls/client-kube-apiserver.key --profiling=false --proxy-client-cert-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt --proxy-client-key-file=/var/lib/rancher/k3s/server/tls/client-auth-proxy.key --requestheader-allowed-names=system:auth-proxy --requestheader-client-ca-file=/var/lib/rancher/k3s/server/tls/request-header-ca.crt --requestheader-extra-headers-prefix=X-Remote-Extra- --requestheader-group-headers=X-Remote-Group --requestheader-username-headers=X-Remote-User --secure-port=6444 --service-account-issuer=https://kubernetes.default.svc.cluster.local --service-account-key-file=/var/lib/rancher/k3s/server/tls/service.key --service-account-signing-key-file=/var/lib/rancher/k3s/server/tls/service.key --service-cluster-ip-range=<IP_ADDRESS>/16 --service-node-port-range=30000-32767 --storage-backend=etcd3 --tls-cert-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt --tls-private-key-file=/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key"
time="2021-06-04T07:03:33.525241341Z" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:33 +0000 UTC"
time="2021-06-04T07:03:33.525616694Z" level=info msg="Active TLS secret  (ver=) (count 9): map[listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-k3d-test2-server-0:k3d-test2-server-0 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-localhost:localhost listener.cattle.io/fingerprint:SHA1=26C30BB4080BB3DB141C45477537C1E591399436]"
time="2021-06-04T07:03:33.546901682Z" level=info msg="Cluster-Http-Server 2021/06/04 07:03:33 http: TLS handshake error from <IP_ADDRESS>:41122: remote error: tls: bad certificate"
time="2021-06-04T07:03:34.806901135Z" level=info msg="Cluster-Http-Server 2021/06/04 07:03:34 http: TLS handshake error from <IP_ADDRESS>:41136: remote error: tls: bad certificate"
{"level":"info","ts":"2021-06-04T07:03:36.088Z","caller":"raft/raft.go:923","msg":"c2ed0eb8fc7bc4fc is starting a new election at term 1"}
{"level":"info","ts":"2021-06-04T07:03:36.088Z","caller":"raft/raft.go:713","msg":"c2ed0eb8fc7bc4fc became candidate at term 2"}
{"level":"info","ts":"2021-06-04T07:03:36.088Z","caller":"raft/raft.go:824","msg":"c2ed0eb8fc7bc4fc received MsgVoteResp from c2ed0eb8fc7bc4fc at term 2"}
{"level":"info","ts":"2021-06-04T07:03:36.088Z","caller":"raft/raft.go:765","msg":"c2ed0eb8fc7bc4fc became leader at term 2"}
{"level":"info","ts":"2021-06-04T07:03:36.088Z","caller":"raft/node.go:325","msg":"raft.node: c2ed0eb8fc7bc4fc elected leader c2ed0eb8fc7bc4fc at term 2"}
{"level":"info","ts":"2021-06-04T07:03:36.088Z","caller":"etcdserver/server.go:2530","msg":"setting up initial cluster version","cluster-version":"3.4"}
{"level":"info","ts":"2021-06-04T07:03:36.090Z","caller":"membership/cluster.go:558","msg":"set initial cluster version","cluster-id":"d94dd8791a0b7a16","local-member-id":"c2ed0eb8fc7bc4fc","cluster-version":"3.4"}
{"level":"info","ts":"2021-06-04T07:03:36.090Z","caller":"api/capability.go:76","msg":"enabled capabilities for version","cluster-version":"3.4"}
{"level":"info","ts":"2021-06-04T07:03:36.090Z","caller":"etcdserver/server.go:2562","msg":"cluster version is updated","cluster-version":"3.4"}
{"level":"info","ts":"2021-06-04T07:03:36.090Z","caller":"etcdserver/server.go:2039","msg":"published local member to cluster through raft","local-member-id":"c2ed0eb8fc7bc4fc","local-member-attributes":"{Name:k3d-test2-server-0-2de3a935 ClientURLs:[https://<IP_ADDRESS>:2379]}","request-path":"/0/members/c2ed0eb8fc7bc4fc/attributes","cluster-id":"d94dd8791a0b7a16","publish-timeout":"15s"}
{"level":"info","ts":"2021-06-04T07:03:36.092Z","caller":"embed/serve.go:191","msg":"serving client traffic securely","address":"<IP_ADDRESS>:2379"}
{"level":"info","ts":"2021-06-04T07:03:36.092Z","caller":"embed/serve.go:191","msg":"serving client traffic securely","address":"<IP_ADDRESS>:2379"}
time="2021-06-04T07:03:36.099196191Z" level=info msg="etcd data store connection OK"
time="2021-06-04T07:03:36.099266347Z" level=info msg="Saving current etcd snapshot set to k3s-etcd-snapshots ConfigMap"
Flag --insecure-port has been deprecated, This flag has no effect now and will be removed in v1.24.
I0604 07:03:36.101060       7 server.go:656] external host was not specified, using <IP_ADDRESS>
I0604 07:03:36.101556       7 server.go:195] Version: v1.21.1+k3s1
time="2021-06-04T07:03:36.105624288Z" level=info msg="Cluster-Http-Server 2021/06/04 07:03:36 http: TLS handshake error from <IP_ADDRESS>:41148: remote error: tls: bad certificate"
I0604 07:03:36.765311       7 shared_informer.go:240] Waiting for caches to sync for node_authorizer
I0604 07:03:36.766513       7 plugins.go:158] Loaded 12 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,RuntimeClass,DefaultIngressClass,MutatingAdmissionWebhook.
I0604 07:03:36.766528       7 plugins.go:161] Loaded 10 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,CertificateSubjectRestriction,ValidatingAdmissionWebhook,ResourceQuota.
I0604 07:03:36.767775       7 plugins.go:158] Loaded 12 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,RuntimeClass,DefaultIngressClass,MutatingAdmissionWebhook.
I0604 07:03:36.767789       7 plugins.go:161] Loaded 10 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,CertificateSubjectRestriction,ValidatingAdmissionWebhook,ResourceQuota.
I0604 07:03:36.804836       7 instance.go:283] Using reconciler: lease
I0604 07:03:36.893536       7 rest.go:130] the default service ipfamily for this cluster is: IPv4
W0604 07:03:37.506424       7 genericapiserver.go:425] Skipping API node.k8s.io/v1alpha1 because it has no resources.
W0604 07:03:37.521344       7 genericapiserver.go:425] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources.
W0604 07:03:37.526290       7 genericapiserver.go:425] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources.
W0604 07:03:37.536628       7 genericapiserver.go:425] Skipping API storage.k8s.io/v1alpha1 because it has no resources.
W0604 07:03:37.540219       7 genericapiserver.go:425] Skipping API flowcontrol.apiserver.k8s.io/v1alpha1 because it has no resources.
W0604 07:03:37.548599       7 genericapiserver.go:425] Skipping API apps/v1beta2 because it has no resources.
W0604 07:03:37.548616       7 genericapiserver.go:425] Skipping API apps/v1beta1 because it has no resources.
I0604 07:03:37.560734       7 plugins.go:158] Loaded 12 mutating admission controller(s) successfully in the following order: NamespaceLifecycle,LimitRanger,ServiceAccount,NodeRestriction,TaintNodesByCondition,Priority,DefaultTolerationSeconds,DefaultStorageClass,StorageObjectInUseProtection,RuntimeClass,DefaultIngressClass,MutatingAdmissionWebhook.
I0604 07:03:37.560750       7 plugins.go:161] Loaded 10 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,CertificateSubjectRestriction,ValidatingAdmissionWebhook,ResourceQuota.
time="2021-06-04T07:03:37.589287716Z" level=info msg="Running kube-scheduler --address=<IP_ADDRESS> --bind-address=<IP_ADDRESS> --kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --port=10251 --profiling=false --secure-port=0"
time="2021-06-04T07:03:37.589351223Z" level=info msg="Waiting for API server to become available"
time="2021-06-04T07:03:37.589881512Z" level=info msg="Running kube-controller-manager --address=<IP_ADDRESS> --allocate-node-cidrs=true --bind-address=<IP_ADDRESS> --cluster-cidr=<IP_ADDRESS>/16 --cluster-signing-kube-apiserver-client-cert-file=/var/lib/rancher/k3s/server/tls/client-ca.crt --cluster-signing-kube-apiserver-client-key-file=/var/lib/rancher/k3s/server/tls/client-ca.key --cluster-signing-kubelet-client-cert-file=/var/lib/rancher/k3s/server/tls/client-ca.crt --cluster-signing-kubelet-client-key-file=/var/lib/rancher/k3s/server/tls/client-ca.key --cluster-signing-kubelet-serving-cert-file=/var/lib/rancher/k3s/server/tls/server-ca.crt --cluster-signing-kubelet-serving-key-file=/var/lib/rancher/k3s/server/tls/server-ca.key --cluster-signing-legacy-unknown-cert-file=/var/lib/rancher/k3s/server/tls/client-ca.crt --cluster-signing-legacy-unknown-key-file=/var/lib/rancher/k3s/server/tls/client-ca.key --configure-cloud-routes=false --controllers=*,-service,-route,-cloud-node-lifecycle --kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --port=10252 --profiling=false --root-ca-file=/var/lib/rancher/k3s/server/tls/server-ca.crt --secure-port=0 --service-account-private-key-file=/var/lib/rancher/k3s/server/tls/service.key --use-service-account-credentials=true"
time="2021-06-04T07:03:37.591289037Z" level=info msg="Node token is available at /var/lib/rancher/k3s/server/token"
time="2021-06-04T07:03:37.591332923Z" level=info msg="To join node to cluster: k3s agent -s https://<IP_ADDRESS>:6443 -t ${NODE_TOKEN}"
time="2021-06-04T07:03:37.592413839Z" level=info msg="Wrote kubeconfig /output/kubeconfig.yaml"
time="2021-06-04T07:03:37.592544054Z" level=info msg="Run: k3s kubectl"
time="2021-06-04T07:03:37.621869354Z" level=info msg="Cluster-Http-Server 2021/06/04 07:03:37 http: TLS handshake error from <IP_ADDRESS>:40528: remote error: tls: bad certificate"
time="2021-06-04T07:03:37.627833818Z" level=info msg="Cluster-Http-Server 2021/06/04 07:03:37 http: TLS handshake error from <IP_ADDRESS>:40536: remote error: tls: bad certificate"
time="2021-06-04T07:03:37.640595920Z" level=info msg="certificate CN=k3d-test2-server-0 signed by CN=k3s-server-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.644747543Z" level=info msg="certificate CN=system:node:k3d-test2-server-0,O=system:nodes signed by CN=k3s-client-ca@1622790211: notBefore=2021-06-04 07:03:31 +0000 UTC notAfter=2022-06-04 07:03:37 +0000 UTC"
time="2021-06-04T07:03:37.661317314Z" level=info msg="Module overlay was already loaded"
time="2021-06-04T07:03:37.661364838Z" level=info msg="Module nf_conntrack was already loaded"
time="2021-06-04T07:03:37.661394678Z" level=info msg="Module br_netfilter was already loaded"
time="2021-06-04T07:03:37.661415353Z" level=info msg="Module iptable_nat was already loaded"
time="2021-06-04T07:03:37.668919064Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_established' to 86400"
time="2021-06-04T07:03:37.669000325Z" level=info msg="Set sysctl 'net/netfilter/nf_conntrack_tcp_timeout_close_wait' to 3600"
time="2021-06-04T07:03:37.670067679Z" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log"
time="2021-06-04T07:03:37.670172364Z" level=info msg="Running containerd -c /var/lib/rancher/k3s/agent/etc/containerd/config.toml -a /run/k3s/containerd/containerd.sock --state /run/k3s/containerd --root /var/lib/rancher/k3s/agent/containerd"
{"level":"warn","ts":"2021-06-04T07:03:37.670Z","caller":"grpclog/grpclog.go:60","msg":"grpc: addrConn.createTransport failed to connect to {/run/k3s/containerd/containerd.sock  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial unix /run/k3s/containerd/containerd.sock: connect: no such file or directory\". Reconnecting..."}
time="2021-06-04T07:03:37.680022621Z" level=info msg="Cluster-Http-Server 2021/06/04 07:03:37 http: TLS handshake error from <IP_ADDRESS>:41352: remote error: tls: bad certificate"
{"level":"info","ts":"2021-06-04T07:03:37.729Z","caller":"raft/raft.go:1530","msg":"c2ed0eb8fc7bc4fc switched to configuration voters=(14045899000511186172) learners=(7837428816332907325)"}
{"level":"info","ts":"2021-06-04T07:03:37.730Z","caller":"membership/cluster.go:392","msg":"added member","cluster-id":"d94dd8791a0b7a16","local-member-id":"c2ed0eb8fc7bc4fc","added-peer-id":"6cc423fbe5eee33d","added-peer-peer-urls":["https://<IP_ADDRESS>:2380"]}
{"level":"info","ts":"2021-06-04T07:03:37.730Z","caller":"rafthttp/peer.go:128","msg":"starting remote peer","remote-peer-id":"6cc423fbe5eee33d"}
{"level":"info","ts":"2021-06-04T07:03:37.730Z","caller":"rafthttp/pipeline.go:71","msg":"started HTTP pipelining with remote peer","local-member-id":"c2ed0eb8fc7bc4fc","remote-peer-id":"6cc423fbe5eee33d"}
{"level":"info","ts":"2021-06-04T07:03:37.730Z","caller":"rafthttp/stream.go:166","msg":"started stream writer with remote peer","local-member-id":"c2ed0eb8fc7bc4fc","remote-peer-id":"6cc423fbe5eee33d"}
{"level":"info","ts":"2021-06-04T07:03:37.730Z","caller":"rafthttp/stream.go:166","msg":"started stream writer with remote peer","local-member-id":"c2ed0eb8fc7bc4fc","remote-peer-id":"6cc423fbe5eee33d"}
{"level":"info","ts":"2021-06-04T07:03:37.731Z","caller":"rafthttp/peer.go:134","msg":"started remote peer","remote-peer-id":"6cc423fbe5eee33d"}
{"level":"info","ts":"2021-06-04T07:03:37.731Z","caller":"rafthttp/stream.go:406","msg":"started stream reader with remote peer","stream-reader-type":"stream Message","local-member-id":"c2ed0eb8fc7bc4fc","remote-peer-id":"6cc423fbe5eee33d"}
{"level":"info","ts":"2021-06-04T07:03:37.731Z","caller":"rafthttp/stream.go:406","msg":"started stream reader with remote peer","stream-reader-type":"stream MsgApp v2","local-member-id":"c2ed0eb8fc7bc4fc","remote-peer-id":"6cc423fbe5eee33d"}
{"level":"info","ts":"2021-06-04T07:03:37.731Z","caller":"rafthttp/transport.go:327","msg":"added remote peer","local-member-id":"c2ed0eb8fc7bc4fc","remote-peer-id":"6cc423fbe5eee33d","remote-peer-urls":["https://<IP_ADDRESS>:2380"]}
{"level":"info","ts":"2021-06-04T07:03:37.731Z","caller":"etcdserver/server.go:1967","msg":"applied a configuration change through raft","local-member-id":"c2ed0eb8fc7bc4fc","raft-conf-change":"ConfChangeAddLearnerNode","raft-conf-change-node-id":"6cc423fbe5eee33d"}
{"level":"warn","ts":"2021-06-04T07:03:37.776Z","caller":"embed/config_logging.go:270","msg":"rejected connection","remote-addr":"<IP_ADDRESS>:35466","server-name":"","ip-addresses":["<IP_ADDRESS>","<IP_ADDRESS>","<IP_ADDRESS>","<IP_ADDRESS>"],"dns-names":["localhost"],"error":"tls: \"<IP_ADDRESS>\" does not match any of DNSNames [\"localhost\"] (lookup <IP_ADDRESS>: Name does not resolve)"}
time="2021-06-04T07:03:38.671485230Z" level=info msg="Containerd is now running"
time="2021-06-04T07:03:38.693285717Z" level=info msg="Connecting to proxy" url="wss://<IP_ADDRESS>:6443/v1-k3s/connect"
time="2021-06-04T07:03:38.696738185Z" level=info msg="Handling backend connection request [k3d-test2-server-0]"
time="2021-06-04T07:03:38.697553444Z" level=warning msg="Disabling CPU quotas due to missing cpu.cfs_period_us"
time="2021-06-04T07:03:38.697685642Z" level=info msg="Running kubelet --address=<IP_ADDRESS> --anonymous-auth=false --authentication-token-webhook=true --authorization-mode=Webhook --cgroup-driver=cgroupfs --client-ca-file=/var/lib/rancher/k3s/agent/client-ca.crt --cloud-provider=external --cluster-dns=<IP_ADDRESS> --cluster-domain=cluster.local --cni-bin-dir=/bin --cni-conf-dir=/var/lib/rancher/k3s/agent/etc/cni/net.d --container-runtime-endpoint=unix:///run/k3s/containerd/containerd.sock --container-runtime=remote --containerd=/run/k3s/containerd/containerd.sock --cpu-cfs-quota=false --eviction-hard=imagefs.available<5%,nodefs.available<5% --eviction-minimum-reclaim=imagefs.available=10%,nodefs.available=10% --fail-swap-on=false --healthz-bind-address=<IP_ADDRESS> --hostname-override=k3d-test2-server-0 --kubeconfig=/var/lib/rancher/k3s/agent/kubelet.kubeconfig --kubelet-cgroups=/k3s --node-labels= --pod-manifest-path=/var/lib/rancher/k3s/agent/pod-manifests --read-only-port=0 --resolv-conf=/tmp/k3s-resolv.conf --runtime-cgroups=/k3s --serialize-image-pulls=false --tls-cert-file=/var/lib/rancher/k3s/agent/serving-kubelet.crt --tls-private-key-file=/var/lib/rancher/k3s/agent/serving-kubelet.key"
time="2021-06-04T07:03:38.698715841Z" level=info msg="Running kube-proxy --cluster-cidr=<IP_ADDRESS>/16 --conntrack-max-per-core=0 --conntrack-tcp-timeout-close-wait=0s --conntrack-tcp-timeout-established=0s --healthz-bind-address=<IP_ADDRESS> --hostname-override=k3d-test2-server-0 --kubeconfig=/var/lib/rancher/k3s/agent/kubeproxy.kubeconfig --proxy-mode=iptables"
Flag --cloud-provider has been deprecated, will be removed in 1.23, in favor of removing cloud provider code from Kubelet.
Flag --cni-bin-dir has been deprecated, will be removed along with dockershim.
Flag --cni-conf-dir has been deprecated, will be removed along with dockershim.
Flag --containerd has been deprecated, This is a cadvisor flag that was mistakenly registered with the Kubelet. Due to legacy concerns, it will follow the standard CLI deprecation timeline before being removed.
W0604 07:03:38.699187       7 server.go:220] WARNING: all flags other than --config, --write-config-to, and --cleanup are deprecated. Please begin using a config file ASAP.
I0604 07:03:38.699736       7 server.go:436] "Kubelet version" kubeletVersion="v1.21.1+k3s1"
W0604 07:03:38.700131       7 proxier.go:653] Failed to read file /lib/modules/5.4.0-66-generic/modules.builtin with error open /lib/modules/5.4.0-66-generic/modules.builtin: no such file or directory. You can ignore this message when kube-proxy is running inside container without mounting /lib/modules
W0604 07:03:38.701013       7 proxier.go:663] Failed to load kernel module ip_vs with modprobe. You can ignore this message when kube-proxy is running inside container without mounting /lib/modules
W0604 07:03:38.701827       7 proxier.go:663] Failed to load kernel module ip_vs_rr with modprobe. You can ignore this message when kube-proxy is running inside container without mounting /lib/modules
W0604 07:03:38.702598       7 proxier.go:663] Failed to load kernel module ip_vs_wrr with modprobe. You can ignore this message when kube-proxy is running inside container without mounting /lib/modules
W0604 07:03:38.703195       7 proxier.go:663] Failed to load kernel module ip_vs_sh with modprobe. You can ignore this message when kube-proxy is running inside container without mounting /lib/modules
W0604 07:03:38.703902       7 proxier.go:663] Failed to load kernel module nf_conntrack with modprobe. You can ignore this message when kube-proxy is running inside container without mounting /lib/modules
time="2021-06-04T07:03:38.705697422Z" level=warning msg="Running modprobe ip_vs failed with message: `modprobe: can't change directory to '5.4.0-66-generic': No such file or directory`, error: exit status 1"
E0604 07:03:38.718837       7 node.go:161] Failed to retrieve node info: nodes "k3d-test2-server-0" is forbidden: User "system:kube-proxy" cannot get resource "nodes" in API group "" at the cluster scope
I0604 07:03:38.731635       7 dynamic_cafile_content.go:167] Starting client-ca-bundle::/var/lib/rancher/k3s/agent/client-ca.crt
E0604 07:03:39.899041       7 node.go:161] Failed to retrieve node info: nodes "k3d-test2-server-0" is forbidden: User "system:kube-proxy" cannot get resource "nodes" in API group "" at the cluster scope
{"level":"warn","ts":"2021-06-04T07:03:40.089Z","caller":"etcdserver/cluster_util.go:315","msg":"failed to reach the peer URL","address":"https://<IP_ADDRESS>:2380/version","remote-member-id":"6cc423fbe5eee33d","error":"Get \"https://<IP_ADDRESS>:2380/version\": dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
{"level":"warn","ts":"2021-06-04T07:03:40.089Z","caller":"etcdserver/cluster_util.go:168","msg":"failed to get version","remote-member-id":"6cc423fbe5eee33d","error":"Get \"https://<IP_ADDRESS>:2380/version\": dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
I0604 07:03:40.504464       7 dynamic_cafile_content.go:167] Starting client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt
I0604 07:03:40.504471       7 dynamic_cafile_content.go:167] Starting request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt
I0604 07:03:40.504736       7 dynamic_serving_content.go:130] Starting serving-cert::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key
I0604 07:03:40.505196       7 secure_serving.go:197] Serving securely on <IP_ADDRESS>:6444
I0604 07:03:40.505234       7 tlsconfig.go:240] Starting DynamicServingCertificateController
I0604 07:03:40.505256       7 available_controller.go:475] Starting AvailableConditionController
I0604 07:03:40.505272       7 cache.go:32] Waiting for caches to sync for AvailableConditionController controller
I0604 07:03:40.505303       7 autoregister_controller.go:141] Starting autoregister controller
I0604 07:03:40.505314       7 cache.go:32] Waiting for caches to sync for autoregister controller
I0604 07:03:40.505347       7 dynamic_serving_content.go:130] Starting aggregator-proxy-cert::/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt::/var/lib/rancher/k3s/server/tls/client-auth-proxy.key
I0604 07:03:40.505381       7 apiservice_controller.go:97] Starting APIServiceRegistrationController
I0604 07:03:40.505429       7 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller
I0604 07:03:40.505542       7 customresource_discovery_controller.go:209] Starting DiscoveryController
I0604 07:03:40.505606       7 controller.go:86] Starting OpenAPI controller
I0604 07:03:40.505670       7 naming_controller.go:291] Starting NamingConditionController
I0604 07:03:40.505720       7 establishing_controller.go:76] Starting EstablishingController
I0604 07:03:40.505765       7 nonstructuralschema_controller.go:192] Starting NonStructuralSchemaConditionController
I0604 07:03:40.505809       7 apiapproval_controller.go:186] Starting KubernetesAPIApprovalPolicyConformantConditionController
I0604 07:03:40.505841       7 crd_finalizer.go:266] Starting CRDFinalizer
I0604 07:03:40.505537       7 apf_controller.go:294] Starting API Priority and Fairness config controller
I0604 07:03:40.505977       7 cluster_authentication_trust_controller.go:440] Starting cluster_authentication_trust_controller controller
I0604 07:03:40.505999       7 shared_informer.go:240] Waiting for caches to sync for cluster_authentication_trust_controller
I0604 07:03:40.506038       7 dynamic_cafile_content.go:167] Starting client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt
I0604 07:03:40.506069       7 dynamic_cafile_content.go:167] Starting request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt
I0604 07:03:40.505256       7 controller.go:83] Starting OpenAPI AggregationController
I0604 07:03:40.507271       7 crdregistration_controller.go:111] Starting crd-autoregister controller
I0604 07:03:40.507378       7 shared_informer.go:240] Waiting for caches to sync for crd-autoregister
time="2021-06-04T07:03:40.523426891Z" level=info msg="Waiting for cloudcontroller rbac role to be created"
I0604 07:03:40.527603       7 controller.go:611] quota admission added evaluator for: namespaces
E0604 07:03:40.535328       7 controller.go:151] Unable to perform initial Kubernetes service initialization: Service "kubernetes" is invalid: spec.clusterIPs: Invalid value: []string{"<IP_ADDRESS>"}: failed to allocated ip:<IP_ADDRESS> with error:cannot allocate resources of type serviceipallocations at this time
E0604 07:03:40.535854       7 controller.go:156] Unable to remove old endpoints from kubernetes service: StorageError: key not found, Code: 1, Key: /registry/masterleases/<IP_ADDRESS>, ResourceVersion: 0, AdditionalErrorMsg:
I0604 07:03:40.565385       7 shared_informer.go:247] Caches are synced for node_authorizer
I0604 07:03:40.605307       7 cache.go:39] Caches are synced for AvailableConditionController controller
I0604 07:03:40.605329       7 cache.go:39] Caches are synced for autoregister controller
I0604 07:03:40.605572       7 cache.go:39] Caches are synced for APIServiceRegistrationController controller
I0604 07:03:40.605915       7 apf_controller.go:299] Running API Priority and Fairness config worker
I0604 07:03:40.606082       7 shared_informer.go:247] Caches are synced for cluster_authentication_trust_controller
I0604 07:03:40.607482       7 shared_informer.go:247] Caches are synced for crd-autoregister
I0604 07:03:41.504509       7 controller.go:132] OpenAPI AggregationController: action for item : Nothing (removed from the queue).
I0604 07:03:41.504558       7 controller.go:132] OpenAPI AggregationController: action for item k8s_internal_local_delegation_chain_0000000000: Nothing (removed from the queue).
I0604 07:03:41.517959       7 storage_scheduling.go:132] created PriorityClass system-node-critical with value<PHONE_NUMBER>
I0604 07:03:41.523466       7 storage_scheduling.go:132] created PriorityClass system-cluster-critical with value<PHONE_NUMBER>
I0604 07:03:41.523576       7 storage_scheduling.go:148] all system priority classes are created successfully or already exist.
I0604 07:03:41.960743       7 controller.go:611] quota admission added evaluator for: roles.rbac.authorization.k8s.io
I0604 07:03:42.000883       7 controller.go:611] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io
W0604 07:03:42.065146       7 lease.go:233] Resetting endpoints for master service "kubernetes" to [<IP_ADDRESS>]
I0604 07:03:42.066572       7 controller.go:611] quota admission added evaluator for: endpoints
I0604 07:03:42.070564       7 controller.go:611] quota admission added evaluator for: endpointslices.discovery.k8s.io
E0604 07:03:42.114219       7 node.go:161] Failed to retrieve node info: nodes "k3d-test2-server-0" not found
time="2021-06-04T07:03:42.527103134Z" level=info msg="Kube API server is now running"
time="2021-06-04T07:03:42.527156713Z" level=info msg="k3s is up and running"
Flag --address has been deprecated, see --bind-address instead.
I0604 07:03:42.533149       7 controllermanager.go:175] Version: v1.21.1+k3s1
I0604 07:03:42.533569       7 deprecated_insecure_serving.go:53] Serving insecurely on <IP_ADDRESS>:10252
time="2021-06-04T07:03:42.535738753Z" level=info msg="Creating CRD addons.k3s.cattle.io"
I0604 07:03:42.535802       7 leaderelection.go:243] attempting to acquire leader lease kube-system/kube-controller-manager...
time="2021-06-04T07:03:42.541004199Z" level=info msg="Creating CRD helmcharts.helm.cattle.io"
time="2021-06-04T07:03:42.554216564Z" level=info msg="Creating CRD helmchartconfigs.helm.cattle.io"
I0604 07:03:42.557563       7 controller.go:611] quota admission added evaluator for: leases.coordination.k8s.io
W0604 07:03:42.558533       7 authorization.go:47] Authorization is disabled
W0604 07:03:42.558553       7 authentication.go:47] Authentication is disabled
I0604 07:03:42.558570       7 deprecated_insecure_serving.go:51] Serving healthz insecurely on <IP_ADDRESS>:10251
I0604 07:03:42.562204       7 leaderelection.go:253] successfully acquired lease kube-system/kube-controller-manager
I0604 07:03:42.562309       7 event.go:291] "Event occurred" object="kube-system/kube-controller-manager" kind="Lease" apiVersion="coordination.k8s.io/v1" type="Normal" reason="LeaderElection" message="k3d-test2-server-0_110dd154-a663-4744-8b5c-5778c7a99679 became leader"
time="2021-06-04T07:03:42.567053020Z" level=info msg="Waiting for CRD addons.k3s.cattle.io to become available"
I0604 07:03:42.659426       7 leaderelection.go:243] attempting to acquire leader lease kube-system/kube-scheduler...
I0604 07:03:42.666224       7 leaderelection.go:253] successfully acquired lease kube-system/kube-scheduler
time="2021-06-04T07:03:42.715858856Z" level=info msg="Waiting for node k3d-test2-server-0: nodes \"k3d-test2-server-0\" not found"
{"level":"warn","ts":"2021-06-04T07:03:42.731Z","caller":"rafthttp/probing_status.go:70","msg":"prober detected unhealthy status","round-tripper-name":"ROUND_TRIPPER_SNAPSHOT","remote-peer-id":"6cc423fbe5eee33d","rtt":"0s","error":"dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
{"level":"warn","ts":"2021-06-04T07:03:42.731Z","caller":"rafthttp/probing_status.go:70","msg":"prober detected unhealthy status","round-tripper-name":"ROUND_TRIPPER_RAFT_MESSAGE","remote-peer-id":"6cc423fbe5eee33d","rtt":"0s","error":"dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
time="2021-06-04T07:03:43.071282702Z" level=info msg="Done waiting for CRD addons.k3s.cattle.io to become available"
time="2021-06-04T07:03:43.071318757Z" level=info msg="Waiting for CRD helmcharts.helm.cattle.io to become available"
I0604 07:03:43.234972       7 shared_informer.go:240] Waiting for caches to sync for tokens
I0604 07:03:43.245109       7 controller.go:611] quota admission added evaluator for: serviceaccounts
I0604 07:03:43.247981       7 controllermanager.go:574] Started "daemonset"
I0604 07:03:43.248051       7 daemon_controller.go:285] Starting daemon sets controller
I0604 07:03:43.248065       7 shared_informer.go:240] Waiting for caches to sync for daemon sets
I0604 07:03:43.257332       7 controllermanager.go:574] Started "replicaset"
I0604 07:03:43.257443       7 replica_set.go:182] Starting replicaset controller
I0604 07:03:43.257461       7 shared_informer.go:240] Waiting for caches to sync for ReplicaSet
I0604 07:03:43.268681       7 controllermanager.go:574] Started "csrapproving"
I0604 07:03:43.268804       7 certificate_controller.go:118] Starting certificate controller "csrapproving"
I0604 07:03:43.268829       7 shared_informer.go:240] Waiting for caches to sync for certificate-csrapproving
I0604 07:03:43.276765       7 controllermanager.go:574] Started "pvc-protection"
I0604 07:03:43.276839       7 pvc_protection_controller.go:110] "Starting PVC protection controller"
I0604 07:03:43.276862       7 shared_informer.go:240] Waiting for caches to sync for PVC protection
I0604 07:03:43.284107       7 controllermanager.go:574] Started "podgc"
I0604 07:03:43.284209       7 gc_controller.go:89] Starting GC controller
I0604 07:03:43.284233       7 shared_informer.go:240] Waiting for caches to sync for GC
I0604 07:03:43.317356       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for controllerrevisions.apps
I0604 07:03:43.317420       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for networkpolicies.networking.k8s.io
I0604 07:03:43.317459       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for roles.rbac.authorization.k8s.io
I0604 07:03:43.317578       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for helmcharts.helm.cattle.io
I0604 07:03:43.317619       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for addons.k3s.cattle.io
I0604 07:03:43.317656       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for rolebindings.rbac.authorization.k8s.io
I0604 07:03:43.317699       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for podtemplates
I0604 07:03:43.317768       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for jobs.batch
I0604 07:03:43.317820       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for statefulsets.apps
I0604 07:03:43.317871       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for csistoragecapacities.storage.k8s.io
I0604 07:03:43.317914       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for events.events.k8s.io
I0604 07:03:43.317947       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for horizontalpodautoscalers.autoscaling
I0604 07:03:43.317982       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for ingresses.extensions
I0604 07:03:43.318029       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for leases.coordination.k8s.io
I0604 07:03:43.318068       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for endpoints
I0604 07:03:43.318102       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for limitranges
I0604 07:03:43.318163       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for serviceaccounts
I0604 07:03:43.318194       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for replicasets.apps
I0604 07:03:43.318253       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for ingresses.networking.k8s.io
I0604 07:03:43.318298       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for poddisruptionbudgets.policy
I0604 07:03:43.318388       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for deployments.apps
I0604 07:03:43.318420       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for daemonsets.apps
I0604 07:03:43.318450       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for cronjobs.batch
I0604 07:03:43.318513       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for endpointslices.discovery.k8s.io
I0604 07:03:43.318554       7 resource_quota_monitor.go:229] QuotaMonitor created object count evaluator for helmchartconfigs.helm.cattle.io
I0604 07:03:43.318581       7 controllermanager.go:574] Started "resourcequota"
I0604 07:03:43.318593       7 resource_quota_controller.go:273] Starting resource quota controller
I0604 07:03:43.318605       7 shared_informer.go:240] Waiting for caches to sync for resource quota
I0604 07:03:43.318628       7 resource_quota_monitor.go:304] QuotaMonitor running
I0604 07:03:43.328459       7 controllermanager.go:574] Started "serviceaccount"
I0604 07:03:43.328523       7 serviceaccounts_controller.go:117] Starting service account controller
I0604 07:03:43.328536       7 shared_informer.go:240] Waiting for caches to sync for service account
I0604 07:03:43.335614       7 shared_informer.go:247] Caches are synced for tokens
I0604 07:03:43.342443       7 garbagecollector.go:142] Starting garbage collector controller
I0604 07:03:43.342461       7 shared_informer.go:240] Waiting for caches to sync for garbage collector
I0604 07:03:43.342500       7 graph_builder.go:289] GraphBuilder running
I0604 07:03:43.342577       7 controllermanager.go:574] Started "garbagecollector"
I0604 07:03:43.439304       7 controllermanager.go:574] Started "ttl"
W0604 07:03:43.439332       7 controllermanager.go:553] "tokencleaner" is disabled
I0604 07:03:43.439387       7 ttl_controller.go:121] Starting TTL controller
I0604 07:03:43.439402       7 shared_informer.go:240] Waiting for caches to sync for TTL
time="2021-06-04T07:03:43.575877931Z" level=info msg="Done waiting for CRD helmcharts.helm.cattle.io to become available"
time="2021-06-04T07:03:43.575925304Z" level=info msg="Waiting for CRD helmchartconfigs.helm.cattle.io to become available"
I0604 07:03:43.592998       7 node_lifecycle_controller.go:377] Sending events to api server.
I0604 07:03:43.594217       7 taint_manager.go:163] "Sending events to api server"
I0604 07:03:43.595010       7 node_lifecycle_controller.go:505] Controller will reconcile labels.
I0604 07:03:43.595074       7 controllermanager.go:574] Started "nodelifecycle"
I0604 07:03:43.595196       7 node_lifecycle_controller.go:539] Starting node controller
I0604 07:03:43.595251       7 shared_informer.go:240] Waiting for caches to sync for taint
time="2021-06-04T07:03:43.695351755Z" level=warning msg="Unable to watch for tunnel endpoints: unknown (get endpoints)"
W0604 07:03:43.740080       7 probe.go:268] Flexvolume plugin directory at /usr/libexec/kubernetes/kubelet-plugins/volume/exec/ does not exist. Recreating.
I0604 07:03:43.740830       7 controllermanager.go:574] Started "attachdetach"
I0604 07:03:43.740908       7 attach_detach_controller.go:327] Starting attach detach controller
I0604 07:03:43.740933       7 shared_informer.go:240] Waiting for caches to sync for attach detach
W0604 07:03:43.768364       7 info.go:53] Couldn't collect info from any of the files in "/etc/machine-id,/var/lib/dbus/machine-id"
I0604 07:03:43.769025       7 server.go:660] "--cgroups-per-qos enabled, but --cgroup-root was not specified.  defaulting to /"
I0604 07:03:43.769236       7 container_manager_linux.go:291] "Container manager verified user specified cgroup-root exists" cgroupRoot=[]
I0604 07:03:43.769316       7 container_manager_linux.go:296] "Creating Container Manager object based on Node Config" nodeConfig={RuntimeCgroupsName:/k3s SystemCgroupsName: KubeletCgroupsName:/k3s ContainerRuntime:remote CgroupsPerQOS:true CgroupRoot:/ CgroupDriver:cgroupfs KubeletRootDir:/var/lib/kubelet ProtectKernelDefaults:false NodeAllocatableConfig:{KubeReservedCgroupName: SystemReservedCgroupName: ReservedSystemCPUs: EnforceNodeAllocatable:map[pods:{}] KubeReserved:map[] SystemReserved:map[] HardEvictionThresholds:[{Signal:imagefs.available Operator:LessThan Value:{Quantity:<nil> Percentage:0.05} GracePeriod:0s MinReclaim:<nil>} {Signal:nodefs.available Operator:LessThan Value:{Quantity:<nil> Percentage:0.05} GracePeriod:0s MinReclaim:<nil>}]} QOSReserved:map[] ExperimentalCPUManagerPolicy:none ExperimentalTopologyManagerScope:container ExperimentalCPUManagerReconcilePeriod:10s ExperimentalMemoryManagerPolicy:None ExperimentalMemoryManagerReservedMemory:[] ExperimentalPodPidsLimit:-1 EnforceCPULimits:false CPUCFSQuotaPeriod:100ms ExperimentalTopologyManagerPolicy:none Rootless:false}
I0604 07:03:43.769358       7 topology_manager.go:120] "Creating topology manager with policy per scope" topologyPolicyName="none" topologyScopeName="container"
I0604 07:03:43.769379       7 container_manager_linux.go:327] "Initializing Topology Manager" policy="none" scope="container"
I0604 07:03:43.769394       7 container_manager_linux.go:332] "Creating device plugin manager" devicePluginEnabled=true
I0604 07:03:43.769585       7 kubelet.go:404] "Attempting to sync node with API server"
I0604 07:03:43.769610       7 kubelet.go:272] "Adding static pod path" path="/var/lib/rancher/k3s/agent/pod-manifests"
I0604 07:03:43.769636       7 kubelet.go:283] "Adding apiserver pod source"
I0604 07:03:43.769658       7 apiserver.go:42] "Waiting for node sync before watching apiserver pods"
I0604 07:03:43.770327       7 kuberuntime_manager.go:222] "Container runtime initialized" containerRuntime="containerd" version="v1.4.4-k3s2" apiVersion="v1alpha2"
I0604 07:03:43.770663       7 server.go:1191] "Started kubelet"
I0604 07:03:43.770835       7 server.go:149] "Starting to listen" address="<IP_ADDRESS>" port=10250
E0604 07:03:43.771211       7 cri_stats_provider.go:369] "Failed to get the info of the filesystem with mountpoint" err="unable to find data in memory cache" mountpoint="/var/lib/rancher/k3s/agent/containerd/io.containerd.snapshotter.v1.overlayfs"
E0604 07:03:43.771279       7 kubelet.go:1306] "Image garbage collection failed once. Stats initialization may not have completed yet" err="invalid capacity 0 on image filesystem"
I0604 07:03:43.771465       7 fs_resource_analyzer.go:67] "Starting FS ResourceAnalyzer"
I0604 07:03:43.771582       7 volume_manager.go:271] "Starting Kubelet Volume Manager"
I0604 07:03:43.771672       7 desired_state_of_world_populator.go:141] "Desired state populator starts to run"
I0604 07:03:43.773043       7 server.go:405] "Adding debug handlers to kubelet server"
I0604 07:03:43.782883       7 cpu_manager.go:199] "Starting CPU manager" policy="none"
I0604 07:03:43.782909       7 cpu_manager.go:200] "Reconciling" reconcilePeriod="10s"
I0604 07:03:43.782936       7 state_mem.go:36] "Initialized new in-memory state store"
I0604 07:03:43.785082       7 policy_none.go:44] "None policy: Start"
E0604 07:03:43.787060       7 nodelease.go:49] "Failed to get node when trying to set owner ref to the node lease" err="nodes \"k3d-test2-server-0\" not found" node="k3d-test2-server-0"
W0604 07:03:43.813207       7 container.go:586] Failed to update stats for container "/kubepods": /sys/fs/cgroup/cpuset/kubepods/cpuset.mems found to be empty, continuing to push stats
W0604 07:03:43.816357       7 container.go:586] Failed to update stats for container "/kubepods/burstable": /sys/fs/cgroup/cpuset/kubepods/burstable/cpuset.mems found to be empty, continuing to push stats
I0604 07:03:43.819366       7 manager.go:600] "Failed to retrieve checkpoint" checkpoint="kubelet_internal_checkpoint" err="checkpoint is not found"
I0604 07:03:43.819655       7 plugin_manager.go:114] "Starting Kubelet Plugin Manager"
E0604 07:03:43.820068       7 eviction_manager.go:255] "Eviction manager: failed to get summary stats" err="failed to get node info: node \"k3d-test2-server-0\" not found"
E0604 07:03:43.872023       7 kubelet.go:2291] "Error getting node" err="node \"k3d-test2-server-0\" not found"
I0604 07:03:43.873299       7 kubelet_node_status.go:71] "Attempting to register node" node="k3d-test2-server-0"
I0604 07:03:43.889706       7 controllermanager.go:574] Started "endpointslicemirroring"
I0604 07:03:43.889759       7 endpointslicemirroring_controller.go:211] Starting EndpointSliceMirroring controller
I0604 07:03:43.889770       7 shared_informer.go:240] Waiting for caches to sync for endpoint_slice_mirroring
E0604 07:03:43.972094       7 kubelet.go:2291] "Error getting node" err="node \"k3d-test2-server-0\" not found"
I0604 07:03:43.976011       7 kubelet_node_status.go:74] "Successfully registered node" node="k3d-test2-server-0"
I0604 07:03:44.039947       7 controllermanager.go:574] Started "ttl-after-finished"
I0604 07:03:44.039990       7 ttlafterfinished_controller.go:109] Starting TTL after finished controller
I0604 07:03:44.040019       7 shared_informer.go:240] Waiting for caches to sync for TTL after finished
time="2021-06-04T07:03:44.079573715Z" level=info msg="Done waiting for CRD helmchartconfigs.helm.cattle.io to become available"
{"level":"warn","ts":"2021-06-04T07:03:44.090Z","caller":"etcdserver/cluster_util.go:315","msg":"failed to reach the peer URL","address":"https://<IP_ADDRESS>:2380/version","remote-member-id":"6cc423fbe5eee33d","error":"Get \"https://<IP_ADDRESS>:2380/version\": dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
{"level":"warn","ts":"2021-06-04T07:03:44.090Z","caller":"etcdserver/cluster_util.go:168","msg":"failed to get version","remote-member-id":"6cc423fbe5eee33d","error":"Get \"https://<IP_ADDRESS>:2380/version\": dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
time="2021-06-04T07:03:44.096990411Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-9.18.2.tgz"
time="2021-06-04T07:03:44.097391956Z" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-crd-9.18.2.tgz"
time="2021-06-04T07:03:44.135485501Z" level=info msg="Failed to get existing traefik HelmChart" error="helmcharts.helm.cattle.io \"traefik\" not found"
time="2021-06-04T07:03:44.135646543Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/metrics-apiservice.yaml"
time="2021-06-04T07:03:44.135753052Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/metrics-server-deployment.yaml"
time="2021-06-04T07:03:44.135848076Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml"
time="2021-06-04T07:03:44.135935636Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/traefik.yaml"
time="2021-06-04T07:03:44.136070759Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml"
time="2021-06-04T07:03:44.136156587Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/auth-delegator.yaml"
time="2021-06-04T07:03:44.136258136Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/auth-reader.yaml"
time="2021-06-04T07:03:44.136330841Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/metrics-server-service.yaml"
time="2021-06-04T07:03:44.136405050Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/resource-reader.yaml"
time="2021-06-04T07:03:44.136483466Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml"
time="2021-06-04T07:03:44.136604906Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/local-storage.yaml"
time="2021-06-04T07:03:44.136679629Z" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/aggregated-metrics-reader.yaml"
I0604 07:03:44.191658       7 controllermanager.go:574] Started "statefulset"
I0604 07:03:44.191685       7 stateful_set.go:146] Starting stateful set controller
I0604 07:03:44.191700       7 shared_informer.go:240] Waiting for caches to sync for stateful set
I0604 07:03:44.237059       7 leaderelection.go:243] attempting to acquire leader lease kube-system/k3s...
time="2021-06-04T07:03:44.237058622Z" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller"
time="2021-06-04T07:03:44.237164371Z" level=info msg="Starting /v1, Kind=Node controller"
time="2021-06-04T07:03:44.243998049Z" level=info msg="Cluster dns configmap has been set successfully"
I0604 07:03:44.244830       7 leaderelection.go:253] successfully acquired lease kube-system/k3s
I0604 07:03:44.263222       7 controller.go:611] quota admission added evaluator for: addons.k3s.cattle.io
I0604 07:03:44.313523       7 controller.go:611] quota admission added evaluator for: deployments.apps
I0604 07:03:44.340434       7 controllermanager.go:574] Started "cronjob"
I0604 07:03:44.340503       7 cronjob_controllerv2.go:125] Starting cronjob controller v2
I0604 07:03:44.340521       7 shared_informer.go:240] Waiting for caches to sync for cronjob
I0604 07:03:44.390102       7 certificate_controller.go:118] Starting certificate controller "csrsigning-kubelet-serving"
I0604 07:03:44.390132       7 shared_informer.go:240] Waiting for caches to sync for certificate-csrsigning-kubelet-serving
I0604 07:03:44.390176       7 dynamic_serving_content.go:130] Starting csr-controller::/var/lib/rancher/k3s/server/tls/server-ca.crt::/var/lib/rancher/k3s/server/tls/server-ca.key
I0604 07:03:44.390600       7 certificate_controller.go:118] Starting certificate controller "csrsigning-kubelet-client"
I0604 07:03:44.390617       7 shared_informer.go:240] Waiting for caches to sync for certificate-csrsigning-kubelet-client
I0604 07:03:44.390636       7 dynamic_serving_content.go:130] Starting csr-controller::/var/lib/rancher/k3s/server/tls/client-ca.crt::/var/lib/rancher/k3s/server/tls/client-ca.key
I0604 07:03:44.391401       7 certificate_controller.go:118] Starting certificate controller "csrsigning-kube-apiserver-client"
I0604 07:03:44.391434       7 shared_informer.go:240] Waiting for caches to sync for certificate-csrsigning-kube-apiserver-client
I0604 07:03:44.391476       7 dynamic_serving_content.go:130] Starting csr-controller::/var/lib/rancher/k3s/server/tls/client-ca.crt::/var/lib/rancher/k3s/server/tls/client-ca.key
I0604 07:03:44.391934       7 controllermanager.go:574] Started "csrsigning"
W0604 07:03:44.391956       7 controllermanager.go:553] "service" is disabled
I0604 07:03:44.392007       7 certificate_controller.go:118] Starting certificate controller "csrsigning-legacy-unknown"
I0604 07:03:44.392019       7 shared_informer.go:240] Waiting for caches to sync for certificate-csrsigning-legacy-unknown
I0604 07:03:44.392040       7 dynamic_serving_content.go:130] Starting csr-controller::/var/lib/rancher/k3s/server/tls/client-ca.crt::/var/lib/rancher/k3s/server/tls/client-ca.key
I0604 07:03:44.540026       7 controllermanager.go:574] Started "endpointslice"
W0604 07:03:44.540048       7 controllermanager.go:553] "cloud-node-lifecycle" is disabled
I0604 07:03:44.540084       7 endpointslice_controller.go:256] Starting endpoint slice controller
I0604 07:03:44.540091       7 shared_informer.go:240] Waiting for caches to sync for endpoint_slice
I0604 07:03:44.547855       7 controller.go:611] quota admission added evaluator for: helmcharts.helm.cattle.io
I0604 07:03:44.660541       7 kubelet_network_linux.go:56] "Initialized protocol iptables rules." protocol=IPv4
E0604 07:03:44.662004       7 kubelet_network_linux.go:79] "Failed to ensure that nat chain exists KUBE-MARK-DROP chain" err="error creating chain \"KUBE-MARK-DROP\": exit status 3: ip6tables v1.8.5 (legacy): can't initialize ip6tables table `nat': Table does not exist (do you need to insmod?)\nPerhaps ip6tables or your kernel needs to be upgraded.\n"
I0604 07:03:44.662036       7 kubelet_network_linux.go:64] "Failed to initialize protocol iptables rules; some functionality may be missing." protocol=IPv6
I0604 07:03:44.662061       7 status_manager.go:157] "Starting to sync pod status with apiserver"
I0604 07:03:44.662088       7 kubelet.go:1846] "Starting kubelet main sync loop"
E0604 07:03:44.662172       7 kubelet.go:1870] "Skipping pod synchronization" err="PLEG is not healthy: pleg has yet to be successful"
I0604 07:03:44.693153       7 controllermanager.go:574] Started "pv-protection"
I0604 07:03:44.693229       7 pv_protection_controller.go:83] Starting PV protection controller
I0604 07:03:44.693251       7 shared_informer.go:240] Waiting for caches to sync for PV protection
time="2021-06-04T07:03:44.721143406Z" level=info msg="Waiting for node k3d-test2-server-0 CIDR not assigned yet"
I0604 07:03:44.769779       7 apiserver.go:52] "Watching apiserver"
I0604 07:03:44.889895       7 controllermanager.go:574] Started "disruption"
I0604 07:03:44.889965       7 disruption.go:363] Starting disruption controller
I0604 07:03:44.889976       7 shared_informer.go:240] Waiting for caches to sync for disruption
time="2021-06-04T07:03:44.947247527Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChartConfig controller"
time="2021-06-04T07:03:44.947283390Z" level=info msg="Starting /v1, Kind=Pod controller"
time="2021-06-04T07:03:44.947283486Z" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller"
time="2021-06-04T07:03:44.947320993Z" level=info msg="Starting batch/v1, Kind=Job controller"
time="2021-06-04T07:03:44.947311373Z" level=info msg="Starting /v1, Kind=Service controller"
time="2021-06-04T07:03:44.947320101Z" level=info msg="Starting /v1, Kind=Endpoints controller"
I0604 07:03:44.979304       7 controller.go:611] quota admission added evaluator for: jobs.batch
I0604 07:03:45.040496       7 controllermanager.go:574] Started "job"
I0604 07:03:45.040535       7 job_controller.go:150] Starting job controller
I0604 07:03:45.040557       7 shared_informer.go:240] Waiting for caches to sync for job
I0604 07:03:45.076207       7 reconciler.go:157] "Reconciler: start to sync state"
time="2021-06-04T07:03:45.143455451Z" level=error msg="No InternalIP found for node "
I0604 07:03:45.190751       7 controllermanager.go:574] Started "persistentvolume-binder"
I0604 07:03:45.190793       7 pv_controller_base.go:308] Starting persistent volume controller
I0604 07:03:45.190816       7 shared_informer.go:240] Waiting for caches to sync for persistent volume
I0604 07:03:45.340118       7 controllermanager.go:574] Started "replicationcontroller"
W0604 07:03:45.340145       7 controllermanager.go:553] "route" is disabled
I0604 07:03:45.340227       7 replica_set.go:182] Starting replicationcontroller controller
I0604 07:03:45.340258       7 shared_informer.go:240] Waiting for caches to sync for ReplicationController
I0604 07:03:45.491284       7 controllermanager.go:574] Started "persistentvolume-expander"
I0604 07:03:45.491406       7 expand_controller.go:327] Starting expand controller
I0604 07:03:45.491423       7 shared_informer.go:240] Waiting for caches to sync for expand
time="2021-06-04T07:03:45.531474803Z" level=info msg="Running cloud-controller-manager with args --profiling=false"
I0604 07:03:45.540325       7 controllermanager.go:142] Version: v1.21.1+k3s1
I0604 07:03:45.546707       7 leaderelection.go:243] attempting to acquire leader lease kube-system/cloud-controller-manager...
I0604 07:03:45.567135       7 leaderelection.go:253] successfully acquired lease kube-system/cloud-controller-manager
I0604 07:03:45.567177       7 event.go:291] "Event occurred" object="kube-system/cloud-controller-manager" kind="Lease" apiVersion="coordination.k8s.io/v1" type="Normal" reason="LeaderElection" message="k3d-test2-server-0_786b4aff-79f6-4dd6-8593-de94cc07fd31 became leader"
I0604 07:03:45.641538       7 controllermanager.go:574] Started "root-ca-cert-publisher"
I0604 07:03:45.641590       7 publisher.go:102] Starting root CA certificate configmap publisher
I0604 07:03:45.641610       7 shared_informer.go:240] Waiting for caches to sync for crt configmap
time="2021-06-04T07:03:45.742540560Z" level=info msg="Updated coredns node hosts entry [<IP_ADDRESS> k3d-test2-server-0]"
I0604 07:03:45.939243       7 controllermanager.go:574] Started "horizontalpodautoscaling"
I0604 07:03:45.939293       7 horizontal.go:169] Starting HPA controller
I0604 07:03:45.939316       7 shared_informer.go:240] Waiting for caches to sync for HPA
I0604 07:03:46.092141       7 controllermanager.go:574] Started "deployment"
I0604 07:03:46.092227       7 deployment_controller.go:153] "Starting controller" controller="deployment"
I0604 07:03:46.092247       7 shared_informer.go:240] Waiting for caches to sync for deployment
I0604 07:03:46.140353       7 controllermanager.go:574] Started "csrcleaner"
I0604 07:03:46.140459       7 cleaner.go:82] Starting CSR cleaner controller
I0604 07:03:46.190658       7 node_ipam_controller.go:91] Sending events to api server.
W0604 07:03:46.310737       7 handler_proxy.go:102] no RequestInfo found in the context
E0604 07:03:46.310840       7 controller.go:116] loading OpenAPI spec for "v1beta1.metrics.k8s.io" failed with: failed to retrieve openAPI spec, http error: ResponseCode: 503, Body: service unavailable
, Header: map[Content-Type:[text/plain; charset=utf-8] X-Content-Type-Options:[nosniff]]
I0604 07:03:46.310857       7 controller.go:129] OpenAPI AggregationController: action for item v1beta1.metrics.k8s.io: Rate Limited Requeue.
I0604 07:03:46.345076       7 node.go:172] Successfully retrieved node IP: <IP_ADDRESS>
I0604 07:03:46.345110       7 server_others.go:141] Detected node IP <IP_ADDRESS>
W0604 07:03:46.348404       7 server_others.go:198] No iptables support for IPv6: exit status 3
I0604 07:03:46.348436       7 server_others.go:209] kube-proxy running in single-stack IPv4 mode
I0604 07:03:46.348470       7 server_others.go:213] Using iptables Proxier.
I0604 07:03:46.348905       7 server.go:643] Version: v1.21.1+k3s1
I0604 07:03:46.349838       7 config.go:315] Starting service config controller
I0604 07:03:46.349871       7 shared_informer.go:240] Waiting for caches to sync for service config
I0604 07:03:46.349947       7 config.go:224] Starting endpoint slice config controller
I0604 07:03:46.349972       7 shared_informer.go:240] Waiting for caches to sync for endpoint slice config
I0604 07:03:46.450354       7 shared_informer.go:247] Caches are synced for endpoint slice config
I0604 07:03:46.450395       7 shared_informer.go:247] Caches are synced for service config
time="2021-06-04T07:03:46.731812635Z" level=info msg="Waiting for node k3d-test2-server-0 CIDR not assigned yet"
time="2021-06-04T07:03:46.841990615Z" level=info msg="Starting /v1, Kind=Secret controller"
{"level":"warn","ts":"2021-06-04T07:03:47.090Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-7339f2ec-8b74-411c-9d2a-60eb217b9046/<IP_ADDRESS>:2379","attempt":0,"error":"rpc error: code = FailedPrecondition desc = etcdserver: can only promote a learner member which is in sync with leader"}
time="2021-06-04T07:03:47.140874573Z" level=info msg="Active TLS secret k3s-serving (ver=389) (count 9): map[listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-<IP_ADDRESS>:<IP_ADDRESS> listener.cattle.io/cn-k3d-test2-server-0:k3d-test2-server-0 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-localhost:localhost listener.cattle.io/fingerprint:SHA1=26C30BB4080BB3DB141C45477537C1E591399436]"
I0604 07:03:47.424931       7 request.go:668] Waited for 1.047462022s due to client-side throttling, not priority and fairness, request: GET:https://<IP_ADDRESS>:6444/apis/apiextensions.k8s.io/v1?timeout=32s
{"level":"warn","ts":"2021-06-04T07:03:47.731Z","caller":"rafthttp/probing_status.go:70","msg":"prober detected unhealthy status","round-tripper-name":"ROUND_TRIPPER_RAFT_MESSAGE","remote-peer-id":"6cc423fbe5eee33d","rtt":"0s","error":"dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
{"level":"warn","ts":"2021-06-04T07:03:47.731Z","caller":"rafthttp/probing_status.go:70","msg":"prober detected unhealthy status","round-tripper-name":"ROUND_TRIPPER_SNAPSHOT","remote-peer-id":"6cc423fbe5eee33d","rtt":"0s","error":"dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
{"level":"warn","ts":"2021-06-04T07:03:48.091Z","caller":"etcdserver/cluster_util.go:315","msg":"failed to reach the peer URL","address":"https://<IP_ADDRESS>:2380/version","remote-member-id":"6cc423fbe5eee33d","error":"Get \"https://<IP_ADDRESS>:2380/version\": dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
{"level":"warn","ts":"2021-06-04T07:03:48.091Z","caller":"etcdserver/cluster_util.go:168","msg":"failed to get version","remote-member-id":"6cc423fbe5eee33d","error":"Get \"https://<IP_ADDRESS>:2380/version\": dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
E0604 07:03:48.477195       7 controllermanager.go:418] unable to get all supported resources from server: unable to retrieve the complete list of server APIs: metrics.k8s.io/v1beta1: the server is currently unable to handle the request
I0604 07:03:48.480530       7 node_controller.go:115] Sending events to api server.
I0604 07:03:48.480668       7 controllermanager.go:285] Started "cloud-node"
I0604 07:03:48.480719       7 node_controller.go:154] Waiting for informer caches to sync
I0604 07:03:48.483718       7 node_lifecycle_controller.go:76] Sending events to api server
I0604 07:03:48.483770       7 controllermanager.go:285] Started "cloud-node-lifecycle"
I0604 07:03:48.581871       7 node_controller.go:390] Initializing node k3d-test2-server-0 with cloud provider
time="2021-06-04T07:03:48.581932410Z" level=info msg="Couldn't find node internal ip annotation or label on node k3d-test2-server-0"
time="2021-06-04T07:03:48.581997850Z" level=info msg="Couldn't find node hostname annotation or label on node k3d-test2-server-0"
time="2021-06-04T07:03:48.586499764Z" level=info msg="Couldn't find node internal ip annotation or label on node k3d-test2-server-0"
time="2021-06-04T07:03:48.586543857Z" level=info msg="Couldn't find node hostname annotation or label on node k3d-test2-server-0"
I0604 07:03:48.590768       7 node_controller.go:454] Successfully initialized node k3d-test2-server-0 with cloud provider
I0604 07:03:48.590909       7 event.go:291] "Event occurred" object="k3d-test2-server-0" kind="Node" apiVersion="v1" type="Normal" reason="Synced" message="Node synced successfully"
time="2021-06-04T07:03:48.698693124Z" level=info msg="Stopped tunnel to <IP_ADDRESS>:6443"
time="2021-06-04T07:03:48.698741457Z" level=info msg="Proxy done" err="context canceled" url="wss://<IP_ADDRESS>:6443/v1-k3s/connect"
time="2021-06-04T07:03:48.698766853Z" level=info msg="Connecting to proxy" url="wss://<IP_ADDRESS>:6443/v1-k3s/connect"
time="2021-06-04T07:03:48.698867965Z" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF"
time="2021-06-04T07:03:48.703631958Z" level=info msg="Handling backend connection request [k3d-test2-server-0]"
time="2021-06-04T07:03:48.743642654Z" level=info msg="Waiting for node k3d-test2-server-0 CIDR not assigned yet"
time="2021-06-04T07:03:50.748633817Z" level=info msg="Waiting for node k3d-test2-server-0 CIDR not assigned yet"
{"level":"warn","ts":"2021-06-04T07:03:52.092Z","caller":"etcdserver/cluster_util.go:315","msg":"failed to reach the peer URL","address":"https://<IP_ADDRESS>:2380/version","remote-member-id":"6cc423fbe5eee33d","error":"Get \"https://<IP_ADDRESS>:2380/version\": dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
{"level":"warn","ts":"2021-06-04T07:03:52.092Z","caller":"etcdserver/cluster_util.go:168","msg":"failed to get version","remote-member-id":"6cc423fbe5eee33d","error":"Get \"https://<IP_ADDRESS>:2380/version\": dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
{"level":"warn","ts":"2021-06-04T07:03:52.732Z","caller":"rafthttp/probing_status.go:70","msg":"prober detected unhealthy status","round-tripper-name":"ROUND_TRIPPER_RAFT_MESSAGE","remote-peer-id":"6cc423fbe5eee33d","rtt":"0s","error":"dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
{"level":"warn","ts":"2021-06-04T07:03:52.732Z","caller":"rafthttp/probing_status.go:70","msg":"prober detected unhealthy status","round-tripper-name":"ROUND_TRIPPER_SNAPSHOT","remote-peer-id":"6cc423fbe5eee33d","rtt":"0s","error":"dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
time="2021-06-04T07:03:52.759861533Z" level=info msg="Waiting for node k3d-test2-server-0 CIDR not assigned yet"
E0604 07:03:53.828106       7 cadvisor_stats_provider.go:415] "Partial failure issuing cadvisor.ContainerInfoV2" err="partial failures: [\"/kubepods\": RecentStats: unable to find data in memory cache], [\"/kubepods/burstable\": RecentStats: unable to find data in memory cache]"
time="2021-06-04T07:03:54.767969167Z" level=info msg="Waiting for node k3d-test2-server-0 CIDR not assigned yet"
{"level":"warn","ts":"2021-06-04T07:03:56.093Z","caller":"etcdserver/cluster_util.go:315","msg":"failed to reach the peer URL","address":"https://<IP_ADDRESS>:2380/version","remote-member-id":"6cc423fbe5eee33d","error":"Get \"https://<IP_ADDRESS>:2380/version\": dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
{"level":"warn","ts":"2021-06-04T07:03:56.093Z","caller":"etcdserver/cluster_util.go:168","msg":"failed to get version","remote-member-id":"6cc423fbe5eee33d","error":"Get \"https://<IP_ADDRESS>:2380/version\": dial tcp <IP_ADDRESS>:2380: connect: connection refused"}
I0604 07:03:56.225642       7 range_allocator.go:82] Sending events to api server.
I0604 07:03:56.225817       7 range_allocator.go:110] No Service CIDR provided. Skipping filtering out service addresses.
I0604 07:03:56.225834       7 range_allocator.go:116] No Secondary Service CIDR provided. Skipping filtering out secondary service addresses.
I0604 07:03:56.225870       7 controllermanager.go:574] Started "nodeipam"
I0604 07:03:56.225973       7 node_ipam_controller.go:154] Starting ipam controller
I0604 07:03:56.225996       7 shared_informer.go:240] Waiting for caches to sync for node
I0604 07:03:56.235716       7 controllermanager.go:574] Started "clusterrole-aggregation"
I0604 07:03:56.235879       7 clusterroleaggregation_controller.go:194] Starting ClusterRoleAggregator
I0604 07:03:56.235901       7 shared_informer.go:240] Waiting for caches to sync for ClusterRoleAggregator
E0604 07:03:56.267930       7 namespaced_resources_deleter.go:161] unable to get all supported resources from server: unable to retrieve the complete list of server APIs: metrics.k8s.io/v1beta1: the server is currently unable to handle the request
I0604 07:03:56.268065       7 controllermanager.go:574] Started "namespace"
W0604 07:03:56.268087       7 controllermanager.go:553] "bootstrapsigner" is disabled
I0604 07:03:56.268189       7 namespace_controller.go:200] Starting namespace controller
I0604 07:03:56.268219       7 shared_informer.go:240] Waiting for caches to sync for namespace
I0604 07:03:56.276718       7 controllermanager.go:574] Started "ephemeral-volume"
I0604 07:03:56.276815       7 controller.go:170] Starting ephemeral volume controller
I0604 07:03:56.276832       7 shared_informer.go:240] Waiting for caches to sync for ephemeral
I0604 07:03:56.286709       7 controllermanager.go:574] Started "endpoint"
I0604 07:03:56.287247       7 shared_informer.go:240] Waiting for caches to sync for resource quota
I0604 07:03:56.287783       7 endpoints_controller.go:189] Starting endpoint controller
I0604 07:03:56.287812       7 shared_informer.go:240] Waiting for caches to sync for endpoint
I0604 07:03:56.292133       7 shared_informer.go:247] Caches are synced for certificate-csrsigning-legacy-unknown
I0604 07:03:56.292680       7 shared_informer.go:247] Caches are synced for certificate-csrsigning-kube-apiserver-client
W0604 07:03:56.297764       7 actual_state_of_world.go:534] Failed to update statusUpdateNeeded field in actual state of world: Failed to set statusUpdateNeeded to needed true, because nodeName="k3d-test2-server-0" does not exist
E0604 07:03:56.305044       7 memcache.go:196] couldn't get resource list for metrics.k8s.io/v1beta1: the server is currently unable to handle the request
E0604 07:03:56.306897       7 memcache.go:101] couldn't get resource list for metrics.k8s.io/v1beta1: the server is currently unable to handle the request
I0604 07:03:56.309989       7 shared_informer.go:240] Waiting for caches to sync for garbage collector
I0604 07:03:56.326678       7 shared_informer.go:247] Caches are synced for node
I0604 07:03:56.326717       7 range_allocator.go:172] Starting range CIDR allocator
I0604 07:03:56.326725       7 shared_informer.go:240] Waiting for caches to sync for cidrallocator
I0604 07:03:56.326739       7 shared_informer.go:247] Caches are synced for cidrallocator
I0604 07:03:56.329025       7 shared_informer.go:247] Caches are synced for service account
I0604 07:03:56.331390       7 range_allocator.go:373] Set node k3d-test2-server-0 PodCIDR to [<IP_ADDRESS>/24]
I0604 07:03:56.336553       7 shared_informer.go:247] Caches are synced for ClusterRoleAggregator
I0604 07:03:56.337236       7 kuberuntime_manager.go:1044] "Updating runtime config through cri with podcidr" CIDR="<IP_ADDRESS>/24"
I0604 07:03:56.337758       7 kubelet_network.go:76] "Updating Pod CIDR" originalPodCIDR="" newPodCIDR="<IP_ADDRESS>/24"
I0604 07:03:56.339442       7 shared_informer.go:247] Caches are synced for TTL
I0604 07:03:56.340442       7 shared_informer.go:247] Caches are synced for endpoint_slice
I0604 07:03:56.340458       7 shared_informer.go:247] Caches are synced for ReplicationController
I0604 07:03:56.341000       7 shared_informer.go:247] Caches are synced for attach detach
I0604 07:03:56.341972       7 shared_informer.go:247] Caches are synced for crt configmap
I0604 07:03:56.348226       7 shared_informer.go:247] Caches are synced for daemon sets
I0604 07:03:56.357503       7 shared_informer.go:247] Caches are synced for ReplicaSet
I0604 07:03:56.368295       7 shared_informer.go:247] Caches are synced for namespace
I0604 07:03:56.368876       7 shared_informer.go:247] Caches are synced for certificate-csrapproving
I0604 07:03:56.377848       7 shared_informer.go:247] Caches are synced for ephemeral
I0604 07:03:56.377882       7 shared_informer.go:247] Caches are synced for PVC protection
I0604 07:03:56.385129       7 shared_informer.go:247] Caches are synced for GC
I0604 07:03:56.390036       7 shared_informer.go:247] Caches are synced for disruption
I0604 07:03:56.390059       7 disruption.go:371] Sending events to api server.
I0604 07:03:56.390245       7 shared_informer.go:247] Caches are synced for certificate-csrsigning-kubelet-serving
I0604 07:03:56.391472       7 shared_informer.go:247] Caches are synced for expand
I0604 07:03:56.391485       7 shared_informer.go:247] Caches are synced for certificate-csrsigning-kubelet-client
I0604 07:03:56.391538       7 shared_informer.go:247] Caches are synced for persistent volume
I0604 07:03:56.392690       7 shared_informer.go:247] Caches are synced for deployment
I0604 07:03:56.392701       7 shared_informer.go:247] Caches are synced for stateful set
I0604 07:03:56.393308       7 shared_informer.go:247] Caches are synced for PV protection
I0604 07:03:56.395357       7 shared_informer.go:247] Caches are synced for taint
I0604 07:03:56.395459       7 node_lifecycle_controller.go:1398] Initializing eviction metric for zone:
I0604 07:03:56.395543       7 event.go:291] "Event occurred" object="k3d-test2-server-0" kind="Node" apiVersion="v1" type="Normal" reason="RegisteredNode" message="Node k3d-test2-server-0 event: Registered Node k3d-test2-server-0 in Controller"
W0604 07:03:56.395543       7 node_lifecycle_controller.go:1013] Missing timestamp for Node k3d-test2-server-0. Assuming now as a timestamp.
I0604 07:03:56.395610       7 node_lifecycle_controller.go:1214] Controller detected that zone  is now in state Normal.
I0604 07:03:56.395463       7 taint_manager.go:187] "Starting NoExecuteTaintManager"
I0604 07:03:56.407769       7 controller.go:611] quota admission added evaluator for: replicasets.apps
I0604 07:03:56.409959       7 event.go:291] "Event occurred" object="kube-system/metrics-server" kind="Deployment" apiVersion="apps/v1" type="Normal" reason="ScalingReplicaSet" message="Scaled up replica set metrics-server-86cbb8457f to 1"
I0604 07:03:56.412142       7 event.go:291] "Event occurred" object="kube-system/local-path-provisioner" kind="Deployment" apiVersion="apps/v1" type="Normal" reason="ScalingReplicaSet" message="Scaled up replica set local-path-provisioner-5ff76fc89d to 1"
I0604 07:03:56.412237       7 event.go:291] "Event occurred" object="kube-system/coredns" kind="Deployment" apiVersion="apps/v1" type="Normal" reason="ScalingReplicaSet" message="Scaled up replica set coredns-7448499f4d to 1"
I0604 07:03:56.429056       7 event.go:291] "Event occurred" object="kube-system/local-path-provisioner-5ff76fc89d" kind="ReplicaSet" apiVersion="apps/v1" type="Normal" reason="SuccessfulCreate" message="Created pod: local-path-provisioner-5ff76fc89d-8mf74"
I0604 07:03:56.438104       7 topology_manager.go:187] "Topology Admit Handler"
I0604 07:03:56.438159       7 event.go:291] "Event occurred" object="kube-system/metrics-server-86cbb8457f" kind="ReplicaSet" apiVersion="apps/v1" type="Normal" reason="SuccessfulCreate" message="Created pod: metrics-server-86cbb8457f-dsx9d"
I0604 07:03:56.438459       7 event.go:291] "Event occurred" object="kube-system/coredns-7448499f4d" kind="ReplicaSet" apiVersion="apps/v1" type="Normal" reason="SuccessfulCreate" message="Created pod: coredns-7448499f4d-4scpk"
I0604 07:03:56.440790       7 shared_informer.go:247] Caches are synced for HPA
I0604 07:03:56.442450       7 controller.go:611] quota admission added evaluator for: events.events.k8s.io
I0604 07:03:56.442469       7 topology_manager.go:187] "Topology Admit Handler"
I0604 07:03:56.443415       7 topology_manager.go:187] "Topology Admit Handler"