VBoxManage says machine already locked, but it is shutdown. Timing issue?

Discussions related to using VirtualBox on Linux hosts.
Post Reply
BrnVrn
Posts: 12
Joined: 23. Jul 2016, 15:15

VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by BrnVrn »

I am building a VirtualBox Fedora 24 guest on a Fedora 23 Host with VirtualBox 5.1.2, using packer 0.10.1

When sending for example "VBoxManage modifyvm fed24 --cableconnected1 on" it crashes with:

Code: Select all

==> vb-fedora-24-np: Gracefully halting virtual machine...
==> vb-fedora-24-np: Executing custom VBoxManage commands...
    vb-fedora-24-np: Executing: modifyvm vb-fedora-24-np --cableconnected1 on
==> vb-fedora-24-np: Error executing command: VBoxManage error: VBoxManage: error: The machine 'vb-fedora-24-np' is already locked for a session (or being unlocked)
==> vb-fedora-24-np: VBoxManage: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component MachineWrap, interface IMachine, callee nsISupports
==> vb-fedora-24-np: VBoxManage: error: Context: "LockMachine(a->session, LockType_Write)" at line 506 of file VBoxManageModifyVM.cpp
But if at the same place, I run "VBoxManage guestcontrol list sessions", it says there are no sessions

Code: Select all

==> vb-fedora-24-np: Executing custom VBoxManage commands...
    vb-fedora-24-np: Executing: guestcontrol vb-fedora-24-np list sessions --verbose
==> vb-fedora-24-np: Error executing command: VBoxManage error: VBoxManage: error: Machine "vb-fedora-24-np" is not running (currently powered off)!
If I insert harmless commands, like "showvminfo myVM --details" about 10x, then it works. So I guess it is some kind of timing issue.
As the error message says "session is being unlocked". But does VirtualBox provide a clean workaround ??? Cleaner than issuing 10x showinfo ..

Thanks

Also the initial problem, is that if I create the machine with virtio interfaces, it disconnects the cables when exporting the machine. So I have to explicitly connect the cables ...
Last edited by BrnVrn on 23. Jul 2016, 16:12, edited 1 time in total.
Perryg
Site Moderator
Posts: 34369
Joined: 6. Sep 2008, 22:55
Primary OS: Linux other
VBox Version: OSE self-compiled
Guest OSses: *NIX

Re: VBoxManage says machine already locked, but it is shutdown

Post by Perryg »

Post the guests log file ( as an attachment ). Right click on the guest in the Main Manager then click show log. Save and post as an attachment. Compress if it is too large to post.
socratis
Site Moderator
Posts: 27329
Joined: 22. Oct 2010, 11:03
Primary OS: Mac OS X other
VBox Version: PUEL
Guest OSses: Win(*>98), Linux*, OSX>10.5
Location: Greece

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by socratis »

BrnVrn wrote:I am building a VirtualBox Fedora 24 guest on a Fedora 23 Host with VirtualBox 5.1.2, using packer 0.10.1
https://en.wikipedia.org/wiki/Packer_(software) wrote: Packer is free and open-source software for creating identical machine images or containers for multiple platforms from a single source configuration. It is used primarily to automate the creation of machine images which have a particular operating system and pre-installed software in it. It was written by Mitchell Hashimoto and became one of the products in his company Hashicorp's software toolkits as open-source proprietary-managed software. Packer can be used with Vagrant or independently. Packer can also be used with configuration management tools such as Chef and Puppet. However, it does not serve as a substitute for these tools.
"Packer" seems to be a tool like Vagrant that operates on top of VirtualBox. Have you tried these commands just with the VBoxManage CLI instead of using "packer"? Do you still get the same results?
Do NOT send me Personal Messages (PMs) for troubleshooting, they are simply deleted.
Do NOT reply with the "QUOTE" button, please use the "POST REPLY", at the bottom of the form.
If you obfuscate any information requested, I will obfuscate my response. These are virtual UUIDs, not real ones.
BrnVrn
Posts: 12
Joined: 23. Jul 2016, 15:15

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by BrnVrn »

I have the error using Packer.
If I just create a very simple VM with Packer, export it to VirtualBox, then I can successfully use the command line to issue VBoxManage commands.
I am also successful if I run Packer in step-by-step mode, which makes me think there is a timing issue.

Here I post two logs, with differents errors I got from VirtualBox 5.1.2.
Attachments
VBox.log
Success
(107.85 KiB) Downloaded 207 times
2016-07-23_17h40_packer.txt
failure trace
(108.44 KiB) Downloaded 199 times
BrnVrn
Posts: 12
Joined: 23. Jul 2016, 15:15

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by BrnVrn »

A trace from VirtualBox when I got the error

==> vb-fedora-24-np: Gracefully halting virtual machine...
==> vb-fedora-24-np: Executing custom VBoxManage commands...
vb-fedora-24-np: Executing: modifyvm vb-fedora-24-np --vrde off
==> vb-fedora-24-np: Error executing command: VBoxManage error: VBoxManage: error: The machine 'vb-fedora-24-np' is already locked for a session (or being unlocked)
==> vb-fedora-24-np: VBoxManage: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component MachineWrap, interface IMachine, callee nsISupports
==> vb-fedora-24-np: VBoxManage: error: Context: "LockMachine(a->session, LockType_Write)" at line 506 of file VBoxManageModifyVM.cpp
==> vb-fedora-24-np: Unregistering and deleting virtual machine...
==> vb-fedora-24-np: Deleting output directory...


Not sure if the Virtual Box log file ends before the error appear? Because Packer shutdown the VM and then launch the VBoxManage commands ...
Attachments
VBox-log-Not-Working-3.txt
(108.02 KiB) Downloaded 192 times
Last edited by BrnVrn on 23. Jul 2016, 18:37, edited 1 time in total.
Perryg
Site Moderator
Posts: 34369
Joined: 6. Sep 2008, 22:55
Primary OS: Linux other
VBox Version: OSE self-compiled
Guest OSses: *NIX

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by Perryg »

Seems you just proved the obvious to me. Not using packer it works and when using packer it does not. I believe you need to consult with packer.
BrnVrn
Posts: 12
Joined: 23. Jul 2016, 15:15

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by BrnVrn »

Here we go, Packer is telling me it is a VirtualBox problem and VirtualBox tells me it is a Packer issue.

To me it looks like VirtualBox is telling Packer that the VM has shutdown when in fact there is still some session hanging on.
When Packer makes another request, boom VirtualBox crashes because there is still a session locking the machine.

Either every automation tools tries to insert delays or retries everywhere, or VirtualBox provides a clean way to tells when it is ready to accept modifyvm commands.

Pure speculation here, but if I read the last lines from VirtualBox:

Code: Select all

00:05:21.112882 Changing the VM state from 'DESTROYING' to 'TERMINATED'
00:05:21.115679 Console: Machine state changed to 'PoweredOff'
00:05:21.115896 GUI: Request to close Runtime UI because VM is powered off already.
00:05:21.115907 GUI: Passing request to close Runtime UI from machine-logic to UI session.
It could be interpreted as The state is set to "terminated" before requesting the UI to close the session ?? Could it be that simple ??
Perryg
Site Moderator
Posts: 34369
Joined: 6. Sep 2008, 22:55
Primary OS: Linux other
VBox Version: OSE self-compiled
Guest OSses: *NIX

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by Perryg »

Look at it this way. If this were truly a VirtualBox "timing" issue it would appear without your 3rd party program. When you interject something into the mix it is always the responsibility of the 3rd party program to do or deal with what ever it is they are doing. I know it can be frustrating and seem like a run around but we simply have no way to know what they are doing or how they are issuing commands. Same goes for vagrant or docker. If packer knows this to be a VirtualBox issue then what do they say the problem is? Do they have a clue or just tell you it is not their fault and no way to back it up? You have already proven that without packer the guest does in fact work the way it is intended to work, or have I missed something?
BrnVrn
Posts: 12
Joined: 23. Jul 2016, 15:15

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by BrnVrn »

Maybe VirtualBox could be improved by either:
- closing sessions before claiming that the machine is shutdown
- warn developers using the API that shutting the machine down does NOT imply that all sessions are closed AND provides a way to know when it is ready to accept modifyVM commands

My last hypothesis might be true, I tried to run "headless" and indeed it worked. Really another hint that VirtualBox bother to close the UI session after claiming that the machine is shutdown, which is kind of misleading to me. Even if there might be good reason to do it this way.

I am not saying it is strictly a VirtualBox issue. But it maybe at the interface: clearly understanding the API and how to use it is key.
Last edited by BrnVrn on 23. Jul 2016, 23:16, edited 1 time in total.
Perryg
Site Moderator
Posts: 34369
Joined: 6. Sep 2008, 22:55
Primary OS: Linux other
VBox Version: OSE self-compiled
Guest OSses: *NIX

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by Perryg »

I'm not going to argue about this and it appears your mind is made up, but I can tell you VirtualBox does not go out of its way to prevent any 3rd party program from working and if packer wanted to improve they would contact the developers to see why they have an issue with the API. It is outlined in the SDK and does change from time to time. Good luck and I hope you find a resolve but at this point I have nothing further to contribute.
BrnVrn
Posts: 12
Joined: 23. Jul 2016, 15:15

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by BrnVrn »

No problem, thanks for your time (and patience and cordialness).

Follow-up here: https://github.com/mitchellh/packer/issues/3744
jchoksi
Posts: 1
Joined: 12. Oct 2016, 14:39

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by jchoksi »

Perryg wrote:I'm not going to argue about this and it appears your mind is made up, but I can tell you VirtualBox does not go out of its way to prevent any 3rd party program from working and if packer wanted to improve they would contact the developers to see why they have an issue with the API. It is outlined in the SDK and does change from time to time. Good luck and I hope you find a resolve but at this point I have nothing further to contribute.
Hi

I went through Packer's code and saw that it was simply making calls to VBoxManage and so after some brief experimentation, I've reproduced the issue using solely VBoxManage commands and no third party products.

You can refer to Virtualbox ticket 16063 (sorry I can't paste a U R L to the ticket directly since I need to be a member of this forum for >1 day and have at least 1 post before I can post U R Ls) to see issue reproduction steps and output.

As closely as possible, I followed the order of VBoxManage commands Packer was executing and I was wondering whether there was some other VBoxManage command it (packer) should have executed either after or before detaching the DVD drive and before running the VBoxManage modifyvm commands? i.e. is there something wrong with the following flow?

Code: Select all

#!/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"
Output for running the above script:

Code: Select all

 $  ./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
Is it important to note that if I add a "sleep 10s" command just before the "VBoxManage.exe modifyvm" command then no errors occur. Also, I don't think it matters what iso is used in case you were trying to reproduce this locally.

Regards,
Jinesh
Last edited by socratis on 12. Oct 2016, 17:36, edited 1 time in total.
Reason: Added missing URL.
socratis
Site Moderator
Posts: 27329
Joined: 22. Oct 2010, 11:03
Primary OS: Mac OS X other
VBox Version: PUEL
Guest OSses: Win(*>98), Linux*, OSX>10.5
Location: Greece

Re: VBoxManage says machine already locked, but it is shutdown. Timing issue?

Post by socratis »

jchoksi wrote:is there something wrong with the following flow?
Not that I can think of, the flow is fine. The flow rate is the problem ;)
jchoksi wrote:if I add a "sleep 10s" command just before the "VBoxManage.exe modifyvm" command then no errors occur
There you have it. Apparently there are commands that take some finite time to execute in the background. For example if I were to issue a defrag command and then issue a chkdsk command, the latter would fail because the disk is locked exclusively.

I can see the problem and the reasoning that VirtualBox returns immediately control to your script, instead of waiting to finish the job. That maybe something that the developers might be investigating. There maybe reasons behind it, or it may very well be a bug (sounds like it).

I saw ticket #16063. Nice. I'll edit your post as well to include the URL.
Do NOT send me Personal Messages (PMs) for troubleshooting, they are simply deleted.
Do NOT reply with the "QUOTE" button, please use the "POST REPLY", at the bottom of the form.
If you obfuscate any information requested, I will obfuscate my response. These are virtual UUIDs, not real ones.
Post Reply