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
