You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cloudstack.apache.org by GitBox <gi...@apache.org> on 2019/07/30 11:48:03 UTC
[GitHub] [cloudstack] digitalgust opened a new issue #3531: Create VM error
in iso network/KVM
digitalgust opened a new issue #3531: Create VM error in iso network/KVM
URL: https://github.com/apache/cloudstack/issues/3531
<!--
Verify first that your issue/request is not already reported on GitHub.
Also test if the latest release and master branch are affected too.
Always add information AFTER of these HTML comments, but no need to delete the comments.
-->
##### ISSUE TYPE
<!-- Pick one below and delete the rest -->
* Bug Report
##### COMPONENT NAME
<!--
Categorize the issue, e.g. API, VR, VPN, UI, etc.
-->
~~~
Mgmt
~~~
##### CLOUDSTACK VERSION
<!--
New line separated list of affected versions, commit ID for issues on master branch.
-->
~~~
cloudstack 4.11.3.0
template 4.11.3
~~~
##### CONFIGURATION
<!--
Information about the configuration if relevant, e.g. basic network, advanced networking, etc. N/A otherwise
-->
advanced network
##### OS / ENVIRONMENT
<!--
Information about the environment if relevant, N/A otherwise
-->
centos 7.6
##### SUMMARY
<!-- Explain the problem/feature briefly -->
install cloudstack ,
add advance network zone,
system vm startup ok ,
then "add isolated network" ok , state show allocated,
then "add instance" , using "CentOS 5.5(64-bit) no GUI (KVM)" template that download completed.
then error occured.
the main error:
```
Unable to allocate vnet as a part of network Ntwk[204|Guest|8] implement Scope=interface com.cloud.dc.DataCenter; id=1
```
full log:
```
2019-07-30 19:32:50,134 DEBUG [c.c.a.ApiServlet] (qtp504527234-20:ctx-0e8ecf9d) (logid:9b131587) ===START=== 10.0.1.11 -- GET command=deployVirtualMachine&response=json&zoneid=404db444-d810-4806-b3f9-a624e7cd9591&templateid=0c41f176-b2b4-11e9-92de-000c29a29fa5&hypervisor=KVM&rootdisksize=20&serviceofferingid=b9a4919e-4c64-44c8-980c-1b40ddccf418&iptonetworklist%5B0%5D.networkid=ea5afaea-559a-42ed-8402-64d80d1b5536&displayname=test&name=test&keyboard=us&_=1564482383498
2019-07-30 19:32:50,138 DEBUG [c.c.a.ApiServer] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) CIDRs from which account 'Acct[29b131fa-b2b4-11e9-92de-000c29a29fa5-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-07-30 19:32:50,149 DEBUG [c.c.u.AccountManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Access granted to Acct[29b131fa-b2b4-11e9-92de-000c29a29fa5-admin] to org.apache.cloudstack.quota.vo.ServiceOfferingVO$$EnhancerByCGLIB$$ac9cd3cc@5eabe31 by AffinityGroupAccessChecker
2019-07-30 19:32:50,149 DEBUG [c.c.u.AccountManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Access granted to Acct[29b131fa-b2b4-11e9-92de-000c29a29fa5-admin] to null by AffinityGroupAccessChecker
2019-07-30 19:32:50,157 DEBUG [c.c.n.NetworkModelImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Service SecurityGroup is not supported in the network id=204
2019-07-30 19:32:50,164 DEBUG [c.c.v.UserVmManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Rootdisksize override validation successful. Template root disk size 8GB Root disk size specified 20GB
2019-07-30 19:32:50,170 DEBUG [c.c.v.UserVmManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Allocating in the DB for vm
2019-07-30 19:32:50,180 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Allocating entries for VM: VM[User|i-2-4-VM]
2019-07-30 19:32:50,181 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Allocating nics for VM[User|i-2-4-VM]
2019-07-30 19:32:50,181 DEBUG [o.a.c.e.o.NetworkOrchestrator] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Allocating nic for vm VM[User|i-2-4-VM] in network Ntwk[204|Guest|8] with requested profile NicProfile[0-0-null-null-null
2019-07-30 19:32:50,194 DEBUG [c.c.n.NetworkModelImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Service SecurityGroup is not supported in the network id=204
2019-07-30 19:32:50,196 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Allocating disks for VM[User|i-2-4-VM]
2019-07-30 19:32:50,198 DEBUG [o.a.c.e.o.VolumeOrchestrator] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Using root disk size of 21474836480 Bytes for volume ROOT-4
2019-07-30 19:32:50,204 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Updating resource Type = volume count for Account = 2 Operation = increasing Amount = 1
2019-07-30 19:32:50,209 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Updating resource Type = primary_storage count for Account = 2 Operation = increasing Amount = 21474836480
2019-07-30 19:32:50,213 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Allocation completed for VM: VM[User|i-2-4-VM]
2019-07-30 19:32:50,213 DEBUG [c.c.v.UserVmManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Successfully allocated DB entry for VM[User|i-2-4-VM]
2019-07-30 19:32:50,215 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Updating resource Type = user_vm count for Account = 2 Operation = increasing Amount = 1
2019-07-30 19:32:50,218 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Updating resource Type = cpu count for Account = 2 Operation = increasing Amount = 1
2019-07-30 19:32:50,222 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Updating resource Type = memory count for Account = 2 Operation = increasing Amount = 512
2019-07-30 19:32:50,238 DEBUG [c.c.n.NetworkModelImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Service SecurityGroup is not supported in the network id=204
2019-07-30 19:32:50,242 DEBUG [c.c.n.NetworkModelImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) Service SecurityGroup is not supported in the network id=204
2019-07-30 19:32:50,251 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-28:ctx-36426215 job-37) (logid:fd521270) Add job-37 into job monitoring
2019-07-30 19:32:50,256 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37) (logid:7ff32765) Executing AsyncJobVO {id:37, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 4, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"keyboard":"us","iptonetworklist[0].networkid":"ea5afaea-559a-42ed-8402-64d80d1b5536","httpmethod":"GET","templateid":"0c41f176-b2b4-11e9-92de-000c29a29fa5","ctxAccountId":"2","uuid":"8a04d3d4-c516-4a70-b44b-54798dc69d2a","cmdEventType":"VM.CREATE","serviceofferingid":"b9a4919e-4c64-44c8-980c-1b40ddccf418","response":"json","ctxUserId":"2","hypervisor":"KVM","displayname":"test","name":"test","zoneid":"404db444-d810-4806-b3f9-a624e7cd9591","rootdisksize":"20","ctxStartEventId":"87","id":"4","ctxDetails":"{\"interface com.cloud.dc.DataCenter\":\"404db444-d810-4806-b3f9-a624e7cd9591\",\"interface com.cloud.template.VirtualMachineTemplate\":\"0c41f176-b2b4-11e9-92de-000c29a29fa5\",\"interface com.cloud.offering.ServiceOffering\":\"b9a4919e-4c64-44c8-980c-1b40ddccf418\",\"interface com.cloud.vm.VirtualMachine\":\"8a04d3d4-c516-4a70-b44b-54798dc69d2a\"}","_":"1564482383498"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 52238131109, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-07-30 19:32:50,258 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) submit async job-37, details: AsyncJobVO {id:37, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 4, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"keyboard":"us","iptonetworklist[0].networkid":"ea5afaea-559a-42ed-8402-64d80d1b5536","httpmethod":"GET","templateid":"0c41f176-b2b4-11e9-92de-000c29a29fa5","ctxAccountId":"2","uuid":"8a04d3d4-c516-4a70-b44b-54798dc69d2a","cmdEventType":"VM.CREATE","serviceofferingid":"b9a4919e-4c64-44c8-980c-1b40ddccf418","response":"json","ctxUserId":"2","hypervisor":"KVM","displayname":"test","name":"test","zoneid":"404db444-d810-4806-b3f9-a624e7cd9591","rootdisksize":"20","ctxStartEventId":"87","id":"4","ctxDetails":"{\"interface com.cloud.dc.DataCenter\":\"404db444-d810-4806-b3f9-a624e7cd9591\",\"interface com.cloud.template.VirtualMachineTemplate\":\"0c41f176-b2b4-11e9-92de-000c29a29fa5\",\"interface com.cloud.offering.ServiceOffering\":\"b9a4919e-4c64-44c8-980c-1b40ddccf418\",\"interface com.cloud.vm.VirtualMachine\":\"8a04d3d4-c516-4a70-b44b-54798dc69d2a\"}","_":"1564482383498"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 52238131109, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-07-30 19:32:50,259 DEBUG [c.c.a.ApiServlet] (qtp504527234-20:ctx-0e8ecf9d ctx-4d5c6019) (logid:9b131587) ===END=== 10.0.1.11 -- GET command=deployVirtualMachine&response=json&zoneid=404db444-d810-4806-b3f9-a624e7cd9591&templateid=0c41f176-b2b4-11e9-92de-000c29a29fa5&hypervisor=KVM&rootdisksize=20&serviceofferingid=b9a4919e-4c64-44c8-980c-1b40ddccf418&iptonetworklist%5B0%5D.networkid=ea5afaea-559a-42ed-8402-64d80d1b5536&displayname=test&name=test&keyboard=us&_=1564482383498
2019-07-30 19:32:50,283 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Service SecurityGroup is not supported in the network id=204
2019-07-30 19:32:50,287 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Service SecurityGroup is not supported in the network id=204
2019-07-30 19:32:50,297 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) DeploymentPlanner allocation algorithm: null
2019-07-30 19:32:50,297 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
2019-07-30 19:32:50,297 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Is ROOT volume READY (pool already allocated)?: No
2019-07-30 19:32:50,303 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Deploy avoids pods: [], clusters: [], hosts: []
2019-07-30 19:32:50,304 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Searching all possible resources under this Zone: 1
2019-07-30 19:32:50,305 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2019-07-30 19:32:50,308 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Removing from the clusterId list these clusters from avoid set: []
2019-07-30 19:32:50,316 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Checking resources in Cluster: 1 under Pod: 1
2019-07-30 19:32:50,316 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Looking for hosts in dc: 1 pod:1 cluster:1
2019-07-30 19:32:50,319 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2019-07-30 19:32:50,322 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2019-07-30 19:32:50,323 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Looking for speed=500Mhz, Ram=512
2019-07-30 19:32:50,329 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Host: 1 has cpu capability (cpu:8, speed:4500) to support requested CPU: 1 and requested speed: 500
2019-07-30 19:32:50,329 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2019-07-30 19:32:50,331 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Hosts's actual total CPU: 36000 and CPU after applying overprovisioning: 36000
2019-07-30 19:32:50,331 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Free CPU: 35000 , Requested CPU: 500
2019-07-30 19:32:50,331 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Free RAM: 5768159232 , Requested RAM: 536870912
2019-07-30 19:32:50,331 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Host has enough CPU and RAM available
2019-07-30 19:32:50,331 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) STATS: Can alloc CPU from host: 1, used: 1000, reserved: 0, actual total: 36000, total with overprovisioning: 36000; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2019-07-30 19:32:50,331 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) STATS: Can alloc MEM from host: 1, used: 1610612736, reserved: 0, total: 7378771968; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2019-07-30 19:32:50,331 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Found a suitable host, adding to list: 1
2019-07-30 19:32:50,331 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674 FirstFitRoutingAllocator) (logid:7ff32765) Host Allocator returning 1 suitable hosts
2019-07-30 19:32:50,333 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Checking suitable pools for volume (Id, Type): (4,ROOT)
2019-07-30 19:32:50,333 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) We need to allocate new storagepool for this volume
2019-07-30 19:32:50,334 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Calling StoragePoolAllocators to find suitable pools
2019-07-30 19:32:50,335 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2019-07-30 19:32:50,335 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) ClusterScopeStoragePoolAllocator looking for storage pool
2019-07-30 19:32:50,335 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored.
2019-07-30 19:32:50,336 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Found pools matching tags: []
2019-07-30 19:32:50,337 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) No storage pools available for shared volume allocation, returning
2019-07-30 19:32:50,337 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) ZoneWideStoragePoolAllocator to find storage pool
2019-07-30 19:32:50,342 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Checking if storage pool is suitable, name: null ,poolId: 1
2019-07-30 19:32:50,343 INFO [c.c.s.StorageManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2019-07-30 19:32:50,344 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Checking pool 1 for storage, totalSize: 2046551916544, usedBytes: 3057909760, usedPct: 0.0014941764903593914, disable threshold: 0.85
2019-07-30 19:32:50,344 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Destination pool id: 1
2019-07-30 19:32:50,355 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Pool ID for the volume with ID 4 is null
2019-07-30 19:32:50,358 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Found storage pool Z1_PRI1_CEPH of type RBD with overprovisioning factor 2
2019-07-30 19:32:50,359 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Total over provisioned capacity calculated is 2 * 2046551916544
2019-07-30 19:32:50,359 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Total capacity of the pool Z1_PRI1_CEPH with ID 1 is 4093103833088
2019-07-30 19:32:50,360 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Checking pool: 1 for storage allocation , maxSize : 4093103833088, totalAllocatedSize : 10687086592, askingSize : 21474836480, allocated disable threshold: 0.85
2019-07-30 19:32:50,360 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2019-07-30 19:32:50,360 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2019-07-30 19:32:50,360 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Host: 1 can access pool: 1
2019-07-30 19:32:50,361 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Found a potential host id: 1 name: host01 and associated storage pools for this VM
2019-07-30 19:32:50,362 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) 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(4|ROOT-->Pool(1))]
2019-07-30 19:32:50,373 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Sync job-38 execution on object VmWorkJobQueue.4
2019-07-30 19:32:51,476 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-7aac0062) (logid:6269f300) AutoScaling Monitor is running...
2019-07-30 19:32:52,236 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-4fe8c12b) (logid:8ed96be9) Execute sync-queue item: SyncQueueItemVO {id:8, queueId: 8, contentType: AsyncJob, contentId: 38, lastProcessMsid: 52238131109, lastprocessNumber: 1, lastProcessTime: Tue Jul 30 19:32:52 CST 2019, created: Tue Jul 30 19:32:50 CST 2019}
2019-07-30 19:32:52,237 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-4fe8c12b) (logid:8ed96be9) Schedule queued job-38
2019-07-30 19:32:52,242 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:b1d212c0) Add job-38 into job monitoring
2019-07-30 19:32:52,249 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Executing AsyncJobVO {id:38, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 52238131109, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue Jul 30 19:32:50 CST 2019}
2019-07-30 19:32:52,250 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Run VM work job: com.cloud.vm.VmWorkStart for VM 4, job origin: 37
2019-07-30 19:32:52,252 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":1,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":4,"handlerName":"VirtualMachineManagerImpl"}
2019-07-30 19:32:52,259 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) 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
2019-07-30 19:32:52,259 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Successfully transitioned to start state for VM[User|i-2-4-VM] reservation id = 20952774-5301-41e8-8fab-c158dc30dd24
2019-07-30 19:32:52,260 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null
2019-07-30 19:32:52,260 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Deploy avoids pods: null, clusters: null, hosts: null
2019-07-30 19:32:52,267 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) DeploymentPlanner allocation algorithm: null
2019-07-30 19:32:52,267 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
2019-07-30 19:32:52,267 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Is ROOT volume READY (pool already allocated)?: No
2019-07-30 19:32:52,267 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2019-07-30 19:32:52,268 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2019-07-30 19:32:52,271 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Checking suitable pools for volume (Id, Type): (4,ROOT)
2019-07-30 19:32:52,271 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) We need to allocate new storagepool for this volume
2019-07-30 19:32:52,272 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Calling StoragePoolAllocators to find suitable pools
2019-07-30 19:32:52,272 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2019-07-30 19:32:52,272 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) ClusterScopeStoragePoolAllocator looking for storage pool
2019-07-30 19:32:52,272 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored.
2019-07-30 19:32:52,273 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Found pools matching tags: []
2019-07-30 19:32:52,274 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) No storage pools available for shared volume allocation, returning
2019-07-30 19:32:52,274 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) ZoneWideStoragePoolAllocator to find storage pool
2019-07-30 19:32:52,280 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Checking if storage pool is suitable, name: null ,poolId: 1
2019-07-30 19:32:52,281 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2019-07-30 19:32:52,282 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Checking pool 1 for storage, totalSize: 2046551916544, usedBytes: 3057909760, usedPct: 0.0014941764903593914, disable threshold: 0.85
2019-07-30 19:32:52,282 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Destination pool id: 1
2019-07-30 19:32:52,295 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Pool ID for the volume with ID 4 is null
2019-07-30 19:32:52,299 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Found storage pool Z1_PRI1_CEPH of type RBD with overprovisioning factor 2
2019-07-30 19:32:52,299 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Total over provisioned capacity calculated is 2 * 2046551916544
2019-07-30 19:32:52,299 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Total capacity of the pool Z1_PRI1_CEPH with ID 1 is 4093103833088
2019-07-30 19:32:52,300 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Checking pool: 1 for storage allocation , maxSize : 4093103833088, totalAllocatedSize : 10687086592, askingSize : 21474836480, allocated disable threshold: 0.85
2019-07-30 19:32:52,300 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2019-07-30 19:32:52,301 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2019-07-30 19:32:52,301 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Host: 1 can access pool: 1
2019-07-30 19:32:52,302 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Found a potential host id: 1 name: host01 and associated storage pools for this VM
2019-07-30 19:32:52,303 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) 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(4|ROOT-->Pool(1))]
2019-07-30 19:32:52,303 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Deployment found - P0=VM[User|i-2-4-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(4|ROOT-->Pool(1))]
2019-07-30 19:32:52,309 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) 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
2019-07-30 19:32:52,313 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Hosts's actual total CPU: 36000 and CPU after applying overprovisioning: 36000
2019-07-30 19:32:52,313 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) We are allocating VM, increasing the used capacity of this host:1
2019-07-30 19:32:52,314 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Current Used CPU: 1000 , Free CPU:35000 ,Requested CPU: 500
2019-07-30 19:32:52,314 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Current Used RAM: 1610612736 , Free RAM:5768159232 ,Requested RAM: 536870912
2019-07-30 19:32:52,314 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) CPU STATS after allocation: for host: 1, old used: 1000, old reserved: 0, actual total: 36000, total with overprovisioning: 36000; new used:1500, reserved:0; requested cpu:500,alloc_from_last:false
2019-07-30 19:32:52,314 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) RAM STATS after allocation: for host: 1, old used: 1610612736, old reserved: 0, total: 7378771968; new used: 2147483648, reserved: 0; requested mem: 536870912,alloc_from_last:false
2019-07-30 19:32:52,319 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Lock is acquired for network id 204 as a part of network implement
2019-07-30 19:32:52,319 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Asking ExternalGuestNetworkGuru to implement Ntwk[204|Guest|8]
2019-07-30 19:32:52,327 DEBUG [c.c.u.d.T.Transaction] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Rolling back the transaction: Time = 1 Name = Work-Job-Executor-8; 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-$Proxy85.take:-1-DataCenterDaoImpl.allocateVnet:212-NativeMethodAccessorImpl.invoke0:-2-NativeMethodAccessorImpl.invoke:62
2019-07-30 19:32:52,327 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Cleaning up because we're unable to implement the network Ntwk[204|Guest|8]
2019-07-30 19:32:52,335 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Lock is acquired for network Ntwk[204|Guest|8] as a part of network shutdown
2019-07-30 19:32:52,337 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Sending network shutdown to VirtualRouter
2019-07-30 19:32:52,338 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Network id=204 is shutdown successfully, cleaning up corresponding resources now.
2019-07-30 19:32:52,344 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Lock is released for network Ntwk[204|Guest|8] as a part of network shutdown
2019-07-30 19:32:52,346 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Lock is released for network id 204 as a part of network implement
2019-07-30 19:32:52,346 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Insufficient capacity
com.cloud.exception.InsufficientVirtualNetworkCapacityException: Unable to allocate vnet as a part of network Ntwk[204|Guest|8] 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:1048)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:987)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1558)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1111)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
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:5100)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-07-30 19:32:52,348 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Cleaning up resources for the vm VM[User|i-2-4-VM] in Starting state
2019-07-30 19:32:52,353 DEBUG [c.c.a.t.Request] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Seq 1-7057422091066277974: Sending { Cmd , MgmtId: 52238131109, via: 1(host01), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"volumesToDisconnect":[],"vmName":"i-2-4-VM","executeInSequence":false,"wait":0}}] }
2019-07-30 19:32:52,506 DEBUG [c.c.a.t.Request] (AgentManager-Handler-9:null) (logid:) Seq 1-7057422091066277974: Processing: { Ans: , MgmtId: 52238131109, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2019-07-30 19:32:52,506 DEBUG [c.c.a.t.Request] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Seq 1-7057422091066277974: Received: { Ans: , MgmtId: 52238131109, via: 1(host01), Ver: v1, Flags: 10, { StopAnswer } }
2019-07-30 19:32:52,516 ERROR [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) 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:961)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.cleanupNicDhcpDnsEntry(NetworkOrchestrator.java:2933)
at com.cloud.vm.UserVmManagerImpl.finalizeStop(UserVmManagerImpl.java:4389)
at com.cloud.vm.VirtualMachineManagerImpl.sendStop(VirtualMachineManagerImpl.java:1485)
at com.cloud.vm.VirtualMachineManagerImpl.cleanup(VirtualMachineManagerImpl.java:1519)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1272)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
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:5100)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-07-30 19:32:52,528 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Successfully released network resources for the vm VM[User|i-2-4-VM]
2019-07-30 19:32:52,528 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Successfully cleanued up resources for the vm VM[User|i-2-4-VM] in Starting state
2019-07-30 19:32:52,535 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) DeploymentPlanner allocation algorithm: null
2019-07-30 19:32:52,535 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
2019-07-30 19:32:52,535 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Is ROOT volume READY (pool already allocated)?: No
2019-07-30 19:32:52,535 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2019-07-30 19:32:52,535 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) The specified host is in avoid set
2019-07-30 19:32:52,536 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Cannot deploy to specified host, returning.
2019-07-30 19:32:52,541 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) 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
2019-07-30 19:32:52,545 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Hosts's actual total CPU: 36000 and CPU after applying overprovisioning: 36000
2019-07-30 19:32:52,545 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Hosts's actual total RAM: 7378771968 and RAM after applying overprovisioning: 7378771968
2019-07-30 19:32:52,545 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) release cpu from host: 1, old used: 1500,reserved: 0, actual total: 36000, total with overprovisioning: 36000; new used: 1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2019-07-30 19:32:52,545 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) release mem from host: 1, old used: 2147483648,reserved: 0, total: 7378771968; new used: 1610612736,reserved:0; movedfromreserved: false,moveToReserveredfalse
2019-07-30 19:32:52,555 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-4-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2019-07-30 19:32:52,555 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38 ctx-535e9141) (logid:7ff32765) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-4-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2019-07-30 19:32:52,555 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 4, job origin: 37
2019-07-30 19:32:52,555 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Unable to complete AsyncJobVO {id:38, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 52238131109, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue Jul 30 19:32:50 CST 2019}, job origin:37
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-4-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1075)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
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:5100)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-07-30 19:32:52,557 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Complete async job-38, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAAzVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0yLTQtVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAVc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AApMAAhmaWxlTmFtZXEAfgAKTAAKbWV0aG9kTmFtZXEAfgAKeHAAAAQzdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0c3EAfgARAAATSXEAfgATcQB-ABRxAH4AFXNxAH4AEf____50ACRzdW4ucmVmbGVjdC5OYXRpdmVNZXRob2RBY2Nlc3NvckltcGx0AB1OYXRpdmVNZXRob2RBY2Nlc3NvckltcGwuamF2YXQAB2ludm9rZTBzcQB-ABEAAAA-cQB-ABhxAH4AGXQABmludm9rZXNxAH4AEQAAACt0AChzdW4ucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABxzcQB-ABEAAAHydAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AHHNxAH4AEQAAAGt0ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JzcQB-ABEAABPscQB-ABNxAH4AFHEAfgAmc3EAfgARAAAAZnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9ic3EAfgARAAACRXQAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHNxAH4AEQAAADF0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnNxAH4AEQAAADh0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxzcQB-ABEAAABndABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgA2dAAPY2FsbFdpdGhDb250ZXh0c3EAfgARAAAANXEAfgA5cQB-ADZ0AA5ydW5XaXRoQ29udGV4dHNxAH4AEQAAAC50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4AMnEAfgAzc3EAfgARAAACEXEAfgAtcQB-AC5xAH4AM3NxAH4AEQAAAf90AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4AN3NxAH4AEQAAAQp0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-ADNzcQB-ABEAAAR9dAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJzcQB-ABEAAAJwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBIcQB-ADNzcQB-ABEAAALsdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-ADNzcgAmamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUxpc3T8DyUxteyOEAIAAUwABGxpc3RxAH4ADHhyACxqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlQ29sbGVjdGlvbhlCAIDLXvceAgABTAABY3QAFkxqYXZhL3V0aWwvQ29sbGVjdGlvbjt4cHNyABNqYXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHEAfgBUeHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABDvc3EAfgBTAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHEAfgBWAAAAAAAAAAF2cgAXY29tLmNsb3VkLmRjLkRhdGFDZW50ZXJjQfdzv5V8swIAAHhwAA
2019-07-30 19:32:52,558 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Publish async job-38 complete on message bus
2019-07-30 19:32:52,559 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Wake up jobs related to job-38
2019-07-30 19:32:52,559 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Update db status for job-38
2019-07-30 19:32:52,561 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Wake up jobs joined with job-38 and disjoin all subjobs created from job- 38
2019-07-30 19:32:52,569 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Done executing com.cloud.vm.VmWorkStart for job-38
2019-07-30 19:32:52,573 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-8:ctx-a9004c7a job-37/job-38) (logid:7ff32765) Remove job-38 from job monitoring
2019-07-30 19:32:52,583 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Sync job-39 execution on object VmWorkJobQueue.4
2019-07-30 19:32:53,049 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-c36865a0) (logid:8716283b) HostStatsCollector is running...
2019-07-30 19:32:53,062 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-c36865a0) (logid:8716283b) Seq 1-7057422091066277975: Received: { Ans: , MgmtId: 52238131109, via: 1(host01), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2019-07-30 19:32:53,345 DEBUG [c.c.a.ApiServlet] (qtp504527234-15:ctx-aef6ed02) (logid:15e6999b) ===START=== 10.0.1.11 -- GET command=queryAsyncJobResult&jobId=7ff32765-b64c-4c0b-9156-64a43d75e636&response=json&_=1564482383499
2019-07-30 19:32:53,349 DEBUG [c.c.a.ApiServer] (qtp504527234-15:ctx-aef6ed02 ctx-e593ff45) (logid:15e6999b) CIDRs from which account 'Acct[29b131fa-b2b4-11e9-92de-000c29a29fa5-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-07-30 19:32:53,360 DEBUG [c.c.a.ApiServlet] (qtp504527234-15:ctx-aef6ed02 ctx-e593ff45) (logid:15e6999b) ===END=== 10.0.1.11 -- GET command=queryAsyncJobResult&jobId=7ff32765-b64c-4c0b-9156-64a43d75e636&response=json&_=1564482383499
2019-07-30 19:32:54,235 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-3c26781f) (logid:9e2ee62a) Execute sync-queue item: SyncQueueItemVO {id:9, queueId: 8, contentType: AsyncJob, contentId: 39, lastProcessMsid: 52238131109, lastprocessNumber: 2, lastProcessTime: Tue Jul 30 19:32:54 CST 2019, created: Tue Jul 30 19:32:52 CST 2019}
2019-07-30 19:32:54,236 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-3c26781f) (logid:9e2ee62a) Schedule queued job-39
2019-07-30 19:32:54,240 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:8584d216) Add job-39 into job monitoring
2019-07-30 19:32:54,246 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Executing AsyncJobVO {id:39, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 52238131109, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue Jul 30 19:32:52 CST 2019}
2019-07-30 19:32:54,247 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Run VM work job: com.cloud.vm.VmWorkStart for VM 4, job origin: 37
2019-07-30 19:32:54,248 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":4,"handlerName":"VirtualMachineManagerImpl"}
2019-07-30 19:32:54,258 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) 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
2019-07-30 19:32:54,259 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Successfully transitioned to start state for VM[User|i-2-4-VM] reservation id = 0d95e588-f769-4007-a32c-0e82d921e178
2019-07-30 19:32:54,260 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Deploy avoids pods: null, clusters: null, hosts: null
2019-07-30 19:32:54,268 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) DeploymentPlanner allocation algorithm: null
2019-07-30 19:32:54,268 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 536870912
2019-07-30 19:32:54,268 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Is ROOT volume READY (pool already allocated)?: No
2019-07-30 19:32:54,273 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Deploy avoids pods: [], clusters: [], hosts: []
2019-07-30 19:32:54,274 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Searching resources only under specified Pod: 1
2019-07-30 19:32:54,274 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
2019-07-30 19:32:54,276 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Removing from the clusterId list these clusters from avoid set: []
2019-07-30 19:32:54,282 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Checking resources in Cluster: 1 under Pod: 1
2019-07-30 19:32:54,282 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Looking for hosts in dc: 1 pod:1 cluster:1
2019-07-30 19:32:54,284 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2019-07-30 19:32:54,288 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2019-07-30 19:32:54,288 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Looking for speed=500Mhz, Ram=512
2019-07-30 19:32:54,293 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Host: 1 has cpu capability (cpu:8, speed:4500) to support requested CPU: 1 and requested speed: 500
2019-07-30 19:32:54,293 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2019-07-30 19:32:54,295 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Hosts's actual total CPU: 36000 and CPU after applying overprovisioning: 36000
2019-07-30 19:32:54,295 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Free CPU: 35000 , Requested CPU: 500
2019-07-30 19:32:54,295 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Free RAM: 5768159232 , Requested RAM: 536870912
2019-07-30 19:32:54,295 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Host has enough CPU and RAM available
2019-07-30 19:32:54,295 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) STATS: Can alloc CPU from host: 1, used: 1000, reserved: 0, actual total: 36000, total with overprovisioning: 36000; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2019-07-30 19:32:54,295 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) STATS: Can alloc MEM from host: 1, used: 1610612736, reserved: 0, total: 7378771968; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2019-07-30 19:32:54,295 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Found a suitable host, adding to list: 1
2019-07-30 19:32:54,295 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96 FirstFitRoutingAllocator) (logid:7ff32765) Host Allocator returning 1 suitable hosts
2019-07-30 19:32:54,297 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Checking suitable pools for volume (Id, Type): (4,ROOT)
2019-07-30 19:32:54,297 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) We need to allocate new storagepool for this volume
2019-07-30 19:32:54,298 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Calling StoragePoolAllocators to find suitable pools
2019-07-30 19:32:54,298 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2019-07-30 19:32:54,298 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) ClusterScopeStoragePoolAllocator looking for storage pool
2019-07-30 19:32:54,298 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored.
2019-07-30 19:32:54,299 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Found pools matching tags: []
2019-07-30 19:32:54,300 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) No storage pools available for shared volume allocation, returning
2019-07-30 19:32:54,300 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) ZoneWideStoragePoolAllocator to find storage pool
2019-07-30 19:32:54,306 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Checking if storage pool is suitable, name: null ,poolId: 1
2019-07-30 19:32:54,307 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2019-07-30 19:32:54,309 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Checking pool 1 for storage, totalSize: 2046551916544, usedBytes: 3057909760, usedPct: 0.0014941764903593914, disable threshold: 0.85
2019-07-30 19:32:54,309 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Destination pool id: 1
2019-07-30 19:32:54,318 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Pool ID for the volume with ID 4 is null
2019-07-30 19:32:54,323 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Found storage pool Z1_PRI1_CEPH of type RBD with overprovisioning factor 2
2019-07-30 19:32:54,323 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Total over provisioned capacity calculated is 2 * 2046551916544
2019-07-30 19:32:54,323 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Total capacity of the pool Z1_PRI1_CEPH with ID 1 is 4093103833088
2019-07-30 19:32:54,324 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Checking pool: 1 for storage allocation , maxSize : 4093103833088, totalAllocatedSize : 10687086592, askingSize : 21474836480, allocated disable threshold: 0.85
2019-07-30 19:32:54,324 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2019-07-30 19:32:54,324 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2019-07-30 19:32:54,324 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Host: 1 can access pool: 1
2019-07-30 19:32:54,325 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Found a potential host id: 1 name: host01 and associated storage pools for this VM
2019-07-30 19:32:54,326 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) 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(4|ROOT-->Pool(1))]
2019-07-30 19:32:54,326 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Deployment found - P0=VM[User|i-2-4-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(4|ROOT-->Pool(1))]
2019-07-30 19:32:54,332 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) 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
2019-07-30 19:32:54,337 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Hosts's actual total CPU: 36000 and CPU after applying overprovisioning: 36000
2019-07-30 19:32:54,337 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) We are allocating VM, increasing the used capacity of this host:1
2019-07-30 19:32:54,337 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Current Used CPU: 1000 , Free CPU:35000 ,Requested CPU: 500
2019-07-30 19:32:54,337 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Current Used RAM: 1610612736 , Free RAM:5768159232 ,Requested RAM: 536870912
2019-07-30 19:32:54,337 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) CPU STATS after allocation: for host: 1, old used: 1000, old reserved: 0, actual total: 36000, total with overprovisioning: 36000; new used:1500, reserved:0; requested cpu:500,alloc_from_last:false
2019-07-30 19:32:54,337 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) RAM STATS after allocation: for host: 1, old used: 1610612736, old reserved: 0, total: 7378771968; new used: 2147483648, reserved: 0; requested mem: 536870912,alloc_from_last:false
2019-07-30 19:32:54,343 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Lock is acquired for network id 204 as a part of network implement
2019-07-30 19:32:54,343 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Asking ExternalGuestNetworkGuru to implement Ntwk[204|Guest|8]
2019-07-30 19:32:54,350 DEBUG [c.c.u.d.T.Transaction] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Rolling back the transaction: Time = 0 Name = Work-Job-Executor-9; 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-$Proxy85.take:-1-DataCenterDaoImpl.allocateVnet:212-NativeMethodAccessorImpl.invoke0:-2-NativeMethodAccessorImpl.invoke:62
2019-07-30 19:32:54,351 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Cleaning up because we're unable to implement the network Ntwk[204|Guest|8]
2019-07-30 19:32:54,358 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Lock is acquired for network Ntwk[204|Guest|8] as a part of network shutdown
2019-07-30 19:32:54,360 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Sending network shutdown to VirtualRouter
2019-07-30 19:32:54,361 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Network id=204 is shutdown successfully, cleaning up corresponding resources now.
2019-07-30 19:32:54,367 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Lock is released for network Ntwk[204|Guest|8] as a part of network shutdown
2019-07-30 19:32:54,368 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Lock is released for network id 204 as a part of network implement
2019-07-30 19:32:54,368 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Insufficient capacity
com.cloud.exception.InsufficientVirtualNetworkCapacityException: Unable to allocate vnet as a part of network Ntwk[204|Guest|8] 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:1048)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:987)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1558)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1111)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
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:5100)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-07-30 19:32:54,372 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Cleaning up resources for the vm VM[User|i-2-4-VM] in Starting state
2019-07-30 19:32:54,379 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Seq 1-7057422091066277976: Sending { Cmd , MgmtId: 52238131109, via: 1(host01), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"volumesToDisconnect":[],"vmName":"i-2-4-VM","executeInSequence":false,"wait":0}}] }
2019-07-30 19:32:54,570 DEBUG [c.c.a.t.Request] (AgentManager-Handler-11:null) (logid:) Seq 1-7057422091066277976: Processing: { Ans: , MgmtId: 52238131109, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2019-07-30 19:32:54,570 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Seq 1-7057422091066277976: Received: { Ans: , MgmtId: 52238131109, via: 1(host01), Ver: v1, Flags: 10, { StopAnswer } }
2019-07-30 19:32:54,580 ERROR [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) 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:961)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.cleanupNicDhcpDnsEntry(NetworkOrchestrator.java:2933)
at com.cloud.vm.UserVmManagerImpl.finalizeStop(UserVmManagerImpl.java:4389)
at com.cloud.vm.VirtualMachineManagerImpl.sendStop(VirtualMachineManagerImpl.java:1485)
at com.cloud.vm.VirtualMachineManagerImpl.cleanup(VirtualMachineManagerImpl.java:1519)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1272)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
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:5100)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-07-30 19:32:54,586 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Successfully released network resources for the vm VM[User|i-2-4-VM]
2019-07-30 19:32:54,586 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Successfully cleanued up resources for the vm VM[User|i-2-4-VM] in Starting state
2019-07-30 19:32:54,593 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) DeploymentPlanner allocation algorithm: null
2019-07-30 19:32:54,593 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 536870912
2019-07-30 19:32:54,593 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Is ROOT volume READY (pool already allocated)?: No
2019-07-30 19:32:54,601 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Deploy avoids pods: [], clusters: [], hosts: [1]
2019-07-30 19:32:54,601 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) DataCenter id = '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM, returning.
2019-07-30 19:32:54,606 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) 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
2019-07-30 19:32:54,611 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Hosts's actual total CPU: 36000 and CPU after applying overprovisioning: 36000
2019-07-30 19:32:54,611 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Hosts's actual total RAM: 7378771968 and RAM after applying overprovisioning: 7378771968
2019-07-30 19:32:54,611 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) release cpu from host: 1, old used: 1500,reserved: 0, actual total: 36000, total with overprovisioning: 36000; new used: 1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2019-07-30 19:32:54,611 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) release mem from host: 1, old used: 2147483648,reserved: 0, total: 7378771968; new used: 1610612736,reserved:0; movedfromreserved: false,moveToReserveredfalse
2019-07-30 19:32:54,620 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-4-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2019-07-30 19:32:54,620 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39 ctx-4bd3af96) (logid:7ff32765) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-4-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2019-07-30 19:32:54,620 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 4, job origin: 37
2019-07-30 19:32:54,620 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Unable to complete AsyncJobVO {id:39, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 52238131109, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue Jul 30 19:32:52 CST 2019}, job origin:37
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-4-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1075)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
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:5100)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
2019-07-30 19:32:54,622 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Complete async job-39, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAAzVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0yLTQtVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAVc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AApMAAhmaWxlTmFtZXEAfgAKTAAKbWV0aG9kTmFtZXEAfgAKeHAAAAQzdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0c3EAfgARAAATSXEAfgATcQB-ABRxAH4AFXNxAH4AEf____50ACRzdW4ucmVmbGVjdC5OYXRpdmVNZXRob2RBY2Nlc3NvckltcGx0AB1OYXRpdmVNZXRob2RBY2Nlc3NvckltcGwuamF2YXQAB2ludm9rZTBzcQB-ABEAAAA-cQB-ABhxAH4AGXQABmludm9rZXNxAH4AEQAAACt0AChzdW4ucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABxzcQB-ABEAAAHydAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AHHNxAH4AEQAAAGt0ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JzcQB-ABEAABPscQB-ABNxAH4AFHEAfgAmc3EAfgARAAAAZnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9ic3EAfgARAAACRXQAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHNxAH4AEQAAADF0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnNxAH4AEQAAADh0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxzcQB-ABEAAABndABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgA2dAAPY2FsbFdpdGhDb250ZXh0c3EAfgARAAAANXEAfgA5cQB-ADZ0AA5ydW5XaXRoQ29udGV4dHNxAH4AEQAAAC50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4AMnEAfgAzc3EAfgARAAACEXEAfgAtcQB-AC5xAH4AM3NxAH4AEQAAAf90AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4AN3NxAH4AEQAAAQp0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-ADNzcQB-ABEAAAR9dAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJzcQB-ABEAAAJwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBIcQB-ADNzcQB-ABEAAALsdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-ADNzcgAmamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUxpc3T8DyUxteyOEAIAAUwABGxpc3RxAH4ADHhyACxqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlQ29sbGVjdGlvbhlCAIDLXvceAgABTAABY3QAFkxqYXZhL3V0aWwvQ29sbGVjdGlvbjt4cHNyABNqYXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHEAfgBUeHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABDvc3EAfgBTAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHEAfgBWAAAAAAAAAAF2cgAXY29tLmNsb3VkLmRjLkRhdGFDZW50ZXJjQfdzv5V8swIAAHhwAA
2019-07-30 19:32:54,624 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Publish async job-39 complete on message bus
2019-07-30 19:32:54,624 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Wake up jobs related to job-39
2019-07-30 19:32:54,624 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Update db status for job-39
2019-07-30 19:32:54,625 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Wake up jobs joined with job-39 and disjoin all subjobs created from job- 39
2019-07-30 19:32:54,634 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Done executing com.cloud.vm.VmWorkStart for job-39
2019-07-30 19:32:54,640 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-9:ctx-c61c8bb0 job-37/job-39) (logid:7ff32765) Remove job-39 from job monitoring
2019-07-30 19:32:54,645 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Destroying vm VM[User|i-2-4-VM] as it failed to create on Host with Id:null
2019-07-30 19:32:54,648 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) 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
2019-07-30 19:32:54,663 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Updating resource Type = volume count for Account = 2 Operation = decreasing Amount = 1
2019-07-30 19:32:54,668 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Updating resource Type = primary_storage count for Account = 2 Operation = decreasing Amount = 21474836480
2019-07-30 19:32:54,673 WARN [o.a.c.alerts] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) AlertType:: 8 | dataCenterId:: 1 | podId:: 1 | clusterId:: null | message:: Failed to deploy Vm with Id: 4, on Host with Id: null
2019-07-30 19:32:54,676 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Updating resource Type = user_vm count for Account = 2 Operation = decreasing Amount = 1
2019-07-30 19:32:54,681 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Updating resource Type = cpu count for Account = 2 Operation = decreasing Amount = 1
2019-07-30 19:32:54,685 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37 ctx-8eba4674) (logid:7ff32765) Updating resource Type = memory count for Account = 2 Operation = decreasing Amount = 512
2019-07-30 19:32:54,693 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-28:ctx-36426215 job-37) (logid:7ff32765) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to insufficient capacity
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:722)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:245)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:212)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4513)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4071)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4058)
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.$Proxy165.startVirtualMachine(Unknown Source)
at org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin.execute(DeployVMCmdByAdmin.java:50)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:150)
at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
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:529)
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)
Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-4-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1075)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
... 18 more
2019-07-30 19:32:54,694 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37) (logid:7ff32765) Complete async job-37, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable to start a VM due to insufficient capacity"}
2019-07-30 19:32:54,695 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37) (logid:7ff32765) Publish async job-37 complete on message bus
2019-07-30 19:32:54,695 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37) (logid:7ff32765) Wake up jobs related to job-37
2019-07-30 19:32:54,695 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37) (logid:7ff32765) Update db status for job-37
2019-07-30 19:32:54,696 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37) (logid:7ff32765) Wake up jobs joined with job-37 and disjoin all subjobs created from job- 37
2019-07-30 19:32:54,699 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-28:ctx-36426215 job-37) (logid:7ff32765) Done executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-37
2019-07-30 19:32:54,699 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-28:ctx-36426215 job-37) (logid:7ff32765) Remove job-37 from job monitoring
2019-07-30 19:32:56,234 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-568ca3db) (logid:1a100b27) Begin cleanup expired async-jobs
2019-07-30 19:32:56,238 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-568ca3db) (logid:1a100b27) End cleanup expired async-jobs
2019-07-30 19:32:56,347 DEBUG [c.c.a.ApiServlet] (qtp504527234-20:ctx-c94fe415) (logid:7aaba03a) ===START=== 10.0.1.11 -- GET command=queryAsyncJobResult&jobId=7ff32765-b64c-4c0b-9156-64a43d75e636&response=json&_=1564482383500
2019-07-30 19:32:56,350 DEBUG [c.c.a.ApiServer] (qtp504527234-20:ctx-c94fe415 ctx-b9239003) (logid:7aaba03a) CIDRs from which account 'Acct[29b131fa-b2b4-11e9-92de-000c29a29fa5-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-07-30 19:32:56,360 DEBUG [c.c.a.ApiServlet] (qtp504527234-20:ctx-c94fe415 ctx-b9239003) (logid:7aaba03a) ===END=== 10.0.1.11 -- GET command=queryAsyncJobResult&jobId=7ff32765-b64c-4c0b-9156-64a43d75e636&response=json&_=1564482383500
2019-07-30 19:32:56,393 DEBUG [c.c.a.ApiServlet] (qtp504527234-15:ctx-cf3b7b99) (logid:cf2b9fcf) ===START=== 10.0.1.11 -- GET command=listVirtualMachines&id=8a04d3d4-c516-4a70-b44b-54798dc69d2a&response=json&_=1564482383501
2019-07-30 19:32:56,397 DEBUG [c.c.a.ApiServer] (qtp504527234-15:ctx-cf3b7b99 ctx-0035245d) (logid:cf2b9fcf) CIDRs from which account 'Acct[29b131fa-b2b4-11e9-92de-000c29a29fa5-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0
2019-07-30 19:32:56,417 DEBUG [c.c.a.ApiServlet] (qtp504527234-15:ctx-cf3b7b99 ctx-0035245d) (logid:cf2b9fcf) ===END=== 10.0.1.11 -- GET command=listVirtualMachines&id=8a04d3d4-c516-4a70-b44b-54798dc69d2a&response=json&_=1564482383501
2019-07-30 19:32:57,527 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) SeqA 2-237: Processing Seq 2-237: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": [\n {\n \"id\": 2,\n \"clientInfo\": \"\",\n \"host\": \"192.168.101.50\",\n \"port\": 5900,\n \"tag\": \"da605636-e1d1-49ba-b1cf-a374cc13fa92\",\n \"createTime\": 1564486239290,\n \"lastUsedTime\": 1564486264134\n }\n ]\n}","wait":0}}] }
2019-07-30 19:32:57,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) SeqA 2-237: Sending Seq 2-237: { Ans: , MgmtId: 52238131109, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-07-30 19:33:02,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 2-238: Processing Seq 2-238: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": [\n {\n \"id\": 2,\n \"clientInfo\": \"\",\n \"host\": \"192.168.101.50\",\n \"port\": 5900,\n \"tag\": \"da605636-e1d1-49ba-b1cf-a374cc13fa92\",\n \"createTime\": 1564486239290,\n \"lastUsedTime\": 1564486264134\n }\n ]\n}","wait":0}}] }
2019-07-30 19:33:02,531 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 2-238: Sending Seq 2-238: { Ans: , MgmtId: 52238131109, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
^C
```
##### STEPS TO REPRODUCE
<!--
For bugs, show exactly how to reproduce the problem, using a minimal test-case. Use Screenshots if accurate.
For new features, show how the feature would be used.
-->
<!-- Paste example playbooks or commands between quotes below -->
~~~
~~~
<!-- You can also paste gist.github.com links for larger files -->
##### EXPECTED RESULTS
<!-- What did you expect to happen when running the steps above? -->
~~~
vm created.
~~~
##### ACTUAL RESULTS
<!-- What actually happened? -->
<!-- Paste verbatim command output between quotes below -->
~~~
vm not created, state "Error"
~~~
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services