K3s fails to start, main control loop seemingly not running

[MrTrustor]

Hi,

I've been using k3s (+Longhorn) for years without issues, but I can't seem to figure out this one. Any help would be appreciated.

This issue appeared after my single node restarted following an electricity outage. I don't think that's actually relevant, because it's plugged into a UPS and was shutdown gracefully, but you never know...

Thank you in advance to anyone who could give me a few ideas of where I should look next to fix this problem.

Environment

• Single node
• OS: Ubuntu 22.04.5 LTS with kernel Linux k8s-1 5.15.0-133-generic #144-Ubuntu
• K3s: k3s version v1.31.5+k3s1 (56ec5dd) / go version go1.22.10 (It was v1.30.5+k3s1 when the issue appeared, and I upgraded to v1.31.5+k3s1 hopping that it would fix the issue, it didn't)
• ufw is inactive (ufw status outputs Status: inactive)
• Systems unit file:

Click to expand

[Unit]
Description=Lightweight Kubernetes
Documentation=https://k3s.io
After=network-online.target
Wants=network-online.target

[Service]
Type=notify
EnvironmentFile=-/etc/default/%N
EnvironmentFile=-/etc/sysconfig/%N
EnvironmentFile=-/etc/systemd/system/k3s.service.env
ExecStartPre=/bin/sh -xc '! /usr/bin/systemctl is-enabled --quiet nm-cloud-setup.service 2>/dev/null'
ExecStart=/usr/local/bin/k3s server
KillMode=process
Delegate=yes
# Having non-zero Limit*s causes performance problems due to accounting overhead
# in the kernel. We recommend using cgroups to do container-local accounting.
LimitNOFILE=1048576
LimitNPROC=infinity
LimitCORE=infinity
TasksMax=infinity
TimeoutStartSec=0
Restart=always
RestartSec=5s

[Install]
WantedBy=multi-user.target

• Config file:

Click to expand

kubelet-arg:
  - "image-gc-low-threshold=20"
  - "image-gc-high-threshold=50"
debug: true

Symptoms

• service k3s start hangs indefinitely, but I can use the kubectl CLI.
• Some pods keep running, some are in an Unknown state, and some crash loop (because they can't attach their Longhorn PV).
• Pods can't seem to resolve DNS queries
• Because pods couldn't resolve DNS queries, I deleted the coredns pod. The deletion was successful, but it was never recreated by the coredns deployment. Interestingly the coredns deployment still reports 1/1 pod ready.
• I tried to create a new Deployment, the most simple possible (the example from the official K8s docs). The Deployment was created, but the corresponding ReplicatSet and Pods were never created.

These symptoms make me think that somehow the main control loop of K8s is not actually running, as there is no reconciliation between the desired state and the actual state of the cluster.

What I tried

• I rebooted, the problem didn't disappear.
• I updated all my ubuntu packages, kernel included, and rebooted. The problem didn't disappear.
• I updated k3s to v1.31.5+k3s1 (from v1.30.5+k3s1), it made no difference.
• I tried adding the node-ip=0.0.0.0 option in the config file to prioritize IPv4 traffic, it made no difference.
• I used crictl to check if containerd was running properly. It seems to be since it reports the list of running containers.
• I used the pragma integrity_check command in sqlite to check if the database was OK, it reported no issue.
• I looked for hours at the debug logs of k3s trying to find errors and track them down, but was unsuccessful.
• I checked if the API server was working. It seems to be, since I can use kubectl from outside the cluster, and I can curl the /ping endpoint from inside pods.

Logs

You can download a log file with debug enabled here (23MB).

[brandond]

It looks like the apiserver is up, but not ready/healthy for some reason. You can run kubectl get --raw /readyz?verbose to see what it's waiting on. /healthz?verbose may show some slightly different but also possibly useful information.

[MrTrustor]

Thank you for your pointer @brandond. Ì found a few additional things, but still no solution :(
The api server seems fine, but for some reason k3s logs that it is still waiting for the API server.

root@k8s-1:/var/lib/rancher/k3s# kubectl get --raw /readyz?verbose
[+]ping ok
[+]log ok
[+]etcd ok
[+]etcd-readiness ok
[+]informer-sync ok
[+]poststarthook/start-apiserver-admission-initializer ok
[+]poststarthook/generic-apiserver-start-informers ok
[+]poststarthook/priority-and-fairness-config-consumer ok
[+]poststarthook/priority-and-fairness-filter ok
[+]poststarthook/storage-object-count-tracker-hook ok
[+]poststarthook/start-apiextensions-informers ok
[+]poststarthook/start-apiextensions-controllers ok
[+]poststarthook/crd-informer-synced ok
[+]poststarthook/start-system-namespaces-controller ok
[+]poststarthook/start-cluster-authentication-info-controller ok
[+]poststarthook/start-kube-apiserver-identity-lease-controller ok
[+]poststarthook/start-kube-apiserver-identity-lease-garbage-collector ok
[+]poststarthook/start-legacy-token-tracking-controller ok
[+]poststarthook/start-service-ip-repair-controllers ok
[+]poststarthook/rbac/bootstrap-roles ok
[+]poststarthook/scheduling/bootstrap-system-priority-classes ok
[+]poststarthook/priority-and-fairness-config-producer ok
[+]poststarthook/bootstrap-controller ok
[+]poststarthook/aggregator-reload-proxy-client-cert ok
[+]poststarthook/start-kube-aggregator-informers ok
[+]poststarthook/apiservice-status-local-available-controller ok
[+]poststarthook/apiservice-status-remote-available-controller ok
[+]poststarthook/apiservice-registration-controller ok
[+]poststarthook/apiservice-discovery-controller ok
[+]poststarthook/kube-apiserver-autoregistration ok
[+]autoregister-completion ok
[+]poststarthook/apiservice-openapi-controller ok
[+]poststarthook/apiservice-openapiv3-controller ok
[+]shutdown ok
readyz check passed

root@k8s-1:/var/lib/rancher/k3s# kubectl get --raw /healthz?verbose
[+]ping ok
[+]log ok
[+]etcd ok
[+]poststarthook/start-apiserver-admission-initializer ok
[+]poststarthook/generic-apiserver-start-informers ok
[+]poststarthook/priority-and-fairness-config-consumer ok
[+]poststarthook/priority-and-fairness-filter ok
[+]poststarthook/storage-object-count-tracker-hook ok
[+]poststarthook/start-apiextensions-informers ok
[+]poststarthook/start-apiextensions-controllers ok
[+]poststarthook/crd-informer-synced ok
[+]poststarthook/start-system-namespaces-controller ok
[+]poststarthook/start-cluster-authentication-info-controller ok
[+]poststarthook/start-kube-apiserver-identity-lease-controller ok
[+]poststarthook/start-kube-apiserver-identity-lease-garbage-collector ok
[+]poststarthook/start-legacy-token-tracking-controller ok
[+]poststarthook/start-service-ip-repair-controllers ok
[+]poststarthook/rbac/bootstrap-roles ok
[+]poststarthook/scheduling/bootstrap-system-priority-classes ok
[+]poststarthook/priority-and-fairness-config-producer ok
[+]poststarthook/bootstrap-controller ok
[+]poststarthook/aggregator-reload-proxy-client-cert ok
[+]poststarthook/start-kube-aggregator-informers ok
[+]poststarthook/apiservice-status-local-available-controller ok
[+]poststarthook/apiservice-status-remote-available-controller ok
[+]poststarthook/apiservice-registration-controller ok
[+]poststarthook/apiservice-discovery-controller ok
[+]poststarthook/kube-apiserver-autoregistration ok
[+]autoregister-completion ok
[+]poststarthook/apiservice-openapi-controller ok
[+]poststarthook/apiservice-openapiv3-controller ok
healthz check passed

root@k8s-1:/var/lib/rancher/k3s# kubectl get componentstatus
Warning: v1 ComponentStatus is deprecated in v1.19+
NAME                 STATUS      MESSAGE                                                                                        ERROR
scheduler            Unhealthy   Get "https://127.0.0.1:10259/healthz": dial tcp 127.0.0.1:10259: connect: connection refused
controller-manager   Unhealthy   Get "https://127.0.0.1:10257/healthz": dial tcp 127.0.0.1:10257: connect: connection refused
etcd-0               Healthy     ok

I also noticed at regular intervals in my logs the following:

Mar 01 02:22:47 k8s-1 k3s[1961362]: time="2025-03-01T02:22:47Z" level=info msg="Waiting for API server to become available to start cloud-controller-manager"
Mar 01 02:22:47 k8s-1 k3s[1961362]: time="2025-03-01T02:22:47Z" level=info msg="Waiting for API server to become available to start kube-scheduler"
Mar 01 02:22:47 k8s-1 k3s[1961362]: time="2025-03-01T02:22:47Z" level=info msg="Waiting for API server to become available"

I'm not sure why it's still waiting on the API server, since everything seems fine on that end. Maybe a networking problem? But I'm not sure what it could be. Any ideas?

In case it's useful, here are the open ports on the server:

root@k8s-1:/var/lib/rancher/k3s# netstat -ltpen
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       User       Inode      PID/Program name
tcp        0      0 127.0.0.1:6444          0.0.0.0:*               LISTEN      0          7331409    1989483/k3s server
tcp        0      0 127.0.0.1:3493          0.0.0.0:*               LISTEN      0          58726      9046/upsd
tcp        0      0 127.0.0.1:10249         0.0.0.0:*               LISTEN      0          7336453    1989483/k3s server
tcp        0      0 127.0.0.1:10248         0.0.0.0:*               LISTEN      0          7331563    1989483/k3s server
tcp        0      0 127.0.0.1:10256         0.0.0.0:*               LISTEN      0          7335770    1989483/k3s server
tcp        0      0 127.0.0.1:10010         0.0.0.0:*               LISTEN      0          7334629    1989582/containerd
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN      0          26998      1/init
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      0          33357      832/sshd: /usr/sbin
tcp        0      0 192.168.1.101:3493      0.0.0.0:*               LISTEN      0          58725      9046/upsd
tcp        0      0 127.0.0.53:53           0.0.0.0:*               LISTEN      101        27177      750/systemd-resolve
tcp6       0      0 :::111                  :::*                    LISTEN      0          25658      1/init
tcp6       0      0 :::22                   :::*                    LISTEN      0          33359      832/sshd: /usr/sbin
tcp6       0      0 :::6443                 :::*                    LISTEN      0          7334453    1989483/k3s server
tcp6       0      0 :::10250                :::*                    LISTEN      0          7338164    1989483/k3s server

[brandond]

So your node is stuck here, waiting for the APIServerReady channel to be closed:

k3s/pkg/cli/server/server.go

Lines 515 to 527 in 8aa543e

	if !serverConfig.ControlConfig.DisableAPIServer {
	<-serverConfig.ControlConfig.Runtime.APIServerReady
	logrus.Info("Kube API server is now running")
	serverConfig.ControlConfig.Runtime.StartupHooksWg.Wait()
	}
	if !serverConfig.ControlConfig.DisableETCD {
	<-serverConfig.ControlConfig.Runtime.ETCDReady
	logrus.Info("ETCD server is now running")
	}
	logrus.Info(version.Program + " is up and running")
	os.Setenv("NOTIFY_SOCKET", notifySocket)
	systemd.SdNotify(true, "READY=1\n")

That occurs here:

k3s/pkg/daemons/control/server.go

Lines 440 to 475 in 8aa543e

	func waitForAPIServerInBackground(ctx context.Context, runtime *config.ControlRuntime) error {
	done := make(chan struct{})
	runtime.APIServerReady = done
	go func() {
	defer close(done)
	etcdLoop:
	for {
	select {
	case <-ctx.Done():
	return
	case <-runtime.ETCDReady:
	break etcdLoop
	case <-time.After(30 * time.Second):
	logrus.Infof("Waiting for etcd server to become available")
	}
	}
	logrus.Infof("Waiting for API server to become available")
	for {
	select {
	case <-ctx.Done():
	return
	case err := <-promise(func() error { return util.WaitForAPIServerReady(ctx, runtime.KubeConfigSupervisor, 30*time.Second) }):
	if err != nil {
	logrus.Infof("Waiting for API server to become available")
	continue
	}
	return
	}
	}
	}()
	return nil
	}

WaitForAPIServerReady polls /readyz, as seen here:

k3s/pkg/util/api.go

Lines 55 to 104 in 8aa543e

	// WaitForAPIServerReady waits for the API Server's /readyz endpoint to report "ok" with timeout.
	// This is modified from WaitForAPIServer from the Kubernetes controller-manager app, but checks the
	// readyz endpoint instead of the deprecated healthz endpoint, and supports context.
	func WaitForAPIServerReady(ctx context.Context, kubeconfigPath string, timeout time.Duration) error {
	var lastErr error
	restConfig, err := GetRESTConfig(kubeconfigPath)
	if err != nil {
	return err
	}
	// By default, idle connections to the apiserver are returned to a global pool
	// between requests. Explicitly flag this client's request for closure so that
	// we re-dial through the loadbalancer in case the endpoints have changed.
	restConfig.Wrap(func(rt http.RoundTripper) http.RoundTripper {
	return roundTripFunc(func(req *http.Request) (*http.Response, error) {
	req.Close = true
	return rt.RoundTrip(req)
	})
	})
	restConfig = dynamic.ConfigFor(restConfig)
	restConfig.GroupVersion = &schema.GroupVersion{}
	restClient, err := rest.RESTClientFor(restConfig)
	if err != nil {
	return err
	}
	err = wait.PollUntilContextTimeout(ctx, time.Second, timeout, true, func(ctx context.Context) (bool, error) {
	healthStatus := 0
	result := restClient.Get().AbsPath("/readyz").Do(ctx).StatusCode(&healthStatus)
	if rerr := result.Error(); rerr != nil {
	lastErr = errors.Wrap(rerr, "failed to get apiserver /readyz status")
	return false, nil
	}
	if healthStatus != http.StatusOK {
	content, _ := result.Raw()
	lastErr = fmt.Errorf("APIServer isn't ready: %v", string(content))
	logrus.Warnf("APIServer isn't ready yet: %v. Waiting a little while.", string(content))
	return false, nil
	}
	return true, nil
	})
	if err != nil {
	return merr.NewErrors(err, lastErr)
	}
	return nil
	}

You could try doing kill -ABRT <pid of k3s process> to get it to dump a stack trace to the logs to see exactly what it's doing.

[MrTrustor]

Thanks for the pointers. I was able to get some logs from SIGABRT, but I didn't find anything more than the lines of code you had already linked.

However, I stumbled upon the k3s certificate command, and I tried k3s certificate rotate just in case, and it worked!
So some certificate, somewhere was probably invalid, but I don't know why and I don't which one it was.

This was really tricky for me to debug, and in the end it was pure luck. Maybe some additional logging statements might be useful?

Thanks again!

[brandond]

If you can share the full stack dump from when you killed it, that would be helpful.

[MrTrustor]

Here you go: https://drive.google.com/file/d/1K0lRosHGlsxgur57CWbVM9iYcmRByWHq/view?usp=sharing

[brandond]

Thanks!

Mar 01 06:03:30 k8s-1 k3s[2002157]: goroutine 31655 gp=0xc001401a40 m=nil [select]:
Mar 01 06:03:30 k8s-1 k3s[2002157]: runtime.gopark(0xc0131bbde8?, 0x2?, 0x10?, 0xe2?, 0xc0131bbdc4?)
Mar 01 06:03:30 k8s-1 k3s[2002157]:         /usr/local/go/src/runtime/proc.go:402 +0xce fp=0xc01cf07c68 sp=0xc01cf07c48 pc=0x44652e
Mar 01 06:03:30 k8s-1 k3s[2002157]: runtime.selectgo(0xc01cf07de8, 0xc0131bbdc0, 0xc001180ee0?, 0x0, 0xc001180ee0?, 0x1)
Mar 01 06:03:30 k8s-1 k3s[2002157]:         /usr/local/go/src/runtime/select.go:327 +0x725 fp=0xc01cf07d88 sp=0xc01cf07c68 pc=0x458b25
Mar 01 06:03:30 k8s-1 k3s[2002157]: k8s.io/apimachinery/pkg/util/wait.loopConditionUntilContext({0x7740c18, 0xc001180ee0}, {0x77237f0, 0xc01e337160}, 0x1, 0x0, 0xc01cf07f48)
Mar 01 06:03:30 k8s-1 k3s[2002157]:         /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/[email protected]/pkg/util/wait/loop.go:66 +0x1e6 fp=0xc01cf07e38 sp=0xc01cf07d88 pc=0xd2b866
Mar 01 06:03:30 k8s-1 k3s[2002157]: k8s.io/apimachinery/pkg/util/wait.PollUntilContextTimeout({0x7740ba8?, 0xc0013dd860?}, 0x3b9aca00, 0x1?, 0x1, 0xc016623f48)
Mar 01 06:03:30 k8s-1 k3s[2002157]:         /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/[email protected]/pkg/util/wait/poll.go:48 +0xa5 fp=0xc01cf07ea8 sp=0xc01cf07e38 pc=0xd2bd85
Mar 01 06:03:30 k8s-1 k3s[2002157]: github.com/k3s-io/k3s/pkg/util.WaitForAPIServerReady({0x7740ba8, 0xc0013dd860}, {0xc001905340?, 0xc0021f9980?}, 0x6fc23ac00)
Mar 01 06:03:30 k8s-1 k3s[2002157]:         /go/src/github.com/k3s-io/k3s/pkg/util/api.go:82 +0x1e5 fp=0xc01cf07f70 sp=0xc01cf07ea8 pc=0x262f265
Mar 01 06:03:30 k8s-1 k3s[2002157]: github.com/k3s-io/k3s/pkg/daemons/control.waitForAPIServerInBackground.func1.1()
Mar 01 06:03:30 k8s-1 k3s[2002157]:         /go/src/github.com/k3s-io/k3s/pkg/daemons/control/server.go:465 +0x37 fp=0xc01cf07fa8 sp=0xc01cf07f70 pc=0x4c152d7
Mar 01 06:03:30 k8s-1 k3s[2002157]: github.com/k3s-io/k3s/pkg/daemons/control.promise.func1()
Mar 01 06:03:30 k8s-1 k3s[2002157]:         /go/src/github.com/k3s-io/k3s/pkg/daemons/control/server.go:481 +0x23 fp=0xc01cf07fe0 sp=0xc01cf07fa8 pc=0x4c15423
Mar 01 06:03:30 k8s-1 k3s[2002157]: runtime.goexit({})
Mar 01 06:03:30 k8s-1 k3s[2002157]:         /usr/local/go/src/runtime/asm_amd64.s:1695 +0x1 fp=0xc01cf07fe8 sp=0xc01cf07fe0 pc=0x4802c1
Mar 01 06:03:30 k8s-1 k3s[2002157]: created by github.com/k3s-io/k3s/pkg/daemons/control.promise in goroutine 4371
Mar 01 06:03:30 k8s-1 k3s[2002157]:         /go/src/github.com/k3s-io/k3s/pkg/daemons/control/server.go:480 +0x78

For some reason it was just stuck in that WaitForAPIServerReady PollUntilContextTimeout loop. It must have been failing at the restClient.Get phase because if it had successfully made the request but got a bad HTTP status we would have seen a log message.

I've never seen this before, but we can add some logging to that path in case this happens again.