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 07:46:20 UTC
[jira] [Commented] (CLOUDSTACK-3354) [automation] scale up VM is
failing
[ https://issues.apache.org/jira/browse/CLOUDSTACK-3354?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13699784#comment-13699784 ]
Harikrishna Patnala commented on CLOUDSTACK-3354:
-------------------------------------------------
After installation of XS tools in the VM we need to update the Virtual machine by setting isdynamically scalable parameter to true and stop start the VM. During start of the VM it sets the static max memory to higher value than in the service offering so that we can dynamically scale the vm upto static max. This Static max value can be set only before start of the VM.
Please refer FS @ https://cwiki.apache.org/confluence/display/CLOUDSTACK/Dynamic+scaling+of+CPU+and+RAM
I'll fix the automation failure.
> [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