[Users] Failure to migrate from one host out of four

Thu Aug 2 12:01:51 UTC 2012

Hi,

Wondering if anyone has encountered the same issue as me. On one host in my cluster, if I migrate in a guest, I cannot migrate it out to another host?  The get "stuck" there, so to speak. Same when a guest is started on that particular host, it is impossible to migrate them out again.

iptables are flushed, for excluding purposes. vdsmd, libvirtd and sanlock are all running.

This is what I caught from libvirtd.log:
2012-08-02 11:44:07.542+0000: 4231: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=0x7fe7e40c8410 refs=3
2012-08-02 11:44:07.542+0000: 4232: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=0x7fe7e40c8410 refs=2
2012-08-02 11:44:07.542+0000: 4232: debug : virConnectIsAlive:18395 : conn=0x7fe7e00c4e50
2012-08-02 11:44:07.562+0000: 4236: debug : virDomainMigrateSetMaxDowntime:16565 : dom=0x7fe7d8000cc0, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1), downtime=50, flags=0
2012-08-02 11:44:07.562+0000: 4236: debug : qemuDomainObjBeginJobInternal:753 : Starting job: migration operation (async=migration out)
2012-08-02 11:44:07.562+0000: 4236: debug : qemuDomainMigrateSetMaxDowntime:9500 : Setting migration downtime to 50ms
2012-08-02 11:44:07.562+0000: 4236: debug : qemuMonitorRef:239 : QEMU_MONITOR_REF: mon=0x7fe7e40c8410 refs=3
2012-08-02 11:44:07.562+0000: 4236: debug : qemuMonitorSetMigrationDowntime:1753 : mon=0x7fe7e40c8410 downtime=50
2012-08-02 11:44:07.562+0000: 4236: debug : qemuMonitorSend:861 : QEMU_MONITOR_SEND_MSG: mon=0x7fe7e40c8410 msg={"execute":"migrate_set_downtime","arguments":{"value":0,050000},"id":"libvirt-261"}
 fd=-1
2012-08-02 11:44:07.563+0000: 4231: debug : qemuMonitorRef:239 : QEMU_MONITOR_REF: mon=0x7fe7e40c8410 refs=4
2012-08-02 11:44:07.563+0000: 4231: debug : qemuMonitorIOWrite:470 : QEMU_MONITOR_IO_WRITE: mon=0x7fe7e40c8410 buf={"execute":"migrate_set_downtime","arguments":{"value":0,050000},"id":"libvirt-261"}
 len=86 ret=86 errno=11
2012-08-02 11:44:07.563+0000: 4231: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=0x7fe7e40c8410 refs=3
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorRef:239 : QEMU_MONITOR_REF: mon=0x7fe7e40c8410 refs=4
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorIOProcess:365 : QEMU_MONITOR_IO_PROCESS: mon=0x7fe7e40c8410 buf={"error": {"class": "JSONParsing", "desc": "Invalid JSON syntax", "data": {}}}
 len=80
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=0x7fe7e40c8410 refs=3
2012-08-02 11:44:07.564+0000: 4236: error : qemuMonitorJSONCheckError:331 : internal error unable to execute QEMU command 'migrate_set_downtime': Invalid JSON syntax
2012-08-02 11:44:07.564+0000: 4236: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=0x7fe7e40c8410 refs=2
2012-08-02 11:44:07.564+0000: 4236: debug : qemuDomainObjEndJob:870 : Stopping job: migration operation (async=migration out)
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorRef:239 : QEMU_MONITOR_REF: mon=0x7fe7e40c8410 refs=3
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorIOProcess:365 : QEMU_MONITOR_IO_PROCESS: mon=0x7fe7e40c8410 buf={"error": {"class": "JSONParsing", "desc": "Invalid JSON syntax", "data": {}}}
 len=80
2012-08-02 11:44:07.564+0000: 4236: debug : virDomainFree:2345 : dom=0x7fe7d8000cc0, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:44:07.564+0000: 4231: error : qemuMonitorJSONIOProcessLine:156 : internal error Unexpected JSON reply '{"error": {"class": "JSONParsing", "desc": "Invalid JSON syntax", "data": {}}}'
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorIO:645 : Error on monitor internal error Unexpected JSON reply '{"error": {"class": "JSONParsing", "desc": "Invalid JSON syntax", "data": {}}}'
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=0x7fe7e40c8410 refs=2
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorIO:679 : Triggering error callback
2012-08-02 11:44:07.564+0000: 4231: debug : qemuProcessHandleMonitorError:345 : Received error on 0x7fe7e4000e50 'milli'
2012-08-02 11:44:07.592+0000: 4232: debug : qemuDomainObjBeginJobInternal:753 : Starting job: async nested (async=migration out)
2012-08-02 11:44:07.593+0000: 4232: debug : qemuMonitorRef:239 : QEMU_MONITOR_REF: mon=0x7fe7e40c8410 refs=3
2012-08-02 11:44:07.593+0000: 4232: debug : qemuMonitorGetMigrationStatus:1776 : mon=0x7fe7e40c8410
2012-08-02 11:44:07.593+0000: 4232: debug : qemuMonitorSend:851 : Attempt to send command while error is set internal error Unexpected JSON reply '{"error": {"class": "JSONParsing", "desc": "Invalid JSON syntax", "data": {}}}'
2012-08-02 11:44:07.593+0000: 4232: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=0x7fe7e40c8410 refs=2
2012-08-02 11:44:07.593+0000: 4232: debug : doPeer2PeerMigrate3:2425 : Finish3 0x7fe7e00c4e50 ret=-1
2012-08-02 11:44:08.798+0000: 4233: debug : virDomainInterfaceStats:7299 : dom=0x7fe7e40c72d0, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1), path=vnet0, stats=0x7fe803e45b10, size=64
2012-08-02 11:44:08.802+0000: 4233: debug : virDomainFree:2345 : dom=0x7fe7e40c72d0, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:44:12.564+0000: 4234: debug : virDomainGetJobInfo:16465 : dom=0x7fe7dc000e00, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1), info=0x7fe803644af0
2012-08-02 11:44:12.564+0000: 4234: debug : virDomainFree:2345 : dom=0x7fe7dc000e00, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:44:13.804+0000: 4235: debug : virDomainGetInfo:4298 : dom=0x7fe7e8001bd0, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1), info=0x7fe802e43b20
2012-08-02 11:44:13.805+0000: 4235: debug : qemudGetProcessInfo:1156 : Got status for 5448/0 user=1770 sys=1445 cpu=0 rss=185496
2012-08-02 11:44:13.805+0000: 4235: debug : virDomainFree:2345 : dom=0x7fe7e8001bd0, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:44:13.806+0000: 4238: debug : virDomainInterfaceStats:7299 : dom=0x7fe7f0002520, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1), path=vnet0, stats=0x7fe801640b10, size=64
2012-08-02 11:44:13.807+0000: 4238: debug : virDomainFree:2345 : dom=0x7fe7f0002520, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:44:16.474+0000: 4232: error : virNetClientProgramDispatchError:174 : An error occurred, but the cause is unknown
2012-08-02 11:44:16.474+0000: 4232: debug : doPeer2PeerMigrate3:2458 : Confirm3 0x7fe7e40029c0 ret=-1 vm=0x7fe7e4000e50
2012-08-02 11:44:16.474+0000: 4232: debug : qemuMigrationConfirm:3109 : driver=0x7fe7f80bd9c0, conn=0x7fe7e40029c0, vm=0x7fe7e4000e50, cookiein=(null), cookieinlen=0, flags=3, retcode=1
2012-08-02 11:44:16.474+0000: 4232: debug : qemuMigrationEatCookie:752 : cookielen=0 cookie='(null)'
2012-08-02 11:44:16.475+0000: 4232: debug : qemuProcessStartCPUs:2644 : Using lock state '(null)'
2012-08-02 11:44:16.475+0000: 4232: debug : qemuDomainObjBeginJobInternal:753 : Starting job: async nested (async=migration out)

And this is from a migration gone well:
2012-08-02 11:41:28.386+0000: 618: debug : qemuProcessStop:3872 : Shutting down VM 'milli' pid=3776 flags=1
2012-08-02 11:41:28.386+0000: 618: debug : qemuMonitorClose:797 : QEMU_MONITOR_CLOSE: mon=0x7f49dc000d50 refs=2
2012-08-02 11:41:28.386+0000: 618: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=0x7f49dc000d50 refs=1
2012-08-02 11:41:28.386+0000: 606: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=0x7f49dc000d50 refs=0
2012-08-02 11:41:28.386+0000: 606: debug : qemuMonitorFree:225 : mon=0x7f49dc000d50
2012-08-02 11:41:28.386+0000: 618: debug : qemuProcessKill:3769 : vm=milli pid=3776 flags=5
2012-08-02 11:41:28.586+0000: 618: debug : qemuDomainCleanupRun:1921 : driver=0x7f49e806f1b0, vm=milli
2012-08-02 11:41:28.586+0000: 618: debug : qemuProcessAutoDestroyRemove:4320 : vm=milli
2012-08-02 11:41:28.586+0000: 618: debug : qemuDriverCloseCallbackUnset:578 : vm=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1, cb=0x4900d0
2012-08-02 11:41:28.586+0000: 618: debug : virCgroupNew:603 : New group /libvirt/qemu/milli
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected mount/mapping 0:cpu at /sys/fs/cgroup/cpu,cpuacct in /system/libvirtd.service
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected mount/mapping 1:cpuacct at /sys/fs/cgroup/cpu,cpuacct in /system/libvirtd.service
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected mount/mapping 2:cpuset at /sys/fs/cgroup/cpuset in
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected mount/mapping 3:memory at /sys/fs/cgroup/memory in
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected mount/mapping 4:devices at /sys/fs/cgroup/devices in
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected mount/mapping 5:freezer at /sys/fs/cgroup/freezer in
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected mount/mapping 6:blkio at /sys/fs/cgroup/blkio in
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:524 : Make group /libvirt/qemu/milli
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgroup/cpuset/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgroup/memory/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgroup/devices/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgroup/freezer/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgroup/blkio/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupRemove:758 : Removing cgroup /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/milli/ and all child cgroups
2012-08-02 11:41:28.588+0000: 618: debug : virCgroupRemoveRecursively:713 : Removing cgroup /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/milli//vcpu1
2012-08-02 11:41:28.595+0000: 618: debug : virCgroupRemoveRecursively:713 : Removing cgroup /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/milli//vcpu0
2012-08-02 11:41:28.603+0000: 618: debug : virCgroupRemoveRecursively:713 : Removing cgroup /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/milli/
2012-08-02 11:41:28.611+0000: 618: debug : virCgroupRemove:758 : Removing cgroup /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/milli/ and all child cgroups
2012-08-02 11:41:28.611+0000: 618: debug : virCgroupRemove:758 : Removing cgroup /sys/fs/cgroup/cpuset/libvirt/qemu/milli/ and all child cgroups
2012-08-02 11:41:28.611+0000: 618: debug : virCgroupRemoveRecursively:713 : Removing cgroup /sys/fs/cgroup/cpuset/libvirt/qemu/milli/
2012-08-02 11:41:28.620+0000: 618: debug : virCgroupRemove:758 : Removing cgroup /sys/fs/cgroup/memory/libvirt/qemu/milli/ and all child cgroups
2012-08-02 11:41:28.620+0000: 618: debug : virCgroupRemoveRecursively:713 : Removing cgroup /sys/fs/cgroup/memory/libvirt/qemu/milli/
2012-08-02 11:41:28.633+0000: 618: debug : virCgroupRemove:758 : Removing cgroup /sys/fs/cgroup/devices/libvirt/qemu/milli/ and all child cgroups
2012-08-02 11:41:28.679+0000: 618: debug : virCgroupRemoveRecursively:713 : Removing cgroup /sys/fs/cgroup/devices/libvirt/qemu/milli/
2012-08-02 11:41:28.684+0000: 618: debug : virCgroupRemove:758 : Removing cgroup /sys/fs/cgroup/freezer/libvirt/qemu/milli/ and all child cgroups
2012-08-02 11:41:28.684+0000: 618: debug : virCgroupRemoveRecursively:713 : Removing cgroup /sys/fs/cgroup/freezer/libvirt/qemu/milli/
2012-08-02 11:41:28.689+0000: 618: debug : virCgroupRemove:758 : Removing cgroup /sys/fs/cgroup/blkio/libvirt/qemu/milli/ and all child cgroups
2012-08-02 11:41:28.689+0000: 618: debug : virCgroupRemoveRecursively:713 : Removing cgroup /sys/fs/cgroup/blkio/libvirt/qemu/milli/
2012-08-02 11:41:28.697+0000: 618: debug : virConnectClose:1496 : conn=0x7f49dc10fac0
2012-08-02 11:41:28.698+0000: 606: debug : virDomainFree:2345 : dom=0xaa0ea0, (VM: name=milli, uuid=2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:41:28.700+0000: 618: debug : qemuDomainObjEndAsyncJob:887 : Stopping async job: migration out

# rpm -qa | egrep '(vdsm|libvirt|sanlock|json)' | sort -d
json-c-0.9-4.fc17.x86_64
json-glib-0.14.2-2.fc17.x86_64
libvirt-0.9.11.4-3.fc17.x86_64
libvirt-client-0.9.11.4-3.fc17.x86_64
libvirt-daemon-0.9.11.4-3.fc17.x86_64
libvirt-daemon-config-network-0.9.11.4-3.fc17.x86_64
libvirt-daemon-config-nwfilter-0.9.11.4-3.fc17.x86_64
libvirt-lock-sanlock-0.9.11.4-3.fc17.x86_64
libvirt-python-0.9.11.4-3.fc17.x86_64
python-simplejson-2.5.2-1.fc17.x86_64
sanlock-2.3-3.fc17.x86_64
sanlock-lib-2.3-3.fc17.x86_64
sanlock-python-2.3-3.fc17.x86_64
vdsm-4.10.0-5.fc17.x86_64
vdsm-cli-4.10.0-5.fc17.noarch
vdsm-python-4.10.0-5.fc17.x86_64
vdsm-xmlrpc-4.10.0-5.fc17.noarch

Best Regards
-------------------------------------------------------------------------------
Karli Sjöberg
Swedish University of Agricultural Sciences
Box 7079 (Visiting Address Kronåsvägen 8)
S-750 07 Uppsala, Sweden
Phone:  +46-(0)18-67 15 66
karli.sjoberg at slu.se<mailto:karli.sjoberg at adm.slu.se>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/users/attachments/20120802/7ea57c18/attachment-0001.html>