packer hangs for a minute or two when it receives interrupt signal, code VBOX_E_INVALID_OBJECT_STATE in debug logs

[wheelerlaw]

Overview of the Issue

when I hit Ctrl + C when packer build ... is running, packer hangs for a minute or two during which my terminal does not respond to any keyboard input, before finally cleaning up the VM and exiting.

I'm not entirely sure if it's a Packer issue or a VBoxManage issue, but I figured I would get the log file out there so someone who knows the interface between Packer and VBoxManage better than I do could make that determination.

Reproduction Steps

1. Download that build file into config.pkr.hcl.
2. Run packer build config.pkr.hcl
3. Wait a minute or two for the boot prompt to come up, and then in your terminal where you ran packer build hit Ctrl + C.
4. You will see packer try to clean up the VM, which gets shut down nearly immediatly.
5. Try to type anything in the terminal (random letters, Ctrl + C, Ctrl + \) and nothing will happen.
6. Wait a few minutes, and packer will try to delete the machine again and will succeed.

Plugin and Packer version

Packer v1.8.4
virtualbox-iso v1.0.4

Simplified Packer Buildfile

packer {
  required_plugins {
    virtualbox = {
      version = "1.0.4"
      source = "github.com/hashicorp/virtualbox"
    }
  }
}

source "virtualbox-iso" "fedora" {
  iso_url = "https://download.fedoraproject.org/pub/fedora/linux/releases/37/Server/x86_64/iso/Fedora-Server-netinst-x86_64-37-1.7.iso"
  iso_checksum = "sha256:149d4bae999022b07bd40f8272f6208bc28884dad5110c63e915d37458e6abc0"
  ssh_username = "packer"
  shutdown_command = "shutdown now"
  guest_os_type = "Fedora_64"
  memory = "1024"
}

build {
  name    = "fedora37-workstation"
  sources = [
    "source.virtualbox-iso.fedora"
  ]
}

Operating system and Environment details

Host OS is Fedora 37 with VirtualBox 7.0.4-1.fc37.x86_64 installed through RPMFusion.

Log Fragments and crash.log files

2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 Received interrupt signal (count: 1). Ignoring.
2022/11/28 01:59:12 Cancelling builder after context cancellation context canceled
Cancelling build after receiving interrupt
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 [WARN] Interrupt detected, quitting waiting for SSH.
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 Executing VBoxManage: []string{"controlvm", "packer-fedora-1669618637", "poweroff"}
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 stdout:
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 stderr: 0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 failed to unlock port lockfile: close tcp 127.0.0.1:2817: use of closed network connection
==> fedora37-workstation.virtualbox-iso.fedora: Cleaning up floppy disk...
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 failed to unlock port lockfile: close tcp 127.0.0.1:5984: use of closed network connection
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 Executing VBoxManage: []string{"storageattach", "packer-fedora-1669618637", "--storagectl", "IDE Controller", "--port", "0", "--device", "1", "--type", "dvddrive", "--medium", "none"}
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 stdout:
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 stderr:
==> fedora37-workstation.virtualbox-iso.fedora: Deregistering and deleting VM...
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 Executing VBoxManage: []string{"unregistervm", "packer-fedora-1669618637", "--delete"}
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 stdout:
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 stderr: VBoxManage: error: Cannot unregister the machine 'packer-fedora-1669618637' while it is locked
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: VBoxManage: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component MachineWrap, interface IMachine, callee nsISupports
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: VBoxManage: error: Context: "Unregister(CleanupMode_DetachAllReturnHardDisksOnly, ComSafeArrayAsOutParam(aMedia))" at line 226 of file VBoxManageMisc.cpp
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:12 Retryable error: VBoxManage error: VBoxManage: error: Cannot unregister the machine 'packer-fedora-1669618637' while it is locked
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: VBoxManage: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component MachineWrap, interface IMachine, callee nsISupports
2022/11/28 01:59:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: VBoxManage: error: Context: "Unregister(CleanupMode_DetachAllReturnHardDisksOnly, ComSafeArrayAsOutParam(aMedia))" at line 226 of file VBoxManageMisc.cpp
2022/11/28 01:59:14 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 01:59:14 [DEBUG] SSH wait cancelled. Exiting loop.
2022/11/28 02:00:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 02:00:12 Executing VBoxManage: []string{"unregistervm", "packer-fedora-1669618637", "--delete"}
2022/11/28 02:00:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 02:00:12 stdout:
2022/11/28 02:00:12 packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64 plugin: 2022/11/28 02:00:12 stderr: 0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
==> fedora37-workstation.virtualbox-iso.fedora: Deleting output directory...
2022/11/28 02:00:12 [INFO] (telemetry) ending virtualbox-iso.fedora
==> Wait completed after 2 minutes 55 seconds
Build 'fedora37-workstation.virtualbox-iso.fedora' errored after 2 minutes 55 seconds: Build was cancelled.
2022/11/28 02:00:12 [INFO] (telemetry) Finalizing.

==> Wait completed after 2 minutes 55 seconds
Cleanly cancelled builds after being interrupted.
2022/11/28 02:00:13 waiting for all plugin processes to complete...
2022/11/28 02:00:13 /home/wheeler/.config/packer/plugins/github.com/hashicorp/virtualbox/packer-plugin-virtualbox_v1.0.4_x5.0_linux_amd64: plugin process exited

[nywilken]

Thanks for bubbling up this thread @wheelerlaw. Looking at the provided logs I see that upon the first deletion attempt, the VM is in a locked state so VBoxManage can't unregister the machine. It appears to be related to the fact that the VM still has a network connection that Packer has been unable to close, which results in a VBOX_E_INVALID_OBJECT_STATE error from VBoxManage

Packer uses this error code to determine if the command is retryable, which in this case the call to unregister is. So Packer will continue calling VBoxManage unregistervm on the VM until it is successful or has exceeded the retries (10 retries).

What you are seeing is expected behavior on how the Packer is interfacing with VBoxManage.

Do you have thoughts on how to improve this error or retry output?