GitHub user arpanbht added a comment to the discussion: vm creation from backups
@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\":\"ba7c3
ced-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-90
04-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-416
3d5fba7dd\",\"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-AAgAAAAAAAAALXBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2s
HDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAACdAAKVm1QYXNzd29yZHQAEnJPMEFCWFFBQmtsUFYzUjJOUXQAGFJldHVybkFmdGVyVm9sdW1lUHJlcGFyZXQAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw","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","pa
th":"/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-b3c
932850659"],"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
```
GitHub link:
https://github.com/apache/cloudstack/discussions/14015#discussioncomment-18230121
----
This is an automatically sent email for [email protected].
To unsubscribe, please send an email to: [email protected]
