Improve logs when adding components to avoid set (#7214)

Co-authored-by: SadiJr <sadi@scclouds.com.br>
Co-authored-by: GaOrtiga <49285692+GaOrtiga@users.noreply.github.com>
Co-authored-by: João Jandre <48719461+JoaoJandre@users.noreply.github.com>

api/src/main/java/com/cloud/deploy/DeploymentPlanner.java

@@ -21,8 +21,12 @@ import java.util.Collection;
 import java.util.HashSet;
 import java.util.Set;
 
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.LogManager;
+
 import com.cloud.dc.DataCenter;
 import com.cloud.dc.Pod;
+import com.cloud.exception.CloudException;
 import com.cloud.exception.InsufficientCapacityException;
 import com.cloud.exception.InsufficientServerCapacityException;
 import com.cloud.exception.ResourceUnavailableException;
@@ -75,7 +79,7 @@ public interface DeploymentPlanner extends Adapter {
 
     public static class ExcludeList implements Serializable {
         private static final long serialVersionUID = -482175549460148301L;
-
+        protected static Logger LOGGER = LogManager.getLogger(ExcludeList.class);
         private Set<Long> _dcIds;
         private Set<Long> _podIds;
         private Set<Long> _clusterIds;
@@ -104,13 +108,26 @@ public interface DeploymentPlanner extends Adapter {
             }
         }
 
+        private void logAvoid(Class<?> scope, CloudException e) {
+            Long id = null;
+            if (e instanceof InsufficientCapacityException) {
+                id = ((InsufficientCapacityException) e).getId();
+            } else if (e instanceof ResourceUnavailableException) {
+                id = ((ResourceUnavailableException) e).getResourceId();
+            } else {
+                LOGGER.debug("Failed to log avoided component due to unexpected exception type [{}].", e.getMessage());
+                return;
+            }
+            LOGGER.debug("Adding {} [{}] to the avoid set due to [{}].", scope.getSimpleName(), id, e.getMessage());
+        }
+
         public boolean add(InsufficientCapacityException e) {
             Class<?> scope = e.getScope();
 
             if (scope == null) {
                 return false;
             }
-
+            logAvoid(scope, e);
             if (Host.class.isAssignableFrom(scope)) {
                 addHost(e.getId());
             } else if (Pod.class.isAssignableFrom(scope)) {
@@ -128,13 +145,14 @@ public interface DeploymentPlanner extends Adapter {
             return true;
         }
 
+
         public boolean add(ResourceUnavailableException e) {
             Class<?> scope = e.getScope();
 
             if (scope == null) {
                 return false;
             }
-
+            logAvoid(scope, e);
             if (Host.class.isAssignableFrom(scope)) {
                 addHost(e.getResourceId());
             } else if (Pod.class.isAssignableFrom(scope)) {

engine/orchestration/src/main/java/com/cloud/vm/VirtualMachineManagerImpl.java

@@ -165,6 +165,7 @@ import com.cloud.deploy.DeploymentPlan;
 import com.cloud.deploy.DeploymentPlanner;
 import com.cloud.deploy.DeploymentPlanner.ExcludeList;
 import com.cloud.deploy.DeploymentPlanningManager;
+import com.cloud.deploy.DeploymentPlanningManagerImpl;
 import com.cloud.deployasis.dao.UserVmDeployAsIsDetailsDao;
 import com.cloud.event.EventTypes;
 import com.cloud.event.UsageEventUtils;
@@ -237,6 +238,7 @@ import com.cloud.user.User;
 import com.cloud.uservm.UserVm;
 import com.cloud.utils.DateUtil;
 import com.cloud.utils.Journal;
+import com.cloud.utils.LogUtils;
 import com.cloud.utils.Pair;
 import com.cloud.utils.Predicate;
 import com.cloud.utils.ReflectionUse;
@@ -1093,6 +1095,7 @@ public class VirtualMachineManagerImpl extends ManagerBase implements VirtualMac
     public void orchestrateStart(final String vmUuid, final Map<VirtualMachineProfile.Param, Object> params, final DeploymentPlan planToDeploy, final DeploymentPlanner planner)
             throws InsufficientCapacityException, ConcurrentOperationException, ResourceUnavailableException {
 
+        logger.debug(() -> LogUtils.logGsonWithoutException("Trying to start VM [%s] using plan [%s] and planner [%s].", vmUuid, planToDeploy, planner));
         final CallContext cctxt = CallContext.current();
         final Account account = cctxt.getCallingAccount();
         final User caller = cctxt.getCallingUser();
@@ -1116,10 +1119,8 @@ public class VirtualMachineManagerImpl extends ManagerBase implements VirtualMac
 
         DataCenterDeployment plan = new DataCenterDeployment(vm.getDataCenterId(), vm.getPodIdToDeployIn(), null, null, null, null, ctx);
         if (planToDeploy != null && planToDeploy.getDataCenterId() != 0) {
-            if (logger.isDebugEnabled()) {
+            VMInstanceVO finalVm = vm;
-                logger.debug("advanceStart: DeploymentPlan is provided, using dcId:" + planToDeploy.getDataCenterId() + ", podId: " + planToDeploy.getPodId() +
+            logger.debug(() -> DeploymentPlanningManagerImpl.logDeploymentWithoutException(finalVm, planToDeploy, planToDeploy.getAvoids(), planner));
-                        ", clusterId: " + planToDeploy.getClusterId() + ", hostId: " + planToDeploy.getHostId() + ", poolId: " + planToDeploy.getPoolId());
-            }
             plan =
                     new DataCenterDeployment(planToDeploy.getDataCenterId(), planToDeploy.getPodId(), planToDeploy.getClusterId(), planToDeploy.getHostId(),
                             planToDeploy.getPoolId(), planToDeploy.getPhysicalNetworkId(), ctx);
@@ -1140,13 +1141,12 @@ public class VirtualMachineManagerImpl extends ManagerBase implements VirtualMac
 
             if (planToDeploy != null) {
                 avoids = planToDeploy.getAvoids();
+                ExcludeList finalAvoids = avoids;
+                logger.debug(() -> LogUtils.logGsonWithoutException("Avoiding components [%s] in deployment of VM [%s].", finalAvoids, vmUuid));
             }
             if (avoids == null) {
                 avoids = new ExcludeList();
             }
-            if (logger.isDebugEnabled()) {
-                logger.debug("Deploy avoids pods: " + avoids.getPodsToAvoid() + ", clusters: " + avoids.getClustersToAvoid() + ", hosts: " + avoids.getHostsToAvoid());
-            }
 
             boolean planChangedByVolume = false;
             boolean reuseVolume = true;

server/src/main/java/com/cloud/agent/manager/allocator/impl/FirstFitAllocator.java

@@ -27,6 +27,7 @@ import javax.naming.ConfigurationException;
 
 import com.cloud.utils.exception.CloudRuntimeException;
 import org.apache.cloudstack.framework.config.dao.ConfigurationDao;
+import org.apache.cloudstack.utils.reflectiontostringbuilderutils.ReflectionToStringBuilderUtils;
 import org.springframework.stereotype.Component;
 
 import com.cloud.agent.manager.allocator.HostAllocator;
@@ -210,6 +211,10 @@ public class FirstFitAllocator extends AdapterBase implements HostAllocator {
         // add all hosts that we are not considering to the avoid list
         List<HostVO> allhostsInCluster = _hostDao.listAllUpAndEnabledNonHAHosts(type, clusterId, podId, dcId, null);
         allhostsInCluster.removeAll(clusterHosts);
+
+        logger.debug(() -> String.format("Adding hosts [%s] to the avoid set because these hosts do not support HA.",
+                ReflectionToStringBuilderUtils.reflectOnlySelectedFields(allhostsInCluster, "uuid", "name")));
+
         for (HostVO host : allhostsInCluster) {
             avoid.addHost(host.getId());
         }
@@ -325,10 +330,8 @@ public class FirstFitAllocator extends AdapterBase implements HostAllocator {
 
             //find number of guest VMs occupying capacity on this host.
             if (_capacityMgr.checkIfHostReachMaxGuestLimit(host)) {
-                if (logger.isDebugEnabled()) {
+                logger.debug(() -> String.format("Adding host [%s] to the avoid set because this host already has the max number of running (user and/or system) VMs.",
-                    logger.debug("Host name: " + host.getName() + ", hostId: " + host.getId() +
+                        ReflectionToStringBuilderUtils.reflectOnlySelectedFields(host, "uuid", "name")));
-                        " already has max Running VMs(count includes system VMs), skipping this and trying other available hosts");
-                }
                 avoid.addHost(host.getId());
                 continue;
             }
@@ -337,7 +340,8 @@ public class FirstFitAllocator extends AdapterBase implements HostAllocator {
             if ((offeringDetails   = _serviceOfferingDetailsDao.findDetail(serviceOfferingId, GPU.Keys.vgpuType.toString())) != null) {
                 ServiceOfferingDetailsVO groupName = _serviceOfferingDetailsDao.findDetail(serviceOfferingId, GPU.Keys.pciDevice.toString());
                 if(!_resourceMgr.isGPUDeviceAvailable(host.getId(), groupName.getValue(), offeringDetails.getValue())){
-                    logger.info("Host name: " + host.getName() + ", hostId: "+ host.getId() +" does not have required GPU devices available");
+                    logger.debug(String.format("Adding host [%s] to avoid set, because this host does not have required GPU devices available.",
+                            ReflectionToStringBuilderUtils.reflectOnlySelectedFields(host, "uuid", "name")));
                     avoid.addHost(host.getId());
                     continue;
                 }

server/src/test/java/com/cloud/deploy/DeploymentPlanningManagerImplTest.java

@@ -252,7 +252,9 @@ public class DeploymentPlanningManagerImplTest {
         Mockito.when(template.isDeployAsIs()).thenReturn(false);
         Mockito.when(templateDao.findById(Mockito.anyLong())).thenReturn(template);
 
-        VMInstanceVO vm = new VMInstanceVO();
+        VMInstanceVO vm = Mockito.mock(VMInstanceVO.class);
+        Mockito.when(vm.getType()).thenReturn(Type.Instance);
+        Mockito.when(vm.getLastHostId()).thenReturn(null);
         Mockito.when(vmProfile.getVirtualMachine()).thenReturn(vm);
         Mockito.when(vmProfile.getId()).thenReturn(instanceId);