Improve logs for VM migrations (#12332)

nvazquez · web-flow · commit 04875f151771 · 2026-01-09T17:50:27.000+01:00
diff --git a/engine/orchestration/src/main/java/com/cloud/vm/VirtualMachineManagerImpl.java b/engine/orchestration/src/main/java/com/cloud/vm/VirtualMachineManagerImpl.java
@@ -3053,7 +3053,7 @@ private void orchestrateMigrate(final String vmUuid, final long srcHostId, final
     }
 
     protected void migrate(final VMInstanceVO vm, final long srcHostId, final DeployDestination dest) throws ResourceUnavailableException, ConcurrentOperationException {
-        logger.info("Migrating {} to {}", vm, dest);
+        logger.info("Start preparing migration of the VM: {} to {}", vm, dest);
         final long dstHostId = dest.getHost().getId();
         final Host fromHost = _hostDao.findById(srcHostId);
         if (fromHost == null) {
@@ -3118,9 +3118,11 @@ protected void migrate(final VMInstanceVO vm, final long srcHostId, final Deploy
             if (pfma == null || !pfma.getResult()) {
                 final String details = pfma != null ? pfma.getDetails() : "null answer returned";
                 final String msg = "Unable to prepare for migration due to " + details;
+                logger.error("Failed to prepare destination host {} for migration of VM {} : {}", dstHostId, vm.getInstanceName(), details);
                 pfma = null;
                 throw new AgentUnavailableException(msg, dstHostId);
             }
+            logger.debug("Successfully prepared destination host {} for migration of VM {} ", dstHostId, vm.getInstanceName());
         } catch (final OperationTimedoutException e1) {
             throw new AgentUnavailableException("Operation timed out", dstHostId);
         } finally {
@@ -3141,18 +3143,23 @@ protected void migrate(final VMInstanceVO vm, final long srcHostId, final Deploy
                     volumeMgr.release(vm.getId(), dstHostId);
                 }
 
-                logger.info("Migration cancelled because state has changed: {}", vm);
-                throw new ConcurrentOperationException("Migration cancelled because state has changed: " + vm);
+                String msg = "Migration cancelled because state has changed: " + vm;
+                logger.warn(msg);
+                throw new ConcurrentOperationException(msg);
             }
         } catch (final NoTransitionException e1) {
             _networkMgr.rollbackNicForMigration(vmSrc, profile);
             volumeMgr.release(vm.getId(), dstHostId);
-            logger.info("Migration cancelled because {}", e1.getMessage());
+            String msg = String.format("Migration cancelled for VM %s due to state transition failure: %s",
+                    vm.getInstanceName(), e1.getMessage());
+            logger.warn(msg, e1);
             throw new ConcurrentOperationException("Migration cancelled because " + e1.getMessage());
         } catch (final CloudRuntimeException e2) {
             _networkMgr.rollbackNicForMigration(vmSrc, profile);
             volumeMgr.release(vm.getId(), dstHostId);
-            logger.info("Migration cancelled because {}", e2.getMessage());
+            String msg = String.format("Migration cancelled for VM %s due to runtime exception: %s",
+                    vm.getInstanceName(), e2.getMessage());
+            logger.error(msg, e2);
             work.setStep(Step.Done);
             _workDao.update(work.getId(), work);
             try {
@@ -3172,8 +3179,12 @@ protected void migrate(final VMInstanceVO vm, final long srcHostId, final Deploy
                 final Answer ma = _agentMgr.send(vm.getLastHostId(), mc);
                 if (ma == null || !ma.getResult()) {
                     final String details = ma != null ? ma.getDetails() : "null answer returned";
+                    String msg = String.format("Migration command failed for VM %s on source host id=%s to destination host %s: %s",
+                            vm.getInstanceName(), vm.getLastHostId(), dstHostId, details);
+                    logger.error(msg);
                     throw new CloudRuntimeException(details);
                 }
+                logger.info("Migration command successful for VM {}", vm.getInstanceName());
             } catch (final OperationTimedoutException e) {
                 boolean success = false;
                 if (HypervisorType.KVM.equals(vm.getHypervisorType())) {
@@ -3210,7 +3221,7 @@ protected void migrate(final VMInstanceVO vm, final long srcHostId, final Deploy
 
             try {
                 if (!checkVmOnHost(vm, dstHostId)) {
-                    logger.error("Unable to complete migration for {}", vm);
+                    logger.error("Migration verification failed for VM {} : VM not found on destination host {} ", vm.getInstanceName(), dstHostId);
                     try {
                         _agentMgr.send(srcHostId, new Commands(cleanup(vm, dpdkInterfaceMapping)), null);
                     } catch (final AgentUnavailableException e) {
@@ -3225,7 +3236,7 @@ protected void migrate(final VMInstanceVO vm, final long srcHostId, final Deploy
             migrated = true;
         } finally {
             if (!migrated) {
-                logger.info("Migration was unsuccessful.  Cleaning up: {}", vm);
+                logger.info("Migration was unsuccessful. Cleaning up: {}", vm);
                 _networkMgr.rollbackNicForMigration(vmSrc, profile);
                 volumeMgr.release(vm.getId(), dstHostId);
                 // deallocate GPU devices for the VM on the destination host
@@ -3237,7 +3248,7 @@ protected void migrate(final VMInstanceVO vm, final long srcHostId, final Deploy
                 try {
                     _agentMgr.send(dstHostId, new Commands(cleanup(vm, dpdkInterfaceMapping)), null);
                 } catch (final AgentUnavailableException ae) {
-                    logger.warn("Looks like the destination Host is unavailable for cleanup", ae);
+                    logger.warn("Destination host {} unavailable for cleanup after failed migration of VM {}", dstHostId, vm.getInstanceName(), ae);
                 }
                 _networkMgr.setHypervisorHostname(profile, dest, false);
                 try {
@@ -3246,6 +3257,7 @@ protected void migrate(final VMInstanceVO vm, final long srcHostId, final Deploy
                     logger.warn(e.getMessage());
                 }
             } else {
+                logger.info("Migration completed successfully for VM %s" + vm);
                 _networkMgr.commitNicForMigration(vmSrc, profile);
                 volumeMgr.release(vm.getId(), srcHostId);
                 // deallocate GPU devices for the VM on the src host after migration is complete
@@ -3276,6 +3288,7 @@ protected MigrateCommand buildMigrateCommand(VMInstanceVO vmInstance, VirtualMac
             migrateCommand.setVlanToPersistenceMap(vlanToPersistenceMap);
         }
 
+        logger.debug("Setting auto convergence to: {}", StorageManager.KvmAutoConvergence.value());
         migrateCommand.setAutoConvergence(StorageManager.KvmAutoConvergence.value());
         migrateCommand.setHostGuid(destination.getHost().getGuid());
 
diff --git a/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtMigrateCommandWrapper.java b/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtMigrateCommandWrapper.java
@@ -278,17 +278,20 @@ Use VIR_DOMAIN_XML_SECURE (value = 1) prior to v1.0.0.
 
                 // abort the vm migration if the job is executed more than vm.migrate.wait
                 final int migrateWait = libvirtComputingResource.getMigrateWait();
+                logger.info("vm.migrate.wait value set to: {}for VM: {}", migrateWait, vmName);
                 if (migrateWait > 0 && sleeptime > migrateWait * 1000) {
                     DomainState state = null;
                     try {
                         state = dm.getInfo().state;
+                        logger.info("VM domain state when trying to abort migration : {}", state);
                     } catch (final LibvirtException e) {
                         logger.info("Couldn't get VM domain state after " + sleeptime + "ms: " + e.getMessage());
                     }
                     if (state != null && state == DomainState.VIR_DOMAIN_RUNNING) {
                         try {
                             DomainJobInfo job = dm.getJobInfo();
-                            logger.info(String.format("Aborting migration of VM [%s] with domain job [%s] due to time out after %d seconds.", vmName, job, migrateWait));
+                            logger.warn("Aborting migration of VM {} with domain job [{}] due to timeout after {} seconds. " +
+                                    "Job stats: data processed={} bytes, data remaining={} bytes", vmName, job, migrateWait, job.getDataProcessed(), job.getDataRemaining());
                             dm.abortJob();
                             result = String.format("Migration of VM [%s] was cancelled by CloudStack due to time out after %d seconds.", vmName, migrateWait);
                             commandState = Command.State.FAILED;
@@ -303,10 +306,12 @@ Use VIR_DOMAIN_XML_SECURE (value = 1) prior to v1.0.0.
 
                 // pause vm if we meet the vm.migrate.pauseafter threshold and not already paused
                 final int migratePauseAfter = libvirtComputingResource.getMigratePauseAfter();
+                logger.info("vm.migrate.pauseafter value set to: {} for VM: {}", migratePauseAfter, vmName);
                 if (migratePauseAfter > 0 && sleeptime > migratePauseAfter) {
                     DomainState state = null;
                     try {
                         state = dm.getInfo().state;
+                        logger.info("VM domain state when trying to pause VM for migration: {}", state);
                     } catch (final LibvirtException e) {
                         logger.info("Couldn't get VM domain state after " + sleeptime + "ms: " + e.getMessage());
                     }
@@ -381,6 +386,7 @@ Use VIR_DOMAIN_XML_SECURE (value = 1) prior to v1.0.0.
         }
 
         if (result == null) {
+            logger.info("Post-migration cleanup for VM {}: ", vmName);
             libvirtComputingResource.destroyNetworkRulesForVM(conn, vmName);
             for (final InterfaceDef iface : ifaces) {
                 String vlanId = libvirtComputingResource.getVlanIdFromBridgeName(iface.getBrName());
@@ -394,6 +400,7 @@ Use VIR_DOMAIN_XML_SECURE (value = 1) prior to v1.0.0.
             commandState = Command.State.COMPLETED;
             libvirtComputingResource.createOrUpdateLogFileForCommand(command, commandState);
         } else if (commandState == null) {
+            logger.error("Migration of VM {} failed with result: {}", vmName, result);
             commandState = Command.State.FAILED;
             libvirtComputingResource.createOrUpdateLogFileForCommand(command, commandState);
         }
diff --git a/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtPrepareForMigrationCommandWrapper.java b/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtPrepareForMigrationCommandWrapper.java
@@ -56,6 +56,7 @@ public Answer execute(final PrepareForMigrationCommand command, final LibvirtCom
         final VirtualMachineTO vm = command.getVirtualMachine();
 
         if (command.isRollback()) {
+            logger.info("Handling rollback for PrepareForMigration of VM {}", vm.getName());
             return handleRollback(command, libvirtComputingResource);
         }
 
@@ -83,6 +84,7 @@ public Answer execute(final PrepareForMigrationCommand command, final LibvirtCom
                 if (interfaceDef != null && interfaceDef.getNetType() == GuestNetType.VHOSTUSER) {
                     DpdkTO to = new DpdkTO(interfaceDef.getDpdkOvsPath(), interfaceDef.getDpdkSourcePort(), interfaceDef.getInterfaceMode());
                     dpdkInterfaceMapping.put(nic.getMac(), to);
+                    logger.debug("Configured DPDK interface for VM {}", vm.getName());
                 }
             }
 
@@ -122,6 +124,7 @@ public Answer execute(final PrepareForMigrationCommand command, final LibvirtCom
                 return new PrepareForMigrationAnswer(command, "failed to connect physical disks to host");
             }
 
+            logger.info("Successfully prepared destination host for migration of VM {}", vm.getName());
             return createPrepareForMigrationAnswer(command, dpdkInterfaceMapping, libvirtComputingResource, vm);
         } catch (final LibvirtException | CloudRuntimeException | InternalErrorException | URISyntaxException e) {
             if (MapUtils.isNotEmpty(dpdkInterfaceMapping)) {
@@ -157,6 +160,7 @@ private Answer handleRollback(PrepareForMigrationCommand command, LibvirtComputi
         KVMStoragePoolManager storagePoolMgr = libvirtComputingResource.getStoragePoolMgr();
         VirtualMachineTO vmTO = command.getVirtualMachine();
 
+        logger.info("Rolling back PrepareForMigration for VM {}: disconnecting physical disks", vmTO.getName());
         if (!storagePoolMgr.disconnectPhysicalDisksViaVmSpec(vmTO)) {
             return new PrepareForMigrationAnswer(command, "failed to disconnect physical disks from host");
         }
diff --git a/server/src/main/java/com/cloud/vm/UserVmManagerImpl.java b/server/src/main/java/com/cloud/vm/UserVmManagerImpl.java
@@ -7189,6 +7189,7 @@ public VirtualMachine migrateVirtualMachine(Long vmId, Host destinationHost) thr
             throw new CloudRuntimeException("Unable to find suitable destination to migrate VM " + vm.getInstanceName());
         }
 
+        logger.info("Starting migration of VM {} from host {} to host {} ", vm.getInstanceName(), srcHostId, dest.getHost().getId());
         collectVmDiskAndNetworkStatistics(vmId, State.Running);
         _itMgr.migrate(vm.getUuid(), srcHostId, dest);
         return findMigratedVm(vm.getId(), vm.getType());
@@ -7260,6 +7261,7 @@ protected void validateStrictHostTagCheck(VMInstanceVO vm, HostVO host) {
 
     private DeployDestination checkVmMigrationDestination(VMInstanceVO vm, Host srcHost, Host destinationHost) throws VirtualMachineMigrationException {
         if (destinationHost == null) {
+            logger.error("Destination host is null for migration of VM: {}", vm.getInstanceName());
             return null;
         }
         if (destinationHost.getId() == srcHost.getId()) {

Original file line number	Diff line number	Diff line change
`@@ -56,6 +56,7 @@ public Answer execute(final PrepareForMigrationCommand command, final LibvirtCom`
`56`	`56`	`final VirtualMachineTO vm = command.getVirtualMachine();`
`57`	`57`
`58`	`58`	`if (command.isRollback()) {`
	`59`	`+ logger.info("Handling rollback for PrepareForMigration of VM {}", vm.getName());`
`59`	`60`	`return handleRollback(command, libvirtComputingResource);`
`60`	`61`	`}`
`61`	`62`
`@@ -83,6 +84,7 @@ public Answer execute(final PrepareForMigrationCommand command, final LibvirtCom`
`83`	`84`	`if (interfaceDef != null && interfaceDef.getNetType() == GuestNetType.VHOSTUSER) {`
`84`	`85`	`DpdkTO to = new DpdkTO(interfaceDef.getDpdkOvsPath(), interfaceDef.getDpdkSourcePort(), interfaceDef.getInterfaceMode());`
`85`	`86`	`dpdkInterfaceMapping.put(nic.getMac(), to);`
	`87`	`+ logger.debug("Configured DPDK interface for VM {}", vm.getName());`
`86`	`88`	`}`
`87`	`89`	`}`
`88`	`90`
`@@ -122,6 +124,7 @@ public Answer execute(final PrepareForMigrationCommand command, final LibvirtCom`
`122`	`124`	`return new PrepareForMigrationAnswer(command, "failed to connect physical disks to host");`
`123`	`125`	`}`
`124`	`126`
	`127`	`+ logger.info("Successfully prepared destination host for migration of VM {}", vm.getName());`
`125`	`128`	`return createPrepareForMigrationAnswer(command, dpdkInterfaceMapping, libvirtComputingResource, vm);`
`126`	`129`	`} catch (final LibvirtException \| CloudRuntimeException \| InternalErrorException \| URISyntaxException e) {`
`127`	`130`	`if (MapUtils.isNotEmpty(dpdkInterfaceMapping)) {`
`@@ -157,6 +160,7 @@ private Answer handleRollback(PrepareForMigrationCommand command, LibvirtComputi`
`157`	`160`	`KVMStoragePoolManager storagePoolMgr = libvirtComputingResource.getStoragePoolMgr();`
`158`	`161`	`VirtualMachineTO vmTO = command.getVirtualMachine();`
`159`	`162`
	`163`	`+ logger.info("Rolling back PrepareForMigration for VM {}: disconnecting physical disks", vmTO.getName());`
`160`	`164`	`if (!storagePoolMgr.disconnectPhysicalDisksViaVmSpec(vmTO)) {`
`161`	`165`	`return new PrepareForMigrationAnswer(command, "failed to disconnect physical disks from host");`
`162`	`166`	`}`
Original file line number	Diff line number	Diff line change
`@@ -7189,6 +7189,7 @@ public VirtualMachine migrateVirtualMachine(Long vmId, Host destinationHost) thr`
`7189`	`7189`	`throw new CloudRuntimeException("Unable to find suitable destination to migrate VM " + vm.getInstanceName());`
`7190`	`7190`	`}`
`7191`	`7191`
	`7192`	`+ logger.info("Starting migration of VM {} from host {} to host {} ", vm.getInstanceName(), srcHostId, dest.getHost().getId());`
`7192`	`7193`	`collectVmDiskAndNetworkStatistics(vmId, State.Running);`
`7193`	`7194`	`_itMgr.migrate(vm.getUuid(), srcHostId, dest);`
`7194`	`7195`	`return findMigratedVm(vm.getId(), vm.getType());`
`@@ -7260,6 +7261,7 @@ protected void validateStrictHostTagCheck(VMInstanceVO vm, HostVO host) {`
`7260`	`7261`
`7261`	`7262`	`private DeployDestination checkVmMigrationDestination(VMInstanceVO vm, Host srcHost, Host destinationHost) throws VirtualMachineMigrationException {`
`7262`	`7263`	`if (destinationHost == null) {`
	`7264`	`+ logger.error("Destination host is null for migration of VM: {}", vm.getInstanceName());`
`7263`	`7265`	`return null;`
`7264`	`7266`	`}`
`7265`	`7267`	`if (destinationHost.getId() == srcHost.getId()) {`