Attached is the proper grep of job-14.
In this small size instance scenario failure, is the XenServer
the system that is saying 'Hey 500Mbytes isn't enough RAM'?
I am trying to understand exactly which system is saying what
in particular is insufficient.
Regards,
Evan
-----Original Message-----
From: Alena Prokharchyk [mailto:alena.prokharc...@citrix.com]
Sent: Monday, June 04, 2012 7:41 PM
To: cloudstack-users@incubator.apache.org
Subject: Re: Unable to add an instance - speed=500Mhz, Ram=512 (host is in
avoid set)
The setup lacks the resources. See more detailed information inline. Btw, to
capture all logs related to vm deployment, grep by job-id should be done (in
this case "grep job-14 management-server.log").
-Alena.
On 6/4/12 7:27 PM, "Evan Miller" <evan.mil...@citrix.com> wrote:
>Trying to setup a single, small VM to my cloud.
>My cloud, so far, consists of:
>
>CloudStack Management Server:
> * OS = Centos 6.2 x86 64-bit
> * CPU = Intel 3050, 2.13 GHz
> * RAM = 2 Gbytes
>
>XenServer:
> * OS = Provided by XenServer 6.0.2 CD
> * Hardware = IBM 3250
> * CPU = Intel Xeon Dual Core, Single Physical CPU@ 1.86 GHz
>
>Template:
>* CentOS 5.6(64-bit) no GUI (XenServer)
>
>Per the management log below, is XenServer refusing to setup the first VM?
>
>
>2012-06-04 18:10:02,907 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) DeploymentPlanner allocation algorithm: random
>2012-06-04 18:10:02,907 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) Trying to allocate a host and storage pools
>from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram:
>536870912
>2012-06-04 18:10:02,907 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) Is ROOT volume READY (pool already allocated)?:
>No
>2012-06-04 18:10:02,907 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) Searching all possible resources under this Zone:
>1
>2012-06-04 18:10:02,909 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) Listing clusters in order of aggregate
>capacity, that have (atleast one host with) enough CPU and RAM capacity
>under this
>Zone: 1
>2012-06-04 18:10:02,910 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) CPUOverprovisioningFactor considered: 1.0
>2012-06-04 18:10:02,918 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) Checking resources in Cluster: 1 under Pod: 1
>2012-06-04 18:10:02,918 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) Calling HostAllocators to find suitable hosts
>2012-06-04 18:10:02,918 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-1:job-14 FirstFitRoutingAllocator) Looking for hosts in dc:
>1 pod:1 cluster:1
>2012-06-04 18:10:02,920 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-1:job-14 FirstFitRoutingAllocator) FirstFitAllocator has
>1 hosts to check for allocation: [Host[-1-Routing]]
>2012-06-04 18:10:02,923 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-1:job-14 FirstFitRoutingAllocator) Found 1 hosts for
>allocation after prioritization: [Host[-1-Routing]]
>2012-06-04 18:10:02,923 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-1:job-14 FirstFitRoutingAllocator) Looking for
>speed=500Mhz, Ram=512
>2012-06-04 18:10:02,923 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-1:job-14 FirstFitRoutingAllocator) Host name:
>xenserver1-cs, hostId: 1 is in avoid set, skipping this and trying
>other available hosts
The host was put in avoid set some time before (the log fragment you've sent
doesn't capture it). The host can be put in avoid set when it doesn't have
enough resources for vm start (cpu/ram).
>2012-06-04 18:10:02,923 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-1:job-14 FirstFitRoutingAllocator) Host Allocator
>returning 0 suitable hosts
>2012-06-04 18:10:02,923 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) No suitable hosts found
>2012-06-04 18:10:02,923 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) No suitable hosts found under this Cluster: 1
>2012-06-04 18:10:02,923 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-1:job-14) Could not find suitable Deployment Destination
>for this VM under any clusters, returning.
>2012-06-04 18:10:03,022 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-1:job-14) 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
>2012-06-04 18:10:03,027 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-1:job-14) Hosts's actual total CPU: 3732 and CPU after
>applying overprovisioning: 3732
>2012-06-04 18:10:03,028 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-1:job-14) release cpu from host: 1, old used:
>1500,reserved: 0, actual total: 3732, total with overprovisioning:
>3732; new used: 1000,reserved:0; movedfromreserved:
>false,moveToReserveredfalse
>2012-06-04 18:10:03,028 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-1:job-14) release mem from host: 1, old used:
>1879048192,reserved: 0, total: 3775173696; new used:
>1342177280,reserved:0; movedfromreserved: false,moveToReserveredfalse
>2012-06-04 18:10:03,183 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-1:job-14) 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
>2012-06-04 18:10:03,888 INFO [api.commands.DeployVMCmd]
>(Job-Executor-1:job-14)
>com.cloud.exception.InsufficientServerCapacityException: Unable to
>create a deployment for VM[User|i-2-7-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1
>2012-06-04 18:10:03,888 WARN [cloud.api.ApiDispatcher]
>(Job-Executor-1:job-14) class com.cloud.api.ServerApiException : Unable
>to create a deployment for VM[User|i-2-7-VM]
>2012-06-04 18:10:03,891 DEBUG [cloud.async.AsyncJobManagerImpl]
>(Job-Executor-1:job-14) Complete async job-14, jobStatus: 2, resultCode:
>530, result:
>com.cloud.api.response.ExceptionResponse@4ebe0382<mailto:com.cloud.api.
>res
>ponse.ExceptionResponse@4ebe0382>
>2012-06-04 18:10:07,258 DEBUG [cloud.async.AsyncJobManagerImpl]
>(catalina-exec-7:null) Async job-14 completed
>
>
>
>I, also, tried to create a medium size VM. This, also, failed with a
>different error related to InsufficientServerCapacityException:
>
>
>
>2012-06-04 17:34:52,550 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-9:job-9) DeploymentPlanner allocation algorithm: random
>2012-06-04 17:34:52,550 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-9:job-9) Trying to allocate a host and storage pools from
>dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram:
>1073741824
>2012-06-04 17:34:52,550 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-9:job-9) Is ROOT volume READY (pool already allocated)?:
>No
>2012-06-04 17:34:52,550 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-9:job-9) Searching all possible resources under this
>Zone: 1
>2012-06-04 17:34:52,551 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-9:job-9) Listing clusters in order of aggregate capacity,
>that have (atleast one host with) enough CPU and RAM capacity under
>this
>Zone: 1
>2012-06-04 17:34:52,552 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-9:job-9) CPUOverprovisioningFactor considered: 1.0
>2012-06-04 17:34:52,558 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-9:job-9) Cannot allocate cluster 1 for vm creation since
>its allocated percentage: 0.9243709585329766 will cross the disable
>capacity threshold: 0.85 for capacity Type : 0, skipping this cluster
CapacityType: 0 means RAM. When we analyze if host is capable for vm
deployment, we always make sure the total RAM (including the RAM we are
allocating for the vm), doesn't exceed RAM capacity threshold (global config
variable cluster.memory.allocated.capacity.disablethreshold).
>2012-06-04 17:34:52,558 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-9:job-9) Could not find suitable Deployment Destination
>for this VM under any clusters, returning.
>2012-06-04 17:34:52,690 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-9:job-9) 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
>2012-06-04 17:34:52,694 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-9:job-9) Hosts's actual total CPU: 3732 and CPU after
>applying overprovisioning: 3732
>2012-06-04 17:34:52,694 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-9:job-9) release cpu from host: 1, old used: 2000,reserved:
>0, actual total: 3732, total with overprovisioning: 3732; new used:
>1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
>2012-06-04 17:34:52,694 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-9:job-9) release mem from host: 1, old used:
>2415919104,reserved: 0, total: 3775173696; new used:
>1342177280,reserved:0; movedfromreserved: false,moveToReserveredfalse
>2012-06-04 17:34:52,842 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-9:job-9) 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
>2012-06-04 17:34:53,463 INFO [api.commands.DeployVMCmd]
>(Job-Executor-9:job-9)
>com.cloud.exception.InsufficientServerCapacityException: Unable to
>create a deployment for VM[User|i-2-5-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1
>2012-06-04 17:34:53,464 WARN [cloud.api.ApiDispatcher]
>(Job-Executor-9:job-9) class com.cloud.api.ServerApiException : Unable
>to create a deployment for VM[User|i-2-5-VM]
>2012-06-04 17:34:53,464 DEBUG [cloud.async.AsyncJobManagerImpl]
>(Job-Executor-9:job-9) Complete async job-9, jobStatus: 2, resultCode:
>530, result:
>com.cloud.api.response.ExceptionResponse@7f378496<mailto:com.cloud.api.
>res
>ponse.ExceptionResponse@7f378496>
>2012-06-04 17:34:56,985 DEBUG [cloud.async.AsyncJobManagerImpl]
>(catalina-exec-17:null) Async job-9 completed
>
>How to overcome these errors?
The solution will be - create the service offering with small amount of RAM/CPU
(depends of how many vms you are planning to run on your host). Or add more
hosts to the Xen cluster.
>
>Regards,
>
>Evan Miller
>
>
2012-06-04 18:10:02,094 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-9:null) submit async job-14, details: AsyncJobVO {id:14, userId:
2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 7,
cmd: com.cloud.api.commands.DeployVMCmd, cmdOriginator: null, cmdInfo:
{"id":"7","response":"json","templateId":"57dca056-e5b4-4700-9504-6d55244da2f3","sessionkey":"65d3off0g53HdzoJlOYHOB9yG1g\u003d","ctxUserId":"2","hypervisor":"XenServer","diskOfferingId":"187dd982-c911-4aee-ba42-52e9eea4f9ed","serviceOfferingId":"ca0c5b3c-73c7-4831-9f9e-ee0e75641675","_":"1338858600664","ctxAccountId":"2","ctxStartEventId":"57","zoneId":"5ddb8fbb-0438-4a03-990b-2aa8361f1f6a"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 207375654364,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2012-06-04 18:10:02,102 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-1:job-14) Executing com.cloud.api.commands.DeployVMCmd for job-14
2012-06-04 18:10:02,190 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) 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
2012-06-04 18:10:02,190 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-1:job-14) Successfully transitioned to start state for
VM[User|i-2-7-VM] reservation id = fab24933-1809-4f2d-b4f0-167cad9876a5
2012-06-04 18:10:02,252 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-1:job-14) Trying to deploy VM, vm has dcId: 1 and podId: null
2012-06-04 18:10:02,253 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-1:job-14) Deploy avoids pods: null, clusters: null, hosts: null
2012-06-04 18:10:02,260 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) DeploymentPlanner allocation algorithm: random
2012-06-04 18:10:02,260 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
2012-06-04 18:10:02,260 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Is ROOT volume READY (pool already allocated)?: No
2012-06-04 18:10:02,260 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Searching all possible resources under this Zone: 1
2012-06-04 18:10:02,262 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Listing clusters in order of aggregate capacity, that
have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2012-06-04 18:10:02,263 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) CPUOverprovisioningFactor considered: 1.0
2012-06-04 18:10:02,272 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Checking resources in Cluster: 1 under Pod: 1
2012-06-04 18:10:02,272 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Calling HostAllocators to find suitable hosts
2012-06-04 18:10:02,273 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2012-06-04 18:10:02,275 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts
to check for allocation: [Host[-1-Routing]]
2012-06-04 18:10:02,278 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Found 1 hosts for allocation
after prioritization: [Host[-1-Routing]]
2012-06-04 18:10:02,278 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Looking for speed=500Mhz,
Ram=512
2012-06-04 18:10:02,289 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Checking if host: 1 has enough
capacity for requested CPU: 500 and requested RAM: 536870912 ,
cpuOverprovisioningFactor: 1.0
2012-06-04 18:10:02,292 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Hosts's actual total CPU: 3732
and CPU after applying overprovisioning: 3732
2012-06-04 18:10:02,292 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Free CPU: 2732 , Requested
CPU: 500
2012-06-04 18:10:02,292 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Free RAM: 2432996416 ,
Requested RAM: 536870912
2012-06-04 18:10:02,292 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Host has enough CPU and RAM
available
2012-06-04 18:10:02,292 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 1, used: 1000, reserved: 0, actual total: 3732, total with
overprovisioning: 3732; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2012-06-04 18:10:02,292 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 1, used: 1342177280, reserved: 0, total: 3775173696; requested mem:
536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2012-06-04 18:10:02,292 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Found a suitable host, adding
to list: 1
2012-06-04 18:10:02,292 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Host Allocator returning 1
suitable hosts
2012-06-04 18:10:02,295 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Checking suitable pools for volume (Id, Type): (10,ROOT)
2012-06-04 18:10:02,295 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) We need to allocate new storagepool for this volume
2012-06-04 18:10:02,295 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Calling StoragePoolAllocators to find suitable pools
2012-06-04 18:10:02,297 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-1:job-14) Looking for pools in dc: 1 pod:1 cluster:1
2012-06-04 18:10:02,299 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-1:job-14) FirstFitStoragePoolAllocator has 1 pools to check for
allocation
2012-06-04 18:10:02,299 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-1:job-14) Checking if storage pool is suitable, name: LS_PRIMARY1
,poolId: 200
2012-06-04 18:10:02,299 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-1:job-14) Is localStorageAllocationNeeded? false
2012-06-04 18:10:02,299 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-1:job-14) Is storage pool shared? true
2012-06-04 18:10:02,300 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-1:job-14) Attempting to look for pool 200 for storage, totalSize:
104586543104, usedBytes: 6538395648, usedPct: 0.06251660542502369, disable
threshold: 0.85
2012-06-04 18:10:02,303 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-1:job-14) Attempting to look for pool 200 for storage, maxSize :
209173086208, totalAllocatedSize : 4860207616, askingSize : 21474836480,
allocated disable threshold: 0.85
2012-06-04 18:10:02,303 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-1:job-14) FirstFitStoragePoolAllocator returning 1 suitable
storage pools
2012-06-04 18:10:02,303 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Checking suitable pools for volume (Id, Type):
(11,DATADISK)
2012-06-04 18:10:02,303 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) We need to allocate new storagepool for this volume
2012-06-04 18:10:02,303 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Calling StoragePoolAllocators to find suitable pools
2012-06-04 18:10:02,303 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-1:job-14) Looking for pools in dc: 1 pod:1 cluster:1
2012-06-04 18:10:02,305 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-1:job-14) FirstFitStoragePoolAllocator has 1 pools to check for
allocation
2012-06-04 18:10:02,305 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-1:job-14) Checking if storage pool is suitable, name: LS_PRIMARY1
,poolId: 200
2012-06-04 18:10:02,305 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-1:job-14) Is localStorageAllocationNeeded? false
2012-06-04 18:10:02,305 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-1:job-14) Is storage pool shared? true
2012-06-04 18:10:02,306 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-1:job-14) Attempting to look for pool 200 for storage, totalSize:
104586543104, usedBytes: 6538395648, usedPct: 0.06251660542502369, disable
threshold: 0.85
2012-06-04 18:10:02,309 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-1:job-14) Attempting to look for pool 200 for storage, maxSize :
209173086208, totalAllocatedSize : 4860207616, askingSize : 21474836480,
allocated disable threshold: 0.85
2012-06-04 18:10:02,309 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-1:job-14) FirstFitStoragePoolAllocator returning 1 suitable
storage pools
2012-06-04 18:10:02,309 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Trying to find a potenial host and associated storage
pools from the suitable host/pool lists for this VM
2012-06-04 18:10:02,309 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Checking if host: 1 can access any suitable storage
pool for volume: ROOT
2012-06-04 18:10:02,310 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Host: 1 can access pool: 200
2012-06-04 18:10:02,311 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Checking if host: 1 can access any suitable storage
pool for volume: DATADISK
2012-06-04 18:10:02,312 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Host: 1 can access pool: 200
2012-06-04 18:10:02,312 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Found a potential host id: 1 name: xenserver1-cs and
associated storage pools for this VM
2012-06-04 18:10:02,315 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) 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(10|ROOT-->Pool(200),
Volume(11|DATADISK-->Pool(200))]
2012-06-04 18:10:02,315 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-1:job-14) Deployment found - P0=VM[User|i-2-7-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(10|ROOT-->Pool(200),
Volume(11|DATADISK-->Pool(200))]
2012-06-04 18:10:02,402 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) 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
2012-06-04 18:10:02,411 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) Hosts's actual total CPU: 3732 and CPU after applying
overprovisioning: 3732
2012-06-04 18:10:02,411 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) We are allocating VM, increasing the used capacity of
this host:1
2012-06-04 18:10:02,411 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) Current Used CPU: 1000 , Free CPU:2732 ,Requested CPU:
500
2012-06-04 18:10:02,411 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) Current Used RAM: 1342177280 , Free RAM:2432996416
,Requested RAM: 536870912
2012-06-04 18:10:02,411 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) CPU STATS after allocation: for host: 1, old used:
1000, old reserved: 0, actual total: 3732, total with overprovisioning: 3732;
new used:1500, reserved:0; requested cpu:500,alloc_from_last:false
2012-06-04 18:10:02,411 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) RAM STATS after allocation: for host: 1, old used:
1342177280, old reserved: 0, total: 3775173696; new used: 1879048192, reserved:
0; requested mem: 536870912,alloc_from_last:false
2012-06-04 18:10:02,478 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-1:job-14) VM is being started in podId: 1
2012-06-04 18:10:02,482 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-1:job-14) Network id=204 is already implemented
2012-06-04 18:10:02,577 DEBUG [db.Transaction.Transaction]
(Job-Executor-1:job-14) Rolling back the transaction: Time = 2 Name =
-AsyncJobManagerImpl$1.run:393-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679;
called by
-Transaction.rollback:837-Transaction.removeUpTo:780-Transaction.close:599-DatabaseCallback.interceptComplete:67-DatabaseCallback.intercept:32-NetworkManagerImpl.assignPublicIpAddress:355-DirectPodBasedNetworkGuru.getIp:158-DirectPodBasedNetworkGuru.reserve:146-DatabaseCallback.intercept:30-NetworkManagerImpl.prepare:1859-VirtualMachineManagerImpl.advanceStart:741-VirtualMachineManagerImpl.start:461
2012-06-04 18:10:02,578 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-1:job-14) Insufficient capacity
2012-06-04 18:10:02,654 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-1:job-14) Cleaning up resources for the vm VM[User|i-2-7-VM] in
Starting state
2012-06-04 18:10:02,656 DEBUG [agent.transport.Request] (Job-Executor-1:job-14)
Seq 1-1788411934: Sending { Cmd , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-7-VM","wait":0}}]
}
2012-06-04 18:10:02,657 DEBUG [agent.transport.Request] (Job-Executor-1:job-14)
Seq 1-1788411934: Executing: { Cmd , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-7-VM","wait":0}}]
}
2012-06-04 18:10:02,782 DEBUG [agent.transport.Request] (Job-Executor-1:job-14)
Seq 1-1788411934: Received: { Ans: , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 110, { StopAnswer } }
2012-06-04 18:10:02,782 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-1:job-14) Cleanup succeeded. Details VM does not exist
2012-06-04 18:10:02,904 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-1:job-14) Successfully cleanued up resources for the vm
VM[User|i-2-7-VM] in Starting state
2012-06-04 18:10:02,907 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) DeploymentPlanner allocation algorithm: random
2012-06-04 18:10:02,907 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
2012-06-04 18:10:02,907 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Is ROOT volume READY (pool already allocated)?: No
2012-06-04 18:10:02,907 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Searching all possible resources under this Zone: 1
2012-06-04 18:10:02,909 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Listing clusters in order of aggregate capacity, that
have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2012-06-04 18:10:02,910 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) CPUOverprovisioningFactor considered: 1.0
2012-06-04 18:10:02,918 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Checking resources in Cluster: 1 under Pod: 1
2012-06-04 18:10:02,918 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Calling HostAllocators to find suitable hosts
2012-06-04 18:10:02,918 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2012-06-04 18:10:02,920 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts
to check for allocation: [Host[-1-Routing]]
2012-06-04 18:10:02,923 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Found 1 hosts for allocation
after prioritization: [Host[-1-Routing]]
2012-06-04 18:10:02,923 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Looking for speed=500Mhz,
Ram=512
2012-06-04 18:10:02,923 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Host name: xenserver1-cs,
hostId: 1 is in avoid set, skipping this and trying other available hosts
2012-06-04 18:10:02,923 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-1:job-14 FirstFitRoutingAllocator) Host Allocator returning 0
suitable hosts
2012-06-04 18:10:02,923 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) No suitable hosts found
2012-06-04 18:10:02,923 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) No suitable hosts found under this Cluster: 1
2012-06-04 18:10:02,923 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-1:job-14) Could not find suitable Deployment Destination for this
VM under any clusters, returning.
2012-06-04 18:10:03,022 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) 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
2012-06-04 18:10:03,027 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) Hosts's actual total CPU: 3732 and CPU after applying
overprovisioning: 3732
2012-06-04 18:10:03,028 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) release cpu from host: 1, old used: 1500,reserved: 0,
actual total: 3732, total with overprovisioning: 3732; new used:
1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-06-04 18:10:03,028 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) release mem from host: 1, old used:
1879048192,reserved: 0, total: 3775173696; new used: 1342177280,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2012-06-04 18:10:03,183 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-1:job-14) 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
2012-06-04 18:10:03,888 INFO [api.commands.DeployVMCmd]
(Job-Executor-1:job-14)
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-7-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2012-06-04 18:10:03,888 WARN [cloud.api.ApiDispatcher] (Job-Executor-1:job-14)
class com.cloud.api.ServerApiException : Unable to create a deployment for
VM[User|i-2-7-VM]
2012-06-04 18:10:03,891 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-1:job-14) Complete async job-14, jobStatus: 2, resultCode: 530,
result: com.cloud.api.response.ExceptionResponse@4ebe0382
2012-06-04 18:10:07,258 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-7:null) Async job-14 completed
