Hi all. My environment: CloudStack 4.3.0 (CentOS6) XenServer 6.2 SP1
1. One host failure. 2. VM is started on another host by CloudStack HA. (VM001,VM002,VM004,VM005) 3. VM003 only startup failure. I want to know the cause of VM003 did not start by CloudStack HA. Resources of the host is enough. I could start VM003 by manual operation after several hours. Although I think the following log is concerned, this means what? 2015-10-11 20:39:45,960 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-a058591d) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 Why ? Best regards. log (excerpt): 2015-10-11 20:28:55,770 DEBUG [c.c.h.HighAvailabilityManagerImpl] (AgentTaskPool-11:ctx-bc69642d) Notifying HA Mgr of to restart vm 451-VM003 2015-10-11 20:28:55,776 INFO [c.c.h.HighAvailabilityManagerImpl] (AgentTaskPool-11:ctx-bc69642d) Schedule vm for HA: VM[User|VM003] 2015-10-11 20:28:55,789 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) HA on VM[User|VM003] 2015-10-11 20:28:55,806 DEBUG [c.c.h.CheckOnAgentInvestigator] (HA-Worker-0:ctx-71125e79 work-139) Unable to reach the agent for VM[User|VM003]: Resource [Host:11] is unreachable: Host 11: Host with specified id is not in the right state: Down 2015-10-11 20:28:55,806 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) SimpleInvestigator found VM[User|VM003]to be alive? null 2015-10-11 20:28:58,135 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) XenServerInvestigator found VM[User|VM003]to be alive? null 2015-10-11 20:28:58,135 DEBUG [c.c.h.UserVmDomRInvestigator] (HA-Worker-0:ctx-71125e79 work-139) testing if VM[User|VM003] is alive 2015-10-11 20:29:10,585 DEBUG [c.c.h.UserVmDomRInvestigator] (HA-Worker-0:ctx-71125e79 work-139) VM[User|VM003] could not be pinged, returning that it is unknown 2015-10-11 20:29:15,040 DEBUG [c.c.h.UserVmDomRInvestigator] (HA-Worker-0:ctx-71125e79 work-139) VM[User|VM003] could not be pinged, returning that it is unknown 2015-10-11 20:29:15,040 DEBUG [c.c.h.UserVmDomRInvestigator] (HA-Worker-0:ctx-71125e79 work-139) Returning null since we're unable to determine state of VM[User|VM003] 2015-10-11 20:29:15,040 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) PingInvestigator found VM[User|VM003]to be alive? null 2015-10-11 20:29:15,040 DEBUG [c.c.h.ManagementIPSystemVMInvestigator] (HA-Worker-0:ctx-71125e79 work-139) Not a System Vm, unable to determine state of VM[User|VM003] returning null 2015-10-11 20:29:15,040 DEBUG [c.c.h.ManagementIPSystemVMInvestigator] (HA-Worker-0:ctx-71125e79 work-139) Testing if VM[User|VM003] is alive 2015-10-11 20:29:15,041 DEBUG [c.c.h.ManagementIPSystemVMInvestigator] (HA-Worker-0:ctx-71125e79 work-139) Unable to find a management nic, cannot ping this system VM, unable to determine state of VM[User|VM003] returning null 2015-10-11 20:29:15,041 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) ManagementIPSysVMInvestigator found VM[User|VM003]to be alive? null 2015-10-11 20:29:15,041 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) KVMInvestigator found VM[User|VM003]to be alive? null 2015-10-11 20:29:15,041 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) HypervInvestigator found VM[User|VM003]to be alive? null 2015-10-11 20:29:15,041 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) VMwareInvestigator found VM[User|VM003]to be alive? null 2015-10-11 20:29:17,190 WARN [c.c.v.VirtualMachineManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) Unable to actually stop VM[User|VM003] but continue with release because it's a force stop 2015-10-11 20:29:17,194 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) VM[User|VM003] is stopped on the host. Proceeding to release resource held. 2015-10-11 20:29:17,205 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) Successfully released network resources for the vm VM[User|VM003] 2015-10-11 20:29:17,205 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) Successfully released storage resources for the vm VM[User|VM003] 2015-10-11 20:29:17,276 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) Successfully transitioned to start state for VM[User|VM003] reservation id = 74b7e3a7-80b4-4153-a6c8-993fd67c23b4 2015-10-11 20:29:17,280 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) Trying to deploy VM, vm has dcId: 1 and podId: 1 2015-10-11 20:29:17,280 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) Deploy avoids pods: null, clusters: null, hosts: null 2015-10-11 20:29:17,290 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 11 new host id: null host id before state transition: null 2015-10-11 20:29:17,299 ERROR [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-0:ctx-71125e79 work-139) Terminating HAWork[139-HA-451-Running-Scheduled] 2015-10-11 20:39:45,960 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-a058591d) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 2015-10-11 20:44:45,961 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-9d3a2c6c) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 2015-10-11 20:49:45,968 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-ec4755fc) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 2015-10-11 20:54:45,960 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-1f2e54b8) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 2015-10-11 20:59:45,962 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-16e34ab2) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 2015-10-11 21:04:45,960 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-fa2aa0b1) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 2015-10-11 21:09:45,960 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-258aa675) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 2015-10-11 21:14:45,962 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-2086ef56) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 2015-10-11 21:19:45,960 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-76e35c5a) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 2015-10-11 21:24:45,961 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-dac946a5) Cannot release reservation, Found VM: VM[User|VM003] Stopped but reserved on host 11 2015-10-11 21:29:45,964 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-6d11e56b) Host has no VMs associated, releasing the planner reservation for host 11 Code: https://github.com/apache/cloudstack/blob/3ded3e90007d08fa98465f2b8c68b7fb075557c0/server/src/com/cloud/deploy/DeploymentPlanningManagerImpl.java#L717 List<VMInstanceVO> vmsByLastHostId = _vmInstanceDao.listByLastHostId(hostId); if (vmsByLastHostId.size() > 0) { // check if any VMs are within skip.counting.hours, if yes // we // cannot release the host for (VMInstanceVO stoppedVM : vmsByLastHostId) { long secondsSinceLastUpdate = (DateUtil.currentGMTTime().getTime() - stoppedVM.getUpdateTime().getTime()) / 1000; if (secondsSinceLastUpdate < _vmCapacityReleaseInterval) { if (s_logger.isDebugEnabled()) { s_logger.debug("Cannot release reservation, Found VM: " + stoppedVM + " Stopped but reserved on host " + hostId); } return false; } } } --------------- Satoru Nakaya (Japan CloudStack User Group)
