Improve logs when adding components to avoid set

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

@@ -21,8 +21,11 @@
 import java.util.HashSet;
 import java.util.Set;
 
+import org.apache.log4j.Logger;
+
 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 +78,7 @@ public enum PlannerResourceUsage {
 
     public static class ExcludeList implements Serializable {
         private static final long serialVersionUID = -482175549460148301L;
-
+        private static final Logger LOGGER = Logger.getLogger(ExcludeList.class);
         private Set<Long> _dcIds;
         private Set<Long> _podIds;
         private Set<Long> _clusterIds;
@@ -104,13 +107,26 @@ public ExcludeList(Set<Long> dcIds, Set<Long> podIds, Set<Long> clusterIds, Set<
             }
         }
 
+        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(String.format("Failed to log avoided component due to unexpected exception type [%s].", e.getMessage()));
+                return;
+            }
+            LOGGER.debug(String.format("Adding %s [%s] to the avoid set due to [%s].", 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 +144,14 @@ public boolean add(InsufficientCapacityException e) {
             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

@@ -166,6 +166,7 @@
 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;
@@ -238,6 +239,7 @@
 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;
@@ -1095,6 +1097,7 @@ protected void checkAndAttemptMigrateVmAcrossCluster(final VMInstanceVO vm, fina
     public void orchestrateStart(final String vmUuid, final Map<VirtualMachineProfile.Param, Object> params, final DeploymentPlan planToDeploy, final DeploymentPlanner planner)
             throws InsufficientCapacityException, ConcurrentOperationException, ResourceUnavailableException {
 
+        s_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();
@@ -1118,10 +1121,7 @@ public void orchestrateStart(final String vmUuid, final Map<VirtualMachineProfil
 
         DataCenterDeployment plan = new DataCenterDeployment(vm.getDataCenterId(), vm.getPodIdToDeployIn(), null, null, null, null, ctx);
         if (planToDeploy != null && planToDeploy.getDataCenterId() != 0) {
-            if (s_logger.isDebugEnabled()) {
-                s_logger.debug("advanceStart: DeploymentPlan is provided, using dcId:" + planToDeploy.getDataCenterId() + ", podId: " + planToDeploy.getPodId() +
-                        ", clusterId: " + planToDeploy.getClusterId() + ", hostId: " + planToDeploy.getHostId() + ", poolId: " + planToDeploy.getPoolId());
-            }
+            s_logger.debug(DeploymentPlanningManagerImpl.logDeploymentWithoutException(vm, planToDeploy, planToDeploy.getAvoids(), planner));
             plan =
                     new DataCenterDeployment(planToDeploy.getDataCenterId(), planToDeploy.getPodId(), planToDeploy.getClusterId(), planToDeploy.getHostId(),
                             planToDeploy.getPoolId(), planToDeploy.getPhysicalNetworkId(), ctx);
@@ -1142,13 +1142,11 @@ public void orchestrateStart(final String vmUuid, final Map<VirtualMachineProfil
 
             if (planToDeploy != null) {
                 avoids = planToDeploy.getAvoids();
+                s_logger.debug(LogUtils.logGsonWithoutException("Avoiding components [%s] in deployment of VM [%s].", avoids, vmUuid));
             }
             if (avoids == null) {
                 avoids = new ExcludeList();
             }
-            if (s_logger.isDebugEnabled()) {
-                s_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 com.cloud.utils.exception.CloudRuntimeException;
 import org.apache.cloudstack.framework.config.dao.ConfigurationDao;
+import org.apache.cloudstack.utils.reflectiontostringbuilderutils.ReflectionToStringBuilderUtils;
 import org.apache.log4j.Logger;
 import org.springframework.stereotype.Component;
 
@@ -212,6 +213,8 @@ public List<Host> allocateTo(VirtualMachineProfile vmProfile, DeploymentPlan pla
         // 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);
+        s_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());
         }
@@ -327,10 +330,8 @@ protected List<Host> allocateTo(DeploymentPlan plan, ServiceOffering offering, V
 
             //find number of guest VMs occupying capacity on this host.
             if (_capacityMgr.checkIfHostReachMaxGuestLimit(host)) {
-                if (s_logger.isDebugEnabled()) {
-                    s_logger.debug("Host name: " + host.getName() + ", hostId: " + host.getId() +
-                        " already has max Running VMs(count includes system VMs), skipping this and trying other available hosts");
-                }
+                s_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.",
+                        ReflectionToStringBuilderUtils.reflectOnlySelectedFields(host, "uuid", "name")));
                 avoid.addHost(host.getId());
                 continue;
             }
@@ -339,7 +340,8 @@ protected List<Host> allocateTo(DeploymentPlan plan, ServiceOffering offering, V
             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())){
-                    s_logger.info("Host name: " + host.getName() + ", hostId: "+ host.getId() +" does not have required GPU devices available");
+                    s_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;
                 }