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/02/11 01:03:19 UTC
[jira] [Created] (CLOUDSTACK-6073) Contrail:MS: Reboot Xen hosts
and guest VM's get auto deleted after being migrated to another host
Parth Jagirdar created CLOUDSTACK-6073:
------------------------------------------
Summary: 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
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.1.5#6160)