VM Hangs after saving state

[Brian Havard]

After upgrading from 2.1.4 to 2.2.2 I've had this problem a number of times, though not always (maybe 1 in 4).

After using a VM for a while (doesn't seem to matter what guest OS) I use Host-Q, pick "Save the machine state", watch the progress bar reach 100% and disappear. At this point the VM screen is still greyed and just sits there forever. I can minimize the VM with a Host tap, Alt-F9, and kill the VirtualBox processes. If I kill the VM process last I can later restore the VM successfully, indicating that the save worked.

Host is Ubuntu Jaunty 32 bit.

The last few lines of the log are:

00:06:39.323 Guest Log: VBOXNP: DLL unloaded.
00:06:40.872 Changing the VM state from 'RUNNING' to 'SUSPENDED'.
00:06:42.684 Changing the VM state from 'SUSPENDED' to 'SAVING'.
00:06:46.093 vboxClipboardConvertToUtf8ForX11: VBoxX11ClipboardReadVBoxData returned VERR_TIMEOUT
00:06:47.277 SharedFolders host service: saving state, u32ClientID = 1
00:06:47.704 Changing the VM state from 'SAVING' to 'SUSPENDED'.
00:06:47.715 Console::powerDown(): A request to power off the VM has been issued (mMachineState=9, InUninit=0)
00:06:47.720 SharedFolders host service: disconnected, u32ClientID = 1
00:06:47.720 VBoxX11ClipboardStopX11: stopping the shared clipboard X11 backend
00:11:47.757 VBoxX11ClipboardStopX11: rc=VERR_TIMEOUT

[Michael Thayer]

Could you please check a few more logs and see if you ever see similar timeout messages at the end on successful shutdowns, and whether you always get them (both of them, that is) on failed shutdowns? Thanks.

[Michael Thayer]

And could you create a core dump of a hanging VirtualBox process for us? See ​http://www.virtualbox.org/wiki/Core_dump

[Brian Havard]

I'm pretty sure I've never seen timeouts logged on successful save & shutdown. I've just tried it a few times and the log looks clean, like this:

00:00:10.106 Changing the VM state from 'RUNNING' to 'SUSPENDED'.
00:00:11.591 Changing the VM state from 'SUSPENDED' to 'SAVING'.
00:00:16.113 SharedFolders host service: saving state, u32ClientID = 1
00:00:16.574 Changing the VM state from 'SAVING' to 'SUSPENDED'.
00:00:16.584 Console::powerDown(): A request to power off the VM has been issued (mMachineState=9, InUninit=0)
00:00:16.590 SharedFolders host service: disconnected, u32ClientID = 1
00:00:16.590 VBoxX11ClipboardStopX11: stopping the shared clipboard X11 backend
00:00:16.590 Shared clipboard: host clipboard thread terminated successfully
00:00:16.594 vboxClipboardDestroy: shutting down host clipboard
00:00:16.594 ****************** Guest state at power off ******************
...

The "vboxClipboardConvertToUtf8ForX11" timeout seems to always occur if it hangs. I've got a stuck VM right now and the last log line is a "stopping the shared clipboard X11 backend".

The second timeout occurs after 5 minutes of waiting which fits what I can see in the code around x11-clipboard.cpp:792. However, even after this 5 minute wait, the VM process still doesn't exit.

I can make it hang every time by copying something to the clipboard within the VM before trying to close it.

I'll have a go at getting a core dump.

[Brian Havard]

Ok, I've got a core dump. It's 29MB big after turning down the VM's base memory size and bzip2 compressing it so I guess emailing it is out. Is there somewhere I can upload it to?

[Michael Thayer]

Can you upload it to ftp.innotek.de/incoming? Note that you won't be able to view it after you have uploaded it, and you only get one shot, as you can't overwrite existing files there. Thanks.

[Michael Thayer]

And could you mention the filename on this ticket? I don't personally have access to that directory either, so I don't know if there are other core files in there :)

[Brian Havard]

Sure, I just uploaded it as 4020.core.bz2

[Michael Thayer]

bjh: I think we have fixed your hang. I will send you a link by private mail to an updated version of VirtualBox that you can try out if you like.

[Brian Havard]

I just tried the updated version. You're right, it doesn't hang any more though it does still log a time-out error. I don't know if that matters.

00:00:23.634 Changing the VM state from 'SAVING' to 'SUSPENDED'.
00:00:23.644 Console::powerDown(): A request to power off the VM has been issued (mMachineState=9, InUninit=0)
00:00:23.650 SharedFolders host service: disconnected, u32ClientID = 4
00:00:23.650 VBoxX11ClipboardStopX11: stopping the shared clipboard X11 backend
00:00:23.650 vboxClipboardConvertToUtf8ForX11: VBoxX11ClipboardReadVBoxData returned VERR_TIMEOUT
00:00:23.656 Shared clipboard: host clipboard thread terminated successfully
00:00:23.657 vboxClipboardDestroy: shutting down host clipboard
00:00:23.658 ****************** Guest state at power off ******************

[Michael Thayer]

The timeout error is expected, and should probably not even be logged - it just means that the guest has not responded to a clipboard request from the host in time, which is not surprising given that the guest has been "put to sleep". So the problem seems to be fixed. Thanks very much for testing!

[Frank Mehnert]

Please reopen if this problem still occurs with VirtualBox 2.2.4.

[Nazgulled]

Hi,

I do have this problem in 2.2.4 but I'm using Windows Vista as a host and I'm talking about a linux guest. Never happened with a Windows guest but I use the linux guest most of the time though...

It gets pretty annoying cause sometimes, maybe I don't kill the processes correctly but, I loose some of my work and the image state says "aborted" instead of "saved".

[MrX1980]

Please try it with v3.0.0

[Nazgulled]

It still happens :(

[Nazgulled]

Still happening with 3.0.4... It's getting very annoying, I'm afraid something goes wrong and I lose my files :/

[Frank Mehnert]

Nazgulled, please could you attach a VBox.log file of such a VM session which was hanging after saving the state? Thank you!

[Nazgulled]

Since this doesn't happen all the time, we'll have to wait that it happens and hope that I don't forget to copy and post the log before it gets overwritten by others. :)

[anonymous]

I'm still seeing this bug. Mac OS 10.5.8 host, WinXP SP3 guest, VirtualBox 3.0.6 (though I updated once, installed this appliance originally on the previous version-- 3.0.5 was it?) When choosing "Save machine state" it gets most of the way through the process, disappears, and then thestate is listed as "Aborted". Next start looks like a cold boot after no shutdown-- WinXP runs chkdsk, files that weren't closed come up corrupted.

I'd post the log, but for some reason it doesn't have any entries for the last few days/boots. ?:-/

I saw in another forum to enable IO APCI to fix this, but I saw in the docs that that can cause problems in an existing windows install...

[anonymous]

Ok, this is weird. I tried it again, and for the first time ever, it saved state properly. However, when I tried to resume the saved state, it almost immediately crashed and once again listed the state as "Aborted". I did nothing that I would expect would change the scenario: I looked at some settings (but changed nothing), including confirming that IO ACPI was and has always been on for this appliance, and I also paused and unpaused the VM briefly. I am copying in a log (I figured out I was reading the dates wrong-- logging is working properly) Log follows:

00:00:02.928 REM: VBoxREM32 00:00:02.946 TM: GIP - u32Mode=1 (SyncTSC) u32UpdateHz=100 00:00:02.978 TM: cTSCTicksPerSecond=0x96c97444 (2 529 784 900) fTSCVirtualized=true fTSCUseRealTSC=false 00:00:02.978 TM: fMaybeUseOffsettedHostTSC=true TSCTiedToExecution=false TSCNotTiedToHalt=false 00:00:02.979 CoreCode: R3=007fd000 R0=5077e000 RC=a0210000 Phys=00000000010da000 cb=0x3000 00:00:03.029 [SMP] BIOS with 1 CPUs 00:00:03.056 SUP: Loaded VBoxDDR0.r0 (/Applications/VirtualBox.app/Contents/MacOS/VBoxDDR0.r0) at 0x426eb060 - ModuleInit at 0000000000000000 and ModuleTerm at 0000000000000000 00:00:03.065 SUP: Loaded VBoxDD2R0.r0 (/Applications/VirtualBox.app/Contents/MacOS/VBoxDD2R0.r0) at 0x423c0060 - ModuleInit at 0000000000000000 and ModuleTerm at 0000000000000000 00:00:03.065 Activating Local APIC 00:00:03.065 CPUMSetGuestCpuIdFeature: Enabled APIC 00:00:03.065 CPUMSetGuestCpuIdFeature: Disabled x2APIC 00:00:03.065 PIT: mode=3 count=0x10000 (65536) - 18.20 Hz (ch=0) 00:00:03.080 Shared Folders service loaded. 00:00:03.113 VDInit finished 00:00:03.116 PIIX3 ATA: LUN#0: disk, PCHS=16383/16/63, total number of sectors 41943040 00:00:03.116 PIIX3 ATA: LUN#1: no unit 00:00:03.116 PIIX3 ATA: LUN#2: CD/DVD, total number of sectors 0, passthrough disabled 00:00:03.116 PIIX3 ATA: LUN#3: no unit 00:00:03.116 PIIX3 ATA: Ctl#0: finished processing RESET 00:00:03.212 PIIX3 ATA: Ctl#1: finished processing RESET 00:00:03.321 NAT: value of BindIP has been ignored 00:00:03.324 Audio: Trying driver 'coreaudio'. 00:00:04.347 DevPcBios: ATA LUN#0 LCHS=1024/255/63 00:00:04.366 PGMR3InitFinalize: 4 MB PSE mask 0000000fffffffff 00:00:04.378 HWACCM: Host CR4=00000660 00:00:04.378 HWACCM: MSR_IA32_FEATURE_CONTROL = 7 00:00:04.378 HWACCM: MSR_IA32_VMX_BASIC_INFO = 5a08000000000d 00:00:04.378 HWACCM: VMCS id = d 00:00:04.378 HWACCM: VMCS size = 800 00:00:04.378 HWACCM: VMCS physical address limit = None 00:00:04.378 HWACCM: VMCS memory type = 6 00:00:04.378 HWACCM: Dual monitor treatment = 1 00:00:04.378 HWACCM: MSR_IA32_VMX_PINBASED_CTLS = 3f00000016 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PIN_EXEC_CONTROLS_EXT_INT_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PIN_EXEC_CONTROLS_NMI_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PIN_EXEC_CONTROLS_VIRTUAL_NMI 00:00:04.378 HWACCM: MSR_IA32_VMX_PROCBASED_CTLS = f7f9fffe0401e172 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_IRQ_WINDOW_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_TSC_OFFSET 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_HLT_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_INVLPG_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_MWAIT_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_RDPMC_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_RDTSC_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_CR3_LOAD_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_CR3_STORE_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_CR8_LOAD_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_CR8_STORE_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_USE_TPR_SHADOW 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_NMI_WINDOW_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_MOV_DR_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_UNCOND_IO_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_USE_IO_BITMAPS 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_USE_MSR_BITMAPS 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_MONITOR_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_PAUSE_EXIT 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_USE_SECONDARY_EXEC_CTRL 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_CR3_LOAD_EXIT *must* be set 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC_CONTROLS_CR3_STORE_EXIT *must* be set 00:00:04.378 HWACCM: MSR_IA32_VMX_PROCBASED_CTLS2 = 4100000000 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC2_VIRT_APIC 00:00:04.378 HWACCM: VMX_VMCS_CTRL_PROC_EXEC2_WBINVD_EXIT 00:00:04.378 HWACCM: MSR_IA32_VMX_ENTRY_CTLS = 3fff000011ff 00:00:04.378 HWACCM: VMX_VMCS_CTRL_ENTRY_CONTROLS_LOAD_DEBUG 00:00:04.378 HWACCM: VMX_VMCS_CTRL_ENTRY_CONTROLS_IA64_MODE 00:00:04.378 HWACCM: VMX_VMCS_CTRL_ENTRY_CONTROLS_ENTRY_SMM 00:00:04.378 HWACCM: VMX_VMCS_CTRL_ENTRY_CONTROLS_DEACTIVATE_DUALMON 00:00:04.378 HWACCM: VMX_VMCS_CTRL_ENTRY_CONTROLS_LOAD_GUEST_PERF_MSR 00:00:04.378 HWACCM: VMX_VMCS_CTRL_ENTRY_CONTROLS_LOAD_DEBUG *must* be set 00:00:04.378 HWACCM: MSR_IA32_VMX_EXIT_CTLS = 3ffff00036dff 00:00:04.378 HWACCM: VMX_VMCS_CTRL_EXIT_CONTROLS_SAVE_DEBUG 00:00:04.378 HWACCM: VMX_VMCS_CTRL_EXIT_CONTROLS_HOST_AMD64 00:00:04.378 HWACCM: VMX_VMCS_CTRL_EXIT_CONTROLS_ACK_EXTERNAL_IRQ 00:00:04.378 HWACCM: VMX_VMCS_CTRL_EXIT_CONTROLS_SAVE_DEBUG *must* be set 00:00:04.378 HWACCM: MSR_IA32_VMX_MISC = 403c0 00:00:04.378 HWACCM: MSR_IA32_VMX_MISC_PREEMPT_TSC_BIT 0 00:00:04.378 HWACCM: MSR_IA32_VMX_MISC_ACTIVITY_STATES 7 00:00:04.378 HWACCM: MSR_IA32_VMX_MISC_CR3_TARGET 4 00:00:04.378 HWACCM: MSR_IA32_VMX_MISC_MAX_MSR 200 00:00:04.378 HWACCM: MSR_IA32_VMX_MISC_MSEG_ID 0 00:00:04.378 HWACCM: MSR_IA32_VMX_CR0_FIXED0 = 80000021 00:00:04.378 HWACCM: MSR_IA32_VMX_CR0_FIXED1 = ffffffff 00:00:04.378 HWACCM: MSR_IA32_VMX_CR4_FIXED0 = 2000 00:00:04.378 HWACCM: MSR_IA32_VMX_CR4_FIXED1 = 67ff 00:00:04.378 HWACCM: MSR_IA32_VMX_VMCS_ENUM = 2c 00:00:04.378 HWACCM: TPR shadow physaddr = 00000000010de000 00:00:04.378 HWACCM: VCPU0: MSR bitmap physaddr = 00000000010ea000 00:00:04.378 HWACCM: VCPU0: VMCS physaddr = 00000000010e2000 00:00:04.378 HWACCM: Real Mode TSS guest physaddr = 00000000f0800000 00:00:04.378 HWACCM: Non-Paging Mode EPT CR3 = 00000000f0803000 00:00:04.378 CPUMSetGuestCpuIdFeature: Enabled sysenter/exit 00:00:04.378 HWACCM: 32-bit guests supported. 00:00:04.378 HWACCM: VMX enabled! 00:00:04.388 VM: Halt method global1 (5) 00:00:04.388 Changing the VM state from 'CREATING' to 'CREATED'. 00:00:04.389 Changing the VM state from 'CREATED' to 'LOADING'. 00:00:04.905 SSM: File header: Format V1.2, VirtualBox Version 3.0.6 r52128, 32-bit host, cbGCPhys=8, cbGCPtr=8 00:00:04.905 PCI: PIIX3/0: register 60: 0b -> 80 00:00:04.905 PCI: PIIX3/0: register 61: 09 -> 89 00:00:04.905 PCI: PIIX3/0: register 62: 0b -> 8b 00:00:04.905 PCI: PIIX3/0: register 63: 09 -> 80 00:00:04.905 PCI: PIIX3/0: register ad: 00 -> ef 00:00:04.905 PCI: PIIX3/0: register de: 00 -> be 00:00:04.905 PCI: piix3ide/0: register 40: 00 -> 07 00:00:04.905 PCI: piix3ide/0: register 41: 80 -> e3 00:00:04.905 PCI: piix3ide/0: register 42: 00 -> 03 00:00:04.905 PCI: piix3ide/0: register 43: 80 -> e3 00:00:04.905 PCI: piix3ide/0: register 48: 00 -> 05 00:00:04.905 PCI: piix3ide/0: register 4a: 00 -> 02 00:00:04.905 PCI: piix3ide/0: register 4b: 00 -> 02 00:00:04.905 PCI: vga/0: 16-bit field COMMAND: 2 -> 7 00:00:04.906 PCI: pcnet/0: 8-bit field LATENCY_TIMER: 0 -> 60 - !READ ONLY! 00:00:04.906 PCI: pcnet/0: 8-bit field INTERRUPT_LINE: b -> 13 00:00:04.906 PCI: VMMDev/0: 8-bit field INTERRUPT_LINE: 9 -> 14 00:00:04.906 PCI: VMMDev/0: 16-bit field COMMAND: 3 -> 7 00:00:04.906 PCI: usb-ohci/0: 8-bit field INTERRUPT_LINE: 9 -> 16 00:00:04.906 PCI: usb-ohci/0: 16-bit field COMMAND: 2 -> 7 00:00:04.906 PCI: acpi/0: 16-bit field COMMAND: 1 -> 7 00:00:04.906 PCI: usb-ehci/0: 8-bit field INTERRUPT_LINE: b -> 13 00:00:04.906 PCI: usb-ehci/0: 16-bit field COMMAND: 2 -> 7 00:00:06.212 TM: cTSCTicksPerSecond=0x9687247c (2 525 439 100) fTSCVirtualized=true fTSCUseRealTSC=false (state load) 00:00:06.218 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0) (restore) 00:00:06.218 RTC: period=0x200 (512) 64 Hz (restore) 00:00:06.218 SharedFolders host service: connected, u32ClientID = 1 00:00:06.218 SharedFolders host service: loading state, u32ClientID = 1 00:00:06.218 SharedFolders host service: success 00:00:06.218 Guest Additions information report: additionsVersion = 0x00010004, osType = 0x00033000 00:00:06.747 00:00:06.747 !!Assertion Failed!! 00:00:06.747 Expression: !VM_FF_ISSET(pVM, VM_FF_PDM_DMA) 00:00:06.747 Location : /Users/vbox/tinderbox/3.0-mac-rel/src/VBox/VMM/PDM.cpp(814) int pdmR3Load(VM*, SSMHANDLE*, uint32_t)

Perhaps that assertion has something to do with it? But what is VM_FF_PDM_DMA?

Thanks again for taking a look into this.

[vasily Levchenko]

Replying to john.doe: John, please attach log, don't copy it.

[anonymous]

Roger that. Since the nature of this bug now better resembles ticket #3609 I have moved it to there, the full log is attached there. Thanks!

[Frank Mehnert]

john.doe's problem is finally fixed, see #5042. So, Nazgulled, if this still happens with VBox 3.0.8 (not yet released), please attach an appropriate VBox.log file.

[anonymous]

#5042 is confirmed fixed as of 3.0.8, thank you for your help! A problem with similar symptoms occurs when a USB device is attached (see #5146), so perhaps Nazgulled can confirm whether or not USB devices were attached when his problem occurred. I hope that helps!

[Nazgulled]

I haven't used VBox that much lately but as far as I can remember, I didn't plug in USB devices when I noticed this problem.

[Frank Mehnert]

So I will close this bug as you already opened a proper ticket for the other problem, thanks for the feedback