cloudstack Issue with managing instances created via VMware.

problem

Hello there. I am currently experiencing an issue when trying to manage an unmanaged instance / vm that was created via VMware. I also tried to unmanage and instance and trying to manage the same vm that was created via CloudStack. I still got the same error. I am experiencing this issue with 2 versions of CloudStack. 4.19.2.0 and 4.18.2.4. Please do ask if any context is needed. I also see that the management server keeps trying to match the unmanaged VMs in its DB, I saw this from the management logs.

CloudStack 4.19.2.0 For context, I have 2 primary storages but I use ds-cloudstack for the storing of Templates, ISOs, unmanaged VMs. I have only 1 secondary storage. I've been stuck on this issue since I tried the same thing on 4.18.2.4.

The error in question is Error Storage pool for disk Hardi disk 1(113-2000) with datastore: ds-cloudstack not found in zone ID: 12e2aff7-19b7-4fc0-85ce-ecf870f6f3f2

Error Storage pool for disk Hardi disk 1(5-2000) with datastore: ds-cloudstack not found in zone ID: 12e2aff7-19b7-4fc0-85ce-ecf870f6f3f2

versions

CloudStack 4.19.2.0 VMware ESXi 7 VMware vCenter TrueNAS iSCSI Ubuntu 24 Windows Server 2022 / 2019 Rocky Linux 9.5

The steps to reproduce the bug

Create a VM via vCenter.
After successfully creating one, see the VM listed under unmanaged instances.
Tick the VM and fill in the necessary details, VLAN etc.
Click on Import.
Error comes out.

What to do about it?

No response

Jun 18 '25 09:06 nimbustech-lab

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

Jun 18 '25 09:06 boring-cyborg[bot]

@nimbustech-lab , few questions;

what is the os your management server runs on?
the dtorages are all NFS?
can you deploy a VM in your env?
if you can, can you unmanage it?
are you trying to import from a managed vsphere cluster or an external one?

Jun 18 '25 10:06 DaanHoogland

@DaanHoogland

what is the os your management server runs on?

the dtorages are all NFS?

can you deploy a VM in your env?

if you can, can you unmanage it?

are you trying to import from a managed vsphere cluster or an external one?

ubuntu 24.04 primary storages uses iSCSI, secondary storage uses NFS. I can deploy a virtual machine via ISO or even Template. I can upload ISO and even create a Template. I unmanaged a VM created via a Template in CloudStack then I tried to manage it back with the same offering it was created. Same error. I am trying to import from a managed vSphere Cluster. I can see the list of unmanaged VMs being the same as the list of VMs in vSphere.

Jun 18 '25 10:06 nimbustech-lab

ok, from what you’ve given so far, there shouldn't be an issue. Can you check if storage tags and/or capacity may be a problem?

Jun 18 '25 11:06 DaanHoogland

ok, from what you’ve given so far, there shouldn't be an issue. Can you check if storage tags and/or capacity may be a problem?

@DaanHoogland

Could you explain further on where I should see the storage tags? It's not traffic type for Storage, right? I also see that last night, there was a primary storage created, reflecting the "ds-cloudstack" having the same size but allocation is different. The newly created has a storage tag "primary" but the "ds-cloudstack" has no storage tags, is that why? and why did CloudStack made a copy of primary storage but it has a tag and the name is much different, with it being like this <IP Address>-local-9693927f3808381c8692acb6dfcc9f45.

Jun 19 '25 02:06 nimbustech-lab

@nimbustech-lab , the storage and the diskoffering used should have matching tags.

Jun 19 '25 06:06 DaanHoogland

Talking about tags. I noticed that when I put a tag for a disk offering which matches the supposed intended primary storage. It will give an error of unable to create instance. When I remove the tag from the disk offering, it can create an instance just fine. Any clue on why?

Error is shown below

Jun 19 '25 07:06 nimbustech-lab

sounds like there was a mismatch anyway. What is the complete list of tags you have for all elements?

Jun 19 '25 08:06 DaanHoogland

for now, I only have primary tags on a custom disk offering and on 1 of the intended primary storages.

Jun 19 '25 08:06 nimbustech-lab

in that case something else goes wrong during allocation of the VM. please see the logs for details.

Jun 19 '25 08:06 DaanHoogland

this it the logs related to the instance I try to create using shared storage disk offering that had the primary tag.

Jun 19 '25 08:06 nimbustech-lab

this is another with local, fat, write-through that has the primary tag. I noticed that i can't add a tag when I removed the tag from a disk offering.

Jun 19 '25 08:06 nimbustech-lab

sorry @nimbustech-lab , these images are too hard to search through. Can you share plain text please? Preferable from entering the command till after the error is thrown (sub-jobs etc may occur)

Jun 19 '25 09:06 DaanHoogland

Hi @DaanHoogland . This is what I got when I tried to create a new VM with the ID, i-4-619-VM.

root@rnd-ubuntu-mgmt-svr:/home/nimbus# grep -i "i-4-619-VM" /var/log/cloudstack/management/management-server.log | less

2025-06-20 02:48:12,232 INFO [c.c.v.VirtualMachineManagerImpl] (qtp341748265-5716:ctx-4c68571b ctx-98e5ca78) (logid:a4cedac3) allocating virtual machine from template:a1905274-90d1-4c9e-bbf1-6067fc93ffda with hostname:i-4-619-VM and 1 networks 2025-06-20 02:48:12,235 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp341748265-5716:ctx-4c68571b ctx-98e5ca78) (logid:a4cedac3) Allocating entries for VM: VM instance {"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"} 2025-06-20 02:48:12,241 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp341748265-5716:ctx-4c68571b ctx-98e5ca78) (logid:a4cedac3) Allocating nics for VM instance {"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"} 2025-06-20 02:48:12,244 DEBUG [o.a.c.e.o.NetworkOrchestrator] (qtp341748265-5716:ctx-4c68571b ctx-98e5ca78) (logid:a4cedac3) Allocating nic for vm VM instance {"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"} in network Network {"id": 214, "name": "VM-NIC1", "uuid": "759ea379-6e4d-4316-a943-2904e70b5706", "networkofferingid": 16} with requested profile NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":0,"reservationId":null,"vmId":0} 2025-06-20 02:48:12,272 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp341748265-5716:ctx-4c68571b ctx-98e5ca78) (logid:a4cedac3) Allocating disks for VM instance {"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"} 2025-06-20 02:48:12,274 INFO [o.a.c.e.o.VolumeOrchestrator] (qtp341748265-5716:ctx-4c68571b ctx-98e5ca78 ctx-31d617df) (logid:a4cedac3) Adding disk object [ROOT-619] to VM [VM instance {"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"}] 2025-06-20 02:48:12,429 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp341748265-5716:ctx-4c68571b ctx-98e5ca78) (logid:a4cedac3) Allocation completed for VM: VM instance {"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"} 2025-06-20 02:48:12,429 DEBUG [c.c.v.UserVmManagerImpl] (qtp341748265-5716:ctx-4c68571b ctx-98e5ca78) (logid:a4cedac3) Successfully allocated DB entry for VM instance {"id":619,"instanceName":"i-4-619-VM","type":"User","uuid":"cd1d3dd3-8474-4b1c-80b3-a2d9d34e3367"} 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,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,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":"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.h.v.r.VmwareResource] (DirectAgent-345:ctx-11d49002) (logid:9556019e) Executing resource 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,"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":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.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,"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":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,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,577 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-87:ctx-80d2d086) (logid:9556019e) Executing resource command 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,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,608 DEBUG [c.c.a.t.Request] (DirectAgent-87:ctx-80d2d086) (logid:9556019e) Seq 2-327073922937792463: Processing: { Ans: , MgmtId: 345049157785, via: 2(192.168.80.81), Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"result":"true","details":"VM i-4-619-VM is no longer on the expected host in vSphere","wait":"0","bypassHostMaintenance":"false"}}] } 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,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,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,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 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,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,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,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":"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.h.v.r.VmwareResource] (DirectAgent-22:ctx-ea084317) (logid:9556019e) Executing resource 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,"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":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.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,"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":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,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,630 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-347:ctx-e73f7263) (logid:9556019e) Executing resource command 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 :

Jun 20 '25 02:06 nimbustech-lab

@nimbustech-lab, I don’t think the problemetic log entry will contain the VM name. Grep for can you grep for i-4-619-VM will not yield the issue. Can you grep job-2149 in that file, and look for errors and excpetions in that output ?

looking at the lines

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,"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":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,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

it is probably somewhere between 02:48:14,427 and 02:48:14,556 that the allocator-choosen storage pool turns out to be full or some other problem with it occurs? It may also be a problem with the source file, though. I can’t tell yet.

Jun 23 '25 08:06 DaanHoogland

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.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,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-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAJxAH4ACnBwcHNxAH4ACAAAAAAAAAADcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, 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":"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,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,"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":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-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAJxAH4ACnBwcHNxAH4ACAAAAAAAAAADcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, 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_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACQVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNIGluc3RhbmNlIHsiaWQiOjYxOSwiaW5zdGFuY2VOYW1lIjoiaS00LTYxOS1WTSIsInR5cGUiOiJVc2VyIiwidXVpZCI6ImNkMWQzZGQzLTg0NzQtNGIxYy04MGIzLWEyZDlkMzRlMzM2NyJ9dXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAVc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAKTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AApMAAptb2R1bGVOYW1lcQB-AApMAA1tb2R1bGVWZXJzaW9ucQB-AAp4cAEAAATMdAADYXBwdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0cHBzcQB-ABEBAAAVbnEAfgATcQB-ABRxAH4AFXEAfgAWcHBzcQB-ABEC_____nB0AC1qZGsuaW50ZXJuYWwucmVmbGVjdC5OYXRpdmVNZXRob2RBY2Nlc3NvckltcGx0AB1OYXRpdmVNZXRob2RBY2Nlc3NvckltcGwuamF2YXQAB2ludm9rZTB0AAlqYXZhLmJhc2V0AAcxMS4wLjI3c3EAfgARAgAAAD5wcQB-ABlxAH4AGnQABmludm9rZXEAfgAccQB-AB1zcQB-ABECAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-AB9xAH4AHHEAfgAdc3EAfgARAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AH3EAfgAccQB-AB1zcQB-ABEBAAAAaXEAfgATdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-ABEBAAAV6nEAfgATcQB-ABRxAH4AFXEAfgApcHBzcQB-ABEBAAAAZnEAfgATdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4AEQEAAAKOcQB-ABN0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4AEQEAAAAwcQB-ABN0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgARAQAAADdxAH4AE3QAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgARAQAAAGZxAH4AE3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AOXQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgARAQAAADRxAH4AE3EAfgA8cQB-ADl0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgARAQAAAC1xAH4AE3QAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgA1cQB-ADZwcHNxAH4AEQEAAAJacQB-ABNxAH4AMHEAfgAxcQB-ADZwcHNxAH4AEQIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA6cQB-ABxxAH4AHXNxAH4AEQIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4ANnEAfgAccQB-AB1zcQB-ABECAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAccQB-AB1zcQB-ABECAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEtxAH4ANnEAfgAccQB-AB1zcQB-ABECAAADPXB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4ANnEAfgAccQB-AB1zcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-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_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, 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":"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,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,"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":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_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, 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_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACQVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNIGluc3RhbmNlIHsiaWQiOjYxOSwiaW5zdGFuY2VOYW1lIjoiaS00LTYxOS1WTSIsInR5cGUiOiJVc2VyIiwidXVpZCI6ImNkMWQzZGQzLTg0NzQtNGIxYy04MGIzLWEyZDlkMzRlMzM2NyJ9dXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAVc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAKTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AApMAAptb2R1bGVOYW1lcQB-AApMAA1tb2R1bGVWZXJzaW9ucQB-AAp4cAEAAATMdAADYXBwdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0cHBzcQB-ABEBAAAVbnEAfgATcQB-ABRxAH4AFXEAfgAWcHBzcQB-ABEC_____nB0AC1qZGsuaW50ZXJuYWwucmVmbGVjdC5OYXRpdmVNZXRob2RBY2Nlc3NvckltcGx0AB1OYXRpdmVNZXRob2RBY2Nlc3NvckltcGwuamF2YXQAB2ludm9rZTB0AAlqYXZhLmJhc2V0AAcxMS4wLjI3c3EAfgARAgAAAD5wcQB-ABlxAH4AGnQABmludm9rZXEAfgAccQB-AB1zcQB-ABECAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-AB9xAH4AHHEAfgAdc3EAfgARAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AH3EAfgAccQB-AB1zcQB-ABEBAAAAaXEAfgATdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-ABEBAAAV6nEAfgATcQB-ABRxAH4AFXEAfgApcHBzcQB-ABEBAAAAZnEAfgATdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4AEQEAAAKOcQB-ABN0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4AEQEAAAAwcQB-ABN0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgARAQAAADdxAH4AE3QAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgARAQAAAGZxAH4AE3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AOXQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgARAQAAADRxAH4AE3EAfgA8cQB-ADl0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgARAQAAAC1xAH4AE3QAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgA1cQB-ADZwcHNxAH4AEQEAAAJacQB-ABNxAH4AMHEAfgAxcQB-ADZwcHNxAH4AEQIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA6cQB-ABxxAH4AHXNxAH4AEQIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4ANnEAfgAccQB-AB1zcQB-ABECAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAccQB-AB1zcQB-ABECAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEtxAH4ANnEAfgAccQB-AB1zcQB-ABECAAADPXB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4ANnEAfgAccQB-AB1zcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-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

Jun 24 '25 10:06 nimbustech-lab

@nimbustech-lab , the problematic logs are these:

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,"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":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

please check the storage from vmware as the storage migration is delegated to vmware and an error is returned.

Jun 24 '25 11:06 DaanHoogland

Did you find anything @nimbustech-lab ?

Jun 25 '25 09:06 DaanHoogland

### Issue Observed: When I use a disk offering with storage tags:

VM creation fails with InsufficientServerCapacityException.
CloudStack seems unable to locate a valid storage pool, even though the storage pool exists and is healthy but does not carry the required tag.

When I use a disk offering without storage tags:

VM creation works fine.
CloudStack automatically selects available storage pools (seemingly at random) without issue.

VM Mapping issue:

As reported, it can't locate the storage pool even if the storage pool has the "primary" tag at CloudStack.

Note: there are no tags put for the storage pools at the vCenter.

Jun 26 '25 09:06 nimbustech-lab

@nimbustech-lab can you perform the copy command as in the log above in vcenter directly?

Jun 26 '25 10:06 DaanHoogland

@DaanHoogland

Could you explain further on what copy command you meant? If you meant copying files command via Ubuntu, I can do that on vCenter but copy pasting commands via vCenter is not possible. Only possible via RDP.

Jun 30 '25 02:06 nimbustech-lab

@nimbustech-lab , can you in vcenter try to copy that volume that fails to the target storage ? If vmware cannot do the copy (as it seems from your logs) then neither can cloudstack orchestrate it. If you try you may also see some diagnostics that is not visible from cloudstack.

Jun 30 '25 06:06 DaanHoogland

If I am understanding correctly, you are asking me to copy a file from another datastore to another or to copy a file within the same datastore. I have tried both and it works. It can copy just fine from a datastore from another. I tried it with VMs that was created within the same datastores and different ones. What other things we can do to find out why managing instances is not possible in my scenario?

@DaanHoogland

Jul 02 '25 04:07 nimbustech-lab

Another thing I realized is when I put in the ID of the intended datastore to a global configuration shown in the picture below, it will fail to start VM. Same case as the storage tagging.

DS-CloudStack

Global Configuration

Jul 02 '25 07:07 nimbustech-lab

@nimbustech-lab from your description I do not get what exactly you tested. What I mean is the execute the copy command from

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,"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":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}].

directly on vcenter, ie copy 5ac6b8c4a7af3e3fbf2fb321fffd9dd7 from VMFS://VMFS datastore: datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9 as ROOT-619 to VMFS://VMFS datastore: datastore-16/datastore-16/?ROLE=Primary&STOREUUID=c651d575-bfbc-401e-bb0c-b23963a38df9

this is the command that returns the error. If you try it on vmware directly it should give an error as well. This is what you did and it didn’t give an error, is that correct?

Can you try deploying a VM in CloudStack, unmanaging it and then manage it again?

Jul 02 '25 07:07 DaanHoogland

I tried to copy a VM file in the datastore-15 (datastore1) to datastore-16 (ds-cloudstack) and it was fine. Copied successfully. I have tried to create it (a VM) twice. 1 VM was stored in datastore-15, another stored in datastore-16. Both can be created then unmanaged just fine. When it comes to managing it back, same error.

Jul 02 '25 08:07 nimbustech-lab

@vishesh92 @nvazquez @shwstppr does this sound familiar to any of you?

I tried to copy a VM file in the datastore-15 (datastore1) to datastore-16 (ds-cloudstack) and it was fine. Copied successfully. I have tried to create it (a VM) twice. 1 VM was stored in datastore-15, another stored in datastore-16. Both can be created then unmanaged just fine. When it comes to managing it back, same error.

@nimbustech-lab normal migration of volumes from cloudstack is fine as well?

Jul 07 '25 07:07 DaanHoogland

Hi @nimbustech-lab can you please try if the same issue can be hit on 4.19.3? There were some issues regarding Vmware connectivity on 4.19.2 such as #10634 which have been addressed

Jul 07 '25 10:07 nvazquez

Hi @nvazquez , @DaanHoogland .

I've just upgraded my CloudStack from 4.19.2.0 to 4.19.3.0. I've created a new Rocky Linux VM then unmanage it. It's fine. When I try to manage it back, the same error occurs. Is there anything I need to validate on vCenter's side?

Jul 08 '25 08:07 nimbustech-lab

@nimbustech-lab , my vmware is not fluent so forgive me if this is a silly question, but the datastore1 on vmware side, does it have the same uuid?

Jul 08 '25 08:07 DaanHoogland

cloudstack cloudstack copied to clipboard

Issue with managing instances created via VMware.

problem

versions

The steps to reproduce the bug

What to do about it?

cloudstack
cloudstack copied to clipboard