You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Srikanteswararao Talluri (JIRA)" <ji...@apache.org> on 2013/06/05 21:38:20 UTC
[jira] [Created] (CLOUDSTACK-2866) [Automation] Unable to start a
VM due to concurrent operation
Srikanteswararao Talluri created CLOUDSTACK-2866:
----------------------------------------------------
Summary: [Automation] Unable to start a VM due to concurrent operation
Key: CLOUDSTACK-2866
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-2866
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: Critical
Fix For: 4.2.0
Steps to reproduce:
1. deploy first VM in an account
2. try to stope the VM created in step1
3. stop the DomR
4. try to deploy another VM in the same account.
===START=== 10.151.133.42 -- GET command=deployVirtualMachine&zoneId=9aaae1c8-294c-41f0-b392-90086e814b53&templateId=b4a014e8-ce23-11e2-afec-06b270000059&hypervisor=XenServer&serviceOfferingId=eefcc446-8827-4bb3-b97f-0877ece9223e&networkIds=b98534fc-25b5-4834-9bc4-7c05d8b23ab9&response=json&sessionkey=gzAU%2FyMzZz0IoXpemIT8%2Fh4mPVg%3D&_=1370460715197
2013-06-06 06:26:05,128 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-9:null) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2013-06-06 06:26:05,131 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-9:null) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2013-06-06 06:26:05,136 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-9:null) ControlledEntity name is:com.cloud.network.Network
2013-06-06 06:26:05,160 DEBUG [cloud.network.NetworkModelImpl] (catalina-exec-9:null) Service SecurityGroup is not supported in the network id=348
2013-06-06 06:26:05,176 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===START=== 10.151.133.42 -- GET command=queryAsyncJobResult&jobId=79b7efa2-0f7d-4d29-87ae-974921a3df46&response=json&sessionkey=gzAU%2FyMzZz0IoXpemIT8%2Fh4mPVg%3D&_=1370460715254
2013-06-06 06:26:05,183 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-9:null) Allocating in the DB for vm
2013-06-06 06:26:05,216 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-391:null) Seq 1-1287849575: Response Received:
2013-06-06 06:26:05,223 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-1287849575: Received: { Ans: , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-06-06 06:26:05,240 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===END=== 10.151.133.42 -- GET command=queryAsyncJobResult&jobId=79b7efa2-0f7d-4d29-87ae-974921a3df46&response=json&sessionkey=gzAU%2FyMzZz0IoXpemIT8%2Fh4mPVg%3D&_=1370460715254
2013-06-06 06:26:05,242 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-9:null) Allocating entries for VM: VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8]
2013-06-06 06:26:05,245 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-9:null) Allocating nics for VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8]
2013-06-06 06:26:05,246 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-118:null) Seq 2-654640756: Executing request
2013-06-06 06:26:05,259 DEBUG [cloud.network.NetworkManagerImpl] (catalina-exec-9:null) Allocating nic for vm VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8] in network Ntwk[348|Guest|8] with requested profile NicProfile[0-0-null-null-null
2013-06-06 06:26:05,283 DEBUG [cloud.network.NetworkModelImpl] (catalina-exec-9:null) Service SecurityGroup is not supported in the network id=348
2013-06-06 06:26:05,286 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-9:null) Allocating disks for VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8]
2013-06-06 06:26:05,304 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-9:null) Allocation completed for VM: VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8]
2013-06-06 06:26:05,305 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-9:null) Successfully allocated DB entry for VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8]
2013-06-06 06:26:05,350 DEBUG [cloud.network.NetworkModelImpl] (catalina-exec-9:null) Service SecurityGroup is not supported in the network id=348
2013-06-06 06:26:05,358 DEBUG [cloud.network.NetworkModelImpl] (catalina-exec-9:null) Service SecurityGroup is not supported in the network id=348
2013-06-06 06:26:05,364 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-232:null) Seq 1-1287849576: Response Received:
2013-06-06 06:26:05,365 DEBUG [agent.transport.Request] (DirectAgent-232:null) Seq 1-1287849576: Processing: { Ans: , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 10, [{"CheckRouterAnswer":{"state":"BACKUP","isBumped":false,"result":true,"details":"Status: BACKUP&Bumped: NO","wait":0}}] }
2013-06-06 06:26:05,365 DEBUG [agent.transport.Request] (RedundantRouterStatusMonitor-6:null) Seq 1-1287849576: Received: { Ans: , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 10, { CheckRouterAnswer } }
2013-06-06 06:26:05,366 DEBUG [agent.manager.AgentManagerImpl] (RedundantRouterStatusMonitor-6:null) Details from executing class com.cloud.agent.api.CheckRouterCommand: Status: BACKUP&Bumped: NO
2013-06-06 06:26:05,375 INFO [network.router.VirtualNetworkApplianceManagerImpl] (RedundantRouterStatusMonitor-6:null) Redundant virtual router (name: r-199-QA, id: 199) just switch from UNKNOWN to BACKUP
2013-06-06 06:26:05,405 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-94:job-645) Executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-645
2013-06-06 06:26:05,409 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-9:null) submit async job-645, details: AsyncJobVO {id:645, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 201, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator: null, cmdInfo: {"sessionkey":"gzAU/yMzZz0IoXpemIT8/h4mPVg\u003d","ctxUserId":"2","serviceOfferingId":"eefcc446-8827-4bb3-b97f-0877ece9223e","httpmethod":"GET","zoneId":"9aaae1c8-294c-41f0-b392-90086e814b53","templateId":"b4a014e8-ce23-11e2-afec-06b270000059","response":"json","id":"201","networkIds":"b98534fc-25b5-4834-9bc4-7c05d8b23ab9","hypervisor":"XenServer","_":"1370460715197","ctxAccountId":"2","ctxStartEventId":"3047"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 7363452993625, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-06-06 06:26:05,412 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null) ===END=== 10.151.133.42 -- GET command=deployVirtualMachine&zoneId=9aaae1c8-294c-41f0-b392-90086e814b53&templateId=b4a014e8-ce23-11e2-afec-06b270000059&hypervisor=XenServer&serviceOfferingId=eefcc446-8827-4bb3-b97f-0877ece9223e&networkIds=b98534fc-25b5-4834-9bc4-7c05d8b23ab9&response=json&sessionkey=gzAU%2FyMzZz0IoXpemIT8%2Fh4mPVg%3D&_=1370460715197
2013-06-06 06:26:05,417 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-94:job-645) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2013-06-06 06:26:05,431 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-94:job-645) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2013-06-06 06:26:05,438 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-94:job-645) ControlledEntity name is:com.cloud.network.Network
2013-06-06 06:26:05,482 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-94:job-645) Service SecurityGroup is not supported in the network id=348
2013-06-06 06:26:05,490 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-94:job-645) Service SecurityGroup is not supported in the network id=348
2013-06-06 06:26:05,538 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Deploy avoids pods: null, clusters: null, hosts: null
2013-06-06 06:26:05,542 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_dec5568@5fcab519
2013-06-06 06:26:05,543 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 100, requested ram: 268435456
2013-06-06 06:26:05,543 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Is ROOT volume READY (pool already allocated)?: No
2013-06-06 06:26:05,543 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-94:job-645) Searching all possible resources under this Zone: 1
2013-06-06 06:26:05,545 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-94:job-645) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2013-06-06 06:26:05,564 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Checking resources in Cluster: 1 under Pod: 1
2013-06-06 06:26:05,568 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2013-06-06 06:26:05,575 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-94:job-645 FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-2-Routing], Host[-1-Routing]]
2013-06-06 06:26:05,581 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-2-Routing], Host[-1-Routing]]
2013-06-06 06:26:05,582 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Looking for speed=100Mhz, Ram=256
2013-06-06 06:26:05,591 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Checking if host: 2 has enough capacity for requested CPU: 100 and requested RAM: 268435456 , cpuOverprovisioningFactor: 1.0
2013-06-06 06:26:05,596 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Hosts's actual total CPU: 9576 and CPU after applying overprovisioning: 9576
2013-06-06 06:26:05,596 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Free CPU: 4776 , Requested CPU: 100
2013-06-06 06:26:05,596 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Free RAM: 13505802240 , Requested RAM: 268435456
2013-06-06 06:26:05,596 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-06-06 06:26:05,596 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 2, used: 4200, reserved: 600, actual total: 9576, total with overprovisioning: 9576; requested cpu:100,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-06 06:26:05,596 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 2, used: 2415919104, reserved: 268435456, total: 16190156800; requested mem: 268435456,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-06 06:26:05,596 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Found a suitable host, adding to list: 2
2013-06-06 06:26:05,606 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 100 and requested RAM: 268435456 , cpuOverprovisioningFactor: 1.0
2013-06-06 06:26:05,610 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Hosts's actual total CPU: 9576 and CPU after applying overprovisioning: 9576
2013-06-06 06:26:05,610 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Free CPU: 6676 , Requested CPU: 100
2013-06-06 06:26:05,611 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Free RAM: 14847979520 , Requested RAM: 268435456
2013-06-06 06:26:05,611 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-06-06 06:26:05,611 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 1700, reserved: 1200, actual total: 9576, total with overprovisioning: 9576; requested cpu:100,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-06 06:26:05,611 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 805306368, reserved: 536870912, total: 16190156800; requested mem: 268435456,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-06 06:26:05,611 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2013-06-06 06:26:05,611 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-94:job-645 FirstFitRoutingAllocator) Host Allocator returning 2 suitable hosts
2013-06-06 06:26:05,614 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Checking suitable pools for volume (Id, Type): (233,ROOT)
2013-06-06 06:26:05,614 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) We need to allocate new storagepool for this volume
2013-06-06 06:26:05,616 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Calling StoragePoolAllocators to find suitable pools
2013-06-06 06:26:05,630 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-94:job-645) Checking pool 1 for storage, totalSize: 1759218630656, usedBytes: 1244502884352, usedPct: 0.7074179767456952, disable threshold: 0.85
2013-06-06 06:26:05,722 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-118:null) Seq 2-654640756: Response Received:
2013-06-06 06:26:05,728 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-654640756: Received: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-06-06 06:26:05,738 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-94:job-645) Checking pool: 1 for volume allocation [Vol[233|vm=201|ROOT]], maxSize : 3518437261312, totalAllocatedSize : 100034532352, askingSize : 21474836480, allocated disable threshold: 0.85
2013-06-06 06:26:05,744 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-239:null) Seq 5-1122435490: Executing request
2013-06-06 06:26:05,768 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-94:job-645) Checking pool 2 for storage, totalSize: 1759218630656, usedBytes: 1244503867392, usedPct: 0.7074185355392316, disable threshold: 0.85
2013-06-06 06:26:05,918 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-94:job-645) Checking pool: 2 for volume allocation [Vol[233|vm=201|ROOT]], maxSize : 3518437261312, totalAllocatedSize : 244989678592, askingSize : 21474836480, allocated disable threshold: 0.85
2013-06-06 06:26:05,918 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-06-06 06:26:05,918 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Checking if host: 2 can access any suitable storage pool for volume: ROOT
2013-06-06 06:26:05,920 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Host: 2 can access pool: 1
2013-06-06 06:26:05,922 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Found a potential host id: 2 name: Rack1Pod1Host17 and associated storage pools for this VM
2013-06-06 06:26:05,924 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) 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(2)-Storage(Volume(233|ROOT-->Pool(1))]
2013-06-06 06:26:05,952 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645) 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-06-06 06:26:05,952 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Successfully transitioned to start state for VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8] reservation id = 76e0a1ad-215c-46f3-b472-5932a593b399
2013-06-06 06:26:05,958 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Trying to deploy VM, vm has dcId: 1 and podId: null
2013-06-06 06:26:05,959 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 2, poolId: null
2013-06-06 06:26:05,959 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Deploy avoids pods: null, clusters: null, hosts: null
2013-06-06 06:26:05,966 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-239:null) Seq 5-1122435490: Response Received:
2013-06-06 06:26:05,970 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 5-1122435490: Received: { Ans: , MgmtId: 7363452993625, via: 5, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-06-06 06:26:05,982 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Deploy avoids pods: null, clusters: null, hosts: null
2013-06-06 06:26:05,984 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_dec5568@5fcab519
2013-06-06 06:26:05,984 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 100, requested ram: 268435456
2013-06-06 06:26:05,984 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Is ROOT volume READY (pool already allocated)?: No
2013-06-06 06:26:05,984 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 2
2013-06-06 06:26:05,986 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2013-06-06 06:26:05,988 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Checking suitable pools for volume (Id, Type): (233,ROOT)
2013-06-06 06:26:05,988 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) We need to allocate new storagepool for this volume
2013-06-06 06:26:05,988 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Calling StoragePoolAllocators to find suitable pools
2013-06-06 06:26:06,000 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-94:job-645) Checking pool 1 for storage, totalSize: 1759218630656, usedBytes: 1244502884352, usedPct: 0.7074179767456952, disable threshold: 0.85
2013-06-06 06:26:06,068 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-94:job-645) Checking pool: 1 for volume allocation [Vol[233|vm=201|ROOT]], maxSize : 3518437261312, totalAllocatedSize : 100034532352, askingSize : 21474836480, allocated disable threshold: 0.85
2013-06-06 06:26:06,075 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-94:job-645) Checking pool 2 for storage, totalSize: 1759218630656, usedBytes: 1244503867392, usedPct: 0.7074185355392316, disable threshold: 0.85
2013-06-06 06:26:06,205 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-94:job-645) Checking pool: 2 for volume allocation [Vol[233|vm=201|ROOT]], maxSize : 3518437261312, totalAllocatedSize : 244989678592, askingSize : 21474836480, allocated disable threshold: 0.85
2013-06-06 06:26:06,205 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-06-06 06:26:06,205 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Checking if host: 2 can access any suitable storage pool for volume: ROOT
2013-06-06 06:26:06,207 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Host: 2 can access pool: 2
2013-06-06 06:26:06,209 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) Found a potential host id: 2 name: Rack1Pod1Host17 and associated storage pools for this VM
2013-06-06 06:26:06,210 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-94:job-645) 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(2)-Storage(Volume(233|ROOT-->Pool(2))]
2013-06-06 06:26:06,211 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Deployment found - P0=VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(233|ROOT-->Pool(2))]
2013-06-06 06:26:06,225 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 2 host id before state transition: null
2013-06-06 06:26:06,238 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645) Hosts's actual total CPU: 9576 and CPU after applying overprovisioning: 9576
2013-06-06 06:26:06,238 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645) We are allocating VM, increasing the used capacity of this host:2
2013-06-06 06:26:06,238 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645) Current Used CPU: 4200 , Free CPU:4776 ,Requested CPU: 100
2013-06-06 06:26:06,239 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645) Current Used RAM: 2415919104 , Free RAM:13505802240 ,Requested RAM: 268435456
2013-06-06 06:26:06,239 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645) CPU STATS after allocation: for host: 2, old used: 4200, old reserved: 600, actual total: 9576, total with overprovisioning: 9576; new used:4300, reserved:600; requested cpu:100,alloc_from_last:false
2013-06-06 06:26:06,239 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-94:job-645) RAM STATS after allocation: for host: 2, old used: 2415919104, old reserved: 268435456, total: 16190156800; new used: 2684354560, reserved: 268435456; requested mem: 268435456,alloc_from_last:false
2013-06-06 06:26:06,245 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) VM is being created in podId: 1
2013-06-06 06:26:06,250 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Lock is acquired for network id 348 as a part of network implement
2013-06-06 06:26:06,250 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Network id=348 is already implemented
2013-06-06 06:26:06,251 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Lock is released for network id 348 as a part of network implement
2013-06-06 06:26:06,266 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===START=== 10.147.38.149 -- GET signature=dPtDEBZ4TbuPhAkJId3ljXLLIfU%3D&apiKey=7DWqOPiih8M6-x9y1A2dC6t1BoGjyqXYIfOtQp0Up3XhMo-FhXsF8JzxZyth3sdJi1jNURNKbR0wrae6LJDkLw&command=queryAsyncJobResult&response=json&jobid=b0ee2f83-9dd1-4af9-baf0-4a1690397203
2013-06-06 06:26:06,272 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-94:job-645) Service SecurityGroup is not supported in the network id=348
2013-06-06 06:26:06,287 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Changing active number of nics for network id=348 on 1
2013-06-06 06:26:06,294 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Asking JuniperSRX to prepare for Nic[362-201-76e0a1ad-215c-46f3-b472-5932a593b399-10.1.1.78]
2013-06-06 06:26:06,303 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Asking Netscaler to prepare for Nic[362-201-76e0a1ad-215c-46f3-b472-5932a593b399-10.1.1.78]
2013-06-06 06:26:06,314 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===END=== 10.147.38.149 -- GET signature=dPtDEBZ4TbuPhAkJId3ljXLLIfU%3D&apiKey=7DWqOPiih8M6-x9y1A2dC6t1BoGjyqXYIfOtQp0Up3XhMo-FhXsF8JzxZyth3sdJi1jNURNKbR0wrae6LJDkLw&command=queryAsyncJobResult&response=json&jobid=b0ee2f83-9dd1-4af9-baf0-4a1690397203
2013-06-06 06:26:06,317 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Asking F5BigIP to prepare for Nic[362-201-76e0a1ad-215c-46f3-b472-5932a593b399-10.1.1.78]
2013-06-06 06:26:06,324 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Asking CiscoNexus1000vVSM to prepare for Nic[362-201-76e0a1ad-215c-46f3-b472-5932a593b399-10.1.1.78]
2013-06-06 06:26:06,324 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Asking CiscoVNMC to prepare for Nic[362-201-76e0a1ad-215c-46f3-b472-5932a593b399-10.1.1.78]
2013-06-06 06:26:06,333 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Asking NiciraNvp to prepare for Nic[362-201-76e0a1ad-215c-46f3-b472-5932a593b399-10.1.1.78]
2013-06-06 06:26:06,333 DEBUG [network.element.NiciraNvpElement] (Job-Executor-94:job-645) Checking if NiciraNvpElement can handle service Connectivity on network test
2013-06-06 06:26:06,340 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Asking MidoNetElement to prepare for Nic[362-201-76e0a1ad-215c-46f3-b472-5932a593b399-10.1.1.78]
2013-06-06 06:26:06,340 DEBUG [network.element.MidoNetElement] (Job-Executor-94:job-645) prepare called with network: Ntwk[348|Guest|8] nic: NicProfile[362-201-76e0a1ad-215c-46f3-b472-5932a593b399-10.1.1.78-vlan://1064 vm: VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8]
2013-06-06 06:26:06,347 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Asking BigSwitchVnsElement to prepare for Nic[362-201-76e0a1ad-215c-46f3-b472-5932a593b399-10.1.1.78]
2013-06-06 06:26:06,347 DEBUG [network.element.BigSwitchVnsElement] (Job-Executor-94:job-645) Checking if BigSwitchVnsElement can handle service Connectivity on network test
2013-06-06 06:26:06,354 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-94:job-645) Asking VirtualRouter to prepare for Nic[362-201-76e0a1ad-215c-46f3-b472-5932a593b399-10.1.1.78]
2013-06-06 06:26:06,371 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-94:job-645) Lock is acquired for network id 348 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(2)-Storage(Volume(233|ROOT-->Pool(2))]
2013-06-06 06:26:06,377 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-94:job-645) Lock is released for network id 348 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(2)-Storage(Volume(233|ROOT-->Pool(2))]
2013-06-06 06:26:06,379 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-94:job-645) Starting router VM[DomainRouter|r-190-QA]
2013-06-06 06:26:06,386 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Unable to transition into Starting state due to Unable to transition to a new state from Stopping via StartRequested
2013-06-06 06:26:06,387 DEBUG [db.Transaction.Transaction] (Job-Executor-94:job-645) Rolling back the transaction: Time = 3 Name = -AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679; called by -Transaction.rollback:890-VirtualMachineManagerImpl.changeToStartState:619-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VirtualMachineManagerImpl.advanceStart:695-VirtualMachineManagerImpl.start:550-VirtualNetworkApplianceManagerImpl.start:2720-VirtualNetworkApplianceManagerImpl.startVirtualRouter:1861-VirtualNetworkApplianceManagerImpl.startRouters:1961-VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork:1939-VirtualRouterElement.prepare:236-NetworkManagerImpl.prepareElement:1959-NetworkManagerImpl.prepareNic:2080
2013-06-06 06:26:06,393 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Determining why we're unable to update the state to Starting for VM[DomainRouter|r-190-QA]. Retry=4
2013-06-06 06:26:06,395 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Unable to find work for VM: VM[DomainRouter|r-190-QA] and state: Stopping
2013-06-06 06:26:06,397 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Unable to transition into Starting state due to Unable to transition to a new state from Stopping via StartRequested
2013-06-06 06:26:06,398 DEBUG [db.Transaction.Transaction] (Job-Executor-94:job-645) Rolling back the transaction: Time = 3 Name = -AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679; called by -Transaction.rollback:890-VirtualMachineManagerImpl.changeToStartState:619-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VirtualMachineManagerImpl.advanceStart:695-VirtualMachineManagerImpl.start:550-VirtualNetworkApplianceManagerImpl.start:2720-VirtualNetworkApplianceManagerImpl.startVirtualRouter:1861-VirtualNetworkApplianceManagerImpl.startRouters:1961-VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork:1939-VirtualRouterElement.prepare:236-NetworkManagerImpl.prepareElement:1959-NetworkManagerImpl.prepareNic:2080
2013-06-06 06:26:06,402 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Determining why we're unable to update the state to Starting for VM[DomainRouter|r-190-QA]. Retry=3
2013-06-06 06:26:06,404 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Unable to find work for VM: VM[DomainRouter|r-190-QA] and state: Stopping
2013-06-06 06:26:06,406 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Unable to transition into Starting state due to Unable to transition to a new state from Stopping via StartRequested
2013-06-06 06:26:06,407 DEBUG [db.Transaction.Transaction] (Job-Executor-94:job-645) Rolling back the transaction: Time = 2 Name = -AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679; called by -Transaction.rollback:890-VirtualMachineManagerImpl.changeToStartState:619-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VirtualMachineManagerImpl.advanceStart:695-VirtualMachineManagerImpl.start:550-VirtualNetworkApplianceManagerImpl.start:2720-VirtualNetworkApplianceManagerImpl.startVirtualRouter:1861-VirtualNetworkApplianceManagerImpl.startRouters:1961-VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork:1939-VirtualRouterElement.prepare:236-NetworkManagerImpl.prepareElement:1959-NetworkManagerImpl.prepareNic:2080
2013-06-06 06:26:06,411 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Determining why we're unable to update the state to Starting for VM[DomainRouter|r-190-QA]. Retry=2
2013-06-06 06:26:06,413 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Unable to find work for VM: VM[DomainRouter|r-190-QA] and state: Stopping
2013-06-06 06:26:06,415 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Unable to transition into Starting state due to Unable to transition to a new state from Stopping via StartRequested
2013-06-06 06:26:06,416 DEBUG [db.Transaction.Transaction] (Job-Executor-94:job-645) Rolling back the transaction: Time = 2 Name = -AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679; called by -Transaction.rollback:890-VirtualMachineManagerImpl.changeToStartState:619-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VirtualMachineManagerImpl.advanceStart:695-VirtualMachineManagerImpl.start:550-VirtualNetworkApplianceManagerImpl.start:2720-VirtualNetworkApplianceManagerImpl.startVirtualRouter:1861-VirtualNetworkApplianceManagerImpl.startRouters:1961-VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork:1939-VirtualRouterElement.prepare:236-NetworkManagerImpl.prepareElement:1959-NetworkManagerImpl.prepareNic:2080
2013-06-06 06:26:06,420 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Determining why we're unable to update the state to Starting for VM[DomainRouter|r-190-QA]. Retry=1
2013-06-06 06:26:06,422 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Unable to find work for VM: VM[DomainRouter|r-190-QA] and state: Stopping
2013-06-06 06:26:06,424 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Unable to transition into Starting state due to Unable to transition to a new state from Stopping via StartRequested
2013-06-06 06:26:06,425 DEBUG [db.Transaction.Transaction] (Job-Executor-94:job-645) Rolling back the transaction: Time = 2 Name = -AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679; called by -Transaction.rollback:890-VirtualMachineManagerImpl.changeToStartState:619-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VirtualMachineManagerImpl.advanceStart:695-VirtualMachineManagerImpl.start:550-VirtualNetworkApplianceManagerImpl.start:2720-VirtualNetworkApplianceManagerImpl.startVirtualRouter:1861-VirtualNetworkApplianceManagerImpl.startRouters:1961-VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork:1939-VirtualRouterElement.prepare:236-NetworkManagerImpl.prepareElement:1959-NetworkManagerImpl.prepareNic:2080
2013-06-06 06:26:06,428 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Determining why we're unable to update the state to Starting for VM[DomainRouter|r-190-QA]. Retry=0
2013-06-06 06:26:06,431 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Unable to find work for VM: VM[DomainRouter|r-190-QA] and state: Stopping
2013-06-06 06:26:06,431 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Failed to start instance VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8]
com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to concurrent operation
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:552)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNetworkApplianceManagerImpl.java:2720)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRouter(VirtualNetworkApplianceManagerImpl.java:1861)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(VirtualNetworkApplianceManagerImpl.java:1961)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1939)
at com.cloud.network.element.VirtualRouterElement.prepare(VirtualRouterElement.java:236)
at com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:1959)
at com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2080)
at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2021)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:842)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:550)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:239)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3341)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2868)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2854)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155)
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)
Caused by: com.cloud.exception.ConcurrentOperationException: Unable to change the state of VM[DomainRouter|r-190-QA]
at com.cloud.vm.VirtualMachineManagerImpl.changeToStartState(VirtualMachineManagerImpl.java:654)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:695)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:550)
... 29 more
2013-06-06 06:26:06,441 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-94:job-645) Cleaning up resources for the vm VM[User|76fceaae-f450-4b84-8191-75ddd1242fe8] in Starting state
2013-06-06 06:26:06,449 DEBUG [agent.transport.Request] (Job-Executor-94:job-645) Seq 2-654640757: Waiting for Seq 654640755 Scheduling: { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-201-QA","wait":0}}] }
2013-06-06 06:26:07,855 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===START=== 10.151.133.42 -- GET command=queryAsyncJobResult&jobId=b319fe12-aa64-459e-bf9f-cbf0463ae4a6&response=json&sessionkey=gzAU%2FyMzZz0IoXpemIT8%2Fh4mPVg%3D&_=1370460717937
2013-06-06 06:26:07,887 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===END=== 10.151.133.42 -- GET command=queryAsyncJobResult&jobId=b319fe12-aa64-459e-bf9f-cbf0463ae4a6&response=json&sessionkey=gzAU%2FyMzZz0IoXpemIT8%2Fh4mPVg%3D&_=1370460717937
2013-06-06 06:26:08,173 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===START=== 10.151.133.42 -- GET command=queryAsyncJobResult&jobId=79b7efa2-0f7d-4d29-87ae-974921a3df46&response=json&sessionkey=gzAU%2FyMzZz0IoXpemIT8%2Fh4mPVg%3D&_=1370460718255
2013-06-06 06:26:08,204 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===END=== 10.151.133.42 -- GET command=queryAsyncJobResult&jobId=79b7efa2-0f7d-4d29-87ae-974921a3df46&response=json&sessionkey=gzAU%2FyMzZz0IoXpemIT8%2Fh4mPVg%3D&_=1370460718255
2013-06-06 06:26:08,498 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===START=== 10.151.133.42 -- GET command=queryAsyncJobResult&jobId=b6d737ad-1f09-4a0b-b693-9e44ed46df08&response=json&sessionkey=gzAU%2FyMzZz0IoXpemIT8%2Fh4mPVg%3D&_=1370460718578
2013-06-06 06:26:08,528 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null) ===START=== 10.147.38.149 -- GET signature=R3nB1jkKL3EF9qSDdqfVimjAjZ8%3D&apiKey=7DWqOPiih8M6-x9y1A2dC6t1BoGjyqXYIfOtQp0Up3XhMo-FhXsF8JzxZyth3sdJi1jNURNKbR0wrae6LJDkLw&command=queryAsyncJobResult&response=json&jobid=9abbfca5-2b58-402e-9f3a-045088e6f68b
2013-06-06 06:26:08,537 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===END=== 10.151.133.42 -- GET command=queryAsyncJobResult&jobId=b6d737ad-1f09-4a0b-b693-9e44ed46df08&response=json&sessionkey=gzAU%2FyMzZz0IoXpemIT8%2Fh4mPVg%3D&_=1370460718578
2013-06-06 06:26:08,565 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null) ===END=== 10.147.38.149 -- GET signature=R3nB1jkKL3EF9qSDdqfVimjAjZ8%3D&apiKey=7DWqOPiih8M6-x9y1A2dC6t1BoGjyqXYIfOtQp0Up3XhMo-FhXsF8JzxZyth3sdJi1jNURNKbR0wrae6LJDkLw&command=queryAsyncJobResult&response=json&jobid=9abbfca5-2b58-402e-9f3a-045088e6f68b
--
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