k3s fails to start with (slow?)nfs and sqlite datastore endpoint

[carlmontanari]

Environmental Info: K3s Version: rancher/k3s:v1.24.1-k3s1

Node(s) CPU architecture, OS, and Version: Linux c1-0 5.15.0-40-generic #43-Ubuntu SMP Wed Jun 15 12:54:21 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

Cluster Configuration: k3s is being deployed via loft/vcluster in a 3 node vanilla k8s cluster (1.24.2) running on ubuntu jammy (nodes like above)

Describe the bug: k3s controller pod continually crashes due to timeouts on startup. This appears to only happen when running the default sqlite datastore endpoint on a cluster with nfs as the default storageclass.

Steps To Reproduce:

• have a cluster with nfs as default storage class -- perhaps from google engineering on this it may have to be a "slow" nfs store that is causing this? (this is in a home lab scenario running nfs off a truenas vm in promox w/ ssd passthrough disks to it, the k8s cluster/k3s pod is running in the same physical server on different ubuntu vms)
• install vcluster into the cluster (via helm/loft/vcluster cli) with default settings (we use k3s as our default distro)

Expected behavior: k3s controller starts up and operates normally

Actual behavior: k3s pod crashes repeatedly, logs show loads of "etcd" (kine I guess) deadline exceeded errors, and we see controllers failing to register.

Additional context / logs: Changing the datastore endpoint to etcd causes the vcluster/k3s pod to operate normally. Disabling storage persistence in vcluster also "fixes" this issue (meaning we dont run the datastore in a pvc, but just in EmptyDir)

See issue in vcluster as well

Full pod logs: localdir-logs.log

And logs from a successful vcluster/k3s startup where we use the persistance=>false setting (so emptyDir instead of pvc on nfs): pvc-logs.log

[brandond]

I'm a little unclear here - the file you attached as localdir-logs.log appears to be from k3s itself. Are you saying that you're running k3s in k3s, with the inner k3s node running on a nfs PV? In general I don't advise running K3s on nfs; it has locking and other filesystem semantics that don't work well with sqlite and containerd.

The only error I see is regarding garbage collection; it seems like it's trying to GC an object that doesn't exist. I've not seen this before; is this inner k3s running vcluster, or just bog-standard k3s?

E0804 17:07:47.459905 7 garbagecollector.go:374] error syncing item &garbagecollector.node{identity:garbagecollector.objectReference{OwnerReference:v1.OwnerReference{APIVersion:"discovery.k8s.io/v1", Kind:"EndpointSlice", Name:"kube-dns-9xrzm", UID:"e6bf1252-0a93-41d2-a476-0bc93619abc5", Controller:(*bool)(nil), BlockOwnerDeletion:(*bool)(nil)}, Namespace:"kube-system"}, dependentsLock:sync.RWMutex{w:sync.Mutex{state:0, sema:0x0}, writerSem:0x0, readerSem:0x0, readerCount:1, readerWait:0}, dependents:map[*garbagecollector.node]struct {}{}, deletingDependents:false, deletingDependentsLock:sync.RWMutex{w:sync.Mutex{state:0, sema:0x0}, writerSem:0x0, readerSem:0x0, readerCount:0, readerWait:0}, beingDeleted:false, beingDeletedLock:sync.RWMutex{w:sync.Mutex{state:0, sema:0x0}, writerSem:0x0, readerSem:0x0, readerCount:0, readerWait:0}, virtual:false, virtualLock:sync.RWMutex{w:sync.Mutex{state:0, sema:0x0}, writerSem:0x0, readerSem:0x0, readerCount:0, readerWait:0}, owners:[]v1.OwnerReference{v1.OwnerReference{APIVersion:"v1", Kind:"Service", Name:"kube-dns", UID:"b0ac8294-abde-486a-8681-17fd0516cc7e", Controller:(*bool)(0xc00f974aca), BlockOwnerDeletion:(*bool)(0xc00f974acb)}}}: endpointslices.discovery.k8s.io "kube-dns-9xrzm" not found

[carlmontanari]

Ah sorry about that! Yeah, both of the logs should be from k3s itself -- im running k3s in k8s. The parent k8s cluster has the nfs storage class.

When we deploy vcluster we deploy a distro (k3s/k0s/k8s, in this case k3s of course) as a container, and a "syncer" (loft vcluster thing) container in a pod in a host/parent cluster. The container for k3s is just standard rancher/k3s:v1.24.1-k3s1 (though I have tried this with another version or two as well just to make sure there wasn't something silly going on).

Totally hear you on the nfs thing 😁, and for my personal use I just dont persist the storage (so we use localdir instead, avoiding nfs), and/or swap the datastore to etcd and all is well. Just hoping to share this and see if there is a fix, as I'm sure others will run into this when using vcluster/k3s especially in homelabs!

Let me know if that is more coherent, and thanks for the crazy fast response!

[brandond]

Does this only happen when the container is running on NFS? Honestly I'm surprised containerd works at all; I would have expected that to blow up before the datastore or apiserver. Or are the inner cluster nodes running with --disable-agent?

Just out of curiosity, you might see what happens if you start the inner k3s with --cluster-init to use embedded etcd instead of sqlite? Honestly I think it would have an even harder time than sqlite, but it's worth trying.

[carlmontanari]

Does this only happen when the container is running on NFS?

As far as I know yes that is correct.

Or are the inner cluster nodes running with --disable-agent

Also correct, yep here is the full launch args from the pod spec:

  - args:
    - -c
    - /bin/k3s server --write-kubeconfig=/data/k3s-config/kube-config.yaml --data-dir=/data
      --disable=traefik,servicelb,metrics-server,local-storage,coredns --disable-network-policy
      --disable-agent --disable-cloud-controller --flannel-backend=none --disable-scheduler
      --kube-controller-manager-arg=controllers=*,-nodeipam,-nodelifecycle,-persistentvolume-binder,-attachdetach,-persistentvolume-expander,-cloud-node-lifecycle
      --kube-apiserver-arg=endpoint-reconciler-type=none --service-cidr=10.101.0.0/16
      && true
    command:
    - /bin/sh

Just out of curiosity, you might see what happens if you start the inner k3s with --cluster-init to use embedded etcd instead of sqlite

Yep, works. Same if we change to the datastore endpoint -> etcd (maybe those are effectively the same thing?).

[moyuduo]

@carlmontanari hello! i meet this issue too when using vcluster to create a cluster, but unlike you i use openebs localpv provisioner. in my case k3s container also has many DeadlineExceeded log.

E0816 02:41:39.147209      43 timeout.go:137] post-timeout activity - time-elapsed: 963.261635ms, GET "/readyz" result: <nil>
{"level":"warn","ts":"2022-08-16T02:41:39.182Z","logger":"etcd-client","caller":"v3@v3.5.1-k3s1/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc003277340/kine.sock","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
E0816 02:41:39.184433      43 timeout.go:137] post-timeout activity - time-elapsed: 1.004674008s, GET "/healthz" result: Header called after Handler finished
goroutine 323754 [running]:
k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP.func1.1()
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/server/filters/timeout.go:105 +0xb0
panic({0x3f26ea0, 0x50a5fc0})
        /usr/local/go/src/runtime/panic.go:1038 +0x215
golang.org/x/net/http2.(*responseWriter).Header(0x7995500)
        /go/pkg/mod/golang.org/x/net@v0.0.0-20210825183410-e898025ed96a/http2/server.go:2616 +0x71
net/http.Error({0x5138fc8, 0xc012794148}, {0xc0017d7b00, 0x427}, 0x2)
        /usr/local/go/src/net/http/server.go:2057 +0x46
k8s.io/apiserver/pkg/server/healthz.handleRootHealth.func1({0x514c6a8, 0xc019ade4c0}, 0xc00c776b00)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/server/healthz/healthz.go:258 +0x87f
k8s.io/apiserver/pkg/endpoints/metrics.InstrumentHandlerFunc.func1({0x514c6a8, 0xc019ade000}, 0xc00c776b00)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/metrics/metrics.go:526 +0x214
net/http.HandlerFunc.ServeHTTP(0xc019a2aba0, {0x514c6a8, 0xc019ade000}, 0x8)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/server/mux.(*pathHandler).ServeHTTP(0xc00a230740, {0x514c6a8, 0xc019ade000}, 0xc00c776b00)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/server/mux/pathrecorder.go:241 +0x210
k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).ServeHTTP(0xc019a2aba0, {0x514c6a8, 0xc019ade000}, 0x0)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/server/mux/pathrecorder.go:234 +0x70
k8s.io/apiserver/pkg/server.director.ServeHTTP({{0x47a5e47, 0x508b2c0}, 0xc000836ea0, 0xc000136af0}, {0x514c6a8, 0xc019ade000}, 0xc00c776b00)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/server/handler.go:154 +0x75c
k8s.io/apiserver/pkg/endpoints/filters.WithWebhookDuration.func1({0x514c6a8, 0xc019ade000}, 0xc00c776900)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filters/webhook_duration.go:31 +0x24e
net/http.HandlerFunc.ServeHTTP(0xc024654610, {0x514c6a8, 0xc019ade000}, 0xbb544a)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1({0x514c6a8, 0xc019ade000}, 0xc00c776900)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filterlatency/filterlatency.go:104 +0x1a5
net/http.HandlerFunc.ServeHTTP(0xc0090c28e8, {0x514c6a8, 0xc019ade000}, 0xc027bdb050)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filters.WithAuthorization.func1({0x514c6a8, 0xc019ade000}, 0xc00c776900)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filters/authorization.go:64 +0x425
net/http.HandlerFunc.ServeHTTP(0x7bae5a8, {0x514c6a8, 0xc019ade000}, 0xa)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1({0x514c6a8, 0xc019ade000}, 0xc00c776900)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filterlatency/filterlatency.go:80 +0x178
net/http.HandlerFunc.ServeHTTP(0xc024654948, {0x514c6a8, 0xc019ade000}, 0xbb544a)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1({0x514c6a8, 0xc019ade000}, 0xc00c776900)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filterlatency/filterlatency.go:104 +0x1a5
net/http.HandlerFunc.ServeHTTP(0xc01630eec0, {0x514c6a8, 0xc019ade000}, 0xc018f924e0)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/server/filters.WithPriorityAndFairness.func1.9()
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/server/filters/priority-and-fairness.go:278 +0x118
k8s.io/apiserver/pkg/util/flowcontrol.(*configController).Handle.func2()
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/util/flowcontrol/apf_filter.go:191 +0x1eb
k8s.io/apiserver/pkg/util/flowcontrol.immediateRequest.Finish(...)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/util/flowcontrol/apf_controller.go:793
k8s.io/apiserver/pkg/util/flowcontrol.(*configController).Handle(0xc000152140, {0x516dc60, 0xc0179499e0}, {0xc02110e840, {0x51701c8, 0xc01630ee00}}, 0x1, 0x511fce0, 0xc01bb75440, 0xc00a6ce6e0)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/util/flowcontrol/apf_filter.go:181 +0x853
k8s.io/apiserver/pkg/server/filters.WithPriorityAndFairness.func1({0x514c6a8, 0xc019ade000}, 0xc00c776900)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/server/filters/priority-and-fairness.go:281 +0xdda
net/http.HandlerFunc.ServeHTTP(0x7bae5a8, {0x514c6a8, 0xc019ade000}, 0xa)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1({0x514c6a8, 0xc019ade000}, 0xc00c776900)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filterlatency/filterlatency.go:80 +0x178
net/http.HandlerFunc.ServeHTTP(0xc024655088, {0x514c6a8, 0xc019ade000}, 0xbb544a)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1({0x514c6a8, 0xc019ade000}, 0xc00c776900)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filterlatency/filterlatency.go:104 +0x1a5
net/http.HandlerFunc.ServeHTTP(0xc0246556d0, {0x514c6a8, 0xc019ade000}, 0xf)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filters.WithImpersonation.func1({0x514c6a8, 0xc019ade000}, 0xc00c776800)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filters/impersonation.go:182 +0x1f3f
net/http.HandlerFunc.ServeHTTP(0x7bae5a8, {0x514c6a8, 0xc019ade000}, 0xa)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1({0x514c6a8, 0xc019ade000}, 0xc00c776800)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filterlatency/filterlatency.go:80 +0x178
net/http.HandlerFunc.ServeHTTP(0xc024655948, {0x514c6a8, 0xc019ade000}, 0xbb544a)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1({0x514c6a8, 0xc019ade000}, 0xc00c776800)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filterlatency/filterlatency.go:104 +0x1a5
net/http.HandlerFunc.ServeHTTP(0x7bae5a8, {0x514c6a8, 0xc019ade000}, 0xa)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1({0x514c6a8, 0xc019ade000}, 0xc00c776800)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filterlatency/filterlatency.go:80 +0x178
net/http.HandlerFunc.ServeHTTP(0xc024655b50, {0x514c6a8, 0xc019ade000}, 0xbb544a)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1({0x514c6a8, 0xc019ade000}, 0xc00c776800)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filterlatency/filterlatency.go:104 +0x1a5
net/http.HandlerFunc.ServeHTTP(0x516dc60, {0x514c6a8, 0xc019ade000}, 0x4b4b4f8)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filters.withAuthentication.func1({0x514c6a8, 0xc019ade000}, 0xc00c776800)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filters/authentication.go:80 +0x839
net/http.HandlerFunc.ServeHTTP(0x516dc28, {0x514c6a8, 0xc019ade000}, 0x508b2c0)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1({0x514c6a8, 0xc019ade000}, 0xc00c776500)
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/endpoints/filterlatency/filterlatency.go:89 +0x46b
net/http.HandlerFunc.ServeHTTP(0x1ac240b, {0x514c6a8, 0xc019ade000}, 0x1)
        /usr/local/go/src/net/http/server.go:2047 +0x2f
k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP.func1()
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/server/filters/timeout.go:110 +0x70
created by k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP
        /go/pkg/mod/github.com/k3s-io/kubernetes/staging/src/k8s.io/apiserver@v1.23.3-k3s1/pkg/server/filters/timeout.go:96 +0x18f

k3s container args:

Command:
      /bin/k3s
    Args:
      server
      --write-kubeconfig=/data/k3s-config/kube-config.yaml
      --data-dir=/data
      --disable=traefik,servicelb,metrics-server,local-storage,coredns
      --disable-network-policy
      --disable-agent
      --disable-scheduler
      --disable-cloud-controller
      --flannel-backend=none
      --kube-controller-manager-arg=controllers=*,-nodeipam,-nodelifecycle,-persistentvolume-binder,-attachdetach,-persistentvolume-expander,-cloud-node-lifecycle
      --service-cidr=10.96.0.0/12

By the way my vcluster version is loftsh/vcluster:0.7.0-alpha.2. Is this issue can be resolved by replace sqlite with etcd as storage in k3s?

[brandond]

Etcd performs worse than sqlite on slow storage. Not using etcd for this reason was one of the original goals of k3s.

[carlmontanari]

@moyuduo You can certainly give it a shot. You can also try with k8s or k0s distributions to see if that changes anything. But, its probably better to post about that over on vcluster here.

@brandond defo don't let me stop you from closing this one -- just wanted to open it up to see if there was something obviously wrong in my setup and at least have some context for any other vcluster users that may encounter this. Thanks a bunch for your help!