[libvirt] virsh stucked in virDomainCreate

Matthias Bolte matthias.bolte at googlemail.com
Wed Mar 17 18:16:40 UTC 2010 

[Let's keep it on the list, so other could help too]

2010/3/15 Anthony Lannuzel <lannuzel at gmail.com>:
> On Sat, Mar 13, 2010 at 6:51 PM, Matthias Bolte
> <matthias.bolte at googlemail.com> wrote:
>> 2010/3/13 Anthony Lannuzel <lannuzel at gmail.com>:
>>> Hi,
>>>
>>> I'm having an issue when trying to start a (previously created) vbox
>>> item : virsh gets stucked in virDomainCreate and I see no error
>>> message (LIBVIRT_DEBUG=1).
>>> Is there any mean to get more information on what is happening ?
>>>
>>> Moreover, now that virsh has stalled, running "connect
>>> vbox:///session" on another virsh instance gets an error from "secret
>>> driver". Is this normal, as if I'm only supposed to have 1 connection
>>> at a time ?
>>>
>>> Thanks
>>> Regards
>>>
>>> Anthony
>>>
>>
>> I tested starting vbox guest using virsh and it works as expected and
>> I can use multiple connections at the same time as expected.
>>
>> What libvirt and vbox versions do you use?
>>
>> Can you give some more details about what you did to trigger this problem?
>>
>> Matthias
>>
>
> Hi,
>
> I'm using virsh 0.7.6 with VirtualBox 3.1.4 on a 2.6.24 kernel with
> openVZ, unionfs and squashfs patches.
>
> Here is what I do :
>
> The domain is created with virDomainDefineXML. Here is the XML file content:
>
> <domain type="vbox">
>  <name>c7c0ab9f-9a19-4a45-92a1-799367789509</name>
>  <uuid>c7c0ab9f-9a19-4a45-92a1-799367789509</uuid>
>  <vcpu>1</vcpu>
>  <memory>196608</memory>
>  <on_poweroff>destroy</on_poweroff>
>  <on_reboot>destroy</on_reboot>
>  <on_crash>destroy</on_crash>
>  <os>
>    <type>hvm</type>
>  </os>
>  <features>
>    <pae></pae>
>    <acpi></acpi>
>    <apic></apic>
>  </features>
>  <devices>
>    <disk device="disk" type="file">
>      <source file="/data/c7c0ab9f-9a19-4a45-92a1-799367789509/ubuntuDesktop-8.04.vdi"/>
>      <target bus="ide" dev="hda"/>
>    </disk>
>    <interface type="bridge">
>      <source bridge="hnsTap0_tap"/>
>      <mac address="00:22:94:ae:a1:86"/>
>      <model type="82543gc"/>
>    </interface>
>    <graphics port="12000" type="rdp"/>
>  </devices>
> </domain>
>
>
>
> Then I try to start it with virsh:
>
> root at hynesim-live:/home/hynesim# virsh
> 10:09:06.685: debug : virInitialize:336 : register drivers
> 10:09:06.685: debug : virRegisterDriver:837 : registering Test as driver 0
> 10:09:06.685: debug : virRegisterNetworkDriver:675 : registering Test
> as network driver 0
> 10:09:06.685: debug : virRegisterInterfaceDriver:706 : registering
> Test as interface driver 0
> 10:09:06.685: debug : virRegisterStorageDriver:737 : registering Test
> as storage driver 0
> 10:09:06.685: debug : virRegisterDeviceMonitor:768 : registering Test
> as device driver 0
> 10:09:06.685: debug : virRegisterSecretDriver:799 : registering Test
> as secret driver 0
> 10:09:06.685: debug : virRegisterDriver:837 : registering OPENVZ as driver 1
> 10:09:06.709: debug : vboxRegister:87 : VBoxCGlueInit found API
> version: 3.1.4 (3001004)
> 10:09:06.718: debug : vboxRegister:104 : VirtualBox API version: 3.1
> 10:09:06.718: debug : virRegisterDriver:837 : registering VBOX as driver 2
> 10:09:06.718: debug : virRegisterNetworkDriver:675 : registering VBOX
> as network driver 1
> 10:09:06.718: debug : virRegisterStorageDriver:737 : registering VBOX
> as storage driver 1
> 10:09:06.718: debug : virRegisterDriver:837 : registering remote as driver 3
> 10:09:06.718: debug : virRegisterNetworkDriver:675 : registering
> remote as network driver 2
> 10:09:06.719: debug : virRegisterInterfaceDriver:706 : registering
> remote as interface driver 1
> 10:09:06.719: debug : virRegisterStorageDriver:737 : registering
> remote as storage driver 2
> 10:09:06.719: debug : virRegisterDeviceMonitor:768 : registering
> remote as device driver 1
> 10:09:06.719: debug : virRegisterSecretDriver:799 : registering remote
> as secret driver 1
> 10:09:06.719: debug : virConnectOpenAuth:1355 : name=(null),
> auth=0x2b78d7561c80, flags=0
> 10:09:06.719: debug : do_open:1112 : no name, allowing driver auto-select
> 10:09:06.719: debug : do_open:1120 : trying driver 0 (Test) ...
> 10:09:06.719: debug : do_open:1126 : driver 0 Test returned DECLINED
> 10:09:06.719: debug : do_open:1120 : trying driver 1 (OPENVZ) ...
> 10:09:06.759: debug : virExecWithHook:637 : LC_ALL=C /usr/sbin/vzctl --help
> 10:09:06.771: debug : do_open:1126 : driver 1 OPENVZ returned SUCCESS
> 10:09:06.771: debug : do_open:1146 : network driver 0 Test returned DECLINED
> 10:09:06.771: debug : do_open:1146 : network driver 1 VBOX returned DECLINED
> 10:09:06.772: debug : doRemoteOpen:564 : proceeding with name = openvz:///system
> 10:09:06.774: debug : remoteIO:8429 : Do proc=66 serial=0 length=28 wait=(nil)
> 10:09:06.774: debug : remoteIO:8491 : We have the buck 66
> 0x2b78dbcf2010 0x2b78dbcf2010
> 10:09:06.776: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 64 total (60 more)
> 10:09:06.776: debug : remoteIOEventLoop:8355 : Giving up the buck 66
> 0x2b78dbcf2010 (nil)
> 10:09:06.776: debug : remoteIO:8522 : All done with our call 66 (nil)
> 0x2b78dbcf2010
> 10:09:06.776: debug : remoteIO:8429 : Do proc=1 serial=1 length=56 wait=(nil)
> 10:09:06.776: debug : remoteIO:8491 : We have the buck 1 0x63fe50 0x63fe50
> 10:09:06.848: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 56 total (52 more)
> 10:09:06.848: debug : remoteIOEventLoop:8355 : Giving up the buck 1
> 0x63fe50 (nil)
> 10:09:06.848: debug : remoteIO:8522 : All done with our call 1 (nil) 0x63fe50
> 10:09:06.848: debug : doRemoteOpen:891 : Adding Handler for remote events
> 10:09:06.848: debug : doRemoteOpen:898 : virEventAddHandle failed: No
> addHandleImpl defined. continuing without events.
> 10:09:06.848: debug : do_open:1146 : network driver 2 remote returned SUCCESS
> 10:09:06.848: debug : do_open:1165 : interface driver 0 Test returned DECLINED
> 10:09:06.849: debug : doRemoteOpen:564 : proceeding with name = openvz:///system
> 10:09:06.850: debug : remoteIO:8429 : Do proc=66 serial=0 length=28 wait=(nil)
> 10:09:06.850: debug : remoteIO:8491 : We have the buck 66 0x67ff00 0x67ff00
> 10:09:06.852: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 64 total (60 more)
> 10:09:06.852: debug : remoteIOEventLoop:8355 : Giving up the buck 66
> 0x67ff00 (nil)
> 10:09:06.852: debug : remoteIO:8522 : All done with our call 66 (nil) 0x67ff00
> 10:09:06.853: debug : remoteIO:8429 : Do proc=1 serial=1 length=56 wait=(nil)
> 10:09:06.853: debug : remoteIO:8491 : We have the buck 1 0x67ff00 0x67ff00
> 10:09:06.901: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 56 total (52 more)
> 10:09:06.901: debug : remoteIOEventLoop:8355 : Giving up the buck 1
> 0x67ff00 (nil)
> 10:09:06.901: debug : remoteIO:8522 : All done with our call 1 (nil) 0x67ff00
> 10:09:06.901: debug : doRemoteOpen:891 : Adding Handler for remote events
> 10:09:06.901: debug : doRemoteOpen:898 : virEventAddHandle failed: No
> addHandleImpl defined. continuing without events.
> 10:09:06.901: debug : do_open:1165 : interface driver 1 remote returned SUCCESS
> 10:09:06.901: debug : do_open:1185 : storage driver 0 Test returned DECLINED
> 10:09:06.901: debug : do_open:1185 : storage driver 1 VBOX returned DECLINED
> 10:09:06.901: debug : do_open:1185 : storage driver 2 remote returned SUCCESS
> 10:09:06.901: debug : do_open:1205 : node driver 0 Test returned DECLINED
> 10:09:06.901: debug : do_open:1205 : node driver 1 remote returned SUCCESS
> 10:09:06.901: debug : do_open:1232 : secret driver 0 Test returned DECLINED
> 10:09:06.901: debug : do_open:1232 : secret driver 1 remote returned SUCCESS
> Bienvenue dans virsh, le terminal de virtualisation interactif.
>
> Taper :  « help » pour l'aide ou « help » avec la commande
>         « quit » pour quitter
>
> virsh # connect vbox:///session
> 10:09:13.993: debug : virConnectClose:1381 : conn=0x63b060
> 10:09:13.994: debug : virUnrefConnect:259 : unref connection 0x63b060 1
> 10:09:13.994: debug : remoteIO:8429 : Do proc=2 serial=2 length=28 wait=(nil)
> 10:09:13.994: debug : remoteIO:8491 : We have the buck 2 0x680170 0x680170
> 10:09:13.995: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 56 total (52 more)
> 10:09:13.995: debug : remoteIOEventLoop:8355 : Giving up the buck 2
> 0x680170 (nil)
> 10:09:13.995: debug : remoteIO:8522 : All done with our call 2 (nil) 0x680170
> 10:09:13.996: debug : remoteIO:8429 : Do proc=2 serial=2 length=28 wait=(nil)
> 10:09:13.996: debug : remoteIO:8491 : We have the buck 2 0x680170 0x680170
> 10:09:13.997: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 56 total (52 more)
> 10:09:13.997: debug : remoteIOEventLoop:8355 : Giving up the buck 2
> 0x680170 (nil)
> 10:09:13.997: debug : remoteIO:8522 : All done with our call 2 (nil) 0x680170
> 10:09:13.997: debug : virDomainObjUnref:680 : obj=0x63ebf0 refs=0
> 10:09:13.997: debug : virDomainObjFree:658 : obj=0x63ebf0
> 10:09:13.997: debug : virReleaseConnect:216 : release connection 0x63b060
> 10:09:13.997: debug : virConnectOpenAuth:1355 : name=vbox:///session,
> auth=0x2b78d7561c80, flags=0
> 10:09:13.997: debug : do_open:1110 : name "vbox:///session" to URI components:
>  scheme vbox
>  opaque (null)
>  authority (null)
>  server (null)
>  user (null)
>  port 0
>  path /session
>
> 10:09:13.997: debug : do_open:1120 : trying driver 0 (Test) ...
> 10:09:13.997: debug : do_open:1126 : driver 0 Test returned DECLINED
> 10:09:13.997: debug : do_open:1120 : trying driver 1 (OPENVZ) ...
> 10:09:13.997: debug : do_open:1126 : driver 1 OPENVZ returned DECLINED
> 10:09:13.997: debug : do_open:1120 : trying driver 2 (VBOX) ...
> 10:09:14.021: debug : vboxOpen:836 : in vboxOpen
> 10:09:14.021: debug : do_open:1126 : driver 2 VBOX returned SUCCESS
> 10:09:14.021: debug : do_open:1146 : network driver 0 Test returned DECLINED
> 10:09:14.021: debug : vboxNetworkOpen:5434 : network initialized
> 10:09:14.021: debug : do_open:1146 : network driver 1 VBOX returned SUCCESS
> 10:09:14.022: debug : do_open:1165 : interface driver 0 Test returned DECLINED
> 10:09:14.022: debug : doRemoteOpen:564 : proceeding with name = vbox:///session
> 10:09:14.024: debug : remoteIO:8429 : Do proc=66 serial=0 length=28 wait=(nil)
> 10:09:14.024: debug : remoteIO:8491 : We have the buck 66 0x6eaa90 0x6eaa90
> 10:09:14.025: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 64 total (60 more)
> 10:09:14.025: debug : remoteIOEventLoop:8355 : Giving up the buck 66
> 0x6eaa90 (nil)
> 10:09:14.025: debug : remoteIO:8522 : All done with our call 66 (nil) 0x6eaa90
> 10:09:14.026: debug : remoteIO:8429 : Do proc=1 serial=1 length=56 wait=(nil)
> 10:09:14.026: debug : remoteIO:8491 : We have the buck 1 0x6eaa90 0x6eaa90
> 10:09:14.027: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 56 total (52 more)
> 10:09:14.027: debug : remoteIOEventLoop:8355 : Giving up the buck 1
> 0x6eaa90 (nil)
> 10:09:14.027: debug : remoteIO:8522 : All done with our call 1 (nil) 0x6eaa90
> 10:09:14.027: debug : doRemoteOpen:891 : Adding Handler for remote events
> 10:09:14.027: debug : doRemoteOpen:898 : virEventAddHandle failed: No
> addHandleImpl defined. continuing without events.
> 10:09:14.027: debug : do_open:1165 : interface driver 1 remote returned SUCCESS
> 10:09:14.027: debug : do_open:1185 : storage driver 0 Test returned DECLINED
> 10:09:14.027: debug : vboxStorageOpen:6186 : vbox storage initialized
> 10:09:14.027: debug : do_open:1185 : storage driver 1 VBOX returned SUCCESS
> 10:09:14.028: debug : do_open:1205 : node driver 0 Test returned DECLINED
> 10:09:14.028: debug : doRemoteOpen:564 : proceeding with name = vbox:///session
> 10:09:14.030: debug : remoteIO:8429 : Do proc=66 serial=0 length=28 wait=(nil)
> 10:09:14.037: debug : remoteIO:8491 : We have the buck 66 0x72ab40 0x72ab40
> 10:09:14.038: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 64 total (60 more)
> 10:09:14.038: debug : remoteIOEventLoop:8355 : Giving up the buck 66
> 0x72ab40 (nil)
> 10:09:14.038: debug : remoteIO:8522 : All done with our call 66 (nil) 0x72ab40
> 10:09:14.038: debug : remoteIO:8429 : Do proc=1 serial=1 length=56 wait=(nil)
> 10:09:14.039: debug : remoteIO:8491 : We have the buck 1 0x72ab40 0x72ab40
> 10:09:14.040: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 56 total (52 more)
> 10:09:14.040: debug : remoteIOEventLoop:8355 : Giving up the buck 1
> 0x72ab40 (nil)
> 10:09:14.040: debug : remoteIO:8522 : All done with our call 1 (nil) 0x72ab40
> 10:09:14.040: debug : doRemoteOpen:891 : Adding Handler for remote events
> 10:09:14.040: debug : doRemoteOpen:898 : virEventAddHandle failed: No
> addHandleImpl defined. continuing without events.
> 10:09:14.040: debug : do_open:1205 : node driver 1 remote returned SUCCESS
> 10:09:14.040: debug : do_open:1232 : secret driver 0 Test returned DECLINED
> 10:09:14.040: debug : doRemoteOpen:564 : proceeding with name = vbox:///session
> 10:09:14.041: debug : remoteIO:8429 : Do proc=66 serial=0 length=28 wait=(nil)
> 10:09:14.041: debug : remoteIO:8491 : We have the buck 66 0x76abf0 0x76abf0
> 10:09:14.042: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 64 total (60 more)
> 10:09:14.042: debug : remoteIOEventLoop:8355 : Giving up the buck 66
> 0x76abf0 (nil)
> 10:09:14.042: debug : remoteIO:8522 : All done with our call 66 (nil) 0x76abf0
> 10:09:14.043: debug : remoteIO:8429 : Do proc=1 serial=1 length=56 wait=(nil)
> 10:09:14.043: debug : remoteIO:8491 : We have the buck 1 0x76abf0 0x76abf0
> 10:09:14.044: debug : remoteIODecodeMessageLength:7913 : Got length,
> now need 56 total (52 more)
> 10:09:14.044: debug : remoteIOEventLoop:8355 : Giving up the buck 1
> 0x76abf0 (nil)
> 10:09:14.044: debug : remoteIO:8522 : All done with our call 1 (nil) 0x76abf0
> 10:09:14.044: debug : doRemoteOpen:891 : Adding Handler for remote events
> 10:09:14.044: debug : doRemoteOpen:898 : virEventAddHandle failed: No
> addHandleImpl defined. continuing without events.
> 10:09:14.044: debug : do_open:1232 : secret driver 1 remote returned SUCCESS
>
> virsh # list --all
> 10:09:19.563: debug : virConnectNumOfDomains:1749 : conn=0x63ebf0
> 10:09:19.568: debug : virConnectNumOfDefinedDomains:4609 : conn=0x63ebf0
> 10:09:19.568: debug : virConnectListDefinedDomains:4648 :
> conn=0x63ebf0, names=0x692430, maxnames=1
>  ID Nom                  État
> ----------------------------------
> 10:09:19.570: debug : virDomainLookupByName:2010 : conn=0x63ebf0,
> name=c7c0ab9f-9a19-4a45-92a1-799367789509
> 10:09:19.571: debug : virGetDomain:345 : New hash entry 0x6a6000
> 10:09:19.571: debug : virDomainGetInfo:2867 : domain=0x6a6000,
> info=0x7fffd3a519e0
>  - c7c0ab9f-9a19-4a45-92a1-799367789509 closed
> 10:09:19.573: debug : virDomainFree:2098 : domain=0x6a6000
> 10:09:19.573: debug : virUnrefDomain:422 : unref domain 0x6a6000
> c7c0ab9f-9a19-4a45-92a1-799367789509 1
> 10:09:19.573: debug : virReleaseDomain:376 : release domain 0x6a6000
> c7c0ab9f-9a19-4a45-92a1-799367789509
> 10:09:19.573: debug : virReleaseDomain:392 : unref connection 0x63ebf0 2
>
> virsh # start c7c0ab9f-9a19-4a45-92a1-799367789509
> 10:09:26.108: debug : virDomainLookupByName:2010 : conn=0x63ebf0,
> name=c7c0ab9f-9a19-4a45-92a1-799367789509
> 10:09:26.112: debug : virGetDomain:345 : New hash entry 0x68bd70
> 10:09:26.112: debug : virDomainGetID:2658 : domain=0x68bd70
> 10:09:26.112: debug : virDomainCreate:4690 : domain=0x68bd70
> 10:09:26.112: debug : virDomainCreate:4693 : 1 0x68bd70
> 10:09:26.112: debug : virDomainCreate:4700 : 2 0x68bd70
> 10:09:26.112: debug : virDomainCreate:4707 : 3 0x68bd70
> 10:09:26.112: debug : virDomainCreate:4710 : 3.1 0x68bd70
> 10:09:26.223: debug : vboxDomainCreate:3321 : before close 0x68bd70
>
>
> I have added some debug lines, that lead to:
>
> in libvirt.c:
> function int virDomainCreate(virDomainPtr domain)
>        ret = conn->driver->domainCreate (domain); // does not return
>
> in vbox/vbox_tmpl.c:
> function static int vboxDomainCreate(virDomainPtr dom)
>                    data->vboxSession->vtbl->Close(data->vboxSession);
> // does not return
>
> Thanks
>

At that point the domain should already be running. I wonder why
closing the session handle would block.

You could try variations of the domain XML config, assuming that a
specify part of the config triggers this problem. For example use your
posted domain XML config, but leave out the graphics part or the
interface part or the disk part to see if that makes a difference.

Matthias

More information about the libvir-list mailing list