@bleader said in XCP-ng 8.2 updates announcements and testing:

Hello @NielsH, no, that XSA is on the guest side, the fixes will be in the kernel used by the guest, unless we missed something, there is currently nothing to be done on the host kernel side.

Hi @bleader
Thanks for your response!

As these vulnerabilities are sometimes very unclear impact-wise; could you perhaps clarify for me:
Does this mean an untrusted VM, that chooses not to run this kernel, could potentially cause harm for the host or to other VMs?

Or is the impact only within the context of the VM, i.e. guest user processes might be able to read data from other processes only inside that VM?

Thanks again!

Hi all,

A little while ago XSA-466 came out. I couldn't find this on the forum / blog and would like to double-check whether xcp-ng is still vulnerable or not.

The post is here: https://xenbits.xen.org/xsa/advisory-466.html

I believe the fix for this would need to be in the xcp-ng host kernel?

Cheers!
Niels

@CJ said in Updates announcements and testing:

@NielsH Kind of off topic but figured I'd mention it as I only recently discovered this.

Not sure what VMs you're running, but if they can survive being off for a short time (redundancy of services or planned outage) you can reboot the host using Smart Reboot under the Advanced tab. While it incurs some downtime, it allows for a much faster reboot time than migrating the VMs to another server and back.

I use local storage as well and it's been a game changer for dealing with pool patches.

Cheers, thanks for the suggestion. In our case we actually are phashing out xcp-ng and are in the process of migrating to Proxmox since we can migrate with 30-35Gbit/s there. The disk performance is so much faster there we can perform all the updates in a single day instead of 2 weeks

Another issue we had was that VM migrations of very large VMs (usually 8cores+) are quite impactful. Because we want to use VMs with 24-48 cores and 128GB RAM as well it simply was not usable enough for us. There's several seconds, or sometimes even minutes of downtime during the last phase of the migration with the large VMs.

With Proxmox we have seen very little downtime (<1s) which we are very happy about.

@olivierlambert said in Updates announcements and testing:

Hello @NielsH I don't want to sound moralistic, but if you are using XCP-ng in production without any subscription, and being worried about patches coming fast enough for your production system, you should really think about getting support for it That's exactly what the subscription money is made for! (well, in part but absolutely used for that).

I mean, you are free to not doing it, and even if we do our best to treat everyone fairly (paying or not) for our patches, we won't be against more support so the project can continue to grow

Hey,

No worries, I understand your point.
For us specifically, we use local storage and the time it takes to migrate all VMs to a different host, reboot, next host, etc... is about 1-1.5 weeks during working hours. This is why, if another batch of updates is coming soon, we would rather wait and do everything at once instead of update twice in a row. I'm aware of the Rolling Pool Upgrade feature but it is not compatible with local storage.

Regarding XCP-ng Pro support, currently the pricing is a bit too steep for us to be feasable due to the amount of hosts we have. We do however pay for XOA Premium which is more affordable and we do find it valuable to support the developers.

I believe I did see some of your posts around regarding a possible all-in pricing plan which may be interesting for us, so once more details regarding that are available it is something for us to look into

@gduperrey Thanks!

I see that shortly after this some more security related patched have become available:
XSA-432: https://www.openwall.com/lists/oss-security/2023/08/08/3
XSA-434: https://www.openwall.com/lists/oss-security/2023/08/08/4
XSA-435: https://www.openwall.com/lists/oss-security/2023/08/08/5

Some of this also seems pretty serious. We were currently busy running patches on our systems. This takes us about 1-2 weeks to complete. Do you think these 3 patches will also become available for XCP-ng? In that case we'd rather wait for those to become available so we don't have to spend another 1-2 weeks immediately after completing the current set of patches.

Thank you!

Yesterday Zenbleed (https://news.ycombinator.com/item?id=36848680) was announced. It mentions there that AMD may have already released microcode patches to fix this.
Is this perhaps the mysterious microcode update form may 16th?

AMD microcode (linux-firmware) and Intel microcode (microcode_ctl). AMD and Intel did not detail what they fix, but everyone is supposed to update. This is the frustrating situation with binary blobs in firmware.

Or can we expect another update to resolve the zenbleed vulnerability in the coming days?

Part 3:

Mar  7 17:00:44 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 164864,"remaining": -1,"iteration": 0}}
Mar  7 17:00:44 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 164864, iter 0, not waiting. Progress = 0
Mar  7 17:00:44 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 166912,"remaining": -1,"iteration": 0}}
Mar  7 17:00:44 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 166912, iter 0, not waiting. Progress = 0
Mar  7 17:00:45 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 168960,"remaining": -1,"iteration": 0}}
Mar  7 17:00:45 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 168960, iter 0, not waiting. Progress = 0
Mar  7 17:00:46 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 171008,"remaining": -1,"iteration": 0}}
Mar  7 17:00:46 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 171008, iter 0, not waiting. Progress = 0
Mar  7 17:00:46 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 172032 of 25229312 (0%)
Mar  7 17:00:47 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 173056,"remaining": -1,"iteration": 0}}
Mar  7 17:00:47 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 173056, iter 0, not waiting. Progress = 0
Mar  7 17:00:47 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 174080,"remaining": -1,"iteration": 0}}
Mar  7 17:00:47 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 174080, iter 0, not waiting. Progress = 0
Mar  7 17:00:48 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 176128,"remaining": -1,"iteration": 0}}
Mar  7 17:00:48 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 176128, iter 0, not waiting. Progress = 0
Mar  7 17:00:49 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 178176,"remaining": -1,"iteration": 0}}
Mar  7 17:00:49 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 178176, iter 0, not waiting. Progress = 0
Mar  7 17:00:50 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 180224,"remaining": -1,"iteration": 0}}
Mar  7 17:00:50 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 180224, iter 0, not waiting. Progress = 0
Mar  7 17:00:50 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 182272,"remaining": -1,"iteration": 0}}
Mar  7 17:00:50 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 182272, iter 0, not waiting. Progress = 0
Mar  7 17:00:51 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 184320,"remaining": -1,"iteration": 0}}
Mar  7 17:00:51 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 184320, iter 0, not waiting. Progress = 0
Mar  7 17:00:51 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 185344 of 25229312 (0%)
Mar  7 17:00:52 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 186368,"remaining": -1,"iteration": 0}}
Mar  7 17:00:52 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 186368, iter 0, not waiting. Progress = 0
Mar  7 17:00:52 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 188416,"remaining": -1,"iteration": 0}}
Mar  7 17:00:52 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 188416, iter 0, not waiting. Progress = 0
Mar  7 17:00:53 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 190464,"remaining": -1,"iteration": 0}}
Mar  7 17:00:53 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 190464, iter 0, not waiting. Progress = 0
Mar  7 17:00:54 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 192512,"remaining": -1,"iteration": 0}}
Mar  7 17:00:54 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 192512, iter 0, not waiting. Progress = 0
Mar  7 17:00:54 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 194560,"remaining": -1,"iteration": 0}}
Mar  7 17:00:54 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 194560, iter 0, not waiting. Progress = 0
Mar  7 17:00:55 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 196608,"remaining": -1,"iteration": 0}}
Mar  7 17:00:55 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 196608, iter 0, not waiting. Progress = 0
Mar  7 17:00:56 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 198656,"remaining": -1,"iteration": 0}}
Mar  7 17:00:56 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 198656, iter 0, not waiting. Progress = 0
Mar  7 17:00:56 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 200704,"remaining": -1,"iteration": 0}}
Mar  7 17:00:56 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 200704, iter 0, not waiting. Progress = 0
Mar  7 17:00:57 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 201728 of 25229312 (0%)
Mar  7 17:00:57 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 202752,"remaining": -1,"iteration": 0}}
Mar  7 17:00:57 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 202752, iter 0, not waiting. Progress = 0
Mar  7 17:00:58 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 204800,"remaining": -1,"iteration": 0}}
Mar  7 17:00:58 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 204800, iter 0, not waiting. Progress = 0
Mar  7 17:00:58 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 206848,"remaining": -1,"iteration": 0}}
Mar  7 17:00:58 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 206848, iter 0, not waiting. Progress = 0
Mar  7 17:00:59 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 208896,"remaining": -1,"iteration": 0}}
Mar  7 17:00:59 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 208896, iter 0, not waiting. Progress = 0
Mar  7 17:01:00 ede-vmh001 systemd[1]: Started Session c89813 of user root.
Mar  7 17:01:00 ede-vmh001 systemd[1]: Starting Session c89813 of user root.
Mar  7 17:01:00 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 210944,"remaining": -1,"iteration": 0}}
Mar  7 17:01:00 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 210944, iter 0, not waiting. Progress = 0
Mar  7 17:01:00 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 212992,"remaining": -1,"iteration": 0}}
Mar  7 17:01:00 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 212992, iter 0, not waiting. Progress = 0
Mar  7 17:01:01 ede-vmh001 systemd[1]: Started Session c89814 of user root.
Mar  7 17:01:01 ede-vmh001 systemd[1]: Starting Session c89814 of user root.
Mar  7 17:01:01 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 215040,"remaining": -1,"iteration": 0}}
Mar  7 17:01:01 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 215040, iter 0, not waiting. Progress = 0
Mar  7 17:01:02 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 217088,"remaining": -1,"iteration": 0}}
Mar  7 17:01:02 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 217088, iter 0, not waiting. Progress = 0
Mar  7 17:01:02 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 218112 of 25229312 (0%)
Mar  7 17:01:02 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 219136,"remaining": -1,"iteration": 0}}
Mar  7 17:01:02 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 219136, iter 0, not waiting. Progress = 0
Mar  7 17:01:03 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 221184,"remaining": -1,"iteration": 0}}
Mar  7 17:01:03 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 221184, iter 0, not waiting. Progress = 0
Mar  7 17:01:03 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 223232,"remaining": -1,"iteration": 0}}
Mar  7 17:01:03 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 223232, iter 0, not waiting. Progress = 0
Mar  7 17:01:04 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 225280,"remaining": -1,"iteration": 0}}
Mar  7 17:01:04 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 225280, iter 0, not waiting. Progress = 0
Mar  7 17:01:05 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 227328,"remaining": -1,"iteration": 0}}
Mar  7 17:01:05 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 227328, iter 0, not waiting. Progress = 0
Mar  7 17:01:05 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 229376,"remaining": -1,"iteration": 0}}
Mar  7 17:01:05 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 229376, iter 0, not waiting. Progress = 0
Mar  7 17:01:06 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 231424,"remaining": -1,"iteration": 0}}
Mar  7 17:01:06 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 231424, iter 0, not waiting. Progress = 0
Mar  7 17:01:06 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 233472,"remaining": -1,"iteration": 0}}
Mar  7 17:01:06 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 233472, iter 0, not waiting. Progress = 0
Mar  7 17:01:07 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 236544,"remaining": -1,"iteration": 0}}
Mar  7 17:01:07 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 236544 of 25229312 (0%)
Mar  7 17:01:07 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 236544, iter 0, not waiting. Progress = 0
Mar  7 17:01:08 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 239616,"remaining": -1,"iteration": 0}}
Mar  7 17:01:08 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 239616, iter 0, not waiting. Progress = 0
Mar  7 17:01:08 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 242688,"remaining": -1,"iteration": 0}}
Mar  7 17:01:08 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 242688, iter 0, not waiting. Progress = 0
Mar  7 17:01:09 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 245760,"remaining": -1,"iteration": 0}}
Mar  7 17:01:09 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 245760, iter 0, not waiting. Progress = 0
Mar  7 17:01:10 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 247808,"remaining": -1,"iteration": 0}}
Mar  7 17:01:10 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 247808, iter 0, not waiting. Progress = 0
Mar  7 17:01:10 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 249856,"remaining": -1,"iteration": 0}}
Mar  7 17:01:10 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 249856, iter 0, not waiting. Progress = 0
Mar  7 17:01:11 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 252928,"remaining": -1,"iteration": 0}}
Mar  7 17:01:11 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 252928, iter 0, not waiting. Progress = 0
Mar  7 17:01:12 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 256000,"remaining": -1,"iteration": 0}}
Mar  7 17:01:12 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 256000, iter 0, not waiting. Progress = 0
Mar  7 17:01:12 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 258048 of 25229312 (1%)
Mar  7 17:01:12 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 259072,"remaining": -1,"iteration": 0}}
Mar  7 17:01:12 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 259072, iter 0, not waiting. Progress = 0
Mar  7 17:01:13 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 262144,"remaining": -1,"iteration": 0}}
Mar  7 17:01:13 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 262144, iter 0, not waiting. Progress = 0
Mar  7 17:01:14 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 264192,"remaining": -1,"iteration": 0}}
Mar  7 17:01:14 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 264192, iter 0, not waiting. Progress = 0
Mar  7 17:01:14 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 267264,"remaining": -1,"iteration": 0}}
Mar  7 17:01:14 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 267264, iter 0, not waiting. Progress = 0
Mar  7 17:01:15 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 269312,"remaining": -1,"iteration": 0}}
Mar  7 17:01:15 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 269312, iter 0, not waiting. Progress = 0
Mar  7 17:01:16 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 272384,"remaining": -1,"iteration": 0}}
Mar  7 17:01:16 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 272384, iter 0, not waiting. Progress = 0
Mar  7 17:01:16 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 275456,"remaining": -1,"iteration": 0}}
Mar  7 17:01:16 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 275456, iter 0, not waiting. Progress = 0
Mar  7 17:01:17 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 277504,"remaining": -1,"iteration": 0}}
Mar  7 17:01:17 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 277504, iter 0, not waiting. Progress = 0
Mar  7 17:01:17 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 278528 of 25229312 (1%)
Mar  7 17:01:17 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 279552,"remaining": -1,"iteration": 0}}
Mar  7 17:01:17 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 279552, iter 0, not waiting. Progress = 0
Mar  7 17:01:18 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 281600,"remaining": -1,"iteration": 0}}
Mar  7 17:01:18 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 281600, iter 0, not waiting. Progress = 0
Mar  7 17:01:19 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 283648,"remaining": -1,"iteration": 0}}
Mar  7 17:01:19 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 283648, iter 0, not waiting. Progress = 0
Mar  7 17:01:19 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 285696,"remaining": -1,"iteration": 0}}
Mar  7 17:01:19 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 285696, iter 0, not waiting. Progress = 0
Mar  7 17:01:20 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 287744,"remaining": -1,"iteration": 0}}
Mar  7 17:01:20 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 287744, iter 0, not waiting. Progress = 0
Mar  7 17:01:21 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 289792,"remaining": -1,"iteration": 0}}
Mar  7 17:01:21 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 289792, iter 0, not waiting. Progress = 0
Mar  7 17:01:21 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 291840,"remaining": -1,"iteration": 0}}
Mar  7 17:01:21 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 291840, iter 0, not waiting. Progress = 0
Mar  7 17:01:22 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 293888,"remaining": -1,"iteration": 0}}
Mar  7 17:01:22 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 293888, iter 0, not waiting. Progress = 0
Mar  7 17:01:22 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 295936,"remaining": -1,"iteration": 0}}
Mar  7 17:01:22 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 295936 of 25229312 (1%)
Mar  7 17:01:22 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 295936, iter 0, not waiting. Progress = 0
Mar  7 17:01:23 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 297984,"remaining": -1,"iteration": 0}}
Mar  7 17:01:23 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 297984, iter 0, not waiting. Progress = 0
Mar  7 17:01:24 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 300032,"remaining": -1,"iteration": 0}}
Mar  7 17:01:24 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 300032, iter 0, not waiting. Progress = 0
Mar  7 17:01:24 ede-vmh001 squeezed[28579]: [6731.51] watch /data/updated <- Tue Mar  7 17:01:24 2023
Mar  7 17:01:24 ede-vmh001 squeezed: [debug||4 ||xenops] watch /data/updated <- Tue Mar  7 17:01:24 2023
Mar  7 17:01:24 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 302080,"remaining": -1,"iteration": 0}}
Mar  7 17:01:24 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 302080, iter 0, not waiting. Progress = 0
Mar  7 17:01:25 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 304128,"remaining": -1,"iteration": 0}}
Mar  7 17:01:25 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 304128, iter 0, not waiting. Progress = 0
Mar  7 17:01:25 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 306176,"remaining": -1,"iteration": 0}}
Mar  7 17:01:25 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 306176, iter 0, not waiting. Progress = 0
Mar  7 17:01:26 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 308224,"remaining": -1,"iteration": 0}}
Mar  7 17:01:26 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 308224, iter 0, not waiting. Progress = 0
Mar  7 17:01:27 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 310272,"remaining": -1,"iteration": 0}}
Mar  7 17:01:27 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 310272, iter 0, not waiting. Progress = 0
Mar  7 17:01:27 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 313344,"remaining": -1,"iteration": 0}}
Mar  7 17:01:27 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 313344, iter 0, not waiting. Progress = 0
Mar  7 17:01:27 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 314368 of 25229312 (1%)
Mar  7 17:01:28 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 316416,"remaining": -1,"iteration": 0}}
Mar  7 17:01:28 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 316416, iter 0, not waiting. Progress = 1
Mar  7 17:01:29 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 319488,"remaining": -1,"iteration": 0}}
Mar  7 17:01:29 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 319488, iter 0, not waiting. Progress = 1
Mar  7 17:01:29 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 321536,"remaining": -1,"iteration": 0}}
Mar  7 17:01:29 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 321536, iter 0, not waiting. Progress = 1
Mar  7 17:01:30 ede-vmh001 systemd[1]: Started Session c89815 of user root.
Mar  7 17:01:30 ede-vmh001 systemd[1]: Starting Session c89815 of user root.
Mar  7 17:01:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 323584,"remaining": -1,"iteration": 0}}
Mar  7 17:01:30 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 323584, iter 0, not waiting. Progress = 1
Mar  7 17:01:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 325632,"remaining": -1,"iteration": 0}}
Mar  7 17:01:30 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 325632, iter 0, not waiting. Progress = 1
Mar  7 17:01:31 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 328704,"remaining": -1,"iteration": 0}}
Mar  7 17:01:31 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 328704, iter 0, not waiting. Progress = 1
Mar  7 17:01:32 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 331776,"remaining": -1,"iteration": 0}}
Mar  7 17:01:32 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 331776, iter 0, not waiting. Progress = 1
Mar  7 17:01:32 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 333824,"remaining": -1,"iteration": 0}}
Mar  7 17:01:32 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 333824, iter 0, not waiting. Progress = 1
Mar  7 17:01:33 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 335872 of 25229312 (1%)
Mar  7 17:01:33 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 336896,"remaining": -1,"iteration": 0}}
Mar  7 17:01:33 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 336896, iter 0, not waiting. Progress = 1
Mar  7 17:01:34 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 338944,"remaining": -1,"iteration": 0}}
Mar  7 17:01:34 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 338944, iter 0, not waiting. Progress = 1
Mar  7 17:01:34 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 340992,"remaining": -1,"iteration": 0}}
Mar  7 17:01:34 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 340992, iter 0, not waiting. Progress = 1
Mar  7 17:01:35 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 343040,"remaining": -1,"iteration": 0}}
Mar  7 17:01:35 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 343040, iter 0, not waiting. Progress = 1
Mar  7 17:01:36 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 345088,"remaining": -1,"iteration": 0}}
Mar  7 17:01:36 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 345088, iter 0, not waiting. Progress = 1
Mar  7 17:01:37 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 347136,"remaining": -1,"iteration": 0}}
Mar  7 17:01:37 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 347136, iter 0, not waiting. Progress = 1
Mar  7 17:01:38 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 349184,"remaining": -1,"iteration": 0}}
Mar  7 17:01:38 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 349184, iter 0, not waiting. Progress = 1
Mar  7 17:01:38 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 350208 of 25229312 (1%)
Mar  7 17:01:38 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 351232,"remaining": -1,"iteration": 0}}
Mar  7 17:01:38 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 351232, iter 0, not waiting. Progress = 1
Mar  7 17:01:39 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 353280,"remaining": -1,"iteration": 0}}
Mar  7 17:01:39 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 353280, iter 0, not waiting. Progress = 1
Mar  7 17:01:39 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 355328,"remaining": -1,"iteration": 0}}
Mar  7 17:01:39 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 355328, iter 0, not waiting. Progress = 1
Mar  7 17:01:40 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 357376,"remaining": -1,"iteration": 0}}
Mar  7 17:01:40 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 357376, iter 0, not waiting. Progress = 1
Mar  7 17:01:41 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 359424,"remaining": -1,"iteration": 0}}
Mar  7 17:01:41 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 359424, iter 0, not waiting. Progress = 1
Mar  7 17:01:41 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 361472,"remaining": -1,"iteration": 0}}
Mar  7 17:01:41 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 361472, iter 0, not waiting. Progress = 1
Mar  7 17:01:42 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 363520,"remaining": -1,"iteration": 0}}
Mar  7 17:01:42 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 363520, iter 0, not waiting. Progress = 1
Mar  7 17:01:42 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 366592,"remaining": -1,"iteration": 0}}
Mar  7 17:01:42 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 366592, iter 0, not waiting. Progress = 1
Mar  7 17:01:43 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 368640 of 25229312 (1%)
Mar  7 17:01:43 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 369664,"remaining": -1,"iteration": 0}}
Mar  7 17:01:43 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 369664, iter 0, not waiting. Progress = 1
Mar  7 17:01:44 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 372736,"remaining": -1,"iteration": 0}}
Mar  7 17:01:44 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 372736, iter 0, not waiting. Progress = 1
Mar  7 17:01:44 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 375808,"remaining": -1,"iteration": 0}}
Mar  7 17:01:44 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 375808, iter 0, not waiting. Progress = 1
Mar  7 17:01:45 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 378880,"remaining": -1,"iteration": 0}}
Mar  7 17:01:45 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 378880, iter 0, not waiting. Progress = 1
Mar  7 17:01:46 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 381952,"remaining": -1,"iteration": 0}}
Mar  7 17:01:46 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 381952, iter 0, not waiting. Progress = 1
Mar  7 17:01:47 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 385024,"remaining": -1,"iteration": 0}}
Mar  7 17:01:47 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 385024, iter 0, not waiting. Progress = 1
Mar  7 17:01:47 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 388096,"remaining": -1,"iteration": 0}}
Mar  7 17:01:47 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 388096, iter 0, not waiting. Progress = 1
Mar  7 17:01:48 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 391168,"remaining": -1,"iteration": 0}}
Mar  7 17:01:48 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 391168, iter 0, not waiting. Progress = 1
Mar  7 17:01:48 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 392192 of 25229312 (1%)

Part 2:

Mar  7 16:59:17 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 68608, iter 0, not waiting. Progress = 0
Mar  7 16:59:19 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 69632,"remaining": -1,"iteration": 0}}
Mar  7 16:59:19 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 69632, iter 0, not waiting. Progress = 0
Mar  7 16:59:20 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 70656,"remaining": -1,"iteration": 0}}
Mar  7 16:59:20 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 70656, iter 0, not waiting. Progress = 0
Mar  7 16:59:23 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 71680,"remaining": -1,"iteration": 0}}
Mar  7 16:59:23 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 71680 of 25229312 (0%)
Mar  7 16:59:23 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 71680, iter 0, not waiting. Progress = 0
Mar  7 16:59:24 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 72704,"remaining": -1,"iteration": 0}}
Mar  7 16:59:24 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 72704, iter 0, not waiting. Progress = 0
Mar  7 16:59:26 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 73728,"remaining": -1,"iteration": 0}}
Mar  7 16:59:26 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 73728, iter 0, not waiting. Progress = 0
Mar  7 16:59:28 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 74752,"remaining": -1,"iteration": 0}}
Mar  7 16:59:28 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 74752 of 25229312 (0%)
Mar  7 16:59:28 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 74752, iter 0, not waiting. Progress = 0
Mar  7 16:59:30 ede-vmh001 systemd[1]: Started Session c89808 of user root.
Mar  7 16:59:30 ede-vmh001 systemd[1]: Starting Session c89808 of user root.
Mar  7 16:59:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 75776,"remaining": -1,"iteration": 0}}
Mar  7 16:59:30 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 75776, iter 0, not waiting. Progress = 0
Mar  7 16:59:32 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 76800,"remaining": -1,"iteration": 0}}
Mar  7 16:59:32 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 76800, iter 0, not waiting. Progress = 0
Mar  7 16:59:33 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 77824,"remaining": -1,"iteration": 0}}
Mar  7 16:59:33 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 77824 of 25229312 (0%)
Mar  7 16:59:33 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 77824, iter 0, not waiting. Progress = 0
Mar  7 16:59:35 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 78848,"remaining": -1,"iteration": 0}}
Mar  7 16:59:35 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 78848, iter 0, not waiting. Progress = 0
Mar  7 16:59:36 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 79872,"remaining": -1,"iteration": 0}}
Mar  7 16:59:36 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 79872, iter 0, not waiting. Progress = 0
Mar  7 16:59:38 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 80896,"remaining": -1,"iteration": 0}}
Mar  7 16:59:38 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 80896, iter 0, not waiting. Progress = 0
Mar  7 16:59:40 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 81920,"remaining": -1,"iteration": 0}}
Mar  7 16:59:40 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 81920 of 25229312 (0%)
Mar  7 16:59:40 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 81920, iter 0, not waiting. Progress = 0
Mar  7 16:59:42 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 82944,"remaining": -1,"iteration": 0}}
Mar  7 16:59:42 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 82944, iter 0, not waiting. Progress = 0
Mar  7 16:59:43 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 83968,"remaining": -1,"iteration": 0}}
Mar  7 16:59:43 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 83968, iter 0, not waiting. Progress = 0
Mar  7 16:59:45 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 84992,"remaining": -1,"iteration": 0}}
Mar  7 16:59:45 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 84992, iter 0, not waiting. Progress = 0
Mar  7 16:59:46 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 86016,"remaining": -1,"iteration": 0}}
Mar  7 16:59:46 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 86016 of 25229312 (0%)
Mar  7 16:59:46 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 86016, iter 0, not waiting. Progress = 0
Mar  7 16:59:48 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 87040,"remaining": -1,"iteration": 0}}
Mar  7 16:59:48 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 87040, iter 0, not waiting. Progress = 0
Mar  7 16:59:49 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 88064,"remaining": -1,"iteration": 0}}
Mar  7 16:59:49 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 88064, iter 0, not waiting. Progress = 0
Mar  7 16:59:51 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 89088,"remaining": -1,"iteration": 0}}
Mar  7 16:59:51 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 89088, iter 0, not waiting. Progress = 0
Mar  7 16:59:52 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 90112,"remaining": -1,"iteration": 0}}
Mar  7 16:59:52 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 90112 of 25229312 (0%)
Mar  7 16:59:52 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 90112, iter 0, not waiting. Progress = 0
Mar  7 16:59:54 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 91136,"remaining": -1,"iteration": 0}}
Mar  7 16:59:54 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 91136, iter 0, not waiting. Progress = 0
Mar  7 16:59:55 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 92160,"remaining": -1,"iteration": 0}}
Mar  7 16:59:55 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 92160, iter 0, not waiting. Progress = 0
Mar  7 16:59:56 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 93184,"remaining": -1,"iteration": 0}}
Mar  7 16:59:56 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 93184, iter 0, not waiting. Progress = 0
Mar  7 16:59:57 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 94208,"remaining": -1,"iteration": 0}}
Mar  7 16:59:57 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 94208, iter 0, not waiting. Progress = 0
Mar  7 16:59:58 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 95232,"remaining": -1,"iteration": 0}}
Mar  7 16:59:58 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 95232 of 25229312 (0%)
Mar  7 16:59:58 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 95232, iter 0, not waiting. Progress = 0
Mar  7 16:59:59 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 96256,"remaining": -1,"iteration": 0}}
Mar  7 16:59:59 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 96256, iter 0, not waiting. Progress = 0
Mar  7 17:00:00 ede-vmh001 systemd[1]: Started Session c89809 of user root.
Mar  7 17:00:00 ede-vmh001 systemd[1]: Starting Session c89809 of user root.
Mar  7 17:00:01 ede-vmh001 systemd[1]: Started Session c89810 of user root.
Mar  7 17:00:01 ede-vmh001 systemd[1]: Starting Session c89810 of user root.
Mar  7 17:00:01 ede-vmh001 systemd[1]: Started Session c89811 of user root.
Mar  7 17:00:01 ede-vmh001 systemd[1]: Starting Session c89811 of user root.
Mar  7 17:00:01 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 97280,"remaining": -1,"iteration": 0}}
Mar  7 17:00:01 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 97280, iter 0, not waiting. Progress = 0
Mar  7 17:00:02 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 98304,"remaining": -1,"iteration": 0}}
Mar  7 17:00:02 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 98304, iter 0, not waiting. Progress = 0
Mar  7 17:00:03 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 99328,"remaining": -1,"iteration": 0}}
Mar  7 17:00:03 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 99328, iter 0, not waiting. Progress = 0
Mar  7 17:00:04 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 100352,"remaining": -1,"iteration": 0}}
Mar  7 17:00:04 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 100352 of 25229312 (0%)
Mar  7 17:00:04 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 100352, iter 0, not waiting. Progress = 0
Mar  7 17:00:05 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 101376,"remaining": -1,"iteration": 0}}
Mar  7 17:00:05 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 101376, iter 0, not waiting. Progress = 0
Mar  7 17:00:06 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 102400,"remaining": -1,"iteration": 0}}
Mar  7 17:00:06 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 102400, iter 0, not waiting. Progress = 0
Mar  7 17:00:07 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 103424,"remaining": -1,"iteration": 0}}
Mar  7 17:00:07 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 103424, iter 0, not waiting. Progress = 0
Mar  7 17:00:08 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 104448,"remaining": -1,"iteration": 0}}
Mar  7 17:00:08 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 104448, iter 0, not waiting. Progress = 0
Mar  7 17:00:09 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 105472,"remaining": -1,"iteration": 0}}
Mar  7 17:00:09 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 105472 of 25229312 (0%)
Mar  7 17:00:09 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 105472, iter 0, not waiting. Progress = 0
Mar  7 17:00:10 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 106496,"remaining": -1,"iteration": 0}}
Mar  7 17:00:10 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 106496, iter 0, not waiting. Progress = 0
Mar  7 17:00:11 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 107520,"remaining": -1,"iteration": 0}}
Mar  7 17:00:11 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 107520, iter 0, not waiting. Progress = 0
Mar  7 17:00:12 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 108544,"remaining": -1,"iteration": 0}}
Mar  7 17:00:12 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 108544, iter 0, not waiting. Progress = 0
Mar  7 17:00:13 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 109568,"remaining": -1,"iteration": 0}}
Mar  7 17:00:13 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 109568, iter 0, not waiting. Progress = 0
Mar  7 17:00:14 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 110592,"remaining": -1,"iteration": 0}}
Mar  7 17:00:14 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 110592, iter 0, not waiting. Progress = 0
Mar  7 17:00:14 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 111616,"remaining": -1,"iteration": 0}}
Mar  7 17:00:14 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 111616 of 25229312 (0%)
Mar  7 17:00:14 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 111616, iter 0, not waiting. Progress = 0
Mar  7 17:00:15 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 112640,"remaining": -1,"iteration": 0}}
Mar  7 17:00:15 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 112640, iter 0, not waiting. Progress = 0
Mar  7 17:00:16 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 113664,"remaining": -1,"iteration": 0}}
Mar  7 17:00:16 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 113664, iter 0, not waiting. Progress = 0
Mar  7 17:00:17 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 114688,"remaining": -1,"iteration": 0}}
Mar  7 17:00:17 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 114688, iter 0, not waiting. Progress = 0
Mar  7 17:00:17 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 115712,"remaining": -1,"iteration": 0}}
Mar  7 17:00:17 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 115712, iter 0, not waiting. Progress = 0
Mar  7 17:00:18 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 116736,"remaining": -1,"iteration": 0}}
Mar  7 17:00:18 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 116736, iter 0, not waiting. Progress = 0
Mar  7 17:00:18 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 117760,"remaining": -1,"iteration": 0}}
Mar  7 17:00:18 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 117760, iter 0, not waiting. Progress = 0
Mar  7 17:00:19 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 118784,"remaining": -1,"iteration": 0}}
Mar  7 17:00:19 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 118784, iter 0, not waiting. Progress = 0
Mar  7 17:00:20 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 119808,"remaining": -1,"iteration": 0}}
Mar  7 17:00:20 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 119808 of 25229312 (0%)
Mar  7 17:00:20 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 119808, iter 0, not waiting. Progress = 0
Mar  7 17:00:20 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 120832,"remaining": -1,"iteration": 0}}
Mar  7 17:00:20 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 120832, iter 0, not waiting. Progress = 0
Mar  7 17:00:21 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 121856,"remaining": -1,"iteration": 0}}
Mar  7 17:00:21 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 121856, iter 0, not waiting. Progress = 0
Mar  7 17:00:21 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 122880,"remaining": -1,"iteration": 0}}
Mar  7 17:00:21 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 122880, iter 0, not waiting. Progress = 0
Mar  7 17:00:22 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 123904,"remaining": -1,"iteration": 0}}
Mar  7 17:00:22 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 123904, iter 0, not waiting. Progress = 0
Mar  7 17:00:23 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 124928,"remaining": -1,"iteration": 0}}
Mar  7 17:00:23 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 124928, iter 0, not waiting. Progress = 0
Mar  7 17:00:23 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 125952,"remaining": -1,"iteration": 0}}
Mar  7 17:00:23 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 125952, iter 0, not waiting. Progress = 0
Mar  7 17:00:24 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 126976,"remaining": -1,"iteration": 0}}
Mar  7 17:00:24 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 126976, iter 0, not waiting. Progress = 0
Mar  7 17:00:25 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 128000,"remaining": -1,"iteration": 0}}
Mar  7 17:00:25 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 128000, iter 0, not waiting. Progress = 0
Mar  7 17:00:25 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 129024,"remaining": -1,"iteration": 0}}
Mar  7 17:00:25 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 129024 of 25229312 (0%)
Mar  7 17:00:25 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 129024, iter 0, not waiting. Progress = 0
Mar  7 17:00:26 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 130048,"remaining": -1,"iteration": 0}}
Mar  7 17:00:26 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 130048, iter 0, not waiting. Progress = 0
Mar  7 17:00:27 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 131072,"remaining": -1,"iteration": 0}}
Mar  7 17:00:27 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 131072, iter 0, not waiting. Progress = 0
Mar  7 17:00:28 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 132096,"remaining": -1,"iteration": 0}}
Mar  7 17:00:28 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 132096, iter 0, not waiting. Progress = 0
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: received 'pause' message (uuid = 42)
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: control: pause requested
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: vbd: pause requested
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: nbd: NBD server pause(0x118aa10)
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: gaps written/skipped: 0/0
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: /var/run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/9d56b5b4-758d-4f41-be21-c47bbe3edf12.vhd: b: 102400, a: 15, f: 0, n: 62392
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: closed image /var/run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/9d56b5b4-758d-4f41-be21-c47bbe3edf12.vhd (0 users, state: 0x00000000, type: 4)
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: nbd: Sending disconnect request
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: nbd: Switching socket to blocking IO mode
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: nbd: Writing disconnection request
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: nbd: sent close request
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: nbd: NBD client full-disable
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: nbd: NBD client cancelling sent reqs
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: nbd: NBD client cancelling pending reqs
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: nbd: Setting closed
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: nbd: Written
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: closed image mirror_vbd/13/xvdh (0 users, state: 0x00000000, type: 15)
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: gaps written/skipped: 0/0
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: /run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/4b8c58fc-70eb-426e-ab86-cf1ac3adf3bb.vhd: b: 102400, a: 102399, f: 102390, n: 0
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: closed image /run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/4b8c58fc-70eb-426e-ab86-cf1ac3adf3bb.vhd (0 users, state: 0x00000002, type: 4)
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: vbd: pause completed
Mar  7 17:00:28 ede-vmh001 tapdisk[13712]: sending 'pause response' message (uuid = 42)
Mar  7 17:00:28 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 133120,"remaining": -1,"iteration": 0}}
Mar  7 17:00:28 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 133120, iter 0, not waiting. Progress = 0
Mar  7 17:00:29 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 134144,"remaining": -1,"iteration": 0}}
Mar  7 17:00:29 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 134144, iter 0, not waiting. Progress = 0
Mar  7 17:00:30 ede-vmh001 systemd[1]: Started Session c89812 of user root.
Mar  7 17:00:30 ede-vmh001 systemd[1]: Starting Session c89812 of user root.
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: received 'resume' message (uuid = 42)
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: control: resuming VBD 42, flags=0x00000000, secondary=0x63b0fc
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: /var/run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/9d56b5b4-758d-4f41-be21-c47bbe3edf12.vhd version: tap 0x00010003, b: 102400, a: 102399, f: 102390, n: 420246320
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: opened image /var/run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/9d56b5b4-758d-4f41-be21-c47bbe3edf12.vhd (1 users, state: 0x00000001, type: 4, rw)
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: VBD CHAIN:
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: /var/run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/9d56b5b4-758d-4f41-be21-c47bbe3edf12.vhd: type:vhd(4) storage:ext(2)
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: Adding secondary image: nbd:mirror_vbd/13/xvdh
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: nbd: Opening nbd export to mirror_vbd/13/xvdh (flags=2408)
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: nbd: Found passed fd. Connecting...
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: nbd: Got size: 214748364800
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: nbd: Got flags: 0
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: nbd: Successfully connected to NBD server
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: nbd: Opening in secondary mode: Read requests will be forwarded
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: opened image mirror_vbd/13/xvdh (1 users, state: 0x00000001, type: 15, rw)
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: In mirror mode
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: Added secondary image
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: nbd: NBD server unpause(0x118aa10) - fdrecv_listening_fd -1, unix_listening_fd=23
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: nbd: registering for unix_listening_fd
Mar  7 17:00:30 ede-vmh001 tapdisk[13712]: sending 'resume response' message (uuid = 42)
Mar  7 17:00:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 135168,"remaining": -1,"iteration": 0}}
Mar  7 17:00:30 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 135168, iter 0, not waiting. Progress = 0
Mar  7 17:00:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 136192,"remaining": -1,"iteration": 0}}
Mar  7 17:00:30 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 136192 of 25229312 (0%)
Mar  7 17:00:30 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 136192, iter 0, not waiting. Progress = 0
Mar  7 17:00:31 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 137216,"remaining": -1,"iteration": 0}}
Mar  7 17:00:31 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 137216, iter 0, not waiting. Progress = 0
Mar  7 17:00:32 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 138240,"remaining": -1,"iteration": 0}}
Mar  7 17:00:32 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 138240, iter 0, not waiting. Progress = 0
Mar  7 17:00:33 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 140288,"remaining": -1,"iteration": 0}}
Mar  7 17:00:33 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 140288, iter 0, not waiting. Progress = 0
Mar  7 17:00:33 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 141312,"remaining": -1,"iteration": 0}}
Mar  7 17:00:33 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 141312, iter 0, not waiting. Progress = 0
Mar  7 17:00:34 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 143360,"remaining": -1,"iteration": 0}}
Mar  7 17:00:34 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 143360, iter 0, not waiting. Progress = 0
Mar  7 17:00:34 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 144384,"remaining": -1,"iteration": 0}}
Mar  7 17:00:34 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 144384, iter 0, not waiting. Progress = 0
Mar  7 17:00:35 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 146432,"remaining": -1,"iteration": 0}}
Mar  7 17:00:35 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 146432, iter 0, not waiting. Progress = 0
Mar  7 17:00:36 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 147456,"remaining": -1,"iteration": 0}}
Mar  7 17:00:36 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 147456 of 25229312 (0%)
Mar  7 17:00:36 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 147456, iter 0, not waiting. Progress = 0
Mar  7 17:00:37 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 148480,"remaining": -1,"iteration": 0}}
Mar  7 17:00:37 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 148480, iter 0, not waiting. Progress = 0
Mar  7 17:00:37 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 150528,"remaining": -1,"iteration": 0}}
Mar  7 17:00:37 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 150528, iter 0, not waiting. Progress = 0
Mar  7 17:00:38 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 151552,"remaining": -1,"iteration": 0}}
Mar  7 17:00:38 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 151552, iter 0, not waiting. Progress = 0
Mar  7 17:00:39 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 153600,"remaining": -1,"iteration": 0}}
Mar  7 17:00:39 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 153600, iter 0, not waiting. Progress = 0
Mar  7 17:00:39 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 154624,"remaining": -1,"iteration": 0}}
Mar  7 17:00:39 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 154624, iter 0, not waiting. Progress = 0
Mar  7 17:00:40 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 156672,"remaining": -1,"iteration": 0}}
Mar  7 17:00:40 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 156672, iter 0, not waiting. Progress = 0
Mar  7 17:00:41 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 158720,"remaining": -1,"iteration": 0}}
Mar  7 17:00:41 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 158720 of 25229312 (0%)
Mar  7 17:00:41 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 158720, iter 0, not waiting. Progress = 0
Mar  7 17:00:42 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 160768,"remaining": -1,"iteration": 0}}
Mar  7 17:00:42 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 160768, iter 0, not waiting. Progress = 0
Mar  7 17:00:43 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 162816,"remaining": -1,"iteration": 0}}
Mar  7 17:00:43 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 162816, iter 0, not waiting. Progress = 0

@NielsH said in Occasional 5-10 minute hang of VM during live migrations:

message from emu-manager: prepare:xenguest

I found some more information regarding the xenguest-output in the daemon.log, it appears to give some more details in what is happening between 16:55 and 17:01:

I'm hitting the post limit so will put into 3 posts
Part 1:

Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: received 'close' message (uuid = 0)
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: nbd: NBD server pause(0x2564610)
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: nbd: NBD server free(0x2564610)
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: gaps written/skipped: 0/0
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: /var/run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/7e4883d8-a296-40a0-8087-6d4209ed47d5.vhd: b: 102400, a: 0, f: 0, n: 0
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: closed image /var/run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/7e4883d8-a296-40a0-8087-6d4209ed47d5.vhd (0 users, state: 0x00000002, type: 4)
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: gaps written/skipped: 0/0
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: /run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/4b8c58fc-70eb-426e-ab86-cf1ac3adf3bb.vhd: b: 102400, a: 102399, f: 102390, n: 0
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: closed image /run/sr-mount/5c93fb03-318e-93cb-c16d-b0f8deca16f9/4b8c58fc-70eb-426e-ab86-cf1ac3adf3bb.vhd (0 users, state: 0x00000002, type: 4)
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: sending 'close response' message (uuid = 0)
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: received 'detach' message (uuid = 0)
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: sending 'detach response' message (uuid = 0)
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: tapdisk-log: closing after 0 errors
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: tapdisk-syslog: 18 messages, 1606 bytes, xmits: 19, failed: 0, dropped: 0
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: tapdisk-control: draining 1 connections
Mar  7 16:55:25 ede-vmh001 tapdisk[5882]: tapdisk-control: done
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] watch /memory/dynamic-min <- 100663296
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||4 ||xenops] watch /memory/dynamic-min <- 100663296
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] watch /memory/dynamic-max <- 100663296
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||4 ||xenops] watch /memory/dynamic-max <- 100663296
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] change_host_free_memory required_mem = 9216 KiB target_mem = 9216 KiB free_mem = 394576612 KiB
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||22 ||xenops] change_host_free_memory required_mem = 9216 KiB target_mem = 9216 KiB free_mem = 394576612 KiB
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] change_host_free_memory all VM target meet true
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||22 ||xenops] change_host_free_memory all VM target meet true
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] total_range = 0 gamma = 1.000000 gamma' = inf
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||22 ||xenops] total_range = 0 gamma = 1.000000 gamma' = inf
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] Total additional memory over dynamic_min = 394567396 KiB; will set gamma = 1.00 (leaving unallocated 0 KiB)
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||22 ||xenops] Total additional memory over dynamic_min = 394567396 KiB; will set gamma = 1.00 (leaving unallocated 0 KiB)
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] Maximum possible free memory if all active domains balloon down to dynamic_min = 394576612
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||22 ||xenops] Maximum possible free memory if all active domains balloon down to dynamic_min = 394576612
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] current host free mem = 394576612 KiB (aiming for 9216 KiB); cannot allocate enough; all domain targets reached; allocation phase
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||22 ||xenops] current host free mem = 394576612 KiB (aiming for 9216 KiB); cannot allocate enough; all domain targets reached; allocation phase
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] F394576612 S0 R0 T536721328; 13 T100663296 A100663296 M100663292 Bxx
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||22 ||xenops] F394576612 S0 R0 T536721328; 13 T100663296 A100663296 M100663292 Bxx
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] Failed to free 9216 KiB of memory: operation impossible within current dynamic_min limits of balloonable domains
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||22 ||xenops] Failed to free 9216 KiB of memory: operation impossible within current dynamic_min limits of balloonable domains
Mar  7 16:55:29 ede-vmh001 squeezed[28579]: [6376.76] balance memory caught: Squeeze.Cannot_free_this_much_memory(_, _)
Mar  7 16:55:29 ede-vmh001 squeezed: [debug||22 ||xenops] balance memory caught: Squeeze.Cannot_free_this_much_memory(_, _)
Mar  7 16:55:30 ede-vmh001 systemd[1]: Started Session c89800 of user root.
Mar  7 16:55:30 ede-vmh001 systemd[1]: Starting Session c89800 of user root.
Mar  7 16:55:30 ede-vmh001 emu-manager-13[21257]: Startup: xenopsd control fds (8, 7).
Mar  7 16:55:30 ede-vmh001 emu-manager-13[21257]: Startup: domid 13.
Mar  7 16:55:30 ede-vmh001 emu-manager-13[21257]: Startup: operation mode (hvm_save, live).
Mar  7 16:55:30 ede-vmh001 emu-manager-13[21257]: Emu `xenguest` is enabled.
Mar  7 16:55:30 ede-vmh001 emu-manager-13[21257]: Emu `qemu` is enabled.
Mar  7 16:55:30 ede-vmh001 emu-manager-13[21257]: Starting `/usr/libexec/xen/bin/xenguest`...
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: Command line: -debug -domid 13 -controloutfd 2 -controlinfd 0 -mode listen
Mar  7 16:55:30 ede-vmh001 emu-manager-13[21257]: Connecting to `xenguest` (/run/xen/xenguest-control-13)...
Mar  7 16:55:30 ede-vmh001 emu-manager-13[21257]: Connecting to `qemu` (/var/run/xen/qmp-libxl-13)...
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: libempserver: Adding client on fd 12 as (0)
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: libempserver: On (0) got message '{ "execute" : "migrate_init" }'
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "return" : {} }
Mar  7 16:55:30 ede-vmh001 emu-manager-13[21257]: Got QMP version negotiation.
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: libempserver: On (0) got message '{ "execute" : "track_dirty" }'
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "return" : {} }
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: libempserver: On (0) got message '{ "execute" : "migrate_progress" }'
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: setting progress_cli to 0
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "return" : {} }
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: libempserver: On (0) got message '{ "execute" : "migrate_live" }'
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "return" : {} }
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: xc: detail: fd 13, dom 13, flags 1, hvm 1
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: xc: info: Saving domain 13, type x86 HVM
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: progress: Start of stream
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: Checking live policy.  25229312 / 0 for 0
Mar  7 16:55:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 0,"remaining": 25229312,"iteration": 0}}
Mar  7 16:55:30 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem 25229312, sent 0, iter 0, not waiting. Progress = 0
Mar  7 16:55:38 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 1024,"remaining": -1,"iteration": 0}}
Mar  7 16:55:38 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 1024 of 25229312 (0%)
Mar  7 16:55:38 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 1024, iter 0, not waiting. Progress = 0
Mar  7 16:55:42 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 2048,"remaining": -1,"iteration": 0}}
Mar  7 16:55:42 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 2048, iter 0, not waiting. Progress = 0
Mar  7 16:55:46 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 3072,"remaining": -1,"iteration": 0}}
Mar  7 16:55:46 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 3072 of 25229312 (0%)
Mar  7 16:55:46 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 3072, iter 0, not waiting. Progress = 0
Mar  7 16:55:51 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 4096,"remaining": -1,"iteration": 0}}
Mar  7 16:55:51 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 4096, iter 0, not waiting. Progress = 0
Mar  7 16:55:55 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 5120,"remaining": -1,"iteration": 0}}
Mar  7 16:55:55 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 5120 of 25229312 (0%)
Mar  7 16:55:55 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 5120, iter 0, not waiting. Progress = 0
Mar  7 16:55:59 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 6144,"remaining": -1,"iteration": 0}}
Mar  7 16:55:59 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 6144, iter 0, not waiting. Progress = 0
Mar  7 16:56:00 ede-vmh001 systemd[1]: Started Session c89801 of user root.
Mar  7 16:56:00 ede-vmh001 systemd[1]: Starting Session c89801 of user root.
Mar  7 16:56:03 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 7168,"remaining": -1,"iteration": 0}}
Mar  7 16:56:03 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 7168 of 25229312 (0%)
Mar  7 16:56:03 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 7168, iter 0, not waiting. Progress = 0
Mar  7 16:56:07 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 8192,"remaining": -1,"iteration": 0}}
Mar  7 16:56:07 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 8192, iter 0, not waiting. Progress = 0
Mar  7 16:56:10 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 9216,"remaining": -1,"iteration": 0}}
Mar  7 16:56:10 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 9216 of 25229312 (0%)
Mar  7 16:56:10 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 9216, iter 0, not waiting. Progress = 0
Mar  7 16:56:14 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 10240,"remaining": -1,"iteration": 0}}
Mar  7 16:56:14 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 10240, iter 0, not waiting. Progress = 0
Mar  7 16:56:19 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 11264,"remaining": -1,"iteration": 0}}
Mar  7 16:56:19 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 11264 of 25229312 (0%)
Mar  7 16:56:19 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 11264, iter 0, not waiting. Progress = 0
Mar  7 16:56:22 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 12288,"remaining": -1,"iteration": 0}}
Mar  7 16:56:22 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 12288, iter 0, not waiting. Progress = 0
Mar  7 16:56:26 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 13312,"remaining": -1,"iteration": 0}}
Mar  7 16:56:26 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 13312 of 25229312 (0%)
Mar  7 16:56:26 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 13312, iter 0, not waiting. Progress = 0
Mar  7 16:56:29 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 14336,"remaining": -1,"iteration": 0}}
Mar  7 16:56:29 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 14336, iter 0, not waiting. Progress = 0
Mar  7 16:56:30 ede-vmh001 systemd[1]: Started Session c89802 of user root.
Mar  7 16:56:30 ede-vmh001 systemd[1]: Starting Session c89802 of user root.
Mar  7 16:56:33 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 15360,"remaining": -1,"iteration": 0}}
Mar  7 16:56:33 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 15360 of 25229312 (0%)
Mar  7 16:56:33 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 15360, iter 0, not waiting. Progress = 0
Mar  7 16:56:36 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 16384,"remaining": -1,"iteration": 0}}
Mar  7 16:56:36 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 16384, iter 0, not waiting. Progress = 0
Mar  7 16:56:40 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 17408,"remaining": -1,"iteration": 0}}
Mar  7 16:56:40 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 17408 of 25229312 (0%)
Mar  7 16:56:40 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 17408, iter 0, not waiting. Progress = 0
Mar  7 16:56:43 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 18432,"remaining": -1,"iteration": 0}}
Mar  7 16:56:43 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 18432, iter 0, not waiting. Progress = 0
Mar  7 16:56:48 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 19456,"remaining": -1,"iteration": 0}}
Mar  7 16:56:48 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 19456 of 25229312 (0%)
Mar  7 16:56:48 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 19456, iter 0, not waiting. Progress = 0
Mar  7 16:56:52 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 20480,"remaining": -1,"iteration": 0}}
Mar  7 16:56:52 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 20480, iter 0, not waiting. Progress = 0
Mar  7 16:56:55 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 21504,"remaining": -1,"iteration": 0}}
Mar  7 16:56:55 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 21504 of 25229312 (0%)
Mar  7 16:56:55 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 21504, iter 0, not waiting. Progress = 0
Mar  7 16:56:58 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 22528,"remaining": -1,"iteration": 0}}
Mar  7 16:56:58 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 22528, iter 0, not waiting. Progress = 0
Mar  7 16:57:00 ede-vmh001 systemd[1]: Started Session c89803 of user root.
Mar  7 16:57:00 ede-vmh001 systemd[1]: Starting Session c89803 of user root.
Mar  7 16:57:00 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 23552,"remaining": -1,"iteration": 0}}
Mar  7 16:57:00 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 23552 of 25229312 (0%)
Mar  7 16:57:00 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 23552, iter 0, not waiting. Progress = 0
Mar  7 16:57:04 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 24576,"remaining": -1,"iteration": 0}}
Mar  7 16:57:04 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 24576, iter 0, not waiting. Progress = 0
Mar  7 16:57:07 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 25600,"remaining": -1,"iteration": 0}}
Mar  7 16:57:07 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 25600 of 25229312 (0%)
Mar  7 16:57:07 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 25600, iter 0, not waiting. Progress = 0
Mar  7 16:57:11 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 26624,"remaining": -1,"iteration": 0}}
Mar  7 16:57:11 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 26624, iter 0, not waiting. Progress = 0
Mar  7 16:57:15 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 27648,"remaining": -1,"iteration": 0}}
Mar  7 16:57:15 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 27648 of 25229312 (0%)
Mar  7 16:57:15 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 27648, iter 0, not waiting. Progress = 0
Mar  7 16:57:19 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 28672,"remaining": -1,"iteration": 0}}
Mar  7 16:57:19 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 28672, iter 0, not waiting. Progress = 0
Mar  7 16:57:23 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 29696,"remaining": -1,"iteration": 0}}
Mar  7 16:57:23 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 29696 of 25229312 (0%)
Mar  7 16:57:23 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 29696, iter 0, not waiting. Progress = 0
Mar  7 16:57:26 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 30720,"remaining": -1,"iteration": 0}}
Mar  7 16:57:26 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 30720, iter 0, not waiting. Progress = 0
Mar  7 16:57:30 ede-vmh001 systemd[1]: Started Session c89804 of user root.
Mar  7 16:57:30 ede-vmh001 systemd[1]: Starting Session c89804 of user root.
Mar  7 16:57:30 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 31744,"remaining": -1,"iteration": 0}}
Mar  7 16:57:30 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 31744 of 25229312 (0%)
Mar  7 16:57:30 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 31744, iter 0, not waiting. Progress = 0
Mar  7 16:57:32 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 32768,"remaining": -1,"iteration": 0}}
Mar  7 16:57:32 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 32768, iter 0, not waiting. Progress = 0
Mar  7 16:57:36 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 33792,"remaining": -1,"iteration": 0}}
Mar  7 16:57:36 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 33792 of 25229312 (0%)
Mar  7 16:57:36 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 33792, iter 0, not waiting. Progress = 0
Mar  7 16:57:41 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 34816,"remaining": -1,"iteration": 0}}
Mar  7 16:57:41 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 34816, iter 0, not waiting. Progress = 0
Mar  7 16:57:44 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 35840,"remaining": -1,"iteration": 0}}
Mar  7 16:57:44 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 35840 of 25229312 (0%)
Mar  7 16:57:44 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 35840, iter 0, not waiting. Progress = 0
Mar  7 16:57:48 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 36864,"remaining": -1,"iteration": 0}}
Mar  7 16:57:48 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 36864, iter 0, not waiting. Progress = 0
Mar  7 16:57:51 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 37888,"remaining": -1,"iteration": 0}}
Mar  7 16:57:51 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 37888 of 25229312 (0%)
Mar  7 16:57:51 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 37888, iter 0, not waiting. Progress = 0
Mar  7 16:57:55 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 38912,"remaining": -1,"iteration": 0}}
Mar  7 16:57:55 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 38912, iter 0, not waiting. Progress = 0
Mar  7 16:57:58 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 39936,"remaining": -1,"iteration": 0}}
Mar  7 16:57:58 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 39936 of 25229312 (0%)
Mar  7 16:57:58 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 39936, iter 0, not waiting. Progress = 0
Mar  7 16:58:00 ede-vmh001 systemd[1]: Started Session c89805 of user root.
Mar  7 16:58:00 ede-vmh001 systemd[1]: Starting Session c89805 of user root.
Mar  7 16:58:02 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 40960,"remaining": -1,"iteration": 0}}
Mar  7 16:58:02 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 40960, iter 0, not waiting. Progress = 0
Mar  7 16:58:05 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 41984,"remaining": -1,"iteration": 0}}
Mar  7 16:58:05 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 41984 of 25229312 (0%)
Mar  7 16:58:05 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 41984, iter 0, not waiting. Progress = 0
Mar  7 16:58:09 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 43008,"remaining": -1,"iteration": 0}}
Mar  7 16:58:09 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 43008, iter 0, not waiting. Progress = 0
Mar  7 16:58:13 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 44032,"remaining": -1,"iteration": 0}}
Mar  7 16:58:13 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 44032 of 25229312 (0%)
Mar  7 16:58:13 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 44032, iter 0, not waiting. Progress = 0
Mar  7 16:58:16 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 45056,"remaining": -1,"iteration": 0}}
Mar  7 16:58:16 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 45056, iter 0, not waiting. Progress = 0
Mar  7 16:58:19 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 46080,"remaining": -1,"iteration": 0}}
Mar  7 16:58:19 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 46080 of 25229312 (0%)
Mar  7 16:58:19 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 46080, iter 0, not waiting. Progress = 0
Mar  7 16:58:22 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 47104,"remaining": -1,"iteration": 0}}
Mar  7 16:58:22 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 47104, iter 0, not waiting. Progress = 0
Mar  7 16:58:27 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 48128,"remaining": -1,"iteration": 0}}
Mar  7 16:58:27 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 48128 of 25229312 (0%)
Mar  7 16:58:27 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 48128, iter 0, not waiting. Progress = 0
Mar  7 16:58:30 ede-vmh001 systemd[1]: Started Session c89806 of user root.
Mar  7 16:58:30 ede-vmh001 systemd[1]: Starting Session c89806 of user root.
Mar  7 16:58:31 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 49152,"remaining": -1,"iteration": 0}}
Mar  7 16:58:31 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 49152, iter 0, not waiting. Progress = 0
Mar  7 16:58:34 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 50176,"remaining": -1,"iteration": 0}}
Mar  7 16:58:34 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 50176 of 25229312 (0%)
Mar  7 16:58:34 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 50176, iter 0, not waiting. Progress = 0
Mar  7 16:58:38 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 51200,"remaining": -1,"iteration": 0}}
Mar  7 16:58:38 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 51200, iter 0, not waiting. Progress = 0
Mar  7 16:58:40 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 52224,"remaining": -1,"iteration": 0}}
Mar  7 16:58:40 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 52224 of 25229312 (0%)
Mar  7 16:58:40 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 52224, iter 0, not waiting. Progress = 0
Mar  7 16:58:43 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 53248,"remaining": -1,"iteration": 0}}
Mar  7 16:58:43 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 53248, iter 0, not waiting. Progress = 0
Mar  7 16:58:45 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 54272,"remaining": -1,"iteration": 0}}
Mar  7 16:58:45 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 54272 of 25229312 (0%)
Mar  7 16:58:45 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 54272, iter 0, not waiting. Progress = 0
Mar  7 16:58:48 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 55296,"remaining": -1,"iteration": 0}}
Mar  7 16:58:48 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 55296, iter 0, not waiting. Progress = 0
Mar  7 16:58:51 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 56320,"remaining": -1,"iteration": 0}}
Mar  7 16:58:51 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 56320 of 25229312 (0%)
Mar  7 16:58:51 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 56320, iter 0, not waiting. Progress = 0
Mar  7 16:58:53 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 57344,"remaining": -1,"iteration": 0}}
Mar  7 16:58:53 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 57344, iter 0, not waiting. Progress = 0
Mar  7 16:58:56 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 58368,"remaining": -1,"iteration": 0}}
Mar  7 16:58:56 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 58368, iter 0, not waiting. Progress = 0
Mar  7 16:58:58 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 59392,"remaining": -1,"iteration": 0}}
Mar  7 16:58:58 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 59392 of 25229312 (0%)
Mar  7 16:58:58 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 59392, iter 0, not waiting. Progress = 0
Mar  7 16:59:00 ede-vmh001 systemd[1]: Started Session c89807 of user root.
Mar  7 16:59:00 ede-vmh001 systemd[1]: Starting Session c89807 of user root.
Mar  7 16:59:01 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 60416,"remaining": -1,"iteration": 0}}
Mar  7 16:59:01 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 60416, iter 0, not waiting. Progress = 0
Mar  7 16:59:02 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 61440,"remaining": -1,"iteration": 0}}
Mar  7 16:59:02 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 61440, iter 0, not waiting. Progress = 0
Mar  7 16:59:05 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 62464,"remaining": -1,"iteration": 0}}
Mar  7 16:59:05 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 62464 of 25229312 (0%)
Mar  7 16:59:05 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 62464, iter 0, not waiting. Progress = 0
Mar  7 16:59:07 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 63488,"remaining": -1,"iteration": 0}}
Mar  7 16:59:07 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 63488, iter 0, not waiting. Progress = 0
Mar  7 16:59:09 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 64512,"remaining": -1,"iteration": 0}}
Mar  7 16:59:09 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 64512, iter 0, not waiting. Progress = 0
Mar  7 16:59:11 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 65536,"remaining": -1,"iteration": 0}}
Mar  7 16:59:11 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 65536 of 25229312 (0%)
Mar  7 16:59:11 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 65536, iter 0, not waiting. Progress = 0
Mar  7 16:59:13 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 66560,"remaining": -1,"iteration": 0}}
Mar  7 16:59:13 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 66560, iter 0, not waiting. Progress = 0
Mar  7 16:59:15 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 67584,"remaining": -1,"iteration": 0}}
Mar  7 16:59:15 ede-vmh001 emu-manager-13[21257]: Event for `xenguest`: rem -1, sent 67584, iter 0, not waiting. Progress = 0
Mar  7 16:59:17 ede-vmh001 xenguest-13-emp[21258]: libempserver:debug: replying to (0): { "event" : "MIGRATION", "data": {"sent": 68608,"remaining": -1,"iteration": 0}}
Mar  7 16:59:17 ede-vmh001 xenguest-13-emp[21258]: progress: Frames iteration 0: 68608 of 25229312 (0%)

Hello,

Unrelated to my other thread ( https://xcp-ng.org/forum/topic/7054/occasional-error-doing-live-migrations/1 ) there is another issue we sometimes see during live migrations.

This is an issue we mainly see on our larger VMs. That means starting at about 12 CPU cores / 48GB RAM, and usually these also have more local storage (500-800GB).

After the migration reaches 99-100% completion, the progress bar resets back to 0%. At this point, on our larger VMs, the VM will sometimes stop responding and sometimes fail the migration completely after 10-15 minutes of being unresponsive, or it will eventually come through after 5-10 minutes of being unresponsive.

In the logs, this is what we see:
Source hypervisor:

ar  7 16:55:26 ede-vmh001 xapi: [debug||58317 |Async.VM.migrate_send R:a55e0f0e16d0|storage_migrate] Local VDI 7e4883d8-a296-40a0-8087-6d4209ed47d5 == remote VDI f8ea0379-07f8-4472-a448-a5af100c80a2
Mar  7 16:55:27 ede-vmh001 xapi: [debug||58317 |Async.VM.migrate_send R:a55e0f0e16d0|storage_migrate] Local VDI 9d56b5b4-758d-4f41-be21-c47bbe3edf12 now mirrored to remote VDI: c972e8b8-0c05-4224-9aa5-2ff4fe54673d
Mar  7 16:55:27 ede-vmh001 xapi: [debug||58317 |Async.VM.migrate_send R:a55e0f0e16d0|storage_migrate] Destroying dummy VDI on remote
Mar  7 16:55:27 ede-vmh001 xapi: [debug||58317 |Async.VM.migrate_send R:a55e0f0e16d0|storage_migrate] Destroying snapshot on src
Mar  7 16:55:27 ede-vmh001 xapi: [ info||61579 HTTP 127.0.0.1->:::80|Querying services D:5d420abb79bd|storage_impl] VDI.destroy dbg:Async.VM.migrate_send R:a55e0f0e16d0 sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:7e4883d8-a296-40a0-8087-6d4209ed47d5
Mar  7 16:55:27 ede-vmh001 xapi: [debug||58317 |Async.VM.migrate_send R:a55e0f0e16d0|task_server] Task 48 completed; duration = 793
Mar  7 16:55:27 ede-vmh001 xapi: [debug||58317 |Async.VM.migrate_send R:a55e0f0e16d0|storage] TASK.signal 48 = ["Completed",{"result":["Mirror_id","5c93fb03-318e-93cb-c16d-b0f8deca16f9/9d56b5b4-758d-4f41-be21-c47bbe3edf12"],"duration":792.6625249385834}]
Mar  7 16:55:27 ede-vmh001 xapi: [ info||61634 HTTP 127.0.0.1->:::80|Querying services D:7c4a3f2d385d|storage_impl] DATA.MIRROR.stat dbg:Async.VM.migrate_send R:a55e0f0e16d0 id:5c93fb03-318e-93cb-c16d-b0f8deca16f9/9d56b5b4-758d-4f41-be21-c47bbe3edf12
Mar  7 16:55:29 ede-vmh001 xapi: [ info||61663 HTTP 127.0.0.1->:::80|Querying services D:a86dc3607764|storage_impl] DP.destroy dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdc allow_leak:false
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61663 HTTP 127.0.0.1->:::80|Querying services D:a86dc3607764|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdc sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:506f2926-a956-4ee8-bafd-739a7b8405a4 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61663 HTTP 127.0.0.1->:::80|Querying services D:a86dc3607764|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdc sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:506f2926-a956-4ee8-bafd-739a7b8405a4 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [ info||61667 HTTP 127.0.0.1->:::80|Querying services D:b8c8ba50906e|storage_impl] DP.destroy dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdb allow_leak:false
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61667 HTTP 127.0.0.1->:::80|Querying services D:b8c8ba50906e|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdb sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:42635a54-c435-46c1-8e2e-7f58b59b3c25 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61667 HTTP 127.0.0.1->:::80|Querying services D:b8c8ba50906e|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdb sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:42635a54-c435-46c1-8e2e-7f58b59b3c25 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [ info||61671 HTTP 127.0.0.1->:::80|Querying services D:14cbc8eaf49c|storage_impl] DP.destroy dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvda allow_leak:false
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61671 HTTP 127.0.0.1->:::80|Querying services D:14cbc8eaf49c|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvda sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:58a45bf4-10bc-4dca-a72b-f5cf3110ef80 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61671 HTTP 127.0.0.1->:::80|Querying services D:14cbc8eaf49c|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvda sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:58a45bf4-10bc-4dca-a72b-f5cf3110ef80 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [ info||61675 HTTP 127.0.0.1->:::80|Querying services D:a4ca021b6388|storage_impl] DP.destroy dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvde allow_leak:false
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61675 HTTP 127.0.0.1->:::80|Querying services D:a4ca021b6388|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvde sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:b2ae45fd-4164-4193-9707-35841ab405e6 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61675 HTTP 127.0.0.1->:::80|Querying services D:a4ca021b6388|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvde sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:b2ae45fd-4164-4193-9707-35841ab405e6 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [ info||61679 HTTP 127.0.0.1->:::80|Querying services D:f301e88246f2|storage_impl] DP.destroy dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdi allow_leak:false
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61679 HTTP 127.0.0.1->:::80|Querying services D:f301e88246f2|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdi sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:962d0e61-0268-47b7-bd34-a01d220a2bd7 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61679 HTTP 127.0.0.1->:::80|Querying services D:f301e88246f2|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdi sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:962d0e61-0268-47b7-bd34-a01d220a2bd7 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [ info||61683 HTTP 127.0.0.1->:::80|Querying services D:32ac53c4a80c|storage_impl] DP.destroy dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdf allow_leak:false
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61683 HTTP 127.0.0.1->:::80|Querying services D:32ac53c4a80c|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdf sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:b3aa5e45-f7d0-42a6-b82c-c10eb8fea20d superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61683 HTTP 127.0.0.1->:::80|Querying services D:32ac53c4a80c|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdf sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:b3aa5e45-f7d0-42a6-b82c-c10eb8fea20d superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [ info||61687 HTTP 127.0.0.1->:::80|Querying services D:93daaf27709b|storage_impl] DP.destroy dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdg allow_leak:false
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61687 HTTP 127.0.0.1->:::80|Querying services D:93daaf27709b|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdg sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:d7a9fee9-c387-45c4-8970-bdb2e89d26f7 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61687 HTTP 127.0.0.1->:::80|Querying services D:93daaf27709b|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdg sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:d7a9fee9-c387-45c4-8970-bdb2e89d26f7 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [ info||61691 HTTP 127.0.0.1->:::80|Querying services D:e4285adb7033|storage_impl] DP.destroy dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdh allow_leak:false
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61691 HTTP 127.0.0.1->:::80|Querying services D:e4285adb7033|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdh sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:9d56b5b4-758d-4f41-be21-c47bbe3edf12 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xapi: [debug||61691 HTTP 127.0.0.1->:::80|Querying services D:e4285adb7033|storage_impl] dbg:Async.VM.migrate_send R:a55e0f0e16d0 dp:mirror_vbd/13/xvdh sr:5c93fb03-318e-93cb-c16d-b0f8deca16f9 vdi:9d56b5b4-758d-4f41-be21-c47bbe3edf12 superstate:activated RW
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] Task 826 reference Async.VM.migrate_send R:a55e0f0e16d0: ["VM_migrate",{"vmm_tmp_dest_id":"e8c6913e-6aae-e486-571f-000000000001","vmm_tmp_src_id":"e8c6913e-6aae-e486-571f-000000000000","vmm_url":"http://10.40.4.42/services/xenops?session_id=OpaqueRef:3e33ae54-0932-4607-a41b-e2c7fcde4fdc","vmm_vgpu_pci_map":{},"vmm_vif_map":{"0":["Local","xapi4"]},"vmm_vdi_map":{"5c93fb03-318e-93cb-c16d-b0f8deca16f9/506f2926-a956-4ee8-bafd-739a7b8405a4":"20df4650-1ccd-6b78-e41d-a2fabf17385b/c61074bc-c3f8-47b1-9e99-75344917c548","5c93fb03-318e-93cb-c16d-b0f8deca16f9/42635a54-c435-46c1-8e2e-7f58b59b3c25":"20df4650-1ccd-6b78-e41d-a2fabf17385b/8174850d-709b-460c-b1ae-46ae7c27bb65","5c93fb03-318e-93cb-c16d-b0f8deca16f9/58a45bf4-10bc-4dca-a72b-f5cf3110ef80":"20df4650-1ccd-6b78-e41d-a2fabf17385b/5416378a-8b6d-49d9-ac6a-3684bae66251","5c93fb03-318e-93cb-c16d-b0f8deca16f9/b2ae45fd-4164-4193-9707-35841ab405e6":"20df4650-1ccd-6b78-e41d-a2fabf17385b/b77f6550-3195-4180-9a28-e0720db8f50e","5c93fb03-318e-93cb-c16d-b0f8deca16f9/962d0e61-0268-47b7-bd34-a01d220a2bd7":"20df4650-1ccd-6b78-e41d-a2fabf17385b/00138f15-3354-4e04-a879-87c11fc93efc","5c93fb03-318e-93cb-c16d-b0f8deca16f9/b3aa5e45-f7d0-42a6-b82c-c10eb8fea20d":"20df4650-1ccd-6b78-e41d-a2fabf17385b/8d6e4142-731f-488b-9471-a815ffd52c86","5c93fb03-318e-93cb-c16d-b0f8deca16f9/d7a9fee9-c387-45c4-8970-bdb2e89d26f7":"20df4650-1ccd-6b78-e41d-a2fabf17385b/9f519d8f-76c6-46e1-afb3-f6c54e9882aa","5c93fb03-318e-93cb-c16d-b0f8deca16f9/9d56b5b4-758d-4f41-be21-c47bbe3edf12":"20df4650-1ccd-6b78-e41d-a2fabf17385b/c972e8b8-0c05-4224-9aa5-2ff4fe54673d"},"vmm_id":"e8c6913e-6aae-e486-571f-70d1791e4a97"}]
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] VM.migrate e8c6913e-6aae-e486-571f-70d1791e4a97 -> http://10.40.4.42/services/xenops?session_id=OpaqueRef:3e33ae54-0932-4607-a41b-e2c7fcde4fdc
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] QMP command for domid 13: {"execute":"query-migratable","id":"qmp-000067-13"}
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] received QMP response qmp-000067-13 (File "xc/device_common.ml", line 502, characters 49-56)
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] query-migratable precheck passed (domid=13)
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] xenstore-rm /local/domain/13/data/cant_suspend_reason
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] assert_can_suspend: OK (domid=13)
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] Destination domain will be built with uuid=e8c6913e-6aae-e486-571f-000000000001
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] Original domain will be moved to uuid=e8c6913e-6aae-e486-571f-000000000000
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] Queue: Aliasing existing tag 'e8c6913e-6aae-e486-571f-70d1791e4a97' to new tag 'e8c6913e-6aae-e486-571f-000000000000'
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] Remapping bootloader VDIs
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_utils] Remapping VIF: 0
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] Remapping normal VDIs
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_utils] Remapping VDI: 5c93fb03-318e-93cb-c16d-b0f8deca16f9/b3aa5e45-f7d0-42a6-b82c-c10eb8fea20d -> 20df4650-1ccd-6b78-e41d-a2fabf17385b/8d6e4142-731f-488b-9471-a815ffd52c86
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_utils] Remapping VDI: 5c93fb03-318e-93cb-c16d-b0f8deca16f9/b2ae45fd-4164-4193-9707-35841ab405e6 -> 20df4650-1ccd-6b78-e41d-a2fabf17385b/b77f6550-3195-4180-9a28-e0720db8f50e
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_utils] Remapping VDI: 5c93fb03-318e-93cb-c16d-b0f8deca16f9/9d56b5b4-758d-4f41-be21-c47bbe3edf12 -> 20df4650-1ccd-6b78-e41d-a2fabf17385b/c972e8b8-0c05-4224-9aa5-2ff4fe54673d
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_utils] Remapping VDI: 5c93fb03-318e-93cb-c16d-b0f8deca16f9/506f2926-a956-4ee8-bafd-739a7b8405a4 -> 20df4650-1ccd-6b78-e41d-a2fabf17385b/c61074bc-c3f8-47b1-9e99-75344917c548
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_utils] Remapping VDI: 5c93fb03-318e-93cb-c16d-b0f8deca16f9/58a45bf4-10bc-4dca-a72b-f5cf3110ef80 -> 20df4650-1ccd-6b78-e41d-a2fabf17385b/5416378a-8b6d-49d9-ac6a-3684bae66251
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_utils] Remapping VDI: 5c93fb03-318e-93cb-c16d-b0f8deca16f9/d7a9fee9-c387-45c4-8970-bdb2e89d26f7 -> 20df4650-1ccd-6b78-e41d-a2fabf17385b/9f519d8f-76c6-46e1-afb3-f6c54e9882aa
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_utils] Remapping VDI: 5c93fb03-318e-93cb-c16d-b0f8deca16f9/42635a54-c435-46c1-8e2e-7f58b59b3c25 -> 20df4650-1ccd-6b78-e41d-a2fabf17385b/8174850d-709b-460c-b1ae-46ae7c27bb65
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_utils] Remapping VDI: 5c93fb03-318e-93cb-c16d-b0f8deca16f9/962d0e61-0268-47b7-bd34-a01d220a2bd7 -> 20df4650-1ccd-6b78-e41d-a2fabf17385b/00138f15-3354-4e04-a879-87c11fc93efc
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] Received vm-id = e8c6913e-6aae-e486-571f-000000000001
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] VM.set_memory_dynamic_range (e8c6913e-6aae-e486-571f-70d1791e4a97, 103079215104, 103079215104)
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] VM = e8c6913e-6aae-e486-571f-70d1791e4a97; domid = 13; set_memory_dynamic_range min = 100663296; max = 100663296
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] rebalance_memory
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] VM_DB.signal e8c6913e-6aae-e486-571f-70d1791e4a97
Mar  7 16:55:29 ede-vmh001 xenopsd-xc: [ info||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] VM e8c6913e-6aae-e486-571f-70d1791e4a97 has memory_limit = 103079211008
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] VM.migrate: Synchronisation point 1
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] Performing: ["VM_save",["e8c6913e-6aae-e486-571f-70d1791e4a97",["Live"],["FD",25],[]]]
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] VM.save e8c6913e-6aae-e486-571f-70d1791e4a97
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] looking for emu-manager in [ featureset : 178bfbff-f6d83203-2e500800-040001f7-0000000f-219c01a9-00400004-00000000-010cd005-00000000-00000000-00000000-00000000-00000000-00000000-00000000-00000000-00000000; timeoffset : 1; usb : true; usb_tablet : true; device-model : qemu-upstream-compat; viridian : false; hpet : true; pae : true; apic : true; acpi : 1; device_id : 0001; videoram : 8; vga : std; nx : true; cores-per-socket : 1 ]
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|mig64] VM = e8c6913e-6aae-e486-571f-70d1791e4a97; domid = 13; suspend live = true
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|mig64] Writing save signature: XenSavedDomv2-\x0A
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|mig64] Writing Xenops header (length=1668)
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|mig64] Writing Xenops record contents
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|emu-manager] connect: args = [ -fd 9b940ee4-28dc-4ddc-83e7-627571199e1f -mode hvm_save -domid 13 -dm qemu -live true ]
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] VM = e8c6913e-6aae-e486-571f-70d1791e4a97; domid = 13; waiting for emu-manager...
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] VM = e8c6913e-6aae-e486-571f-70d1791e4a97; domid = 13; progress = 0 / 100
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] TASK.signal 826 = ["Pending",0.0]
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] VM = e8c6913e-6aae-e486-571f-70d1791e4a97; domid = 13; message from emu-manager: prepare:xenguest
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] Writing Libxc header
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] Writing Libxc record
Mar  7 16:55:30 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] VM = e8c6913e-6aae-e486-571f-70d1791e4a97; domid = 13; waiting for emu-manager...
Mar  7 17:01:28 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] VM = e8c6913e-6aae-e486-571f-70d1791e4a97; domid = 13; progress = 1 / 100
Mar  7 17:01:28 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] TASK.signal 826 = ["Pending",0.00909090909090909]
Mar  7 17:02:22 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] VM = e8c6913e-6aae-e486-571f-70d1791e4a97; domid = 13; progress = 2 / 100
Mar  7 17:02:22 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] TASK.signal 826 = ["Pending",0.01818181818181818]
Mar  7 17:02:25 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] VM = e8c6913e-6aae-e486-571f-70d1791e4a97; domid = 13; progress = 3 / 100
Mar  7 17:02:25 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] TASK.signal 826 = ["Pending",0.02727272727272727]
Mar  7 17:02:28 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] VM = e8c6913e-6aae-e486-571f-70d1791e4a97; domid = 13; progress = 4 / 100
Mar  7 17:02:28 ede-vmh001 xenopsd-xc: [debug||17 |Async.VM.migrate_send R:a55e0f0e16d0|xenops_server] TASK.signal 826 = ["Pending",0.03636363636363636]

Destination:

Mar  7 16:47:06 ede-vmh023 xenopsd-xc: [error||42 |events|task_server] Task 1339 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:48:06 ede-vmh023 xenopsd-xc: [ info||32 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:48:06 ede-vmh023 xenopsd-xc: [error||32 |events|task_server] Task 1350 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:49:06 ede-vmh023 xenopsd-xc: [ info||26 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:49:06 ede-vmh023 xenopsd-xc: [error||26 |events|task_server] Task 1361 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:50:06 ede-vmh023 xenopsd-xc: [ info||17 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:50:06 ede-vmh023 xenopsd-xc: [error||17 |events|task_server] Task 1372 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:51:07 ede-vmh023 xenopsd-xc: [ info||40 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:51:07 ede-vmh023 xenopsd-xc: [error||40 |events|task_server] Task 1383 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:52:07 ede-vmh023 xenopsd-xc: [ info||36 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:52:07 ede-vmh023 xenopsd-xc: [error||36 |events|task_server] Task 1394 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:53:07 ede-vmh023 xenopsd-xc: [ info||38 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:53:07 ede-vmh023 xenopsd-xc: [error||38 |events|task_server] Task 1405 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:54:07 ede-vmh023 xenopsd-xc: [ info||30 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:54:07 ede-vmh023 xenopsd-xc: [error||30 |events|task_server] Task 1416 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:55:08 ede-vmh023 xenopsd-xc: [ info||11 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:55:08 ede-vmh023 xenopsd-xc: [error||11 |events|task_server] Task 1427 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:55:29 ede-vmh023 xenopsd-xc: [debug||28 |Async.VM.migrate_send R:a55e0f0e16d0|xenops] Device.Vif.add domid=12 devid=0 mac=3e:1a:63:bd:7b:6d carrier=true rate=none other_config=[] extra_private_keys=[vif-id=0; vif-uuid=90338c8e-ff8a-1185-ad87-96bcdb31b002; network-uuid=dab4a716-c66b-8adc-370d-bc5b870eb2ed; locking-mode=unlocked; setup-vif-rules=/usr/libexec/xenopsd/setup-vif-rules; setup-pvs-proxy-rules=/usr/libexec/xenopsd/setup-pvs-proxy-rules; xenopsd-backend=classic] extra_xenserver_keys=[static-ip-setting/mac=3e:1a:63:bd:7b:6d; static-ip-setting/error-code=0; static-ip-setting/error-msg=; static-ip-setting/enabled=0; static-ip-setting/enabled6=0]
Mar  7 16:55:29 ede-vmh023 xapi: [error||72 |org.xen.xapi.xenops.classic events D:eecca4959efc|xenops] xenopsd event: Caught Db_exn.Read_missing_uuid("VM", "", "e8c6913e-6aae-e486-571f-000000000001") while updating VIF
Mar  7 16:55:30 ede-vmh023 xapi: [error||72 |org.xen.xapi.xenops.classic events D:eecca4959efc|xenops] xenopsd event: Caught Db_exn.Read_missing_uuid("VM", "", "e8c6913e-6aae-e486-571f-000000000001") while updating VIF
Mar  7 16:56:08 ede-vmh023 xenopsd-xc: [ info||19 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:56:08 ede-vmh023 xenopsd-xc: [error||19 |events|task_server] Task 1439 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:57:08 ede-vmh023 xenopsd-xc: [ info||42 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:57:08 ede-vmh023 xenopsd-xc: [error||42 |events|task_server] Task 1450 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:58:08 ede-vmh023 xenopsd-xc: [ info||32 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:58:08 ede-vmh023 xenopsd-xc: [error||32 |events|task_server] Task 1461 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 16:59:08 ede-vmh023 xenopsd-xc: [ info||36 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 16:59:08 ede-vmh023 xenopsd-xc: [error||36 |events|task_server] Task 1472 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 17:00:09 ede-vmh023 xenopsd-xc: [ info||24 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 17:00:09 ede-vmh023 xenopsd-xc: [error||24 |events|task_server] Task 1483 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 17:01:09 ede-vmh023 xenopsd-xc: [ info||13 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 17:01:09 ede-vmh023 xenopsd-xc: [error||13 |events|task_server] Task 1494 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 17:02:09 ede-vmh023 xenopsd-xc: [ info||21 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 17:02:09 ede-vmh023 xenopsd-xc: [error||21 |events|task_server] Task 1505 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 17:03:09 ede-vmh023 xenopsd-xc: [ info||26 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 17:03:09 ede-vmh023 xenopsd-xc: [error||26 |events|task_server] Task 1516 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 17:04:10 ede-vmh023 xenopsd-xc: [ info||38 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 17:04:10 ede-vmh023 xenopsd-xc: [error||38 |events|task_server] Task 1527 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])
Mar  7 17:05:10 ede-vmh023 xenopsd-xc: [ info||30 |events|xenops_server] Caught Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]]) executing ["VM_check_state","cc1ec41b-58e2-d4db-5af6-000000000001"]: triggering cleanup actions
Mar  7 17:05:10 ede-vmh023 xenopsd-xc: [error||30 |events|task_server] Task 1538 failed; Xenops_interface.Xenopsd_error([S(Does_not_exist);[S(VM);S(cc1ec41b-58e2-d4db-5af6-000000000001/config)]])

Now I'm thinking the Xenops_interface.Xenopsd_error message might be a red herring since it occurs during the entire migration, and also continues after the VM has already started being responsive again

Here, the VM was unreachable from 16:55:30 until 17:00:28.
On our smallers VMs we don't really see the behaviour, but our larger VMs do have it quite often. This means we are always quite anxious to live migrate larger VMs since there's often a few minutes impact.

Is there anything we can do to debug this?

Hello,

We sometimes see a live-migration initiated through XOA fail. The failure is not immediately visible in XOA itself, but rather it looks like the task has cancelled.

We are migrating within the same pool and we also have local storage.
I've been digging through the xensource.log file (which is very very verbose) and I believe this is the relevant cause of the migration failure:

Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||stunnel] stunnel start
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||xmlrpc_client] stunnel pid: 14638 (cached = false) connected to 10.40.1.20:443
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=14638
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||stunnel] stunnel start
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||xmlrpc_client] stunnel pid: 14646 (cached = false) connected to 10.40.1.20:443
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=14646
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||stunnel] stunnel start
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||xmlrpc_client] stunnel pid: 14652 (cached = false) connected to 10.40.1.20:443
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=14652
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Registering mirror id 5c93fb03-318e-93cb-c16d-b0f8deca16f9/58a45bf4-10bc-4dca-a72b-f5cf3110ef80 with task OpaqueRef:ccd4b11a-75d2-4e16-b881-5fa9e6496071
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Waiting for task id=5 to finish
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Calling UPDATES.get Async.VM.migrate_send R:ccd4b11a75d2  30
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Received update: ["Task","4"]
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Calling UPDATES.get Async.VM.migrate_send R:ccd4b11a75d2 507 30
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Received update: ["Task","4"]
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Calling UPDATES.get Async.VM.migrate_send R:ccd4b11a75d2 508 30
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Received update: ["Task","4"]
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Calling UPDATES.get Async.VM.migrate_send R:ccd4b11a75d2 509 30
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Received update: ["Task","4"]
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Calling UPDATES.get Async.VM.migrate_send R:ccd4b11a75d2 510 30
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Received update: ["Task","4"]
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Calling UPDATES.get Async.VM.migrate_send R:ccd4b11a75d2 511 30
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Received update: ["Task","4"]
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Calling UPDATES.get Async.VM.migrate_send R:ccd4b11a75d2 512 30
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Received update: ["Task","4"]
Mar  7 15:15:52 ede-vmh001 xapi: [debug||4350 ||storage_access] Calling UPDATES.get Async.VM.migrate_send R:ccd4b11a75d2 513 30
Mar  7 15:15:56 ede-vmh001 xapi: [debug||4350 ||storage_access] Received update: ["Task","4"]
Mar  7 15:15:56 ede-vmh001 xapi: [debug||4350 ||storage_access] Calling UPDATES.get Async.VM.migrate_send R:ccd4b11a75d2 514 30
Mar  7 15:15:58 ede-vmh001 xapi: [debug||4350 ||storage_access] Received update: ["Task","5"]
Mar  7 15:16:02 ede-vmh001 xapi: [debug||4350 ||stunnel] stunnel start
Mar  7 15:16:02 ede-vmh001 xapi: [debug||4350 ||xmlrpc_client] stunnel pid: 15655 (cached = false) connected to 10.40.1.20:443
Mar  7 15:16:02 ede-vmh001 xapi: [debug||4350 ||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=15655
Mar  7 15:16:02 ede-vmh001 xapi: [error||4350 ||xapi_vm_migrate] Failed to destroy remote VDI
Mar  7 15:16:05 ede-vmh001 xapi: [debug||4350 ||stunnel] stunnel start
Mar  7 15:16:05 ede-vmh001 xapi: [debug||4350 ||xmlrpc_client] stunnel pid: 16137 (cached = false) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh001 xapi: [debug||4350 ||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=16137
Mar  7 15:16:05 ede-vmh001 xapi: [error||4350 ||xapi_vm_migrate] Failed to destroy remote VDI
Mar  7 15:16:05 ede-vmh001 xapi: [error||4350 ||xapi_vm_migrate] Caught Storage_error ([S(Internal_error);S(Storage_error ([S(Internal_error);S(Db_exn.Read_missing_uuid("VDI", "", "61f0bf5f-7519-4fa6-932c-429e2c58d36d"))]))]): cleaning up
Mar  7 15:16:05 ede-vmh001 xapi: [debug||4350 ||xenops] suppressing xenops events on VM: e8c6913e-6aae-e486-571f-70d1791e4a97
Mar  7 15:16:05 ede-vmh001 xapi: [debug||4350 ||xenops] re-enabled xenops events on VM: e8c6913e-6aae-e486-571f-70d1791e4a97; refreshing VM
Mar  7 15:16:06 ede-vmh001 xapi: [debug||4350 ||xenops] Client.UPDATES.inject_barrier 12
Mar  7 15:16:06 ede-vmh001 xapi: [ warn||4350 ||rbac_audit] cannot marshall arguments for the action VM.migrate_send: name and value list lengths don't match. str_names=[session_id,vm,dest,live,vdi_map,vif_map,options,vgpu_map,], xml_values=[S(OpaqueRef:fa6be910-d4bd-4992-898b-78018a664b96),S(OpaqueRef:e8b18063-0391-411c-8541-9617e463359b),{SM:S(http://10.40.4.42/services/SM?session_id=OpaqueRef:16db6288-f24f-4f3a-9a08-e25a0871b384);host:S(OpaqueRef:0b95600a-f71c-4acb-b9f4-5fc8ad718f3b);xenops:S(http://10.40.4.42/services/xenops?session_id=OpaqueRef:16db6288-f24f-4f3a-9a08-e25a0871b384);session_id:S(OpaqueRef:16db6288-f24f-4f3a-9a08-e25a0871b384);master:S(http://10.40.1.20/)},B(true),{OpaqueRef:7fc71b20-c2e1-40aa-ac5e-69926cc82a74:S(OpaqueRef:44ae5260-b2f3-4b79-849d-40d3ee497561);OpaqueRef:a9c86b75-7486-43ee-b78f-289b722008dd:S(OpaqueRef:44ae5260-b2f3-4b79-849d-40d3ee497561);OpaqueRef:79234722-e12b-40d6-92d0-692d4bf0e622:S(OpaqueRef:44ae5260-b2f3-4b79-849d-40d3ee497561);OpaqueRef:d2678008-101e-4815-88f6-7800d3dc4259:S(OpaqueRef:44ae5260-b2f3-4b79-849d-40d3ee497561);OpaqueRef:58e643f1-ea92-4100-a25c-cb4e30cd04c0:S(OpaqueRef:44ae5260-b2f3-4b79-849d-40d3ee497561);OpaqueRef:b8528695-c177-44cc-b730-cc047f568815:S(OpaqueRef:44ae5260-b2f3-4b79-849d-40d3ee497561);OpaqueRef:cb2276ab-a046-4152-ab41-7f653db26125:S(OpaqueRef:44ae5260-b2f3-4b79-849d-40d3ee497561);OpaqueRef:fbc37694-1d57-4b64-b7e7-9fe772219f21:S(OpaqueRef:44ae5260-b2f3-4b79-849d-40d3ee497561)},{},{force:S(false)},]
Mar  7 15:16:06 ede-vmh001 xapi: [error||4350 ||backtrace] Async.VM.migrate_send R:ccd4b11a75d2 failed with exception Storage_error ([S(Internal_error);S(Storage_error ([S(Internal_error);S(Db_exn.Read_missing_uuid("VDI", "", "61f0bf5f-7519-4fa6-932c-429e2c58d36d"))]))])
Mar  7 15:16:06 ede-vmh001 xapi: [error||4350 ||backtrace] Raised Storage_error ([S(Internal_error);S(Storage_error ([S(Internal_error);S(Db_exn.Read_missing_uuid("VDI", "", "61f0bf5f-7519-4fa6-932c-429e2c58d36d"))]))])
Mar  7 15:16:06 ede-vmh001 xapi: [error||4350 ||backtrace] 1/1 xapi Raised at file (Thread 4350 has no backtrace table. Was with_backtraces called?, line 0

Looking at the destination hypervisor, I can see this in the logs:

Mar  7 15:16:05 ede-vmh023 xapi: [debug||3160 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 23989 (cached = true) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3160 /var/lib/xcp/xapi||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=23989
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3160 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 23989 (cached = true) returned stunnel to cache
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3161 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 30802 (cached = true) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3161 /var/lib/xcp/xapi||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=30802
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3161 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 30802 (cached = true) returned stunnel to cache
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3162 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 22558 (cached = true) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3162 /var/lib/xcp/xapi||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=22558
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3162 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 22558 (cached = true) returned stunnel to cache
Mar  7 15:16:05 ede-vmh023 xapi: [ info||3133 |sm_exec D:ee93e87f13ab|xapi_session] Session.destroy trackid=772a4b57ee6ac04bcb859460339b70a1
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3132 HTTP 127.0.0.1->:::80|Querying services D:e386332a6ca6|storage_impl] dbg:Async.VM.migrate_send R:ccd4b11a75d2 dp:fe0ede4a-7fa3-2d79-2cbb-ef7631557dad sr:20df4650-1ccd-6b78-e41d-a2fabf17385b vdi:287325ca-b764-4c9c-930d-e94c24e99b81 superstate:attached  RW
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3163 ||dummytaskhelper] task VDI.detach D:743c1af42d91 created by task O:Async.VM.mig
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3163 |VDI.detach D:743c1af42d91|sm] SM ext vdi_detach sr=OpaqueRef:44ae5260-b2f3-4b79-849d-40d3ee497561 vdi=OpaqueRef:8a61f43e-64c7-4643-88d0-81cc460f79c1
Mar  7 15:16:05 ede-vmh023 xapi: [ info||3163 |sm_exec D:4765aa6c267e|xapi_session] Session.create trackid=078dcc14e422e2a605c04ba9b0b9366e pool=false uname= originator=xapi is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3163 |sm_exec D:4765aa6c267e|xmlrpc_client] stunnel pid: 23989 (cached = true) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3163 |sm_exec D:4765aa6c267e|xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=23989
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3163 |sm_exec D:4765aa6c267e|xmlrpc_client] stunnel pid: 23989 (cached = true) returned stunnel to cache
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3164 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 30802 (cached = true) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3164 /var/lib/xcp/xapi||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=30802
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3164 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 30802 (cached = true) returned stunnel to cache
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3165 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 22558 (cached = true) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3165 /var/lib/xcp/xapi||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=22558
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3165 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 22558 (cached = true) returned stunnel to cache
Mar  7 15:16:05 ede-vmh023 xapi: [ info||3163 |sm_exec D:4765aa6c267e|xapi_session] Session.destroy trackid=078dcc14e422e2a605c04ba9b0b9366e
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3163 ||dummytaskhelper] task VDI.detach D:6439806fd8cd created by task O:Async.VM.mig
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3132 HTTP 127.0.0.1->:::80|Querying services D:e386332a6ca6|storage_impl] dbg:Async.VM.migrate_send R:ccd4b11a75d2 dp:fe0ede4a-7fa3-2d79-2cbb-ef7631557dad sr:20df4650-1ccd-6b78-e41d-a2fabf17385b vdi:287325ca-b764-4c9c-930d-e94c24e99b81 superstate:detached
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3132 :::80||stunnel] stunnel start
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3132 :::80||xmlrpc_client] stunnel pid: 32024 (cached = false) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3132 :::80||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=32024
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3166 :::80||stunnel] stunnel start
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3166 :::80||xmlrpc_client] stunnel pid: 32026 (cached = false) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3166 :::80||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=32026
Mar  7 15:16:05 ede-vmh023 xapi: [ info||3166 HTTP 127.0.0.1->:::80|Querying services D:5003e7b1fbce|storage_impl] VDI.destroy dbg:Async.VM.migrate_send R:ccd4b11a75d2 sr:20df4650-1ccd-6b78-e41d-a2fabf17385b vdi:2d5b73c9-8560-4d2a-884f-c445565735df
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3167 ||dummytaskhelper] task VDI.destroy D:8fe82e3398a0 created by task O:Async.VM.mig
Mar  7 15:16:05 ede-vmh023 xapi: [error||3167 ||backtrace] VDI.destroy D:8fe82e3398a0 failed with exception Storage_access.No_VDI
Mar  7 15:16:05 ede-vmh023 xapi: [error||3167 ||backtrace] Raised Storage_access.No_VDI
Mar  7 15:16:05 ede-vmh023 xapi: [error||3167 ||backtrace] 1/1 xapi Raised at file (Thread 3167 has no backtrace table. Was with_backtraces called?, line 0
Mar  7 15:16:05 ede-vmh023 xapi: [error||3167 ||backtrace]
Mar  7 15:16:05 ede-vmh023 xapi: [error||3167 ||storage_interface] Storage_error ([S(Vdi_does_not_exist);S(2d5b73c9-8560-4d2a-884f-c445565735df)]) (File "storage/storage_interface.ml", line 436, characters 51-58)
Mar  7 15:16:05 ede-vmh023 xapi: [error||3166 HTTP 127.0.0.1->:::80|Querying services D:5003e7b1fbce|storage_interface] Storage_error ([S(Vdi_does_not_exist);S(2d5b73c9-8560-4d2a-884f-c445565735df)]) (File "storage/storage_interface.ml", line 431, characters 49-56)
Mar  7 15:16:05 ede-vmh023 xapi: [error||3166 HTTP 127.0.0.1->:::80|Querying services D:5003e7b1fbce|storage_interface] Storage_error ([S(Vdi_does_not_exist);S(2d5b73c9-8560-4d2a-884f-c445565735df)]) (File "storage/storage_interface.ml", line 436, characters 51-58)
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3131 HTTP 10.40.4.20->:::80|Querying services D:7f3ffc1a6e5f|storage_utils] Got failure: checking for redirect, call was: -> VDI.destroy({vdi:S(2d5b73c9-8560-4d2a-884f-c445565735df);sr:S(20df4650-1ccd-6b78-e41d-a2fabf17385b);dbg:S(Async.VM.migrate_send R:ccd4b11a75d2)}), results.contents: ["Vdi_does_not_exist","2d5b73c9-8560-4d2a-884f-c445565735df"]
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3131 HTTP 10.40.4.20->:::80|Querying services D:7f3ffc1a6e5f|storage_utils] Not a redirect: -> VDI.destroy({vdi:S(2d5b73c9-8560-4d2a-884f-c445565735df);sr:S(20df4650-1ccd-6b78-e41d-a2fabf17385b);dbg:S(Async.VM.migrate_send R:ccd4b11a75d2)})
Mar  7 15:16:05 ede-vmh023 xapi: [error||3131 HTTP 10.40.4.20->:::80|Querying services D:7f3ffc1a6e5f|storage_interface] Storage_error ([S(Vdi_does_not_exist);S(2d5b73c9-8560-4d2a-884f-c445565735df)]) (File "storage/storage_interface.ml", line 431, characters 49-56)
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3131 HTTP 10.40.4.20->:::80|Querying services D:7f3ffc1a6e5f|backtrace] Raised Storage_error ([S(Vdi_does_not_exist);S(2d5b73c9-8560-4d2a-884f-c445565735df)])
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3131 HTTP 10.40.4.20->:::80|Querying services D:7f3ffc1a6e5f|backtrace] 1/3 xapi Raised at file storage/storage_interface.ml, line 432
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3131 HTTP 10.40.4.20->:::80|Querying services D:7f3ffc1a6e5f|backtrace] 2/3 xapi Called from file src/lib/idl.ml, line 558
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3131 HTTP 10.40.4.20->:::80|Querying services D:7f3ffc1a6e5f|backtrace] 3/3 xapi Called from file lib/debug.ml, line 310
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3131 HTTP 10.40.4.20->:::80|Querying services D:7f3ffc1a6e5f|backtrace]
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3166 :::80||stunnel] stunnel start
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3166 :::80||xmlrpc_client] stunnel pid: 32033 (cached = false) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3166 :::80||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=32033
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3168 :::80||stunnel] stunnel start
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3168 :::80||xmlrpc_client] stunnel pid: 32036 (cached = false) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3168 :::80||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=32036
Mar  7 15:16:05 ede-vmh023 xapi: [ info||3168 HTTP 127.0.0.1->:::80|Querying services D:58b5d0abbacb|storage_impl] VDI.destroy dbg:Async.VM.migrate_send R:ccd4b11a75d2 sr:20df4650-1ccd-6b78-e41d-a2fabf17385b vdi:287325ca-b764-4c9c-930d-e94c24e99b81
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3169 ||dummytaskhelper] task VDI.destroy D:059771f03d0a created by task O:Async.VM.mig
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3169 |VDI.destroy D:059771f03d0a|sm] SM ext vdi_delete sr=OpaqueRef:44ae5260-b2f3-4b79-849d-40d3ee497561 vdi=OpaqueRef:8a61f43e-64c7-4643-88d0-81cc460f79c1
Mar  7 15:16:05 ede-vmh023 xapi: [ info||3169 |sm_exec D:07c441429744|xapi_session] Session.create trackid=67cec2a98474155b4800921bb5683d73 pool=false uname= originator=xapi is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3169 |sm_exec D:07c441429744|xmlrpc_client] stunnel pid: 23989 (cached = true) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3169 |sm_exec D:07c441429744|xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=23989
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3169 |sm_exec D:07c441429744|xmlrpc_client] stunnel pid: 23989 (cached = true) returned stunnel to cache
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3170 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 30802 (cached = true) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3170 /var/lib/xcp/xapi||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=30802
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3170 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 30802 (cached = true) returned stunnel to cache
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3171 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 22558 (cached = true) connected to 10.40.1.20:443
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3171 /var/lib/xcp/xapi||xmlrpc_client] with_recorded_stunnelpid task_opt=None s_pid=22558
Mar  7 15:16:05 ede-vmh023 xapi: [debug||3171 /var/lib/xcp/xapi||xmlrpc_client] stunnel pid: 22558 (cached = true) returned stunnel to cache

It doesn´t consistently happen, i.e. I can just retry the migration and it will work, but we aren't sure why it happens.
Does anyone have any idea?

@gduperrey said in Updates announcements and testing:

New Update Candidates (xen, xapi, templates)

• Xen: Enable AVX-512 by default for EPYC Zen4 (Genoa)
• Xapi: Redirect http requests on the host webpage to https by default.
• Guest templates:
  • Add the following templates: RHEL 9, AlmaLinux 9, Rocky Linux 9, CentOS Stream 8 & 9, Oracle Linux 9

Test on XCP-ng 8.2

From an up to date host:

For Xen, Xapi and Guest templates:

yum clean metadata --enablerepo=xcp-ng-testing
yum update xen-dom0-libs xen-dom0-tools xen-hypervisor xen-libs xen-tools xapi-core xapi-tests xapi-xe guest-templates-json guest-templates-json-data-linux guest-templates-json-data-other guest-templates-json-data-windows --enablerepo=xcp-ng-testing
reboot

Versions:

• xen-*: 4.13.4-9.29.1.xcpng8.2
• xapi-*: 1.249.26-2.2.xcpng8.2
• guest-templates-json-*: 1.9.6-1.2.xcpng8.2

What to test

Normal use and anything else you want to test. The closer to your actual use of XCP-ng, the better.

Test window before official release of the updates

No precise ETA, but the sooner the feedback the better.

Hello,

Is there any update on the ETA for this? Since it has been almost a month. We'll do the xcp-ng updates again soon and if these patches are close to release we will wait for them to prevent double work.

Cheers,
Niels

@planedrop said in New patch - sudo:

@eoin said in New patch - sudo:

@Darkbeldin Oh dear.... okay. Is every patch requiring reboot? If not, are there any ways to figure out if a patch needs reboot or not in XOA?

Just wanted to point out that you should always be prepped to reboot a host periodically, this is true for any hypervisor, it's not a good idea to not patch and just leave it running 24/7, especially in an environment where security matters.

Good thing is reboots of XCP-ng hosts don't really take that long.

While this is also what I'm used to, I have always wondered why it is advertised that no host reboots are required for patches, yet every update requires a patch:
https://xcp-ng.com/pricing.html under "Live Patching":

Enables administrators to patch hypervisors without needing to migrate, shut down or suspend VMs (no host reboots required)

@florent said in backup using http instead of https:

@KPS it's an easy win, so here is your christmas present
https://github.com/vatesfr/xen-orchestra/pull/6596
the message should show if nbd is really activated or not in XO, if there is a nbd enabled network on the host , and if the connection is successfull

Just wondering, could NBD also be used in the future for speeding up live migrations with local storage?

Hi,

Yes, indeed 8.2.1. Was a typo

I've updated the BIOS to 3.5. We'll have to see since it only happens every few months and I did not find a way to reproduce it.

Andrew: System Event Log (in the IPMI Interface) shows nothing. Memtest/Supermicro health check tool also shows no errors (sadly).

From this error, since it mentions tcp, could it indicate the cause might also be a NIC or NIC firmware?

Hello,

We have a host that will crash once every couple of months, taking down all VMs on it and rebooting itself after a few minutes.

We are running XCP-ng 8.1 on a Supermicro chassis. Supermicro's own health-check tooling reports the hardware is OK. We have a few other servers with exact same hardware that do not have this issue.

The crash-logs are very very verbose which is good but I am not sure what information is the most relevant. In the dom0.log I see the following which looks to be the cause:

[8463005.075512]   WARN: general protection fault: 0000 [#1] SMP NOPTI
[8463005.075524]   WARN: CPU: 11 PID: 2467 Comm: handler74 Tainted: G           O      4.19.0+1 #1
[8463005.075532]   WARN: Hardware name: Supermicro SYS-2029TP-HC1R/X11DPT-PS, BIOS 3.0a 01/12/2019
[8463005.075547]   WARN: RIP: e030:__tcp_get_metrics+0x2e/0xa0
[8463005.075553]   WARN: Code: 00 48 8b 05 ac dc a6 00 89 c9 48 8d 04 c8 48 8b 00 48 85 c0 74 77 45 31 d2 eb 0c 48 8b 00 41 83 c2 01 48 85 c0 74 5c 45 31 c0 <66> 83 78 20 02 4c 8d 48 10 41 0f 95 c0 31 c9 47 8d 44 00 02 44 8b
[8463005.075568]   WARN: RSP: e02b:ffff8888a56c3bc0 EFLAGS: 00010246
[8463005.075574]   WARN: RAX: ff66e90000441f0f RBX: 0000000000000001 RCX: 0000000000000000
[8463005.075581]   WARN: RDX: ffffffff820c0640 RSI: ffff8888a56c3bf0 RDI: ffff8888a56c3bd0
[8463005.075587]   WARN: RBP: ffff8888a56c3c38 R08: 0000000000000000 R09: ffffffffc050f6f0
[8463005.075594]   WARN: R10: 0000000000000001 R11: 000000002207f80a R12: 00000000000000bb
[8463005.075601]   WARN: R13: ffff8888a13da180 R14: ffff8888a56c3bd0 R15: ffff8888a56c3bf0
[8463005.075617]   WARN: FS:  00007f99d58b5700(0000) GS:ffff8888a56c0000(0000) knlGS:0000000000000000
[8463005.075624]   WARN: CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
[8463005.075629]   WARN: CR2: 00007f83ce8060a0 CR3: 000000089d094000 CR4: 0000000000040660
[8463005.075640]   WARN: Call Trace:
[8463005.075645]   WARN:  <IRQ>
[8463005.075650]   WARN:  tcp_get_metrics+0xd2/0x2c0
[8463005.075660]   WARN:  ? rt_cpu_seq_stop+0x10/0x10
[8463005.075666]   WARN:  tcp_init_metrics+0x44/0x190
[8463005.075673]   WARN:  tcp_init_transfer+0x40/0x100
[8463005.075679]   WARN:  tcp_finish_connect+0x76/0xf0
[8463005.075684]   WARN:  tcp_rcv_state_process+0x6c3/0xde8
[8463005.075691]   WARN:  ? sk_filter_trim_cap+0x47/0x220
[8463005.075697]   WARN:  tcp_v4_do_rcv+0x70/0x1e0
[8463005.075702]   WARN:  tcp_v4_rcv+0x993/0xa90
[8463005.075710]   WARN:  ip_local_deliver_finish+0x98/0x1e0
[8463005.075716]   WARN:  ip_local_deliver+0x6b/0xe0
[8463005.075721]   WARN:  ? ip_rcv_core.isra.18+0x290/0x290
[8463005.075727]   WARN:  ip_rcv+0x52/0xd0
[8463005.075731]   WARN:  ? ip_local_deliver_finish+0x1e0/0x1e0
[8463005.075739]   WARN:  __netif_receive_skb_one_core+0x52/0x70
[8463005.075746]   WARN:  process_backlog+0xa3/0x150
[8463005.075751]   WARN:  net_rx_action+0x2a5/0x3e0
[8463005.075758]   WARN:  __do_softirq+0xd1/0x28c
[8463005.075766]   WARN:  do_softirq_own_stack+0x2a/0x40
[8463005.075771]   WARN:  </IRQ>
[8463005.075778]   WARN:  do_softirq+0x4b/0x70
[8463005.075784]   WARN:  __local_bh_enable_ip+0x57/0x60
[8463005.075794]   WARN:  ovs_packet_cmd_execute+0x296/0x2c0 [openvswitch]
[8463005.075803]   WARN:  genl_family_rcv_msg+0x1f7/0x3b0
[8463005.075809]   WARN:  genl_rcv_msg+0x47/0x90
[8463005.075814]   WARN:  ? genl_family_rcv_msg+0x3b0/0x3b0
[8463005.075820]   WARN:  netlink_rcv_skb+0xd4/0x110
[8463005.075825]   WARN:  genl_rcv+0x24/0x40
[8463005.075830]   WARN:  netlink_unicast+0x182/0x230
[8463005.075836]   WARN:  netlink_sendmsg+0x2ed/0x3e0
[8463005.075841]   WARN:  sock_sendmsg+0x36/0x50
[8463005.075846]   WARN:  ___sys_sendmsg+0x2b5/0x2d0
[8463005.075855]   WARN:  ? ep_send_events_proc+0x86/0x1a0
[8463005.075860]   WARN:  ? ep_modify+0x160/0x160
[8463005.075866]   WARN:  ? ep_scan_ready_list.isra.13+0x1d8/0x200
[8463005.075872]   WARN:  ? ep_poll+0x1fe/0x3c0
[8463005.075878]   WARN:  ? _copy_to_user+0x22/0x30
[8463005.075884]   WARN:  __sys_sendmsg+0x58/0xa0
[8463005.075892]   WARN:  do_syscall_64+0x4e/0x100
[8463005.075897]   WARN:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[8463005.075904]   WARN: RIP: 0033:0x7f99da3f0d5d
[8463005.075908]   WARN: Code: c6 20 00 00 75 10 b8 2e 00 00 00 0f 05 48 3d 01 f0 ff ff 73 31 c3 48 83 ec 08 e8 be f6 ff ff 48 89 04 24 b8 2e 00 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 07 f7 ff ff 48 89 d0 48 83 c4 08 48 3d 01
[8463005.075923]   WARN: RSP: 002b:00007f99d585d7f0 EFLAGS: 00000293 ORIG_RAX: 000000000000002e
[8463005.075930]   WARN: RAX: ffffffffffffffda RBX: 00007f99d585e630 RCX: 00007f99da3f0d5d
[8463005.075937]   WARN: RDX: 0000000000000000 RSI: 00007f99d585d850 RDI: 000000000000001b
[8463005.075944]   WARN: RBP: 0000000000000002 R08: 0000000000000000 R09: 0000000000000001
[8463005.075951]   WARN: R10: 00007f99bc001540 R11: 0000000000000293 R12: 0000000002574310
[8463005.075958]   WARN: R13: 00007f99d585dcf0 R14: 0000000003aad63e R15: 00007f99d585d850
[8463005.075965]   WARN: Modules linked in: tun nfsv3 nfs_acl nfs lockd grace fscache bnx2fc(O) cnic(O) uio fcoe libfcoe libfc scsi_transport_fc openvswitch nsh nf_nat_ipv6 nf_nat_ipv4 nf_conncount nf_nat 8021q garp mrp stp llc ipt_REJECT nf_reject_ipv4 xt_tcpudp xt_multiport dm_multipath xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c iptable_filter sr_mod cdrom sunrpc skx_edac intel_powerclamp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc aesni_intel aes_x86_64 crypto_simd cryptd glue_helper dm_mod uas usb_storage ipmi_si lpc_ich i2c_i801 ipmi_devintf sg ipmi_msghandler acpi_power_meter ip_tables x_tables hid_generic usbhid hid sd_mod megaraid_sas(O) ahci i40e(O) libahci xhci_pci libata xhci_hcd scsi_dh_rdac scsi_dh_hp_sw scsi_dh_emc scsi_dh_alua scsi_mod ipv6 crc_ccitt
[8463005.076066]   WARN: ---[ end trace db0040d21ba45c02 ]---

Does anyone have a clue to what could be done to resolve this or further narrow down where this is coming from?

Cheers,
Niels

@stormi said in Updates announcements and testing:

@NielsH DRPW and SBDR are related to MMIO (and thus PCI Passthrough), but there are other vulnerabilities that are not related to it.

Okay, thanks. We have to update it than sadly, heh.
Cheers!

Thanks for the new update!

We're trying to determine if we are vulnerable to this. In https://xenbits.xen.org/xsa/advisory-404.html I see:

Per Xen's support statement, PCI passthrough should be to trusted

domains because the overall system security depends on factors outside

of Xen's control.

As such, Xen, in a supported configuration, is not vulnerable to

DRPW/SBDR.

Does this mean we are not vulnerable to XSA-404 if we do not use PCI Passthrough?

Cheers,
Niels

@stormi Ah phew, good to hear we won't have to update everything so quickly again

Looks like yet another security patch from Xenserver available now

https://xenbits.xen.org/xsa/advisory-398.html