cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Peter Sadowski <psadow...@dbr360.com>
Subject Can't create VM under specific account
Date Fri, 30 May 2014 15:29:39 GMT
Hello,

I'm having a strange issue under one account, which cannot spin up a VM.
I have plenty of capacity in terms of cpu/memory/storage, but for some reason the VM creation
fails. When trying with different accounts, VM's are created no problems.
Any pointers would be appreciated.
The error log is below.


[root@mgmt-01 management]# grep job-4180 management-server.log
2014-05-30 11:01:17,301 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-4:null) submit
async job-4180, details: AsyncJobVO {id:4180, userId: 52, accountId: 52, sessionKey: null,
instanceType: VirtualMachine, instanceId: 291, cmd: com.cloud.api.commands.DeployVMCmd, cmdOriginator:
null, cmdInfo: {"serviceofferingid":"e989a1ff-e311-4eed-83da-f65bc4b615b7","keyboard":"","ctxUserId":"52","zoneid":"a3ee28a3-5ea5-4b34-9322-ee2530e03301","templateid":"4d9ac466-d3c3-4196-982f-a1838ba0012c","domainid":"99a65170-11f6-49e6-91c5-33d1237a165f","networkids":"8f9caca4-e150-401b-a719-1083a6c011fa,0de0333d-eebf-4b9f-9fbf-c3bc13edc2c1","apikey":"wfwvLHoSAY9LzD_n0Ji6JZlar2QpPrCvkB7hAfDOt5vYkRniGoDM7SO8hyTqZngPf1PqlX1BRhScrcm3-I1AgA","id":"291","hypervisor":"XenServer","name":"tsiapp01","account":"ptearne","ctxAccountId":"52","ctxStartEventId":"76571","signature":"iIzlDRdf9eKP+w6cppDdZRq9bjI\u003d","displayname":"tsiapp01"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode:
0, result: null, initMsid: 257985870280807, completeMsid: null, lastUpdated: null, lastPolled:
null, created: null}
2014-05-30 11:01:17,306 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-1:job-4180)
Executing com.cloud.api.commands.DeployVMCmd for job-4180
2014-05-30 11:01:17,499 DEBUG [cloud.user.AccountManagerImpl] (Job-Executor-1:job-4180) Access
to VM[User|tsiapp01] granted to Acct[52-ptearne] by DomainChecker
2014-05-30 11:01:17,602 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Service SecurityGroup is not supported in the network id=231
2014-05-30 11:01:17,684 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Service SecurityGroup is not supported in the network id=238
2014-05-30 11:01:17,716 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Service SecurityGroup is not supported in the network id=231
2014-05-30 11:01:17,731 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Service SecurityGroup is not supported in the network id=238
2014-05-30 11:01:17,780 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
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
2014-05-30 11:01:17,781 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-4180)
Successfully transitioned to start state for VM[User|tsiapp01] reservation id = bc00de2f-4c97-421d-bb7f-da01a333a586
2014-05-30 11:01:17,807 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-4180)
Trying to deploy VM, vm has dcId: 1 and podId: null
2014-05-30 11:01:17,808 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-4180)
Deploy avoids pods: null, clusters: null, hosts: null
2014-05-30 11:01:17,824 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) DeploymentPlanner
allocation algorithm: random
2014-05-30 11:01:17,824 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Trying
to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 4000,
requested ram: 8589934592
2014-05-30 11:01:17,824 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Is
ROOT volume READY (pool already allocated)?: No
2014-05-30 11:01:17,824 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Searching
all possible resources under this Zone: 1
2014-05-30 11:01:17,838 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Listing
clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and
RAM capacity under this Zone: 1
2014-05-30 11:01:17,845 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) CPUOverprovisioningFactor
considered: 2.0
2014-05-30 11:01:17,920 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Checking
resources in Cluster: 1 under Pod: 1
2014-05-30 11:01:17,920 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Calling
HostAllocators to find suitable hosts
2014-05-30 11:01:17,920 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
2014-05-30 11:01:17,935 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) FirstFitAllocator has 6 hosts to check for allocation: [Host[-2-Routing],
Host[-45-Routing], Host[-3-Routing], Host[-6-Routing], Host[-5-Routing], Host[-1-Routing]]
2014-05-30 11:01:18,004 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Found 6 hosts for allocation after prioritization: [Host[-2-Routing],
Host[-45-Routing], Host[-3-Routing], Host[-6-Routing], Host[-5-Routing], Host[-1-Routing]]
2014-05-30 11:01:18,004 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Looking for speed=4000Mhz, Ram=8192
2014-05-30 11:01:18,030 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Checking if host: 2 has enough capacity for requested CPU: 4000
and requested RAM: 8589934592 , cpuOverprovisioningFactor: 2.0
2014-05-30 11:01:18,045 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning:
128000
2014-05-30 11:01:18,045 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free CPU: 91500 , Requested CPU: 4000
2014-05-30 11:01:18,045 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free RAM: 94066777344 , Requested RAM: 8589934592
2014-05-30 11:01:18,045 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-05-30 11:01:18,045 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 2, used: 36500, reserved: 0, actual
total: 64000, total with overprovisioning: 128000; requested cpu:4000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2014-05-30 11:01:18,046 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 2, used: 40265318400, reserved:
0, total: 134332095744; requested mem: 8589934592,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-05-30 11:01:18,046 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Found a suitable host, adding to list: 2
2014-05-30 11:01:18,059 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Checking if host: 45 has enough capacity for requested CPU: 4000
and requested RAM: 8589934592 , cpuOverprovisioningFactor: 2.0
2014-05-30 11:01:18,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning:
128000
2014-05-30 11:01:18,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free CPU: 112000 , Requested CPU: 4000
2014-05-30 11:01:18,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free RAM: 117152226560 , Requested RAM: 8589934592
2014-05-30 11:01:18,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-05-30 11:01:18,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 45, used: 16000, reserved: 0, actual
total: 64000, total with overprovisioning: 128000; requested cpu:4000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2014-05-30 11:01:18,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 45, used: 17179869184, reserved:
0, total: 134332095744; requested mem: 8589934592,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-05-30 11:01:18,075 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Found a suitable host, adding to list: 45
2014-05-30 11:01:18,088 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Checking if host: 3 has enough capacity for requested CPU: 4000
and requested RAM: 8589934592 , cpuOverprovisioningFactor: 2.0
2014-05-30 11:01:18,103 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning:
128000
2014-05-30 11:01:18,103 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free CPU: 101000 , Requested CPU: 4000
2014-05-30 11:01:18,103 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free RAM: 99569704192 , Requested RAM: 8589934592
2014-05-30 11:01:18,103 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-05-30 11:01:18,103 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 3, used: 27000, reserved: 0, actual
total: 64000, total with overprovisioning: 128000; requested cpu:4000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2014-05-30 11:01:18,103 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 3, used: 34762391552, reserved:
0, total: 134332095744; requested mem: 8589934592,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-05-30 11:01:18,104 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Found a suitable host, adding to list: 3
2014-05-30 11:01:18,117 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Checking if host: 6 has enough capacity for requested CPU: 4000
and requested RAM: 8589934592 , cpuOverprovisioningFactor: 2.0
2014-05-30 11:01:18,132 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning:
128000
2014-05-30 11:01:18,132 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free CPU: 110000 , Requested CPU: 4000
2014-05-30 11:01:18,132 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free RAM: 115541613824 , Requested RAM: 8589934592
2014-05-30 11:01:18,132 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-05-30 11:01:18,132 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 6, used: 18000, reserved: 0, actual
total: 64000, total with overprovisioning: 128000; requested cpu:4000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2014-05-30 11:01:18,132 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 6, used: 18790481920, reserved:
0, total: 134332095744; requested mem: 8589934592,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-05-30 11:01:18,133 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Found a suitable host, adding to list: 6
2014-05-30 11:01:18,147 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Checking if host: 5 has enough capacity for requested CPU: 4000
and requested RAM: 8589934592 , cpuOverprovisioningFactor: 2.0
2014-05-30 11:01:18,162 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning:
128000
2014-05-30 11:01:18,163 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free CPU: 90500 , Requested CPU: 4000
2014-05-30 11:01:18,163 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free RAM: 72457723136 , Requested RAM: 8589934592
2014-05-30 11:01:18,163 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-05-30 11:01:18,163 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 5, used: 37500, reserved: 0, actual
total: 64000, total with overprovisioning: 128000; requested cpu:4000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2014-05-30 11:01:18,163 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 5, used: 61874372608, reserved:
0, total: 134332095744; requested mem: 8589934592,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-05-30 11:01:18,163 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Found a suitable host, adding to list: 5
2014-05-30 11:01:18,179 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 4000
and requested RAM: 8589934592 , cpuOverprovisioningFactor: 2.0
2014-05-30 11:01:18,193 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Hosts's actual total CPU: 26000 and CPU after applying overprovisioning:
52000
2014-05-30 11:01:18,194 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free CPU: 32000 , Requested CPU: 4000
2014-05-30 11:01:18,194 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Free RAM: 98898615552 , Requested RAM: 8589934592
2014-05-30 11:01:18,194 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-05-30 11:01:18,194 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 20000, reserved: 0, actual
total: 26000, total with overprovisioning: 52000; requested cpu:4000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2014-05-30 11:01:18,194 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 35433480192, reserved:
0, total: 134332095744; requested mem: 8589934592,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-05-30 11:01:18,194 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2014-05-30 11:01:18,194 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-4180
FirstFitRoutingAllocator) Host Allocator returning 6 suitable hosts
2014-05-30 11:01:18,203 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Checking
suitable pools for volume (Id, Type): (416,ROOT)
2014-05-30 11:01:18,203 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) We
need to allocate new storagepool for this volume
2014-05-30 11:01:18,212 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Calling
StoragePoolAllocators to find suitable pools
2014-05-30 11:01:18,221 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-1:job-4180)
Looking for pools in dc: 1  pod:1  cluster:1 having tags:[sata]
2014-05-30 11:01:18,236 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-1:job-4180)
FirstFitStoragePoolAllocator has 1 pools to check for allocation
2014-05-30 11:01:18,236 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-1:job-4180)
Checking if storage pool is suitable, name: NJR2-Z1-P1-C1-D1 ,poolId: 204
2014-05-30 11:01:18,237 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-1:job-4180)
Is localStorageAllocationNeeded? false
2014-05-30 11:01:18,237 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-1:job-4180)
Is storage pool shared? true
2014-05-30 11:01:18,244 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-1:job-4180)
Attempting to look for pool 204 for storage, totalSize: 5222680231936, usedBytes: 3857897684992,
usedPct: 0.738681579891004, disable threshold: 0.9
2014-05-30 11:01:18,263 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-1:job-4180)
Attempting to look for pool 204 for storage, maxSize : 20890720927744, totalAllocatedSize
: 8235745441792, askingSize : 42949672960, allocated disable threshold: 0.9
2014-05-30 11:01:18,263 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-1:job-4180)
FirstFitStoragePoolAllocator returning 1 suitable storage pools
2014-05-30 11:01:18,263 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Trying
to find a potenial host and associated storage pools from the suitable host/pool lists for
this VM
2014-05-30 11:01:18,263 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Checking
if host: 2 can access any suitable storage pool for volume: ROOT
2014-05-30 11:01:18,271 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Host:
2 can access pool: 204
2014-05-30 11:01:18,271 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) Found
a potential host id: 2 name: nj5-z1p1c1h04 and associated storage pools for this VM
2014-05-30 11:01:18,280 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) 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(2)-Storage(Volume(416|ROOT-->Pool(204))]
2014-05-30 11:01:18,281 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-4180)
Deployment found  - P0=VM[User|tsiapp01], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(416|ROOT-->Pool(204))]
2014-05-30 11:01:18,319 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
VM state transitted from :Starting to Starting with event: OperationRetryvm's original host
id: null new host id: 2 host id before state transition: null
2014-05-30 11:01:18,363 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 128000
2014-05-30 11:01:18,363 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
We are allocating VM, increasing the used capacity of this host:2
2014-05-30 11:01:18,363 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
Current Used CPU: 36500 , Free CPU:91500 ,Requested CPU: 4000
2014-05-30 11:01:18,363 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
Current Used RAM: 40265318400 , Free RAM:94066777344 ,Requested RAM: 8589934592
2014-05-30 11:01:18,363 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
CPU STATS after allocation: for host: 2, old used: 36500, old reserved: 0, actual total: 64000,
total with overprovisioning: 128000; new used:40500, reserved:0; requested cpu:4000,alloc_from_last:false
2014-05-30 11:01:18,363 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
RAM STATS after allocation: for host: 2, old used: 40265318400, old reserved: 0, total: 134332095744;
new used: 48855252992, reserved: 0; requested mem: 8589934592,alloc_from_last:false
2014-05-30 11:01:18,391 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-4180)
VM is being created in podId: 1
2014-05-30 11:01:18,417 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Lock is acquired for network id 231 as a part of network implement
2014-05-30 11:01:18,417 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Network id=231 is already implemented
2014-05-30 11:01:18,423 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Lock is released for network id 231 as a part of network implement
2014-05-30 11:01:18,515 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Service SecurityGroup is not supported in the network id=231
2014-05-30 11:01:18,543 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Changing active number of nics for network id=231 on 1
2014-05-30 11:01:18,581 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking JuniperSRX to prepare for Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:18,610 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking Netscaler to prepare for Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:18,636 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking F5BigIp to prepare for Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:18,663 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking VirtualRouter to prepare for Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:18,738 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-1:job-4180)
Lock is acquired for network id 231 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(416|ROOT-->Pool(204))]
2014-05-30 11:01:18,763 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-1:job-4180)
Lock is released for network id 231 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(416|ROOT-->Pool(204))]
2014-05-30 11:01:18,815 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Service SecurityGroup is not supported in the network id=231
2014-05-30 11:01:18,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-1:job-4180)
Applying dhcp entry in network Ntwk[231|Guest|8]
2014-05-30 11:01:18,979 DEBUG [agent.manager.ClusteredAgentAttache] (Job-Executor-1:job-4180)
Seq 3-46465042: Forwarding Seq 3-46465042:  { Cmd , MgmtId: 257985870280807, via: 3, Ver:
v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"02:00:13:5f:00:29","vmIpAddress":"172.30.0.245","vmName":"tsiapp01","defaultRouter":"172.30.0.1","defaultDns":"172.30.0.1","accessDetails":{"router.guest.ip":"172.30.0.1","zone.network.type":"Advanced","router.name":"r-258-VM","router.ip":"169.254.1.143"},"wait":0}}]
} to 42026829063690
2014-05-30 11:01:30,993 DEBUG [agent.transport.Request] (Job-Executor-1:job-4180) Seq 3-46465042:
Received:  { Ans: , MgmtId: 257985870280807, via: 3, Ver: v1, Flags: 110, { Answer } }
2014-05-30 11:01:30,994 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-4180)
Unable to contact resource.
2014-05-30 11:01:31,023 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-4180)
Cleaning up resources for the vm VM[User|tsiapp01] in Starting state
2014-05-30 11:01:31,041 DEBUG [agent.manager.ClusteredAgentAttache] (Job-Executor-1:job-4180)
Seq 2-154009619: Forwarding Seq 2-154009619:  { Cmd , MgmtId: 257985870280807, via: 2, Ver:
v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-52-291-VM","wait":0}}] } to
42026829063690
2014-05-30 11:01:31,269 DEBUG [agent.transport.Request] (Job-Executor-1:job-4180) Seq 2-154009619:
Received:  { Ans: , MgmtId: 257985870280807, via: 2, Ver: v1, Flags: 110, { StopAnswer } }
2014-05-30 11:01:31,337 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Service SecurityGroup is not supported in the network id=231
2014-05-30 11:01:31,375 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Changing active number of nics for network id=231 on -1
2014-05-30 11:01:31,402 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking JuniperSRX to release Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:31,402 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking Netscaler to release Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:31,402 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking F5BigIp to release Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:31,402 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking VirtualRouter to release Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:31,403 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking Ovs to release Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:31,403 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking ExternalDhcpServer to release Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:31,403 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking BareMetal to release Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:31,403 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking SecurityGroupProvider to release Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:31,403 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking CiscoNexus1000vVSM to release Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:31,403 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-4180)
Asking VpcVirtualRouter to release Nic[492-291-bc00de2f-4c97-421d-bb7f-da01a333a586-172.30.0.245]
2014-05-30 11:01:31,411 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-4180)
Successfully released network resources for the vm VM[User|tsiapp01]
2014-05-30 11:01:31,412 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-4180)
Successfully cleanued up resources for the vm VM[User|tsiapp01] in Starting state
2014-05-30 11:01:31,419 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-4180) DataCenter
id = '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM, returning.
2014-05-30 11:01:31,464 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host
id: null new host id: null host id before state transition: 2
2014-05-30 11:01:31,489 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 128000
2014-05-30 11:01:31,489 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
release cpu from host: 2, old used: 40500,reserved: 0, actual total: 64000, total with overprovisioning:
128000; new used: 36500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-05-30 11:01:31,490 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
release mem from host: 2, old used: 48855252992,reserved: 0, total: 134332095744; new used:
40265318400,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-05-30 11:01:31,519 DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-1:job-4180) Destroying
vm VM[User|tsiapp01] as it failed to create
2014-05-30 11:01:31,571 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-4180)
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
2014-05-30 11:01:31,788 ERROR [cloud.alert.AlertManagerImpl] (Job-Executor-1:job-4180) Problem
sending email alert
2014-05-30 11:01:31,877 INFO  [api.commands.DeployVMCmd] (Job-Executor-1:job-4180) com.cloud.exception.InsufficientServerCapacityException:
Unable to create a deployment for VM[User|tsiapp01]Scope=interface com.cloud.dc.DataCenter;
id=1
2014-05-30 11:01:31,878 WARN  [cloud.api.ApiDispatcher] (Job-Executor-1:job-4180) class com.cloud.api.ServerApiException
: Unable to create a deployment for VM[User|tsiapp01]
2014-05-30 11:01:31,879 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-1:job-4180)
Complete async job-4180, jobStatus: 2, resultCode: 530, result: Error Code: 533 Error text:
Unable to create a deployment for VM[User|tsiapp01]
2014-05-30 11:01:32,927 DEBUG [cloud.async.AsyncJobManagerImpl] (ApiServer-4:null) Async job-4180
completed

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message