2014-03-24 19:14:54,689 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-15:null) submit async job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ], details: AsyncJobVO {id:1847, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 11729, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator: null, cmdInfo: {"sessionkey":"Y9zoJw97y8mKqHwufhOQV0To9e4\u003d","cmdEventType":"VM.CREATE","ctxUserId":"2","serviceOfferingId":"39cedf2c-d4d8-4c4b-9928-31e5b38b4a6c","httpmethod":"GET","zoneId":"9e00720c-eba8-45bc-820e-314e196b5ab1","templateId":"a2a0a070-0305-11e3-b0bb-62645e13ce15","response":"json","id":"11729","networkIds":"0820cbe0-c537-4acd-91dd-17d2df88664b","hypervisor":"XenServer","name":"test03242","_":"1395656094586","ctxAccountId":"2","ctxStartEventId":"20784","displayname":"test03242"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 108183214607893, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-03-24 19:14:54,690 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]
2014-03-24 19:14:54,692 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===END===  192.168.40.103 -- GET  command=deployVirtualMachine&zoneId=9e00720c-eba8-45bc-820e-314e196b5ab1&templateId=a2a0a070-0305-11e3-b0bb-62645e13ce15&hypervisor=XenServer&serviceOfferingId=39cedf2c-d4d8-4c4b-9928-31e5b38b4a6c&networkIds=0820cbe0-c537-4acd-91dd-17d2df88664b&displayname=test03242&name=test03242&response=json&sessionkey=Y9zoJw97y8mKqHwufhOQV0To9e4%3D&_=1395656094586
2014-03-24 19:14:54,700 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2014-03-24 19:14:54,703 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2014-03-24 19:14:54,706 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) ControlledEntity name is:com.cloud.network.Network
2014-03-24 19:14:54,756 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Service SecurityGroup is not supported in the network id=246
2014-03-24 19:14:54,764 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Service SecurityGroup is not supported in the network id=246
2014-03-24 19:14:54,798 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Deploy avoids pods: [], clusters: [], hosts: []
2014-03-24 19:14:54,802 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_78958a70@2859ae8f
2014-03-24 19:14:54,802 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Trying to allocate a host and storage pools from dc:9, pod:null,cluster:null, requested cpu: 1000, requested ram: 2147483648
2014-03-24 19:14:54,802 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Is ROOT volume READY (pool already allocated)?: No
2014-03-24 19:14:54,802 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Searching all possible resources under this Zone: 9
2014-03-24 19:14:54,804 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 9
2014-03-24 19:14:54,811 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Removing from the clusterId list these clusters from avoid set: []
2014-03-24 19:14:54,825 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking resources in Cluster: 6 under Pod: 8
2014-03-24 19:14:54,829 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Looking for hosts in dc: 9  pod:8  cluster:6
2014-03-24 19:14:54,836 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-62-Routing], Host[-25-Routing]]
2014-03-24 19:14:54,844 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-62-Routing], Host[-25-Routing]]
2014-03-24 19:14:54,844 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=2048
2014-03-24 19:14:54,853 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Checking if host: 62 has enough capacity for requested CPU: 1000 and requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
2014-03-24 19:14:54,858 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Hosts's actual total CPU: 45600 and CPU after applying overprovisioning: 45600
2014-03-24 19:14:54,858 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Free CPU: 45600 , Requested CPU: 1000
2014-03-24 19:14:54,858 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Free RAM: 66725756928 , Requested RAM: 2147483648
2014-03-24 19:14:54,858 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-03-24 19:14:54,859 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 62, used: 0, reserved: 0, actual total: 45600, total with overprovisioning: 45600; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-24 19:14:54,859 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 62, used: 0, reserved: 0, total: 66725756928; requested mem: 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-24 19:14:54,859 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Found a suitable host, adding to list: 62
2014-03-24 19:14:54,869 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Checking if host: 25 has enough capacity for requested CPU: 1000 and requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
2014-03-24 19:14:54,873 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Hosts's actual total CPU: 45600 and CPU after applying overprovisioning: 45600
2014-03-24 19:14:54,873 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Free CPU: 34100 , Requested CPU: 1000
2014-03-24 19:14:54,873 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Free RAM: 47535460352 , Requested RAM: 2147483648
2014-03-24 19:14:54,873 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-03-24 19:14:54,874 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 25, used: 11500, reserved: 0, actual total: 45600, total with overprovisioning: 45600; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-24 19:14:54,874 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 25, used: 19193135104, reserved: 0, total: 66728595456; requested mem: 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-24 19:14:54,874 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Found a suitable host, adding to list: 25
2014-03-24 19:14:54,874 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Host Allocator returning 2 suitable hosts
2014-03-24 19:14:54,877 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking suitable pools for volume (Id, Type): (417,ROOT)
2014-03-24 19:14:54,877 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) We need to allocate new storagepool for this volume
2014-03-24 19:14:54,879 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Calling StoragePoolAllocators to find suitable pools
2014-03-24 19:14:54,881 DEBUG [storage.allocator.LocalStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2014-03-24 19:14:54,881 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) ClusterScopeStoragePoolAllocator looking for storage pool
2014-03-24 19:14:54,881 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Looking for pools in dc: 9  pod:8  cluster:6
2014-03-24 19:14:54,889 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking if storage pool is suitable, name: null ,poolId: 233
2014-03-24 19:14:54,897 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking pool 233 for storage, totalSize: 1099499044864, usedBytes: 191457394688, usedPct: 0.17413147886061317, disable threshold: 0.85
2014-03-24 19:14:54,918 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-120:null) Seq 62-1646460933: Executing request
2014-03-24 19:14:54,937 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking pool: 233 for volume allocation [Vol[417|vm=11729|ROOT]], maxSize : 1099499044864, totalAllocatedSize : 172415254528, askingSize : 21474836480, allocated disable threshold: 0.85
2014-03-24 19:14:54,937 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2014-03-24 19:14:54,937 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2014-03-24 19:14:54,937 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking if host: 62 can access any suitable storage pool for volume: ROOT
2014-03-24 19:14:54,938 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Host: 62 cannot access pool: 233
2014-03-24 19:14:54,938 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking if host: 25 can access any suitable storage pool for volume: ROOT
2014-03-24 19:14:54,940 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Host: 25 can access pool: 233
2014-03-24 19:14:54,941 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Found a potential host id: 25 name: ccndmg03 and associated storage pools for this VM
2014-03-24 19:14:54,943 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(9)-Pod(8)-Cluster(6)-Host(25)-Storage(Volume(417|ROOT-->Pool(233))]
2014-03-24 19:14:54,977 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) 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-03-24 19:14:54,977 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Successfully transitioned to start state for VM[User|test03242] reservation id = e79c492a-aafe-447d-9eb7-11cb84a0b9a0
2014-03-24 19:14:54,989 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Trying to deploy VM, vm has dcId: 9 and podId: null
2014-03-24 19:14:54,989 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) advanceStart: DeploymentPlan is provided, using dcId:9, podId: 8, clusterId: 6, hostId: 25, poolId: null
2014-03-24 19:14:54,990 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Deploy avoids pods: null, clusters: null, hosts: null
2014-03-24 19:14:55,010 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Deploy avoids pods: [], clusters: [], hosts: []
2014-03-24 19:14:55,012 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_78958a70@2859ae8f
2014-03-24 19:14:55,012 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Trying to allocate a host and storage pools from dc:9, pod:8,cluster:6, requested cpu: 1000, requested ram: 2147483648
2014-03-24 19:14:55,012 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Is ROOT volume READY (pool already allocated)?: No
2014-03-24 19:14:55,012 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 25
2014-03-24 19:14:55,015 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Looking for suitable pools for this host under zone: 9, pod: 8, cluster: 6
2014-03-24 19:14:55,017 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking suitable pools for volume (Id, Type): (417,ROOT)
2014-03-24 19:14:55,017 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) We need to allocate new storagepool for this volume
2014-03-24 19:14:55,018 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Calling StoragePoolAllocators to find suitable pools
2014-03-24 19:14:55,018 DEBUG [storage.allocator.LocalStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2014-03-24 19:14:55,018 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) ClusterScopeStoragePoolAllocator looking for storage pool
2014-03-24 19:14:55,018 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Looking for pools in dc: 9  pod:8  cluster:6
2014-03-24 19:14:55,025 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking if storage pool is suitable, name: null ,poolId: 233
2014-03-24 19:14:55,034 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking pool 233 for storage, totalSize: 1099499044864, usedBytes: 191457394688, usedPct: 0.17413147886061317, disable threshold: 0.85
2014-03-24 19:14:55,059 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-120:null) Seq 62-1646460933: Response Received: 
2014-03-24 19:14:55,060 DEBUG [agent.transport.Request] (DirectAgent-120:null) Seq 62-1646460933: Processing:  { Ans: , MgmtId: 108183214607893, via: 62, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-03-24 19:14:55,082 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking pool: 233 for volume allocation [Vol[417|vm=11729|ROOT]], maxSize : 1099499044864, totalAllocatedSize : 172415254528, askingSize : 21474836480, allocated disable threshold: 0.85
2014-03-24 19:14:55,082 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2014-03-24 19:14:55,082 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2014-03-24 19:14:55,082 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking if host: 25 can access any suitable storage pool for volume: ROOT
2014-03-24 19:14:55,084 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Host: 25 can access pool: 233
2014-03-24 19:14:55,085 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Found a potential host id: 25 name: ccndmg03 and associated storage pools for this VM
2014-03-24 19:14:55,086 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(9)-Pod(8)-Cluster(6)-Host(25)-Storage(Volume(417|ROOT-->Pool(233))]
2014-03-24 19:14:55,087 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Deployment found  - P0=VM[User|test03242], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(9)-Pod(8)-Cluster(6)-Host(25)-Storage(Volume(417|ROOT-->Pool(233))]
2014-03-24 19:14:55,105 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 25 host id before state transition: null
2014-03-24 19:14:55,116 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Hosts's actual total CPU: 45600 and CPU after applying overprovisioning: 45600
2014-03-24 19:14:55,116 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) We are allocating VM, increasing the used capacity of this host:25
2014-03-24 19:14:55,116 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Current Used CPU: 11500 , Free CPU:34100 ,Requested CPU: 1000
2014-03-24 19:14:55,116 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Current Used RAM: 19193135104 , Free RAM:47535460352 ,Requested RAM: 2147483648
2014-03-24 19:14:55,116 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) CPU STATS after allocation: for host: 25, old used: 11500, old reserved: 0, actual total: 45600, total with overprovisioning: 45600; new used:12500, reserved:0; requested cpu:1000,alloc_from_last:false
2014-03-24 19:14:55,117 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) RAM STATS after allocation: for host: 25, old used: 19193135104, old reserved: 0, total: 66728595456; new used: 21340618752, reserved: 0; requested mem: 2147483648,alloc_from_last:false
2014-03-24 19:14:55,124 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) VM is being created in podId: 8
2014-03-24 19:14:55,127 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Network id=246 is already implemented
2014-03-24 19:14:55,150 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Service SecurityGroup is not supported in the network id=246
2014-03-24 19:14:55,157 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Changing active number of nics for network id=246 on 1
2014-03-24 19:14:55,168 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Asking VirtualRouter to prepare for Nic[1382-11729-e79c492a-aafe-447d-9eb7-11cb84a0b9a0-172.16.0.159]
2014-03-24 19:14:55,180 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Lock is acquired for network id 246 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(9)-Pod(8)-Cluster(6)-Host(25)-Storage(Volume(417|ROOT-->Pool(233))]
2014-03-24 19:14:55,183 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Lock is released for network id 246 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(9)-Pod(8)-Cluster(6)-Host(25)-Storage(Volume(417|ROOT-->Pool(233))]
2014-03-24 19:14:55,192 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Service SecurityGroup is not supported in the network id=246
2014-03-24 19:14:55,206 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Service SecurityGroup is not supported in the network id=246
2014-03-24 19:14:55,209 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Applying dhcp entry in network Ntwk[246|Guest|8]
2014-03-24 19:14:55,232 DEBUG [agent.transport.Request] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Seq 25-1317470218: Sending  { Cmd , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:51:53:00:10","vmIpAddress":"172.16.0.159","vmName":"test03242","defaultRouter":"172.16.0.1","defaultDns":"172.16.0.1","duid":"00:03:00:01:02:00:51:53:00:10","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"172.16.0.1","zone.network.type":"Advanced","router.name":"r-11692-VM","router.ip":"169.254.0.48"},"wait":0}}] }
2014-03-24 19:14:55,232 DEBUG [agent.transport.Request] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Seq 25-1317470218: Executing:  { Cmd , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:51:53:00:10","vmIpAddress":"172.16.0.159","vmName":"test03242","defaultRouter":"172.16.0.1","defaultDns":"172.16.0.1","duid":"00:03:00:01:02:00:51:53:00:10","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"172.16.0.1","zone.network.type":"Advanced","router.name":"r-11692-VM","router.ip":"169.254.0.48"},"wait":0}}] }
2014-03-24 19:14:55,232 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-367:null) Seq 25-1317470218: Executing request
2014-03-24 19:14:57,069 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 55-74420: Processing Seq 55-74420:  { Cmd , MgmtId: -1, via: 55, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":11717,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2014-03-24 19:14:57,081 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 55-74420: Sending Seq 55-74420:  { Ans: , MgmtId: 108183214607893, via: 55, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-03-24 19:14:57,601 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 43-1098: Processing Seq 43-1098:  { Cmd , MgmtId: -1, via: 43, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":11637,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2014-03-24 19:14:57,613 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 43-1098: Sending Seq 43-1098:  { Ans: , MgmtId: 108183214607893, via: 43, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-03-24 19:14:57,752 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===START===  192.168.40.103 -- GET  command=queryAsyncJobResult&jobId=e90157a7-5edf-4a85-859f-1080751f3bdf&response=json&sessionkey=Y9zoJw97y8mKqHwufhOQV0To9e4%3D&_=1395656097901
2014-03-24 19:14:57,804 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-367:null) Seq 25-1317470218: Response Received: 
2014-03-24 19:14:57,804 DEBUG [agent.transport.Request] (DirectAgent-367:null) Seq 25-1317470218: Processing:  { Ans: , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-03-24 19:14:57,804 DEBUG [agent.manager.AgentAttache] (DirectAgent-367:null) Seq 25-1317470218: No more commands found
2014-03-24 19:14:57,804 DEBUG [agent.transport.Request] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Seq 25-1317470218: Received:  { Ans: , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 110, { Answer } }
2014-03-24 19:14:57,823 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Service SecurityGroup is not supported in the network id=246
2014-03-24 19:14:57,832 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===END===  192.168.40.103 -- GET  command=queryAsyncJobResult&jobId=e90157a7-5edf-4a85-859f-1080751f3bdf&response=json&sessionkey=Y9zoJw97y8mKqHwufhOQV0To9e4%3D&_=1395656097901
2014-03-24 19:14:57,834 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Applying userdata and password entry in network Ntwk[246|Guest|8]
2014-03-24 19:14:57,874 DEBUG [agent.transport.Request] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Seq 25-1317470219: Sending  { Cmd , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"172.16.0.159","vmName":"test03242","executeInSequence":true,"accessDetails":{"router.guest.ip":"172.16.0.1","zone.network.type":"Advanced","router.ip":"169.254.0.48","router.name":"r-11692-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"172.16.0.159","vmName":"test03242","executeInSequence":true,"accessDetails":{"router.guest.ip":"172.16.0.1","zone.network.type":"Advanced","router.ip":"169.254.0.48","router.name":"r-11692-VM"},"wait":0}}] }
2014-03-24 19:14:57,874 DEBUG [agent.transport.Request] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Seq 25-1317470219: Executing:  { Cmd , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"172.16.0.159","vmName":"test03242","executeInSequence":true,"accessDetails":{"router.guest.ip":"172.16.0.1","zone.network.type":"Advanced","router.ip":"169.254.0.48","router.name":"r-11692-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"172.16.0.159","vmName":"test03242","executeInSequence":true,"accessDetails":{"router.guest.ip":"172.16.0.1","zone.network.type":"Advanced","router.ip":"169.254.0.48","router.name":"r-11692-VM"},"wait":0}}] }
2014-03-24 19:14:57,875 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-449:null) Seq 25-1317470219: Executing request
2014-03-24 19:14:58,807 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-449:null) Seq 25-1317470219: Response Received: 
2014-03-24 19:14:58,807 DEBUG [agent.transport.Request] (DirectAgent-449:null) Seq 25-1317470219: Processing:  { Ans: , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-03-24 19:14:58,807 DEBUG [agent.transport.Request] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Seq 25-1317470219: Received:  { Ans: , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 110, { Answer, Answer } }
2014-03-24 19:14:58,810 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Service SecurityGroup is not supported in the network id=246
2014-03-24 19:14:58,814 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking if we need to prepare 1 volumes for VM[User|test03242]
2014-03-24 19:14:58,814 DEBUG [agent.manager.AgentAttache] (DirectAgent-449:null) Seq 25-1317470219: No more commands found
2014-03-24 19:14:58,825 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Failed to start instance VM[User|test03242]
java.lang.NullPointerException
	at org.apache.cloudstack.storage.image.manager.ImageStoreProviderManagerImpl.getImageStore(ImageStoreProviderManagerImpl.java:65)
	at org.apache.cloudstack.storage.datastore.DataStoreManagerImpl.getDataStore(DataStoreManagerImpl.java:47)
	at org.apache.cloudstack.storage.image.TemplateDataFactoryImpl.getTemplate(TemplateDataFactoryImpl.java:90)
	at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2576)
	at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2641)
	at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
	at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
	at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
	at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3440)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3000)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2986)
	at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
	at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
	at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
	at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
	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)
2014-03-24 19:14:58,874 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Cleaning up resources for the vm VM[User|test03242] in Starting state
2014-03-24 19:14:58,878 DEBUG [agent.transport.Request] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Seq 25-1317470220: Sending  { Cmd , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-11729-VM","wait":0}}] }
2014-03-24 19:14:58,878 DEBUG [agent.transport.Request] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Seq 25-1317470220: Executing:  { Cmd , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-11729-VM","wait":0}}] }
2014-03-24 19:14:58,878 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-221:null) Seq 25-1317470220: Executing request
2014-03-24 19:14:58,971 INFO  [xen.resource.CitrixResourceBase] (DirectAgent-221:null) VM does not exist on XenServer483a0b4e-c7b0-4433-aac1-e5a1c1911448
2014-03-24 19:14:58,971 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-221:null) Seq 25-1317470220: Response Received: 
2014-03-24 19:14:58,971 DEBUG [agent.transport.Request] (DirectAgent-221:null) Seq 25-1317470220: Processing:  { Ans: , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM does not exist","wait":0}}] }
2014-03-24 19:14:58,971 DEBUG [agent.manager.AgentAttache] (DirectAgent-221:null) Seq 25-1317470220: No more commands found
2014-03-24 19:14:58,971 DEBUG [agent.transport.Request] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Seq 25-1317470220: Received:  { Ans: , MgmtId: 108183214607893, via: 25, Ver: v1, Flags: 110, { StopAnswer } }
2014-03-24 19:14:58,985 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Service SecurityGroup is not supported in the network id=246
2014-03-24 19:14:58,989 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Changing active number of nics for network id=246 on -1
2014-03-24 19:14:59,019 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Asking VirtualRouter to release Nic[1382-11729-e79c492a-aafe-447d-9eb7-11cb84a0b9a0-172.16.0.159]
2014-03-24 19:14:59,020 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Successfully released network resources for the vm VM[User|test03242]
2014-03-24 19:14:59,020 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Successfully cleanued up resources for the vm VM[User|test03242] in Starting state
2014-03-24 19:14:59,150 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 25
2014-03-24 19:14:59,166 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Hosts's actual total CPU: 45600 and CPU after applying overprovisioning: 45600
2014-03-24 19:14:59,166 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Hosts's actual total RAM: 66728596032 and RAM after applying overprovisioning: 66728595456
2014-03-24 19:14:59,166 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) release cpu from host: 25, old used: 12500,reserved: 0, actual total: 45600, total with overprovisioning: 45600; new used: 11500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-03-24 19:14:59,166 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) release mem from host: 25, old used: 21340618752,reserved: 0, total: 66728595456; new used: 19193135104,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-03-24 19:14:59,364 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) 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-03-24 19:14:59,364 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Successfully transitioned to start state for VM[User|test03242] reservation id = 4e452167-f36b-42e9-a795-7e82e186cf24
2014-03-24 19:14:59,407 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Trying to deploy VM, vm has dcId: 9 and podId: 8
2014-03-24 19:14:59,407 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Deploy avoids pods: [], clusters: [], hosts: [25]
2014-03-24 19:14:59,424 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Deploy avoids pods: [], clusters: [], hosts: [25]
2014-03-24 19:14:59,426 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_78958a70@2859ae8f
2014-03-24 19:14:59,426 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Trying to allocate a host and storage pools from dc:9, pod:8,cluster:null, requested cpu: 1000, requested ram: 2147483648
2014-03-24 19:14:59,426 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Is ROOT volume READY (pool already allocated)?: No
2014-03-24 19:14:59,426 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Searching resources only under specified Pod: 8
2014-03-24 19:14:59,426 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 8
2014-03-24 19:14:59,430 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Removing from the clusterId list these clusters from avoid set: []
2014-03-24 19:14:59,436 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking resources in Cluster: 6 under Pod: 8
2014-03-24 19:14:59,437 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Looking for hosts in dc: 9  pod:8  cluster:6
2014-03-24 19:14:59,441 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-62-Routing], Host[-25-Routing]]
2014-03-24 19:14:59,446 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-62-Routing], Host[-25-Routing]]
2014-03-24 19:14:59,446 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=2048
2014-03-24 19:14:59,452 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Checking if host: 62 has enough capacity for requested CPU: 1000 and requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
2014-03-24 19:14:59,455 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Hosts's actual total CPU: 45600 and CPU after applying overprovisioning: 45600
2014-03-24 19:14:59,455 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Free CPU: 45600 , Requested CPU: 1000
2014-03-24 19:14:59,455 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Free RAM: 66725756928 , Requested RAM: 2147483648
2014-03-24 19:14:59,455 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-03-24 19:14:59,455 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 62, used: 0, reserved: 0, actual total: 45600, total with overprovisioning: 45600; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-24 19:14:59,455 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 62, used: 0, reserved: 0, total: 66725756928; requested mem: 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-24 19:14:59,455 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Found a suitable host, adding to list: 62
2014-03-24 19:14:59,455 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Host name: ccndmg03, hostId: 25 is in avoid set, skipping this and trying other available hosts
2014-03-24 19:14:59,455 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2014-03-24 19:14:59,457 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking suitable pools for volume (Id, Type): (417,ROOT)
2014-03-24 19:14:59,457 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) We need to allocate new storagepool for this volume
2014-03-24 19:14:59,457 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Calling StoragePoolAllocators to find suitable pools
2014-03-24 19:14:59,457 DEBUG [storage.allocator.LocalStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2014-03-24 19:14:59,457 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) ClusterScopeStoragePoolAllocator looking for storage pool
2014-03-24 19:14:59,457 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Looking for pools in dc: 9  pod:8  cluster:6
2014-03-24 19:14:59,462 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking if storage pool is suitable, name: null ,poolId: 233
2014-03-24 19:14:59,467 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking pool 233 for storage, totalSize: 1099499044864, usedBytes: 191457394688, usedPct: 0.17413147886061317, disable threshold: 0.85
2014-03-24 19:14:59,492 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking pool: 233 for volume allocation [Vol[417|vm=11729|ROOT]], maxSize : 1099499044864, totalAllocatedSize : 172415254528, askingSize : 21474836480, allocated disable threshold: 0.85
2014-03-24 19:14:59,492 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2014-03-24 19:14:59,492 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2014-03-24 19:14:59,492 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Checking if host: 62 can access any suitable storage pool for volume: ROOT
2014-03-24 19:14:59,494 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Host: 62 cannot access pool: 233
2014-03-24 19:14:59,494 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Could not find a potential host that has associated storage pools from the suitable host/pool lists for this VM
2014-03-24 19:14:59,496 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Could not find suitable Deployment Destination for this VM under any clusters, returning. 
2014-03-24 19:14:59,496 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Searching resources only under specified Pod: 8
2014-03-24 19:14:59,496 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 8
2014-03-24 19:14:59,500 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Removing from the clusterId list these clusters from avoid set: [6]
2014-03-24 19:14:59,500 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2014-03-24 19:14:59,687 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: null
2014-03-24 19:14:59,767 DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Destroying vm VM[User|test03242] as it failed to create on Host with Id:null
2014-03-24 19:15:00,064 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) 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-03-24 19:15:00,280 WARN  [apache.cloudstack.alerts] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ])  alertType:: 8 // dataCenterId:: 9 // podId:: 8 // clusterId:: null // message:: Failed to deploy Vm with Id: 11729, on Host with Id: null
2014-03-24 19:15:00,384 INFO  [user.vm.DeployVMCmd] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|test03242]Scope=interface com.cloud.dc.DataCenter; id=9
2014-03-24 19:15:00,385 INFO  [user.vm.DeployVMCmd] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Unable to create a deployment for VM[User|test03242]
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|test03242]Scope=interface com.cloud.dc.DataCenter; id=9
	at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:841)
	at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
	at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
	at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3440)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3000)
	at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2986)
	at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
	at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
	at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
	at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
	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)
2014-03-24 19:15:00,388 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-15:job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ]) Complete async job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ], jobStatus: 2, resultCode: 530, result: Error Code: 533 Error text: Unable to create a deployment for VM[User|test03242]
2014-03-24 19:15:00,751 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null) ===START===  192.168.40.103 -- GET  command=queryAsyncJobResult&jobId=e90157a7-5edf-4a85-859f-1080751f3bdf&response=json&sessionkey=Y9zoJw97y8mKqHwufhOQV0To9e4%3D&_=1395656100900
2014-03-24 19:15:00,775 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-20:null) Async job-1847 = [ e90157a7-5edf-4a85-859f-1080751f3bdf ] completed