[
https://issues.apache.org/jira/browse/CLOUDSTACK-2336?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Pranav Saxena reassigned CLOUDSTACK-2336:
-----------------------------------------
Assignee: Pranav Saxena
> UI: SXM : wrong API is being called while trying to migrate a VM with volume
> ----------------------------------------------------------------------------
>
> Key: CLOUDSTACK-2336
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-2336
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: UI
> Affects Versions: 4.2.0
> Environment: Xenserver 6.1 with storage xenmotion feature enabled
> Single zone with two clusters having shared storage pool for each cluster.
> Reporter: Srikanteswararao Talluri
> Assignee: Pranav Saxena
> Priority: Critical
> Fix For: 4.2.0
>
>
> Refer to the environment section for setup used
> From UI:
> 1. In the virtual machine screen, Click on 'migrate' button to list the
> suitable hosts to migrate the VM to.
> 2. Select a host which is in different cluster.
> After selecting the host to migrate to,If VM is
> 1. being migrated to a host in the same cluster - migrateVirtualMachine API
> should be called
> otherwise if,
> 2. being migrated to a host in different cluster then
> migrateVirtualMachineWithVolume API should be called.
> Issue:
> When user is trying to select a host in a different cluster to migrate to,
> operation is failing for the first time (because migrateVirtualMachine is
> being called instead of migrateVirtualMachineWithVolume ). However, it
> succeeds when the host in the different cluster is listed first in the
> 'findHostsForMigration' API call
> ===START=== 10.252.242.121 -- GET
> command=findHostsForMigration&VirtualMachineId=4f417cd8-055e-4efe-a466-3fba321f1666&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826850005
> 2013-05-06 18:50:17,947 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-2:null) Checking pool: 1 for volume allocation
> [Vol[3|vm=3|ROOT]], maxSize : 11804569632768, totalAllocatedSize :
> 66748535808, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:50:18,017 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-2:null) Checking pool: 2 for volume allocation
> [Vol[3|vm=3|ROOT]], maxSize : 11804569632768, totalAllocatedSize :
> 73190986752, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:50:18,068 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-2:null) Checking pool: 1 for volume allocation
> [Vol[7|vm=3|DATADISK]], maxSize : 11804569632768, totalAllocatedSize :
> 66748535808, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:50:18,138 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-2:null) Checking pool: 2 for volume allocation
> [Vol[7|vm=3|DATADISK]], maxSize : 11804569632768, totalAllocatedSize :
> 73190986752, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:50:18,218 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-2:null) Checking pool: 3 for volume allocation
> [Vol[3|vm=3|ROOT]], maxSize : 11804569632768, totalAllocatedSize :
> 92518339584, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:50:18,296 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-2:null) Checking pool: 3 for volume allocation
> [Vol[7|vm=3|DATADISK]], maxSize : 11804569632768, totalAllocatedSize :
> 92518339584, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:50:18,306 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-2:null) FirstFitAllocator has 2 hosts to check for allocation:
> [Host[-2-Routing], Host[-3-Routing]]
> 2013-05-06 18:50:18,312 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-2:null) Found 2 hosts for allocation after prioritization:
> [Host[-2-Routing], Host[-3-Routing]]
> 2013-05-06 18:50:18,312 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-2:null) Looking for speed=500Mhz, Ram=512
> 2013-05-06 18:50:18,321 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) Checking if host: 2 has enough capacity for requested
> CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
> 2013-05-06 18:50:18,325 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) Hosts's actual total CPU: 9576 and CPU after applying
> overprovisioning: 9576
> 2013-05-06 18:50:18,325 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) considerReservedCapacity isfalse , not considering
> reserved capacity for calculating free capacity
> 2013-05-06 18:50:18,325 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) Free CPU: 9076 , Requested CPU: 500
> 2013-05-06 18:50:18,326 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) Free RAM: 15921721344 , Requested RAM: 536870912
> 2013-05-06 18:50:18,326 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) Host has enough CPU and RAM available
> 2013-05-06 18:50:18,326 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) STATS: Can alloc CPU from host: 2, used: 500,
> reserved: 0, actual total: 9576, total with overprovisioning: 9576; requested
> cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2013-05-06 18:50:18,326 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) STATS: Can alloc MEM from host: 2, used: 268435456,
> reserved: 0, total: 16190156800; requested mem:
> 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2013-05-06 18:50:18,326 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-2:null) Found a suitable host, adding to list: 2
> 2013-05-06 18:50:18,334 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) Checking if host: 3 has enough capacity for requested
> CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
> 2013-05-06 18:50:18,338 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) Hosts's actual total CPU: 9580 and CPU after applying
> overprovisioning: 9580
> 2013-05-06 18:50:18,338 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) considerReservedCapacity isfalse , not considering
> reserved capacity for calculating free capacity
> 2013-05-06 18:50:18,338 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) Free CPU: 8480 , Requested CPU: 500
> 2013-05-06 18:50:18,338 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) Free RAM: 14982197248 , Requested RAM: 536870912
> 2013-05-06 18:50:18,338 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) Host has enough CPU and RAM available
> 2013-05-06 18:50:18,338 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) STATS: Can alloc CPU from host: 3, used: 1100,
> reserved: 0, actual total: 9580, total with overprovisioning: 9580; requested
> cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2013-05-06 18:50:18,338 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-2:null) STATS: Can alloc MEM from host: 3, used: 1207959552,
> reserved: 0, total: 16190156800; requested mem:
> 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2013-05-06 18:50:18,338 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-2:null) Found a suitable host, adding to list: 3
> 2013-05-06 18:50:18,338 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-2:null) Host Allocator returning 2 suitable hosts
> 2013-05-06 18:50:18,339 DEBUG [cloud.server.ManagementServerImpl]
> (catalina-exec-2:null) Hosts having capacity and suitable for migration:
> [Host[-2-Routing], Host[-3-Routing]]
> 2013-05-06 18:50:18,358 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null)
> ===END=== 10.252.242.121 -- GET
> command=findHostsForMigration&VirtualMachineId=4f417cd8-055e-4efe-a466-3fba321f1666&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826850005
> 2013-05-06 18:50:18,989 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-412:null) Ping from 2
> 2013-05-06 18:50:23,434 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-31:null) Ping from 3
> 2013-05-06 18:50:24,441 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-412:null) Seq 3-1946091524: Executing request
> 2013-05-06 18:50:24,756 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-412:null) Seq 3-1946091524: Response Received:
> 2013-05-06 18:50:24,757 DEBUG [agent.transport.Request]
> (DirectAgent-412:null) Seq 3-1946091524: Processing: { Ans: , MgmtId:
> 7363452993625, via: 3, Ver: v1, Flags: 10,
> [{"ClusterSyncAnswer":{"_clusterId":2,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}]
> }
> 2013-05-06 18:50:27,511 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null)
> ===START=== 10.252.242.121 -- GET
> command=migrateVirtualMachine&hostid=180882a5-aa3e-4252-b42d-f405d3225a08&virtualmachineid=4f417cd8-055e-4efe-a466-3fba321f1666&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826859656
> 2013-05-06 18:50:27,566 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-23:null) submit async job-283, details: AsyncJobVO {id:283,
> userId: 2, accountId: 2, sessionKey: null, instanceType: None, instanceId:
> null, cmd: org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd,
> cmdOriginator: null, cmdInfo:
> {"response":"json","sessionkey":"cSc24xTjuz69EQZS4m5DA9c3Tpc\u003d","virtualmachineid":"4f417cd8-055e-4efe-a466-3fba321f1666","hostid":"180882a5-aa3e-4252-b42d-f405d3225a08","ctxUserId":"2","httpmethod":"GET","_":"1367826859656","ctxAccountId":"2","ctxStartEventId":"1338"},
> 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-05-06 18:50:27,569 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null)
> ===END=== 10.252.242.121 -- GET
> command=migrateVirtualMachine&hostid=180882a5-aa3e-4252-b42d-f405d3225a08&virtualmachineid=4f417cd8-055e-4efe-a466-3fba321f1666&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826859656
> 2013-05-06 18:50:27,578 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-1:null) VmStatsCollector is running...
> 2013-05-06 18:50:27,579 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-13:job-283) Executing
> org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd for job-283
> 2013-05-06 18:50:27,611 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-241:null) Seq 1-1011950818: Executing request
> 2013-05-06 18:50:27,674 INFO [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-13:job-283) Migrating VM[User|v] to
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(3)-Storage()]
> 2013-05-06 18:50:27,683 INFO [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-13:job-283) Source and destination host are not in same
> cluster, unable to migrate to host: 3
> 2013-05-06 18:50:27,729 ERROR [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-13:job-283) Unexpected exception while executing
> org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd
> com.cloud.utils.exception.CloudRuntimeException: Source and destination host
> are not in same cluster, unable to migrate to host: 3
> at
> com.cloud.vm.VirtualMachineManagerImpl.migrate(VirtualMachineManagerImpl.java:1357)
> at
> com.cloud.vm.UserVmManagerImpl.migrateVirtualMachine(UserVmManagerImpl.java:3535)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd.execute(MigrateVMCmd.java:147)
> 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)
> 2013-05-06 18:50:27,737 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-13:job-283) Complete async job-283, jobStatus: 2, resultCode:
> 530, result: Error Code: 530 Error text: Source and destination host are not
> in same cluster, unable to migrate to host: 3
> 2013-05-06 18:50:27,889 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-241:null) Vm cpu utilization 0.0039062499999999996
> 2013-05-06 18:50:27,891 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-241:null) Seq 1-1011950818: Response Received:
> 2013-05-06 18:50:27,891 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 1-1011950818: Received: { Ans: , MgmtId:
> 7363452993625, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2013-05-06 18:50:27,912 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-309:null) Seq 3-1946102639: Executing request
> 2013-05-06 18:50:28,153 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-309:null) Vm cpu utilization 0.0039062499999999996
> 2013-05-06 18:50:28,153 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-309:null) Vm cpu utilization 0.0039062499999999996
> 2013-05-06 18:50:28,153 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-309:null) Seq 3-1946102639: Response Received:
> 2013-05-06 18:50:28,154 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 3-1946102639: Received: { Ans: , MgmtId:
> 7363452993625, via: 3, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> ===START=== 10.252.242.121 -- GET
> command=findHostsForMigration&VirtualMachineId=4f417cd8-055e-4efe-a466-3fba321f1666&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826924517
> 2013-05-06 18:51:32,468 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-10:null) Checking pool: 1 for volume allocation
> [Vol[3|vm=3|ROOT]], maxSize : 11804569632768, totalAllocatedSize :
> 66748535808, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:51:32,542 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-10:null) Checking pool: 2 for volume allocation
> [Vol[3|vm=3|ROOT]], maxSize : 11804569632768, totalAllocatedSize :
> 73190986752, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:51:32,597 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-10:null) Checking pool: 1 for volume allocation
> [Vol[7|vm=3|DATADISK]], maxSize : 11804569632768, totalAllocatedSize :
> 66748535808, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:51:32,670 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-10:null) Checking pool: 2 for volume allocation
> [Vol[7|vm=3|DATADISK]], maxSize : 11804569632768, totalAllocatedSize :
> 73190986752, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:51:32,780 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-10:null) Checking pool: 3 for volume allocation
> [Vol[3|vm=3|ROOT]], maxSize : 11804569632768, totalAllocatedSize :
> 92518339584, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:51:32,866 DEBUG [cloud.storage.StorageManagerImpl]
> (catalina-exec-10:null) Checking pool: 3 for volume allocation
> [Vol[7|vm=3|DATADISK]], maxSize : 11804569632768, totalAllocatedSize :
> 92518339584, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:51:32,875 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-10:null) FirstFitAllocator has 2 hosts to check for
> allocation: [Host[-3-Routing], Host[-2-Routing]]
> 2013-05-06 18:51:32,882 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-10:null) Found 2 hosts for allocation after prioritization:
> [Host[-3-Routing], Host[-2-Routing]]
> 2013-05-06 18:51:32,882 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-10:null) Looking for speed=500Mhz, Ram=512
> 2013-05-06 18:51:32,892 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) Checking if host: 3 has enough capacity for requested
> CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
> 2013-05-06 18:51:32,896 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) Hosts's actual total CPU: 9580 and CPU after applying
> overprovisioning: 9580
> 2013-05-06 18:51:32,897 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) considerReservedCapacity isfalse , not considering
> reserved capacity for calculating free capacity
> 2013-05-06 18:51:32,897 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) Free CPU: 8480 , Requested CPU: 500
> 2013-05-06 18:51:32,897 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) Free RAM: 14982197248 , Requested RAM: 536870912
> 2013-05-06 18:51:32,897 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) Host has enough CPU and RAM available
> 2013-05-06 18:51:32,897 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) STATS: Can alloc CPU from host: 3, used: 1100,
> reserved: 0, actual total: 9580, total with overprovisioning: 9580; requested
> cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2013-05-06 18:51:32,897 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) STATS: Can alloc MEM from host: 3, used: 1207959552,
> reserved: 0, total: 16190156800; requested mem:
> 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2013-05-06 18:51:32,898 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-10:null) Found a suitable host, adding to list: 3
> 2013-05-06 18:51:32,907 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) Checking if host: 2 has enough capacity for requested
> CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
> 2013-05-06 18:51:32,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) Hosts's actual total CPU: 9576 and CPU after applying
> overprovisioning: 9576
> 2013-05-06 18:51:32,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) considerReservedCapacity isfalse , not considering
> reserved capacity for calculating free capacity
> 2013-05-06 18:51:32,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) Free CPU: 9076 , Requested CPU: 500
> 2013-05-06 18:51:32,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) Free RAM: 15921721344 , Requested RAM: 536870912
> 2013-05-06 18:51:32,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) Host has enough CPU and RAM available
> 2013-05-06 18:51:32,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) STATS: Can alloc CPU from host: 2, used: 500,
> reserved: 0, actual total: 9576, total with overprovisioning: 9576; requested
> cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2013-05-06 18:51:32,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (catalina-exec-10:null) STATS: Can alloc MEM from host: 2, used: 268435456,
> reserved: 0, total: 16190156800; requested mem:
> 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2013-05-06 18:51:32,913 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-10:null) Found a suitable host, adding to list: 2
> 2013-05-06 18:51:32,913 DEBUG [allocator.impl.FirstFitAllocator]
> (catalina-exec-10:null) Host Allocator returning 2 suitable hosts
> 2013-05-06 18:51:32,913 DEBUG [cloud.server.ManagementServerImpl]
> (catalina-exec-10:null) Hosts having capacity and suitable for migration:
> [Host[-3-Routing], Host[-2-Routing]]
> 2013-05-06 18:51:32,947 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null)
> ===END=== 10.252.242.121 -- GET
> command=findHostsForMigration&VirtualMachineId=4f417cd8-055e-4efe-a466-3fba321f1666&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826924517
> 2013-05-06 18:51:34,531 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 3 routers to update status.
> 2013-05-06 18:51:34,534 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-05-06 18:51:34,649 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 3 routers to update status.
> 2013-05-06 18:51:34,651 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-05-06 18:51:36,896 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null)
> ===START=== 10.252.242.121 -- GET
> command=migrateVirtualMachineWithVolume&hostid=180882a5-aa3e-4252-b42d-f405d3225a08&virtualmachineid=4f417cd8-055e-4efe-a466-3fba321f1666&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826929022
> 2013-05-06 18:51:36,953 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-44:job-284) Executing
> org.apache.cloudstack.api.command.admin.vm.MigrateVirtualMachineWithVolumeCmd
> for job-284
> 2013-05-06 18:51:36,955 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-1:null) submit async job-284, details: AsyncJobVO {id:284,
> userId: 2, accountId: 2, sessionKey: null, instanceType: None, instanceId:
> null, cmd:
> org.apache.cloudstack.api.command.admin.vm.MigrateVirtualMachineWithVolumeCmd,
> cmdOriginator: null, cmdInfo:
> {"response":"json","sessionkey":"cSc24xTjuz69EQZS4m5DA9c3Tpc\u003d","virtualmachineid":"4f417cd8-055e-4efe-a466-3fba321f1666","hostid":"180882a5-aa3e-4252-b42d-f405d3225a08","ctxUserId":"2","httpmethod":"GET","_":"1367826929022","ctxAccountId":"2","ctxStartEventId":"1341"},
> 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-05-06 18:51:36,959 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null)
> ===END=== 10.252.242.121 -- GET
> command=migrateVirtualMachineWithVolume&hostid=180882a5-aa3e-4252-b42d-f405d3225a08&virtualmachineid=4f417cd8-055e-4efe-a466-3fba321f1666&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826929022
> 2013-05-06 18:51:37,107 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-44:job-284) Checking pool: 3 for volume allocation
> [Vol[3|vm=3|ROOT]], maxSize : 11804569632768, totalAllocatedSize :
> 92518339584, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:51:37,207 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-44:job-284) Checking pool: 3 for volume allocation
> [Vol[7|vm=3|DATADISK]], maxSize : 11804569632768, totalAllocatedSize :
> 92518339584, askingSize : 0, allocated disable threshold: 0.85
> 2013-05-06 18:51:37,249 DEBUG [cloud.network.NetworkModelImpl]
> (Job-Executor-44:job-284) Service SecurityGroup is not supported in the
> network id=204
> 2013-05-06 18:51:37,256 DEBUG [cloud.storage.VolumeManagerImpl]
> (Job-Executor-44:job-284) Preparing 2 volumes for VM[User|v]
> 2013-05-06 18:51:37,398 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-44:job-284) VM state transitted from :Running to Migrating with
> event: MigrationRequestedvm's original host id: 1 new host id: 3 host id
> before state transition: 1
> 2013-05-06 18:51:37,412 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-44:job-284) Hosts's actual total CPU: 9580 and CPU after
> applying overprovisioning: 9580
> 2013-05-06 18:51:37,412 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-44:job-284) We are allocating VM, increasing the used capacity
> of this host:3
> 2013-05-06 18:51:37,412 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-44:job-284) Current Used CPU: 1100 , Free CPU:8480 ,Requested
> CPU: 500
> 2013-05-06 18:51:37,412 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-44:job-284) Current Used RAM: 1207959552 , Free RAM:14982197248
> ,Requested RAM: 536870912
> 2013-05-06 18:51:37,413 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-44:job-284) CPU STATS after allocation: for host: 3, old used:
> 1100, old reserved: 0, actual total: 9580, total with overprovisioning: 9580;
> new used:1600, reserved:0; requested cpu:500,alloc_from_last:false
> 2013-05-06 18:51:37,413 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-44:job-284) RAM STATS after allocation: for host: 3, old used:
> 1207959552, old reserved: 0, total: 16190156800; new used: 1744830464,
> reserved: 0; requested mem: 536870912,alloc_from_last:false
> 2013-05-06 18:51:37,543 DEBUG [agent.transport.Request]
> (Job-Executor-44:job-284) Seq 3-1946102642: Sending { Cmd , MgmtId:
> 7363452993625, via: 3, Ver: v1, Flags: 100111,
> [{"MigrateWithStorageReceiveCommand":{"vm":{"id":3,"name":"i-2-3-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"CentOS
> 5.3
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"b1861919b4daa27","params":{},"uuid":"4f417cd8-055e-4efe-a466-3fba321f1666","disks":[{"id":3,"name":"ROOT-3","mountPoint":"/export/home/automation/adv/primary","path":"d1dd1588-1d15-41fc-8cc7-9eb4b1ea9400","size":21474836480,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"55b65d1f-db5d-3b61-a01c-c2c285dbc469","deviceId":0},{"id":7,"name":"fsnap","mountPoint":"/export/home/automation/adv/primary","path":"0d735f7b-f237-4e83-8170-849944301d3b","size":21474836480,"type":"DATADISK","storagePoolType":"NetworkFilesystem","storagePoolUuid":"55b65d1f-db5d-3b61-a01c-c2c285dbc469","deviceId":1}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"49ab752f-4ed5-4bb8-9436-ba91f0cb0c91","ip":"10.1.1.25","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:1c:d3:00:01","dns1":"10.103.128.16","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1066","isolationUri":"vlan://1066","isSecurityGroupEnabled":false}]},"volumeToFiler":{"Vol[7|DATADISK|0d735f7b-f237-4e83-8170-849944301d3b|21474836480]":{"id":3,"uuid":"24cc9a0e-cf6c-30d7-9d17-5be24f28dbfc","host":"10.147.28.7","path":"/export/home/automation/adv/pri_2","port":2049,"type":"NetworkFilesystem"},"Vol[3|ROOT|d1dd1588-1d15-41fc-8cc7-9eb4b1ea9400|21474836480]":{"id":3,"uuid":"24cc9a0e-cf6c-30d7-9d17-5be24f28dbfc","host":"10.147.28.7","path":"/export/home/automation/adv/pri_2","port":2049,"type":"NetworkFilesystem"}},"wait":0}}]
> }
> 2013-05-06 18:51:37,545 DEBUG [agent.transport.Request]
> (Job-Executor-44:job-284) Seq 3-1946102642: Executing: { Cmd , MgmtId:
> 7363452993625, via: 3, Ver: v1, Flags: 100111,
> [{"MigrateWithStorageReceiveCommand":{"vm":{"id":3,"name":"i-2-3-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"CentOS
> 5.3
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"b1861919b4daa27","params":{},"uuid":"4f417cd8-055e-4efe-a466-3fba321f1666","disks":[{"id":3,"name":"ROOT-3","mountPoint":"/export/home/automation/adv/primary","path":"d1dd1588-1d15-41fc-8cc7-9eb4b1ea9400","size":21474836480,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"55b65d1f-db5d-3b61-a01c-c2c285dbc469","deviceId":0},{"id":7,"name":"fsnap","mountPoint":"/export/home/automation/adv/primary","path":"0d735f7b-f237-4e83-8170-849944301d3b","size":21474836480,"type":"DATADISK","storagePoolType":"NetworkFilesystem","storagePoolUuid":"55b65d1f-db5d-3b61-a01c-c2c285dbc469","deviceId":1}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"49ab752f-4ed5-4bb8-9436-ba91f0cb0c91","ip":"10.1.1.25","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:1c:d3:00:01","dns1":"10.103.128.16","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1066","isolationUri":"vlan://1066","isSecurityGroupEnabled":false}]},"volumeToFiler":{"Vol[7|DATADISK|0d735f7b-f237-4e83-8170-849944301d3b|21474836480]":{"id":3,"uuid":"24cc9a0e-cf6c-30d7-9d17-5be24f28dbfc","host":"10.147.28.7","path":"/export/home/automation/adv/pri_2","port":2049,"type":"NetworkFilesystem"},"Vol[3|ROOT|d1dd1588-1d15-41fc-8cc7-9eb4b1ea9400|21474836480]":{"id":3,"uuid":"24cc9a0e-cf6c-30d7-9d17-5be24f28dbfc","host":"10.147.28.7","path":"/export/home/automation/adv/pri_2","port":2049,"type":"NetworkFilesystem"}},"wait":0}}]
> }
> 2013-05-06 18:51:37,545 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-33:null) Seq 3-1946102642: Executing request
> 2013-05-06 18:51:37,640 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-33:null) SR retrieved for 24cc9a0e-cf6c-30d7-9d17-5be24f28dbfc
> 2013-05-06 18:51:37,653 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-33:null) Checking 24cc9a0e-cf6c-30d7-9d17-5be24f28dbfc or SR
> d6afa8fe-7efe-c1ef-c9c5-d2c291264a66 on
> XS[00764661-54a6-4d72-b9ae-fccd5d787eb8-10.147.40.20]
> 2013-05-06 18:51:37,669 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-33:null) SR retrieved for 24cc9a0e-cf6c-30d7-9d17-5be24f28dbfc
> 2013-05-06 18:51:37,681 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-33:null) Checking 24cc9a0e-cf6c-30d7-9d17-5be24f28dbfc or SR
> d6afa8fe-7efe-c1ef-c9c5-d2c291264a66 on
> XS[00764661-54a6-4d72-b9ae-fccd5d787eb8-10.147.40.20]
> 2013-05-06 18:51:37,740 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-33:null) Found a network called
> VLAN-3bdb6062-aff5-a3e9-b3c6-724289b3c0b5-1066 on host=10.147.40.20;
> Network=13b75a5a-cd83-b72c-63bb-175d14cf7244;
> pif=5b5d507e-e03a-3d92-a38d-0cffe00a9cf2
> 2013-05-06 18:51:37,786 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-33:null) Seq 3-1946102642: Response Received:
> 2013-05-06 18:51:37,787 DEBUG [agent.transport.Request] (DirectAgent-33:null)
> Seq 3-1946102642: Processing: { Ans: , MgmtId: 7363452993625, via: 3, Ver:
> v1, Flags: 110,
> [{"MigrateWithStorageReceiveAnswer":{"volumeToSr":{"Vol[7|DATADISK|0d735f7b-f237-4e83-8170-849944301d3b|21474836480]":{"ref":"OpaqueRef:8ad4a2c1-c0ba-6581-fc1a-428898e9808c"},"Vol[3|ROOT|d1dd1588-1d15-41fc-8cc7-9eb4b1ea9400|21474836480]":{"ref":"OpaqueRef:8ad4a2c1-c0ba-6581-fc1a-428898e9808c"}},"nicToNetwork":{"[Nic:Guest-10.1.1.25-vlan://1066]":{"ref":"OpaqueRef:e67419ed-5ab7-96c3-8c4b-f4919c71da1d"}},"token":{"session_id":"OpaqueRef:1eefb328-9af3-7e95-065b-5e37cc39f2c9","host":"OpaqueRef:66683eb7-0651-0ce8-4a2b-674f8a64b70b","SM":"http://10.147.40.20/services/SM?session_id=OpaqueRef:1eefb328-9af3-7e95-065b-5e37cc39f2c9","master":"http://10.147.40.20/","xenops":"http://10.147.40.20/services/xenops?session_id=OpaqueRef:1eefb328-9af3-7e95-065b-5e37cc39f2c9"},"result":true,"wait":0}}]
> }
> 2013-05-06 18:51:37,788 DEBUG [agent.transport.Request]
> (Job-Executor-44:job-284) Seq 3-1946102642: Received: { Ans: , MgmtId:
> 7363452993625, via: 3, Ver: v1, Flags: 110, { MigrateWithStorageReceiveAnswer
> } }
> 2013-05-06 18:51:37,793 DEBUG [agent.transport.Request]
> (Job-Executor-44:job-284) Seq 1-1011950821: Sending { Cmd , MgmtId:
> 7363452993625, via: 1, Ver: v1, Flags: 100111,
> [{"MigrateWithStorageSendCommand":{"vm":{"id":3,"name":"i-2-3-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"CentOS
> 5.3
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"b1861919b4daa27","params":{},"uuid":"4f417cd8-055e-4efe-a466-3fba321f1666","disks":[{"id":3,"name":"ROOT-3","mountPoint":"/export/home/automation/adv/primary","path":"d1dd1588-1d15-41fc-8cc7-9eb4b1ea9400","size":21474836480,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"55b65d1f-db5d-3b61-a01c-c2c285dbc469","deviceId":0},{"id":7,"name":"fsnap","mountPoint":"/export/home/automation/adv/primary","path":"0d735f7b-f237-4e83-8170-849944301d3b","size":21474836480,"type":"DATADISK","storagePoolType":"NetworkFilesystem","storagePoolUuid":"55b65d1f-db5d-3b61-a01c-c2c285dbc469","deviceId":1}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"49ab752f-4ed5-4bb8-9436-ba91f0cb0c91","ip":"10.1.1.25","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:1c:d3:00:01","dns1":"10.103.128.16","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1066","isolationUri":"vlan://1066","isSecurityGroupEnabled":false}]},"volumeToSr":{"Vol[7|DATADISK|0d735f7b-f237-4e83-8170-849944301d3b|21474836480]":{"ref":"OpaqueRef:8ad4a2c1-c0ba-6581-fc1a-428898e9808c"},"Vol[3|ROOT|d1dd1588-1d15-41fc-8cc7-9eb4b1ea9400|21474836480]":{"ref":"OpaqueRef:8ad4a2c1-c0ba-6581-fc1a-428898e9808c"}},"nicToNetwork":{"[Nic:Guest-10.1.1.25-vlan://1066]":{"ref":"OpaqueRef:e67419ed-5ab7-96c3-8c4b-f4919c71da1d"}},"token":{"session_id":"OpaqueRef:1eefb328-9af3-7e95-065b-5e37cc39f2c9","host":"OpaqueRef:66683eb7-0651-0ce8-4a2b-674f8a64b70b","SM":"http://10.147.40.20/services/SM?session_id=OpaqueRef:1eefb328-9af3-7e95-065b-5e37cc39f2c9","master":"http://10.147.40.20/","xenops":"http://10.147.40.20/services/xenops?session_id=OpaqueRef:1eefb328-9af3-7e95-065b-5e37cc39f2c9"},"wait":0}}]
> }
> 2013-05-06 18:51:37,793 DEBUG [agent.manager.AgentAttache]
> (DirectAgent-33:null) Seq 3-1946102642: No more commands found
> 2013-05-06 18:51:37,795 DEBUG [agent.transport.Request]
> (Job-Executor-44:job-284) Seq 1-1011950821: Executing: { Cmd , MgmtId:
> 7363452993625, via: 1, Ver: v1, Flags: 100111,
> [{"MigrateWithStorageSendCommand":{"vm":{"id":3,"name":"i-2-3-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"CentOS
> 5.3
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"b1861919b4daa27","params":{},"uuid":"4f417cd8-055e-4efe-a466-3fba321f1666","disks":[{"id":3,"name":"ROOT-3","mountPoint":"/export/home/automation/adv/primary","path":"d1dd1588-1d15-41fc-8cc7-9eb4b1ea9400","size":21474836480,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"55b65d1f-db5d-3b61-a01c-c2c285dbc469","deviceId":0},{"id":7,"name":"fsnap","mountPoint":"/export/home/automation/adv/primary","path":"0d735f7b-f237-4e83-8170-849944301d3b","size":21474836480,"type":"DATADISK","storagePoolType":"NetworkFilesystem","storagePoolUuid":"55b65d1f-db5d-3b61-a01c-c2c285dbc469","deviceId":1}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"49ab752f-4ed5-4bb8-9436-ba91f0cb0c91","ip":"10.1.1.25","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:1c:d3:00:01","dns1":"10.103.128.16","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1066","isolationUri":"vlan://1066","isSecurityGroupEnabled":false}]},"volumeToSr":{"Vol[7|DATADISK|0d735f7b-f237-4e83-8170-849944301d3b|21474836480]":{"ref":"OpaqueRef:8ad4a2c1-c0ba-6581-fc1a-428898e9808c"},"Vol[3|ROOT|d1dd1588-1d15-41fc-8cc7-9eb4b1ea9400|21474836480]":{"ref":"OpaqueRef:8ad4a2c1-c0ba-6581-fc1a-428898e9808c"}},"nicToNetwork":{"[Nic:Guest-10.1.1.25-vlan://1066]":{"ref":"OpaqueRef:e67419ed-5ab7-96c3-8c4b-f4919c71da1d"}},"token":{"session_id":"OpaqueRef:1eefb328-9af3-7e95-065b-5e37cc39f2c9","host":"OpaqueRef:66683eb7-0651-0ce8-4a2b-674f8a64b70b","SM":"http://10.147.40.20/services/SM?session_id=OpaqueRef:1eefb328-9af3-7e95-065b-5e37cc39f2c9","master":"http://10.147.40.20/","xenops":"http://10.147.40.20/services/xenops?session_id=OpaqueRef:1eefb328-9af3-7e95-065b-5e37cc39f2c9"},"wait":0}}]
> }
> 2013-05-06 18:51:37,795 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-425:null) Seq 1-1011950821: Executing request
> 2013-05-06 18:51:40,019 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null)
> ===START=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826932151
> 2013-05-06 18:51:40,054 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null)
> ===END=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826932151
> 2013-05-06 18:51:42,762 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-33:null) Ping from 1
> 2013-05-06 18:51:43,022 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null)
> ===START=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826935151
> 2013-05-06 18:51:43,058 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null)
> ===END=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826935151
> 2013-05-06 18:51:43,382 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-8:null) Ping from 7
> 2013-05-06 18:51:43,861 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-179:null) Seq 1-1011941380: Executing request
> 2013-05-06 18:51:44,130 WARN [xen.resource.CitrixResourceBase]
> (DirectAgent-179:null) Ignoring vm i-2-3-VM because of a lag in stopping the
> vm.
> 2013-05-06 18:51:44,131 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-179:null) Seq 1-1011941380: Response Received:
> 2013-05-06 18:51:44,132 DEBUG [agent.transport.Request]
> (DirectAgent-179:null) Seq 1-1011941380: Processing: { Ans: , MgmtId:
> 7363452993625, via: 1, Ver: v1, Flags: 10,
> [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}]
> }
> 2013-05-06 18:51:46,020 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null)
> ===START=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826938151
> 2013-05-06 18:51:46,056 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null)
> ===END=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826938151
> 2013-05-06 18:51:49,024 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null)
> ===START=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826941152
> 2013-05-06 18:51:49,058 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null)
> ===END=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826941152
> 2013-05-06 18:51:52,031 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null)
> ===START=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826944153
> 2013-05-06 18:51:52,065 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null)
> ===END=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826944153
> 2013-05-06 18:51:55,060 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null)
> ===START=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826947155
> 2013-05-06 18:51:55,095 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null)
> ===END=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826947155
> 2013-05-06 18:51:56,433 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-1:null) HostStatsCollector is running...
> 2013-05-06 18:51:56,448 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-493:null) Seq 1-1011950822: Executing request
> 2013-05-06 18:51:56,683 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-493:null) Seq 1-1011950822: Response Received:
> 2013-05-06 18:51:56,684 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 1-1011950822: Received: { Ans: , MgmtId:
> 7363452993625, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-05-06 18:51:56,695 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-211:null) Seq 2-1149048187: Executing request
> 2013-05-06 18:51:56,786 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-2:null) StorageCollector is running...
> 2013-05-06 18:51:56,848 DEBUG [agent.transport.Request]
> (StatsCollector-2:null) Seq 7-483140689: Received: { Ans: , MgmtId:
> 7363452993625, via: 7, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2013-05-06 18:51:56,946 DEBUG [agent.transport.Request]
> (StatsCollector-2:null) Seq 7-483140690: Received: { Ans: , MgmtId:
> 7363452993625, via: 7, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2013-05-06 18:51:57,113 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-211:null) Seq 2-1149048187: Response Received:
> 2013-05-06 18:51:57,114 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 2-1149048187: Received: { Ans: , MgmtId:
> 7363452993625, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-05-06 18:51:57,125 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-244:null) Seq 3-1946102643: Executing request
> 2013-05-06 18:51:57,348 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-244:null) Seq 3-1946102643: Response Received:
> 2013-05-06 18:51:57,349 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 3-1946102643: Received: { Ans: , MgmtId:
> 7363452993625, via: 3, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-05-06 18:51:58,034 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null)
> ===START=== 10.252.242.121 -- GET
> command=queryAsyncJobResult&jobId=974c8445-3958-44a9-9b92-fdfe5236a0b1&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367826950155
> ^C
> [root@auto-tc ~]#
--
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
