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

Posted to users@cloudstack.apache.org by 不坏阿峰 <on...@gmail.com> on 2013/08/22 19:51:32 UTC

Fail to create Instance in VPC on CS4.1.1

cs-mgt��
eth1: 192.168.230.2

xen01:
eth1: 192.168.230.11
eth2: public+guest   (guest network:192.168.30.0/24  )
eth3: 192.168.250.11

xen01:
eth1: 192.168.230.12
eth2: public+guest  (guest network:192.168.30.0/24  )
eth3: 192.168.250.12

Adv net, can work.

I want to try VPC ,i have create VPC network 172.16.0.0/16 and tier
172.16.0.1/24.   tier network ACLs   ingress, egress TCP/UDP all
allowed configed

VPC router have started and i check from console , it can access
internet and can access storage and cs.

but fail to create vm in tier of VPC.

#############   LOG #############################
2013-08-23 00:30:29,544 DEBUG [cloud.api.ApiServlet]
(catalina-exec-17:null) ===START===  192.168.123.28 -- GET
command=deployVirtualMachine&zoneId=6ad1fb5e-8a4b-42b7-83f2-863c1b3fda4a&templateId=bd1a8e6a-b66f-4484-afcb-2af22890cff6&hypervisor=XenServer&serviceOfferingId=fbf29251-423f-496c-8edb-32b9362c31ab&networkIds=d277c139-f896-443a-a8cc-c74dcb5f92df&response=json&sessionkey=c%2FLK7Wzuq4ia5cxurIMYWevCUkM%3D&_=1377192613840
2013-08-23 00:30:29,554 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-17:null) InfrastructureEntity name
is:com.cloud.offering.ServiceOffering
2013-08-23 00:30:29,556 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-17:null) ControlledEntity name
is:com.cloud.template.VirtualMachineTemplate
2013-08-23 00:30:29,560 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-17:null) ControlledEntity name
is:com.cloud.network.Network
2013-08-23 00:30:29,574 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-17:null) Service SecurityGroup is not supported in the
network id=207
2013-08-23 00:30:29,584 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-17:null) Allocating in the DB for vm
2013-08-23 00:30:29,599 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-17:null) Allocating entries for VM:
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
2013-08-23 00:30:29,600 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-17:null) Allocating nics for
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
2013-08-23 00:30:29,601 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-17:null) Allocating nic for vm
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in network
Ntwk[207|Guest|11] with requested profile
NicProfile[0-0-null-null-null
2013-08-23 00:30:29,617 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-17:null) Service SecurityGroup is not supported in the
network id=207
2013-08-23 00:30:29,618 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-17:null) Allocaing disks for
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
2013-08-23 00:30:29,629 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-17:null) Allocation completed for VM:
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
2013-08-23 00:30:29,629 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-17:null) Successfully allocated DB entry for
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
2013-08-23 00:30:29,651 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-17:null) Service SecurityGroup is not supported in the
network id=207
2013-08-23 00:30:29,657 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-17:null) Service SecurityGroup is not supported in the
network id=207
2013-08-23 00:30:29,674 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-17:null) submit async job-299, details: AsyncJobVO
{id:299, userId: 2, accountId: 2, sessionKey: null, instanceType:
VirtualMachine, instanceId: 171, cmd:
org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator:
null, cmdInfo: {"id":"171","templateId":"bd1a8e6a-b66f-4484-afcb-2af22890cff6","response":"json","sessionkey":"c/LK7Wzuq4ia5cxurIMYWevCUkM\u003d","ctxUserId":"2","networkIds":"d277c139-f896-443a-a8cc-c74dcb5f92df","hypervisor":"XenServer","serviceOfferingId":"fbf29251-423f-496c-8edb-32b9362c31ab","_":"1377192613840","ctxAccountId":"2","ctxStartEventId":"864","zoneId":"6ad1fb5e-8a4b-42b7-83f2-863c1b3fda4a"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 345050143793,
completeMsid: null, lastUpdated: null, lastPolled: null, created:
null}
2013-08-23 00:30:29,675 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-64:job-299) Executing
org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-299
2013-08-23 00:30:29,677 DEBUG [cloud.api.ApiServlet]
(catalina-exec-17:null) ===END===  192.168.123.28 -- GET
command=deployVirtualMachine&zoneId=6ad1fb5e-8a4b-42b7-83f2-863c1b3fda4a&templateId=bd1a8e6a-b66f-4484-afcb-2af22890cff6&hypervisor=XenServer&serviceOfferingId=fbf29251-423f-496c-8edb-32b9362c31ab&networkIds=d277c139-f896-443a-a8cc-c74dcb5f92df&response=json&sessionkey=c%2FLK7Wzuq4ia5cxurIMYWevCUkM%3D&_=1377192613840
2013-08-23 00:30:29,683 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-64:job-299) InfrastructureEntity name
is:com.cloud.offering.ServiceOffering
2013-08-23 00:30:29,686 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-64:job-299) ControlledEntity name
is:com.cloud.template.VirtualMachineTemplate
2013-08-23 00:30:29,690 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-64:job-299) ControlledEntity name
is:com.cloud.network.Network
2013-08-23 00:30:29,720 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-64:job-299) Service SecurityGroup is not supported in
the network id=207
2013-08-23 00:30:29,725 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-64:job-299) Service SecurityGroup is not supported in
the network id=207
2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) DeploymentPlanner allocation algorithm:
random
2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Trying to allocate a host and storage pools
from dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram:
1073741824
2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Is ROOT volume READY (pool already
allocated)?: No
2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Searching all possible resources under this
Zone: 1
2013-08-23 00:30:29,747 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Listing clusters in order of aggregate
capacity, that have (atleast one host with) enough CPU and RAM
capacity under this Zone: 1
2013-08-23 00:30:29,749 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) CPUOverprovisioningFactor considered: 1.0
2013-08-23 00:30:29,755 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Removing from the clusterId list these
clusters that are disabled/clusters under disabled pods: [2, 3, 4]
2013-08-23 00:30:29,763 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Checking resources in Cluster: 1 under Pod:
1
2013-08-23 00:30:29,766 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Looking for hosts
in dc: 1  pod:1  cluster:1
2013-08-23 00:30:29,769 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) FirstFitAllocator
has 2 hosts to check for allocation: [Host[-1-Routing],
Host[-2-Routing]]
2013-08-23 00:30:29,773 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found 2 hosts for
allocation after prioritization: [Host[-1-Routing], Host[-2-Routing]]
2013-08-23 00:30:29,773 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Looking for
speed=1000Mhz, Ram=1024
2013-08-23 00:30:29,776 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Checking if host: 1
has enough capacity for requested CPU: 1000 and requested RAM:
1073741824 , cpuOverprovisioningFactor: 1.0
2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Hosts's actual
total CPU: 13590 and CPU after applying overprovisioning: 13590
2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free CPU: 11590 ,
Requested CPU: 1000
2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free RAM:
8645824576 , Requested RAM: 1073741824
2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host has enough CPU
and RAM available
2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
CPU from host: 1, used: 2000, reserved: 0, actual total: 13590, total
with overprovisioning: 13590; requested
cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
MEM from host: 1, used: 1342177280, reserved: 0, total: 9988001856;
requested mem: 1073741824,alloc_from_last_host?:false
,considerReservedCapacity?: true
2013-08-23 00:30:29,780 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found a suitable
host, adding to list: 1
2013-08-23 00:30:29,783 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Checking if host: 2
has enough capacity for requested CPU: 1000 and requested RAM:
1073741824 , cpuOverprovisioningFactor: 1.0
2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Hosts's actual
total CPU: 13590 and CPU after applying overprovisioning: 13590
2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free CPU: 8090 ,
Requested CPU: 1000
2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free RAM:
4216639552 , Requested RAM: 1073741824
2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host has enough CPU
and RAM available
2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
CPU from host: 2, used: 5500, reserved: 0, actual total: 13590, total
with overprovisioning: 13590; requested
cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
MEM from host: 2, used: 5771362304, reserved: 0, total: 9988001856;
requested mem: 1073741824,alloc_from_last_host?:false
,considerReservedCapacity?: true
2013-08-23 00:30:29,787 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found a suitable
host, adding to list: 2
2013-08-23 00:30:29,787 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host Allocator
returning 2 suitable hosts
2013-08-23 00:30:29,789 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Checking suitable pools for volume (Id,
Type): (174,ROOT)
2013-08-23 00:30:29,789 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) We need to allocate new storagepool for this
volume
2013-08-23 00:30:29,791 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Calling StoragePoolAllocators to find
suitable pools
2013-08-23 00:30:29,793 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-64:job-299) Looking for pools in dc: 1  pod:1  cluster:1
2013-08-23 00:30:29,795 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-64:job-299) FirstFitStoragePoolAllocator has 1 pools to
check for allocation
2013-08-23 00:30:29,795 DEBUG
[storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-64:job-299) Checking if storage pool is suitable, name:
Primary00 ,poolId: 200
2013-08-23 00:30:29,795 DEBUG
[storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-64:job-299) Is localStorageAllocationNeeded? false
2013-08-23 00:30:29,795 DEBUG
[storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-64:job-299) Is storage pool shared? true
2013-08-23 00:30:29,798 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-64:job-299) Checking pool 200 for storage, totalSize:
594456936448, usedBytes: 135866548224, usedPct: 0.22855574540997034,
disable threshold: 0.85
2013-08-23 00:30:29,806 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-64:job-299) Checking pool: 200 for volume allocation
[Vol[174|vm=171|ROOT]], maxSize : 1188913872896, totalAllocatedSize :
56011117568, askingSize : 21474836480, allocated disable threshold:
0.85
2013-08-23 00:30:29,806 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-64:job-299) FirstFitStoragePoolAllocator returning 1
suitable storage pools
2013-08-23 00:30:29,806 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Trying to find a potenial host and
associated storage pools from the suitable host/pool lists for this VM
2013-08-23 00:30:29,806 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Checking if host: 1 can access any suitable
storage pool for volume: ROOT
2013-08-23 00:30:29,808 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Host: 1 can access pool: 200
2013-08-23 00:30:29,808 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Found a potential host id: 1 name: xen02 and
associated storage pools for this VM
2013-08-23 00:30:29,810 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200))]
2013-08-23 00:30:29,831 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) VM state transitted from :Stopped to
Starting with event: StartRequestedvm's original host id: null new
host id: null host id before state transition: null
2013-08-23 00:30:29,831 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) Successfully transitioned to start state for
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] reservation id =
8c058359-70c4-4661-9356-fa6893631f2e
2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) Trying to deploy VM, vm has dcId: 1 and
podId: null
2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) advanceStart: DeploymentPlan is provided,
using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null
2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) Deploy avoids pods: null, clusters: null,
hosts: null
2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) DeploymentPlanner allocation algorithm:
random
2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Trying to allocate a host and storage pools
from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram:
1073741824
2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Is ROOT volume READY (pool already
allocated)?: No
2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) DeploymentPlan has host_id specified,
choosing this host and making no checks on this host: 1
2013-08-23 00:30:29,840 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Looking for suitable pools for this host
under zone: 1, pod: 1, cluster: 1
2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Checking suitable pools for volume (Id,
Type): (174,ROOT)
2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) We need to allocate new storagepool for this
volume
2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Calling StoragePoolAllocators to find
suitable pools
2013-08-23 00:30:29,842 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-64:job-299) Looking for pools in dc: 1  pod:1  cluster:1
2013-08-23 00:30:29,843 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-64:job-299) FirstFitStoragePoolAllocator has 1 pools to
check for allocation
2013-08-23 00:30:29,843 DEBUG
[storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-64:job-299) Checking if storage pool is suitable, name:
Primary00 ,poolId: 200
2013-08-23 00:30:29,843 DEBUG
[storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-64:job-299) Is localStorageAllocationNeeded? false
2013-08-23 00:30:29,843 DEBUG
[storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-64:job-299) Is storage pool shared? true
2013-08-23 00:30:29,846 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-64:job-299) Checking pool 200 for storage, totalSize:
594456936448, usedBytes: 135866548224, usedPct: 0.22855574540997034,
disable threshold: 0.85
2013-08-23 00:30:29,854 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-64:job-299) Checking pool: 200 for volume allocation
[Vol[174|vm=171|ROOT]], maxSize : 1188913872896, totalAllocatedSize :
56011117568, askingSize : 21474836480, allocated disable threshold:
0.85
2013-08-23 00:30:29,854 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-64:job-299) FirstFitStoragePoolAllocator returning 1
suitable storage pools
2013-08-23 00:30:29,854 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Trying to find a potenial host and
associated storage pools from the suitable host/pool lists for this VM
2013-08-23 00:30:29,854 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Checking if host: 1 can access any suitable
storage pool for volume: ROOT
2013-08-23 00:30:29,855 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Host: 1 can access pool: 200
2013-08-23 00:30:29,856 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Found a potential host id: 1 name: xen02 and
associated storage pools for this VM
2013-08-23 00:30:29,857 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200))]
2013-08-23 00:30:29,857 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) Deployment found  -
P0=VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200))]
2013-08-23 00:30:29,862 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) VM state transitted from :Starting to
Starting with event: OperationRetryvm's original host id: null new
host id: 1 host id before state transition: null
2013-08-23 00:30:29,871 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) Hosts's actual total CPU: 13590 and CPU
after applying overprovisioning: 13590
2013-08-23 00:30:29,871 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) We are allocating VM, increasing the used
capacity of this host:1
2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) Current Used CPU: 2000 , Free CPU:11590
,Requested CPU: 1000
2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) Current Used RAM: 1342177280 , Free
RAM:8645824576 ,Requested RAM: 1073741824
2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) CPU STATS after allocation: for host: 1, old
used: 2000, old reserved: 0, actual total: 13590, total with
overprovisioning: 13590; new used:3000, reserved:0; requested
cpu:1000,alloc_from_last:false
2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) RAM STATS after allocation: for host: 1, old
used: 1342177280, old reserved: 0, total: 9988001856; new used:
2415919104, reserved: 0; requested mem:
1073741824,alloc_from_last:false
2013-08-23 00:30:29,875 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) VM is being created in podId: 1
2013-08-23 00:30:29,879 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Lock is acquired for network id 207 as a
part of network implement
2013-08-23 00:30:29,879 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Asking ExternalGuestNetworkGuru to implement
Ntwk[207|Guest|11]
2013-08-23 00:30:29,889 DEBUG [db.Transaction.Transaction]
(Job-Executor-64:job-299) Rolling back the transaction: Time = 1 Name
=  -AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1146-ThreadPoolExecutor$Worker.run:615-Thread.run:679;
called by -Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:131-DataCenterDaoImpl.allocateVnet:192-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-GuestNetworkGuru.allocateVnet:294-GuestNetworkGuru.implement:326-ExternalGuestNetworkGuru.implement:123-NetworkManagerImpl.implementNetwork:1425-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125
2013-08-23 00:30:29,890 INFO  [utils.exception.CSExceptionErrorCode]
(Job-Executor-64:job-299) Could not find exception:
com.cloud.exception.InsufficientVirtualNetworkCapcityException in
error code list for exceptions
2013-08-23 00:30:29,890 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Cleaning up because we're unable to
implement the network Ntwk[207|Guest|11]
2013-08-23 00:30:29,899 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Releasing 0 port forwarding rules for
network id=207 as a part of shutdownNetworkRules
2013-08-23 00:30:29,899 DEBUG [network.firewall.FirewallManagerImpl]
(Job-Executor-64:job-299) There are no rules to forward to the network
elements
2013-08-23 00:30:29,900 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Releasing 0 static nat rules for network
id=207 as a part of shutdownNetworkRules
2013-08-23 00:30:29,900 DEBUG [network.firewall.FirewallManagerImpl]
(Job-Executor-64:job-299) There are no rules to forward to the network
elements
2013-08-23 00:30:29,901 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) There are no rules to forward to the network
elements
2013-08-23 00:30:29,902 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Releasing 0 firewall ingress rules for
network id=207 as a part of shutdownNetworkRules
2013-08-23 00:30:29,902 DEBUG [network.firewall.FirewallManagerImpl]
(Job-Executor-64:job-299) There are no rules to forward to the network
elements
2013-08-23 00:30:29,903 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Releasing 0 firewall egress rules for
network id=207 as a part of shutdownNetworkRules
2013-08-23 00:30:29,903 DEBUG [network.firewall.FirewallManagerImpl]
(Job-Executor-64:job-299) There are no rules to forward to the network
elements
2013-08-23 00:30:29,906 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Releasing 6 Network ACLs for network id=207
as a part of shutdownNetworkRules
2013-08-23 00:30:29,919 DEBUG
[network.element.VpcVirtualRouterElement] (Job-Executor-64:job-299)
Virtual router elemnt doesn't need to apply firewall rules on the
backend; virtual router doesn't exist in the network 207
2013-08-23 00:30:29,923 DEBUG [network.rules.RulesManagerImpl]
(Job-Executor-64:job-299) Found 0 static nat rules to apply for
network id 207
2013-08-23 00:30:29,931 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Sending network shutdown to VpcVirtualRouter
2013-08-23 00:30:29,936 DEBUG
[network.element.VpcVirtualRouterElement] (Job-Executor-64:job-299)
Router VM[DomainRouter|r-166-VM] is not a part the network
Ntwk[207|Guest|11]
2013-08-23 00:30:29,936 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Network id=207 is shutdown successfully,
cleaning up corresponding resources now.
2013-08-23 00:30:29,942 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-64:job-299) Lock is released for network id 207 as a
part of network implement
2013-08-23 00:30:29,942 INFO  [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) Insufficient capacity
com.cloud.exception.InsufficientVirtualNetworkCapcityException: Unable
to allocate vnet as a part of network Ntwk[207|Guest|11] implement
Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.network.guru.GuestNetworkGuru.allocateVnet(GuestNetworkGuru.java:296)
at com.cloud.network.guru.GuestNetworkGuru.implement(GuestNetworkGuru.java:326)
at com.cloud.network.guru.ExternalGuestNetworkGuru.implement(ExternalGuestNetworkGuru.java:123)
at com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.java:1425)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:1596)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:746)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3871)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3464)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3450)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:379)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
2013-08-23 00:30:29,945 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) Cleaning up resources for the vm
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in Starting state
2013-08-23 00:30:29,947 DEBUG [agent.transport.Request]
(Job-Executor-64:job-299) Seq 1-1023805316: Sending  { Cmd , MgmtId:
345050143793, via: 1, Ver: v1, Flags: 100111,
[{"StopCommand":{"isProxy":false,"vmName":"i-2-171-VM","wait":0}}] }
2013-08-23 00:30:29,947 DEBUG [agent.transport.Request]
(Job-Executor-64:job-299) Seq 1-1023805316: Executing:  { Cmd ,
MgmtId: 345050143793, via: 1, Ver: v1, Flags: 100111,
[{"StopCommand":{"isProxy":false,"vmName":"i-2-171-VM","wait":0}}] }
2013-08-23 00:30:29,947 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-395:null) Seq 1-1023805316: Executing request
2013-08-23 00:30:30,209 INFO  [xen.resource.CitrixResourceBase]
(DirectAgent-395:null) VM does not exist on
XenServer992cb98d-123a-4cb6-8410-1532bbcb60f5
2013-08-23 00:30:30,210 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-395:null) Seq 1-1023805316: Response Received:
2013-08-23 00:30:30,210 DEBUG [agent.transport.Request]
(DirectAgent-395:null) Seq 1-1023805316: Processing:  { Ans: , MgmtId:
345050143793, via: 1, Ver: v1, Flags: 110,
[{"StopAnswer":{"vncPort":0,"result":true,"details":"VM does not
exist","wait":0}}] }
2013-08-23 00:30:30,210 DEBUG [agent.manager.AgentAttache]
(DirectAgent-395:null) Seq 1-1023805316: No more commands found
2013-08-23 00:30:30,210 DEBUG [agent.transport.Request]
(Job-Executor-64:job-299) Seq 1-1023805316: Received:  { Ans: ,
MgmtId: 345050143793, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-08-23 00:30:30,217 DEBUG [db.Transaction.Transaction]
(Job-Executor-64:job-299) Rolling back the transaction: Time = 2 Name
=  -AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1146-ThreadPoolExecutor$Worker.run:615-Thread.run:679;
called by -Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:131-NetworkManagerImpl.release:1687-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VirtualMachineManagerImpl.cleanup:962-VirtualMachineManagerImpl.advanceStart:850-VirtualMachineManagerImpl.start:471-VMEntityManagerImpl.deployVirtualMachine:212-VirtualMachineEntityImpl.deploy:209
2013-08-23 00:30:30,217 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) Successfully released network resources for
the vm VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
2013-08-23 00:30:30,217 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) Successfully cleanued up resources for the
vm VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in Starting state
2013-08-23 00:30:30,219 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-64:job-299) DataCenter id = '1' provided is in avoid
set, DeploymentPlanner cannot allocate the VM, returning.
2013-08-23 00:30:30,225 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) VM state transitted from :Starting to
Stopped with event: OperationFailedvm's original host id: null new
host id: null host id before state transition: 1
2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) Hosts's actual total CPU: 13590 and CPU
after applying overprovisioning: 13590
2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) release cpu from host: 1, old used:
3000,reserved: 0, actual total: 13590, total with overprovisioning:
13590; new used: 2000,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) release mem from host: 1, old used:
2415919104,reserved: 0, total: 9988001856; new used:
1342177280,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-08-23 00:30:30,236 DEBUG [cloud.vm.UserVmManagerImpl]
(Job-Executor-64:job-299) Destroying vm
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] as it failed to create
on Host with Id:null
2013-08-23 00:30:30,242 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-64:job-299) VM state transitted from :Stopped to Error
with event: OperationFailedToErrorvm's original host id: null new host
id: null host id before state transition: null
2013-08-23 00:30:30,277 INFO  [user.vm.DeployVMCmd]
(Job-Executor-64:job-299)
com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]Scope=interface
com.cloud.dc.DataCenter; id=1
2013-08-23 00:30:30,277 INFO  [user.vm.DeployVMCmd]
(Job-Executor-64:job-299) Unable to create a deployment for
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for
VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]Scope=interface
com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:728)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3871)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3464)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3450)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:379)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
2013-08-23 00:30:30,278 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-64:job-299) Complete async job-299, jobStatus: 2,
resultCode: 530, result: Error Code: 533 Error text: Unable to create
a deployment for VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]

Re: Fail to create Instance in VPC on CS4.1.1

Posted by 不坏阿峰 <on...@gmail.com>.

Thank you very much.
i search "Unable to allocate vnet as a part of network" and find this link
http://mail-archives.apache.org/mod_mbox/incubator-cloudstack-users/201205.mbox/%3CCAH-3_Gn8Fe_dFXq9ayq-1KHWn0j+Z6Fu6NutzDfH3wN8MdNqiw@mail.gmail.com%3E

i change the Guest network Vlan rang from 300 to 301(both use,
cloudstack alert guest vlan is full ,but can use) ,extend it 300 to
399.  then create instance sucess.
but i did not see new network create,  VPC did not create guest network .

could you explain to me or give me some guide to understand it?

many thanks
Best wish!

2013/8/23 Chiradeep Vittal <Ch...@citrix.com>:
> This might be the problem:
> 2013-08-23 00:30:29,942 INFO  [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-64:job-299) Insufficient capacity
> com.cloud.exception.InsufficientVirtualNetworkCapcityException: Unable
> to allocate vnet as a part of network Ntwk[207|Guest|11] implement
> Scope=interface com.cloud.dc.DataCenter; id=1
>
>
>
> On 8/22/13 10:51 AM, "不坏阿峰" <on...@gmail.com> wrote:
>
>>cs-mgt：
>>eth1: 192.168.230.2
>>
>>xen01:
>>eth1: 192.168.230.11
>>eth2: public+guest   (guest network:192.168.30.0/24  )
>>eth3: 192.168.250.11
>>
>>xen01:
>>eth1: 192.168.230.12
>>eth2: public+guest  (guest network:192.168.30.0/24  )
>>eth3: 192.168.250.12
>>
>>Adv net, can work.
>>
>>I want to try VPC ,i have create VPC network 172.16.0.0/16 and tier
>>172.16.0.1/24.   tier network ACLs   ingress, egress TCP/UDP all
>>allowed configed
>>
>>VPC router have started and i check from console , it can access
>>internet and can access storage and cs.
>>
>>but fail to create vm in tier of VPC.
>>
>>#############   LOG #############################
>>2013-08-23 00:30:29,544 DEBUG [cloud.api.ApiServlet]
>>(catalina-exec-17:null) ===START===  192.168.123.28 -- GET
>>command=deployVirtualMachine&zoneId=6ad1fb5e-8a4b-42b7-83f2-863c1b3fda4a&t
>>emplateId=bd1a8e6a-b66f-4484-afcb-2af22890cff6&hypervisor=XenServer&servic
>>eOfferingId=fbf29251-423f-496c-8edb-32b9362c31ab&networkIds=d277c139-f896-
>>443a-a8cc-c74dcb5f92df&response=json&sessionkey=c%2FLK7Wzuq4ia5cxurIMYWevC
>>UkM%3D&_=1377192613840
>>2013-08-23 00:30:29,554 DEBUG [cloud.api.ApiDispatcher]
>>(catalina-exec-17:null) InfrastructureEntity name
>>is:com.cloud.offering.ServiceOffering
>>2013-08-23 00:30:29,556 DEBUG [cloud.api.ApiDispatcher]
>>(catalina-exec-17:null) ControlledEntity name
>>is:com.cloud.template.VirtualMachineTemplate
>>2013-08-23 00:30:29,560 DEBUG [cloud.api.ApiDispatcher]
>>(catalina-exec-17:null) ControlledEntity name
>>is:com.cloud.network.Network
>>2013-08-23 00:30:29,574 DEBUG [cloud.network.NetworkModelImpl]
>>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>>network id=207
>>2013-08-23 00:30:29,584 DEBUG [cloud.vm.UserVmManagerImpl]
>>(catalina-exec-17:null) Allocating in the DB for vm
>>2013-08-23 00:30:29,599 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(catalina-exec-17:null) Allocating entries for VM:
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:29,600 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(catalina-exec-17:null) Allocating nics for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:29,601 DEBUG [cloud.network.NetworkManagerImpl]
>>(catalina-exec-17:null) Allocating nic for vm
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in network
>>Ntwk[207|Guest|11] with requested profile
>>NicProfile[0-0-null-null-null
>>2013-08-23 00:30:29,617 DEBUG [cloud.network.NetworkModelImpl]
>>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>>network id=207
>>2013-08-23 00:30:29,618 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(catalina-exec-17:null) Allocaing disks for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:29,629 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(catalina-exec-17:null) Allocation completed for VM:
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:29,629 DEBUG [cloud.vm.UserVmManagerImpl]
>>(catalina-exec-17:null) Successfully allocated DB entry for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:29,651 DEBUG [cloud.network.NetworkModelImpl]
>>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>>network id=207
>>2013-08-23 00:30:29,657 DEBUG [cloud.network.NetworkModelImpl]
>>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>>network id=207
>>2013-08-23 00:30:29,674 DEBUG [cloud.async.AsyncJobManagerImpl]
>>(catalina-exec-17:null) submit async job-299, details: AsyncJobVO
>>{id:299, userId: 2, accountId: 2, sessionKey: null, instanceType:
>>VirtualMachine, instanceId: 171, cmd:
>>org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator:
>>null, cmdInfo:
>>{"id":"171","templateId":"bd1a8e6a-b66f-4484-afcb-2af22890cff6","response"
>>:"json","sessionkey":"c/LK7Wzuq4ia5cxurIMYWevCUkM\u003d","ctxUserId":"2","
>>networkIds":"d277c139-f896-443a-a8cc-c74dcb5f92df","hypervisor":"XenServer
>>","serviceOfferingId":"fbf29251-423f-496c-8edb-32b9362c31ab","_":"13771926
>>13840","ctxAccountId":"2","ctxStartEventId":"864","zoneId":"6ad1fb5e-8a4b-
>>42b7-83f2-863c1b3fda4a"},
>>cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
>>processStatus: 0, resultCode: 0, result: null, initMsid: 345050143793,
>>completeMsid: null, lastUpdated: null, lastPolled: null, created:
>>null}
>>2013-08-23 00:30:29,675 DEBUG [cloud.async.AsyncJobManagerImpl]
>>(Job-Executor-64:job-299) Executing
>>org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-299
>>2013-08-23 00:30:29,677 DEBUG [cloud.api.ApiServlet]
>>(catalina-exec-17:null) ===END===  192.168.123.28 -- GET
>>command=deployVirtualMachine&zoneId=6ad1fb5e-8a4b-42b7-83f2-863c1b3fda4a&t
>>emplateId=bd1a8e6a-b66f-4484-afcb-2af22890cff6&hypervisor=XenServer&servic
>>eOfferingId=fbf29251-423f-496c-8edb-32b9362c31ab&networkIds=d277c139-f896-
>>443a-a8cc-c74dcb5f92df&response=json&sessionkey=c%2FLK7Wzuq4ia5cxurIMYWevC
>>UkM%3D&_=1377192613840
>>2013-08-23 00:30:29,683 DEBUG [cloud.api.ApiDispatcher]
>>(Job-Executor-64:job-299) InfrastructureEntity name
>>is:com.cloud.offering.ServiceOffering
>>2013-08-23 00:30:29,686 DEBUG [cloud.api.ApiDispatcher]
>>(Job-Executor-64:job-299) ControlledEntity name
>>is:com.cloud.template.VirtualMachineTemplate
>>2013-08-23 00:30:29,690 DEBUG [cloud.api.ApiDispatcher]
>>(Job-Executor-64:job-299) ControlledEntity name
>>is:com.cloud.network.Network
>>2013-08-23 00:30:29,720 DEBUG [cloud.network.NetworkModelImpl]
>>(Job-Executor-64:job-299) Service SecurityGroup is not supported in
>>the network id=207
>>2013-08-23 00:30:29,725 DEBUG [cloud.network.NetworkModelImpl]
>>(Job-Executor-64:job-299) Service SecurityGroup is not supported in
>>the network id=207
>>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) DeploymentPlanner allocation algorithm:
>>random
>>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Trying to allocate a host and storage pools
>>from dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram:
>>1073741824
>>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Is ROOT volume READY (pool already
>>allocated)?: No
>>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Searching all possible resources under this
>>Zone: 1
>>2013-08-23 00:30:29,747 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Listing clusters in order of aggregate
>>capacity, that have (atleast one host with) enough CPU and RAM
>>capacity under this Zone: 1
>>2013-08-23 00:30:29,749 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) CPUOverprovisioningFactor considered: 1.0
>>2013-08-23 00:30:29,755 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Removing from the clusterId list these
>>clusters that are disabled/clusters under disabled pods: [2, 3, 4]
>>2013-08-23 00:30:29,763 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Checking resources in Cluster: 1 under Pod:
>>1
>>2013-08-23 00:30:29,766 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Looking for hosts
>>in dc: 1  pod:1  cluster:1
>>2013-08-23 00:30:29,769 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) FirstFitAllocator
>>has 2 hosts to check for allocation: [Host[-1-Routing],
>>Host[-2-Routing]]
>>2013-08-23 00:30:29,773 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found 2 hosts for
>>allocation after prioritization: [Host[-1-Routing], Host[-2-Routing]]
>>2013-08-23 00:30:29,773 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Looking for
>>speed=1000Mhz, Ram=1024
>>2013-08-23 00:30:29,776 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Checking if host: 1
>>has enough capacity for requested CPU: 1000 and requested RAM:
>>1073741824 , cpuOverprovisioningFactor: 1.0
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Hosts's actual
>>total CPU: 13590 and CPU after applying overprovisioning: 13590
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free CPU: 11590 ,
>>Requested CPU: 1000
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free RAM:
>>8645824576 , Requested RAM: 1073741824
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host has enough CPU
>>and RAM available
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>>CPU from host: 1, used: 2000, reserved: 0, actual total: 13590, total
>>with overprovisioning: 13590; requested
>>cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>>MEM from host: 1, used: 1342177280, reserved: 0, total: 9988001856;
>>requested mem: 1073741824,alloc_from_last_host?:false
>>,considerReservedCapacity?: true
>>2013-08-23 00:30:29,780 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found a suitable
>>host, adding to list: 1
>>2013-08-23 00:30:29,783 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Checking if host: 2
>>has enough capacity for requested CPU: 1000 and requested RAM:
>>1073741824 , cpuOverprovisioningFactor: 1.0
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Hosts's actual
>>total CPU: 13590 and CPU after applying overprovisioning: 13590
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free CPU: 8090 ,
>>Requested CPU: 1000
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free RAM:
>>4216639552 , Requested RAM: 1073741824
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host has enough CPU
>>and RAM available
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>>CPU from host: 2, used: 5500, reserved: 0, actual total: 13590, total
>>with overprovisioning: 13590; requested
>>cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>>MEM from host: 2, used: 5771362304, reserved: 0, total: 9988001856;
>>requested mem: 1073741824,alloc_from_last_host?:false
>>,considerReservedCapacity?: true
>>2013-08-23 00:30:29,787 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found a suitable
>>host, adding to list: 2
>>2013-08-23 00:30:29,787 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host Allocator
>>returning 2 suitable hosts
>>2013-08-23 00:30:29,789 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Checking suitable pools for volume (Id,
>>Type): (174,ROOT)
>>2013-08-23 00:30:29,789 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) We need to allocate new storagepool for this
>>volume
>>2013-08-23 00:30:29,791 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Calling StoragePoolAllocators to find
>>suitable pools
>>2013-08-23 00:30:29,793 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) Looking for pools in dc: 1  pod:1  cluster:1
>>2013-08-23 00:30:29,795 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator has 1 pools to
>>check for allocation
>>2013-08-23 00:30:29,795 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Checking if storage pool is suitable, name:
>>Primary00 ,poolId: 200
>>2013-08-23 00:30:29,795 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Is localStorageAllocationNeeded? false
>>2013-08-23 00:30:29,795 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Is storage pool shared? true
>>2013-08-23 00:30:29,798 DEBUG [cloud.storage.StorageManagerImpl]
>>(Job-Executor-64:job-299) Checking pool 200 for storage, totalSize:
>>594456936448, usedBytes: 135866548224, usedPct: 0.22855574540997034,
>>disable threshold: 0.85
>>2013-08-23 00:30:29,806 DEBUG [cloud.storage.StorageManagerImpl]
>>(Job-Executor-64:job-299) Checking pool: 200 for volume allocation
>>[Vol[174|vm=171|ROOT]], maxSize : 1188913872896, totalAllocatedSize :
>>56011117568, askingSize : 21474836480, allocated disable threshold:
>>0.85
>>2013-08-23 00:30:29,806 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator returning 1
>>suitable storage pools
>>2013-08-23 00:30:29,806 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Trying to find a potenial host and
>>associated storage pools from the suitable host/pool lists for this VM
>>2013-08-23 00:30:29,806 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Checking if host: 1 can access any suitable
>>storage pool for volume: ROOT
>>2013-08-23 00:30:29,808 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Host: 1 can access pool: 200
>>2013-08-23 00:30:29,808 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Found a potential host id: 1 name: xen02 and
>>associated storage pools for this VM
>>2013-08-23 00:30:29,810 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Returning Deployment Destination:
>>Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(I
>>d))]
>>:
>>Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200)
>>)]
>>2013-08-23 00:30:29,831 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) VM state transitted from :Stopped to
>>Starting with event: StartRequestedvm's original host id: null new
>>host id: null host id before state transition: null
>>2013-08-23 00:30:29,831 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Successfully transitioned to start state for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] reservation id =
>>8c058359-70c4-4661-9356-fa6893631f2e
>>2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Trying to deploy VM, vm has dcId: 1 and
>>podId: null
>>2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) advanceStart: DeploymentPlan is provided,
>>using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null
>>2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Deploy avoids pods: null, clusters: null,
>>hosts: null
>>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) DeploymentPlanner allocation algorithm:
>>random
>>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Trying to allocate a host and storage pools
>>from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram:
>>1073741824
>>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Is ROOT volume READY (pool already
>>allocated)?: No
>>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) DeploymentPlan has host_id specified,
>>choosing this host and making no checks on this host: 1
>>2013-08-23 00:30:29,840 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Looking for suitable pools for this host
>>under zone: 1, pod: 1, cluster: 1
>>2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Checking suitable pools for volume (Id,
>>Type): (174,ROOT)
>>2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) We need to allocate new storagepool for this
>>volume
>>2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Calling StoragePoolAllocators to find
>>suitable pools
>>2013-08-23 00:30:29,842 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) Looking for pools in dc: 1  pod:1  cluster:1
>>2013-08-23 00:30:29,843 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator has 1 pools to
>>check for allocation
>>2013-08-23 00:30:29,843 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Checking if storage pool is suitable, name:
>>Primary00 ,poolId: 200
>>2013-08-23 00:30:29,843 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Is localStorageAllocationNeeded? false
>>2013-08-23 00:30:29,843 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Is storage pool shared? true
>>2013-08-23 00:30:29,846 DEBUG [cloud.storage.StorageManagerImpl]
>>(Job-Executor-64:job-299) Checking pool 200 for storage, totalSize:
>>594456936448, usedBytes: 135866548224, usedPct: 0.22855574540997034,
>>disable threshold: 0.85
>>2013-08-23 00:30:29,854 DEBUG [cloud.storage.StorageManagerImpl]
>>(Job-Executor-64:job-299) Checking pool: 200 for volume allocation
>>[Vol[174|vm=171|ROOT]], maxSize : 1188913872896, totalAllocatedSize :
>>56011117568, askingSize : 21474836480, allocated disable threshold:
>>0.85
>>2013-08-23 00:30:29,854 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator returning 1
>>suitable storage pools
>>2013-08-23 00:30:29,854 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Trying to find a potenial host and
>>associated storage pools from the suitable host/pool lists for this VM
>>2013-08-23 00:30:29,854 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Checking if host: 1 can access any suitable
>>storage pool for volume: ROOT
>>2013-08-23 00:30:29,855 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Host: 1 can access pool: 200
>>2013-08-23 00:30:29,856 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Found a potential host id: 1 name: xen02 and
>>associated storage pools for this VM
>>2013-08-23 00:30:29,857 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Returning Deployment Destination:
>>Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(I
>>d))]
>>:
>>Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200)
>>)]
>>2013-08-23 00:30:29,857 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Deployment found  -
>>P0=VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621],
>>P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Poo
>>l(Id))]
>>:
>>Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200)
>>)]
>>2013-08-23 00:30:29,862 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) VM state transitted from :Starting to
>>Starting with event: OperationRetryvm's original host id: null new
>>host id: 1 host id before state transition: null
>>2013-08-23 00:30:29,871 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) Hosts's actual total CPU: 13590 and CPU
>>after applying overprovisioning: 13590
>>2013-08-23 00:30:29,871 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) We are allocating VM, increasing the used
>>capacity of this host:1
>>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) Current Used CPU: 2000 , Free CPU:11590
>>,Requested CPU: 1000
>>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) Current Used RAM: 1342177280 , Free
>>RAM:8645824576 ,Requested RAM: 1073741824
>>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) CPU STATS after allocation: for host: 1, old
>>used: 2000, old reserved: 0, actual total: 13590, total with
>>overprovisioning: 13590; new used:3000, reserved:0; requested
>>cpu:1000,alloc_from_last:false
>>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) RAM STATS after allocation: for host: 1, old
>>used: 1342177280, old reserved: 0, total: 9988001856; new used:
>>2415919104, reserved: 0; requested mem:
>>1073741824,alloc_from_last:false
>>2013-08-23 00:30:29,875 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) VM is being created in podId: 1
>>2013-08-23 00:30:29,879 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Lock is acquired for network id 207 as a
>>part of network implement
>>2013-08-23 00:30:29,879 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Asking ExternalGuestNetworkGuru to implement
>>Ntwk[207|Guest|11]
>>2013-08-23 00:30:29,889 DEBUG [db.Transaction.Transaction]
>>(Job-Executor-64:job-299) Rolling back the transaction: Time = 1 Name
>>=
>>-AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTa
>>sk$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1146-
>>ThreadPoolExecutor$Worker.run:615-Thread.run:679;
>>called by
>>-Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657
>>-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPost
>>Processor$InterceptorDispatcher.intercept:131-DataCenterDaoImpl.allocateVn
>>et:192-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept
>>:125-GuestNetworkGuru.allocateVnet:294-GuestNetworkGuru.implement:326-Exte
>>rnalGuestNetworkGuru.implement:123-NetworkManagerImpl.implementNetwork:142
>>5-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125
>>2013-08-23 00:30:29,890 INFO  [utils.exception.CSExceptionErrorCode]
>>(Job-Executor-64:job-299) Could not find exception:
>>com.cloud.exception.InsufficientVirtualNetworkCapcityException in
>>error code list for exceptions
>>2013-08-23 00:30:29,890 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Cleaning up because we're unable to
>>implement the network Ntwk[207|Guest|11]
>>2013-08-23 00:30:29,899 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Releasing 0 port forwarding rules for
>>network id=207 as a part of shutdownNetworkRules
>>2013-08-23 00:30:29,899 DEBUG [network.firewall.FirewallManagerImpl]
>>(Job-Executor-64:job-299) There are no rules to forward to the network
>>elements
>>2013-08-23 00:30:29,900 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Releasing 0 static nat rules for network
>>id=207 as a part of shutdownNetworkRules
>>2013-08-23 00:30:29,900 DEBUG [network.firewall.FirewallManagerImpl]
>>(Job-Executor-64:job-299) There are no rules to forward to the network
>>elements
>>2013-08-23 00:30:29,901 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) There are no rules to forward to the network
>>elements
>>2013-08-23 00:30:29,902 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Releasing 0 firewall ingress rules for
>>network id=207 as a part of shutdownNetworkRules
>>2013-08-23 00:30:29,902 DEBUG [network.firewall.FirewallManagerImpl]
>>(Job-Executor-64:job-299) There are no rules to forward to the network
>>elements
>>2013-08-23 00:30:29,903 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Releasing 0 firewall egress rules for
>>network id=207 as a part of shutdownNetworkRules
>>2013-08-23 00:30:29,903 DEBUG [network.firewall.FirewallManagerImpl]
>>(Job-Executor-64:job-299) There are no rules to forward to the network
>>elements
>>2013-08-23 00:30:29,906 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Releasing 6 Network ACLs for network id=207
>>as a part of shutdownNetworkRules
>>2013-08-23 00:30:29,919 DEBUG
>>[network.element.VpcVirtualRouterElement] (Job-Executor-64:job-299)
>>Virtual router elemnt doesn't need to apply firewall rules on the
>>backend; virtual router doesn't exist in the network 207
>>2013-08-23 00:30:29,923 DEBUG [network.rules.RulesManagerImpl]
>>(Job-Executor-64:job-299) Found 0 static nat rules to apply for
>>network id 207
>>2013-08-23 00:30:29,931 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Sending network shutdown to VpcVirtualRouter
>>2013-08-23 00:30:29,936 DEBUG
>>[network.element.VpcVirtualRouterElement] (Job-Executor-64:job-299)
>>Router VM[DomainRouter|r-166-VM] is not a part the network
>>Ntwk[207|Guest|11]
>>2013-08-23 00:30:29,936 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Network id=207 is shutdown successfully,
>>cleaning up corresponding resources now.
>>2013-08-23 00:30:29,942 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Lock is released for network id 207 as a
>>part of network implement
>>2013-08-23 00:30:29,942 INFO  [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Insufficient capacity
>>com.cloud.exception.InsufficientVirtualNetworkCapcityException: Unable
>>to allocate vnet as a part of network Ntwk[207|Guest|11] implement
>>Scope=interface com.cloud.dc.DataCenter; id=1
>>at
>>com.cloud.network.guru.GuestNetworkGuru.allocateVnet(GuestNetworkGuru.java
>>:296)
>>at
>>com.cloud.network.guru.GuestNetworkGuru.implement(GuestNetworkGuru.java:32
>>6)
>>at
>>com.cloud.network.guru.ExternalGuestNetworkGuru.implement(ExternalGuestNet
>>workGuru.java:123)
>>at
>>com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.j
>>ava:1425)
>>at
>>com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorD
>>ispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>>at
>>com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:1596)
>>at
>>com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerI
>>mpl.java:746)
>>at
>>com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.jav
>>a:471)
>>at
>>org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVi
>>rtualMachine(VMEntityManagerImpl.java:212)
>>at
>>org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.dep
>>loy(VirtualMachineEntityImpl.java:209)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3871)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3464)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3450)
>>at
>>com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorD
>>ispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>>at
>>org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.
>>java:379)
>>at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
>>at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
>>at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>>at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>>at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>>at
>>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>>1146)
>>at
>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>>:615)
>>at java.lang.Thread.run(Thread.java:679)
>>2013-08-23 00:30:29,945 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Cleaning up resources for the vm
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in Starting state
>>2013-08-23 00:30:29,947 DEBUG [agent.transport.Request]
>>(Job-Executor-64:job-299) Seq 1-1023805316: Sending  { Cmd , MgmtId:
>>345050143793, via: 1, Ver: v1, Flags: 100111,
>>[{"StopCommand":{"isProxy":false,"vmName":"i-2-171-VM","wait":0}}] }
>>2013-08-23 00:30:29,947 DEBUG [agent.transport.Request]
>>(Job-Executor-64:job-299) Seq 1-1023805316: Executing:  { Cmd ,
>>MgmtId: 345050143793, via: 1, Ver: v1, Flags: 100111,
>>[{"StopCommand":{"isProxy":false,"vmName":"i-2-171-VM","wait":0}}] }
>>2013-08-23 00:30:29,947 DEBUG [agent.manager.DirectAgentAttache]
>>(DirectAgent-395:null) Seq 1-1023805316: Executing request
>>2013-08-23 00:30:30,209 INFO  [xen.resource.CitrixResourceBase]
>>(DirectAgent-395:null) VM does not exist on
>>XenServer992cb98d-123a-4cb6-8410-1532bbcb60f5
>>2013-08-23 00:30:30,210 DEBUG [agent.manager.DirectAgentAttache]
>>(DirectAgent-395:null) Seq 1-1023805316: Response Received:
>>2013-08-23 00:30:30,210 DEBUG [agent.transport.Request]
>>(DirectAgent-395:null) Seq 1-1023805316: Processing:  { Ans: , MgmtId:
>>345050143793, via: 1, Ver: v1, Flags: 110,
>>[{"StopAnswer":{"vncPort":0,"result":true,"details":"VM does not
>>exist","wait":0}}] }
>>2013-08-23 00:30:30,210 DEBUG [agent.manager.AgentAttache]
>>(DirectAgent-395:null) Seq 1-1023805316: No more commands found
>>2013-08-23 00:30:30,210 DEBUG [agent.transport.Request]
>>(Job-Executor-64:job-299) Seq 1-1023805316: Received:  { Ans: ,
>>MgmtId: 345050143793, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
>>2013-08-23 00:30:30,217 DEBUG [db.Transaction.Transaction]
>>(Job-Executor-64:job-299) Rolling back the transaction: Time = 2 Name
>>=
>>-AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTa
>>sk$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1146-
>>ThreadPoolExecutor$Worker.run:615-Thread.run:679;
>>called by
>>-Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657
>>-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPost
>>Processor$InterceptorDispatcher.intercept:131-NetworkManagerImpl.release:1
>>687-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:12
>>5-VirtualMachineManagerImpl.cleanup:962-VirtualMachineManagerImpl.advanceS
>>tart:850-VirtualMachineManagerImpl.start:471-VMEntityManagerImpl.deployVir
>>tualMachine:212-VirtualMachineEntityImpl.deploy:209
>>2013-08-23 00:30:30,217 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Successfully released network resources for
>>the vm VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:30,217 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Successfully cleanued up resources for the
>>vm VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in Starting state
>>2013-08-23 00:30:30,219 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) DataCenter id = '1' provided is in avoid
>>set, DeploymentPlanner cannot allocate the VM, returning.
>>2013-08-23 00:30:30,225 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) VM state transitted from :Starting to
>>Stopped with event: OperationFailedvm's original host id: null new
>>host id: null host id before state transition: 1
>>2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) Hosts's actual total CPU: 13590 and CPU
>>after applying overprovisioning: 13590
>>2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) release cpu from host: 1, old used:
>>3000,reserved: 0, actual total: 13590, total with overprovisioning:
>>13590; new used: 2000,reserved:0; movedfromreserved:
>>false,moveToReserveredfalse
>>2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) release mem from host: 1, old used:
>>2415919104,reserved: 0, total: 9988001856; new used:
>>1342177280,reserved:0; movedfromreserved: false,moveToReserveredfalse
>>2013-08-23 00:30:30,236 DEBUG [cloud.vm.UserVmManagerImpl]
>>(Job-Executor-64:job-299) Destroying vm
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] as it failed to create
>>on Host with Id:null
>>2013-08-23 00:30:30,242 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) VM state transitted from :Stopped to Error
>>with event: OperationFailedToErrorvm's original host id: null new host
>>id: null host id before state transition: null
>>2013-08-23 00:30:30,277 INFO  [user.vm.DeployVMCmd]
>>(Job-Executor-64:job-299)
>>com.cloud.exception.InsufficientServerCapacityException: Unable to
>>create a deployment for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]Scope=interface
>>com.cloud.dc.DataCenter; id=1
>>2013-08-23 00:30:30,277 INFO  [user.vm.DeployVMCmd]
>>(Job-Executor-64:job-299) Unable to create a deployment for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>com.cloud.exception.InsufficientServerCapacityException: Unable to
>>create a deployment for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]Scope=interface
>>com.cloud.dc.DataCenter; id=1
>>at
>>com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerI
>>mpl.java:728)
>>at
>>com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.jav
>>a:471)
>>at
>>org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVi
>>rtualMachine(VMEntityManagerImpl.java:212)
>>at
>>org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.dep
>>loy(VirtualMachineEntityImpl.java:209)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3871)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3464)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3450)
>>at
>>com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorD
>>ispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>>at
>>org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.
>>java:379)
>>at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
>>at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
>>at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>>at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>>at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>>at
>>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>>1146)
>>at
>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>>:615)
>>at java.lang.Thread.run(Thread.java:679)
>>2013-08-23 00:30:30,278 DEBUG [cloud.async.AsyncJobManagerImpl]
>>(Job-Executor-64:job-299) Complete async job-299, jobStatus: 2,
>>resultCode: 530, result: Error Code: 533 Error text: Unable to create
>>a deployment for VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>

Re: Fail to create Instance in VPC on CS4.1.1

Posted by 不坏阿峰 <on...@gmail.com>.

Thank you very much.
i search "Unable to allocate vnet as a part of network" and find this link
http://mail-archives.apache.org/mod_mbox/incubator-cloudstack-users/201205.mbox/%3CCAH-3_Gn8Fe_dFXq9ayq-1KHWn0j+Z6Fu6NutzDfH3wN8MdNqiw@mail.gmail.com%3E

i change the Guest network Vlan rang from 300 to 301(both use,
cloudstack alert guest vlan is full ,but can use) ,extend it 300 to
399.  then create instance sucess.
but i did not see new network create,  VPC did not create guest network .

could you explain to me or give me some guide to understand it?

many thanks
Best wish!

2013/8/23 Chiradeep Vittal <Ch...@citrix.com>:
> This might be the problem:
> 2013-08-23 00:30:29,942 INFO  [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-64:job-299) Insufficient capacity
> com.cloud.exception.InsufficientVirtualNetworkCapcityException: Unable
> to allocate vnet as a part of network Ntwk[207|Guest|11] implement
> Scope=interface com.cloud.dc.DataCenter; id=1
>
>
>
> On 8/22/13 10:51 AM, "不坏阿峰" <on...@gmail.com> wrote:
>
>>cs-mgt：
>>eth1: 192.168.230.2
>>
>>xen01:
>>eth1: 192.168.230.11
>>eth2: public+guest   (guest network:192.168.30.0/24  )
>>eth3: 192.168.250.11
>>
>>xen01:
>>eth1: 192.168.230.12
>>eth2: public+guest  (guest network:192.168.30.0/24  )
>>eth3: 192.168.250.12
>>
>>Adv net, can work.
>>
>>I want to try VPC ,i have create VPC network 172.16.0.0/16 and tier
>>172.16.0.1/24.   tier network ACLs   ingress, egress TCP/UDP all
>>allowed configed
>>
>>VPC router have started and i check from console , it can access
>>internet and can access storage and cs.
>>
>>but fail to create vm in tier of VPC.
>>
>>#############   LOG #############################
>>2013-08-23 00:30:29,544 DEBUG [cloud.api.ApiServlet]
>>(catalina-exec-17:null) ===START===  192.168.123.28 -- GET
>>command=deployVirtualMachine&zoneId=6ad1fb5e-8a4b-42b7-83f2-863c1b3fda4a&t
>>emplateId=bd1a8e6a-b66f-4484-afcb-2af22890cff6&hypervisor=XenServer&servic
>>eOfferingId=fbf29251-423f-496c-8edb-32b9362c31ab&networkIds=d277c139-f896-
>>443a-a8cc-c74dcb5f92df&response=json&sessionkey=c%2FLK7Wzuq4ia5cxurIMYWevC
>>UkM%3D&_=1377192613840
>>2013-08-23 00:30:29,554 DEBUG [cloud.api.ApiDispatcher]
>>(catalina-exec-17:null) InfrastructureEntity name
>>is:com.cloud.offering.ServiceOffering
>>2013-08-23 00:30:29,556 DEBUG [cloud.api.ApiDispatcher]
>>(catalina-exec-17:null) ControlledEntity name
>>is:com.cloud.template.VirtualMachineTemplate
>>2013-08-23 00:30:29,560 DEBUG [cloud.api.ApiDispatcher]
>>(catalina-exec-17:null) ControlledEntity name
>>is:com.cloud.network.Network
>>2013-08-23 00:30:29,574 DEBUG [cloud.network.NetworkModelImpl]
>>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>>network id=207
>>2013-08-23 00:30:29,584 DEBUG [cloud.vm.UserVmManagerImpl]
>>(catalina-exec-17:null) Allocating in the DB for vm
>>2013-08-23 00:30:29,599 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(catalina-exec-17:null) Allocating entries for VM:
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:29,600 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(catalina-exec-17:null) Allocating nics for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:29,601 DEBUG [cloud.network.NetworkManagerImpl]
>>(catalina-exec-17:null) Allocating nic for vm
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in network
>>Ntwk[207|Guest|11] with requested profile
>>NicProfile[0-0-null-null-null
>>2013-08-23 00:30:29,617 DEBUG [cloud.network.NetworkModelImpl]
>>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>>network id=207
>>2013-08-23 00:30:29,618 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(catalina-exec-17:null) Allocaing disks for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:29,629 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(catalina-exec-17:null) Allocation completed for VM:
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:29,629 DEBUG [cloud.vm.UserVmManagerImpl]
>>(catalina-exec-17:null) Successfully allocated DB entry for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:29,651 DEBUG [cloud.network.NetworkModelImpl]
>>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>>network id=207
>>2013-08-23 00:30:29,657 DEBUG [cloud.network.NetworkModelImpl]
>>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>>network id=207
>>2013-08-23 00:30:29,674 DEBUG [cloud.async.AsyncJobManagerImpl]
>>(catalina-exec-17:null) submit async job-299, details: AsyncJobVO
>>{id:299, userId: 2, accountId: 2, sessionKey: null, instanceType:
>>VirtualMachine, instanceId: 171, cmd:
>>org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator:
>>null, cmdInfo:
>>{"id":"171","templateId":"bd1a8e6a-b66f-4484-afcb-2af22890cff6","response"
>>:"json","sessionkey":"c/LK7Wzuq4ia5cxurIMYWevCUkM\u003d","ctxUserId":"2","
>>networkIds":"d277c139-f896-443a-a8cc-c74dcb5f92df","hypervisor":"XenServer
>>","serviceOfferingId":"fbf29251-423f-496c-8edb-32b9362c31ab","_":"13771926
>>13840","ctxAccountId":"2","ctxStartEventId":"864","zoneId":"6ad1fb5e-8a4b-
>>42b7-83f2-863c1b3fda4a"},
>>cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
>>processStatus: 0, resultCode: 0, result: null, initMsid: 345050143793,
>>completeMsid: null, lastUpdated: null, lastPolled: null, created:
>>null}
>>2013-08-23 00:30:29,675 DEBUG [cloud.async.AsyncJobManagerImpl]
>>(Job-Executor-64:job-299) Executing
>>org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-299
>>2013-08-23 00:30:29,677 DEBUG [cloud.api.ApiServlet]
>>(catalina-exec-17:null) ===END===  192.168.123.28 -- GET
>>command=deployVirtualMachine&zoneId=6ad1fb5e-8a4b-42b7-83f2-863c1b3fda4a&t
>>emplateId=bd1a8e6a-b66f-4484-afcb-2af22890cff6&hypervisor=XenServer&servic
>>eOfferingId=fbf29251-423f-496c-8edb-32b9362c31ab&networkIds=d277c139-f896-
>>443a-a8cc-c74dcb5f92df&response=json&sessionkey=c%2FLK7Wzuq4ia5cxurIMYWevC
>>UkM%3D&_=1377192613840
>>2013-08-23 00:30:29,683 DEBUG [cloud.api.ApiDispatcher]
>>(Job-Executor-64:job-299) InfrastructureEntity name
>>is:com.cloud.offering.ServiceOffering
>>2013-08-23 00:30:29,686 DEBUG [cloud.api.ApiDispatcher]
>>(Job-Executor-64:job-299) ControlledEntity name
>>is:com.cloud.template.VirtualMachineTemplate
>>2013-08-23 00:30:29,690 DEBUG [cloud.api.ApiDispatcher]
>>(Job-Executor-64:job-299) ControlledEntity name
>>is:com.cloud.network.Network
>>2013-08-23 00:30:29,720 DEBUG [cloud.network.NetworkModelImpl]
>>(Job-Executor-64:job-299) Service SecurityGroup is not supported in
>>the network id=207
>>2013-08-23 00:30:29,725 DEBUG [cloud.network.NetworkModelImpl]
>>(Job-Executor-64:job-299) Service SecurityGroup is not supported in
>>the network id=207
>>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) DeploymentPlanner allocation algorithm:
>>random
>>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Trying to allocate a host and storage pools
>>from dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram:
>>1073741824
>>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Is ROOT volume READY (pool already
>>allocated)?: No
>>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Searching all possible resources under this
>>Zone: 1
>>2013-08-23 00:30:29,747 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Listing clusters in order of aggregate
>>capacity, that have (atleast one host with) enough CPU and RAM
>>capacity under this Zone: 1
>>2013-08-23 00:30:29,749 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) CPUOverprovisioningFactor considered: 1.0
>>2013-08-23 00:30:29,755 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Removing from the clusterId list these
>>clusters that are disabled/clusters under disabled pods: [2, 3, 4]
>>2013-08-23 00:30:29,763 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Checking resources in Cluster: 1 under Pod:
>>1
>>2013-08-23 00:30:29,766 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Looking for hosts
>>in dc: 1  pod:1  cluster:1
>>2013-08-23 00:30:29,769 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) FirstFitAllocator
>>has 2 hosts to check for allocation: [Host[-1-Routing],
>>Host[-2-Routing]]
>>2013-08-23 00:30:29,773 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found 2 hosts for
>>allocation after prioritization: [Host[-1-Routing], Host[-2-Routing]]
>>2013-08-23 00:30:29,773 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Looking for
>>speed=1000Mhz, Ram=1024
>>2013-08-23 00:30:29,776 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Checking if host: 1
>>has enough capacity for requested CPU: 1000 and requested RAM:
>>1073741824 , cpuOverprovisioningFactor: 1.0
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Hosts's actual
>>total CPU: 13590 and CPU after applying overprovisioning: 13590
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free CPU: 11590 ,
>>Requested CPU: 1000
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free RAM:
>>8645824576 , Requested RAM: 1073741824
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host has enough CPU
>>and RAM available
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>>CPU from host: 1, used: 2000, reserved: 0, actual total: 13590, total
>>with overprovisioning: 13590; requested
>>cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
>>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>>MEM from host: 1, used: 1342177280, reserved: 0, total: 9988001856;
>>requested mem: 1073741824,alloc_from_last_host?:false
>>,considerReservedCapacity?: true
>>2013-08-23 00:30:29,780 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found a suitable
>>host, adding to list: 1
>>2013-08-23 00:30:29,783 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Checking if host: 2
>>has enough capacity for requested CPU: 1000 and requested RAM:
>>1073741824 , cpuOverprovisioningFactor: 1.0
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Hosts's actual
>>total CPU: 13590 and CPU after applying overprovisioning: 13590
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free CPU: 8090 ,
>>Requested CPU: 1000
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free RAM:
>>4216639552 , Requested RAM: 1073741824
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host has enough CPU
>>and RAM available
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>>CPU from host: 2, used: 5500, reserved: 0, actual total: 13590, total
>>with overprovisioning: 13590; requested
>>cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
>>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>>MEM from host: 2, used: 5771362304, reserved: 0, total: 9988001856;
>>requested mem: 1073741824,alloc_from_last_host?:false
>>,considerReservedCapacity?: true
>>2013-08-23 00:30:29,787 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found a suitable
>>host, adding to list: 2
>>2013-08-23 00:30:29,787 DEBUG [allocator.impl.FirstFitAllocator]
>>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host Allocator
>>returning 2 suitable hosts
>>2013-08-23 00:30:29,789 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Checking suitable pools for volume (Id,
>>Type): (174,ROOT)
>>2013-08-23 00:30:29,789 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) We need to allocate new storagepool for this
>>volume
>>2013-08-23 00:30:29,791 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Calling StoragePoolAllocators to find
>>suitable pools
>>2013-08-23 00:30:29,793 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) Looking for pools in dc: 1  pod:1  cluster:1
>>2013-08-23 00:30:29,795 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator has 1 pools to
>>check for allocation
>>2013-08-23 00:30:29,795 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Checking if storage pool is suitable, name:
>>Primary00 ,poolId: 200
>>2013-08-23 00:30:29,795 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Is localStorageAllocationNeeded? false
>>2013-08-23 00:30:29,795 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Is storage pool shared? true
>>2013-08-23 00:30:29,798 DEBUG [cloud.storage.StorageManagerImpl]
>>(Job-Executor-64:job-299) Checking pool 200 for storage, totalSize:
>>594456936448, usedBytes: 135866548224, usedPct: 0.22855574540997034,
>>disable threshold: 0.85
>>2013-08-23 00:30:29,806 DEBUG [cloud.storage.StorageManagerImpl]
>>(Job-Executor-64:job-299) Checking pool: 200 for volume allocation
>>[Vol[174|vm=171|ROOT]], maxSize : 1188913872896, totalAllocatedSize :
>>56011117568, askingSize : 21474836480, allocated disable threshold:
>>0.85
>>2013-08-23 00:30:29,806 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator returning 1
>>suitable storage pools
>>2013-08-23 00:30:29,806 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Trying to find a potenial host and
>>associated storage pools from the suitable host/pool lists for this VM
>>2013-08-23 00:30:29,806 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Checking if host: 1 can access any suitable
>>storage pool for volume: ROOT
>>2013-08-23 00:30:29,808 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Host: 1 can access pool: 200
>>2013-08-23 00:30:29,808 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Found a potential host id: 1 name: xen02 and
>>associated storage pools for this VM
>>2013-08-23 00:30:29,810 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Returning Deployment Destination:
>>Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(I
>>d))]
>>:
>>Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200)
>>)]
>>2013-08-23 00:30:29,831 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) VM state transitted from :Stopped to
>>Starting with event: StartRequestedvm's original host id: null new
>>host id: null host id before state transition: null
>>2013-08-23 00:30:29,831 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Successfully transitioned to start state for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] reservation id =
>>8c058359-70c4-4661-9356-fa6893631f2e
>>2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Trying to deploy VM, vm has dcId: 1 and
>>podId: null
>>2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) advanceStart: DeploymentPlan is provided,
>>using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null
>>2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Deploy avoids pods: null, clusters: null,
>>hosts: null
>>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) DeploymentPlanner allocation algorithm:
>>random
>>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Trying to allocate a host and storage pools
>>from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram:
>>1073741824
>>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Is ROOT volume READY (pool already
>>allocated)?: No
>>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) DeploymentPlan has host_id specified,
>>choosing this host and making no checks on this host: 1
>>2013-08-23 00:30:29,840 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Looking for suitable pools for this host
>>under zone: 1, pod: 1, cluster: 1
>>2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Checking suitable pools for volume (Id,
>>Type): (174,ROOT)
>>2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) We need to allocate new storagepool for this
>>volume
>>2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Calling StoragePoolAllocators to find
>>suitable pools
>>2013-08-23 00:30:29,842 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) Looking for pools in dc: 1  pod:1  cluster:1
>>2013-08-23 00:30:29,843 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator has 1 pools to
>>check for allocation
>>2013-08-23 00:30:29,843 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Checking if storage pool is suitable, name:
>>Primary00 ,poolId: 200
>>2013-08-23 00:30:29,843 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Is localStorageAllocationNeeded? false
>>2013-08-23 00:30:29,843 DEBUG
>>[storage.allocator.AbstractStoragePoolAllocator]
>>(Job-Executor-64:job-299) Is storage pool shared? true
>>2013-08-23 00:30:29,846 DEBUG [cloud.storage.StorageManagerImpl]
>>(Job-Executor-64:job-299) Checking pool 200 for storage, totalSize:
>>594456936448, usedBytes: 135866548224, usedPct: 0.22855574540997034,
>>disable threshold: 0.85
>>2013-08-23 00:30:29,854 DEBUG [cloud.storage.StorageManagerImpl]
>>(Job-Executor-64:job-299) Checking pool: 200 for volume allocation
>>[Vol[174|vm=171|ROOT]], maxSize : 1188913872896, totalAllocatedSize :
>>56011117568, askingSize : 21474836480, allocated disable threshold:
>>0.85
>>2013-08-23 00:30:29,854 DEBUG
>>[storage.allocator.FirstFitStoragePoolAllocator]
>>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator returning 1
>>suitable storage pools
>>2013-08-23 00:30:29,854 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Trying to find a potenial host and
>>associated storage pools from the suitable host/pool lists for this VM
>>2013-08-23 00:30:29,854 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Checking if host: 1 can access any suitable
>>storage pool for volume: ROOT
>>2013-08-23 00:30:29,855 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Host: 1 can access pool: 200
>>2013-08-23 00:30:29,856 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Found a potential host id: 1 name: xen02 and
>>associated storage pools for this VM
>>2013-08-23 00:30:29,857 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) Returning Deployment Destination:
>>Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(I
>>d))]
>>:
>>Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200)
>>)]
>>2013-08-23 00:30:29,857 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Deployment found  -
>>P0=VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621],
>>P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Poo
>>l(Id))]
>>:
>>Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200)
>>)]
>>2013-08-23 00:30:29,862 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) VM state transitted from :Starting to
>>Starting with event: OperationRetryvm's original host id: null new
>>host id: 1 host id before state transition: null
>>2013-08-23 00:30:29,871 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) Hosts's actual total CPU: 13590 and CPU
>>after applying overprovisioning: 13590
>>2013-08-23 00:30:29,871 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) We are allocating VM, increasing the used
>>capacity of this host:1
>>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) Current Used CPU: 2000 , Free CPU:11590
>>,Requested CPU: 1000
>>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) Current Used RAM: 1342177280 , Free
>>RAM:8645824576 ,Requested RAM: 1073741824
>>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) CPU STATS after allocation: for host: 1, old
>>used: 2000, old reserved: 0, actual total: 13590, total with
>>overprovisioning: 13590; new used:3000, reserved:0; requested
>>cpu:1000,alloc_from_last:false
>>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) RAM STATS after allocation: for host: 1, old
>>used: 1342177280, old reserved: 0, total: 9988001856; new used:
>>2415919104, reserved: 0; requested mem:
>>1073741824,alloc_from_last:false
>>2013-08-23 00:30:29,875 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) VM is being created in podId: 1
>>2013-08-23 00:30:29,879 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Lock is acquired for network id 207 as a
>>part of network implement
>>2013-08-23 00:30:29,879 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Asking ExternalGuestNetworkGuru to implement
>>Ntwk[207|Guest|11]
>>2013-08-23 00:30:29,889 DEBUG [db.Transaction.Transaction]
>>(Job-Executor-64:job-299) Rolling back the transaction: Time = 1 Name
>>=
>>-AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTa
>>sk$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1146-
>>ThreadPoolExecutor$Worker.run:615-Thread.run:679;
>>called by
>>-Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657
>>-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPost
>>Processor$InterceptorDispatcher.intercept:131-DataCenterDaoImpl.allocateVn
>>et:192-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept
>>:125-GuestNetworkGuru.allocateVnet:294-GuestNetworkGuru.implement:326-Exte
>>rnalGuestNetworkGuru.implement:123-NetworkManagerImpl.implementNetwork:142
>>5-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125
>>2013-08-23 00:30:29,890 INFO  [utils.exception.CSExceptionErrorCode]
>>(Job-Executor-64:job-299) Could not find exception:
>>com.cloud.exception.InsufficientVirtualNetworkCapcityException in
>>error code list for exceptions
>>2013-08-23 00:30:29,890 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Cleaning up because we're unable to
>>implement the network Ntwk[207|Guest|11]
>>2013-08-23 00:30:29,899 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Releasing 0 port forwarding rules for
>>network id=207 as a part of shutdownNetworkRules
>>2013-08-23 00:30:29,899 DEBUG [network.firewall.FirewallManagerImpl]
>>(Job-Executor-64:job-299) There are no rules to forward to the network
>>elements
>>2013-08-23 00:30:29,900 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Releasing 0 static nat rules for network
>>id=207 as a part of shutdownNetworkRules
>>2013-08-23 00:30:29,900 DEBUG [network.firewall.FirewallManagerImpl]
>>(Job-Executor-64:job-299) There are no rules to forward to the network
>>elements
>>2013-08-23 00:30:29,901 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) There are no rules to forward to the network
>>elements
>>2013-08-23 00:30:29,902 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Releasing 0 firewall ingress rules for
>>network id=207 as a part of shutdownNetworkRules
>>2013-08-23 00:30:29,902 DEBUG [network.firewall.FirewallManagerImpl]
>>(Job-Executor-64:job-299) There are no rules to forward to the network
>>elements
>>2013-08-23 00:30:29,903 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Releasing 0 firewall egress rules for
>>network id=207 as a part of shutdownNetworkRules
>>2013-08-23 00:30:29,903 DEBUG [network.firewall.FirewallManagerImpl]
>>(Job-Executor-64:job-299) There are no rules to forward to the network
>>elements
>>2013-08-23 00:30:29,906 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Releasing 6 Network ACLs for network id=207
>>as a part of shutdownNetworkRules
>>2013-08-23 00:30:29,919 DEBUG
>>[network.element.VpcVirtualRouterElement] (Job-Executor-64:job-299)
>>Virtual router elemnt doesn't need to apply firewall rules on the
>>backend; virtual router doesn't exist in the network 207
>>2013-08-23 00:30:29,923 DEBUG [network.rules.RulesManagerImpl]
>>(Job-Executor-64:job-299) Found 0 static nat rules to apply for
>>network id 207
>>2013-08-23 00:30:29,931 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Sending network shutdown to VpcVirtualRouter
>>2013-08-23 00:30:29,936 DEBUG
>>[network.element.VpcVirtualRouterElement] (Job-Executor-64:job-299)
>>Router VM[DomainRouter|r-166-VM] is not a part the network
>>Ntwk[207|Guest|11]
>>2013-08-23 00:30:29,936 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Network id=207 is shutdown successfully,
>>cleaning up corresponding resources now.
>>2013-08-23 00:30:29,942 DEBUG [cloud.network.NetworkManagerImpl]
>>(Job-Executor-64:job-299) Lock is released for network id 207 as a
>>part of network implement
>>2013-08-23 00:30:29,942 INFO  [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Insufficient capacity
>>com.cloud.exception.InsufficientVirtualNetworkCapcityException: Unable
>>to allocate vnet as a part of network Ntwk[207|Guest|11] implement
>>Scope=interface com.cloud.dc.DataCenter; id=1
>>at
>>com.cloud.network.guru.GuestNetworkGuru.allocateVnet(GuestNetworkGuru.java
>>:296)
>>at
>>com.cloud.network.guru.GuestNetworkGuru.implement(GuestNetworkGuru.java:32
>>6)
>>at
>>com.cloud.network.guru.ExternalGuestNetworkGuru.implement(ExternalGuestNet
>>workGuru.java:123)
>>at
>>com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.j
>>ava:1425)
>>at
>>com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorD
>>ispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>>at
>>com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:1596)
>>at
>>com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerI
>>mpl.java:746)
>>at
>>com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.jav
>>a:471)
>>at
>>org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVi
>>rtualMachine(VMEntityManagerImpl.java:212)
>>at
>>org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.dep
>>loy(VirtualMachineEntityImpl.java:209)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3871)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3464)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3450)
>>at
>>com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorD
>>ispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>>at
>>org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.
>>java:379)
>>at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
>>at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
>>at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>>at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>>at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>>at
>>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>>1146)
>>at
>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>>:615)
>>at java.lang.Thread.run(Thread.java:679)
>>2013-08-23 00:30:29,945 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Cleaning up resources for the vm
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in Starting state
>>2013-08-23 00:30:29,947 DEBUG [agent.transport.Request]
>>(Job-Executor-64:job-299) Seq 1-1023805316: Sending  { Cmd , MgmtId:
>>345050143793, via: 1, Ver: v1, Flags: 100111,
>>[{"StopCommand":{"isProxy":false,"vmName":"i-2-171-VM","wait":0}}] }
>>2013-08-23 00:30:29,947 DEBUG [agent.transport.Request]
>>(Job-Executor-64:job-299) Seq 1-1023805316: Executing:  { Cmd ,
>>MgmtId: 345050143793, via: 1, Ver: v1, Flags: 100111,
>>[{"StopCommand":{"isProxy":false,"vmName":"i-2-171-VM","wait":0}}] }
>>2013-08-23 00:30:29,947 DEBUG [agent.manager.DirectAgentAttache]
>>(DirectAgent-395:null) Seq 1-1023805316: Executing request
>>2013-08-23 00:30:30,209 INFO  [xen.resource.CitrixResourceBase]
>>(DirectAgent-395:null) VM does not exist on
>>XenServer992cb98d-123a-4cb6-8410-1532bbcb60f5
>>2013-08-23 00:30:30,210 DEBUG [agent.manager.DirectAgentAttache]
>>(DirectAgent-395:null) Seq 1-1023805316: Response Received:
>>2013-08-23 00:30:30,210 DEBUG [agent.transport.Request]
>>(DirectAgent-395:null) Seq 1-1023805316: Processing:  { Ans: , MgmtId:
>>345050143793, via: 1, Ver: v1, Flags: 110,
>>[{"StopAnswer":{"vncPort":0,"result":true,"details":"VM does not
>>exist","wait":0}}] }
>>2013-08-23 00:30:30,210 DEBUG [agent.manager.AgentAttache]
>>(DirectAgent-395:null) Seq 1-1023805316: No more commands found
>>2013-08-23 00:30:30,210 DEBUG [agent.transport.Request]
>>(Job-Executor-64:job-299) Seq 1-1023805316: Received:  { Ans: ,
>>MgmtId: 345050143793, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
>>2013-08-23 00:30:30,217 DEBUG [db.Transaction.Transaction]
>>(Job-Executor-64:job-299) Rolling back the transaction: Time = 2 Name
>>=
>>-AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTa
>>sk$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1146-
>>ThreadPoolExecutor$Worker.run:615-Thread.run:679;
>>called by
>>-Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657
>>-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPost
>>Processor$InterceptorDispatcher.intercept:131-NetworkManagerImpl.release:1
>>687-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:12
>>5-VirtualMachineManagerImpl.cleanup:962-VirtualMachineManagerImpl.advanceS
>>tart:850-VirtualMachineManagerImpl.start:471-VMEntityManagerImpl.deployVir
>>tualMachine:212-VirtualMachineEntityImpl.deploy:209
>>2013-08-23 00:30:30,217 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Successfully released network resources for
>>the vm VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>2013-08-23 00:30:30,217 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>>(Job-Executor-64:job-299) Successfully cleanued up resources for the
>>vm VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in Starting state
>>2013-08-23 00:30:30,219 DEBUG [cloud.deploy.FirstFitPlanner]
>>(Job-Executor-64:job-299) DataCenter id = '1' provided is in avoid
>>set, DeploymentPlanner cannot allocate the VM, returning.
>>2013-08-23 00:30:30,225 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) VM state transitted from :Starting to
>>Stopped with event: OperationFailedvm's original host id: null new
>>host id: null host id before state transition: 1
>>2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) Hosts's actual total CPU: 13590 and CPU
>>after applying overprovisioning: 13590
>>2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) release cpu from host: 1, old used:
>>3000,reserved: 0, actual total: 13590, total with overprovisioning:
>>13590; new used: 2000,reserved:0; movedfromreserved:
>>false,moveToReserveredfalse
>>2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) release mem from host: 1, old used:
>>2415919104,reserved: 0, total: 9988001856; new used:
>>1342177280,reserved:0; movedfromreserved: false,moveToReserveredfalse
>>2013-08-23 00:30:30,236 DEBUG [cloud.vm.UserVmManagerImpl]
>>(Job-Executor-64:job-299) Destroying vm
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] as it failed to create
>>on Host with Id:null
>>2013-08-23 00:30:30,242 DEBUG [cloud.capacity.CapacityManagerImpl]
>>(Job-Executor-64:job-299) VM state transitted from :Stopped to Error
>>with event: OperationFailedToErrorvm's original host id: null new host
>>id: null host id before state transition: null
>>2013-08-23 00:30:30,277 INFO  [user.vm.DeployVMCmd]
>>(Job-Executor-64:job-299)
>>com.cloud.exception.InsufficientServerCapacityException: Unable to
>>create a deployment for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]Scope=interface
>>com.cloud.dc.DataCenter; id=1
>>2013-08-23 00:30:30,277 INFO  [user.vm.DeployVMCmd]
>>(Job-Executor-64:job-299) Unable to create a deployment for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>>com.cloud.exception.InsufficientServerCapacityException: Unable to
>>create a deployment for
>>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]Scope=interface
>>com.cloud.dc.DataCenter; id=1
>>at
>>com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerI
>>mpl.java:728)
>>at
>>com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.jav
>>a:471)
>>at
>>org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVi
>>rtualMachine(VMEntityManagerImpl.java:212)
>>at
>>org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.dep
>>loy(VirtualMachineEntityImpl.java:209)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3871)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3464)
>>at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>>3450)
>>at
>>com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorD
>>ispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>>at
>>org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.
>>java:379)
>>at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
>>at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
>>at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>>at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>>at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>>at
>>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>>1146)
>>at
>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>>:615)
>>at java.lang.Thread.run(Thread.java:679)
>>2013-08-23 00:30:30,278 DEBUG [cloud.async.AsyncJobManagerImpl]
>>(Job-Executor-64:job-299) Complete async job-299, jobStatus: 2,
>>resultCode: 530, result: Error Code: 533 Error text: Unable to create
>>a deployment for VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>

Re: Fail to create Instance in VPC on CS4.1.1

Posted by Chiradeep Vittal <Ch...@citrix.com>.

This might be the problem:
2013-08-23 00:30:29,942 INFO  [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-299) Insufficient capacity
com.cloud.exception.InsufficientVirtualNetworkCapcityException: Unable
to allocate vnet as a part of network Ntwk[207|Guest|11] implement
Scope=interface com.cloud.dc.DataCenter; id=1



On 8/22/13 10:51 AM, "不坏阿峰" <on...@gmail.com> wrote:

>cs-mgt：
>eth1: 192.168.230.2
>
>xen01:
>eth1: 192.168.230.11
>eth2: public+guest   (guest network:192.168.30.0/24  )
>eth3: 192.168.250.11
>
>xen01:
>eth1: 192.168.230.12
>eth2: public+guest  (guest network:192.168.30.0/24  )
>eth3: 192.168.250.12
>
>Adv net, can work.
>
>I want to try VPC ,i have create VPC network 172.16.0.0/16 and tier
>172.16.0.1/24.   tier network ACLs   ingress, egress TCP/UDP all
>allowed configed
>
>VPC router have started and i check from console , it can access
>internet and can access storage and cs.
>
>but fail to create vm in tier of VPC.
>
>#############   LOG #############################
>2013-08-23 00:30:29,544 DEBUG [cloud.api.ApiServlet]
>(catalina-exec-17:null) ===START===  192.168.123.28 -- GET
>command=deployVirtualMachine&zoneId=6ad1fb5e-8a4b-42b7-83f2-863c1b3fda4a&t
>emplateId=bd1a8e6a-b66f-4484-afcb-2af22890cff6&hypervisor=XenServer&servic
>eOfferingId=fbf29251-423f-496c-8edb-32b9362c31ab&networkIds=d277c139-f896-
>443a-a8cc-c74dcb5f92df&response=json&sessionkey=c%2FLK7Wzuq4ia5cxurIMYWevC
>UkM%3D&_=1377192613840
>2013-08-23 00:30:29,554 DEBUG [cloud.api.ApiDispatcher]
>(catalina-exec-17:null) InfrastructureEntity name
>is:com.cloud.offering.ServiceOffering
>2013-08-23 00:30:29,556 DEBUG [cloud.api.ApiDispatcher]
>(catalina-exec-17:null) ControlledEntity name
>is:com.cloud.template.VirtualMachineTemplate
>2013-08-23 00:30:29,560 DEBUG [cloud.api.ApiDispatcher]
>(catalina-exec-17:null) ControlledEntity name
>is:com.cloud.network.Network
>2013-08-23 00:30:29,574 DEBUG [cloud.network.NetworkModelImpl]
>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>network id=207
>2013-08-23 00:30:29,584 DEBUG [cloud.vm.UserVmManagerImpl]
>(catalina-exec-17:null) Allocating in the DB for vm
>2013-08-23 00:30:29,599 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(catalina-exec-17:null) Allocating entries for VM:
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>2013-08-23 00:30:29,600 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(catalina-exec-17:null) Allocating nics for
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>2013-08-23 00:30:29,601 DEBUG [cloud.network.NetworkManagerImpl]
>(catalina-exec-17:null) Allocating nic for vm
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in network
>Ntwk[207|Guest|11] with requested profile
>NicProfile[0-0-null-null-null
>2013-08-23 00:30:29,617 DEBUG [cloud.network.NetworkModelImpl]
>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>network id=207
>2013-08-23 00:30:29,618 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(catalina-exec-17:null) Allocaing disks for
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>2013-08-23 00:30:29,629 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(catalina-exec-17:null) Allocation completed for VM:
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>2013-08-23 00:30:29,629 DEBUG [cloud.vm.UserVmManagerImpl]
>(catalina-exec-17:null) Successfully allocated DB entry for
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>2013-08-23 00:30:29,651 DEBUG [cloud.network.NetworkModelImpl]
>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>network id=207
>2013-08-23 00:30:29,657 DEBUG [cloud.network.NetworkModelImpl]
>(catalina-exec-17:null) Service SecurityGroup is not supported in the
>network id=207
>2013-08-23 00:30:29,674 DEBUG [cloud.async.AsyncJobManagerImpl]
>(catalina-exec-17:null) submit async job-299, details: AsyncJobVO
>{id:299, userId: 2, accountId: 2, sessionKey: null, instanceType:
>VirtualMachine, instanceId: 171, cmd:
>org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator:
>null, cmdInfo: 
>{"id":"171","templateId":"bd1a8e6a-b66f-4484-afcb-2af22890cff6","response"
>:"json","sessionkey":"c/LK7Wzuq4ia5cxurIMYWevCUkM\u003d","ctxUserId":"2","
>networkIds":"d277c139-f896-443a-a8cc-c74dcb5f92df","hypervisor":"XenServer
>","serviceOfferingId":"fbf29251-423f-496c-8edb-32b9362c31ab","_":"13771926
>13840","ctxAccountId":"2","ctxStartEventId":"864","zoneId":"6ad1fb5e-8a4b-
>42b7-83f2-863c1b3fda4a"},
>cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
>processStatus: 0, resultCode: 0, result: null, initMsid: 345050143793,
>completeMsid: null, lastUpdated: null, lastPolled: null, created:
>null}
>2013-08-23 00:30:29,675 DEBUG [cloud.async.AsyncJobManagerImpl]
>(Job-Executor-64:job-299) Executing
>org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-299
>2013-08-23 00:30:29,677 DEBUG [cloud.api.ApiServlet]
>(catalina-exec-17:null) ===END===  192.168.123.28 -- GET
>command=deployVirtualMachine&zoneId=6ad1fb5e-8a4b-42b7-83f2-863c1b3fda4a&t
>emplateId=bd1a8e6a-b66f-4484-afcb-2af22890cff6&hypervisor=XenServer&servic
>eOfferingId=fbf29251-423f-496c-8edb-32b9362c31ab&networkIds=d277c139-f896-
>443a-a8cc-c74dcb5f92df&response=json&sessionkey=c%2FLK7Wzuq4ia5cxurIMYWevC
>UkM%3D&_=1377192613840
>2013-08-23 00:30:29,683 DEBUG [cloud.api.ApiDispatcher]
>(Job-Executor-64:job-299) InfrastructureEntity name
>is:com.cloud.offering.ServiceOffering
>2013-08-23 00:30:29,686 DEBUG [cloud.api.ApiDispatcher]
>(Job-Executor-64:job-299) ControlledEntity name
>is:com.cloud.template.VirtualMachineTemplate
>2013-08-23 00:30:29,690 DEBUG [cloud.api.ApiDispatcher]
>(Job-Executor-64:job-299) ControlledEntity name
>is:com.cloud.network.Network
>2013-08-23 00:30:29,720 DEBUG [cloud.network.NetworkModelImpl]
>(Job-Executor-64:job-299) Service SecurityGroup is not supported in
>the network id=207
>2013-08-23 00:30:29,725 DEBUG [cloud.network.NetworkModelImpl]
>(Job-Executor-64:job-299) Service SecurityGroup is not supported in
>the network id=207
>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) DeploymentPlanner allocation algorithm:
>random
>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Trying to allocate a host and storage pools
>from dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram:
>1073741824
>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Is ROOT volume READY (pool already
>allocated)?: No
>2013-08-23 00:30:29,739 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Searching all possible resources under this
>Zone: 1
>2013-08-23 00:30:29,747 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Listing clusters in order of aggregate
>capacity, that have (atleast one host with) enough CPU and RAM
>capacity under this Zone: 1
>2013-08-23 00:30:29,749 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) CPUOverprovisioningFactor considered: 1.0
>2013-08-23 00:30:29,755 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Removing from the clusterId list these
>clusters that are disabled/clusters under disabled pods: [2, 3, 4]
>2013-08-23 00:30:29,763 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Checking resources in Cluster: 1 under Pod:
>1
>2013-08-23 00:30:29,766 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Looking for hosts
>in dc: 1  pod:1  cluster:1
>2013-08-23 00:30:29,769 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) FirstFitAllocator
>has 2 hosts to check for allocation: [Host[-1-Routing],
>Host[-2-Routing]]
>2013-08-23 00:30:29,773 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found 2 hosts for
>allocation after prioritization: [Host[-1-Routing], Host[-2-Routing]]
>2013-08-23 00:30:29,773 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Looking for
>speed=1000Mhz, Ram=1024
>2013-08-23 00:30:29,776 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Checking if host: 1
>has enough capacity for requested CPU: 1000 and requested RAM:
>1073741824 , cpuOverprovisioningFactor: 1.0
>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Hosts's actual
>total CPU: 13590 and CPU after applying overprovisioning: 13590
>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free CPU: 11590 ,
>Requested CPU: 1000
>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free RAM:
>8645824576 , Requested RAM: 1073741824
>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host has enough CPU
>and RAM available
>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>CPU from host: 1, used: 2000, reserved: 0, actual total: 13590, total
>with overprovisioning: 13590; requested
>cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
>2013-08-23 00:30:29,780 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>MEM from host: 1, used: 1342177280, reserved: 0, total: 9988001856;
>requested mem: 1073741824,alloc_from_last_host?:false
>,considerReservedCapacity?: true
>2013-08-23 00:30:29,780 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found a suitable
>host, adding to list: 1
>2013-08-23 00:30:29,783 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Checking if host: 2
>has enough capacity for requested CPU: 1000 and requested RAM:
>1073741824 , cpuOverprovisioningFactor: 1.0
>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Hosts's actual
>total CPU: 13590 and CPU after applying overprovisioning: 13590
>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free CPU: 8090 ,
>Requested CPU: 1000
>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Free RAM:
>4216639552 , Requested RAM: 1073741824
>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host has enough CPU
>and RAM available
>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>CPU from host: 2, used: 5500, reserved: 0, actual total: 13590, total
>with overprovisioning: 13590; requested
>cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
>2013-08-23 00:30:29,787 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) STATS: Can alloc
>MEM from host: 2, used: 5771362304, reserved: 0, total: 9988001856;
>requested mem: 1073741824,alloc_from_last_host?:false
>,considerReservedCapacity?: true
>2013-08-23 00:30:29,787 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Found a suitable
>host, adding to list: 2
>2013-08-23 00:30:29,787 DEBUG [allocator.impl.FirstFitAllocator]
>(Job-Executor-64:job-299 FirstFitRoutingAllocator) Host Allocator
>returning 2 suitable hosts
>2013-08-23 00:30:29,789 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Checking suitable pools for volume (Id,
>Type): (174,ROOT)
>2013-08-23 00:30:29,789 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) We need to allocate new storagepool for this
>volume
>2013-08-23 00:30:29,791 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Calling StoragePoolAllocators to find
>suitable pools
>2013-08-23 00:30:29,793 DEBUG
>[storage.allocator.FirstFitStoragePoolAllocator]
>(Job-Executor-64:job-299) Looking for pools in dc: 1  pod:1  cluster:1
>2013-08-23 00:30:29,795 DEBUG
>[storage.allocator.FirstFitStoragePoolAllocator]
>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator has 1 pools to
>check for allocation
>2013-08-23 00:30:29,795 DEBUG
>[storage.allocator.AbstractStoragePoolAllocator]
>(Job-Executor-64:job-299) Checking if storage pool is suitable, name:
>Primary00 ,poolId: 200
>2013-08-23 00:30:29,795 DEBUG
>[storage.allocator.AbstractStoragePoolAllocator]
>(Job-Executor-64:job-299) Is localStorageAllocationNeeded? false
>2013-08-23 00:30:29,795 DEBUG
>[storage.allocator.AbstractStoragePoolAllocator]
>(Job-Executor-64:job-299) Is storage pool shared? true
>2013-08-23 00:30:29,798 DEBUG [cloud.storage.StorageManagerImpl]
>(Job-Executor-64:job-299) Checking pool 200 for storage, totalSize:
>594456936448, usedBytes: 135866548224, usedPct: 0.22855574540997034,
>disable threshold: 0.85
>2013-08-23 00:30:29,806 DEBUG [cloud.storage.StorageManagerImpl]
>(Job-Executor-64:job-299) Checking pool: 200 for volume allocation
>[Vol[174|vm=171|ROOT]], maxSize : 1188913872896, totalAllocatedSize :
>56011117568, askingSize : 21474836480, allocated disable threshold:
>0.85
>2013-08-23 00:30:29,806 DEBUG
>[storage.allocator.FirstFitStoragePoolAllocator]
>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator returning 1
>suitable storage pools
>2013-08-23 00:30:29,806 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Trying to find a potenial host and
>associated storage pools from the suitable host/pool lists for this VM
>2013-08-23 00:30:29,806 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Checking if host: 1 can access any suitable
>storage pool for volume: ROOT
>2013-08-23 00:30:29,808 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Host: 1 can access pool: 200
>2013-08-23 00:30:29,808 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Found a potential host id: 1 name: xen02 and
>associated storage pools for this VM
>2013-08-23 00:30:29,810 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Returning Deployment Destination:
>Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(I
>d))]
>: 
>Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200)
>)]
>2013-08-23 00:30:29,831 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) VM state transitted from :Stopped to
>Starting with event: StartRequestedvm's original host id: null new
>host id: null host id before state transition: null
>2013-08-23 00:30:29,831 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-64:job-299) Successfully transitioned to start state for
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] reservation id =
>8c058359-70c4-4661-9356-fa6893631f2e
>2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-64:job-299) Trying to deploy VM, vm has dcId: 1 and
>podId: null
>2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-64:job-299) advanceStart: DeploymentPlan is provided,
>using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null
>2013-08-23 00:30:29,835 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-64:job-299) Deploy avoids pods: null, clusters: null,
>hosts: null
>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) DeploymentPlanner allocation algorithm:
>random
>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Trying to allocate a host and storage pools
>from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram:
>1073741824
>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Is ROOT volume READY (pool already
>allocated)?: No
>2013-08-23 00:30:29,838 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) DeploymentPlan has host_id specified,
>choosing this host and making no checks on this host: 1
>2013-08-23 00:30:29,840 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Looking for suitable pools for this host
>under zone: 1, pod: 1, cluster: 1
>2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Checking suitable pools for volume (Id,
>Type): (174,ROOT)
>2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) We need to allocate new storagepool for this
>volume
>2013-08-23 00:30:29,841 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Calling StoragePoolAllocators to find
>suitable pools
>2013-08-23 00:30:29,842 DEBUG
>[storage.allocator.FirstFitStoragePoolAllocator]
>(Job-Executor-64:job-299) Looking for pools in dc: 1  pod:1  cluster:1
>2013-08-23 00:30:29,843 DEBUG
>[storage.allocator.FirstFitStoragePoolAllocator]
>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator has 1 pools to
>check for allocation
>2013-08-23 00:30:29,843 DEBUG
>[storage.allocator.AbstractStoragePoolAllocator]
>(Job-Executor-64:job-299) Checking if storage pool is suitable, name:
>Primary00 ,poolId: 200
>2013-08-23 00:30:29,843 DEBUG
>[storage.allocator.AbstractStoragePoolAllocator]
>(Job-Executor-64:job-299) Is localStorageAllocationNeeded? false
>2013-08-23 00:30:29,843 DEBUG
>[storage.allocator.AbstractStoragePoolAllocator]
>(Job-Executor-64:job-299) Is storage pool shared? true
>2013-08-23 00:30:29,846 DEBUG [cloud.storage.StorageManagerImpl]
>(Job-Executor-64:job-299) Checking pool 200 for storage, totalSize:
>594456936448, usedBytes: 135866548224, usedPct: 0.22855574540997034,
>disable threshold: 0.85
>2013-08-23 00:30:29,854 DEBUG [cloud.storage.StorageManagerImpl]
>(Job-Executor-64:job-299) Checking pool: 200 for volume allocation
>[Vol[174|vm=171|ROOT]], maxSize : 1188913872896, totalAllocatedSize :
>56011117568, askingSize : 21474836480, allocated disable threshold:
>0.85
>2013-08-23 00:30:29,854 DEBUG
>[storage.allocator.FirstFitStoragePoolAllocator]
>(Job-Executor-64:job-299) FirstFitStoragePoolAllocator returning 1
>suitable storage pools
>2013-08-23 00:30:29,854 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Trying to find a potenial host and
>associated storage pools from the suitable host/pool lists for this VM
>2013-08-23 00:30:29,854 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Checking if host: 1 can access any suitable
>storage pool for volume: ROOT
>2013-08-23 00:30:29,855 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Host: 1 can access pool: 200
>2013-08-23 00:30:29,856 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Found a potential host id: 1 name: xen02 and
>associated storage pools for this VM
>2013-08-23 00:30:29,857 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) Returning Deployment Destination:
>Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(I
>d))]
>: 
>Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200)
>)]
>2013-08-23 00:30:29,857 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-64:job-299) Deployment found  -
>P0=VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621],
>P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Poo
>l(Id))]
>: 
>Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(174|ROOT-->Pool(200)
>)]
>2013-08-23 00:30:29,862 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) VM state transitted from :Starting to
>Starting with event: OperationRetryvm's original host id: null new
>host id: 1 host id before state transition: null
>2013-08-23 00:30:29,871 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) Hosts's actual total CPU: 13590 and CPU
>after applying overprovisioning: 13590
>2013-08-23 00:30:29,871 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) We are allocating VM, increasing the used
>capacity of this host:1
>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) Current Used CPU: 2000 , Free CPU:11590
>,Requested CPU: 1000
>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) Current Used RAM: 1342177280 , Free
>RAM:8645824576 ,Requested RAM: 1073741824
>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) CPU STATS after allocation: for host: 1, old
>used: 2000, old reserved: 0, actual total: 13590, total with
>overprovisioning: 13590; new used:3000, reserved:0; requested
>cpu:1000,alloc_from_last:false
>2013-08-23 00:30:29,872 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) RAM STATS after allocation: for host: 1, old
>used: 1342177280, old reserved: 0, total: 9988001856; new used:
>2415919104, reserved: 0; requested mem:
>1073741824,alloc_from_last:false
>2013-08-23 00:30:29,875 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-64:job-299) VM is being created in podId: 1
>2013-08-23 00:30:29,879 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Lock is acquired for network id 207 as a
>part of network implement
>2013-08-23 00:30:29,879 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Asking ExternalGuestNetworkGuru to implement
>Ntwk[207|Guest|11]
>2013-08-23 00:30:29,889 DEBUG [db.Transaction.Transaction]
>(Job-Executor-64:job-299) Rolling back the transaction: Time = 1 Name
>=  
>-AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTa
>sk$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1146-
>ThreadPoolExecutor$Worker.run:615-Thread.run:679;
>called by 
>-Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657
>-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPost
>Processor$InterceptorDispatcher.intercept:131-DataCenterDaoImpl.allocateVn
>et:192-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept
>:125-GuestNetworkGuru.allocateVnet:294-GuestNetworkGuru.implement:326-Exte
>rnalGuestNetworkGuru.implement:123-NetworkManagerImpl.implementNetwork:142
>5-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125
>2013-08-23 00:30:29,890 INFO  [utils.exception.CSExceptionErrorCode]
>(Job-Executor-64:job-299) Could not find exception:
>com.cloud.exception.InsufficientVirtualNetworkCapcityException in
>error code list for exceptions
>2013-08-23 00:30:29,890 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Cleaning up because we're unable to
>implement the network Ntwk[207|Guest|11]
>2013-08-23 00:30:29,899 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Releasing 0 port forwarding rules for
>network id=207 as a part of shutdownNetworkRules
>2013-08-23 00:30:29,899 DEBUG [network.firewall.FirewallManagerImpl]
>(Job-Executor-64:job-299) There are no rules to forward to the network
>elements
>2013-08-23 00:30:29,900 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Releasing 0 static nat rules for network
>id=207 as a part of shutdownNetworkRules
>2013-08-23 00:30:29,900 DEBUG [network.firewall.FirewallManagerImpl]
>(Job-Executor-64:job-299) There are no rules to forward to the network
>elements
>2013-08-23 00:30:29,901 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) There are no rules to forward to the network
>elements
>2013-08-23 00:30:29,902 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Releasing 0 firewall ingress rules for
>network id=207 as a part of shutdownNetworkRules
>2013-08-23 00:30:29,902 DEBUG [network.firewall.FirewallManagerImpl]
>(Job-Executor-64:job-299) There are no rules to forward to the network
>elements
>2013-08-23 00:30:29,903 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Releasing 0 firewall egress rules for
>network id=207 as a part of shutdownNetworkRules
>2013-08-23 00:30:29,903 DEBUG [network.firewall.FirewallManagerImpl]
>(Job-Executor-64:job-299) There are no rules to forward to the network
>elements
>2013-08-23 00:30:29,906 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Releasing 6 Network ACLs for network id=207
>as a part of shutdownNetworkRules
>2013-08-23 00:30:29,919 DEBUG
>[network.element.VpcVirtualRouterElement] (Job-Executor-64:job-299)
>Virtual router elemnt doesn't need to apply firewall rules on the
>backend; virtual router doesn't exist in the network 207
>2013-08-23 00:30:29,923 DEBUG [network.rules.RulesManagerImpl]
>(Job-Executor-64:job-299) Found 0 static nat rules to apply for
>network id 207
>2013-08-23 00:30:29,931 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Sending network shutdown to VpcVirtualRouter
>2013-08-23 00:30:29,936 DEBUG
>[network.element.VpcVirtualRouterElement] (Job-Executor-64:job-299)
>Router VM[DomainRouter|r-166-VM] is not a part the network
>Ntwk[207|Guest|11]
>2013-08-23 00:30:29,936 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Network id=207 is shutdown successfully,
>cleaning up corresponding resources now.
>2013-08-23 00:30:29,942 DEBUG [cloud.network.NetworkManagerImpl]
>(Job-Executor-64:job-299) Lock is released for network id 207 as a
>part of network implement
>2013-08-23 00:30:29,942 INFO  [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-64:job-299) Insufficient capacity
>com.cloud.exception.InsufficientVirtualNetworkCapcityException: Unable
>to allocate vnet as a part of network Ntwk[207|Guest|11] implement
>Scope=interface com.cloud.dc.DataCenter; id=1
>at 
>com.cloud.network.guru.GuestNetworkGuru.allocateVnet(GuestNetworkGuru.java
>:296)
>at 
>com.cloud.network.guru.GuestNetworkGuru.implement(GuestNetworkGuru.java:32
>6)
>at 
>com.cloud.network.guru.ExternalGuestNetworkGuru.implement(ExternalGuestNet
>workGuru.java:123)
>at 
>com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.j
>ava:1425)
>at 
>com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorD
>ispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>at 
>com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:1596)
>at 
>com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerI
>mpl.java:746)
>at 
>com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.jav
>a:471)
>at 
>org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVi
>rtualMachine(VMEntityManagerImpl.java:212)
>at 
>org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.dep
>loy(VirtualMachineEntityImpl.java:209)
>at 
>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>3871)
>at 
>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>3464)
>at 
>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>3450)
>at 
>com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorD
>ispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>at 
>org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.
>java:379)
>at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
>at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
>at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>at 
>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>1146)
>at 
>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>:615)
>at java.lang.Thread.run(Thread.java:679)
>2013-08-23 00:30:29,945 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-64:job-299) Cleaning up resources for the vm
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in Starting state
>2013-08-23 00:30:29,947 DEBUG [agent.transport.Request]
>(Job-Executor-64:job-299) Seq 1-1023805316: Sending  { Cmd , MgmtId:
>345050143793, via: 1, Ver: v1, Flags: 100111,
>[{"StopCommand":{"isProxy":false,"vmName":"i-2-171-VM","wait":0}}] }
>2013-08-23 00:30:29,947 DEBUG [agent.transport.Request]
>(Job-Executor-64:job-299) Seq 1-1023805316: Executing:  { Cmd ,
>MgmtId: 345050143793, via: 1, Ver: v1, Flags: 100111,
>[{"StopCommand":{"isProxy":false,"vmName":"i-2-171-VM","wait":0}}] }
>2013-08-23 00:30:29,947 DEBUG [agent.manager.DirectAgentAttache]
>(DirectAgent-395:null) Seq 1-1023805316: Executing request
>2013-08-23 00:30:30,209 INFO  [xen.resource.CitrixResourceBase]
>(DirectAgent-395:null) VM does not exist on
>XenServer992cb98d-123a-4cb6-8410-1532bbcb60f5
>2013-08-23 00:30:30,210 DEBUG [agent.manager.DirectAgentAttache]
>(DirectAgent-395:null) Seq 1-1023805316: Response Received:
>2013-08-23 00:30:30,210 DEBUG [agent.transport.Request]
>(DirectAgent-395:null) Seq 1-1023805316: Processing:  { Ans: , MgmtId:
>345050143793, via: 1, Ver: v1, Flags: 110,
>[{"StopAnswer":{"vncPort":0,"result":true,"details":"VM does not
>exist","wait":0}}] }
>2013-08-23 00:30:30,210 DEBUG [agent.manager.AgentAttache]
>(DirectAgent-395:null) Seq 1-1023805316: No more commands found
>2013-08-23 00:30:30,210 DEBUG [agent.transport.Request]
>(Job-Executor-64:job-299) Seq 1-1023805316: Received:  { Ans: ,
>MgmtId: 345050143793, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
>2013-08-23 00:30:30,217 DEBUG [db.Transaction.Transaction]
>(Job-Executor-64:job-299) Rolling back the transaction: Time = 2 Name
>=  
>-AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTa
>sk$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1146-
>ThreadPoolExecutor$Worker.run:615-Thread.run:679;
>called by 
>-Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657
>-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPost
>Processor$InterceptorDispatcher.intercept:131-NetworkManagerImpl.release:1
>687-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:12
>5-VirtualMachineManagerImpl.cleanup:962-VirtualMachineManagerImpl.advanceS
>tart:850-VirtualMachineManagerImpl.start:471-VMEntityManagerImpl.deployVir
>tualMachine:212-VirtualMachineEntityImpl.deploy:209
>2013-08-23 00:30:30,217 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-64:job-299) Successfully released network resources for
>the vm VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>2013-08-23 00:30:30,217 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>(Job-Executor-64:job-299) Successfully cleanued up resources for the
>vm VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] in Starting state
>2013-08-23 00:30:30,219 DEBUG [cloud.deploy.FirstFitPlanner]
>(Job-Executor-64:job-299) DataCenter id = '1' provided is in avoid
>set, DeploymentPlanner cannot allocate the VM, returning.
>2013-08-23 00:30:30,225 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) VM state transitted from :Starting to
>Stopped with event: OperationFailedvm's original host id: null new
>host id: null host id before state transition: 1
>2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) Hosts's actual total CPU: 13590 and CPU
>after applying overprovisioning: 13590
>2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) release cpu from host: 1, old used:
>3000,reserved: 0, actual total: 13590, total with overprovisioning:
>13590; new used: 2000,reserved:0; movedfromreserved:
>false,moveToReserveredfalse
>2013-08-23 00:30:30,231 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) release mem from host: 1, old used:
>2415919104,reserved: 0, total: 9988001856; new used:
>1342177280,reserved:0; movedfromreserved: false,moveToReserveredfalse
>2013-08-23 00:30:30,236 DEBUG [cloud.vm.UserVmManagerImpl]
>(Job-Executor-64:job-299) Destroying vm
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621] as it failed to create
>on Host with Id:null
>2013-08-23 00:30:30,242 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-64:job-299) VM state transitted from :Stopped to Error
>with event: OperationFailedToErrorvm's original host id: null new host
>id: null host id before state transition: null
>2013-08-23 00:30:30,277 INFO  [user.vm.DeployVMCmd]
>(Job-Executor-64:job-299)
>com.cloud.exception.InsufficientServerCapacityException: Unable to
>create a deployment for
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]Scope=interface
>com.cloud.dc.DataCenter; id=1
>2013-08-23 00:30:30,277 INFO  [user.vm.DeployVMCmd]
>(Job-Executor-64:job-299) Unable to create a deployment for
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]
>com.cloud.exception.InsufficientServerCapacityException: Unable to
>create a deployment for
>VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]Scope=interface
>com.cloud.dc.DataCenter; id=1
>at 
>com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerI
>mpl.java:728)
>at 
>com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.jav
>a:471)
>at 
>org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVi
>rtualMachine(VMEntityManagerImpl.java:212)
>at 
>org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.dep
>loy(VirtualMachineEntityImpl.java:209)
>at 
>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>3871)
>at 
>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>3464)
>at 
>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:
>3450)
>at 
>com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorD
>ispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>at 
>org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.
>java:379)
>at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
>at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
>at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>at 
>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>1146)
>at 
>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>:615)
>at java.lang.Thread.run(Thread.java:679)
>2013-08-23 00:30:30,278 DEBUG [cloud.async.AsyncJobManagerImpl]
>(Job-Executor-64:job-299) Complete async job-299, jobStatus: 2,
>resultCode: 530, result: Error Code: 533 Error text: Unable to create
>a deployment for VM[User|b5e2d457-5294-4c7d-adbc-2398e21fe621]