Reviewing the logs, grepping for job 77 I get the following errors: This is
when spinning up a instance from a template.
================
[root@lunder ~]# cat /var/log/cloud/management/management-server.log |grep
job-77
2013-03-28 02:07:17,540 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-22:null) submit async job-77, details: AsyncJobVO {id:77,
userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine,
instanceId: 11, cmd: com.cloud.api.commands.DeployVMCmd, cmdOriginator: null,
cmdInfo:
{"sessionkey":"AX3hqEZ8EpqXTA/AsF3oDek4MIc\u003d","ctxUserId":"2","serviceOfferingId":"97b8d235-7b71-4ca0-8a04-fe90ec9220f0","securitygroupids":"f78f103f-77fb-4fbe-b437-91b656c8427f","zoneId":"28b7e853-1b2c-474c-be2f-4b91466fd4a9","templateId":"c4e7d8f3-d80b-45da-a29f-19687d7494f2","response":"json","id":"11","hypervisor":"KVM","name":"temptest","diskOfferingId":"07148505-9dd2-4f31-9494-bb82c64c7436","_":"1364454437368","ctxAccountId":"2","ctxStartEventId":"429","displayname":"temptest"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 279278805451068,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-03-28 02:07:17,540 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-22:job-77) Executing com.cloud.api.commands.DeployVMCmd for job-77
2013-03-28 02:07:17,559 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77) 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-03-28 02:07:17,559 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-22:job-77) Successfully transitioned to start state for
VM[User|i-2-11-VM] reservation id = 77d9fc64-54d5-460e-bf85-ce9378bcf1cb
2013-03-28 02:07:17,562 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-22:job-77) Trying to deploy VM, vm has dcId: 1 and podId: null
2013-03-28 02:07:17,562 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-22:job-77) Deploy avoids pods: null, clusters: null, hosts: null
2013-03-28 02:07:17,563 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) DeploymentPlanner allocation algorithm: random
2013-03-28 02:07:17,564 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
2013-03-28 02:07:17,564 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Is ROOT volume READY (pool already allocated)?: No
2013-03-28 02:07:17,564 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Searching all possible resources under this Zone: 1
2013-03-28 02:07:17,565 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Listing clusters in order of aggregate capacity, that
have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2013-03-28 02:07:17,566 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) CPUOverprovisioningFactor considered: 1.0
2013-03-28 02:07:17,573 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Checking resources in Cluster: 1 under Pod: 1
2013-03-28 02:07:17,573 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Calling HostAllocators to find suitable hosts
2013-03-28 02:07:17,573 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2013-03-28 02:07:17,575 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts
to check for allocation: [Host[-1-Routing]]
2013-03-28 02:07:17,577 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) Found 1 hosts for allocation
after prioritization: [Host[-1-Routing]]
2013-03-28 02:07:17,577 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) Looking for speed=500Mhz,
Ram=512
2013-03-28 02:07:17,578 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) Checking if host: 1 has
enough capacity for requested CPU: 500 and requested RAM: 536870912 ,
cpuOverprovisioningFactor: 1.0
2013-03-28 02:07:17,581 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) Hosts's actual total CPU:
36256 and CPU after applying overprovisioning: 36256
2013-03-28 02:07:17,581 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) Free CPU: 26756 , Requested
CPU: 500
2013-03-28 02:07:17,581 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) Free RAM: 19516366848 ,
Requested RAM: 536870912
2013-03-28 02:07:17,581 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) Host has enough CPU and RAM
available
2013-03-28 02:07:17,581 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 1, used: 9500, reserved: 0, actual total: 36256, total with
overprovisioning: 36256; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2013-03-28 02:07:17,581 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 1, used: 5670699008, reserved: 0, total: 25187065856; requested mem:
536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-03-28 02:07:17,581 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) Found a suitable host, adding
to list: 1
2013-03-28 02:07:17,581 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-22:job-77 FirstFitRoutingAllocator) Host Allocator returning 1
suitable hosts
2013-03-28 02:07:17,582 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Checking suitable pools for volume (Id, Type):
(18,ROOT)
2013-03-28 02:07:17,582 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) We need to allocate new storagepool for this volume
2013-03-28 02:07:17,582 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Calling StoragePoolAllocators to find suitable pools
2013-03-28 02:07:17,582 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-22:job-77) Looking for pools in dc: 1 pod:1 cluster:1
2013-03-28 02:07:17,584 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-22:job-77) FirstFitStoragePoolAllocator has 1 pools to check for
allocation
2013-03-28 02:07:17,584 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-22:job-77) Checking if storage pool is suitable, name: Apollo
,poolId: 200
2013-03-28 02:07:17,584 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-22:job-77) Is localStorageAllocationNeeded? false
2013-03-28 02:07:17,584 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-22:job-77) Is storage pool shared? true
2013-03-28 02:07:17,585 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-22:job-77) Attempting to look for pool 200 for storage,
totalSize: 1732611407872, usedBytes: 11830034432, usedPct:
0.006827863638811944, disable threshold: 0.85
2013-03-28 02:07:17,586 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-22:job-77) Attempting to look for pool 200 for storage, maxSize :
3465222815744, totalAllocatedSize : 268436291584, askingSize : 5368709120,
allocated disable threshold: 0.85
2013-03-28 02:07:17,587 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-22:job-77) FirstFitStoragePoolAllocator returning 1 suitable
storage pools
2013-03-28 02:07:17,587 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Checking suitable pools for volume (Id, Type):
(19,DATADISK)
2013-03-28 02:07:17,587 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) We need to allocate new storagepool for this volume
2013-03-28 02:07:17,587 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Calling StoragePoolAllocators to find suitable pools
2013-03-28 02:07:17,587 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-22:job-77) Looking for pools in dc: 1 pod:1 cluster:1
2013-03-28 02:07:17,588 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-22:job-77) FirstFitStoragePoolAllocator has 1 pools to check for
allocation
2013-03-28 02:07:17,588 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-22:job-77) Checking if storage pool is suitable, name: Apollo
,poolId: 200
2013-03-28 02:07:17,588 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-22:job-77) Is localStorageAllocationNeeded? false
2013-03-28 02:07:17,588 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-22:job-77) Is storage pool shared? true
2013-03-28 02:07:17,589 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-22:job-77) Attempting to look for pool 200 for storage,
totalSize: 1732611407872, usedBytes: 11830034432, usedPct:
0.006827863638811944, disable threshold: 0.85
2013-03-28 02:07:17,590 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-22:job-77) Attempting to look for pool 200 for storage, maxSize :
3465222815744, totalAllocatedSize : 268436291584, askingSize : 5368709120,
allocated disable threshold: 0.85
2013-03-28 02:07:17,590 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-22:job-77) FirstFitStoragePoolAllocator returning 1 suitable
storage pools
2013-03-28 02:07:17,591 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Trying to find a potenial host and associated storage
pools from the suitable host/pool lists for this VM
2013-03-28 02:07:17,591 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Checking if host: 1 can access any suitable storage
pool for volume: DATADISK
2013-03-28 02:07:17,591 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Host: 1 can access pool: 200
2013-03-28 02:07:17,591 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Checking if host: 1 can access any suitable storage
pool for volume: ROOT
2013-03-28 02:07:17,592 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Host: 1 can access pool: 200
2013-03-28 02:07:17,592 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) Found a potential host id: 1 name: lunder.daoenix.com
and associated storage pools for this VM
2013-03-28 02:07:17,594 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-22:job-77) 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(19|DATADISK-->Pool(200),
Volume(18|ROOT-->Pool(200))]
2013-03-28 02:07:17,594 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-22:job-77) Deployment found - P0=VM[User|i-2-11-VM],
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(19|DATADISK-->Pool(200),
Volume(18|ROOT-->Pool(200))]
2013-03-28 02:07:17,597 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77) 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-03-28 02:07:17,602 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77) Hosts's actual total CPU: 36256 and CPU after applying
overprovisioning: 36256
2013-03-28 02:07:17,602 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77) We are allocating VM, increasing the used capacity of
this host:1
2013-03-28 02:07:17,602 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77) Current Used CPU: 9500 , Free CPU:26756 ,Requested
CPU: 500
2013-03-28 02:07:17,602 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77) Current Used RAM: 5670699008 , Free RAM:19516366848
,Requested RAM: 536870912
2013-03-28 02:07:17,602 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77) CPU STATS after allocation: for host: 1, old used:
9500, old reserved: 0, actual total: 36256, total with overprovisioning: 36256;
new used:10000, reserved:0; requested cpu:500,alloc_from_last:false
2013-03-28 02:07:17,602 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-22:job-77) RAM STATS after allocation: for host: 1, old used:
5670699008, old reserved: 0, total: 25187065856; new used: 6207569920,
reserved: 0; requested mem: 536870912,alloc_from_last:false
2013-03-28 02:07:17,604 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-22:job-77) VM is being started in podId: 1
2013-03-28 02:07:17,606 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-22:job-77) Network id=204 is already implemented
2013-03-28 02:07:17,621 DEBUG [db.Transaction.Transaction]
(Job-Executor-22:job-77) Rolling back the transaction: Time = 1 Name =
-AsyncJobManagerImpl$1.run:393-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:837-Transaction.removeUpTo:780-Transaction.close:599-DatabaseCallback.interceptComplete:67-DatabaseCallback.intercept:32-NetworkManagerImpl.assignPublicIpAddress:355-DirectPodBasedNetworkGuru.getIp:158-DirectPodBasedNetworkGuru.reserve:146-DatabaseCallback.intercept:30-NetworkManagerImpl.prepare:1859-VirtualMachineManagerImpl.advanceStart:741-VirtualMachineManagerImpl.start:461
