Unable to start a VM after shutting one down on Solaris 11.1

Discussions related to using VirtualBox on Solaris hosts.
Post Reply
randshuntzinger
Posts: 23
Joined: 14. Aug 2008, 19:18

Unable to start a VM after shutting one down on Solaris 11.1

Post by randshuntzinger »

I am having a problem with starting guests running on top of Solaris 11.1 after a guest has been stopped. I first noticed the problem using the GUI so I tried from the command line to rule out a GUI-specific problem. It happens under the command line as well. Below is a transcript of what I did:

sol04i$ VBoxManage list runningvms
sol04i$ VBoxManage startvm school
Waiting for VM "school" to power on...
VM "school" has been successfully started.
sol04i$ VBoxManage startvm nevada
Waiting for VM "nevada" to power on...
VM "nevada" has been successfully started.
sol04i$ VBoxManage startvm reno
Waiting for VM "reno" to power on...
VM "reno" has been successfully started.
sol04i$ VBoxManage list vms
"reno" {0129672b-10ba-40bb-9169-e94c289e458e}
"school" {9a91e109-bf28-4af8-9caf-2bf2321c77a1}
"nevada" {46268219-d26c-490c-963a-a1f18db0f8b8}
"lasvegas" {f2a638b2-b25a-41a0-b789-8ae3461f271a}
"centos" {13514562-41df-4084-aaa3-b4d13dd134cb}
"indy" {5f9c8ca1-3ce0-4bf8-b3f1-9d5a15942901}
sol04i$ VBoxManage list runningvms
"reno" {0129672b-10ba-40bb-9169-e94c289e458e}
"school" {9a91e109-bf28-4af8-9caf-2bf2321c77a1}
"nevada" {46268219-d26c-490c-963a-a1f18db0f8b8}
[ At this point I shut down the reno VM from the GUI ]
sol04i$ VBoxManage list runningvms
"school" {9a91e109-bf28-4af8-9caf-2bf2321c77a1}
"nevada" {46268219-d26c-490c-963a-a1f18db0f8b8}
sol04i$ VBoxManage startvm indy
Waiting for VM "indy" to power on...
[ I did other things for a couple hours and it didn't start ]
^C
sol04i$ VBoxManage startvm indy
VBoxManage: error: The machine 'indy' is already locked by a session (or being locked or unlocked)
VBoxManage: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component Machine, interface IMachine, callee nsISupports
VBoxManage: error: Context: "LaunchVMProcess(a->session, sessionType.raw(), env.raw(), progress.asOutParam())" at line 592 of file VBoxManageMisc.cpp
sol04i$

The problem is that once I shut down a VM attempts to start a new VM hang indefinitely. If I ^C out of the hung VM it leaves a lock and that VM can't be started again. The only thing I've found which clears the problem is to reboot the server running VirtualBox. This is running VirtualBox 4.3.2 on a Solaris 11.1 server.

Hopefully this isn't a duplicate. I didn't see anything in a quick peek at the forum.

Has anyone else observed this? Is it something I've messed up somewhere or is this likely a bug? Finally, is there a way to clear the problem short of rebooting the server?
noteirak
Site Moderator
Posts: 5229
Joined: 13. Jan 2012, 11:14
Primary OS: Debian other
VBox Version: OSE Debian
Guest OSses: Debian, Win 2k8, Win 7
Contact:

Re: Unable to start a VM after shutting one down on Solaris

Post by noteirak »

How do you want the VMs to be started? as headless or with the GUI?
And we would need a VM log here (if there is one)
Hyperbox - Virtual Infrastructure Manager - https://apps.kamax.lu/hyperbox/
Manage your VirtualBox infrastructure the free way!
randshuntzinger
Posts: 23
Joined: 14. Aug 2008, 19:18

Re: Unable to start a VM after shutting one down on Solaris

Post by randshuntzinger »

Sorry it took so long to respond. I have another problem which is taking most of my time so I've not been able to move forward on this. With respect to your questions:

1. I am bringing it up with a GUI although I may go headless one of these days.
2. As far as I can tell, I don't have a VM log of the sessions which hang. Maybe the hang before the logging starts?

Here is what I get looking at the hung process:

-- pstack output --

6715: /opt/VirtualBox/amd64/VBoxManage startvm indy
----------------- lwp# 1 / thread# 1 --------------------
ffff80ffbf531e17 lwp_park (0, ffff80ffbfffe020, 0)
ffff80ffbf52b842 cond_wait_queue () + 62
ffff80ffbf52bc80 cond_wait_common () + 1dc
ffff80ffbf52bec5 __cond_timedwait () + 5d
ffff80ffbf52bf59 cond_timedwait () + 29
ffff80ffbf52bf8d pthread_cond_timedwait () + 9
ffff80ffb668394f pt_TimedWait () + b4
ffff80ffb6683b21 VBoxNsprPR_WaitCondVar () + 7f
ffff80ffb6683e19 VBoxNsprPR_Wait () + 46
ffff80ffb64a1984 _Z10WaitTargetRK4nsIDjPP10ipcMessagePFjPvP13ipcTargetDataPKS2_ES5_ () + 30e
ffff80ffb64a2f47 _Z15IPC_WaitMessagejRK4nsIDP19ipcIMessageObserverS3_j () + 9f
ffff80ffb64a86cf _ZN12DConnectStub10CallMethodEtPK15nsXPTMethodInfoP17nsXPTCMiniVariant () + 731
ffff80ffb6661d40 PrepareAndDispatch () + 230
ffff80ffb6661de3 SharedStub () + 5b
00000000004e86aa _Z13handleStartVMP10HandlerArg () + 95a
0000000000430b4e main () + 105e
000000000042f33c _start () + 6c
----------------- lwp# 2 / thread# 2 --------------------
ffff80ffbf53ac4a pollsys (ffff80ffbf06ecc0, 2, 0, 0)
ffff80ffbf4dcb37 poll () + 5f
ffff80ffb66825ce _pr_poll_with_poll () + 3b4
ffff80ffb6682759 VBoxNsprPR_Poll () + 9
ffff80ffb64afc81 _Z10ConnThreadPv () + 41
ffff80ffb668445a _pt_root () + 90
ffff80ffb668451f _pt_iprt_root () + c
ffff80ffbe695b0c rtThreadMain () + 2c
ffff80ffbe6f9fb1 _Z18rtThreadNativeMainPv () + 51
ffff80ffbf531b2d _thrp_setup () + a5
ffff80ffbf531dd0 _lwp_start ()
----------------- lwp# 3 / thread# 3 --------------------
ffff80ffbf531e17 lwp_park (0, 0, 0)
ffff80ffbf52b842 cond_wait_queue () + 62
ffff80ffbf52bde0 __cond_wait () + 78
ffff80ffbf52be25 cond_wait () + 1d
ffff80ffbf52be51 pthread_cond_wait () + 9
ffff80ffb6683b0d VBoxNsprPR_WaitCondVar () + 6b
ffff80ffb6683e19 VBoxNsprPR_Wait () + 46
ffff80ffb64a901a _ZN14DConnectWorker3RunEv () + 126
ffff80ffb66534be _ZN8nsThread4MainEPv () + 2e
ffff80ffb668445a _pt_root () + 90
ffff80ffb668451f _pt_iprt_root () + c
ffff80ffbe695b0c rtThreadMain () + 2c
ffff80ffbe6f9fb1 _Z18rtThreadNativeMainPv () + 51
ffff80ffbf531b2d _thrp_setup () + a5
ffff80ffbf531dd0 _lwp_start ()


-- pfiles output --

6715: /opt/VirtualBox/amd64/VBoxManage startvm indy
Current rlimit: 256 file descriptors
0: S_IFCHR mode:0620 dev:551,0 ino:83980419 uid:562 gid:7 rdev:133,2
O_RDWR|O_NOCTTY|O_LARGEFILE
/dev/pts/2
offset:260744
1: S_IFCHR mode:0620 dev:551,0 ino:83980419 uid:562 gid:7 rdev:133,2
O_RDWR|O_NOCTTY|O_LARGEFILE
/dev/pts/2
offset:260744
2: S_IFCHR mode:0620 dev:551,0 ino:83980419 uid:562 gid:7 rdev:133,2
O_RDWR|O_NOCTTY|O_LARGEFILE
/dev/pts/2
offset:260744
3: S_IFIFO mode:0000 dev:548,0 ino:104328 uid:562 gid:14 size:1
O_RDWR|O_NONBLOCK FD_CLOEXEC
4: S_IFIFO mode:0000 dev:548,0 ino:104328 uid:562 gid:14 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
5: S_IFSOCK mode:0666 dev:561,0 ino:23702 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
SOCK_STREAM
SO_SNDBUF(16384),SO_RCVBUF(5120)
sockname: AF_UNIX
peername: AF_UNIX /tmp/.vbox-randy-ipc/ipcd
peer: VBoxXPCOMIPCD[4985] zone: global[0]
6: S_IFDOOR mode:0444 dev:559,0 ino:45 uid:0 gid:0 size:0
O_RDONLY|O_LARGEFILE FD_CLOEXEC door to nscd[758]
/system/volatile/name_service_door
7: S_IFIFO mode:0000 dev:548,0 ino:104329 uid:562 gid:14 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
8: S_IFIFO mode:0000 dev:548,0 ino:104329 uid:562 gid:14 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC

Here is a tail for VBoxSVC.log which shows errors. I suspect that the VM's are shutting down completely and I suppose this may be interfering the startup of new ones. Unfortunately, I don't know enough about VirtualBox to consider this an informed guess - just a guess.

== tail OUTPUT FROM VBoxSVC.log ==
00:00:00.424082 nspr-2 Loading settings file "/home/randy/VirtualBox VMs/Solaris Variants/indy/indy.vbox" with version "1.13-solaris"
00:07:34.595989 main ERROR [COM]: aRC=VBOX_E_OBJECT_IN_USE (0x80bb000c) aIID={05f2bbb6-a3a6-4fb9-9b49-6d0dda7142ac} aComponent={Medium} aText={Medium '/home/randy/VirtualBox VMs/Solaris Hosts/Solaris 11 Hosts/reno/reno.vdi' cannot be closed because it is still attached to 1 virtual machines}, preserve=false
00:07:34.596264 main ERROR [COM]: aRC=VBOX_E_OBJECT_IN_USE (0x80bb000c) aIID={05f2bbb6-a3a6-4fb9-9b49-6d0dda7142ac} aComponent={Medium} aText={Medium '/home/randy/VirtualBox VMs/Solaris Hosts/Solaris 10 Hosts/school/school-disk1.vmdk' cannot be closed because it is still attached to 1 virtual machines}, preserve=false
00:07:34.596474 main ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={480cf695-2d8d-4256-9c7c-cce4184fa048} aComponent={Machine} aText={The object is not ready}, preserve=false
00:07:34.596500 main ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={480cf695-2d8d-4256-9c7c-cce4184fa048} aComponent={Machine} aText={The object is not ready}, preserve=false
00:07:34.596530 main ERROR [COM]: aRC=VBOX_E_OBJECT_IN_USE (0x80bb000c) aIID={05f2bbb6-a3a6-4fb9-9b49-6d0dda7142ac} aComponent={Medium} aText={Medium '/home/randy/VirtualBox VMs/Solaris Hosts/Solaris 11 Hosts/nevada/nevada.vdi' cannot be closed because it is still attached to 1 virtual machines}, preserve=false
00:07:34.596686 main ERROR [COM]: aRC=VBOX_E_OBJECT_IN_USE (0x80bb000c) aIID={05f2bbb6-a3a6-4fb9-9b49-6d0dda7142ac} aComponent={Medium} aText={Medium '/home/randy/VirtualBox VMs/Solaris Hosts/Solaris 11 Hosts/lasvegas/lasvegas.vdi' cannot be closed because it is still attached to 1 virtual machines}, preserve=false
00:07:34.596834 main ERROR [COM]: aRC=VBOX_E_OBJECT_IN_USE (0x80bb000c) aIID={05f2bbb6-a3a6-4fb9-9b49-6d0dda7142ac} aComponent={Medium} aText={Medium '/home/randy/VirtualBox VMs/Linux Hosts/centos/centos.vdi' cannot be closed because it is still attached to 1 virtual machines}, preserve=false
00:07:34.596979 main ERROR [COM]: aRC=VBOX_E_OBJECT_IN_USE (0x80bb000c) aIID={05f2bbb6-a3a6-4fb9-9b49-6d0dda7142ac} aComponent={Medium} aText={Medium '/home/randy/VirtualBox VMs/Solaris Variants/indy/indy.vdi' cannot be closed because it is still attached to 1 virtual machines}, preserve=false
00:07:34.600380 Watcher ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={fafa4e17-1ee2-4905-a10e-fe7c18bf5554} aComponent={VirtualBox} aText={The object is not ready}, preserve=false


Is this information helpful?
mpack
Site Moderator
Posts: 39156
Joined: 4. Sep 2008, 17:09
Primary OS: MS Windows 10
VBox Version: PUEL
Guest OSses: Mostly XP

Re: Unable to start a VM after shutting one down on Solaris

Post by mpack »

I'm afraid that none of those is the VM log. For what we need please read Minimum information needed for assistance, and note that an zipped attachment is preferred, not pasted text.
randshuntzinger
Posts: 23
Joined: 14. Aug 2008, 19:18

Re: Unable to start a VM after shutting one down on Solaris

Post by randshuntzinger »

mpack wrote:I'm afraid that none of those is the VM log. For what we need please read Minimum information needed for assistance, and note that an zipped attachment is preferred, not pasted text.
Did you notice I stated that when a session hung no VM log appears to have been generated? This is the reason I provided the other information instead. I do have VM logs for sessions which did not fail. I can attach one if you think it would be helpful.
mpack
Site Moderator
Posts: 39156
Joined: 4. Sep 2008, 17:09
Primary OS: MS Windows 10
VBox Version: PUEL
Guest OSses: Mostly XP

Re: Unable to start a VM after shutting one down on Solaris

Post by mpack »

? What about all the previous sessions? There will be 4 logs in the Logs subfolder, the most recent of which will tell us if the VM actually shut down properly.
randshuntzinger
Posts: 23
Joined: 14. Aug 2008, 19:18

Re: Unable to start a VM after shutting one down on Solaris

Post by randshuntzinger »

OK - I'm attaching a zip of the log for the last reno run, which is the VM which was shut down before I started indy. Hopefully it will be of some use.
Attachments
reno-vbox-log.zip
VBox.log of the last reno uptime.
(21.55 KiB) Downloaded 35 times
noteirak
Site Moderator
Posts: 5229
Joined: 13. Jan 2012, 11:14
Primary OS: Debian other
VBox Version: OSE Debian
Guest OSses: Debian, Win 2k8, Win 7
Contact:

Re: Unable to start a VM after shutting one down on Solaris

Post by noteirak »

4.3.4 is out and contains quite a few fix. Might be worth trying it out?
Hyperbox - Virtual Infrastructure Manager - https://apps.kamax.lu/hyperbox/
Manage your VirtualBox infrastructure the free way!
mpack
Site Moderator
Posts: 39156
Joined: 4. Sep 2008, 17:09
Primary OS: MS Windows 10
VBox Version: PUEL
Guest OSses: Mostly XP

Re: Unable to start a VM after shutting one down on Solaris

Post by mpack »

Hmm. Did you update the GAs right before the shutdown? Otherwise I don't know why the GAs are being reinitialized 17 hours into the session. Anyway, things seem to be going swimingly until right after that...
VBox.log wrote: 17:36:26.795270 Guest Additions capability report: (0x5 -> 0x5) seamless: yes, hostWindowMapping: no, graphics: yes
17:36:26.795328 VBVA_INFO_SCREEN: [0] @0,0 1918x1127, line 0x1df8, BPP 32, flags 0x1
17:36:26.950778 Starting host clipboard service
17:36:26.950840 Initializing X11 clipboard backend
17:36:26.959299 Shared clipboard: failed to connect to the X11 clipboard - the window system may not be running.
17:36:26.959329 Shared clipboard: failed to setup the termination mechanism.
17:36:26.959381 Shared clipboard: initialisation failed: VERR_NOT_SUPPORTED
17:36:26.959455 Failed to initialise the shared clipboard
17:37:29.135012 Guest Additions capability report: (0x5 -> 0x4) seamless: no, hostWindowMapping: no, graphics: yes
17:37:29.170998 Guest Additions capability report: (0x4 -> 0x4) seamless: no, hostWindowMapping: no, graphics: yes
17:37:29.171112 VBVA_INFO_SCREEN: [0] @0,0 1918x1127, line 0x1df8, BPP 32, flags 0x1
17:37:29.171279 Guest Additions capability report: (0x4 -> 0x0) seamless: no, hostWindowMapping: no, graphics: no
17:37:29.187247 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=ffff80ffae600000 w=1024 h=768 bpp=32 cbLine=0x1000, flags=0x1
17:42:54.104168 OHCI: USB Reset
17:42:54.104243 OHCI: Software reset
17:42:54.113731 EHCI: USB Suspended
17:42:54.123820 EHCI: Hardware reset
17:42:54.424346 EHCI: Hardware reset
17:42:54.425945 Entering S5 power state (power down)
17:42:54.435062 Changing the VM state from 'RUNNING' to 'POWERING_OFF'.
17:42:54.435192 ****************** Guest state at power off ******************
Note the direct transition from running to power off. That's a pretty drastic way to end a long session. It's liable to cause disk corruption if you do that on physical PCs, though I'm not familiar with what protections Solaris might have in that regard.
randshuntzinger
Posts: 23
Joined: 14. Aug 2008, 19:18

Re: Unable to start a VM after shutting one down on Solaris

Post by randshuntzinger »

Sorry it has been so long since I last looked at this, I had other issues distracting me followed by a couple weeks of vacation. Thank you for your comments. I now think I know what was going on and hopefully have the problem resolved.

First, I'll respond to the forcible power off. It isn't uncommon for my Solaris clients to hang on shutdown. When that happens, I do the forcible power off. Obviously, I'd prefer for the system to come down properly.

Now, the problem resolution. When I upgraded to VirtualBox 4.3.6 things changed. Instead of hanging when the VM was started, I started getting an error message immediately. After looking around a bit, I realized there was a problem getting a connection to the X11 server on the Mac where I display the GUI. It appears the issue was an interaction between VirtualBox, the ssh connection between my Mac and the VirtualBox server and the Mac X11 service. Basically, when an X connection was dropped, future attempts to open a new one failed. I found a tweak on the Mac which I hope will resolve the problem.

The fact that nobody else saw this problem was a clue that it might be some kind of interaction like this. I want to thank you for your help.
Post Reply