You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@cloudstack.apache.org by María Noelia Gil <ma...@um.es> on 2014/03/17 10:57:54 UTC
Register ISO
I am trying to register an ISO and a message saying "Task Complete: Register ISO" appears. However, when I want to add a new instance, the ISO does not appear. Any suggestions?
Then I show the contents of the log file:
2014-03-17 10:51:09,892 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2014-03-17 10:51:10,300 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2014-03-17 10:51:10,304 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) There is no secondary storage VM for secondary storage host nfs://192.168.0.70/mnt/secondary
2014-03-17 10:51:10,362 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-7471208: Received: { Ans: , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-03-17 10:51:16,057 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2014-03-17 10:51:16,667 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-7471209: Received: { Ans: , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-03-17 10:51:24,067 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 2 is ready to launch secondary storage VM
2014-03-17 10:51:24,070 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) No running secondary storage vms found in datacenter id=2, starting one
2014-03-17 10:51:24,077 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Found a stopped secondary storage vm, bring it up to running pool. secStorageVm vm id : 2696
2014-03-17 10:51:24,084 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) 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-17 10:51:24,084 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully transitioned to start state for VM[SecondaryStorageVm|s-2696-VM] reservation id = e34c2eb7-1f79-4e01-9554-b686b6a548a6
2014-03-17 10:51:24,133 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Trying to deploy VM, vm has dcId: 2 and podId: 2
2014-03-17 10:51:24,133 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Deploy avoids pods: null, clusters: null, hosts: null
2014-03-17 10:51:24,135 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) DeploymentPlanner allocation algorithm: random
2014-03-17 10:51:24,136 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Trying to allocate a host and storage pools from dc:2, pod:2,cluster:null, requested cpu: 500, requested ram: 268435456
2014-03-17 10:51:24,136 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Is ROOT volume READY (pool already allocated)?: No
2014-03-17 10:51:24,136 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Searching resources only under specified Pod: 2
2014-03-17 10:51:24,137 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 2
2014-03-17 10:51:24,137 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) CPUOverprovisioningFactor considered: 1.0
2014-03-17 10:51:24,144 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Checking resources in Cluster: 2 under Pod: 2
2014-03-17 10:51:24,144 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Looking for hosts in dc: 2 pod:2 cluster:2
2014-03-17 10:51:24,145 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2014-03-17 10:51:24,147 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2014-03-17 10:51:24,148 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=256
2014-03-17 10:51:24,149 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 268435456 , cpuOverprovisioningFactor: 1.0
2014-03-17 10:51:24,151 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 12404 and CPU after applying overprovisioning: 12404
2014-03-17 10:51:24,151 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Free CPU: 12404 , Requested CPU: 500
2014-03-17 10:51:24,151 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Free RAM: 4051263488 , Requested RAM: 268435456
2014-03-17 10:51:24,151 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-03-17 10:51:24,151 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 0, reserved: 0, actual total: 12404, total with overprovisioning: 12404; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-17 10:51:24,152 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 0, reserved: 0, total: 4051263488; requested mem: 268435456,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-17 10:51:24,152 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2014-03-17 10:51:24,152 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2014-03-17 10:51:24,153 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Checking suitable pools for volume (Id, Type): (2697,ROOT)
2014-03-17 10:51:24,153 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) We need to allocate new storagepool for this volume
2014-03-17 10:51:24,153 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Calling StoragePoolAllocators to find suitable pools
2014-03-17 10:51:24,154 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (secstorage-1:null) Looking for pools in dc: 2 pod:2 cluster:2
2014-03-17 10:51:24,155 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (secstorage-1:null) FirstFitStoragePoolAllocator has 1 pools to check for allocation
2014-03-17 10:51:24,155 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (secstorage-1:null) Checking if storage pool is suitable, name: primary1 ,poolId: 200
2014-03-17 10:51:24,155 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (secstorage-1:null) Is localStorageAllocationNeeded? false
2014-03-17 10:51:24,155 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (secstorage-1:null) Is storage pool shared? true
2014-03-17 10:51:24,157 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Checking pool 200 for storage, totalSize: 31572623360, usedBytes: 6412566528, usedPct: 0.2031052806376619, disable threshold: 0.85
2014-03-17 10:51:24,161 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Checking pool: 200 for volume allocation [Vol[2697|vm=2696|ROOT]], maxSize : 63145246720, totalAllocatedSize : 0, askingSize : 0, allocated disable threshold: 0.85
2014-03-17 10:51:24,161 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (secstorage-1:null) FirstFitStoragePoolAllocator returning 1 suitable storage pools
2014-03-17 10:51:24,161 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2014-03-17 10:51:24,161 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2014-03-17 10:51:24,162 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Host: 1 can access pool: 200
2014-03-17 10:51:24,162 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Found a potential host id: 1 name: macro.lab.stalworthy.net and associated storage pools for this VM
2014-03-17 10:51:24,163 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(2)-Pod(2)-Cluster(2)-Host(1)-Storage(Volume(2697|ROOT-->Pool(200))]
2014-03-17 10:51:24,163 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Deployment found - P0=VM[SecondaryStorageVm|s-2696-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(2)-Pod(2)-Cluster(2)-Host(1)-Storage(Volume(2697|ROOT-->Pool(200))]
2014-03-17 10:51:24,241 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2014-03-17 10:51:24,248 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Hosts's actual total CPU: 12404 and CPU after applying overprovisioning: 12404
2014-03-17 10:51:24,248 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) We are allocating VM, increasing the used capacity of this host:1
2014-03-17 10:51:24,248 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Current Used CPU: 0 , Free CPU:12404 ,Requested CPU: 500
2014-03-17 10:51:24,248 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Current Used RAM: 0 , Free RAM:4051263488 ,Requested RAM: 268435456
2014-03-17 10:51:24,248 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) CPU STATS after allocation: for host: 1, old used: 0, old reserved: 0, actual total: 12404, total with overprovisioning: 12404; new used:500, reserved:0; requested cpu:500,alloc_from_last:false
2014-03-17 10:51:24,248 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) RAM STATS after allocation: for host: 1, old used: 0, old reserved: 0, total: 4051263488; new used: 268435456, reserved: 0; requested mem: 268435456,alloc_from_last:false
2014-03-17 10:51:24,300 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) VM is being created in podId: 2
2014-03-17 10:51:24,304 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Lock is acquired for network id 209 as a part of network implement
2014-03-17 10:51:24,304 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Network id=209 is already implemented
2014-03-17 10:51:24,304 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Lock is released for network id 209 as a part of network implement
2014-03-17 10:51:24,306 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 2 is ready to launch console proxy
2014-03-17 10:51:24,306 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Expand console proxy standby capacity for zone zone2
2014-03-17 10:51:24,308 INFO [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Found a stopped console proxy, bring it up to running pool. proxy vm id : 22
2014-03-17 10:51:24,312 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) 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-17 10:51:24,312 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully transitioned to start state for VM[ConsoleProxy|v-22-VM] reservation id = 12cbcc5e-e540-436e-8588-b76f92e08835
2014-03-17 10:51:24,394 DEBUG [cloud.network.NetworkModelImpl] (secstorage-1:null) Service SecurityGroup is not supported in the network id=209
2014-03-17 10:51:24,418 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Trying to deploy VM, vm has dcId: 2 and podId: 2
2014-03-17 10:51:24,418 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: null
2014-03-17 10:51:24,421 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) DeploymentPlanner allocation algorithm: random
2014-03-17 10:51:24,421 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Trying to allocate a host and storage pools from dc:2, pod:2,cluster:null, requested cpu: 500, requested ram: 1073741824
2014-03-17 10:51:24,421 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: No
2014-03-17 10:51:24,421 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Pod: 2
2014-03-17 10:51:24,422 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 2
2014-03-17 10:51:24,423 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) CPUOverprovisioningFactor considered: 1.0
2014-03-17 10:51:24,430 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking resources in Cluster: 2 under Pod: 2
2014-03-17 10:51:24,430 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: 2 pod:2 cluster:2
2014-03-17 10:51:24,431 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2014-03-17 10:51:24,433 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2014-03-17 10:51:24,433 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2014-03-17 10:51:24,434 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2014-03-17 10:51:24,436 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 12404 and CPU after applying overprovisioning: 12404
2014-03-17 10:51:24,436 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 11904 , Requested CPU: 500
2014-03-17 10:51:24,436 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 3782828032 , Requested RAM: 1073741824
2014-03-17 10:51:24,436 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-03-17 10:51:24,436 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 500, reserved: 0, actual total: 12404, total with overprovisioning: 12404; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-17 10:51:24,436 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 268435456, reserved: 0, total: 4051263488; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-17 10:51:24,436 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2014-03-17 10:51:24,436 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2014-03-17 10:51:24,438 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking suitable pools for volume (Id, Type): (23,ROOT)
2014-03-17 10:51:24,438 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) We need to allocate new storagepool for this volume
2014-03-17 10:51:24,438 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Calling StoragePoolAllocators to find suitable pools
2014-03-17 10:51:24,438 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (consoleproxy-1:null) Looking for pools in dc: 2 pod:2 cluster:2
2014-03-17 10:51:24,439 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (consoleproxy-1:null) FirstFitStoragePoolAllocator has 1 pools to check for allocation
2014-03-17 10:51:24,439 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (consoleproxy-1:null) Checking if storage pool is suitable, name: primary1 ,poolId: 200
2014-03-17 10:51:24,439 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (consoleproxy-1:null) Is localStorageAllocationNeeded? false
2014-03-17 10:51:24,439 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (consoleproxy-1:null) Is storage pool shared? true
2014-03-17 10:51:24,441 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Checking pool 200 for storage, totalSize: 31572623360, usedBytes: 6412566528, usedPct: 0.2031052806376619, disable threshold: 0.85
2014-03-17 10:51:24,444 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Checking pool: 200 for volume allocation [Vol[23|vm=22|ROOT]], maxSize : 63145246720, totalAllocatedSize : 0, askingSize : 0, allocated disable threshold: 0.85
2014-03-17 10:51:24,444 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (consoleproxy-1:null) FirstFitStoragePoolAllocator returning 1 suitable storage pools
2014-03-17 10:51:24,444 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2014-03-17 10:51:24,444 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2014-03-17 10:51:24,445 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Host: 1 can access pool: 200
2014-03-17 10:51:24,445 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Found a potential host id: 1 name: macro.lab.stalworthy.net and associated storage pools for this VM
2014-03-17 10:51:24,446 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(2)-Pod(2)-Cluster(2)-Host(1)-Storage(Volume(23|ROOT-->Pool(200))]
2014-03-17 10:51:24,446 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deployment found - P0=VM[ConsoleProxy|v-22-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(2)-Pod(2)-Cluster(2)-Host(1)-Storage(Volume(23|ROOT-->Pool(200))]
2014-03-17 10:51:24,468 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VirtualRouter to prepare for Nic[10776-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.172]
2014-03-17 10:51:24,468 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to prepare for Nic[10776-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.172]
2014-03-17 10:51:24,468 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking SecurityGroupProvider to prepare for Nic[10776-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.172]
2014-03-17 10:51:24,468 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VpcVirtualRouter to prepare for Nic[10776-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.172]
2014-03-17 10:51:24,468 WARN [network.element.VpcVirtualRouterElement] (secstorage-1:null) Network Ntwk[209|Guest|7] is not associated with any VPC
2014-03-17 10:51:24,469 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking NiciraNvp to prepare for Nic[10776-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.172]
2014-03-17 10:51:24,469 DEBUG [network.element.NiciraNvpElement] (secstorage-1:null) Checking if NiciraNvpElement can handle service Connectivity on network defaultGuestNetwork
2014-03-17 10:51:24,470 DEBUG [cloud.network.NetworkModelImpl] (secstorage-1:null) Service SecurityGroup is not supported in the network id=209
2014-03-17 10:51:24,471 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Lock is acquired for network id 207 as a part of network implement
2014-03-17 10:51:24,471 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Network id=207 is already implemented
2014-03-17 10:51:24,472 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Lock is released for network id 207 as a part of network implement
2014-03-17 10:51:24,569 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2014-03-17 10:51:24,577 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 12404 and CPU after applying overprovisioning: 12404
2014-03-17 10:51:24,577 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) We are allocating VM, increasing the used capacity of this host:1
2014-03-17 10:51:24,577 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used CPU: 500 , Free CPU:11904 ,Requested CPU: 500
2014-03-17 10:51:24,577 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used RAM: 268435456 , Free RAM:3782828032 ,Requested RAM: 1073741824
2014-03-17 10:51:24,577 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) CPU STATS after allocation: for host: 1, old used: 500, old reserved: 0, actual total: 12404, total with overprovisioning: 12404; new used:1000, reserved:0; requested cpu:500,alloc_from_last:false
2014-03-17 10:51:24,577 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) RAM STATS after allocation: for host: 1, old used: 268435456, old reserved: 0, total: 4051263488; new used: 1342177280, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2014-03-17 10:51:24,670 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) VM is being created in podId: 2
2014-03-17 10:51:24,674 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 209 as a part of network implement
2014-03-17 10:51:24,674 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=209 is already implemented
2014-03-17 10:51:24,674 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 209 as a part of network implement
2014-03-17 10:51:24,720 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VirtualRouter to prepare for Nic[10777-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-169.254.1.223]
2014-03-17 10:51:24,720 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to prepare for Nic[10777-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-169.254.1.223]
2014-03-17 10:51:24,720 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking SecurityGroupProvider to prepare for Nic[10777-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-169.254.1.223]
2014-03-17 10:51:24,720 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VpcVirtualRouter to prepare for Nic[10777-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-169.254.1.223]
2014-03-17 10:51:24,720 WARN [network.element.VpcVirtualRouterElement] (secstorage-1:null) Network Ntwk[207|Control|3] is not associated with any VPC
2014-03-17 10:51:24,720 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking NiciraNvp to prepare for Nic[10777-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-169.254.1.223]
2014-03-17 10:51:24,720 DEBUG [network.element.NiciraNvpElement] (secstorage-1:null) Checking if NiciraNvpElement can handle service Connectivity on network null
2014-03-17 10:51:24,722 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Lock is acquired for network id 206 as a part of network implement
2014-03-17 10:51:24,722 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Network id=206 is already implemented
2014-03-17 10:51:24,722 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Lock is released for network id 206 as a part of network implement
2014-03-17 10:51:24,746 DEBUG [cloud.network.NetworkModelImpl] (consoleproxy-1:null) Service SecurityGroup is not supported in the network id=209
2014-03-17 10:51:24,822 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[81-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.173]
2014-03-17 10:51:24,822 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[81-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.173]
2014-03-17 10:51:24,822 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[81-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.173]
2014-03-17 10:51:24,823 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[81-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.173]
2014-03-17 10:51:24,823 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[209|Guest|7] is not associated with any VPC
2014-03-17 10:51:24,823 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[81-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.173]
2014-03-17 10:51:24,823 DEBUG [network.element.NiciraNvpElement] (consoleproxy-1:null) Checking if NiciraNvpElement can handle service Connectivity on network defaultGuestNetwork
2014-03-17 10:51:24,824 DEBUG [cloud.network.NetworkModelImpl] (consoleproxy-1:null) Service SecurityGroup is not supported in the network id=209
2014-03-17 10:51:24,826 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 207 as a part of network implement
2014-03-17 10:51:24,826 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=207 is already implemented
2014-03-17 10:51:24,826 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 207 as a part of network implement
2014-03-17 10:51:24,841 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
2014-03-17 10:51:24,842 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2014-03-17 10:51:24,845 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
2014-03-17 10:51:24,846 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2014-03-17 10:51:24,872 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Running Capacity Checker ...
2014-03-17 10:51:24,872 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) recalculating system capacity
2014-03-17 10:51:24,872 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing cpu/ram capacity update
2014-03-17 10:51:24,873 DEBUG [network.guru.PodBasedNetworkGuru] (secstorage-1:null) Allocated a nic NicProfile[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.168-null for VM[SecondaryStorageVm|s-2696-VM]
2014-03-17 10:51:24,880 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 2 VMs on host 1
2014-03-17 10:51:24,881 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 0 VM, not running on host 1
2014-03-17 10:51:24,884 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate cpu capacity, host:1 usedCpu: 1000 reservedCpu: 0
2014-03-17 10:51:24,884 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate memory capacity, host:1 usedMem: 1342177280 reservedMem: 0
2014-03-17 10:51:24,884 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing cpu/ram capacity update
2014-03-17 10:51:24,884 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing storage capacity update
2014-03-17 10:51:24,888 DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:null) Successfully set Capacity - 63145246720 for capacity type - 3 , DataCenterId - 2, HostOrPoolId - 200, PodId 2
2014-03-17 10:51:24,888 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing storage capacity update
2014-03-17 10:51:24,888 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for public ip and Vlans
2014-03-17 10:51:24,898 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done capacity updates for public ip and Vlans
2014-03-17 10:51:24,898 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for private ip
2014-03-17 10:51:24,948 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VirtualRouter to prepare for Nic[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.168]
2014-03-17 10:51:24,948 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to prepare for Nic[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.168]
2014-03-17 10:51:24,949 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking SecurityGroupProvider to prepare for Nic[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.168]
2014-03-17 10:51:24,949 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VpcVirtualRouter to prepare for Nic[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.168]
2014-03-17 10:51:24,949 WARN [network.element.VpcVirtualRouterElement] (secstorage-1:null) Network Ntwk[206|Management|2] is not associated with any VPC
2014-03-17 10:51:24,949 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking NiciraNvp to prepare for Nic[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.168]
2014-03-17 10:51:24,949 DEBUG [network.element.NiciraNvpElement] (secstorage-1:null) Checking if NiciraNvpElement can handle service Connectivity on network null
2014-03-17 10:51:24,951 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Lock is acquired for network id 208 as a part of network implement
2014-03-17 10:51:24,951 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Network id=208 is already implemented
2014-03-17 10:51:24,952 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Lock is released for network id 208 as a part of network implement
2014-03-17 10:51:24,999 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing capacity updates for private ip
2014-03-17 10:51:24,999 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done recalculating system capacity
2014-03-17 10:51:25,021 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done running Capacity Checker ...
2014-03-17 10:51:25,049 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[82-22-12cbcc5e-e540-436e-8588-b76f92e08835-169.254.1.237]
2014-03-17 10:51:25,049 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[82-22-12cbcc5e-e540-436e-8588-b76f92e08835-169.254.1.237]
2014-03-17 10:51:25,049 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[82-22-12cbcc5e-e540-436e-8588-b76f92e08835-169.254.1.237]
2014-03-17 10:51:25,049 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[82-22-12cbcc5e-e540-436e-8588-b76f92e08835-169.254.1.237]
2014-03-17 10:51:25,049 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[207|Control|3] is not associated with any VPC
2014-03-17 10:51:25,049 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[82-22-12cbcc5e-e540-436e-8588-b76f92e08835-169.254.1.237]
2014-03-17 10:51:25,049 DEBUG [network.element.NiciraNvpElement] (consoleproxy-1:null) Checking if NiciraNvpElement can handle service Connectivity on network null
2014-03-17 10:51:25,051 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is acquired for network id 206 as a part of network implement
2014-03-17 10:51:25,051 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=206 is already implemented
2014-03-17 10:51:25,052 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Lock is released for network id 206 as a part of network implement
2014-03-17 10:51:25,100 DEBUG [network.guru.PodBasedNetworkGuru] (secstorage-1:null) Allocated a nic NicProfile[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.166-null for VM[SecondaryStorageVm|s-2696-VM]
2014-03-17 10:51:25,200 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VirtualRouter to prepare for Nic[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.166]
2014-03-17 10:51:25,200 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to prepare for Nic[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.166]
2014-03-17 10:51:25,200 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking SecurityGroupProvider to prepare for Nic[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.166]
2014-03-17 10:51:25,201 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VpcVirtualRouter to prepare for Nic[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.166]
2014-03-17 10:51:25,201 WARN [network.element.VpcVirtualRouterElement] (secstorage-1:null) Network Ntwk[208|Storage|4] is not associated with any VPC
2014-03-17 10:51:25,201 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Allocated a nic NicProfile[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.165-null for VM[ConsoleProxy|v-22-VM]
2014-03-17 10:51:25,201 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking NiciraNvp to prepare for Nic[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.166]
2014-03-17 10:51:25,201 DEBUG [network.element.NiciraNvpElement] (secstorage-1:null) Checking if NiciraNvpElement can handle service Connectivity on network null
2014-03-17 10:51:25,202 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Checking if we need to prepare 1 volumes for VM[SecondaryStorageVm|s-2696-VM]
2014-03-17 10:51:25,251 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to prepare for Nic[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.165]
2014-03-17 10:51:25,251 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to prepare for Nic[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.165]
2014-03-17 10:51:25,251 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to prepare for Nic[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.165]
2014-03-17 10:51:25,251 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to prepare for Nic[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.165]
2014-03-17 10:51:25,251 WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:null) Network Ntwk[206|Management|2] is not associated with any VPC
2014-03-17 10:51:25,251 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to prepare for Nic[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.165]
2014-03-17 10:51:25,251 DEBUG [network.element.NiciraNvpElement] (consoleproxy-1:null) Checking if NiciraNvpElement can handle service Connectivity on network null
2014-03-17 10:51:25,253 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Checking if we need to prepare 1 volumes for VM[ConsoleProxy|v-22-VM]
2014-03-17 10:51:25,276 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Creating volume: Vol[2697|vm=2696|ROOT]
2014-03-17 10:51:25,276 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Trying to create in Pool[200|NetworkFilesystem]
2014-03-17 10:51:25,326 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Creating volume: Vol[23|vm=22|ROOT]
2014-03-17 10:51:25,327 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Trying to create in Pool[200|NetworkFilesystem]
2014-03-17 10:51:25,410 DEBUG [cloud.template.TemplateManagerImpl] (secstorage-1:null) Downloading 3 via 1
2014-03-17 10:51:25,414 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-7471210: Sending { Cmd , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 100111, [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/2b75349f-2762-3df9-b7f6-83c92cd97da6","poolUuid":"2b75349f-2762-3df9-b7f6-83c92cd97da6","poolId":200,"primaryPool":{"id":200,"uuid":"2b75349f-2762-3df9-b7f6-83c92cd97da6","host":"192.168.0.70","path":"/export/primary","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://192.168.0.70/mnt/secondary","primaryStorageUrl":"nfs://192.168.0.70/export/primary","url":"nfs://192.168.0.70/mnt/secondary/template/tmpl/1/3/","format":"QCOW2","accountId":1,"name":"routing-3","wait":10800}}] }
2014-03-17 10:51:25,458 DEBUG [agent.transport.Request] (AgentManager-Handler-15:null) Seq 1-7471210: Processing: { Ans: , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:540)\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVMStoragePoolManager.java:111)\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePoolByURI(KVMStoragePoolManager.java:97)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2253)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1076)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:525)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:701)\n","wait":0}}] }
2014-03-17 10:51:25,458 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-15:null) Seq 1-7471210: No more commands found
2014-03-17 10:51:25,458 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-7471210: Received: { Ans: , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 110, { Answer } }
2014-03-17 10:51:25,458 DEBUG [agent.manager.AgentManagerImpl] (secstorage-1:null) Details from executing class com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: java.lang.NullPointerException
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:540)
at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVMStoragePoolManager.java:111)
at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePoolByURI(KVMStoragePoolManager.java:97)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2253)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1076)
at com.cloud.agent.Agent.processRequest(Agent.java:525)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)
at com.cloud.utils.nio.Task.run(Task.java:83)
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:701)
2014-03-17 10:51:25,459 ERROR [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Failed to start instance VM[SecondaryStorageVm|s-2696-VM]
java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer
at com.cloud.template.TemplateManagerImpl.prepareTemplateForCreate(TemplateManagerImpl.java:647)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at com.cloud.storage.StorageManagerImpl.createVolume(StorageManagerImpl.java:3587)
at com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3478)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:748)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:464)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:269)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:696)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1307)
at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:121)
at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:52)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
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:701)
2014-03-17 10:51:25,511 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up resources for the vm VM[SecondaryStorageVm|s-2696-VM] in Starting state
2014-03-17 10:51:25,513 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-7471211: Sending { Cmd , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"s-2696-VM","wait":0}}] }
2014-03-17 10:51:25,587 DEBUG [agent.transport.Request] (AgentManager-Handler-1:null) Seq 1-7471211: Processing: { Ans: , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2014-03-17 10:51:25,587 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-1:null) Seq 1-7471211: No more commands found
2014-03-17 10:51:25,587 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-7471211: Received: { Ans: , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2014-03-17 10:51:25,591 DEBUG [cloud.network.NetworkModelImpl] (secstorage-1:null) Service SecurityGroup is not supported in the network id=209
2014-03-17 10:51:25,645 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VirtualRouter to release Nic[10776-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.172]
2014-03-17 10:51:25,645 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to release Nic[10776-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.172]
2014-03-17 10:51:25,645 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking SecurityGroupProvider to release Nic[10776-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.172]
2014-03-17 10:51:25,645 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VpcVirtualRouter to release Nic[10776-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.172]
2014-03-17 10:51:25,645 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking NiciraNvp to release Nic[10776-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-192.168.0.172]
2014-03-17 10:51:25,645 DEBUG [network.element.NiciraNvpElement] (secstorage-1:null) Checking if NiciraNvpElement can handle service Connectivity on network defaultGuestNetwork
2014-03-17 10:51:25,647 DEBUG [network.guru.ControlNetworkGuru] (secstorage-1:null) Released nic: NicProfile[10777-2696-null-null-null
2014-03-17 10:51:25,695 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VirtualRouter to release Nic[10777-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,695 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to release Nic[10777-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,695 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking SecurityGroupProvider to release Nic[10777-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,695 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VpcVirtualRouter to release Nic[10777-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,695 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking NiciraNvp to release Nic[10777-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,695 DEBUG [network.element.NiciraNvpElement] (secstorage-1:null) Checking if NiciraNvpElement can handle service Connectivity on network null
2014-03-17 10:51:25,698 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (secstorage-1:null) Releasing ip address for reservationId=e34c2eb7-1f79-4e01-9554-b686b6a548a6, instance=10778
2014-03-17 10:51:25,698 DEBUG [network.guru.PodBasedNetworkGuru] (secstorage-1:null) Released nic: NicProfile[10778-2696-null-null-null
2014-03-17 10:51:25,745 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VirtualRouter to release Nic[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,745 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to release Nic[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,745 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking SecurityGroupProvider to release Nic[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,745 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VpcVirtualRouter to release Nic[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,745 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking NiciraNvp to release Nic[10778-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,745 DEBUG [network.element.NiciraNvpElement] (secstorage-1:null) Checking if NiciraNvpElement can handle service Connectivity on network null
2014-03-17 10:51:25,748 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (secstorage-1:null) Releasing ip address for reservationId=e34c2eb7-1f79-4e01-9554-b686b6a548a6, instance=10779
2014-03-17 10:51:25,749 DEBUG [network.guru.PodBasedNetworkGuru] (secstorage-1:null) Released nic: NicProfile[10779-2696-null-null-null
2014-03-17 10:51:25,796 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VirtualRouter to release Nic[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,796 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to release Nic[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,796 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking SecurityGroupProvider to release Nic[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,796 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VpcVirtualRouter to release Nic[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,796 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking NiciraNvp to release Nic[10779-2696-e34c2eb7-1f79-4e01-9554-b686b6a548a6-null]
2014-03-17 10:51:25,796 DEBUG [network.element.NiciraNvpElement] (secstorage-1:null) Checking if NiciraNvpElement can handle service Connectivity on network null
2014-03-17 10:51:25,796 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully released network resources for the vm VM[SecondaryStorageVm|s-2696-VM]
2014-03-17 10:51:25,796 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully cleanued up resources for the vm VM[SecondaryStorageVm|s-2696-VM] in Starting state
2014-03-17 10:51:25,898 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2014-03-17 10:51:25,901 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Hosts's actual total CPU: 12404 and CPU after applying overprovisioning: 12404
2014-03-17 10:51:25,902 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 12404, total with overprovisioning: 12404; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-03-17 10:51:25,902 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release mem from host: 1, old used: 1342177280,reserved: 0, total: 4051263488; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-03-17 10:51:25,956 WARN [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Exception while trying to start secondary storage vm
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:841)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:464)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:269)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:696)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1307)
at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:121)
at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:52)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
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:701)
Caused by: java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer
at com.cloud.template.TemplateManagerImpl.prepareTemplateForCreate(TemplateManagerImpl.java:647)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at com.cloud.storage.StorageManagerImpl.createVolume(StorageManagerImpl.java:3587)
at com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3478)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:748)
... 20 more
2014-03-17 10:51:25,957 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 2696, will recycle it and start a new one
2014-03-17 10:51:25,959 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) VM is already stopped: VM[SecondaryStorageVm|s-2696-VM]
2014-03-17 10:51:26,007 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Stopped to Expunging with event: ExpungeOperationvm's original host id: null new host id: null host id before state transition: null
2014-03-17 10:51:26,008 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Destroying vm VM[SecondaryStorageVm|s-2696-VM]
2014-03-17 10:51:26,008 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up NICS
2014-03-17 10:51:26,008 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Cleaning network for vm: 2696
2014-03-17 10:51:26,060 DEBUG [cloud.network.NetworkModelImpl] (secstorage-1:null) Service SecurityGroup is not supported in the network id=209
2014-03-17 10:51:26,061 DEBUG [network.guru.DirectNetworkGuru] (secstorage-1:null) Deallocate network: networkId: 209, ip: 192.168.0.172
2014-03-17 10:51:26,208 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=10776
2014-03-17 10:51:26,309 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=10777
2014-03-17 10:51:26,410 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=10778
2014-03-17 10:51:26,510 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=10779
2014-03-17 10:51:26,510 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Cleaning storage for vm: 2696
2014-03-17 10:51:26,569 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Expunging Vol[2697|vm=2696|ROOT]
2014-03-17 10:51:26,573 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Marking volume that was never created as destroyed: Vol[2697|vm=2696|ROOT]
2014-03-17 10:51:26,659 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Expunged VM[SecondaryStorageVm|s-2696-VM]
2014-03-17 10:51:26,711 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) Primary secondary storage is not even started, wait until next turn
2014-03-17 10:51:30,460 DEBUG [cloud.template.TemplateManagerImpl] (consoleproxy-1:null) Downloading 3 via 1
2014-03-17 10:51:30,464 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-7471212: Sending { Cmd , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 100111, [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/2b75349f-2762-3df9-b7f6-83c92cd97da6","poolUuid":"2b75349f-2762-3df9-b7f6-83c92cd97da6","poolId":200,"primaryPool":{"id":200,"uuid":"2b75349f-2762-3df9-b7f6-83c92cd97da6","host":"192.168.0.70","path":"/export/primary","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://192.168.0.70/mnt/secondary","primaryStorageUrl":"nfs://192.168.0.70/export/primary","url":"nfs://192.168.0.70/mnt/secondary/template/tmpl/1/3/","format":"QCOW2","accountId":1,"name":"routing-3","wait":10800}}] }
2014-03-17 10:51:30,518 DEBUG [agent.transport.Request] (AgentManager-Handler-2:null) Seq 1-7471212: Processing: { Ans: , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:540)\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVMStoragePoolManager.java:111)\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePoolByURI(KVMStoragePoolManager.java:97)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2253)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1076)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:525)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:701)\n","wait":0}}] }
2014-03-17 10:51:30,518 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-2:null) Seq 1-7471212: No more commands found
2014-03-17 10:51:30,518 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-7471212: Received: { Ans: , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 110, { Answer } }
2014-03-17 10:51:30,518 DEBUG [agent.manager.AgentManagerImpl] (consoleproxy-1:null) Details from executing class com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: java.lang.NullPointerException
at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:540)
at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVMStoragePoolManager.java:111)
at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePoolByURI(KVMStoragePoolManager.java:97)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2253)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1076)
at com.cloud.agent.Agent.processRequest(Agent.java:525)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)
at com.cloud.utils.nio.Task.run(Task.java:83)
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:701)
2014-03-17 10:51:30,519 ERROR [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Failed to start instance VM[ConsoleProxy|v-22-VM]
java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer
at com.cloud.template.TemplateManagerImpl.prepareTemplateForCreate(TemplateManagerImpl.java:647)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at com.cloud.storage.StorageManagerImpl.createVolume(StorageManagerImpl.java:3587)
at com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3478)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:748)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:464)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:632)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1166)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1985)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:175)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:111)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
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:701)
2014-03-17 10:51:30,574 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-22-VM] in Starting state
2014-03-17 10:51:30,575 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-7471213: Sending { Cmd , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"v-22-VM","wait":0}}] }
2014-03-17 10:51:30,658 DEBUG [agent.transport.Request] (AgentManager-Handler-3:null) Seq 1-7471213: Processing: { Ans: , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2014-03-17 10:51:30,658 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-3:null) Seq 1-7471213: No more commands found
2014-03-17 10:51:30,658 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-7471213: Received: { Ans: , MgmtId: 262241618080206, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2014-03-17 10:51:30,665 DEBUG [cloud.network.NetworkModelImpl] (consoleproxy-1:null) Service SecurityGroup is not supported in the network id=209
2014-03-17 10:51:30,724 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[81-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.173]
2014-03-17 10:51:30,724 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[81-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.173]
2014-03-17 10:51:30,724 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[81-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.173]
2014-03-17 10:51:30,724 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[81-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.173]
2014-03-17 10:51:30,724 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[81-22-12cbcc5e-e540-436e-8588-b76f92e08835-192.168.0.173]
2014-03-17 10:51:30,724 DEBUG [network.element.NiciraNvpElement] (consoleproxy-1:null) Checking if NiciraNvpElement can handle service Connectivity on network defaultGuestNetwork
2014-03-17 10:51:30,727 DEBUG [network.guru.ControlNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[82-22-null-null-null
2014-03-17 10:51:30,774 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[82-22-12cbcc5e-e540-436e-8588-b76f92e08835-null]
2014-03-17 10:51:30,774 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[82-22-12cbcc5e-e540-436e-8588-b76f92e08835-null]
2014-03-17 10:51:30,775 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[82-22-12cbcc5e-e540-436e-8588-b76f92e08835-null]
2014-03-17 10:51:30,775 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[82-22-12cbcc5e-e540-436e-8588-b76f92e08835-null]
2014-03-17 10:51:30,775 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[82-22-12cbcc5e-e540-436e-8588-b76f92e08835-null]
2014-03-17 10:51:30,775 DEBUG [network.element.NiciraNvpElement] (consoleproxy-1:null) Checking if NiciraNvpElement can handle service Connectivity on network null
2014-03-17 10:51:30,778 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (consoleproxy-1:null) Releasing ip address for reservationId=12cbcc5e-e540-436e-8588-b76f92e08835, instance=83
2014-03-17 10:51:30,778 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[83-22-null-null-null
2014-03-17 10:51:30,825 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-null]
2014-03-17 10:51:30,825 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-null]
2014-03-17 10:51:30,825 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-null]
2014-03-17 10:51:30,825 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-null]
2014-03-17 10:51:30,825 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[83-22-12cbcc5e-e540-436e-8588-b76f92e08835-null]
2014-03-17 10:51:30,825 DEBUG [network.element.NiciraNvpElement] (consoleproxy-1:null) Checking if NiciraNvpElement can handle service Connectivity on network null
2014-03-17 10:51:30,825 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully released network resources for the vm VM[ConsoleProxy|v-22-VM]
2014-03-17 10:51:30,825 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully cleanued up resources for the vm VM[ConsoleProxy|v-22-VM] in Starting state
2014-03-17 10:51:30,925 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2014-03-17 10:51:30,930 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 12404 and CPU after applying overprovisioning: 12404
2014-03-17 10:51:30,930 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release cpu from host: 1, old used: 500,reserved: 0, actual total: 12404, total with overprovisioning: 12404; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-03-17 10:51:30,930 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release mem from host: 1, old used: 1073741824,reserved: 0, total: 4051263488; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-03-17 10:51:30,984 WARN [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:841)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:464)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:632)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1166)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1985)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:175)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:111)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
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:701)
Caused by: java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer
at com.cloud.template.TemplateManagerImpl.prepareTemplateForCreate(TemplateManagerImpl.java:647)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at com.cloud.storage.StorageManagerImpl.createVolume(StorageManagerImpl.java:3587)
at com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3478)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:748)
... 19 more