vm creation from backups #14015

arpanbht · 2026-08-31T11:12:38Z

arpanbht
Aug 31, 2026

I am facing an issue while trying to create a new VM from an existing backup in Apache CloudStack.

The backup is available on both NAS storage locations, and I have verified that the corresponding QCOW2 backup file exists physically on the NAS. However, when I attempt to create a VM from the backup through CloudStack, the operation fails.

The Management Server reports that the backup file for the volume does not exist, even though the QCOW2 backup file is present on the backup storage.

Here is the error log

2026-08-31 11:05:58,681 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-49:[ctx-3b9138ee, job-58083, ctx-1245a0d5]) (logid:5076d060) Successfully cleaned up Instance 1211 after create Instance from backup failed
2026-08-31 11:05:58,681 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-49:[ctx-3b9138ee, job-58083]) (logid:5076d060) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.CreateVMFromBackupCmdByAdmin com.cloud.utils.exception.CloudRuntimeException: Failed to create Instance [i-2-1211-VM] from backup [{"externalId":"i-2-1185-VM\/2026.08.31.06.56.07","name":"r3","uuid":"26295893-2f9e-4256-9ddd-a7099cebd291"}] due to: Backup file for the volume [86636972-a7a4-422d-8f31-b3c932850659] does not exist..
        at org.apache.cloudstack.backup.BackupManagerImpl.restoreBackupToVM(BackupManagerImpl.java:1408)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:569)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
        at jdk.proxy3/jdk.proxy3.$Proxy296.restoreBackupToVM(Unknown Source)
        at com.cloud.vm.UserVmManagerImpl.restoreVMFromBackup(UserVmManagerImpl.java:9826)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:569)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
        at jdk.proxy3/jdk.proxy3.$Proxy202.restoreVMFromBackup(Unknown Source)
        at org.apache.cloudstack.api.command.user.vm.CreateVMFromBackupCmd.execute(CreateVMFromBackupCmd.java:124)
        at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:173)
        at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:110)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:686)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:634)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:840)

Here is the output where the file exists

This is for zone 1

zone-1-nfs@zone-1-nfs:~$ find /volume1/cloudstack-backups/ -iname '*86636972-a7a4-422d-8f31-b3c932850659*'
/volume1/cloudstack-backups/i-2-1185-VM/2026.08.28.06.46.00/.root.86636972-a7a4-422d-8f31-b3c932850659.qcow2.l0hA0y
/volume1/cloudstack-backups/i-2-1185-VM/2026.08.28.06.46.00/root.86636972-a7a4-422d-8f31-b3c932850659.qcow2
/volume1/cloudstack-backups/i-2-1185-VM/2026.08.31.06.29.48/root.86636972-a7a4-422d-8f31-b3c932850659.qcow2
/volume1/cloudstack-backups/i-2-1185-VM/2026.08.31.06.56.07/.root.86636972-a7a4-422d-8f31-b3c932850659.qcow2.eyUkiV
/volume1/cloudstack-backups/i-2-1185-VM/2026.08.31.06.56.07/root.86636972-a7a4-422d-8f31-b3c932850659.qcow2

This is for zone 2

zone-2-nfs@nasdr:~$ sudo find /volume1/cloudstack-backups/ -iname '*86636972-a7a4-422d-8f31-b3c932850659*'
Password:
/volume1/cloudstack-backups/i-2-1185-VM/2026.08.31.06.56.07/root.86636972-a7a4-422d-8f31-b3c932850659.qcow2

Answered by abh1sar

Sep 1, 2026

The address of both reposothas to be same. See https://youtu.be/UTSVDCZyUHY?si=bBs__N2PsgB7WJOv

View full answer

DaanHoogland · 2026-09-01T07:22:02Z

DaanHoogland
Sep 1, 2026
Collaborator

@arpanbht , the creation of the instance failed and this is as you demonstrate not because the file is not found. You will have to dig deeper into the log to find the first error related to the job job-58083.

1 reply

arpanbht Sep 1, 2026
Author

@DaanHoogland

I can see only one error when I use the grep command to find the job and I have tested with a new job now and the same error log came from the above error block

312043:2026-09-01 07:52:37,924 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:a72be2e0) Add job-58105 into job monitoring
312044:2026-09-01 07:52:37,929 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp1438988851-5552:[ctx-792075cc, ctx-653f4d36]) (logid:4289a16e) submit async job-58105, details: AsyncJob {"accountId":2,"cmd":"org.apache.cloudstack.api.command.admin.vm.CreateVMFromBackupCmdByAdmin","cmdInfo":"{\"iptonetworklist[0].networkid\":\"5c7f439d-4a2f-4470-8e80-7883e1a61afe\",\"sessionkey\":\"c64Lrh5776du3uCUxZeFUkyUGwQ\",\"hostid\":\"54056d1f-2ba5-4361-950d-63490eae20ba\",\"httpmethod\":\"POST\",\"ctxAccountId\":\"2\",\"uuid\":\"3783a71c-020e-46e7-8438-246c216e0871\",\"domainid\":\"c3b6cbbf-000d-11f1-a20d-94f128ae62ac\",\"cmdEventType\":\"VM.CREATE\",\"bootmode\":\"LEGACY\",\"iothreadsenabled\":\"false\",\"rootdisksize\":\"5\",\"ctxStartEventId\":\"1237438\",\"id\":\"1213\",\"overridediskofferingid\":\"97ec5e72-00c2-4a5e-a4c1-08efc0f325ad\",\"ctxDetails\":\"{\\\"interface org.apache.cloudstack.backup.Backup\\\":\\\"26295893-2f9e-4256-9ddd-a7099cebd291\\\",\\\"interface com.cloud.dc.DataCenter\\\":\\\"fefa5625-f83a-41dd-9004-bb3bb2f96307\\\",\\\"interface com.cloud.dc.Pod\\\":\\\"c207e7a2-044b-4509-b3c8-6dec83b641f3\\\",\\\"interface com.cloud.host.Host\\\":\\\"54056d1f-2ba5-4361-950d-63490eae20ba\\\",\\\"interface com.cloud.offering.DiskOffering\\\":\\\"97ec5e72-00c2-4a5e-a4c1-08efc0f325ad\\\",\\\"interface com.cloud.offering.ServiceOffering\\\":\\\"dd2c2284-22e5-4e8a-83ba-c5de3f632c74\\\",\\\"interface com.cloud.domain.Domain\\\":\\\"c3b6cbbf-000d-11f1-a20d-94f128ae62ac\\\",\\\"interface com.cloud.template.VirtualMachineTemplate\\\":\\\"da5d9cd2-cec7-4519-92e1-1f8e80344188\\\",\\\"interface com.cloud.org.Cluster\\\":\\\"ba7c3ced-1cad-4d86-b868-4163d5fba7dd\\\",\\\"interface com.cloud.vm.VirtualMachine\\\":\\\"3783a71c-020e-46e7-8438-246c216e0871\\\"}\",\"dynamicscalingenabled\":\"true\",\"keypairs\":\"GLOBAL-SSH-KEYPAIR,backend-key-pair,test-autoscale-key-new,test-lb-ssh-keypair\",\"boottype\":\"BIOS\",\"backupid\":\"26295893-2f9e-4256-9ddd-a7099cebd291\",\"clusterid\":\"ba7c3ced-1cad-4d86-b868-4163d5fba7dd\",\"templateid\":\"da5d9cd2-cec7-4519-92e1-1f8e80344188\",\"startvm\":\"true\",\"serviceofferingid\":\"dd2c2284-22e5-4e8a-83ba-c5de3f632c74\",\"response\":\"json\",\"ctxUserId\":\"2\",\"zoneid\":\"fefa5625-f83a-41dd-9004-bb3bb2f96307\",\"podid\":\"c207e7a2-044b-4509-b3c8-6dec83b641f3\",\"account\":\"admin\",\"affinitygroupids\":\"\"}","cmdVersion":0,"completeMsid":null,"created":null,"id":58105,"initMsid":163763490546348,"instanceId":1213,"instanceType":"VirtualMachine","lastPolled":null,"lastUpdated":null,"processStatus":0,"removed":null,"result":null,"resultCode":0,"status":"IN_PROGRESS","userId":2,"uuid":"f2258f45-4584-46aa-823e-548ca865b558"}
312069:2026-09-01 07:52:37,937 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:f2258f45) Executing AsyncJob {"accountId":2,"cmd":"org.apache.cloudstack.api.command.admin.vm.CreateVMFromBackupCmdByAdmin","cmdInfo":"{\"iptonetworklist[0].networkid\":\"5c7f439d-4a2f-4470-8e80-7883e1a61afe\",\"sessionkey\":\"c64Lrh5776du3uCUxZeFUkyUGwQ\",\"hostid\":\"54056d1f-2ba5-4361-950d-63490eae20ba\",\"httpmethod\":\"POST\",\"ctxAccountId\":\"2\",\"uuid\":\"3783a71c-020e-46e7-8438-246c216e0871\",\"domainid\":\"c3b6cbbf-000d-11f1-a20d-94f128ae62ac\",\"cmdEventType\":\"VM.CREATE\",\"bootmode\":\"LEGACY\",\"iothreadsenabled\":\"false\",\"rootdisksize\":\"5\",\"ctxStartEventId\":\"1237438\",\"id\":\"1213\",\"overridediskofferingid\":\"97ec5e72-00c2-4a5e-a4c1-08efc0f325ad\",\"ctxDetails\":\"{\\\"interface org.apache.cloudstack.backup.Backup\\\":\\\"26295893-2f9e-4256-9ddd-a7099cebd291\\\",\\\"interface com.cloud.dc.DataCenter\\\":\\\"fefa5625-f83a-41dd-9004-bb3bb2f96307\\\",\\\"interface com.cloud.dc.Pod\\\":\\\"c207e7a2-044b-4509-b3c8-6dec83b641f3\\\",\\\"interface com.cloud.host.Host\\\":\\\"54056d1f-2ba5-4361-950d-63490eae20ba\\\",\\\"interface com.cloud.offering.DiskOffering\\\":\\\"97ec5e72-00c2-4a5e-a4c1-08efc0f325ad\\\",\\\"interface com.cloud.offering.ServiceOffering\\\":\\\"dd2c2284-22e5-4e8a-83ba-c5de3f632c74\\\",\\\"interface com.cloud.domain.Domain\\\":\\\"c3b6cbbf-000d-11f1-a20d-94f128ae62ac\\\",\\\"interface com.cloud.template.VirtualMachineTemplate\\\":\\\"da5d9cd2-cec7-4519-92e1-1f8e80344188\\\",\\\"interface com.cloud.org.Cluster\\\":\\\"ba7c3ced-1cad-4d86-b868-4163d5fba7dd\\\",\\\"interface com.cloud.vm.VirtualMachine\\\":\\\"3783a71c-020e-46e7-8438-246c216e0871\\\"}\",\"dynamicscalingenabled\":\"true\",\"keypairs\":\"GLOBAL-SSH-KEYPAIR,backend-key-pair,test-autoscale-key-new,test-lb-ssh-keypair\",\"boottype\":\"BIOS\",\"backupid\":\"26295893-2f9e-4256-9ddd-a7099cebd291\",\"clusterid\":\"ba7c3ced-1cad-4d86-b868-4163d5fba7dd\",\"templateid\":\"da5d9cd2-cec7-4519-92e1-1f8e80344188\",\"startvm\":\"true\",\"serviceofferingid\":\"dd2c2284-22e5-4e8a-83ba-c5de3f632c74\",\"response\":\"json\",\"ctxUserId\":\"2\",\"zoneid\":\"fefa5625-f83a-41dd-9004-bb3bb2f96307\",\"podid\":\"c207e7a2-044b-4509-b3c8-6dec83b641f3\",\"account\":\"admin\",\"affinitygroupids\":\"\"}","cmdVersion":0,"completeMsid":null,"created":null,"id":58105,"initMsid":163763490546348,"instanceId":1213,"instanceType":"VirtualMachine","lastPolled":null,"lastUpdated":null,"processStatus":0,"removed":null,"result":null,"resultCode":0,"status":"IN_PROGRESS","userId":2,"uuid":"f2258f45-4584-46aa-823e-548ca865b558"}
312073:2026-09-01 07:52:37,947 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Account [Account [{"accountName":"admin","id":2,"uuid":"143efd0a-000e-11f1-a20d-94f128ae62ac"}]] has access to resource.
312075:2026-09-01 07:52:37,947 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Account [Account [{"accountName":"admin","id":2,"uuid":"143efd0a-000e-11f1-a20d-94f128ae62ac"}]] has access to resource.
312078:2026-09-01 07:52:37,947 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Account [Account [{"accountName":"admin","id":2,"uuid":"143efd0a-000e-11f1-a20d-94f128ae62ac"}]] has access to resource.
312079:2026-09-01 07:52:37,953 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Service SecurityGroup is not supported in the network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312080:2026-09-01 07:52:37,954 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Service SecurityGroup is not supported in the network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312081:2026-09-01 07:52:37,955 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Setting VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}] password to a randomly generated password.
312083:2026-09-01 07:52:37,961 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Trying to deploy VM [error decoding VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}] and details: Plan [{"_dcId":3,"_recreateDisks":false,"preferredHostIds":[],"migrationPlan":false,"hostPriorities":{}}]; avoid list [{}] and planner: [null].
312084:2026-09-01 07:52:37,962 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Checking non dedicated resources to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312085:2026-09-01 07:52:37,965 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Adding pods [[]], clusters [[]] and hosts [[]] to the avoid list in the deploy process of user VM [error decoding VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}], because this VM is not explicitly dedicated to these components.
312086:2026-09-01 07:52:37,965 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Trying to allocate a host and storage pools from datacenter [Zone {"id": "3", "name": "IEM_Compute_Zone_1", "uuid": "fefa5625-f83a-41dd-9004-bb3bb2f96307"}], pod [null], cluster [null], to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}] with requested CPU [3000] and requested RAM [(2.01 GB) 2155872256].
312087:2026-09-01 07:52:37,965 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) ROOT volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] is not ready to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312088:2026-09-01 07:52:37,966 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Adding pods [] to the avoid set because these pods are in the Disabled state.
312089:2026-09-01 07:52:37,967 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Adding clusters [] of pod [3] to the void set because these clusters are in the Disabled state.
312090:2026-09-01 07:52:37,967 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Adding hosts [] of datacenter [fefa5625-f83a-41dd-9004-bb3bb2f96307] to the avoid set, because these hosts are in the Disabled state.
312091:2026-09-01 07:52:37,968 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) DeploymentPlan [DataCenterDeployment] has not specified host. Trying to find another destination to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}], avoiding pods [], clusters [] and hosts [].
312092:2026-09-01 07:52:37,968 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Deploy avoids pods: [], clusters: [], hosts: [].
312093:2026-09-01 07:52:37,968 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Deploy hosts with priorities {}, hosts have NORMAL priority by default
312094:2026-09-01 07:52:37,969 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Searching all possible resources under this Zone: Zone {"id": "3", "name": "IEM_Compute_Zone_1", "uuid": "fefa5625-f83a-41dd-9004-bb3bb2f96307"}
312095:2026-09-01 07:52:37,969 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Listing clusters in order of aggregate capacity, that have (at least one host with) enough CPU and RAM capacity under this Zone: 3
312096:2026-09-01 07:52:37,970 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) CapacityType: CPU is used for Cluster ordering
312097:2026-09-01 07:52:37,971 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Removing from the clusterId list these clusters from avoid set: []
312098:2026-09-01 07:52:37,975 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Checking resources in Cluster: Cluster {id: "3", name: "IEM_Compute_Cluster_1", uuid: "ba7c3ced-1cad-4d86-b868-4163d5fba7dd"} under Pod: HostPod {"id":3,"name":"IEM_Compute_Pod_1","uuid":"c207e7a2-044b-4509-b3c8-6dec83b641f3"}
312099:2026-09-01 07:52:37,976 INFO  [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45)  Guest VM is requested with Custom[UEFI] Boot Type false
312100:2026-09-01 07:52:37,976 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Looking for hosts in zone [3], pod [3], cluster [3]
312101:2026-09-01 07:52:37,978 INFO  [o.a.c.u.r.ReflectionToStringBuilderUtils] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Collection [[]] is empty or has only null values, not reflecting it.
312102:2026-09-01 07:52:37,978 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Adding hosts [null] to the avoid set because these hosts do not support HA.
312103:2026-09-01 07:52:37,978 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) FirstFitAllocator has 3 hosts to check for allocation: [Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, Host {"id":5,"name":"compute1","type":"Routing","uuid":"54056d1f-2ba5-4361-950d-63490eae20ba"}, Host {"id":10,"name":"compute4","type":"Routing","uuid":"6a821625-2e36-4f69-b4b3-5d35cd017d73"}]
312104:2026-09-01 07:52:37,980 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Found 3 hosts for allocation after prioritization: [Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, Host {"id":10,"name":"compute4","type":"Routing","uuid":"6a821625-2e36-4f69-b4b3-5d35cd017d73"}, Host {"id":5,"name":"compute1","type":"Routing","uuid":"54056d1f-2ba5-4361-950d-63490eae20ba"}]
312105:2026-09-01 07:52:37,980 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Looking for speed=3000Mhz, Ram=2056 MB
312106:2026-09-01 07:52:37,980 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host {id: 45, name: compute-3, uuid: aa3ac602-03cd-4df7-bda2-8faa264bd9db} is KVM hypervisor type, no max guest limit check needed
312107:2026-09-01 07:52:37,980 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host [Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}] has required GPU devices available.
312108:2026-09-01 07:52:37,981 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} has cpu capability (cpu: 24, speed: 2100 ) to support requested CPU: 2 and requested speed: 1500
312109:2026-09-01 07:52:37,981 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Checking if host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} has enough capacity for requested CPU: 3000 and requested RAM: (2.01 GB) 2155872256 , cpuOverprovisioningFactor: 5.0
312110:2026-09-01 07:52:37,982 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Hosts's actual total CPU: 50400 and CPU after applying overprovisioning: 252000
312111:2026-09-01 07:52:37,982 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Free CPU: 113200 , Requested CPU: 3000
312112:2026-09-01 07:52:37,982 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Free RAM: (15.39 GB) 16528850944 , Requested RAM: (2.01 GB) 2155872256
312113:2026-09-01 07:52:37,982 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host has enough CPU and RAM available
312114:2026-09-01 07:52:37,982 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) STATS: Can alloc CPU from host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, used: 138800, reserved: 0, actual total: 50400, total with overprovisioning: 252000; requested cpu: 3000, alloc_from_last_host?: false, considerReservedCapacity?: true
312115:2026-09-01 07:52:37,982 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) STATS: Can alloc MEM from host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, used: (109.09 GB) 117138522112, reserved: (0 bytes) 0, total: (124.49 GB) 133667373056; requested mem: (2.01 GB) 2155872256, alloc_from_last_host?: false, considerReservedCapacity?: true
312116:2026-09-01 07:52:37,982 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Found a suitable host, adding to list: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}
312117:2026-09-01 07:52:37,982 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host {id: 10, name: compute4, uuid: 6a821625-2e36-4f69-b4b3-5d35cd017d73} is KVM hypervisor type, no max guest limit check needed
312118:2026-09-01 07:52:37,982 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host [Host {"id":10,"name":"compute4","type":"Routing","uuid":"6a821625-2e36-4f69-b4b3-5d35cd017d73"}] has required GPU devices available.
312119:2026-09-01 07:52:37,983 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host {"id":10,"name":"compute4","type":"Routing","uuid":"6a821625-2e36-4f69-b4b3-5d35cd017d73"} has cpu capability (cpu: 256, speed: 2450 ) to support requested CPU: 2 and requested speed: 1500
312120:2026-09-01 07:52:37,983 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Checking if host: Host {"id":10,"name":"compute4","type":"Routing","uuid":"6a821625-2e36-4f69-b4b3-5d35cd017d73"} has enough capacity for requested CPU: 3000 and requested RAM: (2.01 GB) 2155872256 , cpuOverprovisioningFactor: 5.0
312121:2026-09-01 07:52:37,983 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Hosts's actual total CPU: 627200 and CPU after applying overprovisioning: 3136000
312122:2026-09-01 07:52:37,983 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Free CPU: 2589500 , Requested CPU: 3000
312123:2026-09-01 07:52:37,983 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Free RAM: (20.49 GB) 22000173056 , Requested RAM: (2.01 GB) 2155872256
312124:2026-09-01 07:52:37,983 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host has enough CPU and RAM available
312125:2026-09-01 07:52:37,983 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) STATS: Can alloc CPU from host: Host {"id":10,"name":"compute4","type":"Routing","uuid":"6a821625-2e36-4f69-b4b3-5d35cd017d73"}, used: 546500, reserved: 0, actual total: 627200, total with overprovisioning: 3136000; requested cpu: 3000, alloc_from_last_host?: false, considerReservedCapacity?: true
312126:2026-09-01 07:52:37,983 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) STATS: Can alloc MEM from host: Host {"id":10,"name":"compute4","type":"Routing","uuid":"6a821625-2e36-4f69-b4b3-5d35cd017d73"}, used: (482.07 GB) 517614862336, reserved: (0 bytes) 0, total: (502.56 GB) 539615035392; requested mem: (2.01 GB) 2155872256, alloc_from_last_host?: false, considerReservedCapacity?: true
312127:2026-09-01 07:52:37,984 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Found a suitable host, adding to list: Host {"id":10,"name":"compute4","type":"Routing","uuid":"6a821625-2e36-4f69-b4b3-5d35cd017d73"}
312128:2026-09-01 07:52:37,984 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host {id: 5, name: compute1, uuid: 54056d1f-2ba5-4361-950d-63490eae20ba} is KVM hypervisor type, no max guest limit check needed
312129:2026-09-01 07:52:37,984 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host [Host {"id":5,"name":"compute1","type":"Routing","uuid":"54056d1f-2ba5-4361-950d-63490eae20ba"}] has required GPU devices available.
312130:2026-09-01 07:52:37,984 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host {"id":5,"name":"compute1","type":"Routing","uuid":"54056d1f-2ba5-4361-950d-63490eae20ba"} has cpu capability (cpu: 24, speed: 2100 ) to support requested CPU: 2 and requested speed: 1500
312131:2026-09-01 07:52:37,985 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Checking if host: Host {"id":5,"name":"compute1","type":"Routing","uuid":"54056d1f-2ba5-4361-950d-63490eae20ba"} has enough capacity for requested CPU: 3000 and requested RAM: (2.01 GB) 2155872256 , cpuOverprovisioningFactor: 5.0
312132:2026-09-01 07:52:37,985 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Hosts's actual total CPU: 50400 and CPU after applying overprovisioning: 252000
312133:2026-09-01 07:52:37,985 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Free CPU: 84200 , Requested CPU: 3000
312134:2026-09-01 07:52:37,985 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Free RAM: (340.91 GB) 366052540416 , Requested RAM: (2.01 GB) 2155872256
312135:2026-09-01 07:52:37,985 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host has enough CPU and RAM available
312136:2026-09-01 07:52:37,985 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) STATS: Can alloc CPU from host: Host {"id":5,"name":"compute1","type":"Routing","uuid":"54056d1f-2ba5-4361-950d-63490eae20ba"}, used: 167800, reserved: 0, actual total: 50400, total with overprovisioning: 252000; requested cpu: 3000, alloc_from_last_host?: false, considerReservedCapacity?: true
312137:2026-09-01 07:52:37,985 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) STATS: Can alloc MEM from host: Host {"id":5,"name":"compute1","type":"Routing","uuid":"54056d1f-2ba5-4361-950d-63490eae20ba"}, used: (161.48 GB) 173388333056, reserved: (0 bytes) 0, total: (502.39 GB) 539440873472; requested mem: (2.01 GB) 2155872256, alloc_from_last_host?: false, considerReservedCapacity?: true
312138:2026-09-01 07:52:37,985 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Found a suitable host, adding to list: Host {"id":5,"name":"compute1","type":"Routing","uuid":"54056d1f-2ba5-4361-950d-63490eae20ba"}
312139:2026-09-01 07:52:37,985 DEBUG [c.c.a.m.a.i.FirstFitRoutingAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, FirstFitRoutingAllocator]) (logid:f2258f45) Host Allocator returning 3 suitable hosts
312140:2026-09-01 07:52:37,985 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Re-ordering hosts [Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, Host {"id":10,"name":"compute4","type":"Routing","uuid":"6a821625-2e36-4f69-b4b3-5d35cd017d73"}, Host {"id":5,"name":"compute1","type":"Routing","uuid":"54056d1f-2ba5-4361-950d-63490eae20ba"}] by priorities {}
312141:2026-09-01 07:52:37,986 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Hosts after re-ordering are: [Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, Host {"id":10,"name":"compute4","type":"Routing","uuid":"6a821625-2e36-4f69-b4b3-5d35cd017d73"}, Host {"id":5,"name":"compute1","type":"Routing","uuid":"54056d1f-2ba5-4361-950d-63490eae20ba"}]
312142:2026-09-01 07:52:37,987 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Checking suitable pools for volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}, ROOT] of VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312143:2026-09-01 07:52:37,988 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Calling StoragePoolAllocators to find suitable pools to allocate volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312144:2026-09-01 07:52:37,988 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Trying to find suitable pools to allocate volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}], using StoragePoolAllocator: [LocalStoragePoolAllocator].
312145:2026-09-01 07:52:37,988 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) LocalStoragePoolAllocator is returning null since the disk profile does not use local storage and bypassStorageTypeCheck is false.
312146:2026-09-01 07:52:37,988 INFO  [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) There are no pools to reorder.
312147:2026-09-01 07:52:37,989 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Trying to find suitable pools to allocate volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}], using StoragePoolAllocator: [ClusterScopeStoragePoolAllocator].
312148:2026-09-01 07:52:37,989 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Looking for pools in dc [3], pod [3] and cluster [3]. Disabled pools will be ignored.
312149:2026-09-01 07:52:37,990 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Found pools [[]] that match with tags [[]].
312150:2026-09-01 07:52:37,991 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) No storage pools available for [shared] volume allocation.
312151:2026-09-01 07:52:37,991 INFO  [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Reordering [0] pools
312152:2026-09-01 07:52:37,991 INFO  [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Using volume allocation algorithm random to reorder pools.
312153:2026-09-01 07:52:37,991 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Pools to shuffle: [[]]
312154:2026-09-01 07:52:37,991 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Shuffled list of pools to choose from: [[]]
312155:2026-09-01 07:52:37,991 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Trying to find suitable pools to allocate volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}], using StoragePoolAllocator: [ZoneWideStoragePoolAllocator].
312156:2026-09-01 07:52:37,994 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Checking if storage pool [StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}] is suitable to disk [DskChr[ROOT|5368709120|]].
312157:2026-09-01 07:52:37,995 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] is not allocated to any pool. Cannot check compatibility with pool [StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}].
312158:2026-09-01 07:52:37,995 INFO  [c.c.s.StorageManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Storage pool StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"} does not supply IOPS capacity, assuming enough capacity
312159:2026-09-01 07:52:37,996 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Checking pool StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"} for storage, totalSize: 63330819506176, usedBytes: 6839453351936, usedPct: 0.10799565527916496, disable threshold: 0.98
312160:2026-09-01 07:52:37,996 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Destination pool: StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}
312166:2026-09-01 07:52:38,006 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Pool ID for the volume Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"} is null
312167:2026-09-01 07:52:38,008 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Found storage pool StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"} of type NetworkFilesystem with overprovisioning factor 2
312168:2026-09-01 07:52:38,008 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Total over provisioned capacity calculated is 2 * (57.5990 TB) 63330819506176
312169:2026-09-01 07:52:38,008 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Total capacity of the pool StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"} is (115.1981 TB) 126661639012352
312170:2026-09-01 07:52:38,009 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Checking pool: StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"} for storage allocation , maxSize : (115.1981 TB) 126661639012352, totalAllocatedSize : (4.7864 TB) 5262659290816, askingSize : (5.00 GB) 5368709120, allocated disable threshold: 0.98
312171:2026-09-01 07:52:38,009 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Found suitable zone wide storage pool [StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}] to allocate disk [DskChr[ROOT|5368709120|]] to it, adding to list.
312172:2026-09-01 07:52:38,009 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) [ZoneWideStoragePoolAllocator] is returning [1] suitable storage pools [[StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}]].
312173:2026-09-01 07:52:38,009 INFO  [o.a.c.s.a.ZoneWideStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Reordering [1] pools
312174:2026-09-01 07:52:38,009 INFO  [o.a.c.s.a.ZoneWideStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Using volume allocation algorithm random to reorder pools.
312175:2026-09-01 07:52:38,009 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Pools to shuffle: [[StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}]]
312176:2026-09-01 07:52:38,009 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Shuffled list of pools to choose from: [[StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}]]
312177:2026-09-01 07:52:38,009 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) StoragePoolAllocator [ZoneWideStoragePoolAllocator] found 1 suitable pools to allocate volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312178:2026-09-01 07:52:38,010 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Trying to find a potential host and associated storage pools from the suitable host/pool lists for this VM
312179:2026-09-01 07:52:38,011 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Checking if host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} can access any suitable storage pool for volume: ROOT
312180:2026-09-01 07:52:38,012 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} can access pool: StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}
312181:2026-09-01 07:52:38,013 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Found a potential host Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} and associated storage pools for this VM
312182:2026-09-01 07:52:38,013 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(45)-Storage(Volume(1218|ROOT-->Pool(6))]
312183:2026-09-01 07:52:38,017 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) start parameter value of enterHardwareSetup == null during processing of queued job
312184:2026-09-01 07:52:38,022 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Sync job-58106 execution on object VmWorkJobQueue.1213
312187:2026-09-01 07:52:38,376 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106]) (logid:4717fe24) Add job-58106 into job monitoring
312188:2026-09-01 07:52:38,379 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106]) (logid:f2258f45) Executing AsyncJob {"accountId":2,"cmd":"com.cloud.vm.VmWorkStart","cmdInfo":"rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAEvXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAA3BzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAANzcQB-AAgAAAAAAAAALXBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAACdAAKVm1QYXNzd29yZHQAEnJPMEFCWFFBQmtsUFYzUjJOUXQAGFJldHVybkFmdGVyVm9sdW1lUHJlcGFyZXQAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw","cmdVersion":0,"completeMsid":null,"created":"Tue Sep 01 07:52:38 UTC 2026","id":58106,"initMsid":163763490546348,"instanceId":null,"instanceType":null,"lastPolled":null,"lastUpdated":null,"processStatus":0,"removed":null,"result":null,"resultCode":0,"status":"IN_PROGRESS","userId":2,"uuid":"57be285a-29d3-46e0-bd75-8bcc60e6eb17"}
312189:2026-09-01 07:52:38,379 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106]) (logid:f2258f45) Run VM work job: com.cloud.vm.VmWorkStart for VM 1213, job origin: 58105
312190:2026-09-01 07:52:38,381 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Execute VM work job: com.cloud.vm.VmWorkStart{"accountId":2,"dcId":3,"vmId":1213,"hostId":45,"handlerName":"VirtualMachineManagerImpl","clusterId":3,"userId":2,"podId":3,"rawParams":{"ReturnAfterVolumePrepare":"rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE"}}
312191:2026-09-01 07:52:38,382 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) orchestrating VM start for 'i-2-1213-VM' com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d set to null
312192:2026-09-01 07:52:38,382 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Trying to start VM ["3783a71c-020e-46e7-8438-246c216e0871"] using plan [{"_dcId":3,"_podId":3,"_clusterId":3,"_hostId":45,"_recreateDisks":false,"preferredHostIds":[],"migrationPlan":false,"hostPriorities":{}}] and planner [null].
312193:2026-09-01 07:52:38,389 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} state transited from [Stopped] to [Starting] with event [StartRequested]. VM's original host: null, new host: null, host before state transition: null
312194:2026-09-01 07:52:38,390 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Successfully transitioned to start state for VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} reservation id = 16036fa5-960f-448a-b741-08789bb11e91
312195:2026-09-01 07:52:38,392 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Trying to deploy VM [error decoding VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}] and details: Plan [{"_dcId":3,"_podId":3,"_clusterId":3,"_hostId":45,"_recreateDisks":false,"preferredHostIds":[],"migrationPlan":false,"hostPriorities":{}}]; avoid list [null] and planner: [null].
312196:2026-09-01 07:52:38,392 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Avoiding components [null] in deployment of VM ["3783a71c-020e-46e7-8438-246c216e0871"].
312197:2026-09-01 07:52:38,392 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Deploy avoids pods: null, clusters: null, hosts: null
312198:2026-09-01 07:52:38,394 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Instance start attempt #1
312199:2026-09-01 07:52:38,396 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Trying to deploy VM [error decoding VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}] and details: Plan [error decoding {"_clusterId":3,"_dcId":3,"_physicalNetworkId":null,"_podId":3,"_poolId":null,"migrationPlan":false}]; avoid list [{}] and planner: [null].
312200:2026-09-01 07:52:38,396 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Checking non dedicated resources to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312201:2026-09-01 07:52:38,399 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Adding pods [[]], clusters [[]] and hosts [[]] to the avoid list in the deploy process of user VM [error decoding VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}], because this VM is not explicitly dedicated to these components.
312202:2026-09-01 07:52:38,400 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Trying to allocate a host and storage pools from datacenter [Zone {"id": "3", "name": "IEM_Compute_Zone_1", "uuid": "fefa5625-f83a-41dd-9004-bb3bb2f96307"}], pod [HostPod {"id":3,"name":"IEM_Compute_Pod_1","uuid":"c207e7a2-044b-4509-b3c8-6dec83b641f3"}], cluster [Cluster {id: "3", name: "IEM_Compute_Cluster_1", uuid: "ba7c3ced-1cad-4d86-b868-4163d5fba7dd"}], to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}] with requested CPU [3000] and requested RAM [(2.01 GB) 2155872256].
312203:2026-09-01 07:52:38,400 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) ROOT volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] is not ready to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312204:2026-09-01 07:52:38,401 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Adding pods [] to the avoid set because these pods are in the Disabled state.
312205:2026-09-01 07:52:38,402 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Adding clusters [] of pod [3] to the void set because these clusters are in the Disabled state.
312206:2026-09-01 07:52:38,402 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Adding hosts [] of datacenter [fefa5625-f83a-41dd-9004-bb3bb2f96307] to the avoid set, because these hosts are in the Disabled state.
312207:2026-09-01 07:52:38,402 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) DeploymentPlan [DataCenterDeployment] has specified host [45] without HA flag. Choosing this host to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312208:2026-09-01 07:52:38,403 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Trying to find suitable pools for host [Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}] under pod [Zone {"id": "3", "name": "IEM_Compute_Zone_1", "uuid": "fefa5625-f83a-41dd-9004-bb3bb2f96307"}], cluster [HostPod {"id":3,"name":"IEM_Compute_Pod_1","uuid":"c207e7a2-044b-4509-b3c8-6dec83b641f3"}] and zone [Cluster {id: "3", name: "IEM_Compute_Cluster_1", uuid: "ba7c3ced-1cad-4d86-b868-4163d5fba7dd"}], to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312209:2026-09-01 07:52:38,404 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Checking suitable pools for volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}, ROOT] of VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312210:2026-09-01 07:52:38,405 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Calling StoragePoolAllocators to find suitable pools to allocate volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312211:2026-09-01 07:52:38,405 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Trying to find suitable pools to allocate volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}], using StoragePoolAllocator: [LocalStoragePoolAllocator].
312212:2026-09-01 07:52:38,405 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) LocalStoragePoolAllocator is returning null since the disk profile does not use local storage and bypassStorageTypeCheck is false.
312213:2026-09-01 07:52:38,405 INFO  [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) There are no pools to reorder.
312214:2026-09-01 07:52:38,405 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Trying to find suitable pools to allocate volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}], using StoragePoolAllocator: [ClusterScopeStoragePoolAllocator].
312215:2026-09-01 07:52:38,406 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Looking for pools in dc [3], pod [3] and cluster [3]. Disabled pools will be ignored.
312216:2026-09-01 07:52:38,407 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Found pools [[]] that match with tags [[]].
312217:2026-09-01 07:52:38,407 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) No storage pools available for [shared] volume allocation.
312218:2026-09-01 07:52:38,407 INFO  [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Reordering [0] pools
312219:2026-09-01 07:52:38,407 INFO  [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Using volume allocation algorithm random to reorder pools.
312220:2026-09-01 07:52:38,407 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Pools to shuffle: [[]]
312221:2026-09-01 07:52:38,407 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Shuffled list of pools to choose from: [[]]
312222:2026-09-01 07:52:38,407 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Trying to find suitable pools to allocate volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}], using StoragePoolAllocator: [ZoneWideStoragePoolAllocator].
312223:2026-09-01 07:52:38,409 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Checking if storage pool [StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}] is suitable to disk [DskChr[ROOT|5368709120|]].
312224:2026-09-01 07:52:38,411 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] is not allocated to any pool. Cannot check compatibility with pool [StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}].
312225:2026-09-01 07:52:38,411 INFO  [c.c.s.StorageManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Storage pool StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"} does not supply IOPS capacity, assuming enough capacity
312226:2026-09-01 07:52:38,412 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Checking pool StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"} for storage, totalSize: 63330819506176, usedBytes: 6839453351936, usedPct: 0.10799565527916496, disable threshold: 0.98
312227:2026-09-01 07:52:38,412 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Destination pool: StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}
312228:2026-09-01 07:52:38,421 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Pool ID for the volume Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"} is null
312229:2026-09-01 07:52:38,422 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Found storage pool StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"} of type NetworkFilesystem with overprovisioning factor 2
312230:2026-09-01 07:52:38,422 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Total over provisioned capacity calculated is 2 * (57.5990 TB) 63330819506176
312231:2026-09-01 07:52:38,422 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Total capacity of the pool StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"} is (115.1981 TB) 126661639012352
312232:2026-09-01 07:52:38,423 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Checking pool: StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"} for storage allocation , maxSize : (115.1981 TB) 126661639012352, totalAllocatedSize : (4.7864 TB) 5262659290816, askingSize : (5.00 GB) 5368709120, allocated disable threshold: 0.98
312233:2026-09-01 07:52:38,424 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Found suitable zone wide storage pool [StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}] to allocate disk [DskChr[ROOT|5368709120|]] to it, adding to list.
312234:2026-09-01 07:52:38,424 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) [ZoneWideStoragePoolAllocator] is returning [1] suitable storage pools [[StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}]].
312235:2026-09-01 07:52:38,424 INFO  [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Reordering [1] pools
312236:2026-09-01 07:52:38,424 INFO  [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Using volume allocation algorithm random to reorder pools.
312237:2026-09-01 07:52:38,424 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Pools to shuffle: [[StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}]]
312238:2026-09-01 07:52:38,424 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Shuffled list of pools to choose from: [[StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}]]
312239:2026-09-01 07:52:38,424 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) StoragePoolAllocator [ZoneWideStoragePoolAllocator] found 1 suitable pools to allocate volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] necessary to deploy VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312240:2026-09-01 07:52:38,425 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Trying to find a potential host and associated storage pools from the suitable host/pool lists for this VM
312241:2026-09-01 07:52:38,425 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Checking if host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} can access any suitable storage pool for volume: ROOT
312242:2026-09-01 07:52:38,426 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} can access pool: StoragePool {"id":6,"name":"primary","poolType":"NetworkFilesystem","uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c"}
312243:2026-09-01 07:52:38,427 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Found a potential host Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} and associated storage pools for this VM
312244:2026-09-01 07:52:38,428 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(45)-Storage(Volume(1218|ROOT-->Pool(6))]
312245:2026-09-01 07:52:38,428 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Deployment found - Attempt #1 - P0=VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}, P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(45)-Storage(Volume(1218|ROOT-->Pool(6))]
312246:2026-09-01 07:52:38,434 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Starting","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} state transited from [Starting] to [Starting] with event [OperationRetry]. VM's original host: null, new host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, host before state transition: null
312247:2026-09-01 07:52:38,436 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Hosts's actual total CPU: 50400 and CPU after applying overprovisioning: 252000
312248:2026-09-01 07:52:38,436 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) We are allocating VM, increasing the used capacity of this host:Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}
312249:2026-09-01 07:52:38,436 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Current Used CPU: 138800 , Free CPU:113200 ,Requested CPU: 3000
312250:2026-09-01 07:52:38,436 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Current Used RAM: (109.09 GB) 117138522112 , Free RAM:(15.39 GB) 16528850944 ,Requested RAM: (2.01 GB) 2155872256
312251:2026-09-01 07:52:38,437 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) CPU STATS after allocation: for host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, old used: 138800, old reserved: 0, actual total: 50400, total with overprovisioning: 252000; new used: 141800, reserved: 0; requested cpu: 3000, alloc_from_last: false
312252:2026-09-01 07:52:38,437 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) RAM STATS after allocation: for host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, old used: (109.09 GB) 117138522112, old reserved: (0 bytes) 0, total: (124.49 GB) 133667373056; new used: (111.10 GB) 119294394368, reserved: (0 bytes) 0; requested mem: (2.01 GB) 2155872256, alloc_from_last: false
312253:2026-09-01 07:52:38,438 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} has cpu capability (cpu: 24, speed: 2100 ) to support requested CPU: 2 and requested speed: 1500
312254:2026-09-01 07:52:38,438 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Checking if host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} has enough capacity for requested CPU: 3000 and requested RAM: (2.01 GB) 2155872256 , cpuOverprovisioningFactor: 5.0
312255:2026-09-01 07:52:38,439 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Hosts's actual total CPU: 50400 and CPU after applying overprovisioning: 252000
312256:2026-09-01 07:52:38,439 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) We need to allocate to the last host again, so checking if there is enough reserved capacity
312257:2026-09-01 07:52:38,439 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Reserved CPU: 0 , Requested CPU: 3000
312258:2026-09-01 07:52:38,439 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Reserved RAM: (0 bytes) 0 , Requested RAM: (2.01 GB) 2155872256
312259:2026-09-01 07:52:38,439 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) STATS: Failed to alloc resource from host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} reservedCpu: 0, requested cpu: 3000, reservedMem: (0 bytes) 0, requested mem: (2.01 GB) 2155872256
312260:2026-09-01 07:52:38,439 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Host does not have enough reserved CPU available, cannot allocate to this host.
312261:2026-09-01 07:52:38,439 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Checking if host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"} has enough capacity for requested CPU: 3000 and requested RAM: (2.01 GB) 2155872256 , cpuOverprovisioningFactor: 5.0
312262:2026-09-01 07:52:38,439 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Hosts's actual total CPU: 50400 and CPU after applying overprovisioning: 252000
312263:2026-09-01 07:52:38,439 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Free CPU: 113200 , Requested CPU: 3000
312264:2026-09-01 07:52:38,439 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Free RAM: (15.39 GB) 16528850944 , Requested RAM: (2.01 GB) 2155872256
312265:2026-09-01 07:52:38,440 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Host has enough CPU and RAM available
312266:2026-09-01 07:52:38,440 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) STATS: Can alloc CPU from host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, used: 138800, reserved: 0, actual total: 50400, total with overprovisioning: 252000; requested cpu: 3000, alloc_from_last_host?: false, considerReservedCapacity?: true
312267:2026-09-01 07:52:38,440 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) STATS: Can alloc MEM from host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, used: (109.09 GB) 117138522112, reserved: (0 bytes) 0, total: (124.49 GB) 133667373056; requested mem: (2.01 GB) 2155872256, alloc_from_last_host?: false, considerReservedCapacity?: true
312268:2026-09-01 07:52:38,443 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10} is already implemented
312269:2026-09-01 07:52:38,447 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Service SecurityGroup is not supported in the network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312270:2026-09-01 07:52:38,449 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Changing active number of NICs for Network ID=Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10} on 1
312271:2026-09-01 07:52:38,451 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Asking VirtualRouter to prepare for Nic {"broadcastUri":"vlan:\/\/2446","deviceId":0,"iPv4Address":"10.1.252.58","id":1344,"instanceId":1213,"reservationId":"16036fa5-960f-448a-b741-08789bb11e91","uuid":"31468c8b-84c3-4a24-bc93-1f5156120303"}
312272:2026-09-01 07:52:38,456 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Service SecurityGroup is not supported in the network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312273:2026-09-01 07:52:38,458 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) CONFIG DHCP FOR SUBNETS RULES
312274:2026-09-01 07:52:38,460 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Service SecurityGroup is not supported in the network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312275:2026-09-01 07:52:38,461 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) APPLYING VPC DHCP ENTRY RULES
312276:2026-09-01 07:52:38,461 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Applying dhcp entry in network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312277:2026-09-01 07:52:38,467 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Wait time setting on com.cloud.agent.api.routing.DhcpEntryCommand is 1800 seconds
312278:2026-09-01 07:52:38,467 DEBUG [c.c.a.m.ClusteredAgentAttache] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Seq 5-6226226484839716456: Routed from 163763490546348
312279:2026-09-01 07:52:38,467 DEBUG [c.c.a.t.Request] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Seq 45-6226226484839716456: Sending  { Cmd , MgmtId: 163763490546348, via: 45(compute-3), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:03:00:d5:04:1e","vmIpAddress":"10.1.252.58","vmName":"VM-3783a71c-020e-46e7-8438-246c216e0871","defaultRouter":"10.1.0.1","defaultDns":"10.1.0.1","duid":"00:03:00:01:02:03:00:d5:04:1e","isDefault":"true","executeInSequence":"false","remove":"false","accessDetails":{"router.name":"r-1207-VM","router.guest.ip":"10.1.0.1","router.ip":"169.254.218.28","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}] }
312433:2026-09-01 07:52:40,322 DEBUG [c.c.a.t.Request] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Seq 45-6226226484839716456: Received:  { Ans: , MgmtId: 163763490546348, via: 45(compute-3), Ver: v1, Flags: 10, { GroupAnswer } }
312434:2026-09-01 07:52:40,330 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Service SecurityGroup is not supported in the network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312435:2026-09-01 07:52:40,334 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) APPLYING VPC USERDATA RULES
312436:2026-09-01 07:52:40,334 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Applying userdata and password entry in network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312437:2026-09-01 07:52:40,348 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Checking the wait time in seconds to be used for the following commands : com.cloud.agent.api.routing.SavePasswordCommand, com.cloud.agent.api.routing.VmDataCommand. If there are multiple commands sent at once,then max wait time of those will be used
312438:2026-09-01 07:52:40,348 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Wait time setting on com.cloud.agent.api.routing.SavePasswordCommand, com.cloud.agent.api.routing.VmDataCommand is 1800 seconds
312439:2026-09-01 07:52:40,349 DEBUG [c.c.a.m.ClusteredAgentAttache] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Seq 5-6226226484839716457: Routed from 163763490546348
312440:2026-09-01 07:52:40,350 DEBUG [c.c.a.t.Request] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Seq 45-6226226484839716457: Sending  { Cmd , MgmtId: 163763490546348, via: 45(compute-3), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"10.1.252.58","vmName":"VM-3783a71c-020e-46e7-8438-246c216e0871","executeInSequence":"false","accessDetails":{"router.name":"r-1207-VM","router.guest.ip":"10.1.0.1","router.ip":"169.254.218.28","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.252.58","vmName":"VM-3783a71c-020e-46e7-8438-246c216e0871","executeInSequence":"false","accessDetails":{"router.name":"r-1207-VM","router.guest.ip":"10.1.0.1","router.ip":"169.254.218.28","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}] }
312577:2026-09-01 07:52:46,055 DEBUG [c.c.a.t.Request] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Seq 45-6226226484839716457: Received:  { Ans: , MgmtId: 163763490546348, via: 45(compute-3), Ver: v1, Flags: 10, { GroupAnswer, GroupAnswer } }
312578:2026-09-01 07:52:46,056 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Service SecurityGroup is not supported in the network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312579:2026-09-01 07:52:46,073 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) template Template {"format":"QCOW2","id":238,"name":"ubuntu-24-cloud","uniqueName":"238-2-eec1dc2c-9da5-3006-88a6-cebdad7b9735","uuid":"da5d9cd2-cec7-4519-92e1-1f8e80344188"} with id 238 is already in store:ImageStore {"id":2,"name":"secondary","uuid":"165cc2d2-7449-4151-b461-c938368fb4b5"}, type: Image
312580:2026-09-01 07:52:46,081 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Found [0] snapshots [[]] that have checkpoints for volume with id [1218].
312581:2026-09-01 07:52:46,085 DEBUG [o.a.c.s.m.LinstorDataMotionStrategy] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) canHandle: TEMPLATE -> VOLUME
312584:2026-09-01 07:52:46,086 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type VOLUME
312585:2026-09-01 07:52:46,092 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Wait time setting on org.apache.cloudstack.storage.command.CopyCommand is 1800 seconds
312586:2026-09-01 07:52:46,093 DEBUG [c.c.a.m.ClusteredAgentAttache] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Seq 5-6734570292779161447: Routed from 163763490546348
312587:2026-09-01 07:52:46,093 DEBUG [c.c.a.t.Request] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Seq 5-6734570292779161447: Sending  { Cmd , MgmtId: 163763490546348, via: 5(compute1), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"da5d9cd2-cec7-4519-92e1-1f8e80344188","origUrl":"https://cloud-images.ubuntu.com/noble/current/noble-server-cloudimg-amd64.img","uuid":"da5d9cd2-cec7-4519-92e1-1f8e80344188","id":"238","format":"QCOW2","accountId":"2","checksum":"{SHA-512}84c23d281ef67199d0956a94eb9db2aa96174313518fd4d85f83fa9dd6065ca0159d398399c47022508123eee57bea254778e59ec9decebd2747cc8c121962e7","hvm":"true","displayText":"ubuntu-24-cloud","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c","name":"primary","id":"6","poolType":"NetworkFilesystem","host":"172.16.17.202","path":"/export/primary","port":"2049","url":"NetworkFilesystem://172.16.17.202/export/primary/?ROLE=Primary&STOREUUID=81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c","isManaged":"false"}},"name":"238-2-eec1dc2c-9da5-3006-88a6-cebdad7b9735","size":"(3.50 GB) 3758096384","hypervisorType":"KVM","bootable":"false","uniqueName":"238-2-eec1dc2c-9da5-3006-88a6-cebdad7b9735","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c","name":"primary","id":"6","poolType":"NetworkFilesystem","host":"172.16.17.202","path":"/export/primary","port":"2049","url":"NetworkFilesystem://172.16.17.202/export/primary/?ROLE=Primary&STOREUUID=81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c","isManaged":"false"}},"name":"ROOT-1213","size":"(5.00 GB) 5368709120","volumeId":"1218","vmName":"i-2-1213-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","poolId":"6","id":"1218","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false","checkpointPaths":[],"checkpointImageStoreUrls":[],"followRedirects":"false"}},"executeInSequence":"true","options":{},"options2":{},"wait":"0","bypassHostMaintenance":"false"}}] }
312591:2026-09-01 07:52:47,055 DEBUG [c.c.a.t.Request] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Seq 5-6734570292779161447: Received:  { Ans: , MgmtId: 163763490546348, via: 5(compute1), Ver: v1, Flags: 110, { CopyCmdAnswer } }
312592:2026-09-01 07:52:47,063 DEBUG [o.a.c.s.v.VolumeObject] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Updated {"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248"} from {"encryptFormat":null,"format":"QCOW2","path":null,"poolId":6,"size":5368709120} to {"encryptFormat":null,"format":"QCOW2","path":"ec53c3e4-32d1-498b-afe5-c067187c5248","poolId":6,"size":5368709120}
312595:2026-09-01 07:52:47,073 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Found [0] snapshots [[]] that have checkpoints for volume with id [1218].
312600:2026-09-01 07:52:47,085 INFO  [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Returning from VM start command execution for VM 3783a71c-020e-46e7-8438-246c216e0871 as requested. Volumes are prepared and ready.
312601:2026-09-01 07:52:47,090 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} state transited from [Starting] to [Stopped] with event [AgentReportStopped]. VM's original host: null, new host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, host before state transition: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}
312602:2026-09-01 07:52:47,094 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Hosts's actual total CPU: 50400 and CPU after applying overprovisioning: 252000
312603:2026-09-01 07:52:47,094 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Hosts's actual total RAM: (124.49 GB) 133667377152 and RAM after applying overprovisioning: (124.49 GB) 133667373056
312604:2026-09-01 07:52:47,094 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) release cpu from host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, old used: 141800, reserved: 0, actual total: 50400, total with overprovisioning: 252000; new used: 138800,reserved:0; movedfromreserved: false,moveToReservered: false
312605:2026-09-01 07:52:47,094 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) release mem from host: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}, old used: (111.10 GB) 119294394368, reserved: (0 bytes) 0, total: (124.49 GB) 133667373056; new used: (109.09 GB) 117138522112, reserved: (0 bytes) 0; movedfromreserved: false, moveToReservered: false
312606:2026-09-01 07:52:47,102 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Volume preparation completed for VM VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} (VM state set to Stopped)
312607:2026-09-01 07:52:47,103 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Cleaning up resources for the vm VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} in Stopped state
312608:2026-09-01 07:52:47,105 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Service SecurityGroup is not supported in the network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312609:2026-09-01 07:52:47,107 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) The nic Nic {"broadcastUri":"vlan:\/\/2446","deviceId":0,"iPv4Address":"10.1.252.58","id":1344,"instanceId":1213,"reservationId":"16036fa5-960f-448a-b741-08789bb11e91","uuid":"31468c8b-84c3-4a24-bc93-1f5156120303"} on NicProfile {"broadcastUri":null,"deviceId":0,"iPv4Address":"10.1.252.58","id":1344,"reservationId":"16036fa5-960f-448a-b741-08789bb11e91","uuid":"31468c8b-84c3-4a24-bc93-1f5156120303","vmId":1213} was released according to VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} by guru com.cloud.network.guru.ExternalGuestNetworkGuru@2937d3e, now updating record.
312610:2026-09-01 07:52:47,108 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Changing active number of NICs for Network ID=Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10} on -1
312611:2026-09-01 07:52:47,112 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Asking VirtualRouter to release NicProfile {"broadcastUri":null,"deviceId":0,"iPv4Address":"10.1.252.58","id":1344,"reservationId":"16036fa5-960f-448a-b741-08789bb11e91","uuid":"31468c8b-84c3-4a24-bc93-1f5156120303","vmId":1213}
312612:2026-09-01 07:52:47,112 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Successfully released network resources for the VM VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} in Stopped state
312613:2026-09-01 07:52:47,115 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Found [0] snapshots [[]] that have checkpoints for volume with id [1218].
312614:2026-09-01 07:52:47,116 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Successfully released storage resources for the VM VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} in Stopped state
312615:2026-09-01 07:52:47,116 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Successfully cleaned up resources for the VM VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} in Stopped state
312616:2026-09-01 07:52:47,121 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} state transited from [Stopped] to [Stopped] with event [OperationFailed]. VM's original host: null, new host: null, host before state transition: Host {"id":45,"name":"compute-3","type":"Routing","uuid":"aa3ac602-03cd-4df7-bda2-8faa264bd9db"}
312617:2026-09-01 07:52:47,127 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Done executing VM work job: com.cloud.vm.VmWorkStart{"accountId":2,"dcId":3,"vmId":1213,"hostId":45,"handlerName":"VirtualMachineManagerImpl","clusterId":3,"userId":2,"podId":3,"rawParams":{"ReturnAfterVolumePrepare":"rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE"}}
312618:2026-09-01 07:52:47,127 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Complete async job-58106, jobStatus: SUCCEEDED, resultCode: 0, result: null
312619:2026-09-01 07:52:47,127 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Publish async job-58106 complete on message bus
312620:2026-09-01 07:52:47,128 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Wake up jobs related to job-58106
312621:2026-09-01 07:52:47,128 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Update db status for job-58106
312622:2026-09-01 07:52:47,128 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106, ctx-5ea9b470]) (logid:f2258f45) Wake up jobs joined with job-58106 and disjoin all subjobs created from job- 58106
312623:2026-09-01 07:52:47,133 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106]) (logid:f2258f45) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 1213, job origin: 58105
312624:2026-09-01 07:52:47,133 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106]) (logid:f2258f45) Done executing com.cloud.vm.VmWorkStart for job-58106
312625:2026-09-01 07:52:47,133 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-124:[ctx-3316dad3, job-58105/job-58106]) (logid:f2258f45) Remove job-58106 from job monitoring
312626:2026-09-01 07:52:47,143 DEBUG [o.a.c.b.BackupManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Trying to update state of VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}] with event [RestoringRequested].
312627:2026-09-01 07:52:47,146 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Restoring","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} state transited from [Stopped] to [Restoring] with event [RestoringRequested]. VM's original host: null, new host: null, host before state transition: null
312628:2026-09-01 07:52:47,148 DEBUG [o.a.c.b.BackupManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Trying to update state of volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] with event [RestoreRequested].
312630:2026-09-01 07:52:47,154 DEBUG [o.a.c.b.NASBackupProvider] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Restoring vm VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Restoring","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} from backup Backup {"backupType":"FULL","externalId":"i-2-1185-VM\/2026.08.31.06.56.07","id":101,"uuid":"26295893-2f9e-4256-9ddd-a7099cebd291","vmId":1185} on the NAS Backup Provider
312631:2026-09-01 07:52:47,158 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Wait time setting on org.apache.cloudstack.backup.RestoreBackupCommand is 1800 seconds
312632:2026-09-01 07:52:47,158 DEBUG [c.c.a.m.ClusteredAgentAttache] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Seq 5-6734570292779161448: Routed from 163763490546348
312633:2026-09-01 07:52:47,158 DEBUG [c.c.a.t.Request] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Seq 5-6734570292779161448: Sending  { Cmd , MgmtId: 163763490546348, via: 5(compute1), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.backup.RestoreBackupCommand":{"vmName":"i-2-1213-VM","backupPath":"i-2-1185-VM/2026.08.31.06.56.07","backupRepoType":"nfs","backupRepoAddress":"cloud.zone1nfsdr:/volume1/cloudstack-backups","backupVolumesUUIDs":["86636972-a7a4-422d-8f31-b3c932850659"],"restoreVolumePools":[{"uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c","name":"primary","id":"6","poolType":"NetworkFilesystem","host":"172.16.17.202","path":"/export/primary","port":"2049","url":"NetworkFilesystem://172.16.17.202/export/primary/?ROLE=Primary&STOREUUID=81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c","isManaged":"false"}],"restoreVolumePaths":["/mnt/81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c/ec53c3e4-32d1-498b-afe5-c067187c5248"],"backupFiles":["86636972-a7a4-422d-8f31-b3c932850659"],"vmExists":"true","vmState":"Restoring","mountTimeout":"30","wait":"0","bypassHostMaintenance":"false"}}] }
312647:2026-09-01 07:52:47,908 DEBUG [c.c.a.t.Request] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Seq 5-6734570292779161448: Received:  { Ans: , MgmtId: 163763490546348, via: 5(compute1), Ver: v1, Flags: 110, { BackupAnswer } }
312648:2026-09-01 07:52:47,908 ERROR [o.a.c.b.BackupManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Failed to create Instance [i-2-1213-VM] from backup [{"externalId":"i-2-1185-VM\/2026.08.31.06.56.07","name":"r3","uuid":"26295893-2f9e-4256-9ddd-a7099cebd291"}] due to: Backup file for the volume [86636972-a7a4-422d-8f31-b3c932850659] does not exist..
312649:2026-09-01 07:52:47,910 DEBUG [o.a.c.b.BackupManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Trying to update state of volume [Volume {"id":1218,"instanceId":1213,"name":"ROOT-1213","uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT"}] with event [RestoreFailed].
312650:2026-09-01 07:52:47,915 DEBUG [o.a.c.b.BackupManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Trying to update state of VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Restoring","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}] with event [RestoringFailed].
312651:2026-09-01 07:52:47,918 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} state transited from [Restoring] to [Stopped] with event [RestoringFailed]. VM's original host: null, new host: null, host before state transition: null
312652:2026-09-01 07:52:47,936 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Sync job-58107 execution on object VmWorkJobQueue.1213
312662:2026-09-01 07:52:48,372 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107]) (logid:62c00b47) Add job-58107 into job monitoring
312663:2026-09-01 07:52:48,378 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107]) (logid:f2258f45) Executing AsyncJob {"accountId":2,"cmd":"com.cloud.vm.VmWorkStop","cmdInfo":"rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAEvXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA","cmdVersion":0,"completeMsid":null,"created":"Tue Sep 01 07:52:47 UTC 2026","id":58107,"initMsid":163763490546348,"instanceId":null,"instanceType":null,"lastPolled":null,"lastUpdated":null,"processStatus":0,"removed":null,"result":null,"resultCode":0,"status":"IN_PROGRESS","userId":2,"uuid":"58afe080-b890-47a2-8cb4-d3d696a7246b"}
312664:2026-09-01 07:52:48,378 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107]) (logid:f2258f45) Run VM work job: com.cloud.vm.VmWorkStop for VM 1213, job origin: 58105
312665:2026-09-01 07:52:48,380 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107, ctx-5c2bfa0a]) (logid:f2258f45) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":1213,"handlerName":"VirtualMachineManagerImpl"}
312666:2026-09-01 07:52:48,381 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107, ctx-5c2bfa0a]) (logid:f2258f45) VM is already stopped: VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}
312667:2026-09-01 07:52:48,382 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107, ctx-5c2bfa0a]) (logid:f2258f45) Done executing VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":1213,"handlerName":"VirtualMachineManagerImpl"}
312668:2026-09-01 07:52:48,382 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107, ctx-5c2bfa0a]) (logid:f2258f45) Complete async job-58107, jobStatus: SUCCEEDED, resultCode: 0, result: null
312669:2026-09-01 07:52:48,383 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107, ctx-5c2bfa0a]) (logid:f2258f45) Publish async job-58107 complete on message bus
312670:2026-09-01 07:52:48,383 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107, ctx-5c2bfa0a]) (logid:f2258f45) Wake up jobs related to job-58107
312671:2026-09-01 07:52:48,383 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107, ctx-5c2bfa0a]) (logid:f2258f45) Update db status for job-58107
312672:2026-09-01 07:52:48,384 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107, ctx-5c2bfa0a]) (logid:f2258f45) Wake up jobs joined with job-58107 and disjoin all subjobs created from job- 58107
312673:2026-09-01 07:52:48,391 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107]) (logid:f2258f45) Done with run of VM work job: com.cloud.vm.VmWorkStop for VM 1213, job origin: 58105
312674:2026-09-01 07:52:48,391 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107]) (logid:f2258f45) Done executing com.cloud.vm.VmWorkStop for job-58107
312675:2026-09-01 07:52:48,391 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-120:[ctx-9cacf6a4, job-58105/job-58107]) (logid:f2258f45) Remove job-58107 from job monitoring
312676:2026-09-01 07:52:48,396 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Expunging","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} state transited from [Stopped] to [Expunging] with event [ExpungeOperation]. VM's original host: null, new host: null, host before state transition: null
312677:2026-09-01 07:52:48,402 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Expunging vm VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Expunging","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}
312678:2026-09-01 07:52:48,402 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Cleaning up NICS [] of VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Expunging","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}.
312679:2026-09-01 07:52:48,402 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Cleaning Network for Instance: VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Expunging","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}
312680:2026-09-01 07:52:48,408 DEBUG [o.a.c.n.t.BasicNetworkTopology] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) REMOVE VPC DHCP ENTRY RULES
312681:2026-09-01 07:52:48,409 DEBUG [o.a.c.n.t.BasicNetworkTopology] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Applying dhcp entry in network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312682:2026-09-01 07:52:48,416 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Wait time setting on com.cloud.agent.api.routing.DhcpEntryCommand is 1800 seconds
312683:2026-09-01 07:52:48,416 DEBUG [c.c.a.m.ClusteredAgentAttache] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Seq 5-6226226484839716458: Routed from 163763490546348
312684:2026-09-01 07:52:48,416 DEBUG [c.c.a.t.Request] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Seq 45-6226226484839716458: Sending  { Cmd , MgmtId: 163763490546348, via: 45(compute-3), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:03:00:d5:04:1e","vmIpAddress":"10.1.252.58","vmName":"VM-3783a71c-020e-46e7-8438-246c216e0871","defaultRouter":"10.1.0.1","defaultDns":"10.1.0.1","duid":"00:03:00:01:02:03:00:d5:04:1e","isDefault":"true","executeInSequence":"false","remove":"true","accessDetails":{"router.name":"r-1207-VM","router.guest.ip":"10.1.0.1","router.ip":"169.254.218.28","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}] }
312707:2026-09-01 07:52:50,130 DEBUG [c.c.a.t.Request] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Seq 45-6226226484839716458: Received:  { Ans: , MgmtId: 163763490546348, via: 45(compute-3), Ver: v1, Flags: 10, { GroupAnswer } }
312708:2026-09-01 07:52:50,133 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Service SecurityGroup is not supported in the network Network {"id": 213, "name": "Iem_Compute_Isolate_1", "uuid": "5c7f439d-4a2f-4470-8e80-7883e1a61afe", "networkofferingid": 10}
312709:2026-09-01 07:52:50,137 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Removed NIC ID=1344
312710:2026-09-01 07:52:50,138 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Revoving nic secondary ip entry ...
312711:2026-09-01 07:52:50,138 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Cleaning up hypervisor data structures (ex. SRs in XenServer) for managed storage. Data from VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Expunging","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}.
312712:2026-09-01 07:52:50,139 DEBUG [o.a.c.e.o.VolumeOrchestrator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Cleaning storage for VM [VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Expunging","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}].
312713:2026-09-01 07:52:50,148 DEBUG [o.a.c.e.o.VolumeOrchestrator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, ctx-a5ab6be4]) (logid:f2258f45) Found [0] snapshots [[]] that have checkpoints for volume with id [1218].
312714:2026-09-01 07:52:50,155 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, ctx-a5ab6be4]) (logid:f2258f45) Updating resource Type = volume count for Account with id = 2 Operation = decreasing Amount = 1
312715:2026-09-01 07:52:50,157 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3, ctx-a5ab6be4]) (logid:f2258f45) Updating resource Type = primary_storage count for Account with id = 2 Operation = decreasing Amount = (5.00 GB) 5368709120
312716:2026-09-01 07:52:50,164 DEBUG [o.a.c.e.o.VolumeOrchestrator] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Found [0] snapshots [[]] that have checkpoints for volume with id [1218].
312717:2026-09-01 07:52:50,175 DEBUG [c.c.h.XenServerGuru] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) We are returning the default host to execute commands because the command is not of Copy type.
312718:2026-09-01 07:52:50,175 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Wait time setting on org.apache.cloudstack.storage.command.DeleteCommand is 1800 seconds
312719:2026-09-01 07:52:50,175 DEBUG [c.c.a.m.ClusteredAgentAttache] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Seq 5-3942057048832742062: Routed from 163763490546348
312720:2026-09-01 07:52:50,175 DEBUG [c.c.a.t.Request] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Seq 10-3942057048832742062: Sending  { Cmd , MgmtId: 163763490546348, via: 10(compute4), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c","name":"primary","id":"6","poolType":"NetworkFilesystem","host":"172.16.17.202","path":"/export/primary","port":"2049","url":"NetworkFilesystem://172.16.17.202/export/primary/?ROLE=Primary&STOREUUID=81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c","isManaged":"false"}},"name":"ROOT-1213","size":"(5.00 GB) 5368709120","path":"ec53c3e4-32d1-498b-afe5-c067187c5248","volumeId":"1218","vmName":"i-2-1213-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","poolId":"6","id":"1218","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false","checkpointPaths":[],"checkpointImageStoreUrls":[],"followRedirects":"false"}},"wait":"0","bypassHostMaintenance":"false"}}] }
313411:2026-09-01 07:53:39,381 DEBUG [c.c.a.t.Request] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Seq 10-3942057048832742062: Received:  { Ans: , MgmtId: 163763490546348, via: 10(compute4), Ver: v1, Flags: 10, { Answer } }
313412:2026-09-01 07:53:39,388 INFO  [o.a.c.s.v.VolumeServiceImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Volume VolumeObject {"dataStore":"StoragePool {\"id\":6,\"name\":\"primary\",\"poolType\":\"NetworkFilesystem\",\"uuid\":\"81ecd9fd-9cdf-34cb-b99d-51d0e2cf3a0c\"}","volumeVO":"Volume {\"id\":1218,\"instanceId\":1213,\"name\":\"ROOT-1213\",\"uuid\":\"ec53c3e4-32d1-498b-afe5-c067187c5248\",\"volumeType\":\"ROOT\"}"} is not referred anywhere, remove it from volumes table
313413:2026-09-01 07:53:39,396 DEBUG [c.c.s.d.VolumeDaoImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Removing volume 1218 from DB
313414:2026-09-01 07:53:39,401 DEBUG [c.c.v.ClusteredVirtualMachineManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Expunged VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Expunging","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}
313415:2026-09-01 07:53:39,402 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Starting cleaning up vm VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} resources...
313416:2026-09-01 07:53:39,408 DEBUG [c.c.n.f.FirewallManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) No firewall rules are found for vm: VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Expunging","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}
313417:2026-09-01 07:53:39,410 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Firewall rules are removed successfully as a part of vm VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} expunge
313418:2026-09-01 07:53:39,412 DEBUG [c.c.n.r.RulesManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) No port forwarding rules are found for vm VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Expunging","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"}
313419:2026-09-01 07:53:39,412 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Port forwarding rules are removed successfully as a part of vm VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} expunge
313420:2026-09-01 07:53:39,413 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Removed vm VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} from all load balancers as a part of expunge process
313421:2026-09-01 07:53:39,414 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Successfully cleaned up vm VM instance {"id":1213,"instanceName":"i-2-1213-VM","state":"Stopped","type":"User","uuid":"3783a71c-020e-46e7-8438-246c216e0871"} resources as a part of expunge process
313422:2026-09-01 07:53:39,418 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105, ctx-2a06abb3]) (logid:f2258f45) Successfully cleaned up Instance 1213 after create Instance from backup failed
313423:2026-09-01 07:53:39,418 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:f2258f45) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.CreateVMFromBackupCmdByAdmin com.cloud.utils.exception.CloudRuntimeException: Failed to create Instance [i-2-1213-VM] from backup [{"externalId":"i-2-1185-VM\/2026.08.31.06.56.07","name":"r3","uuid":"26295893-2f9e-4256-9ddd-a7099cebd291"}] due to: Backup file for the volume [86636972-a7a4-422d-8f31-b3c932850659] does not exist..
313464:2026-09-01 07:53:39,418 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:f2258f45) Complete async job-58105, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Failed to create Instance [i-2-1213-VM] from backup [{"externalId":"i-2-1185-VM\/2026.08.31.06.56.07","name":"r3","uuid":"26295893-2f9e-4256-9ddd-a7099cebd291"}] due to: Backup file for the volume [86636972-a7a4-422d-8f31-b3c932850659] does not exist.."}
313465:2026-09-01 07:53:39,419 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:f2258f45) Publish async job-58105 complete on message bus
313466:2026-09-01 07:53:39,419 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:f2258f45) Wake up jobs related to job-58105
313467:2026-09-01 07:53:39,419 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:f2258f45) Update db status for job-58105
313468:2026-09-01 07:53:39,420 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:f2258f45) Wake up jobs joined with job-58105 and disjoin all subjobs created from job- 58105
313469:2026-09-01 07:53:39,422 DEBUG [c.c.a.ApiServer] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:f2258f45) Retrieved cmdEventType from job info: VM.CREATE
313470:2026-09-01 07:53:39,423 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:f2258f45) Done executing org.apache.cloudstack.api.command.admin.vm.CreateVMFromBackupCmdByAdmin for job-58105
313471:2026-09-01 07:53:39,423 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-100:[ctx-ecfb9ac8, job-58105]) (logid:f2258f45) Remove job-58105 from job monitoring

abh1sar · 2026-09-01T12:45:46Z

abh1sar
Sep 1, 2026
Collaborator

@arpanbht how have you added the nas backup repository in cloudstack for both zones?
Please check https://www.shapeblue.com/creating-instance-from-backup/ section: Cross-Zone Backup Replication and Recovery

5 replies

arpanbht Sep 1, 2026
Author

@abh1sar
Yes I have added both the repositories in different zones, here is the reference image

and the value Cross-Zone Instance Creation is set to "TRUE" in both the repositories.

And also tell me Do i need to sync the whole nfs storage like primary, secondary and cloudstack-backups over both the zones or only the cloudstack-backups sync will work?

abh1sar Sep 1, 2026
Collaborator

The address of both reposothas to be same. See https://youtu.be/UTSVDCZyUHY?si=bBs__N2PsgB7WJOv

Answer selected by abh1sar

TheKunalSen Sep 1, 2026

@abh1sar
I saw the video just now
So I just have to make the dns same of those two nas right?

abh1sar Sep 2, 2026
Collaborator

yes

TheKunalSen Sep 2, 2026

@abh1sar
thank you it worked

Navigation Menu

Uh oh!

vm creation from backups #14015

Uh oh!

{{title}}

Uh oh!

Replies: 2 comments 6 replies

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

Uh oh!

vm creation from backups #14015

Uh oh!

arpanbht Aug 31, 2026

Replies: 2 comments · 6 replies

Uh oh!

DaanHoogland Sep 1, 2026 Collaborator

Uh oh!

arpanbht Sep 1, 2026 Author

Uh oh!

abh1sar Sep 1, 2026 Collaborator

Uh oh!

Uh oh!

arpanbht Sep 1, 2026 Author

Uh oh!

abh1sar Sep 1, 2026 Collaborator

Uh oh!

TheKunalSen Sep 1, 2026

Uh oh!

abh1sar Sep 2, 2026 Collaborator

Uh oh!

TheKunalSen Sep 2, 2026

arpanbht
Aug 31, 2026

Replies: 2 comments 6 replies

DaanHoogland
Sep 1, 2026
Collaborator

arpanbht Sep 1, 2026
Author

abh1sar
Sep 1, 2026
Collaborator

arpanbht Sep 1, 2026
Author

abh1sar Sep 1, 2026
Collaborator

abh1sar Sep 2, 2026
Collaborator