Hi JordanPlease see log attached. Can you confirm what's the best way to confirm if a template exists on secondary storage?
On 12/20/22 08:15, jordan j wrote:
Hey Granwille Strauss, Can you upload a full log somewhere? This error usually means there is another underlying issue even though it says Network/interface scope. Deployment for VM instance {id: "100", name: "i-2-100-VM", uuid: "e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"}Scope=interface com.cloud.dc.DataCenter; id=16 Can you also verify the template file is intact on the secondary server? Regards, Jordan On Tue, Dec 20, 2022 at 8:09 AM Granwille Strauss <granwi...@namhost.com.invalid> wrote:Hi Guys I accidentality "deleted" a wrong template. Fortunately, the delete was not successful and gave an error stating that it cannot be deleted because there are active VMs associated with it. However, since I did this, I can now no longer deploy new VMs using said template. Creating a VM now fails since I did this, see attached screenshot. And this is the management log entry: 2022-12-20 08:04:55,618 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481) (logid:4c740aa8) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {id: "100", name: "i-2-100-VM", uuid: "e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"}Scope=interface com.cloud.dc.DataCenter; id=16 2022-12-20 08:04:55,618 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 100, job origin: 2783 2022-12-20 08:04:55,618 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Unable to complete AsyncJobVO: {id:2784, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAZHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAEHBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAA1zcQB-AAgAAAAAAAAAJHBwcHNxAH4ACAAAAAAAAAAPcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 66988330791812, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue Dec 20 07:59:49 SAST 2022, removed: null}, job origin:2783 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {id: "100", name: "i-2-100-VM", uuid: "e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"}Scope=interface com.cloud.dc.DataCenter; id=16 This seems to ONLY happen with this one template that I deleted, I can deploy VMs successfully from other templates but this one that was "deleted", even though it was NOT deleted. So it seems the template broke somehow because now no volume is created for new VMs when using this template. I am using 4.17.1.0. Is this a known issue? -- Regards / Groete <https://www.namhost.com> Granwille Strauss // Senior Systems Admin *e:*granwi...@namhost.com *m:* +264 81 323 1260 <+264813231260> *w:*www.namhost.com <https://www.facebook.com/namhost> <https://twitter.com/namhost> <https://www.instagram.com/namhostinternetservices/> <https://www.linkedin.com/company/namhos> <https://www.youtube.com/channel/UCTd5v-kVPaic_dguGur15AA> <https://www.adsigner.com/v1/l/631091998d4670001fe43ec2/621c9b76c140bb001ed0f818/banner> Namhost Internet Services (Pty) Ltd, 24 Black Eagle Rd, Hermanus, 7210, RSA The content of this message is confidential. If you have received it by mistake, please inform us by email reply and then delete the message. It is forbidden to copy, forward, or in any way reveal the contents of this message to anyone without our explicit consent. The integrity and security of this email cannot be guaranteed over the Internet. Therefore, the sender will not be held liable for any damage caused by the message. For our full privacy policy and disclaimers, please go to https://www.namhost.com/privacy-policy [image: Powered by AdSigner] <https://www.adsigner.com/v1/c/631091998d4670001fe43ec2/621c9b76c140bb001ed0f818>
-- Regards / Groete <https://www.namhost.com> Granwille Strauss // Senior Systems Admin *e:* granwi...@namhost.com *m:* +264 81 323 1260 <tel:+264813231260> *w:* www.namhost.com <https://www.namhost.com/> <https://www.facebook.com/namhost><https://twitter.com/namhost><https://www.instagram.com/namhostinternetservices/><https://www.linkedin.com/company/namhos><https://www.youtube.com/channel/UCTd5v-kVPaic_dguGur15AA> <https://www.adsigner.com/v1/l/631091998d4670001fe43ec2/621c9b76c140bb001ed0f818/banner> Namhost Internet Services (Pty) Ltd, 24 Black Eagle Rd, Hermanus, 7210, RSAThe content of this message is confidential. If you have received it by mistake, please inform us by email reply and then delete the message. It is forbidden to copy, forward, or in any way reveal the contents of this message to anyone without our explicit consent. The integrity and security of this email cannot be guaranteed over the Internet. Therefore, the sender will not be held liable for any damage caused by the message. For our full privacy policy and disclaimers, please go to https://www.namhost.com/privacy-policy
Powered by AdSigner <https://www.adsigner.com/v1/c/631091998d4670001fe43ec2/621c9b76c140bb001ed0f818>
root@hostname /mnt/secondary/template/tmpl $ grep job-2783
/var/log/cloudstack/management/management-server.log
2022-12-20 07:59:49,614 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-6:ctx-c434de23 job-2783) (logid:d0875961) Add job-2783 into
job monitoring
2022-12-20 07:59:49,617 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783) (logid:4c740aa8) Executing
AsyncJobVO: {id:2783, userId: 2, accountId: 2, instanceType: VirtualMachine,
instanceId: 100, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"iptonetworklist[0].networkid":"74aab617-7861-43d6-adaf-776968558389","hostid":"35877892-f831-4dee-b6e2-19ed651f1299","httpmethod":"POST","ctxAccountId":"2","uuid":"e0611ff1-cab5-48d0-ac4e-09fe0f034b19","details[0].memory":"2048","cmdEventType":"VM.CREATE","bootmode":"LEGACY","hypervisor":"KVM","ctxStartEventId":"5572","id":"100","ctxDetails":"{\"interface
com.cloud.offering.ServiceOffering\":\"4acc533e-606c-4f5e-8248-7723c518bb22\",\"interface
com.cloud.host.Host\":\"35877892-f831-4dee-b6e2-19ed651f1299\",\"interface
com.cloud.dc.DataCenter\":\"85c7d919-4560-4c5b-86e5-1c9937436fc7\",\"interface
com.cloud.template.VirtualMachineTemplate\":\"d2c4feca-da5c-44b3-8ecc-40a01fd6c243\",\"interface
com.cloud.org.Cluster\":\"5123966c-2c58-4234-a6e8-c9eff82e62d6\",\"interface
com.cloud.dc.Pod\":\"b78e1312-8e29-449e-b424-ab5f883b28a2\",\"interface
com.cloud.vm.VirtualMachine\":\"e0611ff1-cab5-48d0-ac4e-09fe0f034b19\"}","keypairs":"","group":"Client
Servers","details[0].cpuNumber":"1","keyboard":"us","details[0].cpuSpeed":"2100","boottype":"BIOS","clusterid":"5123966c-2c58-4234-a6e8-c9eff82e62d6","templateid":"d2c4feca-da5c-44b3-8ecc-40a01fd6c243","startvm":"true","serviceofferingid":"4acc533e-606c-4f5e-8248-7723c518bb22","response":"json","ctxUserId":"2","displayname":"Benade-Ent","name":"Benade-Ent","zoneid":"85c7d919-4560-4c5b-86e5-1c9937436fc7","podid":"b78e1312-8e29-449e-b424-ab5f883b28a2","affinitygroupids":""},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 66988330791812, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null, removed: null}
2022-12-20 07:59:49,620 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(qtp262366552-2831:ctx-780ab822 ctx-78f33890) (logid:7e27be65) submit async
job-2783, details: AsyncJobVO: {id:2783, userId: 2, accountId: 2, instanceType:
VirtualMachine, instanceId: 100, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"iptonetworklist[0].networkid":"74aab617-7861-43d6-adaf-776968558389","hostid":"35877892-f831-4dee-b6e2-19ed651f1299","httpmethod":"POST","ctxAccountId":"2","uuid":"e0611ff1-cab5-48d0-ac4e-09fe0f034b19","details[0].memory":"2048","cmdEventType":"VM.CREATE","bootmode":"LEGACY","hypervisor":"KVM","ctxStartEventId":"5572","id":"100","ctxDetails":"{\"interface
com.cloud.offering.ServiceOffering\":\"4acc533e-606c-4f5e-8248-7723c518bb22\",\"interface
com.cloud.host.Host\":\"35877892-f831-4dee-b6e2-19ed651f1299\",\"interface
com.cloud.dc.DataCenter\":\"85c7d919-4560-4c5b-86e5-1c9937436fc7\",\"interface
com.cloud.template.VirtualMachineTemplate\":\"d2c4feca-da5c-44b3-8ecc-40a01fd6c243\",\"interface
com.cloud.org.Cluster\":\"5123966c-2c58-4234-a6e8-c9eff82e62d6\",\"interface
com.cloud.dc.Pod\":\"b78e1312-8e29-449e-b424-ab5f883b28a2\",\"interface
com.cloud.vm.VirtualMachine\":\"e0611ff1-cab5-48d0-ac4e-09fe0f034b19\"}","keypairs":"","group":"Client
Servers","details[0].cpuNumber":"1","keyboard":"us","details[0].cpuSpeed":"2100","boottype":"BIOS","clusterid":"5123966c-2c58-4234-a6e8-c9eff82e62d6","templateid":"d2c4feca-da5c-44b3-8ecc-40a01fd6c243","startvm":"true","serviceofferingid":"4acc533e-606c-4f5e-8248-7723c518bb22","response":"json","ctxUserId":"2","displayname":"Benade-Ent","name":"Benade-Ent","zoneid":"85c7d919-4560-4c5b-86e5-1c9937436fc7","podid":"b78e1312-8e29-449e-b424-ab5f883b28a2","affinitygroupids":""},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 66988330791812, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null, removed: null}
2022-12-20 07:59:49,639 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Service SecurityGroup is not supported in the network id=266
2022-12-20 07:59:49,641 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Service SecurityGroup is not supported in the network id=266
2022-12-20 07:59:49,643 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Destination Host to deploy the VM is specified, specifying a deployment plan to
deploy the VM
2022-12-20 07:59:49,645 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Host:
36 has cpu capability (cpu:32, speed:2100) to support requested CPU: 1 and
requested speed: 2100
2022-12-20 07:59:49,645 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Checking if host: 36 has enough capacity for requested CPU: 2100 and requested
RAM: (2,00 GB) 2147483648 , cpuOverprovisioningFactor: 1.0
2022-12-20 07:59:49,645 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Hosts's actual total CPU: 67200 and CPU after applying overprovisioning: 67200
2022-12-20 07:59:49,645 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
considerReservedCapacity isfalse , not considering reserved capacity for
calculating free capacity
2022-12-20 07:59:49,645 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Free
CPU: 65697 , Requested CPU: 2100
2022-12-20 07:59:49,646 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Free
RAM: (53,78 GB) 57743196160 , Requested RAM: (2,00 GB) 2147483648
2022-12-20 07:59:49,646 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Host
has enough CPU and RAM available
2022-12-20 07:59:49,646 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) STATS:
Can alloc CPU from host: 36, used: 1503, reserved: 0, actual total: 67200,
total with overprovisioning: 67200; requested
cpu:2100,alloc_from_last_host?:false ,considerReservedCapacity?: false
2022-12-20 07:59:49,646 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) STATS:
Can alloc MEM from host: 36, used: (7,75 GB) 8321499136, reserved: (0 bytes) 0,
total: (61,53 GB) 66064695296; requested mem: (2,00 GB) 2147483648,
alloc_from_last_host?: false , considerReservedCapacity?: false
2022-12-20 07:59:49,652 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Adding
pods to avoid lists for non-explicit VM deployment: []
2022-12-20 07:59:49,652 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Adding
clusters to avoid lists for non-explicit VM deployment: []
2022-12-20 07:59:49,652 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Adding
hosts to avoid lists for non-explicit VM deployment: []
2022-12-20 07:59:49,652 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
DeploymentPlanner allocation algorithm: null
2022-12-20 07:59:49,652 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Trying
to allocate a host and storage pools from dc:16, pod:15,cluster:13, requested
cpu: 2100, requested ram: (2,00 GB) 2147483648
2022-12-20 07:59:49,652 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Is
ROOT volume READY (pool already allocated)?: No
2022-12-20 07:59:49,654 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
DeploymentPlan has host_id specified, choosing this host and making no checks
on this host: 36
2022-12-20 07:59:49,655 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Looking for suitable pools for this host under zone: 16, pod: 15, cluster: 13
2022-12-20 07:59:49,657 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Checking suitable pools for volume (Id, Type): (104,ROOT)
2022-12-20 07:59:49,657 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) We
need to allocate new storagepool for this volume
2022-12-20 07:59:49,658 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Calling StoragePoolAllocators to find suitable pools
2022-12-20 07:59:49,658 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2022-12-20 07:59:49,658 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
ClusterScopeStoragePoolAllocator looking for storage pool
2022-12-20 07:59:49,658 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Looking for pools in dc: 16 pod:15 cluster:13. Disabled pools will be ignored.
2022-12-20 07:59:49,659 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Found
pools matching tags: []
2022-12-20 07:59:49,659 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) No
storage pools available for shared volume allocation, returning
2022-12-20 07:59:49,659 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
ZoneWideStoragePoolAllocator to find storage pool
2022-12-20 07:59:49,661 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Checking if storage pool is suitable, name: Prime ,poolId: 25
2022-12-20 07:59:49,661 INFO [c.c.s.StorageManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Storage pool Prime (25) does not supply IOPS capacity, assuming enough capacity
2022-12-20 07:59:49,662 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Checking pool 25 for storage, totalSize: 935081279488, usedBytes: 776340504576,
usedPct: 0.830238527501141, disable threshold: 0.85
2022-12-20 07:59:49,662 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Destination pool id: 25
2022-12-20 07:59:49,669 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Pool
ID for the volume with ID 104 is null
2022-12-20 07:59:49,671 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Found
storage pool Prime of type NetworkFilesystem with overprovisioning factor 2
2022-12-20 07:59:49,671 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Total
over provisioned capacity calculated is 2 * (870,86 GB) 935081279488
2022-12-20 07:59:49,671 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Total
capacity of the pool Prime with ID 25 is (1,7009 TB) 1870162558976
2022-12-20 07:59:49,671 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Checking pool: 25 for storage allocation , maxSize : (1,7009 TB) 1870162558976,
totalAllocatedSize : (165,00 GB) 177167598528, askingSize : (60,00 GB)
64424509440, allocated disable threshold: 0.85
2022-12-20 07:59:49,672 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Trying
to find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2022-12-20 07:59:49,673 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Checking if host: 36 can access any suitable storage pool for volume: ROOT
2022-12-20 07:59:49,673 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Host:
36 can access pool: 25
2022-12-20 07:59:49,674 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Found
a potential host id: 36 name: athena03.namhost.com and associated storage pools
for this VM
2022-12-20 07:59:49,674 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(16)-Pod(15)-Cluster(13)-Host(36)-Storage(Volume(104|ROOT-->Pool(25))]
2022-12-20 07:59:49,678 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) start
parameter value of enterHardwareSetup == null during processing of queued job
2022-12-20 07:59:49,683 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) Sync
job-2784 execution on object VmWorkJobQueue.100
2022-12-20 07:59:50,897 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:fb08110c) Add
job-2784 into job monitoring
2022-12-20 07:59:50,901 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Executing
AsyncJobVO: {id:2784, userId: 2, accountId: 2, instanceType: null, instanceId:
null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAZHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAEHBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAA1zcQB-AAgAAAAAAAAAJHBwcHNxAH4ACAAAAAAAAAAPcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 66988330791812, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Tue Dec 20 07:59:49 SAST 2022, removed: null}
2022-12-20 07:59:50,901 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Run VM
work job: com.cloud.vm.VmWorkStart for VM 100, job origin: 2783
2022-12-20 07:59:50,902 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":16,"podId":15,"clusterId":13,"hostId":36,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":100,"handlerName":"VirtualMachineManagerImpl"}
2022-12-20 07:59:50,903 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) orchestrating VM start for 'i-2-100-VM'
com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d set to null
2022-12-20 07:59:50,913 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) VM instance {id: "100", name: "i-2-100-VM", uuid:
"e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"} state transited from
[Stopped] to [Starting] with event [StartRequested]. VM's original host: null,
new host: null, host before state transition: null
2022-12-20 07:59:50,913 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Successfully transitioned to start state for VM instance {id:
"100", name: "i-2-100-VM", uuid: "e0611ff1-cab5-48d0-ac4e-09fe0f034b19",
type="User"} reservation id = 823f78cf-95b2-4e4a-9bbb-3b21eac4742d
2022-12-20 07:59:50,916 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) advanceStart: DeploymentPlan is provided, using dcId:16,
podId: 15, clusterId: 13, hostId: 36, poolId: null
2022-12-20 07:59:50,917 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Deploy avoids pods: null, clusters: null, hosts: null
2022-12-20 07:59:50,918 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) VM start attempt #1
2022-12-20 07:59:50,922 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Adding pods to avoid lists for non-explicit VM deployment: []
2022-12-20 07:59:50,922 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Adding clusters to avoid lists for non-explicit VM deployment:
[]
2022-12-20 07:59:50,922 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Adding hosts to avoid lists for non-explicit VM deployment: []
2022-12-20 07:59:50,922 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) DeploymentPlanner allocation algorithm: null
2022-12-20 07:59:50,922 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Trying to allocate a host and storage pools from dc:16,
pod:15,cluster:13, requested cpu: 2100, requested ram: (2,00 GB) 2147483648
2022-12-20 07:59:50,922 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Is ROOT volume READY (pool already allocated)?: No
2022-12-20 07:59:50,926 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) DeploymentPlan has host_id specified, choosing this host and
making no checks on this host: 36
2022-12-20 07:59:50,926 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Looking for suitable pools for this host under zone: 16, pod:
15, cluster: 13
2022-12-20 07:59:50,928 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Checking suitable pools for volume (Id, Type): (104,ROOT)
2022-12-20 07:59:50,928 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) We need to allocate new storagepool for this volume
2022-12-20 07:59:50,928 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Calling StoragePoolAllocators to find suitable pools
2022-12-20 07:59:50,928 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) LocalStoragePoolAllocator trying to find storage pool to fit
the vm
2022-12-20 07:59:50,928 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) ClusterScopeStoragePoolAllocator looking for storage pool
2022-12-20 07:59:50,929 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Looking for pools in dc: 16 pod:15 cluster:13. Disabled
pools will be ignored.
2022-12-20 07:59:50,929 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Found pools matching tags: []
2022-12-20 07:59:50,929 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) No storage pools available for shared volume allocation,
returning
2022-12-20 07:59:50,929 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) ZoneWideStoragePoolAllocator to find storage pool
2022-12-20 07:59:50,931 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Checking if storage pool is suitable, name: Prime ,poolId: 25
2022-12-20 07:59:50,931 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Storage pool Prime (25) does not supply IOPS capacity,
assuming enough capacity
2022-12-20 07:59:50,932 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Checking pool 25 for storage, totalSize: 935081279488,
usedBytes: 776340504576, usedPct: 0.830238527501141, disable threshold: 0.85
2022-12-20 07:59:50,932 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Destination pool id: 25
2022-12-20 07:59:50,938 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Pool ID for the volume with ID 104 is null
2022-12-20 07:59:50,940 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Found storage pool Prime of type NetworkFilesystem with
overprovisioning factor 2
2022-12-20 07:59:50,940 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Total over provisioned capacity calculated is 2 * (870,86 GB)
935081279488
2022-12-20 07:59:50,940 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Total capacity of the pool Prime with ID 25 is (1,7009 TB)
1870162558976
2022-12-20 07:59:50,941 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Checking pool: 25 for storage allocation , maxSize : (1,7009
TB) 1870162558976, totalAllocatedSize : (165,00 GB) 177167598528, askingSize :
(60,00 GB) 64424509440, allocated disable threshold: 0.85
2022-12-20 07:59:50,941 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Trying to find a potenial host and associated storage pools
from the suitable host/pool lists for this VM
2022-12-20 07:59:50,942 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Checking if host: 36 can access any suitable storage pool for
volume: ROOT
2022-12-20 07:59:50,942 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Host: 36 can access pool: 25
2022-12-20 07:59:50,942 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Found a potential host id: 36 name: athena03.namhost.com and
associated storage pools for this VM
2022-12-20 07:59:50,943 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(16)-Pod(15)-Cluster(13)-Host(36)-Storage(Volume(104|ROOT-->Pool(25))]
2022-12-20 07:59:50,943 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Deployment found - Attempt #1 - P0=VM instance {id: "100",
name: "i-2-100-VM", uuid: "e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"},
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(16)-Pod(15)-Cluster(13)-Host(36)-Storage(Volume(104|ROOT-->Pool(25))]
2022-12-20 07:59:50,949 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) VM instance {id: "100", name: "i-2-100-VM", uuid:
"e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"} state transited from
[Starting] to [Starting] with event [OperationRetry]. VM's original host: null,
new host: Host {"id": "36", "name": "athena03.namhost.com", "uuid":
"35877892-f831-4dee-b6e2-19ed651f1299", "type"="Routing"}, host before state
transition: null
2022-12-20 07:59:50,954 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Hosts's actual total CPU: 67200 and CPU after applying
overprovisioning: 67200
2022-12-20 07:59:50,954 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) We are allocating VM, increasing the used capacity of this
host:36
2022-12-20 07:59:50,954 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Current Used CPU: 1503 , Free CPU:65697 ,Requested CPU: 2100
2022-12-20 07:59:50,954 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Current Used RAM: (7,75 GB) 8321499136 , Free RAM:(53,78 GB)
57743196160 ,Requested RAM: (2,00 GB) 2147483648
2022-12-20 07:59:50,954 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) CPU STATS after allocation: for host: 36, old used: 1503, old
reserved: 0, actual total: 67200, total with overprovisioning: 67200; new
used:3603, reserved:0; requested cpu:2100,alloc_from_last:false
2022-12-20 07:59:50,954 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) RAM STATS after allocation: for host: 36, old used: (7,75 GB)
8321499136, old reserved: (0 bytes) 0, total: (61,53 GB) 66064695296; new used:
(9,75 GB) 10468982784, reserved: (0 bytes) 0; requested mem: (2,00 GB)
2147483648,alloc_from_last:false
2022-12-20 07:59:50,955 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Host: 36 has cpu capability (cpu:32, speed:2100) to support
requested CPU: 1 and requested speed: 2100
2022-12-20 07:59:50,955 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Checking if host: 36 has enough capacity for requested CPU:
2100 and requested RAM: (2,00 GB) 2147483648 , cpuOverprovisioningFactor: 1.0
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Hosts's actual total CPU: 67200 and CPU after applying
overprovisioning: 67200
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) We need to allocate to the last host again, so checking if
there is enough reserved capacity
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Reserved CPU: 0 , Requested CPU: 2100
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Reserved RAM: (0 bytes) 0 , Requested RAM: (2,00 GB) 2147483648
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) STATS: Failed to alloc resource from host: 36 reservedCpu: 0,
requested cpu: 2100, reservedMem: (0 bytes) 0, requested mem: (2,00 GB)
2147483648
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Host does not have enough reserved CPU available, cannot
allocate to this host.
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Checking if host: 36 has enough capacity for requested CPU:
2100 and requested RAM: (2,00 GB) 2147483648 , cpuOverprovisioningFactor: 1.0
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Hosts's actual total CPU: 67200 and CPU after applying
overprovisioning: 67200
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Free CPU: 65697 , Requested CPU: 2100
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Free RAM: (53,78 GB) 57743196160 , Requested RAM: (2,00 GB)
2147483648
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Host has enough CPU and RAM available
2022-12-20 07:59:50,956 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) STATS: Can alloc CPU from host: 36, used: 1503, reserved: 0,
actual total: 67200, total with overprovisioning: 67200; requested
cpu:2100,alloc_from_last_host?:false ,considerReservedCapacity?: true
2022-12-20 07:59:50,957 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) STATS: Can alloc MEM from host: 36, used: (7,75 GB)
8321499136, reserved: (0 bytes) 0, total: (61,53 GB) 66064695296; requested
mem: (2,00 GB) 2147483648, alloc_from_last_host?: false ,
considerReservedCapacity?: true
2022-12-20 07:59:50,970 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Network id=266 is already implemented
2022-12-20 07:59:50,974 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Service SecurityGroup is not supported in the network id=266
2022-12-20 07:59:50,977 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Changing active number of nics for network id=266 on 1
2022-12-20 07:59:50,981 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Asking VirtualRouter to prepare for
Nic[215-100-null-197.189.211.140]
2022-12-20 07:59:50,991 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Service SecurityGroup is not supported in the network id=266
2022-12-20 07:59:50,993 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) CONFIG DHCP FOR SUBNETS RULES
2022-12-20 07:59:50,998 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Service SecurityGroup is not supported in the network id=266
2022-12-20 07:59:50,999 DEBUG [o.a.c.n.t.AdvancedNetworkTopology]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) APPLYING VPC DHCP ENTRY RULES
2022-12-20 07:59:51,000 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Applying dhcp entry in network Network {"id": 266, "name":
"public network", "uuid": "74aab617-7861-43d6-adaf-776968558389",
"networkofferingid": 8}
2022-12-20 07:59:51,010 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Seq 36-1710804908447415277: Sending { Cmd , MgmtId:
66988330791812, via: 36(athena03.namhost.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"1e:00:f5:00:00:4d","vmIpAddress":"197.189.211.140","vmName":"Benade-Ent","defaultRouter":"197.189.211.137","defaultDns":"197.189.211.139","duid":"00:03:00:01:1e:00:f5:00:00:4d","isDefault":"true","executeInSequence":"false","remove":"false","accessDetails":{"router.name":"r-91-VM","router.guest.ip":"197.189.211.139","router.ip":"169.254.47.221","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}]
}
2022-12-20 07:59:51,505 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Seq 36-1710804908447415277: Received: { Ans: , MgmtId:
66988330791812, via: 36(athena03.namhost.com), Ver: v1, Flags: 10, {
GroupAnswer } }
2022-12-20 07:59:51,509 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Service SecurityGroup is not supported in the network id=266
2022-12-20 07:59:51,510 DEBUG [o.a.c.n.t.AdvancedNetworkTopology]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) APPLYING VPC USERDATA RULES
2022-12-20 07:59:51,510 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Applying userdata and password entry in network Network {"id":
266, "name": "public network", "uuid": "74aab617-7861-43d6-adaf-776968558389",
"networkofferingid": 8}
2022-12-20 07:59:51,521 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Seq 36-1710804908447415278: Sending { Cmd , MgmtId:
66988330791812, via: 36(athena03.namhost.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"197.189.211.140","vmName":"Benade-Ent","executeInSequence":"false","accessDetails":{"router.name":"r-91-VM","router.guest.ip":"197.189.211.139","router.ip":"169.254.47.221","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"197.189.211.140","vmName":"Benade-Ent","executeInSequence":"false","accessDetails":{"router.name":"r-91-VM","router.guest.ip":"197.189.211.139","router.ip":"169.254.47.221","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}]
}
2022-12-20 07:59:52,424 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Seq 36-1710804908447415278: Received: { Ans: , MgmtId:
66988330791812, via: 36(athena03.namhost.com), Ver: v1, Flags: 10, {
GroupAnswer, GroupAnswer } }
2022-12-20 07:59:52,425 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Service SecurityGroup is not supported in the network id=266
2022-12-20 07:59:52,431 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) template 212 is already in store:17, type:Image
2022-12-20 07:59:52,442 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) copyAsync inspecting src type TEMPLATE copyAsync inspecting
dest type VOLUME
2022-12-20 07:59:52,451 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.CopyCommand
2022-12-20 07:59:52,453 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Seq 36-1710804908447415280: Sending { Cmd , MgmtId:
66988330791812, via: 36(athena03.namhost.com), Ver: v1, Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"d2c4feca-da5c-44b3-8ecc-40a01fd6c243","uuid":"d2c4feca-da5c-44b3-8ecc-40a01fd6c243","id":"212","format":"QCOW2","accountId":"2","checksum":"{SHA-512}fbb1808d2823bfad0ac8c17ddc1038871b4678ed326b91ac4949376dd9823da0153faa031ad00ed3ad9772d78982d8fd2bdf3816b1f2d894d10fa5a72fb5d638","hvm":"true","displayText":"Almalinux
8 cPanel
Template","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"3a808086-b3bd-3dda-b27d-18ab9f0059f4","name":"Prime","id":"25","poolType":"NetworkFilesystem","host":"192.168.50.2","path":"/mnt/dataprime","port":"2049","url":"NetworkFilesystem://192.168.50.2/mnt/dataprime/?ROLE=Primary&STOREUUID=3a808086-b3bd-3dda-b27d-18ab9f0059f4","isManaged":"false"}},"name":"5225a781-17b1-4cc6-b112-0e110e2ca4e5","size":"(60,00
GB)
64424509440","hypervisorType":"KVM","bootable":"false","uniqueName":"5225a781-17b1-4cc6-b112-0e110e2ca4e5","directDownload":"false","deployAsIs":"false"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"88695a0f-ac1e-42b8-8eb8-61b258e9e064","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"3a808086-b3bd-3dda-b27d-18ab9f0059f4","name":"Prime","id":"25","poolType":"NetworkFilesystem","host":"192.168.50.2","path":"/mnt/dataprime","port":"2049","url":"NetworkFilesystem://192.168.50.2/mnt/dataprime/?ROLE=Primary&STOREUUID=3a808086-b3bd-3dda-b27d-18ab9f0059f4","isManaged":"false"}},"name":"ROOT-100","size":"(60,00
GB)
64424509440","volumeId":"104","vmName":"i-2-100-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","poolId":"25","id":"104","deviceId":"0","cacheMode":"NONE","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"}},"executeInSequence":"true","options":{},"options2":{},"wait":"0","bypassHostMaintenance":"false"}}]
}
2022-12-20 08:02:11,514 WARN [o.a.c.f.j.i.AsyncJobMonitor]
(Timer-0:ctx-6616ece4) (logid:5c6d1e6b) Task (job-2783) has been pending for
141 seconds
2022-12-20 08:03:11,515 WARN [o.a.c.f.j.i.AsyncJobMonitor]
(Timer-0:ctx-60f0ac1b) (logid:5e5388e3) Task (job-2783) has been pending for
201 seconds
2022-12-20 08:04:11,514 WARN [o.a.c.f.j.i.AsyncJobMonitor]
(Timer-0:ctx-2e7c936a) (logid:a3027c48) Task (job-2783) has been pending for
261 seconds
2022-12-20 08:04:55,237 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Seq 36-1710804908447415280: Received: { Ans: , MgmtId:
66988330791812, via: 36(athena03.namhost.com), Ver: v1, Flags: 110, {
CopyCmdAnswer } }
2022-12-20 08:04:55,241 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Unable to create
Vol[104|vm=100|ROOT]:com.cloud.utils.exception.CloudRuntimeException: Can't
find volume:d2c4feca-da5c-44b3-8ecc-40a01fd6c243
2022-12-20 08:04:55,241 WARN [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Unable to contact resource.
2022-12-20 08:04:55,243 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Cleaning up resources for the vm VM instance {id: "100", name:
"i-2-100-VM", uuid: "e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"} in
Starting state
2022-12-20 08:04:55,247 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) VM instance {id: "100", name: "i-2-100-VM", uuid:
"e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"} is a [User], returning
null for control Nic IP.
2022-12-20 08:04:55,249 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Seq 36-1710804908447415301: Sending { Cmd , MgmtId:
66988330791812, via: 36(athena03.namhost.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeCleanup":"false","forceStop":"false","vlanToPersistenceMap":{"untagged":"true"},"volumesToDisconnect":[],"vmName":"i-2-100-VM","executeInSequence":"false","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-12-20 08:04:55,574 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Seq 36-1710804908447415301: Received: { Ans: , MgmtId:
66988330791812, via: 36(athena03.namhost.com), Ver: v1, Flags: 10, { StopAnswer
} }
2022-12-20 08:04:55,581 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Changing active number of nics for network id=266 on -1
2022-12-20 08:04:55,587 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Successfully released network resources for the VM VM instance
{id: "100", name: "i-2-100-VM", uuid: "e0611ff1-cab5-48d0-ac4e-09fe0f034b19",
type="User"} in Starting state
2022-12-20 08:04:55,590 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Successfully released storage resources for the VM VM instance
{id: "100", name: "i-2-100-VM", uuid: "e0611ff1-cab5-48d0-ac4e-09fe0f034b19",
type="User"} in Starting state
2022-12-20 08:04:55,590 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Successfully cleaned up resources for the VM VM instance {id:
"100", name: "i-2-100-VM", uuid: "e0611ff1-cab5-48d0-ac4e-09fe0f034b19",
type="User"} in Starting state
2022-12-20 08:04:55,591 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) VM start attempt #2
2022-12-20 08:04:55,594 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Adding pods to avoid lists for non-explicit VM deployment: []
2022-12-20 08:04:55,594 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Adding clusters to avoid lists for non-explicit VM deployment:
[]
2022-12-20 08:04:55,594 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Adding hosts to avoid lists for non-explicit VM deployment: []
2022-12-20 08:04:55,594 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) DeploymentPlanner allocation algorithm: null
2022-12-20 08:04:55,594 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Trying to allocate a host and storage pools from dc:16,
pod:15,cluster:13, requested cpu: 2100, requested ram: (2,00 GB) 2147483648
2022-12-20 08:04:55,594 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Is ROOT volume READY (pool already allocated)?: No
2022-12-20 08:04:55,597 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) DeploymentPlan has host_id specified, choosing this host and
making no checks on this host: 36
2022-12-20 08:04:55,597 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) The specified host is in avoid set
2022-12-20 08:04:55,597 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Cannot deploy to specified host, returning.
2022-12-20 08:04:55,606 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) VM instance {id: "100", name: "i-2-100-VM", uuid:
"e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"} state transited from
[Starting] to [Stopped] with event [OperationFailed]. VM's original host: null,
new host: null, host before state transition: Host {"id": "36", "name":
"athena03.namhost.com", "uuid": "35877892-f831-4dee-b6e2-19ed651f1299",
"type"="Routing"}
2022-12-20 08:04:55,610 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Hosts's actual total CPU: 67200 and CPU after applying
overprovisioning: 67200
2022-12-20 08:04:55,610 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Hosts's actual total RAM: (61,53 GB) 66064695296 and RAM after
applying overprovisioning: (61,53 GB) 66064695296
2022-12-20 08:04:55,610 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) release cpu from host: 36, old used: 3603,reserved: 0, actual
total: 67200, total with overprovisioning: 67200; new used: 1503,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2022-12-20 08:04:55,610 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) release mem from host: 36, old used: (9,75 GB)
10468982784,reserved: (0 bytes) 0, total: (61,53 GB) 66064695296; new used:
(7,75 GB) 8321499136,reserved:(0 bytes) 0; movedfromreserved:
false,moveToReserveredfalse
2022-12-20 08:04:55,618 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance {id: "100", name: "i-2-100-VM", uuid:
"e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"}Scope=interface
com.cloud.dc.DataCenter; id=16
2022-12-20 08:04:55,618 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784 ctx-5325e481)
(logid:4c740aa8) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance {id: "100", name: "i-2-100-VM", uuid:
"e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"}Scope=interface
com.cloud.dc.DataCenter; id=16
2022-12-20 08:04:55,618 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Done with
run of VM work job: com.cloud.vm.VmWorkStart for VM 100, job origin: 2783
2022-12-20 08:04:55,618 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Unable to
complete AsyncJobVO: {id:2784, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAZHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAEHBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAA1zcQB-AAgAAAAAAAAAJHBwcHNxAH4ACAAAAAAAAAAPcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 66988330791812, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Tue Dec 20 07:59:49 SAST 2022, removed: null}, job
origin:2783
2022-12-20 08:04:55,622 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Complete
async job-2784, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACIVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNIGluc3RhbmNlIHtpZDogIjEwMCIsIG5hbWU6ICJpLTItMTAwLVZNIiwgdXVpZDogImUwNjExZmYxLWNhYjUtNDhkMC1hYzRlLTA5ZmUwZjAzNGIxOSIsIHR5cGU9IlVzZXIifXVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFXNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ACkwADmRlY2xhcmluZ0NsYXNzcQB-AApMAAhmaWxlTmFtZXEAfgAKTAAKbWV0aG9kTmFtZXEAfgAKTAAKbW9kdWxlTmFtZXEAfgAKTAANbW9kdWxlVmVyc2lvbnEAfgAKeHABAAAEdHQAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHBwc3EAfgARAQAAFMNxAH4AE3EAfgAUcQB-ABVxAH4AFnBwc3EAfgARAv____5wdAAtamRrLmludGVybmFsLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2UwdAAJamF2YS5iYXNldAAHMTEuMC4xN3NxAH4AEQIAAAA-cHEAfgAZcQB-ABp0AAZpbnZva2VxAH4AHHEAfgAdc3EAfgARAgAAACtwdAAxamRrLmludGVybmFsLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAfcQB-ABxxAH4AHXNxAH4AEQIAAAI2cHQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-AB9xAH4AHHEAfgAdc3EAfgARAQAAAGtxAH4AE3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnBwc3EAfgARAQAAFT9xAH4AE3EAfgAUcQB-ABVxAH4AKXBwc3EAfgARAQAAAGZxAH4AE3QAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9icHBzcQB-ABEBAAACbHEAfgATdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0cHBzcQB-ABEBAAAAMHEAfgATdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5wcHNxAH4AEQEAAAA3cQB-ABN0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxwcHNxAH4AEQEAAABmcQB-ABN0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADl0AA9jYWxsV2l0aENvbnRleHRwcHNxAH4AEQEAAAA0cQB-ABNxAH4APHEAfgA5dAAOcnVuV2l0aENvbnRleHRwcHNxAH4AEQEAAAAtcQB-ABN0ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4ANXEAfgA2cHBzcQB-ABEBAAACOHEAfgATcQB-ADBxAH4AMXEAfgA2cHBzcQB-ABECAAACA3B0AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4AOnEAfgAccQB-AB1zcQB-ABECAAABCHB0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-ADZxAH4AHHEAfgAdc3EAfgARAgAABGhwdAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJxAH4AHHEAfgAdc3EAfgARAgAAAnRwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBLcQB-ADZxAH4AHHEAfgAdc3EAfgARAgAAAz1wdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-ADZxAH4AHHEAfgAdc3IAH2phdmEudXRpbC5Db2xsZWN0aW9ucyRFbXB0eUxpc3R6uBe0PKee3gIAAHhweHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABDvc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4c3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhxAH4AVQAAAAAAAAAQdnIAF2NvbS5jbG91ZC5kYy5EYXRhQ2VudGVyU-gkGtLTtlwCAAB4cAA
2022-12-20 08:04:55,623 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Publish
async job-2784 complete on message bus
2022-12-20 08:04:55,623 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Wake up
jobs related to job-2784
2022-12-20 08:04:55,623 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Update db
status for job-2784
2022-12-20 08:04:55,624 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Wake up
jobs joined with job-2784 and disjoin all subjobs created from job- 2784
2022-12-20 08:04:55,628 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Done
executing com.cloud.vm.VmWorkStart for job-2784
2022-12-20 08:04:55,629 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-7:ctx-5298589d job-2783/job-2784) (logid:4c740aa8) Remove
job-2784 from job monitoring
2022-12-20 08:04:55,635 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Destroying vm VM instance {id: "100", name: "i-2-100-VM", uuid:
"e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"} as it failed to create on
Host with Id:36
2022-12-20 08:04:55,639 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8) VM
instance {id: "100", name: "i-2-100-VM", uuid:
"e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"} state transited from
[Stopped] to [Error] with event [OperationFailedToError]. VM's original host:
null, new host: null, host before state transition: null
2022-12-20 08:04:55,653 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Updating resource Type = volume count for Account = 2 Operation = decreasing
Amount = 1
2022-12-20 08:04:55,656 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Updating resource Type = primary_storage count for Account = 2 Operation =
decreasing Amount = (60,00 GB) 64424509440
2022-12-20 08:04:55,662 WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
alertType=[8] dataCenterId=[16] podId=[15] clusterId=[null] message=[Failed to
deploy Vm with Id: 100, on Host with Id: 36].
2022-12-20 08:04:55,666 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Updating resource Type = user_vm count for Account = 2 Operation = decreasing
Amount = 1
2022-12-20 08:04:55,670 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Updating resource Type = cpu count for Account = 2 Operation = decreasing
Amount = 1
2022-12-20 08:04:55,673 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783 ctx-860f46b6) (logid:4c740aa8)
Updating resource Type = memory count for Account = 2 Operation = decreasing
Amount = 2048
2022-12-20 08:04:55,686 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-6:ctx-c434de23 job-2783) (logid:4c740aa8) Unexpected
exception while executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
2022-12-20 08:04:55,689 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783) (logid:4c740aa8) Complete async
job-2783, jobStatus: FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Unable
to start a VM [e0611ff1-cab5-48d0-ac4e-09fe0f034b19] due to [Unable to create
a deployment for VM instance {id: "100", name: "i-2-100-VM", uuid:
"e0611ff1-cab5-48d0-ac4e-09fe0f034b19", type="User"}]."}
2022-12-20 08:04:55,690 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783) (logid:4c740aa8) Publish async
job-2783 complete on message bus
2022-12-20 08:04:55,690 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783) (logid:4c740aa8) Wake up jobs
related to job-2783
2022-12-20 08:04:55,690 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783) (logid:4c740aa8) Update db status
for job-2783
2022-12-20 08:04:55,690 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783) (logid:4c740aa8) Wake up jobs joined
with job-2783 and disjoin all subjobs created from job- 2783
2022-12-20 08:04:55,692 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-6:ctx-c434de23 job-2783) (logid:4c740aa8) Done executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-2783
2022-12-20 08:04:55,692 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-6:ctx-c434de23 job-2783) (logid:4c740aa8) Remove job-2783
from job monitoring
root@hostname /mnt/secondary/template/tmpl $
smime.p7s
Description: S/MIME Cryptographic Signature
