venerdì 28 ottobre 2011

VirtualBox + Powershell = genius (?) in the box

Today I'm facing another strange behavior of the command-line interface "vboxmanage.exe" for Oracle's VirtualBox.
Here is the Powershell code I'm executing on a remote machine to reboot a virtual machine:
$VM = "WindowsXP";
Invoke-Command -ScriptBlock {vboxmanage controlvm $args reset} -ArgumentList $VM ComputerName 10.3.2.127

Ok, I got an error that is:
VBoxManage.exe: error: Invalid machine state: PoweredOff
+ CategoryInfo : NotSpecified: (VBoxManage.exe:...ate: PoweredOff:String) [], RemoteException
+ FullyQualifiedErrorId : NativeCommandError

VBoxManage.exe: error: Details: code VBOX_E_INVALID_VM_STATE (0x80bb0002), component Console, interface IConsole, callee IUnknown
Context: "Reset()" at line 124 of file VBoxManageControlVM.cpp

The weird thing is that on the machine that hosts the VM (10.3.2.127) the reset works fine.
I checked the execution state on both the host and the remote machine and... guess what... I discovered that the state was different: Powered Off on the remote machine, and running on the host.
host: State: running (since 2011-10-22T22:20:35.359000000)
remote: State: powered off (since 2011-10-18T14:39:32.000000000)
To be sure it was the same machine, I checked the UUID of the machine, and it is the same.
And the machine is accessible, too (it works!)
Another strange thing is the time since the VM results stopped on the remote machine, actually 4 days before, probably since the last try in "reset" the VM.

And here is the deal. When then I tried to start the machine remotely, I got this error:
Invoke-Command -ScriptBlock {vboxmanage startvm "WindowsXP" --type headless} -ArgumentList "WindowsXP" -ComputerName 10.3.2.127
Waiting for VM "WindowsXP" to power on...
VBoxManage.exe: error: Failed to open release log (could not open file 'C:\Documents and Settings\perfmon\VirtualBox VMs\WindowsXP\Logs\VBox.log' (fOpen=0x322), VERR_SHARING_VIOLATION)
+ CategoryInfo : NotSpecified: (VBoxManage.exe:...RING_VIOLATION):String) [], RemoteException
+ FullyQualifiedErrorId : NativeCommandError

VBoxManage.exe: error: Details: code E_FAIL (0x80004005), component Console, interface IConsole, callee

Then I recalled that the last time I started the VM directly from the host, and not from the remote machine.
Like this, the handler of the log file is still associated to the process which started the machine (on the host), and the powershell process, which tries to access the machine, cannot get the handler. This results in a false information about the state of the machine.

Thus, to solve the problem, I powered off the VM on the host, and I started it successfully on the remote machine:
Invoke-Command -ScriptBlock {vboxmanage startvm "WindowsXP" --type headless} -ArgumentList "WindowsXP" -ComputerName 10.3.2.127
Waiting for VM "WindowsXP" to power on...
VM "WindowsXP" has been successfully started.
and then I checked if the reset was working:
Invoke-Command -ScriptBlock {vboxmanage controlvm $args reset} -ArgumentList "WindowsXP" -ComputerName 10.3.2.127
and the machine state was:
State: running (since 2011-10-28T12:54:58.718000000)

Here we go!!! :)
Ivano 1, VirtualBox 0