Srikanteswararao Talluri created CLOUDSTACK-3354:
----------------------------------------------------
Summary: [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
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
