You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Parth Jagirdar (JIRA)" <ji...@apache.org> on 2014/03/20 18:54:43 UTC
[jira] [Resolved] (CLOUDSTACK-6073) Contrail:MS: Reboot Xen hosts
and guest VM's get auto deleted after being migrated to another host
[ https://issues.apache.org/jira/browse/CLOUDSTACK-6073?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Parth Jagirdar resolved CLOUDSTACK-6073.
----------------------------------------
Resolution: Fixed
Not seen using latest bits.
> Contrail:MS: Reboot Xen hosts and guest VM's get auto deleted after being migrated to another host
> --------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-6073
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-6073
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: Contrail, Management Server, Xen
> Affects Versions: 4.2.1
> Environment: Contrail
> Reporter: Parth Jagirdar
> Assignee: Parth Jagirdar
> Priority: Blocker
> Fix For: 4.2.1
>
> Attachments: Xen-Reboot.jpg
>
>
> Refer to 5777.
> After Xen host is rebooted VM's fails to start. (Note VM gets migrated to another host)
> After multiple attempts VM;s gets into start state. But mostly falls back to stopped state.
> If VM gets into running state, migration to another hosts results in following error.
> Unable to migrate due to Catch Exception com.cloud.utils.exception.CloudRuntimeException: Migration failed due to com.cloud.utils.exception.CloudRuntimeException: Unable to migrate VM(i-2-38-VM) from host(335fb70f-e798-405b-b274-12053bc43051) due to Task failed! Task record: uuid: 3456c28d-1c6f-ad87-1c7f-a444b32f87a3 nameLabel: Async.VM.pool_migrate nameDescription: allowedOperations: [] currentOperations: {} created: Mon Feb 10 15:52:07 PST 2014 finished: Mon Feb 10 15:52:07 PST 2014 status: failure residentOn: com.xensource.xenapi.Host@f44e28e6 progress: 1.0 type: <none/> result: errorInfo: [VM_BAD_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, running, halted] otherConfig: {} subtaskOf: com.xensource.xenapi.Task@aaf13f6f subtasks: []
> With all this error this VM actually doesnt exist on any Xenservers.
> Which suggests that this VM was removed from Xenserver but still exists in CS.
> 2014-02-10 14:35:17,768 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-45281: Processing Seq 3-45281: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:35:17,773 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-45281: Sending Seq 3-45281: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:35:18,810 DEBUG [c.c.a.ApiServlet] (catalina-exec-6:ctx-b5bd122b) ===START=== 10.215.2.19 -- GET command=listVirtualMachines&id=25cd2c87-200f-4291-85e4-54b04df65ac0&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076423981
> 2014-02-10 14:35:18,832 DEBUG [c.c.a.ApiServlet] (catalina-exec-6:ctx-b5bd122b ctx-5b246cc0) ===END=== 10.215.2.19 -- GET command=listVirtualMachines&id=25cd2c87-200f-4291-85e4-54b04df65ac0&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076423981
> 2014-02-10 14:35:18,923 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-096ac0fe) ===START=== 10.215.2.19 -- GET command=listOsTypes&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076424025
> 2014-02-10 14:35:19,148 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-096ac0fe ctx-2d525580) ===END=== 10.215.2.19 -- GET command=listOsTypes&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076424025
> 2014-02-10 14:35:19,972 DEBUG [c.c.a.ApiServlet] (catalina-exec-8:ctx-c9ac53a3) ===START=== 10.215.2.19 -- GET command=listVirtualMachines&id=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076425125
> 2014-02-10 14:35:19,994 DEBUG [c.c.a.ApiServlet] (catalina-exec-8:ctx-c9ac53a3 ctx-bf92a1ff) ===END=== 10.215.2.19 -- GET command=listVirtualMachines&id=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076425125
> 2014-02-10 14:35:20,090 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-c9702560) ===START=== 10.215.2.19 -- GET command=listOsTypes&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076425184
> 2014-02-10 14:35:20,313 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-c9702560 ctx-24834659) ===END=== 10.215.2.19 -- GET command=listOsTypes&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076425184
> 2014-02-10 14:35:22,384 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-88ec237c) ===START=== 10.215.2.19 -- GET command=startVirtualMachine&id=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076427551
> 2014-02-10 14:35:22,415 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-25:ctx-88ec237c ctx-216f60ab) submit async job-60, details: AsyncJobVO {id:60, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 38, cmd: org.apache.cloudstack.api.command.user.vm.StartVMCmd, cmdInfo: {"id":"6034fed3-bac7-4267-874b-fdbcdd58f610","response":"json","sessionkey":"gJbfxiFXGjIJTBqBPlcyevZSM1g\u003d","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1392076427551","ctxAccountId":"2","ctxStartEventId":"221"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 214151488957798, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2014-02-10 14:35:22,418 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-34:ctx-2cf0628d) Add job-60 into job monitoring
> 2014-02-10 14:35:22,419 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-34:ctx-2cf0628d) Executing AsyncJobVO {id:60, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 38, cmd: org.apache.cloudstack.api.command.user.vm.StartVMCmd, cmdInfo: {"id":"6034fed3-bac7-4267-874b-fdbcdd58f610","response":"json","sessionkey":"gJbfxiFXGjIJTBqBPlcyevZSM1g\u003d","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1392076427551","ctxAccountId":"2","ctxStartEventId":"221"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 214151488957798, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2014-02-10 14:35:22,419 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-88ec237c ctx-216f60ab) ===END=== 10.215.2.19 -- GET command=startVirtualMachine&id=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076427551
> 2014-02-10 14:35:22,447 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the network id=205
> 2014-02-10 14:35:22,451 DEBUG [o.a.c.n.c.m.ContrailGuru] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) update NicProfile 142 on second
> 2014-02-10 14:35:22,453 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the network id=205
> 2014-02-10 14:35:22,478 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Deploy avoids pods: [], clusters: [], hosts: []
> 2014-02-10 14:35:22,479 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@62162cbb
> 2014-02-10 14:35:22,479 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
> 2014-02-10 14:35:22,479 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Is ROOT volume READY (pool already allocated)?: Yes
> 2014-02-10 14:35:22,479 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) This VM has last host_id specified, trying to choose the same host: 2
> 2014-02-10 14:35:22,486 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Checking if host: 2 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
> 2014-02-10 14:35:22,490 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-02-10 14:35:22,490 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) We need to allocate to the last host again, so checking if there is enough reserved capacity
> 2014-02-10 14:35:22,490 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Reserved CPU: 500 , Requested CPU: 500
> 2014-02-10 14:35:22,490 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Reserved RAM: 536870912 , Requested RAM: 536870912
> 2014-02-10 14:35:22,491 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Host has enough CPU and RAM available
> 2014-02-10 14:35:22,491 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) STATS: Can alloc CPU from host: 2, used: 2000, reserved: 500, actual total: 9044, total with overprovisioning: 9044; requested cpu:500,alloc_from_last_host?:true ,considerReservedCapacity?: true
> 2014-02-10 14:35:22,491 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) STATS: Can alloc MEM from host: 2, used: 2684354560, reserved: 536870912, total: 16001258496; requested mem: 536870912,alloc_from_last_host?:true ,considerReservedCapacity?: true
> 2014-02-10 14:35:22,493 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Host: 2 has cpu capability (cpu:4, speed:2261) to support requested CPU: 1 and requested speed: 500
> 2014-02-10 14:35:22,493 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) The last host of this VM is UP and has enough capacity
> 2014-02-10 14:35:22,493 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Now checking for suitable pools under zone: 1, pod: 1, cluster: 1
> 2014-02-10 14:35:22,495 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Checking suitable pools for volume (Id, Type): (38,ROOT)
> 2014-02-10 14:35:22,495 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Volume has pool already allocated, checking if pool can be reused, poolId: 16
> 2014-02-10 14:35:22,496 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Planner need not allocate a pool for this volume since its READY
> 2014-02-10 14:35:22,497 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
> 2014-02-10 14:35:22,497 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Checking if host: 2 can access any suitable storage pool for volume: ROOT
> 2014-02-10 14:35:22,499 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Host: 2 can access pool: 16
> 2014-02-10 14:35:22,502 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Found a potential host id: 2 name: xenserver-1 and associated storage pools for this VM
> 2014-02-10 14:35:22,504 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) 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()]
> 2014-02-10 14:35:22,522 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 2 new host id: null host id before state transition: null
> 2014-02-10 14:35:22,522 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Successfully transitioned to start state for VM[User|third] reservation id = 45e9298d-313c-4b27-aa91-b8479a883c7b
> 2014-02-10 14:35:22,531 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Trying to deploy VM, vm has dcId: 1 and podId: 1
> 2014-02-10 14:35:22,531 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 2, poolId: null
> 2014-02-10 14:35:22,531 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Deploy avoids pods: null, clusters: null, hosts: null
> 2014-02-10 14:35:22,535 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Root volume is ready, need to place VM in volume's cluster
> 2014-02-10 14:35:22,545 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Deploy avoids pods: [], clusters: [], hosts: []
> 2014-02-10 14:35:22,546 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@62162cbb
> 2014-02-10 14:35:22,546 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
> 2014-02-10 14:35:22,546 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Is ROOT volume READY (pool already allocated)?: Yes
> 2014-02-10 14:35:22,546 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 2
> 2014-02-10 14:35:22,548 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
> 2014-02-10 14:35:22,550 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Checking suitable pools for volume (Id, Type): (38,ROOT)
> 2014-02-10 14:35:22,550 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Volume has pool already allocated, checking if pool can be reused, poolId: 16
> 2014-02-10 14:35:22,551 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Planner need not allocate a pool for this volume since its READY
> 2014-02-10 14:35:22,551 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
> 2014-02-10 14:35:22,551 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Checking if host: 2 can access any suitable storage pool for volume: ROOT
> 2014-02-10 14:35:22,553 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Host: 2 can access pool: 16
> 2014-02-10 14:35:22,554 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Found a potential host id: 2 name: xenserver-1 and associated storage pools for this VM
> 2014-02-10 14:35:22,556 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) 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()]
> 2014-02-10 14:35:22,556 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Deployment found - P0=VM[User|third], P0=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()]
> 2014-02-10 14:35:22,567 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 2 new host id: 2 host id before state transition: null
> 2014-02-10 14:35:22,567 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) VM starting again on the last host it was stopped on
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) We are allocating VM, increasing the used capacity of this host:2
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Current Used CPU: 2000 , Free CPU:6544 ,Requested CPU: 500
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Current Used RAM: 2684354560 , Free RAM:12780033024 ,Requested RAM: 536870912
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Reserved CPU: 500 , Requested CPU: 500
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Reserved RAM: 536870912 , Requested RAM: 536870912
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) CPU STATS after allocation: for host: 2, old used: 2000, old reserved: 500, actual total: 9044, total with overprovisioning: 9044; new used:2500, reserved:0; requested cpu:500,alloc_from_last:true
> 2014-02-10 14:35:22,576 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) RAM STATS after allocation: for host: 2, old used: 2684354560, old reserved: 536870912, total: 16001258496; new used: 3221225472, reserved: 0; requested mem: 536870912,alloc_from_last:true
> 2014-02-10 14:35:22,589 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) VM is being created in podId: 1
> 2014-02-10 14:35:22,592 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Network id=205 is already implemented
> 2014-02-10 14:35:22,604 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the network id=205
> 2014-02-10 14:35:22,607 DEBUG [o.a.c.n.c.m.ContrailGuru] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) reserve NicProfile on network id: 205 second
> 2014-02-10 14:35:22,607 DEBUG [o.a.c.n.c.m.ContrailGuru] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) deviceId: 0
> 2014-02-10 14:35:22,609 DEBUG [o.a.c.n.c.m.ContrailGuru] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Reuse existing instance-ip object on i-2-38-VM-0
> 2014-02-10 14:35:22,610 DEBUG [o.a.c.n.c.m.ContrailGuru] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Nic using existing IP address 10.10.255.252
> 2014-02-10 14:35:22,610 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) >> Request: PUT, /virtual-machine/6034fed3-bac7-4267-874b-fdbcdd58f610, {"virtual-machine":{"name":"i-2-38-VM","uuid":"6034fed3-bac7-4267-874b-fdbcdd58f610","fq_name":["i-2-38-VM"]}}
> 2014-02-10 14:35:22,617 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) << Response Status: HTTP/1.1 200 OK
> 2014-02-10 14:35:22,617 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) >> Request: GET, /virtual-machine-interface/3af83c55-31f9-4253-971e-6abfa45e60f0
> 2014-02-10 14:35:22,627 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) << Response Status: HTTP/1.1 200 OK
> 2014-02-10 14:35:22,629 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) >> Request: PUT, /virtual-machine-interface/3af83c55-31f9-4253-971e-6abfa45e60f0, {"virtual-machine-interface":{"virtual_machine_interface_mac_addresses":{"mac_address":["02:3a:f8:3c:55:31"]},"virtual_network_refs":[{"to":["default-domain","default-project","second"],"attr":null,"href":"http://10.223.58.3:8082/virtual-network/738782df-1a33-4336-b09e-a1752571a4ac","uuid":"738782df-1a33-4336-b09e-a1752571a4ac"}],"name":"i-2-38-VM-0","uuid":"3af83c55-31f9-4253-971e-6abfa45e60f0","fq_name":["i-2-38-VM","i-2-38-VM-0"],"parent_type":"virtual-machine","parent_uuid":"6034fed3-bac7-4267-874b-fdbcdd58f610"}}
> 2014-02-10 14:35:22,644 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) << Response Status: HTTP/1.1 200 OK
> 2014-02-10 14:35:22,644 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) >> Request: GET, /virtual-machine-interface/3af83c55-31f9-4253-971e-6abfa45e60f0
> 2014-02-10 14:35:22,654 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) << Response Status: HTTP/1.1 200 OK
> 2014-02-10 14:35:22,655 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) >> Request: POST, /fqname-to-id, {"type":"instance-ip","fq_name":["i-2-38-VM-0"]}
> 2014-02-10 14:35:22,663 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) << Response Status: HTTP/1.1 200 OK
> 2014-02-10 14:35:22,663 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) >> Request: GET, /instance-ip/70ca54d1-3015-4255-b066-780fe7ef7629
> 2014-02-10 14:35:22,686 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) << Response Status: HTTP/1.1 200 OK
> 2014-02-10 14:35:22,687 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) >> Request: GET, /instance-ip/70ca54d1-3015-4255-b066-780fe7ef7629
> 2014-02-10 14:35:22,696 INFO [n.j.c.a.ApiConnector] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) << Response Status: HTTP/1.1 200 OK
> 2014-02-10 14:35:22,699 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Changing active number of nics for network id=205 on 1
> 2014-02-10 14:35:22,707 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Asking ContrailElement to prepare for Nic[142-38-45e9298d-313c-4b27-aa91-b8479a883c7b-10.10.255.252]
> 2014-02-10 14:35:22,708 DEBUG [o.a.c.n.c.m.ContrailElement] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) NetworkElement prepare: second, traffic type: Guest
> 2014-02-10 14:35:22,708 DEBUG [o.a.c.n.c.m.ContrailElement] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) ignore network second
> 2014-02-10 14:35:22,712 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the network id=205
> 2014-02-10 14:35:22,712 DEBUG [o.a.c.n.c.m.ContrailGuru] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) update NicProfile 142 on second
> 2014-02-10 14:35:22,714 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Checking if we need to prepare 1 volumes for VM[User|third]
> 2014-02-10 14:35:22,715 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) No need to recreate the volume: Vol[38|vm=38|ROOT], since it already has a pool assigned: 16, adding disk to VM
> 2014-02-10 14:35:22,768 DEBUG [c.c.a.t.Request] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Seq 2-1390027709: Sending { Cmd , MgmtId: 214151488957798, via: 2(xenserver-1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":38,"name":"i-2-38-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Other (32-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"15880c1b484a43f2","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"6034fed3-bac7-4267-874b-fdbcdd58f610","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6e50be3d-0af9-4865-9e44-2ef4ae48b487","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e028b7db4","id":16,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/contrail/cloudstack_58_4/primary","port":2049,"url":"NetworkFilesystem://10.223.110.232//export/home/parth/contrail/cloudstack_58_4/primary/?ROLE=Primary&STOREUUID=4233346b-ca53-3691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","volumeId":38,"vmName":"i-2-38-VM","accountId":2,"format":"VHD","id":38,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"10.223.110.232","volumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3af83c55-31f9-4253-971e-6abfa45e60f0","ip":"10.10.255.252","netmask":"255.255.0.0","gateway":"10.10.1.1","mac":"02:3a:f8:3c:55:31","broadcastType":"Lswitch","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":false}]},"hostIp":"10.223.58.66","executeInSequence":false,"wait":0}}] }
> 2014-02-10 14:35:22,769 DEBUG [c.c.a.t.Request] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Seq 2-1390027709: Executing: { Cmd , MgmtId: 214151488957798, via: 2(xenserver-1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":38,"name":"i-2-38-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Other (32-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"15880c1b484a43f2","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"6034fed3-bac7-4267-874b-fdbcdd58f610","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6e50be3d-0af9-4865-9e44-2ef4ae48b487","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e028b7db4","id":16,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/contrail/cloudstack_58_4/primary","port":2049,"url":"NetworkFilesystem://10.223.110.232//export/home/parth/contrail/cloudstack_58_4/primary/?ROLE=Primary&STOREUUID=4233346b-ca53-3691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","volumeId":38,"vmName":"i-2-38-VM","accountId":2,"format":"VHD","id":38,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"10.223.110.232","volumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3af83c55-31f9-4253-971e-6abfa45e60f0","ip":"10.10.255.252","netmask":"255.255.0.0","gateway":"10.10.1.1","mac":"02:3a:f8:3c:55:31","broadcastType":"Lswitch","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":false}]},"hostIp":"10.223.58.66","executeInSequence":false,"wait":0}}] }
> 2014-02-10 14:35:22,769 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-338:ctx-a3e2b740) Seq 2-1390027709: Executing request
> 2014-02-10 14:35:22,839 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-338:ctx-a3e2b740) 1. The VM i-2-38-VM is in Starting state.
> 2014-02-10 14:35:22,861 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-338:ctx-a3e2b740) Created VM b846d7f2-53e7-a02d-6679-61896d2ebfad for i-2-38-VM
> 2014-02-10 14:35:22,876 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-338:ctx-a3e2b740) VBD d270a800-599f-91f1-423d-58ca4920b099 created for com.cloud.agent.api.to.DiskTO@674cf7c0
> 2014-02-10 14:35:22,882 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-338:ctx-a3e2b740) VBD eb9e7646-4ae3-8f70-088d-5352f455b2ca created for com.cloud.agent.api.to.DiskTO@6e1d933b
> 2014-02-10 14:35:22,882 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-338:ctx-a3e2b740) Creating VIF for i-2-38-VM on nic [Nic:Guest-10.10.255.252-vlan://untagged]
> 2014-02-10 14:35:22,900 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-338:ctx-a3e2b740) Created a vif 9c833078-b34f-5cb0-7054-b6434908ebd8 on 0
> 2014-02-10 14:35:24,917 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-338:ctx-a3e2b740) 2. The VM i-2-38-VM is in Running state.
> 2014-02-10 14:35:24,917 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-338:ctx-a3e2b740) Seq 2-1390027709: Response Received:
> 2014-02-10 14:35:24,918 DEBUG [c.c.a.t.Request] (DirectAgent-338:ctx-a3e2b740) Seq 2-1390027709: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":38,"name":"i-2-38-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Other (32-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"15880c1b484a43f2","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"6034fed3-bac7-4267-874b-fdbcdd58f610","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6e50be3d-0af9-4865-9e44-2ef4ae48b487","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e028b7db4","id":16,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/contrail/cloudstack_58_4/primary","port":2049,"url":"NetworkFilesystem://10.223.110.232//export/home/parth/contrail/cloudstack_58_4/primary/?ROLE=Primary&STOREUUID=4233346b-ca53-3691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","volumeId":38,"vmName":"i-2-38-VM","accountId":2,"format":"VHD","id":38,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"10.223.110.232","volumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3af83c55-31f9-4253-971e-6abfa45e60f0","ip":"10.10.255.252","netmask":"255.255.0.0","gateway":"10.10.1.1","mac":"02:3a:f8:3c:55:31","broadcastType":"Lswitch","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":false}]},"_iqnToPath":{},"result":true,"wait":0}}] }
> 2014-02-10 14:35:24,918 DEBUG [c.c.a.t.Request] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Seq 2-1390027709: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { StartAnswer } }
> 2014-02-10 14:35:24,962 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) VM state transitted from :Starting to Running with event: OperationSucceededvm's original host id: 2 new host id: 2 host id before state transition: 2
> 2014-02-10 14:35:24,982 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the network id=205
> 2014-02-10 14:35:24,984 DEBUG [o.a.c.n.c.m.ContrailGuru] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) update NicProfile 142 on second
> 2014-02-10 14:35:24,987 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the network id=205
> 2014-02-10 14:35:24,987 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Start completed for VM VM[User|third]
> 2014-02-10 14:35:25,001 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-34:ctx-2cf0628d ctx-216f60ab) Complete async job-60, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmResponse/virtualmachine/{"id":"6034fed3-bac7-4267-874b-fdbcdd58f610","name":"third","displayname":"third","account":"admin","domainid":"4a015670-8ec0-11e3-8ad7-c2c5076d6d66","domain":"ROOT","created":"2014-02-10T10:35:54-0800","state":"Running","haenable":false,"zoneid":"cce32d06-91d9-47f0-90b5-766416d6add2","zonename":"default","hostid":"a21fbbe7-e135-403f-9060-da68096071b2","hostname":"xenserver-1","templateid":"650e4b87-01bc-437b-97a5-76f3b1636e8b","templatename":"DSL","templatedisplaytext":"Damn Small Linux","passwordenabled":false,"serviceofferingid":"d432fb45-b4c4-4560-b66d-c74094093dce","serviceofferingname":"Small Instance","cpunumber":1,"cpuspeed":500,"memory":512,"cpuused":"0.02%","networkkbsread":2,"networkkbswrite":3,"diskkbsread":0,"diskkbswrite":0,"diskioread":0,"diskiowrite":0,"guestosid":"4a19748a-8ec0-11e3-8ad7-c2c5076d6d66","rootdeviceid":0,"rootdevicetype":"ROOT","securitygroup":[],"nic":[{"id":"3af83c55-31f9-4253-971e-6abfa45e60f0","networkid":"738782df-1a33-4336-b09e-a1752571a4ac","networkname":"second","netmask":"255.255.0.0","gateway":"10.10.1.1","ipaddress":"10.10.255.252","broadcasturi":"vlan://untagged","traffictype":"Guest","type":"Isolated","isdefault":true,"macaddress":"02:3a:f8:3c:55:31"}],"hypervisor":"XenServer","instancename":"i-2-38-VM","tags":[],"affinitygroup":[],"displayvm":true,"isdynamicallyscalable":false,"jobid":"aec81d05-d58b-43eb-ac11-3dcc682f69ea","jobstatus":0}
> 2014-02-10 14:35:25,006 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-34:ctx-2cf0628d) Done executing org.apache.cloudstack.api.command.user.vm.StartVMCmd for job-60
> 2014-02-10 14:35:25,022 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-34:ctx-2cf0628d) Remove job-60 from job monitoring
> 2014-02-10 14:35:25,523 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-23cf9a02) ===START=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=aec81d05-d58b-43eb-ac11-3dcc682f69ea&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076430675
> 2014-02-10 14:35:25,543 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-23cf9a02 ctx-fd46c89c) ===END=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=aec81d05-d58b-43eb-ac11-3dcc682f69ea&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076430675
> 2014-02-10 14:35:27,769 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-45282: Processing Seq 3-45282: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:35:27,773 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-45282: Sending Seq 3-45282: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:35:30,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7a7df25d) Found 0 routers to update status.
> 2014-02-10 14:35:30,032 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7a7df25d) Found 0 networks to update RvR status.
> 2014-02-10 14:35:32,769 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-45283: Processing Seq 3-45283: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:35:32,773 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-45283: Sending Seq 3-45283: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:35:34,106 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-989dd76a) StorageCollector is running...
> 2014-02-10 14:35:34,216 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-989dd76a) Seq 4-761272172: Received: { Ans: , MgmtId: 214151488957798, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:35:34,220 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-52:ctx-8ab0ec56) Seq 1-1759117339: Executing request
> 2014-02-10 14:35:34,525 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-52:ctx-8ab0ec56) Seq 1-1759117339: Response Received:
> 2014-02-10 14:35:34,525 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-989dd76a) Seq 1-1759117339: Received: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:35:37,932 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-338:ctx-bb97fb86) Ping from 1(xenserver-2)
> 2014-02-10 14:35:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-52:ctx-5de63ca4) Seq 1-1759117314: Executing request
> 2014-02-10 14:35:38,184 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-52:ctx-5de63ca4) Seq 1-1759117314: Response Received:
> 2014-02-10 14:35:38,185 DEBUG [c.c.a.t.Request] (DirectAgent-52:ctx-5de63ca4) Seq 1-1759117314: Processing: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-02-10 14:35:38,417 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-418:ctx-efd4a8c1) Ping from 2(xenserver-1)
> 2014-02-10 14:35:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-338:ctx-65668ed5) Seq 2-1390018562: Executing request
> 2014-02-10 14:35:39,037 WARN [c.c.h.x.r.CitrixResourceBase] (DirectAgent-338:ctx-65668ed5) Detecting a change in platform for i-2-38-VM
> 2014-02-10 14:35:39,037 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-338:ctx-65668ed5) 11. The VM i-2-38-VM is in Running state
> 2014-02-10 14:35:39,037 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-338:ctx-65668ed5) Seq 2-1390018562: Response Received:
> 2014-02-10 14:35:39,038 DEBUG [c.c.a.t.Request] (DirectAgent-338:ctx-65668ed5) Seq 2-1390018562: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{"i-2-38-VM":{"t":"335fb70f-e798-405b-b274-12053bc43051","u":"Running","v":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0"}},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:35:39,042 DEBUG [c.c.v.VirtualMachineManagerImpl] (DirectAgent-338:ctx-65668ed5) VM i-2-38-VM: cs state = Running and realState = Running
> 2014-02-10 14:35:39,042 DEBUG [c.c.v.VirtualMachineManagerImpl] (DirectAgent-338:ctx-65668ed5) VM i-2-38-VM: cs state = Running and realState = Running
> 2014-02-10 14:35:39,048 DEBUG [c.c.v.VirtualMachineManagerImpl] (DirectAgent-338:ctx-65668ed5) Both states are Running for VM[User|third]
> 2014-02-10 14:35:39,050 DEBUG [c.c.c.CapacityManagerImpl] (DirectAgent-338:ctx-65668ed5) VM state transitted from :Running to Running with event: AgentReportRunningvm's original host id: 2 new host id: 2 host id before state transition: 2
> 2014-02-10 14:35:42,772 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-45284: Processing Seq 3-45284: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:35:42,776 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-45284: Sending Seq 3-45284: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:35:42,785 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-07e5d42c) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:35:42,786 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-7c608efe) Zone 1 is ready to launch console proxy
> 2014-02-10 14:35:47,568 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-9:null) Ping from 4
> 2014-02-10 14:35:52,771 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-45285: Processing Seq 3-45285: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:35:52,775 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-45285: Sending Seq 3-45285: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:35:54,987 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 3
> 2014-02-10 14:35:57,993 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-eede9c08) VmStatsCollector is running...
> 2014-02-10 14:35:58,014 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-271:ctx-ad3bede0) Seq 2-1390027710: Executing request
> 2014-02-10 14:35:58,224 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-271:ctx-ad3bede0) Vm cpu utilization 0.0
> 2014-02-10 14:35:58,224 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-271:ctx-ad3bede0) Vm cpu utilization 0.027343750000000003
> 2014-02-10 14:35:58,224 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-271:ctx-ad3bede0) Vm cpu utilization 0.023593749999999997
> 2014-02-10 14:35:58,236 WARN [c.c.h.x.r.CitrixResourceBase] (DirectAgent-271:ctx-ad3bede0) Error while collecting disk stats from :
> You gave an invalid object reference. The object may have recently been deleted. The class parameter gives the type of reference given, and the handle parameter echoes the bad value given.
> at com.xensource.xenapi.Types.checkResponse(Types.java:209)
> at com.xensource.xenapi.Connection.dispatch(Connection.java:368)
> at com.cloud.hypervisor.xen.resource.XenServerConnectionPool$XenServerConnection.dispatch(XenServerConnectionPool.java:909)
> at com.xensource.xenapi.VBDMetrics.getIoReadKbs(VBDMetrics.java:210)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVmStats(CitrixResourceBase.java:2841)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2741)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:493)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
> at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:35:58,238 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-271:ctx-ad3bede0) Seq 2-1390027710: Response Received:
> 2014-02-10 14:35:58,238 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-eede9c08) Seq 2-1390027710: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2014-02-10 14:35:59,979 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-20359feb) HostStatsCollector is running...
> 2014-02-10 14:35:59,988 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-259:ctx-b19fadf9) Seq 1-1759117340: Executing request
> 2014-02-10 14:36:00,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-bac1ba7c) Found 0 routers to update status.
> 2014-02-10 14:36:00,032 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-bac1ba7c) Found 0 networks to update RvR status.
> 2014-02-10 14:36:00,211 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-259:ctx-b19fadf9) Seq 1-1759117340: Response Received:
> 2014-02-10 14:36:00,212 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-20359feb) Seq 1-1759117340: Received: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:36:00,221 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-203:ctx-1e63f5f9) Seq 2-1390027711: Executing request
> 2014-02-10 14:36:00,409 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-203:ctx-1e63f5f9) Seq 2-1390027711: Response Received:
> 2014-02-10 14:36:00,409 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-20359feb) Seq 2-1390027711: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:36:02,772 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-45287: Processing Seq 3-45287: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:36:02,776 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-45287: Sending Seq 3-45287: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:12,753 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-9dd28416) Zone 1 is ready to launch console proxy
> 2014-02-10 14:36:12,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-2b660ae7) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:36:12,773 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-45288: Processing Seq 3-45288: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:36:12,777 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-45288: Sending Seq 3-45288: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:13,912 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-c898f845) ===START=== 10.215.2.19 -- GET command=listVirtualMachines&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=true&page=1&pagesize=20&_=1392076479071
> 2014-02-10 14:36:13,940 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-c898f845 ctx-3038fc02) ===END=== 10.215.2.19 -- GET command=listVirtualMachines&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=true&page=1&pagesize=20&_=1392076479071
> 2014-02-10 14:36:14,760 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-687e292b) ===START=== 10.215.2.19 -- GET command=listVirtualMachines&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=true&page=1&pagesize=20&_=1392076479932
> 2014-02-10 14:36:14,787 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-687e292b ctx-9a11abc8) ===END=== 10.215.2.19 -- GET command=listVirtualMachines&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=true&page=1&pagesize=20&_=1392076479932
> 2014-02-10 14:36:16,304 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-9d17994c) ===START=== 10.215.2.19 -- GET command=listZones&id=cce32d06-91d9-47f0-90b5-766416d6add2&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076481491
> 2014-02-10 14:36:16,316 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-9d17994c ctx-27f700b1) ===END=== 10.215.2.19 -- GET command=listZones&id=cce32d06-91d9-47f0-90b5-766416d6add2&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076481491
> 2014-02-10 14:36:16,365 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-e93bc823) ===START=== 10.215.2.19 -- GET command=listVirtualMachines&id=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076481542
> 2014-02-10 14:36:16,389 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-e93bc823 ctx-13509922) ===END=== 10.215.2.19 -- GET command=listVirtualMachines&id=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076481542
> 2014-02-10 14:36:16,476 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-a6d15571) ===START=== 10.215.2.19 -- GET command=listOsTypes&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076481609
> 2014-02-10 14:36:16,703 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-a6d15571 ctx-6fddc9c6) ===END=== 10.215.2.19 -- GET command=listOsTypes&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076481609
> 2014-02-10 14:36:19,180 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-eda1d458) ===START=== 10.215.2.19 -- GET command=findHostsForMigration&VirtualMachineId=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076484388
> 2014-02-10 14:36:19,198 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2014-02-10 14:36:19,198 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) ClusterScopeStoragePoolAllocator looking for storage pool
> 2014-02-10 14:36:19,198 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Looking for pools in dc: 1 pod:1 cluster:1
> 2014-02-10 14:36:19,200 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Found pools matching tags: [Pool[16|NetworkFilesystem]]
> 2014-02-10 14:36:19,201 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Removing pool Pool[16|NetworkFilesystem] from avoid set, must have been inserted when searching for another disk's tag
> 2014-02-10 14:36:19,202 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Checking if storage pool is suitable, name: null ,poolId: 16
> 2014-02-10 14:36:19,206 DEBUG [c.c.s.StorageManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Checking pool 16 for storage, totalSize: 11810778316800, usedBytes: 8001863122944, usedPct: 0.6775051489673558, disable threshold: 0.85
> 2014-02-10 14:36:19,210 DEBUG [c.c.s.StorageManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Checking pool: 16 for volume allocation [Vol[38|vm=38|ROOT]], maxSize : 23621556633600, totalAllocatedSize : 26591887360, askingSize : 0, allocated disable threshold: 0.85
> 2014-02-10 14:36:19,210 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
> 2014-02-10 14:36:19,213 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
> 2014-02-10 14:36:19,214 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
> 2014-02-10 14:36:19,214 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Looking for speed=500Mhz, Ram=512
> 2014-02-10 14:36:19,217 DEBUG [c.c.c.CapacityManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Host: 1 has cpu capability (cpu:4, speed:2261) to support requested CPU: 1 and requested speed: 500
> 2014-02-10 14:36:19,217 DEBUG [c.c.c.CapacityManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
> 2014-02-10 14:36:19,218 DEBUG [c.c.c.CapacityManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-02-10 14:36:19,218 DEBUG [c.c.c.CapacityManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) considerReservedCapacity isfalse , not considering reserved capacity for calculating free capacity
> 2014-02-10 14:36:19,218 DEBUG [c.c.c.CapacityManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Free CPU: 9044 , Requested CPU: 500
> 2014-02-10 14:36:19,219 DEBUG [c.c.c.CapacityManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Free RAM: 16001258496 , Requested RAM: 536870912
> 2014-02-10 14:36:19,219 DEBUG [c.c.c.CapacityManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Host has enough CPU and RAM available
> 2014-02-10 14:36:19,219 DEBUG [c.c.c.CapacityManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) STATS: Can alloc CPU from host: 1, used: 0, reserved: 0, actual total: 9044, total with overprovisioning: 9044; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2014-02-10 14:36:19,219 DEBUG [c.c.c.CapacityManagerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) STATS: Can alloc MEM from host: 1, used: 0, reserved: 0, total: 16001258496; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: false
> 2014-02-10 14:36:19,219 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Found a suitable host, adding to list: 1
> 2014-02-10 14:36:19,219 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Host Allocator returning 1 suitable hosts
> 2014-02-10 14:36:19,219 DEBUG [c.c.s.ManagementServerImpl] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) Hosts having capacity and suitable for migration: [Host[-1-Routing]]
> 2014-02-10 14:36:19,227 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-eda1d458 ctx-c51c162b) ===END=== 10.215.2.19 -- GET command=findHostsForMigration&VirtualMachineId=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076484388
> 2014-02-10 14:36:22,774 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-45289: Processing Seq 3-45289: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:36:22,779 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-45289: Sending Seq 3-45289: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:28,303 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-574467ad) ===START=== 10.215.2.19 -- GET command=migrateVirtualMachine&hostid=4e27ed8b-42b7-42c1-b5eb-4b41a0dc7348&virtualmachineid=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076493503
> 2014-02-10 14:36:28,374 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-5:ctx-574467ad ctx-e37bc423) submit async job-61, details: AsyncJobVO {id:61, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd, cmdInfo: {"response":"json","sessionkey":"gJbfxiFXGjIJTBqBPlcyevZSM1g\u003d","virtualmachineid":"6034fed3-bac7-4267-874b-fdbcdd58f610","cmdEventType":"VM.MIGRATE","hostid":"4e27ed8b-42b7-42c1-b5eb-4b41a0dc7348","ctxUserId":"2","httpmethod":"GET","_":"1392076493503","ctxAccountId":"2","ctxStartEventId":"224"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 214151488957798, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2014-02-10 14:36:28,377 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-574467ad ctx-e37bc423) ===END=== 10.215.2.19 -- GET command=migrateVirtualMachine&hostid=4e27ed8b-42b7-42c1-b5eb-4b41a0dc7348&virtualmachineid=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076493503
> 2014-02-10 14:36:28,377 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-35:ctx-3af15cd6) Add job-61 into job monitoring
> 2014-02-10 14:36:28,377 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-35:ctx-3af15cd6) Executing AsyncJobVO {id:61, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd, cmdInfo: {"response":"json","sessionkey":"gJbfxiFXGjIJTBqBPlcyevZSM1g\u003d","virtualmachineid":"6034fed3-bac7-4267-874b-fdbcdd58f610","cmdEventType":"VM.MIGRATE","hostid":"4e27ed8b-42b7-42c1-b5eb-4b41a0dc7348","ctxUserId":"2","httpmethod":"GET","_":"1392076493503","ctxAccountId":"2","ctxStartEventId":"224"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 214151488957798, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2014-02-10 14:36:28,424 INFO [c.c.v.VirtualMachineManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Migrating VM[User|third] to Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
> 2014-02-10 14:36:28,436 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Service SecurityGroup is not supported in the network id=205
> 2014-02-10 14:36:28,439 DEBUG [o.a.c.n.c.m.ContrailGuru] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) update NicProfile 142 on second
> 2014-02-10 14:36:28,450 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Service SecurityGroup is not supported in the network id=205
> 2014-02-10 14:36:28,456 DEBUG [o.a.c.n.c.m.ContrailGuru] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) update NicProfile 142 on second
> 2014-02-10 14:36:28,458 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Preparing 1 volumes for VM[User|third]
> 2014-02-10 14:36:28,475 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) template 202 is already in store:1, type:Image
> 2014-02-10 14:36:28,490 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Seq 1-1759117341: Sending { Cmd , MgmtId: 214151488957798, via: 1(xenserver-2), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.PrepareForMigrationCommand":{"vm":{"id":38,"name":"i-2-38-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Other (32-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"15880c1b484a43f2","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"6034fed3-bac7-4267-874b-fdbcdd58f610","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6e50be3d-0af9-4865-9e44-2ef4ae48b487","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e028b7db4","id":16,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/contrail/cloudstack_58_4/primary","port":2049,"url":"NetworkFilesystem://10.223.110.232//export/home/parth/contrail/cloudstack_58_4/primary/?ROLE=Primary&STOREUUID=4233346b-ca53-3691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","volumeId":38,"vmName":"i-2-38-VM","accountId":2,"format":"VHD","id":38,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"10.223.110.232","volumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/202/202-2-76a7bc62-9209-37ef-9d68-3ce9eeb60cab.iso","origUrl":"http://nfs1.lab.vmops.com/parth/DSL_current.iso","uuid":"650e4b87-01bc-437b-97a5-76f3b1636e8b","id":202,"format":"ISO","accountId":2,"checksum":"5cb7e0d4506c249b78bbe0cd4695b865","hvm":true,"displayText":"Damn Small Linux","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232:/export/home/parth/contrail/cloudstack_58_4/secondary","_role":"Image"}},"name":"202-2-76a7bc62-9209-37ef-9d68-3ce9eeb60cab","hypervisorType":"None"}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3af83c55-31f9-4253-971e-6abfa45e60f0","ip":"10.10.255.252","netmask":"255.255.0.0","gateway":"10.10.1.1","mac":"02:3a:f8:3c:55:31","broadcastType":"Lswitch","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
> 2014-02-10 14:36:28,492 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Seq 1-1759117341: Executing: { Cmd , MgmtId: 214151488957798, via: 1(xenserver-2), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.PrepareForMigrationCommand":{"vm":{"id":38,"name":"i-2-38-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Other (32-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"15880c1b484a43f2","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"6034fed3-bac7-4267-874b-fdbcdd58f610","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6e50be3d-0af9-4865-9e44-2ef4ae48b487","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e028b7db4","id":16,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/contrail/cloudstack_58_4/primary","port":2049,"url":"NetworkFilesystem://10.223.110.232//export/home/parth/contrail/cloudstack_58_4/primary/?ROLE=Primary&STOREUUID=4233346b-ca53-3691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","volumeId":38,"vmName":"i-2-38-VM","accountId":2,"format":"VHD","id":38,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"10.223.110.232","volumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/202/202-2-76a7bc62-9209-37ef-9d68-3ce9eeb60cab.iso","origUrl":"http://nfs1.lab.vmops.com/parth/DSL_current.iso","uuid":"650e4b87-01bc-437b-97a5-76f3b1636e8b","id":202,"format":"ISO","accountId":2,"checksum":"5cb7e0d4506c249b78bbe0cd4695b865","hvm":true,"displayText":"Damn Small Linux","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232:/export/home/parth/contrail/cloudstack_58_4/secondary","_role":"Image"}},"name":"202-2-76a7bc62-9209-37ef-9d68-3ce9eeb60cab","hypervisorType":"None"}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3af83c55-31f9-4253-971e-6abfa45e60f0","ip":"10.10.255.252","netmask":"255.255.0.0","gateway":"10.10.1.1","mac":"02:3a:f8:3c:55:31","broadcastType":"Lswitch","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
> 2014-02-10 14:36:28,492 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-415:ctx-34ae4b0a) Seq 1-1759117341: Executing request
> 2014-02-10 14:36:28,574 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-415:ctx-34ae4b0a) Preparing host for migrating com.cloud.agent.api.to.VirtualMachineTO@c97e544
> 2014-02-10 14:36:28,587 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-415:ctx-34ae4b0a) 4. The VM i-2-38-VM is in Migrating state
> 2014-02-10 14:36:28,587 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-415:ctx-34ae4b0a) Seq 1-1759117341: Response Received:
> 2014-02-10 14:36:28,587 DEBUG [c.c.a.t.Request] (DirectAgent-415:ctx-34ae4b0a) Seq 1-1759117341: Processing: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.PrepareForMigrationAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:28,588 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Seq 1-1759117341: Received: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 110, { PrepareForMigrationAnswer } }
> 2014-02-10 14:36:28,590 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-415:ctx-34ae4b0a) Seq 1-1759117341: No more commands found
> 2014-02-10 14:36:28,613 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) VM state transitted from :Running to Migrating with event: MigrationRequestedvm's original host id: 2 new host id: 1 host id before state transition: 2
> 2014-02-10 14:36:28,622 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-02-10 14:36:28,622 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) We are allocating VM, increasing the used capacity of this host:1
> 2014-02-10 14:36:28,622 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Current Used CPU: 0 , Free CPU:9044 ,Requested CPU: 500
> 2014-02-10 14:36:28,622 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Current Used RAM: 0 , Free RAM:16001258496 ,Requested RAM: 536870912
> 2014-02-10 14:36:28,622 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) CPU STATS after allocation: for host: 1, old used: 0, old reserved: 0, actual total: 9044, total with overprovisioning: 9044; new used:500, reserved:0; requested cpu:500,alloc_from_last:false
> 2014-02-10 14:36:28,622 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) RAM STATS after allocation: for host: 1, old used: 0, old reserved: 0, total: 16001258496; new used: 536870912, reserved: 0; requested mem: 536870912,alloc_from_last:false
> 2014-02-10 14:36:28,631 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Seq 2-1390027712: Sending { Cmd , MgmtId: 214151488957798, via: 2(xenserver-1), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.MigrateCommand":{"vmName":"i-2-38-VM","destIp":"10.223.58.67","hostGuid":"8e944da8-3f1d-424e-8cff-ea03b5be0689","isWindows":false,"vmTO":{"id":38,"name":"i-2-38-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Other (32-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"15880c1b484a43f2","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"6034fed3-bac7-4267-874b-fdbcdd58f610","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6e50be3d-0af9-4865-9e44-2ef4ae48b487","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e028b7db4","id":16,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/contrail/cloudstack_58_4/primary","port":2049,"url":"NetworkFilesystem://10.223.110.232//export/home/parth/contrail/cloudstack_58_4/primary/?ROLE=Primary&STOREUUID=4233346b-ca53-3691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","volumeId":38,"vmName":"i-2-38-VM","accountId":2,"format":"VHD","id":38,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"10.223.110.232","volumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/202/202-2-76a7bc62-9209-37ef-9d68-3ce9eeb60cab.iso","origUrl":"http://nfs1.lab.vmops.com/parth/DSL_current.iso","uuid":"650e4b87-01bc-437b-97a5-76f3b1636e8b","id":202,"format":"ISO","accountId":2,"checksum":"5cb7e0d4506c249b78bbe0cd4695b865","hvm":true,"displayText":"Damn Small Linux","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232:/export/home/parth/contrail/cloudstack_58_4/secondary","_role":"Image"}},"name":"202-2-76a7bc62-9209-37ef-9d68-3ce9eeb60cab","hypervisorType":"None"}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3af83c55-31f9-4253-971e-6abfa45e60f0","ip":"10.10.255.252","netmask":"255.255.0.0","gateway":"10.10.1.1","mac":"02:3a:f8:3c:55:31","broadcastType":"Lswitch","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
> 2014-02-10 14:36:28,632 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Seq 2-1390027712: Executing: { Cmd , MgmtId: 214151488957798, via: 2(xenserver-1), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.MigrateCommand":{"vmName":"i-2-38-VM","destIp":"10.223.58.67","hostGuid":"8e944da8-3f1d-424e-8cff-ea03b5be0689","isWindows":false,"vmTO":{"id":38,"name":"i-2-38-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Other (32-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"15880c1b484a43f2","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"6034fed3-bac7-4267-874b-fdbcdd58f610","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6e50be3d-0af9-4865-9e44-2ef4ae48b487","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e028b7db4","id":16,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/contrail/cloudstack_58_4/primary","port":2049,"url":"NetworkFilesystem://10.223.110.232//export/home/parth/contrail/cloudstack_58_4/primary/?ROLE=Primary&STOREUUID=4233346b-ca53-3691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","volumeId":38,"vmName":"i-2-38-VM","accountId":2,"format":"VHD","id":38,"deviceId":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"10.223.110.232","volumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/202/202-2-76a7bc62-9209-37ef-9d68-3ce9eeb60cab.iso","origUrl":"http://nfs1.lab.vmops.com/parth/DSL_current.iso","uuid":"650e4b87-01bc-437b-97a5-76f3b1636e8b","id":202,"format":"ISO","accountId":2,"checksum":"5cb7e0d4506c249b78bbe0cd4695b865","hvm":true,"displayText":"Damn Small Linux","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232:/export/home/parth/contrail/cloudstack_58_4/secondary","_role":"Image"}},"name":"202-2-76a7bc62-9209-37ef-9d68-3ce9eeb60cab","hypervisorType":"None"}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3af83c55-31f9-4253-971e-6abfa45e60f0","ip":"10.10.255.252","netmask":"255.255.0.0","gateway":"10.10.1.1","mac":"02:3a:f8:3c:55:31","broadcastType":"Lswitch","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
> 2014-02-10 14:36:28,633 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-412:ctx-14b2649a) Seq 2-1390027712: Executing request
> 2014-02-10 14:36:28,706 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-412:ctx-14b2649a) 5. The VM i-2-38-VM is in Stopping state
> 2014-02-10 14:36:29,729 WARN [c.c.h.x.r.CitrixResourceBase] (DirectAgent-412:ctx-14b2649a) Task failed! Task record: uuid: 3456c28d-1c6f-ad87-1c7f-a444b32f87a3
> nameLabel: Async.VM.pool_migrate
> nameDescription:
> allowedOperations: []
> currentOperations: {}
> created: Mon Feb 10 15:52:07 PST 2014
> finished: Mon Feb 10 15:52:07 PST 2014
> status: failure
> residentOn: com.xensource.xenapi.Host@f44e28e6
> progress: 1.0
> type: <none/>
> result:
> errorInfo: [VM_BAD_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, running, halted]
> otherConfig: {}
> subtaskOf: com.xensource.xenapi.Task@aaf13f6f
> subtasks: []
> 2014-02-10 14:36:29,732 WARN [c.c.h.x.r.CitrixResourceBase] (DirectAgent-412:ctx-14b2649a) Unable to migrate VM(i-2-38-VM) from host(335fb70f-e798-405b-b274-12053bc43051) due to Task failed! Task record: uuid: 3456c28d-1c6f-ad87-1c7f-a444b32f87a3
> nameLabel: Async.VM.pool_migrate
> nameDescription:
> allowedOperations: []
> currentOperations: {}
> created: Mon Feb 10 15:52:07 PST 2014
> finished: Mon Feb 10 15:52:07 PST 2014
> status: failure
> residentOn: com.xensource.xenapi.Host@f44e28e6
> progress: 1.0
> type: <none/>
> result:
> errorInfo: [VM_BAD_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, running, halted]
> otherConfig: {}
> subtaskOf: com.xensource.xenapi.Task@aaf13f6f
> subtasks: []
> Task failed! Task record: uuid: 3456c28d-1c6f-ad87-1c7f-a444b32f87a3
> nameLabel: Async.VM.pool_migrate
> nameDescription:
> allowedOperations: []
> currentOperations: {}
> created: Mon Feb 10 15:52:07 PST 2014
> finished: Mon Feb 10 15:52:07 PST 2014
> status: failure
> residentOn: com.xensource.xenapi.Host@f44e28e6
> progress: 1.0
> type: <none/>
> result:
> errorInfo: [VM_BAD_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, running, halted]
> otherConfig: {}
> subtaskOf: com.xensource.xenapi.Task@aaf13f6f
> subtasks: []
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.checkForSuccess(CitrixResourceBase.java:3742)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.migrateVM(CitrixResourceBase.java:3888)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:3446)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:509)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
> at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:36:29,735 WARN [c.c.h.x.r.CitrixResourceBase] (DirectAgent-412:ctx-14b2649a) Catch Exception com.cloud.utils.exception.CloudRuntimeException: Migration failed due to com.cloud.utils.exception.CloudRuntimeException: Unable to migrate VM(i-2-38-VM) from host(335fb70f-e798-405b-b274-12053bc43051) due to Task failed! Task record: uuid: 3456c28d-1c6f-ad87-1c7f-a444b32f87a3
> nameLabel: Async.VM.pool_migrate
> nameDescription:
> allowedOperations: []
> currentOperations: {}
> created: Mon Feb 10 15:52:07 PST 2014
> finished: Mon Feb 10 15:52:07 PST 2014
> status: failure
> residentOn: com.xensource.xenapi.Host@f44e28e6
> progress: 1.0
> type: <none/>
> result:
> errorInfo: [VM_BAD_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, running, halted]
> otherConfig: {}
> subtaskOf: com.xensource.xenapi.Task@aaf13f6f
> subtasks: []
> com.cloud.utils.exception.CloudRuntimeException: Unable to migrate VM(i-2-38-VM) from host(335fb70f-e798-405b-b274-12053bc43051) due to Task failed! Task record: uuid: 3456c28d-1c6f-ad87-1c7f-a444b32f87a3
> nameLabel: Async.VM.pool_migrate
> nameDescription:
> allowedOperations: []
> currentOperations: {}
> created: Mon Feb 10 15:52:07 PST 2014
> finished: Mon Feb 10 15:52:07 PST 2014
> status: failure
> residentOn: com.xensource.xenapi.Host@f44e28e6
> progress: 1.0
> type: <none/>
> result:
> errorInfo: [VM_BAD_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, running, halted]
> otherConfig: {}
> subtaskOf: com.xensource.xenapi.Task@aaf13f6f
> subtasks: []
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.migrateVM(CitrixResourceBase.java:3899)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:3446)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:509)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
> at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:36:29,736 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-412:ctx-14b2649a) 6. The VM i-2-38-VM is in Migrating state
> 2014-02-10 14:36:29,736 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-412:ctx-14b2649a) Seq 2-1390027712: Response Received:
> 2014-02-10 14:36:29,737 DEBUG [c.c.a.t.Request] (DirectAgent-412:ctx-14b2649a) Seq 2-1390027712: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.MigrateAnswer":{"result":false,"details":"Catch Exception com.cloud.utils.exception.CloudRuntimeException: Migration failed due to com.cloud.utils.exception.CloudRuntimeException: Unable to migrate VM(i-2-38-VM) from host(335fb70f-e798-405b-b274-12053bc43051) due to Task failed! Task record: uuid: 3456c28d-1c6f-ad87-1c7f-a444b32f87a3\n nameLabel: Async.VM.pool_migrate\n nameDescription: \n allowedOperations: []\n currentOperations: {}\n created: Mon Feb 10 15:52:07 PST 2014\n finished: Mon Feb 10 15:52:07 PST 2014\n status: failure\n residentOn: com.xensource.xenapi.Host@f44e28e6\n progress: 1.0\n type: <none/>\n result: \n errorInfo: [VM_BAD_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, running, halted]\n otherConfig: {}\n subtaskOf: com.xensource.xenapi.Task@aaf13f6f\n subtasks: []\n","wait":0}}] }
> 2014-02-10 14:36:29,737 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-412:ctx-14b2649a) Seq 2-1390027712: No more commands found
> 2014-02-10 14:36:29,737 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Seq 2-1390027712: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 110, { MigrateAnswer } }
> 2014-02-10 14:36:29,737 INFO [c.c.v.VirtualMachineManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Migration was unsuccessful. Cleaning up: VM[User|third]
> 2014-02-10 14:36:29,743 WARN [o.a.c.alerts] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) alertType:: 17 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Unable to migrate vm i-2-38-VM from host xenserver-1 in zone default and pod demo-pod2
> 2014-02-10 14:36:29,754 DEBUG [c.c.a.m.AgentAttache] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Seq 1-1759117342: Routed from 214151488957798
> 2014-02-10 14:36:29,755 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Seq 1-1759117342: Sending { Cmd , MgmtId: 214151488957798, via: 1(xenserver-2), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-38-VM","wait":0}}] }
> 2014-02-10 14:36:29,755 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Seq 1-1759117342: Executing: { Cmd , MgmtId: 214151488957798, via: 1(xenserver-2), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-38-VM","wait":0}}] }
> 2014-02-10 14:36:29,755 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-249:ctx-6e2f5b3d) Seq 1-1759117342: Executing request
> 2014-02-10 14:36:29,773 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) VM state transitted from :Migrating to Running with event: OperationFailedvm's original host id: 2 new host id: 2 host id before state transition: 1
> 2014-02-10 14:36:29,779 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-02-10 14:36:29,780 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) Hosts's actual total RAM: 16001258112 and RAM after applying overprovisioning: 16001258496
> 2014-02-10 14:36:29,780 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) release cpu from host: 1, old used: 500,reserved: 0, actual total: 9044, total with overprovisioning: 9044; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2014-02-10 14:36:29,780 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-35:ctx-3af15cd6 ctx-e37bc423) release mem from host: 1, old used: 536870912,reserved: 0, total: 16001258496; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2014-02-10 14:36:29,803 ERROR [c.c.a.ApiAsyncJobDispatcher] (Job-Executor-35:ctx-3af15cd6) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd
> com.cloud.utils.exception.CloudRuntimeException: Unable to migrate due to Catch Exception com.cloud.utils.exception.CloudRuntimeException: Migration failed due to com.cloud.utils.exception.CloudRuntimeException: Unable to migrate VM(i-2-38-VM) from host(335fb70f-e798-405b-b274-12053bc43051) due to Task failed! Task record: uuid: 3456c28d-1c6f-ad87-1c7f-a444b32f87a3
> nameLabel: Async.VM.pool_migrate
> nameDescription:
> allowedOperations: []
> currentOperations: {}
> created: Mon Feb 10 15:52:07 PST 2014
> finished: Mon Feb 10 15:52:07 PST 2014
> status: failure
> residentOn: com.xensource.xenapi.Host@f44e28e6
> progress: 1.0
> type: <none/>
> result:
> errorInfo: [VM_BAD_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, running, halted]
> otherConfig: {}
> subtaskOf: com.xensource.xenapi.Task@aaf13f6f
> subtasks: []
> at com.cloud.vm.VirtualMachineManagerImpl.migrate(VirtualMachineManagerImpl.java:1776)
> at com.cloud.vm.VirtualMachineManagerImpl.orchestrateMigrate(VirtualMachineManagerImpl.java:1684)
> at com.cloud.vm.VirtualMachineManagerImpl.migrate(VirtualMachineManagerImpl.java:1652)
> at com.cloud.vm.UserVmManagerImpl.migrateVirtualMachine(UserVmManagerImpl.java:4218)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:622)
> at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
> at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:109)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
> at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:50)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
> at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
> at com.sun.proxy.$Proxy169.migrateVirtualMachine(Unknown Source)
> at org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd.execute(MigrateVMCmd.java:148)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
> at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109)
> at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
> at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:526)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:36:29,805 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-35:ctx-3af15cd6) Complete async job-61, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable to migrate due to Catch Exception com.cloud.utils.exception.CloudRuntimeException: Migration failed due to com.cloud.utils.exception.CloudRuntimeException: Unable to migrate VM(i-2-38-VM) from host(335fb70f-e798-405b-b274-12053bc43051) due to Task failed! Task record: uuid: 3456c28d-1c6f-ad87-1c7f-a444b32f87a3\n nameLabel: Async.VM.pool_migrate\n nameDescription: \n allowedOperations: []\n currentOperations: {}\n created: Mon Feb 10 15:52:07 PST 2014\n finished: Mon Feb 10 15:52:07 PST 2014\n status: failure\n residentOn: com.xensource.xenapi.Host@f44e28e6\n progress: 1.0\n type: \u003cnone/\u003e\n result: \n errorInfo: [VM_BAD_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, running, halted]\n otherConfig: {}\n subtaskOf: com.xensource.xenapi.Task@aaf13f6f\n subtasks: []\n"}
> 2014-02-10 14:36:29,811 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-35:ctx-3af15cd6) Done executing org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd for job-61
> 2014-02-10 14:36:29,815 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-35:ctx-3af15cd6) Remove job-61 from job monitoring
> 2014-02-10 14:36:29,838 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-249:ctx-6e2f5b3d) 9. The VM i-2-38-VM is in Stopping state
> 2014-02-10 14:36:29,859 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-249:ctx-6e2f5b3d) 10. The VM i-2-38-VM is in Stopped state
> 2014-02-10 14:36:29,859 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-249:ctx-6e2f5b3d) Seq 1-1759117342: Response Received:
> 2014-02-10 14:36:29,859 DEBUG [c.c.a.t.Request] (DirectAgent-249:ctx-6e2f5b3d) Seq 1-1759117342: Processing: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","result":true,"details":"Stop VM i-2-38-VM Succeed","wait":0}}] }
> 2014-02-10 14:36:29,859 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-249:ctx-6e2f5b3d) Seq 1-1759117342: Unable to find listener.
> 2014-02-10 14:36:30,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-0b267b87) Found 0 routers to update status.
> 2014-02-10 14:36:30,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-0b267b87) Found 0 networks to update RvR status.
> 2014-02-10 14:36:31,514 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-50756e82) ===START=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=d46bc3b4-b585-4f68-a68c-5442b26a3f95&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076496667
> 2014-02-10 14:36:31,533 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-50756e82 ctx-1dbcd23f) ===END=== 10.215.2.19 -- GET command=queryAsyncJobResult&jobId=d46bc3b4-b585-4f68-a68c-5442b26a3f95&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076496667
> 2014-02-10 14:36:32,774 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-45290: Processing Seq 3-45290: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:36:32,778 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-45290: Sending Seq 3-45290: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:34,525 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-4ea25a30) StorageCollector is running...
> 2014-02-10 14:36:34,634 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-4ea25a30) Seq 4-761272173: Received: { Ans: , MgmtId: 214151488957798, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:36:34,638 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-253:ctx-9be2b2dd) Seq 2-1390027713: Executing request
> 2014-02-10 14:36:34,915 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-253:ctx-9be2b2dd) Seq 2-1390027713: Response Received:
> 2014-02-10 14:36:34,915 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-4ea25a30) Seq 2-1390027713: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:36:35,873 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c872f9d7) Resetting hosts suitable for reconnect
> 2014-02-10 14:36:35,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c872f9d7) Completed resetting hosts suitable for reconnect
> 2014-02-10 14:36:35,875 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c872f9d7) Acquiring hosts for clusters already owned by this management server
> 2014-02-10 14:36:35,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c872f9d7) Completed acquiring hosts for clusters already owned by this management server
> 2014-02-10 14:36:35,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c872f9d7) Acquiring hosts for clusters not owned by any management server
> 2014-02-10 14:36:35,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c872f9d7) Completed acquiring hosts for clusters not owned by any management server
> 2014-02-10 14:36:37,930 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-249:ctx-380661ca) Ping from 1(xenserver-2)
> 2014-02-10 14:36:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-224:ctx-5b2af0d6) Seq 1-1759117314: Executing request
> 2014-02-10 14:36:38,186 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-224:ctx-5b2af0d6) Seq 1-1759117314: Response Received:
> 2014-02-10 14:36:38,187 DEBUG [c.c.a.t.Request] (DirectAgent-224:ctx-5b2af0d6) Seq 1-1759117314: Processing: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:38,399 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-326:ctx-ecd1b6e7) Ping from 2(xenserver-1)
> 2014-02-10 14:36:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-249:ctx-7f7ac5fe) Seq 2-1390018562: Executing request
> 2014-02-10 14:36:39,035 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-249:ctx-7f7ac5fe) VM missing i-2-38-VM old state stopped so removing.
> 2014-02-10 14:36:39,035 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-249:ctx-7f7ac5fe) Seq 2-1390018562: Response Received:
> 2014-02-10 14:36:39,035 DEBUG [c.c.a.t.Request] (DirectAgent-249:ctx-7f7ac5fe) Seq 2-1390018562: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:36:42,757 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-b04a0613) Zone 1 is ready to launch console proxy
> 2014-02-10 14:36:42,764 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-ae542f5e) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:36:42,775 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-45291: Processing Seq 3-45291: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:36:42,780 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-45291: Sending Seq 3-45291: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:47,568 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 4
> 2014-02-10 14:36:47,775 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-45292: Processing Seq 3-45292: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:36:47,779 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-45292: Sending Seq 3-45292: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:54,987 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) Ping from 3
> 2014-02-10 14:36:57,776 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-45294: Processing Seq 3-45294: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:36:57,780 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-45294: Sending Seq 3-45294: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:58,239 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-cb20f99f) VmStatsCollector is running...
> 2014-02-10 14:36:58,256 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-455:ctx-73af3935) Seq 2-1390027714: Executing request
> 2014-02-10 14:36:58,328 WARN [c.c.a.m.DirectAgentAttache] (DirectAgent-455:ctx-73af3935) Seq 2-1390027714: Exception Caught while executing command
> com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVM(CitrixResourceBase.java:7141)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2737)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:493)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
> at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:36:58,331 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-455:ctx-73af3935) Seq 2-1390027714: Response Received:
> 2014-02-10 14:36:58,331 DEBUG [c.c.a.t.Request] (DirectAgent-455:ctx-73af3935) Seq 2-1390027714: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.","wait":0}}] }
> 2014-02-10 14:36:58,331 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-cb20f99f) Seq 2-1390027714: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { Answer } }
> 2014-02-10 14:36:58,331 DEBUG [c.c.a.m.AgentManagerImpl] (StatsCollector-3:ctx-cb20f99f) Details from executing class com.cloud.agent.api.GetVmStatsCommand: com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> 2014-02-10 14:36:58,331 WARN [c.c.v.UserVmManagerImpl] (StatsCollector-3:ctx-cb20f99f) Unable to obtain VM statistics.
> 2014-02-10 14:37:00,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-b642f618) Found 0 routers to update status.
> 2014-02-10 14:37:00,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-b642f618) Found 0 networks to update RvR status.
> 2014-02-10 14:37:00,410 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-4ba43f99) HostStatsCollector is running...
> 2014-02-10 14:37:00,419 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-424:ctx-1367caba) Seq 1-1759117343: Executing request
> 2014-02-10 14:37:00,649 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-424:ctx-1367caba) Seq 1-1759117343: Response Received:
> 2014-02-10 14:37:00,649 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-4ba43f99) Seq 1-1759117343: Received: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:37:00,657 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-325:ctx-ba55e744) Seq 2-1390027715: Executing request
> 2014-02-10 14:37:00,840 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-325:ctx-ba55e744) Seq 2-1390027715: Response Received:
> 2014-02-10 14:37:00,840 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-4ba43f99) Seq 2-1390027715: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:37:07,777 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-45295: Processing Seq 3-45295: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:37:07,781 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-45295: Sending Seq 3-45295: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:12,754 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-d641385c) Zone 1 is ready to launch console proxy
> 2014-02-10 14:37:12,762 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-542c2016) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:37:17,778 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-45296: Processing Seq 3-45296: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:37:17,782 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-45296: Sending Seq 3-45296: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:27,779 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-45297: Processing Seq 3-45297: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:37:27,783 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-45297: Sending Seq 3-45297: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:30,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-d5143919) Found 0 routers to update status.
> 2014-02-10 14:37:30,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-d5143919) Found 0 networks to update RvR status.
> 2014-02-10 14:37:34,916 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-da91c10d) StorageCollector is running...
> 2014-02-10 14:37:35,025 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-da91c10d) Seq 4-761272174: Received: { Ans: , MgmtId: 214151488957798, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:37:35,029 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-285:ctx-285c5002) Seq 2-1390027716: Executing request
> 2014-02-10 14:37:35,326 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-285:ctx-285c5002) Seq 2-1390027716: Response Received:
> 2014-02-10 14:37:35,326 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-da91c10d) Seq 2-1390027716: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:37:35,929 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-0e6feb24) ===START=== 10.215.2.19 -- GET command=listVirtualMachines&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=true&page=1&pagesize=20&_=1392076561079
> 2014-02-10 14:37:35,958 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-0e6feb24 ctx-e1726ec3) ===END=== 10.215.2.19 -- GET command=listVirtualMachines&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=true&page=1&pagesize=20&_=1392076561079
> 2014-02-10 14:37:37,285 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-1039f878) ===START=== 10.215.2.19 -- GET command=listZones&id=cce32d06-91d9-47f0-90b5-766416d6add2&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076562494
> 2014-02-10 14:37:37,300 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-1039f878 ctx-bd0dd379) ===END=== 10.215.2.19 -- GET command=listZones&id=cce32d06-91d9-47f0-90b5-766416d6add2&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076562494
> 2014-02-10 14:37:37,364 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-7165f4b8) ===START=== 10.215.2.19 -- GET command=listVirtualMachines&id=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076562547
> 2014-02-10 14:37:37,387 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-7165f4b8 ctx-b8dac40c) ===END=== 10.215.2.19 -- GET command=listVirtualMachines&id=6034fed3-bac7-4267-874b-fdbcdd58f610&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076562547
> 2014-02-10 14:37:37,491 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-292263b1) ===START=== 10.215.2.19 -- GET command=listOsTypes&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076562606
> 2014-02-10 14:37:37,743 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-292263b1 ctx-ac1fae13) ===END=== 10.215.2.19 -- GET command=listOsTypes&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=1392076562606
> 2014-02-10 14:37:37,780 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-45298: Processing Seq 3-45298: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:37:37,784 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-45298: Sending Seq 3-45298: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:37,951 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-325:ctx-f2c44472) Ping from 1(xenserver-2)
> 2014-02-10 14:37:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-222:ctx-910abaca) Seq 1-1759117314: Executing request
> 2014-02-10 14:37:38,189 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-222:ctx-910abaca) Seq 1-1759117314: Response Received:
> 2014-02-10 14:37:38,190 DEBUG [c.c.a.t.Request] (DirectAgent-222:ctx-910abaca) Seq 1-1759117314: Processing: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:38,396 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-260:ctx-e92300f9) Ping from 2(xenserver-1)
> 2014-02-10 14:37:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-325:ctx-dc3fca39) Seq 2-1390018562: Executing request
> 2014-02-10 14:37:38,968 DEBUG [c.c.a.t.Request] (catalina-exec-10:null) Seq 2-1390027717: Sending { Cmd , MgmtId: 214151488957798, via: 2(xenserver-1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetVncPortCommand":{"id":38,"name":"i-2-38-VM","wait":0}}] }
> 2014-02-10 14:37:38,968 DEBUG [c.c.a.t.Request] (catalina-exec-10:null) Seq 2-1390027717: Executing: { Cmd , MgmtId: 214151488957798, via: 2(xenserver-1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetVncPortCommand":{"id":38,"name":"i-2-38-VM","wait":0}}] }
> 2014-02-10 14:37:38,968 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-16:ctx-c776cf4d) Seq 2-1390027717: Executing request
> 2014-02-10 14:37:39,033 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-325:ctx-dc3fca39) Seq 2-1390018562: Response Received:
> 2014-02-10 14:37:39,034 DEBUG [c.c.a.t.Request] (DirectAgent-325:ctx-dc3fca39) Seq 2-1390018562: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:37:39,059 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-16:ctx-c776cf4d) Seq 2-1390027717: Response Received:
> 2014-02-10 14:37:39,059 DEBUG [c.c.a.t.Request] (DirectAgent-16:ctx-c776cf4d) Seq 2-1390027717: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.GetVncPortAnswer":{"port":0,"result":false,"details":"There are 0 VMs named i-2-38-VM","wait":0}}] }
> 2014-02-10 14:37:39,059 DEBUG [c.c.a.t.Request] (catalina-exec-10:null) Seq 2-1390027717: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetVncPortAnswer } }
> 2014-02-10 14:37:39,059 DEBUG [c.c.a.m.AgentManagerImpl] (catalina-exec-10:null) Details from executing class com.cloud.agent.api.GetVncPortCommand: There are 0 VMs named i-2-38-VM
> 2014-02-10 14:37:39,059 DEBUG [c.c.s.ConsoleProxyServlet] (catalina-exec-10:null) Port info null
> 2014-02-10 14:37:39,059 INFO [c.c.s.ConsoleProxyServlet] (catalina-exec-10:null) Parse host info returned from executing GetVNCPortCommand. host info: null
> 2014-02-10 14:37:39,063 DEBUG [c.c.s.ConsoleProxyServlet] (catalina-exec-10:null) Compose console url: https://10-223-138-75.realhostip.com/ajax?token=q0_dVRCybhgZdNYivppqPrL0oRbpTx9nxngJAbFqn3oUjUVtHDmQ3yZE2y4-6yJkuBXzEK7PS8GYQpdlBoQsH94PJYrLAFQjJWZuz9IenNf8L4NzvwrFgga6tDM2gSKCPMg_lvzToYsjs_cHCCqQmXUQCvToIYApsY_8Hq8GLPixG4fCqRx3uoxVbepzzCW5H-zEKqA3jIJAep5hdD4y1Q
> 2014-02-10 14:37:39,063 DEBUG [c.c.s.ConsoleProxyServlet] (catalina-exec-10:null) the console url is :: <html><title>third</title><frameset><frame src="https://10-223-138-75.realhostip.com/ajax?token=q0_dVRCybhgZdNYivppqPrL0oRbpTx9nxngJAbFqn3oUjUVtHDmQ3yZE2y4-6yJkuBXzEK7PS8GYQpdlBoQsH94PJYrLAFQjJWZuz9IenNf8L4NzvwrFgga6tDM2gSKCPMg_lvzToYsjs_cHCCqQmXUQCvToIYApsY_8Hq8GLPixG4fCqRx3uoxVbepzzCW5H-zEKqA3jIJAep5hdD4y1Q"></frame></frameset></html>
> 2014-02-10 14:37:42,752 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-ec897185) Zone 1 is ready to launch console proxy
> 2014-02-10 14:37:42,762 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-738e759c) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:37:47,568 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) Ping from 4
> 2014-02-10 14:37:47,781 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-45299: Processing Seq 3-45299: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:37:47,785 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-45299: Sending Seq 3-45299: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:52,725 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-3d0a4fb1) ===START=== 10.215.2.19 -- GET command=listVirtualMachines&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=true&page=1&pagesize=20&_=1392076577877
> 2014-02-10 14:37:52,752 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-3d0a4fb1 ctx-b8d0d388) ===END=== 10.215.2.19 -- GET command=listVirtualMachines&response=json&sessionkey=gJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=true&page=1&pagesize=20&_=1392076577877
> 2014-02-10 14:37:52,781 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-45300: Processing Seq 3-45300: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:37:52,785 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-45300: Sending Seq 3-45300: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:54,987 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) Ping from 3
> 2014-02-10 14:37:58,332 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-7ab7bf75) VmStatsCollector is running...
> 2014-02-10 14:37:58,349 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-282:ctx-f29c7e66) Seq 2-1390027718: Executing request
> 2014-02-10 14:37:58,429 WARN [c.c.a.m.DirectAgentAttache] (DirectAgent-282:ctx-f29c7e66) Seq 2-1390027718: Exception Caught while executing command
> com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVM(CitrixResourceBase.java:7141)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2737)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:493)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
> at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:37:58,430 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-282:ctx-f29c7e66) Seq 2-1390027718: Response Received:
> 2014-02-10 14:37:58,430 DEBUG [c.c.a.t.Request] (DirectAgent-282:ctx-f29c7e66) Seq 2-1390027718: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.","wait":0}}] }
> 2014-02-10 14:37:58,430 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-7ab7bf75) Seq 2-1390027718: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { Answer } }
> 2014-02-10 14:37:58,430 DEBUG [c.c.a.m.AgentManagerImpl] (StatsCollector-2:ctx-7ab7bf75) Details from executing class com.cloud.agent.api.GetVmStatsCommand: com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> 2014-02-10 14:37:58,430 WARN [c.c.v.UserVmManagerImpl] (StatsCollector-2:ctx-7ab7bf75) Unable to obtain VM statistics.
> 2014-02-10 14:38:00,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-e3e35814) Found 0 routers to update status.
> 2014-02-10 14:38:00,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-e3e35814) Found 0 networks to update RvR status.
> 2014-02-10 14:38:00,841 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-4d5a8698) HostStatsCollector is running...
> 2014-02-10 14:38:00,849 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-445:ctx-fd874ed4) Seq 1-1759117344: Executing request
> 2014-02-10 14:38:01,073 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-445:ctx-fd874ed4) Seq 1-1759117344: Response Received:
> 2014-02-10 14:38:01,074 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-4d5a8698) Seq 1-1759117344: Received: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:38:01,081 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-228:ctx-1cdd1cf1) Seq 2-1390027719: Executing request
> 2014-02-10 14:38:01,267 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-228:ctx-1cdd1cf1) Seq 2-1390027719: Response Received:
> 2014-02-10 14:38:01,267 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-4d5a8698) Seq 2-1390027719: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:38:02,782 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-45302: Processing Seq 3-45302: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:38:02,787 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-45302: Sending Seq 3-45302: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:05,873 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-52c3ab01) Resetting hosts suitable for reconnect
> 2014-02-10 14:38:05,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-52c3ab01) Completed resetting hosts suitable for reconnect
> 2014-02-10 14:38:05,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-52c3ab01) Acquiring hosts for clusters already owned by this management server
> 2014-02-10 14:38:05,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-52c3ab01) Completed acquiring hosts for clusters already owned by this management server
> 2014-02-10 14:38:05,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-52c3ab01) Acquiring hosts for clusters not owned by any management server
> 2014-02-10 14:38:05,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-52c3ab01) Completed acquiring hosts for clusters not owned by any management server
> 2014-02-10 14:38:12,760 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-dc7efcf8) Zone 1 is ready to launch console proxy
> 2014-02-10 14:38:12,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-423b5c92) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:38:12,783 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-45303: Processing Seq 3-45303: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:38:12,788 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-45303: Sending Seq 3-45303: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:22,786 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-45304: Processing Seq 3-45304: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:38:22,790 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-45304: Sending Seq 3-45304: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:30,024 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:ctx-2c0bba5a) Found 0 running routers.
> 2014-02-10 14:38:30,029 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-4f9c7d0c) Found 0 routers to update status.
> 2014-02-10 14:38:30,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-4f9c7d0c) Found 0 networks to update RvR status.
> 2014-02-10 14:38:30,236 DEBUG [c.c.n.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:ctx-710ab70b) External devices stats collector is running...
> 2014-02-10 14:38:30,298 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-ccaca55c) Snapshot scheduler.poll is being called at 2014-02-10 22:38:30 GMT
> 2014-02-10 14:38:30,300 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-ccaca55c) Got 0 snapshots to be executed at 2014-02-10 22:38:30 GMT
> 2014-02-10 14:38:32,784 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-45305: Processing Seq 3-45305: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:38:32,788 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-45305: Sending Seq 3-45305: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:35,327 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-243b2060) StorageCollector is running...
> 2014-02-10 14:38:35,435 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-243b2060) Seq 4-761272175: Received: { Ans: , MgmtId: 214151488957798, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:38:35,439 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-174:ctx-b0ffd04b) Seq 2-1390027720: Executing request
> 2014-02-10 14:38:35,728 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-174:ctx-b0ffd04b) Seq 2-1390027720: Response Received:
> 2014-02-10 14:38:35,728 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-243b2060) Seq 2-1390027720: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:38:37,940 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-466:ctx-8a982e3b) Ping from 1(xenserver-2)
> 2014-02-10 14:38:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-174:ctx-89dca536) Seq 1-1759117314: Executing request
> 2014-02-10 14:38:38,182 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-174:ctx-89dca536) Seq 1-1759117314: Response Received:
> 2014-02-10 14:38:38,182 DEBUG [c.c.a.t.Request] (DirectAgent-174:ctx-89dca536) Seq 1-1759117314: Processing: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:38,600 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-258:ctx-21b81d02) Ping from 2(xenserver-1)
> 2014-02-10 14:38:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-89:ctx-76b6b30c) Seq 2-1390018562: Executing request
> 2014-02-10 14:38:39,086 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-89:ctx-76b6b30c) Seq 2-1390018562: Response Received:
> 2014-02-10 14:38:39,086 DEBUG [c.c.a.t.Request] (DirectAgent-89:ctx-76b6b30c) Seq 2-1390018562: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:38:42,756 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-cf975fa4) Zone 1 is ready to launch console proxy
> 2014-02-10 14:38:42,762 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-7a48cc65) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:38:42,785 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-45306: Processing Seq 3-45306: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:38:42,789 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-45306: Sending Seq 3-45306: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:47,567 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 4
> 2014-02-10 14:38:52,786 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-45307: Processing Seq 3-45307: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:38:52,791 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-45307: Sending Seq 3-45307: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:54,987 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-9:null) Ping from 3
> 2014-02-10 14:38:57,786 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-45309: Processing Seq 3-45309: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:38:57,790 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-45309: Sending Seq 3-45309: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:58,431 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-419bf9a3) VmStatsCollector is running...
> 2014-02-10 14:38:58,450 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-225:ctx-182ba614) Seq 2-1390027721: Executing request
> 2014-02-10 14:38:58,525 WARN [c.c.a.m.DirectAgentAttache] (DirectAgent-225:ctx-182ba614) Seq 2-1390027721: Exception Caught while executing command
> com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVM(CitrixResourceBase.java:7141)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2737)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:493)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
> at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:38:58,527 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-225:ctx-182ba614) Seq 2-1390027721: Response Received:
> 2014-02-10 14:38:58,527 DEBUG [c.c.a.t.Request] (DirectAgent-225:ctx-182ba614) Seq 2-1390027721: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.","wait":0}}] }
> 2014-02-10 14:38:58,527 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-419bf9a3) Seq 2-1390027721: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { Answer } }
> 2014-02-10 14:38:58,527 DEBUG [c.c.a.m.AgentManagerImpl] (StatsCollector-3:ctx-419bf9a3) Details from executing class com.cloud.agent.api.GetVmStatsCommand: com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> 2014-02-10 14:38:58,527 WARN [c.c.v.UserVmManagerImpl] (StatsCollector-3:ctx-419bf9a3) Unable to obtain VM statistics.
> 2014-02-10 14:39:00,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-da500bba) Found 0 routers to update status.
> 2014-02-10 14:39:00,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-da500bba) Found 0 networks to update RvR status.
> 2014-02-10 14:39:00,252 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-4a5d6144) Checking if any host reservation can be released ...
> 2014-02-10 14:39:00,260 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-4a5d6144) Cannot release reservation, Found 5 VMs Running on host 2
> 2014-02-10 14:39:00,260 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-4a5d6144) Done running HostReservationReleaseChecker ...
> 2014-02-10 14:39:00,287 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Running Capacity Checker ...
> 2014-02-10 14:39:00,287 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) recalculating system capacity
> 2014-02-10 14:39:00,288 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Executing cpu/ram capacity update
> 2014-02-10 14:39:00,292 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-59ff3a70) Found 0 VMs on host 1
> 2014-02-10 14:39:00,294 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-59ff3a70) Found 0 VM, not running on host 1
> 2014-02-10 14:39:00,295 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-59ff3a70) No need to calibrate cpu capacity, host:1 usedCpu: 0 reservedCpu: 0
> 2014-02-10 14:39:00,295 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-59ff3a70) No need to calibrate memory capacity, host:1 usedMem: 0 reservedMem: 0
> 2014-02-10 14:39:00,303 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-59ff3a70) Found 5 VMs on host 2
> 2014-02-10 14:39:00,312 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-59ff3a70) Found 0 VM, not running on host 2
> 2014-02-10 14:39:00,315 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-59ff3a70) No need to calibrate cpu capacity, host:2 usedCpu: 2500 reservedCpu: 0
> 2014-02-10 14:39:00,315 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-59ff3a70) No need to calibrate memory capacity, host:2 usedMem: 3221225472 reservedMem: 0
> 2014-02-10 14:39:00,315 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Done executing cpu/ram capacity update
> 2014-02-10 14:39:00,315 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Executing storage capacity update
> 2014-02-10 14:39:00,325 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-59ff3a70) Successfully set Capacity - 23621556633600 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 16, PodId 1
> 2014-02-10 14:39:00,325 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Done executing storage capacity update
> 2014-02-10 14:39:00,325 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Executing capacity updates for public ip and Vlans
> 2014-02-10 14:39:00,340 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Done capacity updates for public ip and Vlans
> 2014-02-10 14:39:00,340 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Executing capacity updates for private ip
> 2014-02-10 14:39:00,346 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Done executing capacity updates for private ip
> 2014-02-10 14:39:00,346 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Done recalculating system capacity
> 2014-02-10 14:39:00,364 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-59ff3a70) Done running Capacity Checker ...
> 2014-02-10 14:39:01,267 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-b39b0684) HostStatsCollector is running...
> 2014-02-10 14:39:01,276 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-446:ctx-8147a9eb) Seq 1-1759117345: Executing request
> 2014-02-10 14:39:01,500 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-446:ctx-8147a9eb) Seq 1-1759117345: Response Received:
> 2014-02-10 14:39:01,502 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-b39b0684) Seq 1-1759117345: Received: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:39:01,509 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-382:ctx-60ff9a26) Seq 2-1390027722: Executing request
> 2014-02-10 14:39:01,694 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-382:ctx-60ff9a26) Seq 2-1390027722: Response Received:
> 2014-02-10 14:39:01,694 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-b39b0684) Seq 2-1390027722: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:39:07,787 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-45310: Processing Seq 3-45310: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:39:07,792 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-45310: Sending Seq 3-45310: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:12,758 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-a32d7ddb) Zone 1 is ready to launch console proxy
> 2014-02-10 14:39:12,764 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-f1f5136f) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:39:17,788 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-45311: Processing Seq 3-45311: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:39:17,792 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-45311: Sending Seq 3-45311: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:27,789 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-45312: Processing Seq 3-45312: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:39:27,793 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-45312: Sending Seq 3-45312: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:30,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-4ea86ef5) Found 0 routers to update status.
> 2014-02-10 14:39:30,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-4ea86ef5) Found 0 networks to update RvR status.
> 2014-02-10 14:39:35,729 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-cb4dae1d) StorageCollector is running...
> 2014-02-10 14:39:35,838 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-cb4dae1d) Seq 4-761272176: Received: { Ans: , MgmtId: 214151488957798, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:39:35,842 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-69:ctx-96573069) Seq 2-1390027723: Executing request
> 2014-02-10 14:39:35,873 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-4664ac95) Resetting hosts suitable for reconnect
> 2014-02-10 14:39:35,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-4664ac95) Completed resetting hosts suitable for reconnect
> 2014-02-10 14:39:35,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-4664ac95) Acquiring hosts for clusters already owned by this management server
> 2014-02-10 14:39:35,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-4664ac95) Completed acquiring hosts for clusters already owned by this management server
> 2014-02-10 14:39:35,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-4664ac95) Acquiring hosts for clusters not owned by any management server
> 2014-02-10 14:39:35,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-4664ac95) Completed acquiring hosts for clusters not owned by any management server
> 2014-02-10 14:39:36,128 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-69:ctx-96573069) Seq 2-1390027723: Response Received:
> 2014-02-10 14:39:36,128 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-cb4dae1d) Seq 2-1390027723: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:39:37,790 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-45313: Processing Seq 3-45313: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:39:37,794 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-45313: Sending Seq 3-45313: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:37,932 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-38:ctx-e345b6a3) Ping from 1(xenserver-2)
> 2014-02-10 14:39:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-69:ctx-d4555d96) Seq 1-1759117314: Executing request
> 2014-02-10 14:39:38,182 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-69:ctx-d4555d96) Seq 1-1759117314: Response Received:
> 2014-02-10 14:39:38,182 DEBUG [c.c.a.t.Request] (DirectAgent-69:ctx-d4555d96) Seq 1-1759117314: Processing: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:38,399 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-370:ctx-67d244ac) Ping from 2(xenserver-1)
> 2014-02-10 14:39:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-38:ctx-7bf8c480) Seq 2-1390018562: Executing request
> 2014-02-10 14:39:39,036 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-38:ctx-7bf8c480) Seq 2-1390018562: Response Received:
> 2014-02-10 14:39:39,036 DEBUG [c.c.a.t.Request] (DirectAgent-38:ctx-7bf8c480) Seq 2-1390018562: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:39:42,760 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-ecc402ab) Zone 1 is ready to launch console proxy
> 2014-02-10 14:39:42,764 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-96ae696a) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:39:47,567 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 4
> 2014-02-10 14:39:47,791 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-45314: Processing Seq 3-45314: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:39:47,795 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-45314: Sending Seq 3-45314: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:52,791 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-45315: Processing Seq 3-45315: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:39:52,795 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-45315: Sending Seq 3-45315: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:54,986 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) Ping from 3
> 2014-02-10 14:39:58,528 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-1d8f4ec4) VmStatsCollector is running...
> 2014-02-10 14:39:58,546 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-151:ctx-505b0ef3) Seq 2-1390027724: Executing request
> 2014-02-10 14:39:58,620 WARN [c.c.a.m.DirectAgentAttache] (DirectAgent-151:ctx-505b0ef3) Seq 2-1390027724: Exception Caught while executing command
> com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVM(CitrixResourceBase.java:7141)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2737)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:493)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
> at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:39:58,621 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-151:ctx-505b0ef3) Seq 2-1390027724: Response Received:
> 2014-02-10 14:39:58,621 DEBUG [c.c.a.t.Request] (DirectAgent-151:ctx-505b0ef3) Seq 2-1390027724: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.","wait":0}}] }
> 2014-02-10 14:39:58,621 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-1d8f4ec4) Seq 2-1390027724: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { Answer } }
> 2014-02-10 14:39:58,621 DEBUG [c.c.a.m.AgentManagerImpl] (StatsCollector-2:ctx-1d8f4ec4) Details from executing class com.cloud.agent.api.GetVmStatsCommand: com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> 2014-02-10 14:39:58,621 WARN [c.c.v.UserVmManagerImpl] (StatsCollector-2:ctx-1d8f4ec4) Unable to obtain VM statistics.
> 2014-02-10 14:40:00,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-0c7bc8f1) Found 0 routers to update status.
> 2014-02-10 14:40:00,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-0c7bc8f1) Found 0 networks to update RvR status.
> 2014-02-10 14:40:01,695 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-5ce8171a) HostStatsCollector is running...
> 2014-02-10 14:40:01,706 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-148:ctx-a399863d) Seq 1-1759117346: Executing request
> 2014-02-10 14:40:01,930 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-148:ctx-a399863d) Seq 1-1759117346: Response Received:
> 2014-02-10 14:40:01,931 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-5ce8171a) Seq 1-1759117346: Received: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:40:01,937 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-175:ctx-14183950) Seq 2-1390027725: Executing request
> 2014-02-10 14:40:02,119 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-175:ctx-14183950) Seq 2-1390027725: Response Received:
> 2014-02-10 14:40:02,119 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-5ce8171a) Seq 2-1390027725: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:40:02,793 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-45317: Processing Seq 3-45317: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:40:02,797 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-45317: Sending Seq 3-45317: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:12,757 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-0d123b57) Zone 1 is ready to launch console proxy
> 2014-02-10 14:40:12,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-c9ab23e3) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:40:12,793 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-45318: Processing Seq 3-45318: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:40:12,797 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-45318: Sending Seq 3-45318: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:22,793 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-45319: Processing Seq 3-45319: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:40:22,797 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-45319: Sending Seq 3-45319: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:30,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-d20186d2) Found 0 routers to update status.
> 2014-02-10 14:40:30,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-d20186d2) Found 0 networks to update RvR status.
> 2014-02-10 14:40:32,794 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-45320: Processing Seq 3-45320: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:40:32,799 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-45320: Sending Seq 3-45320: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:36,129 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-c9a87e02) StorageCollector is running...
> 2014-02-10 14:40:36,240 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-c9a87e02) Seq 4-761272177: Received: { Ans: , MgmtId: 214151488957798, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:40:36,243 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-114:ctx-bc8e2688) Seq 2-1390027726: Executing request
> 2014-02-10 14:40:36,527 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-114:ctx-bc8e2688) Seq 2-1390027726: Response Received:
> 2014-02-10 14:40:36,527 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-c9a87e02) Seq 2-1390027726: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:40:37,932 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-175:ctx-faee3b46) Ping from 1(xenserver-2)
> 2014-02-10 14:40:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-114:ctx-df3f84d6) Seq 1-1759117314: Executing request
> 2014-02-10 14:40:38,182 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-114:ctx-df3f84d6) Seq 1-1759117314: Response Received:
> 2014-02-10 14:40:38,182 DEBUG [c.c.a.t.Request] (DirectAgent-114:ctx-df3f84d6) Seq 1-1759117314: Processing: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:38,400 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-468:ctx-e23894d0) Ping from 2(xenserver-1)
> 2014-02-10 14:40:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-114:ctx-84e13d0b) Seq 2-1390018562: Executing request
> 2014-02-10 14:40:39,054 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-114:ctx-84e13d0b) Seq 2-1390018562: Response Received:
> 2014-02-10 14:40:39,054 DEBUG [c.c.a.t.Request] (DirectAgent-114:ctx-84e13d0b) Seq 2-1390018562: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:40:42,759 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-2945943a) Zone 1 is ready to launch console proxy
> 2014-02-10 14:40:42,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-e3c9f63b) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:40:42,795 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-45321: Processing Seq 3-45321: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:40:42,800 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-45321: Sending Seq 3-45321: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:47,566 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 4
> 2014-02-10 14:40:52,796 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-45322: Processing Seq 3-45322: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:40:52,800 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-45322: Sending Seq 3-45322: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:54,986 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) Ping from 3
> 2014-02-10 14:40:57,796 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-45324: Processing Seq 3-45324: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:40:57,800 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-45324: Sending Seq 3-45324: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:58,622 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-dde6856e) VmStatsCollector is running...
> 2014-02-10 14:40:58,640 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-123:ctx-5c36cbe8) Seq 2-1390027727: Executing request
> 2014-02-10 14:40:58,713 WARN [c.c.a.m.DirectAgentAttache] (DirectAgent-123:ctx-5c36cbe8) Seq 2-1390027727: Exception Caught while executing command
> com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVM(CitrixResourceBase.java:7141)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2737)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:493)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
> at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:40:58,714 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-123:ctx-5c36cbe8) Seq 2-1390027727: Response Received:
> 2014-02-10 14:40:58,715 DEBUG [c.c.a.t.Request] (DirectAgent-123:ctx-5c36cbe8) Seq 2-1390027727: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.","wait":0}}] }
> 2014-02-10 14:40:58,715 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-dde6856e) Seq 2-1390027727: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { Answer } }
> 2014-02-10 14:40:58,715 DEBUG [c.c.a.m.AgentManagerImpl] (StatsCollector-1:ctx-dde6856e) Details from executing class com.cloud.agent.api.GetVmStatsCommand: com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> 2014-02-10 14:40:58,715 WARN [c.c.v.UserVmManagerImpl] (StatsCollector-1:ctx-dde6856e) Unable to obtain VM statistics.
> 2014-02-10 14:41:00,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-ab233b94) Found 0 routers to update status.
> 2014-02-10 14:41:00,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-ab233b94) Found 0 networks to update RvR status.
> 2014-02-10 14:41:02,120 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-d640815a) HostStatsCollector is running...
> 2014-02-10 14:41:02,130 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-195:ctx-6f2696ce) Seq 1-1759117347: Executing request
> 2014-02-10 14:41:02,351 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-195:ctx-6f2696ce) Seq 1-1759117347: Response Received:
> 2014-02-10 14:41:02,351 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-d640815a) Seq 1-1759117347: Received: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:41:02,359 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-344:ctx-c8b772fa) Seq 2-1390027728: Executing request
> 2014-02-10 14:41:02,541 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-344:ctx-c8b772fa) Seq 2-1390027728: Response Received:
> 2014-02-10 14:41:02,541 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-d640815a) Seq 2-1390027728: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:41:05,872 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-34737948) Resetting hosts suitable for reconnect
> 2014-02-10 14:41:05,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-34737948) Completed resetting hosts suitable for reconnect
> 2014-02-10 14:41:05,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-34737948) Acquiring hosts for clusters already owned by this management server
> 2014-02-10 14:41:05,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-34737948) Completed acquiring hosts for clusters already owned by this management server
> 2014-02-10 14:41:05,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-34737948) Acquiring hosts for clusters not owned by any management server
> 2014-02-10 14:41:05,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-34737948) Completed acquiring hosts for clusters not owned by any management server
> 2014-02-10 14:41:07,797 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-45325: Processing Seq 3-45325: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:41:07,802 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-45325: Sending Seq 3-45325: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:12,754 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-85920355) Zone 1 is ready to launch console proxy
> 2014-02-10 14:41:12,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-48d7b976) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:41:17,798 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-45326: Processing Seq 3-45326: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:41:17,802 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-45326: Sending Seq 3-45326: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:27,808 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-45327: Processing Seq 3-45327: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:41:27,813 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-45327: Sending Seq 3-45327: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:30,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-e543e64c) Found 0 routers to update status.
> 2014-02-10 14:41:30,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-e543e64c) Found 0 networks to update RvR status.
> 2014-02-10 14:41:36,528 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-bb4e55f0) StorageCollector is running...
> 2014-02-10 14:41:36,658 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-bb4e55f0) Seq 4-761272178: Received: { Ans: , MgmtId: 214151488957798, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:41:36,662 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-329:ctx-b3c50c53) Seq 2-1390027729: Executing request
> 2014-02-10 14:41:36,949 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-329:ctx-b3c50c53) Seq 2-1390027729: Response Received:
> 2014-02-10 14:41:36,949 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-bb4e55f0) Seq 2-1390027729: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-02-10 14:41:37,801 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-45328: Processing Seq 3-45328: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:41:37,806 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-45328: Sending Seq 3-45328: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:37,932 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-344:ctx-b4d89ed1) Ping from 1(xenserver-2)
> 2014-02-10 14:41:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-329:ctx-5367de97) Seq 1-1759117314: Executing request
> 2014-02-10 14:41:38,181 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-329:ctx-5367de97) Seq 1-1759117314: Response Received:
> 2014-02-10 14:41:38,181 DEBUG [c.c.a.t.Request] (DirectAgent-329:ctx-5367de97) Seq 1-1759117314: Processing: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:38,402 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-323:ctx-bd019cfc) Ping from 2(xenserver-1)
> 2014-02-10 14:41:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-329:ctx-e1585c86) Seq 2-1390018562: Executing request
> 2014-02-10 14:41:39,030 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-329:ctx-e1585c86) Seq 2-1390018562: Response Received:
> 2014-02-10 14:41:39,030 DEBUG [c.c.a.t.Request] (DirectAgent-329:ctx-e1585c86) Seq 2-1390018562: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:41:42,751 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-9088df57) Zone 1 is ready to launch console proxy
> 2014-02-10 14:41:42,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-28d2d4b1) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:41:47,567 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) Ping from 4
> 2014-02-10 14:41:47,801 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-45329: Processing Seq 3-45329: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:41:47,805 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-45329: Sending Seq 3-45329: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:54,986 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 3
> 2014-02-10 14:41:57,801 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-45331: Processing Seq 3-45331: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-02-10 14:41:57,805 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-45331: Sending Seq 3-45331: { Ans: , MgmtId: 214151488957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:58,716 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-4f87ed5b) VmStatsCollector is running...
> 2014-02-10 14:41:58,734 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-99:ctx-87c8824c) Seq 2-1390027730: Executing request
> 2014-02-10 14:41:58,816 WARN [c.c.a.m.DirectAgentAttache] (DirectAgent-99:ctx-87c8824c) Seq 2-1390027730: Exception Caught while executing command
> com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVM(CitrixResourceBase.java:7141)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2737)
> at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:493)
> at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
> at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
> at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:41:58,817 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-99:ctx-87c8824c) Seq 2-1390027730: Response Received:
> 2014-02-10 14:41:58,817 DEBUG [c.c.a.t.Request] (DirectAgent-99:ctx-87c8824c) Seq 2-1390027730: Processing: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.","wait":0}}] }
> 2014-02-10 14:41:58,817 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-4f87ed5b) Seq 2-1390027730: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { Answer } }
> 2014-02-10 14:41:58,817 DEBUG [c.c.a.m.AgentManagerImpl] (StatsCollector-2:ctx-4f87ed5b) Details from executing class com.cloud.agent.api.GetVmStatsCommand: com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-38-VM does not exist.
> 2014-02-10 14:41:58,817 WARN [c.c.v.UserVmManagerImpl] (StatsCollector-2:ctx-4f87ed5b) Unable to obtain VM statistics.
> 2014-02-10 14:42:00,030 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-856bb813) Found 0 routers to update status.
> 2014-02-10 14:42:00,031 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-856bb813) Found 0 networks to update RvR status.
> 2014-02-10 14:42:02,542 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-d7879c2b) HostStatsCollector is running...
> 2014-02-10 14:42:02,551 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-33:ctx-15d78667) Seq 1-1759117348: Executing request
> 2014-02-10 14:42:02,773 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-33:ctx-15d78667) Seq 1-1759117348: Response Received:
> 2014-02-10 14:42:02,774 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-d7879c2b) Seq 1-1759117348: Received: { Ans: , MgmtId: 214151488957798, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-02-10 14:42:02,781 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-290:ctx-6919265f) Seq 2-1390027731: Executing request
> 2014-02-10 14:42:02,961 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-290:ctx-6919265f) Seq 2-1390027731: Response Received:
> 2014-02-10 14:42:02,962 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-d7879c2b) Seq 2-1390027731: Received: { Ans: , MgmtId: 214151488957798, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> ^C
--
This message was sent by Atlassian JIRA
(v6.2#6252)