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
