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

Hello,

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

I already managed to upload the ISOS.

I created a disko offer, and a computing offer.

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

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

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

2020-03-31 13:51:59,833 DEBUG [c.c.a.ApiServlet] = (qtp504527234-14:ctx-0599648e) (logid:4f662644) =3D=3D=3DSTART=3D=3D=3D = 172.26.0.190 -- GET = command=3DdeployVirtualMachine&response=3Djson&zoneid=3Df525= ca16-891e-4749-b147-d426ecfab483&podid=3D673181c2-43fb-45e2-91b0-7496f= 2975a7b&clusterid=3D81cb2d64-d39c-40c5-a3ad-8b8e9fce4f83&hostid=3D= 6d169723-2440-46a5-a815-67580656dd6d&templateid=3Deb47e5c4-c18e-4706-8= f54-518dd5eee6e0&hypervisor=3DKVM&serviceofferingid=3D91e18f3a-1fe= 7-4184-a58d-e5d503a15af2&diskofferingid=3D0a97d09f-a648-44a2-89e7-336f= db444a09&iptonetworklist%5B0%5D.networkid=3D19cbc69f-91b5-48bb-8de3-e1= c582e07a4a&displayname=3DVmteste&name=3DVmteste&_=3D1585672416= 295
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=3D208
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=3D208
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 =3D volume count = for Account =3D 2 Operation =3D increasing Amount =3D 1
2020-03-31 13:52:00,121 DEBUG = [c.c.r.ResourceLimitManagerImpl] (qtp504527234-14:ctx-0599648e = ctx-db3e314d) (logid:4f662644) Updating resource Type =3D = primary_storage count for Account =3D 2 Operation =3D increasing Amount = =3D 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 =3D user_vm count = for Account =3D 2 Operation =3D increasing Amount =3D 1
2020-03-31 13:52:00,130 DEBUG = [c.c.r.ResourceLimitManagerImpl] (qtp504527234-14:ctx-0599648e = ctx-db3e314d) (logid:4f662644) Updating resource Type =3D cpu count for = Account =3D 2 Operation =3D increasing Amount =3D 1
2020-03-31 13:52:00,133 DEBUG = [c.c.r.ResourceLimitManagerImpl] (qtp504527234-14:ctx-0599648e = ctx-db3e314d) (logid:4f662644) Updating resource Type =3D memory count = for Account =3D 2 Operation =3D increasing Amount =3D 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=3D208
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=3D208
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","ho= stid":"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-4a55= d81b031b","cmdEventType":"VM.CREATE","diskofferingid":"0a97d09f-a648-44a2-= 89e7-336fdb444a09","serviceofferingid":"91e18f3a-1fe7-4184-a58d-e5d503a15a= f2","response":"json","ctxUserId":"2","hypervisor":"KVM","displayname":"Vm= teste","name":"Vmteste","zoneid":"f525ca16-891e-4749-b147-d426ecfab483","c= txStartEventId":"734","id":"124","ctxDetails":"{\"interface = com.cloud.dc.Pod\":\"673181c2-43fb-45e2-91b0-7496f2975a7b\",\"interface = com.cloud.org.Cluster\":\"81cb2d64-d39c-40c5-a3ad-8b8e9fce4f83\",\"interfa= ce = com.cloud.offering.ServiceOffering\":\"91e18f3a-1fe7-4184-a58d-e5d503a15af= 2\",\"interface = com.cloud.host.Host\":\"6d169723-2440-46a5-a815-67580656dd6d\",\"interface= = com.cloud.template.VirtualMachineTemplate\":\"eb47e5c4-c18e-4706-8f54-518d= d5eee6e0\",\"interface = com.cloud.dc.DataCenter\":\"f525ca16-891e-4749-b147-d426ecfab483\",\"inter= face = 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) =3D=3D=3DEND=3D= =3D=3D 172.26.0.190 -- GET = command=3DdeployVirtualMachine&response=3Djson&zoneid=3Df525= ca16-891e-4749-b147-d426ecfab483&podid=3D673181c2-43fb-45e2-91b0-7496f= 2975a7b&clusterid=3D81cb2d64-d39c-40c5-a3ad-8b8e9fce4f83&hostid=3D= 6d169723-2440-46a5-a815-67580656dd6d&templateid=3Deb47e5c4-c18e-4706-8= f54-518dd5eee6e0&hypervisor=3DKVM&serviceofferingid=3D91e18f3a-1fe= 7-4184-a58d-e5d503a15af2&diskofferingid=3D0a97d09f-a648-44a2-89e7-336f= db444a09&iptonetworklist%5B0%5D.networkid=3D19cbc69f-91b5-48bb-8de3-e1= c582e07a4a&displayname=3DVmteste&name=3DVmteste&_=3D1585672416= 295
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","ho= stid":"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-4a55= d81b031b","cmdEventType":"VM.CREATE","diskofferingid":"0a97d09f-a648-44a2-= 89e7-336fdb444a09","serviceofferingid":"91e18f3a-1fe7-4184-a58d-e5d503a15a= f2","response":"json","ctxUserId":"2","hypervisor":"KVM","displayname":"Vm= teste","name":"Vmteste","zoneid":"f525ca16-891e-4749-b147-d426ecfab483","c= txStartEventId":"734","id":"124","ctxDetails":"{\"interface = com.cloud.dc.Pod\":\"673181c2-43fb-45e2-91b0-7496f2975a7b\",\"interface = com.cloud.org.Cluster\":\"81cb2d64-d39c-40c5-a3ad-8b8e9fce4f83\",\"interfa= ce = com.cloud.offering.ServiceOffering\":\"91e18f3a-1fe7-4184-a58d-e5d503a15af= 2\",\"interface = com.cloud.host.Host\":\"6d169723-2440-46a5-a815-67580656dd6d\",\"interface= = com.cloud.template.VirtualMachineTemplate\":\"eb47e5c4-c18e-4706-8f54-518d= d5eee6e0\",\"interface = com.cloud.dc.DataCenter\":\"f525ca16-891e-4749-b147-d426ecfab483\",\"inter= face = 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=3D208
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=3D208
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-->Poo= l(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: = rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm= 9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtM= AAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTm= FtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFu= bmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS= 91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-Z= tlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AA= N4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAfHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA= AAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubG= FuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0= aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAA= x3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4= cA, 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,"rawP= arams":{"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 =3D = 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-->Poo= l(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=3DVM[User|i-2-124-VM], = P0=3DDest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type--&g= t;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 =3D 1 Name =3D Work-Job-Executor-1; called by = -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-Transacti= onLegacy.close:657-TransactionContextInterceptor.invoke:36-ReflectiveMetho= dInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMe= thodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy57.take:-1-= DataCenterDaoImpl.allocateVnet:212-NativeMethodAccessorImpl.invoke0:-2-Nat= iveMethodAccessorImpl.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=3D208 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=3Dinterface com.cloud.dc.DataCenter; id=3D1
= at = com.cloud.network.guru.GuestNetworkGuru.allocateVnet(GuestNetworkGuru.java= :291)
at = com.cloud.network.guru.GuestNetworkGuru.implement(GuestNetworkGuru.java:32= 0)
= at = com.cloud.network.guru.ExternalGuestNetworkGuru.implement(ExternalGuestNet= workGuru.java:132)
at = org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNe= twork(NetworkOrchestrator.java:1132)
at = org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNe= twork(NetworkOrchestrator.java:1071)
at = org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(Net= workOrchestrator.java:1642)
at = com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana= gerImpl.java:1099)
at = com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana= gerImpl.java:5107)
at = sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
= at = sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:= 62)
at = sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorIm= pl.java:43)
at = java.lang.reflect.Method.invoke(Method.java:498)
at = com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.j= ava:107)
at = com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManag= erImpl.java:5270)
at = com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
= at = org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInConte= xt(AsyncJobManagerImpl.java:583)
at = org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Managed= ContextRunnable.java:49)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(De= faultManagedContext.java:56)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithC= ontext(DefaultManagedContext.java:103)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCo= ntext(DefaultManagedContext.java:53)
at = org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCo= ntextRunnable.java:46)
at = org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJ= obManagerImpl.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","ex= ecuteInSequence":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(VirtualRout= erElement.java:962)
at = org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.cleanupNicD= hcpDnsEntry(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.j= ava:1507)
at = com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana= gerImpl.java:1260)
at = com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana= gerImpl.java:5107)
at = sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
= at = sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:= 62)
at = sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorIm= pl.java:43)
at = java.lang.reflect.Method.invoke(Method.java:498)
at = com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.j= ava:107)
at = com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManag= erImpl.java:5270)
at = com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
= at = org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInConte= xt(AsyncJobManagerImpl.java:583)
at = org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Managed= ContextRunnable.java:49)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(De= faultManagedContext.java:56)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithC= ontext(DefaultManagedContext.java:103)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCo= ntext(DefaultManagedContext.java:53)
at = org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCo= ntextRunnable.java:46)
at = org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJ= obManagerImpl.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=3Dinterface = com.cloud.dc.DataCenter; id=3D1
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=3Dinterface = com.cloud.dc.DataCenter; id=3D1
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: = rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm= 9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtM= AAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTm= FtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFu= bmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS= 91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-Z= tlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AA= N4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAfHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA= AAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubG= FuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0= aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAA= x3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4= cA, 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=3Dinterface = com.cloud.dc.DataCenter; id=3D1
at = com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana= gerImpl.java:1063)
at = com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana= gerImpl.java:5107)
at = sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
= at = sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:= 62)
at = sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorIm= pl.java:43)
at = java.lang.reflect.Method.invoke(Method.java:498)
at = com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.j= ava:107)
at = com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManag= erImpl.java:5270)
at = com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
= at = org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInConte= xt(AsyncJobManagerImpl.java:583)
at = org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Managed= ContextRunnable.java:49)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(De= faultManagedContext.java:56)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithC= ontext(DefaultManagedContext.java:103)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCo= ntext(DefaultManagedContext.java:53)
at = org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCo= ntextRunnable.java:46)
at = org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJ= obManagerImpl.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: = rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RX= hjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3Vk= LmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaW= R0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20u= Y2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZX= QAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4= cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibG= XVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVz= c2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdG= Fja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlz= dDt4cHEAfgANdAA1VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS= 0yLTEyNC1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4= cAAAABVzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTn= VtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1l= cQB-AAp4cAAABCd0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHl= ZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRzcQB-ABEA= ABPzcQB-ABNxAH4AFHEAfgAVc3EAfgAR_____nQAJHN1bi5yZWZsZWN0Lk5hdGl2ZU1ldGhvZE= FjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHNx= AH4AEQAAAD5xAH4AGHEAfgAZdAAGaW52b2tlc3EAfgARAAAAK3QAKHN1bi5yZWZsZWN0LkRlbG= VnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBs= LmphdmFxAH4AHHNxAH4AEQAAAfJ0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2= QuamF2YXEAfgAcc3EAfgARAAAAa3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJv= eHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnNxAH4AEQ= AAFJZxAH4AE3EAfgAUcQB-ACZzcQB-ABEAAABmdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRp= c3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-ABEAAAJHdA= A_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5h= Z2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfg= ARAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENv= bnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfg= ARAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZh= dWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbH= NxAH4AEQAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwu= RGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADZ0AA9jYWxsV2l0aENvbnRleHRzcQB-ABEAAAA1cQ= B-ADlxAH4ANnQADnJ1bldpdGhDb250ZXh0c3EAfgARAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRz= dGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAycQB-ADNzcQ= B-ABEAAAITcQB-AC1xAH4ALnEAfgAzc3EAfgARAAAB_3QALmphdmEudXRpbC5jb25jdXJyZW50= LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA3c3EAfgARAA= ABCnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFx= AH4AM3NxAH4AEQAABH10ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3= J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4AEQAAAnB0AC5qYXZh= LnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEhxAH4AM3NxAH= 4AEQAAAux0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AM3NyACZqYXZhLnV0= aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAMeH= IALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4C= AAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3= R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-AFR4c3IAEWphdmEubGFuZy5JbnRl= Z2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cA= AAEO9zcQB-AFMAAAAAdwQAAAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFs= dWV4cQB-AFYAAAAAAAAAAXZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlclPoJBrS07ZcAgAAeH= AA
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 =3D volume = count for Account =3D 2 Operation =3D decreasing Amount =3D 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 =3D = primary_storage count for Account =3D 2 Operation =3D decreasing Amount = =3D 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 =3D = user_vm count for Account =3D 2 Operation =3D decreasing Amount =3D 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 =3D cpu = count for Account =3D 2 Operation =3D decreasing Amount =3D 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 =3D memory = count for Account =3D 2 Operation =3D decreasing Amount =3D 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(DelegatingMethodAccessorIm= pl.java:43)
at = java.lang.reflect.Method.invoke(Method.java:498)
at = org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(Ao= pUtils.java:338)
at = org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoi= nt(ReflectiveMethodInvocation.java:197)
at = org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Refle= ctiveMethodInvocation.java:163)
at = org.apache.cloudstack.network.contrail.management.EventUtils$EventIntercep= tor.invoke(EventUtils.java:107)
at = org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Refle= ctiveMethodInvocation.java:174)
at = com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:= 51)
at = org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Refle= ctiveMethodInvocation.java:174)
at = org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(Exp= oseInvocationInterceptor.java:92)
at = org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Refle= ctiveMethodInvocation.java:185)
at = org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopP= roxy.java:212)
at = com.sun.proxy.$Proxy190.startVirtualMachine(Unknown Source)
= at = org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin.execute(Depl= oyVMCmdByAdmin.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.runInConte= xt(AsyncJobManagerImpl.java:583)
at = org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Managed= ContextRunnable.java:49)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(De= faultManagedContext.java:56)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithC= ontext(DefaultManagedContext.java:103)
at = org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCo= ntext(DefaultManagedContext.java:53)
at = org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCo= ntextRunnable.java:46)
at = org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJ= obManagerImpl.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) =3D=3D=3DSTART=3D=3D=3D = 172.26.0.190 -- GET = command=3DqueryAsyncJobResult&jobId=3Dd9d8d7a4-bd0b-4f4a-9df3-ff= feff7eeb49&response=3Djson&_=3D1585672416296
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) =3D=3D=3DEND=3D=3D=3D 172.26.0.190 = -- GET = command=3DqueryAsyncJobResult&jobId=3Dd9d8d7a4-bd0b-4f4a-9df3-ff= feff7eeb49&response=3Djson&_=3D1585672416296
2020-03-31 13:52:03,254 DEBUG [c.c.a.ApiServlet] = (qtp504527234-251:ctx-9b48d289) (logid:a4f81600) =3D=3D=3DSTART=3D=3D=3D = 172.26.0.190 -- GET = command=3DlistVirtualMachines&id=3D153092ed-cd93-454e-8621-4a55d= 81b031b&response=3Djson&_=3D1585672416297
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) =3D=3D=3DEND=3D=3D=3D 172.26.0.190 -- GET = command=3DlistVirtualMachines&id=3D153092ed-cd93-454e-8621-4a55d= 81b031b&response=3Djson&_=3D1585672416297