You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Devdeep Singh (JIRA)" <ji...@apache.org> on 2013/06/06 15:14:20 UTC
[jira] [Resolved] (CLOUDSTACK-2866) [Automation] Unable to start a
VM due to concurrent operation
[ https://issues.apache.org/jira/browse/CLOUDSTACK-2866?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Devdeep Singh resolved CLOUDSTACK-2866.
---------------------------------------
Resolution: Not A Problem
The only way I could reproduce the stack trace given in the bug was.
1. Deploy an instance for an account. The router vm also gets created.
2. Stop the instance.
3. Stop the router vm for the account (only admin can do it) and immediately put a request for deploying a vm of the same account. The router vm should still be in stopping state while the request for new instance deployment is placed.
Since an instance deployment request is placed, ms looks for a router vm of the account and if it doesn't find any in running state it tries to start one. Since the router vm is actually in stopping state the concurrent exception is throw and the stack trace given in the bug gets logged.
However, this doesn't actually fail the vm deployment request. Cloudstack retries vm deployment and it goes through next time. So this doesn't cause any problem, but an exception does get logged.
Kindly, reopen the bug if it causes vm deployment to fail.
> [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