Hi everybody,
I installed a CloudStack 4.3.0 system with a manager (in a virtual machine),
two NFS primary storage, one NFS secondary storare and two host agent on ubuntu
distribution.
The cluster have one advanced zone without security group configuration with
KVM hipervisors.
I create some VM but now does not allow me to create more giving the error message
"Unable to start a VM due to insufficient capacity".
I am sure that the resources (ip, ram, cpu and storage) are enough to create
new instances. In dashboard I see all ok.
From the management-server.log I see this errors messages (see attachment for
full version) when I try to deploy a new virtual machine with 1x1GHz cpu, 1GB
or RAM and 20GB disk space:
2014-07-31 14:59:11,983 DEBUG [c.c.a.t.Request] (AgentManager-Handler-12:null) Seq 1-684594119: Processing: { Ans: , MgmtId: 77916390353436, via: 1, Ver: v1,
Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"VmDataCommand
failed, check agent logs","wait":0}}] }
2014-07-31 14:59:11,983 INFO [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Unable to contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is
unreachable: Unable to apply userdata and password entry on router
2014-07-31 14:59:12,453 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) VM state transitted from :Starting
to Stopped with event: OperationFailedvm's original host id: null new host id:
null host id before state transition: 7
2014-07-31 14:59:12,677 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) VM state transitted from :Starting
to Stopped with event: OperationFailedvm's original host id: null new host id:
null host id before state transition: null
2014-07-31 14:59:12,708 DEBUG [c.c.v.UserVmManagerImpl]
(Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Destroying vm VM[User|csweb2] as it
failed to create on Host with Id:null
2014-07-31 14:59:12,738 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) 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
2014-07-31 14:59:12,929 WARN [o.a.c.alerts] (Job-Executor-26:ctx-ab3aee38
ctx-d8600c16) alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId::
null // message:: Failed to deploy Vm with Id: 70, on Host with Id: null
2014-07-31 14:59:13,159 ERROR [c.c.a.ApiAsyncJobDispatcher]
(Job-Executor-26:ctx-ab3aee38) Unexpected exception while executing
org.apache.cloudstack.api.command.user.vm.DeployVMCmd
com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to
insufficient capacity
Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|csweb2]Scope=interface com.cloud.dc.DataCenter;
id=1
2014-07-31 14:59:13,161 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-26:ctx-ab3aee38) Complete async job-783,
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"}
2014-07-31 14:59:46,280 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-27:ctx-82be396e ctx-41f0cf24) Stopped called on VM[User|csweb2]
but the state is Error
2014-07-31 14:59:46,330 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-27:ctx-82be396e ctx-41f0cf24) VM state transitted from :Error to
Expunging with event: DestroyRequestedvm's original host id: null new host id:
null host id before state transition: null
I tried to search in others log file ("VmDataCommand failed, check agent
logs"), but I don't found nothing...
Can anyone Help me?
--
U g o V a s i <[email protected]>
P r o c n e s.r.l >)
via Cotonificio 45 33010 Tavagnacco IT
phone: +390432486523 fax: +390432486523
Le informazioni contenute in questo messaggio sono riservate e
confidenziali ed è vietata la diffusione in qualunque modo eseguita.
Qualora Lei non fosse la persona a cui il presente messaggio è
destinato, La invitiamo ad eliminarlo e a non leggerlo, dandocene
gentilmente comunicazione.
Per qualsiasi informazione si prega di contattare [email protected] .
Rif. D.L. 196/2003
2014-07-31 14:59:10,556 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-c61df92d) ===START=== 127.0.0.1 -- GET command=deployVirtualMachine&response=json&sessionkey=JYBJ9eNoOH5hAbD%2BDNV0M8Dr7JI%3D&zoneid=ed6ce5de-2ff4-4d57-aa88-27e904082928&templateid=0d935ed9-38b0-4a59-8651-927ba09f2597&hypervisor=KVM&serviceofferingid=ba47a8d5-6984-40fa-bf3a-a1aa39d0195b&diskofferingid=b487cedd-dc96-4c73-9045-c070c5dd0f29&networkids=14e56990-ee1f-46e4-b0c1-eac18daaf433&displayname=csweb2&name=csweb2&_=1406811550539
2014-07-31 14:59:10,562 DEBUG [c.c.a.ApiDispatcher] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2014-07-31 14:59:10,565 DEBUG [c.c.a.ApiDispatcher] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2014-07-31 14:59:10,567 DEBUG [c.c.a.ApiDispatcher] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) ControlledEntity name is:com.cloud.network.Network
2014-07-31 14:59:10,570 DEBUG [c.c.a.ApiDispatcher] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) InfrastructureEntity name is:com.cloud.offering.DiskOffering
2014-07-31 14:59:10,581 DEBUG [c.c.n.NetworkModelImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:10,639 DEBUG [c.c.v.UserVmManagerImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Allocating in the DB for vm
2014-07-31 14:59:10,650 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Allocating entries for VM: VM[User|csweb2]
2014-07-31 14:59:10,651 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Allocating nics for VM[User|csweb2]
2014-07-31 14:59:10,651 DEBUG [o.a.c.e.o.NetworkOrchestrator] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Allocating nic for vm VM[User|csweb2] in network Ntwk[209|Guest|8] with requested profile NicProfile[0-0-null-null-null
2014-07-31 14:59:10,694 DEBUG [c.c.n.NetworkModelImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:10,695 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Allocating disks for VM[User|csweb2]
2014-07-31 14:59:10,702 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Allocation completed for VM: VM[User|csweb2]
2014-07-31 14:59:10,702 DEBUG [c.c.v.UserVmManagerImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Successfully allocated DB entry for VM[User|csweb2]
2014-07-31 14:59:10,757 DEBUG [c.c.n.NetworkModelImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:10,760 DEBUG [c.c.n.NetworkModelImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:10,919 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) submit async job-783, details: AsyncJobVO {id:783, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 70, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdInfo: {"sessionkey":"JYBJ9eNoOH5hAbD+DNV0M8Dr7JI\u003d","serviceofferingid":"ba47a8d5-6984-40fa-bf3a-a1aa39d0195b","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"ed6ce5de-2ff4-4d57-aa88-27e904082928","templateid":"0d935ed9-38b0-4a59-8651-927ba09f2597","httpmethod":"GET","networkids":"14e56990-ee1f-46e4-b0c1-eac18daaf433","response":"json","id":"70","hypervisor":"KVM","name":"csweb2","_":"1406811550539","ctxAccountId":"2","diskofferingid":"b487cedd-dc96-4c73-9045-c070c5dd0f29","ctxStartEventId":"2119","displayname":"csweb2"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 77916390353436, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-07-31 14:59:10,920 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-26:ctx-ab3aee38) Add job-783 into job monitoring
2014-07-31 14:59:10,920 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-26:ctx-ab3aee38) Executing AsyncJobVO {id:783, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 70, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdInfo: {"sessionkey":"JYBJ9eNoOH5hAbD+DNV0M8Dr7JI\u003d","serviceofferingid":"ba47a8d5-6984-40fa-bf3a-a1aa39d0195b","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"ed6ce5de-2ff4-4d57-aa88-27e904082928","templateid":"0d935ed9-38b0-4a59-8651-927ba09f2597","httpmethod":"GET","networkids":"14e56990-ee1f-46e4-b0c1-eac18daaf433","response":"json","id":"70","hypervisor":"KVM","name":"csweb2","_":"1406811550539","ctxAccountId":"2","diskofferingid":"b487cedd-dc96-4c73-9045-c070c5dd0f29","ctxStartEventId":"2119","displayname":"csweb2"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 77916390353436, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-07-31 14:59:10,922 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-c61df92d ctx-d8600c16) ===END=== 127.0.0.1 -- GET command=deployVirtualMachine&response=json&sessionkey=JYBJ9eNoOH5hAbD%2BDNV0M8Dr7JI%3D&zoneid=ed6ce5de-2ff4-4d57-aa88-27e904082928&templateid=0d935ed9-38b0-4a59-8651-927ba09f2597&hypervisor=KVM&serviceofferingid=ba47a8d5-6984-40fa-bf3a-a1aa39d0195b&diskofferingid=b487cedd-dc96-4c73-9045-c070c5dd0f29&networkids=14e56990-ee1f-46e4-b0c1-eac18daaf433&displayname=csweb2&name=csweb2&_=1406811550539
2014-07-31 14:59:10,926 DEBUG [c.c.a.ApiDispatcher] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2014-07-31 14:59:10,927 DEBUG [c.c.a.ApiDispatcher] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2014-07-31 14:59:10,929 DEBUG [c.c.a.ApiDispatcher] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) ControlledEntity name is:com.cloud.network.Network
2014-07-31 14:59:10,931 DEBUG [c.c.a.ApiDispatcher] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) InfrastructureEntity name is:com.cloud.offering.DiskOffering
2014-07-31 14:59:10,997 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:11,000 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:11,016 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Deploy avoids pods: [], clusters: [], hosts: []
2014-07-31 14:59:11,020 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@5fb98c06
2014-07-31 14:59:11,020 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
2014-07-31 14:59:11,020 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Is ROOT volume READY (pool already allocated)?: No
2014-07-31 14:59:11,020 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Searching all possible resources under this Zone: 1
2014-07-31 14:59:11,021 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2014-07-31 14:59:11,024 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Removing from the clusterId list these clusters from avoid set: []
2014-07-31 14:59:11,032 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking resources in Cluster: 1 under Pod: 1
2014-07-31 14:59:11,032 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2014-07-31 14:59:11,035 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-7-Routing], Host[-1-Routing]]
2014-07-31 14:59:11,038 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-7-Routing], Host[-1-Routing]]
2014-07-31 14:59:11,038 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2014-07-31 14:59:11,042 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Host: 7 has cpu capability (cpu:16, speed:2266) to support requested CPU: 1 and requested speed: 1000
2014-07-31 14:59:11,042 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Checking if host: 7 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2014-07-31 14:59:11,044 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Hosts's actual total CPU: 36256 and CPU after applying overprovisioning: 36256
2014-07-31 14:59:11,044 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Free CPU: 22256 , Requested CPU: 1000
2014-07-31 14:59:11,044 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Free RAM: 37754884096 , Requested RAM: 1073741824
2014-07-31 14:59:11,044 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-07-31 14:59:11,044 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 7, used: 14000, reserved: 0, actual total: 36256, total with overprovisioning: 36256; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-07-31 14:59:11,044 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 7, used: 12884901888, reserved: 0, total: 50639785984; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-07-31 14:59:11,044 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Found a suitable host, adding to list: 7
2014-07-31 14:59:11,049 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:16, speed:2266) to support requested CPU: 1 and requested speed: 1000
2014-07-31 14:59:11,049 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2014-07-31 14:59:11,051 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Hosts's actual total CPU: 36256 and CPU after applying overprovisioning: 36256
2014-07-31 14:59:11,051 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Free CPU: 25256 , Requested CPU: 1000
2014-07-31 14:59:11,051 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Free RAM: 39902384128 , Requested RAM: 1073741824
2014-07-31 14:59:11,051 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-07-31 14:59:11,051 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 11000, reserved: 0, actual total: 36256, total with overprovisioning: 36256; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-07-31 14:59:11,051 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 10737418240, reserved: 0, total: 50639802368; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-07-31 14:59:11,051 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2014-07-31 14:59:11,051 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16 FirstFitRoutingAllocator) Host Allocator returning 2 suitable hosts
2014-07-31 14:59:11,052 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking suitable pools for volume (Id, Type): (77,ROOT)
2014-07-31 14:59:11,052 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) We need to allocate new storagepool for this volume
2014-07-31 14:59:11,053 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Calling StoragePoolAllocators to find suitable pools
2014-07-31 14:59:11,053 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2014-07-31 14:59:11,053 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) ClusterScopeStoragePoolAllocator looking for storage pool
2014-07-31 14:59:11,053 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Looking for pools in dc: 1 pod:1 cluster:1 having tags:[cs3]
2014-07-31 14:59:11,054 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Found pools matching tags: [Pool[6|NetworkFilesystem]]
2014-07-31 14:59:11,055 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Removing pool Pool[6|NetworkFilesystem] from avoid set, must have been inserted when searching for another disk's tag
2014-07-31 14:59:11,056 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking if storage pool is suitable, name: null ,poolId: 6
2014-07-31 14:59:11,058 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking pool 6 for storage, totalSize: 566160261120, usedBytes: 401583636480, usedPct: 0.7093108860829827, disable threshold: 0.85
2014-07-31 14:59:11,061 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 6-562273: Processing Seq 6-562273: { Cmd , MgmtId: -1, via: 6, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":11,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-07-31 14:59:11,064 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking pool: 6 for volume allocation [Vol[77|vm=70|ROOT]], maxSize : 1132320522240, totalAllocatedSize : 154369905664, askingSize : 21474836480, allocated disable threshold: 0.85
2014-07-31 14:59:11,064 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2014-07-31 14:59:11,064 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2014-07-31 14:59:11,064 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking if host: 7 can access any suitable storage pool for volume: ROOT
2014-07-31 14:59:11,065 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Host: 7 can access pool: 6
2014-07-31 14:59:11,065 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Found a potential host id: 7 name: csh1b and associated storage pools for this VM
2014-07-31 14:59:11,066 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) 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(7)-Storage(Volume(77|ROOT-->Pool(6))]
2014-07-31 14:59:11,098 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 6-562273: Sending Seq 6-562273: { Ans: , MgmtId: 77916390353436, via: 6, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-07-31 14:59:11,129 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) 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
2014-07-31 14:59:11,129 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Successfully transitioned to start state for VM[User|csweb2] reservation id = 20f6e469-496b-4fe6-b722-196d531d0c65
2014-07-31 14:59:11,163 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Trying to deploy VM, vm has dcId: 1 and podId: null
2014-07-31 14:59:11,163 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 7, poolId: null
2014-07-31 14:59:11,163 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Deploy avoids pods: null, clusters: null, hosts: null
2014-07-31 14:59:11,172 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Deploy avoids pods: [], clusters: [], hosts: []
2014-07-31 14:59:11,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@5fb98c06
2014-07-31 14:59:11,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
2014-07-31 14:59:11,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Is ROOT volume READY (pool already allocated)?: No
2014-07-31 14:59:11,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 7
2014-07-31 14:59:11,174 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2014-07-31 14:59:11,175 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking suitable pools for volume (Id, Type): (77,ROOT)
2014-07-31 14:59:11,175 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) We need to allocate new storagepool for this volume
2014-07-31 14:59:11,175 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Calling StoragePoolAllocators to find suitable pools
2014-07-31 14:59:11,176 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2014-07-31 14:59:11,176 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) ClusterScopeStoragePoolAllocator looking for storage pool
2014-07-31 14:59:11,176 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Looking for pools in dc: 1 pod:1 cluster:1 having tags:[cs3]
2014-07-31 14:59:11,176 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Found pools matching tags: [Pool[6|NetworkFilesystem]]
2014-07-31 14:59:11,177 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Removing pool Pool[6|NetworkFilesystem] from avoid set, must have been inserted when searching for another disk's tag
2014-07-31 14:59:11,178 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking if storage pool is suitable, name: null ,poolId: 6
2014-07-31 14:59:11,180 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking pool 6 for storage, totalSize: 566160261120, usedBytes: 401583636480, usedPct: 0.7093108860829827, disable threshold: 0.85
2014-07-31 14:59:11,182 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking pool: 6 for volume allocation [Vol[77|vm=70|ROOT]], maxSize : 1132320522240, totalAllocatedSize : 154369905664, askingSize : 21474836480, allocated disable threshold: 0.85
2014-07-31 14:59:11,182 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2014-07-31 14:59:11,182 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2014-07-31 14:59:11,182 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Checking if host: 7 can access any suitable storage pool for volume: ROOT
2014-07-31 14:59:11,183 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Host: 7 can access pool: 6
2014-07-31 14:59:11,183 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Found a potential host id: 7 name: csh1b and associated storage pools for this VM
2014-07-31 14:59:11,183 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) 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(7)-Storage(Volume(77|ROOT-->Pool(6))]
2014-07-31 14:59:11,183 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Deployment found - P0=VM[User|csweb2], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage(Volume(77|ROOT-->Pool(6))]
2014-07-31 14:59:11,284 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 7 host id before state transition: null
2014-07-31 14:59:11,289 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Hosts's actual total CPU: 36256 and CPU after applying overprovisioning: 36256
2014-07-31 14:59:11,289 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) We are allocating VM, increasing the used capacity of this host:7
2014-07-31 14:59:11,289 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Current Used CPU: 14000 , Free CPU:22256 ,Requested CPU: 1000
2014-07-31 14:59:11,289 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Current Used RAM: 12884901888 , Free RAM:37754884096 ,Requested RAM: 1073741824
2014-07-31 14:59:11,289 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) CPU STATS after allocation: for host: 7, old used: 14000, old reserved: 0, actual total: 36256, total with overprovisioning: 36256; new used:15000, reserved:0; requested cpu:1000,alloc_from_last:false
2014-07-31 14:59:11,289 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) RAM STATS after allocation: for host: 7, old used: 12884901888, old reserved: 0, total: 50639785984; new used: 13958643712, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2014-07-31 14:59:11,326 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) VM is being created in podId: 1
2014-07-31 14:59:11,327 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Network id=209 is already implemented
2014-07-31 14:59:11,374 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:11,378 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Changing active number of nics for network id=209 on 1
2014-07-31 14:59:11,424 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Asking VirtualRouter to prepare for Nic[100-70-20f6e469-496b-4fe6-b722-196d531d0c65-10.1.1.29]
2014-07-31 14:59:11,431 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Lock is acquired for network id 209 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage(Volume(77|ROOT-->Pool(6))]
2014-07-31 14:59:11,434 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Lock is released for network id 209 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage(Volume(77|ROOT-->Pool(6))]
2014-07-31 14:59:11,439 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:11,447 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:11,450 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Applying dhcp entry in network Ntwk[209|Guest|8]
2014-07-31 14:59:11,462 DEBUG [c.c.a.t.Request] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Seq 1-684594118: Sending { Cmd , MgmtId: 77916390353436, via: 1(csh3b), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:41:b7:00:19","vmIpAddress":"10.1.1.29","vmName":"csweb2","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:41:b7:00:19","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.name":"r-29-VM","router.ip":"169.254.0.116"},"wait":0}}] }
2014-07-31 14:59:11,662 DEBUG [c.c.a.t.Request] (AgentManager-Handler-4:null) Seq 1-684594118: Processing: { Ans: , MgmtId: 77916390353436, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-07-31 14:59:11,662 DEBUG [c.c.a.t.Request] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Seq 1-684594118: Received: { Ans: , MgmtId: 77916390353436, via: 1, Ver: v1, Flags: 10, { Answer } }
2014-07-31 14:59:11,667 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:11,670 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Applying userdata and password entry in network Ntwk[209|Guest|8]
2014-07-31 14:59:11,681 DEBUG [c.c.a.t.Request] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Seq 1-684594119: Sending { Cmd , MgmtId: 77916390353436, via: 1(csh3b), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"10.1.1.29","vmName":"csweb2","executeInSequence":false,"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.0.116","router.name":"r-29-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.29","vmName":"csweb2","executeInSequence":false,"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.0.116","router.name":"r-29-VM"},"wait":0}}] }
2014-07-31 14:59:11,983 DEBUG [c.c.a.t.Request] (AgentManager-Handler-12:null) Seq 1-684594119: Processing: { Ans: , MgmtId: 77916390353436, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"VmDataCommand failed, check agent logs","wait":0}}] }
2014-07-31 14:59:11,983 DEBUG [c.c.a.t.Request] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Seq 1-684594119: Received: { Ans: , MgmtId: 77916390353436, via: 1, Ver: v1, Flags: 10, { Answer, Answer } }
2014-07-31 14:59:11,983 INFO [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Unable to contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is unreachable: Unable to apply userdata and password entry on router
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:3915)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyUserData(VirtualNetworkApplianceManagerImpl.java:3118)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:622)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy240.applyUserData(Unknown Source)
at com.cloud.network.element.VirtualRouterElement.addPasswordAndUserdata(VirtualRouterElement.java:949)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1192)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1309)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1245)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:960)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:761)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:601)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:228)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:207)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3581)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3161)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3147)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:622)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:50)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy169.startVirtualMachine(Unknown Source)
at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:443)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109)
at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66)
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 com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:509)
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 java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2014-07-31 14:59:12,064 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Cleaning up resources for the vm VM[User|csweb2] in Starting state
2014-07-31 14:59:12,067 DEBUG [c.c.a.t.Request] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Seq 7-564073337: Sending { Cmd , MgmtId: 77916390353436, via: 7(csh1b), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-70-VM","wait":0}}] }
2014-07-31 14:59:12,219 DEBUG [c.c.a.t.Request] (AgentManager-Handler-1:null) Seq 7-564073337: Processing: { Ans: , MgmtId: 77916390353436, via: 7, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2014-07-31 14:59:12,220 DEBUG [c.c.a.t.Request] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Seq 7-564073337: Received: { Ans: , MgmtId: 77916390353436, via: 7, Ver: v1, Flags: 10, { StopAnswer } }
2014-07-31 14:59:12,225 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Service SecurityGroup is not supported in the network id=209
2014-07-31 14:59:12,227 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Changing active number of nics for network id=209 on -1
2014-07-31 14:59:12,343 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Asking VirtualRouter to release NicProfile[100-70-20f6e469-496b-4fe6-b722-196d531d0c65-10.1.1.29-null
2014-07-31 14:59:12,343 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Successfully released network resources for the vm VM[User|csweb2]
2014-07-31 14:59:12,343 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Successfully cleanued up resources for the vm VM[User|csweb2] in Starting state
2014-07-31 14:59:12,349 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Deploy avoids pods: [], clusters: [], hosts: [7]
2014-07-31 14:59:12,349 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) DataCenter id = '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM, returning.
2014-07-31 14:59:12,453 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 7
2014-07-31 14:59:12,457 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Hosts's actual total CPU: 36256 and CPU after applying overprovisioning: 36256
2014-07-31 14:59:12,458 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Hosts's actual total RAM: 50639785984 and RAM after applying overprovisioning: 50639785984
2014-07-31 14:59:12,458 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) release cpu from host: 7, old used: 15000,reserved: 0, actual total: 36256, total with overprovisioning: 36256; new used: 14000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-07-31 14:59:12,458 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) release mem from host: 7, old used: 13958643712,reserved: 0, total: 50639785984; new used: 12884901888,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-07-31 14:59:12,557 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) 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
2014-07-31 14:59:12,557 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Successfully transitioned to start state for VM[User|csweb2] reservation id = 1d3c8a23-d2fa-4cfb-bacc-0122cba2d63f
2014-07-31 14:59:12,593 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Trying to deploy VM, vm has dcId: 1 and podId: 1
2014-07-31 14:59:12,593 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Deploy avoids pods: [], clusters: [], hosts: [7]
2014-07-31 14:59:12,600 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Deploy avoids pods: [], clusters: [], hosts: [7]
2014-07-31 14:59:12,600 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) DataCenter id = '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM, returning.
2014-07-31 14:59:12,677 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: null
2014-07-31 14:59:12,708 DEBUG [c.c.v.UserVmManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) Destroying vm VM[User|csweb2] as it failed to create on Host with Id:null
2014-07-31 14:59:12,738 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) 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
2014-07-31 14:59:12,929 WARN [o.a.c.alerts] (Job-Executor-26:ctx-ab3aee38 ctx-d8600c16) alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Failed to deploy Vm with Id: 70, on Host with Id: null
2014-07-31 14:59:13,159 ERROR [c.c.a.ApiAsyncJobDispatcher] (Job-Executor-26:ctx-ab3aee38) Unexpected exception while executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd
com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to insufficient capacity
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:605)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:207)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3581)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3161)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3147)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:622)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:50)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy169.startVirtualMachine(Unknown Source)
at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:443)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109)
at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66)
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 com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:509)
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 java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|csweb2]Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:921)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:761)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:601)
... 38 more
2014-07-31 14:59:13,161 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-26:ctx-ab3aee38) Complete async job-783, 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"}
2014-07-31 14:59:13,200 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-26:ctx-ab3aee38) Done executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-783
2014-07-31 14:59:13,218 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-26:ctx-ab3aee38) Remove job-783 from job monitoring
