[Bug]: Creation stuck on waiting for the system-upgrade-controller

[mducoli]

Description

Hi, I'm trying to deploy a single node cluster but the creation gets stuck on waiting for the system-upgrade-controller deployment to become available (stuck on "Still creating...").
Here is the log:

module.kube-hetzner.null_resource.kustomization (remote-exec): + echo 'Waiting for the system-upgrade-controller deployment to become available...'
module.kube-hetzner.null_resource.kustomization (remote-exec): Waiting for the system-upgrade-controller deployment to become available...
module.kube-hetzner.null_resource.kustomization (remote-exec): + kubectl -n system-upgrade wait --for=condition=available --timeout=360s deployment/system-upgrade-controller
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec): + mkdir -p /etc/rancher/k3s
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec): + '[' -f /tmp/config.yaml ']'
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec): + mv /tmp/config.yaml /etc/rancher/k3s/config.yaml
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec): + chmod 0600 /etc/rancher/k3s/config.yaml
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec): + '[' -e /etc/rancher/k3s/k3s.yaml ']'
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec): + exit 0
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"]: Provisioning with 'remote-exec'...
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec): Connecting to remote host via SSH...
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec):   Host: 128.140.125.10
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec):   User: root
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec):   Password: false
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec):   Private key: true
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec):   Certificate: false
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec):   SSH Agent: false
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec):   Checking Host Key: false
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec):   Target Platform: unix
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"] (remote-exec): Connected!
module.kube-hetzner.null_resource.control_planes["0-0-control-plane-fsn1"]: Creation complete after 14s [id=8204391808950219635]
module.kube-hetzner.data.remote_file.kubeconfig: Reading...
module.kube-hetzner.data.remote_file.kubeconfig: Read complete after 1s [id=128.140.125.10:22:/etc/rancher/k3s/k3s.yaml]
module.kube-hetzner.local_sensitive_file.kubeconfig[0]: Creating...
module.kube-hetzner.local_sensitive_file.kubeconfig[0]: Creation complete after 0s [id=7b135c248f15516588c0fb17fdb72d7e2da5eb7f]
module.kube-hetzner.null_resource.kustomization: Still creating... [20s elapsed]
module.kube-hetzner.null_resource.kustomization: Still creating... [30s elapsed]

...

module.kube-hetzner.null_resource.kustomization: Still creating... [6m0s elapsed]
module.kube-hetzner.null_resource.kustomization: Still creating... [6m10s elapsed]
module.kube-hetzner.null_resource.kustomization (remote-exec): error: timed out waiting for the condition on deployments/system-upgrade-controller
╷
│ Error: remote-exec provisioner error
│ 
│   with module.kube-hetzner.null_resource.kustomization,
│   on .terraform/modules/kube-hetzner/init.tf line 260, in resource "null_resource" "kustomization":
│  260:   provisioner "remote-exec" {
│ 
│ error executing "/tmp/terraform_1489449519.sh": Process exited with status 1
╵

I read many issues but didn't find anything useful (#623 and #311 in particular).

I'm fairly new to Kubernetes and this project so I don't know if this is useful but logging into the machine I found that the system-upgrade-controller couldn't start because "had untolerated taint {node.cloudprovider.kubernetes.io/uninitialized: true}".

I also tried more than 10 different kube.tf but nothing changed.

Thanks for your help.

Kube.tf file

locals {
  hcloud_token = "..."
}

module "kube-hetzner" {
  providers = {
    hcloud = hcloud
  }
  hcloud_token = var.hcloud_token != "" ? var.hcloud_token : local.hcloud_token

  source = "kube-hetzner/kube-hetzner/hcloud"

  version = "2.6.0"

  ssh_public_key = file("...")
  ssh_private_key = file("...")

  network_region = "eu-central"

  cluster_name = "cluster_14"
  create_kustomization = false

  control_plane_nodepools = [
    {
      name        = "control-plane-fsn1",
      server_type = "cax21",
      location    = "fsn1",
      labels      = [],
      taints      = [],
      count       = 1
    } 
  ]

  agent_nodepools = [
    {
      name        = "agent-arm-small",
      server_type = "cax11",
      location    = "fsn1",
      labels      = [],
      taints      = [],
      count       = 0
    }
  ]

  automatically_upgrade_os = false
  automatically_upgrade_k3s = false
}

provider "hcloud" {
  token = var.hcloud_token != "" ? var.hcloud_token : local.hcloud_token
}

terraform {
  required_version = ">= 1.4.0"
  required_providers {
    hcloud = {
      source  = "hetznercloud/hcloud"
      version = ">= 1.41.0"
    }
  }
}

output "kubeconfig" {
  value     = module.kube-hetzner.kubeconfig
  sensitive = true
}

variable "hcloud_token" {
  sensitive = true
  default   = ""
}

Screenshots

No response

Platform

Linux

[Silvest89]

It's related to this
#907

TLDR:
It happens when scheduling on control plane nodes is possible

[mysticaltech]

@mducoli @DoubleREW Please try setting initial_k3s_channel to "v1.26", and also set cluster_autoscaler_version to "v1.26.4".

That should make it work. Now we also need to investigate why it's failing on v1.27, @kube-hetzner/core please don't hesitate to take this on, I'm a bit short on time lately.

And PR welcome if anyone find a fix to make v1.27 work with single node clusters. Don't hesitate to refer to the debug section in the readme.

[Silvest89]

@mysticaltech
The CCM runs with hostNetwork: true so I guess, it's either kubelet (or something else) port that is running on 10260 since 1.27

[M4t7e]

In Kubernetes 1.27 there was a change where a new feature (kubernetes/kubernetes#108838) was added. This will attempt to listen on port 10260.

Listening ports in K3s 1.27:

# ss -tlpen
State  Recv-Q Send-Q  Local Address:Port    Peer Address:Port Process                                                                                                                                                                                                                                                                            
LISTEN 0      4096        127.0.0.1:10248        0.0.0.0:*     users:(("k3s-server",pid=1938,fd=165)) ino:20446 sk:102e cgroup:/system.slice/k3s.service <->                                                                                                                                                                                     
LISTEN 0      4096        127.0.0.1:10249        0.0.0.0:*     users:(("k3s-server",pid=1938,fd=200)) ino:22471 sk:102f cgroup:/system.slice/k3s.service <->                                                                                                                                                                                     
LISTEN 0      4096        127.0.0.1:10256        0.0.0.0:*     users:(("k3s-server",pid=1938,fd=198)) ino:22469 sk:1030 cgroup:/system.slice/k3s.service <->                                                                                                                                                                                     
LISTEN 0      4096        127.0.0.1:10257        0.0.0.0:*     users:(("k3s-server",pid=1938,fd=177)) ino:20994 sk:1031 cgroup:/system.slice/k3s.service <->                                                                                                                                                                                     
LISTEN 0      4096        127.0.0.1:10259        0.0.0.0:*     users:(("k3s-server",pid=1938,fd=155)) ino:20796 sk:1032 cgroup:/system.slice/k3s.service <->                                                                                                                                                                                     
LISTEN 0      4096     10.0.255.101:2379         0.0.0.0:*     users:(("k3s-server",pid=1938,fd=11)) ino:20227 sk:1033 cgroup:/system.slice/k3s.service <->                                                                                                                                                                                      
LISTEN 0      4096     10.0.255.101:2380         0.0.0.0:*     users:(("k3s-server",pid=1938,fd=9)) ino:20225 sk:1034 cgroup:/system.slice/k3s.service <->                                                                                                                                                                                       
LISTEN 0      4096        127.0.0.1:2380         0.0.0.0:*     users:(("k3s-server",pid=1938,fd=10)) ino:20226 sk:1035 cgroup:/system.slice/k3s.service <->                                                                                                                                                                                      
LISTEN 0      4096        127.0.0.1:2381         0.0.0.0:*     users:(("k3s-server",pid=1938,fd=15)) ino:19263 sk:1036 cgroup:/system.slice/k3s.service <->                                                                                                                                                                                      
LISTEN 0      4096        127.0.0.1:2379         0.0.0.0:*     users:(("k3s-server",pid=1938,fd=12)) ino:20228 sk:1037 cgroup:/system.slice/k3s.service <->                                                                                                                                                                                      
LISTEN 0      4096        127.0.0.1:6444         0.0.0.0:*     users:(("k3s-server",pid=1938,fd=18)) ino:19392 sk:1038 cgroup:/system.slice/k3s.service <->                                                                                                                                                                                      
LISTEN 0      4096        127.0.0.1:9879         0.0.0.0:*     users:(("cilium-agent",pid=3805,fd=36)) ino:29376 sk:1039 cgroup:/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podb4dd4c59_73d5_4c9d_8e32_67ffe04260e5.slice/cri-containerd-0ad1a1b8dcadffaca1a7414c87e093087902f697b29e5052d6548461db831f00.scope <->              
LISTEN 0      4096        127.0.0.1:9890         0.0.0.0:*     users:(("cilium-agent",pid=3805,fd=6)) ino:28724 sk:103a cgroup:/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podb4dd4c59_73d5_4c9d_8e32_67ffe04260e5.slice/cri-containerd-0ad1a1b8dcadffaca1a7414c87e093087902f697b29e5052d6548461db831f00.scope <->               
LISTEN 0      4096        127.0.0.1:9891         0.0.0.0:*     users:(("cilium-operator",pid=3363,fd=3)) ino:26911 sk:103b cgroup:/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pode8ff8932_d26c_408f_8961_e0fd7f116aa5.slice/cri-containerd-b1897e301212c9a42b2f06fbb943a832db245fea6afdf8f34759358cd0fc4193.scope <->          
LISTEN 0      4096        127.0.0.1:10010        0.0.0.0:*     users:(("containerd",pid=1989,fd=11)) ino:20295 sk:103c cgroup:/system.slice/k3s.service <->                                                                                                                                                                                      
LISTEN 0      128           0.0.0.0:22           0.0.0.0:*     users:(("sshd",pid=1317,fd=3)) ino:18093 sk:103d cgroup:/system.slice/sshd.service <->                                                                                                                                                                                            
LISTEN 0      4096        127.0.0.1:9234         0.0.0.0:*     users:(("cilium-operator",pid=3363,fd=9)) ino:26922 sk:103e cgroup:/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pode8ff8932_d26c_408f_8961_e0fd7f116aa5.slice/cri-containerd-b1897e301212c9a42b2f06fbb943a832db245fea6afdf8f34759358cd0fc4193.scope <->          
LISTEN 0      4096        127.0.0.1:36121        0.0.0.0:*     users:(("cilium-agent",pid=3805,fd=30)) ino:28497 sk:103f fwmark:0xb00 cgroup:/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podb4dd4c59_73d5_4c9d_8e32_67ffe04260e5.slice/cri-containerd-0ad1a1b8dcadffaca1a7414c87e093087902f697b29e5052d6548461db831f00.scope <-> 
LISTEN 0      4096                *:9962               *:*     users:(("cilium-agent",pid=3805,fd=8)) ino:28433 sk:1040 cgroup:/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podb4dd4c59_73d5_4c9d_8e32_67ffe04260e5.slice/cri-containerd-0ad1a1b8dcadffaca1a7414c87e093087902f697b29e5052d6548461db831f00.scope v6only:0 <->      
LISTEN 0      4096                *:4244               *:*     users:(("cilium-agent",pid=3805,fd=55)) ino:29421 sk:1041 cgroup:/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podb4dd4c59_73d5_4c9d_8e32_67ffe04260e5.slice/cri-containerd-0ad1a1b8dcadffaca1a7414c87e093087902f697b29e5052d6548461db831f00.scope v6only:0 <->     
LISTEN 0      4096                *:4240               *:*     users:(("cilium-agent",pid=3805,fd=66)) ino:30256 sk:1042 cgroup:/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podb4dd4c59_73d5_4c9d_8e32_67ffe04260e5.slice/cri-containerd-0ad1a1b8dcadffaca1a7414c87e093087902f697b29e5052d6548461db831f00.scope v6only:0 <->     
LISTEN 0      4096                *:10250              *:*     users:(("k3s-server",pid=1938,fd=150)) ino:20442 sk:1043 cgroup:/system.slice/k3s.service v6only:0 <->                                                                                                                                                                            
LISTEN 0      128              [::]:22              [::]:*     users:(("sshd",pid=1317,fd=4)) ino:18095 sk:1044 cgroup:/system.slice/sshd.service v6only:1 <->                                                                                                                                                                                   
LISTEN 0      4096                *:10260              *:*     users:(("k3s-server",pid=1938,fd=199)) ino:23674 sk:1045 cgroup:/system.slice/k3s.service v6only:0 <->                                                                                                                                                                            
LISTEN 0      4096                *:6443               *:*     users:(("k3s-server",pid=1938,fd=7)) ino:20222 sk:1046 cgroup:/system.slice/k3s.service v6only:0 <->

With version 1.27 K3s binds itself to port 10260, but also Hetzner CCM tries to do the same. See the log output here:

# kubectl logs -f -n kube-system hcloud-cloud-controller-manager-b6b64df54-jkfwt
Flag --allow-untagged-cloud has been deprecated, This flag is deprecated and will be removed in a future release. A cluster-id will be required on cloud instances.
I0815 10:43:05.610031       1 serving.go:348] Generated self-signed cert in-memory
I0815 10:43:06.907824       1 serving.go:348] Generated self-signed cert in-memory
W0815 10:43:06.907870       1 client_config.go:618] Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
failed to create listener: failed to listen on 0.0.0.0:10260: listen tcp 0.0.0.0:10260: bind: address already in use
Error: failed to create listener: failed to listen on 0.0.0.0:10260: listen tcp 0.0.0.0:10260: bind: address already in use

I don't know exactly why Hetzner CCM is trying to listen on this port. It seems that this only happens for a few seconds on startup and after that the port is released. I saw the behaiviour on 1.26 for a short while during deployment with watch -n 0.1 ss -tlpen:

# ss -tlpen
[...]
LISTEN 0      4096                *:10260              *:*     users:(("hcloud-cloud-co",pid=11545,fd=3)) ino:152602 sk:9dae cgroup:/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod1dd0976e_3b5d_419d_adf0_5a1cdecbb677.slice/cri-containerd-30c55c84ce8ebb29b4584a59efe59a69c24aa9cba792ae9dc5062cafbad451db.scope v6only:0 <->

[apricote]

Hello 👋 Are you still running the k3s-included cloud-provider in addition to HCCM? That might explain why k3s is also trying to register that port.

[M4t7e]

Hey @apricote, thank you for reaching out! 🙂

I hope we don't do so. Here are all places where we set cloud-provider:

• terraform-hcloud-kube-hetzner/locals.tf

  Line 332 in 746ada7

  kubelet_arg = ["cloud-provider=external", "volume-plugin-dir=/var/lib/kubelet/volumeplugins"]

• terraform-hcloud-kube-hetzner/templates/autoscaler.yaml.tpl

  Line 172 in 746ada7

  - --cloud-provider=hetzner

• terraform-hcloud-kube-hetzner/templates/ccm.yaml.tpl

  Line 14 in 746ada7

  - "--cloud-provider=hcloud"

Here is where we disable the embedded CCM:

• Initialization CP node:
  

  terraform-hcloud-kube-hetzner/init.tf

  Line 18 in 746ada7

  disable-cloud-controller = true

• Other CP nodes:
  

  terraform-hcloud-kube-hetzner/control_planes.tf

  Line 107 in 746ada7

  disable-cloud-controller = true

Here are the node-args from kubectl get nodes -o yaml command:

[
  "server",
  "--advertise-address", "10.0.255.101",
  "--cluster-cidr", "10.0.128.0/17",
  "--cluster-init", "true",
  "--disable", "local-storage",
  "--disable", "traefik",
  "--disable-cloud-controller", "true",
  "--disable-network-policy", "true",
  "--flannel-backend", "none",
  "--flannel-iface", "eth1",
  "--kube-controller-manager-arg", "flex-volume-plugin-dir=/var/lib/kubelet/volumeplugins",
  "--kubelet-arg", "cloud-provider=external",
  "--kubelet-arg", "volume-plugin-dir=/var/lib/kubelet/volumeplugins",
  "--node-ip", "10.0.255.101",
  "--node-label", "k3s_upgrade=true",
  "--node-name", "k3a-p-ctl-hoq-hnr-lxs",
  "--selinux", "true",
  "--service-cidr", "10.0.64.0/18",
  "--tls-san", "78.46.202.228",
  "--token", "********",
]

-> See cloud-provider and disable-cloud-controller

... I hope we don't have a misconfiguration here.

Before 1.27 this port binding was not happening in K3s, but the Hetzner CCM seems to to it always at startup for a couple of seconds (I still don't know why and I could not find anything in the code) and releases the port afterwards. I'm not sure if it is now the intention of Kubernetes to always bind to this port, as I don't fully understand the intention of their change in kubernetes/kubernetes#108838.

[apricote]

From my POV it's a bug/undesired behavior in hccm (coming from k/cloud-provider). I tried debugging it today, because the code that serves the port is behind two checks that should be negative (feature flag + len(webhooks)>0) but I was not successful yet. Will continue to investigate tomorrow.

[M4t7e]

Just some additional info in case it was not clear from this issue history. In this particular case, K3s is deployed on a single node. First I thought it could be specific to single node deployments, but it seems to happen also in cluster deployments.

Here a test with 3 CP and 3 Worker nodes and the status changes of the HCCM Pod:

# kubectl get pods -A -o wide | grep hcloud-cloud-controller-manager
kube-system      hcloud-cloud-controller-manager-b6b64df54-726vw   0/1     Pending             0          35s   <none>         <none>                  <none>           <none>
[...]
# kubectl get pods -A -o wide | grep hcloud-cloud-controller-manager
kube-system      hcloud-cloud-controller-manager-b6b64df54-726vw   0/1     ContainerCreating   0          36s   10.0.255.101   k3a-p-ctl-hoq-hnr-pvj   <none>           <none>
[...]
# kubectl get pods -A -o wide | grep hcloud-cloud-controller-manager
kube-system      hcloud-cloud-controller-manager-b6b64df54-726vw   1/1     Running             0          40s   10.0.255.101   k3a-p-ctl-hoq-hnr-pvj   <none>           <none>
[...]
# kubectl get pods -A -o wide | grep hcloud-cloud-controller-manager
kube-system      hcloud-cloud-controller-manager-b6b64df54-726vw   0/1     Error               0          43s   10.0.255.101   k3a-p-ctl-hoq-hnr-pvj   <none>           <none>
# kubectl get pods -A -o wide | grep hcloud-cloud-controller-manager
[...]
# kubectl get pods -A -o wide | grep hcloud-cloud-controller-manager
kube-system      hcloud-cloud-controller-manager-b6b64df54-726vw   0/1     CrashLoopBackOff   4 (80s ago)   3m45s   10.0.255.101   k3a-p-ctl-hoq-hnr-pvj   <none>           <none
[...]

-> The HCCM Pod has been scheduled on a CP node and fails for the exact same reason:

# kubectl logs -n kube-system hcloud-cloud-controller-manager-b6b64df54-726vw 
Flag --allow-untagged-cloud has been deprecated, This flag is deprecated and will be removed in a future release. A cluster-id will be required on cloud instances.
I0815 14:49:15.065990       1 serving.go:348] Generated self-signed cert in-memory
I0815 14:49:15.850851       1 serving.go:348] Generated self-signed cert in-memory
W0815 14:49:15.850888       1 client_config.go:618] Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
failed to create listener: failed to listen on 0.0.0.0:10260: listen tcp 0.0.0.0:10260: bind: address already in use
Error: failed to create listener: failed to listen on 0.0.0.0:10260: listen tcp 0.0.0.0:10260: bind: address already in use
Usage:
  cloud-controller-manager [flags]
[...]

... and K3s CP nodes bind themselves on port 10260 (what explains the HCCM error):

# ss -tlpen | grep 10260
LISTEN 0      4096               *:10260            *:*    users:(("k3s-server",pid=1936,fd=196)) ino:23034 sk:f cgroup:/system.slice/k3s.service v6only:0 <->

But here comes the interesting part, this only happens if we use Klipper LB and disable the Hetzner Load Balancer! If you are lucky and the HCCM was scheduled on a worker node, still everything is fine, because there is no port conflict anymore. But if it was scheduled on a control plane node, it fails due to the port conflict. In case the Hetzner LB is used, K3s does not bind on port 10260 and HCCM can bind on it without errors.

We normally don't allow scheduling on control plane nodes with node-role.kubernetes.io/control-plane:NoSchedule taint. But "critical workloads" are still allowed. Since HCCM sets the priority class to system-cluster-critical, it explains the random deployment between control plane and worker nodes.

Why K3s control plane nodes bind on port 10260 only in case Klipper LB is used -> Hetzner LB disabled? Is it related to kubernetes/kubernetes#108838? Acts K3s here as partial CCM, because the LB functionality is not provided by the Cloud CCM? And is this new feature also the root cause for Hetznerr CCM binding on port 10260 @apricote? They mention in the PR:

Added the ability to host webhooks in the cloud controller manager.

-> My wild guess would be this feature could be now in both, K3s CCM and HCCM. Since HCCM is not provided as a service from Hetzner Cloud, but is running inside of the K3s cluster, they can be in conflict in case K3s CCM (probably partially enabled because of Klipper LB) and HCCM are running on the same node.

[apricote]

I have found the source of the port binding and opened an issue upstream for it: kubernetes/kubernetes#120043.

As a workaround you can set --webhook-secure-port 0 on HCCM, this should disable the port binding.

[apricote]

Fix is published as v1.17.2. Thanks for the debugging help (and noticing the issue).

[M4t7e]

Thank you very much for your great investigation and the provided workaround @apricote 🙏

This issue should be solved when #938 is merged and available in the next release.

[b-reich]

I think the upstream bug is fixed? hetznercloud/hcloud-cloud-controller-manager#492
Which is the proper way to upgrade the controller?

just run kubectl apply -f https://github.com/hetznercloud/hcloud-cloud-controller-manager/releases/latest/download/ccm-networks.yaml?

edit: I just edit the version via kubectl edit deployments.apps -n kube-system hcloud-cloud-controller-manager

[mysticaltech]

Should be fixed now as #938 has been merged and released.