Attached is the job-18 log snippet.
Sorry for not including this attachment with the previous email.
Regards,
Evan
-----Original Message-----
From: Evan Miller [mailto:evan.mil...@citrix.com]
Sent: Tuesday, June 05, 2012 12:48 PM
To: cloudstack-users@incubator.apache.org
Subject: RE: Unable to add an instance - speed=500Mhz, Ram=512 (host is in
avoid set)
-----Original Message-----
From: Alena Prokharchyk [mailto:alena.prokharc...@citrix.com]
Sent: Tuesday, June 05, 2012 12:08 PM
To: cloudstack-users@incubator.apache.org
Subject: Re: Unable to add an instance - speed=500Mhz, Ram=512 (host is in
avoid set)
On 6/5/12 11:49 AM, "Evan Miller" <evan.mil...@citrix.com> wrote:
>RECOMMENDATION:
>Need to improve the 3.0.0 - 3.0.2 Basic Installation Guide.
>I don't have huge ranges of ip addresses available. So, it would be
>extremely beneficial to have some idea, in advance, as to how ip
>addresses will be consumed by a basic cloud setup. For example, I was
>surprised to learn that in my basic setup, one CloudStack Management
>Server (also serving primary and secondary filesystems) and one
>XenServer using one connected nic, the following ip addresses were
>required even before adding a single VM instance:
>
> CSMS - 1 ip (management) [not surprising] XenServer - 1 ip
> (management) [not surprising] s-1-VM - 3 ips (2 - management, 1 -
> guest) [surprising] v-2-VM - 2 ips (1 - management, 1 - guest)
> [surprising]
>
>So, for each VM instance, is only one guest ip address required? Or is
>more required?
Only one guest IP.
>> After adding the guest IP to the pod, still not able to add a VM
>> instance to the cloud. Goth this popup error window:
>> Unable to create a deployment for VM[User|i-2-9-VM]
>> Seeing insufficient capacity for job-18 in management-server.log
>> Attaching the log file snippet. It is hard for me to determine the
>> precise insufficiency. Please let me know.
>> Also, the dashboard shows that the fourth guest ip address is still
>> taken. When will CSMS give back the ip address of the VM instance
>> that failed? Logging out and redisplaying the dashboard from the
>> browser still shows the fourth direct ip is taken. Destroying all
>> failed instances didn't help either. Clinging to that ip address
>> seems like a bug to me.
>> Also, how long does expunging take after I destroy an instance?
>> That is, when does the instance finally become expunged?
>> I see instances expunging for about 24 hours now.
>> Regards,
>> Evan
>
>Also, I, actually, don't see in XenCenter 6.0 what device is using the
>end (last) guest ip address that I defined. However, it is apparently
>used by something. What is using the last
>(end) guest ip address? The dashboard says the 3 direct ip addresses
>are used, but I can't identify what is using the third (last or end)
>guest ip address.
You can check cloud.nics table (select instance_id where ip4_address=<ip> and
network_id=<id of the guest network>
>
>
>Regards,
>Evan
>
>-----Original Message-----
>From: Alena Prokharchyk [mailto:alena.prokharc...@citrix.com]
>Sent: Monday, June 04, 2012 9:14 PM
>To: cloudstack-users@incubator.apache.org
>Subject: Re: Unable to add an instance - speed=500Mhz, Ram=512 (host is
>in avoid set)
>
>On 6/4/12 8:07 PM, "Evan Miller" <evan.mil...@citrix.com> wrote:
>
>>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.
>
>
>
>Here is the reason for the failure: Nic reservation failed due to
>Insufficient capacity exception (DirectPodBasedNetworkGuru.getIp:158):
>
>
>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-Futur
>eTa
>s
>k$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:111
>0-T
>h
>readPoolExecutor$Worker.run:603-Thread.run:679; called by
>-Transaction.rollback:837-Transaction.removeUpTo:780-Transaction.close:
>599
>-
>DatabaseCallback.interceptComplete:67-DatabaseCallback.intercept:32-Net
>wor
>k
>ManagerImpl.assignPublicIpAddress:355-DirectPodBasedNetworkGuru.getIp:1
>58-
>D
>irectPodBasedNetworkGuru.reserve:146-DatabaseCallback.intercept:30-Netw
>ork
>M
>anagerImpl.prepare:1859-VirtualMachineManagerImpl.advanceStart:741-Virt
>ual
>M
>achineManagerImpl.start:461
>2012-06-04 18:10:02,578 INFO [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-1:job-14) Insufficient capacity
>
>
>Looks like the Guest network doesn't have free guest IPs in the POD1
>targeted for deployment. To add the additional Ips, do this:
>
>* select Zone
>* Select Guest Network on the network diagram
>* Add guest IP range to the POD.
>
>
>-Alena.
>
>
>
>
>>
>>
>>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-05 12:33:35,965 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-7:null) submit async job-18, details: AsyncJobVO {id:18, userId:
2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 9,
cmd: com.cloud.api.commands.DeployVMCmd, cmdOriginator: null, cmdInfo:
{"id":"9","response":"json","templateId":"57dca056-e5b4-4700-9504-6d55244da2f3","sessionkey":"I97AO2LfG/sGVZ5XXOEKEDqkOEs\u003d","ctxUserId":"2","hypervisor":"XenServer","diskOfferingId":"187dd982-c911-4aee-ba42-52e9eea4f9ed","serviceOfferingId":"bce95fc6-ed64-40c1-90ba-6e4b54e1a947","_":"1338924800849","ctxAccountId":"2","ctxStartEventId":"77","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-05 12:33:35,968 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-5:job-18) Executing com.cloud.api.commands.DeployVMCmd for job-18
2012-06-05 12:33:36,034 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) 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-05 12:33:36,034 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-5:job-18) Successfully transitioned to start state for
VM[User|i-2-9-VM] reservation id = 7896dcab-126e-45e6-a998-9d0512f3ff74
2012-06-05 12:33:36,083 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-5:job-18) Trying to deploy VM, vm has dcId: 1 and podId: null
2012-06-05 12:33:36,083 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-5:job-18) Deploy avoids pods: null, clusters: null, hosts: null
2012-06-05 12:33:36,085 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) DeploymentPlanner allocation algorithm: random
2012-06-05 12:33:36,085 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
2012-06-05 12:33:36,085 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Is ROOT volume READY (pool already allocated)?: No
2012-06-05 12:33:36,085 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Searching all possible resources under this Zone: 1
2012-06-05 12:33:36,087 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Listing clusters in order of aggregate capacity, that
have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2012-06-05 12:33:36,087 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) CPUOverprovisioningFactor considered: 1.0
2012-06-05 12:33:36,094 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Checking resources in Cluster: 1 under Pod: 1
2012-06-05 12:33:36,094 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Calling HostAllocators to find suitable hosts
2012-06-05 12:33:36,094 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2012-06-05 12:33:36,096 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts
to check for allocation: [Host[-1-Routing]]
2012-06-05 12:33:36,098 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) Found 1 hosts for allocation
after prioritization: [Host[-1-Routing]]
2012-06-05 12:33:36,098 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) Looking for speed=1000Mhz,
Ram=1024
2012-06-05 12:33:36,100 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) Checking if host: 1 has enough
capacity for requested CPU: 1000 and requested RAM: 1073741824 ,
cpuOverprovisioningFactor: 1.0
2012-06-05 12:33:36,107 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) Hosts's actual total CPU: 3732
and CPU after applying overprovisioning: 3732
2012-06-05 12:33:36,108 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) Free CPU: 2732 , Requested
CPU: 1000
2012-06-05 12:33:36,108 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) Free RAM: 2432996416 ,
Requested RAM: 1073741824
2012-06-05 12:33:36,108 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) Host has enough CPU and RAM
available
2012-06-05 12:33:36,108 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 1, used: 1000, reserved: 0, actual total: 3732, total with
overprovisioning: 3732; requested cpu:1000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2012-06-05 12:33:36,108 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 1, used: 1342177280, reserved: 0, total: 3775173696; requested mem:
1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2012-06-05 12:33:36,108 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) Found a suitable host, adding
to list: 1
2012-06-05 12:33:36,108 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-5:job-18 FirstFitRoutingAllocator) Host Allocator returning 1
suitable hosts
2012-06-05 12:33:36,109 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Checking suitable pools for volume (Id, Type): (14,ROOT)
2012-06-05 12:33:36,110 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) We need to allocate new storagepool for this volume
2012-06-05 12:33:36,110 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Calling StoragePoolAllocators to find suitable pools
2012-06-05 12:33:36,111 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-5:job-18) Looking for pools in dc: 1 pod:1 cluster:1
2012-06-05 12:33:36,112 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-5:job-18) FirstFitStoragePoolAllocator has 1 pools to check for
allocation
2012-06-05 12:33:36,112 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-5:job-18) Checking if storage pool is suitable, name: LS_PRIMARY1
,poolId: 200
2012-06-05 12:33:36,112 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-5:job-18) Is localStorageAllocationNeeded? false
2012-06-05 12:33:36,112 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-5:job-18) Is storage pool shared? true
2012-06-05 12:33:36,113 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-5:job-18) Attempting to look for pool 200 for storage, totalSize:
104586543104, usedBytes: 6727925760, usedPct: 0.06432878992194824, disable
threshold: 0.85
2012-06-05 12:33:36,115 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-5:job-18) Attempting to look for pool 200 for storage, maxSize :
209173086208, totalAllocatedSize : 4860207616, askingSize : 21474836480,
allocated disable threshold: 0.85
2012-06-05 12:33:36,115 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-5:job-18) FirstFitStoragePoolAllocator returning 1 suitable
storage pools
2012-06-05 12:33:36,115 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Checking suitable pools for volume (Id, Type):
(15,DATADISK)
2012-06-05 12:33:36,115 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) We need to allocate new storagepool for this volume
2012-06-05 12:33:36,115 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Calling StoragePoolAllocators to find suitable pools
2012-06-05 12:33:36,116 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-5:job-18) Looking for pools in dc: 1 pod:1 cluster:1
2012-06-05 12:33:36,117 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-5:job-18) FirstFitStoragePoolAllocator has 1 pools to check for
allocation
2012-06-05 12:33:36,117 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-5:job-18) Checking if storage pool is suitable, name: LS_PRIMARY1
,poolId: 200
2012-06-05 12:33:36,117 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-5:job-18) Is localStorageAllocationNeeded? false
2012-06-05 12:33:36,117 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-5:job-18) Is storage pool shared? true
2012-06-05 12:33:36,118 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-5:job-18) Attempting to look for pool 200 for storage, totalSize:
104586543104, usedBytes: 6727925760, usedPct: 0.06432878992194824, disable
threshold: 0.85
2012-06-05 12:33:36,120 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-5:job-18) Attempting to look for pool 200 for storage, maxSize :
209173086208, totalAllocatedSize : 4860207616, askingSize : 21474836480,
allocated disable threshold: 0.85
2012-06-05 12:33:36,120 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-5:job-18) FirstFitStoragePoolAllocator returning 1 suitable
storage pools
2012-06-05 12:33:36,120 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Trying to find a potenial host and associated storage
pools from the suitable host/pool lists for this VM
2012-06-05 12:33:36,120 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Checking if host: 1 can access any suitable storage
pool for volume: ROOT
2012-06-05 12:33:36,121 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Host: 1 can access pool: 200
2012-06-05 12:33:36,121 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Checking if host: 1 can access any suitable storage
pool for volume: DATADISK
2012-06-05 12:33:36,122 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Host: 1 can access pool: 200
2012-06-05 12:33:36,123 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Found a potential host id: 1 name: xenserver1-cs and
associated storage pools for this VM
2012-06-05 12:33:36,124 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) 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(14|ROOT-->Pool(200),
Volume(15|DATADISK-->Pool(200))]
2012-06-05 12:33:36,124 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-5:job-18) Deployment found - P0=VM[User|i-2-9-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(14|ROOT-->Pool(200),
Volume(15|DATADISK-->Pool(200))]
2012-06-05 12:33:36,200 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) 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-05 12:33:36,205 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) Hosts's actual total CPU: 3732 and CPU after applying
overprovisioning: 3732
2012-06-05 12:33:36,206 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) We are allocating VM, increasing the used capacity of
this host:1
2012-06-05 12:33:36,206 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) Current Used CPU: 1000 , Free CPU:2732 ,Requested CPU:
1000
2012-06-05 12:33:36,206 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) Current Used RAM: 1342177280 , Free RAM:2432996416
,Requested RAM: 1073741824
2012-06-05 12:33:36,206 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) CPU STATS after allocation: for host: 1, old used:
1000, old reserved: 0, actual total: 3732, total with overprovisioning: 3732;
new used:2000, reserved:0; requested cpu:1000,alloc_from_last:false
2012-06-05 12:33:36,206 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) RAM STATS after allocation: for host: 1, old used:
1342177280, old reserved: 0, total: 3775173696; new used: 2415919104, reserved:
0; requested mem: 1073741824,alloc_from_last:false
2012-06-05 12:33:36,258 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-5:job-18) VM is being started in podId: 1
2012-06-05 12:33:36,261 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-5:job-18) Network id=204 is already implemented
2012-06-05 12:33:36,325 DEBUG [db.Transaction.Transaction]
(Job-Executor-5:job-18) Rolling back the transaction: Time = 1 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-05 12:33:36,325 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-5:job-18) Insufficient capacity
2012-06-05 12:33:36,384 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-5:job-18) Cleaning up resources for the vm VM[User|i-2-9-VM] in
Starting state
2012-06-05 12:33:36,386 DEBUG [agent.transport.Request] (Job-Executor-5:job-18)
Seq 1-1788414127: Sending { Cmd , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-9-VM","wait":0}}]
}
2012-06-05 12:33:36,386 DEBUG [agent.transport.Request] (Job-Executor-5:job-18)
Seq 1-1788414127: Executing: { Cmd , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-9-VM","wait":0}}]
}
2012-06-05 12:33:36,512 DEBUG [agent.transport.Request] (Job-Executor-5:job-18)
Seq 1-1788414127: Received: { Ans: , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 110, { StopAnswer } }
2012-06-05 12:33:36,512 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-5:job-18) Cleanup succeeded. Details VM does not exist
2012-06-05 12:33:36,695 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-5:job-18) Successfully cleanued up resources for the vm
VM[User|i-2-9-VM] in Starting state
2012-06-05 12:33:36,696 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) DeploymentPlanner allocation algorithm: random
2012-06-05 12:33:36,697 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
2012-06-05 12:33:36,697 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Is ROOT volume READY (pool already allocated)?: No
2012-06-05 12:33:36,697 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Searching all possible resources under this Zone: 1
2012-06-05 12:33:36,698 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Listing clusters in order of aggregate capacity, that
have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2012-06-05 12:33:36,699 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) CPUOverprovisioningFactor considered: 1.0
2012-06-05 12:33:36,704 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) 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
2012-06-05 12:33:36,704 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-5:job-18) Could not find suitable Deployment Destination for this
VM under any clusters, returning.
2012-06-05 12:33:36,804 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) 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-05 12:33:36,808 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) Hosts's actual total CPU: 3732 and CPU after applying
overprovisioning: 3732
2012-06-05 12:33:36,808 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) 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-05 12:33:36,808 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) release mem from host: 1, old used:
2415919104,reserved: 0, total: 3775173696; new used: 1342177280,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2012-06-05 12:33:36,956 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-5:job-18) 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-05 12:33:37,526 INFO [api.commands.DeployVMCmd]
(Job-Executor-5:job-18)
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-9-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2012-06-05 12:33:37,527 WARN [cloud.api.ApiDispatcher] (Job-Executor-5:job-18)
class com.cloud.api.ServerApiException : Unable to create a deployment for
VM[User|i-2-9-VM]
2012-06-05 12:33:37,527 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-5:job-18) Complete async job-18, jobStatus: 2, resultCode: 530,
result: com.cloud.api.response.ExceptionResponse@3031ef49
2012-06-05 12:33:41,078 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-13:null) Async job-18 completed
