VirtualBox loses track of running VMs

[mark1ewis]

Occasionally, VirtualBox will lose track of all running VMs. After that point, running VBoxManage list runningvms will not return any VMs, running VBoxManage showvminfo lists the VM as powered off, attempting to unregister the VM will not complain that the VM is running, etc.

Newly started VMs are correctly tracked, until the error occurs again.

The VMs are definitely still running, I can ssh into the machines and they function fine. The VBoxHeadless and VBoxSVC processes are still running, and there are no entries written to the VBox.log or VBoxSVC.log files at the time. I've confirmed that all interaction with VBox is occurring from the same user account.

I experienced this with VirtualBox 4.2.10 with Ubuntu 13.04 as the host OS, so I tried upgrading to Ubuntu 13.10 with 4.2.13 (both versions from Ubuntu packages), then I switched to the official 4.3.0 Ubuntu package from virtualbox.org. I've exported my VMs as OVF, wiped out my VM folders and the .config/VirtualBox directory to get a clean start and reimported, and in all configurations the issue still persists.

There does not seem to be an obvious trigger for the behavior-- sometimes hours will pass, other times it occurs every few minutes. No other significant activity is going on at the time; it happens in the middle of the night with no users on the system at about the same frequency as during the day.

There are scripts running that every couple of seconds run "VBoxManage listvms" and then several possibly concurrent "VBoxManage guestproperty get" commands. Also, my use case is that I always allocate new VMs by creating a linked clone from a template snapshot.

One interesting thing to note is that in the output of "VBoxManage showvminfo", where it says that the state is powered off, it says that it has been powered off since the same timestamp as the VM was started.

I'm attaching output of several commands I ran at the console to try to diagnose the problem:

1. The setup script used to allocate each new VM
2. A list of running VMs showing only one recently allocated VM running
3. Output of showvminfo for one of the VMs still running but not included on the previous list.
4. List of running VBoxHeadless processes
5. List of running VBoxSVC processes
6. A couple of sample VBoxSVC.log files. They all look the same as these.
7. The VBox.log file for the VM that is running but not shown on the list of running VMs. I don't see anything interesting in this log.

[mark1ewis]

Note that this ticket seems similar to #9223. It didn't look similar enough to add onto that existing ticket, but it may be related.

[mark1ewis]

The attachments "01" and "06" are the sample VBoxSVC.log files; the full file names had colons in them and Trac doesn't seem to like that.

[mark1ewis]

It looks like in some cases but not always, I'm also seeing the following errors in the VBoxSVC log:

00:00:00.280984 nspr-4   ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={22781af3-1c96-4126-9edf-67a020e0e858} aComponent={Machine} aText={An unexpected process (PID=0x000027EB) has tried to lock the machine '4790302c-8ee6-417e-aa1b-6adf24b3191e', while only the process started by LaunchVMProcess (PID=0xFFFFFFFF) is allowed}, preserve=false
00:00:00.281574 nspr-2   ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={22781af3-1c96-4126-9edf-67a020e0e858} aComponent={Machine} aText={An unexpected process (PID=0x000027FA) has tried to lock the machine '4790302c-8ee6-417e-aa1b-6adf24b3191e', while only the process started by LaunchVMProcess (PID=0xFFFFFFFF) is allowed}, preserve=false
00:00:00.282878 nspr-5   ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={22781af3-1c96-4126-9edf-67a020e0e858} aComponent={Machine} aText={An unexpected process (PID=0x000027E9) has tried to lock the machine '4790302c-8ee6-417e-aa1b-6adf24b3191e', while only the process started by LaunchVMProcess (PID=0xFFFFFFFF) is allowed}, preserve=false

[aeichner]

Please reopen if still relevant with a recent VirtualBox release.