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

2 Aug 2012

      ...
<div>2012-08-02 11:44:08.802+0000: 4233: debug : virDomainFree:2345 : dom=
=3D0x7fe7e40c72d0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b=
8bccc1)</div><div>2012-08-02 11:44:12.564+0000: 4234: debug : virDomainGetJ=
obInfo:16465 : dom=3D0x7fe7dc000e00, (VM: name=3Dmilli, uuid=3D2291f0d8-634=
1-4821-8774-2ed84b8bccc1), info=3D0x7fe803644af0</div><div>2012-08-02 11:44=
:12.564+0000: 4234: debug : virDomainFree:2345 : dom=3D0x7fe7dc000e00, (VM:=
 name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1)</div><div>2012-=
08-02 11:44:13.804+0000: 4235: debug : virDomainGetInfo:4298 : dom=3D0x7fe7=
e8001bd0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1), =
info=3D0x7fe802e43b20</div><div>2012-08-02 11:44:13.805+0000: 4235: debug :=
 qemudGetProcessInfo:1156 : Got status for 5448/0 user=3D1770 sys=3D1445 cp=
u=3D0 rss=3D185496</div><div>2012-08-02 11:44:13.805+0000: 4235: debug : vi=
rDomainFree:2345 : dom=3D0x7fe7e8001bd0, (VM: name=3Dmilli, uuid=3D2291f0d8=
-6341-4821-8774-2ed84b8bccc1)</div><div>2012-08-02 11:44:13.806+0000: 4238:=
 debug : virDomainInterfaceStats:7299 : dom=3D0x7fe7f0002520, (VM: name=3Dm=
illi, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1), path=3Dvnet0, stats=3D0=
x7fe801640b10, size=3D64</div><div>2012-08-02 11:44:13.807+0000: 4238: debu=
g : virDomainFree:2345 : dom=3D0x7fe7f0002520, (VM: name=3Dmilli, uuid=3D22=
91f0d8-6341-4821-8774-2ed84b8bccc1)</div><div>2012-08-02 11:44:16.474+0000:=
 4232: error : virNetClientProgramDispatchError:174 : An error occurred, bu=
t the cause is unknown</div><div>2012-08-02 11:44:16.474+0000: 4232: debug =
: doPeer2PeerMigrate3:2458 : Confirm3 0x7fe7e40029c0 ret=3D-1 vm=3D0x7fe7e4=
000e50</div><div>2012-08-02 11:44:16.474+0000: 4232: debug : qemuMigrationC=
onfirm:3109 : driver=3D0x7fe7f80bd9c0, conn=3D0x7fe7e40029c0, vm=3D0x7fe7e4=
000e50, cookiein=3D(null), cookieinlen=3D0, flags=3D3, retcode=3D1</div><di=
v>2012-08-02 11:44:16.474+0000: 4232: debug : qemuMigrationEatCookie:752 : =
cookielen=3D0 cookie=3D'(null)'</div><div>2012-08-02 11:44:16.475+0000: 423=
2: debug : qemuProcessStartCPUs:2644 : Using lock state '(null)'</div><div>=
2012-08-02 11:44:16.475+0000: 4232: debug : qemuDomainObjBeginJobInternal:7=
53 : Starting job: async nested (async=3Dmigration out)</div></div><div><br=
</div><div>And this is from a migration gone well:</div><div><div>2012-08-=
02 11:41:28.386+0000: 618: debug : qemuProcessStop:3872 : Shutting down VM =
'milli' pid=3D3776 flags=3D1</div><div>2012-08-02 11:41:28.386+0000: 618: d=
ebug : qemuMonitorClose:797 : QEMU_MONITOR_CLOSE: mon=3D0x7f49dc000d50 refs=
=3D2</div><div>2012-08-02 11:41:28.386+0000: 618: debug : qemuMonitorUnref:=
248 : QEMU_MONITOR_UNREF: mon=3D0x7f49dc000d50 refs=3D1</div><div>2012-08-0=
2 11:41:28.386+0000: 606: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF=
: mon=3D0x7f49dc000d50 refs=3D0</div><div>2012-08-02 11:41:28.386+0000: 606=
: debug : qemuMonitorFree:225 : mon=3D0x7f49dc000d50</div><div>2012-08-02 1=
1:41:28.386+0000: 618: debug : qemuProcessKill:3769 : vm=3Dmilli pid=3D3776=
 flags=3D5</div><div>2012-08-02 11:41:28.586+0000: 618: debug : qemuDomainC=
leanupRun:1921 : driver=3D0x7f49e806f1b0, vm=3Dmilli</div><div>2012-08-02 1=
1:41:28.586+0000: 618: debug : qemuProcessAutoDestroyRemove:4320 : vm=3Dmil=
--_000_0CBBF9E4118E4C0C82215A5FE4D6D522sluse_
Content-Type: text/plain; charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable

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 a=
re all running.

This is what I caught from libvirtd.log:
2012-08-02 11:44:07.542+0000: 4231: debug : qemuMonitorUnref:248 : QEMU_MON=
ITOR_UNREF: mon=3D0x7fe7e40c8410 refs=3D3
2012-08-02 11:44:07.542+0000: 4232: debug : qemuMonitorUnref:248 : QEMU_MON=
ITOR_UNREF: mon=3D0x7fe7e40c8410 refs=3D2
2012-08-02 11:44:07.542+0000: 4232: debug : virConnectIsAlive:18395 : conn=
=3D0x7fe7e00c4e50
2012-08-02 11:44:07.562+0000: 4236: debug : virDomainMigrateSetMaxDowntime:=
16565 : dom=3D0x7fe7d8000cc0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-=
8774-2ed84b8bccc1), downtime=3D50, flags=3D0
2012-08-02 11:44:07.562+0000: 4236: debug : qemuDomainObjBeginJobInternal:7=
53 : Starting job: migration operation (async=3Dmigration 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_MONIT=
OR_REF: mon=3D0x7fe7e40c8410 refs=3D3
2012-08-02 11:44:07.562+0000: 4236: debug : qemuMonitorSetMigrationDowntime=
:1753 : mon=3D0x7fe7e40c8410 downtime=3D50
2012-08-02 11:44:07.562+0000: 4236: debug : qemuMonitorSend:861 : QEMU_MONI=
TOR_SEND_MSG: mon=3D0x7fe7e40c8410 msg=3D{"execute":"migrate_set_downtime",=
"arguments":{"value":0,050000},"id":"libvirt-261"}
 fd=3D-1
2012-08-02 11:44:07.563+0000: 4231: debug : qemuMonitorRef:239 : QEMU_MONIT=
OR_REF: mon=3D0x7fe7e40c8410 refs=3D4
2012-08-02 11:44:07.563+0000: 4231: debug : qemuMonitorIOWrite:470 : QEMU_M=
ONITOR_IO_WRITE: mon=3D0x7fe7e40c8410 buf=3D{"execute":"migrate_set_downtim=
e","arguments":{"value":0,050000},"id":"libvirt-261"}
 len=3D86 ret=3D86 errno=3D11
2012-08-02 11:44:07.563+0000: 4231: debug : qemuMonitorUnref:248 : QEMU_MON=
ITOR_UNREF: mon=3D0x7fe7e40c8410 refs=3D3
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorRef:239 : QEMU_MONIT=
OR_REF: mon=3D0x7fe7e40c8410 refs=3D4
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorIOProcess:365 : QEMU=
_MONITOR_IO_PROCESS: mon=3D0x7fe7e40c8410 buf=3D{"error": {"class": "JSONPa=
rsing", "desc": "Invalid JSON syntax", "data": {}}}
 len=3D80
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorUnref:248 : QEMU_MON=
ITOR_UNREF: mon=3D0x7fe7e40c8410 refs=3D3
2012-08-02 11:44:07.564+0000: 4236: error : qemuMonitorJSONCheckError:331 :=
 internal error unable to execute QEMU command 'migrate_set_downtime': Inva=
lid JSON syntax
2012-08-02 11:44:07.564+0000: 4236: debug : qemuMonitorUnref:248 : QEMU_MON=
ITOR_UNREF: mon=3D0x7fe7e40c8410 refs=3D2
2012-08-02 11:44:07.564+0000: 4236: debug : qemuDomainObjEndJob:870 : Stopp=
ing job: migration operation (async=3Dmigration out)
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorRef:239 : QEMU_MONIT=
OR_REF: mon=3D0x7fe7e40c8410 refs=3D3
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorIOProcess:365 : QEMU=
_MONITOR_IO_PROCESS: mon=3D0x7fe7e40c8410 buf=3D{"error": {"class": "JSONPa=
rsing", "desc": "Invalid JSON syntax", "data": {}}}
 len=3D80
2012-08-02 11:44:07.564+0000: 4236: debug : virDomainFree:2345 : dom=3D0x7f=
e7d8000cc0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:44:07.564+0000: 4231: error : qemuMonitorJSONIOProcessLine:15=
6 : 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 mo=
nitor internal error Unexpected JSON reply '{"error": {"class": "JSONParsin=
g", "desc": "Invalid JSON syntax", "data": {}}}'
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorUnref:248 : QEMU_MON=
ITOR_UNREF: mon=3D0x7fe7e40c8410 refs=3D2
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:3=
45 : Received error on 0x7fe7e4000e50 'milli'
2012-08-02 11:44:07.592+0000: 4232: debug : qemuDomainObjBeginJobInternal:7=
53 : Starting job: async nested (async=3Dmigration out)
2012-08-02 11:44:07.593+0000: 4232: debug : qemuMonitorRef:239 : QEMU_MONIT=
OR_REF: mon=3D0x7fe7e40c8410 refs=3D3
2012-08-02 11:44:07.593+0000: 4232: debug : qemuMonitorGetMigrationStatus:1=
776 : mon=3D0x7fe7e40c8410
2012-08-02 11:44:07.593+0000: 4232: debug : qemuMonitorSend:851 : Attempt t=
o send command while error is set internal error Unexpected JSON reply '{"e=
rror": {"class": "JSONParsing", "desc": "Invalid JSON syntax", "data": {}}}=
'
2012-08-02 11:44:07.593+0000: 4232: debug : qemuMonitorUnref:248 : QEMU_MON=
ITOR_UNREF: mon=3D0x7fe7e40c8410 refs=3D2
2012-08-02 11:44:07.593+0000: 4232: debug : doPeer2PeerMigrate3:2425 : Fini=
sh3 0x7fe7e00c4e50 ret=3D-1
2012-08-02 11:44:08.798+0000: 4233: debug : virDomainInterfaceStats:7299 : =
dom=3D0x7fe7e40c72d0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed=
84b8bccc1), path=3Dvnet0, stats=3D0x7fe803e45b10, size=3D64
2012-08-02 11:44:08.802+0000: 4233: debug : virDomainFree:2345 : dom=3D0x7f=
e7e40c72d0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:44:12.564+0000: 4234: debug : virDomainGetJobInfo:16465 : dom=
=3D0x7fe7dc000e00, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b=
8bccc1), info=3D0x7fe803644af0
2012-08-02 11:44:12.564+0000: 4234: debug : virDomainFree:2345 : dom=3D0x7f=
e7dc000e00, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:44:13.804+0000: 4235: debug : virDomainGetInfo:4298 : dom=3D0=
x7fe7e8001bd0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bcc=
c1), info=3D0x7fe802e43b20
2012-08-02 11:44:13.805+0000: 4235: debug : qemudGetProcessInfo:1156 : Got =
status for 5448/0 user=3D1770 sys=3D1445 cpu=3D0 rss=3D185496
2012-08-02 11:44:13.805+0000: 4235: debug : virDomainFree:2345 : dom=3D0x7f=
e7e8001bd0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:44:13.806+0000: 4238: debug : virDomainInterfaceStats:7299 : =
dom=3D0x7fe7f0002520, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed=
84b8bccc1), path=3Dvnet0, stats=3D0x7fe801640b10, size=3D64
2012-08-02 11:44:13.807+0000: 4238: debug : virDomainFree:2345 : dom=3D0x7f=
e7f0002520, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:44:16.474+0000: 4232: error : virNetClientProgramDispatchErro=
r:174 : An error occurred, but the cause is unknown
2012-08-02 11:44:16.474+0000: 4232: debug : doPeer2PeerMigrate3:2458 : Conf=
irm3 0x7fe7e40029c0 ret=3D-1 vm=3D0x7fe7e4000e50
2012-08-02 11:44:16.474+0000: 4232: debug : qemuMigrationConfirm:3109 : dri=
ver=3D0x7fe7f80bd9c0, conn=3D0x7fe7e40029c0, vm=3D0x7fe7e4000e50, cookiein=
=3D(null), cookieinlen=3D0, flags=3D3, retcode=3D1
2012-08-02 11:44:16.474+0000: 4232: debug : qemuMigrationEatCookie:752 : co=
okielen=3D0 cookie=3D'(null)'
2012-08-02 11:44:16.475+0000: 4232: debug : qemuProcessStartCPUs:2644 : Usi=
ng lock state '(null)'
2012-08-02 11:44:16.475+0000: 4232: debug : qemuDomainObjBeginJobInternal:7=
53 : Starting job: async nested (async=3Dmigration 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=3D3776 flags=3D1
2012-08-02 11:41:28.386+0000: 618: debug : qemuMonitorClose:797 : QEMU_MONI=
TOR_CLOSE: mon=3D0x7f49dc000d50 refs=3D2
2012-08-02 11:41:28.386+0000: 618: debug : qemuMonitorUnref:248 : QEMU_MONI=
TOR_UNREF: mon=3D0x7f49dc000d50 refs=3D1
2012-08-02 11:41:28.386+0000: 606: debug : qemuMonitorUnref:248 : QEMU_MONI=
TOR_UNREF: mon=3D0x7f49dc000d50 refs=3D0
2012-08-02 11:41:28.386+0000: 606: debug : qemuMonitorFree:225 : mon=3D0x7f=
49dc000d50
2012-08-02 11:41:28.386+0000: 618: debug : qemuProcessKill:3769 : vm=3Dmill=
i pid=3D3776 flags=3D5
2012-08-02 11:41:28.586+0000: 618: debug : qemuDomainCleanupRun:1921 : driv=
er=3D0x7f49e806f1b0, vm=3Dmilli
2012-08-02 11:41:28.586+0000: 618: debug : qemuProcessAutoDestroyRemove:432=
0 : vm=3Dmilli
2012-08-02 11:41:28.586+0000: 618: debug : qemuDriverCloseCallbackUnset:578=
 : vm=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1, cb=3D0x4900d0
2012-08-02 11:41:28.586+0000: 618: debug : virCgroupNew:603 : New group /li=
bvirt/qemu/milli
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected m=
ount/mapping 0:cpu at /sys/fs/cgroup/cpu,cpuacct in /system/libvirtd.servic=
e
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected m=
ount/mapping 1:cpuacct at /sys/fs/cgroup/cpu,cpuacct in /system/libvirtd.se=
rvice
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected m=
ount/mapping 2:cpuset at /sys/fs/cgroup/cpuset in
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected m=
ount/mapping 3:memory at /sys/fs/cgroup/memory in
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected m=
ount/mapping 4:devices at /sys/fs/cgroup/devices in
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected m=
ount/mapping 5:freezer at /sys/fs/cgroup/freezer in
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected m=
ount/mapping 6:blkio at /sys/fs/cgroup/blkio in
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:524 : Make gr=
oup /libvirt/qemu/milli
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make co=
ntroller /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/mi=
lli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make co=
ntroller /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/mi=
lli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make co=
ntroller /sys/fs/cgroup/cpuset/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make co=
ntroller /sys/fs/cgroup/memory/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make co=
ntroller /sys/fs/cgroup/devices/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make co=
ntroller /sys/fs/cgroup/freezer/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make co=
ntroller /sys/fs/cgroup/blkio/libvirt/qemu/milli/
2012-08-02 11:41:28.587+0000: 618: debug : virCgroupRemove:758 : Removing c=
group /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 c=
group /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 c=
group /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 c=
group /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 c=
group /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 c=
group /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 c=
group /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=3D0x=
7f49dc10fac0
2012-08-02 11:41:28.698+0000: 606: debug : virDomainFree:2345 : dom=3D0xaa0=
ea0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1)
2012-08-02 11:41:28.700+0000: 618: debug : qemuDomainObjEndAsyncJob:887 : S=
topping 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=F6berg
Swedish University of Agricultural Sciences
Box 7079 (Visiting Address Kron=E5sv=E4gen 8)
S-750 07 Uppsala, Sweden
Phone:  +46-(0)18-67 15 66
karli.sjoberg@slu.se<mailto:karli.sjoberg@adm.slu.se>

--_000_0CBBF9E4118E4C0C82215A5FE4D6D522sluse_
Content-Type: text/html; charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable

<html><head></head><body style=3D"word-wrap: break-word; -webkit-nbsp-mode:=
 space; -webkit-line-break: after-white-space; ">Hi,<div><br></div><div><di=
v>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 hos=
t?  The get "stuck" there, so to speak. Same when a guest is started o=
n that particular host, it is impossible to migrate them out again.</d=
iv><div><br></div><div>iptables are flushed, for excluding purposes. v=
dsmd, libvirtd and sanlock are all running.</div><div><br></div><div>This i=
s what I caught from libvirtd.log:</div><div>2012-08-02 11:44:07.542+0000: =
4231: debug : qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=3D0x7fe7e40c84=
10 refs=3D3</div><div><div>2012-08-02 11:44:07.542+0000: 4232: debug : qemu=
MonitorUnref:248 : QEMU_MONITOR_UNREF: mon=3D0x7fe7e40c8410 refs=3D2</div><=
div>2012-08-02 11:44:07.542+0000: 4232: debug : virConnectIsAlive:18395 : c=
onn=3D0x7fe7e00c4e50</div><div>2012-08-02 11:44:07.562+0000: 4236: debug : =
virDomainMigrateSetMaxDowntime:16565 : dom=3D0x7fe7d8000cc0, (VM: name=3Dmi=
lli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1), downtime=3D50, flags=3D0=
</div><div>2012-08-02 11:44:07.562+0000: 4236: debug : qemuDomainObjBeginJo=
bInternal:753 : Starting job: migration operation (async=3Dmigration out)</=
div><div>2012-08-02 11:44:07.562+0000: 4236: debug : qemuDomainMigrateSetMa=
xDowntime:9500 : Setting migration downtime to 50ms</div><div>2012-08-02 11=
:44:07.562+0000: 4236: debug : qemuMonitorRef:239 : QEMU_MONITOR_REF: mon=
=3D0x7fe7e40c8410 refs=3D3</div><div>2012-08-02 11:44:07.562+0000: 4236: de=
bug : qemuMonitorSetMigrationDowntime:1753 : mon=3D0x7fe7e40c8410 downtime=
=3D50</div><div>2012-08-02 11:44:07.562+0000: 4236: debug : qemuMonitorSend=
:861 : QEMU_MONITOR_SEND_MSG: mon=3D0x7fe7e40c8410 msg=3D{"execute":"migrat=
e_set_downtime","arguments":{"value":0,050000},"id":"libvirt-261"}</div><di=
v> fd=3D-1</div><div>2012-08-02 11:44:07.563+0000: 4231: debug : qemuM=
onitorRef:239 : QEMU_MONITOR_REF: mon=3D0x7fe7e40c8410 refs=3D4</div><div>2=
012-08-02 11:44:07.563+0000: 4231: debug : qemuMonitorIOWrite:470 : QEMU_MO=
NITOR_IO_WRITE: mon=3D0x7fe7e40c8410 buf=3D{"execute":"migrate_set_downtime=
","arguments":{"value":0,050000},"id":"libvirt-261"}</div><div> len=3D=
86 ret=3D86 errno=3D11</div><div>2012-08-02 11:44:07.563+0000: 4231: debug =
: qemuMonitorUnref:248 : QEMU_MONITOR_UNREF: mon=3D0x7fe7e40c8410 refs=3D3<=
/div><div>2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorRef:239 : =
QEMU_MONITOR_REF: mon=3D0x7fe7e40c8410 refs=3D4</div><div>2012-08-02 11:44:=
07.564+0000: 4231: debug : qemuMonitorIOProcess:365 : QEMU_MONITOR_IO_PROCE=
SS: mon=3D0x7fe7e40c8410 buf=3D{"error": {"class": "JSONParsing", "desc": "=
Invalid JSON syntax", "data": {}}}</div><div> len=3D80</div><div>2012-=
08-02 11:44:07.564+0000: 4231: debug : qemuMonitorUnref:248 : QEMU_MONITOR_=
UNREF: mon=3D0x7fe7e40c8410 refs=3D3</div><div>2012-08-02 11:44:07.564+0000=
: 4236: error : qemuMonitorJSONCheckError:331 : internal error unable to ex=
ecute QEMU command 'migrate_set_downtime': Invalid JSON syntax</div><div>20=
12-08-02 11:44:07.564+0000: 4236: debug : qemuMonitorUnref:248 : QEMU_MONIT=
OR_UNREF: mon=3D0x7fe7e40c8410 refs=3D2</div><div>2012-08-02 11:44:07.564+0=
000: 4236: debug : qemuDomainObjEndJob:870 : Stopping job: migration operat=
ion (async=3Dmigration out)</div><div>2012-08-02 11:44:07.564+0000: 4231: d=
ebug : qemuMonitorRef:239 : QEMU_MONITOR_REF: mon=3D0x7fe7e40c8410 refs=3D3=
</div><div>2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorIOProcess=
:365 : QEMU_MONITOR_IO_PROCESS: mon=3D0x7fe7e40c8410 buf=3D{"error": {"clas=
s": "JSONParsing", "desc": "Invalid JSON syntax", "data": {}}}</div><div>&n=
bsp;len=3D80</div><div>2012-08-02 11:44:07.564+0000: 4236: debug : virDomai=
nFree:2345 : dom=3D0x7fe7d8000cc0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-=
4821-8774-2ed84b8bccc1)</div><div>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": =
{}}}'</div><div>2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorIO:6=
45 : Error on monitor internal error Unexpected JSON reply '{"error": {"cla=
ss": "JSONParsing", "desc": "Invalid JSON syntax", "data": {}}}'</div><div>=
2012-08-02 11:44:07.564+0000: 4231: debug : qemuMonitorUnref:248 : QEMU_MON=
ITOR_UNREF: mon=3D0x7fe7e40c8410 refs=3D2</div><div>2012-08-02 11:44:07.564=
+0000: 4231: debug : qemuMonitorIO:679 : Triggering error callback</div><di=
v>2012-08-02 11:44:07.564+0000: 4231: debug : qemuProcessHandleMonitorError=
:345 : Received error on 0x7fe7e4000e50 'milli'</div><div>2012-08-02 11:44:=
07.592+0000: 4232: debug : qemuDomainObjBeginJobInternal:753 : Starting job=
: async nested (async=3Dmigration out)</div><div>2012-08-02 11:44:07.593+00=
00: 4232: debug : qemuMonitorRef:239 : QEMU_MONITOR_REF: mon=3D0x7fe7e40c84=
10 refs=3D3</div><div>2012-08-02 11:44:07.593+0000: 4232: debug : qemuMonit=
orGetMigrationStatus:1776 : mon=3D0x7fe7e40c8410</div><div>2012-08-02 11:44=
:07.593+0000: 4232: debug : qemuMonitorSend:851 : Attempt to send command w=
hile error is set internal error Unexpected JSON reply '{"error": {"class":=
 "JSONParsing", "desc": "Invalid JSON syntax", "data": {}}}'</div><div>2012=
-08-02 11:44:07.593+0000: 4232: debug : qemuMonitorUnref:248 : QEMU_MONITOR=
_UNREF: mon=3D0x7fe7e40c8410 refs=3D2</div><div>2012-08-02 11:44:07.593+000=
0: 4232: debug : doPeer2PeerMigrate3:2425 : Finish3 0x7fe7e00c4e50 ret=3D-1=
</div><div>2012-08-02 11:44:08.798+0000: 4233: debug : virDomainInterfaceSt=
ats:7299 : dom=3D0x7fe7e40c72d0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-48=
21-8774-2ed84b8bccc1), path=3Dvnet0, stats=3D0x7fe803e45b10, size=3D64</div=
li</div><div>2012-08-02 11:41:28.586+0000: 618: debug : qemuDriverCloseCall=
backUnset:578 : vm=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2ed84b8bccc1, cb=
=3D0x4900d0</div><div>2012-08-02 11:41:28.586+0000: 618: debug : virCgroupN=
ew:603 : New group /libvirt/qemu/milli</div><div>2012-08-02 11:41:28.587+00=
00: 618: debug : virCgroupDetect:262 : Detected mount/mapping 0:cpu at /sys=
/fs/cgroup/cpu,cpuacct in /system/libvirtd.service</div><div>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</div><di=
v>2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected=
 mount/mapping 2:cpuset at /sys/fs/cgroup/cpuset in</div><div>2012-08-02 11=
:41:28.587+0000: 618: debug : virCgroupDetect:262 : Detected mount/mapping =
3:memory at /sys/fs/cgroup/memory in</div><div>2012-08-02 11:41:28.587+0000=
: 618: debug : virCgroupDetect:262 : Detected mount/mapping 4:devices at /s=
ys/fs/cgroup/devices in</div><div>2012-08-02 11:41:28.587+0000: 618: debug =
: virCgroupDetect:262 : Detected mount/mapping 5:freezer at /sys/fs/cgroup/=
freezer in</div><div>2012-08-02 11:41:28.587+0000: 618: debug : virCgroupDe=
tect:262 : Detected mount/mapping 6:blkio at /sys/fs/cgroup/blkio in</div><=
div>2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:524 : Mak=
e group /libvirt/qemu/milli</div><div>2012-08-02 11:41:28.587+0000: 618: de=
bug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgroup/cpu,cpuacct/s=
ystem/libvirtd.service/libvirt/qemu/milli/</div><div>2012-08-02 11:41:28.58=
7+0000: 618: debug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgrou=
p/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/milli/</div><div>2012-08=
-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup:546 : Make controlle=
r /sys/fs/cgroup/cpuset/libvirt/qemu/milli/</div><div>2012-08-02 11:41:28.5=
87+0000: 618: debug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgro=
up/memory/libvirt/qemu/milli/</div><div>2012-08-02 11:41:28.587+0000: 618: =
debug : virCgroupMakeGroup:546 : Make controller /sys/fs/cgroup/devices/lib=
virt/qemu/milli/</div><div>2012-08-02 11:41:28.587+0000: 618: debug : virCg=
roupMakeGroup:546 : Make controller /sys/fs/cgroup/freezer/libvirt/qemu/mil=
li/</div><div>2012-08-02 11:41:28.587+0000: 618: debug : virCgroupMakeGroup=
:546 : Make controller /sys/fs/cgroup/blkio/libvirt/qemu/milli/</div><div>2=
012-08-02 11:41:28.587+0000: 618: debug : virCgroupRemove:758 : Removing cg=
roup /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/milli/=
 and all child cgroups</div><div>2012-08-02 11:41:28.588+0000: 618: debug :=
 virCgroupRemoveRecursively:713 : Removing cgroup /sys/fs/cgroup/cpu,cpuacc=
t/system/libvirtd.service/libvirt/qemu/milli//vcpu1</div><div>2012-08-02 11=
:41:28.595+0000: 618: debug : virCgroupRemoveRecursively:713 : Removing cgr=
oup /sys/fs/cgroup/cpu,cpuacct/system/libvirtd.service/libvirt/qemu/milli//=
vcpu0</div><div>2012-08-02 11:41:28.603+0000: 618: debug : virCgroupRemoveR=
ecursively:713 : Removing cgroup /sys/fs/cgroup/cpu,cpuacct/system/libvirtd=
.service/libvirt/qemu/milli/</div><div>2012-08-02 11:41:28.611+0000: 618: d=
ebug : virCgroupRemove:758 : Removing cgroup /sys/fs/cgroup/cpu,cpuacct/sys=
tem/libvirtd.service/libvirt/qemu/milli/ and all child cgroups</div><div>20=
12-08-02 11:41:28.611+0000: 618: debug : virCgroupRemove:758 : Removing cgr=
oup /sys/fs/cgroup/cpuset/libvirt/qemu/milli/ and all child cgroups</div><d=
iv>2012-08-02 11:41:28.611+0000: 618: debug : virCgroupRemoveRecursively:71=
3 : Removing cgroup /sys/fs/cgroup/cpuset/libvirt/qemu/milli/</div><div>201=
2-08-02 11:41:28.620+0000: 618: debug : virCgroupRemove:758 : Removing cgro=
up /sys/fs/cgroup/memory/libvirt/qemu/milli/ and all child cgroups</div><di=
v>2012-08-02 11:41:28.620+0000: 618: debug : virCgroupRemoveRecursively:713=
 : Removing cgroup /sys/fs/cgroup/memory/libvirt/qemu/milli/</div><div>2012=
-08-02 11:41:28.633+0000: 618: debug : virCgroupRemove:758 : Removing cgrou=
p /sys/fs/cgroup/devices/libvirt/qemu/milli/ and all child cgroups</div><di=
v>2012-08-02 11:41:28.679+0000: 618: debug : virCgroupRemoveRecursively:713=
 : Removing cgroup /sys/fs/cgroup/devices/libvirt/qemu/milli/</div><div>201=
2-08-02 11:41:28.684+0000: 618: debug : virCgroupRemove:758 : Removing cgro=
up /sys/fs/cgroup/freezer/libvirt/qemu/milli/ and all child cgroups</div><d=
iv>2012-08-02 11:41:28.684+0000: 618: debug : virCgroupRemoveRecursively:71=
3 : Removing cgroup /sys/fs/cgroup/freezer/libvirt/qemu/milli/</div><div>20=
12-08-02 11:41:28.689+0000: 618: debug : virCgroupRemove:758 : Removing cgr=
oup /sys/fs/cgroup/blkio/libvirt/qemu/milli/ and all child cgroups</div><di=
v>2012-08-02 11:41:28.689+0000: 618: debug : virCgroupRemoveRecursively:713=
 : Removing cgroup /sys/fs/cgroup/blkio/libvirt/qemu/milli/</div><div>2012-=
08-02 11:41:28.697+0000: 618: debug : virConnectClose:1496 : conn=3D0x7f49d=
c10fac0</div><div>2012-08-02 11:41:28.698+0000: 606: debug : virDomainFree:=
2345 : dom=3D0xaa0ea0, (VM: name=3Dmilli, uuid=3D2291f0d8-6341-4821-8774-2e=
d84b8bccc1)</div><div>2012-08-02 11:41:28.700+0000: 618: debug : qemuDomain=
ObjEndAsyncJob:887 : Stopping async job: migration out</div></div><div><br>=
</div><div><div><div># rpm -qa | egrep '(vdsm|libvirt|sanlock|json)' | sort=
 -d</div><div>json-c-0.9-4.fc17.x86_64</div><div>json-glib-0.14.2-2.fc17.x8=
6_64</div><div>libvirt-0.9.11.4-3.fc17.x86_64</div><div>libvirt-client-0.9.=
11.4-3.fc17.x86_64</div><div>libvirt-daemon-0.9.11.4-3.fc17.x86_64</div><di=
v>libvirt-daemon-config-network-0.9.11.4-3.fc17.x86_64</div><div>libvirt-da=
emon-config-nwfilter-0.9.11.4-3.fc17.x86_64</div><div>libvirt-lock-sanlock-=
0.9.11.4-3.fc17.x86_64</div><div>libvirt-python-0.9.11.4-3.fc17.x86_64</div=
...
<div>python-simplejson-2.5.2-1.fc17.x86_64</div><div>sanlock-2.3-3.fc17.x8=
6_64</div><div>sanlock-lib-2.3-3.fc17.x86_64</div><div>sanlock-python-2.3-3=
.fc17.x86_64</div><div>vdsm-4.10.0-5.fc17.x86_64</div><div>vdsm-cli-4.10.0-=
5.fc17.noarch</div><div>vdsm-python-4.10.0-5.fc17.x86_64</div><div>vdsm-xml=
rpc-4.10.0-5.fc17.noarch</div></div></div><div>
<div><br class=3D"Apple-interchange-newline"><br></div><div>Best Regards<br=
--------------------------------------------------------------------------=
-----<br>Karli Sj=F6berg<br>Swedish University of Agricultural Sciences<br>=
Box 7079 (Visiting Address Kron=E5sv=E4gen 8)<br>S-750 07 Uppsala, Sweden<b=
r>Phone:  +46-(0)18-67 15 66</div><div><a href=3D"mailto:karli.sjoberg=
@adm.slu.se">karli.sjoberg@slu.se</a></div>
</div>
<br></div></body></html>=
--_000_0CBBF9E4118E4C0C82215A5FE4D6D522sluse_--

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

Karli Sjöberg