4.3.16: should "savestate" be aborting the vm?

[neilo]

Using a fresh install of 4.3.16 on Windows 7 Pro SP1, I find that

• $ VBoxManage.exe controlvm <uuid> savestate

leaves the VM in an aborted state. In Logs/VBox.log I see the following:

• $ grep "VM state" VBox.log
  00:00:00.972364 Changing the VM state from 'CREATING' to 'CREATED'.
  00:00:00.977306 Changing the VM state from 'CREATED' to 'POWERING_ON'.
  00:00:00.998114 Changing the VM state from 'POWERING_ON' to 'RUNNING'.
  00:02:28.626006 Changing the VM state from 'RUNNING' to 'SUSPENDING'.
  00:02:28.722622 Changing the VM state from 'SUSPENDING' to 'SUSPENDED'.
  00:02:28.728527 Changing the VM state from 'SUSPENDED' to 'SAVING'.
  00:02:30.033601 SSM: Successfully saved the VM state to 'C:\Users\xxxxx\VirtualBox VMs\trusty64_default_1410996474733_91815\Snapshots\2014-09-17T23-30-27-735
  155700Z.sav'
  00:02:30.033612 Changing the VM state from 'SAVING' to 'SUSPENDED'.
  00:02:30.033687 Changing the VM state from 'SUSPENDED' to 'POWERING_OFF'.
  00:02:30.033801 Changing the VM state from 'POWERING_OFF' to 'OFF'.
  00:02:30.034611 Changing the VM state from 'OFF' to 'DESTROYING'.
  00:02:30.040039 Changing the VM state from 'DESTROYING' to 'TERMINATED'.

If I then show the vm state

• $ VBoxManage.exe showvminfo <uuid>| grep State
  State: saved (since 2014-09-17T23:30:29.069000000)

I see state is saved, but this invocation of VBoxManage.exe crashes. If I immediately run it again

• $ VBoxManage.exe showvminfo <uuid>| grep State
  State: aborted (since 2014-09-17T23:33:05.833000000)

The state is now "aborted". That isn't the expected behavior, is it?

[scottgus1]

This may just be terminology in the log, or it may be a glitch.

Does your guest save-state and restart properly, despite the log messages? If so, the messages may just be issues with how the log is written, or everything may be working properly.

Regarding the change in operation with Vboxmanage, try it without grep and read through it for the "State" line. Maybe the piping is at fault, or maybe it's another issue.

[mpack]

Since I don't see how a Windows Host is relevant to the question asked, I'll move this topic to "Using VirtualBox".

[neilo]

@mpack - sure, thanks. I wasn't sure which forum to use.

@scottgus1 -

Nothing to do with the "| grep State", same result if I don't grep and instead manually inspect the full output. Again, note that "vboxmanage showvminfo <uuid>" crashes on the first invocation after savestate, and then doesn't crash thereafter.

Finally, I confirmed the guest does not restart properly after savestate, here is the error:

• $ /c/Program\ Files/Oracle/VirtualBox/VBoxManage.exe startvm 1ad06baf-f276-4f8a-9d07-86ba0ada29e0
  Waiting for VM "1ad06baf-f276-4f8a-9d07-86ba0ada29e0" to power on...
  VBoxManage.exe: error: The virtual machine 'trusty64_default_1411056660085_30660' has terminated unexpectedly during startup with exit code 1 (0x1). More details may be available in 'C:\Users\nokamoto\VirtualBox VMs\trusty64_default_1411056660085_30660\Logs\VBoxStartup.log'
  VBoxManage.exe: error: Details: code E_FAIL (0x80004005), component Machine, interface IMachine

and here are the last few lines of VBoxStartup.log:

• 778.8d8: supR3HardenedScreenImage/NtCreateSection: cache hit (VINF_SUCCESS) on \Device\HarddiskVolume2\Program Files\Oracle\VirtualBox\QtGuiVBox4.dll
  778.8d8: \Device\HarddiskVolume2\Windows\winsxs\amd64_microsoft.windows.common-controls_6595b64144ccf1df_5.82.7601.18201_none_a4d3b9377117c3df\comctl32.dll: Owner is not trusted installer (01 02 00 00 00 00 00 05 20 00 00 00 20 02 00 00)
  778.8d8: supHardenedWinVerifyImageByHandle: -> -5667 (\Device\HarddiskVolume2\Windows\winsxs\amd64_microsoft.windows.common-controls_6595b64144ccf1df_5.82.7601.18201_none_a4d3b9377117c3df\comctl32.dll)
  778.8d8: Error (rc=0):
  778.8d8: supR3HardenedScreenImage/NtCreateSection: rc=Unknown Status -5667 (0xffffe9dd) fImage=1 fProtect=0xf fAccess=0x10 \Device\HarddiskVolume2\Windows\winsxs\amd64_microsoft.windows.common-controls_6595b64144ccf1df_5.82.7601.18201_none_
  a4d3b9377117c3df\comctl32.dll: supHardenedWinVerifyImageByHandle: TrustedInstaller is not the owner of '\Device\HarddiskVolume2\Windows\winsxs\amd64_microsoft.windows.common-controls_6595b64144ccf1df_5.82.7601.18201_none_a4d3b9377117c3df\comctl32.dll'.
  778.8d8: supR3HardenedMonitor_LdrLoadDll: returns rcNt=0xc0000190 'C:\Program Files\Oracle\VirtualBox\VirtualBox.dll'
  778.8d8: Fatal error:
  778.8d8: supR3HardenedMainGetTrustedMain: LoadLibrary "C:\Program Files\Oracle\VirtualBox/VirtualBox.dll" failed, rc=1790
  20b4.19f4: supR3HardenedWinDoReSpawn(2): Quitting: ExitCode=0x1 rcNt=0x0
  510.13e4: supR3HardenedWinDoReSpawn(1): Quitting: ExitCode=0x1 rcNt=0x0

[scottgus1]

All those "supR3HardenedWinDoReSpawn"s mentioned in the log snippet make me wonder if this issue is part of the anti-invasion hardening the developers have been working on. See viewtopic.php?f=6&t=62615 for 4.3.14 and viewtopic.php?f=6&t=63556 for 4.3.16, the version you're using.

I wonder if rolling back to 4.3.12 (don't forget the extension pack) would make the problem go away? If you can test that way and the issue does resolve, then send some info on the bugtracker, and use a full log.

(after editing the last sentence to include the comment about the extension pack, it also sparks me to ask if your present version and extension pack match?)

[neilo]

4.3.12 definitely does not have this symptom -- that's the version I was using day before yesterday. So yes I could revert to that, and I plan to revert as soon as it seems we've extracted enough debugging information to help the developers.

I have never explicitly installed the extension pack for this or any prior version, if that helps.

[neilo]

build 4.3.17-96101 also has these symptoms.

I'll try posting to the "Windows 4.3.16 specifically for errors due to security" thread, and see what develops there.