cloudstack-users-cn mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From 不坏阿峰 <onlydeb...@gmail.com>
Subject Fail to create Instance in VPC on CS4.1.1
Date Thu, 22 Aug 2013 17:51:32 GMT
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]

Mime
View raw message