[ https://issues.apache.org/jira/browse/CLOUDSTACK-2866?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Devdeep Singh reassigned CLOUDSTACK-2866: ----------------------------------------- Assignee: Devdeep Singh > [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 > Assignee: Devdeep Singh > Priority: Blocker > 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