Launching system vms fails during installation

[SammyOina]

problem

I am following the installation guide https://docs.cloudstack.apache.org/en/latest/quickinstallationguide/qig.html However it fails at the end with system vms failing to launch

versions

Running cloudstack 4.20.0.0

The steps to reproduce the bug

1. Follow installation guide https://docs.cloudstack.apache.org/en/latest/quickinstallationguide/qig.html

What to do about it?

Please help me figure out the failure reason; this is my first CloudStack installation

[boring-cyborg]

Thanks for opening your first issue here! Be sure to follow the issue template!

[SammyOina]

2025-02-03 23:18:59,575 ERROR [c.c.c.ClusterServiceServletImpl] (Cluster-Worker-3:[ctx-c6c2a092]) (logid:1cd75554) Exception from : https://127.0.0.1:9090/clusterservice, method : null, exception : javax.net.ssl.SSLPeerUnverifiedException: Certificate for <127.0.0.1> doesn't match any of the subject alternative names: [10.172.192.34, 10.172.192.30, fe80:0:0:0:ce96:e5ff:fef5:25bb, cloudstack.internal, ultraviolet.local]
	

2025-02-03 23:18:59,575 DEBUG [c.c.c.ClusterManagerImpl] (Cluster-Worker-3:[ctx-c6c2a092]) (logid:1cd75554) Cluster PDU 224948475209146 -> 224948475209146 completed. time: 1ms. agent: 0, pdu seq: 26, pdu ack seq: 0, json: {"managementServerHostId":1,"managementServerHostUuid":"6c6e9883-0c56-4fce-8cde-10bc9d666ef9","collectionTime":"Feb 3, 2025, 11:18:59 PM","sessions":1,"cpuUtilization":0.0,"totalJvmMemoryBytes":499646464,"freeJvmMemoryBytes":63666648,"maxJvmMemoryBytes":1908932607,"processJvmMemoryBytes":0,"jvmUptime":1523578,"jvmStartTime":1738623215954,"availableProcessors":24,"loadAverage":0.255859375,"totalInit":523567104,"totalUsed":666691872,"totalCommitted":737280000,"pid":308945,"jvmName":"308945@ultraviolet.local","jvmVendor":"Ubuntu","jvmVersion":"21.0.5+11-Ubuntu-1ubuntu124.04","osDistribution":"Ubuntu 24.04.1 LTS","agentCount":1,"heapMemoryUsed":436744784,"heapMemoryTotal":1908932608,"threadsBlockedCount":0,"threadsDaemonCount":17,"threadsRunnableCount":19,"threadsTerminatedCount":0,"threadsTotalCount":402,"threadsWaitingCount":305,"systemMemoryTotal":32965242880,"systemMemoryFree":16111304704,"systemMemoryUsed":1253684,"systemMemoryVirtualSize":17203412992,"logInfo":"","systemTotalCpuCycles":76346.82099999998,"systemLoadAverages":[0.26,0.1,0.18],"systemCyclesUsage":[486749,160113,102606275],"dbLocal":true,"usageLocal":false,"systemBootTime":"Feb 3, 2025, 11:20:59 AM","kernelVersion":"6.11.0+"}
2025-02-03 23:18:59,793 DEBUG [o.a.c.h.H.HAManagerBgPollTask] (BackgroundTaskPollManager-6:[ctx-ffdaf835]) (logid:6b3a1b8f) HA health check task is running...
2025-02-03 23:19:00,557 DEBUG [c.c.a.t.Request] (AgentManager-Handler-2:[]) (logid:) Seq 2-3494511835862794589: Processing:  { Ans: , MgmtId: 224948475209146, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-02-03 23:19:00,557 DEBUG [c.c.a.t.Request] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Seq 2-3494511835862794589: Received:  { Ans: , MgmtId: 224948475209146, via: 2(ultraviolet.local), Ver: v1, Flags: 10, { StopAnswer } }
2025-02-03 23:19:00,561 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Released nic: NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":1127,"reservationId":null,"vmId":660} for vm VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}
2025-02-03 23:19:00,561 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) The nic Nic {"broadcastUri":null,"deviceId":0,"iPv4Address":"169.254.213.95","id":1127,"instanceId":660,"reservationId":"77331f67-53f1-4fa4-8112-738d1dd97387"} on NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":1127,"reservationId":null,"vmId":660} was released according to VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"} by guru com.cloud.network.guru.ControlNetworkGuru@48d54b1c, now updating record.
2025-02-03 23:19:00,564 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Releasing ip address for reservationId=77331f67-53f1-4fa4-8112-738d1dd97387, nic=1128
2025-02-03 23:19:00,564 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Released nic: NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":1128,"reservationId":null,"vmId":660} for vm VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}
2025-02-03 23:19:00,564 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) The nic Nic {"broadcastUri":null,"deviceId":1,"iPv4Address":"172.16.10.30","id":1128,"instanceId":660,"reservationId":"77331f67-53f1-4fa4-8112-738d1dd97387"} on NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":1128,"reservationId":null,"vmId":660} was released according to VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"} by guru com.cloud.network.guru.PodBasedNetworkGuru@1324605b, now updating record.
2025-02-03 23:19:00,565 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Successfully released network resources for the VM VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"} in Starting state
2025-02-03 23:19:00,567 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Successfully released storage resources for the VM VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"} in Starting state
2025-02-03 23:19:00,567 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Successfully cleaned up resources for the VM VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"} in Starting state
2025-02-03 23:19:00,567 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) VM start attempt #2
2025-02-03 23:19:00,568 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Root volume is ready, need to place VM in volume's cluster
2025-02-03 23:19:00,568 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Vol[376|name=ROOT-660|vm=660|ROOT] is READY, changing deployment plan to use this pool's dcId: 2, podId: 2, and clusterId: 2
2025-02-03 23:19:00,568 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Trying to deploy VM [error decoding VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}] and details: Plan [error decoding {"_clusterId":2,"_dcId":2,"_physicalNetworkId":null,"_podId":2,"_poolId":2,"migrationPlan":false}]; avoid list [{"_podIds":[],"_clusterIds":[],"_hostIds":[2]}] and planner: [].
2025-02-03 23:19:00,569 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Trying to allocate a host and storage pools from datacenter [{"name":"uv-dell-2","uuid":"bf6f5332-ddfc-4793-95b9-c1696e1b48dc"}], pod [{"name":"pod2","uuid":"6b30cf43-a40b-43c6-bc30-dba58280cb16"}], cluster [{"name":"cluster2","uuid":"dc1279a6-9c80-4be4-bd71-a30934575f38"}], to deploy VM [{"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}] with requested CPU [500] and requested RAM [(512.00 MB) 536870912].
2025-02-03 23:19:00,569 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) ROOT volume [42ae9d0b-d015-4219-9399-6e30f42e8ec8] is ready to deploy VM [db9ad80f-05d6-4082-94c5-191ddbecfb33].
2025-02-03 23:19:00,570 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Adding pods [] to the avoid set because these pods are in the Disabled state.
2025-02-03 23:19:00,570 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Adding clusters [] of pod [2] to the void set because these clusters are in the Disabled state.
2025-02-03 23:19:00,571 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Adding hosts [] of datacenter [bf6f5332-ddfc-4793-95b9-c1696e1b48dc] to the avoid set, because these hosts are in the Disabled state.
2025-02-03 23:19:00,571 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) DeploymentPlan [DataCenterDeployment] has not specified host. Trying to find another destination to deploy VM [db9ad80f-05d6-4082-94c5-191ddbecfb33], avoiding pods [], clusters [] and hosts [2].
2025-02-03 23:19:00,571 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Deploy avoids pods: [], clusters: [], hosts: [2].
2025-02-03 23:19:00,571 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Deploy hosts with priorities {}, hosts have NORMAL priority by default
2025-02-03 23:19:00,571 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Searching resources only under specified Cluster: 2
2025-02-03 23:19:00,573 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Checking resources in Cluster: 2 under Pod: 2
2025-02-03 23:19:00,573 INFO  [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac, FirstFitRoutingAllocator]) (logid:6d42f2b9)  Guest VM is requested with Custom[UEFI] Boot Type false
2025-02-03 23:19:00,573 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac, FirstFitRoutingAllocator]) (logid:6d42f2b9) Looking for hosts in zone [2], pod [2], cluster [2]
2025-02-03 23:19:00,574 INFO  [o.a.c.u.r.ReflectionToStringBuilderUtils] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac, FirstFitRoutingAllocator]) (logid:6d42f2b9) Collection [[]] is empty or has only null values, not reflecting it.
2025-02-03 23:19:00,574 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac, FirstFitRoutingAllocator]) (logid:6d42f2b9) Adding hosts [null] to the avoid set because these hosts do not support HA.
2025-02-03 23:19:00,574 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac, FirstFitRoutingAllocator]) (logid:6d42f2b9) FirstFitAllocator has 1 hosts to check for allocation: [Host {"id":2,"name":"ultraviolet.local","type":"Routing","uuid":"86b3b883-4b15-4328-a3fe-56e41cd46ad3"}]
2025-02-03 23:19:00,575 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac, FirstFitRoutingAllocator]) (logid:6d42f2b9) Found 1 hosts for allocation after prioritization: [Host {"id":2,"name":"ultraviolet.local","type":"Routing","uuid":"86b3b883-4b15-4328-a3fe-56e41cd46ad3"}]
2025-02-03 23:19:00,575 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac, FirstFitRoutingAllocator]) (logid:6d42f2b9) Looking for speed=500Mhz, Ram=512 MB
2025-02-03 23:19:00,575 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac, FirstFitRoutingAllocator]) (logid:6d42f2b9) Host name: ultraviolet.local, hostId: 2 is in avoid set, skipping this and trying other available hosts
2025-02-03 23:19:00,575 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac, FirstFitRoutingAllocator]) (logid:6d42f2b9) Host Allocator returning 0 suitable hosts
2025-02-03 23:19:00,575 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) No suitable hosts found.
2025-02-03 23:19:00,575 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) No suitable hosts found under this Cluster: 2
2025-02-03 23:19:00,575 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Could not find suitable Deployment Destination for this VM under any clusters, returning. 
2025-02-03 23:19:00,576 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Searching resources only under specified Cluster: 2
2025-02-03 23:19:00,576 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) The specified cluster is in avoid set, returning.
2025-02-03 23:19:00,576 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) VM start attempt #3
2025-02-03 23:19:00,576 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Trying to deploy VM [error decoding VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}] and details: Plan [error decoding {"_clusterId":null,"_dcId":2,"_physicalNetworkId":null,"_podId":2,"_poolId":null,"migrationPlan":false}]; avoid list [{"_podIds":[],"_clusterIds":[2],"_hostIds":[2]}] and planner: [].
2025-02-03 23:19:00,577 DEBUG [o.a.c.u.r.ReflectionToStringBuilderUtils] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Object is null, not reflecting it.
2025-02-03 23:19:00,577 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Trying to allocate a host and storage pools from datacenter [{"name":"uv-dell-2","uuid":"bf6f5332-ddfc-4793-95b9-c1696e1b48dc"}], pod [{"name":"pod2","uuid":"6b30cf43-a40b-43c6-bc30-dba58280cb16"}], cluster [null], to deploy VM [{"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}] with requested CPU [500] and requested RAM [(512.00 MB) 536870912].
2025-02-03 23:19:00,577 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) ROOT volume [42ae9d0b-d015-4219-9399-6e30f42e8ec8] is not ready to deploy VM [db9ad80f-05d6-4082-94c5-191ddbecfb33].
2025-02-03 23:19:00,578 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Adding pods [] to the avoid set because these pods are in the Disabled state.
2025-02-03 23:19:00,578 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Adding clusters [] of pod [2] to the void set because these clusters are in the Disabled state.
2025-02-03 23:19:00,578 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Adding hosts [] of datacenter [bf6f5332-ddfc-4793-95b9-c1696e1b48dc] to the avoid set, because these hosts are in the Disabled state.
2025-02-03 23:19:00,579 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) DeploymentPlan [DataCenterDeployment] has not specified host. Trying to find another destination to deploy VM [db9ad80f-05d6-4082-94c5-191ddbecfb33], avoiding pods [], clusters [2] and hosts [2].
2025-02-03 23:19:00,579 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Deploy avoids pods: [], clusters: [2], hosts: [2].
2025-02-03 23:19:00,579 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Deploy hosts with priorities {}, hosts have NORMAL priority by default
2025-02-03 23:19:00,579 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Searching resources only under specified Pod: 2
2025-02-03 23:19:00,579 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Listing clusters in order of aggregate capacity, that have (at least one host with) enough CPU and RAM capacity under this Pod: 2
2025-02-03 23:19:00,580 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Removing from the clusterId list these clusters from avoid set: [2]
2025-02-03 23:19:00,580 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2025-02-03 23:19:00,584 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"} state transited from [Starting] to [Stopped] with event [OperationFailed]. VM's original host: null, new host: null, host before state transition: Host {"id":2,"name":"ultraviolet.local","type":"Routing","uuid":"86b3b883-4b15-4328-a3fe-56e41cd46ad3"}
2025-02-03 23:19:00,587 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Hosts's actual total CPU: 68256 and CPU after applying overprovisioning: 68256
2025-02-03 23:19:00,587 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Hosts's actual total RAM: (29.70 GB) 31891501056 and RAM after applying overprovisioning: (29.70 GB) 31891501056
2025-02-03 23:19:00,587 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) release cpu from host: 2, old used: 1000,reserved: 0, actual total: 68256, total with overprovisioning: 68256; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2025-02-03 23:19:00,587 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) release mem from host: 2, old used: (1.50 GB) 1610612736,reserved: (0 bytes) 0, total: (29.70 GB) 31891501056; new used: (1.00 GB) 1073741824,reserved:(0 bytes) 0; movedfromreserved: false,moveToReserveredfalse
2025-02-03 23:19:00,588 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}Scope=interface com.cloud.dc.DataCenter; id=2
2025-02-03 23:19:00,588 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171, ctx-b872c7ac]) (logid:6d42f2b9) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}Scope=interface com.cloud.dc.DataCenter; id=2
2025-02-03 23:19:00,588 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171]) (logid:6d42f2b9) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 660, job origin: 1025
2025-02-03 23:19:00,588 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171]) (logid:6d42f2b9) Unable to complete AsyncJobVO: {id:1171, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAClHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 224948475209146, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Feb 03 23:18:54 UTC 2025, removed: null}, job origin: 1025 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}Scope=interface com.cloud.dc.DataCenter; id=2
	
2025-02-03 23:19:00,588 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171]) (logid:6d42f2b9) Complete async job-1171, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uVk1PcAAAABACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvblZNT3AAAAAVAgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACcVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNIGluc3RhbmNlIHsiaWQiOjY2MCwiaW5zdGFuY2VOYW1lIjoicy02NjAtVk0iLCJ0eXBlIjoiU2Vjb25kYXJ5U3RvcmFnZVZtIiwidXVpZCI6ImRiOWFkODBmLTA1ZDYtNDA4Mi05NGM1LTE5MWRkYmVjZmIzMyJ9dXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAATc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAKTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AApMAAptb2R1bGVOYW1lcQB-AApMAA1tb2R1bGVWZXJzaW9ucQB-AAp4cAEAAATVdAADYXBwdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0cHBzcQB-ABEBAAAVW3EAfgATcQB-ABRxAH4AFXEAfgAWcHBzcQB-ABECAAAAZ3B0AC9qZGsuaW50ZXJuYWwucmVmbGVjdC5EaXJlY3RNZXRob2RIYW5kbGVBY2Nlc3NvcnQAH0RpcmVjdE1ldGhvZEhhbmRsZUFjY2Vzc29yLmphdmF0AAZpbnZva2V0AAlqYXZhLmJhc2V0AAYyMS4wLjVzcQB-ABECAAACRHB0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAbcQB-ABxxAH4AHXNxAH4AEQEAAABqcQB-ABN0ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JwcHNxAH4AEQEAABXXcQB-ABNxAH4AFHEAfgAVcQB-ACRwcHNxAH4AEQEAAABjcQB-ABN0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnBwc3EAfgARAQAAAoxxAH4AE3QAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHBwc3EAfgARAQAAADFxAH4AE3QAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVucHBzcQB-ABEBAAAAOHEAfgATdABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxscHBzcQB-ABEBAAAAZ3EAfgATdABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgA0dAAPY2FsbFdpdGhDb250ZXh0cHBzcQB-ABEBAAAANXEAfgATcQB-ADdxAH4ANHQADnJ1bldpdGhDb250ZXh0cHBzcQB-ABEBAAAALnEAfgATdAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ADBxAH4AMXBwc3EAfgARAQAAAlhxAH4AE3EAfgArcQB-ACxxAH4AMXBwc3EAfgARAgAAAjxwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ADVxAH4AHHEAfgAdc3EAfgARAgAAAT1wdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAxcQB-ABxxAH4AHXNxAH4AEQIAAAR4cHQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2VycQB-ABxxAH4AHXNxAH4AEQIAAAKCcHQALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ARnEAfgAxcQB-ABxxAH4AHXNxAH4AEQIAAAYvcHQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAxcQB-ABxxAH4AHXNyAB9qYXZhLnV0aWwuQ29sbGVjdGlvbnMkRW1wdHlMaXN0ergXtDynnt4CAAB4cHhzcgARamF2YS5sYW5nLkludGVnZXIS4qCk94GHOAIAAUkABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAQ73NyABNqYXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cQB-AFAAAAAAAAAAAnZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlchBQVG0DRR4AAgAAeHAA
2025-02-03 23:19:00,588 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171]) (logid:6d42f2b9) Publish async job-1171 complete on message bus
2025-02-03 23:19:00,588 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171]) (logid:6d42f2b9) Wake up jobs related to job-1171
2025-02-03 23:19:00,588 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171]) (logid:6d42f2b9) Update db status for job-1171
2025-02-03 23:19:00,589 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171]) (logid:6d42f2b9) Wake up jobs joined with job-1171 and disjoin all subjobs created from job- 1171
2025-02-03 23:19:00,591 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171]) (logid:6d42f2b9) Done executing com.cloud.vm.VmWorkStart for job-1171
2025-02-03 23:19:00,592 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-146:[ctx-3da299cf, job-1025/job-1171]) (logid:6d42f2b9) Remove job-1171 from job monitoring
2025-02-03 23:19:00,594 WARN  [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Unable to start secondary storage VM [660] due to [Unable to create a deployment for VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}]. com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}Scope=interface com.cloud.dc.DataCenter; id=2
	
2025-02-03 23:19:00,594 INFO  [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Unable to start secondary storage VM [660] for standby capacity, it will be recycled and will start a new one.
2025-02-03 23:19:00,597 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Sync job-1172 execution on object VmWorkJobQueue.660
2025-02-03 23:19:00,643 DEBUG [c.c.a.t.Request] (AgentManager-Handler-3:[]) (logid:) Seq 2-3494511835862794590: Processing:  { Ans: , MgmtId: 224948475209146, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-02-03 23:19:00,643 DEBUG [c.c.a.t.Request] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Seq 2-3494511835862794590: Received:  { Ans: , MgmtId: 224948475209146, via: 2(ultraviolet.local), Ver: v1, Flags: 10, { StopAnswer } }
2025-02-03 23:19:00,648 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Released nic: NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":1124,"reservationId":null,"vmId":659} for vm VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}
2025-02-03 23:19:00,648 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) The nic Nic {"broadcastUri":null,"deviceId":0,"iPv4Address":"169.254.180.24","id":1124,"instanceId":659,"reservationId":"df5d43a8-1aa2-4889-887c-ce6c41bd01ea"} on NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":1124,"reservationId":null,"vmId":659} was released according to VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"} by guru com.cloud.network.guru.ControlNetworkGuru@48d54b1c, now updating record.
2025-02-03 23:19:00,650 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Releasing ip address for reservationId=df5d43a8-1aa2-4889-887c-ce6c41bd01ea, nic=1125
2025-02-03 23:19:00,651 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Released nic: NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":1125,"reservationId":null,"vmId":659} for vm VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}
2025-02-03 23:19:00,651 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) The nic Nic {"broadcastUri":null,"deviceId":1,"iPv4Address":"172.16.10.22","id":1125,"instanceId":659,"reservationId":"df5d43a8-1aa2-4889-887c-ce6c41bd01ea"} on NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":1125,"reservationId":null,"vmId":659} was released according to VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"} by guru com.cloud.network.guru.PodBasedNetworkGuru@1324605b, now updating record.
2025-02-03 23:19:00,652 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Successfully released network resources for the VM VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"} in Starting state
2025-02-03 23:19:00,654 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Successfully released storage resources for the VM VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"} in Starting state
2025-02-03 23:19:00,654 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Successfully cleaned up resources for the VM VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"} in Starting state
2025-02-03 23:19:00,654 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) VM start attempt #2
2025-02-03 23:19:00,654 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Root volume is ready, need to place VM in volume's cluster
2025-02-03 23:19:00,654 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Vol[375|name=ROOT-659|vm=659|ROOT] is READY, changing deployment plan to use this pool's dcId: 2, podId: 2, and clusterId: 2
2025-02-03 23:19:00,655 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Trying to deploy VM [error decoding VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}] and details: Plan [error decoding {"_clusterId":2,"_dcId":2,"_physicalNetworkId":null,"_podId":2,"_poolId":2,"migrationPlan":false}]; avoid list [{"_podIds":[],"_clusterIds":[],"_hostIds":[2]}] and planner: [].
2025-02-03 23:19:00,656 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Trying to allocate a host and storage pools from datacenter [{"name":"uv-dell-2","uuid":"bf6f5332-ddfc-4793-95b9-c1696e1b48dc"}], pod [{"name":"pod2","uuid":"6b30cf43-a40b-43c6-bc30-dba58280cb16"}], cluster [{"name":"cluster2","uuid":"dc1279a6-9c80-4be4-bd71-a30934575f38"}], to deploy VM [{"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}] with requested CPU [500] and requested RAM [(1.00 GB) 1073741824].
2025-02-03 23:19:00,656 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) ROOT volume [6eca55c4-4173-4d17-9163-d10cc67d72de] is ready to deploy VM [9176a552-5253-423d-ac17-5d017511ce21].
2025-02-03 23:19:00,657 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Adding pods [] to the avoid set because these pods are in the Disabled state.
2025-02-03 23:19:00,657 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Adding clusters [] of pod [2] to the void set because these clusters are in the Disabled state.
2025-02-03 23:19:00,657 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Adding hosts [] of datacenter [bf6f5332-ddfc-4793-95b9-c1696e1b48dc] to the avoid set, because these hosts are in the Disabled state.
2025-02-03 23:19:00,658 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) DeploymentPlan [DataCenterDeployment] has not specified host. Trying to find another destination to deploy VM [9176a552-5253-423d-ac17-5d017511ce21], avoiding pods [], clusters [] and hosts [2].
2025-02-03 23:19:00,658 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Deploy avoids pods: [], clusters: [], hosts: [2].
2025-02-03 23:19:00,658 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Deploy hosts with priorities {}, hosts have NORMAL priority by default
2025-02-03 23:19:00,658 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Searching resources only under specified Cluster: 2
2025-02-03 23:19:00,660 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Checking resources in Cluster: 2 under Pod: 2
2025-02-03 23:19:00,660 INFO  [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32, FirstFitRoutingAllocator]) (logid:795c34a4)  Guest VM is requested with Custom[UEFI] Boot Type false
2025-02-03 23:19:00,660 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32, FirstFitRoutingAllocator]) (logid:795c34a4) Looking for hosts in zone [2], pod [2], cluster [2]
2025-02-03 23:19:00,661 INFO  [o.a.c.u.r.ReflectionToStringBuilderUtils] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32, FirstFitRoutingAllocator]) (logid:795c34a4) Collection [[]] is empty or has only null values, not reflecting it.
2025-02-03 23:19:00,661 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32, FirstFitRoutingAllocator]) (logid:795c34a4) Adding hosts [null] to the avoid set because these hosts do not support HA.
2025-02-03 23:19:00,661 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32, FirstFitRoutingAllocator]) (logid:795c34a4) FirstFitAllocator has 1 hosts to check for allocation: [Host {"id":2,"name":"ultraviolet.local","type":"Routing","uuid":"86b3b883-4b15-4328-a3fe-56e41cd46ad3"}]
2025-02-03 23:19:00,662 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32, FirstFitRoutingAllocator]) (logid:795c34a4) Found 1 hosts for allocation after prioritization: [Host {"id":2,"name":"ultraviolet.local","type":"Routing","uuid":"86b3b883-4b15-4328-a3fe-56e41cd46ad3"}]
2025-02-03 23:19:00,662 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32, FirstFitRoutingAllocator]) (logid:795c34a4) Looking for speed=500Mhz, Ram=1024 MB
2025-02-03 23:19:00,662 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32, FirstFitRoutingAllocator]) (logid:795c34a4) Host name: ultraviolet.local, hostId: 2 is in avoid set, skipping this and trying other available hosts
2025-02-03 23:19:00,662 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32, FirstFitRoutingAllocator]) (logid:795c34a4) Host Allocator returning 0 suitable hosts
2025-02-03 23:19:00,662 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) No suitable hosts found.
2025-02-03 23:19:00,662 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) No suitable hosts found under this Cluster: 2
2025-02-03 23:19:00,662 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Could not find suitable Deployment Destination for this VM under any clusters, returning. 
2025-02-03 23:19:00,663 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Searching resources only under specified Cluster: 2
2025-02-03 23:19:00,663 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) The specified cluster is in avoid set, returning.
2025-02-03 23:19:00,663 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) VM start attempt #3
2025-02-03 23:19:00,663 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Trying to deploy VM [error decoding VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}] and details: Plan [error decoding {"_clusterId":null,"_dcId":2,"_physicalNetworkId":null,"_podId":2,"_poolId":null,"migrationPlan":false}]; avoid list [{"_podIds":[],"_clusterIds":[2],"_hostIds":[2]}] and planner: [].
2025-02-03 23:19:00,664 DEBUG [o.a.c.u.r.ReflectionToStringBuilderUtils] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Object is null, not reflecting it.
2025-02-03 23:19:00,664 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Trying to allocate a host and storage pools from datacenter [{"name":"uv-dell-2","uuid":"bf6f5332-ddfc-4793-95b9-c1696e1b48dc"}], pod [{"name":"pod2","uuid":"6b30cf43-a40b-43c6-bc30-dba58280cb16"}], cluster [null], to deploy VM [{"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}] with requested CPU [500] and requested RAM [(1.00 GB) 1073741824].
2025-02-03 23:19:00,664 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) ROOT volume [6eca55c4-4173-4d17-9163-d10cc67d72de] is not ready to deploy VM [9176a552-5253-423d-ac17-5d017511ce21].
2025-02-03 23:19:00,665 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Adding pods [] to the avoid set because these pods are in the Disabled state.
2025-02-03 23:19:00,665 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Adding clusters [] of pod [2] to the void set because these clusters are in the Disabled state.
2025-02-03 23:19:00,665 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Adding hosts [] of datacenter [bf6f5332-ddfc-4793-95b9-c1696e1b48dc] to the avoid set, because these hosts are in the Disabled state.
2025-02-03 23:19:00,666 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) DeploymentPlan [DataCenterDeployment] has not specified host. Trying to find another destination to deploy VM [9176a552-5253-423d-ac17-5d017511ce21], avoiding pods [], clusters [2] and hosts [2].
2025-02-03 23:19:00,666 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Deploy avoids pods: [], clusters: [2], hosts: [2].
2025-02-03 23:19:00,666 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Deploy hosts with priorities {}, hosts have NORMAL priority by default
2025-02-03 23:19:00,666 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Searching resources only under specified Pod: 2
2025-02-03 23:19:00,666 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Listing clusters in order of aggregate capacity, that have (at least one host with) enough CPU and RAM capacity under this Pod: 2
2025-02-03 23:19:00,668 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Removing from the clusterId list these clusters from avoid set: [2]
2025-02-03 23:19:00,668 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2025-02-03 23:19:00,672 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"} state transited from [Starting] to [Stopped] with event [OperationFailed]. VM's original host: null, new host: null, host before state transition: Host {"id":2,"name":"ultraviolet.local","type":"Routing","uuid":"86b3b883-4b15-4328-a3fe-56e41cd46ad3"}
2025-02-03 23:19:00,674 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Hosts's actual total CPU: 68256 and CPU after applying overprovisioning: 68256
2025-02-03 23:19:00,674 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Hosts's actual total RAM: (29.70 GB) 31891501056 and RAM after applying overprovisioning: (29.70 GB) 31891501056
2025-02-03 23:19:00,674 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) release cpu from host: 2, old used: 500,reserved: 0, actual total: 68256, total with overprovisioning: 68256; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2025-02-03 23:19:00,674 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) release mem from host: 2, old used: (1.00 GB) 1073741824,reserved: (0 bytes) 0, total: (29.70 GB) 31891501056; new used: (0 bytes) 0,reserved:(0 bytes) 0; movedfromreserved: false,moveToReserveredfalse
2025-02-03 23:19:00,675 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}Scope=interface com.cloud.dc.DataCenter; id=2
2025-02-03 23:19:00,675 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}Scope=interface com.cloud.dc.DataCenter; id=2
2025-02-03 23:19:00,675 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170]) (logid:795c34a4) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 659, job origin: 1024
2025-02-03 23:19:00,675 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170]) (logid:795c34a4) Unable to complete AsyncJobVO: {id:1170, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAACk3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 224948475209146, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Feb 03 23:18:54 UTC 2025, removed: null}, job origin: 1024 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}Scope=interface com.cloud.dc.DataCenter; id=2
	

2025-02-03 23:19:00,676 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170]) (logid:795c34a4) Complete async job-1170, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uVk1PcAAAABACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvblZNT3AAAAAVAgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACWVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNIGluc3RhbmNlIHsiaWQiOjY1OSwiaW5zdGFuY2VOYW1lIjoidi02NTktVk0iLCJ0eXBlIjoiQ29uc29sZVByb3h5IiwidXVpZCI6IjkxNzZhNTUyLTUyNTMtNDIzZC1hYzE3LTVkMDE3NTExY2UyMSJ9dXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAATc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAKTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AApMAAptb2R1bGVOYW1lcQB-AApMAA1tb2R1bGVWZXJzaW9ucQB-AAp4cAEAAATVdAADYXBwdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0cHBzcQB-ABEBAAAVW3EAfgATcQB-ABRxAH4AFXEAfgAWcHBzcQB-ABECAAAAZ3B0AC9qZGsuaW50ZXJuYWwucmVmbGVjdC5EaXJlY3RNZXRob2RIYW5kbGVBY2Nlc3NvcnQAH0RpcmVjdE1ldGhvZEhhbmRsZUFjY2Vzc29yLmphdmF0AAZpbnZva2V0AAlqYXZhLmJhc2V0AAYyMS4wLjVzcQB-ABECAAACRHB0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAbcQB-ABxxAH4AHXNxAH4AEQEAAABqcQB-ABN0ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JwcHNxAH4AEQEAABXXcQB-ABNxAH4AFHEAfgAVcQB-ACRwcHNxAH4AEQEAAABjcQB-ABN0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnBwc3EAfgARAQAAAoxxAH4AE3QAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHBwc3EAfgARAQAAADFxAH4AE3QAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVucHBzcQB-ABEBAAAAOHEAfgATdABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxscHBzcQB-ABEBAAAAZ3EAfgATdABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgA0dAAPY2FsbFdpdGhDb250ZXh0cHBzcQB-ABEBAAAANXEAfgATcQB-ADdxAH4ANHQADnJ1bldpdGhDb250ZXh0cHBzcQB-ABEBAAAALnEAfgATdAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ADBxAH4AMXBwc3EAfgARAQAAAlhxAH4AE3EAfgArcQB-ACxxAH4AMXBwc3EAfgARAgAAAjxwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ADVxAH4AHHEAfgAdc3EAfgARAgAAAT1wdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAxcQB-ABxxAH4AHXNxAH4AEQIAAAR4cHQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2VycQB-ABxxAH4AHXNxAH4AEQIAAAKCcHQALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ARnEAfgAxcQB-ABxxAH4AHXNxAH4AEQIAAAYvcHQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAxcQB-ABxxAH4AHXNyAB9qYXZhLnV0aWwuQ29sbGVjdGlvbnMkRW1wdHlMaXN0ergXtDynnt4CAAB4cHhzcgARamF2YS5sYW5nLkludGVnZXIS4qCk94GHOAIAAUkABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAQ73NyABNqYXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cQB-AFAAAAAAAAAAAnZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlchBQVG0DRR4AAgAAeHAA
2025-02-03 23:19:00,676 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170]) (logid:795c34a4) Publish async job-1170 complete on message bus
2025-02-03 23:19:00,676 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170]) (logid:795c34a4) Wake up jobs related to job-1170
2025-02-03 23:19:00,676 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170]) (logid:795c34a4) Update db status for job-1170
2025-02-03 23:19:00,676 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170]) (logid:795c34a4) Wake up jobs joined with job-1170 and disjoin all subjobs created from job- 1170
2025-02-03 23:19:00,679 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170]) (logid:795c34a4) Done executing com.cloud.vm.VmWorkStart for job-1170
2025-02-03 23:19:00,679 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170]) (logid:795c34a4) Remove job-1170 from job monitoring
2025-02-03 23:19:00,680 WARN  [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Unable to start proxy [659] due to [Unable to create a deployment for VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}]. com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}Scope=interface com.cloud.dc.DataCenter; id=2
	
2025-02-03 23:19:00,681 INFO  [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Unable to start console proxy vm for standby capacity, vm id : 659, will recycle it and start a new one
2025-02-03 23:19:00,683 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Sync job-1173 execution on object VmWorkJobQueue.659
2025-02-03 23:19:01,262 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-4:[]) (logid:) Ping from Routing host 2(ultraviolet.local)
2025-02-03 23:19:01,262 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-4:[]) (logid:) Process host VM state report from ping process. host: 2.
2025-02-03 23:19:01,262 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-4:[]) (logid:) Process VM state report. host: 2, number of records in report: 0.
2025-02-03 23:19:01,263 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-4:[]) (logid:) Done with process of VM state report. host: 2
2025-02-03 23:19:02,010 DEBUG [c.c.a.ApiServlet] (qtp1047478056-368:[ctx-c00ddb81]) (logid:43e5c4f0) ===START===  0:0:0:0:0:0:0:1 -- GET  command=readyForShutdown&response=json&sessionkey=0INeJHuBjMAMtV8_JkBzblVPNI0
2025-02-03 23:19:02,010 DEBUG [c.c.a.ApiServlet] (qtp1047478056-368:[ctx-c00ddb81]) (logid:43e5c4f0) Two factor authentication is already verified for the user 2, so skipping
2025-02-03 23:19:02,012 DEBUG [c.c.a.ApiServer] (qtp1047478056-368:[ctx-c00ddb81, ctx-62c60540]) (logid:43e5c4f0) CIDRs from which account 'Account [{"accountName":"admin","id":2,"uuid":"8c19107f-dfd2-11ef-bca6-cc96e5f525ba"}]' is allowed to perform API calls: 0.0.0.0/0,::/0
2025-02-03 23:19:02,013 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker] (qtp1047478056-368:[ctx-c00ddb81, ctx-62c60540]) (logid:43e5c4f0) RoleService is enabled. We will use it instead of StaticRoleBasedAPIAccessChecker.
2025-02-03 23:19:02,013 DEBUG [o.a.c.r.ApiRateLimitServiceImpl] (qtp1047478056-368:[ctx-c00ddb81, ctx-62c60540]) (logid:43e5c4f0) API rate limiting is disabled. We will not use ApiRateLimitService.
2025-02-03 23:19:02,014 INFO  [c.c.a.ApiServlet] (qtp1047478056-368:[ctx-c00ddb81, ctx-62c60540]) (logid:43e5c4f0) (userId=2 accountId=2 sessionId=node0xft6iuusa10qlorpsfpw2n3w0) 0:0:0:0:0:0:0:1 -- GET command=readyForShutdown&response=json&sessionkey=0INeJHuBjMAMtV8_JkBzblVPNI0 200 {"readyforshutdownresponse":{"readyforshutdown":{"readyforshutdown":true,"shutdowntriggered":false,"pendingjobscount":0}}}
2025-02-03 23:19:02,014 DEBUG [c.c.a.ApiServlet] (qtp1047478056-368:[ctx-c00ddb81, ctx-62c60540]) (logid:43e5c4f0) ===END===  0:0:0:0:0:0:0:1 -- GET  command=readyForShutdown&response=json&sessionkey=0INeJHuBjMAMtV8_JkBzblVPNI0
2025-02-03 23:19:02,489 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$6] (AsyncJobMgr-Heartbeat-1:[ctx-a781ef82]) (logid:b6fd3caa) Execute sync-queue item: SyncQueueItemVO {id:1127, queueId: 1124, contentType: AsyncJob, contentId: 1172, lastProcessMsid: 224948475209146, lastprocessNumber: 3, lastProcessTime: Mon Feb 03 23:19:02 UTC 2025, created: Mon Feb 03 23:19:00 UTC 2025}
2025-02-03 23:19:02,490 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:[ctx-a781ef82]) (logid:b6fd3caa) Schedule queued job-1172
2025-02-03 23:19:02,491 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$6] (AsyncJobMgr-Heartbeat-1:[ctx-a781ef82]) (logid:b6fd3caa) Execute sync-queue item: SyncQueueItemVO {id:1128, queueId: 1123, contentType: AsyncJob, contentId: 1173, lastProcessMsid: 224948475209146, lastprocessNumber: 3, lastProcessTime: Mon Feb 03 23:19:02 UTC 2025, created: Mon Feb 03 23:19:00 UTC 2025}
2025-02-03 23:19:02,491 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:[ctx-a781ef82]) (logid:b6fd3caa) Schedule queued job-1173
2025-02-03 23:19:02,491 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172]) (logid:f6f7f51b) Add job-1172 into job monitoring
2025-02-03 23:19:02,492 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173]) (logid:571890c8) Add job-1173 into job monitoring
2025-02-03 23:19:02,494 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172]) (logid:6d42f2b9) Executing AsyncJobVO: {id:1172, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo: rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAClHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 224948475209146, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Feb 03 23:19:00 UTC 2025, removed: null}
2025-02-03 23:19:02,494 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172]) (logid:6d42f2b9) Run VM work job: com.cloud.vm.VmWorkStop for VM 660, job origin: 1025
2025-02-03 23:19:02,494 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173]) (logid:795c34a4) Executing AsyncJobVO: {id:1173, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo: rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAACk3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 224948475209146, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Feb 03 23:19:00 UTC 2025, removed: null}
2025-02-03 23:19:02,494 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172, ctx-c4ff0b9f]) (logid:6d42f2b9) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":660,"handlerName":"VirtualMachineManagerImpl"}
2025-02-03 23:19:02,494 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173]) (logid:795c34a4) Run VM work job: com.cloud.vm.VmWorkStop for VM 659, job origin: 1024
2025-02-03 23:19:02,495 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173, ctx-61d48ae8]) (logid:795c34a4) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":659,"handlerName":"VirtualMachineManagerImpl"}
2025-02-03 23:19:02,495 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172, ctx-c4ff0b9f]) (logid:6d42f2b9) VM is already stopped: VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}
2025-02-03 23:19:02,495 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172, ctx-c4ff0b9f]) (logid:6d42f2b9) Done executing VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":660,"handlerName":"VirtualMachineManagerImpl"}
2025-02-03 23:19:02,495 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172, ctx-c4ff0b9f]) (logid:6d42f2b9) Complete async job-1172, jobStatus: SUCCEEDED, resultCode: 0, result: null
2025-02-03 23:19:02,495 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172, ctx-c4ff0b9f]) (logid:6d42f2b9) Publish async job-1172 complete on message bus
2025-02-03 23:19:02,495 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172, ctx-c4ff0b9f]) (logid:6d42f2b9) Wake up jobs related to job-1172
2025-02-03 23:19:02,495 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172, ctx-c4ff0b9f]) (logid:6d42f2b9) Update db status for job-1172
2025-02-03 23:19:02,495 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173, ctx-61d48ae8]) (logid:795c34a4) VM is already stopped: VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}
2025-02-03 23:19:02,495 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173, ctx-61d48ae8]) (logid:795c34a4) Done executing VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":659,"handlerName":"VirtualMachineManagerImpl"}
2025-02-03 23:19:02,495 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173, ctx-61d48ae8]) (logid:795c34a4) Complete async job-1173, jobStatus: SUCCEEDED, resultCode: 0, result: null
2025-02-03 23:19:02,496 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172, ctx-c4ff0b9f]) (logid:6d42f2b9) Wake up jobs joined with job-1172 and disjoin all subjobs created from job- 1172
2025-02-03 23:19:02,496 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173, ctx-61d48ae8]) (logid:795c34a4) Publish async job-1173 complete on message bus
2025-02-03 23:19:02,496 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173, ctx-61d48ae8]) (logid:795c34a4) Wake up jobs related to job-1173
2025-02-03 23:19:02,496 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173, ctx-61d48ae8]) (logid:795c34a4) Update db status for job-1173
2025-02-03 23:19:02,496 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173, ctx-61d48ae8]) (logid:795c34a4) Wake up jobs joined with job-1173 and disjoin all subjobs created from job- 1173
2025-02-03 23:19:02,498 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172]) (logid:6d42f2b9) Done with run of VM work job: com.cloud.vm.VmWorkStop for VM 660, job origin: 1025
2025-02-03 23:19:02,498 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172]) (logid:6d42f2b9) Done executing com.cloud.vm.VmWorkStop for job-1172
2025-02-03 23:19:02,498 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-147:[ctx-dfcaa17f, job-1025/job-1172]) (logid:6d42f2b9) Remove job-1172 from job monitoring
2025-02-03 23:19:02,499 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173]) (logid:795c34a4) Done with run of VM work job: com.cloud.vm.VmWorkStop for VM 659, job origin: 1024
2025-02-03 23:19:02,499 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173]) (logid:795c34a4) Done executing com.cloud.vm.VmWorkStop for job-1173
2025-02-03 23:19:02,499 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-148:[ctx-a4d8d11e, job-1024/job-1173]) (logid:795c34a4) Remove job-1173 from job monitoring
2025-02-03 23:19:02,502 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"} state transited from [Stopped] to [Expunging] with event [ExpungeOperation]. VM's original host: null, new host: null, host before state transition: null
2025-02-03 23:19:02,503 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"} state transited from [Stopped] to [Expunging] with event [ExpungeOperation]. VM's original host: null, new host: null, host before state transition: null
2025-02-03 23:19:02,503 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Expunging vm VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}
2025-02-03 23:19:02,503 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Cleaning up NICS [] of VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}.
2025-02-03 23:19:02,503 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Cleaning network for vm: 659
2025-02-03 23:19:02,504 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Expunging vm VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}
2025-02-03 23:19:02,504 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Cleaning up NICS [] of VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}.
2025-02-03 23:19:02,504 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Cleaning network for vm: 660
2025-02-03 23:19:02,505 DEBUG [c.c.n.g.PublicNetworkGuru] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) public network deallocate network: networkId: 204, ip: 172.16.10.11
2025-02-03 23:19:02,506 DEBUG [c.c.n.IpAddressManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) IP address [Ip[172.16.10.11-2]] is direct; therefore, the resource count should not be updated.
2025-02-03 23:19:02,506 DEBUG [c.c.n.g.PublicNetworkGuru] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) public network deallocate network: networkId: 204, ip: 172.16.10.12
2025-02-03 23:19:02,507 DEBUG [c.c.n.IpAddressManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) IP address [Ip[172.16.10.12-2]] is direct; therefore, the resource count should not be updated.
2025-02-03 23:19:02,507 DEBUG [c.c.n.g.PublicNetworkGuru] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Deallocated nic: NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":1123,"reservationId":null,"vmId":659}
2025-02-03 23:19:02,508 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Removed nic id=1123
2025-02-03 23:19:02,508 DEBUG [c.c.n.g.PublicNetworkGuru] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Deallocated nic: NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":1126,"reservationId":null,"vmId":660}
2025-02-03 23:19:02,508 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Revoving nic secondary ip entry ...
2025-02-03 23:19:02,509 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Removed nic id=1126
2025-02-03 23:19:02,509 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Revoving nic secondary ip entry ...
2025-02-03 23:19:02,510 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Removed nic id=1124
2025-02-03 23:19:02,510 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Revoving nic secondary ip entry ...
2025-02-03 23:19:02,511 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Removed nic id=1127
2025-02-03 23:19:02,511 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Revoving nic secondary ip entry ...
2025-02-03 23:19:02,512 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Removed nic id=1125
2025-02-03 23:19:02,513 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Revoving nic secondary ip entry ...
2025-02-03 23:19:02,513 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Cleaning up hypervisor data structures (ex. SRs in XenServer) for managed storage. Data from VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}.
2025-02-03 23:19:02,513 DEBUG [o.a.c.e.o.VolumeOrchestrator] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Cleaning storage for VM [null].
2025-02-03 23:19:02,514 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Removed nic id=1128
2025-02-03 23:19:02,514 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Revoving nic secondary ip entry ...
2025-02-03 23:19:02,514 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Cleaning up hypervisor data structures (ex. SRs in XenServer) for managed storage. Data from VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}.
2025-02-03 23:19:02,514 DEBUG [o.a.c.e.o.VolumeOrchestrator] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Cleaning storage for VM [null].
2025-02-03 23:19:02,519 WARN  [o.a.c.m.w.WebhookServiceImpl] (consoleproxy-1:[ctx-e304a582, ctx-3898cff9]) (logid:2d8931cd) Skipping delivering event [ID: null, description: {"details":"Volume Type: ROOT Volume Id: 6eca55c4-4173-4d17-9163-d10cc67d72de Vm Id: 9176a552-5253-423d-ac17-5d017511ce21","event":"VOLUME.DESTROY","status":"Completed"}] to any webhook as account ID is missing
2025-02-03 23:19:02,519 WARN  [o.a.c.f.e.EventDistributorImpl] (consoleproxy-1:[ctx-e304a582, ctx-3898cff9]) (logid:2d8931cd) Failed to publish event [category: ActionEvent, type: VOLUME.DESTROY] on bus webhookEventBus
2025-02-03 23:19:02,520 WARN  [o.a.c.m.w.WebhookServiceImpl] (secstorage-1:[ctx-ebc123fd, ctx-01996650]) (logid:8fc3b243) Skipping delivering event [ID: null, description: {"details":"Volume Type: ROOT Volume Id: 42ae9d0b-d015-4219-9399-6e30f42e8ec8 Vm Id: db9ad80f-05d6-4082-94c5-191ddbecfb33","event":"VOLUME.DESTROY","status":"Completed"}] to any webhook as account ID is missing
2025-02-03 23:19:02,520 WARN  [o.a.c.f.e.EventDistributorImpl] (secstorage-1:[ctx-ebc123fd, ctx-01996650]) (logid:8fc3b243) Failed to publish event [category: ActionEvent, type: VOLUME.DESTROY] on bus webhookEventBus
2025-02-03 23:19:02,530 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand
2025-02-03 23:19:02,531 DEBUG [c.c.h.XenServerGuru] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) We are returning the default host to execute commands because the command is not of Copy type.
2025-02-03 23:19:02,531 DEBUG [c.c.a.m.ClusteredAgentAttache] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Seq 2-3494511835862794591: Routed from 224948475209146
2025-02-03 23:19:02,531 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand
2025-02-03 23:19:02,531 DEBUG [c.c.h.XenServerGuru] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) We are returning the default host to execute commands because the command is not of Copy type.
2025-02-03 23:19:02,531 DEBUG [c.c.a.t.Request] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Seq 2-3494511835862794591: Sending  { Cmd , MgmtId: 224948475209146, via: 2(ultraviolet.local), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6eca55c4-4173-4d17-9163-d10cc67d72de","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"e46a7f5f-fd84-31dc-92dc-f6a77fda375a","name":"Primary2","id":"2","poolType":"NetworkFilesystem","host":"172.16.10.2","path":"/export/primary","port":"2049","url":"NetworkFilesystem://172.16.10.2/export/primary/?ROLE=Primary&STOREUUID=e46a7f5f-fd84-31dc-92dc-f6a77fda375a","isManaged":"false"}},"name":"ROOT-659","size":"(0 bytes) 0","path":"6eca55c4-4173-4d17-9163-d10cc67d72de","volumeId":"375","vmName":"v-659-VM","accountId":"1","format":"QCOW2","provisioningType":"THIN","poolId":"2","id":"375","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"wait":"0","bypassHostMaintenance":"true"}}] }
2025-02-03 23:19:02,532 DEBUG [c.c.a.m.ClusteredAgentAttache] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Seq 2-3494511835862794592: Routed from 224948475209146
2025-02-03 23:19:02,532 DEBUG [c.c.a.t.Request] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Seq 2-3494511835862794592: Sending  { Cmd , MgmtId: 224948475209146, via: 2(ultraviolet.local), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"42ae9d0b-d015-4219-9399-6e30f42e8ec8","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"e46a7f5f-fd84-31dc-92dc-f6a77fda375a","name":"Primary2","id":"2","poolType":"NetworkFilesystem","host":"172.16.10.2","path":"/export/primary","port":"2049","url":"NetworkFilesystem://172.16.10.2/export/primary/?ROLE=Primary&STOREUUID=e46a7f5f-fd84-31dc-92dc-f6a77fda375a","isManaged":"false"}},"name":"ROOT-660","size":"(0 bytes) 0","path":"42ae9d0b-d015-4219-9399-6e30f42e8ec8","volumeId":"376","vmName":"s-660-VM","accountId":"1","format":"QCOW2","provisioningType":"THIN","poolId":"2","id":"376","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"wait":"0","bypassHostMaintenance":"true"}}] }
2025-02-03 23:19:02,603 DEBUG [c.c.a.t.Request] (AgentManager-Handler-6:[]) (logid:) Seq 2-3494511835862794592: Processing:  { Ans: , MgmtId: 224948475209146, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-02-03 23:19:02,603 DEBUG [c.c.a.t.Request] (AgentManager-Handler-5:[]) (logid:) Seq 2-3494511835862794591: Processing:  { Ans: , MgmtId: 224948475209146, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-02-03 23:19:02,603 DEBUG [c.c.a.t.Request] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Seq 2-3494511835862794592: Received:  { Ans: , MgmtId: 224948475209146, via: 2(ultraviolet.local), Ver: v1, Flags: 10, { Answer } }
2025-02-03 23:19:02,603 DEBUG [c.c.a.t.Request] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Seq 2-3494511835862794591: Received:  { Ans: , MgmtId: 224948475209146, via: 2(ultraviolet.local), Ver: v1, Flags: 10, { Answer } }
2025-02-03 23:19:02,606 INFO  [o.a.c.s.v.VolumeServiceImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Volume 376 is not referred anywhere, remove it from volumes table
2025-02-03 23:19:02,606 DEBUG [c.c.s.d.VolumeDaoImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Removing volume 376 from DB
2025-02-03 23:19:02,606 INFO  [o.a.c.s.v.VolumeServiceImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Volume 375 is not referred anywhere, remove it from volumes table
2025-02-03 23:19:02,606 DEBUG [c.c.s.d.VolumeDaoImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Removing volume 375 from DB
2025-02-03 23:19:02,609 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Expunged VM instance {"id":660,"instanceName":"s-660-VM","type":"SecondaryStorageVm","uuid":"db9ad80f-05d6-4082-94c5-191ddbecfb33"}
2025-02-03 23:19:02,609 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Expunged VM instance {"id":659,"instanceName":"v-659-VM","type":"ConsoleProxy","uuid":"9176a552-5253-423d-ac17-5d017511ce21"}
2025-02-03 23:19:02,610 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) received secondary storage vm alert
2025-02-03 23:19:02,611 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Secondary Storage Vm creation failure in zone [uv-dell-2].
2025-02-03 23:19:02,611 DEBUG [c.c.a.ConsoleProxyAlertAdapter] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) received console proxy alert
2025-02-03 23:19:02,611 DEBUG [c.c.a.ConsoleProxyAlertAdapter] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) Console proxy creation failure. Zone [uv-dell-2].
2025-02-03 23:19:02,611 WARN  [c.c.a.AlertManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) alertType=[19] dataCenterId=[2] podId=[null] clusterId=[null] message=[Secondary Storage Vm creation failure in zone [uv-dell-2]. Error details: null].
2025-02-03 23:19:02,612 WARN  [c.c.a.AlertManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) alertType=[10] dataCenterId=[2] podId=[null] clusterId=[null] message=[Console proxy creation failure. Zone [uv-dell-2]. Error details: null].
2025-02-03 23:19:02,613 WARN  [c.c.a.AlertManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) No recipients set in global setting 'alert.email.addresses', skipping sending alert with subject [Secondary Storage Vm creation failure in zone [uv-dell-2]. Error details: null] and content [Secondary Storage Vm creation failure (zone uv-dell-2)].
2025-02-03 23:19:02,613 INFO  [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:[ctx-ebc123fd]) (logid:8fc3b243) Primary secondary storage is not even started, wait until next turn
2025-02-03 23:19:02,613 WARN  [c.c.a.AlertManagerImpl] (consoleproxy-1:[ctx-e304a582]) (logid:2d8931cd) No recipients set in global setting 'alert.email.addresses', skipping sending alert with subject [Console proxy creation failure. Zone [uv-dell-2]. Error details: null] and content [Console proxy creation failure (zone uv-dell-2)].

[Pearl1594]

@SammyOina it seems that the systemVMs aren't able to find a suitable host, based on these logs:

2025-02-03 23:19:00,662 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) No suitable hosts found.
2025-02-03 23:19:00,662 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) No suitable hosts found under this Cluster: 2
2025-02-03 23:19:00,662 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Could not find suitable Deployment Destination for this VM under any clusters, returning. 
2025-02-03 23:19:00,663 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) Searching resources only under specified Cluster: 2
2025-02-03 23:19:00,663 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-145:[ctx-41bfec57, job-1024/job-1170, ctx-d4c64b32]) (logid:795c34a4) The specified cluster is in avoid set, returning.

You'd probably need to check why is the host/cluster in the avoid set.

[SammyOina]

As far as I can tell the host should be healthy not be on avoid set since it is a brand new installation. Is there any reason it would be on avoid set.? How can I check or fix this?

Same with the cluster it seems to be ok

[weizhouapache]

@SammyOina
can you upload the logs of another system vm ?

[SammyOina]

@SammyOina can you upload the logs of another system vm ?

Both system vms keep starting and stopping soon after. Not sure I can get logs from them