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, "不坏阿峰" <onlydeb...@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]
