678870 – don't overwrite useful error message with "failed to parse XML"

Bug 678870 - don't overwrite useful error message with "failed to parse XML"

Summary: don't overwrite useful error message with "failed to parse XML"

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 6
Classification:	Red Hat
Component:	libvirt
Sub Component:
Version:	6.1
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	unspecified
Target Milestone:	rc
Target Release:	---
Assignee:	Jiri Denemark
QA Contact:	Virtualization Bugs
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	664225
TreeView+	depends on / blocked

Reported:	2011-02-20 14:36 UTC by Erez Shinan
Modified:	2011-05-19 13:28 UTC (History)
CC List:	13 users (show)
Fixed In Version:	libvirt-0.8.7-10.el6
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2011-05-19 13:28:03 UTC
Target Upstream Version:

Attachments	(Terms of Use)
Add an attachment (proposed patch, testcase, etc.)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHBA-2011:0596	0	normal	SHIPPED_LIVE	libvirt bug fix and enhancement update	2011-05-18 17:56:36 UTC

Description Erez Shinan 2011-02-20 14:36:31 UTC

Description of problem:
libvirt fails on migration between two VMs.
Error given is:
error: operation failed: failed to parse XML

Version-Release number of selected component (if applicable):
libvirt-0.8.7-7.el6.x86_64
kernel-2.6.32-117.el6.x86_64
(same on both vms)

How reproducible:
always


Steps to Reproduce:
1. Created VM with the following XML
<domain type='kvm' id='1'>
  <name>ayal</name>
  <uuid>9ffe28b6-6134-4b1e-8804-1185f49c436f</uuid>
  <memory>20480</memory>
  <currentMemory>20480</currentMemory>
  <vcpu>1</vcpu>
  <sysinfo type='smbios'>
    <system>
      <entry name='manufacturer'>Red Hat</entry>
      <entry name='product'>RHEL</entry>
      <entry name='version'>6Server-6.0.0.37.el6</entry>
      <entry name='serial'>553773D4-199C-7AA9-11BD-905F455409A8_52:54:00:0b:44:bb</entry>
      <entry name='uuid'>9ffe28b6-6134-4b1e-8804-1185f49c436f</entry>
    </system>
  </sysinfo>
  <os>
    <type arch='x86_64' machine='rhel6.0.0'>hvm</type>
    <boot dev='hd'/>
  </os>
  <clock offset='variable' adjustment='0'/>
  <on_poweroff>destroy</on_poweroff>
  <on_reboot>restart</on_reboot>
  <on_crash>destroy</on_crash>
  <devices>
    <emulator>/usr/bin/qemu-system-x86_64</emulator>
    <disk type='file' device='cdrom'>
      <driver name='qemu' type='raw'/>
      <target dev='hdc' bus='ide'/>
      <readonly/>
      <alias name='ide0-1-0'/>
      <address type='drive' controller='0' bus='1' unit='0'/>
    </disk>
    <controller type='virtio-serial' index='0' ports='16'>
      <alias name='virtio-serial0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>
    </controller>
    <controller type='ide' index='0'>
      <alias name='ide0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x1'/>
    </controller>
    <interface type='bridge'>
      <mac address='aa:bb:dd:dd:aa:bb'/>
      <source bridge='virbr0'/>
      <target dev='vnet0'/>
      <model type='virtio'/>
      <alias name='net0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>
    </interface>
    <channel type='unix'>
      <source mode='bind' path='/var/lib/libvirt/qemu/channels/ayal.com.redhat.rhevm.vdsm'/>
      <target type='virtio' name='com.redhat.rhevm.vdsm'/>
      <alias name='channel0'/>
      <address type='virtio-serial' controller='0' bus='0' port='1'/>
    </channel>
    <input type='mouse' bus='ps2'/>
    <graphics type='vnc' port='5900' autoport='yes' listen='0'/>
    <video>
      <model type='cirrus' vram='9216' heads='1'/>
      <alias name='video0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>
    </video>
    <memballoon model='none'>
      <alias name='balloon0'/>
    </memballoon>
  </devices>
</domain>

2. run: LIBVIRT_DEBUG=1 LIBVIRT_LOG_FILTERS="1:util 1:libvirt 1:qemu 1:remote" virsh -c qemu+tcp://10.35.1.67/system migrate ayal qemu+tcp://10.35.1.66/system --p2p

Resulting output is:

10:05:34.032: 2655: info : libvirt version: 0.8.7, package: 7.el6 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2011-02-17-11:07:22, hs20-bc2-5.build.redhat.com)
10:05:34.032: 2655: debug : virInitialize:361 : register drivers
10:05:34.032: 2655: debug : virRegisterDriver:969 : registering Test as driver 0
10:05:34.032: 2655: debug : virRegisterNetworkDriver:775 : registering Test as network driver 0
10:05:34.032: 2655: debug : virRegisterInterfaceDriver:806 : registering Test as interface driver 0
10:05:34.032: 2655: debug : virRegisterStorageDriver:837 : registering Test as storage driver 0
10:05:34.032: 2655: debug : virRegisterDeviceMonitor:868 : registering Test as device driver 0
10:05:34.032: 2655: debug : virRegisterSecretDriver:899 : registering Test as secret driver 0
10:05:34.032: 2655: debug : virRegisterNWFilterDriver:930 : registering Test as network filter driver 0
10:05:34.033: 2655: debug : virRegisterDriver:969 : registering ESX as driver 1
10:05:34.033: 2655: debug : virRegisterInterfaceDriver:806 : registering ESX as interface driver 1
10:05:34.033: 2655: debug : virRegisterNetworkDriver:775 : registering ESX as network driver 1
10:05:34.033: 2655: debug : virRegisterStorageDriver:837 : registering ESX as storage driver 1
10:05:34.033: 2655: debug : virRegisterDeviceMonitor:868 : registering ESX as device driver 1
10:05:34.033: 2655: debug : virRegisterSecretDriver:899 : registering ESX as secret driver 1
10:05:34.033: 2655: debug : virRegisterNWFilterDriver:930 : registering ESX as network filter driver 1
10:05:34.033: 2655: debug : virRegisterDriver:969 : registering remote as driver 2
10:05:34.033: 2655: debug : virRegisterNetworkDriver:775 : registering remote as network driver 2
10:05:34.033: 2655: debug : virRegisterInterfaceDriver:806 : registering remote as interface driver 2
10:05:34.033: 2655: debug : virRegisterStorageDriver:837 : registering remote as storage driver 2
10:05:34.033: 2655: debug : virRegisterDeviceMonitor:868 : registering remote as device driver 2
10:05:34.033: 2655: debug : virRegisterSecretDriver:899 : registering remote as secret driver 2
10:05:34.033: 2655: debug : virRegisterNWFilterDriver:930 : registering remote as network filter driver 2
10:05:34.033: 2655: debug : virConnectOpenAuth:1544 : name=qemu+tcp://10.35.1.67/system, auth=0x7ffef1cf1740, flags=0
10:05:34.033: 2655: debug : do_open:1250 : name "qemu+tcp://10.35.1.67/system" to URI components:
  scheme qemu+tcp
  opaque (null)
  authority (null)
  server 10.35.1.67
  user (null)
  port 0
  path /system

10:05:34.033: 2655: debug : do_open:1289 : trying driver 0 (Test) ...
10:05:34.033: 2655: debug : do_open:1295 : driver 0 Test returned DECLINED
10:05:34.033: 2655: debug : do_open:1289 : trying driver 1 (ESX) ...
10:05:34.033: 2655: debug : do_open:1295 : driver 1 ESX returned DECLINED
10:05:34.033: 2655: debug : do_open:1289 : trying driver 2 (remote) ...
10:05:34.033: 2655: debug : doRemoteOpen:574 : proceeding with name = qemu:///system
10:05:34.034: 2655: debug : remoteIO:10383 : Do proc=66 serial=0 length=28 wait=(nil)
10:05:34.034: 2655: debug : remoteIO:10455 : We have the buck 66 0x7ffeeb854010 0x7ffeeb854010
10:05:34.094: 2655: debug : remoteIODecodeMessageLength:9796 : Got length, now need 64 total (60 more)
10:05:34.094: 2655: debug : remoteIOEventLoop:10309 : Giving up the buck 66 0x7ffeeb854010 (nil)
10:05:34.094: 2655: debug : remoteIO:10483 : All done with our call 66 (nil) 0x7ffeeb854010
10:05:34.094: 2655: debug : remoteIO:10383 : Do proc=1 serial=1 length=56 wait=(nil)
10:05:34.094: 2655: debug : remoteIO:10455 : We have the buck 1 0x2185370 0x2185370
10:05:34.384: 2655: debug : remoteIODecodeMessageLength:9796 : Got length, now need 56 total (52 more)
10:05:34.385: 2655: debug : remoteIOEventLoop:10309 : Giving up the buck 1 0x2185370 (nil)
10:05:34.385: 2655: debug : remoteIO:10483 : All done with our call 1 (nil) 0x2185370
10:05:34.385: 2655: debug : doRemoteOpen:916 : Adding Handler for remote events
10:05:34.385: 2655: debug : virEventAddHandleImpl:103 : Add handle fd=5 events=1 cb=0x7ffef1a30280 opaque=0x2181d10
10:05:34.385: 2655: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.385: 2655: debug : doRemoteOpen:926 : Adding Timeout for remote event queue flushing
10:05:34.385: 2655: debug : virEventAddTimeoutImpl:199 : Adding timer 1 with -1 ms freq
10:05:34.385: 2655: debug : virEventAddTimeoutImpl:207 : Used 0 timeout slots, adding at least 10 more
10:05:34.385: 2655: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.385: 2655: debug : do_open:1295 : driver 2 remote returned SUCCESS
10:05:34.385: 2655: debug : do_open:1315 : network driver 0 Test returned DECLINED
10:05:34.385: 2655: debug : do_open:1315 : network driver 1 ESX returned DECLINED
10:05:34.385: 2655: debug : do_open:1315 : network driver 2 remote returned SUCCESS
10:05:34.385: 2655: debug : do_open:1334 : interface driver 0 Test returned DECLINED
10:05:34.385: 2655: debug : do_open:1334 : interface driver 1 ESX returned DECLINED
10:05:34.385: 2655: debug : do_open:1334 : interface driver 2 remote returned SUCCESS
10:05:34.385: 2655: debug : do_open:1354 : storage driver 0 Test returned DECLINED
10:05:34.385: 2655: debug : do_open:1354 : storage driver 1 ESX returned DECLINED
10:05:34.385: 2655: debug : do_open:1354 : storage driver 2 remote returned SUCCESS
10:05:34.385: 2655: debug : do_open:1374 : node driver 0 Test returned DECLINED
10:05:34.385: 2655: debug : do_open:1374 : node driver 1 ESX returned DECLINED
10:05:34.385: 2655: debug : do_open:1374 : node driver 2 remote returned SUCCESS
10:05:34.385: 2655: debug : do_open:1401 : secret driver 0 Test returned DECLINED
10:05:34.385: 2655: debug : do_open:1401 : secret driver 1 ESX returned DECLINED
10:05:34.385: 2655: debug : do_open:1401 : secret driver 2 remote returned SUCCESS
10:05:34.385: 2655: debug : do_open:1421 : nwfilter driver 0 Test returned DECLINED
10:05:34.385: 2655: debug : do_open:1421 : nwfilter driver 1 ESX returned DECLINED
10:05:34.385: 2655: debug : do_open:1421 : nwfilter driver 2 remote returned SUCCESS
10:05:34.385: 2655: debug : virDomainLookupByName:2206 : conn=0x2181d10, name=ayal
10:05:34.385: 2655: debug : remoteIO:10383 : Do proc=23 serial=2 length=36 wait=(nil)
10:05:34.385: 2655: debug : remoteIO:10455 : We have the buck 23 0x2185710 0x2185710
10:05:34.385: 2655: debug : virEventUpdateHandleImpl:136 : Update handle w=2 e=0
10:05:34.385: 2655: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.386: 2655: debug : remoteIODecodeMessageLength:9796 : Got length, now need 84 total (80 more)
10:05:34.386: 2655: debug : remoteIOEventLoop:10309 : Giving up the buck 23 0x2185710 (nil)
10:05:34.386: 2655: debug : virEventUpdateHandleImpl:136 : Update handle w=2 e=1
10:05:34.386: 2655: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.386: 2655: debug : remoteIO:10483 : All done with our call 23 (nil) 0x2185710
10:05:34.386: 2655: debug : virGetDomain:381 : New hash entry 0x2185150
10:05:34.388: 2656: debug : virDomainLookupByName:2206 : conn=0x2181d10, name=ayal
10:05:34.388: 2656: debug : remoteIO:10383 : Do proc=23 serial=3 length=36 wait=(nil)
10:05:34.388: 2656: debug : remoteIO:10455 : We have the buck 23 0x7ffee4000920 0x7ffee4000920
10:05:34.388: 2656: debug : virEventUpdateHandleImpl:136 : Update handle w=2 e=0
10:05:34.388: 2656: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.389: 2656: debug : remoteIODecodeMessageLength:9796 : Got length, now need 84 total (80 more)
10:05:34.389: 2656: debug : remoteIOEventLoop:10309 : Giving up the buck 23 0x7ffee4000920 (nil)
10:05:34.389: 2656: debug : virEventUpdateHandleImpl:136 : Update handle w=2 e=1
10:05:34.389: 2656: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.389: 2656: debug : remoteIO:10483 : All done with our call 23 (nil) 0x7ffee4000920
10:05:34.389: 2656: debug : virGetDomain:383 : Existing hash entry 0x2185150: refs now 2
10:05:34.389: 2656: debug : virDomainMigrateToURI:3871 : dom=0x2185150, (VM: name=ayal, uuid=9ffe28b6-6134-4b1e-8804-1185f49c436f), duri=0x2180800, flags=2, dname=(null), bandwidth=0
10:05:34.389: 2656: debug : remoteIO:10383 : Do proc=60 serial=4 length=32 wait=(nil)
10:05:34.389: 2656: debug : remoteIO:10455 : We have the buck 60 0x7ffee4000920 0x7ffee4000920
10:05:34.389: 2656: debug : virEventUpdateHandleImpl:136 : Update handle w=2 e=0
10:05:34.389: 2656: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.389: 2656: debug : remoteIODecodeMessageLength:9796 : Got length, now need 60 total (56 more)
10:05:34.389: 2656: debug : remoteIOEventLoop:10309 : Giving up the buck 60 0x7ffee4000920 (nil)
10:05:34.389: 2656: debug : virEventUpdateHandleImpl:136 : Update handle w=2 e=1
10:05:34.389: 2656: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.389: 2656: debug : remoteIO:10483 : All done with our call 60 (nil) 0x7ffee4000920
10:05:34.390: 2656: debug : remoteIO:10383 : Do proc=62 serial=5 length=112 wait=(nil)
10:05:34.390: 2656: debug : remoteIO:10455 : We have the buck 62 0x7ffee4000920 0x7ffee4000920
10:05:34.390: 2656: debug : virEventUpdateHandleImpl:136 : Update handle w=2 e=0
10:05:34.390: 2656: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.807: 2656: debug : remoteIODecodeMessageLength:9796 : Got length, now need 164 total (160 more)
10:05:34.807: 2656: debug : remoteIOEventLoop:10309 : Giving up the buck 62 0x7ffee4000920 (nil)
10:05:34.807: 2656: debug : virEventUpdateHandleImpl:136 : Update handle w=2 e=1
10:05:34.807: 2656: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.807: 2656: debug : remoteIO:10483 : All done with our call 62 (nil) 0x7ffee4000920
10:05:34.807: 2656: debug : virDomainFree:2294 : dom=0x2185150, (VM: name=ayal, uuid=9ffe28b6-6134-4b1e-8804-1185f49c436f), 
10:05:34.807: 2656: debug : virUnrefDomain:462 : unref domain 0x2185150 ayal 2
10:05:34.807: 2655: debug : virDomainFree:2294 : dom=0x2185150, (VM: name=ayal, uuid=9ffe28b6-6134-4b1e-8804-1185f49c436f), 
10:05:34.807: 2655: debug : virUnrefDomain:462 : unref domain 0x2185150 ayal 1
10:05:34.807: 2655: debug : virReleaseDomain:415 : release domain 0x2185150 ayal 9ffe28b6-6134-4b1e-8804-1185f49c436f
10:05:34.807: 2655: debug : virReleaseDomain:432 : unref connection 0x2181d10 2
error: operation failed: failed to parse XML

10:05:34.807: 2655: debug : virConnectClose:1570 : conn=0x2181d10
10:05:34.808: 2655: debug : virUnrefConnect:317 : unref connection 0x2181d10 1
10:05:34.808: 2655: debug : virReleaseConnect:249 : release connection 0x2181d10
10:05:34.808: 2655: debug : virEventRemoveTimeoutImpl:270 : Remove timer 1
10:05:34.808: 2655: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.808: 2655: debug : virEventRemoveHandleImpl:163 : Remove handle w=2
10:05:34.808: 2655: debug : virEventRemoveHandleImpl:176 : mark delete 1 5
10:05:34.808: 2655: debug : virEventInterruptLocked:657 : Skip interrupt, 0 0
10:05:34.808: 2655: debug : remoteIO:10383 : Do proc=2 serial=6 length=28 wait=(nil)
10:05:34.808: 2655: debug : remoteIO:10455 : We have the buck 2 0x2185b10 0x2185b10
10:05:34.808: 2655: debug : remoteIODecodeMessageLength:9796 : Got length, now need 56 total (52 more)
10:05:34.808: 2655: debug : remoteIOEventLoop:10309 : Giving up the buck 2 0x2185b10 (nil)
10:05:34.808: 2655: debug : remoteIO:10483 : All done with our call 2 (nil) 0x2185b10

  
Actual results:


Expected results:


Additional info:
iptables wasn't running

Comment 2 Daniel Berrangé 2011-02-21 11:39:30 UTC

Unfortunately the logfile from virsh isn't much help in debugging migration issues. Can you instead provide the /var/log/libvirt/libvirtd.log from the destination host.

Comment 3 Erez Shinan 2011-02-22 13:10:30 UTC

> Can you instead provide the /var/log/libvirt/libvirtd.log from the
destination host.

I'm not sure which part is relevant, so I'm pasting all of it:

15:06:13.219: 1549: info : libvirt version: 0.8.7, package: 7.el6 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2011-02-17-11:07:22, hs20-bc2-5.build.redhat.com)
15:06:13.219: 1549: debug : virHookCheck:114 : No hook script /etc/libvirt/hooks/daemon
15:06:13.226: 1549: debug : virHookCheck:114 : No hook script /etc/libvirt/hooks/qemu
15:06:13.226: 1549: debug : virHookCheck:114 : No hook script /etc/libvirt/hooks/lxc
15:06:13.674: 1549: debug : virCommandRunAsync:1148 : About to run /usr/sbin/brctl setfd virbr0 0
15:06:13.674: 1549: debug : virExecWithHook:717 : /usr/sbin/brctl setfd virbr0 0
15:06:13.674: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1578
15:06:13.796: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:13.797: 1549: debug : virCommandRunAsync:1148 : About to run /usr/sbin/brctl stp virbr0 on
15:06:13.797: 1549: debug : virExecWithHook:717 : /usr/sbin/brctl stp virbr0 on
15:06:13.797: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1601
15:06:13.799: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:13.799: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table filter --insert INPUT --in-interface virbr0 --protocol tcp --destination-port 67 --jump ACCEPT
15:06:13.799: 1549: debug : virExecWithHook:717 : /sbin/iptables --table filter --insert INPUT --in-interface virbr0 --protocol tcp --destination-port 67 --jump ACCEPT
15:06:13.800: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1604
15:06:13.936: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:13.936: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table filter --insert INPUT --in-interface virbr0 --protocol udp --destination-port 67 --jump ACCEPT
15:06:13.936: 1549: debug : virExecWithHook:717 : /sbin/iptables --table filter --insert INPUT --in-interface virbr0 --protocol udp --destination-port 67 --jump ACCEPT
15:06:13.936: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1605
15:06:14.007: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.007: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table mangle --insert POSTROUTING --out-interface virbr0 --protocol udp --destination-port 68 --jump CHECKSUM --checksum-fill
15:06:14.007: 1549: debug : virExecWithHook:717 : /sbin/iptables --table mangle --insert POSTROUTING --out-interface virbr0 --protocol udp --destination-port 68 --jump CHECKSUM --checksum-fill
15:06:14.007: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1607
15:06:14.045: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.045: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table filter --insert INPUT --in-interface virbr0 --protocol tcp --destination-port 53 --jump ACCEPT
15:06:14.045: 1549: debug : virExecWithHook:717 : /sbin/iptables --table filter --insert INPUT --in-interface virbr0 --protocol tcp --destination-port 53 --jump ACCEPT
15:06:14.045: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1615
15:06:14.051: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.051: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table filter --insert INPUT --in-interface virbr0 --protocol udp --destination-port 53 --jump ACCEPT
15:06:14.051: 1549: debug : virExecWithHook:717 : /sbin/iptables --table filter --insert INPUT --in-interface virbr0 --protocol udp --destination-port 53 --jump ACCEPT
15:06:14.051: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1616
15:06:14.061: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.061: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table filter --insert FORWARD --in-interface virbr0 --jump REJECT
15:06:14.061: 1549: debug : virExecWithHook:717 : /sbin/iptables --table filter --insert FORWARD --in-interface virbr0 --jump REJECT
15:06:14.062: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1617
15:06:14.118: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.119: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table filter --insert FORWARD --out-interface virbr0 --jump REJECT
15:06:14.119: 1549: debug : virExecWithHook:717 : /sbin/iptables --table filter --insert FORWARD --out-interface virbr0 --jump REJECT
15:06:14.119: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1620
15:06:14.121: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.121: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table filter --insert FORWARD --in-interface virbr0 --out-interface virbr0 --jump ACCEPT
15:06:14.121: 1549: debug : virExecWithHook:717 : /sbin/iptables --table filter --insert FORWARD --in-interface virbr0 --out-interface virbr0 --jump ACCEPT
15:06:14.121: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1621
15:06:14.122: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.122: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table filter --insert FORWARD --source 192.168.122.0/24 --in-interface virbr0 --jump ACCEPT
15:06:14.122: 1549: debug : virExecWithHook:717 : /sbin/iptables --table filter --insert FORWARD --source 192.168.122.0/24 --in-interface virbr0 --jump ACCEPT
15:06:14.123: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1622
15:06:14.124: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.124: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table filter --insert FORWARD --destination 192.168.122.0/24 --out-interface virbr0 --match state --state ESTABLISHED,RELATED --jump ACCEPT
15:06:14.124: 1549: debug : virExecWithHook:717 : /sbin/iptables --table filter --insert FORWARD --destination 192.168.122.0/24 --out-interface virbr0 --match state --state ESTABLISHED,RELATED --jump ACCEPT
15:06:14.124: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1623
15:06:14.524: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.524: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table nat --insert POSTROUTING --source 192.168.122.0/24 ! --destination 192.168.122.0/24 --jump MASQUERADE
15:06:14.524: 1549: debug : virExecWithHook:717 : /sbin/iptables --table nat --insert POSTROUTING --source 192.168.122.0/24 ! --destination 192.168.122.0/24 --jump MASQUERADE
15:06:14.524: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1628
15:06:14.822: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.822: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table nat --insert POSTROUTING --source 192.168.122.0/24 -p udp ! --destination 192.168.122.0/24 --jump MASQUERADE --to-ports 1024-65535
15:06:14.822: 1549: debug : virExecWithHook:717 : /sbin/iptables --table nat --insert POSTROUTING --source 192.168.122.0/24 -p udp ! --destination 192.168.122.0/24 --jump MASQUERADE --to-ports 1024-65535
15:06:14.823: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1633
15:06:14.824: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.824: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/iptables --table nat --insert POSTROUTING --source 192.168.122.0/24 -p tcp ! --destination 192.168.122.0/24 --jump MASQUERADE --to-ports 1024-65535
15:06:14.824: 1549: debug : virExecWithHook:717 : /sbin/iptables --table nat --insert POSTROUTING --source 192.168.122.0/24 -p tcp ! --destination 192.168.122.0/24 --jump MASQUERADE --to-ports 1024-65535
15:06:14.825: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1634
15:06:14.826: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.826: 1549: debug : virCommandRunAsync:1148 : About to run /sbin/ip addr add 192.168.122.1/24 broadcast 192.168.122.255 dev virbr0
15:06:14.826: 1549: debug : virExecWithHook:717 : /sbin/ip addr add 192.168.122.1/24 broadcast 192.168.122.255 dev virbr0
15:06:14.826: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1635
15:06:14.827: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.827: 1549: debug : virCommandRunAsync:1148 : About to run /usr/sbin/dnsmasq --strict-order --bind-interfaces --pid-file=/var/run/libvirt/network/default.pid --conf-file=  --listen-address 192.168.122.1 --except-interface lo --dhcp-range 192.168.122.2,192.168.122.254 --dhcp-lease-max=253 --dhcp-no-override
15:06:14.827: 1549: debug : virExecWithHook:717 : /usr/sbin/dnsmasq --strict-order --bind-interfaces --pid-file=/var/run/libvirt/network/default.pid --conf-file=  --listen-address 192.168.122.1 --except-interface lo --dhcp-range 192.168.122.2,192.168.122.254 --dhcp-lease-max=253 --dhcp-no-override
15:06:14.828: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1636
15:06:14.898: 1549: debug : virCommandRun:1049 : Result stdout: '' stderr: ''
15:06:14.945: 1549: debug : virRunWithHook:825 : /tmp/virtdZJVkdV
15:06:15.250: 1549: debug : virRunWithHook:825 : /tmp/virtduiqHOC
15:06:15.261: 1549: debug : virRunWithHook:825 : /tmp/virtdLIEVrk
15:06:15.373: 1549: debug : virCommandRunAsync:1148 : About to run /usr/sbin/dmidecode -q -t 0,1
15:06:15.373: 1549: debug : virExecWithHook:717 : /usr/sbin/dmidecode -q -t 0,1
15:06:15.374: 1549: debug : virCommandRunAsync:1164 : Command result 0, with PID 1745
15:06:15.416: 1549: debug : virCommandRun:1049 : Result stdout: 'BIOS Information
	Vendor: Bochs
	Version: Bochs
	Release Date: 01/01/2007
	Address: 0xE8000
	Runtime Size: 96 kB
	ROM Size: 64 kB
	Characteristics:
		BIOS characteristics not supported
		Targeted content distribution is supported
	BIOS Revision: 1.0

System Information
	Manufacturer: Bochs
	Product Name: Bochs
	Version: Not Specified
	Serial Number: Not Specified
	UUID: CC9EAC8F-9990-3E52-ACC5-CCF1F81BE879
	Wake-up Type: Power Switch
	SKU Number: Not Specified
	Family: Not Specified

' stderr: ''
15:06:15.448: 1549: debug : virCgroupNew:555 : New group /
15:06:15.448: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 0:cpu at /cgroup/cpu in 
15:06:15.448: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 1:cpuacct at /cgroup/cpuacct in 
15:06:15.448: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 2:cpuset at /cgroup/cpuset in 
15:06:15.448: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 3:memory at /cgroup/memory in 
15:06:15.448: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 4:devices at /cgroup/devices in 
15:06:15.449: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 5:freezer at /cgroup/freezer in 
15:06:15.449: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 6:blkio at /cgroup/blkio in 
15:06:15.449: 1549: debug : virCgroupNew:555 : New group /libvirt
15:06:15.449: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 0:cpu at /cgroup/cpu in 
15:06:15.449: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 1:cpuacct at /cgroup/cpuacct in 
15:06:15.449: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 2:cpuset at /cgroup/cpuset in 
15:06:15.449: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 3:memory at /cgroup/memory in 
15:06:15.449: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 4:devices at /cgroup/devices in 
15:06:15.449: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 5:freezer at /cgroup/freezer in 
15:06:15.449: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 6:blkio at /cgroup/blkio in 
15:06:15.449: 1549: debug : virCgroupMakeGroup:497 : Make group /libvirt
15:06:15.449: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpu/libvirt/
15:06:15.449: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpuacct/libvirt/
15:06:15.449: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpuset/libvirt/
15:06:15.449: 1549: debug : virCgroupCpuSetInherit:431 : Setting up inheritance / -> /libvirt
15:06:15.449: 1549: debug : virCgroupGetValueStr:320 : Get value /cgroup/cpuset/cpuset.cpus
15:06:15.449: 1549: debug : virCgroupCpuSetInherit:444 : Inherit cpuset.cpus = 0
15:06:15.449: 1549: debug : virCgroupSetValueStr:290 : Set value '/cgroup/cpuset/libvirt/cpuset.cpus' to '0'
15:06:15.450: 1549: debug : virCgroupGetValueStr:320 : Get value /cgroup/cpuset/cpuset.mems
15:06:15.450: 1549: debug : virCgroupCpuSetInherit:444 : Inherit cpuset.mems = 0
15:06:15.450: 1549: debug : virCgroupSetValueStr:290 : Set value '/cgroup/cpuset/libvirt/cpuset.mems' to '0'
15:06:15.450: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/memory/libvirt/
15:06:15.450: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/devices/libvirt/
15:06:15.450: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/freezer/libvirt/
15:06:15.450: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/blkio/libvirt/
15:06:15.450: 1549: debug : virCgroupNew:555 : New group /libvirt/qemu
15:06:15.450: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 0:cpu at /cgroup/cpu in 
15:06:15.451: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 1:cpuacct at /cgroup/cpuacct in 
15:06:15.451: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 2:cpuset at /cgroup/cpuset in 
15:06:15.451: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 3:memory at /cgroup/memory in 
15:06:15.451: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 4:devices at /cgroup/devices in 
15:06:15.451: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 5:freezer at /cgroup/freezer in 
15:06:15.451: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 6:blkio at /cgroup/blkio in 
15:06:15.451: 1549: debug : virCgroupMakeGroup:497 : Make group /libvirt/qemu
15:06:15.451: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpu/libvirt/qemu/
15:06:15.451: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpuacct/libvirt/qemu/
15:06:15.451: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpuset/libvirt/qemu/
15:06:15.451: 1549: debug : virCgroupCpuSetInherit:431 : Setting up inheritance /libvirt -> /libvirt/qemu
15:06:15.451: 1549: debug : virCgroupGetValueStr:320 : Get value /cgroup/cpuset/libvirt/cpuset.cpus
15:06:15.451: 1549: debug : virCgroupCpuSetInherit:444 : Inherit cpuset.cpus = 0
15:06:15.451: 1549: debug : virCgroupSetValueStr:290 : Set value '/cgroup/cpuset/libvirt/qemu/cpuset.cpus' to '0'
15:06:15.451: 1549: debug : virCgroupGetValueStr:320 : Get value /cgroup/cpuset/libvirt/cpuset.mems
15:06:15.451: 1549: debug : virCgroupCpuSetInherit:444 : Inherit cpuset.mems = 0
15:06:15.451: 1549: debug : virCgroupSetValueStr:290 : Set value '/cgroup/cpuset/libvirt/qemu/cpuset.mems' to '0'
15:06:15.451: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/memory/libvirt/qemu/
15:06:15.451: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/devices/libvirt/qemu/
15:06:15.451: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/freezer/libvirt/qemu/
15:06:15.451: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/blkio/libvirt/qemu/
15:06:15.485: 1549: info : qemudLoadDriverConfig:312 : Configured cgroup controller 'cpu'
15:06:15.485: 1549: info : qemudLoadDriverConfig:312 : Configured cgroup controller 'memory'
15:06:15.485: 1549: info : qemudLoadDriverConfig:312 : Configured cgroup controller 'devices'
15:06:15.485: 1549: info : qemudLoadDriverConfig:312 : Configured cgroup controller 'blkio'
15:06:15.513: 1549: info : qemudSecurityInit:1415 : No security driver available
15:06:15.518: 1549: debug : virConnectOpen:1472 : name=qemu:///system
15:06:15.518: 1549: debug : do_open:1250 : name "qemu:///system" to URI components:
  scheme qemu
  opaque (null)
  authority (null)
  server (null)
  user (null)
  port 0
  path /system

15:06:15.518: 1549: debug : do_open:1289 : trying driver 0 (Test) ...
15:06:15.518: 1549: debug : do_open:1295 : driver 0 Test returned DECLINED
15:06:15.518: 1549: debug : do_open:1289 : trying driver 1 (ESX) ...
15:06:15.518: 1549: debug : do_open:1295 : driver 1 ESX returned DECLINED
15:06:15.518: 1549: debug : do_open:1289 : trying driver 2 (remote) ...
15:06:15.518: 1549: debug : do_open:1295 : driver 2 remote returned DECLINED
15:06:15.518: 1549: debug : do_open:1289 : trying driver 3 (QEMU) ...
15:06:15.518: 1549: debug : do_open:1295 : driver 3 QEMU returned SUCCESS
15:06:15.518: 1549: debug : do_open:1315 : network driver 0 Test returned DECLINED
15:06:15.518: 1549: debug : do_open:1315 : network driver 1 ESX returned DECLINED
15:06:15.518: 1549: debug : do_open:1315 : network driver 2 remote returned DECLINED
15:06:15.518: 1549: debug : do_open:1315 : network driver 3 Network returned SUCCESS
15:06:15.518: 1549: debug : do_open:1334 : interface driver 0 Test returned DECLINED
15:06:15.518: 1549: debug : do_open:1334 : interface driver 1 ESX returned DECLINED
15:06:15.518: 1549: debug : do_open:1334 : interface driver 2 remote returned DECLINED
15:06:15.600: 1549: debug : do_open:1334 : interface driver 3 Interface returned SUCCESS
15:06:15.600: 1549: debug : do_open:1354 : storage driver 0 Test returned DECLINED
15:06:15.600: 1549: debug : do_open:1354 : storage driver 1 ESX returned DECLINED
15:06:15.600: 1549: debug : do_open:1354 : storage driver 2 remote returned DECLINED
15:06:15.600: 1549: debug : do_open:1354 : storage driver 3 storage returned SUCCESS
15:06:15.600: 1549: debug : do_open:1374 : node driver 0 Test returned DECLINED
15:06:15.600: 1549: debug : do_open:1374 : node driver 1 ESX returned DECLINED
15:06:15.600: 1549: debug : do_open:1374 : node driver 2 remote returned DECLINED
15:06:15.600: 1549: debug : do_open:1374 : node driver 3 udevDeviceMonitor returned SUCCESS
15:06:15.600: 1549: debug : do_open:1401 : secret driver 0 Test returned DECLINED
15:06:15.600: 1549: debug : do_open:1401 : secret driver 1 ESX returned DECLINED
15:06:15.600: 1549: debug : do_open:1401 : secret driver 2 remote returned DECLINED
15:06:15.600: 1549: debug : do_open:1401 : secret driver 3 secret returned SUCCESS
15:06:15.600: 1549: debug : do_open:1421 : nwfilter driver 0 Test returned DECLINED
15:06:15.600: 1549: debug : do_open:1421 : nwfilter driver 1 ESX returned DECLINED
15:06:15.600: 1549: debug : do_open:1421 : nwfilter driver 2 remote returned DECLINED
15:06:15.600: 1549: debug : do_open:1421 : nwfilter driver 3 nwfilter returned SUCCESS
15:06:15.600: 1549: debug : virConnectOpen:1472 : name=qemu:///system
15:06:15.600: 1549: debug : do_open:1250 : name "qemu:///system" to URI components:
  scheme qemu
  opaque (null)
  authority (null)
  server (null)
  user (null)
  port 0
  path /system

15:06:15.600: 1549: debug : do_open:1289 : trying driver 0 (Test) ...
15:06:15.600: 1549: debug : do_open:1295 : driver 0 Test returned DECLINED
15:06:15.601: 1549: debug : do_open:1289 : trying driver 1 (ESX) ...
15:06:15.601: 1549: debug : do_open:1295 : driver 1 ESX returned DECLINED
15:06:15.601: 1549: debug : do_open:1289 : trying driver 2 (remote) ...
15:06:15.601: 1549: debug : do_open:1295 : driver 2 remote returned DECLINED
15:06:15.601: 1549: debug : do_open:1289 : trying driver 3 (QEMU) ...
15:06:15.601: 1549: debug : do_open:1295 : driver 3 QEMU returned SUCCESS
15:06:15.601: 1549: debug : do_open:1315 : network driver 0 Test returned DECLINED
15:06:15.601: 1549: debug : do_open:1315 : network driver 1 ESX returned DECLINED
15:06:15.601: 1549: debug : do_open:1315 : network driver 2 remote returned DECLINED
15:06:15.601: 1549: debug : do_open:1315 : network driver 3 Network returned SUCCESS
15:06:15.601: 1549: debug : do_open:1334 : interface driver 0 Test returned DECLINED
15:06:15.601: 1549: debug : do_open:1334 : interface driver 1 ESX returned DECLINED
15:06:15.601: 1549: debug : do_open:1334 : interface driver 2 remote returned DECLINED
15:06:15.606: 1549: debug : do_open:1334 : interface driver 3 Interface returned SUCCESS
15:06:15.606: 1549: debug : do_open:1354 : storage driver 0 Test returned DECLINED
15:06:15.606: 1549: debug : do_open:1354 : storage driver 1 ESX returned DECLINED
15:06:15.606: 1549: debug : do_open:1354 : storage driver 2 remote returned DECLINED
15:06:15.606: 1549: debug : do_open:1354 : storage driver 3 storage returned SUCCESS
15:06:15.606: 1549: debug : do_open:1374 : node driver 0 Test returned DECLINED
15:06:15.606: 1549: debug : do_open:1374 : node driver 1 ESX returned DECLINED
15:06:15.606: 1549: debug : do_open:1374 : node driver 2 remote returned DECLINED
15:06:15.606: 1549: debug : do_open:1374 : node driver 3 udevDeviceMonitor returned SUCCESS
15:06:15.606: 1549: debug : do_open:1401 : secret driver 0 Test returned DECLINED
15:06:15.606: 1549: debug : do_open:1401 : secret driver 1 ESX returned DECLINED
15:06:15.606: 1549: debug : do_open:1401 : secret driver 2 remote returned DECLINED
15:06:15.606: 1549: debug : do_open:1401 : secret driver 3 secret returned SUCCESS
15:06:15.606: 1549: debug : do_open:1421 : nwfilter driver 0 Test returned DECLINED
15:06:15.606: 1549: debug : do_open:1421 : nwfilter driver 1 ESX returned DECLINED
15:06:15.606: 1549: debug : do_open:1421 : nwfilter driver 2 remote returned DECLINED
15:06:15.606: 1549: debug : do_open:1421 : nwfilter driver 3 nwfilter returned SUCCESS
15:06:15.606: 1549: debug : virConnectClose:1570 : conn=0x125b170
15:06:15.607: 1549: debug : virConnectClose:1570 : conn=0x1110670
15:06:15.609: 1549: debug : virRunWithHook:825 : ip link set lo netns -1
15:06:15.621: 1549: debug : virRunWithHook:843 : Command stderr: RTNETLINK answers: No such process

15:06:15.627: 1549: debug : virCgroupNew:555 : New group /
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 0:cpu at /cgroup/cpu in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 1:cpuacct at /cgroup/cpuacct in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 2:cpuset at /cgroup/cpuset in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 3:memory at /cgroup/memory in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 4:devices at /cgroup/devices in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 5:freezer at /cgroup/freezer in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 6:blkio at /cgroup/blkio in 
15:06:15.627: 1549: debug : virCgroupNew:555 : New group /libvirt
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 0:cpu at /cgroup/cpu in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 1:cpuacct at /cgroup/cpuacct in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 2:cpuset at /cgroup/cpuset in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 3:memory at /cgroup/memory in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 4:devices at /cgroup/devices in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 5:freezer at /cgroup/freezer in 
15:06:15.627: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 6:blkio at /cgroup/blkio in 
15:06:15.627: 1549: debug : virCgroupMakeGroup:497 : Make group /libvirt
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpu/libvirt/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpuacct/libvirt/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpuset/libvirt/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/memory/libvirt/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/devices/libvirt/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/freezer/libvirt/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/blkio/libvirt/
15:06:15.628: 1549: debug : virCgroupNew:555 : New group /libvirt/lxc
15:06:15.628: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 0:cpu at /cgroup/cpu in 
15:06:15.628: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 1:cpuacct at /cgroup/cpuacct in 
15:06:15.628: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 2:cpuset at /cgroup/cpuset in 
15:06:15.628: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 3:memory at /cgroup/memory in 
15:06:15.628: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 4:devices at /cgroup/devices in 
15:06:15.628: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 5:freezer at /cgroup/freezer in 
15:06:15.628: 1549: debug : virCgroupDetect:245 : Detected mount/mapping 6:blkio at /cgroup/blkio in 
15:06:15.628: 1549: debug : virCgroupMakeGroup:497 : Make group /libvirt/lxc
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpu/libvirt/lxc/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpuacct/libvirt/lxc/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/cpuset/libvirt/lxc/
15:06:15.628: 1549: debug : virCgroupCpuSetInherit:431 : Setting up inheritance /libvirt -> /libvirt/lxc
15:06:15.628: 1549: debug : virCgroupGetValueStr:320 : Get value /cgroup/cpuset/libvirt/cpuset.cpus
15:06:15.628: 1549: debug : virCgroupCpuSetInherit:444 : Inherit cpuset.cpus = 0
15:06:15.628: 1549: debug : virCgroupSetValueStr:290 : Set value '/cgroup/cpuset/libvirt/lxc/cpuset.cpus' to '0'
15:06:15.628: 1549: debug : virCgroupGetValueStr:320 : Get value /cgroup/cpuset/libvirt/cpuset.mems
15:06:15.628: 1549: debug : virCgroupCpuSetInherit:444 : Inherit cpuset.mems = 0
15:06:15.628: 1549: debug : virCgroupSetValueStr:290 : Set value '/cgroup/cpuset/libvirt/lxc/cpuset.mems' to '0'
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/memory/libvirt/lxc/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/devices/libvirt/lxc/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/freezer/libvirt/lxc/
15:06:15.628: 1549: debug : virCgroupMakeGroup:509 : Make controller /cgroup/blkio/libvirt/lxc/
15:06:15.629: 1549: debug : virConnectOpen:1472 : name=lxc:///
15:06:15.629: 1549: debug : do_open:1250 : name "lxc:///" to URI components:
  scheme lxc
  opaque (null)
  authority (null)
  server (null)
  user (null)
  port 0
  path /

15:06:15.629: 1549: debug : do_open:1289 : trying driver 0 (Test) ...
15:06:15.629: 1549: debug : do_open:1295 : driver 0 Test returned DECLINED
15:06:15.629: 1549: debug : do_open:1289 : trying driver 1 (ESX) ...
15:06:15.629: 1549: debug : do_open:1295 : driver 1 ESX returned DECLINED
15:06:15.629: 1549: debug : do_open:1289 : trying driver 2 (remote) ...
15:06:15.629: 1549: debug : do_open:1295 : driver 2 remote returned DECLINED
15:06:15.629: 1549: debug : do_open:1289 : trying driver 3 (QEMU) ...
15:06:15.629: 1549: debug : do_open:1295 : driver 3 QEMU returned DECLINED
15:06:15.629: 1549: debug : do_open:1289 : trying driver 4 (LXC) ...
15:06:15.629: 1549: debug : do_open:1295 : driver 4 LXC returned SUCCESS
15:06:15.629: 1549: debug : do_open:1315 : network driver 0 Test returned DECLINED
15:06:15.629: 1549: debug : do_open:1315 : network driver 1 ESX returned DECLINED
15:06:15.629: 1549: debug : do_open:1315 : network driver 2 remote returned DECLINED
15:06:15.629: 1549: debug : do_open:1315 : network driver 3 Network returned SUCCESS
15:06:15.629: 1549: debug : do_open:1334 : interface driver 0 Test returned DECLINED
15:06:15.629: 1549: debug : do_open:1334 : interface driver 1 ESX returned DECLINED
15:06:15.629: 1549: debug : do_open:1334 : interface driver 2 remote returned DECLINED
15:06:15.633: 1549: debug : do_open:1334 : interface driver 3 Interface returned SUCCESS
15:06:15.633: 1549: debug : do_open:1354 : storage driver 0 Test returned DECLINED
15:06:15.633: 1549: debug : do_open:1354 : storage driver 1 ESX returned DECLINED
15:06:15.633: 1549: debug : do_open:1354 : storage driver 2 remote returned DECLINED
15:06:15.633: 1549: debug : do_open:1354 : storage driver 3 storage returned SUCCESS
15:06:15.633: 1549: debug : do_open:1374 : node driver 0 Test returned DECLINED
15:06:15.633: 1549: debug : do_open:1374 : node driver 1 ESX returned DECLINED
15:06:15.633: 1549: debug : do_open:1374 : node driver 2 remote returned DECLINED
15:06:15.633: 1549: debug : do_open:1374 : node driver 3 udevDeviceMonitor returned SUCCESS
15:06:15.633: 1549: debug : do_open:1401 : secret driver 0 Test returned DECLINED
15:06:15.633: 1549: debug : do_open:1401 : secret driver 1 ESX returned DECLINED
15:06:15.633: 1549: debug : do_open:1401 : secret driver 2 remote returned DECLINED
15:06:15.633: 1549: debug : do_open:1401 : secret driver 3 secret returned SUCCESS
15:06:15.633: 1549: debug : do_open:1421 : nwfilter driver 0 Test returned DECLINED
15:06:15.633: 1549: debug : do_open:1421 : nwfilter driver 1 ESX returned DECLINED
15:06:15.633: 1549: debug : do_open:1421 : nwfilter driver 2 remote returned DECLINED
15:06:15.633: 1549: debug : do_open:1421 : nwfilter driver 3 nwfilter returned SUCCESS
15:06:15.633: 1549: debug : virConnectClose:1570 : conn=0x1110670

Comment 4 Daniel Berrangé 2011-02-22 14:13:02 UTC

This log doesn't show any signs of you having attempted migration. This is merely showing the steps libvirtd takes at initial daemon startup. Are you sure this log corresponds to the machine which was the migration target host ?

Comment 5 Erez Shinan 2011-02-22 14:21:05 UTC

I'm sorry. Let me give it another go.

10:45:46.415: 1487: debug : qemudDispatchServer:1324 : CLIENT_CONNECT: fd=25, readonly=0 localAddr=0.0.0.0;16509 remoteAddr=10.35.1.67;55649
10:45:46.417: 1490: debug : virConnectOpen:1472 : name=qemu:///system
10:45:46.417: 1490: debug : do_open:1250 : name "qemu:///system" to URI components:
  scheme qemu
  opaque (null)
  authority (null)
  server (null)
  user (null)
  port 0
  path /system

10:45:46.417: 1490: debug : do_open:1289 : trying driver 0 (Test) ...
10:45:46.417: 1490: debug : do_open:1295 : driver 0 Test returned DECLINED
10:45:46.417: 1490: debug : do_open:1289 : trying driver 1 (ESX) ...
10:45:46.417: 1490: debug : do_open:1295 : driver 1 ESX returned DECLINED
10:45:46.417: 1490: debug : do_open:1289 : trying driver 2 (remote) ...
10:45:46.417: 1490: debug : do_open:1295 : driver 2 remote returned DECLINED
10:45:46.417: 1490: debug : do_open:1289 : trying driver 3 (QEMU) ...
10:45:46.417: 1490: debug : do_open:1295 : driver 3 QEMU returned SUCCESS
10:45:46.417: 1490: debug : do_open:1315 : network driver 0 Test returned DECLINED
10:45:46.417: 1490: debug : do_open:1315 : network driver 1 ESX returned DECLINED
10:45:46.417: 1490: debug : do_open:1315 : network driver 2 remote returned DECLINED
10:45:46.417: 1490: debug : do_open:1315 : network driver 3 Network returned SUCCESS
10:45:46.417: 1490: debug : do_open:1334 : interface driver 0 Test returned DECLINED
10:45:46.417: 1490: debug : do_open:1334 : interface driver 1 ESX returned DECLINED
10:45:46.417: 1490: debug : do_open:1334 : interface driver 2 remote returned DECLINED
10:45:46.597: 1490: debug : do_open:1334 : interface driver 3 Interface returned ERROR
10:45:46.597: 1490: debug : do_open:1354 : storage driver 0 Test returned DECLINED
10:45:46.597: 1490: debug : do_open:1354 : storage driver 1 ESX returned DECLINED
10:45:46.597: 1490: debug : do_open:1354 : storage driver 2 remote returned DECLINED
10:45:46.597: 1490: debug : do_open:1354 : storage driver 3 storage returned SUCCESS
10:45:46.597: 1490: debug : do_open:1374 : node driver 0 Test returned DECLINED
10:45:46.597: 1490: debug : do_open:1374 : node driver 1 ESX returned DECLINED
10:45:46.597: 1490: debug : do_open:1374 : node driver 2 remote returned DECLINED
10:45:46.597: 1490: debug : do_open:1374 : node driver 3 udevDeviceMonitor returned SUCCESS
10:45:46.597: 1490: debug : do_open:1401 : secret driver 0 Test returned DECLINED
10:45:46.597: 1490: debug : do_open:1401 : secret driver 1 ESX returned DECLINED
10:45:46.597: 1490: debug : do_open:1401 : secret driver 2 remote returned DECLINED
10:45:46.597: 1490: debug : do_open:1401 : secret driver 3 secret returned SUCCESS
10:45:46.597: 1490: debug : do_open:1421 : nwfilter driver 0 Test returned DECLINED
10:45:46.597: 1490: debug : do_open:1421 : nwfilter driver 1 ESX returned DECLINED
10:45:46.597: 1490: debug : do_open:1421 : nwfilter driver 2 remote returned DECLINED
10:45:46.597: 1490: debug : do_open:1421 : nwfilter driver 3 nwfilter returned SUCCESS
10:45:46.884: 1488: debug : virDrvSupportsFeature:1629 : conn=0x7f28e009e540, feature=4
10:45:46.886: 1491: debug : virDomainMigratePrepare2:4084 : dconn=0x7f28e009e540, cookie=0x7f28eddefaf0, cookielen=0x7f28eddefafc, uri_in=(null), uri_out=0x7f28e4011c80,flags=2, dname=(null), bandwidth=0, dom_xml=<domain type='kvm' id='1'>
  <name>ayal</name>
  <uuid>9ffe28b6-6134-4b1e-8804-1185f49c436f</uuid>
  <memory>20480</memory>
  <currentMemory>20480</currentMemory>
  <vcpu>1</vcpu>
  <sysinfo type='smbios'>
    <system>
      <entry name='manufacturer'>Red Hat</entry>
      <entry name='product'>RHEL</entry>
      <entry name='version'>6Server-6.0.0.37.el6</entry>
      <entry name='serial'>553773D4-199C-7AA9-11BD-905F455409A8_52:54:00:0b:44:bb</entry>
      <entry name='uuid'>9ffe28b6-6134-4b1e-8804-1185f49c436f</entry>
    </system>
  </sysinfo>
  <os>
    <type arch='x86_64' machine='rhel6.0.0'>hvm</type>
    <boot dev='hd'/>
  </os>
  <clock offset='variable' adjustment='0'/>
  <on_poweroff>destroy</on_poweroff>
  <on_reboot>restart</on_reboot>
  <on_crash>destroy</on_crash>
  <devices>
    <emulator>/usr/bin/qemu-system-x86_64</emulator>
    <disk type='file' device='cdrom'>
      <driver name='qemu' type='raw'/>
      <target dev='hdc' bus='ide'/>
      <readonly/>
      <alias name='ide0-1-0'/>
      <address type='drive' controller='0' bus='1' unit='0'/>
    </disk>
    <controller type='virtio-serial' index='0' ports='16'>
      <alias name='virtio-serial0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>
    </controller>
    <controller type='ide' index='0'>
      <alias name='ide0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x1'/>
    </controller>
    <interface type='bridge'>
      <mac address='aa:bb:dd:dd:aa:bb'/>
      <source bridge='virbr0'/>
      <target dev='vnet0'/>
      <model type='virtio'/>
      <alias name='net0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>
    </interface>
    <channel type='unix'>
      <source mode='bind' path='/var/lib/libvirt/qemu/channels/ayal.com.redhat.rhevm.vdsm'/>
      <target type='virtio' name='com.redhat.rhevm.vdsm'/>
      <alias name='channel0'/>
      <address type='virtio-serial' controller='0' bus='0' port='1'/>
    </channel>
    <input type='mouse' bus='ps2'/>
    <graphics type='vnc' port='5900' autoport='yes' listen='0' passwd='*****'/>
    <video>
      <model type='cirrus' vram='9216' heads='1'/>
      <alias name='video0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>
    </video>
    <memballoon model='none'>
      <alias name='balloon0'/>
    </memballoon>
  </devices>
</domain>

10:45:46.886: 1491: debug : qemudDomainMigratePrepare2:8776 : Generated uri_out=tcp:vm-18-101.eng.lab.tlv.redhat.com:49158
10:45:46.888: 1487: debug : qemudDispatchClientFailure:1527 : CLIENT_DISCONNECT: fd=25
10:45:46.888: 1487: debug : virConnectClose:1570 : conn=0x7f28e009e540

Comment 6 Jiri Denemark 2011-03-01 16:52:51 UTC

So the problem was that the target machine was not able to run any guests. And any helpful error message was overwritten with a useless "failed to parse xml" one. This was fixed upstream as part of

commit 766de43533b7ae2406804e92e83e3ad67df6495d
Author: Daniel P. Berrange <berrange>
Date:   Mon Jan 31 10:47:03 2011 +0000

    Move all the QEMU migration code to a new file

So the few relevant parts of it need to be backported to RHEL libvirt.

After solving that, there are still some issues but they are either config/envirotnment issues which we will get back to tomorrow.

Comment 7 Eric Blake 2011-03-01 17:03:53 UTC

See also this upstream conversation:
https://www.redhat.com/archives/libvir-list/2011-January/msg01280.html
https://www.redhat.com/archives/libvir-list/2011-February/msg00354.html

It seems like it would be pretty trivial to backport just the deletion of the error message that overwrites the error.

Comment 8 Eric Blake 2011-03-01 17:25:33 UTC

In POST:
http://post-office.corp.redhat.com/archives/rhvirt-patches/2011-March/msg00011.html

Comment 11 Vivian Bian 2011-03-09 08:30:47 UTC

Hi Erez , 
To check this bug , I have following questions to ask here :
1. from the xml provided above , the emulator is qemu-system-x86_64 
       <emulator>/usr/bin/qemu-system-x86_64</emulator>

Is it fine to modify it to /usr/libexec/qemu-kvm , if not , please provide the url to download qemu-system-x86_64 for RHEL6.1

2. from the xml there is the following channel defination , which mentions vdsm and rhevm 
   <channel type='unix'>
      <source mode='bind'
path='/var/lib/libvirt/qemu/channels/ayal.com.redhat.rhevm.vdsm'/>
      <target type='virtio' name='com.redhat.rhevm.vdsm'/>
      <alias name='channel0'/>
      <address type='virtio-serial' controller='0' bus='0' port='1'/>
    </channel>

According to this , would you please list the requested xml sections here (a complete xml is required to reproduce this bug).

3. Since, on a scratch installed RHEL6.1 , we may not have the rhevm and vdsm environment set . I wonder if it could be reproduced without vdsm . 

4. From the XML provided, there is no guest os image section . So I wonder if the guest could be started even on the source machine .

Comment 12 Erez Shinan 2011-03-10 13:02:36 UTC

Hi Vivian,
1. I don't know. Try it, and see.
2. I provided you with the complete xml. There are no sections for rhevm or vdsm
3. rhevm and vdsm are not required to reproduce this bug
4. What do you mean? You need two hosts to perform migration. You also need a running vm on the source machine, but it doesn't need to start from an image. That's all you need.

Comment 13 Jiri Denemark 2011-03-11 07:01:26 UTC

One way (not the only one, though) to test this is:
On the target machine
1. stop libvirtd service
2. disable kvm by removing kvm, kvm_intel modules
3. start libvirtd service
4. you can verify that virsh capabilities doesn't contain any <guest> element

Try to migrate a running domain from source to target machine.

When the bug is present, migration fails "failed to parse XML" error. With this bug fixed libvirt gives much better error: "unknown OS type hvm" which is enough to reveal that the target host was misconfigured.

Comment 14 Vivian Bian 2011-03-11 07:08:05 UTC

checked with libvirt-0.8.7-10.el6.x86_64 PASSED 

[on source machine]
# virsh start guest 
#  LIBVIRT_DEBUG=1 LIBVIRT_LOG_FILTERS="1:util 1:libvirt 1:qemu 1:remote"
virsh -c qemu+tcp://10.35.1.67/system migrate ayal qemu+tcp://10.35.1.66/system
--p2p > result.log 2>&1

[on target machine]
1. stop libvirtd service
2. disable kvm by removing kvm, kvm_intel modules
3. start libvirtd service


with the buggy libvirt-0.8.7-7.el6, could see "failed to parse XML" error in result.log 

with the bug fixed libvirt-0.8.7-10.el6, got "unknow OS type hvm" in result.log 

So set bug status to VERIFIED .

Comment 17 errata-xmlrpc 2011-05-19 13:28:03 UTC

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHBA-2011-0596.html

Note You need to log in before you can comment on or make changes to this bug.