VirtualBox GUI Intermittently Hangs at Startup of Virtual Machine => Fixed in SVN

[Arend Dittmer]

I am creating, configuring and running a virtual machine named mypocket7 from a script through VBoxManage. After the Virtual Machine is created with createvm the script attaches two immutable virtual hard drives in vmdk format to the created vm. The virtual hard drives are stored on a USB flash drive formatted with FAT32. The script also attaches a page volume vmdk from local disk and a DVD

VBoxManage storageattach MyPocket7 --storagectl "IDE Controller" --port 0 --device 0 --type hdd --mtype immutable --medium "/Volumes/MYPOCKET7/vm-images/usbcomp_7.vmdk"
VBoxManage storageattach MyPocket7 --storagectl "IDE Controller" --port 0 --device 1 --type hdd --mtype immutable --medium "/Volumes/MYPOCKET7/vm-images/usbcomp_user.vmdk"
VBoxManage storageattach MyPocket7 --storagectl "IDE Controller" --port 1 --device 0 --type hdd --medium "/tmp/vmusbcomp2736/pagefile_vol_vmware.vmdk"
VBoxManage storageattach MyPocket7 --storagectl "IDE Controller" --port 1 --device 1 --type dvddrive --medium host:'host:MATSHITA DVD-R   UJ-898' --passthrough on

The script then launches the vm. I have tried

VirtualBox" --startvm MyPocket7

and

VBoxManage" startvm MyPocket7

with the same result: The VirtualBox GUI 'hangs' intermittently at startup before a log file is created. While the 'hang' occurs intermittently, when it occurs OSX always reports the same stack trace for the VirtualBox/VBoxManage process. I have observed the hang with Snow Leopard as well as Lion and on both of the Macs I own (a Mac Mini and a Macbook).

The main VirtualBox/VBoxManage thread hangs at

                      17 Console::powerUp(IProgress**, bool) + 6109 (in VBoxC.dylib) [0x1052c6f1d]
                        17 SharedStub + 91 (in VBoxXPCOM.dylib) [0x1028c759b]
                          17 PrepareAndDispatch + 507 (in VBoxXPCOM.dylib) [0x1028c8368]
                            17 DConnectStub::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) + 1471 (in VBoxXPCOMIPCC.dylib) [0x102cbeefb]
                              17 IPC_WaitMessage(unsigned int, nsID const&, ipcIMessageObserver*, ipcIMessageObserver*, unsigned int) + 242 (in VBoxXPCOMIPCC.dylib) [0x102cb5cea]
                                17 _ZL10WaitTargetRK4nsIDjPP10ipcMessagePFjPvP13ipcTargetDataPKS2_ES5_ + 632 (in VBoxXPCOMIPCC.dylib) [0x102cb597c]

Within the same process a second thread that was spawned by the main thread and enumerates media waits as well

          17 VBoxGlobal::startEnumeratingMedia()::MediaEnumThread::run() + 444 (in VirtualBox.dylib) [0x10106f41c]
            17 VBoxMedium::blockAndQueryState() + 101 (in VirtualBox.dylib) [0x10102c405]
              17 CMedium::RefreshState() + 61 (in VirtualBox.dylib) [0x10122077d]
                17 SharedStub + 91 (in VBoxXPCOM.dylib) [0x1028c759b]
                  17 PrepareAndDispatch + 507 (in VBoxXPCOM.dylib) [0x1028c8368]
                    17 DConnectStub::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) + 1471 (in VBoxXPCOMIPCC.dylib) [0x102cbeefb]
                      17 IPC_WaitMessage(unsigned int, nsID const&, ipcIMessageObserver*, ipcIMessageObserver*, unsigned int) + 242 (in VBoxXPCOMIPCC.dylib) [0x102cb5cea]
                        17 _ZL10WaitTargetRK4nsIDjPP10ipcMessagePFjPvP13ipcTargetDataPKS2_ES5_ + 632 (in VBoxXPCOMIPCC.dylib) [0x102cb597c]

The complete stack trace generated after the OSX 'force quit' is attached.

I did a little homework looking at the relevant code sections and believe that there may be a race condition between two threads in the VirtualBox/VBoxManage process. There is one thread that enumerates the media list in startEnumerating media and there is a second thread that looks for immutable images to reset, which can probably not complete as the enumeration thread is still working. I wonder if this issue is only a problem when storing immutable drives on a USB flash drive resulting in a 'slower' device enumeration that conflicts with the powerUp call during which VirtualBox/VBoxManage looks for immutable images to reset.

        if (!fCurrentSnapshotIsOnline)
        {
            LogFlowThisFunc(("Looking for immutable images to reset\n"));

            com::SafeIfaceArray<IMediumAttachment> atts;
            rc = mMachine->COMGETTER(MediumAttachments)(ComSafeArrayAsOutParam(atts));
... 

[Arend Dittmer]

Stack Trace VirtualBox

[Christian Pötzsch]

Can you attach the content of "Sample Process" in the Activity Manager of the process VBoxSVC when this hangs happens?

The pagefile vmdk is just a normal vmdk, right?

[Arend Dittmer]

Replying to poetzsch:

Can you attach the content of "Sample Process" in the Activity Manager of the process VBoxSVC when this hangs happens?

The pagefile vmdk is just a normal vmdk, right?

Thank you very for looking into this right away. Yes, the pagefile is a regular vmdk that is dynamically growing and split into multiple extents. I am attaching the descriptor for your reference.

I will try to reproduce again. You are referring to the 'Activity Monitor', right?

[Christian Pötzsch]

Yes the "Activity Monitor", sorry.

Can you also give a little bit more info on the other disks. How big they are, virtually and in reality. Are they also splitted? Maybe you could also check what happens when the disks are not immutable.

I tried with an external usb disk as well, but couldn't reproduce it so far.

[Arend Dittmer]

Replying to poetzsch:

Yes the "Activity Monitor", sorry.

Can you also give a little bit more info on the other disks. How big they are, virtually and in reality. Are they also splitted? Maybe you could also check what happens when the disks are not immutable.

I tried with an external usb disk as well, but couldn't reproduce it so far.

I just reproduced again. Just as a side note ... I have seen the issue when staring with VBoxManage as well as with VirtualBox but it seems to me that the probability of the error occurring is much higher when starting with 'VBoxManage startvm'. I am attaching the sample of VBoxSvc.

The other drives are also vmdks, that are split and preallocated. usbcomp_7 is 24GB and usbcomp_user is 5GB. I am also attaching their descriptors. The ls output of the directory where the images are located below:

-rwxrwxrwx  1 adittmer  staff  2147221504 Aug 28 17:50 usbcomp_7-f001.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Aug 28 17:51 usbcomp_7-f002.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Aug 28 17:51 usbcomp_7-f003.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:36 usbcomp_7-f004.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:38 usbcomp_7-f005.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:41 usbcomp_7-f006.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Aug 28 17:51 usbcomp_7-f007.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:46 usbcomp_7-f008.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:48 usbcomp_7-f009.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:50 usbcomp_7-f010.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:53 usbcomp_7-f011.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:55 usbcomp_7-f012.vmdk
-rwxrwxrwx  1 adittmer  staff     3145728 Jul  5 23:55 usbcomp_7-f013.vmdk
-rwxrwxrwx  1 adittmer  staff        1279 Jul  6 19:21 usbcomp_7.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Aug 28 17:50 usbcomp_user-f001.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  6 00:01 usbcomp_user-f002.vmdk
-rwxrwxrwx  1 adittmer  staff  1074266112 Aug 28 17:50 usbcomp_user-f003.vmdk
-rwxrwxrwx  1 adittmer  staff         890 Jul  6 19:22 usbcomp_user.vmdk

[Arend Dittmer]

This is the complete create and launch script.

[Arend Dittmer]

Logfile of create and launch script.

[Christian Pötzsch]

Thanks for the info. When I look at the bt your assumption seems to be right. Anyway, I have to reproduce this which will need some time.

[Arend Dittmer]

Replying to poetzsch:

Thanks for the info. When I look at the bt your assumption seems to be right. Anyway, I have to reproduce this which will need some time.

Thank you very much. I really appreciate you looking into this. You probably already saw this indication of an unreleased lock in the sample.

    +                     2674 Medium::RefreshState(unsigned int*)  (in VBoxSVC) + 332  [0x1000e56fc]
    +                       2674 Medium::queryInfo(bool, bool)  (in VBoxSVC) + 1290  [0x1000e3b6a]
    +                         2674 util::AutoLockBase::acquire()  (in VBoxSVC) + 17  [0x1001d5471]
    +                           2674 util::AutoLockBase::callLockOnAllHandles()  (in VBoxSVC) + 50  [0x1001d52f2]
    +                             2674 RTSemRWRequestRead  (in VBoxRT.dylib) + 355  [0x1003f1463]
    +                               2674 _ZL34rtSemEventMultiPosixWaitIndefiniteP23RTSEMEVENTMULTIINTERNALjPK15RTLOCKVALSRCPOS  (in VBoxRT.dylib) + 101  [0x1003833e5]

If it helps with reproducing the issue I am more than happy to send you a USB drive. Just let me know.

[Arend Dittmer]

Replying to poetzsch:

Thanks for the info. When I look at the bt your assumption seems to be right. Anyway, I have to reproduce this which will need some time.

To your earlier question ... as the issue is intermittent it is of course hard to say for sure .... but it looks like this is not an issue with drives attached as normal drives ('non-immutable')

[Arend Dittmer]

Replying to poetzsch:

Thanks for the info. When I look at the bt your assumption seems to be right. Anyway, I have to reproduce this which will need some time.

Looked a little bit further into this. I found that not having the 'capture hint' that needs to be OK'ed pop up makes it much more likely that the error condition will occur. So the highest probability for the hang to occur is when starting the VM with 'VBoxManage startvm' and suppressing the initial capture window with "$VMM_PATH/VBoxManage" setextradata global GUI/SuppressMessages ,confirmInputCapture,remindAboutAutoCapture". With these changes and my current setup I can reproduce the issue with almost all startup attempts.

I added a few lines of code to the constructor of UIMachine in VirtualBox-4.0.12_OSE/src/VBox/Frontends/VirtualBox/src/runtime/UIMachine.cpp that synchronize the media enumeration thread. I have not been able to reproduce the issue after incorporating these changes. When swapping out the binaries with the originals the issue appears again.

--- 392,399 ----
bash-3.2$ diff --context=4 /Users/adittmer/VBOX_4.X/fix/VirtualBox-4.0.12_OSE/src/VBox/Frontends/VirtualBox/src/runtime/UIMachine.cpp /Users/adittmer/VBOX_4.X/VirtualBox-4.0.12_OSE/src/VBox/Frontends/VirtualBox/src/runtime/UIMachine.cpp
*** /Users/adittmer/VBOX_4.X/fix/VirtualBox-4.0.12_OSE/src/VBox/Frontends/VirtualBox/src/runtime/UIMachine.cpp  2011-07-15 08:33:53.000000000 -0700
--- /Users/adittmer/VBOX_4.X/VirtualBox-4.0.12_OSE/src/VBox/Frontends/VirtualBox/src/runtime/UIMachine.cpp      2011-09-04 16:05:02.000000000 -0700
***************
*** 392,399 ****
--- 392,404 ----
  
      /* Cache IMedium data: */
      vboxGlobal().startEnumeratingMedia();
  
+     /* Make sure asynchronous enum thread has finished before proceeding */
+     QEventLoop wait_for_enum_complete;
+     connect (&vboxGlobal(), SIGNAL (mediumEnumFinished (const VBoxMediaList &)), &wait_for_enum_complete, SLOT(quit()));
+     wait_for_enum_complete.exec();
+ 
      /* Storing self: */
      if (m_ppThis)
          *m_ppThis = this;

[Christian Pötzsch]

I think I fixed it. Can you give ​this test build a try?

[Arend Dittmer]

Thank you very much. My initial tests indicate that you fixed the problem.

[Arend Dittmer]

Will this fix be in 4.1.4?

[Frank Mehnert]

Yes, 4.1.4 will include this fix.

[Frank Mehnert]

And 4.1.4 was finally released today.