How to debug VM deployment issues (capacity issues?) #12192

bradh352 · 2025-12-04T14:38:27Z

bradh352
Dec 4, 2025

My cluster is currently unable to deploy any new VMs due to a capacity planner issue. I can't tell what resource it is thinking it is out of. I can live migrate any vms that are running ok. Infact, I shutdown almost all the VMs running and I still can't start one back up that I shut down.

I'm running 4.22.

I just rebooted each node to slot in new disks, I had to shut down some VMs for this because I didn't have enough RAM to live migrate all. And it was when I tried to restart the VMs that this all started to go sideways. All nodes are online. All hosts show healthy. Not sure where to go from here.

2025-12-04 14:33:19,232 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-2:[ctx-c71520ee, job-21766, ctx-f9cabd87]) (logid:de988890) Trying to deploy VM [error decoding VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Stopped","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}] and details: Plan [{"_dcId":1,"_podId":1,"_clusterId":1,"_poolId":1,"_hostId":1,"_recreateDisks":false,"preferredHostIds":[],"migrationPlan":false,"hostPriorities":{}}]; avoid list [{}] and planner: [null].
2025-12-04 14:33:19,233 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-2:[ctx-c71520ee, job-21766, ctx-f9cabd87]) (logid:de988890) Adding pods [[]], clusters [[]] and hosts [[]] to the avoid list in the deploy process of user VM [error decoding VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Stopped","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}], because this VM is not explicitly dedicated to these components.
2025-12-04 14:33:19,377 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Trying to deploy VM [error decoding VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}] and details: Plan [{"_dcId":1,"_podId":1,"_clusterId":1,"_hostId":1,"_recreateDisks":false,"preferredHostIds":[],"migrationPlan":false,"hostPriorities":{}}]; avoid list [null] and planner: [null].
2025-12-04 14:33:19,378 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Trying to deploy VM [error decoding VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}] and details: Plan [error decoding {"_clusterId":1,"_dcId":1,"_physicalNetworkId":null,"_podId":1,"_poolId":1,"migrationPlan":false}]; avoid list [{}] and planner: [null].
2025-12-04 14:33:19,380 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Adding pods [[]], clusters [[]] and hosts [[]] to the avoid list in the deploy process of user VM [error decoding VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}], because this VM is not explicitly dedicated to these components.
2025-12-04 14:33:19,406 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Trying to deploy VM [error decoding VM instance {"id":661,"instanceName":"r-661-VM","state":"Starting","type":"DomainRouter","uuid":"2af967de-e5a8-4ded-8e42-cc3c9923daac"}] and details: Plan [error decoding {"_clusterId":null,"_dcId":1,"_physicalNetworkId":null,"_podId":1,"_poolId":null,"migrationPlan":false}]; avoid list [{}] and planner: [null].
2025-12-04 14:33:19,410 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Adding pods [[]], clusters [[]] and hosts [[]] to the avoid list in the deploy process of VR VM [error decoding VM instance {"id":661,"instanceName":"r-661-VM","state":"Starting","type":"DomainRouter","uuid":"2af967de-e5a8-4ded-8e42-cc3c9923daac"}], because this VM is not dedicated to this components.
2025-12-04 14:33:19,433 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) VM instance {"id":661,"instanceName":"r-661-VM","state":"Stopped","type":"DomainRouter","uuid":"2af967de-e5a8-4ded-8e42-cc3c9923daac"} state transited from [Starting] to [Stopped] with event [OperationFailed]. VM's original host: null, new host: null, host before state transition: null
2025-12-04 14:33:19,433 WARN  [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Insufficient capacity com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":661,"instanceName":"r-661-VM","state":"Starting","type":"DomainRouter","uuid":"2af967de-e5a8-4ded-8e42-cc3c9923daac"}Scope=interface com.cloud.dc.DataCenter; id=1
2025-12-04 14:33:19,433 DEBUG [c.c.d.D.ExcludeList] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Adding DataCenter [1] to the avoid set due to [Unable to create a deployment for VM instance {"id":661,"instanceName":"r-661-VM","state":"Starting","type":"DomainRouter","uuid":"2af967de-e5a8-4ded-8e42-cc3c9923daac"}].
2025-12-04 14:33:19,587 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Trying to deploy VM [error decoding VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}] and details: Plan [error decoding {"_clusterId":1,"_dcId":1,"_physicalNetworkId":null,"_podId":1,"_poolId":1,"migrationPlan":false}]; avoid list [{"_dcIds":[1],"_podIds":[],"_clusterIds":[],"_hostIds":[1]}] and planner: [null].
2025-12-04 14:33:19,589 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Adding pods [[]], clusters [[]] and hosts [[]] to the avoid list in the deploy process of user VM [error decoding VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}], because this VM is not explicitly dedicated to these components.
2025-12-04 14:33:19,594 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Stopped","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"} state transited from [Starting] to [Stopped] with event [OperationFailed]. VM's original host: Host {"id":31,"name":"hv102.internal.nexthop.ai","type":"Routing","uuid":"8a8a2f0b-be76-4179-a2b9-c9785a81d061"}, new host: null, host before state transition: Host {"id":1,"name":"hv101.internal.nexthop.ai","type":"Routing","uuid":"f8827e39-531b-47c8-9fa7-928fc708c562"}
2025-12-04 14:33:19,598 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}Scope=interface com.cloud.dc.DataCenter; id=1
2025-12-04 14:33:19,598 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}Scope=interface com.cloud.dc.DataCenter; id=1
2025-12-04 14:33:19,598 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769]) (logid:de988890) Unable to complete AsyncJob {"accountId":202,"cmd":"com.cloud.vm.VmWorkStart","cmdInfo":"rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAADKAAAAAAAAAMoAAAAAAAAAK3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAAFdAAQQ29uc2lkZXJMYXN0SG9zdHQAEHJPMEFCWFFBQldaaGJITmx0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3QACEJvb3RNb2RldAASck8wQUJYUUFCa3hGUjBGRFdRdAAIQm9vdFR5cGV0AA9yTzBBQlhRQUJGVkZSa2t0AAhVZWZpRmxhZ3QADnJPMEFCWFFBQTFsbGN3eHA","cmdVersion":0,"completeMsid":null,"created":"Thu Dec 04 14:33:19 UTC 2025","id":21769,"initMsid":117047427410415,"instanceId":null,"instanceType":null,"lastPolled":null,"lastUpdated":null,"processStatus":0,"removed":null,"result":null,"resultCode":0,"status":"IN_PROGRESS","userId":202,"uuid":"85403b8e-97ca-4df8-806b-3ff114714ed0"}, job origin: 21766 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}Scope=interface com.cloud.dc.DataCenter; id=1
2025-12-04 14:33:19,599 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769]) (logid:de988890) Complete async job-21769, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uVk1PcAAAABACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvblZNT3AAAAAVAgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACjVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNIGluc3RhbmNlIHsiaWQiOjQzLCJpbnN0YW5jZU5hbWUiOiJpLTYyNS00My1WTSIsInN0YXRlIjoiU3RhcnRpbmciLCJ0eXBlIjoiVXNlciIsInV1aWQiOiJhZDI4YzgyOC1mMGExLTQxMWYtODJkOC1lOWJlMjcxMTg4NzAifXVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFXNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ACkwADmRlY2xhcmluZ0NsYXNzcQB-AApMAAhmaWxlTmFtZXEAfgAKTAAKbWV0aG9kTmFtZXEAfgAKTAAKbW9kdWxlTmFtZXEAfgAKTAANbW9kdWxlVmVyc2lvbnEAfgAKeHABAAAFrnQAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHBwc3EAfgARAQAAFz9xAH4AE3EAfgAUcQB-ABVxAH4AFnBwc3EAfgARAv____5wdAAtamRrLmludGVybmFsLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2UwdAAJamF2YS5iYXNldAAHMTcuMC4xNnNxAH4AEQIAAABNcHEAfgAZcQB-ABp0AAZpbnZva2VxAH4AHHEAfgAdc3EAfgARAgAAACtwdAAxamRrLmludGVybmFsLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAfcQB-ABxxAH4AHXNxAH4AEQIAAAI5cHQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-AB9xAH4AHHEAfgAdc3EAfgARAQAAAGZxAH4AE3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnBwc3EAfgARAQAAF7txAH4AE3EAfgAUcQB-ABVxAH4AKXBwc3EAfgARAQAAAGNxAH4AE3QAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9icHBzcQB-ABEBAAACunEAfgATdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0cHBzcQB-ABEBAAAAMXEAfgATdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5wcHNxAH4AEQEAAAA4cQB-ABN0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxwcHNxAH4AEQEAAABncQB-ABN0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADl0AA9jYWxsV2l0aENvbnRleHRwcHNxAH4AEQEAAAA1cQB-ABNxAH4APHEAfgA5dAAOcnVuV2l0aENvbnRleHRwcHNxAH4AEQEAAAAucQB-ABN0ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4ANXEAfgA2cHBzcQB-ABEBAAAChnEAfgATcQB-ADBxAH4AMXEAfgA2cHBzcQB-ABECAAACG3B0AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4AOnEAfgAccQB-AB1zcQB-ABECAAABCHB0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-ADZxAH4AHHEAfgAdc3EAfgARAgAABHBwdAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJxAH4AHHEAfgAdc3EAfgARAgAAAntwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBLcQB-ADZxAH4AHHEAfgAdc3EAfgARAgAAA0hwdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-ADZxAH4AHHEAfgAdc3IAH2phdmEudXRpbC5Db2xsZWN0aW9ucyRFbXB0eUxpc3R6uBe0PKee3gIAAHhweHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABDvc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4c3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhxAH4AVQAAAAAAAAABdnIAF2NvbS5jbG91ZC5kYy5EYXRhQ2VudGVyEFBUbQNFHgACAAB4cAA
2025-12-04 14:33:19,608 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-2:[ctx-c71520ee, job-21766]) (logid:de988890) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM [ad28c828-f0a1-411f-82d8-e9be27118870] due to [Unable to create a deployment for VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}].
Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}Scope=interface com.cloud.dc.DataCenter; id=1
2025-12-04 14:33:19,608 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-2:[ctx-c71520ee, job-21766]) (logid:de988890) Complete async job-21766, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Unable to start a VM [ad28c828-f0a1-411f-82d8-e9be27118870] due to [Unable to create a deployment for VM instance {"id":43,"instanceName":"i-625-43-VM","state":"Starting","type":"User","uuid":"ad28c828-f0a1-411f-82d8-e9be27118870"}]."}

Answered by prashanthr2

Dec 4, 2025

@bradh352 I see below in the logs

2025-12-04 14:33:19,426 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Using volume allocation algorithm random to reorder pools.
2025-12-04 14:33:19,426 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Trying to find suitable pools to allocate volume [Volume {"id":1701,"instanceId":661,"name":"ROOT-661","uuid":"09fa0cd6-5db0-4029-aa23-45e5d285574a","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":661,"instanceName":"r-661-VM","state":"Starting","type":"DomainRouter"…

View full answer

prashanthr2 · 2025-12-04T14:48:40Z

prashanthr2
Dec 4, 2025

@bradh352 From the logs I see it is trying to start the VR associated with the VM's as well and is failing.. Can you attach full management server log ( from all the management servers)

1 reply

bhouse-nexthop Dec 4, 2025

@bradh352 From the logs I see it is trying to start the VR associated with the VM's as well and is failing.. Can you attach full management server log ( from all the management servers)

Attached, thanks!

node1.log.gz
node2.log.gz
node3.log.gz

bradh352 · 2025-12-04T14:56:43Z

bradh352
Dec 4, 2025
Author

I am also seeing something weird, one of my hosts is listed 3 times.

root@hv101:~# cmk listHosts
{
  "count": 5,
  "host": [
    {
      "arch": "x86_64",
      "capabilities": "hvm,snapshot",
      "clusterid": "91c00538-aa42-4778-908a-a814e2637e0f",
      "clustername": "g1",
      "clustertype": "CloudManaged",
      "cpuallocated": "5.19%",
      "cpuallocatedpercentage": "5.19%",
      "cpuallocatedvalue": 449000,
      "cpuallocatedwithoverprovisioning": "5.19%",
      "cpuloadaverage": 2.2,
      "cpunumber": 192,
      "cpusockets": 1,
      "cpuspeed": 4510,
      "cpuused": "0.85%",
      "cpuwithoverprovisioning": "8659200",
      "created": "2025-10-09T22:02:49+0000",
      "details": {
        "Host.OS": "Ubuntu",
        "Host.OS.Kernel.Version": "6.14.0-35-generic",
        "Host.OS.Version": "24.04",
        "com.cloud.network.Networks.RouterPrivateIpStrategy": "HostLocal",
        "host.uefi.enable": "true",
        "secured": "true"
      },
      "disconnected": "2025-10-10T18:16:21+0000",
      "encryptionsupported": true,
      "events": "AgentDisconnected; PingTimeout; ManagementServerDown; StartAgentRebalance; HostDown; Ping; Remove; AgentConnected; ShutdownRequested",
      "explicithosttags": "g1,testbed-vr1",
      "hahost": false,
      "hasannotations": false,
      "hostha": {
        "haenable": false,
        "hastate": "Disabled"
      },
      "hosttags": "g1,testbed-vr1",
      "hypervisor": "KVM",
      "id": "f8827e39-531b-47c8-9fa7-928fc708c562",
      "instanceconversionsupported": false,
      "ipaddress": "10.10.0.10",
      "islocalstorageactive": false,
      "istagarule": false,
      "lastpinged": "1970-01-20T22:44:55+0000",
      "managementserverid": "fdf510d4-7023-45fd-a35c-74c678a19c2f",
      "managementservername": "hv101.internal.nexthop.ai",
      "memoryallocated": 949456207872,
      "memoryallocatedbytes": 949456207872,
      "memoryallocatedpercentage": "63.11%",
      "memorytotal": 1504426590208,
      "memoryused": 73649917952,
      "memorywithoverprovisioning": "1504426590208",
      "name": "hv101.internal.nexthop.ai",
      "networkkbsread": 4282,
      "networkkbswrite": 121472,
      "outofbandmanagement": {
        "enabled": false,
        "powerstate": "Disabled"
      },
      "podid": "b88c9376-fdc8-4cfc-8601-8826eed9ad97",
      "podname": "pod1",
      "resourcestate": "Enabled",
      "state": "Up",
      "type": "Routing",
      "ueficapability": true,
      "version": "4.22.0.1",
      "zoneid": "d9a16f24-9e15-43a7-afd0-baa96a7e5ef3",
      "zonename": "us-west-1"
    },
    {
      "arch": "x86_64",
      "capabilities": "hvm,snapshot",
      "clusterid": "91c00538-aa42-4778-908a-a814e2637e0f",
      "clustername": "g1",
      "clustertype": "CloudManaged",
      "cpuallocated": "3.4%",
      "cpuallocatedpercentage": "3.4%",
      "cpuallocatedvalue": 294500,
      "cpuallocatedwithoverprovisioning": "3.4%",
      "cpuloadaverage": 1.31,
      "cpunumber": 192,
      "cpusockets": 1,
      "cpuspeed": 4510,
      "cpuused": "0.62%",
      "cpuwithoverprovisioning": "8659200",
      "created": "2025-10-12T12:39:15+0000",
      "details": {
        "Host.OS": "Ubuntu",
        "Host.OS.Kernel.Version": "6.14.0-35-generic",
        "Host.OS.Version": "24.04",
        "com.cloud.network.Networks.RouterPrivateIpStrategy": "HostLocal",
        "host.uefi.enable": "true",
        "secured": "true"
      },
      "encryptionsupported": true,
      "events": "AgentDisconnected; PingTimeout; ManagementServerDown; StartAgentRebalance; HostDown; Ping; Remove; AgentConnected; ShutdownRequested",
      "explicithosttags": "g1,testbed-vr2",
      "hahost": false,
      "hasannotations": false,
      "hostha": {
        "haenable": false,
        "hastate": "Disabled"
      },
      "hosttags": "g1,testbed-vr2",
      "hypervisor": "KVM",
      "id": "8a8a2f0b-be76-4179-a2b9-c9785a81d061",
      "instanceconversionsupported": false,
      "ipaddress": "10.10.0.11",
      "islocalstorageactive": false,
      "istagarule": false,
      "lastpinged": "1970-01-20T22:44:55+0000",
      "managementserverid": "9d1acb32-7bb5-4667-a3f5-2614e0242138",
      "managementservername": "hv102.internal.nexthop.ai",
      "memoryallocated": 631494410240,
      "memoryallocatedbytes": 631494410240,
      "memoryallocatedpercentage": "41.98%",
      "memorytotal": 1504426852352,
      "memoryused": 70121820160,
      "memorywithoverprovisioning": "1504426852352",
      "name": "hv102.internal.nexthop.ai",
      "networkkbsread": 402497,
      "networkkbswrite": 52830,
      "outofbandmanagement": {
        "enabled": false,
        "powerstate": "Disabled"
      },
      "podid": "b88c9376-fdc8-4cfc-8601-8826eed9ad97",
      "podname": "pod1",
      "resourcestate": "Enabled",
      "state": "Up",
      "type": "Routing",
      "ueficapability": true,
      "version": "4.22.0.1",
      "zoneid": "d9a16f24-9e15-43a7-afd0-baa96a7e5ef3",
      "zonename": "us-west-1"
    },
    {
      "arch": "x86_64",
      "capabilities": "hvm,snapshot",
      "clusterid": "91c00538-aa42-4778-908a-a814e2637e0f",
      "clustername": "g1",
      "clustertype": "CloudManaged",
      "cpuallocated": "3.3%",
      "cpuallocatedpercentage": "3.3%",
      "cpuallocatedvalue": 285832,
      "cpuallocatedwithoverprovisioning": "3.3%",
      "cpuloadaverage": 2.15,
      "cpunumber": 192,
      "cpusockets": 1,
      "cpuspeed": 4510,
      "cpuused": "0.98%",
      "cpuwithoverprovisioning": "8659200",
      "created": "2025-10-12T12:41:00+0000",
      "details": {
        "Host.OS": "Ubuntu",
        "Host.OS.Kernel.Version": "6.14.0-35-generic",
        "Host.OS.Version": "24.04",
        "com.cloud.network.Networks.RouterPrivateIpStrategy": "HostLocal",
        "host.uefi.enable": "true",
        "secured": "true"
      },
      "encryptionsupported": true,
      "events": "AgentDisconnected; PingTimeout; ManagementServerDown; StartAgentRebalance; HostDown; Ping; Remove; AgentConnected; ShutdownRequested",
      "explicithosttags": "g1",
      "hahost": false,
      "hasannotations": false,
      "hostha": {
        "haenable": false,
        "hastate": "Disabled"
      },
      "hosttags": "g1",
      "hypervisor": "KVM",
      "id": "76f35578-d1b4-4a3c-94fc-68a12c6ce308",
      "instanceconversionsupported": false,
      "ipaddress": "10.10.0.12",
      "islocalstorageactive": false,
      "istagarule": false,
      "lastpinged": "1970-01-20T22:44:55+0000",
      "managementserverid": "7a874b2e-8da0-46f6-a68b-5f2ad3f19fa4",
      "managementservername": "hv103.internal.nexthop.ai",
      "memoryallocated": 607201001472,
      "memoryallocatedbytes": 607201001472,
      "memoryallocatedpercentage": "40.36%",
      "memorytotal": 1504426852352,
      "memoryused": 66510381056,
      "memorywithoverprovisioning": "1504426852352",
      "name": "hv103.internal.nexthop.ai",
      "networkkbsread": 1498,
      "networkkbswrite": 25342,
      "outofbandmanagement": {
        "enabled": false,
        "powerstate": "Disabled"
      },
      "podid": "b88c9376-fdc8-4cfc-8601-8826eed9ad97",
      "podname": "pod1",
      "resourcestate": "Enabled",
      "state": "Up",
      "type": "Routing",
      "ueficapability": true,
      "version": "4.22.0.1",
      "zoneid": "d9a16f24-9e15-43a7-afd0-baa96a7e5ef3",
      "zonename": "us-west-1"
    },
    {
      "created": "2025-11-18T14:31:44+0000",
      "events": "AgentDisconnected; PingTimeout; ManagementServerDown; StartAgentRebalance; HostDown; Ping; Remove; AgentConnected; ShutdownRequested",
      "hasannotations": false,
      "hostha": {
        "haenable": false,
        "hastate": "Disabled"
      },
      "id": "7c51bc6a-93de-46e2-b87c-4c248d536efa",
      "ipaddress": "10.10.3.74",
      "islocalstorageactive": false,
      "lastpinged": "1970-01-20T22:44:55+0000",
      "managementserverid": "fdf510d4-7023-45fd-a35c-74c678a19c2f",
      "managementservername": "hv101.internal.nexthop.ai",
      "memoryallocated": 0,
      "name": "v-506-VM",
      "outofbandmanagement": {
        "enabled": false,
        "powerstate": "Disabled"
      },
      "podid": "b88c9376-fdc8-4cfc-8601-8826eed9ad97",
      "podname": "pod1",
      "resourcestate": "Enabled",
      "state": "Up",
      "type": "ConsoleProxy",
      "version": "4.22.0.0",
      "virtualmachineid": "6797cefc-76d7-4097-bb98-48268a25ec42",
      "zoneid": "d9a16f24-9e15-43a7-afd0-baa96a7e5ef3",
      "zonename": "us-west-1"
    },
    {
      "created": "2025-11-18T14:31:46+0000",
      "events": "AgentDisconnected; PingTimeout; ManagementServerDown; StartAgentRebalance; HostDown; Ping; Remove; AgentConnected; ShutdownRequested",
      "hasannotations": false,
      "hostha": {
        "haenable": false,
        "hastate": "Disabled"
      },
      "id": "51f69e9f-d790-4ad9-93c6-5f670bcf5718",
      "ipaddress": "10.10.11.128",
      "islocalstorageactive": false,
      "lastpinged": "1970-01-20T22:44:55+0000",
      "managementserverid": "fdf510d4-7023-45fd-a35c-74c678a19c2f",
      "managementservername": "hv101.internal.nexthop.ai",
      "memoryallocated": 0,
      "name": "s-507-VM",
      "outofbandmanagement": {
        "enabled": false,
        "powerstate": "Disabled"
      },
      "podid": "b88c9376-fdc8-4cfc-8601-8826eed9ad97",
      "podname": "pod1",
      "resourcestate": "Enabled",
      "state": "Up",
      "type": "SecondaryStorageVM",
      "version": "4.22.0.0",
      "virtualmachineid": "8b3e3f57-eda3-4a89-9ca0-b5d912dd4b3b",
      "zoneid": "d9a16f24-9e15-43a7-afd0-baa96a7e5ef3",
      "zonename": "us-west-1"
    }
  ]
}

0 replies

bradh352 · 2025-12-04T15:13:35Z

bradh352
Dec 4, 2025
Author

I think I got it back up. Looks like one of the virtual routers was in a bad state. It was showing as up, but then there was another VR for the same VPC in the stopped state. Deleting the stopped one and the running one for the vpc, then telling it to restart the vpc ultimately resolved the issue.

0 replies

prashanthr2 · 2025-12-04T15:14:06Z

prashanthr2
Dec 4, 2025

@bradh352 I see below in the logs

2025-12-04 14:33:19,426 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Using volume allocation algorithm random to reorder pools.
2025-12-04 14:33:19,426 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Trying to find suitable pools to allocate volume [Volume {"id":1701,"instanceId":661,"name":"ROOT-661","uuid":"09fa0cd6-5db0-4029-aa23-45e5d285574a","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":661,"instanceName":"r-661-VM","state":"Starting","type":"DomainRouter","uuid":"2af967de-e5a8-4ded-8e42-cc3c9923daac"}], using StoragePoolAllocator: [ZoneWideStoragePoolAllocator].
2025-12-04 14:33:19,428 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Checking if storage pool [StoragePool {"id":1,"name":"vm-images","poolType":"RBD","uuid":"824b8d90-5fd8-3d34-9008-e982e8a4196c"}] is suitable to disk [DskChr[ROOT|5242880000|]].
2025-12-04 14:33:19,428 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Cannot check compatibility of pool [StoragePool {"id":1,"name":"vm-images","poolType":"RBD","uuid":"824b8d90-5fd8-3d34-9008-e982e8a4196c"}] because volume [Volume {"id":1701,"instanceId":661,"name":"ROOT-661","uuid":"09fa0cd6-5db0-4029-aa23-45e5d285574a","volumeType":"ROOT"}] is not in [Ready] state.
2025-12-04 14:33:19,428 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-6:[ctx-8a912d50, job-21766/job-21769, ctx-77b2d201]) (logid:de988890) Pool [StoragePool {"id":1,"name":"vm-images","poolType":"RBD","uuid":"824b8d90-5fd8-3d34-9008-e982e8a4196c"}] is not compatible with volume [Volume {"id":1701,"instanceId":661,"name":"ROOT-661","uuid":"09fa0cd6-5db0-4029-aa23-45e5d285574a","volumeType":"ROOT"}], skipping it.

What is the state of the volume associated with the VR? r-661-VM. The deployment/Start of the VR is failing causing the VM starts to fail.. Can you try to do network restart with cleanup=true

2 replies

bradh352 Dec 4, 2025
Author

yeah, i think this one showed stopped. Not sure why it was in that state or what got it there. But that definitely explains it. Thanks.

slavkap Dec 4, 2025
Collaborator

Can you check if there is connection with the storage? CloudStack is trying to create a volume from a template which should be on the primary storage already but the agent never returns the answer (at least there isn't any in the management logs). I'm not sure why the format is QCOW2 when this template is on the RBD storage

2025-12-04 13:32:16,218 DEBUG [c.c.a.m.ClusteredAgentAttache] (Work-Job-Executor-20:[ctx-fff6609f, job-20610/job-20649, ctx-7c1656d5]) (logid:2a5b4a11) Seq 1-5373075830429712385: Forwarding Seq 1-5373075830429712385: { Cmd , MgmtId: 117047427
410415, via: 1(hv101.internal.nexthop.ai), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"a66ed61f-c551-4dab-b1ac-d8c8e8ccc26e","origUrl":"http://download.cloudstack.org/systemvm/4.22/systemvmtemplate-4.22.0-x86_64-kvm.qcow2.bz2","uuid":"a66ed61f-c551-4dab-b1ac-d8c8e8ccc26e","id":"270","format":"QCOW2","accountId":"202","checksum":"{SHA-512}10987c4fb3158d40006b1a1db89bf6e9b6c3995294f295e1ca564c26c9543453d4d21a7d8c967d5487b489d88194ecfba9829f00e929b17e3ddaa70751cece90","hvm":"true","displayText":"systemvm-kvm-4.22.0-x86_64","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"824b8d90-5fd8-3d34-9008-e982e8a4196c","name":"vm-images","id":"1","poolType":"RBD","host":"hv101,hv102,hv103","path":"vm-images","port":"0","url":"RBD://hv101,hv102,hv103/vm-images/?ROLE=Primary&STOREUUID=824b8d90-5fd8-3d34-9008-e982e8a4196c","isManaged":"false"}},"name":"270-202-366de7c9-7398-33c7-b1ef-8273c0f508a9","size":"(4.88 GB) 5242880000","hypervisorType":"KVM","bootable":"false","uniqueName":"270-202-366de7c9-7398-33c7-b1ef-8273c0f508a9","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"09fa0cd6-5db0-4029-aa23-45e5d285574a","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"824b8d90-5fd8-3d34-9008-e982e8a4196c","name":"vm-images","id":"1","poolType":"RBD","host":"hv101,hv102,hv103","path":"vm-images","port":"0","url":"RBD://hv101,hv102,hv103/vm-images/?ROLE=Primary&STOREUUID=824b8d90-5fd8-3d34-9008-e982e8a4196c","isManaged":"false"}},"name":"ROOT-661","size":"(4.88 GB) 5242880000","volumeId":"1701","vmName":"r-661-VM","accountId":"625","format":"QCOW2","provisioningType":"THIN","poolId":"1","id":"1701","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false","checkpointPaths":[],"checkpointImageStoreUrls":[],"followRedirects":"false"}},"executeInSequence":"true","options":{},"options2":{},"wait":"0","bypassHostMaintenance":"false"}}] } to 173787997696661

@bradh352 , can you check the logs on this host hv101.internal.nexthop.ai everything with the log ID logid:2a5b4a11

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

How to debug VM deployment issues (capacity issues?) #12192

Uh oh!

{{title}}

Uh oh!

Replies: 4 comments 3 replies

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

How to debug VM deployment issues (capacity issues?) #12192

Uh oh!

bradh352 Dec 4, 2025

Replies: 4 comments · 3 replies

Uh oh!

prashanthr2 Dec 4, 2025

Uh oh!

bhouse-nexthop Dec 4, 2025

Uh oh!

bradh352 Dec 4, 2025 Author

Uh oh!

bradh352 Dec 4, 2025 Author

Uh oh!

prashanthr2 Dec 4, 2025

Uh oh!

bradh352 Dec 4, 2025 Author

Uh oh!

slavkap Dec 4, 2025 Collaborator

bradh352
Dec 4, 2025

Replies: 4 comments 3 replies

prashanthr2
Dec 4, 2025

bradh352
Dec 4, 2025
Author

bradh352
Dec 4, 2025
Author

prashanthr2
Dec 4, 2025

bradh352 Dec 4, 2025
Author

slavkap Dec 4, 2025
Collaborator