cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Srikanteswararao Talluri (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (CLOUDSTACK-2866) [Automation] Unable to start a VM due to concurrent operation
Date Wed, 05 Jun 2013 19:38:20 GMT

     [ https://issues.apache.org/jira/browse/CLOUDSTACK-2866?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Srikanteswararao Talluri updated CLOUDSTACK-2866:
-------------------------------------------------

    Priority: Blocker  (was: Critical)
    
> [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: 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

Mime
View raw message