Replies: 7 comments 2 replies
-
|
Thanks for opening your first issue here! Be sure to follow the issue template! |
Beta Was this translation helpful? Give feedback.
0 replies
-
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":"[email protected]","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)]. |
Beta Was this translation helpful? Give feedback.
0 replies
-
|
@SammyOina it seems that the systemVMs aren't able to find a suitable host, based on these logs: You'd probably need to check why is the host/cluster in the avoid set. |
Beta Was this translation helpful? Give feedback.
0 replies
-
|
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 |
Beta Was this translation helpful? Give feedback.
0 replies
-
|
@SammyOina |
Beta Was this translation helpful? Give feedback.
0 replies
-
Both system vms keep starting and stopping soon after. Not sure I can get logs from them |
Beta Was this translation helpful? Give feedback.
1 reply
-
|
@SammyOina I think @weizhouapache means you need to re-upload management server logs for the latest failures. Last logs indicated cluster was in disabled state. Maybe it was some other disabled cluster in your environment. |
Beta Was this translation helpful? Give feedback.
-
|
Have same problem |
Beta Was this translation helpful? Give feedback.
1 reply
-
|
@UAnton Check logs where an exception was seen for the latest system vm. It must be having log line like the following at the start of the flow,
|
Beta Was this translation helpful? Give feedback.
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
-
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
What to do about it?
Please help me figure out the failure reason; this is my first CloudStack installation
Beta Was this translation helpful? Give feedback.
All reactions