cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Vivek Kumar <vivek.ku...@indiqus.com>
Subject Re: Deploy VM error
Date Tue, 31 Mar 2020 18:35:41 GMT
Hello F5, 

Can you check the guest VLAN range ? Just click on the Infrastructure > Zone > Physical Network -> Click on the network where you have defined the Guest  - Can you find any range in VLAN/VNI Range ? 

Please find the screenshot for the reference -



 

Vivek Kumar
Manager - Cloud & DevOps 
IndiQus Technologies
24*7  O +91 11 4055 1411  |   M +91 7503460090 
www.indiqus.com <http://indiqus.com/>

This message is intended only for the use of the individual or entity to which it is addressed and may contain information that is confidential and/or privileged. If you are not the intended recipient please delete the original message and any copy of it from your computer system. You are hereby notified that any dissemination, distribution or copying of this communication is strictly prohibited unless proper authorization has been obtained for such action. If you have received this communication in error, please notify the sender immediately. Although IndiQus attempts to sweep e-mail and attachments for viruses, it does not guarantee that both are virus-free and accepts no liability for any damage sustained as a result of viruses.

> On 31-Mar-2020, at 10:25 PM, F5 <f5infonorte@gmail.com> wrote:
> 
> 
> 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