You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by William Jiang <Wi...@manwin.com> on 2013/08/01 00:06:55 UTC
cannot create instance from new created template--error "unable to
create a deployment for VM"
Hi all,
We just upgraded our cloudstack from 3.02 to 4.1 and xenserver hosts from 6.0.2 to 6.1.
When I tried to create an instance from our new created windows 2008 R2 template, I got the error of "unable to create a deployment for VM[user|test0731-win08]".
It was working well in old version.and for the new created template, it's no problem to download it.
Any idea or comments will be greatly appreciated.
The management-server.log as following:
2013-07-31 17:00:05,952 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===START=== 10.3.12.164 -- GET command=deployVirtualMachine&zoneId=2e115e65-3a77-4a92-a01b-e61380b6e2fb&templateId=152a7a03-5c0b-4623-819b-76c29dcfabad&hypervisor=XenServer&serviceOfferingId=24a7728d-31b3-47ad-8ada-3f28c2b58ca8&displayname=test0731-win08&name=test0731-win08&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304831675
2013-07-31 17:00:05,956 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-13:null) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2013-07-31 17:00:05,957 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-13:null) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2013-07-31 17:00:05,978 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-13:null) Allocating in the DB for vm
2013-07-31 17:00:05,985 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-13:null) Allocating entries for VM: VM[User|test0731-win08]
2013-07-31 17:00:05,985 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-13:null) Allocating nics for VM[User|test0731-win08]
2013-07-31 17:00:05,986 DEBUG [cloud.network.NetworkManagerImpl] (catalina-exec-13:null) Allocating nic for vm VM[User|test0731-win08] in network Ntwk[204|Guest|5] with requested profile NicProfile[0-0-null-null-null
2013-07-31 17:00:05,991 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-13:null) Allocaing disks for VM[User|test0731-win08]
2013-07-31 17:00:05,996 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-13:null) Allocation completed for VM: VM[User|test0731-win08]
2013-07-31 17:00:05,996 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-13:null) Successfully allocated DB entry for VM[User|test0731-win08]
2013-07-31 17:00:06,022 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-13:null) submit async job-1134, details: AsyncJobVO {id:1134, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 205, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator: null, cmdInfo: {"sessionkey":"HDreO5WAFQBLrWY7gqkU1YP71uc\u003d","ctxUserId":"2","serviceOfferingId":"24a7728d-31b3-47ad-8ada-3f28c2b58ca8","zoneId":"2e115e65-3a77-4a92-a01b-e61380b6e2fb","templateId":"152a7a03-5c0b-4623-819b-76c29dcfabad","response":"json","id":"205","hypervisor":"XenServer","name":"test0731-win08","projectid":"20bc456a-fe80-4cbb-8d67-ea0f70ece80a","_":"1375304831675","ctxAccountId":"2","ctxStartEventId":"14906","displayname":"test0731-win08"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 110492071566, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-07-31 17:00:06,024 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-25:job-1134) Executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-1134
2013-07-31 17:00:06,024 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===END=== 10.3.12.164 -- GET command=deployVirtualMachine&zoneId=2e115e65-3a77-4a92-a01b-e61380b6e2fb&templateId=152a7a03-5c0b-4623-819b-76c29dcfabad&hypervisor=XenServer&serviceOfferingId=24a7728d-31b3-47ad-8ada-3f28c2b58ca8&displayname=test0731-win08&name=test0731-win08&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304831675
2013-07-31 17:00:06,028 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-25:job-1134) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2013-07-31 17:00:06,029 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-25:job-1134) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2013-07-31 17:00:06,053 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) DeploymentPlanner allocation algorithm: random
2013-07-31 17:00:06,053 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 4000, requested ram: 2147483648
2013-07-31 17:00:06,053 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Is ROOT volume READY (pool already allocated)?: No
2013-07-31 17:00:06,053 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Searching all possible resources under this Zone: 1
2013-07-31 17:00:06,054 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2013-07-31 17:00:06,054 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) CPUOverprovisioningFactor considered: 1.0
2013-07-31 17:00:06,060 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Checking resources in Cluster: 1 under Pod: 1
2013-07-31 17:00:06,062 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2013-07-31 17:00:06,063 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) FirstFitAllocator has 4 hosts to check for allocation: [Host[-2-Routing], Host[-3-Routing], Host[-1-Routing], Host[-4-Routing]]
2013-07-31 17:00:06,065 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Found 4 hosts for allocation after prioritization: [Host[-2-Routing], Host[-3-Routing], Host[-1-Routing], Host[-4-Routing]]
2013-07-31 17:00:06,066 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Looking for speed=4000Mhz, Ram=2048
2013-07-31 17:00:06,067 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Checking if host: 2 has enough capacity for requested CPU: 4000 and requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
2013-07-31 17:00:06,068 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-07-31 17:00:06,068 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Free CPU: -6500 , Requested CPU: 4000
2013-07-31 17:00:06,068 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Free RAM: 213251223808 , Requested RAM: 2147483648
2013-07-31 17:00:06,068 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) STATS: Failed to alloc resource from host: 2 reservedCpu: 0, used cpu: 70500, requested cpu: 4000, actual total cpu: 64000, total cpu with overprovisioning: 64000, reservedMem: 0, used Mem: 56342085632, requested mem: 2147483648, total Mem:269593309440 ,considerReservedCapacity?: true
2013-07-31 17:00:06,068 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Host does not have enough CPU available, cannot allocate to this host.
2013-07-31 17:00:06,068 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Not using host 2; numCpusGood: true; cpuFreqGood: true, host has capacity?false
2013-07-31 17:00:06,070 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Checking if host: 3 has enough capacity for requested CPU: 4000 and requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
2013-07-31 17:00:06,071 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-07-31 17:00:06,071 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Free CPU: 10000 , Requested CPU: 4000
2013-07-31 17:00:06,071 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Free RAM: 207295312128 , Requested RAM: 2147483648
2013-07-31 17:00:06,071 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-07-31 17:00:06,071 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 3, used: 54000, reserved: 0, actual total: 64000, total with overprovisioning: 64000; requested cpu:4000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-07-31 17:00:06,071 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 3, used: 62297997312, reserved: 0, total: 269593309440; requested mem: 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-07-31 17:00:06,071 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Found a suitable host, adding to list: 3
2013-07-31 17:00:06,073 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 4000 and requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
2013-07-31 17:00:06,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-07-31 17:00:06,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Free CPU: 39000 , Requested CPU: 4000
2013-07-31 17:00:06,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Free RAM: 210537509120 , Requested RAM: 2147483648
2013-07-31 17:00:06,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-07-31 17:00:06,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 25000, reserved: 0, actual total: 64000, total with overprovisioning: 64000; requested cpu:4000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-07-31 17:00:06,074 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 59055800320, reserved: 0, total: 269593309440; requested mem: 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-07-31 17:00:06,074 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2013-07-31 17:00:06,075 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Checking if host: 4 has enough capacity for requested CPU: 4000 and requested RAM: 2147483648 , cpuOverprovisioningFactor: 1.0
2013-07-31 17:00:06,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-07-31 17:00:06,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Free CPU: 48000 , Requested CPU: 4000
2013-07-31 17:00:06,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Free RAM: 261003374848 , Requested RAM: 2147483648
2013-07-31 17:00:06,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-07-31 17:00:06,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 4, used: 16000, reserved: 0, actual total: 64000, total with overprovisioning: 64000; requested cpu:4000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-07-31 17:00:06,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 4, used: 8589934592, reserved: 0, total: 269593309440; requested mem: 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-07-31 17:00:06,077 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Found a suitable host, adding to list: 4
2013-07-31 17:00:06,077 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-25:job-1134 FirstFitRoutingAllocator) Host Allocator returning 3 suitable hosts
2013-07-31 17:00:06,077 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Checking suitable pools for volume (Id, Type): (255,ROOT)
2013-07-31 17:00:06,078 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) We need to allocate new storagepool for this volume
2013-07-31 17:00:06,078 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Calling StoragePoolAllocators to find suitable pools
2013-07-31 17:00:06,079 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-25:job-1134) Looking for pools in dc: 1 pod:1 cluster:1
2013-07-31 17:00:06,080 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-25:job-1134) FirstFitStoragePoolAllocator has 5 pools to check for allocation
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen2-cld.na.manwin.local Local Storage ,poolId: 207
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen3-cld.na.manwin.local Local Storage ,poolId: 208
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: CloudStackPrimary ,poolId: 202
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:06,080 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? true
2013-07-31 17:00:06,081 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-25:job-1134) Checking pool 202 for storage, totalSize: 15536092086272, usedBytes: 4209378328576, usedPct: 0.2709419012967547, disable threshold: 0.85
2013-07-31 17:00:06,086 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-25:job-1134) Checking pool: 202 for volume allocation [Vol[255|vm=205|ROOT]], maxSize : 15536092086272, totalAllocatedSize : 3451618590720, askingSize : 42949672960, allocated disable threshold: 0.85
2013-07-31 17:00:06,086 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen1-cld.na.manwin.local Local Storage ,poolId: 204
2013-07-31 17:00:06,086 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:06,086 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:06,086 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:06,086 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen4-cld.na.manwin.local Local Storage ,poolId: 206
2013-07-31 17:00:06,086 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:06,086 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:06,086 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:06,086 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-25:job-1134) FirstFitStoragePoolAllocator returning 1 suitable storage pools
2013-07-31 17:00:06,086 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-07-31 17:00:06,086 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Checking if host: 3 can access any suitable storage pool for volume: ROOT
2013-07-31 17:00:06,087 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Host: 3 can access pool: 202
2013-07-31 17:00:06,087 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Found a potential host id: 3 name: xen2-cld.na.manwin.local and associated storage pools for this VM
2013-07-31 17:00:06,088 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) 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(3)-Storage(Volume(255|ROOT-->Pool(202))]
2013-07-31 17:00:06,097 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) 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-07-31 17:00:06,097 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-25:job-1134) Successfully transitioned to start state for VM[User|test0731-win08] reservation id = 087944d0-6a3b-4b93-88e6-08641bc66ae4
2013-07-31 17:00:06,099 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-25:job-1134) Trying to deploy VM, vm has dcId: 1 and podId: null
2013-07-31 17:00:06,099 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-25:job-1134) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 3, poolId: null
2013-07-31 17:00:06,099 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-25:job-1134) Deploy avoids pods: null, clusters: null, hosts: null
2013-07-31 17:00:06,100 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) DeploymentPlanner allocation algorithm: random
2013-07-31 17:00:06,100 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 4000, requested ram: 2147483648
2013-07-31 17:00:06,100 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Is ROOT volume READY (pool already allocated)?: No
2013-07-31 17:00:06,100 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 3
2013-07-31 17:00:06,101 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2013-07-31 17:00:06,102 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Checking suitable pools for volume (Id, Type): (255,ROOT)
2013-07-31 17:00:06,102 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) We need to allocate new storagepool for this volume
2013-07-31 17:00:06,102 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Calling StoragePoolAllocators to find suitable pools
2013-07-31 17:00:06,102 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-25:job-1134) Looking for pools in dc: 1 pod:1 cluster:1
2013-07-31 17:00:06,103 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-25:job-1134) FirstFitStoragePoolAllocator has 5 pools to check for allocation
2013-07-31 17:00:06,104 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen3-cld.na.manwin.local Local Storage ,poolId: 208
2013-07-31 17:00:06,104 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:06,104 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:06,104 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:06,104 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: CloudStackPrimary ,poolId: 202
2013-07-31 17:00:06,104 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:06,104 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? true
2013-07-31 17:00:06,105 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-25:job-1134) Checking pool 202 for storage, totalSize: 15536092086272, usedBytes: 4209378328576, usedPct: 0.2709419012967547, disable threshold: 0.85
2013-07-31 17:00:06,109 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-25:job-1134) Checking pool: 202 for volume allocation [Vol[255|vm=205|ROOT]], maxSize : 15536092086272, totalAllocatedSize : 3451618590720, askingSize : 42949672960, allocated disable threshold: 0.85
2013-07-31 17:00:06,109 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen2-cld.na.manwin.local Local Storage ,poolId: 207
2013-07-31 17:00:06,109 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:06,109 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:06,109 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:06,109 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen1-cld.na.manwin.local Local Storage ,poolId: 204
2013-07-31 17:00:06,110 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:06,110 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:06,110 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:06,110 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen4-cld.na.manwin.local Local Storage ,poolId: 206
2013-07-31 17:00:06,110 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:06,110 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:06,110 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:06,110 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-25:job-1134) FirstFitStoragePoolAllocator returning 1 suitable storage pools
2013-07-31 17:00:06,110 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-07-31 17:00:06,110 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Checking if host: 3 can access any suitable storage pool for volume: ROOT
2013-07-31 17:00:06,110 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Host: 3 can access pool: 202
2013-07-31 17:00:06,111 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Found a potential host id: 3 name: xen2-cld.na.manwin.local and associated storage pools for this VM
2013-07-31 17:00:06,111 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) 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(3)-Storage(Volume(255|ROOT-->Pool(202))]
2013-07-31 17:00:06,111 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-25:job-1134) Deployment found - P0=VM[User|test0731-win08], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(3)-Storage(Volume(255|ROOT-->Pool(202))]
2013-07-31 17:00:06,114 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 3 host id before state transition: null
2013-07-31 17:00:06,117 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-07-31 17:00:06,117 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) We are allocating VM, increasing the used capacity of this host:3
2013-07-31 17:00:06,117 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) Current Used CPU: 54000 , Free CPU:10000 ,Requested CPU: 4000
2013-07-31 17:00:06,117 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) Current Used RAM: 62297997312 , Free RAM:207295312128 ,Requested RAM: 2147483648
2013-07-31 17:00:06,117 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) CPU STATS after allocation: for host: 3, old used: 54000, old reserved: 0, actual total: 64000, total with overprovisioning: 64000; new used:58000, reserved:0; requested cpu:4000,alloc_from_last:false
2013-07-31 17:00:06,117 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) RAM STATS after allocation: for host: 3, old used: 62297997312, old reserved: 0, total: 269593309440; new used: 64445480960, reserved: 0; requested mem: 2147483648,alloc_from_last:false
2013-07-31 17:00:06,119 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-25:job-1134) VM is being created in podId: 1
2013-07-31 17:00:06,121 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Lock is acquired for network id 204 as a part of network implement
2013-07-31 17:00:06,121 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Network id=204 is already implemented
2013-07-31 17:00:06,121 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Lock is released for network id 204 as a part of network implement
2013-07-31 17:00:06,134 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Changing active number of nics for network id=204 on 1
2013-07-31 17:00:06,135 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking NiciraNvp to prepare for Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:06,135 DEBUG [network.element.NiciraNvpElement] (Job-Executor-25:job-1134) Checking if NiciraNvpElement can handle service Connectivity on network guestNetworkForBasicZone
2013-07-31 17:00:06,137 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking JuniperSRX to prepare for Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:06,139 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking Netscaler to prepare for Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:06,140 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking F5BigIP to prepare for Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:06,142 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking CiscoNexus1000vVSM to prepare for Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:06,142 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking BigSwitchVnsElement to prepare for Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:06,142 DEBUG [network.element.BigSwitchVnsElement] (Job-Executor-25:job-1134) Checking if BigSwitchVnsElement can handle service Connectivity on network guestNetworkForBasicZone
2013-07-31 17:00:06,144 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking VirtualRouter to prepare for Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:06,149 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-25:job-1134) Lock is acquired for network id 204 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(3)-Storage(Volume(255|ROOT-->Pool(202))]
2013-07-31 17:00:06,151 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-25:job-1134) Skipping VR deployment: Found a running or starting VR in Pod null id=1
2013-07-31 17:00:06,152 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-25:job-1134) Lock is released for network id 204 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(3)-Storage(Volume(255|ROOT-->Pool(202))]
2013-07-31 17:00:06,157 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-25:job-1134) Applying dhcp entry in network Ntwk[204|Guest|5]
2013-07-31 17:00:06,167 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 2-1305018907: Sending { Cmd , MgmtId: 110492071566, via: 2, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:d2:7e:00:00:22","vmIpAddress":"10.3.34.44","vmName":"test0731-win08","defaultRouter":"10.3.34.1","defaultDns":"10.3.34.29","duid":"00:03:00:01:06:d2:7e:00:00:22","isDefault":true,"accessDetails":{"router.guest.ip":"10.3.34.29","zone.network.type":"Basic","router.name":"r-4-VM","router.ip":"169.254.3.241"},"wait":0}}] }
2013-07-31 17:00:06,167 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 2-1305018907: Executing: { Cmd , MgmtId: 110492071566, via: 2, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:d2:7e:00:00:22","vmIpAddress":"10.3.34.44","vmName":"test0731-win08","defaultRouter":"10.3.34.1","defaultDns":"10.3.34.29","duid":"00:03:00:01:06:d2:7e:00:00:22","isDefault":true,"accessDetails":{"router.guest.ip":"10.3.34.29","zone.network.type":"Basic","router.name":"r-4-VM","router.ip":"169.254.3.241"},"wait":0}}] }
2013-07-31 17:00:06,167 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-258:null) Seq 2-1305018907: Executing request
2013-07-31 17:00:07,204 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-07-31 17:00:07,450 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-07-31 17:00:07,714 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
2013-07-31 17:00:07,714 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-07-31 17:00:07,747 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
2013-07-31 17:00:07,747 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-07-31 17:00:09,075 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-258:null) Seq 2-1305018907: Response Received:
2013-07-31 17:00:09,076 DEBUG [agent.transport.Request] (DirectAgent-258:null) Seq 2-1305018907: Processing: { Ans: , MgmtId: 110492071566, via: 2, Ver: v1, Flags: 110, [{"Answer":{"result":true,"wait":0}}] }
2013-07-31 17:00:09,076 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 2-1305018907: Received: { Ans: , MgmtId: 110492071566, via: 2, Ver: v1, Flags: 110, { Answer } }
2013-07-31 17:00:09,076 DEBUG [agent.manager.AgentAttache] (DirectAgent-258:null) Seq 2-1305018907: No more commands found
2013-07-31 17:00:09,082 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-25:job-1134) Applying userdata and password entry in network Ntwk[204|Guest|5]
2013-07-31 17:00:09,091 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===START=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304834815
2013-07-31 17:00:09,092 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 2-1305018908: Sending { Cmd , MgmtId: 110492071566, via: 2, Ver: v1, Flags: 100111, [{"routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.3.34.44","vmName":"test0731-win08","accessDetails":{"router.guest.ip":"10.3.34.29","zone.network.type":"Basic","router.ip":"169.254.3.241","router.name":"r-4-VM"},"wait":0}},{"routing.VmDataCommand":{"vmIpAddress":"10.3.34.44","vmName":"test0731-win08","accessDetails":{"router.guest.ip":"10.3.34.29","zone.network.type":"Basic","router.ip":"169.254.3.241","router.name":"r-4-VM"},"wait":0}}] }
2013-07-31 17:00:09,092 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 2-1305018908: Executing: { Cmd , MgmtId: 110492071566, via: 2, Ver: v1, Flags: 100111, [{"routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.3.34.44","vmName":"test0731-win08","accessDetails":{"router.guest.ip":"10.3.34.29","zone.network.type":"Basic","router.ip":"169.254.3.241","router.name":"r-4-VM"},"wait":0}},{"routing.VmDataCommand":{"vmIpAddress":"10.3.34.44","vmName":"test0731-win08","accessDetails":{"router.guest.ip":"10.3.34.29","zone.network.type":"Basic","router.ip":"169.254.3.241","router.name":"r-4-VM"},"wait":0}}] }
2013-07-31 17:00:09,092 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-219:null) Seq 2-1305018908: Executing request
2013-07-31 17:00:09,110 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===END=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304834815
2013-07-31 17:00:10,640 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 6
2013-07-31 17:00:12,053 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===START=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304837777
2013-07-31 17:00:12,064 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===END=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304837777
2013-07-31 17:00:13,914 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2013-07-31 17:00:13,927 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-205:null) Seq 1-1396834849: Executing request
2013-07-31 17:00:14,224 WARN [xen.resource.CitrixResourceBase] (DirectAgent-205:null) Found 2 VMs with name: i-4-36-VM
2013-07-31 17:00:14,248 WARN [xen.resource.CitrixResourceBase] (DirectAgent-205:null) Found 2 VMs with name: i-4-50-VM
2013-07-31 17:00:14,862 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-205:null) Vm cpu utilization 10.39
2013-07-31 17:00:14,862 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-205:null) Vm cpu utilization 0.0
2013-07-31 17:00:14,862 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-205:null) Vm cpu utilization 1.6300000000000001
2013-07-31 17:00:14,862 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-205:null) Vm cpu utilization 9.9
2013-07-31 17:00:14,862 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-205:null) Vm cpu utilization 0.0
2013-07-31 17:00:14,862 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-205:null) Vm cpu utilization 0.5
2013-07-31 17:00:14,862 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-205:null) Seq 1-1396834849: Response Received:
2013-07-31 17:00:14,863 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-1396834849: Received: { Ans: , MgmtId: 110492071566, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-07-31 17:00:14,885 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-353:null) Seq 2-1305018909: Executing request
2013-07-31 17:00:15,055 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null) ===START=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304840779
2013-07-31 17:00:15,068 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null) ===END=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304840779
2013-07-31 17:00:15,191 WARN [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Found 2 VMs with name: i-5-119-VM
2013-07-31 17:00:15,224 WARN [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Found 2 VMs with name: i-4-136-VM
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 45.091249999999995
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 9.485000000000001
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 0.13625
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 1.2
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 1.225
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 10.1625
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 0.2875
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 0.24
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 0.8656250000000001
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 1.28
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 0.0
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 0.7125
2013-07-31 17:00:15,551 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-353:null) Vm cpu utilization 0.43499999999999994
2013-07-31 17:00:15,551 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-353:null) Seq 2-1305018909: Response Received:
2013-07-31 17:00:15,552 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 2-1305018909: Received: { Ans: , MgmtId: 110492071566, via: 2, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-07-31 17:00:15,571 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-464:null) Seq 3-451674646: Executing request
2013-07-31 17:00:15,920 WARN [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Found 2 VMs with name: i-4-95-VM
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 0.0
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 0.255
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 1.1675000000000002
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 15.312500000000002
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 0.76
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 0.415
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 0.27
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 0.1275
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 3.1850000000000005
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 0.135
2013-07-31 17:00:16,471 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-464:null) Vm cpu utilization 0.375
2013-07-31 17:00:16,471 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-464:null) Seq 3-451674646: Response Received:
2013-07-31 17:00:16,472 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 3-451674646: Received: { Ans: , MgmtId: 110492071566, via: 3, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-07-31 17:00:16,478 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-366:null) Seq 4-63308308: Executing request
2013-07-31 17:00:17,129 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-366:null) Vm cpu utilization 0.48000000000000004
2013-07-31 17:00:17,130 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-366:null) Vm cpu utilization 0.5025
2013-07-31 17:00:17,130 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-366:null) Seq 4-63308308: Response Received:
2013-07-31 17:00:17,130 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-63308308: Received: { Ans: , MgmtId: 110492071566, via: 4, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-07-31 17:00:18,056 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===START=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304843780
2013-07-31 17:00:18,067 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===END=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304843780
2013-07-31 17:00:21,058 DEBUG [cloud.api.ApiServlet] (catalina-exec-12:null) ===START=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304846782
2013-07-31 17:00:21,069 DEBUG [cloud.api.ApiServlet] (catalina-exec-12:null) ===END=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304846782
2013-07-31 17:00:21,448 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) Ping from 110
2013-07-31 17:00:21,898 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-359:null) Ping from 4
2013-07-31 17:00:21,988 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-366:null) Ping from 1
2013-07-31 17:00:23,259 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-392:null) Ping from 2
2013-07-31 17:00:23,906 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-219:null) Seq 2-1305018908: Response Received:
2013-07-31 17:00:23,906 DEBUG [agent.transport.Request] (DirectAgent-219:null) Seq 2-1305018908: Processing: { Ans: , MgmtId: 110492071566, via: 2, Ver: v1, Flags: 110, [{"Answer":{"result":true,"wait":0}},{"Answer":{"result":true,"wait":0}}] }
2013-07-31 17:00:23,906 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 2-1305018908: Received: { Ans: , MgmtId: 110492071566, via: 2, Ver: v1, Flags: 110, { Answer, Answer } }
2013-07-31 17:00:23,906 DEBUG [agent.manager.AgentAttache] (DirectAgent-219:null) Seq 2-1305018908: No more commands found
2013-07-31 17:00:23,906 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking Ovs to prepare for Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:23,906 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking SecurityGroupProvider to prepare for Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:23,909 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking VpcVirtualRouter to prepare for Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:23,909 WARN [network.element.VpcVirtualRouterElement] (Job-Executor-25:job-1134) Network Ntwk[204|Guest|5] is not associated with any VPC
2013-07-31 17:00:23,913 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-25:job-1134) Checking if we need to prepare 1 volumes for VM[User|test0731-win08]
2013-07-31 17:00:23,914 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-25:job-1134) Creating volume: Vol[255|vm=205|ROOT]
2013-07-31 17:00:23,914 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-25:job-1134) Trying to create in Pool[202|IscsiLUN]
2013-07-31 17:00:23,923 DEBUG [cloud.template.TemplateManagerImpl] (Job-Executor-25:job-1134) Downloading 279 via 1
2013-07-31 17:00:23,926 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 1-1396834850: Sending { Cmd , MgmtId: 110492071566, via: 1, Ver: v1, Flags: 100111, [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/2865ed4f-e8da-31f2-9353-c0abd93d8aba","poolUuid":"2865ed4f-e8da-31f2-9353-c0abd93d8aba","poolId":202,"primaryPool":{"id":202,"uuid":"2865ed4f-e8da-31f2-9353-c0abd93d8aba","host":"10.3.34.5","path":"/iqn.2001-05.com.equallogic:0-1cb196-305b0190a-84600000019511bd-cloudstackprimary/0","port":3260,"type":"IscsiLUN"},"secondaryStorageUrl":"nfs://mgt-cld.na.manwin.local/home/secondary","primaryStorageUrl":"nfs://10.3.34.5/iqn.2001-05.com.equallogic:0-1cb196-305b0190a-84600000019511bd-cloudstackprimary/0","url":"nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd","format":"VHD","accountId":4,"name":"628792ca-90cc-4222-934e-d680581dacf9","wait":10800}}] }
2013-07-31 17:00:23,926 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 1-1396834850: Executing: { Cmd , MgmtId: 110492071566, via: 1, Ver: v1, Flags: 100111, [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/2865ed4f-e8da-31f2-9353-c0abd93d8aba","poolUuid":"2865ed4f-e8da-31f2-9353-c0abd93d8aba","poolId":202,"primaryPool":{"id":202,"uuid":"2865ed4f-e8da-31f2-9353-c0abd93d8aba","host":"10.3.34.5","path":"/iqn.2001-05.com.equallogic:0-1cb196-305b0190a-84600000019511bd-cloudstackprimary/0","port":3260,"type":"IscsiLUN"},"secondaryStorageUrl":"nfs://mgt-cld.na.manwin.local/home/secondary","primaryStorageUrl":"nfs://10.3.34.5/iqn.2001-05.com.equallogic:0-1cb196-305b0190a-84600000019511bd-cloudstackprimary/0","url":"nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd","format":"VHD","accountId":4,"name":"628792ca-90cc-4222-934e-d680581dacf9","wait":10800}}] }
2013-07-31 17:00:23,926 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-183:null) Seq 1-1396834850: Executing request
2013-07-31 17:00:24,060 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===START=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304849785
2013-07-31 17:00:24,071 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===END=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304849785
2013-07-31 17:00:24,241 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-464:null) Ping from 3
2013-07-31 17:00:26,346 WARN [xen.resource.CitrixResourceBase] (DirectAgent-183:null) Task failed! Task record: uuid: 8c8f6849-e23a-c40c-81aa-8296c53888aa
nameLabel: Async.host.call_plugin
nameDescription:
allowedOperations: []
currentOperations: {}
created: Wed Jul 31 17:07:31 EDT 2013
finished: Wed Jul 31 17:07:31 EDT 2013
status: failure
residentOn: com.xensource.xenapi.Host@d4c02742
progress: 1.0
type: <none/>
result:
errorInfo: [XENAPI_PLUGIN_FAILURE, signal: SIGKILL, ]
otherConfig: {}
subtaskOf: com.xensource.xenapi.Task@aaf13f6f
subtasks: []
2013-07-31 17:00:26,442 WARN [xen.resource.CitrixResourceBase] (DirectAgent-183:null) callHostPlugin failed for cmd: kill_copy_process with args namelabel: 628792ca-90cc-4222-934e-d680581dacf9.vhd, due to Task failed! Task record: uuid: 8c8f6849-e23a-c40c-81aa-8296c53888aa
nameLabel: Async.host.call_plugin
nameDescription:
allowedOperations: []
currentOperations: {}
created: Wed Jul 31 17:07:31 EDT 2013
finished: Wed Jul 31 17:07:31 EDT 2013
status: failure
residentOn: com.xensource.xenapi.Host@d4c02742
progress: 1.0
type: <none/>
result:
errorInfo: [XENAPI_PLUGIN_FAILURE, signal: SIGKILL, ]
otherConfig: {}
subtaskOf: com.xensource.xenapi.Task@aaf13f6f
subtasks: []
Task failed! Task record: uuid: 8c8f6849-e23a-c40c-81aa-8296c53888aa
nameLabel: Async.host.call_plugin
nameDescription:
allowedOperations: []
currentOperations: {}
created: Wed Jul 31 17:07:31 EDT 2013
finished: Wed Jul 31 17:07:31 EDT 2013
status: failure
residentOn: com.xensource.xenapi.Host@d4c02742
progress: 1.0
type: <none/>
result:
errorInfo: [XENAPI_PLUGIN_FAILURE, signal: SIGKILL, ]
otherConfig: {}
subtaskOf: com.xensource.xenapi.Task@aaf13f6f
subtasks: []
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.checkForSuccess(CitrixResourceBase.java:3177)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.callHostPluginAsync(CitrixResourceBase.java:3490)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.killCopyProcess(CitrixResourceBase.java:2657)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.copy_vhd_from_secondarystorage(CitrixResourceBase.java:2703)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2729)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:501)
at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:73)
at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-07-31 17:00:26,455 WARN [xen.resource.CitrixResourceBase] (DirectAgent-183:null) kill_copy_process failed
2013-07-31 17:00:26,455 WARN [xen.resource.CitrixResourceBase] (DirectAgent-183:null) can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6
2013-07-31 17:00:26,455 WARN [xen.resource.CitrixResourceBase] (DirectAgent-183:null) Catch Exception com.cloud.utils.exception.CloudRuntimeException on host:21870d6d-c300-4f6d-80c2-b4bedc7f1f25 for template: nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6
com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.copy_vhd_from_secondarystorage(CitrixResourceBase.java:2707)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2729)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:501)
at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:73)
at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-07-31 17:00:26,455 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-183:null) Seq 1-1396834850: Response Received:
2013-07-31 17:00:26,456 DEBUG [agent.transport.Request] (DirectAgent-183:null) Seq 1-1396834850: Processing: { Ans: , MgmtId: 110492071566, via: 1, Ver: v1, Flags: 110, [{"storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result":false,"details":"Catch Exception com.cloud.utils.exception.CloudRuntimeException on host:21870d6d-c300-4f6d-80c2-b4bedc7f1f25 for template: nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6","wait":0}}] }
2013-07-31 17:00:26,456 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 1-1396834850: Received: { Ans: , MgmtId: 110492071566, via: 1, Ver: v1, Flags: 110, { PrimaryStorageDownloadAnswer } }
2013-07-31 17:00:26,456 DEBUG [agent.manager.AgentAttache] (DirectAgent-183:null) Seq 1-1396834850: No more commands found
2013-07-31 17:00:26,456 DEBUG [agent.manager.AgentManagerImpl] (Job-Executor-25:job-1134) Details from executing class com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: Catch Exception com.cloud.utils.exception.CloudRuntimeException on host:21870d6d-c300-4f6d-80c2-b4bedc7f1f25 for template: nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6
2013-07-31 17:00:26,456 DEBUG [cloud.template.TemplateManagerImpl] (Job-Executor-25:job-1134) Template 279 download to pool 202 failed due to Catch Exception com.cloud.utils.exception.CloudRuntimeException on host:21870d6d-c300-4f6d-80c2-b4bedc7f1f25 for template: nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6
2013-07-31 17:00:26,456 DEBUG [cloud.template.TemplateManagerImpl] (Job-Executor-25:job-1134) Downloading 279 via 3
2013-07-31 17:00:26,459 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 3-451674647: Sending { Cmd , MgmtId: 110492071566, via: 3, Ver: v1, Flags: 100111, [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/2865ed4f-e8da-31f2-9353-c0abd93d8aba","poolUuid":"2865ed4f-e8da-31f2-9353-c0abd93d8aba","poolId":202,"primaryPool":{"id":202,"uuid":"2865ed4f-e8da-31f2-9353-c0abd93d8aba","host":"10.3.34.5","path":"/iqn.2001-05.com.equallogic:0-1cb196-305b0190a-84600000019511bd-cloudstackprimary/0","port":3260,"type":"IscsiLUN"},"secondaryStorageUrl":"nfs://mgt-cld.na.manwin.local/home/secondary","primaryStorageUrl":"nfs://10.3.34.5/iqn.2001-05.com.equallogic:0-1cb196-305b0190a-84600000019511bd-cloudstackprimary/0","url":"nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd","format":"VHD","accountId":4,"name":"628792ca-90cc-4222-934e-d680581dacf9","wait":10800}}] }
2013-07-31 17:00:26,459 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 3-451674647: Executing: { Cmd , MgmtId: 110492071566, via: 3, Ver: v1, Flags: 100111, [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/2865ed4f-e8da-31f2-9353-c0abd93d8aba","poolUuid":"2865ed4f-e8da-31f2-9353-c0abd93d8aba","poolId":202,"primaryPool":{"id":202,"uuid":"2865ed4f-e8da-31f2-9353-c0abd93d8aba","host":"10.3.34.5","path":"/iqn.2001-05.com.equallogic:0-1cb196-305b0190a-84600000019511bd-cloudstackprimary/0","port":3260,"type":"IscsiLUN"},"secondaryStorageUrl":"nfs://mgt-cld.na.manwin.local/home/secondary","primaryStorageUrl":"nfs://10.3.34.5/iqn.2001-05.com.equallogic:0-1cb196-305b0190a-84600000019511bd-cloudstackprimary/0","url":"nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd","format":"VHD","accountId":4,"name":"628792ca-90cc-4222-934e-d680581dacf9","wait":10800}}] }
2013-07-31 17:00:26,459 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-305:null) Seq 3-451674647: Executing request
2013-07-31 17:00:27,062 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null) ===START=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304852787
2013-07-31 17:00:27,072 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null) ===END=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304852787
2013-07-31 17:00:28,505 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-159:null) Seq 2-1305018373: Executing request
2013-07-31 17:00:29,041 WARN [xen.resource.CitrixResourceBase] (DirectAgent-305:null) destoryVDIbyNameLabel failed due to there are 0 VDIs with name cloud-d5cf9ee7-786c-4862-bd53-6bb50bc5f46a
2013-07-31 17:00:29,043 WARN [xen.resource.CitrixResourceBase] (DirectAgent-305:null) can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6
2013-07-31 17:00:29,043 WARN [xen.resource.CitrixResourceBase] (DirectAgent-305:null) Catch Exception com.cloud.utils.exception.CloudRuntimeException on host:a956ec58-a7bd-43e5-8a68-18182a3d3ade for template: nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6
com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.copy_vhd_from_secondarystorage(CitrixResourceBase.java:2707)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2729)
at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:501)
at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:73)
at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-07-31 17:00:29,043 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-305:null) Seq 3-451674647: Response Received:
2013-07-31 17:00:29,044 DEBUG [agent.transport.Request] (DirectAgent-305:null) Seq 3-451674647: Processing: { Ans: , MgmtId: 110492071566, via: 3, Ver: v1, Flags: 110, [{"storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result":false,"details":"Catch Exception com.cloud.utils.exception.CloudRuntimeException on host:a956ec58-a7bd-43e5-8a68-18182a3d3ade for template: nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6","wait":0}}] }
2013-07-31 17:00:29,044 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 3-451674647: Received: { Ans: , MgmtId: 110492071566, via: 3, Ver: v1, Flags: 110, { PrimaryStorageDownloadAnswer } }
2013-07-31 17:00:29,044 DEBUG [agent.manager.AgentManagerImpl] (Job-Executor-25:job-1134) Details from executing class com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: Catch Exception com.cloud.utils.exception.CloudRuntimeException on host:a956ec58-a7bd-43e5-8a68-18182a3d3ade for template: nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6
2013-07-31 17:00:29,044 DEBUG [cloud.template.TemplateManagerImpl] (Job-Executor-25:job-1134) Template 279 download to pool 202 failed due to Catch Exception com.cloud.utils.exception.CloudRuntimeException on host:a956ec58-a7bd-43e5-8a68-18182a3d3ade for template: nfs://mgt-cld.na.manwin.local/home/secondary/template/tmpl/4/279/628792ca-90cc-4222-934e-d680581dacf9.vhd due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 3bcca549-8365-35ce-8a87-17ac8768adc6
2013-07-31 17:00:29,044 DEBUG [agent.manager.AgentAttache] (DirectAgent-305:null) Seq 3-451674647: No more commands found
2013-07-31 17:00:29,044 DEBUG [cloud.template.TemplateManagerImpl] (Job-Executor-25:job-1134) Template 279 is not found on and can not be downloaded to pool 202
2013-07-31 17:00:29,044 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-25:job-1134) Cannot use this pool Pool[202|IscsiLUN] because we can't propagate template Tmpl[279-VHD-628792ca-90cc-4222-934e-d680581dacf9
2013-07-31 17:00:29,047 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-25:job-1134) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:202] is unreachable: Unable to create Vol[255|vm=205|ROOT]
at com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3488)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:748)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3865)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3458)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3444)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:379)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
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:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-07-31 17:00:29,049 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-25:job-1134) Cleaning up resources for the vm VM[User|test0731-win08] in Starting state
2013-07-31 17:00:29,050 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 3-451674648: Sending { Cmd , MgmtId: 110492071566, via: 3, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-4-205-VM","wait":0}}] }
2013-07-31 17:00:29,050 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 3-451674648: Executing: { Cmd , MgmtId: 110492071566, via: 3, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-4-205-VM","wait":0}}] }
2013-07-31 17:00:29,050 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-140:null) Seq 3-451674648: Executing request
2013-07-31 17:00:29,246 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-159:null) Seq 2-1305018373: Response Received:
2013-07-31 17:00:29,246 DEBUG [agent.transport.Request] (DirectAgent-159:null) Seq 2-1305018373: Processing: { Ans: , MgmtId: 110492071566, via: 2, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2013-07-31 17:00:29,307 INFO [xen.resource.CitrixResourceBase] (DirectAgent-140:null) VM does not exist on XenServera956ec58-a7bd-43e5-8a68-18182a3d3ade
2013-07-31 17:00:29,307 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-140:null) Seq 3-451674648: Response Received:
2013-07-31 17:00:29,308 DEBUG [agent.transport.Request] (DirectAgent-140:null) Seq 3-451674648: Processing: { Ans: , MgmtId: 110492071566, via: 3, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"details":"VM does not exist","wait":0}}] }
2013-07-31 17:00:29,308 DEBUG [agent.manager.AgentAttache] (DirectAgent-140:null) Seq 3-451674648: No more commands found
2013-07-31 17:00:29,308 DEBUG [agent.transport.Request] (Job-Executor-25:job-1134) Seq 3-451674648: Received: { Ans: , MgmtId: 110492071566, via: 3, Ver: v1, Flags: 110, { StopAnswer } }
2013-07-31 17:00:29,313 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Changing active number of nics for network id=204 on -1
2013-07-31 17:00:29,314 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking NiciraNvp to release Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:29,314 DEBUG [network.element.NiciraNvpElement] (Job-Executor-25:job-1134) Checking if NiciraNvpElement can handle service Connectivity on network guestNetworkForBasicZone
2013-07-31 17:00:29,315 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking JuniperSRX to release Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:29,315 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking Netscaler to release Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:29,315 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking F5BigIP to release Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:29,315 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking CiscoNexus1000vVSM to release Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:29,315 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking BigSwitchVnsElement to release Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:29,315 DEBUG [network.element.BigSwitchVnsElement] (Job-Executor-25:job-1134) Checking if BigSwitchVnsElement can handle service Connectivity on network guestNetworkForBasicZone
2013-07-31 17:00:29,315 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking VirtualRouter to release Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:29,315 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking Ovs to release Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:29,315 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking SecurityGroupProvider to release Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:29,315 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-25:job-1134) Asking VpcVirtualRouter to release Nic[273-205-087944d0-6a3b-4b93-88e6-08641bc66ae4-10.3.34.44]
2013-07-31 17:00:29,315 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-25:job-1134) Successfully released network resources for the vm VM[User|test0731-win08]
2013-07-31 17:00:29,315 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-25:job-1134) Successfully cleanued up resources for the vm VM[User|test0731-win08] in Starting state
2013-07-31 17:00:29,316 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) DeploymentPlanner allocation algorithm: random
2013-07-31 17:00:29,316 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 4000, requested ram: 2147483648
2013-07-31 17:00:29,316 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Is ROOT volume READY (pool already allocated)?: No
2013-07-31 17:00:29,316 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 3
2013-07-31 17:00:29,317 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2013-07-31 17:00:29,318 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Checking suitable pools for volume (Id, Type): (255,ROOT)
2013-07-31 17:00:29,318 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) We need to allocate new storagepool for this volume
2013-07-31 17:00:29,319 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Calling StoragePoolAllocators to find suitable pools
2013-07-31 17:00:29,319 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-25:job-1134) Looking for pools in dc: 1 pod:1 cluster:1
2013-07-31 17:00:29,320 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-25:job-1134) FirstFitStoragePoolAllocator has 5 pools to check for allocation
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen2-cld.na.manwin.local Local Storage ,poolId: 207
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen4-cld.na.manwin.local Local Storage ,poolId: 206
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: CloudStackPrimary ,poolId: 202
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is in avoid set, skipping this pool
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen3-cld.na.manwin.local Local Storage ,poolId: 208
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Checking if storage pool is suitable, name: xen1-cld.na.manwin.local Local Storage ,poolId: 204
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is localStorageAllocationNeeded? false
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) Is storage pool shared? false
2013-07-31 17:00:29,320 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-25:job-1134) StoragePool is not of correct type, skipping this pool
2013-07-31 17:00:29,320 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-25:job-1134) FirstFitStoragePoolAllocator returning 0 suitable storage pools
2013-07-31 17:00:29,320 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) No suitable pools found for volume: Vol[255|vm=205|ROOT] under cluster: 1
2013-07-31 17:00:29,320 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) No suitable pools found
2013-07-31 17:00:29,320 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-25:job-1134) Cannnot deploy to specified host, returning.
2013-07-31 17:00:29,323 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 3
2013-07-31 17:00:29,326 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) Hosts's actual total CPU: 64000 and CPU after applying overprovisioning: 64000
2013-07-31 17:00:29,326 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) release cpu from host: 3, old used: 58000,reserved: 0, actual total: 64000, total with overprovisioning: 64000; new used: 54000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-07-31 17:00:29,326 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) release mem from host: 3, old used: 64445480960,reserved: 0, total: 269593309440; new used: 62297997312,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-07-31 17:00:29,329 DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-25:job-1134) Destroying vm VM[User|test0731-win08] as it failed to create on Host with Id:null
2013-07-31 17:00:29,332 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-25:job-1134) 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
2013-07-31 17:00:29,349 INFO [user.vm.DeployVMCmd] (Job-Executor-25:job-1134) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|test0731-win08]Scope=interface com.cloud.dc.DataCenter; id=1
2013-07-31 17:00:29,349 INFO [user.vm.DeployVMCmd] (Job-Executor-25:job-1134) Unable to create a deployment for VM[User|test0731-win08]
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|test0731-win08]Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:728)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3865)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3458)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3444)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:379)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
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:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-07-31 17:00:29,349 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-25:job-1134) Complete async job-1134, jobStatus: 2, resultCode: 530, result: Error Code: 533 Error text: Unable to create a deployment for VM[User|test0731-win08]
2013-07-31 17:00:30,064 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===START=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304855789
2013-07-31 17:00:30,070 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-17:null) Async job-1134 completed
2013-07-31 17:00:30,073 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===END=== 10.3.12.164 -- GET command=queryAsyncJobResult&jobId=d397077c-eaa9-420d-a59e-e369fb3ff8da&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304855789
2013-07-31 17:00:30,084 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null) ===START=== 10.3.12.164 -- GET command=listVirtualMachines&id=af33180d-b351-45a0-acf7-ab0348572da7&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304855807
2013-07-31 17:00:30,097 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null) ===END=== 10.3.12.164 -- GET command=listVirtualMachines&id=af33180d-b351-45a0-acf7-ab0348572da7&response=json&sessionkey=HDreO5WAFQBLrWY7gqkU1YP71uc%3D&projectid=20bc456a-fe80-4cbb-8d67-ea0f70ece80a&_=1375304855807
Best regards,
William
This e-mail may be privileged and/or confidential, and the sender does not waive any related rights and obligations. Any distribution, use or copying of this e-mail or the information it contains by other than an intended recipient is unauthorized. If you received this e-mail in error, please advise me (by return e-mail or otherwise) immediately. Ce courrier ?lectronique est confidentiel et prot?g?. L'exp?diteur ne renonce pas aux droits et obligations qui s'y rapportent. Toute diffusion, utilisation ou copie de ce message ou des renseignements qu'il contient par une personne autre que le (les) destinataire(s) d?sign?(s) est interdite. Si vous recevez ce courrier ?lectronique par erreur, veuillez m'en aviser imm?diatement, par retour de courrier ?lectronique ou par un autre moyen.