dmacvicar / terraform-provider-libvirt

Terraform provider to provision infrastructure with Linux's KVM using libvirt
Apache License 2.0
1.59k stars 458 forks source link

Error: failed to connect: failed to connect to libvirt on the remote host: ssh: rejected: connect failed (open failed) #1121

Open mhtr opened 1 day ago

mhtr commented 1 day ago

System Information

Linux distribution

Debian 12

Terraform version

terraform -v
Terraform v1.9.8
on linux_amd64

Provider and libvirt versions

terraform-provider-libvirt -version
v0.8.1 

with fix from 1117

Description of Issue/Question

Failed to connect to libvirt on the remote host when run terraform plan, but with virsh everything is ok

virsh -c "qemu+ssh://mokhrimenko@10.10.25.10/system?sshauth=privkey&keyfile=/home/mokhrimenko/.ssh/id_ed25519&no_verify=1"

Setup

terraform {
  required_providers {
    libvirt = {
      source = "terraform.local/local/libvirt"
      version = "0.8.1"
    }
  }
}

provider "libvirt" {
    uri = "qemu+ssh://username@host/system?sshauth=privkey&keyfile=/home/username/.ssh/id_ed25519&no_verify=1"
}

resource "libvirt_volume" "volume" {
  name     = "test-vm.qcow2"
  size     = 20 * 1024 * 1024 * 1024
}

Additional information:

In logs on libvirt_host I see that terraform_host is connected via ssh

Oct 24 10:26:14 libvirt_host sshd[1677704]: Connection from terraform_host port 42622 on libvirt_host port 12345 rdomain ""
Oct 24 10:26:14 libvirt_host sshd[1677704]: Accepted key ED25519 SHA256:<SHA> found at /home/username/.ssh/authorized_keys:1
Oct 24 10:26:14 libvirt_host sshd[1677704]: Postponed publickey for username from terraform_host port 42622 ssh2 [preauth]
Oct 24 10:26:14 libvirt_host sshd[1677704]: Accepted key ED25519 SHA256:<SHA> found at /home/username/.ssh/authorized_keys:1
Oct 24 10:26:14 libvirt_host sshd[1677704]: Accepted publickey for username from terraform_host port 42622 ssh2: ED25519 SHA256:<SHA>
Oct 24 10:26:14 libvirt_host sshd[1677704]: pam_unix(sshd:session): session opened for user username(uid=1000) by (uid=0)
Oct 24 10:26:14 libvirt_host sshd[1677704]: pam_env(sshd:session): deprecated reading of user environment enabled
Oct 24 10:26:14 libvirt_host sshd[1677704]: User child is on pid 1677711
Oct 24 10:26:14 libvirt_host sshd[1677704]: pam_unix(sshd:session): session closed for user username

But I have error with connecting to libvirt debug logs:

2024-10-24T10:39:02.453Z [DEBUG] provider: plugin started: path=.terraform/providers/terraform.local/local/libvirt/0.8.1/linux_amd64/terraform-provider-libvirt_v0.8.1 pid=122654
2024-10-24T10:39:02.453Z [DEBUG] provider: waiting for RPC address: plugin=.terraform/providers/terraform.local/local/libvirt/0.8.1/linux_amd64/terraform-provider-libvirt_v0.8.1
2024-10-24T10:39:02.460Z [INFO]  provider.terraform-provider-libvirt_v0.8.1: configuring server automatic mTLS: timestamp=2024-10-24T10:39:02.459Z
2024-10-24T10:39:02.475Z [DEBUG] provider: using plugin: version=5
2024-10-24T10:39:02.475Z [DEBUG] provider.terraform-provider-libvirt_v0.8.1: plugin address: network=unix address=/tmp/plugin565250099 timestamp=2024-10-24T10:39:02.475Z
2024-10-24T10:39:02.497Z [INFO]  provider.terraform-provider-libvirt_v0.8.1: 2024/10/24 10:39:02 [DEBUG] Configuring provider for 'qemu+ssh://username@<libvirt_host_ip>/system?sshauth=privkey&keyfile=/home/username/.ssh/id_ed25519&no_verify=1': &{map[uri:0xc0000d4000] 0xc0002719a0 <nil> 0xc000414f00 map[] <nil> {{<nil>} <nil>} 0xc000161ca0 0xc000361110 0xc00028cb60 false {{{} 1} {0 0}} false false}: timestamp=2024-10-24T10:39:02.495Z
2024-10-24T10:39:02.497Z [INFO]  provider.terraform-provider-libvirt_v0.8.1: 2024/10/24 10:39:02 [INFO] establishing ssh connection to '<libvirt_host_ip>': timestamp=2024-10-24T10:39:02.495Z
2024-10-24T10:39:02.498Z [INFO]  provider.terraform-provider-libvirt_v0.8.1: 2024/10/24 10:39:02 [DEBUG] using ssh port from ssh_config: '12345': timestamp=2024-10-24T10:39:02.495Z
2024-10-24T10:39:02.498Z [INFO]  provider.terraform-provider-libvirt_v0.8.1: 2024/10/24 10:39:02 [DEBUG] port for ssh connection is: '12345': timestamp=2024-10-24T10:39:02.495Z
2024-10-24T10:39:02.499Z [INFO]  provider.terraform-provider-libvirt_v0.8.1: 2024/10/24 10:39:02 [DEBUG] auth methods for <libvirt_host_ip>: privkey: timestamp=2024-10-24T10:39:02.495Z
2024-10-24T10:39:02.499Z [INFO]  provider.terraform-provider-libvirt_v0.8.1: 2024/10/24 10:39:02 [DEBUG] ssh identity files for host '<libvirt_host_ip>': [/home/username/.ssh/id_ed25519]: timestamp=2024-10-24T10:39:02.495Z
2024-10-24T10:39:02.499Z [INFO]  provider.terraform-provider-libvirt_v0.8.1: 2024/10/24 10:39:02 [DEBUG] Reading ssh key '/home/username/.ssh/id_ed25519': timestamp=2024-10-24T10:39:02.495Z
2024-10-24T10:39:02.499Z [INFO]  provider.terraform-provider-libvirt_v0.8.1: 2024/10/24 10:39:02 [INFO] SSH connecting to '<libvirt_host_ip>' (<libvirt_host_ip>): timestamp=2024-10-24T10:39:02.495Z
2024-10-24T10:39:02.668Z [ERROR] provider.terraform-provider-libvirt_v0.8.1: Response contains error diagnostic: tf_rpc=Configure @module=sdk.proto diagnostic_detail="" diagnostic_summary="failed to connect: failed to connect to libvirt on the remote host: ssh: rejected: connect failed (open failed)" tf_proto_version=5.6 tf_provider_addr=provider @caller=/home/username/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.24.0/tfprotov5/internal/diag/diagnostics.go:58 diagnostic_severity=ERROR tf_req_id=4f89945f-396c-74df-e741-cf3e55212d3b timestamp=2024-10-24T10:39:02.668Z
2024-10-24T10:39:02.670Z [ERROR] vertex "provider[\"terraform.local/local/libvirt\"]" error: failed to connect: failed to connect to libvirt on the remote host: ssh: rejected: connect failed (open failed)
2024-10-24T10:39:02.671Z [WARN]  Planning encountered errors, so plan is not applyable
2024-10-24T10:39:02.671Z [INFO]  backend/local: plan operation completed

Planning failed. Terraform encountered an error while generating this plan.

╷
│ Error: failed to connect: failed to connect to libvirt on the remote host: ssh: rejected: connect failed (open failed)
│ 
│   with provider["terraform.local/local/libvirt"],
│   on main.tf line 10, in provider "libvirt":
│   10: provider "libvirt" {
│ 
╵
2024-10-24T10:39:02.679Z [DEBUG] provider.stdio: received EOF, stopping recv loop: err="rpc error: code = Unavailable desc = error reading from server: EOF"
2024-10-24T10:39:02.681Z [INFO]  provider: plugin process exited: plugin=.terraform/providers/terraform.local/local/libvirt/0.8.1/linux_amd64/terraform-provider-libvirt_v0.8.1 id=122654
2024-10-24T10:39:02.681Z [DEBUG] provider: plugin exited
memetb commented 1 day ago

failed to connect to libvirt on the remote host: ssh: rejected: connect failed (open failed)

This is not a bug at all. The error you are getting is coming directly from the OS. It's saying it wasn't able to open a tcp/ip connection, let alone an ssh one.

I am not sure what your first log output is, but it appears to be a red herring from what I can tell.

mhtr commented 1 day ago

@memetb The first log output from sshd on libvirt host when command terraform plan is executed. This means that the connection via ssh to the host is established, but then something goes wrong. But at the same time the command virsh -c ... with the same uri as in terraform is executed without problems

memetb commented 1 day ago

The code that is emitting the logs you are showing is here:

        log.Printf("[INFO] SSH connecting to '%v' (%v)", target, hostName)
        conn, err := ssh.Dial("tcp", net.JoinHostPort(hostName, port), &cfg)

        if err != nil {
            return nil, fmt.Errorf("failed to connect to remote host '%v': %w", target, err)
        }

Can you do me a favor and post:

  1. the stanza for this host in ~/.ssh/config
  2. an attempt at connecting to the server via a cli call to ssh -v
  3. show more details about the call to virsh. It has many possible options, it may not be going over ssh at all.
mhtr commented 22 hours ago

The code that is emitting the logs you are showing is here

Are you sure? Looks like the code that is emitting the error is here when it trying to connect to unix socket.

    address := u.Query().Get("socket")
    if address == "" {
        address = defaultUnixSock
    }

    c, err := sshClient.Dial("unix", address)
    if err != nil {
        return nil, fmt.Errorf("failed to connect to libvirt on the remote host: %w", err) <---- the error message is like the error log from terraform
    }

Because the error log is

Error: failed to connect: failed to connect to libvirt on the remote host: ssh: rejected: connect failed (open failed)
  1. the stanza for this host in ~/.ssh/config
Host libvirt_host
    Port 12345
  1. an attempt at connecting to the server via a cli call to ssh -v
OpenSSH_9.2p1 Debian-2+deb12u3, OpenSSL 3.0.14 4 Jun 2024
debug1: Reading configuration data /home/username/.ssh/config
debug1: /home/username/.ssh/config line 1: Applying options for <libvirt_host>
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: include /etc/ssh/ssh_config.d/*.conf matched no files
debug1: /etc/ssh/ssh_config line 21: Applying options for *
debug1: Connecting to <libvirt_host> [<libvirt_host>] port 12345.
debug1: Connection established.
debug1: identity file /home/username/.ssh/id_rsa type -1
debug1: identity file /home/username/.ssh/id_rsa-cert type -1
debug1: identity file /home/username/.ssh/id_ecdsa type -1
debug1: identity file /home/username/.ssh/id_ecdsa-cert type -1
debug1: identity file /home/username/.ssh/id_ecdsa_sk type -1
debug1: identity file /home/username/.ssh/id_ecdsa_sk-cert type -1
debug1: identity file /home/username/.ssh/id_ed25519 type 3
debug1: identity file /home/username/.ssh/id_ed25519-cert type -1
debug1: identity file /home/username/.ssh/id_ed25519_sk type -1
debug1: identity file /home/username/.ssh/id_ed25519_sk-cert type -1
debug1: identity file /home/username/.ssh/id_xmss type -1
debug1: identity file /home/username/.ssh/id_xmss-cert type -1
debug1: identity file /home/username/.ssh/id_dsa type -1
debug1: identity file /home/username/.ssh/id_dsa-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_9.2p1 Debian-2+deb12u3
debug1: Remote protocol version 2.0, remote software version OpenSSH_9.2p1 Debian-2+deb12u3
debug1: compat_banner: match: OpenSSH_9.2p1 Debian-2+deb12u3 pat OpenSSH* compat 0x04000000
debug1: Authenticating to <libvirt_host>:12345 as 'username'
debug1: load_hostkeys: fopen /home/username/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: algorithm: sntrup761x25519-sha512@openssh.com
debug1: kex: host key algorithm: ssh-ed25519
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: SSH2_MSG_KEX_ECDH_REPLY received
debug1: Server host key: ssh-ed25519 SHA256:5MvPCke/XBgLCJiNlnMcChV8RS+5P2XwCkSulk+d8Dg
debug1: load_hostkeys: fopen /home/username/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug1: Host '[<libvirt_host>]:12345' is known and matches the ED25519 host key.
debug1: Found key in /home/username/.ssh/known_hosts:5
debug1: ssh_packet_send2_wrapped: resetting send seqnr 3
debug1: rekey out after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: ssh_packet_read_poll2: resetting read seqnr 3
debug1: SSH2_MSG_NEWKEYS received
debug1: rekey in after 134217728 blocks
debug1: Will attempt key: /home/username/.ssh/id_rsa 
debug1: Will attempt key: /home/username/.ssh/id_ecdsa 
debug1: Will attempt key: /home/username/.ssh/id_ecdsa_sk 
debug1: Will attempt key: /home/username/.ssh/id_ed25519 ED25519 SHA256:Y9gw3CEhjS6fumcAGw8WPjWsuUkOoZyu6ICcYjjUNBU
debug1: Will attempt key: /home/username/.ssh/id_ed25519_sk 
debug1: Will attempt key: /home/username/.ssh/id_xmss 
debug1: Will attempt key: /home/username/.ssh/id_dsa 
debug1: SSH2_MSG_EXT_INFO received
debug1: kex_input_ext_info: server-sig-algs=<ssh-ed25519,sk-ssh-ed25519@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ecdsa-sha2-nistp256@openssh.com,webauthn-sk-ecdsa-sha2-nistp256@openssh.com,ssh-dss,ssh-rsa,rsa-sha2-256,rsa-sha2-512>
debug1: kex_input_ext_info: publickey-hostbound@openssh.com=<0>
debug1: SSH2_MSG_SERVICE_ACCEPT received
#################################################################
#                          ALERT!!!                             #
#  You are entering into a secured area! Your IP, Login Time,   #
#   Username has been noted and has been sent to the server     #
#                       administrator!                          #
#   This service is restricted to authorized users only. All    #
#            activities on this system are logged.              #
#  Unauthorized access will be fully investigated and reported  #
#        to the appropriate law enforcement agencies.           #
#################################################################
debug1: Authentications that can continue: publickey
debug1: Next authentication method: publickey
debug1: Trying private key: /home/username/.ssh/id_rsa
debug1: Trying private key: /home/username/.ssh/id_ecdsa
debug1: Trying private key: /home/username/.ssh/id_ecdsa_sk
debug1: Offering public key: /home/username/.ssh/id_ed25519 ED25519 SHA256:Y9gw3CEhjS6fumcAGw8WPjWsuUkOoZyu6ICcYjjUNBU
debug1: Server accepts key: /home/username/.ssh/id_ed25519 ED25519 SHA256:Y9gw3CEhjS6fumcAGw8WPjWsuUkOoZyu6ICcYjjUNBU
Authenticated to <libvirt_host> ([<libvirt_host>]:12345) using "publickey".
debug1: channel 0: new session [client-session] (inactive timeout: 0)
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
debug1: pledge: filesystem
debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
debug1: client_input_hostkeys: searching /home/username/.ssh/known_hosts for [<libvirt_host>]:12345 / (none)
debug1: client_input_hostkeys: searching /home/username/.ssh/known_hosts2 for [<libvirt_host>]:12345 / (none)
debug1: client_input_hostkeys: hostkeys file /home/username/.ssh/known_hosts2 does not exist
debug1: client_input_hostkeys: no new or deprecated keys from server
debug1: Remote: /home/username/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug1: Remote: /home/username/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug1: Sending environment.
debug1: channel 0: setting env LANG = "en_US.UTF-8"
debug1: channel 0: setting env LC_CTYPE = "UTF-8"
debug1: pledge: fork
Linux <libvirt_host> 6.1.0-20-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.85-1 (2024-04-11) x86_64

The programs included with the Debian GNU/Linux system are free software;
the exact distribution terms for each program are described in the
individual files in /usr/share/doc/*/copyright.

Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent
permitted by applicable law.
Last login: Thu Oct 24 09:07:47 2024 from <terraform_host>
  1. show more details about the call to virsh. It has many possible options, it may not be going over ssh at all.
virsh -c "qemu+ssh://username@<libvirt_host>/system?sshauth=privkey&keyfile=/home/username/.ssh/id_ed25519&no_verify=1"
Welcome to virsh, the virtualization interactive terminal.

Type:  'help' for help with commands
       'quit' to quit

virsh # 
memetb commented 20 hours ago

@mhtr from all I'm seeing, my gut is saying that this is some sort of proper ssh authentication error that isn't verbose enough: meaning the behaviour is correct, but we're just not seeing why it's failing. The plugin clearly isn't segfaulting, and it seems it is attempting to make a connection with the correct parameters.

It would really help out if you could isolate the issue by carrying over things one by one. That is, take this starting query string:

qemu+ssh://username@host/system?sshauth=privkey&keyfile=/home/username/.ssh/id_ed25519&no_verify=1

And start by:

  1. simply removing/moving the ~/.ssh/config file altogether - then the query string should work on its own as before
  2. second, try putting all of the configurations into the sshconfig stanza and only cnonect with qemu+ssh://host/system
  3. then one by one carry over the bits (e.g. IdentityFile in sshconfig will become keyfile in querystring)

Let me know what you discover.

Fyi: StrictHostKeyChecking <-> no_verify IdentityFile <-> keyfile sshauth=privkey is unnecessary if you specify IdentityFile.