savestate order matters for multiple headless VMs

[kihjin]

I was able to replicate this issue on two machines.

Pre-condition: You have N > 1 VMs running headless mode

Test: Run controlvm savestate on all of them, one by one

Result: If the first VM that you started is savestate'd before the others, the other savestate attempts will fail. The system will report the other VMs as having 'aborted,' yet they continue to function normally. After this point none of the controlvm functions for these vms will work.

Further information: ​http://forums.virtualbox.org/viewtopic.php?f=1&t=16068

My testing has revealed that if the VMs are NOT started with VBoxHeadless, but, instead, started with the GUI, this behavior is not encountered. Note below:

kyle@anarix:~/vm$ ps x | grep virt
  431 ?        Ssl    0:01 /usr/lib/virtualbox/VirtualBox
  444 ?        S      0:00 /usr/lib/virtualbox/VBoxXPCOMIPCD
  451 ?        Sl     0:01 /usr/lib/virtualbox/VBoxSVC --automate
  460 ?        Sl     0:09 /usr/lib/virtualbox/VirtualBox -comment UBUNTU1 -startvm c13c4a38-4e1d-453a-b0d6-89545c95a83c
  479 ?        Sl     0:10 /usr/lib/virtualbox/VirtualBox -comment UBUNTU2 -startvm d4524a2a-1e00-4d33-9d54-9f5d1ab8d4f5
  496 ?        Sl     0:10 /usr/lib/virtualbox/VirtualBox -comment UBUNTU3 -startvm 07103247-31fb-42f0-bb2e-6fa919e88fc4
  513 ?        Sl     0:10 /usr/lib/virtualbox/VirtualBox -comment UBUNTU4 -startvm eec292b7-242f-4022-ad8c-bebc695d02a6
kyle@anarix:~/vm$ VBoxManage controlvm c13c4a38-4e1d-453a-b0d6-89545c95a83c savestate
VirtualBox Command Line Management Interface Version 2.1.4
(C) 2005-2009 Sun Microsystems, Inc.
All rights reserved.

0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
kyle@anarix:~/vm$ VBoxManage controlvm d4524a2a-1e00-4d33-9d54-9f5d1ab8d4f5 savestate
VirtualBox Command Line Management Interface Version 2.1.4
(C) 2005-2009 Sun Microsystems, Inc.
All rights reserved.

0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
kyle@anarix:~/vm$ VBoxManage controlvm 07103247-31fb-42f0-bb2e-6fa919e88fc4 savestate
VirtualBox Command Line Management Interface Version 2.1.4
(C) 2005-2009 Sun Microsystems, Inc.
All rights reserved.

0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
kyle@anarix:~/vm$ VBoxManage controlvm eec292b7-242f-4022-ad8c-bebc695d02a6 savestate
VirtualBox Command Line Management Interface Version 2.1.4
(C) 2005-2009 Sun Microsystems, Inc.
All rights reserved.

0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
kyle@anarix:~/vm$ ps x | grep virt
  431 ?        Ssl    0:02 /usr/lib/virtualbox/VirtualBox
  444 ?        S      0:00 /usr/lib/virtualbox/VBoxXPCOMIPCD
  451 ?        Sl     0:01 /usr/lib/virtualbox/VBoxSVC --automate

In the above scenario I started the VMs in sequential order. I was able to stop them in sequential order using controlvm.

The following scenario shows what happens when the VMs are running headless:

kyle@anarix:~/vm$ ./start-all.sh 
+ for x in 1 2 3 4
+ sleep 1
+ screen -S UBUNTU1 -d -m VBoxHeadless -s UBUNTU1 -p 10001
+ for x in 1 2 3 4
+ sleep 2
+ screen -S UBUNTU2 -d -m VBoxHeadless -s UBUNTU2 -p 10002
+ for x in 1 2 3 4
+ sleep 3
+ screen -S UBUNTU3 -d -m VBoxHeadless -s UBUNTU3 -p 10003
+ for x in 1 2 3 4
+ sleep 4
+ screen -S UBUNTU4 -d -m VBoxHeadless -s UBUNTU4 -p 10004
kyle@anarix:~/vm$ screen -ls
There are screens on:
	1840.UBUNTU4	(04/04/2009 09:18:08 PM)	(Detached)
	1809.UBUNTU3	(04/04/2009 09:18:04 PM)	(Detached)
	1778.UBUNTU2	(04/04/2009 09:18:01 PM)	(Detached)
	1731.UBUNTU1	(04/04/2009 09:17:59 PM)	(Detached)
4 Sockets in /var/run/screen/S-kyle.

kyle@anarix:~/vm$ ps x | grep virt
 1733 pts/2    Ssl+   0:10 /usr/lib/virtualbox/VBoxHeadless -s UBUNTU1 -p 10001
 1746 pts/2    S+     0:00 /usr/lib/virtualbox/VBoxXPCOMIPCD
 1753 ?        Sl     0:00 /usr/lib/virtualbox/VBoxSVC --automate
 1780 pts/3    Ssl+   0:10 /usr/lib/virtualbox/VBoxHeadless -s UBUNTU2 -p 10002
 1811 pts/4    Ssl+   0:10 /usr/lib/virtualbox/VBoxHeadless -s UBUNTU3 -p 10003
 1841 pts/5    Ssl+   0:10 /usr/lib/virtualbox/VBoxHeadless -s UBUNTU4 -p 10004
kyle@anarix:~/vm$ ./stop-all.sh 
+ for x in 1 2 3 4
+ sleep 1
+ VBoxManage controlvm UBUNTU1 savestate
VirtualBox Command Line Management Interface Version 2.1.4
(C) 2005-2009 Sun Microsystems, Inc.
All rights reserved.

0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
+ for x in 1 2 3 4
+ sleep 2
+ VBoxManage controlvm UBUNTU2 savestate
VirtualBox Command Line Management Interface Version 2.1.4
(C) 2005-2009 Sun Microsystems, Inc.
All rights reserved.

[!] FAILED calling a->virtualBox->OpenExistingSession (a->session, uuid) at line 2784!
[!] Primary RC  = VBOX_E_INVALID_SESSION_STATE (0x80BB000B) - Current session state prohibits operation
[!] Full error info present: true , basic error info present: true 
[!] Result Code = VBOX_E_INVALID_SESSION_STATE (0x80BB000B) - Current session state prohibits operation
[!] Text        = The machine 'UBUNTU2' does not have an open session
[!] Component   = Machine, Interface: IMachine, {ea6fb7ea-1993-4642-b113-f29eb39e0df0}
[!] Callee      = IVirtualBox, {339abca2-f47a-4302-87f5-7bc324e6bbde}
+ for x in 1 2 3 4
+ sleep 3
+ VBoxManage controlvm UBUNTU3 savestate
VirtualBox Command Line Management Interface Version 2.1.4
(C) 2005-2009 Sun Microsystems, Inc.
All rights reserved.

[!] FAILED calling a->virtualBox->OpenExistingSession (a->session, uuid) at line 2784!
[!] Primary RC  = VBOX_E_INVALID_SESSION_STATE (0x80BB000B) - Current session state prohibits operation
[!] Full error info present: true , basic error info present: true 
[!] Result Code = VBOX_E_INVALID_SESSION_STATE (0x80BB000B) - Current session state prohibits operation
[!] Text        = The machine 'UBUNTU3' does not have an open session
[!] Component   = Machine, Interface: IMachine, {ea6fb7ea-1993-4642-b113-f29eb39e0df0}
[!] Callee      = IVirtualBox, {339abca2-f47a-4302-87f5-7bc324e6bbde}
+ for x in 1 2 3 4
+ sleep 4
+ VBoxManage controlvm UBUNTU4 savestate
VirtualBox Command Line Management Interface Version 2.1.4
(C) 2005-2009 Sun Microsystems, Inc.
All rights reserved.

[!] FAILED calling a->virtualBox->OpenExistingSession (a->session, uuid) at line 2784!
[!] Primary RC  = VBOX_E_INVALID_SESSION_STATE (0x80BB000B) - Current session state prohibits operation
[!] Full error info present: true , basic error info present: true 
[!] Result Code = VBOX_E_INVALID_SESSION_STATE (0x80BB000B) - Current session state prohibits operation
[!] Text        = The machine 'UBUNTU4' does not have an open session
[!] Component   = Machine, Interface: IMachine, {ea6fb7ea-1993-4642-b113-f29eb39e0df0}
[!] Callee      = IVirtualBox, {339abca2-f47a-4302-87f5-7bc324e6bbde}
kyle@anarix:~/vm$ VBoxManage list vms | grep -E '^(Name|UUID|State)'
Name:            UBUNTU1
UUID:            c13c4a38-4e1d-453a-b0d6-89545c95a83c
State:           saved (since 2009-04-05T01:27:58.000000000)
Name:            UBUNTU2
UUID:            d4524a2a-1e00-4d33-9d54-9f5d1ab8d4f5
State:           aborted (since 2009-04-05T01:14:58.000000000)
Name:            UBUNTU3
UUID:            07103247-31fb-42f0-bb2e-6fa919e88fc4
State:           aborted (since 2009-04-05T01:14:59.000000000)
Name:            UBUNTU4
UUID:            eec292b7-242f-4022-ad8c-bebc695d02a6
State:           aborted (since 2009-04-05T01:14:59.000000000)
kyle@anarix:~/vm$ VBoxManage controlvm UBUNTU3 poweroff
VirtualBox Command Line Management Interface Version 2.1.4
(C) 2005-2009 Sun Microsystems, Inc.
All rights reserved.

[!] FAILED calling a->virtualBox->OpenExistingSession (a->session, uuid) at line 2784!
[!] Primary RC  = VBOX_E_INVALID_SESSION_STATE (0x80BB000B) - Current session state prohibits operation
[!] Full error info present: true , basic error info present: true 
[!] Result Code = VBOX_E_INVALID_SESSION_STATE (0x80BB000B) - Current session state prohibits operation
[!] Text        = The machine 'UBUNTU3' does not have an open session
[!] Component   = Machine, Interface: IMachine, {ea6fb7ea-1993-4642-b113-f29eb39e0df0}
[!] Callee      = IVirtualBox, {339abca2-f47a-4302-87f5-7bc324e6bbde}

During the "stop" script, I had four rdp sessions open to each of the VMs. Only the first session actually ended. The remaining three sessions were active and responsive. The last step illustrates how the controlvm fails to work after everything. Note that vbox reports the others as having 'aborted.'

Further testing showed that as long as the first VM started is the last one savestate'd the others would savestate successfully.

kyle@anarix:~/vm$ VBoxManage list vms | grep -E '^(Name|UUID|State)'
Name:            UBUNTU1
UUID:            c13c4a38-4e1d-453a-b0d6-89545c95a83c
State:           running (since 2009-04-05T02:07:27.089000000)
Name:            UBUNTU2
UUID:            d4524a2a-1e00-4d33-9d54-9f5d1ab8d4f5
State:           running (since 2009-04-05T02:07:29.035000000)
Name:            UBUNTU3
UUID:            07103247-31fb-42f0-bb2e-6fa919e88fc4
State:           running (since 2009-04-05T02:07:32.038000000)
Name:            UBUNTU4
UUID:            eec292b7-242f-4022-ad8c-bebc695d02a6
State:           running (since 2009-04-05T02:07:36.107000000)
kyle@anarix:~/vm$ ./stop-all.sh 
+ for x in 2 3 4 1
+ sleep 2
+ VBoxManage -nologo controlvm UBUNTU2 savestate
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
+ for x in 2 3 4 1
+ sleep 3
+ VBoxManage -nologo controlvm UBUNTU3 savestate
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
+ for x in 2 3 4 1
+ sleep 4
+ VBoxManage -nologo controlvm UBUNTU4 savestate
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
+ for x in 2 3 4 1
+ sleep 1
+ VBoxManage -nologo controlvm UBUNTU1 savestate
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%

Here's what happen when the first one started doesn't come last:

kyle@anarix:~/vm$ ./start-all.sh 
+ for x in 1 2 3 4
+ sleep 1
+ screen -S UBUNTU1 -d -m VBoxHeadless -s UBUNTU1 -p 10001
+ for x in 1 2 3 4
+ sleep 2
+ screen -S UBUNTU2 -d -m VBoxHeadless -s UBUNTU2 -p 10002
+ for x in 1 2 3 4
+ sleep 3
+ screen -S UBUNTU3 -d -m VBoxHeadless -s UBUNTU3 -p 10003
+ for x in 1 2 3 4
+ sleep 4
+ screen -S UBUNTU4 -d -m VBoxHeadless -s UBUNTU4 -p 10004
kyle@anarix:~/vm$ vim stop-all.sh 
kyle@anarix:~/vm$ ./stop-all.sh 
+ for x in 2 3 1 4
+ sleep 2
+ VBoxManage -nologo controlvm UBUNTU2 savestate
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
+ for x in 2 3 1 4
+ sleep 3
+ VBoxManage -nologo controlvm UBUNTU3 savestate
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
+ for x in 2 3 1 4
+ sleep 1
+ VBoxManage -nologo controlvm UBUNTU1 savestate
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%
+ for x in 2 3 1 4
+ sleep 4
+ VBoxManage -nologo controlvm UBUNTU4 savestate
[!] FAILED calling a->virtualBox->OpenExistingSession (a->session, uuid) at line 2784!
[!] Primary RC  = VBOX_E_INVALID_SESSION_STATE (0x80BB000B) - Current session state prohibits operation
[!] Full error info present: true , basic error info present: true 
[!] Result Code = VBOX_E_INVALID_SESSION_STATE (0x80BB000B) - Current session state prohibits operation
[!] Text        = The machine 'UBUNTU4' does not have an open session
[!] Component   = Machine, Interface: IMachine, {ea6fb7ea-1993-4642-b113-f29eb39e0df0}
[!] Callee      = IVirtualBox, {339abca2-f47a-4302-87f5-7bc324e6bbde}

[kihjin]

VBox logs for UBUNTU{1,2,3,4}

[Frank Mehnert]

I save some strange problem when starting VMs with VBoxHeadless and doing savestate with VBox 2.1.4. I didn't saw this with the current trunk. Could you check with VirtualBox 2.2.0 Beta 2?

[Frank Mehnert]

No response, closing.