Timout error on agent(s) creation

[gschafra]

Description

Agent creation in the deployment process with terraform apply -auto-approve fails with a timeout (might be related to #623?):

....
module.kube-hetzner.module.agents["0-0-agent-med"].hcloud_server.server: Still creating... [6m41s elapsed]
module.kube-hetzner.module.agents["0-0-agent-med"].hcloud_server.server: Still creating... [6m51s elapsed]
module.kube-hetzner.module.agents["0-0-agent-med"].hcloud_server.server: Still creating... [7m1s elapsed]
module.kube-hetzner.module.agents["0-0-agent-med"].hcloud_server.server: Still creating... [7m11s elapsed]
module.kube-hetzner.module.agents["0-0-agent-med"].hcloud_server.server: Still creating... [7m21s elapsed]
module.kube-hetzner.module.agents["0-0-agent-med"].hcloud_server.server: Still creating... [7m31s elapsed]
╷
│ Error: file provisioner error
│ 
│   with module.kube-hetzner.null_resource.control_planes["0-1-control-plane-fsn1"],
│   on .terraform/modules/kube-hetzner/control_planes.tf line 95, in resource "null_resource" "control_planes":
│   95:   provisioner "file" {
│ 
│ timeout - last error: <nil>
╵

Kube.tf file

locals {
  hcloud_token = "xxxxxxxxxxx"
}

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

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

  ssh_public_key = file("${path.module}/clamav_scanning_service_terraform_key.pub")

  ssh_private_key = file("${path.module}/clamav_scanning_service_terraform_key.key")

  network_region = "eu-central" 

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

  agent_nodepools = [
    {
      name        = "agent-med",
      server_type = "cpx21",
      location    = "fsn1",
      labels      = [],
      taints      = [],
      count       = 3

    },
    {
      name        = "storage",
      server_type = "cpx21",
      location    = "fsn1",

      labels      = [
        "node.kubernetes.io/server-usage=storage"
      ],
      taints      = [],
      count       = 1

    },
  ]

  load_balancer_type     = "lb11"
  load_balancer_location = "fsn1"

  enable_csi_driver_smb = true

  restrict_outbound_traffic = false

  disable_network_policy = true

}

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

terraform {
  required_version = ">= 1.3.3"
  required_providers {
    hcloud = {
      source  = "hetznercloud/hcloud"
      version = ">= 1.39.0"
    }
  }
}

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

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

Screenshots

Platform

Windows WSL (Ubuntu v22.04)

[mysticaltech]

@gschafra Please try again, I think fsn1 has suffered some maintenance lately.

[gschafra]

After giving another try it fails (timeout) again, this time on creation of one of the three control planes. I've then just did a terraform apply -auto-approve again, and now the third VM was successfully created, but fails on provisioning:

module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Destruction complete after 8s
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Creating...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Still creating... [10s elapsed]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Still creating... [20s elapsed]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Still creating... [30s elapsed]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Still creating... [40s elapsed]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Still creating... [50s elapsed]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Still creating... [1m0s elapsed]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Still creating... [1m10s elapsed]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Still creating... [1m20s elapsed]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Provisioning with 'local-exec'...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (local-exec): (output suppressed due to sensitive value in config)
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Provisioning with 'local-exec'...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (local-exec): Executing: ["/bin/sh" "-c" "until ssh -o UserKnownHostsFile=/dev/null -o StrictHostKeyChecking=no -o IdentitiesOnly=yes -o PubkeyAuthentication=yes -i /tmp/ruy6w7ku7x4txzleuj5b -o ConnectTimeout=2 -p 22 [email protected] true 2> /dev/null\ndo\n  echo \"Waiting for MicroOS to become available...\"\n  sleep 3\ndone\n"]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (local-exec): Waiting for MicroOS to become available...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Still creating... [1m30s elapsed]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (local-exec): Waiting for MicroOS to become available...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (local-exec): Waiting for MicroOS to become available...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Still creating... [1m40s elapsed]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (local-exec): Waiting for MicroOS to become available...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (local-exec): Waiting for MicroOS to become available...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Provisioning with 'local-exec'...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (local-exec): Executing: ["/bin/sh" "-c" "rm /tmp/ruy6w7ku7x4txzleuj5b\n"]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Provisioning with 'remote-exec'...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec): Connecting to remote host via SSH...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec):   Host: 162.55.171.40
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec):   User: root
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec):   Password: false
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec):   Private key: true
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec):   Certificate: false
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec):   SSH Agent: false
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec):   Checking Host Key: false
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec):   Target Platform: unix
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec): Connected!
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server (remote-exec): Automatic OS updates are enabled
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server.server: Creation complete after 1m49s [id=34434947]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server_network.server: Creating...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries: Creating...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries: Provisioning with 'file'...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries: Provisioning with 'remote-exec'...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec): Connecting to remote host via SSH...
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec):   Host: 162.55.171.40
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec):   User: root
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec):   Password: false
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec):   Private key: true
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec):   Certificate: false
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec):   SSH Agent: false
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec):   Checking Host Key: false
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec):   Target Platform: unix
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec): Connected!
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries (remote-exec): No update required to the registries.yaml file
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].null_resource.registries: Creation complete after 1s [id=2324914122357229631]
module.kube-hetzner.module.control_planes["0-0-control-plane-fsn1"].hcloud_server_network.server: Creation complete after 4s [id=34434947-3076664]
module.kube-hetzner.null_resource.first_control_plane: Creating...
module.kube-hetzner.null_resource.first_control_plane: Provisioning with 'file'...
module.kube-hetzner.null_resource.first_control_plane: Provisioning with 'remote-exec'...
module.kube-hetzner.null_resource.first_control_plane (remote-exec): Connecting to remote host via SSH...
module.kube-hetzner.null_resource.first_control_plane (remote-exec):   Host: 162.55.171.40
module.kube-hetzner.null_resource.first_control_plane (remote-exec):   User: root
module.kube-hetzner.null_resource.first_control_plane (remote-exec):   Password: false
module.kube-hetzner.null_resource.first_control_plane (remote-exec):   Private key: true
module.kube-hetzner.null_resource.first_control_plane (remote-exec):   Certificate: false
module.kube-hetzner.null_resource.first_control_plane (remote-exec):   SSH Agent: false
module.kube-hetzner.null_resource.first_control_plane (remote-exec):   Checking Host Key: false
module.kube-hetzner.null_resource.first_control_plane (remote-exec):   Target Platform: unix
module.kube-hetzner.null_resource.first_control_plane: Still creating... [10s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [20s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [30s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [40s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [50s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [1m0s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [1m10s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [1m20s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [1m30s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [1m40s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [1m50s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [2m0s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [2m10s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [2m20s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [2m30s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [2m40s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [2m50s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [3m0s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [3m10s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [3m20s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [3m30s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [3m40s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [3m50s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [4m0s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [4m10s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [4m20s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [4m30s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [4m40s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [4m50s elapsed]
module.kube-hetzner.null_resource.first_control_plane: Still creating... [5m0s elapsed]
╷
│ Error: remote-exec provisioner error
│ 
│   with module.kube-hetzner.null_resource.first_control_plane,
│   on .terraform/modules/kube-hetzner/init.tf line 44, in resource "null_resource" "first_control_plane":
│   44:   provisioner "remote-exec" {
│ 
│ timeout - last error: <nil>
╵

Should I do an terraform apply again?

[gschafra]

Additionally found this in the journalctl system logs:

Jul 03 07:58:46 k3s-control-plane-fsn1-xoy sshd[1744]: Invalid user empty from 188.166.5.84 port 48898
Jul 03 07:58:46 k3s-control-plane-fsn1-xoy sshd[1744]: Received disconnect from 188.166.5.84 port 48898:11: Bye Bye [preauth]
Jul 03 07:58:46 k3s-control-plane-fsn1-xoy sshd[1744]: Disconnected from invalid user empty 188.166.5.84 port 48898 [preauth]
Jul 03 07:58:58 k3s-control-plane-fsn1-xoy sshd[1749]: Received disconnect from 62.122.184.70 port 20648:11: Client disconnecting normally [preauth]
Jul 03 07:58:58 k3s-control-plane-fsn1-xoy sshd[1749]: Disconnected from authenticating user root 62.122.184.70 port 20648 [preauth]
Jul 03 07:58:58 k3s-control-plane-fsn1-xoy sshd[1747]: Received disconnect from 196.49.0.60 port 57752:11: Bye Bye [preauth]
Jul 03 07:58:58 k3s-control-plane-fsn1-xoy sshd[1747]: Disconnected from authenticating user root 196.49.0.60 port 57752 [preauth]
Jul 03 07:59:15 k3s-control-plane-fsn1-xoy sshd[1753]: error: kex_exchange_identification: client sent invalid protocol identifier "MGLNDD_162.55.171.40_22"
Jul 03 07:59:15 k3s-control-plane-fsn1-xoy sshd[1753]: banner exchange: Connection from 192.241.217.6 port 47836: invalid format
Jul 03 07:59:18 k3s-control-plane-fsn1-xoy sshd[1754]: Invalid user sj from 165.22.10.60 port 56754
Jul 03 07:59:18 k3s-control-plane-fsn1-xoy sshd[1754]: Received disconnect from 165.22.10.60 port 56754:11: Bye Bye [preauth]
Jul 03 07:59:18 k3s-control-plane-fsn1-xoy sshd[1754]: Disconnected from invalid user sj 165.22.10.60 port 56754 [preauth]

According to https://serverfault.com/questions/1015547/what-causes-ssh-error-kex-exchange-identification-connection-closed-by-remote this might be caused by an connection interruption :

In OpenSSH source code, kex_exchange_identification is a function to exchange server and client identification (duh), and the specified error happened if the socket connection between OpenSSH server and client is interrupted (see EPIPE), i.e. client already closed its connection.

[gschafra]

.... after another terraform apply, I've got this:

module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec): Ok: transaction number 8.
module.kube-hetzner.null_resource.agents["0-1-agent-med"]: Provisioning with 'remote-exec'...
module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec): Connecting to remote host via SSH...
module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec):   Host: 91.107.207.220
module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec):   User: root
module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec):   Password: false
module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec):   Private key: true
module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec):   Certificate: false
module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec):   SSH Agent: false
module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec):   Checking Host Key: false
module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec):   Target Platform: unix
module.kube-hetzner.null_resource.agents["0-1-agent-med"] (remote-exec): Connected!
module.kube-hetzner.null_resource.agents["0-1-agent-med"]: Creation complete after 27s [id=3408984723099812300]
module.kube-hetzner.null_resource.agents["0-0-agent-med"]: Still creating... [30s elapsed]
module.kube-hetzner.null_resource.kustomization: Still creating... [30s elapsed]
module.kube-hetzner.null_resource.agents["0-0-agent-med"]: Still creating... [40s elapsed]
module.kube-hetzner.null_resource.kustomization: Still creating... [40s elapsed]
....
module.kube-hetzner.null_resource.agents["0-0-agent-med"]: Still creating... [5m0s elapsed]
module.kube-hetzner.null_resource.kustomization: Still creating... [5m0s elapsed]
╷
│ Error: remote-exec provisioner error
│ 
│   with module.kube-hetzner.null_resource.agents["0-0-agent-med"],
│   on .terraform/modules/kube-hetzner/agents.tf line 74, in resource "null_resource" "agents":
│   74:   provisioner "remote-exec" {
│ 
│ timeout - last error: <nil>
╵
╷
│ Error: file provisioner error
│ 
│   with module.kube-hetzner.null_resource.kustomization,
│   on .terraform/modules/kube-hetzner/init.tf line 212, in resource "null_resource" "kustomization":
│  212:   provisioner "file" {
│ 
│ timeout - last error: <nil>

With error on agent:

[gschafra]

Is there a way, to configure (golbal) timeouts?

[mysticaltech]

@gschafra These low timeouts are not usual, are you using the latest version? Also please try from a new project, and use cloudflare https://one.one.one.one.

We do not have ways to configure timeouts, but it should not be needed, they are quite larger than in your screenshot.

[mysticaltech]

@gschafra Please try the above first! Normally it should work, if not try with another connection like a mobile hotspot shared from your phone.

If again it does not work, please have a look at this PR that did not merge #778, which seeked to add higher timeouts.

[mysticaltech]

The thing is, you do need a stable connection, and connecting through cloudflare (or any other good vpn) should help, hence my first recommendation above (especially if you are in a country that tries to filter encrypted traffic).