You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Srikanteswararao Talluri (JIRA)" <ji...@apache.org> on 2013/05/06 10:58:16 UTC
[jira] [Commented] (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:comment-tabpanel&focusedCommentId=13649602#comment-13649602 ]
Srikanteswararao Talluri commented on CLOUDSTACK-2336:
------------------------------------------------------
Following log is where 'findHostForMigration' returned a host with 'requiredstoragemigration' as false, UI is calling 'migrateVirtualMachineWithVolume'
===START=== 10.252.242.121 -- GET command=findHostsForMigration&VirtualMachineId=959a1f08-a6cd-4e2c-9ebc-0c91e66e4d1a&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367830196510
2013-05-06 19:46:04,428 DEBUG [cloud.storage.StorageManagerImpl] (catalina-exec-21:null) Checking pool: 1 for volume allocation [Vol[5|vm=5|ROOT]], maxSize : 11804569632768, totalAllocatedSize : 66748535808, askingSize : 0, allocated disable threshold: 0.85
2013-05-06 19:46:04,503 DEBUG [cloud.storage.StorageManagerImpl] (catalina-exec-21:null) Checking pool: 2 for volume allocation [Vol[5|vm=5|ROOT]], maxSize : 11804569632768, totalAllocatedSize : 73190986752, askingSize : 0, allocated disable threshold: 0.85
2013-05-06 19:46:04,531 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 3 routers to update status.
2013-05-06 19:46:04,539 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-05-06 19:46:04,566 DEBUG [cloud.storage.StorageManagerImpl] (catalina-exec-21:null) Checking pool: 1 for volume allocation [Vol[8|vm=5|DATADISK]], maxSize : 11804569632768, totalAllocatedSize : 66748535808, askingSize : 0, allocated disable threshold: 0.85
2013-05-06 19:46:04,638 DEBUG [cloud.storage.StorageManagerImpl] (catalina-exec-21:null) Checking pool: 2 for volume allocation [Vol[8|vm=5|DATADISK]], maxSize : 11804569632768, totalAllocatedSize : 73190986752, askingSize : 0, allocated disable threshold: 0.85
2013-05-06 19:46:04,648 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 3 routers to update status.
2013-05-06 19:46:04,655 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-05-06 19:46:04,740 DEBUG [cloud.storage.StorageManagerImpl] (catalina-exec-21:null) Checking pool: 3 for volume allocation [Vol[5|vm=5|ROOT]], maxSize : 11804569632768, totalAllocatedSize : 114530046976, askingSize : 0, allocated disable threshold: 0.85
2013-05-06 19:46:04,837 DEBUG [cloud.storage.StorageManagerImpl] (catalina-exec-21:null) Checking pool: 3 for volume allocation [Vol[8|vm=5|DATADISK]], maxSize : 11804569632768, totalAllocatedSize : 114530046976, askingSize : 0, allocated disable threshold: 0.85
2013-05-06 19:46:04,846 DEBUG [allocator.impl.FirstFitAllocator] (catalina-exec-21:null) FirstFitAllocator has 2 hosts to check for allocation: [Host[-3-Routing], Host[-1-Routing]]
2013-05-06 19:46:04,853 DEBUG [allocator.impl.FirstFitAllocator] (catalina-exec-21:null) Found 2 hosts for allocation after prioritization: [Host[-3-Routing], Host[-1-Routing]]
2013-05-06 19:46:04,853 DEBUG [allocator.impl.FirstFitAllocator] (catalina-exec-21:null) Looking for speed=500Mhz, Ram=512
2013-05-06 19:46:04,862 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) Checking if host: 3 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2013-05-06 19:46:04,867 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) Hosts's actual total CPU: 9580 and CPU after applying overprovisioning: 9580
2013-05-06 19:46:04,867 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) considerReservedCapacity isfalse , not considering reserved capacity for calculating free capacity
2013-05-06 19:46:04,867 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) Free CPU: 8480 , Requested CPU: 500
2013-05-06 19:46:04,867 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) Free RAM: 14982197248 , Requested RAM: 536870912
2013-05-06 19:46:04,867 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) Host has enough CPU and RAM available
2013-05-06 19:46:04,868 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21: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 19:46:04,868 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21: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 19:46:04,868 DEBUG [allocator.impl.FirstFitAllocator] (catalina-exec-21:null) Found a suitable host, adding to list: 3
2013-05-06 19:46:04,877 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2013-05-06 19:46:04,881 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) Hosts's actual total CPU: 9576 and CPU after applying overprovisioning: 9576
2013-05-06 19:46:04,881 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) considerReservedCapacity isfalse , not considering reserved capacity for calculating free capacity
2013-05-06 19:46:04,881 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) Free CPU: 9076 , Requested CPU: 500
2013-05-06 19:46:04,882 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) Free RAM: 15116414976 , Requested RAM: 536870912
2013-05-06 19:46:04,882 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) Host has enough CPU and RAM available
2013-05-06 19:46:04,882 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) STATS: Can alloc CPU from host: 1, used: 500, reserved: 0, actual total: 9576, total with overprovisioning: 9576; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: false
2013-05-06 19:46:04,882 DEBUG [cloud.capacity.CapacityManagerImpl] (catalina-exec-21:null) STATS: Can alloc MEM from host: 1, used: 1073741824, reserved: 0, total: 16190156800; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: false
2013-05-06 19:46:04,882 DEBUG [allocator.impl.FirstFitAllocator] (catalina-exec-21:null) Found a suitable host, adding to list: 1
2013-05-06 19:46:04,882 DEBUG [allocator.impl.FirstFitAllocator] (catalina-exec-21:null) Host Allocator returning 2 suitable hosts
2013-05-06 19:46:04,882 DEBUG [cloud.server.ManagementServerImpl] (catalina-exec-21:null) Hosts having capacity and suitable for migration: [Host[-3-Routing], Host[-1-Routing]]
2013-05-06 19:46:04,897 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===END=== 10.252.242.121 -- GET command=findHostsForMigration&VirtualMachineId=959a1f08-a6cd-4e2c-9ebc-0c91e66e4d1a&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367830196510
2013-05-06 19:46:13,179 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===START=== 10.252.242.121 -- GET command=migrateVirtualMachineWithVolume&hostid=5f6b0dc2-bf83-43ea-88b1-239a6bf2d4ea&virtualmachineid=959a1f08-a6cd-4e2c-9ebc-0c91e66e4d1a&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367830205391
2013-05-06 19:46:13,225 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-58:job-298) Executing org.apache.cloudstack.api.command.admin.vm.MigrateVirtualMachineWithVolumeCmd for job-298
2013-05-06 19:46:13,227 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-5:null) submit async job-298, details: AsyncJobVO {id:298, 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":"959a1f08-a6cd-4e2c-9ebc-0c91e66e4d1a","hostid":"5f6b0dc2-bf83-43ea-88b1-239a6bf2d4ea","ctxUserId":"2","httpmethod":"GET","_":"1367830205391","ctxAccountId":"2","ctxStartEventId":"1385"}, 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 19:46:13,234 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===END=== 10.252.242.121 -- GET command=migrateVirtualMachineWithVolume&hostid=5f6b0dc2-bf83-43ea-88b1-239a6bf2d4ea&virtualmachineid=959a1f08-a6cd-4e2c-9ebc-0c91e66e4d1a&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367830205391
2013-05-06 19:46:13,282 ERROR [cloud.async.AsyncJobManagerImpl] (Job-Executor-58:job-298) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.MigrateVirtualMachineWithVolumeCmd
com.cloud.exception.InvalidParameterValueException: Migration of the vm VM[User|p]from host Host[-2-Routing] to destination host Host[-1-Routing] doesn't involve migrating the volumes.
at com.cloud.vm.UserVmManagerImpl.migrateVirtualMachineWithVolume(UserVmManagerImpl.java:3613)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.admin.vm.MigrateVirtualMachineWithVolumeCmd.execute(MigrateVirtualMachineWithVolumeCmd.java:137)
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 19:46:13,284 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-58:job-298) Complete async job-298, jobStatus: 2, resultCode: 530, result: Error Code: 530 Error text: Migration of the vm VM[User|p]from host Host[-2-Routing] to destination host Host[-1-Routing] doesn't involve migrating the volumes.
2013-05-06 19:46:14,186 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-05-06 19:46:14,247 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 7-483140808: Received: { Ans: , MgmtId: 7363452993625, via: 7, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-05-06 19:46:14,342 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 7-483140809: Received: { Ans: , MgmtId: 7363452993625, via: 7, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-05-06 19:46:16,282 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===START=== 10.252.242.121 -- GET command=queryAsyncJobResult&jobId=083daec1-ba61-44d6-9629-9bc4870f753b&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367830208491
2013-05-06 19:46:16,302 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-15:null) Async job-298 completed
2013-05-06 19:46:16,315 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===END=== 10.252.242.121 -- GET command=queryAsyncJobResult&jobId=083daec1-ba61-44d6-9629-9bc4870f753b&response=json&sessionkey=cSc24xTjuz69EQZS4m5DA9c3Tpc%3D&_=1367830208491
2013-05-06 19:46:19,080 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-124:null) Ping from 2
2013-05-06 19:46:23,431 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-451:null) Ping from 3
2013-05-06 19:46:24,441 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-124:null) Seq 3-1946091524: Executing request
2013-05-06 19:46:24,713 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-124:null) Seq 3-1946091524: Response Received:
2013-05-06 19:46:24,715 DEBUG [agent.transport.Request] (DirectAgent-124: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 19:46:30,899 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 6
2013-05-06 19:46:31,095 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-05-06 19:46:31,497 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-05-06 19:46:31,542 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-451:null) Seq 2-1149042694: Executing request
2013-05-06 19:46:31,703 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-451:null) Seq 2-1149042694: Response Received:
2013-05-06 19:46:31,704 DEBUG [agent.transport.Request] (DirectAgent-451:null) Seq 2-1149042694: Processing: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 10, [{"Answer":{"result":true,"wait":0}}] }
2013-05-06 19:46:34,531 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 3 routers to update status.
2013-05-06 19:46:34,534 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-05-06 19:46:34,648 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 3 routers to update status.
2013-05-06 19:46:34,650 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
^C
> 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