cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From F5 <f5infono...@gmail.com>
Subject Deploy VM error
Date Tue, 31 Mar 2020 16:55:49 GMT

Hello,

I've been struggling for some time to start a KVM environment with ACS.

I already managed to upload the ISOS.

I created a disko offer, and a computing offer.

When I create an instance I came across the following error:

System Capacity
Memory 1.50 GB / 6.63 GB
CPU 1.00 GHz / 12.40 GHz
Storage 10.80 GB / 49.98 GB
Public IP Addresses 2 / 10
Management IP Addresses 2 / 21
Secondary Storage 11.51 GB / 59.76 GB
Local Storage 585.68 MB / 99.95 GB

Failed to deploy VM VM[User|i-2-124-VM


2020-03-31 13:51:59,833 DEBUG [c.c.a.ApiServlet] (qtp504527234-14:ctx-0599648e) (logid:4f662644) ===START===  172.26.0.190 -- GET  command=deployVirtualMachine&response=json&zoneid=f525ca16-891e-4749-b147-d426ecfab483&podid=673181c2-43fb-45e2-91b0-7496f2975a7b&clusterid=81cb2d64-d39c-40c5-a3ad-8b8e9fce4f83&hostid=6d169723-2440-46a5-a815-67580656dd6d&templateid=eb47e5c4-c18e-4706-8f54-518dd5eee6e0&hypervisor=KVM&serviceofferingid=91e18f3a-1fe7-4184-a58d-e5d503a15af2&diskofferingid=0a97d09f-a648-44a2-89e7-336fdb444a09&iptonetworklist%5B0%5D.networkid=19cbc69f-91b5-48bb-8de3-e1c582e07a4a&displayname=Vmteste&name=Vmteste&_=1585672416295
2020-03-31 13:51:59,866 DEBUG [c.c.a.ApiServer] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) CIDRs from which account 'Acct[e8c8861d-5f9c-11ea-bb9d-080027a1c01e-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2020-03-31 13:51:59,909 DEBUG [c.c.u.AccountManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Access granted to Acct[e8c8861d-5f9c-11ea-bb9d-080027a1c01e-admin] to org.apache.cloudstack.quota.vo.ServiceOfferingVO$$EnhancerByCGLIB$$3bcf647@45f3fc7f by AffinityGroupAccessChecker
2020-03-31 13:51:59,910 DEBUG [c.c.u.AccountManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Access granted to Acct[e8c8861d-5f9c-11ea-bb9d-080027a1c01e-admin] to com.cloud.storage.DiskOfferingVO$$EnhancerByCGLIB$$ac86733a@51a8f01c by AffinityGroupAccessChecker
2020-03-31 13:51:59,945 DEBUG [c.c.n.NetworkModelImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Service SecurityGroup is not supported in the network id=208
2020-03-31 13:51:59,985 DEBUG [c.c.v.UserVmManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Allocating in the DB for vm
2020-03-31 13:52:00,055 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Allocating entries for VM: VM[User|i-2-124-VM]
2020-03-31 13:52:00,057 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Allocating nics for VM[User|i-2-124-VM]
2020-03-31 13:52:00,058 DEBUG [o.a.c.e.o.NetworkOrchestrator] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Allocating nic for vm VM[User|i-2-124-VM] in network Ntwk[208|Guest|22] with requested profile NicProfile[0-0-null-null-null
2020-03-31 13:52:00,110 DEBUG [c.c.n.NetworkModelImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Service SecurityGroup is not supported in the network id=208
2020-03-31 13:52:00,111 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Allocating disks for VM[User|i-2-124-VM]
2020-03-31 13:52:00,117 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Updating resource Type = volume count for Account = 2 Operation = increasing Amount = 1
2020-03-31 13:52:00,121 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Updating resource Type = primary_storage count for Account = 2 Operation = increasing Amount = 5368709120
2020-03-31 13:52:00,124 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Allocation completed for VM: VM[User|i-2-124-VM]
2020-03-31 13:52:00,124 DEBUG [c.c.v.UserVmManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Successfully allocated DB entry for VM[User|i-2-124-VM]
2020-03-31 13:52:00,128 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Updating resource Type = user_vm count for Account = 2 Operation = increasing Amount = 1
2020-03-31 13:52:00,130 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Updating resource Type = cpu count for Account = 2 Operation = increasing Amount = 1
2020-03-31 13:52:00,133 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Updating resource Type = memory count for Account = 2 Operation = increasing Amount = 512
2020-03-31 13:52:00,158 DEBUG [c.c.n.NetworkModelImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Service SecurityGroup is not supported in the network id=208
2020-03-31 13:52:00,162 DEBUG [c.c.n.NetworkModelImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) Service SecurityGroup is not supported in the network id=208
2020-03-31 13:52:00,189 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-1:ctx-b4014d05 job-608) (logid:bc01a954) Add job-608 into job monitoring
2020-03-31 13:52:00,191 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) submit async job-608, details: AsyncJobVO {id:608, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 124, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"iptonetworklist[0].networkid":"19cbc69f-91b5-48bb-8de3-e1c582e07a4a","hostid":"6d169723-2440-46a5-a815-67580656dd6d","httpmethod":"GET","clusterid":"81cb2d64-d39c-40c5-a3ad-8b8e9fce4f83","templateid":"eb47e5c4-c18e-4706-8f54-518dd5eee6e0","ctxAccountId":"2","uuid":"153092ed-cd93-454e-8621-4a55d81b031b","cmdEventType":"VM.CREATE","diskofferingid":"0a97d09f-a648-44a2-89e7-336fdb444a09","serviceofferingid":"91e18f3a-1fe7-4184-a58d-e5d503a15af2","response":"json","ctxUserId":"2","hypervisor":"KVM","displayname":"Vmteste","name":"Vmteste","zoneid":"f525ca16-891e-4749-b147-d426ecfab483","ctxStartEventId":"734","id":"124","ctxDetails":"{\"interface com.cloud.dc.Pod\":\"673181c2-43fb-45e2-91b0-7496f2975a7b\",\"interface com.cloud.org.Cluster\":\"81cb2d64-d39c-40c5-a3ad-8b8e9fce4f83\",\"interface com.cloud.offering.ServiceOffering\":\"91e18f3a-1fe7-4184-a58d-e5d503a15af2\",\"interface com.cloud.host.Host\":\"6d169723-2440-46a5-a815-67580656dd6d\",\"interface com.cloud.template.VirtualMachineTemplate\":\"eb47e5c4-c18e-4706-8f54-518dd5eee6e0\",\"interface com.cloud.dc.DataCenter\":\"f525ca16-891e-4749-b147-d426ecfab483\",\"interface com.cloud.offering.DiskOffering\":\"0a97d09f-a648-44a2-89e7-336fdb444a09\",\"interface com.cloud.vm.VirtualMachine\":\"153092ed-cd93-454e-8621-4a55d81b031b\"}","podid":"673181c2-43fb-45e2-91b0-7496f2975a7b","_":"1585672416295"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 8796757934110, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2020-03-31 13:52:00,193 DEBUG [c.c.a.ApiServlet] (qtp504527234-14:ctx-0599648e ctx-db3e314d) (logid:4f662644) ===END===  172.26.0.190 -- GET  command=deployVirtualMachine&response=json&zoneid=f525ca16-891e-4749-b147-d426ecfab483&podid=673181c2-43fb-45e2-91b0-7496f2975a7b&clusterid=81cb2d64-d39c-40c5-a3ad-8b8e9fce4f83&hostid=6d169723-2440-46a5-a815-67580656dd6d&templateid=eb47e5c4-c18e-4706-8f54-518dd5eee6e0&hypervisor=KVM&serviceofferingid=91e18f3a-1fe7-4184-a58d-e5d503a15af2&diskofferingid=0a97d09f-a648-44a2-89e7-336fdb444a09&iptonetworklist%5B0%5D.networkid=19cbc69f-91b5-48bb-8de3-e1c582e07a4a&displayname=Vmteste&name=Vmteste&_=1585672416295
2020-03-31 13:52:00,193 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608) (logid:d9d8d7a4) Executing AsyncJobVO {id:608, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 124, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"iptonetworklist[0].networkid":"19cbc69f-91b5-48bb-8de3-e1c582e07a4a","hostid":"6d169723-2440-46a5-a815-67580656dd6d","httpmethod":"GET","clusterid":"81cb2d64-d39c-40c5-a3ad-8b8e9fce4f83","templateid":"eb47e5c4-c18e-4706-8f54-518dd5eee6e0","ctxAccountId":"2","uuid":"153092ed-cd93-454e-8621-4a55d81b031b","cmdEventType":"VM.CREATE","diskofferingid":"0a97d09f-a648-44a2-89e7-336fdb444a09","serviceofferingid":"91e18f3a-1fe7-4184-a58d-e5d503a15af2","response":"json","ctxUserId":"2","hypervisor":"KVM","displayname":"Vmteste","name":"Vmteste","zoneid":"f525ca16-891e-4749-b147-d426ecfab483","ctxStartEventId":"734","id":"124","ctxDetails":"{\"interface com.cloud.dc.Pod\":\"673181c2-43fb-45e2-91b0-7496f2975a7b\",\"interface com.cloud.org.Cluster\":\"81cb2d64-d39c-40c5-a3ad-8b8e9fce4f83\",\"interface com.cloud.offering.ServiceOffering\":\"91e18f3a-1fe7-4184-a58d-e5d503a15af2\",\"interface com.cloud.host.Host\":\"6d169723-2440-46a5-a815-67580656dd6d\",\"interface com.cloud.template.VirtualMachineTemplate\":\"eb47e5c4-c18e-4706-8f54-518dd5eee6e0\",\"interface com.cloud.dc.DataCenter\":\"f525ca16-891e-4749-b147-d426ecfab483\",\"interface com.cloud.offering.DiskOffering\":\"0a97d09f-a648-44a2-89e7-336fdb444a09\",\"interface com.cloud.vm.VirtualMachine\":\"153092ed-cd93-454e-8621-4a55d81b031b\"}","podid":"673181c2-43fb-45e2-91b0-7496f2975a7b","_":"1585672416295"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 8796757934110, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2020-03-31 13:52:00,319 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Service SecurityGroup is not supported in the network id=208
2020-03-31 13:52:00,324 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Service SecurityGroup is not supported in the network id=208
2020-03-31 13:52:00,327 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Destination Host to deploy the VM is specified, specifying a deployment plan to deploy the VM
2020-03-31 13:52:00,360 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) DeploymentPlanner allocation algorithm: null
2020-03-31 13:52:00,361 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
2020-03-31 13:52:00,361 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Is ROOT volume READY (pool already allocated)?: No
2020-03-31 13:52:00,361 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2020-03-31 13:52:00,364 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2020-03-31 13:52:00,371 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Checking suitable pools for volume (Id, Type): (127,ROOT)
2020-03-31 13:52:00,372 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) We need to allocate new storagepool for this volume
2020-03-31 13:52:00,376 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Calling StoragePoolAllocators to find suitable pools
2020-03-31 13:52:00,380 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2020-03-31 13:52:00,389 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Checking if storage pool is suitable, name: null ,poolId: 1
2020-03-31 13:52:00,395 INFO  [c.c.s.StorageManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2020-03-31 13:52:00,399 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Checking pool 1 for storage, totalSize: 53660876800, usedBytes: 11387019264, usedPct: 0.21220337689301416, disable threshold: 0.85
2020-03-31 13:52:00,399 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Destination pool id: 1
2020-03-31 13:52:00,459 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Pool ID for the volume with ID 127 is null
2020-03-31 13:52:00,463 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Found storage pool kvm-lab-01-local-fdf04200 of type Filesystem with over-provisioning factor 2
2020-03-31 13:52:00,463 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Total over-provisioned capacity calculated is 2 * 53660876800
2020-03-31 13:52:00,463 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Total capacity of the pool kvm-lab-01-local-fdf04200 with ID 1 is 107321753600
2020-03-31 13:52:00,464 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Checking pool: 1 for storage allocation , maxSize : 107321753600, totalAllocatedSize : 614129152, askingSize : 5368709120, allocated disable threshold: 0.85
2020-03-31 13:52:00,464 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Found suitable local storage pool 1, adding to list
2020-03-31 13:52:00,464 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) LocalStoragePoolAllocator returning 1 suitable storage pools
2020-03-31 13:52:00,464 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2020-03-31 13:52:00,465 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2020-03-31 13:52:00,466 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Host: 1 can access pool: 1
2020-03-31 13:52:00,468 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Found a potential host id: 1 name: kvm-lab-01 and associated storage pools for this VM
2020-03-31 13:52:00,470 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(127|ROOT-->Pool(1))]
2020-03-31 13:52:00,560 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Sync job-609 execution on object VmWorkJobQueue.124
2020-03-31 13:52:01,686 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-babe2baf) (logid:0f7d8141) Execute sync-queue item: SyncQueueItemVO {id:438, queueId: 438, contentType: AsyncJob, contentId: 609, lastProcessMsid: 8796757934110, lastprocessNumber: 1, lastProcessTime: Tue Mar 31 13:52:01 BRT 2020, created: Tue Mar 31 13:52:00 BRT 2020}
2020-03-31 13:52:01,687 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-babe2baf) (logid:0f7d8141) Schedule queued job-609
2020-03-31 13:52:01,704 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:26fd9193) Add job-609 into job monitoring
2020-03-31 13:52:01,708 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-d073b571) (logid:40314552) Begin cleanup expired async-jobs
2020-03-31 13:52:01,711 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Executing AsyncJobVO {id:609, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAfHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 8796757934110, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue Mar 31 13:52:00 BRT 2020, removed: null}
2020-03-31 13:52:01,712 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-d073b571) (logid:40314552) End cleanup expired async-jobs
2020-03-31 13:52:01,715 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Run VM work job: com.cloud.vm.VmWorkStart for VM 124, job origin: 608
2020-03-31 13:52:01,717 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":1,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":124,"handlerName":"VirtualMachineManagerImpl"}
2020-03-31 13:52:01,724 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
2020-03-31 13:52:01,724 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Successfully transitioned to start state for VM[User|i-2-124-VM] reservation id = e55bdd7d-2abf-4d82-95e8-a9dabb87a8cf
2020-03-31 13:52:01,731 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null
2020-03-31 13:52:01,731 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Deploy avoids pods: null, clusters: null, hosts: null
2020-03-31 13:52:01,737 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) DeploymentPlanner allocation algorithm: null
2020-03-31 13:52:01,737 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
2020-03-31 13:52:01,737 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Is ROOT volume READY (pool already allocated)?: No
2020-03-31 13:52:01,737 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2020-03-31 13:52:01,738 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2020-03-31 13:52:01,741 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Checking suitable pools for volume (Id, Type): (127,ROOT)
2020-03-31 13:52:01,741 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) We need to allocate new storagepool for this volume
2020-03-31 13:52:01,742 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Calling StoragePoolAllocators to find suitable pools
2020-03-31 13:52:01,742 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2020-03-31 13:52:01,745 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Checking if storage pool is suitable, name: null ,poolId: 1
2020-03-31 13:52:01,746 INFO  [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2020-03-31 13:52:01,747 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Checking pool 1 for storage, totalSize: 53660876800, usedBytes: 11387019264, usedPct: 0.21220337689301416, disable threshold: 0.85
2020-03-31 13:52:01,747 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Destination pool id: 1
2020-03-31 13:52:01,754 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Pool ID for the volume with ID 127 is null
2020-03-31 13:52:01,757 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Found storage pool kvm-lab-01-local-fdf04200 of type Filesystem with over-provisioning factor 2
2020-03-31 13:52:01,757 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Total over-provisioned capacity calculated is 2 * 53660876800
2020-03-31 13:52:01,757 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Total capacity of the pool kvm-lab-01-local-fdf04200 with ID 1 is 107321753600
2020-03-31 13:52:01,773 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Checking pool: 1 for storage allocation , maxSize : 107321753600, totalAllocatedSize : 614129152, askingSize : 5368709120, allocated disable threshold: 0.85
2020-03-31 13:52:01,773 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Found suitable local storage pool 1, adding to list
2020-03-31 13:52:01,773 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) LocalStoragePoolAllocator returning 1 suitable storage pools
2020-03-31 13:52:01,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2020-03-31 13:52:01,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2020-03-31 13:52:01,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Host: 1 can access pool: 1
2020-03-31 13:52:01,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Found a potential host id: 1 name: kvm-lab-01 and associated storage pools for this VM
2020-03-31 13:52:01,776 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(127|ROOT-->Pool(1))]
2020-03-31 13:52:01,777 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Deployment found  - P0=VM[User|i-2-124-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(127|ROOT-->Pool(1))]
2020-03-31 13:52:01,800 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2020-03-31 13:52:01,807 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Hosts's actual total CPU: 12400 and CPU after applying overprovisioning: 12400
2020-03-31 13:52:01,807 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) We are allocating VM, increasing the used capacity of this host:1
2020-03-31 13:52:01,807 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Current Used CPU: 1000 , Free CPU:11400 ,Requested CPU: 500
2020-03-31 13:52:01,807 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Current Used RAM: 1610612736 , Free RAM:5504905216 ,Requested RAM: 536870912
2020-03-31 13:52:01,807 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) CPU STATS after allocation: for host: 1, old used: 1000, old reserved: 0, actual total: 12400, total with overprovisioning: 12400; new used:1500, reserved:0; requested cpu:500,alloc_from_last:false
2020-03-31 13:52:01,807 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) RAM STATS after allocation: for host: 1, old used: 1610612736, old reserved: 0, total: 7115517952; new used: 2147483648, reserved: 0; requested mem: 536870912,alloc_from_last:false
2020-03-31 13:52:01,837 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Lock is acquired for network id 208 as a part of network implement
2020-03-31 13:52:01,837 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Asking ExternalGuestNetworkGuru to implement Ntwk[208|Guest|22]
2020-03-31 13:52:01,957 DEBUG [c.c.u.d.T.Transaction] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Rolling back the transaction: Time = 1 Name =  Work-Job-Executor-1; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy57.take:-1-DataCenterDaoImpl.allocateVnet:212-NativeMethodAccessorImpl.invoke0:-2-NativeMethodAccessorImpl.invoke:62
2020-03-31 13:52:01,959 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Cleaning up because we're unable to implement the network Ntwk[208|Guest|22]
2020-03-31 13:52:01,970 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Lock is acquired for network Ntwk[208|Guest|22] as a part of network shutdown
2020-03-31 13:52:01,973 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Sending network shutdown to VirtualRouter
2020-03-31 13:52:01,975 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Network id=208 is shutdown successfully, cleaning up corresponding resources now.
2020-03-31 13:52:01,990 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Lock is released for network Ntwk[208|Guest|22] as a part of network shutdown
2020-03-31 13:52:01,997 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Lock is released for network id 208 as a part of network implement
2020-03-31 13:52:01,997 INFO  [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Insufficient capacity 
com.cloud.exception.InsufficientVirtualNetworkCapacityException: Unable to allocate vnet as a part of network Ntwk[208|Guest|22] implement Scope=interface com.cloud.dc.DataCenter; id=1
	at com.cloud.network.guru.GuestNetworkGuru.allocateVnet(GuestNetworkGuru.java:291)
	at com.cloud.network.guru.GuestNetworkGuru.implement(GuestNetworkGuru.java:320)
	at com.cloud.network.guru.ExternalGuestNetworkGuru.implement(ExternalGuestNetworkGuru.java:132)
	at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:1132)
	at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:1071)
	at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1642)
	at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1099)
	at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5107)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
	at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5270)
	at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
	at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:583)
	at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
	at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
	at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:531)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2020-03-31 13:52:02,003 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Cleaning up resources for the vm VM[User|i-2-124-VM] in Starting state
2020-03-31 13:52:02,008 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Seq 1-8585549739628429360: Sending  { Cmd , MgmtId: 8796757934110, via: 1(kvm-lab-01), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"volumesToDisconnect":[],"vmName":"i-2-124-VM","executeInSequence":false,"wait":0}}] }
2020-03-31 13:52:02,236 DEBUG [c.c.a.t.Request] (AgentManager-Handler-3:null) (logid:) Seq 1-8585549739628429360: Processing:  { Ans: , MgmtId: 8796757934110, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2020-03-31 13:52:02,237 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Seq 1-8585549739628429360: Received:  { Ans: , MgmtId: 8796757934110, via: 1(kvm-lab-01), Ver: v1, Flags: 10, { StopAnswer } }
2020-03-31 13:52:02,255 ERROR [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Failed to remove dhcp-dns entry due to: 
com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is unreachable: Can't find at least one router!
	at com.cloud.network.element.VirtualRouterElement.removeDhcpEntry(VirtualRouterElement.java:962)
	at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.cleanupNicDhcpDnsEntry(NetworkOrchestrator.java:3020)
	at com.cloud.vm.UserVmManagerImpl.finalizeStop(UserVmManagerImpl.java:4549)
	at com.cloud.vm.VirtualMachineManagerImpl.sendStop(VirtualMachineManagerImpl.java:1473)
	at com.cloud.vm.VirtualMachineManagerImpl.cleanup(VirtualMachineManagerImpl.java:1507)
	at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1260)
	at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5107)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
	at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5270)
	at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
	at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:583)
	at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
	at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
	at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:531)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2020-03-31 13:52:02,270 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Successfully released network resources for the vm VM[User|i-2-124-VM]
2020-03-31 13:52:02,270 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Successfully cleaned up resources for the VM VM[User|i-2-124-VM] in Starting state
2020-03-31 13:52:02,277 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) DeploymentPlanner allocation algorithm: null
2020-03-31 13:52:02,277 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
2020-03-31 13:52:02,277 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Is ROOT volume READY (pool already allocated)?: No
2020-03-31 13:52:02,277 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2020-03-31 13:52:02,278 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) The specified host is in avoid set
2020-03-31 13:52:02,278 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Cannot deploy to specified host, returning.
2020-03-31 13:52:02,292 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2020-03-31 13:52:02,298 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Hosts's actual total CPU: 12400 and CPU after applying overprovisioning: 12400
2020-03-31 13:52:02,298 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Hosts's actual total RAM: 7115517952 and RAM after applying overprovisioning: 7115517952
2020-03-31 13:52:02,298 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) release cpu from host: 1, old used: 1500,reserved: 0, actual total: 12400, total with overprovisioning: 12400; new used: 1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2020-03-31 13:52:02,298 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) release mem from host: 1, old used: 2147483648,reserved: 0, total: 7115517952; new used: 1610612736,reserved:0; movedfromreserved: false,moveToReserveredfalse
2020-03-31 13:52:02,301 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-26b15051) (logid:316e6c2c) Found 0 routers to update status. 
2020-03-31 13:52:02,302 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-26b15051) (logid:316e6c2c) Found 0 VPC networks to update Redundant State. 
2020-03-31 13:52:02,303 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-26b15051) (logid:316e6c2c) Found 1 networks to update RvR status. 
2020-03-31 13:52:02,309 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-124-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2020-03-31 13:52:02,310 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609 ctx-0907bbc6) (logid:d9d8d7a4) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-124-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2020-03-31 13:52:02,310 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 124, job origin: 608
2020-03-31 13:52:02,310 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Unable to complete AsyncJobVO {id:609, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAfHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 8796757934110, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue Mar 31 13:52:00 BRT 2020, removed: null}, job origin:608
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-124-VM]Scope=interface com.cloud.dc.DataCenter; id=1
	at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1063)
	at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5107)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
	at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5270)
	at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
	at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:583)
	at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
	at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
	at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:531)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2020-03-31 13:52:02,318 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Complete async job-609, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA1VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0yLTEyNC1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABVzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AAp4cAAABCd0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRzcQB-ABEAABPzcQB-ABNxAH4AFHEAfgAVc3EAfgAR_____nQAJHN1bi5yZWZsZWN0Lk5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHNxAH4AEQAAAD5xAH4AGHEAfgAZdAAGaW52b2tlc3EAfgARAAAAK3QAKHN1bi5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AHHNxAH4AEQAAAfJ0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAcc3EAfgARAAAAa3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnNxAH4AEQAAFJZxAH4AE3EAfgAUcQB-ACZzcQB-ABEAAABmdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-ABEAAAJHdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgARAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgARAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4AEQAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADZ0AA9jYWxsV2l0aENvbnRleHRzcQB-ABEAAAA1cQB-ADlxAH4ANnQADnJ1bldpdGhDb250ZXh0c3EAfgARAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAycQB-ADNzcQB-ABEAAAITcQB-AC1xAH4ALnEAfgAzc3EAfgARAAAB_3QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA3c3EAfgARAAABCnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AM3NxAH4AEQAABH10ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4AEQAAAnB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEhxAH4AM3NxAH4AEQAAAux0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AM3NyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAMeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-AFR4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcQB-AFMAAAAAdwQAAAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cQB-AFYAAAAAAAAAAXZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlclPoJBrS07ZcAgAAeHAA
2020-03-31 13:52:02,319 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Publish async job-609 complete on message bus
2020-03-31 13:52:02,319 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Wake up jobs related to job-609
2020-03-31 13:52:02,319 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Update db status for job-609
2020-03-31 13:52:02,320 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Wake up jobs joined with job-609 and disjoin all subjobs created from job- 609
2020-03-31 13:52:02,332 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Done executing com.cloud.vm.VmWorkStart for job-609
2020-03-31 13:52:02,333 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-1:ctx-24c1cfde job-608/job-609) (logid:d9d8d7a4) Remove job-609 from job monitoring
2020-03-31 13:52:02,345 ERROR [c.c.v.UserVmManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) VM VM[User|i-2-124-VM] unexpectedly went to Stopped state
2020-03-31 13:52:02,347 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Destroying vm VM[User|i-2-124-VM] as it failed to create on Host with Id:1
2020-03-31 13:52:02,359 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) VM state transitted from :Stopped to Error with event: OperationFailedToErrorvm's original host id: null new host id: null host id before state transition: null
2020-03-31 13:52:02,373 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Updating resource Type = volume count for Account = 2 Operation = decreasing Amount = 1
2020-03-31 13:52:02,380 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Updating resource Type = primary_storage count for Account = 2 Operation = decreasing Amount = 5368709120
2020-03-31 13:52:02,387 WARN  [c.c.a.AlertManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) AlertType:: 8 | dataCenterId:: 1 | podId:: 1 | clusterId:: null | message:: Failed to deploy Vm with Id: 124, on Host with Id: 1
2020-03-31 13:52:02,392 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Updating resource Type = user_vm count for Account = 2 Operation = decreasing Amount = 1
2020-03-31 13:52:02,398 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Updating resource Type = cpu count for Account = 2 Operation = decreasing Amount = 1
2020-03-31 13:52:02,405 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Updating resource Type = memory count for Account = 2 Operation = decreasing Amount = 512
2020-03-31 13:52:02,416 WARN  [o.a.c.a.c.a.v.DeployVMCmdByAdmin] (API-Job-Executor-1:ctx-b4014d05 job-608 ctx-e868ef86) (logid:d9d8d7a4) Exception: 
com.cloud.exception.ConcurrentOperationException: Failed to deploy VM VM[User|i-2-124-VM]
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4240)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4222)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174)
	at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
	at com.sun.proxy.$Proxy190.startVirtualMachine(Unknown Source)
	at org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin.execute(DeployVMCmdByAdmin.java:67)
	at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
	at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
	at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:583)
	at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
	at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
	at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
	at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:531)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2020-03-31 13:52:02,418 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608) (logid:d9d8d7a4) Complete async job-608, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed to deploy VM VM[User|i-2-124-VM]"}
2020-03-31 13:52:02,420 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608) (logid:d9d8d7a4) Publish async job-608 complete on message bus
2020-03-31 13:52:02,420 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608) (logid:d9d8d7a4) Wake up jobs related to job-608
2020-03-31 13:52:02,420 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608) (logid:d9d8d7a4) Update db status for job-608
2020-03-31 13:52:02,421 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608) (logid:d9d8d7a4) Wake up jobs joined with job-608 and disjoin all subjobs created from job- 608
2020-03-31 13:52:02,428 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-b4014d05 job-608) (logid:d9d8d7a4) Done executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-608
2020-03-31 13:52:02,428 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-1:ctx-b4014d05 job-608) (logid:d9d8d7a4) Remove job-608 from job monitoring
2020-03-31 13:52:02,547 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) (logid:) SeqA 6-130909: Processing Seq 6-130909:  { Cmd , MgmtId: -1, via: 6, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":118,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2020-03-31 13:52:02,556 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) (logid:) SeqA 6-130909: Sending Seq 6-130909:  { Ans: , MgmtId: 8796757934110, via: 6, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2020-03-31 13:52:03,211 DEBUG [c.c.a.ApiServlet] (qtp504527234-14:ctx-8b223ede) (logid:aa4573c8) ===START===  172.26.0.190 -- GET  command=queryAsyncJobResult&jobId=d9d8d7a4-bd0b-4f4a-9df3-fffeff7eeb49&response=json&_=1585672416296
2020-03-31 13:52:03,221 DEBUG [c.c.a.ApiServer] (qtp504527234-14:ctx-8b223ede ctx-627eabb9) (logid:aa4573c8) CIDRs from which account 'Acct[e8c8861d-5f9c-11ea-bb9d-080027a1c01e-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2020-03-31 13:52:03,249 DEBUG [c.c.a.ApiServlet] (qtp504527234-14:ctx-8b223ede ctx-627eabb9) (logid:aa4573c8) ===END===  172.26.0.190 -- GET  command=queryAsyncJobResult&jobId=d9d8d7a4-bd0b-4f4a-9df3-fffeff7eeb49&response=json&_=1585672416296
2020-03-31 13:52:03,254 DEBUG [c.c.a.ApiServlet] (qtp504527234-251:ctx-9b48d289) (logid:a4f81600) ===START===  172.26.0.190 -- GET  command=listVirtualMachines&id=153092ed-cd93-454e-8621-4a55d81b031b&response=json&_=1585672416297
2020-03-31 13:52:03,260 DEBUG [c.c.a.ApiServer] (qtp504527234-251:ctx-9b48d289 ctx-adf301e9) (logid:a4f81600) CIDRs from which account 'Acct[e8c8861d-5f9c-11ea-bb9d-080027a1c01e-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2020-03-31 13:52:03,283 DEBUG [c.c.a.ApiServlet] (qtp504527234-251:ctx-9b48d289 ctx-adf301e9) (logid:a4f81600) ===END===  172.26.0.190 -- GET  command=listVirtualMachines&id=153092ed-cd93-454e-8621-4a55d81b031b&response=json&_=1585672416297


Mime
View raw message