You are viewing a plain text version of this content. The canonical link for it is here.

Posted to dev@cloudstack.apache.org by William Jiang <Wi...@manwin.com> on 2013/06/18 16:45:11 UTC

starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Hi,

We have a Ubuntu 12.04 VM with one disk on shared storage, it was working well before but now we saw the error of "unable to create a deployment for VM[user|i-2-107-VM]" during starting.
We saw this kind of issue happened on a windows server 2008 VM before.

In /var/log/cloud/management/management-server.log
We got following errors:

2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We need to allocate to the last host again, so checking if there is enough reserved capacity
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9 reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem: 1073741824
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Host does not have enough reserved CPU available, cannot allocate to this host.
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM does not have enough capacity
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM

Any ideas about this issue?

Thanks,
William
This e-mail may be privileged and/or confidential, and the sender does not waive any related rights and obligations. Any distribution, use or copying of this e-mail or the information it contains by other than an intended recipient is unauthorized. If you received this e-mail in error, please advise me (by return e-mail or otherwise) immediately. Ce courrier ?lectronique est confidentiel et prot?g?. L'exp?diteur ne renonce pas aux droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou copie de ce message ou des renseignements qu'il contient par une personne autre que le (les) destinataire(s) d?sign?(s) est interdite. Si vous recevez ce courrier ?lectronique par erreur, veuillez m'en aviser imm?diatement, par retour de courrier ?lectronique ou par un autre moyen.

Re: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Posted by Nitin Mehta <Ni...@citrix.com>.

The error seems to be somewhere between these logs. Are there more logs in
between these ones ? Also are you hitting it consistently ? Retry and also
check XS logs
 
8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04 (Manwin
EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics
":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121"
,"netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a
4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri"
:"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled"
:false}]},"wait":0}}] }
2013-06-14 12:28:49,113 DEBUG [agent.transport.Request]
(Job-Executor-16:job-626) Seq 9-1193017840: Executing:  { Cmd , MgmtId:
110492071566, via: 9, Ver: v1, Flags: 100111,
[{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub",
"type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824
,"arch":"x86_64","os":"Other Ubuntu
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse
":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"na
me":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b
-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePool
Type":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966b
e61006","deviceId":0},{"id":107,"name":"Ubuntu12.04 (Manwin
EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics
":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121"
,"netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a
4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri"
:"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled"
:false}]},"wait":0}}] }
2013-06-14 12:28:59,317 DEBUG [agent.transport.Request]
(Job-Executor-16:job-626) Seq 9-1193017840: Received:  { Ans: , MgmtId:
110492071566, via: 9, Ver: v1, Flags: 110, { StartAnswer } }
2013-06-14 12:28:59,318 WARN  [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-16:job-626) Cleanup failed due to Unable to start i-2-107-VM
due to
2013-06-14 12:28:59,321 INFO  [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-16:job-626) Unable to start VM on Host[-9-Routing] due to
Unable to start i-2-107-VM due to
2013-06-14 12:28:59,322 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-16:job-626) Cleaning up resources for the vm
VM[User|i-2-107-VM] in Starting state
2013-06-14 12:28:59,323 DEBUG [agent.transport.Request]
(Job-Executor-16:job-626) Seq 9-1193017841: Sending  { Cmd , MgmtId:
110492071566, via: 9, Ver: v1, Flags: 100111,
[{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
2013-06-14 12:28:59,323 DEBUG [agent.transport.Request]
(Job-Executor-16:job-626) Seq 9-1193017841: Executing:  { Cmd , MgmtId:
110492071566, via: 9, Ver: v1, Flags: 100111,
[{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
2013-06-14 12:28:59,747 DEBUG [agent.transport.Request]
(Job-Executor-16:job-626) Seq 9-1193017841: Received:  { Ans: , MgmtId:
110492071566, via: 9, Ver: v1, Flags: 110, { StopAnswer } }
2013-06-14 12:28:59,747 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-16:job-626) Cleanup succeeded. Details VM does not exist



On 19/06/13 9:07 PM, "William Jiang" <Wi...@manwin.com> wrote:

>Hi,
>There is no agent log on  management server /var/log/cloud/agent, do I
>need manually enable it ?
>
>Thanks,
>William
>
>-----Original Message-----
>From: Wei ZHOU [mailto:ustcweizhou@gmail.com]
>Sent: June-19-13 10:25 AM
>To: dev@cloudstack.apache.org
>Subject: Re: starting VM and get error of "unable to create a deployment
>for VM[user|i-2-107-VM]"
>
>William,
>
>There can be several seasons.
>Could you attach the agent.log?
>
>-Wei
>
>
>2013/6/19 William Jiang <Wi...@manwin.com>
>
>> Anybody has the same situation before ? Any comments or suggestions
>> will be great appreciated.
>>
>> Thanks,
>> William
>>
>>
>> -----Original Message-----
>> From: William Jiang [mailto:William.Jiang@manwin.com]
>> Sent: June-18-13 12:45 PM
>> To: dev@cloudstack.apache.org; users@cloudstack.apache.org
>> Subject: RE: starting VM and get error of "unable to create a
>> deployment for VM[user|i-2-107-VM]"
>>
>> Hi,
>> Ubuntu 12.04 does not fully supported by xenserver 6.0.2, but we have
>> some Ubuntu 12.04 work well, and we also saw same issue in one windows
>> server
>> 2008 R2 VM which is fully supported by hypervisor.
>>
>> The complete logs as following:
>>
>>
>> ######################################################################
>> ######################################################################
>> #############
>> 2013-06-14 12:28:34,328 DEBUG [cloud.async.AsyncJobManagerImpl]
>> (catalina-exec-18:null) submit async job-626, details: AsyncJobVO
>> {id:626,
>> userId: 2, accountId: 2, sessionKey: null, instanceType:
>> VirtualMachine,
>> instanceId: 107, cmd: com.cloud.api.commands.StartVMCmd, cmdOriginator:
>> null, cmdInfo:
>> {"id":"2d7d30a0-83d1-4050-a8dd-1b702fbb08e6","response":"json","sessio
>> nkey":"eihe8Buev1Ale+nhxw+w1nqQ\u003d","ctxUserId":"2","_":"1371227586
>> 576","ctxAccountId":"2","ctxStartEventId":"2584"},
>> cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
>> processStatus: 0, resultCode: 0, result: null, initMsid: 110492071566,
>> completeMsid: null, lastUpdated: null, lastPolled: null, created:
>> null}
>> 2013-06-14 12:28:34,331 DEBUG [cloud.async.AsyncJobManagerImpl]
>> (Job-Executor-16:job-626) Executing com.cloud.api.commands.StartVMCmd
>> for
>> job-626
>> 2013-06-14 12:28:34,349 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Service SecurityGroup is not supported in
>> the network id=214
>> 2013-06-14 12:28:34,353 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Service SecurityGroup is not supported in
>> the network id=214
>> 2013-06-14 12:28:34,355 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) VM state transitted from :Stopped to
>> Starting with event: StartRequestedvm's original host id: 9 new host
>> id: null host id before state transition: null
>> 2013-06-14 12:28:34,356 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Successfully transitioned to start state for
>> VM[User|i-2-107-VM] reservation id =
>> 3ee7e4d1-a732-4e6b-96d3-eb02caec4df3
>> 2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Trying to deploy VM, vm has dcId: 3 and
>> podId: 3
>> 2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Deploy avoids pods: null, clusters: null,
>>hosts:
>> null
>> 2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Root volume is ready, need to place VM in
>> volume's cluster
>> 2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing
>> deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId:
>> 3
>> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm:
>> random
>> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Trying to allocate a host and storage pools
>> from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram:
>> 1073741824
>> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Is ROOT volume READY (pool already
>>allocated)?:
>> Yes
>> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) This VM has last host_id specified, trying
>> to choose the same host: 9
>> 2013-06-14 12:28:34,361 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Checking if host: 9 has enough capacity for
>> requested CPU: 1000 and requested RAM: 1073741824 ,
>> cpuOverprovisioningFactor: 1.0
>> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU
>> after applying overprovisioning: 18616
>> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) We need to allocate to the last host again,
>> so checking if there is enough reserved capacity
>> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
>> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
>> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
>> reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
>> 1073741824
>> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Host does not have enough reserved CPU
>> available, cannot allocate to this host.
>> 2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) The last host of this VM does not have
>> enough capacity
>> 2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Cannot choose the last host to deploy this
>> VM
>> 2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Searching resources only under specified
>>Cluster:
>> 3
>> 2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod:
>> 3
>> 2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Calling HostAllocators to find suitable
>> hosts
>> 2013-06-14 12:28:34,366 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in
>>dc:
>> 3  pod:3  cluster:3
>> 2013-06-14 12:28:34,367 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator
>> has 1 hosts to check for allocation: [Host[-9-Routing]]
>> 2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for
>> allocation after prioritization: [Host[-9-Routing]]
>> 2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for
>> speed=1000Mhz, Ram=1024
>> 2013-06-14 12:28:34,369 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Checking if host: 9
>> has enough capacity for requested CPU: 1000 and requested RAM:
>> 1073741824 ,
>> cpuOverprovisioningFactor: 1.0
>> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Hosts's actual
>> total
>> CPU: 18616 and CPU after applying overprovisioning: 18616
>> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free CPU: 5116 ,
>> Requested CPU: 1000
>> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free RAM:
>> 27069551616 , Requested RAM: 1073741824
>> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host has enough CPU
>> and RAM available
>> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc
>> CPU from host: 9, used: 13500, reserved: 0, actual total: 18616, total
>> with
>> overprovisioning: 18616; requested
>> cpu:1000,alloc_from_last_host?:false
>> ,considerReservedCapacity?: true
>> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc
>> MEM from host: 9, used: 10066329600, reserved: 0, total: 37135881216;
>> requested
>> mem: 1073741824,alloc_from_last_host?:false
>> ,considerReservedCapacity?: true
>> 2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found a suitable
>> host, adding to list: 9
>> 2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator
>> returning
>> 1 suitable hosts
>> 2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Checking suitable pools for volume (Id, Type):
>> (129,ROOT)
>> 2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Volume is in READY state and has pool
>> already allocated, checking if pool can be reused, poolId: 203
>> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Planner need not allocate a pool for this
>> volume since its READY
>> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Trying to find a potenial host and
>> associated storage pools from the suitable host/pool lists for this VM
>> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Checking if host: 9 can access any suitable
>> storage pool for volume: ROOT
>> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Host: 9 can access pool: 203
>> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Found a potential host id: 9 name:
>> xenserver1.eu.manwin.local and associated storage pools for this VM
>> 2013-06-14 12:28:34,374 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Returning Deployment Destination:
>> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Po
>> ol(Id))]
>> : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
>> 2013-06-14 12:28:34,374 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Deployment found  - P0=VM[User|i-2-107-VM],
>> P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type--
>> >Pool(Id))]
>> : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
>> 2013-06-14 12:28:34,377 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) VM state transitted from :Starting to
>> Starting with event: OperationRetryvm's original host id: 9 new host
>> id: 9 host id before state transition: null
>> 2013-06-14 12:28:34,378 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) VM starting again on the last host it was
>> stopped on
>> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU
>> after applying overprovisioning: 18616
>> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) We are allocating VM, increasing the used
>> capacity of this host:9
>> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Current Used CPU: 13500 , Free CPU:5116
>> ,Requested CPU: 1000
>> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Current Used RAM: 10066329600 , Free
>> RAM:27069551616 ,Requested RAM: 1073741824
>> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) We are allocating VM to the last host again,
>> so adjusting the reserved capacity if it is not less than required
>> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
>> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
>> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) CPU STATS after allocation: for host: 9, old
>> used: 13500, old reserved: 0, actual total: 18616, total with
>> overprovisioning: 18616; new used:14500, reserved:0; requested
>> cpu:1000,alloc_from_last:true
>> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) RAM STATS after allocation: for host: 9, old
>> used: 10066329600, old reserved: 0, total: 37135881216; new used:
>> 11140071424, reserved: 0; requested mem:
>> 1073741824,alloc_from_last:true
>> 2013-06-14 12:28:34,382 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) VM is being started in podId: 3
>> 2013-06-14 12:28:34,384 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Network id=214 is already implemented
>> 2013-06-14 12:28:34,390 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Service SecurityGroup is not supported in
>> the network id=214
>> 2013-06-14 12:28:34,394 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Changing active number of nics for network
>> id=214 on 1
>> 2013-06-14 12:28:34,395 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Asking JuniperSRX to prepare for
>> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
>> 2013-06-14 12:28:34,397 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Asking Netscaler to prepare for
>> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
>> 2013-06-14 12:28:34,399 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Asking F5BigIp to prepare for
>> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
>> 2013-06-14 12:28:34,400 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Asking VirtualRouter to prepare for
>> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
>> 2013-06-14 12:28:34,406 DEBUG
>> [network.router.VirtualNetworkApplianceManagerImpl]
>> (Job-Executor-16:job-626) Starting a router for Ntwk[214|Guest|6] in
>> datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$74446509@3
>> 2013-06-14 12:28:34,415 DEBUG
>> [network.router.VirtualNetworkApplianceManagerImpl]
>> (Job-Executor-16:job-626) Applying dhcp entry in network
>> Ntwk[214|Guest|6]
>> 2013-06-14 12:28:34,423 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017838: Sending  { Cmd , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 100111,
>> 
>>[{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"
>>10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns"
>>:"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.net
>>work.type":"Basic","
>> router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
>> 2013-06-14 12:28:34,424 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017838: Executing:  { Cmd , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 100111,
>> 
>>[{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"
>>10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns"
>>:"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.net
>>work.type":"Basic","
>> router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
>> 2013-06-14 12:28:37,832 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017838: Received:  { Ans: , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
>> 2013-06-14 12:28:37,832 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Cleanup succeeded. Details null
>> 2013-06-14 12:28:37,839 DEBUG
>> [network.router.VirtualNetworkApplianceManagerImpl]
>> (Job-Executor-16:job-626) Applying userdata and password entry in
>> network Ntwk[214|Guest|6]
>> 2013-06-14 12:28:37,845 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017839: Sending  { Cmd , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 100111,
>> 
>>[{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1"
>>,"accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Ba
>>sic","router.ip":"169.254.3.42","
>> router.name":"r-102-VM"},"wait":0}}] }
>> 2013-06-14 12:28:37,846 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017839: Executing:  { Cmd , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 100111,
>> 
>>[{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1"
>>,"accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Ba
>>sic","router.ip":"169.254.3.42","
>> router.name":"r-102-VM"},"wait":0}}] }
>> 2013-06-14 12:28:49,101 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017839: Received:  { Ans: , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
>> 2013-06-14 12:28:49,101 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Cleanup succeeded. Details null
>> 2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Asking Ovs to prepare for
>> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
>> 2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Asking ExternalDhcpServer to prepare for
>> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
>> 2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Asking BareMetal to prepare for
>> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
>> 2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Asking SecurityGroupProvider to prepare for
>> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
>> 2013-06-14 12:28:49,105 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Service SecurityGroup is not supported in
>> the network id=214
>> 2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl]
>> (Job-Executor-16:job-626) Checking if we need to prepare 1 volumes for
>> VM[User|i-2-107-VM]
>> 2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl]
>> (Job-Executor-16:job-626) No need to recreate the volume:
>> Vol[129|vm=107|ROOT], since it already has a pool assigned: 203,
>> adding disk to VM
>> 2013-06-14 12:28:49,113 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017840: Sending  { Cmd , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 100111,
>> [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyG
>> rub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":
>> 1073741824,"arch":"x86_64","os":"Other
>> Ubuntu
>> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitC
>> puUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"i
>> d":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","
>> path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type"
>> :"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e
>> 77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubunt
>> u12.04
>> (Manwin
>> EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],
>> "nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10
>> .4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"0
>> 6:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"G
>> uest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged"
>> ,"isSecurityGroupEnabled":false}]},"wait":0}}]
>> }
>> 2013-06-14 12:28:49,113 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017840: Executing:  { Cmd , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 100111,
>> [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyG
>> rub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":
>> 1073741824,"arch":"x86_64","os":"Other
>> Ubuntu
>> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitC
>> puUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"i
>> d":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","
>> path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type"
>> :"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e
>> 77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubunt
>> u12.04
>> (Manwin
>> EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],
>> "nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10
>> .4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"0
>> 6:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"G
>> uest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged"
>> ,"isSecurityGroupEnabled":false}]},"wait":0}}]
>> }
>> 2013-06-14 12:28:59,317 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017840: Received:  { Ans: , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 110, { StartAnswer } }
>> 2013-06-14 12:28:59,318 WARN  [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Cleanup failed due to Unable to start
>> i-2-107-VM due to
>> 2013-06-14 12:28:59,321 INFO  [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Unable to start VM on Host[-9-Routing] due
>> to Unable to start i-2-107-VM due to
>> 2013-06-14 12:28:59,322 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Cleaning up resources for the vm
>> VM[User|i-2-107-VM] in Starting state
>> 2013-06-14 12:28:59,323 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017841: Sending  { Cmd , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 100111,
>> [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
>> 2013-06-14 12:28:59,323 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017841: Executing:  { Cmd , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 100111,
>> [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
>> 2013-06-14 12:28:59,747 DEBUG [agent.transport.Request]
>> (Job-Executor-16:job-626) Seq 9-1193017841: Received:  { Ans: , MgmtId:
>> 110492071566, via: 9, Ver: v1, Flags: 110, { StopAnswer } }
>> 2013-06-14 12:28:59,747 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Cleanup succeeded. Details VM does not exist
>> 2013-06-14 12:28:59,751 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Service SecurityGroup is not supported in
>> the network id=214
>> 2013-06-14 12:28:59,754 DEBUG [cloud.network.NetworkManagerImpl]
>> (Job-Executor-16:job-626) Changing active number of nics for network
>> id=214 on -1
>> 2013-06-14 12:28:59,755 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Successfully cleanued up resources for the
>> vm VM[User|i-2-107-VM] in Starting state
>> 2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Root volume is ready, need to place VM in
>> volume's cluster
>> 2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing
>> deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId:
>> 3
>> 2013-06-14 12:28:59,757 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm:
>> random
>> 2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Trying to allocate a host and storage pools
>> from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram:
>> 1073741824
>> 2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Is ROOT volume READY (pool already
>>allocated)?:
>> Yes
>> 2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) This VM has last host_id specified, trying
>> to choose the same host: 9
>> 2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) The last host of this VM is in avoid set
>> 2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Cannot choose the last host to deploy this
>> VM
>> 2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Searching resources only under specified
>>Cluster:
>> 3
>> 2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod:
>> 3
>> 2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Calling HostAllocators to find suitable
>> hosts
>> 2013-06-14 12:28:59,762 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in
>>dc:
>> 3  pod:3  cluster:3
>> 2013-06-14 12:28:59,763 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator
>> has 1 hosts to check for allocation: [Host[-9-Routing]]
>> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for
>> allocation after prioritization: [Host[-9-Routing]]
>> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for
>> speed=1000Mhz, Ram=1024
>> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host name:
>> xenserver1.eu.manwin.local, hostId: 9 is in avoid set, skipping this
>> and trying other available hosts
>> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
>> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator
>> returning
>> 0 suitable hosts
>> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) No suitable hosts found
>> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) No suitable hosts found under this Cluster:
>> 3
>> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Could not find suitable Deployment
>> Destination for this VM under any clusters, returning.
>> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm:
>> random
>> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Trying to allocate a host and storage pools
>> from dc:3, pod:3,cluster:null, requested cpu: 1000, requested ram:
>> 1073741824
>> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Is ROOT volume READY (pool already
>> allocated)?: No
>> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) This VM has last host_id specified, trying
>> to choose the same host: 9
>> 2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) The last host of this VM is in avoid set
>> 2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Cannot choose the last host to deploy this
>> VM
>> 2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Searching resources only under specified
>> Pod: 3
>> 2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Listing clusters in order of aggregate
>> capacity, that have (atleast one host with) enough CPU and RAM
>> capacity under this
>> Pod: 3
>> 2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) CPUOverprovisioningFactor considered: 1.0
>> 2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) Removing from the clusterId list these
>> clusters from avoid set: [3]
>> 2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner]
>> (Job-Executor-16:job-626) No clusters found after removing disabled
>> clusters and clusters in avoid list, returning.
>> 2013-06-14 12:28:59,773 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) VM state transitted from :Starting to
>> Stopped with event: OperationFailedvm's original host id: 9 new host
>> id: null host id before state transition: 9
>> 2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU
>> after applying overprovisioning: 18616
>> 2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) release cpu from host: 9, old used:
>> 14500,reserved: 0, actual total: 18616, total with overprovisioning:
>> 18616; new used: 13500,reserved:0; movedfromreserved:
>> false,moveToReserveredfalse
>> 2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl]
>> (Job-Executor-16:job-626) release mem from host: 9, old used:
>> 11140071424,reserved: 0, total: 37135881216; new used:
>> 10066329600,reserved:0; movedfromreserved: false,moveToReserveredfalse
>> 2013-06-14 12:28:59,779 INFO  [cloud.api.ApiDispatcher]
>> (Job-Executor-16:job-626) Unable to create a deployment for
>> VM[User|i-2-107-VM]
>> 2013-06-14 12:28:59,779 DEBUG [cloud.async.AsyncJobManagerImpl]
>> (Job-Executor-16:job-626) Complete async job-626, jobStatus: 2, 
>>resultCode:
>> 530, result: com.cloud.api.response.ExceptionResponse@23a1eaf3
>> 2013-06-14 12:29:04,397 DEBUG [cloud.async.AsyncJobManagerImpl]
>> (catalina-exec-21:null) Async job-626 completed
>> ######################################################################
>> ######################################################################
>> ################################################################
>>
>>
>> Great thanks,
>> William
>>
>>
>>
>> -----Original Message-----
>> From: Nitin Mehta [mailto:Nitin.Mehta@citrix.com]
>> Sent: June-18-13 12:02 PM
>> To: dev@cloudstack.apache.org; users@cloudstack.apache.org
>> Subject: Re: starting VM and get error of "unable to create a
>> deployment for VM[user|i-2-107-VM]"
>>
>> Can you check the hypervisor admin guide to see if this version of
>> guest os is supported ?
>> Also can u please paste the complete logs (grep for job-626 would work
>> as
>> well)
>>
>> On 18/06/13 8:15 PM, "William Jiang" <Wi...@manwin.com> wrote:
>>
>> >Hi,
>> >
>> >We have a Ubuntu 12.04 VM with one disk on shared storage, it was
>> >working well before but now we saw the error of "unable to create a
>> >deployment for VM[user|i-2-107-VM]" during starting.
>> >We saw this kind of issue happened on a windows server 2008 VM before.
>> >
>> >In /var/log/cloud/management/management-server.log
>> >We got following errors:
>> >
>> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> >(Job-Executor-16:job-626) We need to allocate to the last host again,
>> >so checking if there is enough reserved capacity
>> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> >(Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
>> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> >(Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
>> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> >(Job-Executor-16:job-626) STATS: Failed to alloc resource from host:
>> >9
>> >reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
>> >1073741824
>> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>> >(Job-Executor-16:job-626) Host does not have enough reserved CPU
>> >available, cannot allocate to this host.
>> >2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>> >(Job-Executor-16:job-626) The last host of this VM does not have
>> >enough capacity
>> >2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>> >(Job-Executor-16:job-626) Cannot choose the last host to deploy this
>> >VM
>> >
>> >Any ideas about this issue?
>> >
>> >Thanks,
>> >William
>> >This e-mail may be privileged and/or confidential, and the sender
>> >does not waive any related rights and obligations. Any distribution,
>> >use or copying of this e-mail or the information it contains by other
>> >than an intended recipient is unauthorized. If you received this
>> >e-mail in error, please advise me (by return e-mail or otherwise)
>> >immediately. Ce courrier ?lectronique est confidentiel et prot?g?.
>> >L'exp?diteur ne renonce pas aux droits et obligations qui s'y
>> >rapportent. Toute diffusion, utilisation ou copie de ce message ou
>> >des renseignements qu'il contient par une personne autre que le (les)
>> >destinataire(s)
>> >d?sign?(s) est interdite. Si vous recevez ce courrier ?lectronique
>> >par erreur, veuillez m'en aviser imm?diatement, par retour de
>> >courrier
>> ?lectronique ou par un autre moyen.
>>
>> This e-mail may be privileged and/or confidential, and the sender does
>> not waive any related rights and obligations. Any distribution, use or
>> copying of this e-mail or the information it contains by other than an
>> intended recipient is unauthorized. If you received this e-mail in
>> error, please advise me (by return e-mail or otherwise) immediately.
>> Ce courrier électronique est confidentiel et protégé. L'expéditeur ne
>> renonce pas aux droits et obligations qui s'y rapportent. Toute
>> diffusion, utilisation ou copie de ce message ou des renseignements
>> qu'il contient par une personne autre que le (les) destinataire(s)
>> désigné(s) est interdite. Si vous recevez ce courrier électronique par
>> erreur, veuillez m'en aviser immédiatement, par retour de courrier 
>>électronique ou par un autre moyen.
>> This e-mail may be privileged and/or confidential, and the sender does
>> not waive any related rights and obligations. Any distribution, use or
>> copying of this e-mail or the information it contains by other than an
>> intended recipient is unauthorized. If you received this e-mail in
>> error, please advise me (by return e-mail or otherwise) immediately.
>> Ce courrier électronique est confidentiel et protégé. L'expéditeur ne
>> renonce pas aux droits et obligations qui s'y rapportent. Toute
>> diffusion, utilisation ou copie de ce message ou des renseignements
>> qu'il contient par une personne autre que le (les) destinataire(s)
>> désigné(s) est interdite. Si vous recevez ce courrier électronique par
>> erreur, veuillez m'en aviser immédiatement, par retour de courrier 
>>électronique ou par un autre moyen.
>>
>This e-mail may be privileged and/or confidential, and the sender does 
>not waive any related rights and obligations. Any distribution, use or 
>copying of this e-mail or the information it contains by other than an 
>intended recipient is unauthorized. If you received this e-mail in error, 
>please advise me (by return e-mail or otherwise) immediately. Ce courrier 
>électronique est confidentiel et protégé. L'expéditeur ne renonce pas aux 
>droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou 
>copie de ce message ou des renseignements qu'il contient par une personne 
>autre que le (les) destinataire(s) désigné(s) est interdite. Si vous 
>recevez ce courrier électronique par erreur, veuillez m'en aviser 
>immédiatement, par retour de courrier électronique ou par un autre moyen.

RE: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Posted by William Jiang <Wi...@manwin.com>.

Hi,
There is no agent log on  management server /var/log/cloud/agent, do I need manually enable it ?

Thanks,
William

-----Original Message-----
From: Wei ZHOU [mailto:ustcweizhou@gmail.com]
Sent: June-19-13 10:25 AM
To: dev@cloudstack.apache.org
Subject: Re: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

William,

There can be several seasons.
Could you attach the agent.log?

-Wei


2013/6/19 William Jiang <Wi...@manwin.com>

> Anybody has the same situation before ? Any comments or suggestions
> will be great appreciated.
>
> Thanks,
> William
>
>
> -----Original Message-----
> From: William Jiang [mailto:William.Jiang@manwin.com]
> Sent: June-18-13 12:45 PM
> To: dev@cloudstack.apache.org; users@cloudstack.apache.org
> Subject: RE: starting VM and get error of "unable to create a
> deployment for VM[user|i-2-107-VM]"
>
> Hi,
> Ubuntu 12.04 does not fully supported by xenserver 6.0.2, but we have
> some Ubuntu 12.04 work well, and we also saw same issue in one windows
> server
> 2008 R2 VM which is fully supported by hypervisor.
>
> The complete logs as following:
>
>
> ######################################################################
> ######################################################################
> #############
> 2013-06-14 12:28:34,328 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-18:null) submit async job-626, details: AsyncJobVO
> {id:626,
> userId: 2, accountId: 2, sessionKey: null, instanceType:
> VirtualMachine,
> instanceId: 107, cmd: com.cloud.api.commands.StartVMCmd, cmdOriginator:
> null, cmdInfo:
> {"id":"2d7d30a0-83d1-4050-a8dd-1b702fbb08e6","response":"json","sessio
> nkey":"eihe8Buev1Ale+nhxw+w1nqQ\u003d","ctxUserId":"2","_":"1371227586
> 576","ctxAccountId":"2","ctxStartEventId":"2584"},
> cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
> processStatus: 0, resultCode: 0, result: null, initMsid: 110492071566,
> completeMsid: null, lastUpdated: null, lastPolled: null, created:
> null}
> 2013-06-14 12:28:34,331 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-16:job-626) Executing com.cloud.api.commands.StartVMCmd
> for
> job-626
> 2013-06-14 12:28:34,349 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Service SecurityGroup is not supported in
> the network id=214
> 2013-06-14 12:28:34,353 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Service SecurityGroup is not supported in
> the network id=214
> 2013-06-14 12:28:34,355 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) VM state transitted from :Stopped to
> Starting with event: StartRequestedvm's original host id: 9 new host
> id: null host id before state transition: null
> 2013-06-14 12:28:34,356 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Successfully transitioned to start state for
> VM[User|i-2-107-VM] reservation id =
> 3ee7e4d1-a732-4e6b-96d3-eb02caec4df3
> 2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Trying to deploy VM, vm has dcId: 3 and
> podId: 3
> 2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Deploy avoids pods: null, clusters: null, hosts:
> null
> 2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Root volume is ready, need to place VM in
> volume's cluster
> 2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing
> deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId:
> 3
> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm:
> random
> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Trying to allocate a host and storage pools
> from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram:
> 1073741824
> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?:
> Yes
> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) This VM has last host_id specified, trying
> to choose the same host: 9
> 2013-06-14 12:28:34,361 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Checking if host: 9 has enough capacity for
> requested CPU: 1000 and requested RAM: 1073741824 ,
> cpuOverprovisioningFactor: 1.0
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU
> after applying overprovisioning: 18616
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) We need to allocate to the last host again,
> so checking if there is enough reserved capacity
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
> reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
> 1073741824
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Host does not have enough reserved CPU
> available, cannot allocate to this host.
> 2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) The last host of this VM does not have
> enough capacity
> 2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Cannot choose the last host to deploy this
> VM
> 2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Searching resources only under specified Cluster:
> 3
> 2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod:
> 3
> 2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Calling HostAllocators to find suitable
> hosts
> 2013-06-14 12:28:34,366 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc:
> 3  pod:3  cluster:3
> 2013-06-14 12:28:34,367 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator
> has 1 hosts to check for allocation: [Host[-9-Routing]]
> 2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for
> allocation after prioritization: [Host[-9-Routing]]
> 2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for
> speed=1000Mhz, Ram=1024
> 2013-06-14 12:28:34,369 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Checking if host: 9
> has enough capacity for requested CPU: 1000 and requested RAM:
> 1073741824 ,
> cpuOverprovisioningFactor: 1.0
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Hosts's actual
> total
> CPU: 18616 and CPU after applying overprovisioning: 18616
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free CPU: 5116 ,
> Requested CPU: 1000
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free RAM:
> 27069551616 , Requested RAM: 1073741824
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host has enough CPU
> and RAM available
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc
> CPU from host: 9, used: 13500, reserved: 0, actual total: 18616, total
> with
> overprovisioning: 18616; requested
> cpu:1000,alloc_from_last_host?:false
> ,considerReservedCapacity?: true
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc
> MEM from host: 9, used: 10066329600, reserved: 0, total: 37135881216;
> requested
> mem: 1073741824,alloc_from_last_host?:false
> ,considerReservedCapacity?: true
> 2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found a suitable
> host, adding to list: 9
> 2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator
> returning
> 1 suitable hosts
> 2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Checking suitable pools for volume (Id, Type):
> (129,ROOT)
> 2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Volume is in READY state and has pool
> already allocated, checking if pool can be reused, poolId: 203
> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Planner need not allocate a pool for this
> volume since its READY
> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Trying to find a potenial host and
> associated storage pools from the suitable host/pool lists for this VM
> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Checking if host: 9 can access any suitable
> storage pool for volume: ROOT
> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Host: 9 can access pool: 203
> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Found a potential host id: 9 name:
> xenserver1.eu.manwin.local and associated storage pools for this VM
> 2013-06-14 12:28:34,374 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Returning Deployment Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Po
> ol(Id))]
> : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
> 2013-06-14 12:28:34,374 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Deployment found  - P0=VM[User|i-2-107-VM],
> P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type--
> >Pool(Id))]
> : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
> 2013-06-14 12:28:34,377 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) VM state transitted from :Starting to
> Starting with event: OperationRetryvm's original host id: 9 new host
> id: 9 host id before state transition: null
> 2013-06-14 12:28:34,378 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) VM starting again on the last host it was
> stopped on
> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU
> after applying overprovisioning: 18616
> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) We are allocating VM, increasing the used
> capacity of this host:9
> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Current Used CPU: 13500 , Free CPU:5116
> ,Requested CPU: 1000
> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Current Used RAM: 10066329600 , Free
> RAM:27069551616 ,Requested RAM: 1073741824
> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) We are allocating VM to the last host again,
> so adjusting the reserved capacity if it is not less than required
> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) CPU STATS after allocation: for host: 9, old
> used: 13500, old reserved: 0, actual total: 18616, total with
> overprovisioning: 18616; new used:14500, reserved:0; requested
> cpu:1000,alloc_from_last:true
> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) RAM STATS after allocation: for host: 9, old
> used: 10066329600, old reserved: 0, total: 37135881216; new used:
> 11140071424, reserved: 0; requested mem:
> 1073741824,alloc_from_last:true
> 2013-06-14 12:28:34,382 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) VM is being started in podId: 3
> 2013-06-14 12:28:34,384 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Network id=214 is already implemented
> 2013-06-14 12:28:34,390 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Service SecurityGroup is not supported in
> the network id=214
> 2013-06-14 12:28:34,394 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Changing active number of nics for network
> id=214 on 1
> 2013-06-14 12:28:34,395 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking JuniperSRX to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:34,397 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking Netscaler to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:34,399 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking F5BigIp to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:34,400 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking VirtualRouter to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:34,406 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-16:job-626) Starting a router for Ntwk[214|Guest|6] in
> datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$74446509@3
> 2013-06-14 12:28:34,415 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-16:job-626) Applying dhcp entry in network
> Ntwk[214|Guest|6]
> 2013-06-14 12:28:34,423 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017838: Sending  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","
> router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
> 2013-06-14 12:28:34,424 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017838: Executing:  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","
> router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
> 2013-06-14 12:28:37,832 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017838: Received:  { Ans: , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
> 2013-06-14 12:28:37,832 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Cleanup succeeded. Details null
> 2013-06-14 12:28:37,839 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-16:job-626) Applying userdata and password entry in
> network Ntwk[214|Guest|6]
> 2013-06-14 12:28:37,845 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017839: Sending  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","
> router.name":"r-102-VM"},"wait":0}}] }
> 2013-06-14 12:28:37,846 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017839: Executing:  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","
> router.name":"r-102-VM"},"wait":0}}] }
> 2013-06-14 12:28:49,101 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017839: Received:  { Ans: , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
> 2013-06-14 12:28:49,101 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Cleanup succeeded. Details null
> 2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking Ovs to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking ExternalDhcpServer to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking BareMetal to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking SecurityGroupProvider to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:49,105 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Service SecurityGroup is not supported in
> the network id=214
> 2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-16:job-626) Checking if we need to prepare 1 volumes for
> VM[User|i-2-107-VM]
> 2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-16:job-626) No need to recreate the volume:
> Vol[129|vm=107|ROOT], since it already has a pool assigned: 203,
> adding disk to VM
> 2013-06-14 12:28:49,113 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017840: Sending  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyG
> rub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":
> 1073741824,"arch":"x86_64","os":"Other
> Ubuntu
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitC
> puUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"i
> d":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","
> path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type"
> :"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e
> 77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubunt
> u12.04
> (Manwin
> EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],
> "nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10
> .4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"0
> 6:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"G
> uest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged"
> ,"isSecurityGroupEnabled":false}]},"wait":0}}]
> }
> 2013-06-14 12:28:49,113 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017840: Executing:  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyG
> rub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":
> 1073741824,"arch":"x86_64","os":"Other
> Ubuntu
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitC
> puUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"i
> d":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","
> path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type"
> :"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e
> 77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubunt
> u12.04
> (Manwin
> EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],
> "nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10
> .4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"0
> 6:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"G
> uest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged"
> ,"isSecurityGroupEnabled":false}]},"wait":0}}]
> }
> 2013-06-14 12:28:59,317 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017840: Received:  { Ans: , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 110, { StartAnswer } }
> 2013-06-14 12:28:59,318 WARN  [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Cleanup failed due to Unable to start
> i-2-107-VM due to
> 2013-06-14 12:28:59,321 INFO  [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Unable to start VM on Host[-9-Routing] due
> to Unable to start i-2-107-VM due to
> 2013-06-14 12:28:59,322 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Cleaning up resources for the vm
> VM[User|i-2-107-VM] in Starting state
> 2013-06-14 12:28:59,323 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017841: Sending  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
> 2013-06-14 12:28:59,323 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017841: Executing:  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
> 2013-06-14 12:28:59,747 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017841: Received:  { Ans: , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 110, { StopAnswer } }
> 2013-06-14 12:28:59,747 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Cleanup succeeded. Details VM does not exist
> 2013-06-14 12:28:59,751 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Service SecurityGroup is not supported in
> the network id=214
> 2013-06-14 12:28:59,754 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Changing active number of nics for network
> id=214 on -1
> 2013-06-14 12:28:59,755 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Successfully cleanued up resources for the
> vm VM[User|i-2-107-VM] in Starting state
> 2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Root volume is ready, need to place VM in
> volume's cluster
> 2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing
> deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId:
> 3
> 2013-06-14 12:28:59,757 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm:
> random
> 2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Trying to allocate a host and storage pools
> from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram:
> 1073741824
> 2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?:
> Yes
> 2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) This VM has last host_id specified, trying
> to choose the same host: 9
> 2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) The last host of this VM is in avoid set
> 2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Cannot choose the last host to deploy this
> VM
> 2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Searching resources only under specified Cluster:
> 3
> 2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod:
> 3
> 2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Calling HostAllocators to find suitable
> hosts
> 2013-06-14 12:28:59,762 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc:
> 3  pod:3  cluster:3
> 2013-06-14 12:28:59,763 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator
> has 1 hosts to check for allocation: [Host[-9-Routing]]
> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for
> allocation after prioritization: [Host[-9-Routing]]
> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for
> speed=1000Mhz, Ram=1024
> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host name:
> xenserver1.eu.manwin.local, hostId: 9 is in avoid set, skipping this
> and trying other available hosts
> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator
> returning
> 0 suitable hosts
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) No suitable hosts found
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) No suitable hosts found under this Cluster:
> 3
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Could not find suitable Deployment
> Destination for this VM under any clusters, returning.
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm:
> random
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Trying to allocate a host and storage pools
> from dc:3, pod:3,cluster:null, requested cpu: 1000, requested ram:
> 1073741824
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Is ROOT volume READY (pool already
> allocated)?: No
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) This VM has last host_id specified, trying
> to choose the same host: 9
> 2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) The last host of this VM is in avoid set
> 2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Cannot choose the last host to deploy this
> VM
> 2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Searching resources only under specified
> Pod: 3
> 2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Listing clusters in order of aggregate
> capacity, that have (atleast one host with) enough CPU and RAM
> capacity under this
> Pod: 3
> 2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) CPUOverprovisioningFactor considered: 1.0
> 2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Removing from the clusterId list these
> clusters from avoid set: [3]
> 2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) No clusters found after removing disabled
> clusters and clusters in avoid list, returning.
> 2013-06-14 12:28:59,773 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) VM state transitted from :Starting to
> Stopped with event: OperationFailedvm's original host id: 9 new host
> id: null host id before state transition: 9
> 2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU
> after applying overprovisioning: 18616
> 2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) release cpu from host: 9, old used:
> 14500,reserved: 0, actual total: 18616, total with overprovisioning:
> 18616; new used: 13500,reserved:0; movedfromreserved:
> false,moveToReserveredfalse
> 2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) release mem from host: 9, old used:
> 11140071424,reserved: 0, total: 37135881216; new used:
> 10066329600,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-06-14 12:28:59,779 INFO  [cloud.api.ApiDispatcher]
> (Job-Executor-16:job-626) Unable to create a deployment for
> VM[User|i-2-107-VM]
> 2013-06-14 12:28:59,779 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-16:job-626) Complete async job-626, jobStatus: 2, resultCode:
> 530, result: com.cloud.api.response.ExceptionResponse@23a1eaf3
> 2013-06-14 12:29:04,397 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-21:null) Async job-626 completed
> ######################################################################
> ######################################################################
> ################################################################
>
>
> Great thanks,
> William
>
>
>
> -----Original Message-----
> From: Nitin Mehta [mailto:Nitin.Mehta@citrix.com]
> Sent: June-18-13 12:02 PM
> To: dev@cloudstack.apache.org; users@cloudstack.apache.org
> Subject: Re: starting VM and get error of "unable to create a
> deployment for VM[user|i-2-107-VM]"
>
> Can you check the hypervisor admin guide to see if this version of
> guest os is supported ?
> Also can u please paste the complete logs (grep for job-626 would work
> as
> well)
>
> On 18/06/13 8:15 PM, "William Jiang" <Wi...@manwin.com> wrote:
>
> >Hi,
> >
> >We have a Ubuntu 12.04 VM with one disk on shared storage, it was
> >working well before but now we saw the error of "unable to create a
> >deployment for VM[user|i-2-107-VM]" during starting.
> >We saw this kind of issue happened on a windows server 2008 VM before.
> >
> >In /var/log/cloud/management/management-server.log
> >We got following errors:
> >
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) We need to allocate to the last host again,
> >so checking if there is enough reserved capacity
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) STATS: Failed to alloc resource from host:
> >9
> >reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
> >1073741824
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) Host does not have enough reserved CPU
> >available, cannot allocate to this host.
> >2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> >(Job-Executor-16:job-626) The last host of this VM does not have
> >enough capacity
> >2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> >(Job-Executor-16:job-626) Cannot choose the last host to deploy this
> >VM
> >
> >Any ideas about this issue?
> >
> >Thanks,
> >William
> >This e-mail may be privileged and/or confidential, and the sender
> >does not waive any related rights and obligations. Any distribution,
> >use or copying of this e-mail or the information it contains by other
> >than an intended recipient is unauthorized. If you received this
> >e-mail in error, please advise me (by return e-mail or otherwise)
> >immediately. Ce courrier ?lectronique est confidentiel et prot?g?.
> >L'exp?diteur ne renonce pas aux droits et obligations qui s'y
> >rapportent. Toute diffusion, utilisation ou copie de ce message ou
> >des renseignements qu'il contient par une personne autre que le (les)
> >destinataire(s)
> >d?sign?(s) est interdite. Si vous recevez ce courrier ?lectronique
> >par erreur, veuillez m'en aviser imm?diatement, par retour de
> >courrier
> ?lectronique ou par un autre moyen.
>
> This e-mail may be privileged and/or confidential, and the sender does
> not waive any related rights and obligations. Any distribution, use or
> copying of this e-mail or the information it contains by other than an
> intended recipient is unauthorized. If you received this e-mail in
> error, please advise me (by return e-mail or otherwise) immediately.
> Ce courrier électronique est confidentiel et protégé. L'expéditeur ne
> renonce pas aux droits et obligations qui s'y rapportent. Toute
> diffusion, utilisation ou copie de ce message ou des renseignements
> qu'il contient par une personne autre que le (les) destinataire(s)
> désigné(s) est interdite. Si vous recevez ce courrier électronique par
> erreur, veuillez m'en aviser immédiatement, par retour de courrier électronique ou par un autre moyen.
> This e-mail may be privileged and/or confidential, and the sender does
> not waive any related rights and obligations. Any distribution, use or
> copying of this e-mail or the information it contains by other than an
> intended recipient is unauthorized. If you received this e-mail in
> error, please advise me (by return e-mail or otherwise) immediately.
> Ce courrier électronique est confidentiel et protégé. L'expéditeur ne
> renonce pas aux droits et obligations qui s'y rapportent. Toute
> diffusion, utilisation ou copie de ce message ou des renseignements
> qu'il contient par une personne autre que le (les) destinataire(s)
> désigné(s) est interdite. Si vous recevez ce courrier électronique par
> erreur, veuillez m'en aviser immédiatement, par retour de courrier électronique ou par un autre moyen.
>
This e-mail may be privileged and/or confidential, and the sender does not waive any related rights and obligations. Any distribution, use or copying of this e-mail or the information it contains by other than an intended recipient is unauthorized. If you received this e-mail in error, please advise me (by return e-mail or otherwise) immediately. Ce courrier électronique est confidentiel et protégé. L'expéditeur ne renonce pas aux droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou copie de ce message ou des renseignements qu'il contient par une personne autre que le (les) destinataire(s) désigné(s) est interdite. Si vous recevez ce courrier électronique par erreur, veuillez m'en aviser immédiatement, par retour de courrier électronique ou par un autre moyen.

Re: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Posted by Wei ZHOU <us...@gmail.com>.

William,

There can be several seasons.
Could you attach the agent.log?

-Wei


2013/6/19 William Jiang <Wi...@manwin.com>

> Anybody has the same situation before ? Any comments or suggestions will
> be great appreciated.
>
> Thanks,
> William
>
>
> -----Original Message-----
> From: William Jiang [mailto:William.Jiang@manwin.com]
> Sent: June-18-13 12:45 PM
> To: dev@cloudstack.apache.org; users@cloudstack.apache.org
> Subject: RE: starting VM and get error of "unable to create a deployment
> for VM[user|i-2-107-VM]"
>
> Hi,
> Ubuntu 12.04 does not fully supported by xenserver 6.0.2, but we have some
> Ubuntu 12.04 work well, and we also saw same issue in one windows server
> 2008 R2 VM which is fully supported by hypervisor.
>
> The complete logs as following:
>
>
> #########################################################################################################################################################
> 2013-06-14 12:28:34,328 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-18:null) submit async job-626, details: AsyncJobVO {id:626,
> userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine,
> instanceId: 107, cmd: com.cloud.api.commands.StartVMCmd, cmdOriginator:
> null, cmdInfo:
> {"id":"2d7d30a0-83d1-4050-a8dd-1b702fbb08e6","response":"json","sessionkey":"eihe8Buev1Ale+nhxw+w1nqQ\u003d","ctxUserId":"2","_":"1371227586576","ctxAccountId":"2","ctxStartEventId":"2584"},
> cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
> processStatus: 0, resultCode: 0, result: null, initMsid: 110492071566,
> completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2013-06-14 12:28:34,331 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-16:job-626) Executing com.cloud.api.commands.StartVMCmd for
> job-626
> 2013-06-14 12:28:34,349 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Service SecurityGroup is not supported in the
> network id=214
> 2013-06-14 12:28:34,353 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Service SecurityGroup is not supported in the
> network id=214
> 2013-06-14 12:28:34,355 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) VM state transitted from :Stopped to Starting
> with event: StartRequestedvm's original host id: 9 new host id: null host
> id before state transition: null
> 2013-06-14 12:28:34,356 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Successfully transitioned to start state for
> VM[User|i-2-107-VM] reservation id = 3ee7e4d1-a732-4e6b-96d3-eb02caec4df3
> 2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Trying to deploy VM, vm has dcId: 3 and podId: 3
> 2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Deploy avoids pods: null, clusters: null, hosts:
> null
> 2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Root volume is ready, need to place VM in
> volume's cluster
> 2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing
> deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 3
> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Trying to allocate a host and storage pools from
> dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram: 1073741824
> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?:
> Yes
> 2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) This VM has last host_id specified, trying to
> choose the same host: 9
> 2013-06-14 12:28:34,361 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Checking if host: 9 has enough capacity for
> requested CPU: 1000 and requested RAM: 1073741824 ,
> cpuOverprovisioningFactor: 1.0
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after
> applying overprovisioning: 18616
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) We need to allocate to the last host again, so
> checking if there is enough reserved capacity
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
> reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
> 1073741824
> 2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Host does not have enough reserved CPU available,
> cannot allocate to this host.
> 2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) The last host of this VM does not have enough
> capacity
> 2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
> 2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Searching resources only under specified Cluster:
> 3
> 2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod: 3
> 2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Calling HostAllocators to find suitable hosts
> 2013-06-14 12:28:34,366 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc:
> 3  pod:3  cluster:3
> 2013-06-14 12:28:34,367 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator has 1
> hosts to check for allocation: [Host[-9-Routing]]
> 2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for
> allocation after prioritization: [Host[-9-Routing]]
> 2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for
> speed=1000Mhz, Ram=1024
> 2013-06-14 12:28:34,369 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Checking if host: 9 has
> enough capacity for requested CPU: 1000 and requested RAM: 1073741824 ,
> cpuOverprovisioningFactor: 1.0
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Hosts's actual total
> CPU: 18616 and CPU after applying overprovisioning: 18616
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free CPU: 5116 ,
> Requested CPU: 1000
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free RAM: 27069551616 ,
> Requested RAM: 1073741824
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host has enough CPU and
> RAM available
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc CPU
> from host: 9, used: 13500, reserved: 0, actual total: 18616, total with
> overprovisioning: 18616; requested cpu:1000,alloc_from_last_host?:false
> ,considerReservedCapacity?: true
> 2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc MEM
> from host: 9, used: 10066329600, reserved: 0, total: 37135881216; requested
> mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found a suitable host,
> adding to list: 9
> 2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator returning
> 1 suitable hosts
> 2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Checking suitable pools for volume (Id, Type):
> (129,ROOT)
> 2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Volume is in READY state and has pool already
> allocated, checking if pool can be reused, poolId: 203
> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Planner need not allocate a pool for this volume
> since its READY
> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Trying to find a potenial host and associated
> storage pools from the suitable host/pool lists for this VM
> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Checking if host: 9 can access any suitable
> storage pool for volume: ROOT
> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Host: 9 can access pool: 203
> 2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Found a potential host id: 9 name:
> xenserver1.eu.manwin.local and associated storage pools for this VM
> 2013-06-14 12:28:34,374 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Returning Deployment Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
> 2013-06-14 12:28:34,374 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Deployment found  - P0=VM[User|i-2-107-VM],
> P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
> 2013-06-14 12:28:34,377 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) VM state transitted from :Starting to Starting
> with event: OperationRetryvm's original host id: 9 new host id: 9 host id
> before state transition: null
> 2013-06-14 12:28:34,378 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) VM starting again on the last host it was stopped
> on
> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after
> applying overprovisioning: 18616
> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) We are allocating VM, increasing the used
> capacity of this host:9
> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Current Used CPU: 13500 , Free CPU:5116
> ,Requested CPU: 1000
> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Current Used RAM: 10066329600 , Free
> RAM:27069551616 ,Requested RAM: 1073741824
> 2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) We are allocating VM to the last host again, so
> adjusting the reserved capacity if it is not less than required
> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) CPU STATS after allocation: for host: 9, old
> used: 13500, old reserved: 0, actual total: 18616, total with
> overprovisioning: 18616; new used:14500, reserved:0; requested
> cpu:1000,alloc_from_last:true
> 2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) RAM STATS after allocation: for host: 9, old
> used: 10066329600, old reserved: 0, total: 37135881216; new used:
> 11140071424, reserved: 0; requested mem: 1073741824,alloc_from_last:true
> 2013-06-14 12:28:34,382 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) VM is being started in podId: 3
> 2013-06-14 12:28:34,384 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Network id=214 is already implemented
> 2013-06-14 12:28:34,390 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Service SecurityGroup is not supported in the
> network id=214
> 2013-06-14 12:28:34,394 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Changing active number of nics for network id=214
> on 1
> 2013-06-14 12:28:34,395 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking JuniperSRX to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:34,397 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking Netscaler to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:34,399 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking F5BigIp to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:34,400 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking VirtualRouter to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:34,406 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-16:job-626) Starting a router for Ntwk[214|Guest|6] in
> datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$74446509@3
> 2013-06-14 12:28:34,415 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-16:job-626) Applying dhcp entry in network Ntwk[214|Guest|6]
> 2013-06-14 12:28:34,423 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017838: Sending  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","
> router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
> 2013-06-14 12:28:34,424 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017838: Executing:  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","
> router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
> 2013-06-14 12:28:37,832 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017838: Received:  { Ans: , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
> 2013-06-14 12:28:37,832 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Cleanup succeeded. Details null
> 2013-06-14 12:28:37,839 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-16:job-626) Applying userdata and password entry in network
> Ntwk[214|Guest|6]
> 2013-06-14 12:28:37,845 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017839: Sending  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","
> router.name":"r-102-VM"},"wait":0}}] }
> 2013-06-14 12:28:37,846 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017839: Executing:  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","
> router.name":"r-102-VM"},"wait":0}}] }
> 2013-06-14 12:28:49,101 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017839: Received:  { Ans: , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
> 2013-06-14 12:28:49,101 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Cleanup succeeded. Details null
> 2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking Ovs to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking ExternalDhcpServer to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking BareMetal to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Asking SecurityGroupProvider to prepare for
> Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
> 2013-06-14 12:28:49,105 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Service SecurityGroup is not supported in the
> network id=214
> 2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-16:job-626) Checking if we need to prepare 1 volumes for
> VM[User|i-2-107-VM]
> 2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-16:job-626) No need to recreate the volume:
> Vol[129|vm=107|ROOT], since it already has a pool assigned: 203, adding
> disk to VM
> 2013-06-14 12:28:49,113 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017840: Sending  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Other
> Ubuntu
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04
> (Manwin
> EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}]
> }
> 2013-06-14 12:28:49,113 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017840: Executing:  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Other
> Ubuntu
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04
> (Manwin
> EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}]
> }
> 2013-06-14 12:28:59,317 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017840: Received:  { Ans: , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 110, { StartAnswer } }
> 2013-06-14 12:28:59,318 WARN  [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Cleanup failed due to Unable to start i-2-107-VM
> due to
> 2013-06-14 12:28:59,321 INFO  [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Unable to start VM on Host[-9-Routing] due to
> Unable to start i-2-107-VM due to
> 2013-06-14 12:28:59,322 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Cleaning up resources for the vm
> VM[User|i-2-107-VM] in Starting state
> 2013-06-14 12:28:59,323 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017841: Sending  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
> 2013-06-14 12:28:59,323 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017841: Executing:  { Cmd , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 100111,
> [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
> 2013-06-14 12:28:59,747 DEBUG [agent.transport.Request]
> (Job-Executor-16:job-626) Seq 9-1193017841: Received:  { Ans: , MgmtId:
> 110492071566, via: 9, Ver: v1, Flags: 110, { StopAnswer } }
> 2013-06-14 12:28:59,747 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Cleanup succeeded. Details VM does not exist
> 2013-06-14 12:28:59,751 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Service SecurityGroup is not supported in the
> network id=214
> 2013-06-14 12:28:59,754 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-16:job-626) Changing active number of nics for network id=214
> on -1
> 2013-06-14 12:28:59,755 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Successfully cleanued up resources for the vm
> VM[User|i-2-107-VM] in Starting state
> 2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Root volume is ready, need to place VM in
> volume's cluster
> 2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing
> deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 3
> 2013-06-14 12:28:59,757 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
> 2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Trying to allocate a host and storage pools from
> dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram: 1073741824
> 2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?:
> Yes
> 2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) This VM has last host_id specified, trying to
> choose the same host: 9
> 2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) The last host of this VM is in avoid set
> 2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
> 2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Searching resources only under specified Cluster:
> 3
> 2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod: 3
> 2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Calling HostAllocators to find suitable hosts
> 2013-06-14 12:28:59,762 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc:
> 3  pod:3  cluster:3
> 2013-06-14 12:28:59,763 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator has 1
> hosts to check for allocation: [Host[-9-Routing]]
> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for
> allocation after prioritization: [Host[-9-Routing]]
> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for
> speed=1000Mhz, Ram=1024
> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host name:
> xenserver1.eu.manwin.local, hostId: 9 is in avoid set, skipping this and
> trying other available hosts
> 2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator returning
> 0 suitable hosts
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) No suitable hosts found
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) No suitable hosts found under this Cluster: 3
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Could not find suitable Deployment Destination
> for this VM under any clusters, returning.
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Trying to allocate a host and storage pools from
> dc:3, pod:3,cluster:null, requested cpu: 1000, requested ram: 1073741824
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: No
> 2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) This VM has last host_id specified, trying to
> choose the same host: 9
> 2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) The last host of this VM is in avoid set
> 2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
> 2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Searching resources only under specified Pod: 3
> 2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Listing clusters in order of aggregate capacity,
> that have (atleast one host with) enough CPU and RAM capacity under this
> Pod: 3
> 2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) CPUOverprovisioningFactor considered: 1.0
> 2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) Removing from the clusterId list these clusters
> from avoid set: [3]
> 2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-16:job-626) No clusters found after removing disabled
> clusters and clusters in avoid list, returning.
> 2013-06-14 12:28:59,773 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) VM state transitted from :Starting to Stopped
> with event: OperationFailedvm's original host id: 9 new host id: null host
> id before state transition: 9
> 2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after
> applying overprovisioning: 18616
> 2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) release cpu from host: 9, old used:
> 14500,reserved: 0, actual total: 18616, total with overprovisioning: 18616;
> new used: 13500,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-16:job-626) release mem from host: 9, old used:
> 11140071424,reserved: 0, total: 37135881216; new used:
> 10066329600,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-06-14 12:28:59,779 INFO  [cloud.api.ApiDispatcher]
> (Job-Executor-16:job-626) Unable to create a deployment for
> VM[User|i-2-107-VM]
> 2013-06-14 12:28:59,779 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-16:job-626) Complete async job-626, jobStatus: 2, resultCode:
> 530, result: com.cloud.api.response.ExceptionResponse@23a1eaf3
> 2013-06-14 12:29:04,397 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-21:null) Async job-626 completed
> ############################################################################################################################################################################################################
>
>
> Great thanks,
> William
>
>
>
> -----Original Message-----
> From: Nitin Mehta [mailto:Nitin.Mehta@citrix.com]
> Sent: June-18-13 12:02 PM
> To: dev@cloudstack.apache.org; users@cloudstack.apache.org
> Subject: Re: starting VM and get error of "unable to create a deployment
> for VM[user|i-2-107-VM]"
>
> Can you check the hypervisor admin guide to see if this version of guest
> os is supported ?
> Also can u please paste the complete logs (grep for job-626 would work as
> well)
>
> On 18/06/13 8:15 PM, "William Jiang" <Wi...@manwin.com> wrote:
>
> >Hi,
> >
> >We have a Ubuntu 12.04 VM with one disk on shared storage, it was
> >working well before but now we saw the error of "unable to create a
> >deployment for VM[user|i-2-107-VM]" during starting.
> >We saw this kind of issue happened on a windows server 2008 VM before.
> >
> >In /var/log/cloud/management/management-server.log
> >We got following errors:
> >
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) We need to allocate to the last host again,
> >so checking if there is enough reserved capacity
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
> >reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
> >1073741824
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) Host does not have enough reserved CPU
> >available, cannot allocate to this host.
> >2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> >(Job-Executor-16:job-626) The last host of this VM does not have enough
> >capacity
> >2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> >(Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
> >
> >Any ideas about this issue?
> >
> >Thanks,
> >William
> >This e-mail may be privileged and/or confidential, and the sender does
> >not waive any related rights and obligations. Any distribution, use or
> >copying of this e-mail or the information it contains by other than an
> >intended recipient is unauthorized. If you received this e-mail in
> >error, please advise me (by return e-mail or otherwise) immediately. Ce
> >courrier ?lectronique est confidentiel et prot?g?. L'exp?diteur ne
> >renonce pas aux droits et obligations qui s'y rapportent. Toute
> >diffusion, utilisation ou copie de ce message ou des renseignements
> >qu'il contient par une personne autre que le (les) destinataire(s)
> >d?sign?(s) est interdite. Si vous recevez ce courrier ?lectronique par
> >erreur, veuillez m'en aviser imm?diatement, par retour de courrier
> ?lectronique ou par un autre moyen.
>
> This e-mail may be privileged and/or confidential, and the sender does not
> waive any related rights and obligations. Any distribution, use or copying
> of this e-mail or the information it contains by other than an intended
> recipient is unauthorized. If you received this e-mail in error, please
> advise me (by return e-mail or otherwise) immediately. Ce courrier
> électronique est confidentiel et protégé. L'expéditeur ne renonce pas aux
> droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou
> copie de ce message ou des renseignements qu'il contient par une personne
> autre que le (les) destinataire(s) désigné(s) est interdite. Si vous
> recevez ce courrier électronique par erreur, veuillez m'en aviser
> immédiatement, par retour de courrier électronique ou par un autre moyen.
> This e-mail may be privileged and/or confidential, and the sender does not
> waive any related rights and obligations. Any distribution, use or copying
> of this e-mail or the information it contains by other than an intended
> recipient is unauthorized. If you received this e-mail in error, please
> advise me (by return e-mail or otherwise) immediately. Ce courrier
> électronique est confidentiel et protégé. L'expéditeur ne renonce pas aux
> droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou
> copie de ce message ou des renseignements qu'il contient par une personne
> autre que le (les) destinataire(s) désigné(s) est interdite. Si vous
> recevez ce courrier électronique par erreur, veuillez m'en aviser
> immédiatement, par retour de courrier électronique ou par un autre moyen.
>

RE: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Posted by William Jiang <Wi...@manwin.com>.

Anybody has the same situation before ? Any comments or suggestions will be great appreciated.

Thanks,
William

-----Original Message-----
From: William Jiang [mailto:William.Jiang@manwin.com]
Sent: June-18-13 12:45 PM
To: dev@cloudstack.apache.org; users@cloudstack.apache.org
Subject: RE: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Hi,
Ubuntu 12.04 does not fully supported by xenserver 6.0.2, but we have some Ubuntu 12.04 work well, and we also saw same issue in one windows server 2008 R2 VM which is fully supported by hypervisor.

The complete logs as following:

#########################################################################################################################################################
2013-06-14 12:28:34,328 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-18:null) submit async job-626, details: AsyncJobVO {id:626, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 107, cmd: com.cloud.api.commands.StartVMCmd, cmdOriginator: null, cmdInfo: {"id":"2d7d30a0-83d1-4050-a8dd-1b702fbb08e6","response":"json","sessionkey":"eihe8Buev1Ale+nhxw+w1nqQ\u003d","ctxUserId":"2","_":"1371227586576","ctxAccountId":"2","ctxStartEventId":"2584"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 110492071566, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-06-14 12:28:34,331 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-16:job-626) Executing com.cloud.api.commands.StartVMCmd for job-626
2013-06-14 12:28:34,349 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,353 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,355 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 9 new host id: null host id before state transition: null
2013-06-14 12:28:34,356 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Successfully transitioned to start state for VM[User|i-2-107-VM] reservation id = 3ee7e4d1-a732-4e6b-96d3-eb02caec4df3
2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Trying to deploy VM, vm has dcId: 3 and podId: 3
2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Deploy avoids pods: null, clusters: null, hosts: null
2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Root volume is ready, need to place VM in volume's cluster
2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 3
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: Yes
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:34,361 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Checking if host: 9 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We need to allocate to the last host again, so checking if there is enough reserved capacity
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9 reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem: 1073741824
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Host does not have enough reserved CPU available, cannot allocate to this host.
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM does not have enough capacity
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Cluster: 3
2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod: 3
2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Calling HostAllocators to find suitable hosts
2013-06-14 12:28:34,366 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc: 3  pod:3  cluster:3
2013-06-14 12:28:34,367 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-9-Routing]]
2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-9-Routing]]
2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2013-06-14 12:28:34,369 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Checking if host: 9 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free CPU: 5116 , Requested CPU: 1000
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free RAM: 27069551616 , Requested RAM: 1073741824
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 9, used: 13500, reserved: 0, actual total: 18616, total with overprovisioning: 18616; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 9, used: 10066329600, reserved: 0, total: 37135881216; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found a suitable host, adding to list: 9
2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking suitable pools for volume (Id, Type): (129,ROOT)
2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Volume is in READY state and has pool already allocated, checking if pool can be reused, poolId: 203
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Planner need not allocate a pool for this volume since its READY
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking if host: 9 can access any suitable storage pool for volume: ROOT
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Host: 9 can access pool: 203
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Found a potential host id: 9 name: xenserver1.eu.manwin.local and associated storage pools for this VM
2013-06-14 12:28:34,374 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
2013-06-14 12:28:34,374 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Deployment found  - P0=VM[User|i-2-107-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
2013-06-14 12:28:34,377 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 9 new host id: 9 host id before state transition: null
2013-06-14 12:28:34,378 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM starting again on the last host it was stopped on
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We are allocating VM, increasing the used capacity of this host:9
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Current Used CPU: 13500 , Free CPU:5116 ,Requested CPU: 1000
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Current Used RAM: 10066329600 , Free RAM:27069551616 ,Requested RAM: 1073741824
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) CPU STATS after allocation: for host: 9, old used: 13500, old reserved: 0, actual total: 18616, total with overprovisioning: 18616; new used:14500, reserved:0; requested cpu:1000,alloc_from_last:true
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) RAM STATS after allocation: for host: 9, old used: 10066329600, old reserved: 0, total: 37135881216; new used: 11140071424, reserved: 0; requested mem: 1073741824,alloc_from_last:true
2013-06-14 12:28:34,382 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) VM is being started in podId: 3
2013-06-14 12:28:34,384 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Network id=214 is already implemented
2013-06-14 12:28:34,390 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,394 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Changing active number of nics for network id=214 on 1
2013-06-14 12:28:34,395 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking JuniperSRX to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,397 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking Netscaler to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,399 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking F5BigIp to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,400 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking VirtualRouter to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,406 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Starting a router for Ntwk[214|Guest|6] in datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$74446509@3
2013-06-14 12:28:34,415 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Applying dhcp entry in network Ntwk[214|Guest|6]
2013-06-14 12:28:34,423 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
2013-06-14 12:28:34,424 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
2013-06-14 12:28:37,832 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
2013-06-14 12:28:37,832 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details null
2013-06-14 12:28:37,839 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Applying userdata and password entry in network Ntwk[214|Guest|6]
2013-06-14 12:28:37,845 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","router.name":"r-102-VM"},"wait":0}}] }
2013-06-14 12:28:37,846 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","router.name":"r-102-VM"},"wait":0}}] }
2013-06-14 12:28:49,101 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
2013-06-14 12:28:49,101 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details null
2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking Ovs to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking ExternalDhcpServer to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking BareMetal to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking SecurityGroupProvider to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,105 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-16:job-626) Checking if we need to prepare 1 volumes for VM[User|i-2-107-VM]
2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-16:job-626) No need to recreate the volume: Vol[129|vm=107|ROOT], since it already has a pool assigned: 203, adding disk to VM
2013-06-14 12:28:49,113 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Other Ubuntu (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04 (Manwin EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
2013-06-14 12:28:49,113 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Other Ubuntu (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04 (Manwin EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
2013-06-14 12:28:59,317 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { StartAnswer } }
2013-06-14 12:28:59,318 WARN  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup failed due to Unable to start i-2-107-VM due to
2013-06-14 12:28:59,321 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Unable to start VM on Host[-9-Routing] due to Unable to start i-2-107-VM due to
2013-06-14 12:28:59,322 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleaning up resources for the vm VM[User|i-2-107-VM] in Starting state
2013-06-14 12:28:59,323 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
2013-06-14 12:28:59,323 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
2013-06-14 12:28:59,747 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { StopAnswer } }
2013-06-14 12:28:59,747 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details VM does not exist
2013-06-14 12:28:59,751 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:59,754 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Changing active number of nics for network id=214 on -1
2013-06-14 12:28:59,755 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Successfully cleanued up resources for the vm VM[User|i-2-107-VM] in Starting state
2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Root volume is ready, need to place VM in volume's cluster
2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 3
2013-06-14 12:28:59,757 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: Yes
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM is in avoid set
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Cluster: 3
2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod: 3
2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Calling HostAllocators to find suitable hosts
2013-06-14 12:28:59,762 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc: 3  pod:3  cluster:3
2013-06-14 12:28:59,763 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-9-Routing]]
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-9-Routing]]
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host name: xenserver1.eu.manwin.local, hostId: 9 is in avoid set, skipping this and trying other available hosts
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No suitable hosts found
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No suitable hosts found under this Cluster: 3
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:null, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: No
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM is in avoid set
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Pod: 3
2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 3
2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) CPUOverprovisioningFactor considered: 1.0
2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Removing from the clusterId list these clusters from avoid set: [3]
2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2013-06-14 12:28:59,773 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 9 new host id: null host id before state transition: 9
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) release cpu from host: 9, old used: 14500,reserved: 0, actual total: 18616, total with overprovisioning: 18616; new used: 13500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) release mem from host: 9, old used: 11140071424,reserved: 0, total: 37135881216; new used: 10066329600,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-14 12:28:59,779 INFO  [cloud.api.ApiDispatcher] (Job-Executor-16:job-626) Unable to create a deployment for VM[User|i-2-107-VM]
2013-06-14 12:28:59,779 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-16:job-626) Complete async job-626, jobStatus: 2, resultCode: 530, result: com.cloud.api.response.ExceptionResponse@23a1eaf3
2013-06-14 12:29:04,397 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-21:null) Async job-626 completed ############################################################################################################################################################################################################

Great thanks,
William

-----Original Message-----
From: Nitin Mehta [mailto:Nitin.Mehta@citrix.com]
Sent: June-18-13 12:02 PM
To: dev@cloudstack.apache.org; users@cloudstack.apache.org
Subject: Re: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Can you check the hypervisor admin guide to see if this version of guest os is supported ?
Also can u please paste the complete logs (grep for job-626 would work as
well)

On 18/06/13 8:15 PM, "William Jiang" <Wi...@manwin.com> wrote:

>Hi,
>
>We have a Ubuntu 12.04 VM with one disk on shared storage, it was
>working well before but now we saw the error of "unable to create a
>deployment for VM[user|i-2-107-VM]" during starting.
>We saw this kind of issue happened on a windows server 2008 VM before.
>
>In /var/log/cloud/management/management-server.log
>We got following errors:
>
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) We need to allocate to the last host again,
>so checking if there is enough reserved capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
>reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
>1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Host does not have enough reserved CPU
>available, cannot allocate to this host.
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) The last host of this VM does not have enough
>capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
>
>Any ideas about this issue?
>
>Thanks,
>William
>This e-mail may be privileged and/or confidential, and the sender does
>not waive any related rights and obligations. Any distribution, use or
>copying of this e-mail or the information it contains by other than an
>intended recipient is unauthorized. If you received this e-mail in
>error, please advise me (by return e-mail or otherwise) immediately. Ce
>courrier ?lectronique est confidentiel et prot?g?. L'exp?diteur ne
>renonce pas aux droits et obligations qui s'y rapportent. Toute
>diffusion, utilisation ou copie de ce message ou des renseignements
>qu'il contient par une personne autre que le (les) destinataire(s)
>d?sign?(s) est interdite. Si vous recevez ce courrier ?lectronique par
>erreur, veuillez m'en aviser imm?diatement, par retour de courrier ?lectronique ou par un autre moyen.

This e-mail may be privileged and/or confidential, and the sender does not waive any related rights and obligations. Any distribution, use or copying of this e-mail or the information it contains by other than an intended recipient is unauthorized. If you received this e-mail in error, please advise me (by return e-mail or otherwise) immediately. Ce courrier électronique est confidentiel et protégé. L'expéditeur ne renonce pas aux droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou copie de ce message ou des renseignements qu'il contient par une personne autre que le (les) destinataire(s) désigné(s) est interdite. Si vous recevez ce courrier électronique par erreur, veuillez m'en aviser immédiatement, par retour de courrier électronique ou par un autre moyen.
This e-mail may be privileged and/or confidential, and the sender does not waive any related rights and obligations. Any distribution, use or copying of this e-mail or the information it contains by other than an intended recipient is unauthorized. If you received this e-mail in error, please advise me (by return e-mail or otherwise) immediately. Ce courrier électronique est confidentiel et protégé. L'expéditeur ne renonce pas aux droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou copie de ce message ou des renseignements qu'il contient par une personne autre que le (les) destinataire(s) désigné(s) est interdite. Si vous recevez ce courrier électronique par erreur, veuillez m'en aviser immédiatement, par retour de courrier électronique ou par un autre moyen.

RE: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Posted by William Jiang <Wi...@manwin.com>.

Anybody has the same situation before ? Any comments or suggestions will be great appreciated.

Thanks,
William

-----Original Message-----
From: William Jiang [mailto:William.Jiang@manwin.com]
Sent: June-18-13 12:45 PM
To: dev@cloudstack.apache.org; users@cloudstack.apache.org
Subject: RE: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Hi,
Ubuntu 12.04 does not fully supported by xenserver 6.0.2, but we have some Ubuntu 12.04 work well, and we also saw same issue in one windows server 2008 R2 VM which is fully supported by hypervisor.

The complete logs as following:

#########################################################################################################################################################
2013-06-14 12:28:34,328 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-18:null) submit async job-626, details: AsyncJobVO {id:626, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 107, cmd: com.cloud.api.commands.StartVMCmd, cmdOriginator: null, cmdInfo: {"id":"2d7d30a0-83d1-4050-a8dd-1b702fbb08e6","response":"json","sessionkey":"eihe8Buev1Ale+nhxw+w1nqQ\u003d","ctxUserId":"2","_":"1371227586576","ctxAccountId":"2","ctxStartEventId":"2584"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 110492071566, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-06-14 12:28:34,331 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-16:job-626) Executing com.cloud.api.commands.StartVMCmd for job-626
2013-06-14 12:28:34,349 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,353 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,355 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 9 new host id: null host id before state transition: null
2013-06-14 12:28:34,356 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Successfully transitioned to start state for VM[User|i-2-107-VM] reservation id = 3ee7e4d1-a732-4e6b-96d3-eb02caec4df3
2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Trying to deploy VM, vm has dcId: 3 and podId: 3
2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Deploy avoids pods: null, clusters: null, hosts: null
2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Root volume is ready, need to place VM in volume's cluster
2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 3
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: Yes
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:34,361 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Checking if host: 9 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We need to allocate to the last host again, so checking if there is enough reserved capacity
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9 reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem: 1073741824
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Host does not have enough reserved CPU available, cannot allocate to this host.
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM does not have enough capacity
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Cluster: 3
2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod: 3
2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Calling HostAllocators to find suitable hosts
2013-06-14 12:28:34,366 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc: 3  pod:3  cluster:3
2013-06-14 12:28:34,367 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-9-Routing]]
2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-9-Routing]]
2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2013-06-14 12:28:34,369 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Checking if host: 9 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free CPU: 5116 , Requested CPU: 1000
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free RAM: 27069551616 , Requested RAM: 1073741824
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 9, used: 13500, reserved: 0, actual total: 18616, total with overprovisioning: 18616; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 9, used: 10066329600, reserved: 0, total: 37135881216; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found a suitable host, adding to list: 9
2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking suitable pools for volume (Id, Type): (129,ROOT)
2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Volume is in READY state and has pool already allocated, checking if pool can be reused, poolId: 203
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Planner need not allocate a pool for this volume since its READY
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking if host: 9 can access any suitable storage pool for volume: ROOT
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Host: 9 can access pool: 203
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Found a potential host id: 9 name: xenserver1.eu.manwin.local and associated storage pools for this VM
2013-06-14 12:28:34,374 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
2013-06-14 12:28:34,374 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Deployment found  - P0=VM[User|i-2-107-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
2013-06-14 12:28:34,377 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 9 new host id: 9 host id before state transition: null
2013-06-14 12:28:34,378 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM starting again on the last host it was stopped on
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We are allocating VM, increasing the used capacity of this host:9
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Current Used CPU: 13500 , Free CPU:5116 ,Requested CPU: 1000
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Current Used RAM: 10066329600 , Free RAM:27069551616 ,Requested RAM: 1073741824
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) CPU STATS after allocation: for host: 9, old used: 13500, old reserved: 0, actual total: 18616, total with overprovisioning: 18616; new used:14500, reserved:0; requested cpu:1000,alloc_from_last:true
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) RAM STATS after allocation: for host: 9, old used: 10066329600, old reserved: 0, total: 37135881216; new used: 11140071424, reserved: 0; requested mem: 1073741824,alloc_from_last:true
2013-06-14 12:28:34,382 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) VM is being started in podId: 3
2013-06-14 12:28:34,384 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Network id=214 is already implemented
2013-06-14 12:28:34,390 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,394 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Changing active number of nics for network id=214 on 1
2013-06-14 12:28:34,395 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking JuniperSRX to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,397 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking Netscaler to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,399 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking F5BigIp to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,400 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking VirtualRouter to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,406 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Starting a router for Ntwk[214|Guest|6] in datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$74446509@3
2013-06-14 12:28:34,415 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Applying dhcp entry in network Ntwk[214|Guest|6]
2013-06-14 12:28:34,423 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
2013-06-14 12:28:34,424 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
2013-06-14 12:28:37,832 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
2013-06-14 12:28:37,832 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details null
2013-06-14 12:28:37,839 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Applying userdata and password entry in network Ntwk[214|Guest|6]
2013-06-14 12:28:37,845 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","router.name":"r-102-VM"},"wait":0}}] }
2013-06-14 12:28:37,846 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","router.name":"r-102-VM"},"wait":0}}] }
2013-06-14 12:28:49,101 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
2013-06-14 12:28:49,101 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details null
2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking Ovs to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking ExternalDhcpServer to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking BareMetal to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking SecurityGroupProvider to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,105 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-16:job-626) Checking if we need to prepare 1 volumes for VM[User|i-2-107-VM]
2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-16:job-626) No need to recreate the volume: Vol[129|vm=107|ROOT], since it already has a pool assigned: 203, adding disk to VM
2013-06-14 12:28:49,113 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Other Ubuntu (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04 (Manwin EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
2013-06-14 12:28:49,113 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Other Ubuntu (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04 (Manwin EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
2013-06-14 12:28:59,317 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { StartAnswer } }
2013-06-14 12:28:59,318 WARN  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup failed due to Unable to start i-2-107-VM due to
2013-06-14 12:28:59,321 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Unable to start VM on Host[-9-Routing] due to Unable to start i-2-107-VM due to
2013-06-14 12:28:59,322 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleaning up resources for the vm VM[User|i-2-107-VM] in Starting state
2013-06-14 12:28:59,323 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
2013-06-14 12:28:59,323 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
2013-06-14 12:28:59,747 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { StopAnswer } }
2013-06-14 12:28:59,747 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details VM does not exist
2013-06-14 12:28:59,751 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:59,754 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Changing active number of nics for network id=214 on -1
2013-06-14 12:28:59,755 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Successfully cleanued up resources for the vm VM[User|i-2-107-VM] in Starting state
2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Root volume is ready, need to place VM in volume's cluster
2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 3
2013-06-14 12:28:59,757 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: Yes
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM is in avoid set
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Cluster: 3
2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod: 3
2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Calling HostAllocators to find suitable hosts
2013-06-14 12:28:59,762 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc: 3  pod:3  cluster:3
2013-06-14 12:28:59,763 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-9-Routing]]
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-9-Routing]]
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host name: xenserver1.eu.manwin.local, hostId: 9 is in avoid set, skipping this and trying other available hosts
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No suitable hosts found
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No suitable hosts found under this Cluster: 3
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:null, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: No
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM is in avoid set
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Pod: 3
2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 3
2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) CPUOverprovisioningFactor considered: 1.0
2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Removing from the clusterId list these clusters from avoid set: [3]
2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2013-06-14 12:28:59,773 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 9 new host id: null host id before state transition: 9
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) release cpu from host: 9, old used: 14500,reserved: 0, actual total: 18616, total with overprovisioning: 18616; new used: 13500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) release mem from host: 9, old used: 11140071424,reserved: 0, total: 37135881216; new used: 10066329600,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-14 12:28:59,779 INFO  [cloud.api.ApiDispatcher] (Job-Executor-16:job-626) Unable to create a deployment for VM[User|i-2-107-VM]
2013-06-14 12:28:59,779 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-16:job-626) Complete async job-626, jobStatus: 2, resultCode: 530, result: com.cloud.api.response.ExceptionResponse@23a1eaf3
2013-06-14 12:29:04,397 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-21:null) Async job-626 completed ############################################################################################################################################################################################################

Great thanks,
William

-----Original Message-----
From: Nitin Mehta [mailto:Nitin.Mehta@citrix.com]
Sent: June-18-13 12:02 PM
To: dev@cloudstack.apache.org; users@cloudstack.apache.org
Subject: Re: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Can you check the hypervisor admin guide to see if this version of guest os is supported ?
Also can u please paste the complete logs (grep for job-626 would work as
well)

On 18/06/13 8:15 PM, "William Jiang" <Wi...@manwin.com> wrote:

>Hi,
>
>We have a Ubuntu 12.04 VM with one disk on shared storage, it was
>working well before but now we saw the error of "unable to create a
>deployment for VM[user|i-2-107-VM]" during starting.
>We saw this kind of issue happened on a windows server 2008 VM before.
>
>In /var/log/cloud/management/management-server.log
>We got following errors:
>
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) We need to allocate to the last host again,
>so checking if there is enough reserved capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
>reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
>1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Host does not have enough reserved CPU
>available, cannot allocate to this host.
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) The last host of this VM does not have enough
>capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
>
>Any ideas about this issue?
>
>Thanks,
>William
>This e-mail may be privileged and/or confidential, and the sender does
>not waive any related rights and obligations. Any distribution, use or
>copying of this e-mail or the information it contains by other than an
>intended recipient is unauthorized. If you received this e-mail in
>error, please advise me (by return e-mail or otherwise) immediately. Ce
>courrier ?lectronique est confidentiel et prot?g?. L'exp?diteur ne
>renonce pas aux droits et obligations qui s'y rapportent. Toute
>diffusion, utilisation ou copie de ce message ou des renseignements
>qu'il contient par une personne autre que le (les) destinataire(s)
>d?sign?(s) est interdite. Si vous recevez ce courrier ?lectronique par
>erreur, veuillez m'en aviser imm?diatement, par retour de courrier ?lectronique ou par un autre moyen.

This e-mail may be privileged and/or confidential, and the sender does not waive any related rights and obligations. Any distribution, use or copying of this e-mail or the information it contains by other than an intended recipient is unauthorized. If you received this e-mail in error, please advise me (by return e-mail or otherwise) immediately. Ce courrier électronique est confidentiel et protégé. L'expéditeur ne renonce pas aux droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou copie de ce message ou des renseignements qu'il contient par une personne autre que le (les) destinataire(s) désigné(s) est interdite. Si vous recevez ce courrier électronique par erreur, veuillez m'en aviser immédiatement, par retour de courrier électronique ou par un autre moyen.
This e-mail may be privileged and/or confidential, and the sender does not waive any related rights and obligations. Any distribution, use or copying of this e-mail or the information it contains by other than an intended recipient is unauthorized. If you received this e-mail in error, please advise me (by return e-mail or otherwise) immediately. Ce courrier électronique est confidentiel et protégé. L'expéditeur ne renonce pas aux droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou copie de ce message ou des renseignements qu'il contient par une personne autre que le (les) destinataire(s) désigné(s) est interdite. Si vous recevez ce courrier électronique par erreur, veuillez m'en aviser immédiatement, par retour de courrier électronique ou par un autre moyen.

RE: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Posted by William Jiang <Wi...@manwin.com>.

Hi Nitin,
Ubuntu 12.04 does not fully supported by xenserver 6.0.2, but we have some Ubuntu 12.04 work well, and we also saw same issue in one windows server 2008 R2 VM which is fully supported by hypervisor.

The complete logs as following:

#########################################################################################################################################################
2013-06-14 12:28:34,328 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-18:null) submit async job-626, details: AsyncJobVO {id:626, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 107, cmd: com.cloud.api.commands.StartVMCmd, cmdOriginator: null, cmdInfo: {"id":"2d7d30a0-83d1-4050-a8dd-1b702fbb08e6","response":"json","sessionkey":"eihe8Buev1Ale+nhxw+w1nqQ\u003d","ctxUserId":"2","_":"1371227586576","ctxAccountId":"2","ctxStartEventId":"2584"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 110492071566, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-06-14 12:28:34,331 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-16:job-626) Executing com.cloud.api.commands.StartVMCmd for job-626
2013-06-14 12:28:34,349 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,353 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,355 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 9 new host id: null host id before state transition: null
2013-06-14 12:28:34,356 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Successfully transitioned to start state for VM[User|i-2-107-VM] reservation id = 3ee7e4d1-a732-4e6b-96d3-eb02caec4df3
2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Trying to deploy VM, vm has dcId: 3 and podId: 3
2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Deploy avoids pods: null, clusters: null, hosts: null
2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Root volume is ready, need to place VM in volume's cluster
2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 3
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: Yes
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:34,361 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Checking if host: 9 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We need to allocate to the last host again, so checking if there is enough reserved capacity
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9 reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem: 1073741824
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Host does not have enough reserved CPU available, cannot allocate to this host.
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM does not have enough capacity
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Cluster: 3
2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod: 3
2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Calling HostAllocators to find suitable hosts
2013-06-14 12:28:34,366 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc: 3  pod:3  cluster:3
2013-06-14 12:28:34,367 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-9-Routing]]
2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-9-Routing]]
2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2013-06-14 12:28:34,369 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Checking if host: 9 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free CPU: 5116 , Requested CPU: 1000
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free RAM: 27069551616 , Requested RAM: 1073741824
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 9, used: 13500, reserved: 0, actual total: 18616, total with overprovisioning: 18616; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 9, used: 10066329600, reserved: 0, total: 37135881216; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found a suitable host, adding to list: 9
2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking suitable pools for volume (Id, Type): (129,ROOT)
2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Volume is in READY state and has pool already allocated, checking if pool can be reused, poolId: 203
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Planner need not allocate a pool for this volume since its READY
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking if host: 9 can access any suitable storage pool for volume: ROOT
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Host: 9 can access pool: 203
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Found a potential host id: 9 name: xenserver1.eu.manwin.local and associated storage pools for this VM
2013-06-14 12:28:34,374 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
2013-06-14 12:28:34,374 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Deployment found  - P0=VM[User|i-2-107-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
2013-06-14 12:28:34,377 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 9 new host id: 9 host id before state transition: null
2013-06-14 12:28:34,378 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM starting again on the last host it was stopped on
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We are allocating VM, increasing the used capacity of this host:9
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Current Used CPU: 13500 , Free CPU:5116 ,Requested CPU: 1000
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Current Used RAM: 10066329600 , Free RAM:27069551616 ,Requested RAM: 1073741824
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) CPU STATS after allocation: for host: 9, old used: 13500, old reserved: 0, actual total: 18616, total with overprovisioning: 18616; new used:14500, reserved:0; requested cpu:1000,alloc_from_last:true
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) RAM STATS after allocation: for host: 9, old used: 10066329600, old reserved: 0, total: 37135881216; new used: 11140071424, reserved: 0; requested mem: 1073741824,alloc_from_last:true
2013-06-14 12:28:34,382 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) VM is being started in podId: 3
2013-06-14 12:28:34,384 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Network id=214 is already implemented
2013-06-14 12:28:34,390 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,394 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Changing active number of nics for network id=214 on 1
2013-06-14 12:28:34,395 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking JuniperSRX to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,397 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking Netscaler to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,399 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking F5BigIp to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,400 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking VirtualRouter to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,406 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Starting a router for Ntwk[214|Guest|6] in datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$74446509@3
2013-06-14 12:28:34,415 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Applying dhcp entry in network Ntwk[214|Guest|6]
2013-06-14 12:28:34,423 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
2013-06-14 12:28:34,424 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
2013-06-14 12:28:37,832 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
2013-06-14 12:28:37,832 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details null
2013-06-14 12:28:37,839 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Applying userdata and password entry in network Ntwk[214|Guest|6]
2013-06-14 12:28:37,845 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","router.name":"r-102-VM"},"wait":0}}] }
2013-06-14 12:28:37,846 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","router.name":"r-102-VM"},"wait":0}}] }
2013-06-14 12:28:49,101 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
2013-06-14 12:28:49,101 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details null
2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking Ovs to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking ExternalDhcpServer to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking BareMetal to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking SecurityGroupProvider to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,105 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-16:job-626) Checking if we need to prepare 1 volumes for VM[User|i-2-107-VM]
2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-16:job-626) No need to recreate the volume: Vol[129|vm=107|ROOT], since it already has a pool assigned: 203, adding disk to VM
2013-06-14 12:28:49,113 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Other Ubuntu (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04 (Manwin EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
2013-06-14 12:28:49,113 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Other Ubuntu (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04 (Manwin EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
2013-06-14 12:28:59,317 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { StartAnswer } }
2013-06-14 12:28:59,318 WARN  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup failed due to Unable to start i-2-107-VM due to
2013-06-14 12:28:59,321 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Unable to start VM on Host[-9-Routing] due to Unable to start i-2-107-VM due to
2013-06-14 12:28:59,322 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleaning up resources for the vm VM[User|i-2-107-VM] in Starting state
2013-06-14 12:28:59,323 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
2013-06-14 12:28:59,323 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
2013-06-14 12:28:59,747 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { StopAnswer } }
2013-06-14 12:28:59,747 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details VM does not exist
2013-06-14 12:28:59,751 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:59,754 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Changing active number of nics for network id=214 on -1
2013-06-14 12:28:59,755 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Successfully cleanued up resources for the vm VM[User|i-2-107-VM] in Starting state
2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Root volume is ready, need to place VM in volume's cluster
2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 3
2013-06-14 12:28:59,757 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: Yes
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM is in avoid set
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Cluster: 3
2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod: 3
2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Calling HostAllocators to find suitable hosts
2013-06-14 12:28:59,762 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc: 3  pod:3  cluster:3
2013-06-14 12:28:59,763 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-9-Routing]]
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-9-Routing]]
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host name: xenserver1.eu.manwin.local, hostId: 9 is in avoid set, skipping this and trying other available hosts
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No suitable hosts found
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No suitable hosts found under this Cluster: 3
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:null, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: No
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM is in avoid set
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Pod: 3
2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 3
2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) CPUOverprovisioningFactor considered: 1.0
2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Removing from the clusterId list these clusters from avoid set: [3]
2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2013-06-14 12:28:59,773 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 9 new host id: null host id before state transition: 9
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) release cpu from host: 9, old used: 14500,reserved: 0, actual total: 18616, total with overprovisioning: 18616; new used: 13500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) release mem from host: 9, old used: 11140071424,reserved: 0, total: 37135881216; new used: 10066329600,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-14 12:28:59,779 INFO  [cloud.api.ApiDispatcher] (Job-Executor-16:job-626) Unable to create a deployment for VM[User|i-2-107-VM]
2013-06-14 12:28:59,779 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-16:job-626) Complete async job-626, jobStatus: 2, resultCode: 530, result: com.cloud.api.response.ExceptionResponse@23a1eaf3
2013-06-14 12:29:04,397 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-21:null) Async job-626 completed
############################################################################################################################################################################################################

Great thanks,
William

-----Original Message-----
From: Nitin Mehta [mailto:Nitin.Mehta@citrix.com]
Sent: June-18-13 12:02 PM
To: dev@cloudstack.apache.org; users@cloudstack.apache.org
Subject: Re: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Can you check the hypervisor admin guide to see if this version of guest os is supported ?
Also can u please paste the complete logs (grep for job-626 would work as
well)

On 18/06/13 8:15 PM, "William Jiang" <Wi...@manwin.com> wrote:

>Hi,
>
>We have a Ubuntu 12.04 VM with one disk on shared storage, it was
>working well before but now we saw the error of "unable to create a
>deployment for VM[user|i-2-107-VM]" during starting.
>We saw this kind of issue happened on a windows server 2008 VM before.
>
>In /var/log/cloud/management/management-server.log
>We got following errors:
>
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) We need to allocate to the last host again,
>so checking if there is enough reserved capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
>reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
>1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Host does not have enough reserved CPU
>available, cannot allocate to this host.
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) The last host of this VM does not have enough
>capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
>
>Any ideas about this issue?
>
>Thanks,
>William
>This e-mail may be privileged and/or confidential, and the sender does
>not waive any related rights and obligations. Any distribution, use or
>copying of this e-mail or the information it contains by other than an
>intended recipient is unauthorized. If you received this e-mail in
>error, please advise me (by return e-mail or otherwise) immediately. Ce
>courrier ?lectronique est confidentiel et prot?g?. L'exp?diteur ne
>renonce pas aux droits et obligations qui s'y rapportent. Toute
>diffusion, utilisation ou copie de ce message ou des renseignements
>qu'il contient par une personne autre que le (les) destinataire(s)
>d?sign?(s) est interdite. Si vous recevez ce courrier ?lectronique par
>erreur, veuillez m'en aviser imm?diatement, par retour de courrier ?lectronique ou par un autre moyen.

This e-mail may be privileged and/or confidential, and the sender does not waive any related rights and obligations. Any distribution, use or copying of this e-mail or the information it contains by other than an intended recipient is unauthorized. If you received this e-mail in error, please advise me (by return e-mail or otherwise) immediately. Ce courrier électronique est confidentiel et protégé. L'expéditeur ne renonce pas aux droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou copie de ce message ou des renseignements qu'il contient par une personne autre que le (les) destinataire(s) désigné(s) est interdite. Si vous recevez ce courrier électronique par erreur, veuillez m'en aviser immédiatement, par retour de courrier électronique ou par un autre moyen.

RE: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Posted by William Jiang <Wi...@manwin.com>.

Hi Nitin,
Ubuntu 12.04 does not fully supported by xenserver 6.0.2, but we have some Ubuntu 12.04 work well, and we also saw same issue in one windows server 2008 R2 VM which is fully supported by hypervisor.

The complete logs as following:

#########################################################################################################################################################
2013-06-14 12:28:34,328 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-18:null) submit async job-626, details: AsyncJobVO {id:626, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 107, cmd: com.cloud.api.commands.StartVMCmd, cmdOriginator: null, cmdInfo: {"id":"2d7d30a0-83d1-4050-a8dd-1b702fbb08e6","response":"json","sessionkey":"eihe8Buev1Ale+nhxw+w1nqQ\u003d","ctxUserId":"2","_":"1371227586576","ctxAccountId":"2","ctxStartEventId":"2584"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 110492071566, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-06-14 12:28:34,331 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-16:job-626) Executing com.cloud.api.commands.StartVMCmd for job-626
2013-06-14 12:28:34,349 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,353 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,355 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 9 new host id: null host id before state transition: null
2013-06-14 12:28:34,356 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Successfully transitioned to start state for VM[User|i-2-107-VM] reservation id = 3ee7e4d1-a732-4e6b-96d3-eb02caec4df3
2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Trying to deploy VM, vm has dcId: 3 and podId: 3
2013-06-14 12:28:34,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Deploy avoids pods: null, clusters: null, hosts: null
2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Root volume is ready, need to place VM in volume's cluster
2013-06-14 12:28:34,359 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 3
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: Yes
2013-06-14 12:28:34,360 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:34,361 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Checking if host: 9 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We need to allocate to the last host again, so checking if there is enough reserved capacity
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9 reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem: 1073741824
2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Host does not have enough reserved CPU available, cannot allocate to this host.
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM does not have enough capacity
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Cluster: 3
2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod: 3
2013-06-14 12:28:34,366 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Calling HostAllocators to find suitable hosts
2013-06-14 12:28:34,366 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc: 3  pod:3  cluster:3
2013-06-14 12:28:34,367 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-9-Routing]]
2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-9-Routing]]
2013-06-14 12:28:34,368 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2013-06-14 12:28:34,369 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Checking if host: 9 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free CPU: 5116 , Requested CPU: 1000
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Free RAM: 27069551616 , Requested RAM: 1073741824
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 9, used: 13500, reserved: 0, actual total: 18616, total with overprovisioning: 18616; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-14 12:28:34,371 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 9, used: 10066329600, reserved: 0, total: 37135881216; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found a suitable host, adding to list: 9
2013-06-14 12:28:34,371 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking suitable pools for volume (Id, Type): (129,ROOT)
2013-06-14 12:28:34,372 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Volume is in READY state and has pool already allocated, checking if pool can be reused, poolId: 203
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Planner need not allocate a pool for this volume since its READY
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking if host: 9 can access any suitable storage pool for volume: ROOT
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Host: 9 can access pool: 203
2013-06-14 12:28:34,373 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Found a potential host id: 9 name: xenserver1.eu.manwin.local and associated storage pools for this VM
2013-06-14 12:28:34,374 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
2013-06-14 12:28:34,374 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Deployment found  - P0=VM[User|i-2-107-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(3)-Pod(3)-Cluster(3)-Host(9)-Storage()]
2013-06-14 12:28:34,377 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 9 new host id: 9 host id before state transition: null
2013-06-14 12:28:34,378 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM starting again on the last host it was stopped on
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We are allocating VM, increasing the used capacity of this host:9
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Current Used CPU: 13500 , Free CPU:5116 ,Requested CPU: 1000
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Current Used RAM: 10066329600 , Free RAM:27069551616 ,Requested RAM: 1073741824
2013-06-14 12:28:34,380 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) CPU STATS after allocation: for host: 9, old used: 13500, old reserved: 0, actual total: 18616, total with overprovisioning: 18616; new used:14500, reserved:0; requested cpu:1000,alloc_from_last:true
2013-06-14 12:28:34,381 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) RAM STATS after allocation: for host: 9, old used: 10066329600, old reserved: 0, total: 37135881216; new used: 11140071424, reserved: 0; requested mem: 1073741824,alloc_from_last:true
2013-06-14 12:28:34,382 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) VM is being started in podId: 3
2013-06-14 12:28:34,384 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Network id=214 is already implemented
2013-06-14 12:28:34,390 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:34,394 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Changing active number of nics for network id=214 on 1
2013-06-14 12:28:34,395 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking JuniperSRX to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,397 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking Netscaler to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,399 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking F5BigIp to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,400 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking VirtualRouter to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:34,406 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Starting a router for Ntwk[214|Guest|6] in datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$74446509@3
2013-06-14 12:28:34,415 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Applying dhcp entry in network Ntwk[214|Guest|6]
2013-06-14 12:28:34,423 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
2013-06-14 12:28:34,424 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:48:2e:00:00:a4","vmIpAddress":"10.4.16.121","vmName":"ubuntu1","defaultRouter":"10.4.16.65","defaultDns":"10.4.16.123","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.name":"r-102-VM","router.ip":"169.254.3.42"},"wait":0}}] }
2013-06-14 12:28:37,832 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017838: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
2013-06-14 12:28:37,832 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details null
2013-06-14 12:28:37,839 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-16:job-626) Applying userdata and password entry in network Ntwk[214|Guest|6]
2013-06-14 12:28:37,845 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","router.name":"r-102-VM"},"wait":0}}] }
2013-06-14 12:28:37,846 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"routing.VmDataCommand":{"vmIpAddress":"10.4.16.121","vmName":"ubuntu1","accessDetails":{"router.guest.ip":"10.4.16.123","zone.network.type":"Basic","router.ip":"169.254.3.42","router.name":"r-102-VM"},"wait":0}}] }
2013-06-14 12:28:49,101 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017839: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { Answer } }
2013-06-14 12:28:49,101 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details null
2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking Ovs to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,101 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking ExternalDhcpServer to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking BareMetal to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,103 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Asking SecurityGroupProvider to prepare for Nic[171-107-3ee7e4d1-a732-4e6b-96d3-eb02caec4df3-10.4.16.121]
2013-06-14 12:28:49,105 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-16:job-626) Checking if we need to prepare 1 volumes for VM[User|i-2-107-VM]
2013-06-14 12:28:49,106 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-16:job-626) No need to recreate the volume: Vol[129|vm=107|ROOT], since it already has a pool assigned: 203, adding disk to VM
2013-06-14 12:28:49,113 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Other Ubuntu (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04 (Manwin EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
2013-06-14 12:28:49,113 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":107,"name":"i-2-107-VM","bootloader":"PyGrub","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Other Ubuntu (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"7660f3d82965a6c7","params":{},"disks":[{"id":129,"name":"ROOT-107","mountPoint":"/mnt/san3/cloudstack/primary","path":"860f603b-36cd-465f-b447-b6a924d690bf","size":16106127360,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7ec6e77f-76bb-3dca-a846-8b966be61006","deviceId":0},{"id":107,"name":"Ubuntu12.04 (Manwin EU)xxxx","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.4.16.121","netmask":"255.255.255.192","gateway":"10.4.16.65","mac":"06:48:2e:00:00:a4","dns1":"10.4.16.21","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
2013-06-14 12:28:59,317 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017840: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { StartAnswer } }
2013-06-14 12:28:59,318 WARN  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup failed due to Unable to start i-2-107-VM due to
2013-06-14 12:28:59,321 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Unable to start VM on Host[-9-Routing] due to Unable to start i-2-107-VM due to
2013-06-14 12:28:59,322 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleaning up resources for the vm VM[User|i-2-107-VM] in Starting state
2013-06-14 12:28:59,323 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Sending  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
2013-06-14 12:28:59,323 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Executing:  { Cmd , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-107-VM","wait":0}}] }
2013-06-14 12:28:59,747 DEBUG [agent.transport.Request] (Job-Executor-16:job-626) Seq 9-1193017841: Received:  { Ans: , MgmtId: 110492071566, via: 9, Ver: v1, Flags: 110, { StopAnswer } }
2013-06-14 12:28:59,747 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Cleanup succeeded. Details VM does not exist
2013-06-14 12:28:59,751 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Service SecurityGroup is not supported in the network id=214
2013-06-14 12:28:59,754 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-16:job-626) Changing active number of nics for network id=214 on -1
2013-06-14 12:28:59,755 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Successfully cleanued up resources for the vm VM[User|i-2-107-VM] in Starting state
2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Root volume is ready, need to place VM in volume's cluster
2013-06-14 12:28:59,757 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-16:job-626) Vol[129|vm=107|ROOT] is READY, changing deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 3
2013-06-14 12:28:59,757 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:3, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: Yes
2013-06-14 12:28:59,758 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM is in avoid set
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:59,759 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Cluster: 3
2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Checking resources in Cluster: 3 under Pod: 3
2013-06-14 12:28:59,762 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Calling HostAllocators to find suitable hosts
2013-06-14 12:28:59,762 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for hosts in dc: 3  pod:3  cluster:3
2013-06-14 12:28:59,763 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-9-Routing]]
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-9-Routing]]
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host name: xenserver1.eu.manwin.local, hostId: 9 is in avoid set, skipping this and trying other available hosts
2013-06-14 12:28:59,765 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-16:job-626 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No suitable hosts found
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No suitable hosts found under this Cluster: 3
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) DeploymentPlanner allocation algorithm: random
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:null, requested cpu: 1000, requested ram: 1073741824
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Is ROOT volume READY (pool already allocated)?: No
2013-06-14 12:28:59,765 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) This VM has last host_id specified, trying to choose the same host: 9
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) The last host of this VM is in avoid set
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
2013-06-14 12:28:59,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Searching resources only under specified Pod: 3
2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 3
2013-06-14 12:28:59,768 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) CPUOverprovisioningFactor considered: 1.0
2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) Removing from the clusterId list these clusters from avoid set: [3]
2013-06-14 12:28:59,770 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-16:job-626) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2013-06-14 12:28:59,773 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 9 new host id: null host id before state transition: 9
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) Hosts's actual total CPU: 18616 and CPU after applying overprovisioning: 18616
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) release cpu from host: 9, old used: 14500,reserved: 0, actual total: 18616, total with overprovisioning: 18616; new used: 13500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-14 12:28:59,775 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-16:job-626) release mem from host: 9, old used: 11140071424,reserved: 0, total: 37135881216; new used: 10066329600,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-14 12:28:59,779 INFO  [cloud.api.ApiDispatcher] (Job-Executor-16:job-626) Unable to create a deployment for VM[User|i-2-107-VM]
2013-06-14 12:28:59,779 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-16:job-626) Complete async job-626, jobStatus: 2, resultCode: 530, result: com.cloud.api.response.ExceptionResponse@23a1eaf3
2013-06-14 12:29:04,397 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-21:null) Async job-626 completed
############################################################################################################################################################################################################

Great thanks,
William

-----Original Message-----
From: Nitin Mehta [mailto:Nitin.Mehta@citrix.com]
Sent: June-18-13 12:02 PM
To: dev@cloudstack.apache.org; users@cloudstack.apache.org
Subject: Re: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Can you check the hypervisor admin guide to see if this version of guest os is supported ?
Also can u please paste the complete logs (grep for job-626 would work as
well)

On 18/06/13 8:15 PM, "William Jiang" <Wi...@manwin.com> wrote:

>Hi,
>
>We have a Ubuntu 12.04 VM with one disk on shared storage, it was
>working well before but now we saw the error of "unable to create a
>deployment for VM[user|i-2-107-VM]" during starting.
>We saw this kind of issue happened on a windows server 2008 VM before.
>
>In /var/log/cloud/management/management-server.log
>We got following errors:
>
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) We need to allocate to the last host again,
>so checking if there is enough reserved capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
>reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
>1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Host does not have enough reserved CPU
>available, cannot allocate to this host.
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) The last host of this VM does not have enough
>capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
>
>Any ideas about this issue?
>
>Thanks,
>William
>This e-mail may be privileged and/or confidential, and the sender does
>not waive any related rights and obligations. Any distribution, use or
>copying of this e-mail or the information it contains by other than an
>intended recipient is unauthorized. If you received this e-mail in
>error, please advise me (by return e-mail or otherwise) immediately. Ce
>courrier ?lectronique est confidentiel et prot?g?. L'exp?diteur ne
>renonce pas aux droits et obligations qui s'y rapportent. Toute
>diffusion, utilisation ou copie de ce message ou des renseignements
>qu'il contient par une personne autre que le (les) destinataire(s)
>d?sign?(s) est interdite. Si vous recevez ce courrier ?lectronique par
>erreur, veuillez m'en aviser imm?diatement, par retour de courrier ?lectronique ou par un autre moyen.

This e-mail may be privileged and/or confidential, and the sender does not waive any related rights and obligations. Any distribution, use or copying of this e-mail or the information it contains by other than an intended recipient is unauthorized. If you received this e-mail in error, please advise me (by return e-mail or otherwise) immediately. Ce courrier électronique est confidentiel et protégé. L'expéditeur ne renonce pas aux droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou copie de ce message ou des renseignements qu'il contient par une personne autre que le (les) destinataire(s) désigné(s) est interdite. Si vous recevez ce courrier électronique par erreur, veuillez m'en aviser immédiatement, par retour de courrier électronique ou par un autre moyen.

Re: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Posted by tawfiq zidi <ta...@gmail.com>.

Can you specify the host Type and it's availabilty status  ?


On Tue, Jun 18, 2013 at 5:01 PM, Nitin Mehta <Ni...@citrix.com> wrote:

> Can you check the hypervisor admin guide to see if this version of guest
> os is supported ?
> Also can u please paste the complete logs (grep for job-626 would work as
> well)
>
> On 18/06/13 8:15 PM, "William Jiang" <Wi...@manwin.com> wrote:
>
> >Hi,
> >
> >We have a Ubuntu 12.04 VM with one disk on shared storage, it was working
> >well before but now we saw the error of "unable to create a deployment
> >for VM[user|i-2-107-VM]" during starting.
> >We saw this kind of issue happened on a windows server 2008 VM before.
> >
> >In /var/log/cloud/management/management-server.log
> >We got following errors:
> >
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) We need to allocate to the last host again, so
> >checking if there is enough reserved capacity
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
> >reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
> >1073741824
> >2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
> >(Job-Executor-16:job-626) Host does not have enough reserved CPU
> >available, cannot allocate to this host.
> >2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> >(Job-Executor-16:job-626) The last host of this VM does not have enough
> >capacity
> >2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
> >(Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
> >
> >Any ideas about this issue?
> >
> >Thanks,
> >William
> >This e-mail may be privileged and/or confidential, and the sender does
> >not waive any related rights and obligations. Any distribution, use or
> >copying of this e-mail or the information it contains by other than an
> >intended recipient is unauthorized. If you received this e-mail in error,
> >please advise me (by return e-mail or otherwise) immediately. Ce courrier
> >?lectronique est confidentiel et prot?g?. L'exp?diteur ne renonce pas aux
> >droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou
> >copie de ce message ou des renseignements qu'il contient par une personne
> >autre que le (les) destinataire(s) d?sign?(s) est interdite. Si vous
> >recevez ce courrier ?lectronique par erreur, veuillez m'en aviser
> >imm?diatement, par retour de courrier ?lectronique ou par un autre moyen.
>
>

Re: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Posted by Nitin Mehta <Ni...@citrix.com>.

Can you check the hypervisor admin guide to see if this version of guest
os is supported ?
Also can u please paste the complete logs (grep for job-626 would work as
well) 

On 18/06/13 8:15 PM, "William Jiang" <Wi...@manwin.com> wrote:

>Hi,
>
>We have a Ubuntu 12.04 VM with one disk on shared storage, it was working
>well before but now we saw the error of "unable to create a deployment
>for VM[user|i-2-107-VM]" during starting.
>We saw this kind of issue happened on a windows server 2008 VM before.
>
>In /var/log/cloud/management/management-server.log
>We got following errors:
>
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) We need to allocate to the last host again, so
>checking if there is enough reserved capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
>reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
>1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Host does not have enough reserved CPU
>available, cannot allocate to this host.
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) The last host of this VM does not have enough
>capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
>
>Any ideas about this issue?
>
>Thanks,
>William
>This e-mail may be privileged and/or confidential, and the sender does
>not waive any related rights and obligations. Any distribution, use or
>copying of this e-mail or the information it contains by other than an
>intended recipient is unauthorized. If you received this e-mail in error,
>please advise me (by return e-mail or otherwise) immediately. Ce courrier
>?lectronique est confidentiel et prot?g?. L'exp?diteur ne renonce pas aux
>droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou
>copie de ce message ou des renseignements qu'il contient par une personne
>autre que le (les) destinataire(s) d?sign?(s) est interdite. Si vous
>recevez ce courrier ?lectronique par erreur, veuillez m'en aviser
>imm?diatement, par retour de courrier ?lectronique ou par un autre moyen.

Re: starting VM and get error of "unable to create a deployment for VM[user|i-2-107-VM]"

Posted by Nitin Mehta <Ni...@citrix.com>.

Can you check the hypervisor admin guide to see if this version of guest
os is supported ?
Also can u please paste the complete logs (grep for job-626 would work as
well) 

On 18/06/13 8:15 PM, "William Jiang" <Wi...@manwin.com> wrote:

>Hi,
>
>We have a Ubuntu 12.04 VM with one disk on shared storage, it was working
>well before but now we saw the error of "unable to create a deployment
>for VM[user|i-2-107-VM]" during starting.
>We saw this kind of issue happened on a windows server 2008 VM before.
>
>In /var/log/cloud/management/management-server.log
>We got following errors:
>
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) We need to allocate to the last host again, so
>checking if there is enough reserved capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved CPU: 0 , Requested CPU: 1000
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Reserved RAM: 0 , Requested RAM: 1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) STATS: Failed to alloc resource from host: 9
>reservedCpu: 0, requested cpu: 1000, reservedMem: 0, requested mem:
>1073741824
>2013-06-14 12:28:34,362 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-16:job-626) Host does not have enough reserved CPU
>available, cannot allocate to this host.
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) The last host of this VM does not have enough
>capacity
>2013-06-14 12:28:34,362 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-16:job-626) Cannot choose the last host to deploy this VM
>
>Any ideas about this issue?
>
>Thanks,
>William
>This e-mail may be privileged and/or confidential, and the sender does
>not waive any related rights and obligations. Any distribution, use or
>copying of this e-mail or the information it contains by other than an
>intended recipient is unauthorized. If you received this e-mail in error,
>please advise me (by return e-mail or otherwise) immediately. Ce courrier
>?lectronique est confidentiel et prot?g?. L'exp?diteur ne renonce pas aux
>droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou
>copie de ce message ou des renseignements qu'il contient par une personne
>autre que le (les) destinataire(s) d?sign?(s) est interdite. Si vous
>recevez ce courrier ?lectronique par erreur, veuillez m'en aviser
>imm?diatement, par retour de courrier ?lectronique ou par un autre moyen.