Bug 757138

Summary: "An error occurred, but the cause is unknown" when trying to start a Virtualbox domain
Product: [Community] Virtualization Tools Reporter: jc <jc.guillain>
Component: libvirtAssignee: Libvirt Maintainers <libvirt-maint>
Status: CLOSED DEFERRED QA Contact:
Severity: high Docs Contact:
Priority: unspecified    
Version: unspecifiedCC: crobinso, jc.guillain, xen-maint
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-03-23 14:39:02 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description jc 2011-11-25 14:57:27 UTC
Description of problem:
When trying to start a virtualbox domain with virsh, an unknown error occurs.
(when the domain is started using Virtualbox GUI it works, and I have no problem to stop it with virsh...)


Version-Release number of selected component (if applicable):
libvirt 0.9.2-7
virtualbox 4.0.10

How reproducible:
Every time

Steps to Reproduce:
1. Create à virtualbox domain with virtualbox.
2. Try to start it with virsh
3.
  
Actual results:

virsh # start freenas1
error: Failed to start domain freenas1
error: An error occurred, but the cause is unknown

Expected results:
Domain started, or a more descriptive error message.

Additional info:

XML config file of the domain :

<domain type='vbox' id='1'>
  <name>freenas1</name>
  <uuid>07aadf11-2090-4690-9518-52766722c544</uuid>
  <memory>524288</memory>
  <currentMemory>524288</currentMemory>
  <vcpu>1</vcpu>
  <os>
    <type arch='x86_64'>hvm</type>
    <boot dev='hd'/>
  </os>
  <features>
    <acpi/>
    <apic/>
  </features>
  <clock offset='localtime'/>
  <on_poweroff>destroy</on_poweroff>
  <on_reboot>destroy</on_reboot>
  <on_crash>destroy</on_crash>
  <devices>
    <disk type='file' device='disk'>
      <source file='/data/Freenas1Disk1.vdi'/>
      <target dev='hda' bus='ide'/>
    </disk>
    <input type='mouse' bus='ps2'/>
    <graphics type='desktop' display='localhost:10.0'/>
    <video>
      <model type='vbox' vram='8192' heads='1'>
        <acceleration accel3d='no' accel2d='no'/>
      </model>
    </video>
  </devices>
</domain>

virsh debug output :

virsh # start freenas1
15:51:31.043: 5796: debug : virConnectOpenAuth:1328 : name=(null), auth=0x7f19ee32d320, flags=0
15:51:31.043: 5796: debug : do_open:1065 : no name, allowing driver auto-select
15:51:31.043: 5796: debug : do_open:1102 : trying driver 0 (Test) ...
15:51:31.043: 5796: debug : do_open:1108 : driver 0 Test returned DECLINED
15:51:31.043: 5796: debug : do_open:1102 : trying driver 1 (Xen) ...
15:51:31.043: 5796: debug : do_open:1108 : driver 1 Xen returned DECLINED
15:51:31.043: 5796: debug : do_open:1102 : trying driver 2 (OPENVZ) ...
15:51:31.043: 5796: debug : do_open:1108 : driver 2 OPENVZ returned DECLINED
15:51:31.043: 5796: debug : do_open:1102 : trying driver 3 (VMWARE) ...
15:51:31.043: 5796: debug : do_open:1108 : driver 3 VMWARE returned DECLINED
15:51:31.043: 5796: debug : do_open:1102 : trying driver 4 (VBOX) ...
15:51:31.050: 5796: debug : vboxOpen:1035 : in vboxOpen
15:51:31.050: 5796: debug : do_open:1108 : driver 4 VBOX returned SUCCESS
15:51:31.050: 5796: debug : do_open:1130 : network driver 0 Test returned DECLINED
15:51:31.050: 5796: debug : vboxNetworkOpen:6953 : network initialized
15:51:31.050: 5796: debug : do_open:1130 : network driver 1 VBOX returned SUCCESS
15:51:31.050: 5796: debug : do_open:1145 : interface driver 0 Test returned DECLINED
15:51:31.051: 5796: debug : doRemoteOpen:596 : proceeding with name = vbox:///system
15:51:31.051: 5796: debug : remoteIO:5824 : Do proc=66 serial=0 length=28 wait=(nil)
15:51:31.051: 5796: debug : remoteIO:5896 : We have the buck 66 0x7f19e6c37010 0x7f19e6c37010
15:51:31.051: 5796: debug : remoteIODecodeMessageLength:5214 : Got length, now need 64 total (60 more)
15:51:31.051: 5796: debug : remoteIOEventLoop:5750 : Giving up the buck 66 0x7f19e6c37010 (nil)
15:51:31.051: 5796: debug : remoteIO:5924 : All done with our call 66 (nil) 0x7f19e6c37010
15:51:31.051: 5796: debug : remoteIO:5824 : Do proc=1 serial=1 length=56 wait=(nil)
15:51:31.051: 5796: debug : remoteIO:5896 : We have the buck 1 0x7f19e003fec0 0x7f19e003fec0
15:51:31.052: 5796: debug : remoteIODecodeMessageLength:5214 : Got length, now need 176 total (172 more)
15:51:31.052: 5796: debug : remoteIOEventLoop:5750 : Giving up the buck 1 0x7f19e003fec0 (nil)
15:51:31.052: 5796: debug : remoteIO:5924 : All done with our call 1 (nil) 0x7f19e003fec0
15:51:31.052: 5796: debug : do_open:1145 : interface driver 1 remote returned ERROR
15:51:31.052: 5796: debug : do_open:1161 : storage driver 0 Test returned DECLINED
15:51:31.052: 5796: debug : vboxStorageOpen:7764 : vbox storage initialized
15:51:31.052: 5796: debug : do_open:1161 : storage driver 1 VBOX returned SUCCESS
15:51:31.052: 5796: debug : do_open:1177 : node driver 0 Test returned DECLINED
15:51:31.053: 5796: debug : doRemoteOpen:596 : proceeding with name = vbox:///system
15:51:31.053: 5796: debug : remoteIO:5824 : Do proc=66 serial=0 length=28 wait=(nil)
15:51:31.053: 5796: debug : remoteIO:5896 : We have the buck 66 0x7f19e0081f90 0x7f19e0081f90
15:51:31.054: 5796: debug : remoteIODecodeMessageLength:5214 : Got length, now need 64 total (60 more)
15:51:31.054: 5796: debug : remoteIOEventLoop:5750 : Giving up the buck 66 0x7f19e0081f90 (nil)
15:51:31.054: 5796: debug : remoteIO:5924 : All done with our call 66 (nil) 0x7f19e0081f90
15:51:31.054: 5796: debug : remoteIO:5824 : Do proc=1 serial=1 length=56 wait=(nil)
15:51:31.054: 5796: debug : remoteIO:5896 : We have the buck 1 0x7f19e0081f90 0x7f19e0081f90
15:51:31.055: 5796: debug : remoteIODecodeMessageLength:5214 : Got length, now need 176 total (172 more)
15:51:31.055: 5796: debug : remoteIOEventLoop:5750 : Giving up the buck 1 0x7f19e0081f90 (nil)
15:51:31.055: 5796: debug : remoteIO:5924 : All done with our call 1 (nil) 0x7f19e0081f90
15:51:31.055: 5796: debug : do_open:1177 : node driver 1 remote returned ERROR
15:51:31.055: 5796: debug : do_open:1193 : secret driver 0 Test returned DECLINED
15:51:31.055: 5796: debug : doRemoteOpen:596 : proceeding with name = vbox:///system
15:51:31.055: 5796: debug : remoteIO:5824 : Do proc=66 serial=0 length=28 wait=(nil)
15:51:31.055: 5796: debug : remoteIO:5896 : We have the buck 66 0x7f19e0081f90 0x7f19e0081f90
15:51:31.056: 5796: debug : remoteIODecodeMessageLength:5214 : Got length, now need 64 total (60 more)
15:51:31.056: 5796: debug : remoteIOEventLoop:5750 : Giving up the buck 66 0x7f19e0081f90 (nil)
15:51:31.056: 5796: debug : remoteIO:5924 : All done with our call 66 (nil) 0x7f19e0081f90
15:51:31.056: 5796: debug : remoteIO:5824 : Do proc=1 serial=1 length=56 wait=(nil)
15:51:31.056: 5796: debug : remoteIO:5896 : We have the buck 1 0x7f19e0081f90 0x7f19e0081f90
15:51:31.057: 5796: debug : remoteIODecodeMessageLength:5214 : Got length, now need 176 total (172 more)
15:51:31.057: 5796: debug : remoteIOEventLoop:5750 : Giving up the buck 1 0x7f19e0081f90 (nil)
15:51:31.057: 5796: debug : remoteIO:5924 : All done with our call 1 (nil) 0x7f19e0081f90
15:51:31.057: 5796: debug : do_open:1193 : secret driver 1 remote returned ERROR
15:51:31.057: 5796: debug : do_open:1209 : nwfilter driver 0 Test returned DECLINED
15:51:31.057: 5796: debug : doRemoteOpen:596 : proceeding with name = vbox:///system
15:51:31.057: 5796: debug : remoteIO:5824 : Do proc=66 serial=0 length=28 wait=(nil)
15:51:31.057: 5796: debug : remoteIO:5896 : We have the buck 66 0x7f19e0081f90 0x7f19e0081f90
15:51:31.058: 5796: debug : remoteIODecodeMessageLength:5214 : Got length, now need 64 total (60 more)
15:51:31.058: 5796: debug : remoteIOEventLoop:5750 : Giving up the buck 66 0x7f19e0081f90 (nil)
15:51:31.058: 5796: debug : remoteIO:5924 : All done with our call 66 (nil) 0x7f19e0081f90
15:51:31.058: 5796: debug : remoteIO:5824 : Do proc=1 serial=1 length=56 wait=(nil)
15:51:31.058: 5796: debug : remoteIO:5896 : We have the buck 1 0x7f19e0081f90 0x7f19e0081f90
15:51:31.059: 5796: debug : remoteIODecodeMessageLength:5214 : Got length, now need 176 total (172 more)
15:51:31.059: 5796: debug : remoteIOEventLoop:5750 : Giving up the buck 1 0x7f19e0081f90 (nil)
15:51:31.059: 5796: debug : remoteIO:5924 : All done with our call 1 (nil) 0x7f19e0081f90
15:51:31.059: 5796: debug : do_open:1209 : nwfilter driver 1 remote returned ERROR
15:51:31.060: 5796: debug : virDomainLookupByName:2030 : conn=0x6f6350, name=freenas1
15:51:31.061: 5796: debug : virDomainGetID:2718 : dom=0x7f19e002db00, (VM: name=freenas1, uuid=07aadf11-2090-4690-9518-52766722c544), 
15:51:31.061: 5796: debug : virDomainCreate:6300 : dom=0x7f19e002db00, (VM: name=freenas1, uuid=07aadf11-2090-4690-9518-52766722c544), 
15:51:31.566: 5796: debug : virDomainGetName:2623 : domain=0x7f19e002db00
error: Failed to start domain freenas1
15:51:31.566: 5796: debug : virDomainFree:2118 : dom=0x7f19e002db00, (VM: name=freenas1, uuid=07aadf11-2090-4690-9518-52766722c544), 
15:51:31.566: 5796: debug : virUnrefDomain:276 : unref domain 0x7f19e002db00 freenas1 1
15:51:31.566: 5796: debug : virReleaseDomain:238 : release domain 0x7f19e002db00 freenas1 07aadf11-2090-4690-9518-52766722c544
15:51:31.566: 5796: debug : virReleaseDomain:246 : unref connection 0x6f6350 2
error: An error occurred, but the cause is unknown

Comment 1 Dave Allan 2011-11-28 01:26:56 UTC
jc, you should mention this on the upstream libvirt list as well.  I'm not sure how much attention the people who work on the vbox driver pay to bugzilla.

Comment 2 Cole Robinson 2016-03-23 14:39:02 UTC
Given the age of this bug, just closing. If anyone can still reproduce with modern libvirt and virtualbox, please file a new bug