search

xcp-ng / xcp

Entry point for issues and wiki. Also contains some scripts and sources.
https://xcp-ng.org
1.31k stars 74 forks source link

live migration failed - Xenops_interface.Does_not_exist #269

Closed elialum closed 4 years ago

elialum commented 5 years ago

Live migration of a VM inside pool (different host, same SR)

Source xcp-ng host versions -

[root@xenserver13 log]# rpm -qa | grep 'xcp'
xen-hypervisor-4.7.6-6.5.1.xcpng.x86_64
xen-tools-4.7.6-6.5.1.xcpng.x86_64
xenopsd-xenlight-0.66.0-1.1.xcpng.x86_64
xcp-ng-deps-7.6.0-5.noarch
vhd-tool-0.27.0-1.1.xcp.el7.centos.x86_64
xcp-ng-plymouth-theme-1.0.0-3.noarch
xcp-ng-release-config-7.6.0-3.x86_64
xcp-ng-pv-tools-7.32.0-2.1.xcp.noarch
xcp-ng-release-7.6.0-3.x86_64
message-switch-1.12.0-5.1.xcp.el7.centos.x86_64
openvswitch-2.5.3-2.2.3.3.xcpng.x86_64
xcp-emu-manager-1.1.2-1.xcpng.x86_64
xen-libs-4.7.6-6.5.1.xcpng.x86_64
xapi-tests-1.110.1-1.7.xcpng.x86_64
xen-dom0-tools-4.7.6-6.5.1.xcpng.x86_64
xenopsd-xc-0.66.0-1.1.xcpng.x86_64
xcp-ng-xapi-plugins-1.4.0-1.xcpng.noarch
xcp-ng-center-7.6.3.21-1.noarch
xcp-featured-1.1.1-2.el7.centos.x86_64
xapi-core-1.110.1-1.7.xcpng.x86_64
xsconsole-10.1.7-1.2.xcp.x86_64
xcp-rrdd-1.9.0-4.el7.centos.x86_64
xcp-ng-generic-lib-1.1.1-1.xcpng.x86_64
xen-dom0-libs-4.7.6-6.5.1.xcpng.x86_64
xenopsd-0.66.0-1.1.xcpng.x86_64
microcode_ctl-2.1-26.xs5.1.xcpng.x86_64
xapi-xe-1.110.1-1.7.xcpng.x86_64
xcp-networkd-0.34.0-3.el7.centos.x86_64
xenserver-firstboot-1.0.9-1.2.xcp.noarch
xcp-python-libs-2.0.5-1.1.xcp.noarch

Destination server versions - 

[root@xenserver14 log]# rpm -qa | grep 'xcp'
xen-libs-4.7.6-6.5.1.xcpng.x86_64
xenopsd-xc-0.66.0-1.1.xcpng.x86_64
xapi-tests-1.110.1-1.7.xcpng.x86_64
vhd-tool-0.27.0-1.1.xcp.el7.centos.x86_64
xcp-ng-plymouth-theme-1.0.0-3.noarch
xcp-ng-release-config-7.6.0-3.x86_64
xcp-ng-pv-tools-7.32.0-2.1.xcp.noarch
xenopsd-0.66.0-1.1.xcpng.x86_64
microcode_ctl-2.1-26.xs5.1.xcpng.x86_64
xcp-ng-release-7.6.0-3.x86_64
xcp-emu-manager-1.1.2-1.xcpng.x86_64
message-switch-1.12.0-5.1.xcp.el7.centos.x86_64
xen-hypervisor-4.7.6-6.5.1.xcpng.x86_64
xen-dom0-libs-4.7.6-6.5.1.xcpng.x86_64
xen-dom0-tools-4.7.6-6.5.1.xcpng.x86_64
xcp-featured-1.1.1-2.el7.centos.x86_64
xcp-ng-deps-7.6.0-5.noarch
xapi-core-1.110.1-1.7.xcpng.x86_64
xsconsole-10.1.7-1.2.xcp.x86_64
xcp-rrdd-1.9.0-4.el7.centos.x86_64
xen-tools-4.7.6-6.5.1.xcpng.x86_64
openvswitch-2.5.3-2.2.3.3.xcpng.x86_64
xcp-ng-center-7.6.3.21-1.noarch
xenopsd-xenlight-0.66.0-1.1.xcpng.x86_64
xcp-ng-generic-lib-1.1.1-1.xcpng.x86_64
xcp-ng-xapi-plugins-1.4.0-1.xcpng.noarch
xapi-xe-1.110.1-1.7.xcpng.x86_64
xcp-networkd-0.34.0-3.el7.centos.x86_64
xenserver-firstboot-1.0.9-1.2.xcp.noarch
xcp-python-libs-2.0.5-1.1.xcp.noarch

Source server relevant logs - 

[root@xenserver13 log]# zgrep '814c8b22-d896-bc76-a421-7afce8e8a538' xensource.log* | grep 'Sep 11'| grep 'Async.VM.pool_migrate'
xensource.log.1:Sep 11 08:55:38 xenserver13 xapi: [debug|xenserver13|312761 INET :::80|Async.VM.pool_migrate R:3e35c13ce76f|xenops] suppressing xenops events on VM: 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:55:38 xenserver13 xapi: [ info|xenserver13|312761 INET :::80|Async.VM.pool_migrate R:3e35c13ce76f|xapi] xenops: VM.migrate 814c8b22-d896-bc76-a421-7afce8e8a538 to http://192.168.3.148/services/xenops?session_id=OpaqueRef:996f821e-5780-4f84-a639-04e62828098c
xensource.log.1:Sep 11 08:55:38 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Task 52485 reference Async.VM.pool_migrate R:3e35c13ce76f: ["VM_migrate",["814c8b22-d896-bc76-a421-7afce8e8a538",{},{},{},"http://192.168.3.148/services/xenops?session_id=OpaqueRef:996f821e-5780-4f84-a639-04e62828098c"]]
xensource.log.1:Sep 11 08:55:38 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM.migrate 814c8b22-d896-bc76-a421-7afce8e8a538 -> http://192.168.3.148/services/xenops?session_id=OpaqueRef:996f821e-5780-4f84-a639-04e62828098c
xensource.log.1:Sep 11 08:55:38 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Queue: Aliasing existing tag '814c8b22-d896-bc76-a421-7afce8e8a538' to new tag '814c8b22-d896-bc76-a421-000000000000'
xensource.log.1:Sep 11 08:55:38 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM.set_memory_dynamic_range (814c8b22-d896-bc76-a421-7afce8e8a538, 2147483648, 2147483648)
xensource.log.1:Sep 11 08:55:38 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; set_memory_dynamic_range min = 2097152; max = 2097152
xensource.log.1:Sep 11 08:58:11 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM_DB.signal 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:11 xenserver13 xenopsd-xc: [ info|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM 814c8b22-d896-bc76-a421-7afce8e8a538 has memory_limit = 2147483648
xensource.log.1:Sep 11 08:58:14 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["VM_save",["814c8b22-d896-bc76-a421-7afce8e8a538",["Live"],["FD",21],[]]]
xensource.log.1:Sep 11 08:58:14 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM.save 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:14 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|mig64] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; suspend live = true
xensource.log.1:Sep 11 08:58:14 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; waiting for emu-manager...
xensource.log.1:Sep 11 08:58:15 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 0 / 100
xensource.log.1:Sep 11 08:58:15 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; message from emu-manager: prepare:xenguest
xensource.log.1:Sep 11 08:58:15 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; waiting for emu-manager...
xensource.log.1:Sep 11 08:58:15 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 1 / 100
xensource.log.1:Sep 11 08:58:16 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 2 / 100
xensource.log.1:Sep 11 08:58:16 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 3 / 100
xensource.log.1:Sep 11 08:58:17 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 4 / 100
xensource.log.1:Sep 11 08:58:17 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 6 / 100
xensource.log.1:Sep 11 08:58:18 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 7 / 100
xensource.log.1:Sep 11 08:58:19 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 9 / 100
xensource.log.1:Sep 11 08:58:20 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 11 / 100
xensource.log.1:Sep 11 08:58:20 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 12 / 100
xensource.log.1:Sep 11 08:58:21 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 14 / 100
xensource.log.1:Sep 11 08:58:21 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 16 / 100
xensource.log.1:Sep 11 08:58:22 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 19 / 100
xensource.log.1:Sep 11 08:58:22 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 23 / 100
xensource.log.1:Sep 11 08:58:23 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 27 / 100
xensource.log.1:Sep 11 08:58:23 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 30 / 100
xensource.log.1:Sep 11 08:58:24 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 34 / 100
xensource.log.1:Sep 11 08:58:24 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 35 / 100
xensource.log.1:Sep 11 08:58:25 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 39 / 100
xensource.log.1:Sep 11 08:58:25 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 40 / 100
xensource.log.1:Sep 11 08:58:26 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 41 / 100
xensource.log.1:Sep 11 08:58:26 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 43 / 100
xensource.log.1:Sep 11 08:58:27 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 45 / 100
xensource.log.1:Sep 11 08:58:27 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 46 / 100
xensource.log.1:Sep 11 08:58:28 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 49 / 100
xensource.log.1:Sep 11 08:58:28 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 52 / 100
xensource.log.1:Sep 11 08:58:29 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 56 / 100
xensource.log.1:Sep 11 08:58:29 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 57 / 100
xensource.log.1:Sep 11 08:58:30 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 61 / 100
xensource.log.1:Sep 11 08:58:30 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 65 / 100
xensource.log.1:Sep 11 08:58:31 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 71 / 100
xensource.log.1:Sep 11 08:58:31 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 74 / 100
xensource.log.1:Sep 11 08:58:32 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 76 / 100
xensource.log.1:Sep 11 08:58:33 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 77 / 100
xensource.log.1:Sep 11 08:58:34 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 89 / 100
xensource.log.1:Sep 11 08:58:34 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 90 / 100
xensource.log.1:Sep 11 08:58:34 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; message from emu-manager: suspend:
xensource.log.1:Sep 11 08:58:34 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; Requesting domain suspend
xensource.log.1:Sep 11 08:58:34 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; Waiting for domain to acknowledge shutdown request
xensource.log.1:Sep 11 08:58:34 xenserver13 xenopsd-xc: [ info|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; Domain acknowledged shutdown request
xensource.log.1:Sep 11 08:58:34 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] EVENT on our VM: 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:34 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] EVENT on our VM: 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:34 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; suspending qemu-dm
xensource.log.1:Sep 11 08:58:34 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; waiting for emu-manager...
xensource.log.1:Sep 11 08:58:35 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 91 / 100
xensource.log.1:Sep 11 08:58:36 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 92 / 100
xensource.log.1:Sep 11 08:58:37 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 93 / 100
xensource.log.1:Sep 11 08:58:39 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 94 / 100
xensource.log.1:Sep 11 08:58:40 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 95 / 100
xensource.log.1:Sep 11 08:58:41 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 96 / 100
xensource.log.1:Sep 11 08:58:42 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 97 / 100
xensource.log.1:Sep 11 08:58:43 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; progress = 90 / 100
xensource.log.1:Sep 11 08:58:44 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; message from emu-manager: result:0 0
xensource.log.1:Sep 11 08:58:44 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; emu-manager completed successfully
xensource.log.1:Sep 11 08:58:44 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; writing 13038 bytes from /var/lib/xen/qemu-save.8
xensource.log.1:Sep 11 08:58:44 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|mig64] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; suspend complete
xensource.log.1:Sep 11 08:58:44 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; Final memory usage of the domain = 524285 pages
xensource.log.1:Sep 11 08:58:44 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; Disk backends have all been flushed
xensource.log.1:Sep 11 08:58:47 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] VM = 814c8b22-d896-bc76-a421-7afce8e8a538; domid = 8; Storing final memory usage
xensource.log.1:Sep 11 08:58:47 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Writing extra/814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:47 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["VM_rename",["814c8b22-d896-bc76-a421-7afce8e8a538","814c8b22-d896-bc76-a421-000000000000"]]
xensource.log.1:Sep 11 08:58:47 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM.rename 814c8b22-d896-bc76-a421-7afce8e8a538 -> 814c8b22-d896-bc76-a421-000000000000
xensource.log.1:Sep 11 08:58:47 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] Renaming domain 8 from 814c8b22-d896-bc76-a421-7afce8e8a538 to 814c8b22-d896-bc76-a421-000000000000
xensource.log.1:Sep 11 08:58:47 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] Removing xenstore tree at /xapi/814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:47 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] Removing xenstore tree at /vss/814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] Removing xenstore tree at /vm/814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Renaming extra/814c8b22-d896-bc76-a421-7afce8e8a538 -> extra/814c8b22-d896-bc76-a421-000000000000
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Removing VM/814c8b22-d896-bc76-a421-7afce8e8a538/config
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Deleting VM/814c8b22-d896-bc76-a421-7afce8e8a538/config
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] DB.delete /var/run/nonpersistent/xenopsd/classic/VM/814c8b22-d896-bc76-a421-7afce8e8a538/config
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] DB.delete /var/run/nonpersistent/xenopsd/classic/VM/814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Removing VM/814c8b22-d896-bc76-a421-7afce8e8a538/vbd.xvda
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Deleting VM/814c8b22-d896-bc76-a421-7afce8e8a538/vbd.xvda
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] DB.delete /var/run/nonpersistent/xenopsd/classic/VM/814c8b22-d896-bc76-a421-7afce8e8a538/vbd.xvda
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] DB.delete /var/run/nonpersistent/xenopsd/classic/VM/814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Removing VM/814c8b22-d896-bc76-a421-7afce8e8a538/vif.1
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Deleting VM/814c8b22-d896-bc76-a421-7afce8e8a538/vif.1
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] DB.delete /var/run/nonpersistent/xenopsd/classic/VM/814c8b22-d896-bc76-a421-7afce8e8a538/vif.1
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] DB.delete /var/run/nonpersistent/xenopsd/classic/VM/814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Removing VM/814c8b22-d896-bc76-a421-7afce8e8a538/vif.0
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Deleting VM/814c8b22-d896-bc76-a421-7afce8e8a538/vif.0
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] DB.delete /var/run/nonpersistent/xenopsd/classic/VM/814c8b22-d896-bc76-a421-7afce8e8a538/vif.0
xensource.log.1:Sep 11 08:58:48 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] DB.delete /var/run/nonpersistent/xenopsd/classic/VM/814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:52 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["VM_hook_script",["814c8b22-d896-bc76-a421-7afce8e8a538","VM_pre_destroy","suspend"]]
xensource.log.1:Sep 11 08:58:56 xenserver13 xenopsd-xc: [debug|xenserver13|18 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["VM_hook_script",["814c8b22-d896-bc76-a421-7afce8e8a538","VM_post_destroy","suspend"]]
xensource.log.1:Sep 11 08:58:56 xenserver13 xapi: [ info|xenserver13|312761 INET :::80|Async.VM.pool_migrate R:3e35c13ce76f|xenops] xenops: VM.remove 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:56 xenserver13 xenopsd-xc: [debug|xenserver13|29 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Task 52498 reference Async.VM.pool_migrate R:3e35c13ce76f: ["Atomic",["VM_remove","814c8b22-d896-bc76-a421-7afce8e8a538"]]
xensource.log.1:Sep 11 08:58:56 xenserver13 xenopsd-xc: [debug|xenserver13|29 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM.remove 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:56 xenserver13 xenopsd-xc: [ info|xenserver13|29 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Caught Xenops_interface.Does_not_exist(_) executing ["Atomic",["VM_remove","814c8b22-d896-bc76-a421-7afce8e8a538"]]: triggering cleanup actions
xensource.log.1:Sep 11 08:58:56 xenserver13 xenopsd-xc: [debug|xenserver13|29 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Task 52499 reference Async.VM.pool_migrate R:3e35c13ce76f: ["VM_check_state","814c8b22-d896-bc76-a421-7afce8e8a538"]
xensource.log.1:Sep 11 08:58:56 xenserver13 xenopsd-xc: [ info|xenserver13|29 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Caught Xenops_interface.Does_not_exist(_) executing ["VM_check_state","814c8b22-d896-bc76-a421-7afce8e8a538"]: triggering cleanup actions
xensource.log.1:Sep 11 08:58:56 xenserver13 xapi: [debug|xenserver13|312761 INET :::80|Async.VM.pool_migrate R:3e35c13ce76f|xenops] Metadata for VM 814c8b22-d896-bc76-a421-7afce8e8a538 was already removed
xensource.log.1:Sep 11 08:58:57 xenserver13 xapi: [debug|xenserver13|312761 INET :::80|Async.VM.pool_migrate R:3e35c13ce76f|xenops] re-enabled xenops events on VM: 814c8b22-d896-bc76-a421-7afce8e8a538; refreshing VM
xensource.log.1:Sep 11 08:58:57 xenserver13 xenopsd-xc: [debug|xenserver13|105295 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] UPDATES.refresh_vm 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:57 xenserver13 xenopsd-xc: [debug|xenserver13|105295 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM_DB.signal 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:57 xenserver13 xenopsd-xc: [debug|xenserver13|105296 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] UPDATES.inject_barrier 814c8b22-d896-bc76-a421-7afce8e8a538 6
xensource.log.1:Sep 11 09:01:06 xenserver13 xenopsd-xc: [debug|xenserver13|33 |Async.VM.pool_migrate R:f88ca8b78c4e|xenops] EVENT on other VM: 814c8b22-d896-bc76-a421-7afce8e8a538

Destination server logs - 

[root@xenserver14 log]# zgrep '814c8b22-d896-bc76-a421-7afce8e8a538' xensource.log* | grep 'Sep 11'| grep 'Async.VM.pool_migrate'
xensource.log.1:Sep 11 08:55:37 xenserver14 xapi: [debug|xenserver14|1812086 |Async.VM.pool_migrate R:3e35c13ce76f|audit] VM.pool_migrate: VM = '814c8b22-d896-bc76-a421-7afce8e8a538 (israel27.jetserver.net)'; host = '7d2e505b-ce66-4575-b5d9-f00f30c52589 (xenserver14)'
xensource.log.1:Sep 11 08:58:11 xenserver14 xenopsd-xc: [debug|xenserver14|32928 ||xenopsd] Received request = [{"uri":"/services/xenops/memory/814c8b22-d896-bc76-a421-000000000001","query":{"session_id":"OpaqueRef:996f821e-5780-4f84-a639-04e62828098c"},"cookie":{"instance_id":"b7f44e29-e90f-49ba-b11b-e7b46e73502e","final_id":"814c8b22-d896-bc76-a421-7afce8e8a538","dbg":"Async.VM.pool_migrate R:3e35c13ce76f","memory_limit":"2147483648"}}]
xensource.log.1:Sep 11 08:58:12 xenserver14 xenopsd-xc: [debug|xenserver14|32928 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM.receive_memory id = 814c8b22-d896-bc76-a421-000000000001, final_id=814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:12 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Task 16110 reference Async.VM.pool_migrate R:3e35c13ce76f: ["VM_receive_memory",["814c8b22-d896-bc76-a421-000000000001","814c8b22-d896-bc76-a421-7afce8e8a538",2147483648,22]]
xensource.log.1:Sep 11 08:58:12 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Queue: Aliasing existing tag '814c8b22-d896-bc76-a421-000000000001' to new tag '814c8b22-d896-bc76-a421-7afce8e8a538'
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["VM_rename",["814c8b22-d896-bc76-a421-000000000001","814c8b22-d896-bc76-a421-7afce8e8a538"]]
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM.rename 814c8b22-d896-bc76-a421-000000000001 -> 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] Renaming domain 8 from 814c8b22-d896-bc76-a421-000000000001 to 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /local/domain/8/vm (/vm/814c8b22-d896-bc76-a421-7afce8e8a538)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /local/domain/8/vss (/vss/814c8b22-d896-bc76-a421-7afce8e8a538)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538 ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8 ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif/0 ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif/0/vif-ifindex (42)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif/0/vif-ofport (34)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif/0/vif (vif8.0)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif/0/hotplug (online)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif/1 ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif/1/vif-ifindex (43)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif/1/vif-ofport (35)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif/1/vif (vif8.1)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/hotplug/8/vif/1/hotplug (online)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0 ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/backend-kind (vif)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/backend-id (0)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/vif-id (0)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/vif-uuid (90fd6069-751d-58a7-7fae-bca0904af40d)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/network-uuid (02e69892-177e-4d77-d406-7a7ed544ad73)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/locking-mode (unlocked)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/setup-vif-rules (/usr/libexec/xenopsd/setup-vif-rules)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/setup-pvs-proxy-rules (/usr/libexec/xenopsd/setup-pvs-proxy-rules)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/xenopsd-backend (classic)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/mac (de:54:e2:9f:52:e1)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/MTU (1500)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/bridge (xapi2)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/bridge-MAC (fe:ff:ff:ff:ff:ff)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/rate (3840)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/0/timeslice (0)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1 ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/backend-kind (vif)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/backend-id (0)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/vif-id (1)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/vif-uuid (7eae9835-2c85-a411-f554-ee862715ce57)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/network-uuid (743d9764-4f36-d574-c096-4d228e3cd38c)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/locking-mode (unlocked)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/setup-vif-rules (/usr/libexec/xenopsd/setup-vif-rules)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/setup-pvs-proxy-rules (/usr/libexec/xenopsd/setup-pvs-proxy-rules)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/xenopsd-backend (classic)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/mac (82:2d:89:a8:01:35)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/MTU (1500)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/bridge (xapi3)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /xapi/814c8b22-d896-bc76-a421-7afce8e8a538/private/vif/1/bridge-MAC (fe:ff:ff:ff:ff:ff)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vss/814c8b22-d896-bc76-a421-7afce8e8a538 ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538 ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/uuid (814c8b22-d896-bc76-a421-7afce8e8a538)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/name (israel27.jetserver.net)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/domains ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/domains/8 (/local/domain/8)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/domains/8/create-time (5680144819649285)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/devices ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/devices/vif ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/devices/vif/0 (1)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/devices/vif/1 (1)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/rtc ()
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops] About to write to /vm/814c8b22-d896-bc76-a421-7afce8e8a538/rtc/timeoffset (10800)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Renaming extra/814c8b22-d896-bc76-a421-000000000001 -> extra/814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Adding VM/814c8b22-d896-bc76-a421-7afce8e8a538/config
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Writing VM/814c8b22-d896-bc76-a421-7afce8e8a538/config
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Adding VM/814c8b22-d896-bc76-a421-7afce8e8a538/vbd.xvda
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Writing VM/814c8b22-d896-bc76-a421-7afce8e8a538/vbd.xvda
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Adding VM/814c8b22-d896-bc76-a421-7afce8e8a538/vif.0
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Writing VM/814c8b22-d896-bc76-a421-7afce8e8a538/vif.0
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Adding VM/814c8b22-d896-bc76-a421-7afce8e8a538/vif.1
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_utils] TypedTable: Writing VM/814c8b22-d896-bc76-a421-7afce8e8a538/vif.1
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["VBD_set_active",["814c8b22-d896-bc76-a421-7afce8e8a538","xvda"],true]
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VBD.set_active 814c8b22-d896-bc76-a421-7afce8e8a538.xvda true
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VBD_DB.signal 814c8b22-d896-bc76-a421-7afce8e8a538.xvda
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["Parallel","814c8b22-d896-bc76-a421-7afce8e8a538","VBD.plug RW vm=814c8b22-d896-bc76-a421-7afce8e8a538",[["VBD_plug",["814c8b22-d896-bc76-a421-7afce8e8a538","xvda"]]]]
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] begin_Parallel:task=16110.atoms=1.(VBD.plug RW vm=814c8b22-d896-bc76-a421-7afce8e8a538)
xensource.log.1:Sep 11 08:58:48 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] queue_atomics_and_wait: Parallel:task=16110.atoms=1.(VBD.plug RW vm=814c8b22-d896-bc76-a421-7afce8e8a538): chunk of 1 atoms
xensource.log.1:Sep 11 08:58:51 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] end_Parallel:task=16110.atoms=1.(VBD.plug RW vm=814c8b22-d896-bc76-a421-7afce8e8a538)
xensource.log.1:Sep 11 08:58:51 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["Parallel","814c8b22-d896-bc76-a421-7afce8e8a538","VBD.plug RO vm=814c8b22-d896-bc76-a421-7afce8e8a538",[]]
xensource.log.1:Sep 11 08:58:51 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] begin_Parallel:task=16110.atoms=0.(VBD.plug RO vm=814c8b22-d896-bc76-a421-7afce8e8a538)
xensource.log.1:Sep 11 08:58:51 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] end_Parallel:task=16110.atoms=0.(VBD.plug RO vm=814c8b22-d896-bc76-a421-7afce8e8a538)
xensource.log.1:Sep 11 08:58:51 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["VM_create_device_model",["814c8b22-d896-bc76-a421-7afce8e8a538",true]]
xensource.log.1:Sep 11 08:58:51 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM.create_device_model 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:52 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["VM_unpause","814c8b22-d896-bc76-a421-7afce8e8a538"]
xensource.log.1:Sep 11 08:58:52 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM.unpause 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:52 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM_DB.signal 814c8b22-d896-bc76-a421-7afce8e8a538
xensource.log.1:Sep 11 08:58:52 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["VM_set_domain_action_request",["814c8b22-d896-bc76-a421-7afce8e8a538",[]]]
xensource.log.1:Sep 11 08:58:52 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] VM.set_domain_action_request 814c8b22-d896-bc76-a421-7afce8e8a538 None
xensource.log.1:Sep 11 08:58:52 xenserver14 xenopsd-xc: [debug|xenserver14|31 |Async.VM.pool_migrate R:3e35c13ce76f|xenops_server] Performing: ["VM_hook_script",["814c8b22-d896-bc76-a421-7afce8e8a538","VM_post_migrate","destination"]]
elialum commented 5 years ago

I was able to reproduce this again, this time with a VM with no network interfaces. Turned off VM, removed network interfaces started VM again (with no network), initiated live migration.

This is live migration inside pool (same SR)

cat /var/log/daemon.log | grep "emu|xenguest|emp" (SENDING SERVER)

[root@xenserver12 ~]# cat /var/log/daemon.log | grep "emu\|xenguest\|emp"
Sep 15 09:56:15 xenserver12 systemd[1]: Starting Cleanup of Temporary Directories...
Sep 15 09:56:15 xenserver12 systemd[1]: Started Cleanup of Temporary Directories.
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: Command line: -controloutfd 7 -controlinfd 8 -mode hvm_build -image /usr/libexec/xen/boot/hvmloader -domid 1 -store_port 5 -store_domid 0 -console_port 6 -console_domid 0 -mem_max_mib 4088 -mem_start_mib 4088 -fork true
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: Domain Properties: Type HVM, hap 1
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: Determined the following parameters from xenstore:
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: vcpu/number:4 vcpu/weight:256 vcpu/cap:0
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: nx: 1, pae 1, cores-per-socket 1, x86-fip-width 0, nested 0
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: apic: 1 acpi: 1 acpi_s4: 0 acpi_s3: 0 tsc_mode: 0 hpet: 1
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: nomigrate 0, timeoffset 10800
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: viridian: 0, time_ref_count: 0, reference_tsc: 0
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: vcpu/0/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: vcpu/1/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: vcpu/2/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: vcpu/3/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_allocate: cmdline="(null)", features="(null)"
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: Calculated provisional MMIO hole size as 0x10000000
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: Final lower MMIO hole size is 0x10000000
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_kernel_file: filename="/usr/libexec/xen/boot/hvmloader"
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_malloc_filemap    : 582 kB
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_boot_xen_init: ver 4.7, caps xen-3.0-x86_64 xen-3.0-x86_32p hvm-3.0-x86_32 hvm-3.0-x86_32p hvm-3.0-x86_64
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_parse_image: called
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_find_loader: trying multiboot-binary loader ...
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: loader probe failed
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_find_loader: trying HVM-generic loader ...
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: loader probe OK
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: xc: detail: elf_parse_binary: phdr: paddr=0x100000 memsz=0x7acc4
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: xc: detail: elf_parse_binary: memory: 0x100000 -> 0x17acc4
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_mem_init: mem 4088 MB, pages 0xff800 pages, 4k each
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_mem_init: 0xff800 pages
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_boot_mem_init: called
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_malloc            : 8688 kB
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: xc: detail: PHYSICAL MEMORY ALLOCATION:
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: xc: detail:   4KB PAGES: 0x0000000000000200
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: xc: detail:   2MB PAGES: 0x00000000000003fb
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: xc: detail:   1GB PAGES: 0x0000000000000002
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_build_image: called
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_pfn_to_ptr_retcount: domU mapping: pfn 0x100+0x7b at 0x7f3ae202c000
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_alloc_segment:   kernel       : 0x100000 -> 0x17b000  (pfn 0x100 + 0x7b pages)
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: xc: detail: elf_load_binary: phdr 0 at 0x7f3ae1fb1000 -> 0x7f3ae2022111
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: alloc_pgtables_hvm: doing nothing
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_build_image  : virt_alloc_end : 0x17b000
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_build_image  : virt_pgtab_end : 0x0
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_boot_image: called
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: bootearly: doing nothing
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_compat_check: supported guest type: xen-3.0-x86_64
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_compat_check: supported guest type: xen-3.0-x86_32p
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_compat_check: supported guest type: hvm-3.0-x86_32 <= matches
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_compat_check: supported guest type: hvm-3.0-x86_32p
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_compat_check: supported guest type: hvm-3.0-x86_64
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: clear_page: pfn 0xfefff, mfn 0xfefff
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: clear_page: pfn 0xfeffc, mfn 0xfeffc
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: domain builder memory footprint
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail:    allocated
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail:       malloc             : 8693 kB
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail:       anon mmap          : 0 bytes
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail:    mapped
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail:       file mmap          : 582 kB
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail:       domU mmap          : 492 kB
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: vcpu_hvm: called
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_release: called
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: Parsing '17cbfbff-97ba2223-2d93fbff-00000003-00000001-00000000-00000000-00000000-00001000-9c000400' as featureset
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: domainbuilder: detail: xc_dom_gnttab_hvm_seed: called, pfn=0x10f800
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: Writing to control: 'result:1044476 1044479#012'
Sep 15 13:40:55 xenserver12 xenguest-1-build[16039]: All done
Sep 15 13:40:58 xenserver12 forkexecd: [ info|xenserver12|0 ||forkexecd] qemu-dm-1[16514]: Arguments: 1 --syslog -std-vga -videoram 8 -vnc unix:/var/run/xen/vnc-1,lock-key-sync=off -acpi -monitor null -xen-domid 1 -m size=4096 -boot order=c -usb -device usb-tablet,port=2 -smp 4,maxcpus=4 -serial pty -display none -nodefaults -trace enable=xen_platform_log -sandbox on,obsolete=deny,elevateprivileges=allow,spawn=deny,resourcecontrol=deny -S -global PIIX4_PM.revision_id=0x1 -global ide-hd.ver=0.10.2 -global piix3-ide-xen.subvendor_id=0x5853 -global piix3-ide-xen.subsystem_id=0x0001 -global piix3-usb-uhci.subvendor_id=0x5853 -global piix3-usb-uhci.subsystem_id=0x0001 -global rtl8139.subvendor_id=0x5853 -global rtl8139.subsystem_id=0x0001 -parallel null -qmp unix:/var/run/xen/qmp-libxl-1,server,nowait -qmp unix:/var/run/xen/qmp-event-1,server,nowait -device xen-platform,addr=3,device-id=0x0001,revision=0x2,class-id=0x0100,subvendor_id=0x5853,subsystem_id=0x0001 -drive file=,if=ide,index=3,media=cdrom,force-lba=off -drive file=/dev/sm/backend/31f1bc5f-9e95-b068-57c3-7d74f31e5234/1124fc99-ae76-489e-a535-9af28535edf9,if=ide,index=0,media=disk,force-lba=on,format=raw -net none
Sep 15 13:40:58 xenserver12 forkexecd: [ info|xenserver12|0 ||forkexecd] qemu-dm-1[16514]: Exec: /usr/lib64/xen/bin/qemu-system-i386 qemu-dm-1 -machine pc-0.10,accel=xen,max-ram-below-4g=4026531840,allow-unassigned=true,trad_compat=true -vnc unix:/var/run/xen/vnc-1,lock-key-sync=off -monitor null -xen-domid 1 -m size=4096 -boot order=c -usb -device usb-tablet,port=2 -smp 4,maxcpus=4 -serial pty -display none -nodefaults -trace enable=xen_platform_log -sandbox on,obsolete=deny,elevateprivileges=allow,spawn=deny,resourcecontrol=deny -S -global PIIX4_PM.revision_id=0x1 -global ide-hd.ver=0.10.2 -global piix3-ide-xen.subvendor_id=0x5853 -global piix3-ide-xen.subsystem_id=0x0001 -global piix3-usb-uhci.subvendor_id=0x5853 -global piix3-usb-uhci.subsystem_id=0x0001 -global rtl8139.subvendor_id=0x5853 -global rtl8139.subsystem_id=0x0001 -parallel null -qmp unix:/var/run/xen/qmp-libxl-1,server,nowait -qmp unix:/var/run/xen/qmp-event-1,server,nowait -device xen-platform,addr=3,device-id=0x0001,revision=0x2,class-id=0x0100,subvendor_id=0x5853,subsystem_id=0x0001 -drive file=,if=ide,index=3,media=cdrom,force-lba=off -drive file=/dev/sm/backend/31f1bc5f-9e95-b068-57c3-7d74f31e5234/1124fc99-ae76-489e-a535-9af28535edf9,if=ide,index=0,media=disk,force-lba=on,format=raw -net none -device VGA,vgamem_mb=8,rombar=1,romfile=,subvendor_id=0x5853,subsystem_id=0x0001,addr=2,qemu-extended-regs=false -vnc-clipboard-socket-fd 4 -xen-domid-restrict -chroot /var/xen/qemu/root-1 -runas 65536.994
Sep 15 13:40:58 xenserver12 qemu-dm-1[16518]: Moving to cgroup slice ''
Sep 15 13:40:58 xenserver12 qemu-dm-1[16518]: core dump limit: 67108864
Sep 15 13:40:59 xenserver12 qemu-dm-1[16518]: qemu-dm-1: -serial pty: char device redirected to /dev/pts/2 (label serial0)
Sep 15 13:43:19 xenserver12 /usr/lib64/xen/bin/emu-manager[17945]: Called with fork argument: `--fork true`.
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Startup: xenopsd control fds (8, 7).
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Startup: domid 1.
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Startup: operation mode (hvm_save, live).
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Emu `xenguest` is enabled.
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Emu `qemu` is enabled.
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Starting `/usr/libexec/xen/bin/xenguest`...
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: Command line: -debug -domid 1 -controloutfd 2 -controlinfd 0 -mode listen
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Connecting to `xenguest` (/var/xen/xenguest/1/control)...
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Connecting to `qemu` (/var/run/xen/qmp-libxl-1)...
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver: Adding client on fd 10 as (0)
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver: On (0) got message '{ "execute" : "migrate_init" }'
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Got QMP version negotiation.
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver: On (0) got message '{ "execute" : "track_dirty" }'
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver: On (0) got message '{ "execute" : "migrate_progress" }'
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: setting progress_cli to 0
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver: On (0) got message '{ "execute" : "migrate_live" }'
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: xc: detail: fd 11, dom 1, flags 1, hvm 1
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: xc: info: Saving domain 1, type x86 HVM
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: progress: Start of stream
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: Checking live policy.  1177600 / 0 for 0
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 0,"remaining": 1177600,"iteration": 0}}
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem 1177600, sent 0, iter 0, not waiting. Progress = 0
Sep 15 13:43:19 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 10240,"remaining": -1,"iteration": 0}}
Sep 15 13:43:19 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 10240, iter 0, not waiting. Progress = 0
Sep 15 13:43:20 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 21504,"remaining": -1,"iteration": 0}}
Sep 15 13:43:20 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 21504, iter 0, not waiting. Progress = 1
Sep 15 13:43:20 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 31744,"remaining": -1,"iteration": 0}}
Sep 15 13:43:20 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 31744, iter 0, not waiting. Progress = 2
Sep 15 13:43:21 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 43008,"remaining": -1,"iteration": 0}}
Sep 15 13:43:21 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 43008, iter 0, not waiting. Progress = 2
Sep 15 13:43:21 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 54272,"remaining": -1,"iteration": 0}}
Sep 15 13:43:21 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 54272, iter 0, not waiting. Progress = 3
Sep 15 13:43:22 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 65536,"remaining": -1,"iteration": 0}}
Sep 15 13:43:22 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 65536, iter 0, not waiting. Progress = 4
Sep 15 13:43:22 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 76800,"remaining": -1,"iteration": 0}}
Sep 15 13:43:22 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 76800, iter 0, not waiting. Progress = 5
Sep 15 13:43:23 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 88064,"remaining": -1,"iteration": 0}}
Sep 15 13:43:23 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 88064, iter 0, not waiting. Progress = 5
Sep 15 13:43:23 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 99328,"remaining": -1,"iteration": 0}}
Sep 15 13:43:23 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 99328, iter 0, not waiting. Progress = 6
Sep 15 13:43:24 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 0: 104448 of 1177600 (8%)
Sep 15 13:43:24 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 110592,"remaining": -1,"iteration": 0}}
Sep 15 13:43:24 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 110592, iter 0, not waiting. Progress = 7
Sep 15 13:43:25 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 120832,"remaining": -1,"iteration": 0}}
Sep 15 13:43:25 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 120832, iter 0, not waiting. Progress = 8
Sep 15 13:43:25 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 132096,"remaining": -1,"iteration": 0}}
Sep 15 13:43:25 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 132096, iter 0, not waiting. Progress = 8
Sep 15 13:43:26 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 143360,"remaining": -1,"iteration": 0}}
Sep 15 13:43:26 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 143360, iter 0, not waiting. Progress = 9
Sep 15 13:43:26 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 154624,"remaining": -1,"iteration": 0}}
Sep 15 13:43:26 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 154624, iter 0, not waiting. Progress = 10
Sep 15 13:43:27 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 165888,"remaining": -1,"iteration": 0}}
Sep 15 13:43:27 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 165888, iter 0, not waiting. Progress = 11
Sep 15 13:43:27 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 177152,"remaining": -1,"iteration": 0}}
Sep 15 13:43:27 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 177152, iter 0, not waiting. Progress = 12
Sep 15 13:43:28 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 188416,"remaining": -1,"iteration": 0}}
Sep 15 13:43:28 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 188416, iter 0, not waiting. Progress = 12
Sep 15 13:43:28 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 199680,"remaining": -1,"iteration": 0}}
Sep 15 13:43:28 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 199680, iter 0, not waiting. Progress = 13
Sep 15 13:43:29 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 210944,"remaining": -1,"iteration": 0}}
Sep 15 13:43:29 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 0: 210944 of 1177600 (17%)
Sep 15 13:43:29 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 210944, iter 0, not waiting. Progress = 14
Sep 15 13:43:29 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 222208,"remaining": -1,"iteration": 0}}
Sep 15 13:43:29 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 222208, iter 0, not waiting. Progress = 15
Sep 15 13:43:30 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 234496,"remaining": -1,"iteration": 0}}
Sep 15 13:43:30 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 234496, iter 0, not waiting. Progress = 15
Sep 15 13:43:30 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 245760,"remaining": -1,"iteration": 0}}
Sep 15 13:43:30 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 245760, iter 0, not waiting. Progress = 16
Sep 15 13:43:31 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 257024,"remaining": -1,"iteration": 0}}
Sep 15 13:43:31 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 257024, iter 0, not waiting. Progress = 17
Sep 15 13:43:31 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 268288,"remaining": -1,"iteration": 0}}
Sep 15 13:43:31 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 268288, iter 0, not waiting. Progress = 18
Sep 15 13:43:32 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 279552,"remaining": -1,"iteration": 0}}
Sep 15 13:43:32 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 279552, iter 0, not waiting. Progress = 18
Sep 15 13:43:32 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 290816,"remaining": -1,"iteration": 0}}
Sep 15 13:43:32 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 290816, iter 0, not waiting. Progress = 19
Sep 15 13:43:33 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 302080,"remaining": -1,"iteration": 0}}
Sep 15 13:43:33 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 302080, iter 0, not waiting. Progress = 20
Sep 15 13:43:34 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 312320,"remaining": -1,"iteration": 0}}
Sep 15 13:43:34 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 312320, iter 0, not waiting. Progress = 21
Sep 15 13:43:34 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 0: 316416 of 1177600 (26%)
Sep 15 13:43:34 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 323584,"remaining": -1,"iteration": 0}}
Sep 15 13:43:34 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 323584, iter 0, not waiting. Progress = 21
Sep 15 13:43:35 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 333824,"remaining": -1,"iteration": 0}}
Sep 15 13:43:35 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 333824, iter 0, not waiting. Progress = 22
Sep 15 13:43:35 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 345088,"remaining": -1,"iteration": 0}}
Sep 15 13:43:35 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 345088, iter 0, not waiting. Progress = 23
Sep 15 13:43:36 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 356352,"remaining": -1,"iteration": 0}}
Sep 15 13:43:36 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 356352, iter 0, not waiting. Progress = 24
Sep 15 13:43:36 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 367616,"remaining": -1,"iteration": 0}}
Sep 15 13:43:36 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 367616, iter 0, not waiting. Progress = 24
Sep 15 13:43:37 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 378880,"remaining": -1,"iteration": 0}}
Sep 15 13:43:37 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 378880, iter 0, not waiting. Progress = 25
Sep 15 13:43:37 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 389120,"remaining": -1,"iteration": 0}}
Sep 15 13:43:37 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 389120, iter 0, not waiting. Progress = 26
Sep 15 13:43:38 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 400384,"remaining": -1,"iteration": 0}}
Sep 15 13:43:38 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 400384, iter 0, not waiting. Progress = 27
Sep 15 13:43:38 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 411648,"remaining": -1,"iteration": 0}}
Sep 15 13:43:38 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 411648, iter 0, not waiting. Progress = 27
Sep 15 13:43:39 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 0: 420864 of 1177600 (35%)
Sep 15 13:43:39 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 421888,"remaining": -1,"iteration": 0}}
Sep 15 13:43:39 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 421888, iter 0, not waiting. Progress = 28
Sep 15 13:43:39 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 432128,"remaining": -1,"iteration": 0}}
Sep 15 13:43:39 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 432128, iter 0, not waiting. Progress = 29
Sep 15 13:43:40 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 443392,"remaining": -1,"iteration": 0}}
Sep 15 13:43:40 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 443392, iter 0, not waiting. Progress = 30
Sep 15 13:43:40 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 453632,"remaining": -1,"iteration": 0}}
Sep 15 13:43:40 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 453632, iter 0, not waiting. Progress = 30
Sep 15 13:43:41 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 463872,"remaining": -1,"iteration": 0}}
Sep 15 13:43:41 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 463872, iter 0, not waiting. Progress = 31
Sep 15 13:43:41 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 475136,"remaining": -1,"iteration": 0}}
Sep 15 13:43:41 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 475136, iter 0, not waiting. Progress = 32
Sep 15 13:43:42 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 486400,"remaining": -1,"iteration": 0}}
Sep 15 13:43:42 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 486400, iter 0, not waiting. Progress = 33
Sep 15 13:43:43 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 497664,"remaining": -1,"iteration": 0}}
Sep 15 13:43:43 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 497664, iter 0, not waiting. Progress = 33
Sep 15 13:43:43 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 507904,"remaining": -1,"iteration": 0}}
Sep 15 13:43:43 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 507904, iter 0, not waiting. Progress = 34
Sep 15 13:43:44 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 519168,"remaining": -1,"iteration": 0}}
Sep 15 13:43:44 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 519168, iter 0, not waiting. Progress = 35
Sep 15 13:43:44 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 0: 524288 of 1177600 (44%)
Sep 15 13:43:44 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 530432,"remaining": -1,"iteration": 0}}
Sep 15 13:43:44 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 530432, iter 0, not waiting. Progress = 36
Sep 15 13:43:45 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 541696,"remaining": -1,"iteration": 0}}
Sep 15 13:43:45 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 541696, iter 0, not waiting. Progress = 36
Sep 15 13:43:45 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 551936,"remaining": -1,"iteration": 0}}
Sep 15 13:43:45 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 551936, iter 0, not waiting. Progress = 37
Sep 15 13:43:46 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 563200,"remaining": -1,"iteration": 0}}
Sep 15 13:43:46 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 563200, iter 0, not waiting. Progress = 38
Sep 15 13:43:46 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 573440,"remaining": -1,"iteration": 0}}
Sep 15 13:43:46 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 573440, iter 0, not waiting. Progress = 38
Sep 15 13:43:47 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 583680,"remaining": -1,"iteration": 0}}
Sep 15 13:43:47 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 583680, iter 0, not waiting. Progress = 39
Sep 15 13:43:47 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 593920,"remaining": -1,"iteration": 0}}
Sep 15 13:43:47 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 593920, iter 0, not waiting. Progress = 40
Sep 15 13:43:48 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 604160,"remaining": -1,"iteration": 0}}
Sep 15 13:43:48 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 604160, iter 0, not waiting. Progress = 41
Sep 15 13:43:48 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 614400,"remaining": -1,"iteration": 0}}
Sep 15 13:43:48 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 614400, iter 0, not waiting. Progress = 41
Sep 15 13:43:49 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 624640,"remaining": -1,"iteration": 0}}
Sep 15 13:43:49 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 624640, iter 0, not waiting. Progress = 42
Sep 15 13:43:49 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 0: 626688 of 1177600 (53%)
Sep 15 13:43:49 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 634880,"remaining": -1,"iteration": 0}}
Sep 15 13:43:49 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 634880, iter 0, not waiting. Progress = 43
Sep 15 13:43:50 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 645120,"remaining": -1,"iteration": 0}}
Sep 15 13:43:50 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 645120, iter 0, not waiting. Progress = 43
Sep 15 13:43:50 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 656384,"remaining": -1,"iteration": 0}}
Sep 15 13:43:50 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 656384, iter 0, not waiting. Progress = 44
Sep 15 13:43:51 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 667648,"remaining": -1,"iteration": 0}}
Sep 15 13:43:51 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 667648, iter 0, not waiting. Progress = 45
Sep 15 13:43:51 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 677888,"remaining": -1,"iteration": 0}}
Sep 15 13:43:51 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 677888, iter 0, not waiting. Progress = 46
Sep 15 13:43:52 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 688128,"remaining": -1,"iteration": 0}}
Sep 15 13:43:52 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 688128, iter 0, not waiting. Progress = 46
Sep 15 13:43:52 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 699392,"remaining": -1,"iteration": 0}}
Sep 15 13:43:52 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 699392, iter 0, not waiting. Progress = 47
Sep 15 13:43:53 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 710656,"remaining": -1,"iteration": 0}}
Sep 15 13:43:53 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 710656, iter 0, not waiting. Progress = 48
Sep 15 13:43:53 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 720896,"remaining": -1,"iteration": 0}}
Sep 15 13:43:53 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 720896, iter 0, not waiting. Progress = 48
Sep 15 13:43:54 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 0: 728064 of 1177600 (61%)
Sep 15 13:43:54 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 731136,"remaining": -1,"iteration": 0}}
Sep 15 13:43:54 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 731136, iter 0, not waiting. Progress = 49
Sep 15 13:43:55 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 741376,"remaining": -1,"iteration": 0}}
Sep 15 13:43:55 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 741376, iter 0, not waiting. Progress = 50
Sep 15 13:43:55 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 751616,"remaining": -1,"iteration": 0}}
Sep 15 13:43:55 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 751616, iter 0, not waiting. Progress = 51
Sep 15 13:43:56 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 761856,"remaining": -1,"iteration": 0}}
Sep 15 13:43:56 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 761856, iter 0, not waiting. Progress = 51
Sep 15 13:43:56 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 773120,"remaining": -1,"iteration": 0}}
Sep 15 13:43:56 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 773120, iter 0, not waiting. Progress = 52
Sep 15 13:43:57 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 783360,"remaining": -1,"iteration": 0}}
Sep 15 13:43:57 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 783360, iter 0, not waiting. Progress = 53
Sep 15 13:43:57 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 794624,"remaining": -1,"iteration": 0}}
Sep 15 13:43:57 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 794624, iter 0, not waiting. Progress = 53
Sep 15 13:43:58 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 804864,"remaining": -1,"iteration": 0}}
Sep 15 13:43:58 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 804864, iter 0, not waiting. Progress = 54
Sep 15 13:43:58 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 816128,"remaining": -1,"iteration": 0}}
Sep 15 13:43:58 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 816128, iter 0, not waiting. Progress = 55
Sep 15 13:43:59 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 827392,"remaining": -1,"iteration": 0}}
Sep 15 13:43:59 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 827392, iter 0, not waiting. Progress = 56
Sep 15 13:43:59 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 0: 830464 of 1177600 (70%)
Sep 15 13:43:59 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 838656,"remaining": -1,"iteration": 0}}
Sep 15 13:43:59 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 838656, iter 0, not waiting. Progress = 56
Sep 15 13:44:00 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 849920,"remaining": -1,"iteration": 0}}
Sep 15 13:44:00 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 849920, iter 0, not waiting. Progress = 57
Sep 15 13:44:00 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 861184,"remaining": -1,"iteration": 0}}
Sep 15 13:44:00 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 861184, iter 0, not waiting. Progress = 58
Sep 15 13:44:01 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 872448,"remaining": -1,"iteration": 0}}
Sep 15 13:44:01 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 872448, iter 0, not waiting. Progress = 59
Sep 15 13:44:01 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 884736,"remaining": -1,"iteration": 0}}
Sep 15 13:44:01 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 884736, iter 0, not waiting. Progress = 60
Sep 15 13:44:02 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 896000,"remaining": -1,"iteration": 0}}
Sep 15 13:44:02 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 896000, iter 0, not waiting. Progress = 60
Sep 15 13:44:02 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 907264,"remaining": -1,"iteration": 0}}
Sep 15 13:44:02 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 907264, iter 0, not waiting. Progress = 61
Sep 15 13:44:03 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 918528,"remaining": -1,"iteration": 0}}
Sep 15 13:44:03 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 918528, iter 0, not waiting. Progress = 62
Sep 15 13:44:03 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 929792,"remaining": -1,"iteration": 0}}
Sep 15 13:44:03 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 929792, iter 0, not waiting. Progress = 63
Sep 15 13:44:04 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 0: 937984 of 1177600 (79%)
Sep 15 13:44:04 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 941056,"remaining": -1,"iteration": 0}}
Sep 15 13:44:04 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 941056, iter 0, not waiting. Progress = 63
Sep 15 13:44:05 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 952320,"remaining": -1,"iteration": 0}}
Sep 15 13:44:05 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 952320, iter 0, not waiting. Progress = 64
Sep 15 13:44:05 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 962560,"remaining": -1,"iteration": 0}}
Sep 15 13:44:05 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 962560, iter 0, not waiting. Progress = 65
Sep 15 13:44:06 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 972800,"remaining": -1,"iteration": 0}}
Sep 15 13:44:06 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 972800, iter 0, not waiting. Progress = 66
Sep 15 13:44:06 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 988160,"remaining": -1,"iteration": 0}}
Sep 15 13:44:06 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 988160, iter 0, not waiting. Progress = 67
Sep 15 13:44:07 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1058816,"remaining": -1,"iteration": 0}}
Sep 15 13:44:07 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1058816, iter 0, not waiting. Progress = 71
Sep 15 13:44:07 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1070080,"remaining": -1,"iteration": 0}}
Sep 15 13:44:07 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1070080, iter 0, not waiting. Progress = 72
Sep 15 13:44:08 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1081344,"remaining": -1,"iteration": 0}}
Sep 15 13:44:08 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1081344, iter 0, not waiting. Progress = 73
Sep 15 13:44:08 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1093632,"remaining": -1,"iteration": 0}}
Sep 15 13:44:08 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1093632, iter 0, not waiting. Progress = 74
Sep 15 13:44:09 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1104896,"remaining": -1,"iteration": 0}}
Sep 15 13:44:09 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1104896, iter 0, not waiting. Progress = 75
Sep 15 13:44:09 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 0: 1110016 of 1177600 (94%)
Sep 15 13:44:09 xenserver12 xenguest-1-emp[17946]: Checking live policy.  237432 / 1177600 for 1
Sep 15 13:44:09 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1177600,"remaining": 237432,"iteration": 1}}
Sep 15 13:44:09 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem 237432, sent 1177600, iter 1, not waiting. Progress = 83
Sep 15 13:44:10 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1189888,"remaining": -1,"iteration": 1}}
Sep 15 13:44:10 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1189888, iter 1, not waiting. Progress = 83
Sep 15 13:44:10 xenserver12 emu-manager-1[17945]: `xenguest` live stage is done!
Sep 15 13:44:10 xenserver12 xenguest-1-emp[17946]: libempserver: On (0) got message '{ "execute" : "migrate_pause" }'
Sep 15 13:44:10 xenserver12 xenguest-1-emp[17946]: Received pause message
Sep 15 13:44:10 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:44:10 xenserver12 xenguest-1-emp[17946]: libempserver: On (0) got message '{ "execute" : "migrate_paused" }'
Sep 15 13:44:10 xenserver12 xenguest-1-emp[17946]: Received paused message
Sep 15 13:44:10 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:44:10 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1202176,"remaining": -1,"iteration": 1}}
Sep 15 13:44:10 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1202176, iter 1, waiting. Progress = 84
Sep 15 13:44:11 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1214464,"remaining": -1,"iteration": 1}}
Sep 15 13:44:11 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1214464, iter 1, waiting. Progress = 85
Sep 15 13:44:11 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1226752,"remaining": -1,"iteration": 1}}
Sep 15 13:44:11 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1226752, iter 1, waiting. Progress = 85
Sep 15 13:44:12 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1239040,"remaining": -1,"iteration": 1}}
Sep 15 13:44:12 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1239040, iter 1, waiting. Progress = 86
Sep 15 13:44:12 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1251328,"remaining": -1,"iteration": 1}}
Sep 15 13:44:12 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1251328, iter 1, waiting. Progress = 87
Sep 15 13:44:13 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1264640,"remaining": -1,"iteration": 1}}
Sep 15 13:44:13 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1264640, iter 1, waiting. Progress = 88
Sep 15 13:44:13 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1276928,"remaining": -1,"iteration": 1}}
Sep 15 13:44:13 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1276928, iter 1, waiting. Progress = 88
Sep 15 13:44:14 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1289216,"remaining": -1,"iteration": 1}}
Sep 15 13:44:14 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1289216, iter 1, waiting. Progress = 89
Sep 15 13:44:14 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 1: 115712 of 237432 (48%)
Sep 15 13:44:14 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1301504,"remaining": -1,"iteration": 1}}
Sep 15 13:44:14 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1301504, iter 1, waiting. Progress = 90
Sep 15 13:44:15 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1312768,"remaining": -1,"iteration": 1}}
Sep 15 13:44:15 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1312768, iter 1, waiting. Progress = 90
Sep 15 13:44:15 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1324032,"remaining": -1,"iteration": 1}}
Sep 15 13:44:15 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1324032, iter 1, waiting. Progress = 91
Sep 15 13:44:16 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1335296,"remaining": -1,"iteration": 1}}
Sep 15 13:44:16 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1335296, iter 1, waiting. Progress = 92
Sep 15 13:44:16 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1346560,"remaining": -1,"iteration": 1}}
Sep 15 13:44:16 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1346560, iter 1, waiting. Progress = 92
Sep 15 13:44:17 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1357824,"remaining": -1,"iteration": 1}}
Sep 15 13:44:17 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1357824, iter 1, waiting. Progress = 93
Sep 15 13:44:17 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1369088,"remaining": -1,"iteration": 1}}
Sep 15 13:44:17 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1369088, iter 1, waiting. Progress = 94
Sep 15 13:44:18 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1380352,"remaining": -1,"iteration": 1}}
Sep 15 13:44:18 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1380352, iter 1, waiting. Progress = 94
Sep 15 13:44:18 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1391616,"remaining": -1,"iteration": 1}}
Sep 15 13:44:18 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1391616, iter 1, waiting. Progress = 95
Sep 15 13:44:19 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 1: 224256 of 237432 (94%)
Sep 15 13:44:19 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1403904,"remaining": -1,"iteration": 1}}
Sep 15 13:44:19 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1403904, iter 1, waiting. Progress = 96
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 1: 237432 of 237432 (100%)
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: passing down stop message
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: waiting for suspend
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: suspend was received
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1189888,"remaining": -1,"iteration": 1}}
Sep 15 13:44:20 xenserver12 emu-manager-1[17945]: Event for `xenguest`: rem -1, sent 1189888, iter 1, waiting. Progress = 83
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: progress: Frames iteration 2: 20396 of 20396 (100%)
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: Finished, send complete
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: libempserver:debug: Sending event
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"status":"completed"}}
Sep 15 13:44:20 xenserver12 emu-manager-1[17945]: Emu `xenguest` is completed.
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: libempserver: On (0) got message '{ "execute" : "migrate_abort" }'
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: Received abort command!
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: libempserver: On (0) got message '{ "execute" : "quit" }'
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: xencall:buffer: debug: total allocations:2833 total releases:2833
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: xencall:buffer: debug: current allocations:0 maximum allocations:3
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: xencall:buffer: debug: cache current size:1
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: xencall:buffer: debug: cache hits:1428 misses:1 toobig:1404
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: xencall:buffer: debug: total allocations:0 total releases:0
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: xencall:buffer: debug: current allocations:0 maximum allocations:0
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: xencall:buffer: debug: cache current size:0
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: xencall:buffer: debug: cache hits:0 misses:0 toobig:0
Sep 15 13:44:20 xenserver12 xenguest-1-emp[17946]: All done
Sep 15 13:44:20 xenserver12 emu-manager-1[17945]: Emu `xenguest` completed normally.
Sep 15 13:44:20 xenserver12 qemu-dm-1[16518]: qemu-dm-1: terminating on signal 15 from pid 1576 (<unknown process>)

cat /var/log/daemon.log | grep "emu|xenguest|emp" (RECIEVING SERVER)

[root@xenserver13 ~]# cat /var/log/daemon.log | grep "emu\|xenguest\|emp"
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: Command line: -controloutfd 7 -controlinfd 8 -mode hvm_build -image /usr/libexec/xen/boot/hvmloader -domid 1 -store_port 5 -store_domid 0 -console_port 6 -console_domid 0 -mem_max_mib 8184 -mem_start_mib 8184 -fork true
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: Domain Properties: Type HVM, hap 1
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: Determined the following parameters from xenstore:
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: vcpu/number:4 vcpu/weight:256 vcpu/cap:0
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: nx: 1, pae 1, cores-per-socket 1, x86-fip-width 0, nested 0
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: apic: 1 acpi: 1 acpi_s4: 0 acpi_s3: 0 tsc_mode: 0 hpet: 1
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: nomigrate 0, timeoffset 10800
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: viridian: 0, time_ref_count: 0, reference_tsc: 0
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: vcpu/0/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: vcpu/1/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: vcpu/2/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: vcpu/3/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_allocate: cmdline="(null)", features="(null)"
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: Calculated provisional MMIO hole size as 0x10000000
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: Final lower MMIO hole size is 0x10000000
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_kernel_file: filename="/usr/libexec/xen/boot/hvmloader"
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_malloc_filemap    : 582 kB
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_boot_xen_init: ver 4.7, caps xen-3.0-x86_64 xen-3.0-x86_32p hvm-3.0-x86_32 hvm-3.0-x86_32p hvm-3.0-x86_64
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_parse_image: called
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_find_loader: trying multiboot-binary loader ...
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: loader probe failed
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_find_loader: trying HVM-generic loader ...
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: loader probe OK
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: xc: detail: elf_parse_binary: phdr: paddr=0x100000 memsz=0x7acc4
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: xc: detail: elf_parse_binary: memory: 0x100000 -> 0x17acc4
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_mem_init: mem 8184 MB, pages 0x1ff800 pages, 4k each
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_mem_init: 0x1ff800 pages
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_boot_mem_init: called
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_malloc            : 16880 kB
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: xc: detail: PHYSICAL MEMORY ALLOCATION:
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: xc: detail:   4KB PAGES: 0x0000000000000200
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: xc: detail:   2MB PAGES: 0x00000000000003fb
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: xc: detail:   1GB PAGES: 0x0000000000000006
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_build_image: called
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_pfn_to_ptr_retcount: domU mapping: pfn 0x100+0x7b at 0x7f2cdbd53000
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_alloc_segment:   kernel       : 0x100000 -> 0x17b000  (pfn 0x100 + 0x7b pages)
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: xc: detail: elf_load_binary: phdr 0 at 0x7f2cdbcd8000 -> 0x7f2cdbd49111
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: alloc_pgtables_hvm: doing nothing
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_build_image  : virt_alloc_end : 0x17b000
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_build_image  : virt_pgtab_end : 0x0
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_boot_image: called
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: bootearly: doing nothing
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_compat_check: supported guest type: xen-3.0-x86_64
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_compat_check: supported guest type: xen-3.0-x86_32p
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_compat_check: supported guest type: hvm-3.0-x86_32 <= matches
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_compat_check: supported guest type: hvm-3.0-x86_32p
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_compat_check: supported guest type: hvm-3.0-x86_64
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: clear_page: pfn 0xfefff, mfn 0xfefff
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: clear_page: pfn 0xfeffc, mfn 0xfeffc
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: domain builder memory footprint
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail:    allocated
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail:       malloc             : 16885 kB
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail:       anon mmap          : 0 bytes
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail:    mapped
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail:       file mmap          : 582 kB
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail:       domU mmap          : 492 kB
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: vcpu_hvm: called
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_release: called
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: Parsing '17cbfbff-97ba2223-2d93fbff-00000003-00000001-00000000-00000000-00000000-00001000-9c000400' as featureset
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: domainbuilder: detail: xc_dom_gnttab_hvm_seed: called, pfn=0x20f800
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: Writing to control: 'result:1044476 1044479#012'
Sep 15 07:30:06 xenserver13 xenguest-1-build[32062]: All done
Sep 15 07:30:16 xenserver13 forkexecd: [ info|xenserver13|0 ||forkexecd] qemu-dm-1[32766]: Arguments: 1 --syslog -std-vga -videoram 8 -vnc unix:/var/run/xen/vnc-1,lock-key-sync=off -acpi -monitor null -xen-domid 1 -m size=8192 -boot order=dcn -usb -device usb-tablet,port=2 -smp 4,maxcpus=4 -serial pty -display none -nodefaults -trace enable=xen_platform_log -sandbox on,obsolete=deny,elevateprivileges=allow,spawn=deny,resourcecontrol=deny -S -global PIIX4_PM.revision_id=0x1 -global ide-hd.ver=0.10.2 -global piix3-ide-xen.subvendor_id=0x5853 -global piix3-ide-xen.subsystem_id=0x0001 -global piix3-usb-uhci.subvendor_id=0x5853 -global piix3-usb-uhci.subsystem_id=0x0001 -global rtl8139.subvendor_id=0x5853 -global rtl8139.subsystem_id=0x0001 -parallel null -qmp unix:/var/run/xen/qmp-libxl-1,server,nowait -qmp unix:/var/run/xen/qmp-event-1,server,nowait -device xen-platform,addr=3,device-id=0x0001,revision=0x2,class-id=0x0100,subvendor_id=0x5853,subsystem_id=0x0001 -drive file=/dev/sm/backend/31f1bc5f-9e95-b068-57c3-7d74f31e5234/51c48ebe-a3b3-47e6-be84-5ba68f274f9e,if=ide,index=0,media=disk,force-lba=on,format=raw -device rtl8139,netdev=tapnet1,mac=1e:81:bb:79:77:bf,addr=5 -netdev tap,id=tapnet1,fd=7 -device rtl8139,netdev=tapnet0,mac=16:9e:63:f3:30:17,addr=4 -netdev tap,id=tapnet0,fd=8
Sep 15 07:30:16 xenserver13 forkexecd: [ info|xenserver13|0 ||forkexecd] qemu-dm-1[32766]: Exec: /usr/lib64/xen/bin/qemu-system-i386 qemu-dm-1 -machine pc-0.10,accel=xen,max-ram-below-4g=4026531840,allow-unassigned=true,trad_compat=true -vnc unix:/var/run/xen/vnc-1,lock-key-sync=off -monitor null -xen-domid 1 -m size=8192 -boot order=dcn -usb -device usb-tablet,port=2 -smp 4,maxcpus=4 -serial pty -display none -nodefaults -trace enable=xen_platform_log -sandbox on,obsolete=deny,elevateprivileges=allow,spawn=deny,resourcecontrol=deny -S -global PIIX4_PM.revision_id=0x1 -global ide-hd.ver=0.10.2 -global piix3-ide-xen.subvendor_id=0x5853 -global piix3-ide-xen.subsystem_id=0x0001 -global piix3-usb-uhci.subvendor_id=0x5853 -global piix3-usb-uhci.subsystem_id=0x0001 -global rtl8139.subvendor_id=0x5853 -global rtl8139.subsystem_id=0x0001 -parallel null -qmp unix:/var/run/xen/qmp-libxl-1,server,nowait -qmp unix:/var/run/xen/qmp-event-1,server,nowait -device xen-platform,addr=3,device-id=0x0001,revision=0x2,class-id=0x0100,subvendor_id=0x5853,subsystem_id=0x0001 -drive file=/dev/sm/backend/31f1bc5f-9e95-b068-57c3-7d74f31e5234/51c48ebe-a3b3-47e6-be84-5ba68f274f9e,if=ide,index=0,media=disk,force-lba=on,format=raw -device rtl8139,netdev=tapnet1,mac=1e:81:bb:79:77:bf,addr=5 -netdev tap,id=tapnet1,fd=7 -device rtl8139,netdev=tapnet0,mac=16:9e:63:f3:30:17,addr=4 -netdev tap,id=tapnet0,fd=8 -device VGA,vgamem_mb=8,rombar=1,romfile=,subvendor_id=0x5853,subsystem_id=0x0001,addr=2,qemu-extended-regs=false -vnc-clipboard-socket-fd 4 -xen-domid-restrict -chroot /var/xen/qemu/root-1 -runas 65536.994
Sep 15 07:30:16 xenserver13 qemu-dm-1[334]: Moving to cgroup slice ''
Sep 15 07:30:16 xenserver13 qemu-dm-1[334]: core dump limit: 67108864
Sep 15 07:30:16 xenserver13 qemu-dm-1[334]: qemu-dm-1: -serial pty: char device redirected to /dev/pts/2 (label serial0)
Sep 15 09:47:46 xenserver13 systemd[1]: Starting Cleanup of Temporary Directories...
Sep 15 09:47:46 xenserver13 systemd[1]: Started Cleanup of Temporary Directories.
Sep 15 13:43:19 xenserver13 /usr/lib64/xen/bin/emu-manager[30452]: Called with fork argument: `--fork true`.
Sep 15 13:43:19 xenserver13 emu-manager-2[30452]: Startup: xenopsd control fds (8, 7).
Sep 15 13:43:19 xenserver13 emu-manager-2[30452]: Startup: domid 2.
Sep 15 13:43:19 xenserver13 emu-manager-2[30452]: Startup: operation mode (hvm_restore, non-live).
Sep 15 13:43:19 xenserver13 emu-manager-2[30452]: Emu `xenguest` is enabled.
Sep 15 13:43:19 xenserver13 emu-manager-2[30452]: Emu `qemu` is enabled.
Sep 15 13:43:19 xenserver13 emu-manager-2[30452]: Starting `/usr/libexec/xen/bin/xenguest`...
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: Command line: -debug -domid 2 -controloutfd 2 -controlinfd 0 -mode listen
Sep 15 13:43:19 xenserver13 emu-manager-2[30452]: Connecting to `xenguest` (/var/xen/xenguest/2/control)...
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: libempserver: Adding client on fd 10 as (0)
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: libempserver: On (0) got message '{ "execute" : "migrate_init" }'
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: libempserver: On (0) got message '{ "execute" : "set_args", "arguments" : { "store_port":"5", "console_port":"6" } }'
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: libempserver: On (0) got message '{ "execute" : "restore" }'
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: Domain Properties: Type HVM, hap 1
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: Determined the following parameters from xenstore:
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: vcpu/number:4 vcpu/weight:256 vcpu/cap:0
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: nx: 1, pae 1, cores-per-socket 1, x86-fip-width 0, nested 0
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: apic: 1 acpi: 1 acpi_s4: 0 acpi_s3: 0 tsc_mode: 0 hpet: 1
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: nomigrate 0, timeoffset 10800
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: viridian: 0, time_ref_count: 0, reference_tsc: 0
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: vcpu/0/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: vcpu/1/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: vcpu/2/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: vcpu/3/affinity:1111111111111111111111111111111111111111111111111111111111111111
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: xc: detail: fd 11, dom 2, hvm 1, pae 1, superpages 0, stream_type 0
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: xc: info: Found x86 HVM domain from Xen 4.7
Sep 15 13:43:19 xenserver13 xenguest-2-emp[30454]: xc: info: Restoring domain
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: domainbuilder: detail: xc_dom_gnttab_hvm_seed: called, pfn=0x10f800
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xc: info: Restore successful
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xc: info: XenStore: mfn 0xfeffc, dom 0, evt 5
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xc: info: Console: mfn 0xfefff, dom 0, evt 6
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: Parsing '17cbfbff-97ba2223-2d93fbff-00000003-00000001-00000000-00000000-00000000-00001000-9c000400' as featureset
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: Restore complete, send result
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: libempserver:debug: Sending event
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"status":"completed","result":"1044476 1044479"}}
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: All done
Sep 15 13:44:20 xenserver13 emu-manager-2[30452]: Emu `xenguest` is completed.
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: libempserver: On (0) got message '{ "execute" : "quit" }'
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: libempserver:debug: replying to (0): { "return" : {} }
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xencall:buffer: debug: total allocations:2123 total releases:2123
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xencall:buffer: debug: current allocations:0 maximum allocations:2
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xencall:buffer: debug: cache current size:2
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xencall:buffer: debug: cache hits:1096 misses:2 toobig:1025
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xencall:buffer: debug: total allocations:0 total releases:0
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xencall:buffer: debug: current allocations:0 maximum allocations:0
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xencall:buffer: debug: cache current size:0
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: xencall:buffer: debug: cache hits:0 misses:0 toobig:0
Sep 15 13:44:20 xenserver13 xenguest-2-emp[30454]: All done
Sep 15 13:44:20 xenserver13 emu-manager-2[30452]: Emu `xenguest` completed normally.
[root@xenserver13 ~]#

Relevant output from "xensource.log" from sending server - 

Sep 15 13:56:09 xenserver12 xapi: [ info|xenserver12|66894 INET :::80|Async.VM.pool_migrate R:cb67d5d07c2b|xapi] xenops: VM.migrate 8629520f-5a82-9fd6-a324-961d510f267d to http://192.168.3.225/services/xenops?session_id=OpaqueRef:8430c7dc-96b2-4eeb-9227-35921f06fbf1
Sep 15 13:56:09 xenserver12 xenopsd-xc: [debug|xenserver12|580 |queue|xenops_server] Queue.push ["VM_migrate",["8629520f-5a82-9fd6-a324-961d510f267d",{},{},{},"http://192.168.3.225/services/xenops?session_id=OpaqueRef:8430c7dc-96b2-4eeb-9227-35921f06fbf1"]] onto 8629520f-5a82-9fd6-a324-961d510f267d:[  ]
Sep 15 13:56:09 xenserver12 xenopsd-xc: [debug|xenserver12|18 ||xenops_server] Queue.pop returned ["VM_migrate",["8629520f-5a82-9fd6-a324-961d510f267d",{},{},{},"http://192.168.3.225/services/xenops?session_id=OpaqueRef:8430c7dc-96b2-4eeb-9227-35921f06fbf1"]]
Sep 15 13:56:09 xenserver12 xenopsd-xc: [debug|xenserver12|18 |Async.VM.pool_migrate R:cb67d5d07c2b|xenops_server] Task 43 reference Async.VM.pool_migrate R:cb67d5d07c2b: ["VM_migrate",["8629520f-5a82-9fd6-a324-961d510f267d",{},{},{},"http://192.168.3.225/services/xenops?session_id=OpaqueRef:8430c7dc-96b2-4eeb-9227-35921f06fbf1"]]
Sep 15 13:56:09 xenserver12 xenopsd-xc: [debug|xenserver12|18 |Async.VM.pool_migrate R:cb67d5d07c2b|xenops_server] VM.migrate 8629520f-5a82-9fd6-a324-961d510f267d -> http://192.168.3.225/services/xenops?session_id=OpaqueRef:8430c7dc-96b2-4eeb-9227-35921f06fbf1
Sep 15 13:56:09 xenserver12 xenopsd-xc: [ info|xenserver12|18 |Async.VM.pool_migrate R:cb67d5d07c2b|xenops_server] Caught Xenops_interface.Does_not_exist(_) executing ["VM_migrate",["8629520f-5a82-9fd6-a324-961d510f267d",{},{},{},"http://192.168.3.225/services/xenops?session_id=OpaqueRef:8430c7dc-96b2-4eeb-9227-35921f06fbf1"]]: triggering cleanup actions
Sep 15 13:56:09 xenserver12 xenopsd-xc: [debug|xenserver12|18 |Async.VM.pool_migrate R:cb67d5d07c2b|xenops_server] Task 44 reference Async.VM.pool_migrate R:cb67d5d07c2b: ["VM_check_state","8629520f-5a82-9fd6-a324-961d510f267d"]
Sep 15 13:56:09 xenserver12 xenopsd-xc: [ info|xenserver12|18 |Async.VM.pool_migrate R:cb67d5d07c2b|xenops_server] Caught Xenops_interface.Does_not_exist(_) executing ["VM_check_state","8629520f-5a82-9fd6-a324-961d510f267d"]: triggering cleanup actions
Sep 15 13:56:09 xenserver12 xenopsd-xc: [debug|xenserver12|18 ||xenops_server] TASK.signal 43 = ["Failed",["Does_not_exist",["VM","8629520f-5a82-9fd6-a324-961d510f267d/config"]]]
jakubeliasz commented 4 years ago

same here, trying to migrate a VM with no network devices fails with:

"Failed","Migrating VM 'test' from 'xcp2' to 'xcp1' Internal error: xenopsd internal error: Xenops_migrate.Remote_failed("error from remote: Xs_protocol.Enoent(\"directory\")")

VM shows as running but actually it's not:

"Failed","Shutting down VM 'test' on 'xcp2' Internal error: Object with type VM and id 34e4c391-9a72-fb9b-0436-395e727cf273/config does not exist in xenopsd","xcp2"

Restarting toolstack on xcp2 helps and VM is shown as shut off.

stormi commented 4 years ago

This looks like the same issue as what the patch described in https://xcp-ng.org/forum/topic/2279/fix-to-xcp-ng fixes. You'll find on that thread updated xenops and xenopsd RPMs for XCP-ng 8.0. Could you install them, restart the toolstack, and test again with a VM with no network device?

jakubeliasz commented 4 years ago

@stormi yes, with those two updated RPMs I am able to migrate a networkless VM, thank you!

elialum commented 4 years ago

Thanks for the fix @stormi ! I noted it's flagged as "version 8", a patch will also be available for 7.6?

stormi commented 4 years ago

I thought the bug was only on 8.0. I can easily provide a fix for 7.6 too. The drawback is that updating xenopsd can cause migration failures during the pool update, so I'm not sure yet that I will deliver the update to everyone as a mandatory update. I'd like not to cause more harm than good.

elialum commented 4 years ago

Well, live migration failures still happening on a regular basis still... (7.6 latest updates) To be honest, We gave up :/

I don't see how the live migration going to be as stable as vmware vmotion anytime soon...

olivierlambert commented 4 years ago

I never had migration failure in my production. Maybe because I'm using shared storage and it's less prone to failure.

elialum commented 4 years ago

We only use enterprise shared storage here (NetApp). 3 out of 10 VMS are failing

elialum commented 4 years ago

Mostly CentOS boxes BTW, with heavy IO / CPU usage For some reason Debian/Ubunto never failed

olivierlambert commented 4 years ago

Okay I have mostly Debian guest, so it might explain the diff. Feel free to open support ticket so our team can take a look remotely and investigate.

stormi commented 4 years ago

Since there was positive feedback, I have sent builds of the patched xenopsd packages to the testing repositories, as a first step towards providing them as official updates.

You can test them on 7.6 and 8.0

On 8.0

yum update xenopsd xenopsd-xc --enablerepo=xcp-ng-testing
xe-toolstack-restart

On 7.6

yum update xenopsd xenopsd-xc xenopsd-xenlight --enablerepo=xcp-ng-updates_testing
xe-toolstack-restart
stormi commented 4 years ago

XCP-ng 8.1 has the fixed behaviour. I still hesitate regarding 8.0, as updating xenopsd can cause more migration issues during the upgrade than it solves. 7.6 is now EOL but the update remains available in the xcp-ng-testing repo for anyone who needs it.

elialum commented 4 years ago

Confirmed fixed after updating from "xcp-ng-updates_testing" repo see also https://github.com/xcp-ng/xcp/issues/395

stormi commented 4 years ago

Leaving open since the fix is not published to official repos for 8.0.

stormi commented 4 years ago

I don't think I'm ever going to push this update to 8.0 update repositories, due to the risks of unwanted downtime during the update process itself. XCP-ng 8.1 has the fixed behaviour and the update candidate is still available if needed in 8.0's testing repository:

yum update xenopsd xenopsd-xc --enablerepo=xcp-ng-testing
xe-toolstack-restart