nimbustech-lab commented on issue #11052:
URL: https://github.com/apache/cloudstack/issues/11052#issuecomment-2999754143
Hi @DaanHoogland . I've managed to grep the job you mentioned. Thank you for
helping me with this. Here are the logs.
2025-06-20 02:48:12,525 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-18:ctx-a674dfb9 job-2149) (logid:129e78b0) Add job-2149 into
job monitoring
2025-06-20 02:48:12,531 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(qtp341748265-5716:ctx-4c68571b ctx-98e5ca78) (logid:a4cedac3) submit async
job-2149, details: AsyncJobVO: {id:2149, userId: 4, accountId: 4, instanceType:
VirtualMachine, instanceId: 619, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"iptonetworklist[0].networkid":"759ea379-6e4d-4316-a943-2904e70b5706","sessionkey":"qq9TANz-lGM6Dlt8pRtA5L-nlBM","httpmethod":"GET","ctxAccountId":"4","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367","cmdEventType":"VM.CREATE","diskofferingid":"833b4f12-0509-4a4f-88a0-7236e53c7107","bootmode":"LEGACY","iothreadsenabled":"false","rootdisksize":"35","ctxStartEventId":"3533","id":"619","overridediskofferingid":"833b4f12-0509-4a4f-88a0-7236e53c7107","ctxDetails":"{\"interface
com.cloud.offering.DiskOffering\":\"833b4f12-0509-4a4f-88a0-7236e53c7107\",\"interface
com.cloud.vm.VirtualMachine\":\"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367\",\"interface
com.cloud.template.V
irtualMachineTemplate\":\"a1905274-90d1-4c9e-bbf1-6067fc93ffda\",\"interface
com.cloud.dc.DataCenter\":\"12e2aff7-19b7-4fc0-85ce-ecf870f6f3f2\",\"interface
com.cloud.offering.ServiceOffering\":\"f72a9858-4ae5-4498-bdc5-f4909a2c54d4\"}","dynamicscalingenabled":"true","keypairs":"","boottype":"BIOS","templateid":"a1905274-90d1-4c9e-bbf1-6067fc93ffda","startvm":"true","size":"35","serviceofferingid":"f72a9858-4ae5-4498-bdc5-f4909a2c54d4","response":"json","ctxUserId":"4","displayname":"WinServer2022-VM-04","name":"WinServer2022-VM-04","zoneid":"12e2aff7-19b7-4fc0-85ce-ecf870f6f3f2","affinitygroupids":""},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 345049157785, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null, removed: null}
2025-06-20 02:48:12,534 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149) (logid:9556019e) Executing
AsyncJobVO: {id:2149, userId: 4, accountId: 4, instanceType: VirtualMachine,
instanceId: 619, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"iptonetworklist[0].networkid":"759ea379-6e4d-4316-a943-2904e70b5706","sessionkey":"qq9TANz-lGM6Dlt8pRtA5L-nlBM","httpmethod":"GET","ctxAccountId":"4","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367","cmdEventType":"VM.CREATE","diskofferingid":"833b4f12-0509-4a4f-88a0-7236e53c7107","bootmode":"LEGACY","iothreadsenabled":"false","rootdisksize":"35","ctxStartEventId":"3533","id":"619","overridediskofferingid":"833b4f12-0509-4a4f-88a0-7236e53c7107","ctxDetails":"{\"interface
com.cloud.offering.DiskOffering\":\"833b4f12-0509-4a4f-88a0-7236e53c7107\",\"interface
com.cloud.vm.VirtualMachine\":\"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367\",\"interface
com.cloud.template.VirtualMachineTemplate\":
\"a1905274-90d1-4c9e-bbf1-6067fc93ffda\",\"interface
com.cloud.dc.DataCenter\":\"12e2aff7-19b7-4fc0-85ce-ecf870f6f3f2\",\"interface
com.cloud.offering.ServiceOffering\":\"f72a9858-4ae5-4498-bdc5-f4909a2c54d4\"}","dynamicscalingenabled":"true","keypairs":"","boottype":"BIOS","templateid":"a1905274-90d1-4c9e-bbf1-6067fc93ffda","startvm":"true","size":"35","serviceofferingid":"f72a9858-4ae5-4498-bdc5-f4909a2c54d4","response":"json","ctxUserId":"4","displayname":"WinServer2022-VM-04","name":"WinServer2022-VM-04","zoneid":"12e2aff7-19b7-4fc0-85ce-ecf870f6f3f2","affinitygroupids":""},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 345049157785, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null, removed: null}
2025-06-20 02:48:12,547 DEBUG [c.c.u.AccountManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Account [9eb8fb08-04e4-495e-bde8-4c4848558d03] has access to resource.
2025-06-20 02:48:12,547 DEBUG [c.c.u.AccountManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Account [9eb8fb08-04e4-495e-bde8-4c4848558d03] has access to resource.
2025-06-20 02:48:12,547 DEBUG [c.c.u.AccountManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Account [9eb8fb08-04e4-495e-bde8-4c4848558d03] has access to resource.
2025-06-20 02:48:12,574 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Service SecurityGroup is not supported in the network id=214
2025-06-20 02:48:12,578 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Service SecurityGroup is not supported in the network id=214
2025-06-20 02:48:12,591 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Adding pods to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:12,591 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Adding clusters to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:12,591 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Adding hosts to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:12,591 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
DeploymentPlanner allocation algorithm: null
2025-06-20 02:48:12,591 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Trying to allocate a host and storage pools from dc:3, pod:null,cluster:null,
requested cpu: 6000, requested ram: (8.00 GB) 8589934592
2025-06-20 02:48:12,591 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Is
ROOT volume READY (pool already allocated)?: No
2025-06-20 02:48:12,598 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Deploy avoids pods: [], clusters: [], hosts: []
2025-06-20 02:48:12,598 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Deploy hosts with priorities {} , hosts have NORMAL priority by default
2025-06-20 02:48:12,599 DEBUG [c.c.d.FirstFitPlanner]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Searching all possible resources under this Zone: 3
2025-06-20 02:48:12,601 DEBUG [c.c.d.FirstFitPlanner]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Listing clusters in order of aggregate capacity, that have (at least one host
with) enough CPU and RAM capacity under this Zone: 3
2025-06-20 02:48:12,604 DEBUG [c.c.d.FirstFitPlanner]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Removing from the clusterId list these clusters from avoid set: []
2025-06-20 02:48:12,612 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking resources in Cluster: 2 under Pod: 3
2025-06-20 02:48:12,615 INFO [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Guest VM is requested with
Custom[UEFI] Boot Type false
2025-06-20 02:48:12,615 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Looking for hosts in zone [3], pod
[3], cluster [2].
2025-06-20 02:48:12,619 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) FirstFitAllocator has 1 hosts to
check for allocation: [Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}]
2025-06-20 02:48:12,624 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Found 1 hosts for allocation after
prioritization: [Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}]
2025-06-20 02:48:12,624 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Looking for speed=6000Mhz, Ram=8192
MB
2025-06-20 02:48:12,630 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Host: 2 has cpu capability (cpu:80,
speed:2399) to support requested CPU: 4 and requested speed: 1500
2025-06-20 02:48:12,630 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Checking if host: 2 has enough
capacity for requested CPU: 6000 and requested RAM: (8.00 GB) 8589934592 ,
cpuOverprovisioningFactor: 1.0
2025-06-20 02:48:12,632 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Hosts's actual total CPU: 191920 and
CPU after applying overprovisioning: 191920
2025-06-20 02:48:12,632 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Free CPU: 174420 , Requested CPU:
6000
2025-06-20 02:48:12,632 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Free RAM: (106.44 GB) 114287067136 ,
Requested RAM: (8.00 GB) 8589934592
2025-06-20 02:48:12,632 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Host has enough CPU and RAM available
2025-06-20 02:48:12,632 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) STATS: Can alloc CPU from host: 2,
used: 17500, reserved: 0, actual total: 191920, total with overprovisioning:
191920; requested cpu:6000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2025-06-20 02:48:12,632 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) STATS: Can alloc MEM from host: 2,
used: (21.50 GB) 23085449216, reserved: (0 bytes) 0, total: (127.94 GB)
137372516352; requested mem: (8.00 GB) 8589934592, alloc_from_last_host?: false
, considerReservedCapacity?: true
2025-06-20 02:48:12,632 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Found a suitable host, adding to
list: 2
2025-06-20 02:48:12,632 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4
FirstFitRoutingAllocator) (logid:9556019e) Host Allocator returning 1 suitable
hosts
2025-06-20 02:48:12,633 INFO [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Re-ordering hosts [Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}]
by priorities {}
2025-06-20 02:48:12,633 INFO [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Hosts
after re-ordering are: [Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}]
2025-06-20 02:48:12,635 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking suitable pools for volume (Id, Type): (614,ROOT)
2025-06-20 02:48:12,635 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) We
need to allocate new storagepool for this volume
2025-06-20 02:48:12,636 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Calling StoragePoolAllocators to find suitable pools
2025-06-20 02:48:12,642 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking if storage pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}] is
suitable to disk [DskChr[ROOT|37580963840|]].
2025-06-20 02:48:12,646 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Volume [Vol[614|name=ROOT-619|vm=619|ROOT]] is not allocated to any pool.
Cannot check compatibility with pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}].
2025-06-20 02:48:12,647 INFO [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Storage pool ds-cloudstack (4) does not supply IOPS capacity, assuming enough
capacity
2025-06-20 02:48:12,648 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking pool 4 for storage, totalSize: 1099243192320, usedBytes: 644175888384,
usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:12,648 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Destination pool id: 4
2025-06-20 02:48:12,667 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Pool
ID for the volume with ID 614 is null
2025-06-20 02:48:12,674 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Found
storage pool ds-cloudstack of type VMFS with overprovisioning factor 2
2025-06-20 02:48:12,674 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Total
over provisioned capacity calculated is 2 * (1023.75 GB) 1099243192320
2025-06-20 02:48:12,674 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Total
capacity of the pool ds-cloudstack with ID 4 is (1.9995 TB) 2198486384640
2025-06-20 02:48:12,675 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking pool: 4 for storage allocation , maxSize : (1.9995 TB) 2198486384640,
totalAllocatedSize : (114.77 GB) 123228651520, askingSize : (35.00 GB)
37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:12,675 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Found
suitable local storage pool [Pool[4|VMFS]] to allocate disk
[DskChr[ROOT|37580963840|]] to it, adding to list.
2025-06-20 02:48:12,676 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
LocalStoragePoolAllocator is returning [1] suitable storage pools
[[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}]].
2025-06-20 02:48:12,676 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Using
allocation algorithm [random] to reorder pools.
2025-06-20 02:48:12,680 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking suitable pools for volume (Id, Type): (615,DATADISK)
2025-06-20 02:48:12,680 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) We
need to allocate new storagepool for this volume
2025-06-20 02:48:12,681 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Calling StoragePoolAllocators to find suitable pools
2025-06-20 02:48:12,685 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking if storage pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}] is
suitable to disk [DskChr[DATADISK|37580963840|]].
2025-06-20 02:48:12,687 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Volume [Vol[615|name=DATA-619|vm=619|DATADISK]] is not allocated to any pool.
Cannot check compatibility with pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}].
2025-06-20 02:48:12,688 INFO [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Storage pool ds-cloudstack (4) does not supply IOPS capacity, assuming enough
capacity
2025-06-20 02:48:12,689 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking pool 4 for storage, totalSize: 1099243192320, usedBytes: 644175888384,
usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:12,689 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Destination pool id: 4
2025-06-20 02:48:12,707 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Pool
ID for the volume with ID 615 is null
2025-06-20 02:48:12,713 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Found
storage pool ds-cloudstack of type VMFS with overprovisioning factor 2
2025-06-20 02:48:12,713 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Total
over provisioned capacity calculated is 2 * (1023.75 GB) 1099243192320
2025-06-20 02:48:12,713 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Total
capacity of the pool ds-cloudstack with ID 4 is (1.9995 TB) 2198486384640
2025-06-20 02:48:12,715 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking pool: 4 for storage allocation , maxSize : (1.9995 TB) 2198486384640,
totalAllocatedSize : (114.77 GB) 123228651520, askingSize : (35.00 GB)
37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:12,715 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Found
suitable local storage pool [Pool[4|VMFS]] to allocate disk
[DskChr[DATADISK|37580963840|]] to it, adding to list.
2025-06-20 02:48:12,717 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
LocalStoragePoolAllocator is returning [1] suitable storage pools
[[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}]].
2025-06-20 02:48:12,717 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Using
allocation algorithm [random] to reorder pools.
2025-06-20 02:48:12,721 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Trying to find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2025-06-20 02:48:12,722 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking if host: 2 can access any suitable storage pool for volume: DATADISK
2025-06-20 02:48:12,723 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Host:
2 can access pool: 4
2025-06-20 02:48:12,725 INFO [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Storage pool ds-cloudstack (4) does not supply IOPS capacity, assuming enough
capacity
2025-06-20 02:48:12,726 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking pool 4 for storage, totalSize: 1099243192320, usedBytes: 644175888384,
usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:12,726 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Destination pool id: 4
2025-06-20 02:48:12,729 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Pool
ID for the volume with ID 615 is null
2025-06-20 02:48:12,733 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Found
storage pool ds-cloudstack of type VMFS with overprovisioning factor 2
2025-06-20 02:48:12,734 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Total
over provisioned capacity calculated is 2 * (1023.75 GB) 1099243192320
2025-06-20 02:48:12,734 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Total
capacity of the pool ds-cloudstack with ID 4 is (1.9995 TB) 2198486384640
2025-06-20 02:48:12,735 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking pool: 4 for storage allocation , maxSize : (1.9995 TB) 2198486384640,
totalAllocatedSize : (114.77 GB) 123228651520, askingSize : (35.00 GB)
37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:12,735 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking if host: 2 can access any suitable storage pool for volume: ROOT
2025-06-20 02:48:12,735 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Host:
2 can access pool: 4
2025-06-20 02:48:12,737 INFO [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Storage pool ds-cloudstack (4) does not supply IOPS capacity, assuming enough
capacity
2025-06-20 02:48:12,738 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking pool 4 for storage, totalSize: 1099243192320, usedBytes: 644175888384,
usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:12,738 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Destination pool id: 4
2025-06-20 02:48:12,745 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Pool
ID for the volume with ID 614 is null
2025-06-20 02:48:12,750 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Found
storage pool ds-cloudstack of type VMFS with overprovisioning factor 2
2025-06-20 02:48:12,750 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Total
over provisioned capacity calculated is 2 * (1023.75 GB) 1099243192320
2025-06-20 02:48:12,750 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Total
capacity of the pool ds-cloudstack with ID 4 is (1.9995 TB) 2198486384640
2025-06-20 02:48:12,751 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Checking pool: 4 for storage allocation , maxSize : (1.9995 TB) 2198486384640,
totalAllocatedSize : (114.77 GB) 123228651520, askingSize : (35.00 GB)
37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:12,754 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Found
a potential host id: 2 name: 192.168.80.81 and associated storage pools for
this VM
2025-06-20 02:48:12,754 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(3)-Pod(3)-Cluster(2)-Host(2)-Storage(Volume(614|ROOT-->Pool(4)Volume(615|DATADISK-->Pool(4))]
2025-06-20 02:48:12,772 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) start
parameter value of enterHardwareSetup == null during processing of queued job
2025-06-20 02:48:12,785 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Sync
job-2150 execution on object VmWorkJobQueue.619
2025-06-20 02:48:14,132 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:aa1994ba) Add
job-2150 into job monitoring
2025-06-20 02:48:14,140 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e)
Executing AsyncJobVO: {id:2150, userId: 4, accountId: 4, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAEAAAAAAAAAAQAAAAAAAACa3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAA3BzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAJxAH4ACnBwcHNxAH4AC
AAAAAAAAAADcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 345049157785, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Fri Jun 20 02:48:12 UTC 2025, removed: null}
2025-06-20 02:48:14,141 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e) Run VM
work job: com.cloud.vm.VmWorkStart for VM 619, job origin: 2149
2025-06-20 02:48:14,145 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Execute VM work job:
com.cloud.vm.VmWorkStart{"accountId":4,"dcId":3,"vmId":619,"hostId":2,"handlerName":"VirtualMachineManagerImpl","clusterId":2,"userId":4,"podId":3,"rawParams":{}}
2025-06-20 02:48:14,146 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) orchestrating VM start for 'i-4-619-VM'
com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d set to null
2025-06-20 02:48:14,154 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
state transited from [Stopped] to [Starting] with event [StartRequested]. VM's
original host: null, new host: null, host before state transition: null
2025-06-20 02:48:14,155 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Successfully transitioned to start state for VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
reservation id = 469163ee-aecd-49cf-ab8d-543e7cb0236b
2025-06-20 02:48:14,160 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) advanceStart: DeploymentPlan is provided, using dcId:3, podId:
3, clusterId: 2, hostId: 2, poolId: null
2025-06-20 02:48:14,161 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Deploy avoids pods: null, clusters: null, hosts: null
2025-06-20 02:48:14,166 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) VM start attempt #1
2025-06-20 02:48:14,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Adding pods to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:14,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Adding clusters to avoid lists for non-explicit VM deployment:
[]
2025-06-20 02:48:14,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Adding hosts to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:14,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) DeploymentPlanner allocation algorithm: null
2025-06-20 02:48:14,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Trying to allocate a host and storage pools from dc:3,
pod:3,cluster:2, requested cpu: 6000, requested ram: (8.00 GB) 8589934592
2025-06-20 02:48:14,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Is ROOT volume READY (pool already allocated)?: No
2025-06-20 02:48:14,179 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) DeploymentPlan has host_id specified, choosing this host: 2
2025-06-20 02:48:14,180 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Looking for suitable pools for this host under zone: 3, pod:
3, cluster: 2
2025-06-20 02:48:14,183 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking suitable pools for volume (Id, Type): (614,ROOT)
2025-06-20 02:48:14,183 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) We need to allocate new storagepool for this volume
2025-06-20 02:48:14,184 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Calling StoragePoolAllocators to find suitable pools
2025-06-20 02:48:14,187 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking if storage pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}] is
suitable to disk [DskChr[ROOT|37580963840|]].
2025-06-20 02:48:14,190 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Volume [Vol[614|name=ROOT-619|vm=619|ROOT]] is not allocated
to any pool. Cannot check compatibility with pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}].
2025-06-20 02:48:14,190 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Storage pool ds-cloudstack (4) does not supply IOPS capacity,
assuming enough capacity
2025-06-20 02:48:14,192 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking pool 4 for storage, totalSize: 1099243192320,
usedBytes: 644175888384, usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:14,192 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Destination pool id: 4
2025-06-20 02:48:14,197 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Pool ID for the volume with ID 614 is null
2025-06-20 02:48:14,201 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Found storage pool ds-cloudstack of type VMFS with
overprovisioning factor 2
2025-06-20 02:48:14,201 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Total over provisioned capacity calculated is 2 * (1023.75 GB)
1099243192320
2025-06-20 02:48:14,201 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Total capacity of the pool ds-cloudstack with ID 4 is (1.9995
TB) 2198486384640
2025-06-20 02:48:14,202 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking pool: 4 for storage allocation , maxSize : (1.9995
TB) 2198486384640, totalAllocatedSize : (114.77 GB) 123228651520, askingSize :
(35.00 GB) 37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:14,202 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Found suitable local storage pool [Pool[4|VMFS]] to allocate
disk [DskChr[ROOT|37580963840|]] to it, adding to list.
2025-06-20 02:48:14,202 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) LocalStoragePoolAllocator is returning [1] suitable storage
pools
[[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}]].
2025-06-20 02:48:14,202 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Using allocation algorithm [random] to reorder pools.
2025-06-20 02:48:14,205 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking suitable pools for volume (Id, Type): (615,DATADISK)
2025-06-20 02:48:14,205 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) We need to allocate new storagepool for this volume
2025-06-20 02:48:14,206 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Calling StoragePoolAllocators to find suitable pools
2025-06-20 02:48:14,209 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking if storage pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}] is
suitable to disk [DskChr[DATADISK|37580963840|]].
2025-06-20 02:48:14,210 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Volume [Vol[615|name=DATA-619|vm=619|DATADISK]] is not
allocated to any pool. Cannot check compatibility with pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}].
2025-06-20 02:48:14,211 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Storage pool ds-cloudstack (4) does not supply IOPS capacity,
assuming enough capacity
2025-06-20 02:48:14,212 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking pool 4 for storage, totalSize: 1099243192320,
usedBytes: 644175888384, usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:14,212 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Destination pool id: 4
2025-06-20 02:48:14,216 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Pool ID for the volume with ID 615 is null
2025-06-20 02:48:14,219 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Found storage pool ds-cloudstack of type VMFS with
overprovisioning factor 2
2025-06-20 02:48:14,219 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Total over provisioned capacity calculated is 2 * (1023.75 GB)
1099243192320
2025-06-20 02:48:14,219 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Total capacity of the pool ds-cloudstack with ID 4 is (1.9995
TB) 2198486384640
2025-06-20 02:48:14,220 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking pool: 4 for storage allocation , maxSize : (1.9995
TB) 2198486384640, totalAllocatedSize : (114.77 GB) 123228651520, askingSize :
(35.00 GB) 37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:14,220 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Found suitable local storage pool [Pool[4|VMFS]] to allocate
disk [DskChr[DATADISK|37580963840|]] to it, adding to list.
2025-06-20 02:48:14,221 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) LocalStoragePoolAllocator is returning [1] suitable storage
pools
[[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}]].
2025-06-20 02:48:14,221 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Using allocation algorithm [random] to reorder pools.
2025-06-20 02:48:14,225 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Volume encryption requirements are met by provided host Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}
2025-06-20 02:48:14,225 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Trying to find a potenial host and associated storage pools
from the suitable host/pool lists for this VM
2025-06-20 02:48:14,227 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking if host: 2 can access any suitable storage pool for
volume: DATADISK
2025-06-20 02:48:14,228 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Host: 2 can access pool: 4
2025-06-20 02:48:14,230 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Storage pool ds-cloudstack (4) does not supply IOPS capacity,
assuming enough capacity
2025-06-20 02:48:14,232 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking pool 4 for storage, totalSize: 1099243192320,
usedBytes: 644175888384, usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:14,232 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Destination pool id: 4
2025-06-20 02:48:14,236 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Pool ID for the volume with ID 615 is null
2025-06-20 02:48:14,239 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Found storage pool ds-cloudstack of type VMFS with
overprovisioning factor 2
2025-06-20 02:48:14,240 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Total over provisioned capacity calculated is 2 * (1023.75 GB)
1099243192320
2025-06-20 02:48:14,240 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Total capacity of the pool ds-cloudstack with ID 4 is (1.9995
TB) 2198486384640
2025-06-20 02:48:14,240 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking pool: 4 for storage allocation , maxSize : (1.9995
TB) 2198486384640, totalAllocatedSize : (114.77 GB) 123228651520, askingSize :
(35.00 GB) 37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:14,241 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking if host: 2 can access any suitable storage pool for
volume: ROOT
2025-06-20 02:48:14,241 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Host: 2 can access pool: 4
2025-06-20 02:48:14,242 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Storage pool ds-cloudstack (4) does not supply IOPS capacity,
assuming enough capacity
2025-06-20 02:48:14,243 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking pool 4 for storage, totalSize: 1099243192320,
usedBytes: 644175888384, usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:14,243 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Destination pool id: 4
2025-06-20 02:48:14,249 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Pool ID for the volume with ID 614 is null
2025-06-20 02:48:14,253 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Found storage pool ds-cloudstack of type VMFS with
overprovisioning factor 2
2025-06-20 02:48:14,253 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Total over provisioned capacity calculated is 2 * (1023.75 GB)
1099243192320
2025-06-20 02:48:14,253 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Total capacity of the pool ds-cloudstack with ID 4 is (1.9995
TB) 2198486384640
2025-06-20 02:48:14,254 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking pool: 4 for storage allocation , maxSize : (1.9995
TB) 2198486384640, totalAllocatedSize : (114.77 GB) 123228651520, askingSize :
(35.00 GB) 37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:14,256 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Found a potential host id: 2 name: 192.168.80.81 and
associated storage pools for this VM
2025-06-20 02:48:14,256 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(3)-Pod(3)-Cluster(2)-Host(2)-Storage(Volume(614|ROOT-->Pool(4)Volume(615|DATADISK-->Pool(4))]
2025-06-20 02:48:14,258 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Deployment found - Attempt #1 - P0=VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"},
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(3)-Pod(3)-Cluster(2)-Host(2)-Storage(Volume(614|ROOT-->Pool(4)Volume(615|DATADISK-->Pool(4))]
2025-06-20 02:48:14,270 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
state transited from [Starting] to [Starting] with event [OperationRetry].
VM's original host: null, new host: Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"},
host before state transition: null
2025-06-20 02:48:14,279 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Hosts's actual total CPU: 191920 and CPU after applying
overprovisioning: 191920
2025-06-20 02:48:14,279 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) We are allocating VM, increasing the used capacity of this
host:2
2025-06-20 02:48:14,279 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Current Used CPU: 17500 , Free CPU:174420 ,Requested CPU: 6000
2025-06-20 02:48:14,279 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Current Used RAM: (21.50 GB) 23085449216 , Free RAM:(106.44
GB) 114287067136 ,Requested RAM: (8.00 GB) 8589934592
2025-06-20 02:48:14,279 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) CPU STATS after allocation: for host: 2, old used: 17500, old
reserved: 0, actual total: 191920, total with overprovisioning: 191920; new
used:23500, reserved:0; requested cpu:6000,alloc_from_last:false
2025-06-20 02:48:14,279 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) RAM STATS after allocation: for host: 2, old used: (21.50 GB)
23085449216, old reserved: (0 bytes) 0, total: (127.94 GB) 137372516352; new
used: (29.50 GB) 31675383808, reserved: (0 bytes) 0; requested mem: (8.00 GB)
8589934592,alloc_from_last:false
2025-06-20 02:48:14,280 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Host: 2 has cpu capability (cpu:80, speed:2399) to support
requested CPU: 4 and requested speed: 1500
2025-06-20 02:48:14,281 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking if host: 2 has enough capacity for requested CPU:
6000 and requested RAM: (8.00 GB) 8589934592 , cpuOverprovisioningFactor: 1.0
2025-06-20 02:48:14,282 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Hosts's actual total CPU: 191920 and CPU after applying
overprovisioning: 191920
2025-06-20 02:48:14,282 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) We need to allocate to the last host again, so checking if
there is enough reserved capacity
2025-06-20 02:48:14,282 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Reserved CPU: 0 , Requested CPU: 6000
2025-06-20 02:48:14,282 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Reserved RAM: (0 bytes) 0 , Requested RAM: (8.00 GB) 8589934592
2025-06-20 02:48:14,282 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) STATS: Failed to alloc resource from host: 2 reservedCpu: 0,
requested cpu: 6000, reservedMem: (0 bytes) 0, requested mem: (8.00 GB)
8589934592
2025-06-20 02:48:14,282 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Host does not have enough reserved CPU available, cannot
allocate to this host.
2025-06-20 02:48:14,282 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Checking if host: 2 has enough capacity for requested CPU:
6000 and requested RAM: (8.00 GB) 8589934592 , cpuOverprovisioningFactor: 1.0
2025-06-20 02:48:14,283 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Hosts's actual total CPU: 191920 and CPU after applying
overprovisioning: 191920
2025-06-20 02:48:14,283 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Free CPU: 174420 , Requested CPU: 6000
2025-06-20 02:48:14,283 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Free RAM: (106.44 GB) 114287067136 , Requested RAM: (8.00 GB)
8589934592
2025-06-20 02:48:14,283 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Host has enough CPU and RAM available
2025-06-20 02:48:14,283 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) STATS: Can alloc CPU from host: 2, used: 17500, reserved: 0,
actual total: 191920, total with overprovisioning: 191920; requested
cpu:6000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2025-06-20 02:48:14,283 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) STATS: Can alloc MEM from host: 2, used: (21.50 GB)
23085449216, reserved: (0 bytes) 0, total: (127.94 GB) 137372516352; requested
mem: (8.00 GB) 8589934592, alloc_from_last_host?: false ,
considerReservedCapacity?: true
2025-06-20 02:48:14,293 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Network id=214 is already implemented
2025-06-20 02:48:14,312 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Service SecurityGroup is not supported in the network id=214
2025-06-20 02:48:14,322 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Changing active number of nics for network id=214 on 1
2025-06-20 02:48:14,327 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Service SecurityGroup is not supported in the network id=214
2025-06-20 02:48:14,346 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) template 221 is already in store:2, type:Image
2025-06-20 02:48:14,391 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) copyAsync inspecting src type TEMPLATE copyAsync inspecting
dest type VOLUME
2025-06-20 02:48:14,415 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.CopyCommand
2025-06-20 02:48:14,419 DEBUG [c.c.h.XenServerGuru]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) We are returning the default host to execute commands because
the target hypervisor of the source data is not XenServer.
2025-06-20 02:48:14,424 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Seq 2-327073922937792462: Sending { Cmd , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"5ac6b8c4a7af3e3fbf2fb321fffd9dd7","uuid":"a1905274-90d1-4c9e-bbf1-6067fc93ffda","id":"221","format":"OVA","accountId":"4","hvm":"true","displayText":"This
is the template for Windows Server 2022 with custom (unconstrained)
offering.","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":"4","poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":"0","url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","isManaged":"false"}},"name":"221-
4-cdb53111-8212-38a5-91ec-2bece31fe4b9","size":"(35.00 GB)
37580963840","hypervisorType":"VMware","bootable":"false","uniqueName":"221-4-cdb53111-8212-38a5-91ec-2bece31fe4b9","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3fe7354e-5cad-4616-a1a2-996ff4486e2e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":"4","poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":"0","url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","fullCloneFlag":"true","diskProvisioningStrictnessFlag":"false","isManaged":"false"}},"name":"ROOT-619","size":"(35.00
GB)
37580963840","volumeId":"614","vmName":"i-4-619-VM","accountId":"4","format":"OVA","provisioningType":"FAT","poolId":"4","id":"614","deviceId":"0
","cacheMode":"WRITETHROUGH","hypervisorType":"VMware","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"executeInSequence":"true","options":{},"options2":{},"wait":"0","bypassHostMaintenance":"false"}}]
}
2025-06-20 02:48:14,426 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Seq 2-327073922937792462: Executing: { Cmd , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"5ac6b8c4a7af3e3fbf2fb321fffd9dd7","uuid":"a1905274-90d1-4c9e-bbf1-6067fc93ffda","id":"221","format":"OVA","accountId":"4","hvm":"true","displayText":"This
is the template for Windows Server 2022 with custom (unconstrained)
offering.","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":"4","poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":"0","url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","isManaged":"false"}},"name":"2
21-4-cdb53111-8212-38a5-91ec-2bece31fe4b9","size":"(35.00 GB)
37580963840","hypervisorType":"VMware","bootable":"false","uniqueName":"221-4-cdb53111-8212-38a5-91ec-2bece31fe4b9","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3fe7354e-5cad-4616-a1a2-996ff4486e2e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":"4","poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":"0","url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","fullCloneFlag":"true","diskProvisioningStrictnessFlag":"false","isManaged":"false"}},"name":"ROOT-619","size":"(35.00
GB)
37580963840","volumeId":"614","vmName":"i-4-619-VM","accountId":"4","format":"OVA","provisioningType":"FAT","poolId":"4","id":"614","deviceId"
:"0","cacheMode":"WRITETHROUGH","hypervisorType":"VMware","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"executeInSequence":"true","options":{},"options2":{},"wait":"0","bypassHostMaintenance":"false"}}]
}
2025-06-20 02:48:14,427 DEBUG [c.c.s.r.VmwareStorageProcessor]
(DirectAgent-345:ctx-11d49002 192.168.80.81, job-2149/job-2150, cmd:
CopyCommand) (logid:9556019e) VmwareProcessor instance - create full clone =
TRUE
2025-06-20 02:48:14,427 DEBUG [c.c.s.r.VmwareStorageProcessor]
(DirectAgent-345:ctx-11d49002 192.168.80.81, job-2149/job-2150, cmd:
CopyCommand) (logid:9556019e) VmwareProcessor instance -
diskProvisioningStrictness = FALSE
2025-06-20 02:48:14,427 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-345:ctx-11d49002 192.168.80.81, job-2149/job-2150, cmd:
CopyCommand) (logid:9556019e) VmwareStorageProcessor and
VmwareStorageSubsystemCommandHandler successfully reconfigured
2025-06-20 02:48:14,427 DEBUG [c.c.s.r.StorageSubsystemCommandHandlerBase]
(DirectAgent-345:ctx-11d49002 192.168.80.81, job-2149/job-2150, cmd:
CopyCommand) (logid:9556019e) Executing command CopyCommand:
[{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"5ac6b8c4a7af3e3fbf2fb321fffd9dd7","uuid":"a1905274-90d1-4c9e-bbf1-6067fc93ffda","id":221,"format":"OVA","accountId":4,"hvm":true,"displayText":"This
is the template for Windows Server 2022 with custom (unconstrained)
offering.","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":4,"poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":0,"url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","isManaged":false}},"name":"221-4-cdb53111-8212-38a5-91ec-2bece31fe4b9","size":37580963840,"hypervisorType":"VMware","bootable":false,"u
niqueName":"221-4-cdb53111-8212-38a5-91ec-2bece31fe4b9","directDownload":false,"deployAsIs":false,"followRedirects":false}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3fe7354e-5cad-4616-a1a2-996ff4486e2e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":4,"poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":0,"url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","fullCloneFlag":true,"diskProvisioningStrictnessFlag":false,"isManaged":false}},"name":"ROOT-619","size":37580963840,"volumeId":614,"vmName":"i-4-619-VM","accountId":4,"format":"OVA","provisioningType":"FAT","poolId":4,"id":614,"deviceId":0,"cacheMode":"WRITETHROUGH","hypervisorType":"VMware","directDownload":false,"deployAsIs":false,"followRedirects":false}},"executeInSequence":true,"options":
{},"options2":{},"wait":0,"bypassHostMaintenance":false}].
2025-06-20 02:48:14,540 INFO [c.c.h.v.u.VmwareHelper]
(DirectAgent-345:ctx-11d49002 192.168.80.81, job-2149/job-2150, cmd:
CopyCommand) (logid:9556019e) [ignored]failed to get message for exception:
Unable to find datastore in vSphere
2025-06-20 02:48:14,540 ERROR [c.c.h.v.r.VmwareResource]
(DirectAgent-345:ctx-11d49002 192.168.80.81, job-2149/job-2150, cmd:
CopyCommand) (logid:9556019e) CopyCommand failed due to [Exception:
java.lang.Exception
2025-06-20 02:48:14,541 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Seq 2-327073922937792462: Received: { Ans: , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 110, { CopyCmdAnswer } }
2025-06-20 02:48:14,550 ERROR [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Unable to create volume
[{"name":"ROOT-619","uuid":"3fe7354e-5cad-4616-a1a2-996ff4486e2e"}] due to
[CopyCommand failed due to [Exception: java.lang.Exception
2025-06-20 02:48:14,551 WARN [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Unable to contact resource.
2025-06-20 02:48:14,556 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Cleaning up resources for the vm VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
in Starting state
2025-06-20 02:48:14,569 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
is a [User], returning null for control Nic IP.
2025-06-20 02:48:14,576 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Seq 2-327073922937792463: Sending { Cmd , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeCleanup":"false","forceStop":"false","vlanToPersistenceMap":{"700":"true"},"volumesToDisconnect":[],"vmName":"i-4-619-VM","executeInSequence":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2025-06-20 02:48:14,576 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Seq 2-327073922937792463: Executing: { Cmd , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeCleanup":"false","forceStop":"false","vlanToPersistenceMap":{"700":"true"},"volumesToDisconnect":[],"vmName":"i-4-619-VM","executeInSequence":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2025-06-20 02:48:14,590 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-87:ctx-80d2d086 192.168.80.81, job-2149/job-2150, cmd:
StopCommand) (logid:9556019e) find VM i-4-619-VM on host
2025-06-20 02:48:14,590 INFO [c.c.h.v.m.HostMO]
(DirectAgent-87:ctx-80d2d086 192.168.80.81, job-2149/job-2150, cmd:
StopCommand) (logid:9556019e) VM i-4-619-VM not found in host cache
2025-06-20 02:48:14,590 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-87:ctx-80d2d086 192.168.80.81, job-2149/job-2150, cmd:
StopCommand) (logid:9556019e) load VM cache on host
2025-06-20 02:48:14,600 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-87:ctx-80d2d086 192.168.80.81, job-2149/job-2150, cmd:
StopCommand) (logid:9556019e) running query for 2 propertypaths and max null
objects
2025-06-20 02:48:14,608 DEBUG [c.c.h.v.m.BaseMO]
(DirectAgent-87:ctx-80d2d086 192.168.80.81, job-2149/job-2150, cmd:
StopCommand) (logid:9556019e) vmware result : null
2025-06-20 02:48:14,608 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-87:ctx-80d2d086 192.168.80.81, job-2149/job-2150, cmd:
StopCommand) (logid:9556019e) VM i-4-619-VM is no longer on the expected host
in vSphere
2025-06-20 02:48:14,609 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Seq 2-327073922937792463: Received: { Ans: , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 110, { StopAnswer } }
2025-06-20 02:48:14,623 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Service SecurityGroup is not supported in the network id=214
2025-06-20 02:48:14,627 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) The nic Nic
{"broadcastUri":"vlan:\/\/700","deviceId":0,"iPv4Address":null,"id":1863,"instanceId":619,"reservationId":"469163ee-aecd-49cf-ab8d-543e7cb0236b"}
on NicProfile
{"broadcastUri":null,"deviceId":0,"iPv4Address":null,"id":1863,"reservationId":"469163ee-aecd-49cf-ab8d-543e7cb0236b","vmId":619}
was released according to VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
by guru com.cloud.network.guru.ExternalGuestNetworkGuru@74884fdd, now updating
record.
2025-06-20 02:48:14,628 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Changing active number of nics for network id=214 on -1
2025-06-20 02:48:14,884 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Successfully released network resources for the VM VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
in Starting state
2025-06-20 02:48:14,893 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Successfully released storage resources for the VM VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
in Starting state
2025-06-20 02:48:14,893 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Successfully cleaned up resources for the VM VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
in Starting state
2025-06-20 02:48:14,894 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) VM start attempt #2
2025-06-20 02:48:14,901 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Adding pods to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:14,901 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Adding clusters to avoid lists for non-explicit VM deployment:
[]
2025-06-20 02:48:14,901 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Adding hosts to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:14,901 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) DeploymentPlanner allocation algorithm: null
2025-06-20 02:48:14,901 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Trying to allocate a host and storage pools from dc:3,
pod:3,cluster:2, requested cpu: 6000, requested ram: (8.00 GB) 8589934592
2025-06-20 02:48:14,901 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Is ROOT volume READY (pool already allocated)?: No
2025-06-20 02:48:14,905 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) DeploymentPlan has host_id specified, choosing this host: 2
2025-06-20 02:48:14,906 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) The specified host is in avoid set
2025-06-20 02:48:14,906 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Cannot deploy to specified host, returning.
2025-06-20 02:48:14,926 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
state transited from [Starting] to [Stopped] with event [OperationFailed].
VM's original host: null, new host: null, host before state transition: Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}
2025-06-20 02:48:14,932 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Hosts's actual total CPU: 191920 and CPU after applying
overprovisioning: 191920
2025-06-20 02:48:14,933 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Hosts's actual total RAM: (127.94 GB) 137372516352 and RAM
after applying overprovisioning: (127.94 GB) 137372516352
2025-06-20 02:48:14,933 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) release cpu from host: 2, old used: 23500,reserved: 0, actual
total: 191920, total with overprovisioning: 191920; new used: 17500,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2025-06-20 02:48:14,933 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) release mem from host: 2, old used: (29.50 GB)
31675383808,reserved: (0 bytes) 0, total: (127.94 GB) 137372516352; new used:
(21.50 GB) 23085449216,reserved:(0 bytes) 0; movedfromreserved:
false,moveToReserveredfalse
2025-06-20 02:48:14,947 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}Scope=interface
com.cloud.dc.DataCenter; id=3
2025-06-20 02:48:14,947 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150 ctx-01b8dfa1)
(logid:9556019e) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}Scope=interface
com.cloud.dc.DataCenter; id=3
2025-06-20 02:48:14,947 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e) Done
with run of VM work job: com.cloud.vm.VmWorkStart for VM 619, job origin: 2149
2025-06-20 02:48:14,947 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e) Unable
to complete AsyncJobVO: {id:2150, userId: 4, accountId: 4, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAEAAAAAAAAAAQAAAAAAAACa3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAA3BzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAJxAH4ACnBwcHNxAH
4ACAAAAAAAAAADcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 345049157785, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Fri Jun 20 02:48:12 UTC 2025, removed: null}, job
origin:2149
2025-06-20 02:48:14,955 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e) Complete
async job-2150, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uVk1PcAAAABACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvblZNT3AAAAAVAgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACQVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lb
nQgZm9yIFZNIGluc3RhbmNlIHsiaWQiOjYxOSwiaW5zdGFuY2VOYW1lIjoiaS00LTYxOS1WTSIsInR5cGUiOiJVc2VyIiwidXVpZCI6ImNkMWQzZGQzLTg0NzQtNGIxYy04MGIzLWEyZDlkMzRlMzM2NyJ9dXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAVc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAKTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AApMAAptb2R1bGVOYW1lcQB-AApMAA1tb2R1bGVWZXJzaW9ucQB-AAp4cAEAAATMdAADYXBwdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0cHBzcQB-ABEBAAAVbnEAfgATcQB-ABRxAH4AFXEAfgAWcHBzcQB-ABEC_____nB0AC1qZGsuaW50ZXJuYWwucmVmbGVjdC5OYXRpdmVNZXRob2RBY2Nlc3NvckltcGx0AB1OYXRpdmVNZXRob2RBY2Nlc3NvckltcGwuamF2YXQAB2ludm9rZTB0AAlqYXZhLmJhc2V0AAcxMS4wLjI3c3EAfgARAgAAAD5wcQB-ABlxAH4AGnQABmludm9rZXEAfgAccQB-AB1zcQB-ABECAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW
1wbC5qYXZhcQB-AB9xAH4AHHEAfgAdc3EAfgARAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AH3EAfgAccQB-AB1zcQB-ABEBAAAAaXEAfgATdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-ABEBAAAV6nEAfgATcQB-ABRxAH4AFXEAfgApcHBzcQB-ABEBAAAAZnEAfgATdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4AEQEAAAKOcQB-ABN0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4AEQEAAAAwcQB-ABN0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgARAQAAADdxAH4AE3QAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgARAQAAAGZxAH4AE3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZ
hdWx0TWFuYWdlZENvbnRleHRxAH4AOXQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgARAQAAADRxAH4AE3EAfgA8cQB-ADl0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgARAQAAAC1xAH4AE3QAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgA1cQB-ADZwcHNxAH4AEQEAAAJacQB-ABNxAH4AMHEAfgAxcQB-ADZwcHNxAH4AEQIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA6cQB-ABxxAH4AHXNxAH4AEQIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4ANnEAfgAccQB-AB1zcQB-ABECAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAccQB-AB1zcQB-ABECAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEtxAH4ANnEAfgAccQB-AB1zcQB-ABECAAADPXB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4ANnEAfgAccQB-AB1zcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4
cAAAEO9zcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHEAfgBVAAAAAAAAAAN2cgAXY29tLmNsb3VkLmRjLkRhdGFDZW50ZXIQUFRtA0UeAAIAAHhwAA
2025-06-20 02:48:14,956 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e) Publish
async job-2150 complete on message bus
2025-06-20 02:48:14,956 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e) Wake up
jobs related to job-2150
2025-06-20 02:48:14,956 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e) Update
db status for job-2150
2025-06-20 02:48:14,957 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e) Wake up
jobs joined with job-2150 and disjoin all subjobs created from job- 2150
2025-06-20 02:48:14,977 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e) Done
executing com.cloud.vm.VmWorkStart for job-2150
2025-06-20 02:48:14,978 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-29:ctx-94f5ba93 job-2149/job-2150) (logid:9556019e) Remove
job-2150 from job monitoring
2025-06-20 02:48:14,988 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) start
parameter value of enterHardwareSetup == null during processing of queued job
2025-06-20 02:48:14,996 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) Sync
job-2151 execution on object VmWorkJobQueue.619
2025-06-20 02:48:16,126 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:8f760c6e) Add
job-2151 into job monitoring
2025-06-20 02:48:16,134 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e)
Executing AsyncJobVO: {id:2151, userId: 4, accountId: 4, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAEAAAAAAAAAAQAAAAAAAACa3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc
3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status:
IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid:
345049157785, completeMsid: null, lastUpdated: null, lastPolled: null, created:
Fri Jun 20 02:48:14 UTC 2025, removed: null}
2025-06-20 02:48:16,135 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e) Run VM
work job: com.cloud.vm.VmWorkStart for VM 619, job origin: 2149
2025-06-20 02:48:16,138 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Execute VM work job:
com.cloud.vm.VmWorkStart{"accountId":4,"dcId":0,"vmId":619,"handlerName":"VirtualMachineManagerImpl","userId":4,"rawParams":{}}
2025-06-20 02:48:16,139 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) orchestrating VM start for 'i-4-619-VM'
com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d set to null
2025-06-20 02:48:16,147 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
state transited from [Stopped] to [Starting] with event [StartRequested]. VM's
original host: null, new host: null, host before state transition: null
2025-06-20 02:48:16,147 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Successfully transitioned to start state for VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
reservation id = 3937a520-5226-4f99-aa81-881b7482c30f
2025-06-20 02:48:16,154 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Deploy avoids pods: null, clusters: null, hosts: null
2025-06-20 02:48:16,159 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) VM start attempt #1
2025-06-20 02:48:16,167 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Adding pods to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:16,167 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Adding clusters to avoid lists for non-explicit VM deployment:
[]
2025-06-20 02:48:16,167 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Adding hosts to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:16,167 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) DeploymentPlanner allocation algorithm: null
2025-06-20 02:48:16,167 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Trying to allocate a host and storage pools from dc:3,
pod:null,cluster:null, requested cpu: 6000, requested ram: (8.00 GB) 8589934592
2025-06-20 02:48:16,167 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Is ROOT volume READY (pool already allocated)?: No
2025-06-20 02:48:16,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Deploy avoids pods: [], clusters: [], hosts: []
2025-06-20 02:48:16,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Deploy hosts with priorities {} , hosts have NORMAL priority
by default
2025-06-20 02:48:16,174 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Searching all possible resources under this Zone: 3
2025-06-20 02:48:16,176 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Listing clusters in order of aggregate capacity, that have (at
least one host with) enough CPU and RAM capacity under this Zone: 3
2025-06-20 02:48:16,180 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Removing from the clusterId list these clusters from avoid
set: []
2025-06-20 02:48:16,189 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking resources in Cluster: 2 under Pod: 3
2025-06-20 02:48:16,191 INFO [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Guest VM is requested with
Custom[UEFI] Boot Type false
2025-06-20 02:48:16,191 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Looking for hosts in zone [3], pod
[3], cluster [2].
2025-06-20 02:48:16,195 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) FirstFitAllocator has 1 hosts to
check for allocation: [Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}]
2025-06-20 02:48:16,200 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Found 1 hosts for allocation after
prioritization: [Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}]
2025-06-20 02:48:16,200 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Looking for speed=6000Mhz, Ram=8192
MB
2025-06-20 02:48:16,206 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Host: 2 has cpu capability (cpu:80,
speed:2399) to support requested CPU: 4 and requested speed: 1500
2025-06-20 02:48:16,206 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Checking if host: 2 has enough
capacity for requested CPU: 6000 and requested RAM: (8.00 GB) 8589934592 ,
cpuOverprovisioningFactor: 1.0
2025-06-20 02:48:16,208 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Hosts's actual total CPU: 191920 and
CPU after applying overprovisioning: 191920
2025-06-20 02:48:16,208 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Free CPU: 174420 , Requested CPU:
6000
2025-06-20 02:48:16,208 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Free RAM: (106.44 GB) 114287067136 ,
Requested RAM: (8.00 GB) 8589934592
2025-06-20 02:48:16,208 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Host has enough CPU and RAM available
2025-06-20 02:48:16,208 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) STATS: Can alloc CPU from host: 2,
used: 17500, reserved: 0, actual total: 191920, total with overprovisioning:
191920; requested cpu:6000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2025-06-20 02:48:16,208 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) STATS: Can alloc MEM from host: 2,
used: (21.50 GB) 23085449216, reserved: (0 bytes) 0, total: (127.94 GB)
137372516352; requested mem: (8.00 GB) 8589934592, alloc_from_last_host?: false
, considerReservedCapacity?: true
2025-06-20 02:48:16,208 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Found a suitable host, adding to
list: 2
2025-06-20 02:48:16,208 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Host Allocator returning 1 suitable
hosts
2025-06-20 02:48:16,209 INFO [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Re-ordering hosts [Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}]
by priorities {}
2025-06-20 02:48:16,209 INFO [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Hosts after re-ordering are: [Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}]
2025-06-20 02:48:16,212 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking suitable pools for volume (Id, Type): (614,ROOT)
2025-06-20 02:48:16,216 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Setting pool_id to NULL for volume id=614 as it is in
Allocated state
2025-06-20 02:48:16,216 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) We need to allocate new storagepool for this volume
2025-06-20 02:48:16,217 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Calling StoragePoolAllocators to find suitable pools
2025-06-20 02:48:16,223 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking if storage pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}] is
suitable to disk [DskChr[ROOT|37580963840|]].
2025-06-20 02:48:16,226 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Volume [Vol[614|name=ROOT-619|vm=619|ROOT]] is not allocated
to any pool. Cannot check compatibility with pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}].
2025-06-20 02:48:16,228 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Storage pool ds-cloudstack (4) does not supply IOPS capacity,
assuming enough capacity
2025-06-20 02:48:16,229 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking pool 4 for storage, totalSize: 1099243192320,
usedBytes: 644175888384, usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:16,229 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Destination pool id: 4
2025-06-20 02:48:16,235 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Pool ID for the volume with ID 614 is null
2025-06-20 02:48:16,239 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Found storage pool ds-cloudstack of type VMFS with
overprovisioning factor 2
2025-06-20 02:48:16,239 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Total over provisioned capacity calculated is 2 * (1023.75 GB)
1099243192320
2025-06-20 02:48:16,239 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Total capacity of the pool ds-cloudstack with ID 4 is (1.9995
TB) 2198486384640
2025-06-20 02:48:16,240 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking pool: 4 for storage allocation , maxSize : (1.9995
TB) 2198486384640, totalAllocatedSize : (114.77 GB) 123228651520, askingSize :
(35.00 GB) 37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:16,240 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Found suitable local storage pool [Pool[4|VMFS]] to allocate
disk [DskChr[ROOT|37580963840|]] to it, adding to list.
2025-06-20 02:48:16,241 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) LocalStoragePoolAllocator is returning [1] suitable storage
pools
[[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}]].
2025-06-20 02:48:16,241 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Using allocation algorithm [random] to reorder pools.
2025-06-20 02:48:16,244 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking suitable pools for volume (Id, Type): (615,DATADISK)
2025-06-20 02:48:16,245 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) We need to allocate new storagepool for this volume
2025-06-20 02:48:16,245 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Calling StoragePoolAllocators to find suitable pools
2025-06-20 02:48:16,251 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking if storage pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}] is
suitable to disk [DskChr[DATADISK|37580963840|]].
2025-06-20 02:48:16,253 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Volume [Vol[615|name=DATA-619|vm=619|DATADISK]] is not
allocated to any pool. Cannot check compatibility with pool
[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}].
2025-06-20 02:48:16,254 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Storage pool ds-cloudstack (4) does not supply IOPS capacity,
assuming enough capacity
2025-06-20 02:48:16,255 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking pool 4 for storage, totalSize: 1099243192320,
usedBytes: 644175888384, usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:16,255 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Destination pool id: 4
2025-06-20 02:48:16,260 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Pool ID for the volume with ID 615 is null
2025-06-20 02:48:16,265 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Found storage pool ds-cloudstack of type VMFS with
overprovisioning factor 2
2025-06-20 02:48:16,265 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Total over provisioned capacity calculated is 2 * (1023.75 GB)
1099243192320
2025-06-20 02:48:16,265 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Total capacity of the pool ds-cloudstack with ID 4 is (1.9995
TB) 2198486384640
2025-06-20 02:48:16,266 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking pool: 4 for storage allocation , maxSize : (1.9995
TB) 2198486384640, totalAllocatedSize : (114.77 GB) 123228651520, askingSize :
(35.00 GB) 37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:16,266 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Found suitable local storage pool [Pool[4|VMFS]] to allocate
disk [DskChr[DATADISK|37580963840|]] to it, adding to list.
2025-06-20 02:48:16,267 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) LocalStoragePoolAllocator is returning [1] suitable storage
pools
[[{"name":"ds-cloudstack","uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9"}]].
2025-06-20 02:48:16,267 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Using allocation algorithm [random] to reorder pools.
2025-06-20 02:48:16,270 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Trying to find a potenial host and associated storage pools
from the suitable host/pool lists for this VM
2025-06-20 02:48:16,271 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking if host: 2 can access any suitable storage pool for
volume: DATADISK
2025-06-20 02:48:16,272 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Host: 2 can access pool: 4
2025-06-20 02:48:16,273 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Storage pool ds-cloudstack (4) does not supply IOPS capacity,
assuming enough capacity
2025-06-20 02:48:16,274 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking pool 4 for storage, totalSize: 1099243192320,
usedBytes: 644175888384, usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:16,274 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Destination pool id: 4
2025-06-20 02:48:16,277 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Pool ID for the volume with ID 615 is null
2025-06-20 02:48:16,280 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Found storage pool ds-cloudstack of type VMFS with
overprovisioning factor 2
2025-06-20 02:48:16,280 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Total over provisioned capacity calculated is 2 * (1023.75 GB)
1099243192320
2025-06-20 02:48:16,280 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Total capacity of the pool ds-cloudstack with ID 4 is (1.9995
TB) 2198486384640
2025-06-20 02:48:16,281 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking pool: 4 for storage allocation , maxSize : (1.9995
TB) 2198486384640, totalAllocatedSize : (114.77 GB) 123228651520, askingSize :
(35.00 GB) 37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:16,281 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking if host: 2 can access any suitable storage pool for
volume: ROOT
2025-06-20 02:48:16,282 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Host: 2 can access pool: 4
2025-06-20 02:48:16,283 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Storage pool ds-cloudstack (4) does not supply IOPS capacity,
assuming enough capacity
2025-06-20 02:48:16,284 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking pool 4 for storage, totalSize: 1099243192320,
usedBytes: 644175888384, usedPct: 0.5860176282051283, disable threshold: 0.85
2025-06-20 02:48:16,284 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Destination pool id: 4
2025-06-20 02:48:16,289 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Pool ID for the volume with ID 614 is null
2025-06-20 02:48:16,294 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Found storage pool ds-cloudstack of type VMFS with
overprovisioning factor 2
2025-06-20 02:48:16,294 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Total over provisioned capacity calculated is 2 * (1023.75 GB)
1099243192320
2025-06-20 02:48:16,294 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Total capacity of the pool ds-cloudstack with ID 4 is (1.9995
TB) 2198486384640
2025-06-20 02:48:16,295 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking pool: 4 for storage allocation , maxSize : (1.9995
TB) 2198486384640, totalAllocatedSize : (114.77 GB) 123228651520, askingSize :
(35.00 GB) 37580963840, allocated disable threshold: 0.85
2025-06-20 02:48:16,297 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Found a potential host id: 2 name: 192.168.80.81 and
associated storage pools for this VM
2025-06-20 02:48:16,298 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(3)-Pod(3)-Cluster(2)-Host(2)-Storage(Volume(614|ROOT-->Pool(4)Volume(615|DATADISK-->Pool(4))]
2025-06-20 02:48:16,299 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Deployment found - Attempt #1 - P0=VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"},
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(3)-Pod(3)-Cluster(2)-Host(2)-Storage(Volume(614|ROOT-->Pool(4)Volume(615|DATADISK-->Pool(4))]
2025-06-20 02:48:16,312 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
state transited from [Starting] to [Starting] with event [OperationRetry].
VM's original host: null, new host: Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"},
host before state transition: null
2025-06-20 02:48:16,319 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Hosts's actual total CPU: 191920 and CPU after applying
overprovisioning: 191920
2025-06-20 02:48:16,319 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) We are allocating VM, increasing the used capacity of this
host:2
2025-06-20 02:48:16,319 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Current Used CPU: 17500 , Free CPU:174420 ,Requested CPU: 6000
2025-06-20 02:48:16,319 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Current Used RAM: (21.50 GB) 23085449216 , Free RAM:(106.44
GB) 114287067136 ,Requested RAM: (8.00 GB) 8589934592
2025-06-20 02:48:16,319 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) CPU STATS after allocation: for host: 2, old used: 17500, old
reserved: 0, actual total: 191920, total with overprovisioning: 191920; new
used:23500, reserved:0; requested cpu:6000,alloc_from_last:false
2025-06-20 02:48:16,319 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) RAM STATS after allocation: for host: 2, old used: (21.50 GB)
23085449216, old reserved: (0 bytes) 0, total: (127.94 GB) 137372516352; new
used: (29.50 GB) 31675383808, reserved: (0 bytes) 0; requested mem: (8.00 GB)
8589934592,alloc_from_last:false
2025-06-20 02:48:16,321 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Host: 2 has cpu capability (cpu:80, speed:2399) to support
requested CPU: 4 and requested speed: 1500
2025-06-20 02:48:16,321 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking if host: 2 has enough capacity for requested CPU:
6000 and requested RAM: (8.00 GB) 8589934592 , cpuOverprovisioningFactor: 1.0
2025-06-20 02:48:16,322 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Hosts's actual total CPU: 191920 and CPU after applying
overprovisioning: 191920
2025-06-20 02:48:16,322 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) We need to allocate to the last host again, so checking if
there is enough reserved capacity
2025-06-20 02:48:16,322 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Reserved CPU: 0 , Requested CPU: 6000
2025-06-20 02:48:16,322 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Reserved RAM: (0 bytes) 0 , Requested RAM: (8.00 GB) 8589934592
2025-06-20 02:48:16,322 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) STATS: Failed to alloc resource from host: 2 reservedCpu: 0,
requested cpu: 6000, reservedMem: (0 bytes) 0, requested mem: (8.00 GB)
8589934592
2025-06-20 02:48:16,322 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Host does not have enough reserved CPU available, cannot
allocate to this host.
2025-06-20 02:48:16,322 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking if host: 2 has enough capacity for requested CPU:
6000 and requested RAM: (8.00 GB) 8589934592 , cpuOverprovisioningFactor: 1.0
2025-06-20 02:48:16,324 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Hosts's actual total CPU: 191920 and CPU after applying
overprovisioning: 191920
2025-06-20 02:48:16,324 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Free CPU: 174420 , Requested CPU: 6000
2025-06-20 02:48:16,324 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Free RAM: (106.44 GB) 114287067136 , Requested RAM: (8.00 GB)
8589934592
2025-06-20 02:48:16,324 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Host has enough CPU and RAM available
2025-06-20 02:48:16,324 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) STATS: Can alloc CPU from host: 2, used: 17500, reserved: 0,
actual total: 191920, total with overprovisioning: 191920; requested
cpu:6000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2025-06-20 02:48:16,324 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) STATS: Can alloc MEM from host: 2, used: (21.50 GB)
23085449216, reserved: (0 bytes) 0, total: (127.94 GB) 137372516352; requested
mem: (8.00 GB) 8589934592, alloc_from_last_host?: false ,
considerReservedCapacity?: true
2025-06-20 02:48:16,334 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Network id=214 is already implemented
2025-06-20 02:48:16,365 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Service SecurityGroup is not supported in the network id=214
2025-06-20 02:48:16,370 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Changing active number of nics for network id=214 on 1
2025-06-20 02:48:16,376 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Service SecurityGroup is not supported in the network id=214
2025-06-20 02:48:16,396 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) template 221 is already in store:2, type:Image
2025-06-20 02:48:16,439 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) copyAsync inspecting src type TEMPLATE copyAsync inspecting
dest type VOLUME
2025-06-20 02:48:16,465 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.CopyCommand
2025-06-20 02:48:16,468 DEBUG [c.c.h.XenServerGuru]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) We are returning the default host to execute commands because
the target hypervisor of the source data is not XenServer.
2025-06-20 02:48:16,472 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Seq 2-327073922937792465: Sending { Cmd , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"5ac6b8c4a7af3e3fbf2fb321fffd9dd7","uuid":"a1905274-90d1-4c9e-bbf1-6067fc93ffda","id":"221","format":"OVA","accountId":"4","hvm":"true","displayText":"This
is the template for Windows Server 2022 with custom (unconstrained)
offering.","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":"4","poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":"0","url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","isManaged":"false"}},"name":"221-
4-cdb53111-8212-38a5-91ec-2bece31fe4b9","size":"(35.00 GB)
37580963840","hypervisorType":"VMware","bootable":"false","uniqueName":"221-4-cdb53111-8212-38a5-91ec-2bece31fe4b9","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3fe7354e-5cad-4616-a1a2-996ff4486e2e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":"4","poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":"0","url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","fullCloneFlag":"true","diskProvisioningStrictnessFlag":"false","isManaged":"false"}},"name":"ROOT-619","size":"(35.00
GB)
37580963840","volumeId":"614","vmName":"i-4-619-VM","accountId":"4","format":"OVA","provisioningType":"FAT","poolId":"4","id":"614","deviceId":"0
","cacheMode":"WRITETHROUGH","hypervisorType":"VMware","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"executeInSequence":"true","options":{},"options2":{},"wait":"0","bypassHostMaintenance":"false"}}]
}
2025-06-20 02:48:16,474 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Seq 2-327073922937792465: Executing: { Cmd , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"5ac6b8c4a7af3e3fbf2fb321fffd9dd7","uuid":"a1905274-90d1-4c9e-bbf1-6067fc93ffda","id":"221","format":"OVA","accountId":"4","hvm":"true","displayText":"This
is the template for Windows Server 2022 with custom (unconstrained)
offering.","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":"4","poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":"0","url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","isManaged":"false"}},"name":"2
21-4-cdb53111-8212-38a5-91ec-2bece31fe4b9","size":"(35.00 GB)
37580963840","hypervisorType":"VMware","bootable":"false","uniqueName":"221-4-cdb53111-8212-38a5-91ec-2bece31fe4b9","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3fe7354e-5cad-4616-a1a2-996ff4486e2e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":"4","poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":"0","url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","fullCloneFlag":"true","diskProvisioningStrictnessFlag":"false","isManaged":"false"}},"name":"ROOT-619","size":"(35.00
GB)
37580963840","volumeId":"614","vmName":"i-4-619-VM","accountId":"4","format":"OVA","provisioningType":"FAT","poolId":"4","id":"614","deviceId"
:"0","cacheMode":"WRITETHROUGH","hypervisorType":"VMware","directDownload":"false","deployAsIs":"false","followRedirects":"false"}},"executeInSequence":"true","options":{},"options2":{},"wait":"0","bypassHostMaintenance":"false"}}]
}
2025-06-20 02:48:16,475 DEBUG [c.c.s.r.VmwareStorageProcessor]
(DirectAgent-22:ctx-ea084317 192.168.80.81, job-2149/job-2151, cmd:
CopyCommand) (logid:9556019e) VmwareProcessor instance - create full clone =
TRUE
2025-06-20 02:48:16,475 DEBUG [c.c.s.r.VmwareStorageProcessor]
(DirectAgent-22:ctx-ea084317 192.168.80.81, job-2149/job-2151, cmd:
CopyCommand) (logid:9556019e) VmwareProcessor instance -
diskProvisioningStrictness = FALSE
2025-06-20 02:48:16,475 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-22:ctx-ea084317 192.168.80.81, job-2149/job-2151, cmd:
CopyCommand) (logid:9556019e) VmwareStorageProcessor and
VmwareStorageSubsystemCommandHandler successfully reconfigured
2025-06-20 02:48:16,475 DEBUG [c.c.s.r.StorageSubsystemCommandHandlerBase]
(DirectAgent-22:ctx-ea084317 192.168.80.81, job-2149/job-2151, cmd:
CopyCommand) (logid:9556019e) Executing command CopyCommand:
[{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"5ac6b8c4a7af3e3fbf2fb321fffd9dd7","uuid":"a1905274-90d1-4c9e-bbf1-6067fc93ffda","id":221,"format":"OVA","accountId":4,"hvm":true,"displayText":"This
is the template for Windows Server 2022 with custom (unconstrained)
offering.","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":4,"poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":0,"url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","isManaged":false}},"name":"221-4-cdb53111-8212-38a5-91ec-2bece31fe4b9","size":37580963840,"hypervisorType":"VMware","bootable":false,"un
iqueName":"221-4-cdb53111-8212-38a5-91ec-2bece31fe4b9","directDownload":false,"deployAsIs":false,"followRedirects":false}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3fe7354e-5cad-4616-a1a2-996ff4486e2e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c651d575-bfbc-401e-bb0c-b23963a38df9","name":"ds-cloudstack","id":4,"poolType":"VMFS","host":"VMFS
datastore: datastore-16","path":"datastore-16","port":0,"url":"VMFS://VMFS
datastore:
datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9","fullCloneFlag":true,"diskProvisioningStrictnessFlag":false,"isManaged":false}},"name":"ROOT-619","size":37580963840,"volumeId":614,"vmName":"i-4-619-VM","accountId":4,"format":"OVA","provisioningType":"FAT","poolId":4,"id":614,"deviceId":0,"cacheMode":"WRITETHROUGH","hypervisorType":"VMware","directDownload":false,"deployAsIs":false,"followRedirects":false}},"executeInSequence":true,"options":{
},"options2":{},"wait":0,"bypassHostMaintenance":false}].
2025-06-20 02:48:16,581 INFO [c.c.h.v.u.VmwareHelper]
(DirectAgent-22:ctx-ea084317 192.168.80.81, job-2149/job-2151, cmd:
CopyCommand) (logid:9556019e) [ignored]failed to get message for exception:
Unable to find datastore in vSphere
2025-06-20 02:48:16,581 ERROR [c.c.h.v.r.VmwareResource]
(DirectAgent-22:ctx-ea084317 192.168.80.81, job-2149/job-2151, cmd:
CopyCommand) (logid:9556019e) CopyCommand failed due to [Exception:
java.lang.Exception
2025-06-20 02:48:16,582 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Seq 2-327073922937792465: Received: { Ans: , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 110, { CopyCmdAnswer } }
2025-06-20 02:48:16,590 ERROR [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Unable to create volume
[{"name":"ROOT-619","uuid":"3fe7354e-5cad-4616-a1a2-996ff4486e2e"}] due to
[CopyCommand failed due to [Exception: java.lang.Exception
2025-06-20 02:48:16,603 WARN [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Unable to contact resource.
2025-06-20 02:48:16,608 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Cleaning up resources for the vm VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
in Starting state
2025-06-20 02:48:16,624 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
is a [User], returning null for control Nic IP.
2025-06-20 02:48:16,629 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Seq 2-327073922937792466: Sending { Cmd , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeCleanup":"false","forceStop":"false","vlanToPersistenceMap":{"700":"true"},"volumesToDisconnect":[],"vmName":"i-4-619-VM","executeInSequence":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2025-06-20 02:48:16,630 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Seq 2-327073922937792466: Executing: { Cmd , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeCleanup":"false","forceStop":"false","vlanToPersistenceMap":{"700":"true"},"volumesToDisconnect":[],"vmName":"i-4-619-VM","executeInSequence":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2025-06-20 02:48:16,641 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-347:ctx-e73f7263 192.168.80.81, job-2149/job-2151, cmd:
StopCommand) (logid:9556019e) find VM i-4-619-VM on host
2025-06-20 02:48:16,641 INFO [c.c.h.v.m.HostMO]
(DirectAgent-347:ctx-e73f7263 192.168.80.81, job-2149/job-2151, cmd:
StopCommand) (logid:9556019e) VM i-4-619-VM not found in host cache
2025-06-20 02:48:16,641 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-347:ctx-e73f7263 192.168.80.81, job-2149/job-2151, cmd:
StopCommand) (logid:9556019e) load VM cache on host
2025-06-20 02:48:16,652 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-347:ctx-e73f7263 192.168.80.81, job-2149/job-2151, cmd:
StopCommand) (logid:9556019e) running query for 2 propertypaths and max null
objects
2025-06-20 02:48:16,661 DEBUG [c.c.h.v.m.BaseMO]
(DirectAgent-347:ctx-e73f7263 192.168.80.81, job-2149/job-2151, cmd:
StopCommand) (logid:9556019e) vmware result : null
2025-06-20 02:48:16,661 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-347:ctx-e73f7263 192.168.80.81, job-2149/job-2151, cmd:
StopCommand) (logid:9556019e) VM i-4-619-VM is no longer on the expected host
in vSphere
2025-06-20 02:48:16,661 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Seq 2-327073922937792466: Received: { Ans: , MgmtId:
345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 110, { StopAnswer } }
2025-06-20 02:48:16,672 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Service SecurityGroup is not supported in the network id=214
2025-06-20 02:48:16,676 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) The nic Nic
{"broadcastUri":"vlan:\/\/700","deviceId":0,"iPv4Address":null,"id":1863,"instanceId":619,"reservationId":"3937a520-5226-4f99-aa81-881b7482c30f"}
on NicProfile
{"broadcastUri":null,"deviceId":0,"iPv4Address":null,"id":1863,"reservationId":"3937a520-5226-4f99-aa81-881b7482c30f","vmId":619}
was released according to VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
by guru com.cloud.network.guru.ExternalGuestNetworkGuru@74884fdd, now updating
record.
2025-06-20 02:48:16,677 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Changing active number of nics for network id=214 on -1
2025-06-20 02:48:16,685 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Successfully released network resources for the VM VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
in Starting state
2025-06-20 02:48:16,696 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Successfully released storage resources for the VM VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
in Starting state
2025-06-20 02:48:16,697 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Successfully cleaned up resources for the VM VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
in Starting state
2025-06-20 02:48:16,698 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) VM start attempt #2
2025-06-20 02:48:16,707 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Adding pods to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:16,707 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Adding clusters to avoid lists for non-explicit VM deployment:
[]
2025-06-20 02:48:16,707 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Adding hosts to avoid lists for non-explicit VM deployment: []
2025-06-20 02:48:16,707 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) DeploymentPlanner allocation algorithm: null
2025-06-20 02:48:16,707 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Trying to allocate a host and storage pools from dc:3,
pod:null,cluster:null, requested cpu: 6000, requested ram: (8.00 GB) 8589934592
2025-06-20 02:48:16,707 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Is ROOT volume READY (pool already allocated)?: No
2025-06-20 02:48:16,717 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Deploy avoids pods: [], clusters: [], hosts: [2]
2025-06-20 02:48:16,717 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Deploy hosts with priorities {} , hosts have NORMAL priority
by default
2025-06-20 02:48:16,718 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Searching all possible resources under this Zone: 3
2025-06-20 02:48:16,720 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Listing clusters in order of aggregate capacity, that have (at
least one host with) enough CPU and RAM capacity under this Zone: 3
2025-06-20 02:48:16,723 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Removing from the clusterId list these clusters from avoid
set: []
2025-06-20 02:48:16,731 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Checking resources in Cluster: 2 under Pod: 3
2025-06-20 02:48:16,732 INFO [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Guest VM is requested with
Custom[UEFI] Boot Type false
2025-06-20 02:48:16,732 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Looking for hosts in zone [3], pod
[3], cluster [2].
2025-06-20 02:48:16,736 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) FirstFitAllocator has 1 hosts to
check for allocation: [Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}]
2025-06-20 02:48:16,739 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Found 1 hosts for allocation after
prioritization: [Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}]
2025-06-20 02:48:16,739 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Looking for speed=6000Mhz, Ram=8192
MB
2025-06-20 02:48:16,739 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Host name: 192.168.80.81, hostId: 2
is in avoid set, skipping this and trying other available hosts
2025-06-20 02:48:16,739 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858
FirstFitRoutingAllocator) (logid:9556019e) Host Allocator returning 0 suitable
hosts
2025-06-20 02:48:16,739 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) No suitable hosts found.
2025-06-20 02:48:16,740 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) No suitable hosts found under this Cluster: 2
2025-06-20 02:48:16,741 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Could not find suitable Deployment Destination for this VM
under any clusters, returning.
2025-06-20 02:48:16,742 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Searching all possible resources under this Zone: 3
2025-06-20 02:48:16,744 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Listing clusters in order of aggregate capacity, that have (at
least one host with) enough CPU and RAM capacity under this Zone: 3
2025-06-20 02:48:16,747 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Removing from the clusterId list these clusters from avoid
set: [2]
2025-06-20 02:48:16,748 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) No clusters found after removing disabled clusters and
clusters in avoid list, returning.
2025-06-20 02:48:16,766 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
state transited from [Starting] to [Stopped] with event [OperationFailed].
VM's original host: null, new host: null, host before state transition: Host
{"id":2,"name":"192.168.80.81","type":"Routing","uuid":"2c7b726b-c9b7-4b12-9c27-28a5f58aede0"}
2025-06-20 02:48:16,773 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Hosts's actual total CPU: 191920 and CPU after applying
overprovisioning: 191920
2025-06-20 02:48:16,773 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Hosts's actual total RAM: (127.94 GB) 137372516352 and RAM
after applying overprovisioning: (127.94 GB) 137372516352
2025-06-20 02:48:16,774 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) release cpu from host: 2, old used: 23500,reserved: 0, actual
total: 191920, total with overprovisioning: 191920; new used: 17500,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2025-06-20 02:48:16,774 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) release mem from host: 2, old used: (29.50 GB)
31675383808,reserved: (0 bytes) 0, total: (127.94 GB) 137372516352; new used:
(21.50 GB) 23085449216,reserved:(0 bytes) 0; movedfromreserved:
false,moveToReserveredfalse
2025-06-20 02:48:16,786 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}Scope=interface
com.cloud.dc.DataCenter; id=3
2025-06-20 02:48:16,786 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151 ctx-ff58a858)
(logid:9556019e) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}Scope=interface
com.cloud.dc.DataCenter; id=3
2025-06-20 02:48:16,786 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e) Done
with run of VM work job: com.cloud.vm.VmWorkStart for VM 619, job origin: 2149
2025-06-20 02:48:16,786 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e) Unable
to complete AsyncJobVO: {id:2151, userId: 4, accountId: 4, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAEAAAAAAAAAAQAAAAAAAACa3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbV
Bhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status:
IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid:
345049157785, completeMsid: null, lastUpdated: null, lastPolled: null, created:
Fri Jun 20 02:48:14 UTC 2025, removed: null}, job origin:2149
2025-06-20 02:48:16,789 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e) Complete
async job-2151, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uVk1PcAAAABACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvblZNT3AAAAAVAgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACQVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lb
nQgZm9yIFZNIGluc3RhbmNlIHsiaWQiOjYxOSwiaW5zdGFuY2VOYW1lIjoiaS00LTYxOS1WTSIsInR5cGUiOiJVc2VyIiwidXVpZCI6ImNkMWQzZGQzLTg0NzQtNGIxYy04MGIzLWEyZDlkMzRlMzM2NyJ9dXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAVc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAKTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AApMAAptb2R1bGVOYW1lcQB-AApMAA1tb2R1bGVWZXJzaW9ucQB-AAp4cAEAAATMdAADYXBwdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0cHBzcQB-ABEBAAAVbnEAfgATcQB-ABRxAH4AFXEAfgAWcHBzcQB-ABEC_____nB0AC1qZGsuaW50ZXJuYWwucmVmbGVjdC5OYXRpdmVNZXRob2RBY2Nlc3NvckltcGx0AB1OYXRpdmVNZXRob2RBY2Nlc3NvckltcGwuamF2YXQAB2ludm9rZTB0AAlqYXZhLmJhc2V0AAcxMS4wLjI3c3EAfgARAgAAAD5wcQB-ABlxAH4AGnQABmludm9rZXEAfgAccQB-AB1zcQB-ABECAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW
1wbC5qYXZhcQB-AB9xAH4AHHEAfgAdc3EAfgARAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AH3EAfgAccQB-AB1zcQB-ABEBAAAAaXEAfgATdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-ABEBAAAV6nEAfgATcQB-ABRxAH4AFXEAfgApcHBzcQB-ABEBAAAAZnEAfgATdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4AEQEAAAKOcQB-ABN0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4AEQEAAAAwcQB-ABN0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgARAQAAADdxAH4AE3QAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgARAQAAAGZxAH4AE3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZ
hdWx0TWFuYWdlZENvbnRleHRxAH4AOXQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgARAQAAADRxAH4AE3EAfgA8cQB-ADl0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgARAQAAAC1xAH4AE3QAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgA1cQB-ADZwcHNxAH4AEQEAAAJacQB-ABNxAH4AMHEAfgAxcQB-ADZwcHNxAH4AEQIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA6cQB-ABxxAH4AHXNxAH4AEQIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4ANnEAfgAccQB-AB1zcQB-ABECAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAccQB-AB1zcQB-ABECAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEtxAH4ANnEAfgAccQB-AB1zcQB-ABECAAADPXB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4ANnEAfgAccQB-AB1zcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4
cAAAEO9zcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHEAfgBVAAAAAAAAAAN2cgAXY29tLmNsb3VkLmRjLkRhdGFDZW50ZXIQUFRtA0UeAAIAAHhwAA
2025-06-20 02:48:16,790 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e) Publish
async job-2151 complete on message bus
2025-06-20 02:48:16,790 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e) Wake up
jobs related to job-2151
2025-06-20 02:48:16,790 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e) Update
db status for job-2151
2025-06-20 02:48:16,791 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e) Wake up
jobs joined with job-2151 and disjoin all subjobs created from job- 2151
2025-06-20 02:48:16,805 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e) Done
executing com.cloud.vm.VmWorkStart for job-2151
2025-06-20 02:48:16,807 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-30:ctx-6fdefcee job-2149/job-2151) (logid:9556019e) Remove
job-2151 from job monitoring
2025-06-20 02:48:16,819 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Destroying vm VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
as it failed to create on Host with Id:null
2025-06-20 02:48:16,837 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) VM
instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}
state transited from [Stopped] to [Error] with event [OperationFailedToError].
VM's original host: null, new host: null, host before state transition: null
2025-06-20 02:48:16,839 DEBUG [c.c.s.d.VolumeDaoImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Removing volume 614 from DB
2025-06-20 02:48:16,849 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Updating resource Type = volume count for Account = 4 Operation = decreasing
Amount = 1
2025-06-20 02:48:16,855 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Updating resource Type = primary_storage count for Account = 4 Operation =
decreasing Amount = (35.00 GB) 37580963840
2025-06-20 02:48:16,868 DEBUG [c.c.s.d.VolumeDaoImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Removing volume 615 from DB
2025-06-20 02:48:16,877 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Updating resource Type = volume count for Account = 4 Operation = decreasing
Amount = 1
2025-06-20 02:48:16,882 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Updating resource Type = primary_storage count for Account = 4 Operation =
decreasing Amount = (35.00 GB) 37580963840
2025-06-20 02:48:16,894 WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
alertType=[8] dataCenterId=[3] podId=[null] clusterId=[null] message=[Failed to
deploy Vm with Id: 619, on Host with Id: null].
2025-06-20 02:48:16,902 WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e) No
recipients set in global setting 'alert.email.addresses', skipping sending
alert with subject [Failed to deploy Vm with Id: 619, on Host with Id: null]
and content [Failed to deploy Vm with Id: 619, on Host with Id: null].
2025-06-20 02:48:16,904 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Updating resource Type = user_vm count for Account = 4 Operation = decreasing
Amount = 1
2025-06-20 02:48:16,910 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Updating resource Type = cpu count for Account = 4 Operation = decreasing
Amount = 4
2025-06-20 02:48:16,916 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149 ctx-e75ebfd4) (logid:9556019e)
Updating resource Type = memory count for Account = 4 Operation = decreasing
Amount = 8192
2025-06-20 02:48:16,930 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-18:ctx-a674dfb9 job-2149) (logid:9556019e) Unexpected
exception while executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
2025-06-20 02:48:16,932 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149) (logid:9556019e) Complete async
job-2149, jobStatus: FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Unable
to start a VM [cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367] due to [Unable to create
a deployment for VM instance
{"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}]."}
2025-06-20 02:48:16,933 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149) (logid:9556019e) Publish async
job-2149 complete on message bus
2025-06-20 02:48:16,933 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149) (logid:9556019e) Wake up jobs
related to job-2149
2025-06-20 02:48:16,933 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149) (logid:9556019e) Update db status
for job-2149
2025-06-20 02:48:16,934 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149) (logid:9556019e) Wake up jobs
joined with job-2149 and disjoin all subjobs created from job- 2149
2025-06-20 02:48:16,939 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-a674dfb9 job-2149) (logid:9556019e) Done executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-2149
2025-06-20 02:48:16,939 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-18:ctx-a674dfb9 job-2149) (logid:9556019e) Remove job-2149
from job monitoring
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
