search

k3s-io / k3s

Lightweight Kubernetes
https://k3s.io
Apache License 2.0
27.83k stars 2.33k forks source link

k3s fails to to start, systemd keeps restarting it #6262

Closed swoutch closed 1 year ago

swoutch commented 2 years ago

Environmental Info: K3s Version: 

k3s version v1.24.6+k3s1 (a8e0c66d)
go version go1.18.6

Node(s) CPU architecture, OS, and Version: 

Linux linux.0e9675.com 4.19.0 #1 SMP Thu Sep 23 18:26:47 MSK 2021 x86_64 GNU/Linux

Cluster Configuration: Single node

Describe the bug: The node is stuck in NotReady state:

$ k3s kubectl get nodes
NAME               STATUS     ROLES                  AGE   VERSION
linux.0e9675.com   NotReady   control-plane,master   35m   v1.24.6+k3s1

The k3s service keeps restarting:

$ journalctl -u k3s
...
Oct 12 08:37:11 linux.0e9675.com systemd[1]: k3s.service: Scheduled restart job, restart counter is at 88.
...

Steps To Reproduce:

Actual behavior: The node is never ready. The k3s service fails to start, and systemd keeps restarting it.

Additional context / logs: Here are the full logs:

$ journalctl -u k3s
Oct 12 08:02:54 linux.0e9675.com systemd[1]: Starting Lightweight Kubernetes...
Oct 12 08:02:54 linux.0e9675.com sh[199557]: + /usr/bin/systemctl is-enabled --quiet nm-cloud-setup.service
Oct 12 08:02:54 linux.0e9675.com sh[199558]: /bin/sh: 1: /usr/bin/systemctl: not found
Oct 12 08:02:54 linux.0e9675.com modprobe[199559]: modprobe: FATAL: Module br_netfilter not found in directory /lib/modules/4.19.0
Oct 12 08:02:54 linux.0e9675.com modprobe[199560]: modprobe: FATAL: Module overlay not found in directory /lib/modules/4.19.0
Oct 12 08:02:54 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:54+01:00" level=info msg="Acquiring lock file /var/lib/rancher/k3s/data/.lock"
Oct 12 08:02:54 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:54+01:00" level=info msg="Preparing data dir /var/lib/rancher/k3s/data/ec00304416df58a8da2a883b1b87ab882b199ef11c4e01b28f07d643c8067d91"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="Starting k3s v1.24.6+k3s1 (a8e0c66d)"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="Configuring sqlite3 database connection pooling: maxIdleConns=2, maxOpenConns=0, connMaxLifetime=0s"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="Configuring database table schema and indexes, this may take a moment..."
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="Database tables and indexes are up to date"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="Kine available at unix://kine.sock"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="generated self-signed CA certificate CN=k3s-client-ca@1665558179: notBefore=2022-10-12 07:02:59.582091715 +0000 UTC notAfter=2032-10-09 07:02:59.582091715 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=system:admin,O=system:masters signed by CN=k3s-client-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=system:kube-controller-manager signed by CN=k3s-client-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=system:kube-scheduler signed by CN=k3s-client-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=system:apiserver,O=system:masters signed by CN=k3s-client-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=system:kube-proxy signed by CN=k3s-client-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=system:k3s-controller signed by CN=k3s-client-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=k3s-cloud-controller-manager signed by CN=k3s-client-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="generated self-signed CA certificate CN=k3s-server-ca@1665558179: notBefore=2022-10-12 07:02:59.594288309 +0000 UTC notAfter=2032-10-09 07:02:59.594288309 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=kube-apiserver signed by CN=k3s-server-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="generated self-signed CA certificate CN=k3s-request-header-ca@1665558179: notBefore=2022-10-12 07:02:59.605602859 +0000 UTC notAfter=2032-10-09 07:02:59.605602859 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=system:auth-proxy signed by CN=k3s-request-header-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="generated self-signed CA certificate CN=etcd-server-ca@1665558179: notBefore=2022-10-12 07:02:59.607341675 +0000 UTC notAfter=2032-10-09 07:02:59.607341675 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=etcd-server signed by CN=etcd-server-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=etcd-client signed by CN=etcd-server-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="generated self-signed CA certificate CN=etcd-peer-ca@1665558179: notBefore=2022-10-12 07:02:59.609824094 +0000 UTC notAfter=2032-10-09 07:02:59.609824094 +0000 UTC"
Oct 12 08:02:59 linux.0e9675.com k3s[199561]: time="2022-10-12T08:02:59+01:00" level=info msg="certificate CN=etcd-peer signed by CN=etcd-peer-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:02:59 +0000 UTC"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="certificate CN=k3s,O=k3s signed by CN=k3s-server-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:03:00 +0000 UTC"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=warning msg="dynamiclistener [::]:6443: no cached certificate available for preload - deferring certificate load until storage initialization or first client request"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Active TLS secret / (ver=) (count 10): map[listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-45.15.141.120:45.15.141.120 listener.cattle.io/cn-__1-f16284:::1 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc:kubernetes.default.svc listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-linux.0e9675.com:linux.0e9675.com listener.cattle.io/cn-localhost:localhost listener.cattle.io/fingerprint:SHA1=113FBA834F6E969D8D972A73360B0BD145666916]"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" 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=127.0.0.1 --cert-dir=/var/lib/rancher/k3s/server/tls/temporary-certs --client-ca-file=/var/lib/rancher/k3s/server/tls/client-ca.crt --egress-selector-config-file=/var/lib/rancher/k3s/server/etc/egress-selector-config.yaml --enable-admission-plugins=NodeRestriction --enable-aggregator-routing=true --etcd-servers=unix://kine.sock --feature-gates=JobTrackingWithFinalizers=true --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 --kubelet-preferred-address-types=InternalIP,ExternalIP,Hostname --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=10.43.0.0/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"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Running kube-scheduler --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --authorization-kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --bind-address=127.0.0.1 --kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --leader-elect=false --profiling=false --secure-port=10259"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Running kube-controller-manager --allocate-node-cidrs=true --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --authorization-kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --bind-address=127.0.0.1 --cluster-cidr=10.42.0.0/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/server-ca.crt --cluster-signing-legacy-unknown-key-file=/var/lib/rancher/k3s/server/tls/server-ca.key --configure-cloud-routes=false --controllers=*,-service,-route,-cloud-node-lifecycle --feature-gates=JobTrackingWithFinalizers=true --kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --leader-elect=false --profiling=false --root-ca-file=/var/lib/rancher/k3s/server/tls/server-ca.crt --secure-port=10257 --service-account-private-key-file=/var/lib/rancher/k3s/server/tls/service.key --service-cluster-ip-range=10.43.0.0/16 --use-service-account-credentials=true"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Running cloud-controller-manager --allocate-node-cidrs=true --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --authorization-kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --bind-address=127.0.0.1 --cloud-provider=k3s --cluster-cidr=10.42.0.0/16 --configure-cloud-routes=false --kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --leader-elect=false --node-status-update-frequency=1m0s --profiling=false"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="To join server node to cluster: k3s server -s https://45.15.141.120:6443 -t ${SERVER_NODE_TOKEN}"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="To join agent node to cluster: k3s agent -s https://45.15.141.120:6443 -t ${AGENT_NODE_TOKEN}"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Run: k3s kubectl"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Tunnel server egress proxy mode: agent"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Tunnel server egress proxy waiting for runtime core to become available"
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: I1012 08:03:00.273717  199561 server.go:576] external host was not specified, using 45.15.141.120
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: I1012 08:03:00.274410  199561 server.go:168] Version: v1.24.6+k3s1
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: I1012 08:03:00.274687  199561 server.go:170] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""
Oct 12 08:03:00 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:00+01:00" level=info msg="Waiting for API server to become available"
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:01+01:00" level=info msg="certificate CN=linux.0e9675.com signed by CN=k3s-server-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:03:01 +0000 UTC"
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:01+01:00" level=info msg="certificate CN=system:node:linux.0e9675.com,O=system:nodes signed by CN=k3s-client-ca@1665558179: notBefore=2022-10-12 07:02:59 +0000 UTC notAfter=2023-10-12 07:03:01 +0000 UTC"
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:01+01:00" level=info msg="Module overlay was already loaded"
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:01+01:00" level=info msg="Module nf_conntrack was already loaded"
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:01+01:00" level=info msg="Module br_netfilter was already loaded"
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:01+01:00" level=info msg="Module iptable_nat was already loaded"
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: W1012 08:03:01.623918  199561 sysinfo.go:203] Nodes topology is not available, providing CPU topology
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:01+01:00" level=info msg="Logging containerd to /var/lib/rancher/k3s/agent/containerd/containerd.log"
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:01+01:00" 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"
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: I1012 08:03:01.796053  199561 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.
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: I1012 08:03:01.802014  199561 plugins.go:161] Loaded 11 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,PodSecurity,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,CertificateSubjectRestriction,ValidatingAdmissionWebhook,ResourceQuota.
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: I1012 08:03:01.809610  199561 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.
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: I1012 08:03:01.823543  199561 plugins.go:161] Loaded 11 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,PodSecurity,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,CertificateSubjectRestriction,ValidatingAdmissionWebhook,ResourceQuota.
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: I1012 08:03:01.823415  199561 shared_informer.go:255] Waiting for caches to sync for node_authorizer
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: W1012 08:03:01.924102  199561 genericapiserver.go:557] Skipping API apiextensions.k8s.io/v1beta1 because it has no resources.
Oct 12 08:03:01 linux.0e9675.com k3s[199561]: I1012 08:03:01.926180  199561 instance.go:274] Using reconciler: lease
Oct 12 08:03:02 linux.0e9675.com k3s[199561]: I1012 08:03:02.462402  199561 instance.go:586] API group "internal.apiserver.k8s.io" is not enabled, skipping.
Oct 12 08:03:02 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:02+01:00" level=info msg="Containerd is now running"
Oct 12 08:03:02 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:02+01:00" level=info msg="Running kubelet --address=0.0.0.0 --anonymous-auth=false --authentication-token-webhook=true --authorization-mode=Webhook --cgroup-driver=systemd --client-ca-file=/var/lib/rancher/k3s/agent/client-ca.crt --cloud-provider=external --cluster-dns=10.43.0.10 --cluster-domain=cluster.local --container-runtime-endpoint=unix:///run/k3s/containerd/containerd.sock --containerd=/run/k3s/containerd/containerd.sock --eviction-hard=imagefs.available<5%,nodefs.available<5% --eviction-minimum-reclaim=imagefs.available=10%,nodefs.available=10% --fail-swap-on=false --healthz-bind-address=127.0.0.1 --hostname-override=linux.0e9675.com --kubeconfig=/var/lib/rancher/k3s/agent/kubelet.kubeconfig --node-labels= --pod-infra-container-image=rancher/mirrored-pause:3.6 --pod-manifest-path=/var/lib/rancher/k3s/agent/pod-manifests --read-only-port=0 --resolv-conf=/etc/resolv.conf --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"
Oct 12 08:03:02 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:02+01:00" level=info msg="Connecting to proxy" url="wss://127.0.0.1:6443/v1-k3s/connect"
Oct 12 08:03:02 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:02+01:00" level=info msg="Handling backend connection request [linux.0e9675.com]"
Oct 12 08:03:02 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:02+01:00" level=info msg="Waiting to retrieve kube-proxy configuration; server is not ready: https://127.0.0.1:6443/v1-k3s/readyz: 500 Internal Server Error"
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.206927  199561 genericapiserver.go:557] Skipping API authentication.k8s.io/v1beta1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.211400  199561 genericapiserver.go:557] Skipping API authorization.k8s.io/v1beta1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.249719  199561 genericapiserver.go:557] Skipping API certificates.k8s.io/v1beta1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.256592  199561 genericapiserver.go:557] Skipping API coordination.k8s.io/v1beta1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.283967  199561 genericapiserver.go:557] Skipping API networking.k8s.io/v1beta1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.291980  199561 genericapiserver.go:557] Skipping API node.k8s.io/v1alpha1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.310435  199561 genericapiserver.go:557] Skipping API rbac.authorization.k8s.io/v1beta1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.310864  199561 genericapiserver.go:557] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.315827  199561 genericapiserver.go:557] Skipping API scheduling.k8s.io/v1beta1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.316332  199561 genericapiserver.go:557] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.328792  199561 genericapiserver.go:557] Skipping API storage.k8s.io/v1alpha1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.340422  199561 genericapiserver.go:557] Skipping API flowcontrol.apiserver.k8s.io/v1alpha1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.352500  199561 genericapiserver.go:557] Skipping API apps/v1beta2 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.353043  199561 genericapiserver.go:557] Skipping API apps/v1beta1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.361068  199561 genericapiserver.go:557] Skipping API admissionregistration.k8s.io/v1beta1 because it has no resources.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: I1012 08:03:03.386023  199561 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.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: I1012 08:03:03.386441  199561 plugins.go:161] Loaded 11 validating admission controller(s) successfully in the following order: LimitRanger,ServiceAccount,PodSecurity,Priority,PersistentVolumeClaimResize,RuntimeClass,CertificateApproval,CertificateSigning,CertificateSubjectRestriction,ValidatingAdmissionWebhook,ResourceQuota.
Oct 12 08:03:03 linux.0e9675.com k3s[199561]: W1012 08:03:03.454559  199561 genericapiserver.go:557] Skipping API apiregistration.k8s.io/v1beta1 because it has no resources.
Oct 12 08:03:05 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:05+01:00" level=info msg="Tunnel server egress proxy waiting for runtime core to become available"
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.201619  199561 secure_serving.go:210] Serving securely on 127.0.0.1:6444
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.203254  199561 dynamic_cafile_content.go:157] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt"
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.220091  199561 dynamic_serving_content.go:132] "Starting controller" name="serving-cert::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.crt::/var/lib/rancher/k3s/server/tls/serving-kube-apiserver.key"
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.221043  199561 tlsconfig.go:240] "Starting DynamicServingCertificateController"
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.222449  199561 dynamic_serving_content.go:132] "Starting controller" name="aggregator-proxy-cert::/var/lib/rancher/k3s/server/tls/client-auth-proxy.crt::/var/lib/rancher/k3s/server/tls/client-auth-proxy.key"
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.238366  199561 controller.go:80] Starting OpenAPI V3 AggregationController
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.239375  199561 cluster_authentication_trust_controller.go:440] Starting cluster_authentication_trust_controller controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.239600  199561 shared_informer.go:255] Waiting for caches to sync for cluster_authentication_trust_controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.239820  199561 apf_controller.go:317] Starting API Priority and Fairness config controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.240088  199561 controller.go:83] Starting OpenAPI AggregationController
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.240430  199561 customresource_discovery_controller.go:209] Starting DiscoveryController
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.241160  199561 autoregister_controller.go:141] Starting autoregister controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.241377  199561 cache.go:32] Waiting for caches to sync for autoregister controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.241635  199561 available_controller.go:491] Starting AvailableConditionController
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.241848  199561 cache.go:32] Waiting for caches to sync for AvailableConditionController controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.242447  199561 apiservice_controller.go:97] Starting APIServiceRegistrationController
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.242538  199561 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.242616  199561 dynamic_cafile_content.go:157] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt"
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.267584  199561 dynamic_cafile_content.go:157] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/server/tls/client-ca.crt"
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.268149  199561 dynamic_cafile_content.go:157] "Starting controller" name="request-header::/var/lib/rancher/k3s/server/tls/request-header-ca.crt"
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.290009  199561 controller.go:85] Starting OpenAPI controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.290543  199561 controller.go:85] Starting OpenAPI V3 controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.290780  199561 naming_controller.go:291] Starting NamingConditionController
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.291132  199561 establishing_controller.go:76] Starting EstablishingController
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.291169  199561 nonstructuralschema_controller.go:192] Starting NonStructuralSchemaConditionController
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.291198  199561 apiapproval_controller.go:186] Starting KubernetesAPIApprovalPolicyConformantConditionController
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.291222  199561 crd_finalizer.go:266] Starting CRDFinalizer
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.298510  199561 crdregistration_controller.go:111] Starting crd-autoregister controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.299013  199561 shared_informer.go:255] Waiting for caches to sync for crd-autoregister
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.464051  199561 controller.go:132] OpenAPI AggregationController: action for item k8s_internal_local_delegation_chain_0000000000: Nothing (removed from the queue).
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.534005  199561 shared_informer.go:262] Caches are synced for node_authorizer
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.539838  199561 shared_informer.go:262] Caches are synced for cluster_authentication_trust_controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.540395  199561 apf_controller.go:322] Running API Priority and Fairness config worker
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.541600  199561 cache.go:39] Caches are synced for autoregister controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.542170  199561 cache.go:39] Caches are synced for AvailableConditionController controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.542769  199561 cache.go:39] Caches are synced for APIServiceRegistrationController controller
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.603415  199561 shared_informer.go:262] Caches are synced for crd-autoregister
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: I1012 08:03:07.607175  199561 controller.go:611] quota admission added evaluator for: namespaces
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:07+01:00" level=info msg="Waiting to retrieve kube-proxy configuration; server is not ready: https://127.0.0.1:6443/v1-k3s/readyz: 500 Internal Server Error"
Oct 12 08:03:07 linux.0e9675.com k3s[199561]: E1012 08:03:07.859659  199561 controller.go:166] Unable to perform initial Kubernetes service initialization: Service "kubernetes" is invalid: spec.clusterIPs: Invalid value: []string{"10.43.0.1"}: failed to allocate IP 10.43.0.1: cannot allocate resources of type serviceipallocations at this time
Oct 12 08:03:08 linux.0e9675.com k3s[199561]: I1012 08:03:08.255488  199561 storage_scheduling.go:95] created PriorityClass system-node-critical with value 2000001000
Oct 12 08:03:08 linux.0e9675.com k3s[199561]: I1012 08:03:08.267776  199561 storage_scheduling.go:95] created PriorityClass system-cluster-critical with value 2000000000
Oct 12 08:03:08 linux.0e9675.com k3s[199561]: I1012 08:03:08.268615  199561 storage_scheduling.go:111] all system priority classes are created successfully or already exist.
Oct 12 08:03:08 linux.0e9675.com k3s[199561]: I1012 08:03:08.983147  199561 controller.go:611] quota admission added evaluator for: roles.rbac.authorization.k8s.io
Oct 12 08:03:09 linux.0e9675.com k3s[199561]: I1012 08:03:09.042693  199561 controller.go:611] quota admission added evaluator for: rolebindings.rbac.authorization.k8s.io
Oct 12 08:03:09 linux.0e9675.com k3s[199561]: I1012 08:03:09.148471  199561 alloc.go:327] "allocated clusterIPs" service="default/kubernetes" clusterIPs=map[IPv4:10.43.0.1]
Oct 12 08:03:09 linux.0e9675.com k3s[199561]: W1012 08:03:09.156558  199561 lease.go:234] Resetting endpoints for master service "kubernetes" to [45.15.141.120]
Oct 12 08:03:09 linux.0e9675.com k3s[199561]: I1012 08:03:09.158687  199561 controller.go:611] quota admission added evaluator for: endpoints
Oct 12 08:03:09 linux.0e9675.com k3s[199561]: I1012 08:03:09.165032  199561 controller.go:611] quota admission added evaluator for: endpointslices.discovery.k8s.io
Oct 12 08:03:09 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:09+01:00" level=info msg="Kube API server is now running"
Oct 12 08:03:09 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:09+01:00" level=info msg="ETCD server is now running"
Oct 12 08:03:09 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:09+01:00" level=info msg="k3s is up and running"
Oct 12 08:03:09 linux.0e9675.com systemd[1]: Started Lightweight Kubernetes.
Oct 12 08:03:09 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:09+01:00" level=info msg="Waiting for cloud-controller-manager privileges to become available"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: Flag --cloud-provider has been deprecated, will be removed in 1.24 or later, in favor of removing cloud provider code from Kubelet.
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: 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.
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: Flag --pod-infra-container-image has been deprecated, will be removed in 1.27. Image garbage collector will get sandbox image information from CRI.
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.033714  199561 server.go:192] "--pod-infra-container-image will not be pruned by the image garbage collector in kubelet and should also be set in the remote runtime"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:10+01:00" level=info msg="Applying CRD addons.k3s.cattle.io"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.198064  199561 server.go:395] "Kubelet version" kubeletVersion="v1.24.6+k3s1"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.198464  199561 server.go:397] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.236224  199561 dynamic_cafile_content.go:157] "Starting controller" name="client-ca-bundle::/var/lib/rancher/k3s/agent/client-ca.crt"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: W1012 08:03:10.256329  199561 reflector.go:324] k8s.io/client-go@v1.24.6-k3s1/tools/cache/reflector.go:167: failed to list *v1.Endpoints: endpoints "kubernetes" is forbidden: User "system:k3s-controller" cannot list resource "endpoints" in API group "" in the namespace "default"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: E1012 08:03:10.256951  199561 reflector.go:138] k8s.io/client-go@v1.24.6-k3s1/tools/cache/reflector.go:167: Failed to watch *v1.Endpoints: failed to list *v1.Endpoints: endpoints "kubernetes" is forbidden: User "system:k3s-controller" cannot list resource "endpoints" in API group "" in the namespace "default"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: W1012 08:03:10.275766  199561 sysinfo.go:203] Nodes topology is not available, providing CPU topology
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.293752  199561 server.go:644] "--cgroups-per-qos enabled, but --cgroup-root was not specified.  defaulting to /"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.294984  199561 container_manager_linux.go:262] "Container manager verified user specified cgroup-root exists" cgroupRoot=[]
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.295414  199561 container_manager_linux.go:267] "Creating Container Manager object based on Node Config" nodeConfig={RuntimeCgroupsName: SystemCgroupsName: KubeletCgroupsName: KubeletOOMScoreAdj:-999 ContainerRuntime: CgroupsPerQOS:true CgroupRoot:/ CgroupDriver:systemd 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 ExperimentalCPUManagerPolicyOptions:map[] ExperimentalTopologyManagerScope:container ExperimentalCPUManagerReconcilePeriod:10s ExperimentalMemoryManagerPolicy:None ExperimentalMemoryManagerReservedMemory:[] ExperimentalPodPidsLimit:-1 EnforceCPULimits:true CPUCFSQuotaPeriod:100ms ExperimentalTopologyManagerPolicy:none}
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.295735  199561 topology_manager.go:133] "Creating topology manager with policy per scope" topologyPolicyName="none" topologyScopeName="container"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.295985  199561 container_manager_linux.go:302] "Creating device plugin manager" devicePluginEnabled=true
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.296405  199561 state_mem.go:36] "Initialized new in-memory state store"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:10+01:00" level=info msg="Tunnel server egress proxy waiting for runtime core to become available"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.395958  199561 kubelet.go:376] "Attempting to sync node with API server"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.396082  199561 kubelet.go:267] "Adding static pod path" path="/var/lib/rancher/k3s/agent/pod-manifests"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.396178  199561 kubelet.go:278] "Adding apiserver pod source"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.396229  199561 apiserver.go:42] "Waiting for node sync before watching apiserver pods"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.472110  199561 kuberuntime_manager.go:239] "Container runtime initialized" containerRuntime="containerd" version="v1.6.8-k3s1" apiVersion="v1"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.473129  199561 server.go:1177] "Started kubelet"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.512630  199561 server.go:150] "Starting to listen" address="0.0.0.0" port=10250
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.533522  199561 fs_resource_analyzer.go:67] "Starting FS ResourceAnalyzer"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.576167  199561 server.go:410] "Adding debug handlers to kubelet server"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.578277  199561 volume_manager.go:289] "Starting Kubelet Volume Manager"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.587338  199561 desired_state_of_world_populator.go:145] "Desired state populator starts to run"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.642845  199561 kubelet_network_linux.go:76] "Initialized protocol iptables rules." protocol=IPv4
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: E1012 08:03:10.670488  199561 cri_stats_provider.go:455] "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"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: E1012 08:03:10.670929  199561 kubelet.go:1298] "Image garbage collection failed once. Stats initialization may not have completed yet" err="invalid capacity 0 on image filesystem"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: E1012 08:03:10.679970  199561 kubelet.go:2424] "Error getting node" err="node \"linux.0e9675.com\" not found"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.691674  199561 kubelet_network_linux.go:76] "Initialized protocol iptables rules." protocol=IPv6
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.691711  199561 status_manager.go:161] "Starting to sync pod status with apiserver"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.691742  199561 kubelet.go:1986] "Starting kubelet main sync loop"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: E1012 08:03:10.691831  199561 kubelet.go:2010] "Skipping pod synchronization" err="[container runtime status check may not have completed yet, PLEG is not healthy: pleg has yet to be successful]"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.745211  199561 kubelet_node_status.go:70] "Attempting to register node" node="linux.0e9675.com"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: E1012 08:03:10.780735  199561 kubelet.go:2424] "Error getting node" err="node \"linux.0e9675.com\" not found"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: E1012 08:03:10.801049  199561 kubelet.go:2010] "Skipping pod synchronization" err="container runtime status check may not have completed yet"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: E1012 08:03:10.890393  199561 kubelet.go:2424] "Error getting node" err="node \"linux.0e9675.com\" not found"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:10+01:00" level=info msg="Applying CRD helmcharts.helm.cattle.io"
Oct 12 08:03:10 linux.0e9675.com k3s[199561]: I1012 08:03:10.926837  199561 kubelet_node_status.go:73] "Successfully registered node" node="linux.0e9675.com"
Oct 12 08:03:11 linux.0e9675.com k3s[199561]: E1012 08:03:11.071200  199561 kubelet.go:2010] "Skipping pod synchronization" err="container runtime status check may not have completed yet"
Oct 12 08:03:11 linux.0e9675.com k3s[199561]: I1012 08:03:11.215405  199561 serving.go:355] Generated self-signed cert in-memory
Oct 12 08:03:11 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:11+01:00" level=info msg="Annotations and labels have been set successfully on node: linux.0e9675.com"
Oct 12 08:03:11 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:11+01:00" level=info msg="Starting flannel with backend vxlan"
Oct 12 08:03:11 linux.0e9675.com k3s[199561]: I1012 08:03:11.358782  199561 controller.go:611] quota admission added evaluator for: leases.coordination.k8s.io
Oct 12 08:03:11 linux.0e9675.com k3s[199561]: I1012 08:03:11.465794  199561 apiserver.go:52] "Watching apiserver"
Oct 12 08:03:11 linux.0e9675.com k3s[199561]: E1012 08:03:11.506660  199561 kubelet.go:2010] "Skipping pod synchronization" err="container runtime status check may not have completed yet"
Oct 12 08:03:11 linux.0e9675.com k3s[199561]: W1012 08:03:11.795810  199561 reflector.go:324] k8s.io/client-go@v1.24.6-k3s1/tools/cache/reflector.go:167: failed to list *v1.Endpoints: endpoints "kubernetes" is forbidden: User "system:k3s-controller" cannot list resource "endpoints" in API group "" in the namespace "default"
Oct 12 08:03:11 linux.0e9675.com k3s[199561]: E1012 08:03:11.796681  199561 reflector.go:138] k8s.io/client-go@v1.24.6-k3s1/tools/cache/reflector.go:167: Failed to watch *v1.Endpoints: failed to list *v1.Endpoints: endpoints "kubernetes" is forbidden: User "system:k3s-controller" cannot list resource "endpoints" in API group "" in the namespace "default"
Oct 12 08:03:12 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:12+01:00" level=info msg="Applying CRD helmchartconfigs.helm.cattle.io"
Oct 12 08:03:12 linux.0e9675.com k3s[199561]: E1012 08:03:12.469492  199561 kubelet.go:2010] "Skipping pod synchronization" err="container runtime status check may not have completed yet"
Oct 12 08:03:13 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:13+01:00" level=info msg="Waiting to retrieve kube-proxy configuration; server is not ready: https://127.0.0.1:6443/v1-k3s/readyz: 500 Internal Server Error"
Oct 12 08:03:13 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:13+01:00" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-10.19.300.tgz"
Oct 12 08:03:13 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:13+01:00" level=info msg="Writing static file: /var/lib/rancher/k3s/server/static/charts/traefik-crd-10.19.300.tgz"
Oct 12 08:03:13 linux.0e9675.com k3s[199561]: W1012 08:03:13.936150  199561 reflector.go:324] k8s.io/client-go@v1.24.6-k3s1/tools/cache/reflector.go:167: failed to list *v1.Endpoints: endpoints "kubernetes" is forbidden: User "system:k3s-controller" cannot list resource "endpoints" in API group "" in the namespace "default"
Oct 12 08:03:13 linux.0e9675.com k3s[199561]: E1012 08:03:13.936381  199561 reflector.go:138] k8s.io/client-go@v1.24.6-k3s1/tools/cache/reflector.go:167: Failed to watch *v1.Endpoints: failed to list *v1.Endpoints: endpoints "kubernetes" is forbidden: User "system:k3s-controller" cannot list resource "endpoints" in API group "" in the namespace "default"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: E1012 08:03:14.079044  199561 kubelet.go:2010] "Skipping pod synchronization" err="container runtime status check may not have completed yet"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Failed to get existing traefik HelmChart" error="helmcharts.helm.cattle.io \"traefik\" not found"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/traefik.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/aggregated-metrics-reader.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/coredns.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/local-storage.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/auth-delegator.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/auth-reader.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/metrics-apiservice.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/metrics-server-deployment.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/metrics-server-service.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/ccm.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/rolebindings.yaml"
Oct 12 08:03:14 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:14+01:00" level=info msg="Writing manifest: /var/lib/rancher/k3s/server/manifests/metrics-server/resource-reader.yaml"
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:15+01:00" level=info msg="Waiting for cloud-controller-manager privileges to become available: timed out waiting for the condition"
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:15+01:00" level=info msg="Starting k3s.cattle.io/v1, Kind=Addon controller"
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:15+01:00" level=info msg="Creating deploy event broadcaster"
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: I1012 08:03:15.738081  199561 controller.go:611] quota admission added evaluator for: addons.k3s.cattle.io
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: I1012 08:03:15.869776  199561 controllermanager.go:180] Version: v1.24.6+k3s1
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: I1012 08:03:15.869946  199561 controllermanager.go:182] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:15+01:00" level=info msg="Creating svccontroller event broadcaster"
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:15+01:00" level=info msg="Starting /v1, Kind=Secret controller"
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:15+01:00" level=info msg="Starting /v1, Kind=Node controller"
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:15+01:00" level=warning msg="Unable to fetch coredns config map: configmaps \"coredns\" not found"
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: I1012 08:03:15.994976  199561 secure_serving.go:210] Serving securely on 127.0.0.1:10257
Oct 12 08:03:15 linux.0e9675.com k3s[199561]: I1012 08:03:15.999514  199561 requestheader_controller.go:169] Starting RequestHeaderAuthRequestController
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:15.999686  199561 shared_informer.go:255] Waiting for caches to sync for RequestHeaderAuthRequestController
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.000674  199561 tlsconfig.go:240] "Starting DynamicServingCertificateController"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Event(v1.ObjectReference{Kind:\"Addon\", Namespace:\"kube-system\", Name:\"ccm\", UID:\"5913aad2-cf21-4f7e-bbf3-ab5b6e4577a7\", APIVersion:\"k3s.cattle.io/v1\", ResourceVersion:\"226\", FieldPath:\"\"}): type: 'Normal' reason: 'ApplyingManifest' Applying manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\""
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.001370  199561 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.001588  199561 shared_informer.go:255] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::client-ca-file
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.001848  199561 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.002126  199561 shared_informer.go:255] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=warning msg="Unable to fetch coredns config map: configmaps \"coredns\" not found"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Updating TLS secret for kube-system/k3s-serving (count: 10): map[listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-45.15.141.120:45.15.141.120 listener.cattle.io/cn-__1-f16284:::1 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc:kubernetes.default.svc listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-linux.0e9675.com:linux.0e9675.com listener.cattle.io/cn-localhost:localhost listener.cattle.io/fingerprint:SHA1=113FBA834F6E969D8D972A73360B0BD145666916]"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.100049  199561 shared_informer.go:262] Caches are synced for RequestHeaderAuthRequestController
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.101867  199561 shared_informer.go:262] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::client-ca-file
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.102172  199561 shared_informer.go:262] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Active TLS secret kube-system/k3s-serving (ver=224) (count 10): map[listener.cattle.io/cn-10.43.0.1:10.43.0.1 listener.cattle.io/cn-127.0.0.1:127.0.0.1 listener.cattle.io/cn-45.15.141.120:45.15.141.120 listener.cattle.io/cn-__1-f16284:::1 listener.cattle.io/cn-kubernetes:kubernetes listener.cattle.io/cn-kubernetes.default:kubernetes.default listener.cattle.io/cn-kubernetes.default.svc:kubernetes.default.svc listener.cattle.io/cn-kubernetes.default.svc.cluster.local:kubernetes.default.svc.cluster.local listener.cattle.io/cn-linux.0e9675.com:linux.0e9675.com listener.cattle.io/cn-localhost:localhost listener.cattle.io/fingerprint:SHA1=113FBA834F6E969D8D972A73360B0BD145666916]"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Cluster dns configmap has been set successfully"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=warning msg="Unable to fetch coredns config map: configmaps \"coredns\" not found"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Labels and annotations have been set successfully on node: linux.0e9675.com"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=warning msg="Unable to fetch coredns config map: configmaps \"coredns\" not found"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=warning msg="Unable to fetch coredns config map: configmaps \"coredns\" not found"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.500839  199561 shared_informer.go:255] Waiting for caches to sync for tokens
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.602204  199561 controller.go:611] quota admission added evaluator for: serviceaccounts
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.602843  199561 shared_informer.go:262] Caches are synced for tokens
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Event(v1.ObjectReference{Kind:\"Addon\", Namespace:\"kube-system\", Name:\"ccm\", UID:\"5913aad2-cf21-4f7e-bbf3-ab5b6e4577a7\", APIVersion:\"k3s.cattle.io/v1\", ResourceVersion:\"226\", FieldPath:\"\"}): type: 'Normal' reason: 'AppliedManifest' Applied manifest at \"/var/lib/rancher/k3s/server/manifests/ccm.yaml\""
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.710014  199561 controllermanager.go:593] Started "endpointslicemirroring"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.712155  199561 endpointslicemirroring_controller.go:212] Starting EndpointSliceMirroring controller
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.712449  199561 shared_informer.go:255] Waiting for caches to sync for endpoint_slice_mirroring
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChart controller"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Starting helm.cattle.io/v1, Kind=HelmChartConfig controller"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Event(v1.ObjectReference{Kind:\"Addon\", Namespace:\"kube-system\", Name:\"coredns\", UID:\"4530857f-3a9b-41f7-86e8-88e9f0015ac1\", APIVersion:\"k3s.cattle.io/v1\", ResourceVersion:\"238\", FieldPath:\"\"}): type: 'Normal' reason: 'ApplyingManifest' Applying manifest at \"/var/lib/rancher/k3s/server/manifests/coredns.yaml\""
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.772785  199561 cpu_manager.go:213] "Starting CPU manager" policy="none"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.773206  199561 cpu_manager.go:214] "Reconciling" reconcilePeriod="10s"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.773455  199561 state_mem.go:36] "Initialized new in-memory state store"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.776934  199561 policy_none.go:49] "None policy: Start"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Starting apps/v1, Kind=DaemonSet controller"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: time="2022-10-12T08:03:16+01:00" level=info msg="Starting apps/v1, Kind=Deployment controller"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.821340  199561 memory_manager.go:168] "Starting memorymanager" policy="None"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: I1012 08:03:16.821695  199561 state_mem.go:35] "Initializing new in-memory state store"
Oct 12 08:03:16 linux.0e9675.com k3s[199561]: E1012 08:03:16.823817  199561 kubelet.go:1378] "Failed to start ContainerManager" err="open /proc/sys/kernel/panic: permission denied"
Oct 12 08:03:16 linux.0e9675.com systemd[1]: k3s.service: Main process exited, code=exited, status=1/FAILURE
Oct 12 08:03:16 linux.0e9675.com systemd[1]: k3s.service: Failed with result 'exit-code'.
brandond commented 2 years ago

Oct 12 08:03:16 linux.0e9675.com k3s[199561]: E1012 08:03:16.823817 199561 kubelet.go:1378] "Failed to start ContainerManager" err="open /proc/sys/kernel/panic: permission denied"

What sort of host are you running this on? Is this some sort of VPS where you don't have full root access to the underlying node? There's no other reason that k3s shouldn't have access to this.

swoutch commented 2 years ago

What sort of host are you running this on? Is this some sort of VPS where you don't have full root access to the underlying node?

I indeed run it on a VPS, virtualized with openVZ. I thought I had full root access but I will check with the support.

Thanks for your help!

In your opinion, the issue is not related to modprobe not finding the br_netfilter and overlay kernel modules? (first lines of the logs)

brandond commented 2 years ago

No, those are not fatal errors. You're probably not going to be able to use Kubernetes on a VPS that doesn't give you real root on the node.