You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Harikrishna Patnala (JIRA)" <ji...@apache.org> on 2013/07/04 10:35:19 UTC
[jira] [Updated] (CLOUDSTACK-3354) [automation] scale up VM is
failing
[ https://issues.apache.org/jira/browse/CLOUDSTACK-3354?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Harikrishna Patnala updated CLOUDSTACK-3354:
--------------------------------------------
Status: Ready To Review (was: In Progress)
> [automation] scale up VM is failing
> -----------------------------------
>
> Key: CLOUDSTACK-3354
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3354
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: Management Server
> Affects Versions: 4.2.0
> Environment: xenserver 6.1
> Reporter: Srikanteswararao Talluri
> Assignee: Harikrishna Patnala
> Priority: Blocker
> Fix For: 4.2.0
>
>
> Steps to reproduce:
> 1. create instance with tiny instance.
> 2. mount xstools iso
> 3. install xen pv drivers <mountpoint>/Linux/install.sh
> 4. Scaleup the vm created in step 1 to a big instance.
> 2013-07-04 15:52:22,664 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===START=== 10.101.255.52 -- GET command=scaleVirtualMachine&id=adf50367-09ae-447d-9954-44f2e767e3de&serviceofferingid=31381d8f-445b-4e89-86d1-0c5903d8e4ad&response=json&sessionkey=CS5Ro9Vvbhn2TB1iTqjoB1s4lfQ%3D&_=1372913891906
> 2013-07-04 15:52:22,679 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-6:null) ControlledEntity name is:com.cloud.vm.VirtualMachine
> 2013-07-04 15:52:22,683 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-6:null) ControlledEntity name is:com.cloud.uservm.UserVm
> 2013-07-04 15:52:22,685 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-6:null) ControlledEntity name is:com.cloud.network.router.VirtualRouter
> 2013-07-04 15:52:22,690 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-6:null) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
> 2013-07-04 15:52:22,743 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-6:null) submit async job-926, details: AsyncJobVO {id:926, userId: 2, accountId: 2, sessionKey: null, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.user.vm.ScaleVMCmd, cmdOriginator: null, cmdInfo: {"id":"adf50367-09ae-447d-9954-44f2e767e3de","response":"json","sessionkey":"CS5Ro9Vvbhn2TB1iTqjoB1s4lfQ\u003d","serviceofferingid":"31381d8f-445b-4e89-86d1-0c5903d8e4ad","ctxUserId":"2","httpmethod":"GET","_":"1372913891906","ctxAccountId":"2","ctxStartEventId":"4321"}, 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-07-04 15:52:22,747 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===END=== 10.101.255.52 -- GET command=scaleVirtualMachine&id=adf50367-09ae-447d-9954-44f2e767e3de&serviceofferingid=31381d8f-445b-4e89-86d1-0c5903d8e4ad&response=json&sessionkey=CS5Ro9Vvbhn2TB1iTqjoB1s4lfQ%3D&_=1372913891906
> 2013-07-04 15:52:22,771 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-38:job-926) Executing org.apache.cloudstack.api.command.user.vm.ScaleVMCmd for job-926
> 2013-07-04 15:52:22,782 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-38:job-926) ControlledEntity name is:com.cloud.vm.VirtualMachine
> 2013-07-04 15:52:22,785 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-38:job-926) ControlledEntity name is:com.cloud.uservm.UserVm
> 2013-07-04 15:52:22,787 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-38:job-926) ControlledEntity name is:com.cloud.network.router.VirtualRouter
> 2013-07-04 15:52:22,790 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-38:job-926) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
> 2013-07-04 15:52:22,859 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Checking if host: 1 has enough capacity for requested CPU: 0 and requested RAM: 402653184 , cpuOverprovisioningFactor: 1.0
> 2013-07-04 15:52:22,864 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total CPU: 9576 and CPU after applying overprovisioning: 9576
> 2013-07-04 15:52:22,864 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) considerReservedCapacity isfalse , not considering reserved capacity for calculating free capacity
> 2013-07-04 15:52:22,864 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Free CPU: 7576 , Requested CPU: 0
> 2013-07-04 15:52:22,865 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Free RAM: 14982197248 , Requested RAM: 402653184
> 2013-07-04 15:52:22,865 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Host has enough CPU and RAM available
> 2013-07-04 15:52:22,865 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) STATS: Can alloc CPU from host: 1, used: 2000, reserved: 0, actual total: 9576, total with overprovisioning: 9576; requested cpu:0,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2013-07-04 15:52:22,865 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) STATS: Can alloc MEM from host: 1, used: 1207959552, reserved: 0, total: 16190156800; requested mem: 402653184,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2013-07-04 15:52:22,905 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total CPU: 9576 and CPU after applying overprovisioning: 9576
> 2013-07-04 15:52:22,906 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total RAM: 16190157312 and RAM after applying overprovisioning: 16190156800
> 2013-07-04 15:52:22,906 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) release cpu from host: 1, old used: 2000,reserved: 0, actual total: 9576, total with overprovisioning: 9576; new used: 1900,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-04 15:52:22,906 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) release mem from host: 1, old used: 1207959552,reserved: 0, total: 16190156800; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-04 15:52:22,925 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total CPU: 9576 and CPU after applying overprovisioning: 9576
> 2013-07-04 15:52:22,925 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) We are allocating VM, increasing the used capacity of this host:1
> 2013-07-04 15:52:22,925 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Current Used CPU: 1900 , Free CPU:7676 ,Requested CPU: 100
> 2013-07-04 15:52:22,925 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Current Used RAM: 1073741824 , Free RAM:15116414976 ,Requested RAM: 536870912
> 2013-07-04 15:52:22,925 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) CPU STATS after allocation: for host: 1, old used: 1900, old reserved: 0, actual total: 9576, total with overprovisioning: 9576; new used:2000, reserved:0; requested cpu:100,alloc_from_last:false
> 2013-07-04 15:52:22,925 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) RAM STATS after allocation: for host: 1, old used: 1073741824, old reserved: 0, total: 16190156800; new used: 1610612736, reserved: 0; requested mem: 536870912,alloc_from_last:false
> 2013-07-04 15:52:22,935 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 1-1227952754: Sending { Cmd , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 100111, [{"ScaleVmCommand":{"vm":{"id":1,"name":"i-2-250-QA","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":536870912,"maxRam":536870912,"rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false},"vmName":"i-2-250-QA","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":536870912,"maxRam":536870912,"wait":0}}] }
> 2013-07-04 15:52:22,936 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 1-1227952754: Executing: { Cmd , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 100111, [{"ScaleVmCommand":{"vm":{"id":1,"name":"i-2-250-QA","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":536870912,"maxRam":536870912,"rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false},"vmName":"i-2-250-QA","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":536870912,"maxRam":536870912,"wait":0}}] }
> 2013-07-04 15:52:22,936 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-485:null) Seq 1-1227952754: Executing request
> 2013-07-04 15:52:23,045 WARN [xen.resource.CitrixResourceBase] (DirectAgent-485:null) Unable to upgrade i-2-250-QA due to Unable to Scale the vm: i-2-250-QAas vm does not have xs tools to support dynamic scaling
> com.cloud.utils.exception.CloudRuntimeException: Unable to Scale the vm: i-2-250-QAas vm does not have xs tools to support dynamic scaling
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:684)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:626)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:73)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:102)
> at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
> 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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
> 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-07-04 15:52:23,058 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-485:null) Seq 1-1227952754: Response Received:
> 2013-07-04 15:52:23,059 DEBUG [agent.transport.Request] (DirectAgent-485:null) Seq 1-1227952754: Processing: { Ans: , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 110, [{"ScaleVmAnswer":{"result":false,"details":"Unable to upgrade i-2-250-QA due to Unable to Scale the vm: i-2-250-QAas vm does not have xs tools to support dynamic scaling","wait":0}}] }
> 2013-07-04 15:52:23,059 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 1-1227952754: Received: { Ans: , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 110, { ScaleVmAnswer } }
> 2013-07-04 15:52:23,059 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-38:job-926) Unable to scale vm due to Unable to upgrade i-2-250-QA due to Unable to Scale the vm: i-2-250-QAas vm does not have xs tools to support dynamic scaling
> 2013-07-04 15:52:23,064 DEBUG [agent.manager.AgentAttache] (DirectAgent-485:null) Seq 1-1227952754: No more commands found
> 2013-07-04 15:52:23,072 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total CPU: 9576 and CPU after applying overprovisioning: 9576
> 2013-07-04 15:52:23,072 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total RAM: 16190157312 and RAM after applying overprovisioning: 16190156800
> 2013-07-04 15:52:23,072 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) release cpu from host: 1, old used: 2000,reserved: 0, actual total: 9576, total with overprovisioning: 9576; new used: 1900,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-04 15:52:23,072 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) release mem from host: 1, old used: 1610612736,reserved: 0, total: 16190156800; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-04 15:52:23,092 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total CPU: 9576 and CPU after applying overprovisioning: 9576
> 2013-07-04 15:52:23,093 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) We are allocating VM, increasing the used capacity of this host:1
> 2013-07-04 15:52:23,093 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Current Used CPU: 1900 , Free CPU:7676 ,Requested CPU: 100
> 2013-07-04 15:52:23,093 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Current Used RAM: 1073741824 , Free RAM:15116414976 ,Requested RAM: 134217728
> 2013-07-04 15:52:23,093 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) CPU STATS after allocation: for host: 1, old used: 1900, old reserved: 0, actual total: 9576, total with overprovisioning: 9576; new used:2000, reserved:0; requested cpu:100,alloc_from_last:false
> 2013-07-04 15:52:23,093 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) RAM STATS after allocation: for host: 1, old used: 1073741824, old reserved: 0, total: 16190156800; new used: 1207959552, reserved: 0; requested mem: 134217728,alloc_from_last:false
> 2013-07-04 15:52:23,101 WARN [cloud.vm.UserVmManagerImpl] (Job-Executor-38:job-926) Received exception while scaling
> com.cloud.utils.exception.CloudRuntimeException: Unable to scale vm due to Unable to upgrade i-2-250-QA due to Unable to Scale the vm: i-2-250-QAas vm does not have xs tools to support dynamic scaling
> at com.cloud.vm.VirtualMachineManagerImpl.reConfigureVm(VirtualMachineManagerImpl.java:3265)
> at com.cloud.vm.UserVmManagerImpl.upgradeVirtualMachine(UserVmManagerImpl.java:1217)
> at com.cloud.vm.UserVmManagerImpl.upgradeVirtualMachine(UserVmManagerImpl.java:1090)
> at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at org.apache.cloudstack.api.command.user.vm.ScaleVMCmd.execute(ScaleVMCmd.java:92)
> 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-07-04 15:52:23,162 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Deploy avoids pods: null, clusters: null, hosts: [1]
> 2013-07-04 15:52:23,166 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_3bfcabe3@dcd88ea
> 2013-07-04 15:52:23,166 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 100, requested ram: 536870912
> 2013-07-04 15:52:23,166 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Is ROOT volume READY (pool already allocated)?: No
> 2013-07-04 15:52:23,166 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) This VM has last host_id specified, trying to choose the same host: 1
> 2013-07-04 15:52:23,168 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) The last host of this VM is in avoid set
> 2013-07-04 15:52:23,168 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Cannot choose the last host to deploy this VM
> 2013-07-04 15:52:23,168 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-38:job-926) Searching resources only under specified Cluster: 1
> 2013-07-04 15:52:23,182 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Checking resources in Cluster: 1 under Pod: 1
> 2013-07-04 15:52:23,187 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
> 2013-07-04 15:52:23,195 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-38:job-926 FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-2-Routing], Host[-1-Routing]]
> 2013-07-04 15:52:23,202 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-2-Routing], Host[-1-Routing]]
> 2013-07-04 15:52:23,202 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Looking for speed=100Mhz, Ram=512
> 2013-07-04 15:52:23,211 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Checking if host: 2 has enough capacity for requested CPU: 100 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
> 2013-07-04 15:52:23,215 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Hosts's actual total CPU: 9592 and CPU after applying overprovisioning: 9592
> 2013-07-04 15:52:23,215 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Free CPU: 6892 , Requested CPU: 100
> 2013-07-04 15:52:23,215 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Free RAM: 14176890880 , Requested RAM: 536870912
> 2013-07-04 15:52:23,215 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2013-07-04 15:52:23,216 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 2, used: 2700, reserved: 0, actual total: 9592, total with overprovisioning: 9592; requested cpu:100,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2013-07-04 15:52:23,216 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 2, used: 2013265920, reserved: 0, total: 16190156800; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2013-07-04 15:52:23,216 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Found a suitable host, adding to list: 2
> 2013-07-04 15:52:23,216 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Host name: Rack1Pod1Host15, hostId: 1 is in avoid set, skipping this and trying other available hosts
> 2013-07-04 15:52:23,216 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-38:job-926 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
> 2013-07-04 15:52:23,219 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Checking suitable pools for volume (Id, Type): (310,ROOT)
> 2013-07-04 15:52:23,219 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) We need to allocate new storagepool for this volume
> 2013-07-04 15:52:23,227 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Calling StoragePoolAllocators to find suitable pools
> 2013-07-04 15:52:23,234 DEBUG [storage.allocator.LocalStoragePoolAllocator] (Job-Executor-38:job-926) LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2013-07-04 15:52:23,234 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-38:job-926) ClusterScopeStoragePoolAllocator looking for storage pool
> 2013-07-04 15:52:23,235 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-38:job-926) Looking for pools in dc: 1 pod:1 cluster:1
> 2013-07-04 15:52:23,242 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-38:job-926) Checking if storage pool is suitable, name: null ,poolId: 1
> 2013-07-04 15:52:23,249 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-38:job-926) Checking pool 1 for storage, totalSize: 1759218630656, usedBytes: 1443518676992, usedPct: 0.8205453556694783, disable threshold: 0.85
> 2013-07-04 15:52:23,308 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-38:job-926) Checking pool: 1 for volume allocation [Vol[310|vm=250|ROOT]], maxSize : 3518437261312, totalAllocatedSize : 55198319616, askingSize : 0, allocated disable threshold: 0.85
> 2013-07-04 15:52:23,310 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-38:job-926) Checking if storage pool is suitable, name: null ,poolId: 2
> 2013-07-04 15:52:23,317 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-38:job-926) Checking pool 2 for storage, totalSize: 1759218630656, usedBytes: 1443519528960, usedPct: 0.8205458399572099, disable threshold: 0.85
> 2013-07-04 15:52:23,412 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-38:job-926) Checking pool: 2 for volume allocation [Vol[310|vm=250|ROOT]], maxSize : 3518437261312, totalAllocatedSize : 123817133056, askingSize : 0, allocated disable threshold: 0.85
> 2013-07-04 15:52:23,412 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-38:job-926) FirstFitStoragePoolAllocator returning 2 suitable storage pools
> 2013-07-04 15:52:23,413 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
> 2013-07-04 15:52:23,413 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Checking if host: 2 can access any suitable storage pool for volume: ROOT
> 2013-07-04 15:52:23,415 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Host: 2 can access pool: 1
> 2013-07-04 15:52:23,417 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Found a potential host id: 2 name: Rack1Pod1Host17 and associated storage pools for this VM
> 2013-07-04 15:52:23,420 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-38:job-926) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(310|ROOT-->Pool(1))]
> 2013-07-04 15:52:23,420 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-38:job-926) Found Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(310|ROOT-->Pool(1))] for scaling the vm to.
> 2013-07-04 15:52:23,420 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-38:job-926) Migrating VM[User|t] to Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(310|ROOT-->Pool(1))]
> 2013-07-04 15:52:23,448 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-38:job-926) Service SecurityGroup is not supported in the network id=362
> 2013-07-04 15:52:23,457 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-38:job-926) Preparing 1 volumes for VM[User|t]
> 2013-07-04 15:52:23,472 WARN [cloud.template.TemplateManagerImpl] (Job-Executor-38:job-926) Unable to find secondary storage in zone id=1
> 2013-07-04 15:52:23,500 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 2-1194332178: Sending { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100111, [{"PrepareForMigrationCommand":{"vm":{"id":250,"name":"i-2-250-QA","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS 5.3 (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"d7c51073404cbac6","params":{},"uuid":"adf50367-09ae-447d-9954-44f2e767e3de","disks":[{"id":310,"name":"ROOT-250","mountPoint":"/vol/dgVol/automation/adv/pri_3","path":"fa920753-87d8-4b17-b4d7-482e72665491","size":21474836480,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"cb8c6c62-71ea-3269-94b9-b1c0a4055d45","deviceId":0}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"5cbd89f8-4265-4f1d-be72-af4b717c6e13","ip":"10.1.1.254","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:0d:e7:00:01","dns1":"10.103.128.16","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1067","isolationUri":"vlan://1067","isSecurityGroupEnabled":false}]},"wait":0}}] }
> 2013-07-04 15:52:23,501 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 2-1194332178: Executing: { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100111, [{"PrepareForMigrationCommand":{"vm":{"id":250,"name":"i-2-250-QA","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS 5.3 (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"d7c51073404cbac6","params":{},"uuid":"adf50367-09ae-447d-9954-44f2e767e3de","disks":[{"id":310,"name":"ROOT-250","mountPoint":"/vol/dgVol/automation/adv/pri_3","path":"fa920753-87d8-4b17-b4d7-482e72665491","size":21474836480,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"cb8c6c62-71ea-3269-94b9-b1c0a4055d45","deviceId":0}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"5cbd89f8-4265-4f1d-be72-af4b717c6e13","ip":"10.1.1.254","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:0d:e7:00:01","dns1":"10.103.128.16","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1067","isolationUri":"vlan://1067","isSecurityGroupEnabled":false}]},"wait":0}}] }
> 2013-07-04 15:52:23,501 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-453:null) Seq 2-1194332178: Executing request
> 2013-07-04 15:52:23,653 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-453:null) Preparing host for migrating com.cloud.agent.api.to.VirtualMachineTO@754845b6
> 2013-07-04 15:52:23,737 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-453:null) Creating VLAN 1067 on host 10.147.40.17 on device eth0
> 2013-07-04 15:52:24,143 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-453:null) VLAN is created for 1067. The uuid is 9d2d1acb-e98e-9a1d-3ad3-f87bd6cd35f8
> 2013-07-04 15:52:24,143 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-453:null) 4. The VM i-2-250-QA is in Migrating state
> 2013-07-04 15:52:24,143 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-453:null) Seq 2-1194332178: Response Received:
> 2013-07-04 15:52:24,144 DEBUG [agent.transport.Request] (DirectAgent-453:null) Seq 2-1194332178: Processing: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 110, [{"PrepareForMigrationAnswer":{"result":true,"wait":0}}] }
> 2013-07-04 15:52:24,144 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 2-1194332178: Received: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 110, { PrepareForMigrationAnswer } }
> 2013-07-04 15:52:24,147 DEBUG [agent.manager.AgentAttache] (DirectAgent-453:null) Seq 2-1194332178: No more commands found
> 2013-07-04 15:52:24,164 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) VM state transitted from :Running to Migrating with event: MigrationRequestedvm's original host id: 1 new host id: 2 host id before state transition: 1
> 2013-07-04 15:52:24,179 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total CPU: 9592 and CPU after applying overprovisioning: 9592
> 2013-07-04 15:52:24,179 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) We are allocating VM, increasing the used capacity of this host:2
> 2013-07-04 15:52:24,179 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Current Used CPU: 2700 , Free CPU:6892 ,Requested CPU: 100
> 2013-07-04 15:52:24,180 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Current Used RAM: 2013265920 , Free RAM:14176890880 ,Requested RAM: 134217728
> 2013-07-04 15:52:24,180 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) CPU STATS after allocation: for host: 2, old used: 2700, old reserved: 0, actual total: 9592, total with overprovisioning: 9592; new used:2800, reserved:0; requested cpu:100,alloc_from_last:false
> 2013-07-04 15:52:24,180 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) RAM STATS after allocation: for host: 2, old used: 2013265920, old reserved: 0, total: 16190156800; new used: 2147483648, reserved: 0; requested mem: 134217728,alloc_from_last:false
> 2013-07-04 15:52:24,192 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 1-1227952755: Sending { Cmd , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 100111, [{"MigrateCommand":{"vmName":"i-2-250-QA","destIp":"10.147.40.17","hostGuid":"48ef2a16-e459-4761-a4b5-ac9c1c3b4e1c","isWindows":false,"wait":0}}] }
> 2013-07-04 15:52:24,192 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 1-1227952755: Executing: { Cmd , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 100111, [{"MigrateCommand":{"vmName":"i-2-250-QA","destIp":"10.147.40.17","hostGuid":"48ef2a16-e459-4761-a4b5-ac9c1c3b4e1c","isWindows":false,"wait":0}}] }
> 2013-07-04 15:52:24,193 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-50:null) Seq 1-1227952755: Executing request
> 2013-07-04 15:52:24,274 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-50:null) 5. The VM i-2-250-QA is in Stopping state
> 2013-07-04 15:52:25,051 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-453:null) Ping from 5
> 2013-07-04 15:52:25,215 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-388:null) Ping from 1
> 2013-07-04 15:52:25,796 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===START=== 10.101.255.52 -- GET command=queryAsyncJobResult&jobId=297c9a77-6075-4224-9917-35ec55279b7f&response=json&sessionkey=CS5Ro9Vvbhn2TB1iTqjoB1s4lfQ%3D&_=1372913895224
> 2013-07-04 15:52:25,832 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===END=== 10.101.255.52 -- GET command=queryAsyncJobResult&jobId=297c9a77-6075-4224-9917-35ec55279b7f&response=json&sessionkey=CS5Ro9Vvbhn2TB1iTqjoB1s4lfQ%3D&_=1372913895224
> 2013-07-04 15:52:26,636 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-346:null) Seq 5-1817575429: Executing request
> 2013-07-04 15:52:26,714 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-341:null) Ping from 2
> 2013-07-04 15:52:26,903 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-346:null) Seq 5-1817575429: Response Received:
> 2013-07-04 15:52:26,904 DEBUG [agent.transport.Request] (DirectAgent-346:null) Seq 5-1817575429: Processing: { Ans: , MgmtId: 7363452993625, via: 5, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":2,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2013-07-04 15:52:28,572 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 10-6156: Processing Seq 10-6156: { Cmd , MgmtId: -1, via: 10, Ver: v1, Flags: 11, [{"ConsoleProxyLoadReportCommand":{"_proxyVmId":4,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2013-07-04 15:52:28,581 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 10-6156: Sending Seq 10-6156: { Ans: , MgmtId: 7363452993625, via: 10, Ver: v1, Flags: 100010, [{"AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-07-04 15:52:28,688 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-388:null) Seq 1-1227948042: Executing request
> 2013-07-04 15:52:28,794 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===START=== 10.101.255.52 -- GET command=queryAsyncJobResult&jobId=297c9a77-6075-4224-9917-35ec55279b7f&response=json&sessionkey=CS5Ro9Vvbhn2TB1iTqjoB1s4lfQ%3D&_=1372913898225
> 2013-07-04 15:52:28,828 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===END=== 10.101.255.52 -- GET command=queryAsyncJobResult&jobId=297c9a77-6075-4224-9917-35ec55279b7f&response=json&sessionkey=CS5Ro9Vvbhn2TB1iTqjoB1s4lfQ%3D&_=1372913898225
> 2013-07-04 15:52:29,056 WARN [xen.resource.CitrixResourceBase] (DirectAgent-388:null) Ignoring vm i-2-250-QA because of a lag in stopping the vm.
> 2013-07-04 15:52:29,057 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-388:null) Seq 1-1227948042: Response Received:
> 2013-07-04 15:52:29,058 DEBUG [agent.transport.Request] (DirectAgent-388:null) Seq 1-1227948042: Processing: { Ans: , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2013-07-04 15:52:30,202 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-346:null) Seq 2-1194328070: Executing request
> 2013-07-04 15:52:30,420 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-346:null) Seq 2-1194328070: Response Received:
> 2013-07-04 15:52:30,420 DEBUG [agent.transport.Request] (DirectAgent-346:null) Seq 2-1194328070: Processing: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 10, [{"Answer":{"result":true,"wait":0}}] }
> 2013-07-04 15:52:30,606 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 12-5170: Processing Seq 12-5170: { Cmd , MgmtId: -1, via: 12, Ver: v1, Flags: 11, [{"ConsoleAccessAuthenticationCommand":{"_host":"10.147.40.15","_port":"-1","_vmId":"adf50367-09ae-447d-9954-44f2e767e3de","_sid":"d7c51073404cbac6","_ticket":"LCq34kwAjRZTNUofg6SlVBRcbw8=","_isReauthenticating":true,"wait":0}}] }
> 2013-07-04 15:52:30,606 DEBUG [cloud.consoleproxy.AgentHookBase] (AgentManager-Handler-7:null) Console authentication. Ticket in url for 10.147.40.15:-1-adf50367-09ae-447d-9954-44f2e767e3de is LCq34kwAjRZTNUofg6SlVBRcbw8=
> 2013-07-04 15:52:30,621 INFO [cloud.consoleproxy.AgentHookBase] (AgentManager-Handler-7:null) Re-authentication request, ask host 2 for new console info
> 2013-07-04 15:52:30,626 DEBUG [agent.transport.Request] (AgentManager-Handler-7:null) Seq 2-1194332179: Sending { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100011, [{"GetVncPortCommand":{"id":250,"name":"i-2-250-QA","wait":0}}] }
> 2013-07-04 15:52:30,626 DEBUG [agent.transport.Request] (AgentManager-Handler-7:null) Seq 2-1194332179: Executing: { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100011, [{"GetVncPortCommand":{"id":250,"name":"i-2-250-QA","wait":0}}] }
> 2013-07-04 15:52:30,626 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-392:null) Seq 2-1194332179: Executing request
> 2013-07-04 15:52:30,641 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 12-5171: Processing Seq 12-5171: { Cmd , MgmtId: -1, via: 12, Ver: v1, Flags: 11, [{"ConsoleProxyLoadReportCommand":{"_proxyVmId":47,"_loadInfo":"{\n \"connections\": [\n {\n \"id\": 1,\n \"clientInfo\": \"\",\n \"host\": \"10.147.40.15\",\n \"port\": -1,\n \"tag\": \"adf50367-09ae-447d-9954-44f2e767e3de\",\n \"createTime\": 1372913511162,\n \"lastUsedTime\": 1372913796710\n }\n ]\n}","wait":0}}] }
> 2013-07-04 15:52:30,649 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 12-5171: Sending Seq 12-5171: { Ans: , MgmtId: 7363452993625, via: 12, Ver: v1, Flags: 100010, [{"AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-07-04 15:52:31,012 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-392:null) Seq 2-1194332179: Response Received:
> 2013-07-04 15:52:31,012 DEBUG [agent.transport.Request] (DirectAgent-392:null) Seq 2-1194332179: Processing: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 10, [{"GetVncPortAnswer":{"address":"consoleurl=https://10.147.40.15/console?uuid=6d68f0df-4865-80f4-5f76-1d32bef95137&sessionref=OpaqueRef:17fa14d0-11cb-1673-7562-1dd357f88e88","port":-1,"result":true,"wait":0}}] }
> 2013-07-04 15:52:31,012 DEBUG [agent.transport.Request] (AgentManager-Handler-7:null) Seq 2-1194332179: Received: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 10, { GetVncPortAnswer } }
> 2013-07-04 15:52:31,012 INFO [cloud.servlet.ConsoleProxyServlet] (AgentManager-Handler-7:null) Parse host info returned from executing GetVNCPortCommand. host info: consoleurl=https://10.147.40.15/console?uuid=6d68f0df-4865-80f4-5f76-1d32bef95137&sessionref=OpaqueRef:17fa14d0-11cb-1673-7562-1dd357f88e88
> 2013-07-04 15:52:31,013 INFO [cloud.consoleproxy.AgentHookBase] (AgentManager-Handler-7:null) Re-authentication result. vm: 250, tunnel url: https://10.147.40.15/console?uuid=6d68f0df-4865-80f4-5f76-1d32bef95137, tunnel session: OpaqueRef:17fa14d0-11cb-1673-7562-1dd357f88e88
> 2013-07-04 15:52:31,013 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 12-5170: Sending Seq 12-5170: { Ans: , MgmtId: 7363452993625, via: 12, Ver: v1, Flags: 100010, [{"ConsoleAccessAuthenticationAnswer":{"_success":true,"_isReauthenticating":true,"_port":0,"_tunnelUrl":"https://10.147.40.15/console?uuid=6d68f0df-4865-80f4-5f76-1d32bef95137","_tunnelSession":"OpaqueRef:17fa14d0-11cb-1673-7562-1dd357f88e88","result":true,"wait":0}}] }
> 2013-07-04 15:52:31,796 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===START=== 10.101.255.52 -- GET command=queryAsyncJobResult&jobId=297c9a77-6075-4224-9917-35ec55279b7f&response=json&sessionkey=CS5Ro9Vvbhn2TB1iTqjoB1s4lfQ%3D&_=1372913901227
> 2013-07-04 15:52:31,828 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===END=== 10.101.255.52 -- GET command=queryAsyncJobResult&jobId=297c9a77-6075-4224-9917-35ec55279b7f&response=json&sessionkey=CS5Ro9Vvbhn2TB1iTqjoB1s4lfQ%3D&_=1372913901227
> 2013-07-04 15:52:32,150 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 12-5172: Processing Seq 12-5172: { Cmd , MgmtId: -1, via: 12, Ver: v1, Flags: 11, [{"ConsoleAccessAuthenticationCommand":{"_host":"10.147.40.15","_port":"-1","_vmId":"adf50367-09ae-447d-9954-44f2e767e3de","_sid":"d7c51073404cbac6","_ticket":"LCq34kwAjRZTNUofg6SlVBRcbw8=","_isReauthenticating":true,"wait":0}}] }
> 2013-07-04 15:52:32,150 DEBUG [cloud.consoleproxy.AgentHookBase] (AgentManager-Handler-11:null) Console authentication. Ticket in url for 10.147.40.15:-1-adf50367-09ae-447d-9954-44f2e767e3de is LCq34kwAjRZTNUofg6SlVBRcbw8=
> 2013-07-04 15:52:32,164 INFO [cloud.consoleproxy.AgentHookBase] (AgentManager-Handler-11:null) Re-authentication request, ask host 2 for new console info
> 2013-07-04 15:52:32,169 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 2-1194332180: Sending { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100011, [{"GetVncPortCommand":{"id":250,"name":"i-2-250-QA","wait":0}}] }
> 2013-07-04 15:52:32,169 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 2-1194332180: Executing: { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100011, [{"GetVncPortCommand":{"id":250,"name":"i-2-250-QA","wait":0}}] }
> 2013-07-04 15:52:32,170 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-99:null) Seq 2-1194332180: Executing request
> 2013-07-04 15:52:32,448 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-50:null) 6. The VM i-2-250-QA is in Stopping state
> 2013-07-04 15:52:32,449 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-50:null) Seq 1-1227952755: Response Received:
> 2013-07-04 15:52:32,449 DEBUG [agent.transport.Request] (DirectAgent-50:null) Seq 1-1227952755: Processing: { Ans: , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 110, [{"MigrateAnswer":{"result":true,"details":"migration succeeded","wait":0}}] }
> 2013-07-04 15:52:32,450 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 1-1227952755: Received: { Ans: , MgmtId: 7363452993625, via: 1, Ver: v1, Flags: 110, { MigrateAnswer } }
> 2013-07-04 15:52:32,453 DEBUG [agent.manager.AgentAttache] (DirectAgent-50:null) Seq 1-1227952755: No more commands found
> 2013-07-04 15:52:32,490 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-38:job-926) Service SecurityGroup is not supported in the network id=362
> 2013-07-04 15:52:32,501 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-38:job-926) Service SecurityGroup is not supported in the network id=362
> 2013-07-04 15:52:32,501 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) VM state transitted from :Migrating to Running with event: OperationSucceededvm's original host id: 1 new host id: 2 host id before state transition: 2
> 2013-07-04 15:52:32,515 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total CPU: 9576 and CPU after applying overprovisioning: 9576
> 2013-07-04 15:52:32,515 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total RAM: 16190157312 and RAM after applying overprovisioning: 16190156800
> 2013-07-04 15:52:32,515 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) release cpu from host: 1, old used: 2000,reserved: 0, actual total: 9576, total with overprovisioning: 9576; new used: 1900,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-04 15:52:32,515 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) release mem from host: 1, old used: 1207959552,reserved: 0, total: 16190156800; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-04 15:52:32,518 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-99:null) Seq 2-1194332180: Response Received:
> 2013-07-04 15:52:32,518 DEBUG [agent.transport.Request] (DirectAgent-99:null) Seq 2-1194332180: Processing: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 10, [{"GetVncPortAnswer":{"address":"consoleurl=https://10.147.40.17/console?uuid=96377be2-6069-f023-df92-075b434990b1&sessionref=OpaqueRef:17fa14d0-11cb-1673-7562-1dd357f88e88","port":-1,"result":true,"wait":0}}] }
> 2013-07-04 15:52:32,519 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 2-1194332180: Received: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 10, { GetVncPortAnswer } }
> 2013-07-04 15:52:32,519 INFO [cloud.servlet.ConsoleProxyServlet] (AgentManager-Handler-11:null) Parse host info returned from executing GetVNCPortCommand. host info: consoleurl=https://10.147.40.17/console?uuid=96377be2-6069-f023-df92-075b434990b1&sessionref=OpaqueRef:17fa14d0-11cb-1673-7562-1dd357f88e88
> 2013-07-04 15:52:32,519 INFO [cloud.consoleproxy.AgentHookBase] (AgentManager-Handler-11:null) Re-authentication result. vm: 250, tunnel url: https://10.147.40.17/console?uuid=96377be2-6069-f023-df92-075b434990b1, tunnel session: OpaqueRef:17fa14d0-11cb-1673-7562-1dd357f88e88
> 2013-07-04 15:52:32,519 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 12-5172: Sending Seq 12-5172: { Ans: , MgmtId: 7363452993625, via: 12, Ver: v1, Flags: 100010, [{"ConsoleAccessAuthenticationAnswer":{"_success":true,"_isReauthenticating":true,"_port":0,"_tunnelUrl":"https://10.147.40.17/console?uuid=96377be2-6069-f023-df92-075b434990b1","_tunnelSession":"OpaqueRef:17fa14d0-11cb-1673-7562-1dd357f88e88","result":true,"wait":0}}] }
> 2013-07-04 15:52:32,528 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 2-1194332181: Sending { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100011, [{"CheckVirtualMachineCommand":{"vmName":"i-2-250-QA","wait":20}}] }
> 2013-07-04 15:52:32,529 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 2-1194332181: Executing: { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100011, [{"CheckVirtualMachineCommand":{"vmName":"i-2-250-QA","wait":20}}] }
> 2013-07-04 15:52:32,529 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-267:null) Seq 2-1194332181: Executing request
> 2013-07-04 15:52:32,675 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-267:null) 3. The VM i-2-250-QA is in Running state
> 2013-07-04 15:52:32,676 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-267:null) Seq 2-1194332181: Response Received:
> 2013-07-04 15:52:32,676 DEBUG [agent.transport.Request] (DirectAgent-267:null) Seq 2-1194332181: Processing: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 10, [{"CheckVirtualMachineAnswer":{"state":"Running","result":true,"wait":0}}] }
> 2013-07-04 15:52:32,676 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 2-1194332181: Received: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 10, { CheckVirtualMachineAnswer } }
> 2013-07-04 15:52:32,756 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 2-1194332182: Sending { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100111, [{"ScaleVmCommand":{"vm":{"id":1,"name":"i-2-250-QA","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":536870912,"maxRam":536870912,"rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false},"vmName":"i-2-250-QA","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":536870912,"maxRam":536870912,"wait":0}}] }
> 2013-07-04 15:52:32,757 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 2-1194332182: Executing: { Cmd , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 100111, [{"ScaleVmCommand":{"vm":{"id":1,"name":"i-2-250-QA","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":536870912,"maxRam":536870912,"rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false},"vmName":"i-2-250-QA","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":536870912,"maxRam":536870912,"wait":0}}] }
> 2013-07-04 15:52:32,759 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-126:null) Seq 2-1194332182: Executing request
> 2013-07-04 15:52:32,904 WARN [xen.resource.CitrixResourceBase] (DirectAgent-126:null) Unable to upgrade i-2-250-QA due to Unable to Scale the vm: i-2-250-QAas vm does not have xs tools to support dynamic scaling
> com.cloud.utils.exception.CloudRuntimeException: Unable to Scale the vm: i-2-250-QAas vm does not have xs tools to support dynamic scaling
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:684)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:626)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:73)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:102)
> at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
> 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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
> 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-07-04 15:52:32,906 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-126:null) Seq 2-1194332182: Response Received:
> 2013-07-04 15:52:32,906 DEBUG [agent.transport.Request] (DirectAgent-126:null) Seq 2-1194332182: Processing: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 110, [{"ScaleVmAnswer":{"result":false,"details":"Unable to upgrade i-2-250-QA due to Unable to Scale the vm: i-2-250-QAas vm does not have xs tools to support dynamic scaling","wait":0}}] }
> 2013-07-04 15:52:32,907 DEBUG [agent.transport.Request] (Job-Executor-38:job-926) Seq 2-1194332182: Received: { Ans: , MgmtId: 7363452993625, via: 2, Ver: v1, Flags: 110, { ScaleVmAnswer } }
> 2013-07-04 15:52:32,907 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-38:job-926) Unable to scale vm due to Unable to upgrade i-2-250-QA due to Unable to Scale the vm: i-2-250-QAas vm does not have xs tools to support dynamic scaling
> 2013-07-04 15:52:32,911 DEBUG [agent.manager.AgentAttache] (DirectAgent-126:null) Seq 2-1194332182: No more commands found
> 2013-07-04 15:52:32,918 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total CPU: 9592 and CPU after applying overprovisioning: 9592
> 2013-07-04 15:52:32,918 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total RAM: 16190157312 and RAM after applying overprovisioning: 16190156800
> 2013-07-04 15:52:32,918 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) release cpu from host: 2, old used: 2800,reserved: 0, actual total: 9592, total with overprovisioning: 9592; new used: 2700,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-04 15:52:32,919 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) release mem from host: 2, old used: 2147483648,reserved: 0, total: 16190156800; new used: 1610612736,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-04 15:52:32,941 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Hosts's actual total CPU: 9592 and CPU after applying overprovisioning: 9592
> 2013-07-04 15:52:32,942 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) We are allocating VM, increasing the used capacity of this host:2
> 2013-07-04 15:52:32,942 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Current Used CPU: 2700 , Free CPU:6892 ,Requested CPU: 100
> 2013-07-04 15:52:32,942 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) Current Used RAM: 1610612736 , Free RAM:14579544064 ,Requested RAM: 134217728
> 2013-07-04 15:52:32,942 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) CPU STATS after allocation: for host: 2, old used: 2700, old reserved: 0, actual total: 9592, total with overprovisioning: 9592; new used:2800, reserved:0; requested cpu:100,alloc_from_last:false
> 2013-07-04 15:52:32,942 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-38:job-926) RAM STATS after allocation: for host: 2, old used: 1610612736, old reserved: 0, total: 16190156800; new used: 1744830464, reserved: 0; requested mem: 134217728,alloc_from_last:false
> 2013-07-04 15:52:32,949 WARN [cloud.vm.UserVmManagerImpl] (Job-Executor-38:job-926) Received exception while scaling
> com.cloud.utils.exception.CloudRuntimeException: Unable to scale vm due to Unable to upgrade i-2-250-QA due to Unable to Scale the vm: i-2-250-QAas vm does not have xs tools to support dynamic scaling
> at com.cloud.vm.VirtualMachineManagerImpl.reConfigureVm(VirtualMachineManagerImpl.java:3265)
> at com.cloud.vm.UserVmManagerImpl.upgradeVirtualMachine(UserVmManagerImpl.java:1217)
> at com.cloud.vm.UserVmManagerImpl.upgradeVirtualMachine(UserVmManagerImpl.java:1090)
> at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at org.apache.cloudstack.api.command.user.vm.ScaleVMCmd.execute(ScaleVMCmd.java:92)
> 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-07-04 15:52:32,989 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-38:job-926) Complete async job-926, jobStatus: 2, resultCode: 530, result: Error Code: 530 Error text: Failed to scale vm
> 2013-07-04 15:52:34,802 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null) ===START=== 10.101.255.52 -- GET command=queryAsyncJobResult&jobId=297c9a77-6075-4224-9917-35ec55279b7f&response=json&sessionkey=CS5Ro9Vvbhn2TB1iTqjoB1s4lfQ%3D&_=1372913904229
> 2013-07-04 15:52:34,822 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-8:null) Async job-926 completed
--
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