[
https://issues.apache.org/jira/browse/CLOUDSTACK-3354?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Srikanteswararao Talluri closed CLOUDSTACK-3354.
------------------------------------------------
working fine now. Hence, closing this bug
> [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
