> 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
