[Xen-API] libvirt: libxenlight failed to create new domain

[Guillaume Thouvenin <thouveng@xxxxxxxxx>]

Hello,

 I'm trying to create a VM by using libvirt as toolstack but it failed. The xenopsd-xc is running. I installed xen from RPM that I build. The XML that I'm using to create the VM is in the log of the error. I used the command "virsh -c xen:/// create machine.xml" that I launched in dom0. The xl command is working. The only strange thing is that if I run "virsh -c xen:/// list --all" I see nothing where I expect to find at least the dom0. But maybe it is because I can only see VM create with libvirt...

In the log I have:

013-10-25 11:54:06.532+000026801: debug : do_open:1135 : name "xen:///" to URI components:
  scheme xen
  server (null)
  user (null)
  port 0
  path /

2013-10-25 11:54:06.532+000026801: debug : do_open:1182 : trying driver 0 (Test) ...
2013-10-25 11:54:06.532+000026801: debug : do_open:1188 : driver 0 Test returned DECLINED
2013-10-25 11:54:06.532+000026801: debug : do_open:1182 : trying driver 1 (ESX) ...
2013-10-25 11:54:06.532+000026801: debug : do_open:1188 : driver 1 ESX returned DECLINED
2013-10-25 11:54:06.532+000026801: debug : do_open:1182 : trying driver 2 (remote) ...
2013-10-25 11:54:06.532+000026801: debug : do_open:1188 : driver 2 remote returned DECLINED
2013-10-25 11:54:06.532+000026801: debug : do_open:1182 : trying driver 3 (Xen) ...
2013-10-25 11:54:06.532+000026801: debug : virCommandRunAsync:2200 : About to run /usr/sbin/xend status
2013-10-25 11:54:06.544+000026801: debug : virFileClose:72 : Closed fd 23
2013-10-25 11:54:06.544+000026801: debug : virFileClose:72 : Closed fd 25
2013-10-25 11:54:06.544+000026801: debug : virFileClose:72 : Closed fd 27
2013-10-25 11:54:06.544+000026801: debug : virCommandRunAsync:2218 : Command result 0, with PID 28416
2013-10-25 11:54:07.057+000026801: debug : virCommandRun:2016 : Result exit status 3, stdout: '' stderr: ''
2013-10-25 11:54:07.057+000026801: debug : virFileClose:72 : Closed fd 24
2013-10-25 11:54:07.057+000026801: debug : virFileClose:72 : Closed fd 26
2013-10-25 11:54:07.057+000026801: debug : do_open:1188 : driver 3 Xen returned DECLINED
2013-10-25 11:54:07.057+000026801: debug : do_open:1182 : trying driver 4 (xenlight) ...
2013-10-25 11:54:07.057+000026801: debug : do_open:1188 : driver 4 xenlight returned SUCCESS
2013-10-25 11:54:07.057+000026801: debug : do_open:1210 : network driver 0 Test returned DECLINED
2013-10-25 11:54:07.057+000026801: debug : do_open:1210 : network driver 1 ESX returned DECLINED
2013-10-25 11:54:07.057+000026801: debug : do_open:1210 : network driver 2 remote returned DECLINED
2013-10-25 11:54:07.057+000026801: debug : do_open:1210 : network driver 3 Network returned SUCCESS
2013-10-25 11:54:07.057+000026801: debug : do_open:1225 : interface driver 0 Test returned DECLINED
2013-10-25 11:54:07.057+000026801: debug : do_open:1225 : interface driver 1 ESX returned DECLINED
2013-10-25 11:54:07.057+000026801: debug : do_open:1225 : interface driver 2 remote returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1225 : interface driver 3 Interface returned SUCCESS
2013-10-25 11:54:07.116+000026801: debug : do_open:1241 : storage driver 0 Test returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1241 : storage driver 1 ESX returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1241 : storage driver 2 remote returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1241 : storage driver 3 storage returned SUCCESS
2013-10-25 11:54:07.116+000026801: debug : do_open:1257 : node driver 0 Test returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1257 : node driver 1 ESX returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1257 : node driver 2 remote returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1257 : node driver 3 udevDeviceMonitor returned SUCCESS
2013-10-25 11:54:07.116+000026801: debug : do_open:1273 : secret driver 0 Test returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1273 : secret driver 1 ESX returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1273 : secret driver 2 remote returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1273 : secret driver 3 secret returned SUCCESS
2013-10-25 11:54:07.116+000026801: debug : do_open:1289 : nwfilter driver 0 Test returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1289 : nwfilter driver 1 ESX returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1289 : nwfilter driver 2 remote returned DECLINED
2013-10-25 11:54:07.116+000026801: debug : do_open:1289 : nwfilter driver 3 nwfilter returned SUCCESS
2013-10-25 11:54:07.116+000026801: debug : virNetMessageEncodePayload:358 : Encode length as 28
2013-10-25 11:54:07.116+000026801: debug : virNetServerClientSendMessageLocked:1119 : msg=0x1c0cd10 proc=1 len=28 offset=0
2013-10-25 11:54:07.116+000026801: debug : virNetServerClientSendMessageLocked:1127 : RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x1c0be30 len=28 prog=536903814 vers=1 proc=1 type=1 status=0 serial=2
2013-10-25 11:54:07.116+000026801: debug : virNetServerClientCalculateHandleMode:152 : tls=(nil) hs=-1, rx=0x1c0bcc0 tx=0x1c0cd10
2013-10-25 11:54:07.116+000026801: debug : virNetServerClientCalculateHandleMode:183 : mode=3
2013-10-25 11:54:07.116+000026801: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=11 events=3
2013-10-25 11:54:07.116+000026801: debug : virEventPollInterruptLocked:716 : Interrupting
2013-10-25 11:54:07.116+000026801: debug : virObjectUnref:135 : OBJECT_UNREF: obj=0x1c07210
2013-10-25 11:54:07.116+000026801: debug : virObjectUnref:135 : OBJECT_UNREF: obj=0x1c0be30
2013-10-25 11:54:07.116+000026800: debug : virEventPollRunOnce:640 : Poll got 1 event(s)
2013-10-25 11:54:07.116+000026800: debug : virEventPollDispatchTimeouts:425 : Dispatch 2
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:470 : Dispatch 8
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=0 w=1
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:498 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=1 w=2
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=2 w=3
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=3 w=4
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=4 w=5
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=5 w=6
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=6 w=7
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=7 w=11
2013-10-25 11:54:07.117+000026800: debug : virEventPollCleanupTimeouts:516 : Cleanup 2
2013-10-25 11:54:07.117+000026800: debug : virEventPollCleanupHandles:564 : Cleanup 8
2013-10-25 11:54:07.117+000026800: debug : virEventRunDefaultImpl:244 : running default event implementation
2013-10-25 11:54:07.117+000026800: debug : virEventPollCleanupTimeouts:516 : Cleanup 2
2013-10-25 11:54:07.117+000026800: debug : virEventPollCleanupHandles:564 : Cleanup 8
2013-10-25 11:54:07.117+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=0 w=1, f=7 e=1 d=0
2013-10-25 11:54:07.117+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=1 w=2, f=9 e=1 d=0
2013-10-25 11:54:07.117+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=2 w=3, f=12 e=1 d=0
2013-10-25 11:54:07.117+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=3 w=4, f=13 e=1 d=0
2013-10-25 11:54:07.117+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=4 w=5, f=6 e=1 d=0
2013-10-25 11:54:07.117+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=5 w=6, f=15 e=1 d=0
2013-10-25 11:54:07.117+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=6 w=7, f=14 e=1 d=0
2013-10-25 11:54:07.117+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=7 w=11, f=22 e=5 d=0
2013-10-25 11:54:07.117+000026800: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
2013-10-25 11:54:07.117+000026800: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1382702051527
2013-10-25 11:54:07.117+000026800: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1382702051527 now=1382702047117
2013-10-25 11:54:07.117+000026800: debug : virEventPollCalculateTimeout:361 : Timeout at 1382702051527 due in 4410 ms
2013-10-25 11:54:07.117+000026800: debug : virEventPollRunOnce:629 : EVENT_POLL_RUN: nhandles=8 timeout=4410
2013-10-25 11:54:07.117+000026800: debug : virEventPollRunOnce:640 : Poll got 1 event(s)
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchTimeouts:425 : Dispatch 2
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:470 : Dispatch 8
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=0 w=1
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=1 w=2
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=2 w=3
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=3 w=4
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=4 w=5
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=5 w=6
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=6 w=7
2013-10-25 11:54:07.117+000026800: debug : virEventPollDispatchHandles:484 : i=7 w=11
2013-10-25 11:54:07.126+000026800: debug : virEventPollDispatchHandles:498 : EVENT_POLL_DISPATCH_HANDLE: watch=11 events=1
2013-10-25 11:54:07.126+000026800: debug : virNetMessageDecodeLength:152 : Got length, now need 584 total (580 more)
2013-10-25 11:54:07.126+000026800: debug : virNetServerClientCalculateHandleMode:152 : tls=(nil) hs=-1, rx=0x1c0bcc0 tx=(nil)
2013-10-25 11:54:07.126+000026800: debug : virNetServerClientCalculateHandleMode:183 : mode=1
2013-10-25 11:54:07.126+000026800: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=11 events=1
2013-10-25 11:54:07.126+000026800: debug : virEventPollInterruptLocked:712 : Skip interrupt, 1 614053888
2013-10-25 11:54:07.126+000026800: debug : virNetServerClientDispatchRead:875 : RPC_SERVER_CLIENT_MSG_RX: client=0x1c0be30 len=584 prog=536903814 vers=1 proc=10 type=0 status=0 serial=3
2013-10-25 11:54:07.126+000026800: debug : virKeepAliveCheckMessage:384 : ka=0x1c0aed0, client=0x1c0be30, msg=0x1c0bcc0
2013-10-25 11:54:07.126+000026800: debug : virEventPollUpdateTimeout:260 : EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
2013-10-25 11:54:07.126+000026800: debug : virEventPollUpdateTimeout:278 : Set timer freq=5000 expires=1382702052126
2013-10-25 11:54:07.126+000026800: debug : virEventPollInterruptLocked:712 : Skip interrupt, 1 614053888
2013-10-25 11:54:07.126+000026800: debug : virObjectRef:168 : OBJECT_REF: obj=0x1c0be30
2013-10-25 11:54:07.126+000026800: debug : virNetServerDispatchNewMessage:218 : server=0x1bfa020 client=0x1c0be30 message=0x1c0bcc0
2013-10-25 11:54:07.126+000026800: debug : virObjectRef:168 : OBJECT_REF: obj=0x1c07210
2013-10-25 11:54:07.126+000026800: debug : virNetMessageNew:45 : msg=0x1c0c830 tracked=1
2013-10-25 11:54:07.126+000026800: debug : virNetServerClientCalculateHandleMode:152 : tls=(nil) hs=-1, rx=0x1c0c830 tx=(nil)
2013-10-25 11:54:07.126+000026800: debug : virNetServerClientCalculateHandleMode:183 : mode=1
2013-10-25 11:54:07.126+000026800: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=11 events=1
2013-10-25 11:54:07.126+000026800: debug : virEventPollInterruptLocked:712 : Skip interrupt, 1 614053888
2013-10-25 11:54:07.126+000026800: debug : virEventPollCleanupTimeouts:516 : Cleanup 2
2013-10-25 11:54:07.126+000026800: debug : virEventPollCleanupHandles:564 : Cleanup 8
2013-10-25 11:54:07.126+000026800: debug : virEventRunDefaultImpl:244 : running default event implementation
2013-10-25 11:54:07.126+000026800: debug : virEventPollCleanupTimeouts:516 : Cleanup 2
2013-10-25 11:54:07.126+000026800: debug : virEventPollCleanupHandles:564 : Cleanup 8
2013-10-25 11:54:07.126+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=0 w=1, f=7 e=1 d=0
2013-10-25 11:54:07.126+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=1 w=2, f=9 e=1 d=0
2013-10-25 11:54:07.126+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=2 w=3, f=12 e=1 d=0
2013-10-25 11:54:07.126+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=3 w=4, f=13 e=1 d=0
2013-10-25 11:54:07.126+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=4 w=5, f=6 e=1 d=0
2013-10-25 11:54:07.126+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=5 w=6, f=15 e=1 d=0
2013-10-25 11:54:07.126+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=6 w=7, f=14 e=1 d=0
2013-10-25 11:54:07.126+000026800: debug : virEventPollMakePollFDs:393 : Prepare n=7 w=11, f=22 e=1 d=0
2013-10-25 11:54:07.126+000026802: debug : virNetServerHandleJob:189 : server=0x1bfa020 client=0x1c0be30 message=0x1c0bcc0 prog=0x1c07210
2013-10-25 11:54:07.126+000026800: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
2013-10-25 11:54:07.126+000026800: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1382702052126
2013-10-25 11:54:07.126+000026800: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1382702052126 now=1382702047126
2013-10-25 11:54:07.126+000026802: debug : virNetServerProgramDispatch:284 : prog=536903814 ver=1 type=0 status=0 serial=3 proc=10
2013-10-25 11:54:07.126+000026800: debug : virEventPollCalculateTimeout:361 : Timeout at 1382702052126 due in 5000 ms
2013-10-25 11:54:07.126+000026800: debug : virEventPollRunOnce:629 : EVENT_POLL_RUN: nhandles=8 timeout=5000
2013-10-25 11:54:07.141+000026802: debug : remoteDispatchDomainCreateXMLHelper:1151 : server=0x1bfa020 client=0x1c0be30 msg=0x1c0bcc0 rerr=0x7fae1e307be0 args=0x7fae08000b50 ret=0x7fae080008c0
2013-10-25 11:54:07.141+000026802: debug : virDomainCreateXML:1945 : conn=0x7fadf8052e70, xmlDesc=<domain type='xen' >
  <name>centosvm1</name>
  <bootloader>/usr/bin/pygrub</bootloader>
  <os>
    <type>linux</type>
  </os>
  <memory>131072</memory>
  <vcpu>1</vcpu>
  <devices>
    <disk type='file'>
      <source file='/usr/share/xapi/images/images/centos_hard_drive2.vhd'/>
      <target dev='sda1'/>
    </disk>
    <interface type='bridge'>
      <source bridge='xenbr2'/>
      <mac address='aa:00:00:00:00:11'/>
      <script path='/etc/xen/scripts/vif-bridge'/>
    </interface>
    <console tty='/dev/pts/5'/>
  </devices>
</domain>
, flags=0
2013-10-25 11:54:07.149+000026802: debug : virFileClose:72 : Closed fd 25
2013-10-25 11:54:07.159+000026802: debug : virObjectNew:110 : OBJECT_NEW: obj=0x7fae08007750 classname=virDomainObj
2013-10-25 11:54:07.159+000026802: debug : virObjectNew:110 : OBJECT_NEW: obj=0x7fae08007890 classname=libxlDomainObjPrivate
2013-10-25 11:54:07.163+000026802: debug : virDomainObjNew:1782 : obj=0x7fae08007750
2013-10-25 11:54:07.234+000026802: error : libxlVmStart:958 : internal error libxenlight failed to create new domain 'centosvm1'

Any help is welcome,

Regards

_______________________________________________
Xen-api mailing list
Xen-api@xxxxxxxxxxxxx
http://lists.xen.org/cgi-bin/mailman/listinfo/xen-api