Any immediate "VBoxManage modifyvm" commands after detaching a dvd drive fail with 'The machine 'vm_name' is already locked for a session'

[Jinesh Choksi]

Issue occurred on:

• The tests below were carried out on VirtualBox v5.1.6.
• The issue was also confirmed to be present in v5.1.2 and v5.1.0.
• The issue was not present in v5.0.26.

Issue description:

• After a VM is powered down, and a SATA dvd drive is detached from it via: "VBoxManage.exe storageattach" any immediately following "VBoxManage.exe modifyvm" commands fail with a "The machine 'vm_name' is already locked for a session" error.
• However, if we insert a delay (sleep) between the calls to "VBoxManage.exe storageattach" and "VBoxManage.exe modifyvm" then no errors occurr.
• This issue is related to the following forum thread: ​https://forums.virtualbox.org/viewtopic.php?f=7&t=78830 and the following Packer issue: ​https://github.com/mitchellh/packer/issues/3744

Steps to reproduce:

• Execute the test1.sh script to reproduce the issue:

Script name: test1.sh

#!/usr/bin/env bash

echo "INFO: Creating VM: test1"
./VBoxManage.exe createvm --name "test1" --ostype "RedHat_64" --register

echo "INFO: Adding a SATA controller to VM: test1"
./VBoxManage.exe storagectl "test1" --name "SATA Controller" --add "sata" --portcount 1

# test.iso = CentOS-6.7-x86_64-minimal.iso
echo "INFO: Attaching a DVD drive with a CentOS 6.x ISO to VM: test1"
./VBoxManage.exe storageattach "test1" --storagectl "SATA Controller" --port 1 --device 0 --type "dvddrive" --medium "./test.iso"

echo "INFO: Starting VM: test1"
./VBoxManage.exe startvm "test1" --type "gui"

echo "INFO: Waiting 10 seconds"
sleep 10s

echo "INFO: Powering off VM: test1"
./VBoxManage.exe controlvm "test1" "poweroff"

echo "INFO: Detaching the DVD drive from VM: test1"
./VBoxManage.exe storageattach "test1" --storagectl "SATA Controller" --port 1 --device 0 --medium "none"

# The following command will fail with the following error:
#  VBoxManage.exe: error: The machine 'test1' is already locked for a session (or being unlocked)
#  VBoxManage.exe: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component MachineWrap, interface IMachine, callee IUnknown
#  VBoxManage.exe: error: Context: "LockMachine(a->session, LockType_Write)" at line 507 of file VBoxManageModifyVM.cpp
echo "INFO: Adjusting memory size of VM: test1"
./VBoxManage.exe modifyvm "test1" --memory "2048"

• Execute the test2.sh script to see that the issue doesn't occurr if a delay is introduced between the last two VBoxManage calls:

Script name: test2.sh

#!/usr/bin/env bash

echo "INFO: Creating VM: test2"
./VBoxManage.exe createvm --name "test2" --ostype "RedHat_64" --register

echo "INFO: Adding a SATA controller to VM: test2"
./VBoxManage.exe storagectl "test2" --name "SATA Controller" --add "sata" --portcount 1

# test.iso = CentOS-6.7-x86_64-minimal.iso
echo "INFO: Attaching a DVD drive with a CentOS 6.x ISO to VM: test2"
./VBoxManage.exe storageattach "test2" --storagectl "SATA Controller" --port 1 --device 0 --type "dvddrive" --medium "./test.iso"

echo "INFO: Starting VM: test2"
./VBoxManage.exe startvm "test2" --type "gui"

echo "INFO: Waiting 10 seconds"
sleep 10s

echo "INFO: Powering off VM: test2"
./VBoxManage.exe controlvm "test2" "poweroff"

echo "INFO: Detaching the DVD drive from VM: test2"
./VBoxManage.exe storageattach "test2" --storagectl "SATA Controller" --port 1 --device 0 --medium "none"

echo "INFO: Waiting another 10 seconds"
sleep 10s

# The following command will work fine:
echo "INFO: Adjusting memory size of VM: test2"
./VBoxManage.exe modifyvm "test2" --memory "2048"

Actual results:

• Output of test1.sh script's execution:

 $  ./test1.sh
INFO: Creating VM: test1
Virtual machine 'test1' is created and registered.
UUID: 6bf55cf5-a752-49ca-9730-67e791e2fa96
Settings file: 'C:\apps\VirtualBox\Machines\test1\test1.vbox'
INFO: Adding a SATA controller to VM: test1
INFO: Attaching a DVD drive with a CentOS 6.x ISO to VM: test1
INFO: Starting VM: test1
Waiting for VM "test1" to power on...
VM "test1" has been successfully started.
INFO: Waiting 10 seconds
INFO: Powering off VM: test1
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
INFO: Detaching the DVD drive from VM: test1
INFO: Adjusting memory size of VM: test1
VBoxManage.exe: error: The machine 'test1' is already locked for a session (or being unlocked)
VBoxManage.exe: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component MachineWrap, interface IMachine, callee IUnknown
VBoxManage.exe: error: Context: "LockMachine(a->session, LockType_Write)" at line 507 of file VBoxManageModifyVM.cpp

• Output of test2.sh script's execution:

 $  ./test2.sh
INFO: Creating VM: test2
Virtual machine 'test2' is created and registered.
UUID: 46de8c6c-96ca-4bc3-aee4-76646d092f7a
Settings file: 'C:\apps\VirtualBox\Machines\test2\test2.vbox'
INFO: Adding a SATA controller to VM: test2
INFO: Attaching a DVD drive with a CentOS 6.x ISO to VM: test2
INFO: Starting VM: test2
Waiting for VM "test2" to power on...
VM "test2" has been successfully started.
INFO: Waiting 10 seconds
INFO: Powering off VM: test2
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
INFO: Detaching the DVD drive from VM: test2
INFO: Waiting another 10 seconds
INFO: Adjusting memory size of VM: test2

Expected results:

The call to the "VBoxManage.exe modifyvm" command should not error if it is called immediately after a call to "VBoxManage.exe storageattach".

[Jinesh Choksi]

The issue is present in VirtualBox v5.1.8.

For all affected versions, a workaround is to provision the instance headless.

[joelhandwell]

vboxmanage -v 5.1.14r112924

got following error:

VBoxManage.exe: error: The machine 'packer-virtualbox-iso-1486496972' is already locked for a session (or being unlocked) ==> virtualbox-iso: VBoxManage.exe: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component MachineWrap, interface IMachine, callee IUnknown ==> virtualbox-iso: VBoxManage.exe: error: Context: "LockMachine(a->session, LockType_Write)" at line 507 of file VBoxManageModifyVM.cpp ==> virtualbox-iso: Unregistering and deleting virtual machine... ==> virtualbox-iso: Deleting output directory... Build 'virtualbox-iso' errored: Error deleting port forwarding rule: VBoxManage error: VBoxManage.exe: error: The machine 'packer-virtualbox-iso-1486496972' is already locked for a session (or being unlocked) VBoxManage.exe: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component MachineWrap, interface IMachine, callee IUnknown

VBoxManage.exe: error: Context: "LockMachine(a->session, LockType_Write)" at line 507 of file VBoxManageModifyVM.cpp

related with ​https://github.com/mitchellh/packer/issues/1193

[Jinesh Choksi]

@joelhandwell: If you don't want to have Packer provision the instance in headless mode, then from Packer 0.11.0 and above, you can add the following to your vbox builder:

"post_shutdown_delay": "30s"

to work around the issue. Doing so adds a sleep period after the VM was powered off by Packer but before any subsequent actions are done on the VM.

See my comment here: ​https://github.com/mitchellh/packer/issues/3744#issuecomment-256060647

@VirtualBox devs: This issue is present in VirtualBox v5.1.12 and v5.1.14.