cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Srikanteswararao Talluri (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CLOUDSTACK-1832) ZWPS: NPE while executing primaryStorageDownload
Date Thu, 28 Mar 2013 13:31:19 GMT
Srikanteswararao Talluri created CLOUDSTACK-1832:
----------------------------------------------------

             Summary: ZWPS: NPE while executing primaryStorageDownload
                 Key: CLOUDSTACK-1832
                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-1832
             Project: CloudStack
          Issue Type: Bug
      Security Level: Public (Anyone can view this level - this is the default.)
          Components: Management Server
    Affects Versions: 4.2.0
            Reporter: Srikanteswararao Talluri
            Priority: Blocker
             Fix For: 4.2.0


Steps to reproduce:
==============
1. create a zone with zone wide primary storage
2. Add a cluster wide primary storage with tag "cwps"
3. create a compute offering with storage tag "cwps" and deploy a VM using this compute offering.

Now, while deploying VM , primary storage download command fails with NPE


=START===  10.252.250.64 -- GET  command=deployVirtualMachine&zoneId=b94fdce2-740e-4830-ba18-78bd89290a4f&templateId=ae308efe-97c2-11e2-a463-06e1a6000030&hypervisor=KVM&serviceOfferingId=17e9a075-ac44-4869-973b-08b07e2739d8&securitygroupids=7b4c3af0-97c3-11e2-a463-06e1a6000030&displayname=c&name=c&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476961630
2013-03-29 00:18:46,327 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-10:null) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2013-03-29 00:18:46,330 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-10:null) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2013-03-29 00:18:46,336 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-10:null) ControlledEntity name is:com.cloud.network.security.SecurityGroup
2013-03-29 00:18:46,384 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-10:null) Allocating in the DB for vm
2013-03-29 00:18:46,407 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-10:null) Allocating entries for VM: VM[User|c]
2013-03-29 00:18:46,409 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-10:null) Allocating nics for VM[User|c]
2013-03-29 00:18:46,410 DEBUG [cloud.network.NetworkManagerImpl] (catalina-exec-10:null) Allocating nic for vm VM[User|c] in network Ntwk[204|Guest|6] with requested profile NicProfile[0-0-null-null-null
2013-03-29 00:18:46,427 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-10:null) Allocaing disks for VM[User|c]
2013-03-29 00:18:46,441 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-10:null) Allocation completed for VM: VM[User|c]
2013-03-29 00:18:46,441 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-10:null) Successfully allocated DB entry for VM[User|c]
2013-03-29 00:18:46,535 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-10:null) submit async job-46, details: AsyncJobVO {id:46, userId: 2, accountId: 2, sessionKey: null, instanceType: null, instanceId: 8, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator: null, cmdInfo: {"sessionkey":"fBgbfTKbB6aYlrhmnXUliOGoMHk\u003d","ctxUserId":"2","serviceOfferingId":"17e9a075-ac44-4869-973b-08b07e2739d8","securitygroupids":"7b4c3af0-97c3-11e2-a463-06e1a6000030","zoneId":"b94fdce2-740e-4830-ba18-78bd89290a4f","templateId":"ae308efe-97c2-11e2-a463-06e1a6000030","response":"json","id":"8","hypervisor":"KVM","name":"c","_":"1364476961630","ctxAccountId":"2","ctxStartEventId":"153","displayname":"c"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 7566222426160, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-03-29 00:18:46,539 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null) ===END===  10.252.250.64 -- GET  command=deployVirtualMachine&zoneId=b94fdce2-740e-4830-ba18-78bd89290a4f&templateId=ae308efe-97c2-11e2-a463-06e1a6000030&hypervisor=KVM&serviceOfferingId=17e9a075-ac44-4869-973b-08b07e2739d8&securitygroupids=7b4c3af0-97c3-11e2-a463-06e1a6000030&displayname=c&name=c&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476961630
2013-03-29 00:18:46,542 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-46:job-46) Executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-46
2013-03-29 00:18:46,554 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-46:job-46) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2013-03-29 00:18:46,557 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-46:job-46) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2013-03-29 00:18:46,562 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-46:job-46) ControlledEntity name is:com.cloud.network.security.SecurityGroup
2013-03-29 00:18:46,638 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) DeploymentPlanner allocation algorithm: random
2013-03-29 00:18:46,638 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 100, requested ram: 536870912
2013-03-29 00:18:46,638 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Is ROOT volume READY (pool already allocated)?: No
2013-03-29 00:18:46,638 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Searching all possible resources under this Zone: 1
2013-03-29 00:18:46,640 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2013-03-29 00:18:46,661 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Checking resources in Cluster: 1 under Pod: 1
2013-03-29 00:18:46,661 DEBUG [allocator.impl.RandomAllocator] (Job-Executor-46:job-46) Looking for hosts in dc: 1  pod:1  cluster:1
2013-03-29 00:18:46,665 DEBUG [allocator.impl.RandomAllocator] (Job-Executor-46:job-46) Random Allocator found 1  hosts
2013-03-29 00:18:46,665 DEBUG [allocator.impl.RandomAllocator] (Job-Executor-46:job-46) Random Host Allocator returning 1 suitable hosts
2013-03-29 00:18:46,667 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Checking suitable pools for volume (Id, Type): (14,ROOT)
2013-03-29 00:18:46,667 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) We need to allocate new storagepool for this volume
2013-03-29 00:18:46,668 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Calling StoragePoolAllocators to find suitable pools
2013-03-29 00:18:46,679 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-46:job-46) Checking pool 2 for storage, totalSize: 5902284816384, usedBytes: 2789847498752, usedPct: 0.47267246253649675, disable threshold: 0.85
2013-03-29 00:18:46,686 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-46:job-46) Checking pool: 2 for volume allocation [Vol[14|vm=8|ROOT]], maxSize : 11804569632768, totalAllocatedSize : 0, askingSize : 8589934592, allocated disable threshold: 0.85
2013-03-29 00:18:46,686 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-03-29 00:18:46,686 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2013-03-29 00:18:46,688 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Host: 1 can access pool: 2
2013-03-29 00:18:46,688 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Found a potential host id: 1 name: Rack1Pod1Host22 and associated storage pools for this VM
2013-03-29 00:18:46,690 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(14|ROOT-->Pool(2))]
2013-03-29 00:18:46,720 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
2013-03-29 00:18:46,721 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-46:job-46) Successfully transitioned to start state for VM[User|c] reservation id = 8e281981-3019-4b28-a649-db7aba952e06
2013-03-29 00:18:46,729 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-46:job-46) Trying to deploy VM, vm has dcId: 1 and podId: null
2013-03-29 00:18:46,730 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-46:job-46) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: 2
2013-03-29 00:18:46,730 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-46:job-46) Deploy avoids pods: null, clusters: null, hosts: null
2013-03-29 00:18:46,732 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) DeploymentPlanner allocation algorithm: random
2013-03-29 00:18:46,733 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 100, requested ram: 536870912
2013-03-29 00:18:46,733 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Is ROOT volume READY (pool already allocated)?: Yes
2013-03-29 00:18:46,733 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) DeploymentPlan has host_id specified, making no checks on this host, looks like admin test: 1
2013-03-29 00:18:46,736 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2013-03-29 00:18:46,738 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Checking suitable pools for volume (Id, Type): (14,ROOT)
2013-03-29 00:18:46,739 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Volume has pool already allocated, checking if pool can be reused, poolId: null
2013-03-29 00:18:46,741 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Planner need not allocate a pool for this volume since its READY
2013-03-29 00:18:46,741 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-03-29 00:18:46,741 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2013-03-29 00:18:46,744 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Host: 1 can access pool: 2
2013-03-29 00:18:46,744 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Found a potential host id: 1 name: Rack1Pod1Host22 and associated storage pools for this VM
2013-03-29 00:18:46,746 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(14|ROOT-->Pool(2))]
2013-03-29 00:18:46,747 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-46:job-46) Deployment found  - P0=VM[User|c], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(14|ROOT-->Pool(2))]
2013-03-29 00:18:46,763 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2013-03-29 00:18:46,780 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) Hosts's actual total CPU: 12404 and CPU after applying overprovisioning: 12404
2013-03-29 00:18:46,781 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) We are allocating VM, increasing the used capacity of this host:1
2013-03-29 00:18:46,781 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) Current Used CPU: 3000 , Free CPU:9404 ,Requested CPU: 100
2013-03-29 00:18:46,781 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) Current Used RAM: 3087007744 , Free RAM:5157568512 ,Requested RAM: 536870912
2013-03-29 00:18:46,781 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) CPU STATS after allocation: for host: 1, old used: 3000, old reserved: 0, actual total: 12404, total with overprovisioning: 12404; new used:3100, reserved:0; requested cpu:100,alloc_from_last:false
2013-03-29 00:18:46,781 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) RAM STATS after allocation: for host: 1, old used: 3087007744, old reserved: 0, total: 8244576256; new used: 3623878656, reserved: 0; requested mem: 536870912,alloc_from_last:false
2013-03-29 00:18:46,788 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-46:job-46) VM is being created in podId: 1
2013-03-29 00:18:46,794 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Lock is acquired for network id 204 as a part of network implement
2013-03-29 00:18:46,795 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Network id=204 is already implemented
2013-03-29 00:18:46,796 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Lock is released for network id 204 as a part of network implement
2013-03-29 00:18:46,845 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Changing active number of nics for network id=204 on 1
2013-03-29 00:18:46,851 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking ElasticLoadBalancerElement to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:46,859 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking NiciraNvpElement to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:46,859 DEBUG [network.element.NiciraNvpElement] (Job-Executor-46:job-46) Checking if NiciraNvpElement can handle service Connectivity on network defaultGuestNetwork
2013-03-29 00:18:46,867 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking BigSwitchVnsElement to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:46,867 DEBUG [network.element.BigSwitchVnsElement] (Job-Executor-46:job-46) Checking if BigSwitchVnsElement can handle service Connectivity on network defaultGuestNetwork
2013-03-29 00:18:46,875 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking Ovs to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:46,875 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking BareMetalDhcp to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:46,883 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking BareMetalPxe to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:46,890 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking BareMetalUserdata to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:46,898 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking SecurityGroupProvider to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:46,906 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking VirtualRouter to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:46,925 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-46:job-46) 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(1)-Storage(Volume(14|ROOT-->Pool(2))]
2013-03-29 00:18:46,932 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-46:job-46) Skipping VR deployment: Found a running or starting VR in Pod null id=1
2013-03-29 00:18:46,933 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-46:job-46) 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(1)-Storage(Volume(14|ROOT-->Pool(2))]
2013-03-29 00:18:46,954 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-46:job-46) Applying dhcp entry in network Ntwk[204|Guest|6]
2013-03-29 00:18:46,987 DEBUG [agent.transport.Request] (Job-Executor-46:job-46) Seq 1-173801884: Sending  { Cmd , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:af:a4:00:00:12","vmIpAddress":"10.147.40.167","vmName":"c","defaultRouter":"10.147.40.1","defaultDns":"10.147.40.164","duid":"00:03:00:01:06:af:a4:00:00:12","isDefault":true,"accessDetails":{"router.guest.ip":"10.147.40.164","zone.network.type":"Basic","router.name":"r-4-VM","router.ip":"169.254.1.50"},"wait":0}}] }
2013-03-29 00:18:48,043 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2013-03-29 00:18:48,095 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-173801885: Received:  { Ans: , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-03-29 00:18:48,609 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476963918
2013-03-29 00:18:48,629 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-25:null) Async job-43 completed
2013-03-29 00:18:48,637 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476963918
2013-03-29 00:18:49,202 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 1-173801884: Processing:  { Ans: , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":true,"wait":0}}] }
2013-03-29 00:18:49,203 DEBUG [agent.transport.Request] (Job-Executor-46:job-46) Seq 1-173801884: Received:  { Ans: , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 110, { Answer } }
2013-03-29 00:18:49,205 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-9:null) Seq 1-173801884: No more commands found
2013-03-29 00:18:49,232 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-46:job-46) Applying userdata and password entry in network Ntwk[204|Guest|6]
2013-03-29 00:18:49,262 DEBUG [agent.transport.Request] (Job-Executor-46:job-46) Seq 1-173801886: Sending  { Cmd , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 100111, [{"routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.147.40.167","vmName":"c","accessDetails":{"router.guest.ip":"10.147.40.164","zone.network.type":"Basic","router.ip":"169.254.1.50","router.name":"r-4-VM"},"wait":0}},{"routing.VmDataCommand":{"vmIpAddress":"10.147.40.167","vmName":"c","accessDetails":{"router.guest.ip":"10.147.40.164","zone.network.type":"Basic","router.ip":"169.254.1.50","router.name":"r-4-VM"},"wait":0}}] }
2013-03-29 00:18:49,621 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=4c2dd791-e013-4907-b22c-8854267d727e&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476964929
2013-03-29 00:18:49,656 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=4c2dd791-e013-4907-b22c-8854267d727e&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476964929
2013-03-29 00:18:51,609 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476966918
2013-03-29 00:18:51,629 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-13:null) Async job-43 completed
2013-03-29 00:18:51,636 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476966918
2013-03-29 00:18:52,622 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=4c2dd791-e013-4907-b22c-8854267d727e&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476967929
2013-03-29 00:18:52,654 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=4c2dd791-e013-4907-b22c-8854267d727e&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476967929
2013-03-29 00:18:54,610 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476969956
2013-03-29 00:18:54,631 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-5:null) Async job-43 completed
2013-03-29 00:18:54,638 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476969956
2013-03-29 00:18:55,132 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2013-03-29 00:18:55,192 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 3-1391067429: Received:  { Ans: , MgmtId: 7566222426160, via: 3, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-03-29 00:18:55,622 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=4c2dd791-e013-4907-b22c-8854267d727e&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476970968
2013-03-29 00:18:55,656 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=4c2dd791-e013-4907-b22c-8854267d727e&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476970968
2013-03-29 00:18:56,384 DEBUG [agent.transport.Request] (AgentManager-Handler-14:null) Seq 1-173801886: Processing:  { Ans: , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":true,"wait":0}},{"Answer":{"result":true,"wait":0}}] }
2013-03-29 00:18:56,386 DEBUG [agent.transport.Request] (Job-Executor-46:job-46) Seq 1-173801886: Received:  { Ans: , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 110, { Answer, Answer } }
2013-03-29 00:18:56,387 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking VpcVirtualRouter to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,389 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-14:null) Seq 1-173801886: No more commands found
2013-03-29 00:18:56,399 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking NiciraNvp to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,400 DEBUG [network.element.NiciraNvpElement] (Job-Executor-46:job-46) Checking if NiciraNvpElement can handle service Connectivity on network defaultGuestNetwork
2013-03-29 00:18:56,411 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking JuniperSRX to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,418 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking Netscaler to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,426 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking F5BigIP to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,433 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking CiscoNexus1000vVSM to prepare for Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,442 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-46:job-46) Checking if we need to prepare 1 volumes for VM[User|c]
2013-03-29 00:18:56,507 DEBUG [cloud.template.TemplateManagerImpl] (Job-Executor-46:job-46) Downloading 4 via 1
2013-03-29 00:18:56,512 DEBUG [agent.transport.Request] (Job-Executor-46:job-46) Seq 1-173801887: Sending  { Cmd , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 100111, [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/8e3875d5-a448-3f92-8f14-647083280540","poolUuid":"8e3875d5-a448-3f92-8f14-647083280540","poolId":2,"primaryPool":{"id":2,"uuid":"8e3875d5-a448-3f92-8f14-647083280540","host":"10.147.28.7","path":"/export/home/talluri/kvmc","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://10.147.28.7/export/home/talluri/kvms","primaryStorageUrl":"nfs://10.147.28.7/export/home/talluri/kvmc","url":"nfs://10.147.28.7/export/home/talluri/kvms/template/tmpl//1/4//ad4ed058-0823-34b4-91e8-684b01a9cf4c.qcow2","format":"QCOW2","accountId":1,"name":"centos55-x86_64","wait":10800}}] }
2013-03-29 00:18:56,536 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 1-173801887: Processing:  { Ans: , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:470)\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVMStoragePoolManager.java:103)\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePoolByURI(KVMStoragePoolManager.java:96)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2264)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1123)\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:679)\n","wait":0}}] }
2013-03-29 00:18:56,536 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-11:null) Seq 1-173801887: No more commands found
2013-03-29 00:18:56,537 DEBUG [agent.transport.Request] (Job-Executor-46:job-46) Seq 1-173801887: Received:  { Ans: , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 110, { Answer } }
2013-03-29 00:18:56,537 DEBUG [agent.manager.AgentManagerImpl] (Job-Executor-46:job-46) Details from executing class com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: java.lang.NullPointerException
        at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:470)
        at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.createStoragePool(KVMStoragePoolManager.java:103)
        at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePoolByURI(KVMStoragePoolManager.java:96)
        at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2264)
        at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1123)
        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:679)

2013-03-29 00:18:56,549 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-46:job-46) Unable to create Vol[14|vm=8|ROOT]:java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer
2013-03-29 00:18:56,549 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-46:job-46) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:2] is unreachable: Unable to create Vol[14|vm=8|ROOT]:java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer
        at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2218)
        at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2267)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:47)
        at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy289.prepare(Unknown Source)
        at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:751)
        at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:469)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:47)
        at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy198.start(Unknown Source)
        at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:47)
        at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy320.deployVirtualMachine(Unknown Source)
        at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2941)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2539)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2525)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.event.ActionEventInterceptor.AroundAnyMethod(ActionEventInterceptor.java:48)
        at sun.reflect.GeneratedMethodAccessor214.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:47)
        at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy259.startVirtualMachine(Unknown Source)
        at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:379)
        at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:165)
        at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:689)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:47)
        at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
        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-03-29 00:18:56,560 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-46:job-46) Cleaning up resources for the vm VM[User|c] in Starting state
2013-03-29 00:18:56,563 DEBUG [agent.transport.Request] (Job-Executor-46:job-46) Seq 1-173801888: Sending  { Cmd , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-8-VM","wait":0}}] }
2013-03-29 00:18:56,777 DEBUG [agent.transport.Request] (AgentManager-Handler-12:null) Seq 1-173801888: Processing:  { Ans: , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-03-29 00:18:56,777 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-12:null) Seq 1-173801888: No more commands found
2013-03-29 00:18:56,777 DEBUG [agent.transport.Request] (Job-Executor-46:job-46) Seq 1-173801888: Received:  { Ans: , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-03-29 00:18:56,793 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Changing active number of nics for network id=204 on -1
2013-03-29 00:18:56,801 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking ElasticLoadBalancerElement to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,803 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking NiciraNvpElement to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,803 DEBUG [network.element.NiciraNvpElement] (Job-Executor-46:job-46) Checking if NiciraNvpElement can handle service Connectivity on network defaultGuestNetwork
2013-03-29 00:18:56,803 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking BigSwitchVnsElement to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,804 DEBUG [network.element.BigSwitchVnsElement] (Job-Executor-46:job-46) Checking if BigSwitchVnsElement can handle service Connectivity on network defaultGuestNetwork
2013-03-29 00:18:56,804 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking Ovs to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,805 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking BareMetalDhcp to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,805 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking BareMetalPxe to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,805 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking BareMetalUserdata to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,806 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking SecurityGroupProvider to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,806 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking VirtualRouter to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,806 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking VpcVirtualRouter to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,807 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking NiciraNvp to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,807 DEBUG [network.element.NiciraNvpElement] (Job-Executor-46:job-46) Checking if NiciraNvpElement can handle service Connectivity on network defaultGuestNetwork
2013-03-29 00:18:56,807 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking JuniperSRX to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,808 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking Netscaler to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,808 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking F5BigIP to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,809 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-46:job-46) Asking CiscoNexus1000vVSM to release Nic[15-8-8e281981-3019-4b28-a649-db7aba952e06-10.147.40.167]
2013-03-29 00:18:56,809 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-46:job-46) Successfully released network resources for the vm VM[User|c]
2013-03-29 00:18:56,809 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-46:job-46) Successfully cleanued up resources for the vm VM[User|c] in Starting state
2013-03-29 00:18:56,812 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) DeploymentPlanner allocation algorithm: random
2013-03-29 00:18:56,812 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 100, requested ram: 536870912
2013-03-29 00:18:56,813 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Is ROOT volume READY (pool already allocated)?: Yes
2013-03-29 00:18:56,813 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) DeploymentPlan has host_id specified, making no checks on this host, looks like admin test: 1
2013-03-29 00:18:56,815 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2013-03-29 00:18:56,818 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Checking suitable pools for volume (Id, Type): (14,ROOT)
2013-03-29 00:18:56,818 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Volume has pool already allocated, checking if pool can be reused, poolId: null
2013-03-29 00:18:56,821 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Pool of the volume is in avoid set, need to reallocate a pool for this volume
2013-03-29 00:18:56,821 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) We need to allocate new storagepool for this volume
2013-03-29 00:18:56,821 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Calling StoragePoolAllocators to find suitable pools
2013-03-29 00:18:56,833 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) No suitable pools found for volume: Vol[14|vm=8|ROOT] under cluster: 1
2013-03-29 00:18:56,833 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) No suitable pools found
2013-03-29 00:18:56,833 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-46:job-46) Cannnot deploy to specified host, returning.
2013-03-29 00:18:56,853 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) 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
2013-03-29 00:18:56,864 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) Hosts's actual total CPU: 12404 and CPU after applying overprovisioning: 12404
2013-03-29 00:18:56,864 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) Hosts's actual total RAM: 8244576256 and RAM after applying overprovisioning: 8244576256
2013-03-29 00:18:56,865 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) release cpu from host: 1, old used: 3100,reserved: 0, actual total: 12404, total with overprovisioning: 12404; new used: 3000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-03-29 00:18:56,865 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) release mem from host: 1, old used: 3623878656,reserved: 0, total: 8244576256; new used: 3087007744,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-03-29 00:18:56,877 DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-46:job-46) Destroying vm VM[User|c] as it failed to create on Host with Id:null
2013-03-29 00:18:56,896 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-46:job-46) 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-03-29 00:18:56,907 WARN  [apache.cloudstack.alerts] (Job-Executor-46:job-46)  alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Failed to deploy Vm with Id: 8, on Host with Id: null
2013-03-29 00:18:56,961 INFO  [user.vm.DeployVMCmd] (Job-Executor-46:job-46) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|c]Scope=interface com.cloud.dc.DataCenter; id=1
2013-03-29 00:18:56,963 INFO  [user.vm.DeployVMCmd] (Job-Executor-46:job-46) Unable to create a deployment for VM[User|c]
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|c]Scope=interface com.cloud.dc.DataCenter; id=1
        at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:726)
        at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:469)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:47)
        at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy198.start(Unknown Source)
        at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:47)
        at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy320.deployVirtualMachine(Unknown Source)
        at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2941)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2539)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2525)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.event.ActionEventInterceptor.AroundAnyMethod(ActionEventInterceptor.java:48)
        at sun.reflect.GeneratedMethodAccessor214.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:47)
        at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy259.startVirtualMachine(Unknown Source)
        at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:379)
        at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:165)
        at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:689)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
        at com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:47)
        at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
        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-03-29 00:18:56,966 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-46:job-46) Complete async job-46, jobStatus: 2, resultCode: 530, result: Error Code: 533 Error text: Unable to create a deployment for VM[User|c]
2013-03-29 00:18:57,609 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476972956
2013-03-29 00:18:57,630 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-6:null) Async job-43 completed
2013-03-29 00:18:57,637 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476972956
2013-03-29 00:18:58,757 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=4c2dd791-e013-4907-b22c-8854267d727e&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476973967
2013-03-29 00:18:58,779 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-17:null) Async job-46 completed
2013-03-29 00:18:58,787 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=4c2dd791-e013-4907-b22c-8854267d727e&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476973967
2013-03-29 00:18:58,829 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===START===  10.252.250.64 -- GET  command=listVirtualMachines&id=9faabb67-5956-4f4b-b43f-4efe75a94bef&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476974173
2013-03-29 00:18:58,862 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===END===  10.252.250.64 -- GET  command=listVirtualMachines&id=9faabb67-5956-4f4b-b43f-4efe75a94bef&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476974173
2013-03-29 00:19:00,620 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476975957
2013-03-29 00:19:00,641 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-15:null) Async job-43 completed
2013-03-29 00:19:00,648 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476975957
2013-03-29 00:19:02,205 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2013-03-29 00:19:02,756 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-173801889: Received:  { Ans: , MgmtId: 7566222426160, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-03-29 00:19:03,614 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476978957
2013-03-29 00:19:03,639 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-19:null) Async job-43 completed
2013-03-29 00:19:03,648 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476978957
2013-03-29 00:19:05,177 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) Ping from 1
2013-03-29 00:19:06,618 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===START===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476981958
2013-03-29 00:19:06,639 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-16:null) Async job-43 completed
2013-03-29 00:19:06,646 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===END===  10.252.250.64 -- GET  command=queryAsyncJobResult&jobId=2030eff4-67b5-4b1d-8c04-1bb88c2ff326&response=json&sessionkey=fBgbfTKbB6aYlrhmnXUliOGoMHk%3D&_=1364476981958
2013-03-29 00:19:07,442 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-03-29 00:19:07,839 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
^C


--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

Mime
View raw message