engine: do not orphan an instance on a forced power report during start

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

@@ -695,6 +695,7 @@ protected void advanceExpunge(VMInstanceVO vm) throws ResourceUnavailableExcepti
 
         advanceStop(vm.getUuid(), VmDestroyForcestop.value());
         vm = _vmDao.findByUuid(vm.getUuid());
+        ensureInstanceIsStoppedOnLastKnownHost(vm);
 
         try {
             if (!stateTransitTo(vm, VirtualMachine.Event.ExpungeOperation, vm.getHostId())) {
@@ -2209,8 +2210,13 @@ private List<Map<String, String>> getVolumesToDisconnect(VirtualMachine vm) {
         return volumesToDisconnect;
     }
 
-    protected Pair<Boolean, String> sendStop(final VirtualMachineGuru guru, final VirtualMachineProfile profile, final boolean force, final boolean checkBeforeCleanup) {
-        final VirtualMachine vm = profile.getVirtualMachine();
+    /**
+     * Build a StopCommand carrying everything the host needs to tear an instance down: the external hypervisor
+     * details, the VLAN persistence map that decides whether a bridge may be deleted, the control NIC address used
+     * for system VMs, and the volumes to disconnect. Callers that build a StopCommand without these will make the
+     * host delete bridges belonging to persistent networks and leave volumes connected.
+     */
+    protected StopCommand buildStopCommand(final VirtualMachine vm, final VirtualMachineProfile profile, final boolean checkBeforeCleanup) {
         Map<String, Boolean> vlanToPersistenceMap = getVlanToPersistenceMapForVM(vm.getId());
         StopCommand stpCmd = new StopCommand(vm, getExecuteInSequence(vm.getHypervisorType()), checkBeforeCleanup);
         updateStopCommandForExternalHypervisorType(vm.getHypervisorType(), profile, stpCmd);
@@ -2219,7 +2225,21 @@ protected Pair<Boolean, String> sendStop(final VirtualMachineGuru guru, final Vi
         }
         stpCmd.setControlIp(getControlNicIpForVM(vm));
         stpCmd.setVolumesToDisconnect(getVolumesToDisconnect(vm));
-        final StopCommand stop = stpCmd;
+        return stpCmd;
+    }
+
+    /**
+     * Build a StopCommand that the host carries out even when the instance is running. With checkBeforeCleanup set,
+     * the host refuses a running instance with "vm is still running on host", and a running instance is exactly what
+     * the callers of this need stopped.
+     */
+    protected StopCommand buildUnconditionalStopCommand(final VirtualMachine vm) {
+        return buildStopCommand(vm, new VirtualMachineProfileImpl(vm), false);
+    }
+
+    protected Pair<Boolean, String> sendStop(final VirtualMachineGuru guru, final VirtualMachineProfile profile, final boolean force, final boolean checkBeforeCleanup) {
+        final VirtualMachine vm = profile.getVirtualMachine();
+        final StopCommand stop = buildStopCommand(vm, profile, checkBeforeCleanup);
         try {
             Answer answer = null;
             if(vm.getHostId() != null) {
@@ -5437,6 +5457,7 @@ private void handlePowerOnReportWithNoPendingJobsOnVM(final VMInstanceVO vm) {
         case Destroyed:
         case Expunging:
             logger.info("Receive power on report when Instance is in destroyed or expunging state. Instance: {}, state: {}.", vm, vm.getState());
+            stopUnmanagedInstanceOnReportingHost(vm);
             break;
 
         case Migrating:
@@ -5452,11 +5473,78 @@ private void handlePowerOnReportWithNoPendingJobsOnVM(final VMInstanceVO vm) {
         case Error:
         default:
             logger.info("Receive power on report when Instance is in error or unexpected state. Instance: {}, state: {}.", vm, vm.getState());
+            _alertMgr.sendAlert(AlertManager.AlertType.ALERT_TYPE_SYNC, vm.getDataCenterId(), vm.getPodIdToDeployIn(),
+                    VM_SYNC_ALERT_SUBJECT, String.format("Instance %s is reported running by host %s but is in %s state. "
+                            + "It is not managed by CloudStack and may need to be stopped on the host.",
+                            vm.getInstanceName(), vm.getPowerHostId(), vm.getState()));
             break;
         }
     }
 
-    private void handlePowerOffReportWithNoPendingJobsOnVM(final VMInstanceVO vm) {
+    /**
+     * Send a StopCommand for an instance to the last host it is known to have run on, whatever the database state
+     * says. Used before expunging, where the instance's addresses and volumes are about to be released and a domain
+     * left running on the host would keep using them.
+     *
+     * External instances are skipped: their teardown is done by their extension in finalizeExpunge, and a
+     * StopCommand issued from here would not carry the details that path needs.
+     */
+    protected void ensureInstanceIsStoppedOnLastKnownHost(final VMInstanceVO vm) {
+        if (vm == null || HypervisorType.External.equals(vm.getHypervisorType())) {
+            return;
+        }
+        final Long hostId = vm.getHostId() != null ? vm.getHostId() : vm.getLastHostId();
+        if (hostId == null) {
+            return;
+        }
+        try {
+            final StopCommand stop = buildUnconditionalStopCommand(vm);
+            final Answer answer = _agentMgr.send(hostId, stop);
+            if (answer != null && answer.getResult()) {
+                return;
+            }
+            logger.warn("Unable to confirm instance {} is stopped on host {} before expunging: {}", vm, hostId,
+                    answer == null ? "no answer from host" : answer.getDetails());
+        } catch (final AgentUnavailableException | OperationTimedoutException e) {
+            logger.warn("Unable to confirm instance {} is stopped on host {} before expunging.", vm, hostId, e);
+        }
+    }
+
+    /**
+     * The host reports an instance as powered on that the database considers destroyed or expunged. It will never be
+     * managed again, and its addresses and storage have already been handed back, so stop it on the host that
+     * reported it instead of leaving it running unmanaged.
+     *
+     * External instances are skipped, as in ensureInstanceIsStoppedOnLastKnownHost().
+     */
+    protected void stopUnmanagedInstanceOnReportingHost(final VMInstanceVO vm) {
+        if (HypervisorType.External.equals(vm.getHypervisorType())) {
+            return;
+        }
+        final Long powerHostId = vm.getPowerHostId();
+        if (powerHostId == null) {
+            logger.warn("Instance {} is reported powered on but no reporting host is recorded, cannot stop it.", vm);
+            return;
+        }
+        try {
+            final StopCommand stop = buildUnconditionalStopCommand(vm);
+            final Answer answer = _agentMgr.send(powerHostId, stop);
+            if (answer != null && answer.getResult()) {
+                logger.info("Stopped unmanaged instance {} on host {}.", vm, powerHostId);
+                return;
+            }
+            logger.warn("Unable to stop unmanaged instance {} on host {}: {}", vm, powerHostId,
+                    answer == null ? "no answer from host" : answer.getDetails());
+        } catch (final AgentUnavailableException | OperationTimedoutException e) {
+            logger.warn("Unable to stop unmanaged instance {} on host {}.", vm, powerHostId, e);
+        }
+        _alertMgr.sendAlert(AlertManager.AlertType.ALERT_TYPE_SYNC, vm.getDataCenterId(), vm.getPodIdToDeployIn(),
+                VM_SYNC_ALERT_SUBJECT, String.format("Instance %s is reported running by host %s but is in %s state, "
+                        + "and could not be stopped. It may need to be stopped on the host.",
+                        vm.getInstanceName(), powerHostId, vm.getState()));
+    }
+
+    protected void handlePowerOffReportWithNoPendingJobsOnVM(final VMInstanceVO vm) {
         switch (vm.getState()) {
         case Starting:
         case Stopping:
@@ -5480,20 +5568,19 @@ private void handlePowerOffReportWithNoPendingJobsOnVM(final VMInstanceVO vm) {
                 return;
             }
 
-            if (PowerState.PowerOff.equals(vm.getPowerState())) {
+            if (PowerState.PowerOff.equals(vm.getPowerState()) || PowerState.PowerReportMissing.equals(vm.getPowerState())) {
+                // forceStop only if the host reported the instance as powered off, not for a missing report.
+                final boolean forceStop = PowerState.PowerOff.equals(vm.getPowerState());
                 final VirtualMachineGuru vmGuru = getVmGuru(vm);
                 final VirtualMachineProfile profile = new VirtualMachineProfileImpl(vm);
-                Pair<Boolean, String> result = sendStop(vmGuru, profile, true, true);
+                Pair<Boolean, String> result = sendStop(vmGuru, profile, forceStop, true);
                 if (!result.first()) {
+                    logger.warn("Unable to stop VM {} on its host, not releasing its resources: {}", vm, result.second());
                     return;
                 } else {
                     // Release resources on StopCommand success
                     releaseVmResources(profile, true);
                 }
-            } else if (PowerState.PowerReportMissing.equals(vm.getPowerState())) {
-                final VirtualMachineProfile profile = new VirtualMachineProfileImpl(vm);
-                // VM will be sync-ed to Stopped state, release the resources
-                releaseVmResources(profile, true);
             }
 
             try {

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

@@ -18,9 +18,12 @@
 
 import java.util.Date;
 import java.util.HashMap;
+import java.util.HashSet;
 import java.util.List;
 import java.util.Map;
 import java.util.Set;
+import java.util.concurrent.ConcurrentHashMap;
+import java.util.regex.Pattern;
 import java.util.stream.Collectors;
 
 import javax.inject.Inject;
@@ -34,6 +37,7 @@
 import org.apache.logging.log4j.Logger;
 
 import com.cloud.agent.api.HostVmStateReportEntry;
+import com.cloud.alert.AlertManager;
 import com.cloud.configuration.ManagementServiceConfiguration;
 import com.cloud.host.Host;
 import com.cloud.host.HostVO;
@@ -48,6 +52,18 @@ public class VirtualMachinePowerStateSyncImpl implements VirtualMachinePowerStat
     @Inject VMInstanceDao _instanceDao;
     @Inject HostDao hostDao;
     @Inject ManagementServiceConfiguration mgmtServiceConf;
+    @Inject AlertManager _alertMgr;
+
+    protected static final String UNKNOWN_INSTANCES_ALERT_SUBJECT = "Instances running on a host that CloudStack has no record of";
+
+    /**
+     * The names CloudStack gives the instances it creates: i-[account]-[id]-[suffix] for user instances and
+     * [prefix]-[id]-[suffix] for system VMs (r router, s secondary storage, v console proxy, b internal LB,
+     * l elastic LB, NS NetScaler VPX). See VirtualMachineName.
+     */
+    private static final Pattern CLOUDSTACK_INSTANCE_NAME = Pattern.compile("^(i-\\d+-\\d+|(r|s|v|b|l|NS)-\\d+)-.+$");
+
+    private final Map<Long, Set<String>> unknownInstancesByHost = new ConcurrentHashMap<>();
 
     private LazyCache<Long, VMInstanceVO> vmCache;
     private LazyCache<Long, HostVO> hostCache;
@@ -66,14 +82,14 @@ public void resetHostSyncState(Host host) {
     @Override
     public void processHostVmStateReport(long hostId, Map<String, HostVmStateReportEntry> report) {
         logger.debug("Process host VM state report. host: {}", hostCache.get(hostId));
-        Map<Long, VirtualMachine.PowerState> translatedInfo = convertVmStateReport(report);
+        Map<Long, VirtualMachine.PowerState> translatedInfo = convertVmStateReport(hostId, report);
         processReport(hostId, translatedInfo, false);
     }
 
     @Override
     public void processHostVmStatePingReport(long hostId, Map<String, HostVmStateReportEntry> report, boolean force) {
         logger.debug("Process host VM state report from ping process. host: {}", hostCache.get(hostId));
-        Map<Long, VirtualMachine.PowerState> translatedInfo = convertVmStateReport(report);
+        Map<Long, VirtualMachine.PowerState> translatedInfo = convertVmStateReport(hostId, report);
         processReport(hostId, translatedInfo, force);
     }
 
@@ -114,6 +130,21 @@ private List<VMInstanceVO> filterOutdatedFromMissingVmReport(List<VMInstanceVO>
                 .collect(Collectors.toList());
     }
 
+    /**
+     * A host report only lists the instances that were running on the host when the report was collected. When the
+     * management server changes an instance's state around that moment, an in-flight report may have been collected
+     * before the change and therefore says nothing about it. Treating such an instance as missing would undo the
+     * change that just happened, so instances whose state changed within the graceful period are left alone and
+     * judged by a later report instead.
+     */
+    protected boolean hasRecentStateChange(VMInstanceVO instance, Date currentTime, long milliSecondsGracefulPeriod) {
+        Date lastStateChange = instance.getUpdateTime();
+        if (lastStateChange == null) {
+            return false;
+        }
+        return currentTime.getTime() - lastStateChange.getTime() < milliSecondsGracefulPeriod;
+    }
+
     private void processMissingVmReport(long hostId, Set<Long> vmIds, boolean force) {
         // any state outdates should be checked against the time before this list was retrieved
         Date startTime = DateUtil.currentGMTTime();
@@ -143,6 +174,12 @@ private void processMissingVmReport(long hostId, Set<Long> vmIds, boolean force)
                     vmStateUpdateTime = instance.getCreated();
                 }
             }
+            if (hasRecentStateChange(instance, currentTime, milliSecondsGracefulPeriod)) {
+                logger.debug("vm id: {} - state changed at {}, which is within the graceful period ({} ms); " +
+                                "the report may have been collected before that change, skipping missing report",
+                        instance.getId(), DateUtil.getOutputString(instance.getUpdateTime()), milliSecondsGracefulPeriod);
+                continue;
+            }
             logger.debug("Detected missing VM. host: {}, vm id: {}({}), power state: {}, last state update: {}",
                     hostId,
                     instance.getId(),
@@ -151,8 +188,8 @@ private void processMissingVmReport(long hostId, Set<Long> vmIds, boolean force)
                     DateUtil.getOutputString(vmStateUpdateTime));
             long milliSecondsSinceLastStateUpdate = currentTime.getTime() - vmStateUpdateTime.getTime();
             if (force || (milliSecondsSinceLastStateUpdate > milliSecondsGracefulPeriod)) {
-                logger.debug("vm id: {} - time since last state update({} ms) has passed graceful period",
-                        instance.getId(), milliSecondsSinceLastStateUpdate);
+                logger.debug("vm id: {} - reporting missing (time since last state update: {} ms, graceful period: {} ms, forced: {})",
+                        instance.getId(), milliSecondsSinceLastStateUpdate, milliSecondsGracefulPeriod, force);
                 // this is where a race condition might have happened if we don't re-fetch the instance;
                 // between the startime of this job and the currentTime of this missing-branch
                 // an update might have occurred that we should not override in case of out of band migration
@@ -178,23 +215,77 @@ private void processReport(long hostId, Map<Long, VirtualMachine.PowerState> tra
         logger.debug("Done with process of VM state report. host: {}", () -> hostCache.get(hostId));
     }
 
-    public Map<Long, VirtualMachine.PowerState> convertVmStateReport(Map<String, HostVmStateReportEntry> states) {
+    public Map<Long, VirtualMachine.PowerState> convertVmStateReport(long hostId, Map<String, HostVmStateReportEntry> states) {
         final HashMap<Long, VirtualMachine.PowerState> map = new HashMap<>();
         if (MapUtils.isEmpty(states)) {
+            reportUnknownInstances(hostId, new HashSet<>());
             return map;
         }
+        Set<String> unknownInstanceNames = new HashSet<>();
         Map<String, Long> nameIdMap = _instanceDao.getNameIdMapForVmInstanceNames(states.keySet());
         for (Map.Entry<String, HostVmStateReportEntry> entry : states.entrySet()) {
             Long id = nameIdMap.get(entry.getKey());
             if (id != null) {
                 map.put(id, entry.getValue().getState());
             } else {
                 logger.debug("Unable to find matched VM in CloudStack DB. name: {} powerstate: {}", entry.getKey(), entry.getValue());
+                if (isRunningCloudStackInstance(entry.getKey(), entry.getValue())) {
+                    unknownInstanceNames.add(entry.getKey());
+                }
             }
         }
+        reportUnknownInstances(hostId, unknownInstanceNames);
         return map;
     }
 
+    /**
+     * Whether an entry the database has no record of is worth raising. A host report is not limited to CloudStack's
+     * own instances: VMware lists every VM on the host in any power state, including the worker VMs CloudStack creates
+     * and destroys for volume operations (named by a bare UUID) and anything else the vCenter places there, and a KVM
+     * host may run domains of its own. Only a powered-on instance carrying a CloudStack instance name can be one that
+     * CloudStack left running, everything else stays at debug level as before.
+     */
+    protected static boolean isRunningCloudStackInstance(String name, HostVmStateReportEntry entry) {
+        return name != null && entry != null && VirtualMachine.PowerState.PowerOn.equals(entry.getState())
+                && CLOUDSTACK_INSTANCE_NAME.matcher(name).matches();
+    }
+
+    /**
+     * A host reporting an instance that CloudStack has no record of means something is running there unmanaged,
+     * usually left behind by a deploy or an expunge that did not reach the host. Previously this produced one debug
+     * line per instance per report and nothing else, so it could go unnoticed indefinitely.
+     *
+     * Logged at warn level, and only when the set of unknown instances on a host changes, so a standing condition
+     * does not repeat on every report.
+     *
+     * @return true when the set changed and was reported, false when there was nothing new to say.
+     */
+    protected boolean reportUnknownInstances(long hostId, Set<String> unknownInstanceNames) {
+        Set<String> previous = unknownInstancesByHost.get(hostId);
+        if (unknownInstanceNames.equals(previous) || (CollectionUtils.isEmpty(unknownInstanceNames) && previous == null)) {
+            return false;
+        }
+        if (unknownInstanceNames.isEmpty()) {
+            unknownInstancesByHost.remove(hostId);
+            logger.info("No unknown instances are reported anymore. host: {}", () -> hostCache.get(hostId));
+            return true;
+        }
+        unknownInstancesByHost.put(hostId, unknownInstanceNames);
+        HostVO host = hostCache.get(hostId);
+        String names = String.join(", ", unknownInstanceNames);
+        logger.warn("Host reports {} instance(s) that do not exist in CloudStack DB, they are running unmanaged. " +
+                        "host: {}, instances: [{}]",
+                unknownInstanceNames.size(), host, names);
+        if (host != null) {
+            _alertMgr.sendAlert(AlertManager.AlertType.ALERT_TYPE_SYNC, host.getDataCenterId(), host.getPodId(),
+                    UNKNOWN_INSTANCES_ALERT_SUBJECT,
+                    String.format("Host %s reports %d instance(s) that do not exist in CloudStack: %s. They are "
+                                    + "running unmanaged and may still be holding addresses and storage.",
+                            host.getName(), unknownInstanceNames.size(), names));
+        }
+        return true;
+    }
+
     protected VMInstanceVO getVmFromId(long vmId) {
         return _instanceDao.findById(vmId);
     }