You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Pranav Saxena (JIRA)" <ji...@apache.org> on 2013/06/21 20:58:23 UTC

[jira] [Resolved] (CLOUDSTACK-2336) UI: SXM : wrong API is being called while trying to migrate a VM with volume

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

Pranav Saxena resolved CLOUDSTACK-2336.
---------------------------------------

    Resolution: Fixed

Fixed by Jessica and hence marking it as Resolved. 
                
> 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: Jessica Wang
>            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