cloud-controller-manager exited

[janekmichalik]

Environmental Info:
K3s Version:

root@<hidden>:/home/devuser# k3s -v
k3s version v1.25.4+k3s1 (0dc63334)
go version go1.19.3

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

AWS EC2 instance:

root@<hidden>:/home/<hidden># cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=20.04
DISTRIB_CODENAME=focal
DISTRIB_DESCRIPTION="Ubuntu 20.04.6 LTS"
root@<hidden>:/home/<hidden>#
root@<hidden>:/home/<hidden># uname -a
Linux <hidden> 5.11.0-1016-aws #17~20.04.1-Ubuntu SMP Thu Aug 12 05:39:36 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
root@<hidden>:/home/<hidden># cat /proc/cpuinfo | grep 'vendor' | uniq
vendor_id	: AuthenticAMD
root@<hidden>:/home/<hidden># cat /proc/cpuinfo | grep 'model name' | uniq
model name	: AMD EPYC 7R32
root@<hidden>:/home/<hidden># cat /proc/cpuinfo | grep processor | wc -l
32

Cluster Configuration: 1 server only

Describe the bug:

cloud-controller-manager exited due to Apr 20 13:02:35 <hidden> k3s[84782]: time="2023-04-20T13:02:35+02:00" level=error msg="cloud-controller-manager exited: unable to load configmap based request-header-client-ca-file: configmaps \"extension-apiserver-authentication\" is forbidden: User \"k3s-cloud-controller-manager\" cannot get resource \"configmaps\" in API group \"\" in the namespace \"kube-system\"", the role was created at "2023-04-20T13:02:30Z" and the role binding was created at "2023-04-20T13:02:36Z". It means that at the moment when cloud-controller-manager tries to get config map, it has not permissions due to lack of role binding. And it causes that taint node.cloudprovider.kubernetes.io/uninitialized=true:NoSchedule remains on the node and pods stay in pending state.

Restarting the k3s service resolves the issue, cloud-controller is restarted and the role binding already exists, that is probably why it is working after k3s restart, but it is not how it should work.

Steps To Reproduce:

• Installed K3s:

INSTALL_K3S_VERSION=v1.25.4+k3s1 INSTALL_K3S_EXEC="--disable traefik --service-node-port-range 30000-30050
--kube-apiserver-arg=enable-admission-plugins=NodeRestriction,ServiceAccount --kube-apiserver-arg=request-timeout=5m0s
--kube-apiserver-arg=audit-log-path=/var/lib/rancher/k3s/server/logs/audit.log
--kube-apiserver-arg=tls-cipher-suites=TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305,TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305,TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
--kube-apiserver-arg=audit-log-maxbackup=10 --kube-controller-manager-arg=terminated-pod-gc-threshold=1000
--kube-controller-manager-arg=leader-elect-lease-duration=30s --kube-controller-manager-arg=leader-elect-renew-deadline=20s
--kube-controller-manager-arg=bind-address=127.0.0.1 --kube-scheduler-arg=bind-address=127.0.0.1
--kubelet-arg=streaming-connection-idle-timeout=5m --kubelet-arg=rotate-server-certificates=true
--kubelet-arg=eviction-hard=imagefs.available<20Gi,memory.available<100Mi,nodefs.available<20Gi,nodefs.inodesFree<5%
--kubelet-arg=eviction-minimum-reclaim=imagefs.available=1Gi,nodefs.available=1Gi" ./k3s_installer.sh

I do not have steps to reproduce, as it occurs periodically.

Expected behavior:

cloud-controller-manager running properly, maybe it should ensure that role and role binding are created before trying to get the configmap.

Actual behavior:

cloud-controller-manager exited, it was not able to get the required config map due to lack of permissions.

Additional context / logs:

role details:

root@<hidden>:~# kubectl get role -n kube-system extension-apiserver-authentication-reader -o yaml
apiVersion: rbac.authorization.k8s.io/v1
kind: Role
metadata:
  annotations:
    rbac.authorization.kubernetes.io/autoupdate: "true"
  creationTimestamp: "2023-04-20T13:02:30Z"
  labels:
    kubernetes.io/bootstrapping: rbac-defaults
  name: extension-apiserver-authentication-reader
  namespace: kube-system
  resourceVersion: "176"
  uid: bd705934-437e-45e4-9233-b6982d11d1d0
rules:
- apiGroups:
  - ""
  resourceNames:
  - extension-apiserver-authentication
  resources:
  - configmaps
  verbs:
  - get
  - list
  - watch

role binding details:

root@<hidden>:~# kubectl -n kube-system get rolebinding -o yaml k3s-cloud-controller-manager-authentication-reader
apiVersion: rbac.authorization.k8s.io/v1
kind: RoleBinding
metadata:
  annotations:
    objectset.rio.cattle.io/applied: <hidden>
    objectset.rio.cattle.io/id: ""
    objectset.rio.cattle.io/owner-gvk: k3s.cattle.io/v1, Kind=Addon
    objectset.rio.cattle.io/owner-name: ccm
    objectset.rio.cattle.io/owner-namespace: kube-system
  creationTimestamp: "2023-04-20T13:02:36Z"
  labels:
    objectset.rio.cattle.io/hash: 5089468545c5482413c7f05e837e9b88f02ad052
  name: k3s-cloud-controller-manager-authentication-reader
  namespace: kube-system
  resourceVersion: "247"
  uid: b8168fc0-0d35-461a-b5a4-8d41a7215c4d
roleRef:
  apiGroup: rbac.authorization.k8s.io
  kind: Role
  name: extension-apiserver-authentication-reader
subjects:
- apiGroup: rbac.authorization.k8s.io
  kind: User
  name: k3s-cloud-controller-manager
  namespace: kube-system

journalctl logs related to cloud controller:

root@<hidden>:~# journalctl -u k3s.service | grep cloud-controller
Apr 20 13:02:25 <hidden>k3s[84782]: time="2023-04-20T13:02:25+02:00" level=info msg="certificate CN=k3s-cloud-controller-manager signed by CN=k3s-client-ca@1681995745: notBefore=2023-04-20 13:02:25 +0000 UTC notAfter=2024-04-19 13:02:25 +0000 UTC"
Apr 20 13:02:25 <hidden> k3s[84782]: time="2023-04-20T13:02:25+02: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-config=/var/lib/rancher/k3s/server/etc/cloud-config.yaml --cloud-provider=k3s --cluster-cidr=10.42.0.0/16 --configure-cloud-routes=false --controllers=*,-route --kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig --leader-elect=false --leader-elect-resource-name=k3s-cloud-controller-manager --node-status-update-frequency=1m0s --profiling=false"
Apr 20 13:02:31 <hidden> k3s[84782]: time="2023-04-20T13:02:31+02:00" level=info msg="Waiting for cloud-controller-manager privileges to become available"
Apr 20 13:02:35 <hidden> k3s[84782]: unable to load configmap based request-header-client-ca-file: configmaps "extension-apiserver-authentication" is forbidden: User "k3s-cloud-controller-manager" cannot get resource "configmaps" in API group "" in the namespace "kube-system"
Apr 20 13:02:35 <hidden> k3s[84782]: Error: unable to load configmap based request-header-client-ca-file: configmaps "extension-apiserver-authentication" is forbidden: User "k3s-cloud-controller-manager" cannot get resource "configmaps" in API group "" in the namespace "kube-system"
Apr 20 13:02:35 <hidden> k3s[84782]:   cloud-controller-manager [flags]
Apr 20 13:02:35 <hidden> k3s[84782]:       --leader-elect-resource-name string        The name of resource object that is used for locking during leader election. (default "cloud-controller-manager")
Apr 20 13:02:35 <hidden> k3s[84782]:   -h, --help                             help for cloud-controller-manager
Apr 20 13:02:35 <hidden> k3s[84782]: time="2023-04-20T13:02:35+02:00" level=error msg="cloud-controller-manager exited: unable to load configmap based request-header-client-ca-file: configmaps \"extension-apiserver-authentication\" is forbidden: User \"k3s-cloud-controller-manager\" cannot get resource \"configmaps\" in API group \"\" in the namespace \"kube-system\""
Apr 20 13:02:36 <hidden> k3s[84782]: time="2023-04-20T13:02:36+02:00" level=info msg="Slow SQL (started: 2023-04-20 13:02:33.991100151 +000 CEST m=+15.104670164) (total time: 2.104021479s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?) : [[/registry/clusterrolebindings/k3s-cloud-controller-manager-auth-delegator 1 0 0 0 0 [<hidden>]
Apr 20 13:02:36 <hidden> k3s[84782]: I0420 13:02:36.095642   84782 trace.go:205] Trace[1885216390]: "Create etcd3" audit-id:239071e7-361e-4035-83d9-c50e59baa653,key:/clusterrolebindings/k3s-cloud-controller-manager-auth-delegator,type:*rbac.ClusterRoleBinding (20-Apr-2023 13:02:33.990) (total time: 2105ms):

[brandond]

maybe it should ensure that role and role binding are created before trying to get the configmap.

It does, actually, although it only checks for our custom RBAC, not core Kubernetes RBAC.

k3s/pkg/daemons/control/server.go

Lines 380 to 392 in 944f811

	// checkForCloudControllerPrivileges makes a SubjectAccessReview request to the apiserver
	// to validate that the embedded cloud controller manager has the required privileges,
	// and does not return until the requested access is granted.
	// If the CCM RBAC changes, the ResourceAttributes checked for by this function should
	// be modified to check for the most recently added privilege.
	func checkForCloudControllerPrivileges(ctx context.Context, runtime *config.ControlRuntime, timeout time.Duration) error {
	return util.WaitForRBACReady(ctx, runtime.KubeConfigAdmin, timeout, authorizationv1.ResourceAttributes{
	Namespace: metav1.NamespaceSystem,
	Verb: "watch",
	Resource: "endpointslices",
	Group: "discovery.k8s.io",
	}, version.Program+"-cloud-controller-manager")
	}

Can you post the complete server logs? In the snippet you quoted I see some slow SQL warnings:

Apr 20 13:02:36 <hidden> k3s[84782]: time="2023-04-20T13:02:36+02:00" level=info msg="Slow SQL (started: 2023-04-20 13:02:33.991100151 +000 CEST m=+15.104670164) (total time: 2.104021479s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?) : [[/registry/clusterrolebindings/k3s-cloud-controller-manager-auth-delegator 1 0 0 0 0 [<hidden>]

This makes me think that there's something else going on with your datastore performance that's causing some of the core RBAC to be missing at this point even though our custom RBAC is present. Access to the extension-apiserver-authentication configmap should be granted by the core Kuberneres role extension-apiserver-authentication-reader that for some reason is taking excessively long to be created on your node.

What kind of disk are you using? How many cores and how much memory does this node have? It looks like you're just using the embedded sqlite datastore, which is generally pretty forgiving of slow disk, but the times between your log messages are much longer than I would expect.

[janekmichalik]

root@<hidden>:/home/<hidden># grep MemTotal /proc/meminfo
MemTotal:       130524204 kB

root@<hidden>:/home/<hidden># grep 'cpu cores' /proc/cpuinfo | uniq
cpu cores	: 16

root@<hidden>:/home/<hidden># lshw -c storage -c disk
  *-storage:0
       description: Non-Volatile memory controller
       product: Amazon.com, Inc.
       vendor: Amazon.com, Inc.
       physical id: 4
       bus info: pci@0000:00:04.0
       version: 00
       width: 32 bits
       clock: 33MHz
       capabilities: storage pciexpress msix nvm_express bus_master cap_list
       configuration: driver=nvme latency=0
       resources: irq:11 memory:fd010000-fd013fff
     *-nvme0
          description: NVMe device
          product: Amazon Elastic Block Store
          physical id: 0
          logical name: /dev/nvme0
          version: 1.0
          serial: vol0b802cac479ac41bb
          configuration: nqn=nqn.2014.08.org.nvmexpress:1d0f1d0fvol0b802cac479ac41bbAmazon Elastic Block Store state=live
        *-namespace
             description: NVMe namespace
             physical id: 1
             logical name: /dev/nvme0n1
             size: 550GiB (590GB)
             capabilities: partitioned partitioned:dos
             configuration: logicalsectorsize=512 sectorsize=512 signature=0f25cffe
  *-storage:1
       description: Non-Volatile memory controller
       product: NVMe SSD Controller
       vendor: Amazon.com, Inc.
       physical id: 1f
       bus info: pci@0000:00:1f.0
       version: 00
       width: 32 bits
       clock: 33MHz
       capabilities: storage pciexpress msix nvm_express bus_master cap_list
       configuration: driver=nvme latency=0
       resources: irq:0 memory:fd018000-fd01bfff memory:fe800000-fe801fff
     *-nvme1
          description: NVMe device
          product: Amazon EC2 NVMe Instance Storage
          physical id: 0
          logical name: /dev/nvme1
          version: 0
          serial: AWS2236BE4FA42C13BFE
          configuration: nqn=nqn.2008-08.com.amazon.aws:ec2-nvme-instance:AWS2236BE4FA42C13BFE state=live
        *-namespace
             description: NVMe namespace
             physical id: 1
             logical name: /dev/nvme1n1
             size: 838GiB (900GB)
             configuration: logicalsectorsize=512 sectorsize=512

Currently, I m not able to attach full logs from journalctl, as the error is once appearing and once not.

@brandond

[brandond]

If you're running on ec2, have you checked the cloudwatch metrics to see if your instance or disk volumes are running out of CPU or io credits and being throttled?

[janekmichalik]

@brandond I do not have access there currently, trying to get one.

I found another reproduction of the issue, and I have gathered logs.
k3s.log

[brandond]

Yeah something is definitely wrong with your disk. Just creating the very first row in the database during initial setup caused a slow SQL error. This process normally takes like, milliseconds at the most.

Apr 24 11:54:04 <hidden> k3s[84855]: time="2023-04-24T11:54:04+02:00" level=info msg="Configuring sqlite3 database connection pooling: maxIdleConns=2, maxOpenConns=0, connMaxLifetime=0s"
Apr 24 11:54:04 <hidden> k3s[84855]: time="2023-04-24T11:54:04+02:00" level=info msg="Configuring database table schema and indexes, this may take a moment..."
Apr 24 11:54:07 <hidden> k3s[84855]: time="2023-04-24T11:54:07+02:00" level=info msg="Database tables and indexes are up to date"
Apr 24 11:54:09 <hidden> k3s[84855]: time="2023-04-24T11:54:09+02:00" level=info msg="Slow SQL (started: 2023-04-24 11:54:07.941613409 +0200 CEST m=+7.038912399) (total time: 1.536657724s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?) : [[compact_rev_key 1 0 0 0 0 [] []]]"
Apr 24 11:54:09 <hidden> k3s[84855]: time="2023-04-24T11:54:09+02:00" level=info msg="Kine available at unix://kine.sock"

1.5 seconds to insert the very first row in the databse, before ANYTHING else is running, is bonkers slow. Figure out why the IO on this node is so bad and your problems should go away.