libvirt users - Oct 2020 - Re: unable to migrate: virPortAllocatorSetUsed:299 : internal error: Failed to reserve port 49153

On libvirt 6.8.0 and qemu 5.1.0, when trying to live migrate "error:
internal error: Failed to reserve port" error is received and
migration does not succeed:

virsh # migrate cartridge qemu+tls://ratchet.lan/system --live
--persistent --undefinesource --copy-storage-all --verbose
error: internal error: Failed to reserve port 49153

virsh #

On target host with debug logs, nothing interesting but the error
itself is found in the logs

...
2020-10-12 02:11:33.852+0000: 6871: debug :
qemuMonitorJSONIOProcessLine:220 : Line [{"return": {},
"id":
"libvirt-373"}]
2020-10-12 02:11:33.852+0000: 6871: info :
qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY:
mon=0x7fe784255020 reply={"return": {}, "id":
"libvirt-373"}
2020-10-12 02:11:33.852+0000: 6825: debug :
qemuDomainObjExitMonitorInternal:5615 : Exited monitor
(mon=0x7fe784255020 vm=0x55f086c81ea0 name=cartridge)
2020-10-12 02:11:33.852+0000: 6825: debug : qemuDomainObjEndJob:1140 :
Stopping job: async nested (async=migration in vm=0x55f086c81ea0
name=cartridge)
2020-10-12 02:11:33.852+0000: 6825: error :
virPortAllocatorSetUsed:299 : internal error: Failed to reserve port
49153
2020-10-12 02:11:33.852+0000: 6825: debug :
qemuMigrationParamsReset:1206 : Resetting migration parameters
0x7fe784257c30, flags 0x59
2020-10-12 02:11:33.852+0000: 6825: debug :
qemuDomainObjBeginJobInternal:835 : Starting job: job=async nested
agentJob=none asyncJob=none (vm=0x55f086c81ea0 name=cartridge, current
job=none agentJob=none async=migration in)
2020-10-12 02:11:33.852+0000: 6825: debug :
qemuDomainObjBeginJobInternal:887 : Started job: async nested
(async=migration in vm=0x55f086c81ea0 name=cartridge)
2020-10-12 02:11:33.852+0000: 6825: debug :
qemuDomainObjEnterMonitorInternal:5590 : Entering monitor
(mon=0x7fe784255020 vm=0x55f086c81ea0 name=cartridge)
2020-10-12 02:11:33.852+0000: 6825: debug :
qemuMonitorSetMigrationCapabilities:3853 : mon:0x7fe784255020
vm:0x55f086c81ea0 fd:30
2020-10-12 02:11:33.852+0000: 6825: info : qemuMonitorSend:944 :
QEMU_MONITOR_SEND_MSG: mon=0x7fe784255020
msg={"execute":"migrate-set-capabilities","arguments":{"capabilities":[{"capability":"xbzrle","state":false},{"capability":"auto-converge","state":false},{"capability":"rdma-pin-all","state":false},{"capability>
 fd=-1
...

Full logs:
destination:
https://drive.google.com/file/d/1g986SbSVijvwZd8d7xDrJwo_AmKH-JnV/view?usp=sharing

source:
https://drive.google.com/file/d/1lsV2EOBxF7xH5-lgz2Psh9YSkOePXvAd/view?usp=sharing

On target host, nothing is listening on the target port:

ratchet /var/log/libvirt/qemu # netstat -lnp | grep 49153 | wc -l
0

and nc -l 49153 succeeds without issues.

Do you have any suggestions on how to proceed here?

This problem reliably reproduces for me in 6.8.0 and at HEAD but not
in 6.7.0 with no change in environment or VM configs.

Should I file a bug?

On Sun, Oct 11, 2020 at 7:46 PM Vjaceslavs Klimovs <vklimovs@gmail.com>
wrote:
>
> On libvirt 6.8.0 and qemu 5.1.0, when trying to live migrate "error:
> internal error: Failed to reserve port" error is received and
> migration does not succeed:
>
> virsh # migrate cartridge qemu+tls://ratchet.lan/system --live
> --persistent --undefinesource --copy-storage-all --verbose
> error: internal error: Failed to reserve port 49153
>
> virsh #
>
> On target host with debug logs, nothing interesting but the error
> itself is found in the logs
>
> ...
> 2020-10-12 02:11:33.852+0000: 6871: debug :
> qemuMonitorJSONIOProcessLine:220 : Line [{"return": {},
"id":
> "libvirt-373"}]
> 2020-10-12 02:11:33.852+0000: 6871: info :
> qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY:
> mon=0x7fe784255020 reply={"return": {}, "id":
"libvirt-373"}
> 2020-10-12 02:11:33.852+0000: 6825: debug :
> qemuDomainObjExitMonitorInternal:5615 : Exited monitor
> (mon=0x7fe784255020 vm=0x55f086c81ea0 name=cartridge)
> 2020-10-12 02:11:33.852+0000: 6825: debug : qemuDomainObjEndJob:1140 :
> Stopping job: async nested (async=migration in vm=0x55f086c81ea0
> name=cartridge)
> 2020-10-12 02:11:33.852+0000: 6825: error :
> virPortAllocatorSetUsed:299 : internal error: Failed to reserve port
> 49153
> 2020-10-12 02:11:33.852+0000: 6825: debug :
> qemuMigrationParamsReset:1206 : Resetting migration parameters
> 0x7fe784257c30, flags 0x59
> 2020-10-12 02:11:33.852+0000: 6825: debug :
> qemuDomainObjBeginJobInternal:835 : Starting job: job=async nested
> agentJob=none asyncJob=none (vm=0x55f086c81ea0 name=cartridge, current
> job=none agentJob=none async=migration in)
> 2020-10-12 02:11:33.852+0000: 6825: debug :
> qemuDomainObjBeginJobInternal:887 : Started job: async nested
> (async=migration in vm=0x55f086c81ea0 name=cartridge)
> 2020-10-12 02:11:33.852+0000: 6825: debug :
> qemuDomainObjEnterMonitorInternal:5590 : Entering monitor
> (mon=0x7fe784255020 vm=0x55f086c81ea0 name=cartridge)
> 2020-10-12 02:11:33.852+0000: 6825: debug :
> qemuMonitorSetMigrationCapabilities:3853 : mon:0x7fe784255020
> vm:0x55f086c81ea0 fd:30
> 2020-10-12 02:11:33.852+0000: 6825: info : qemuMonitorSend:944 :
> QEMU_MONITOR_SEND_MSG: mon=0x7fe784255020
>
msg={"execute":"migrate-set-capabilities","arguments":{"capabilities":[{"capability":"xbzrle","state":false},{"capability":"auto-converge","state":false},{"capability":"rdma-pin-all","state":false},{"capability>
>  fd=-1
> ...
>
> Full logs:
> destination:
https://drive.google.com/file/d/1g986SbSVijvwZd8d7xDrJwo_AmKH-JnV/view?usp=sharing
>
> source:
>
https://drive.google.com/file/d/1lsV2EOBxF7xH5-lgz2Psh9YSkOePXvAd/view?usp=sharing
>
> On target host, nothing is listening on the target port:
>
> ratchet /var/log/libvirt/qemu # netstat -lnp | grep 49153 | wc -l
> 0
>
> and nc -l 49153 succeeds without issues.
>
> Do you have any suggestions on how to proceed here?

On 10/12/20 4:46 AM, Vjaceslavs Klimovs wrote:
> On libvirt 6.8.0 and qemu 5.1.0, when trying to live migrate "error:
> internal error: Failed to reserve port" error is received and
> migration does not succeed:
> 
> virsh # migrate cartridge qemu+tls://ratchet.lan/system --live
> --persistent --undefinesource --copy-storage-all --verbose
> error: internal error: Failed to reserve port 49153
> 
> virsh #
> 
Sorry for not replying earlier. But this is a clear libvirt bug and I 
think it's a regression introduced by the following commit:

https://gitlab.com/libvirt/libvirt/-/commit/e74d627bb3b

The problem is, if you have two or more disks that need to be copied 
over to the destination, the @server_started variable is not set after 
the first iteration of the "for (i = 0; i < vm->def->ndisks;
i++)" loop.
I think this should be the fix:


diff --git i/src/qemu/qemu_migration.c w/src/qemu/qemu_migration.c
index 2f5d61f8e7..6f764b0c73 100644
--- i/src/qemu/qemu_migration.c
+++ w/src/qemu/qemu_migration.c
@@ -479,9 +479,11 @@ qemuMigrationDstStartNBDServer(virQEMUDriverPtr driver,
 
QEMU_ASYNC_JOB_MIGRATION_IN) < 0)
              goto cleanup;

-        if (!server_started &&
-            qemuMonitorNBDServerStart(priv->mon, &server, tls_alias)
< 0)
-            goto exit_monitor;
+        if (!server_started) {
+            if (qemuMonitorNBDServerStart(priv->mon, &server, 
tls_alias) < 0)
+                goto exit_monitor;
+            server_started = true;
+        }

          if (qemuBlockExportAddNBD(vm, diskAlias, disk->src, diskAlias, 
true, NULL) < 0)
              goto exit_monitor;



Can you please give it a try? If it fixes the issue, I'll post it as a 
patch.

Thanks,
Michal

On 10/26/20 9:39 AM, Michal Privoznik wrote:
> On 10/12/20 4:46 AM, Vjaceslavs Klimovs wrote:
>> On libvirt 6.8.0 and qemu 5.1.0, when trying to live migrate
"error:
>> internal error: Failed to reserve port" error is received and
>> migration does not succeed:
>>
>> virsh # migrate cartridge qemu+tls://ratchet.lan/system --live
>> --persistent --undefinesource --copy-storage-all --verbose
>> error: internal error: Failed to reserve port 49153
>>
>> virsh #
>>
> 
> Sorry for not replying earlier. But this is a clear libvirt bug and I 
> think it's a regression introduced by the following commit:
> 
> https://gitlab.com/libvirt/libvirt/-/commit/e74d627bb3b
> 
> The problem is, if you have two or more disks that need to be copied 
> over to the destination, the @server_started variable is not set after 
> the first iteration of the "for (i = 0; i < vm->def->ndisks;
i++)" loop.
> I think this should be the fix:
> 
Actually, you will need a second patch too. Here's the series:

https://www.redhat.com/archives/libvir-list/2020-October/msg01358.html

Michal