You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by F5 <f5...@gmail.com> on 2020/03/31 16:55:49 UTC
Deploy VM error
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
Re: RE: RE: Deploy VM error
Posted by F5 <f5...@gmail.com>.
when i add in sorce 0.0.0.0/0 it automatically fills in to my network.
Infrastructure> Zones> Physical Network> Public> configure> Ip Range
I'm thinking it can be in this configuration, I configured it as follows:
Gateway - 172.26.0.1
Netmask - 255.255.255.0
VLAN / VNI - vlan: // untagged
Start IP - 172.26.0.170
End IP - 172.26.0.180
Account: system
Domain: ROOT
System VMs: true
It's an advanced zone, can you confirm that I did it right?
Thank you for your help
Re: RE: RE: Deploy VM error
Posted by Andrija Panic <an...@gmail.com>.
for beginning, add 0.0.0.0/0 to both source and destination and
allow all protocols
if that doesn't work you have a different problem.
On Wed, 1 Apr 2020 at 18:36, F5 <f5...@gmail.com> wrote:
> exit rules do not block the exit?
>
> Configure the rules to block Traffic
>
> for example, in the configuration I made, I would be blocking all traffic
> to the internet:
>
> Source CIDR
> 10.1.3.0/24
> Target CIDR
> 0.0.0.0/0
> _________________
> when I ping 8.8.8.8
>
> From 172.26.0.178 icmp_seq = 5 Destination Host Unreachable
> __________
> View IP Addresses
> Network IPs
> 172.26.0.178 [Source NAT]
>
--
Andrija Panić
Re: RE: RE: Deploy VM error
Posted by F5 <f5...@gmail.com>.
exit rules do not block the exit?
Configure the rules to block Traffic
for example, in the configuration I made, I would be blocking all traffic to the internet:
Source CIDR
10.1.3.0/24
Target CIDR
0.0.0.0/0
_________________
when I ping 8.8.8.8
From 172.26.0.178 icmp_seq = 5 Destination Host Unreachable
__________
View IP Addresses
Network IPs
172.26.0.178 [Source NAT]
RE: RE: Deploy VM error
Posted by Adam Witwicki <aw...@oakfordis.com>.
You have to add a rule for your network
-----Original Message-----
From: F5 <f5...@gmail.com>
Sent: 01 April 2020 13:51
To: users@cloudstack.apache.org
Subject: Re: RE: Deploy VM error
** This mail originated from OUTSIDE the Oakford corporate network. Treat hyperlinks and attachments in this email with caution. **
egress rules nothing configured.
in Instance resolv.conf is with dns 8.8.8.8
but it does not solve even for that address.
Is there any light of what can be?
Disclaimer Notice:
This email has been sent by Oakford Technology Limited, while we have checked this e-mail and any attachments for viruses, we can not guarantee that they are virus-free. You must therefore take full responsibility for virus checking.
This message and any attachments are confidential and should only be read by those to whom they are addressed. If you are not the intended recipient, please contact us, delete the message from your computer and destroy any copies. Any distribution or copying without our prior permission is prohibited.
Internet communications are not always secure and therefore Oakford Technology Limited does not accept legal responsibility for this message. The recipient is responsible for verifying its authenticity before acting on the contents. Any views or opinions presented are solely those of the author and do not necessarily represent those of Oakford Technology Limited.
Registered address: Oakford Technology Limited, The Manor House, Potterne, Wiltshire. SN10 5PN.
Registered in England and Wales No. 5971519
Re: RE: Deploy VM error
Posted by F5 <f5...@gmail.com>.
egress rules nothing configured.
in Instance resolv.conf is with dns 8.8.8.8
but it does not solve even for that address.
Is there any light of what can be?
RE: Deploy VM error
Posted by Adam Witwicki <aw...@oakfordis.com>.
Network egress rules?
Network > your isolated network name > egress rules tab
Adam
-----Original Message-----
From: F5 <f5...@gmail.com>
Sent: 01 April 2020 13:24
To: users@cloudstack.apache.org
Subject: Re: Deploy VM error
** This mail originated from OUTSIDE the Oakford corporate network. Treat hyperlinks and attachments in this email with caution. **
Perfect, that was it, manually adding the range and it worked.
Thanks.
Taking advantage of the moment, I am new to ACS, now that I have created a VM, what causes it not to be surfing the internet, is there any additional configuration for this?
Disclaimer Notice:
This email has been sent by Oakford Technology Limited, while we have checked this e-mail and any attachments for viruses, we can not guarantee that they are virus-free. You must therefore take full responsibility for virus checking.
This message and any attachments are confidential and should only be read by those to whom they are addressed. If you are not the intended recipient, please contact us, delete the message from your computer and destroy any copies. Any distribution or copying without our prior permission is prohibited.
Internet communications are not always secure and therefore Oakford Technology Limited does not accept legal responsibility for this message. The recipient is responsible for verifying its authenticity before acting on the contents. Any views or opinions presented are solely those of the author and do not necessarily represent those of Oakford Technology Limited.
Registered address: Oakford Technology Limited, The Manor House, Potterne, Wiltshire. SN10 5PN.
Registered in England and Wales No. 5971519
Re: Deploy VM error
Posted by F5 <f5...@gmail.com>.
Perfect, that was it, manually adding the range and it worked.
Thanks.
Taking advantage of the moment, I am new to ACS, now that I have created a VM, what causes it not to be surfing the internet, is there any additional configuration for this?
Re: Deploy VM error
Posted by Vivek Kumar <vi...@indiqus.com>.
Hello F5,
Can you click on edit and add some range ( I hope you had already configured that while configuring the zone, same needs to be added here. Seems like a bug in CloudStack 4.13, it always wipe out the guest VLAN range so need to put that again). Can you just add the range and try to provision the instance.
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 01-Apr-2020, at 12:28 AM, F5 <f5...@gmail.com> wrote:
>
> Details
> State Enabled
> KVM traffic label cloudbr1
> ___________________________________
> Network
> Name Type VLAN/VNI ID Broadcast URI IPv4 CIDR IPv6 CIDR
> redeMarciel Isolated 10.1.3.0/24
> ___________________________________
>
> Dedicated VLAN/VNI Ranges
> VLAN/VNI Range(s) Domain Account Quickview
> No data to show
>
> ___________________
>
Re: Deploy VM error
Posted by F5 <f5...@gmail.com>.
Details
State Enabled
KVM traffic label cloudbr1
___________________________________
Network
Name Type VLAN/VNI ID Broadcast URI IPv4 CIDR IPv6 CIDR
redeMarciel Isolated 10.1.3.0/24
___________________________________
Dedicated VLAN/VNI Ranges
VLAN/VNI Range(s) Domain Account Quickview
No data to show
___________________
Re: Deploy VM error
Posted by Vivek Kumar <vi...@indiqus.com>.
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 <f5...@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
>