Random EOF Error while running boot command on sendkey API

[newedgex]

Overview of the Issue

While building different VM's on Proxmox (unrelated to the version happened with v6,v7 or the latest v8) I'm getting the build fail randomly during "Typing boot command".
It's not related to a single VM, it can happen to different types of VM's be it linux or windows based and I have been observing the bug for 2 months.

It seems completely random as trying to start the build few times it will fail until it will work suddenly.

--> proxmox-iso.ubuntu-server: Error running boot command: Put "https://proxmox-02-01.upstream.domain.com:8006/api2/json/nodes/proxmox-02-01/qemu/102/sendkey": EOF

It happens only during "Typing boot command"

==> proxmox-iso.ubuntu: Creating VM
==> proxmox-iso.ubuntu: No VM ID given, getting next free from Proxmox
==> proxmox-iso.ubuntu: Starting VM
==> proxmox-iso.ubuntu: Waiting 25s for boot
==> proxmox-iso.ubuntu: Typing the boot command
==> proxmox-iso.ubuntu: Error running boot command: Put "https://proxmox-02-01.xxxxx.com:8006/api2/json/nodes/proxmox-02-01/qemu/101/sendkey": EOF
==> proxmox-iso.ubuntu: Stopping VM
==> proxmox-iso.ubuntu: Deleting VM
Build 'proxmox-iso.ubuntu' errored after 2 minutes 6 seconds: Error running boot command: Put "https://proxmox-02-01.xxxxx.com:8006/api2/json/nodes/proxmox-02-01/qemu/101/sendkey": EOF

Reproduction Steps

• Try to build the packer template while being connected through wireguard with proxmox

Operating system and Environment details

• Packer v1.9.4
• packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64
• Arch Linux fully up to date (actually it's a new fresh installation , had the same problem also on other devices)
• Proxmox 8.0.4
• There's a wireguard connection with the Proxmox server since it's remote and I don't want the back connection to Packer's HTTP's server to be in cleartext.

Log Fragments and crash.log files

2023/10/12 10:12:06 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:06 Plugin address: unix /tmp/packer-plugin4053739862
2023/10/12 10:12:06 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:06 Waiting for connection...
2023/10/12 10:12:06 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:06 Serving a plugin connection...
2023/10/12 10:12:06 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:06 [TRACE] starting builder iso
2023/10/12 10:12:06 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:06 Number of sockets 0 is too small, using default: 1
2023/10/12 10:12:06 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:06 OS not set, using default 'other'
2023/10/12 10:12:06 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:06 Disk 0 cache mode not set, using default 'none'
2023/10/12 10:12:07 Build debug mode: false
2023/10/12 10:12:07 Force build: false
2023/10/12 10:12:07 On error: 
2023/10/12 10:12:07 Waiting on builds to complete...
2023/10/12 10:12:07 Starting build run: proxmox-iso.ubuntu-server
proxmox-iso.ubuntu-server: output will be in this color.
2023/10/12 10:12:07 Running builder: 
2023/10/12 10:12:07 [INFO] (telemetry) Starting builder proxmox-iso.ubuntu-server

2023/10/12 10:12:07 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:07 using token auth
2023/10/12 10:12:07 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:07 No URLs were provided to Step Download. Continuing...
==> proxmox-iso.ubuntu-server: Creating VM
==> proxmox-iso.ubuntu-server: No VM ID given, getting next free from Proxmox
==> proxmox-iso.ubuntu-server: Starting VM
==> proxmox-iso.ubuntu-server: Waiting 20s for boot
==> proxmox-iso.ubuntu-server: Typing the boot command
2023/10/12 10:12:35 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:35 [INFO] Waiting 2s
2023/10/12 10:12:37 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:37 [INFO] Waiting 2s
2023/10/12 10:12:44 packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64 plugin: 2023/10/12 10:12:44 [INFO] Waiting 5s
==> proxmox-iso.ubuntu-server: Error running boot command: Put "https://proxmox-02-01.upstream.domain.com:8006/api2/json/nodes/proxmox-02-01/qemu/102/sendkey": EOF
==> proxmox-iso.ubuntu-server: Stopping VM
==> proxmox-iso.ubuntu-server: Deleting VM
2023/10/12 10:12:55 [INFO] (telemetry) ending proxmox-iso.ubuntu-server
==> Wait completed after 48 seconds 224 milliseconds
2023/10/12 10:12:55 machine readable: error-count []string{"1"}
==> Some builds didn't complete successfully and had errors:
2023/10/12 10:12:55 machine readable: proxmox-iso.ubuntu-server,error []string{"Error running boot command: Put \"https://proxmox-02-01.upstream.domain.com:8006/api2/json/nodes/proxmox-02-01/qemu/102/sendkey\": EOF"}
==> Builds finished but no artifacts were created.
2023/10/12 10:12:55 [INFO] (telemetry) Finalizing.
Build 'proxmox-iso.ubuntu-server' errored after 48 seconds 224 milliseconds: Error running boot command: Put "https://proxmox-02-01.upstream.domain.com:8006/api2/json/nodes/proxmox-02-01/qemu/102/sendkey": EOF

==> Wait completed after 48 seconds 224 milliseconds

==> Some builds didn't complete successfully and had errors:
--> proxmox-iso.ubuntu-server: Error running boot command: Put "https://proxmox-02-01.upstream.domain.com:8006/api2/json/nodes/proxmox-02-01/qemu/102/sendkey": EOF

==> Builds finished but no artifacts were created.
2023/10/12 10:12:56 waiting for all plugin processes to complete...
2023/10/12 10:12:56 /home/user/.config/packer/plugins/github.com/hashicorp/proxmox/packer-plugin-proxmox_v1.1.5_x5.0_linux_amd64: plugin process exited

[jonasschultheiss]

i had the same error this morning, for me it got fixed by using http as protocol instead of https.
tho i use it in a local network without a dns record or manual tsl certs

[newedgex]

Yeah, that won't work for me since the environment has some requirements that needs to be followed, so https is a must and not even self signed cert is allowed when accessing proxmox.
I'm not sure even http would fix it though , I tried multiple workarounds , thought it fixed but the bug keeps returning, so the workarounds where no real solution..
It's definitely happening during the "plugin: 2023/10/12 10:12:35 [INFO] Waiting 2s"

[newedgex]

I'v reported this also on proxmox forums https://forum.proxmox.com/threads/api-error-running-boot-command-sendkey-eof.134796/ for some help.
The interesting parts : https://github.com/hashicorp/packer-plugin-proxmox/blob/main/builder/proxmox/common/step_type_boot_command.go#L34 and https://github.com/hashicorp/packer-plugin-proxmox/blob/main/builder/proxmox/common/bootcommand_driver.go#L26

[lbajolet-hashicorp]

Hi @newedgex,

Thanks for reporting this one.

I'm not certain where the actual problem lies, and I don't have a PVE instance on which to replicate the problem, but given the code being called, I would suggest that in addition to posting the issue on the PVE forums you also create one on the API client we rely upon (https://github.com/Telmate/proxmox-api-go).

The code for the driver calls SendKey on the API client (https://github.com/Telmate/proxmox-api-go/blob/master/proxmox/client.go#L411), which from the looks of it only relies on a PUT request to the endpoint, but I presume there could be something with the session that auto-closes in between two calls in your case, hence the EOF?

I'll keep this on my watchlist, and see if I can see something in the code in the meantime.

[newedgex]

Hi @lbajolet-hashicorp , just did so , in case there's further information needed I'd be happy to provide more information.
Thanks allot for the proxmox plugin :)

[smougenot]

Same trouble for me

Tool	Version
Packer	1.9.4
Proxmox	8.0.4
/hashicorp/proxmox	1.1.5

Using local network, DNS record and a Letsencrypt managed certificate

[grilme99]

Currently getting this error myself. I'm running Proxmox 8.1.3 and Packer 1.10.0.

Interestingly, this error only happens when I don't interact with the VM on the Proxmox UI. To make the Packer build succeed, I:

• Run the build command
• Open the VM on Proxmox and go to the Console tab to view Packer run its commands
• It runs through everything and succeeds

However, if I don't open the VM on Proxmox, the build fails 100% of the time. I have no idea why.

Below is the logs from Packer, with debug mode enabled:

2024/01/13 23:41:04 [INFO] Packer version: 1.10.0 [go1.20.11 darwin arm64]
2024/01/13 23:41:04 [TRACE] discovering plugins in /opt/homebrew/bin
2024/01/13 23:41:04 [TRACE] discovering plugins in .
2024/01/13 23:41:04 [TRACE] discovering plugins in ~/.config/packer/plugins
2024/01/13 23:41:04 [INFO] Discovered potential plugin: proxmox = ~/.config/packer/plugins/github.com/hashicorp/proxmox/packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64
2024/01/13 23:41:04 [INFO] found external [-packer-default-plugin-name- clone iso] builders from proxmox plugin
2024/01/13 23:41:04 [INFO] PACKER_CONFIG env var not set; checking the default config file path
2024/01/13 23:41:04 [INFO] PACKER_CONFIG env var set; attempting to open config file: ~/.packerconfig
2024/01/13 23:41:04 [WARN] Config file doesn't exist: ~/.packerconfig
2024/01/13 23:41:04 [INFO] Setting cache directory: ~/.cache/packer
2024/01/13 23:41:04 [TRACE] listing potential installations for "github.com/hashicorp/proxmox" that match "1.1.6". plugingetter.ListInstallationsOptions{FromFolders:[]string{"/opt/homebrew/bin", ".", "~/.config/packer/plugins"}, BinaryInstallationOptions:plugingetter.BinaryInstallationOptions{APIVersionMajor:"5", APIVersionMinor:"0", OS:"darwin", ARCH:"arm64", Ext:"", Checksummers:[]plugingetter.Checksummer{plugingetter.Checksummer{Type:"sha256", Hash:(*sha256.digest)(0x140005a6100)}}}}
2024/01/13 23:41:04 [TRACE] Found the following "github.com/hashicorp/proxmox" installations: [{~/.config/packer/plugins/github.com/hashicorp/proxmox/packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 v1.1.6}]
2024/01/13 23:41:04 [INFO] found external [-packer-default-plugin-name- clone iso] builders from proxmox plugin
2024/01/13 23:41:04 [TRACE] validateValue: not active for root_password, so skipping
2024/01/13 23:41:04 [TRACE] validateValue: not active for ssh_username, so skipping
2024/01/13 23:41:04 [TRACE] validateValue: not active for ssh_password, so skipping
2024/01/13 23:41:04 [INFO] Starting external plugin ~/.config/packer/plugins/github.com/hashicorp/proxmox/packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 start builder iso
2024/01/13 23:41:04 Starting plugin: ~/.config/packer/plugins/github.com/hashicorp/proxmox/packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 []string{"~/.config/packer/plugins/github.com/hashicorp/proxmox/packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64", "start", "builder", "iso"}
2024/01/13 23:41:04 Waiting for RPC address for: ~/.config/packer/plugins/github.com/hashicorp/proxmox/packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64
2024/01/13 23:41:04 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:04 Plugin address: unix /var/folders/3z/b1mmlz6n5kq_ls1kk1tzvr280000gn/T/packer-plugin888184925
2024/01/13 23:41:04 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:04 Waiting for connection...
2024/01/13 23:41:04 Received unix RPC address for ~/.config/packer/plugins/github.com/hashicorp/proxmox/packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64: addr is /var/folders/3z/b1mmlz6n5kq_ls1kk1tzvr280000gn/T/packer-plugin888184925
2024/01/13 23:41:04 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:04 Serving a plugin connection...
2024/01/13 23:41:04 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:04 [TRACE] starting builder iso
2024/01/13 23:41:04 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:04 Number of sockets 0 is too small, using default: 1
2024/01/13 23:41:04 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:04 CPU type not set, using default 'kvm64'
2024/01/13 23:41:04 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:04 OS not set, using default 'other'
2024/01/13 23:41:04 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:04 Disk 0 cache mode not set, using default 'none'
2024/01/13 23:41:04 [INFO] Starting internal plugin packer-provisioner-shell
2024/01/13 23:41:04 Starting plugin: /opt/homebrew/bin/packer []string{"/opt/homebrew/bin/packer", "plugin", "packer-provisioner-shell"}
2024/01/13 23:41:04 Waiting for RPC address for: /opt/homebrew/bin/packer
2024/01/13 23:41:04 packer-provisioner-shell plugin: [INFO] Packer version: 1.10.0 [go1.20.11 darwin arm64]
2024/01/13 23:41:04 packer-provisioner-shell plugin: [INFO] PACKER_CONFIG env var not set; checking the default config file path
2024/01/13 23:41:04 packer-provisioner-shell plugin: [INFO] PACKER_CONFIG env var set; attempting to open config file: ~/.packerconfig
2024/01/13 23:41:04 packer-provisioner-shell plugin: [WARN] Config file doesn't exist: ~/.packerconfig
2024/01/13 23:41:04 packer-provisioner-shell plugin: [INFO] Setting cache directory: ~/.cache/packer
2024/01/13 23:41:04 packer-provisioner-shell plugin: args: []string{"packer-provisioner-shell"}
2024/01/13 23:41:04 packer-provisioner-shell plugin: Plugin address: unix /var/folders/3z/b1mmlz6n5kq_ls1kk1tzvr280000gn/T/packer-plugin2788805345
2024/01/13 23:41:04 packer-provisioner-shell plugin: Waiting for connection...
2024/01/13 23:41:04 Received unix RPC address for /opt/homebrew/bin/packer: addr is /var/folders/3z/b1mmlz6n5kq_ls1kk1tzvr280000gn/T/packer-plugin2788805345
2024/01/13 23:41:04 packer-provisioner-shell plugin: Serving a plugin connection...
2024/01/13 23:41:04 Build debug mode: false
2024/01/13 23:41:04 Force build: false
2024/01/13 23:41:04 On error: 
2024/01/13 23:41:04 Waiting on builds to complete...
proxmox-iso.alpine-linux: output will be in this color.

2024/01/13 23:41:04 Starting build run: proxmox-iso.alpine-linux
2024/01/13 23:41:04 Running builder: 
2024/01/13 23:41:04 [INFO] (telemetry) Starting builder proxmox-iso.alpine-linux
2024/01/13 23:41:04 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:04 using token auth
2024/01/13 23:41:04 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:04 No URLs were provided to Step Download. Continuing...
==> proxmox-iso.alpine-linux: Creating VM
==> proxmox-iso.alpine-linux: No VM ID given, getting next free from Proxmox
==> proxmox-iso.alpine-linux: Starting VM
==> proxmox-iso.alpine-linux: Starting HTTP server on port 8184
==> proxmox-iso.alpine-linux: Waiting 10s for boot
2024/01/13 23:41:09 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:09 Found available port: 8184 on IP: 0.0.0.0
==> proxmox-iso.alpine-linux: Typing the boot command
2024/01/13 23:41:19 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:19 [INFO] Waiting 1s
2024/01/13 23:41:20 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:20 [INFO] Waiting 5s
2024/01/13 23:41:25 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:25 [INFO] Waiting 1s
2024/01/13 23:41:29 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:29 [INFO] Waiting 1s
2024/01/13 23:41:31 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:31 [INFO] Waiting 1s
2024/01/13 23:41:33 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:33 [INFO] Waiting 1s
2024/01/13 23:41:34 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:34 [INFO] Waiting 1s
2024/01/13 23:41:35 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:35 [INFO] Waiting 1s
2024/01/13 23:41:36 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:36 [INFO] Waiting 1s
2024/01/13 23:41:38 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:38 [INFO] Waiting 1s
2024/01/13 23:41:39 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:39 [INFO] Waiting 1s
2024/01/13 23:41:41 packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64 plugin: 2024/01/13 23:41:41 [INFO] Waiting 5s
==> proxmox-iso.alpine-linux: Error running boot command: Put "https://10.69.1.230:8006/api2/json/nodes/pve/qemu/100/sendkey": EOF
==> proxmox-iso.alpine-linux: Stopping VM
==> proxmox-iso.alpine-linux: Deleting VM
2024/01/13 23:41:50 [INFO] (telemetry) ending proxmox-iso.alpine-linux
==> Wait completed after 45 seconds 331 milliseconds
2024/01/13 23:41:50 machine readable: error-count []string{"1"}
==> Some builds didn't complete successfully and had errors:
2024/01/13 23:41:50 machine readable: proxmox-iso.alpine-linux,error []string{"Error running boot command: Put \"https://10.69.1.230:8006/api2/json/nodes/pve/qemu/100/sendkey\": EOF"}
==> Builds finished but no artifacts were created.
2024/01/13 23:41:50 [INFO] (telemetry) Finalizing.
Build 'proxmox-iso.alpine-linux' errored after 45 seconds 331 milliseconds: Error running boot command: Put "https://10.69.1.230:8006/api2/json/nodes/pve/qemu/100/sendkey": EOF

==> Wait completed after 45 seconds 331 milliseconds

==> Some builds didn't complete successfully and had errors:
--> proxmox-iso.alpine-linux: Error running boot command: Put "https://10.69.1.230:8006/api2/json/nodes/pve/qemu/100/sendkey": EOF

==> Builds finished but no artifacts were created.
2024/01/13 23:41:50 waiting for all plugin processes to complete...
2024/01/13 23:41:50 /opt/homebrew/bin/packer: plugin process exited
2024/01/13 23:41:50 ~/.config/packer/plugins/github.com/hashicorp/proxmox/packer-plugin-proxmox_v1.1.6_x5.0_darwin_arm64: plugin process exited

[michaelpayne02]

Fixed by updating proxmox packages

[Blefish]

I was able to workaround by not using <wait5s> but instead short timeouts followed by a real command. I used spacebar, but other commands like <right> is also fine <wait><spacebar><wait><spacebar><wait><spacebar><wait><spacebar><wait><spacebar>

This helps keep the connection open, but I suspect there is something timeouting in the API so connection is dropped.