Return-Path: 
 <issues-return-39051-apmail-cloudstack-issues-archive=cloudstack.apache.org@cloudstack.apache.org>
X-Original-To: apmail-cloudstack-issues-archive@www.apache.org
Delivered-To: apmail-cloudstack-issues-archive@www.apache.org
Received: from mail.apache.org (hermes.apache.org [140.211.11.3])
	by minotaur.apache.org (Postfix) with SMTP id BEECE10DA5
	for <apmail-cloudstack-issues-archive@www.apache.org>;
 Fri, 14 Feb 2014 22:47:34 +0000 (UTC)
Received: (qmail 53561 invoked by uid 500); 14 Feb 2014 22:47:22 -0000
Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org
Received: (qmail 53529 invoked by uid 500); 14 Feb 2014 22:47:21 -0000
Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm
Precedence: bulk
List-Help: <mailto:issues-help@cloudstack.apache.org>
List-Unsubscribe: <mailto:issues-unsubscribe@cloudstack.apache.org>
List-Post: <mailto:issues@cloudstack.apache.org>
List-Id: <issues.cloudstack.apache.org>
Reply-To: dev@cloudstack.apache.org
Delivered-To: mailing list issues@cloudstack.apache.org
Received: (qmail 53516 invoked by uid 500); 14 Feb 2014 22:47:20 -0000
Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org
Received: (qmail 53510 invoked by uid 99); 14 Feb 2014 22:47:20 -0000
Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28)
    by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 14 Feb 2014 22:47:20 +0000
Date: Fri, 14 Feb 2014 22:47:20 +0000 (UTC)
From: "Anirban Chakraborty (JIRA)" <jira@apache.org>
To: cloudstack-issues@incubator.apache.org
Message-ID: <JIRA.12694384.1392076902423.46619.1392418040552@arcas>
In-Reply-To: <JIRA.12694384.1392076902423@arcas>
References: <JIRA.12694384.1392076902423@arcas>
Subject: [jira] [Commented] (CLOUDSTACK-6073) Contrail:MS: Reboot Xen hosts
 and guest VM's get auto deleted after being migrated to another host
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394


    [ https://issues.apache.org/jira/browse/CLOUDSTACK-6073?page=3Dcom.atla=
ssian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=
=3D13902064#comment-13902064 ]=20

Anirban Chakraborty commented on CLOUDSTACK-6073:
-------------------------------------------------

Issue not seen in the latest nightly build. Please verify with CS4.3 and th=
e latest contrail bits.

> Contrail:MS: Reboot Xen hosts and guest VM's get auto deleted after being=
 migrated to another host
> -------------------------------------------------------------------------=
-------------------------
>
>                 Key: CLOUDSTACK-6073
>                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-607=
3
>             Project: CloudStack
>          Issue Type: Bug
>      Security Level: Public(Anyone can view this level - this is the defa=
ult.)=20
>          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 bac=
k to stopped state.
> If VM gets into running state, migration to another hosts results in foll=
owing error.
> Unable to migrate due to Catch Exception com.cloud.utils.exception.CloudR=
untimeException: Migration failed due to com.cloud.utils.exception.CloudRun=
timeException: Unable to migrate VM(i-2-38-VM) from host(335fb70f-e798-405b=
-b274-12053bc43051) due to Task failed! Task record: uuid: 3456c28d-1c6f-ad=
87-1c7f-a444b32f87a3 nameLabel: Async.VM.pool_migrate nameDescription: allo=
wedOperations: [] currentOperations: {} created: Mon Feb 10 15:52:07 PST 20=
14 finished: Mon Feb 10 15:52:07 PST 2014 status: failure residentOn: com.x=
ensource.xenapi.Host@f44e28e6 progress: 1.0 type: <none/> result: errorInfo=
: [VM_BAD_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, runn=
ing, halted] otherConfig: {} subtaskOf: com.xensource.xenapi.Task@aaf13f6f =
subtasks: []=20
> With all this error this VM actually doesnt exist on any Xenservers.
> Which suggests that this VM was removed from Xenserver but still exists i=
n CS.
> 2014-02-10 14:35:17,768 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-8:null) SeqA 3-45281: Processing Seq 3-45281:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:35:17,773 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-8:null) SeqA 3-45281: Sending Seq 3-45281:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:35:18,810 DEBUG [c.c.a.ApiServlet] (catalina-exec-6:ctx-b5b=
d122b) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistVirtualMa=
chines&id=3D25cd2c87-200f-4291-85e4-54b04df65ac0&response=3Djson&sessionkey=
=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076423981
> 2014-02-10 14:35:18,832 DEBUG [c.c.a.ApiServlet] (catalina-exec-6:ctx-b5b=
d122b ctx-5b246cc0) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dli=
stVirtualMachines&id=3D25cd2c87-200f-4291-85e4-54b04df65ac0&response=3Djson=
&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076423981
> 2014-02-10 14:35:18,923 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-09=
6ac0fe) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistOsTypes&=
response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D13920764240=
25
> 2014-02-10 14:35:19,148 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-09=
6ac0fe ctx-2d525580) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dl=
istOsTypes&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D=
1392076424025
> 2014-02-10 14:35:19,972 DEBUG [c.c.a.ApiServlet] (catalina-exec-8:ctx-c9a=
c53a3) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistVirtualMa=
chines&id=3D6034fed3-bac7-4267-874b-fdbcdd58f610&response=3Djson&sessionkey=
=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076425125
> 2014-02-10 14:35:19,994 DEBUG [c.c.a.ApiServlet] (catalina-exec-8:ctx-c9a=
c53a3 ctx-bf92a1ff) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dli=
stVirtualMachines&id=3D6034fed3-bac7-4267-874b-fdbcdd58f610&response=3Djson=
&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076425125
> 2014-02-10 14:35:20,090 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-c9=
702560) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistOsTypes&=
response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D13920764251=
84
> 2014-02-10 14:35:20,313 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-c9=
702560 ctx-24834659) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dl=
istOsTypes&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D=
1392076425184
> 2014-02-10 14:35:22,384 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-88=
ec237c) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DstartVirtual=
Machine&id=3D6034fed3-bac7-4267-874b-fdbcdd58f610&response=3Djson&sessionke=
y=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076427551
> 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: AsyncJobV=
O {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","ctxStartEvent=
Id":"221"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCod=
e: 0, result: null, initMsid: 214151488957798, completeMsid: null, lastUpda=
ted: 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-Exec=
utor-34:ctx-2cf0628d) Executing AsyncJobVO {id:60, userId: 2, accountId: 2,=
 instanceType: VirtualMachine, instanceId: 38, cmd: org.apache.cloudstack.a=
pi.command.user.vm.StartVMCmd, cmdInfo: {"id":"6034fed3-bac7-4267-874b-fdbc=
dd58f610","response":"json","sessionkey":"gJbfxiFXGjIJTBqBPlcyevZSM1g\u003d=
","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1392076=
427551","ctxAccountId":"2","ctxStartEventId":"221"}, cmdVersion: 0, status:=
 IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2141=
51488957798, completeMsid: null, lastUpdated: null, lastPolled: null, creat=
ed: null}
> 2014-02-10 14:35:22,419 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-88=
ec237c ctx-216f60ab) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Ds=
tartVirtualMachine&id=3D6034fed3-bac7-4267-874b-fdbcdd58f610&response=3Djso=
n&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076427551
> 2014-02-10 14:35:22,447 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-34:c=
tx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the net=
work id=3D205
> 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:c=
tx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the net=
work id=3D205
> 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 algorit=
hm: 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 storag=
e pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 5368=
70912
> 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 a=
llocated)?: 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-3=
4:ctx-2cf0628d ctx-216f60ab) Checking if host: 2 has enough capacity for re=
quested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: =
1.0
> 2014-02-10 14:35:22,490 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4:ctx-2cf0628d ctx-216f60ab) Hosts's actual total CPU: 9044 and CPU after a=
pplying overprovisioning: 9044
> 2014-02-10 14:35:22,490 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4: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-3=
4:ctx-2cf0628d ctx-216f60ab) Reserved CPU: 500 , Requested CPU: 500
> 2014-02-10 14:35:22,490 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4:ctx-2cf0628d ctx-216f60ab) Reserved RAM: 536870912 , Requested RAM: 53687=
0912
> 2014-02-10 14:35:22,491 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4: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-3=
4:ctx-2cf0628d ctx-216f60ab) STATS: Can alloc CPU from host: 2, used: 2000,=
 reserved: 500, actual total: 9044, total with overprovisioning: 9044; requ=
ested cpu:500,alloc_from_last_host?:true ,considerReservedCapacity?: true
> 2014-02-10 14:35:22,491 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4:ctx-2cf0628d ctx-216f60ab) STATS: Can alloc MEM from host: 2, used: 26843=
54560, reserved: 536870912, total: 16001258496; requested mem: 536870912,al=
loc_from_last_host?:true ,considerReservedCapacity?: true
> 2014-02-10 14:35:22,493 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4: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 h=
as 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 unde=
r 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, c=
hecking 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 a=
ssociated 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 s=
uitable 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: x=
enserver-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: De=
st[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-3=
4:ctx-2cf0628d ctx-216f60ab) VM state transitted from :Stopped to Starting =
with event: StartRequestedvm's original host id: 2 new host id: null host i=
d before state transition: null
> 2014-02-10 14:35:22,522 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Exec=
utor-34:ctx-2cf0628d ctx-216f60ab) Successfully transitioned to start state=
 for VM[User|third] reservation id =3D 45e9298d-313c-4b27-aa91-b8479a883c7b
> 2014-02-10 14:35:22,531 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Exec=
utor-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-Exec=
utor-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-Exec=
utor-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-Exec=
utor-34:ctx-2cf0628d ctx-216f60ab) Root volume is ready, need to place VM i=
n 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 algorit=
hm: 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 storag=
e pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 5368=
70912
> 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 a=
llocated)?: 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, c=
hecking 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 a=
ssociated 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 s=
uitable 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: x=
enserver-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: De=
st[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-Exec=
utor-34:ctx-2cf0628d ctx-216f60ab) Deployment found  - P0=3DVM[User|third],=
 P0=3DDest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->P=
ool(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-3=
4: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-3=
4:ctx-2cf0628d ctx-216f60ab) VM starting again on the last host it was stop=
ped on
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4:ctx-2cf0628d ctx-216f60ab) Hosts's actual total CPU: 9044 and CPU after a=
pplying overprovisioning: 9044
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4:ctx-2cf0628d ctx-216f60ab) We are allocating VM, increasing the used capa=
city of this host:2
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4:ctx-2cf0628d ctx-216f60ab) Current Used CPU: 2000 , Free CPU:6544 ,Reques=
ted CPU: 500
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4:ctx-2cf0628d ctx-216f60ab) Current Used RAM: 2684354560 , Free RAM:127800=
33024 ,Requested RAM: 536870912
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4:ctx-2cf0628d ctx-216f60ab) We are allocating VM to the last host again, s=
o 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-3=
4:ctx-2cf0628d ctx-216f60ab) Reserved CPU: 500 , Requested CPU: 500
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4:ctx-2cf0628d ctx-216f60ab) Reserved RAM: 536870912 , Requested RAM: 53687=
0912
> 2014-02-10 14:35:22,575 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4:ctx-2cf0628d ctx-216f60ab) CPU STATS after allocation: for host: 2, old u=
sed: 2000, old reserved: 500, actual total: 9044, total with overprovisioni=
ng: 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-3=
4:ctx-2cf0628d ctx-216f60ab) RAM STATS after allocation: for host: 2, old u=
sed: 2684354560, old reserved: 536870912, total: 16001258496; new used: 322=
1225472, reserved: 0; requested mem: 536870912,alloc_from_last:true
> 2014-02-10 14:35:22,589 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Exec=
utor-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-Execut=
or-34:ctx-2cf0628d ctx-216f60ab) Network id=3D205 is already implemented
> 2014-02-10 14:35:22,604 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-34:c=
tx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the net=
work id=3D205
> 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-426=
7-874b-fdbcdd58f610, {"virtual-machine":{"name":"i-2-38-VM","uuid":"6034fed=
3-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/3af83c5=
5-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/3af83c5=
5-31f9-4253-971e-6abfa45e60f0, {"virtual-machine-interface":{"virtual_machi=
ne_interface_mac_addresses":{"mac_address":["02:3a:f8:3c:55:31"]},"virtual_=
network_refs":[{"to":["default-domain","default-project","second"],"attr":n=
ull,"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-V=
M","i-2-38-VM-0"],"parent_type":"virtual-machine","parent_uuid":"6034fed3-b=
ac7-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/3af83c5=
5-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-b0=
66-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-b0=
66-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-Execut=
or-34:ctx-2cf0628d ctx-216f60ab) Changing active number of nics for network=
 id=3D205 on 1
> 2014-02-10 14:35:22,707 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Execut=
or-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:c=
tx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the net=
work id=3D205
> 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-Executo=
r-34:ctx-2cf0628d ctx-216f60ab) Checking if we need to prepare 1 volumes fo=
r VM[User|third]
> 2014-02-10 14:35:22,715 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Job-Executo=
r-34:ctx-2cf0628d ctx-216f60ab) No need to recreate the volume: Vol[38|vm=
=3D38|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-2cf0=
628d ctx-216f60ab) Seq 2-1390027709: Sending  { Cmd , MgmtId: 2141514889577=
98, via: 2(xenserver-1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.Sta=
rtCommand":{"vm":{"id":38,"name":"i-2-38-VM","bootloader":"PyGrub","type":"=
User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":53=
6870912,"arch":"x86_64","os":"Other (32-bit)","bootArgs":"","rebootOnCrash"=
:false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":fals=
e,"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":[{"dat=
a":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6e50be3d-0af=
9-4865-9e44-2ef4ae48b487","volumeType":"ROOT","dataStore":{"org.apache.clou=
dstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e=
028b7db4","id":16,"poolType":"NetworkFilesystem","host":"10.223.110.232","p=
ath":"/export/home/parth/contrail/cloudstack_58_4/primary","port":2049,"url=
":"NetworkFilesystem://10.223.110.232//export/home/parth/contrail/cloudstac=
k_58_4/primary/?ROLE=3DPrimary&STOREUUID=3D4233346b-ca53-3691-bdbc-6f7e028b=
7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44f-8b02-4649-af80-=
99dc554a1041","volumeId":38,"vmName":"i-2-38-VM","accountId":2,"format":"VH=
D","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":"53=
68709120"}},{"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":"3af8=
3c55-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":"Lswitc=
h","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-2cf0=
628d ctx-216f60ab) Seq 2-1390027709: Executing:  { Cmd , MgmtId: 2141514889=
57798, 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":"","rebootOnCra=
sh":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":f=
alse,"vncPassword":"15880c1b484a43f2","params":{"platform":"viridian:true;a=
cpi:1;apic:true;pae:true;nx:true;timeoffset:0","Message.ReservedCapacityFre=
ed.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.c=
loudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca53-3691-bdbc-6=
f7e028b7db4","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/clouds=
tack_58_4/primary/?ROLE=3DPrimary&STOREUUID=3D4233346b-ca53-3691-bdbc-6f7e0=
28b7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44f-8b02-4649-af=
80-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":"3=
af83c55-31f9-4253-971e-6abfa45e60f0","ip":"10.10.255.252","netmask":"255.25=
5.0.0","gateway":"10.10.1.1","mac":"02:3a:f8:3c:55:31","broadcastType":"Lsw=
itch","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabl=
ed":false}]},"hostIp":"10.223.58.66","executeInSequence":false,"wait":0}}] =
}
> 2014-02-10 14:35:22,769 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
38: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.2=
52-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-3=
38:ctx-a3e2b740) Seq 2-1390027709: Response Received:
> 2014-02-10 14:35:24,918 DEBUG [c.c.a.t.Request] (DirectAgent-338:ctx-a3e2=
b740) 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","o=
s":"Other (32-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"l=
imitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"15880c1b4=
84a43f2","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:t=
rue;timeoffset:0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"603=
4fed3-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.PrimaryD=
ataStoreTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e028b7db4","id":16,"poolTyp=
e":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/c=
ontrail/cloudstack_58_4/primary","port":2049,"url":"NetworkFilesystem://10.=
223.110.232//export/home/parth/contrail/cloudstack_58_4/primary/?ROLE=3DPri=
mary&STOREUUID=3D4233346b-ca53-3691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","=
size":5368709120,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","volumeId":3=
8,"vmName":"i-2-38-VM","accountId":2,"format":"VHD","id":38,"deviceId":0,"h=
ypervisorType":"XenServer"}},"diskSeq":0,"path":"e5e5d44f-8b02-4649-af80-99=
dc554a1041","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","acco=
untId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"ne=
tworkRateMbps":200,"defaultNic":true,"uuid":"3af83c55-31f9-4253-971e-6abfa4=
5e60f0","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","broadca=
stUri":"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-2cf0=
628d ctx-216f60ab) Seq 2-1390027709: Received:  { Ans: , MgmtId: 2141514889=
57798, via: 2, Ver: v1, Flags: 10, { StartAnswer } }
> 2014-02-10 14:35:24,962 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
4: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:c=
tx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the net=
work id=3D205
> 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:c=
tx-2cf0628d ctx-216f60ab) Service SecurityGroup is not supported in the net=
work id=3D205
> 2014-02-10 14:35:24,987 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Exec=
utor-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-Exec=
utor-34:ctx-2cf0628d ctx-216f60ab) Complete async job-60, jobStatus: SUCCEE=
DED, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmRespon=
se/virtualmachine/{"id":"6034fed3-bac7-4267-874b-fdbcdd58f610","name":"thir=
d","displayname":"third","account":"admin","domainid":"4a015670-8ec0-11e3-8=
ad7-c2c5076d6d66","domain":"ROOT","created":"2014-02-10T10:35:54-0800","sta=
te":"Running","haenable":false,"zoneid":"cce32d06-91d9-47f0-90b5-766416d6ad=
d2","zonename":"default","hostid":"a21fbbe7-e135-403f-9060-da68096071b2","h=
ostname":"xenserver-1","templateid":"650e4b87-01bc-437b-97a5-76f3b1636e8b",=
"templatename":"DSL","templatedisplaytext":"Damn Small Linux","passwordenab=
led":false,"serviceofferingid":"d432fb45-b4c4-4560-b66d-c74094093dce","serv=
iceofferingname":"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-1=
1e3-8ad7-c2c5076d6d66","rootdeviceid":0,"rootdevicetype":"ROOT","securitygr=
oup":[],"nic":[{"id":"3af83c55-31f9-4253-971e-6abfa45e60f0","networkid":"73=
8782df-1a33-4336-b09e-a1752571a4ac","networkname":"second","netmask":"255.2=
55.0.0","gateway":"10.10.1.1","ipaddress":"10.10.255.252","broadcasturi":"v=
lan://untagged","traffictype":"Guest","type":"Isolated","isdefault":true,"m=
acaddress":"02:3a:f8:3c:55:31"}],"hypervisor":"XenServer","instancename":"i=
-2-38-VM","tags":[],"affinitygroup":[],"displayvm":true,"isdynamicallyscala=
ble":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-Exec=
utor-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-23=
cf9a02) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DqueryAsyncJo=
bResult&jobId=3Daec81d05-d58b-43eb-ac11-3dcc682f69ea&response=3Djson&sessio=
nkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076430675
> 2014-02-10 14:35:25,543 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-23=
cf9a02 ctx-fd46c89c) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dq=
ueryAsyncJobResult&jobId=3Daec81d05-d58b-43eb-ac11-3dcc682f69ea&response=3D=
json&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076430675
> 2014-02-10 14:35:27,769 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-4:null) SeqA 3-45282: Processing Seq 3-45282:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:35:27,773 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-4:null) SeqA 3-45282: Sending Seq 3-45282:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"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 statu=
s.
> 2014-02-10 14:35:32,769 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-6:null) SeqA 3-45283: Processing Seq 3-45283:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:35:32,773 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-6:null) SeqA 3-45283: Sending Seq 3-45283:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:35:34,106 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ct=
x-989dd76a) StorageCollector is running...
> 2014-02-10 14:35:34,216 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-989=
dd76a) 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-5=
2:ctx-8ab0ec56) Seq 1-1759117339: Executing request
> 2014-02-10 14:35:34,525 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-5=
2:ctx-8ab0ec56) Seq 1-1759117339: Response Received:
> 2014-02-10 14:35:34,525 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-989=
dd76a) 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-3=
38:ctx-bb97fb86) Ping from 1(xenserver-2)
> 2014-02-10 14:35:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-5=
2:ctx-5de63ca4) Seq 1-1759117314: Executing request
> 2014-02-10 14:35:38,184 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-5=
2:ctx-5de63ca4) Seq 1-1759117314: Response Received:
> 2014-02-10 14:35:38,185 DEBUG [c.c.a.t.Request] (DirectAgent-52:ctx-5de63=
ca4) 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-4=
18:ctx-efd4a8c1) Ping from 2(xenserver-1)
> 2014-02-10 14:35:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
38: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-3=
38:ctx-65668ed5) Seq 2-1390018562: Response Received:
> 2014-02-10 14:35:39,038 DEBUG [c.c.a.t.Request] (DirectAgent-338:ctx-6566=
8ed5) Seq 2-1390018562: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_cluste=
rId":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;timeof=
fset:0"}},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:35:39,042 DEBUG [c.c.v.VirtualMachineManagerImpl] (DirectAg=
ent-338:ctx-65668ed5) VM i-2-38-VM: cs state =3D Running and realState =3D =
Running
> 2014-02-10 14:35:39,042 DEBUG [c.c.v.VirtualMachineManagerImpl] (DirectAg=
ent-338:ctx-65668ed5) VM i-2-38-VM: cs state =3D Running and realState =3D =
Running
> 2014-02-10 14:35:39,048 DEBUG [c.c.v.VirtualMachineManagerImpl] (DirectAg=
ent-338:ctx-65668ed5) Both states are Running for VM[User|third]
> 2014-02-10 14:35:39,050 DEBUG [c.c.c.CapacityManagerImpl] (DirectAgent-33=
8:ctx-65668ed5) VM state transitted from :Running to Running with event: Ag=
entReportRunningvm's original host id: 2 new host id: 2 host id before stat=
e transition: 2
> 2014-02-10 14:35:42,772 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-7:null) SeqA 3-45284: Processing Seq 3-45284:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:35:42,776 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-7:null) SeqA 3-45284: Sending Seq 3-45284:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:35:42,785 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-1:ctx-07e5d42c) Zone 1 is ready to launch secondary storage VM
> 2014-02-10 14:35:42,786 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-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-Ha=
ndler-9:null) Ping from 4
> 2014-02-10 14:35:52,771 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-5:null) SeqA 3-45285: Processing Seq 3-45285:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:35:52,775 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-5:null) SeqA 3-45285: Sending Seq 3-45285:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:35:54,987 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-11:null) Ping from 3
> 2014-02-10 14:35:57,993 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ct=
x-eede9c08) VmStatsCollector is running...
> 2014-02-10 14:35:58,014 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
71: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 ha=
ndle 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$XenS=
erverConnection.dispatch(XenServerConnectionPool.java:909)
>         at com.xensource.xenapi.VBDMetrics.getIoReadKbs(VBDMetrics.java:2=
10)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVmStat=
s(CitrixResourceBase.java:2841)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(C=
itrixResourceBase.java:2741)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRe=
quest(CitrixResourceBase.java:493)
>         at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeR=
equest(XenServer56Resource.java:59)
>         at com.cloud.hypervisor.xen.resource.XenServer610Resource.execute=
Request(XenServer610Resource.java:106)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(D=
irectAgentAttache.java:216)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable$1=
.run(ManagedContextRunnable.java:49)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable.r=
un(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$ScheduledFutu=
reTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutu=
reTask.run(ScheduledThreadPoolExecutor.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx=
ecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.java:615)
>         at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:35:58,238 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
71:ctx-ad3bede0) Seq 2-1390027710: Response Received:
> 2014-02-10 14:35:58,238 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-eed=
e9c08) 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:ct=
x-20359feb) HostStatsCollector is running...
> 2014-02-10 14:35:59,988 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
59: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 statu=
s.
> 2014-02-10 14:36:00,211 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
59:ctx-b19fadf9) Seq 1-1759117340: Response Received:
> 2014-02-10 14:36:00,212 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-203=
59feb) 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-2=
03:ctx-1e63f5f9) Seq 2-1390027711: Executing request
> 2014-02-10 14:36:00,409 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
03:ctx-1e63f5f9) Seq 2-1390027711: Response Received:
> 2014-02-10 14:36:00,409 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-203=
59feb) 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-Ha=
ndler-12:null) SeqA 3-45287: Processing Seq 3-45287:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:36:02,776 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-12:null) SeqA 3-45287: Sending Seq 3-45287:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:12,753 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-9dd28416) Zone 1 is ready to launch console proxy
> 2014-02-10 14:36:12,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-1:null) SeqA 3-45288: Processing Seq 3-45288:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:36:12,777 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-1:null) SeqA 3-45288: Sending Seq 3-45288:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:13,912 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-c8=
98f845) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistVirtualM=
achines&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=
=3Dtrue&page=3D1&pagesize=3D20&_=3D1392076479071
> 2014-02-10 14:36:13,940 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-c8=
98f845 ctx-3038fc02) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dl=
istVirtualMachines&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g=
%3D&listAll=3Dtrue&page=3D1&pagesize=3D20&_=3D1392076479071
> 2014-02-10 14:36:14,760 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-68=
7e292b) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistVirtualM=
achines&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=
=3Dtrue&page=3D1&pagesize=3D20&_=3D1392076479932
> 2014-02-10 14:36:14,787 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-68=
7e292b ctx-9a11abc8) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dl=
istVirtualMachines&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g=
%3D&listAll=3Dtrue&page=3D1&pagesize=3D20&_=3D1392076479932
> 2014-02-10 14:36:16,304 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-9d=
17994c) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistZones&id=
=3Dcce32d06-91d9-47f0-90b5-766416d6add2&response=3Djson&sessionkey=3DgJbfxi=
FXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076481491
> 2014-02-10 14:36:16,316 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-9d=
17994c ctx-27f700b1) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dl=
istZones&id=3Dcce32d06-91d9-47f0-90b5-766416d6add2&response=3Djson&sessionk=
ey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076481491
> 2014-02-10 14:36:16,365 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-e93=
bc823) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistVirtualMa=
chines&id=3D6034fed3-bac7-4267-874b-fdbcdd58f610&response=3Djson&sessionkey=
=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076481542
> 2014-02-10 14:36:16,389 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-e93=
bc823 ctx-13509922) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dli=
stVirtualMachines&id=3D6034fed3-bac7-4267-874b-fdbcdd58f610&response=3Djson=
&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076481542
> 2014-02-10 14:36:16,476 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-a6=
d15571) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistOsTypes&=
response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D13920764816=
09
> 2014-02-10 14:36:16,703 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-a6=
d15571 ctx-6fddc9c6) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dl=
istOsTypes&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D=
1392076481609
> 2014-02-10 14:36:19,180 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-ed=
a1d458) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DfindHostsFor=
Migration&VirtualMachineId=3D6034fed3-bac7-4267-874b-fdbcdd58f610&response=
=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076484388
> 2014-02-10 14:36:19,198 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (cata=
lina-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) ClusterScopeStoragePoolAlloc=
ator 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|Networ=
kFilesystem] from avoid set, must have been inserted when searching for ano=
ther disk's tag
> 2014-02-10 14:36:19,202 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (c=
atalina-exec-24:ctx-eda1d458 ctx-c51c162b) Checking if storage pool is suit=
able, name: null ,poolId: 16
> 2014-02-10 14:36:19,206 DEBUG [c.c.s.StorageManagerImpl] (catalina-exec-2=
4:ctx-eda1d458 ctx-c51c162b) Checking pool 16 for storage, totalSize: 11810=
778316800, usedBytes: 8001863122944, usedPct: 0.6775051489673558, disable t=
hreshold: 0.85
> 2014-02-10 14:36:19,210 DEBUG [c.c.s.StorageManagerImpl] (catalina-exec-2=
4:ctx-eda1d458 ctx-c51c162b) Checking pool: 16 for volume allocation [Vol[3=
8|vm=3D38|ROOT]], maxSize : 23621556633600, totalAllocatedSize : 2659188736=
0, 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) ClusterScopeStoragePoolAlloc=
ator returning 1 suitable storage pools
> 2014-02-10 14:36:19,213 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (catalina-e=
xec-24:ctx-eda1d458 ctx-c51c162b) FirstFitAllocator has 1 hosts to check fo=
r allocation: [Host[-1-Routing]]
> 2014-02-10 14:36:19,214 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (catalina-e=
xec-24:ctx-eda1d458 ctx-c51c162b) Found 1 hosts for allocation after priori=
tization: [Host[-1-Routing]]
> 2014-02-10 14:36:19,214 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (catalina-e=
xec-24:ctx-eda1d458 ctx-c51c162b) Looking for speed=3D500Mhz, Ram=3D512
> 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 r=
equested 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 consid=
ering 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: 536870=
912
> 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, r=
eserved: 0, actual total: 9044, total with overprovisioning: 9044; requeste=
d 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, r=
eserved: 0, total: 16001258496; requested mem: 536870912,alloc_from_last_ho=
st?:false ,considerReservedCapacity?: false
> 2014-02-10 14:36:19,219 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (catalina-e=
xec-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-e=
xec-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 migra=
tion: [Host[-1-Routing]]
> 2014-02-10 14:36:19,227 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-ed=
a1d458 ctx-c51c162b) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Df=
indHostsForMigration&VirtualMachineId=3D6034fed3-bac7-4267-874b-fdbcdd58f61=
0&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D139207648=
4388
> 2014-02-10 14:36:22,774 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-10:null) SeqA 3-45289: Processing Seq 3-45289:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:36:22,779 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-10:null) SeqA 3-45289: Sending Seq 3-45289:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:28,303 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-574=
467ad) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DmigrateVirtua=
lMachine&hostid=3D4e27ed8b-42b7-42c1-b5eb-4b41a0dc7348&virtualmachineid=3D6=
034fed3-bac7-4267-874b-fdbcdd58f610&response=3Djson&sessionkey=3DgJbfxiFXGj=
IJTBqBPlcyevZSM1g%3D&_=3D1392076493503
> 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: {"respo=
nse":"json","sessionkey":"gJbfxiFXGjIJTBqBPlcyevZSM1g\u003d","virtualmachin=
eid":"6034fed3-bac7-4267-874b-fdbcdd58f610","cmdEventType":"VM.MIGRATE","ho=
stid":"4e27ed8b-42b7-42c1-b5eb-4b41a0dc7348","ctxUserId":"2","httpmethod":"=
GET","_":"1392076493503","ctxAccountId":"2","ctxStartEventId":"224"}, cmdVe=
rsion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: nul=
l, initMsid: 214151488957798, completeMsid: null, lastUpdated: null, lastPo=
lled: null, created: null}
> 2014-02-10 14:36:28,377 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-574=
467ad ctx-e37bc423) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dmi=
grateVirtualMachine&hostid=3D4e27ed8b-42b7-42c1-b5eb-4b41a0dc7348&virtualma=
chineid=3D6034fed3-bac7-4267-874b-fdbcdd58f610&response=3Djson&sessionkey=
=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076493503
> 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-Exec=
utor-35:ctx-3af15cd6) Executing AsyncJobVO {id:61, userId: 2, accountId: 2,=
 instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.comma=
nd.admin.vm.MigrateVMCmd, cmdInfo: {"response":"json","sessionkey":"gJbfxiF=
XGjIJTBqBPlcyevZSM1g\u003d","virtualmachineid":"6034fed3-bac7-4267-874b-fdb=
cdd58f610","cmdEventType":"VM.MIGRATE","hostid":"4e27ed8b-42b7-42c1-b5eb-4b=
41a0dc7348","ctxUserId":"2","httpmethod":"GET","_":"1392076493503","ctxAcco=
untId":"2","ctxStartEventId":"224"}, cmdVersion: 0, status: IN_PROGRESS, pr=
ocessStatus: 0, resultCode: 0, result: null, initMsid: 214151488957798, com=
pleteMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2014-02-10 14:36:28,424 INFO  [c.c.v.VirtualMachineManagerImpl] (Job-Exec=
utor-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[Z=
one(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
> 2014-02-10 14:36:28,436 DEBUG [c.c.n.NetworkModelImpl] (Job-Executor-35:c=
tx-3af15cd6 ctx-e37bc423) Service SecurityGroup is not supported in the net=
work id=3D205
> 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:c=
tx-3af15cd6 ctx-e37bc423) Service SecurityGroup is not supported in the net=
work id=3D205
> 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-Executo=
r-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-Ex=
ecutor-35:ctx-3af15cd6 ctx-e37bc423) template 202 is already in store:1, ty=
pe:Image
> 2014-02-10 14:36:28,490 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af1=
5cd6 ctx-e37bc423) Seq 1-1759117341: Sending  { Cmd , MgmtId: 2141514889577=
98, via: 1(xenserver-2), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.Pre=
pareForMigrationCommand":{"vm":{"id":38,"name":"i-2-38-VM","bootloader":"Py=
Grub","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":5368709=
12,"maxRam":536870912,"arch":"x86_64","os":"Other (32-bit)","bootArgs":"","=
rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicall=
yScaleVm":false,"vncPassword":"15880c1b484a43f2","params":{"platform":"viri=
dian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","Message.Reserved=
CapacityFreed.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":{"o=
rg.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca53-=
3691-bdbc-6f7e028b7db4","id":16,"poolType":"NetworkFilesystem","host":"10.2=
23.110.232","path":"/export/home/parth/contrail/cloudstack_58_4/primary","p=
ort":2049,"url":"NetworkFilesystem://10.223.110.232//export/home/parth/cont=
rail/cloudstack_58_4/primary/?ROLE=3DPrimary&STOREUUID=3D4233346b-ca53-3691=
-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44f-8=
b02-4649-af80-99dc554a1041","volumeId":38,"vmName":"i-2-38-VM","accountId":=
2,"format":"VHD","id":38,"deviceId":0,"hypervisorType":"XenServer"}},"diskS=
eq":0,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","type":"ROOT","_details=
":{"managed":"false","storagePort":"2049","storageHost":"10.223.110.232","v=
olumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.Templa=
teObjectTO":{"path":"template/tmpl/2/202/202-2-76a7bc62-9209-37ef-9d68-3ce9=
eeb60cab.iso","origUrl":"http://nfs1.lab.vmops.com/parth/DSL_current.iso","=
uuid":"650e4b87-01bc-437b-97a5-76f3b1636e8b","id":202,"format":"ISO","accou=
ntId":2,"checksum":"5cb7e0d4506c249b78bbe0cd4695b865","hvm":true,"displayTe=
xt":"Damn Small Linux","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_=
url":"nfs://10.223.110.232:/export/home/parth/contrail/cloudstack_58_4/seco=
ndary","_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-6=
abfa45e60f0","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","br=
oadcastUri":"vlan://untagged","isSecurityGroupEnabled":false}]},"wait":0}}]=
 }
> 2014-02-10 14:36:28,492 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af1=
5cd6 ctx-e37bc423) Seq 1-1759117341: Executing:  { Cmd , MgmtId: 2141514889=
57798, 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":5368=
70912,"maxRam":536870912,"arch":"x86_64","os":"Other (32-bit)","bootArgs":"=
","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamic=
allyScaleVm":false,"vncPassword":"15880c1b484a43f2","params":{"platform":"v=
iridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","Message.Reser=
vedCapacityFreed.Flag":"false"},"uuid":"6034fed3-bac7-4267-874b-fdbcdd58f61=
0","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uu=
id":"6e50be3d-0af9-4865-9e44-2ef4ae48b487","volumeType":"ROOT","dataStore":=
{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4233346b-ca=
53-3691-bdbc-6f7e028b7db4","id":16,"poolType":"NetworkFilesystem","host":"1=
0.223.110.232","path":"/export/home/parth/contrail/cloudstack_58_4/primary"=
,"port":2049,"url":"NetworkFilesystem://10.223.110.232//export/home/parth/c=
ontrail/cloudstack_58_4/primary/?ROLE=3DPrimary&STOREUUID=3D4233346b-ca53-3=
691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size":5368709120,"path":"e5e5d44=
f-8b02-4649-af80-99dc554a1041","volumeId":38,"vmName":"i-2-38-VM","accountI=
d":2,"format":"VHD","id":38,"deviceId":0,"hypervisorType":"XenServer"}},"di=
skSeq":0,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","type":"ROOT","_deta=
ils":{"managed":"false","storagePort":"2049","storageHost":"10.223.110.232"=
,"volumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.Tem=
plateObjectTO":{"path":"template/tmpl/2/202/202-2-76a7bc62-9209-37ef-9d68-3=
ce9eeb60cab.iso","origUrl":"http://nfs1.lab.vmops.com/parth/DSL_current.iso=
","uuid":"650e4b87-01bc-437b-97a5-76f3b1636e8b","id":202,"format":"ISO","ac=
countId":2,"checksum":"5cb7e0d4506c249b78bbe0cd4695b865","hvm":true,"displa=
yText":"Damn Small Linux","imageDataStore":{"com.cloud.agent.api.to.NfsTO":=
{"_url":"nfs://10.223.110.232:/export/home/parth/contrail/cloudstack_58_4/s=
econdary","_role":"Image"}},"name":"202-2-76a7bc62-9209-37ef-9d68-3ce9eeb60=
cab","hypervisorType":"None"}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceI=
d":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3af83c55-31f9-4253-971=
e-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-4=
15: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.Virt=
ualMachineTO@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-4=
15:ctx-34ae4b0a) Seq 1-1759117341: Response Received:
> 2014-02-10 14:36:28,587 DEBUG [c.c.a.t.Request] (DirectAgent-415:ctx-34ae=
4b0a) 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-3af1=
5cd6 ctx-e37bc423) Seq 1-1759117341: Received:  { Ans: , MgmtId: 2141514889=
57798, 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-3=
5: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-3=
5:ctx-3af15cd6 ctx-e37bc423) Hosts's actual total CPU: 9044 and CPU after a=
pplying overprovisioning: 9044
> 2014-02-10 14:36:28,622 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
5:ctx-3af15cd6 ctx-e37bc423) We are allocating VM, increasing the used capa=
city of this host:1
> 2014-02-10 14:36:28,622 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
5: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-3=
5:ctx-3af15cd6 ctx-e37bc423) Current Used RAM: 0 , Free RAM:16001258496 ,Re=
quested RAM: 536870912
> 2014-02-10 14:36:28,622 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
5:ctx-3af15cd6 ctx-e37bc423) CPU STATS after allocation: for host: 1, old u=
sed: 0, old reserved: 0, actual total: 9044, total with overprovisioning: 9=
044; 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-3=
5:ctx-3af15cd6 ctx-e37bc423) RAM STATS after allocation: for host: 1, old u=
sed: 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-3af1=
5cd6 ctx-e37bc423) Seq 2-1390027712: Sending  { Cmd , MgmtId: 2141514889577=
98, via: 2(xenserver-1), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.Mig=
rateCommand":{"vmName":"i-2-38-VM","destIp":"10.223.58.67","hostGuid":"8e94=
4da8-3f1d-424e-8cff-ea03b5be0689","isWindows":false,"vmTO":{"id":38,"name":=
"i-2-38-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":500,"ma=
xSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Oth=
er (32-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpu=
Use":false,"enableDynamicallyScaleVm":false,"vncPassword":"15880c1b484a43f2=
","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;tim=
eoffset:0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"6034fed3-b=
ac7-4267-874b-fdbcdd58f610","disks":[{"data":{"org.apache.cloudstack.storag=
e.to.VolumeObjectTO":{"uuid":"6e50be3d-0af9-4865-9e44-2ef4ae48b487","volume=
Type":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStor=
eTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e028b7db4","id":16,"poolType":"Net=
workFilesystem","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=3DPrimary&ST=
OREUUID=3D4233346b-ca53-3691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size":5=
368709120,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","volumeId":38,"vmNa=
me":"i-2-38-VM","accountId":2,"format":"VHD","id":38,"deviceId":0,"hypervis=
orType":"XenServer"}},"diskSeq":0,"path":"e5e5d44f-8b02-4649-af80-99dc554a1=
041","type":"ROOT","_details":{"managed":"false","storagePort":"2049","stor=
ageHost":"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","i=
d":202,"format":"ISO","accountId":2,"checksum":"5cb7e0d4506c249b78bbe0cd469=
5b865","hvm":true,"displayText":"Damn Small Linux","imageDataStore":{"com.c=
loud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232:/export/home/parth/c=
ontrail/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":"25=
5.255.0.0","gateway":"10.10.1.1","mac":"02:3a:f8:3c:55:31","broadcastType":=
"Lswitch","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupE=
nabled":false}]},"wait":0}}] }
> 2014-02-10 14:36:28,632 DEBUG [c.c.a.t.Request] (Job-Executor-35:ctx-3af1=
5cd6 ctx-e37bc423) Seq 2-1390027712: Executing:  { Cmd , MgmtId: 2141514889=
57798, via: 2(xenserver-1), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.=
MigrateCommand":{"vmName":"i-2-38-VM","destIp":"10.223.58.67","hostGuid":"8=
e944da8-3f1d-424e-8cff-ea03b5be0689","isWindows":false,"vmTO":{"id":38,"nam=
e":"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,"limit=
CpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"15880c1b484a4=
3f2","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;=
timeoffset:0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"6034fed=
3-bac7-4267-874b-fdbcdd58f610","disks":[{"data":{"org.apache.cloudstack.sto=
rage.to.VolumeObjectTO":{"uuid":"6e50be3d-0af9-4865-9e44-2ef4ae48b487","vol=
umeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataS=
toreTO":{"uuid":"4233346b-ca53-3691-bdbc-6f7e028b7db4","id":16,"poolType":"=
NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/contr=
ail/cloudstack_58_4/primary","port":2049,"url":"NetworkFilesystem://10.223.=
110.232//export/home/parth/contrail/cloudstack_58_4/primary/?ROLE=3DPrimary=
&STOREUUID=3D4233346b-ca53-3691-bdbc-6f7e028b7db4"}},"name":"ROOT-38","size=
":5368709120,"path":"e5e5d44f-8b02-4649-af80-99dc554a1041","volumeId":38,"v=
mName":"i-2-38-VM","accountId":2,"format":"VHD","id":38,"deviceId":0,"hyper=
visorType":"XenServer"}},"diskSeq":0,"path":"e5e5d44f-8b02-4649-af80-99dc55=
4a1041","type":"ROOT","_details":{"managed":"false","storagePort":"2049","s=
torageHost":"10.223.110.232","volumeSize":"5368709120"}},{"data":{"org.apac=
he.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/202/202=
-2-76a7bc62-9209-37ef-9d68-3ce9eeb60cab.iso","origUrl":"http://nfs1.lab.vmo=
ps.com/parth/DSL_current.iso","uuid":"650e4b87-01bc-437b-97a5-76f3b1636e8b"=
,"id":202,"format":"ISO","accountId":2,"checksum":"5cb7e0d4506c249b78bbe0cd=
4695b865","hvm":true,"displayText":"Damn Small Linux","imageDataStore":{"co=
m.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232:/export/home/part=
h/contrail/cloudstack_58_4/secondary","_role":"Image"}},"name":"202-2-76a7b=
c62-9209-37ef-9d68-3ce9eeb60cab","hypervisorType":"None"}},"diskSeq":3,"typ=
e":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"u=
uid":"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","broadcastTyp=
e":"Lswitch","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGro=
upEnabled":false}]},"wait":0}}] }
> 2014-02-10 14:36:28,633 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-4=
12: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-d=
8d2-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:                 uu=
id: 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-d=
8d2-10394df0aab7, running, halted]
>          otherConfig: {}
>            subtaskOf: com.xensource.xenapi.Task@aaf13f6f
>             subtasks: []
> Task failed! Task record:                 uuid: 3456c28d-1c6f-ad87-1c7f-a=
444b32f87a3
>            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-d=
8d2-10394df0aab7, running, halted]
>          otherConfig: {}
>            subtaskOf: com.xensource.xenapi.Task@aaf13f6f
>             subtasks: []
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.checkForS=
uccess(CitrixResourceBase.java:3742)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.migrateVM=
(CitrixResourceBase.java:3888)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(C=
itrixResourceBase.java:3446)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRe=
quest(CitrixResourceBase.java:509)
>         at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeR=
equest(XenServer56Resource.java:59)
>         at com.cloud.hypervisor.xen.resource.XenServer610Resource.execute=
Request(XenServer610Resource.java:106)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(D=
irectAgentAttache.java:216)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable$1=
.run(ManagedContextRunnable.java:49)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable.r=
un(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$ScheduledFutu=
reTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutu=
reTask.run(ScheduledThreadPoolExecutor.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx=
ecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.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.CloudRuntimeEx=
ception: Migration failed due to com.cloud.utils.exception.CloudRuntimeExce=
ption: Unable to migrate VM(i-2-38-VM) from host(335fb70f-e798-405b-b274-12=
053bc43051) 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-d=
8d2-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-d=
8d2-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(C=
itrixResourceBase.java:3446)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRe=
quest(CitrixResourceBase.java:509)
>         at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeR=
equest(XenServer56Resource.java:59)
>         at com.cloud.hypervisor.xen.resource.XenServer610Resource.execute=
Request(XenServer610Resource.java:106)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(D=
irectAgentAttache.java:216)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable$1=
.run(ManagedContextRunnable.java:49)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable.r=
un(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$ScheduledFutu=
reTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutu=
reTask.run(ScheduledThreadPoolExecutor.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx=
ecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.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-4=
12:ctx-14b2649a) Seq 2-1390027712: Response Received:
> 2014-02-10 14:36:29,737 DEBUG [c.c.a.t.Request] (DirectAgent-412:ctx-14b2=
649a) Seq 2-1390027712: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.MigrateAnswer":{"result":fa=
lse,"details":"Catch Exception com.cloud.utils.exception.CloudRuntimeExcept=
ion: Migration failed due to com.cloud.utils.exception.CloudRuntimeExceptio=
n: Unable to migrate VM(i-2-38-VM) from host(335fb70f-e798-405b-b274-12053b=
c43051) due to Task failed! Task record:                 uuid: 3456c28d-1c6=
f-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          resident=
On: com.xensource.xenapi.Host@f44e28e6\n            progress: 1.0\n        =
        type: <none/>\n              result: \n           errorInfo: [VM_BA=
D_POWER_STATE, OpaqueRef:6a71fc11-cc9d-c1eb-d8d2-10394df0aab7, running, hal=
ted]\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-3af1=
5cd6 ctx-e37bc423) Seq 2-1390027712: Received:  { Ans: , MgmtId: 2141514889=
57798, via: 2, Ver: v1, Flags: 110, { MigrateAnswer } }
> 2014-02-10 14:36:29,737 INFO  [c.c.v.VirtualMachineManagerImpl] (Job-Exec=
utor-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-3af15cd=
6 ctx-e37bc423)  alertType:: 17 // dataCenterId:: 1 // podId:: 1 // cluster=
Id:: 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-3af1=
5cd6 ctx-e37bc423) Seq 1-1759117342: Sending  { Cmd , MgmtId: 2141514889577=
98, via: 1(xenserver-2), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.Sto=
pCommand":{"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-3af1=
5cd6 ctx-e37bc423) Seq 1-1759117342: Executing:  { Cmd , MgmtId: 2141514889=
57798, 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-2=
49:ctx-6e2f5b3d) Seq 1-1759117342: Executing request
> 2014-02-10 14:36:29,773 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
5: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-3=
5:ctx-3af15cd6 ctx-e37bc423) Hosts's actual total CPU: 9044 and CPU after a=
pplying overprovisioning: 9044
> 2014-02-10 14:36:29,780 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
5: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-3=
5:ctx-3af15cd6 ctx-e37bc423) release cpu from host: 1, old used: 500,reserv=
ed: 0, actual total: 9044, total with overprovisioning: 9044; new used: 0,r=
eserved:0; movedfromreserved: false,moveToReserveredfalse
> 2014-02-10 14:36:29,780 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-3=
5: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.cloudstac=
k.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 m=
igrate VM(i-2-38-VM) from host(335fb70f-e798-405b-b274-12053bc43051) due to=
 Task failed! Task record:                 uuid: 3456c28d-1c6f-ad87-1c7f-a4=
44b32f87a3
>            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-d=
8d2-10394df0aab7, running, halted]
>          otherConfig: {}
>            subtaskOf: com.xensource.xenapi.Task@aaf13f6f
>             subtasks: []
>         at com.cloud.vm.VirtualMachineManagerImpl.migrate(VirtualMachineM=
anagerImpl.java:1776)
>         at com.cloud.vm.VirtualMachineManagerImpl.orchestrateMigrate(Virt=
ualMachineManagerImpl.java:1684)
>         at com.cloud.vm.VirtualMachineManagerImpl.migrate(VirtualMachineM=
anagerImpl.java:1652)
>         at com.cloud.vm.UserVmManagerImpl.migrateVirtualMachine(UserVmMan=
agerImpl.java:4218)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccess=
orImpl.java:57)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMeth=
odAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:622)
>         at org.springframework.aop.support.AopUtils.invokeJoinpointUsingR=
eflection(AopUtils.java:317)
>         at org.springframework.aop.framework.ReflectiveMethodInvocation.i=
nvokeJoinpoint(ReflectiveMethodInvocation.java:183)
>         at org.springframework.aop.framework.ReflectiveMethodInvocation.p=
roceed(ReflectiveMethodInvocation.java:150)
>         at org.apache.cloudstack.network.contrail.management.EventUtils$E=
ventInterceptor.invoke(EventUtils.java:109)
>         at org.springframework.aop.framework.ReflectiveMethodInvocation.p=
roceed(ReflectiveMethodInvocation.java:161)
>         at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInter=
ceptor.java:50)
>         at org.springframework.aop.framework.ReflectiveMethodInvocation.p=
roceed(ReflectiveMethodInvocation.java:161)
>         at org.springframework.aop.interceptor.ExposeInvocationIntercepto=
r.invoke(ExposeInvocationInterceptor.java:91)
>         at org.springframework.aop.framework.ReflectiveMethodInvocation.p=
roceed(ReflectiveMethodInvocation.java:172)
>         at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(Jd=
kDynamicAopProxy.java:204)
>         at com.sun.proxy.$Proxy169.migrateVirtualMachine(Unknown Source)
>         at org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd.execut=
e(MigrateVMCmd.java:148)
>         at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
>         at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJo=
bDispatcher.java:109)
>         at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatche=
r.java:66)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatch=
er.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.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable.r=
un(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(ThreadPoolEx=
ecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.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-Exec=
utor-35:ctx-3af15cd6) Complete async job-61, jobStatus: FAILED, resultCode:=
 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"u=
uidList":[],"errorcode":530,"errortext":"Unable to migrate due to Catch Exc=
eption com.cloud.utils.exception.CloudRuntimeException: Migration failed du=
e to com.cloud.utils.exception.CloudRuntimeException: Unable to migrate VM(=
i-2-38-VM) from host(335fb70f-e798-405b-b274-12053bc43051) due to Task fail=
ed! Task record:                 uuid: 3456c28d-1c6f-ad87-1c7f-a444b32f87a3=
\n           nameLabel: Async.VM.pool_migrate\n     nameDescription: \n   a=
llowedOperations: []\n   currentOperations: {}\n             created: Mon F=
eb 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-Exec=
utor-35:ctx-3af15cd6) Done executing org.apache.cloudstack.api.command.admi=
n.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-2=
49:ctx-6e2f5b3d) Seq 1-1759117342: Response Received:
> 2014-02-10 14:36:29,859 DEBUG [c.c.a.t.Request] (DirectAgent-249:ctx-6e2f=
5b3d) Seq 1-1759117342: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"platform":"vir=
idian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","result":true,"d=
etails":"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 statu=
s.
> 2014-02-10 14:36:31,514 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-50=
756e82) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DqueryAsyncJo=
bResult&jobId=3Dd46bc3b4-b585-4f68-a68c-5442b26a3f95&response=3Djson&sessio=
nkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076496667
> 2014-02-10 14:36:31,533 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-50=
756e82 ctx-1dbcd23f) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dq=
ueryAsyncJobResult&jobId=3Dd46bc3b4-b585-4f68-a68c-5442b26a3f95&response=3D=
json&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076496667
> 2014-02-10 14:36:32,774 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-2:null) SeqA 3-45290: Processing Seq 3-45290:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:36:32,778 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-2:null) SeqA 3-45290: Sending Seq 3-45290:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:34,525 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ct=
x-4ea25a30) StorageCollector is running...
> 2014-02-10 14:36:34,634 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-4ea=
25a30) 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-2=
53:ctx-9be2b2dd) Seq 2-1390027713: Executing request
> 2014-02-10 14:36:34,915 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
53:ctx-9be2b2dd) Seq 2-1390027713: Response Received:
> 2014-02-10 14:36:34,915 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-4ea=
25a30) 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] (ClusteredAgentManage=
r Timer:ctx-c872f9d7) Resetting hosts suitable for reconnect
> 2014-02-10 14:36:35,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-c872f9d7) Completed resetting hosts suitable for reconnect
> 2014-02-10 14:36:35,875 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-c872f9d7) Acquiring hosts for clusters already owned by this ma=
nagement server
> 2014-02-10 14:36:35,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r 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] (ClusteredAgentManage=
r Timer:ctx-c872f9d7) Acquiring hosts for clusters not owned by any managem=
ent server
> 2014-02-10 14:36:35,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-c872f9d7) Completed acquiring hosts for clusters not owned by a=
ny management server
> 2014-02-10 14:36:37,930 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
49:ctx-380661ca) Ping from 1(xenserver-2)
> 2014-02-10 14:36:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
24:ctx-5b2af0d6) Seq 1-1759117314: Executing request
> 2014-02-10 14:36:38,186 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
24:ctx-5b2af0d6) Seq 1-1759117314: Response Received:
> 2014-02-10 14:36:38,187 DEBUG [c.c.a.t.Request] (DirectAgent-224:ctx-5b2a=
f0d6) 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-3=
26:ctx-ecd1b6e7) Ping from 2(xenserver-1)
> 2014-02-10 14:36:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
49: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-2=
49:ctx-7f7ac5fe) Seq 2-1390018562: Response Received:
> 2014-02-10 14:36:39,035 DEBUG [c.c.a.t.Request] (DirectAgent-249:ctx-7f7a=
c5fe) Seq 2-1390018562: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_cluste=
rId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:36:42,757 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-b04a0613) Zone 1 is ready to launch console proxy
> 2014-02-10 14:36:42,764 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-13:null) SeqA 3-45291: Processing Seq 3-45291:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:36:42,780 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-13:null) SeqA 3-45291: Sending Seq 3-45291:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:47,568 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-15:null) Ping from 4
> 2014-02-10 14:36:47,775 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-8:null) SeqA 3-45292: Processing Seq 3-45292:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:36:47,779 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-8:null) SeqA 3-45292: Sending Seq 3-45292:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:54,987 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-4:null) Ping from 3
> 2014-02-10 14:36:57,776 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-6:null) SeqA 3-45294: Processing Seq 3-45294:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:36:57,780 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-6:null) SeqA 3-45294: Sending Seq 3-45294:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:36:58,239 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ct=
x-cb20f99f) VmStatsCollector is running...
> 2014-02-10 14:36:58,256 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-4=
55:ctx-73af3935) Seq 2-1390027714: Executing request
> 2014-02-10 14:36:58,328 WARN  [c.c.a.m.DirectAgentAttache] (DirectAgent-4=
55: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(Cit=
rixResourceBase.java:7141)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(C=
itrixResourceBase.java:2737)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRe=
quest(CitrixResourceBase.java:493)
>         at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeR=
equest(XenServer56Resource.java:59)
>         at com.cloud.hypervisor.xen.resource.XenServer610Resource.execute=
Request(XenServer610Resource.java:106)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(D=
irectAgentAttache.java:216)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable$1=
.run(ManagedContextRunnable.java:49)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable.r=
un(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$ScheduledFutu=
reTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutu=
reTask.run(ScheduledThreadPoolExecutor.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx=
ecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.java:615)
>         at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:36:58,331 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-4=
55:ctx-73af3935) Seq 2-1390027714: Response Received:
> 2014-02-10 14:36:58,331 DEBUG [c.c.a.t.Request] (DirectAgent-455:ctx-73af=
3935) Seq 2-1390027714: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"det=
ails":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-3=
8-VM does not exist.","wait":0}}] }
> 2014-02-10 14:36:58,331 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-cb2=
0f99f) 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.GetVmStats=
Command: 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 statu=
s.
> 2014-02-10 14:37:00,410 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ct=
x-4ba43f99) HostStatsCollector is running...
> 2014-02-10 14:37:00,419 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-4=
24:ctx-1367caba) Seq 1-1759117343: Executing request
> 2014-02-10 14:37:00,649 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-4=
24:ctx-1367caba) Seq 1-1759117343: Response Received:
> 2014-02-10 14:37:00,649 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-4ba=
43f99) 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-3=
25:ctx-ba55e744) Seq 2-1390027715: Executing request
> 2014-02-10 14:37:00,840 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
25:ctx-ba55e744) Seq 2-1390027715: Response Received:
> 2014-02-10 14:37:00,840 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-4ba=
43f99) 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-Ha=
ndler-3:null) SeqA 3-45295: Processing Seq 3-45295:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:37:07,781 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-3:null) SeqA 3-45295: Sending Seq 3-45295:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:12,754 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-d641385c) Zone 1 is ready to launch console proxy
> 2014-02-10 14:37:12,762 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-7:null) SeqA 3-45296: Processing Seq 3-45296:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:37:17,782 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-7:null) SeqA 3-45296: Sending Seq 3-45296:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:27,779 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-9:null) SeqA 3-45297: Processing Seq 3-45297:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:37:27,783 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-9:null) SeqA 3-45297: Sending Seq 3-45297:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"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 statu=
s.
> 2014-02-10 14:37:34,916 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ct=
x-da91c10d) StorageCollector is running...
> 2014-02-10 14:37:35,025 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-da9=
1c10d) 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-2=
85:ctx-285c5002) Seq 2-1390027716: Executing request
> 2014-02-10 14:37:35,326 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
85:ctx-285c5002) Seq 2-1390027716: Response Received:
> 2014-02-10 14:37:35,326 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-da9=
1c10d) 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-0e=
6feb24) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistVirtualM=
achines&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=
=3Dtrue&page=3D1&pagesize=3D20&_=3D1392076561079
> 2014-02-10 14:37:35,958 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-0e=
6feb24 ctx-e1726ec3) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dl=
istVirtualMachines&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g=
%3D&listAll=3Dtrue&page=3D1&pagesize=3D20&_=3D1392076561079
> 2014-02-10 14:37:37,285 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-10=
39f878) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistZones&id=
=3Dcce32d06-91d9-47f0-90b5-766416d6add2&response=3Djson&sessionkey=3DgJbfxi=
FXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076562494
> 2014-02-10 14:37:37,300 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-10=
39f878 ctx-bd0dd379) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dl=
istZones&id=3Dcce32d06-91d9-47f0-90b5-766416d6add2&response=3Djson&sessionk=
ey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076562494
> 2014-02-10 14:37:37,364 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-716=
5f4b8) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistVirtualMa=
chines&id=3D6034fed3-bac7-4267-874b-fdbcdd58f610&response=3Djson&sessionkey=
=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076562547
> 2014-02-10 14:37:37,387 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-716=
5f4b8 ctx-b8dac40c) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dli=
stVirtualMachines&id=3D6034fed3-bac7-4267-874b-fdbcdd58f610&response=3Djson=
&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D1392076562547
> 2014-02-10 14:37:37,491 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-29=
2263b1) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistOsTypes&=
response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D13920765626=
06
> 2014-02-10 14:37:37,743 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-29=
2263b1 ctx-ac1fae13) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dl=
istOsTypes&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&_=3D=
1392076562606
> 2014-02-10 14:37:37,780 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-11:null) SeqA 3-45298: Processing Seq 3-45298:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:37:37,784 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-11:null) SeqA 3-45298: Sending Seq 3-45298:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:37,951 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
25:ctx-f2c44472) Ping from 1(xenserver-2)
> 2014-02-10 14:37:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
22:ctx-910abaca) Seq 1-1759117314: Executing request
> 2014-02-10 14:37:38,189 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
22:ctx-910abaca) Seq 1-1759117314: Response Received:
> 2014-02-10 14:37:38,190 DEBUG [c.c.a.t.Request] (DirectAgent-222:ctx-910a=
baca) 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-2=
60:ctx-e92300f9) Ping from 2(xenserver-1)
> 2014-02-10 14:37:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
25:ctx-dc3fca39) Seq 2-1390018562: Executing request
> 2014-02-10 14:37:38,968 DEBUG [c.c.a.t.Request] (catalina-exec-10:null) S=
eq 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) S=
eq 2-1390027717: Executing:  { Cmd , MgmtId: 214151488957798, via: 2(xenser=
ver-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-1=
6:ctx-c776cf4d) Seq 2-1390027717: Executing request
> 2014-02-10 14:37:39,033 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
25:ctx-dc3fca39) Seq 2-1390018562: Response Received:
> 2014-02-10 14:37:39,034 DEBUG [c.c.a.t.Request] (DirectAgent-325:ctx-dc3f=
ca39) Seq 2-1390018562: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_cluste=
rId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:37:39,059 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
6:ctx-c776cf4d) Seq 2-1390027717: Response Received:
> 2014-02-10 14:37:39,059 DEBUG [c.c.a.t.Request] (DirectAgent-16:ctx-c776c=
f4d) 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) S=
eq 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-1=
0: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 in=
fo: 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?tok=
en=3Dq0_dVRCybhgZdNYivppqPrL0oRbpTx9nxngJAbFqn3oUjUVtHDmQ3yZE2y4-6yJkuBXzEK=
7PS8GYQpdlBoQsH94PJYrLAFQjJWZuz9IenNf8L4NzvwrFgga6tDM2gSKCPMg_lvzToYsjs_cHC=
CqQmXUQCvToIYApsY_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 s=
rc=3D"https://10-223-138-75.realhostip.com/ajax?token=3Dq0_dVRCybhgZdNYivpp=
qPrL0oRbpTx9nxngJAbFqn3oUjUVtHDmQ3yZE2y4-6yJkuBXzEK7PS8GYQpdlBoQsH94PJYrLAF=
QjJWZuz9IenNf8L4NzvwrFgga6tDM2gSKCPMg_lvzToYsjs_cHCCqQmXUQCvToIYApsY_8Hq8GL=
PixG4fCqRx3uoxVbepzzCW5H-zEKqA3jIJAep5hdD4y1Q"></frame></frameset></html>
> 2014-02-10 14:37:42,752 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-ec897185) Zone 1 is ready to launch console proxy
> 2014-02-10 14:37:42,762 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-12:null) Ping from 4
> 2014-02-10 14:37:47,781 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-1:null) SeqA 3-45299: Processing Seq 3-45299:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:37:47,785 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-1:null) SeqA 3-45299: Sending Seq 3-45299:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:52,725 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-3d0=
a4fb1) =3D=3D=3DSTART=3D=3D=3D  10.215.2.19 -- GET  command=3DlistVirtualMa=
chines&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%3D&listAll=
=3Dtrue&page=3D1&pagesize=3D20&_=3D1392076577877
> 2014-02-10 14:37:52,752 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-3d0=
a4fb1 ctx-b8d0d388) =3D=3D=3DEND=3D=3D=3D  10.215.2.19 -- GET  command=3Dli=
stVirtualMachines&response=3Djson&sessionkey=3DgJbfxiFXGjIJTBqBPlcyevZSM1g%=
3D&listAll=3Dtrue&page=3D1&pagesize=3D20&_=3D1392076577877
> 2014-02-10 14:37:52,781 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-10:null) SeqA 3-45300: Processing Seq 3-45300:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:37:52,785 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-10:null) SeqA 3-45300: Sending Seq 3-45300:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:37:54,987 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-2:null) Ping from 3
> 2014-02-10 14:37:58,332 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ct=
x-7ab7bf75) VmStatsCollector is running...
> 2014-02-10 14:37:58,349 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
82:ctx-f29c7e66) Seq 2-1390027718: Executing request
> 2014-02-10 14:37:58,429 WARN  [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
82: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(Cit=
rixResourceBase.java:7141)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(C=
itrixResourceBase.java:2737)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRe=
quest(CitrixResourceBase.java:493)
>         at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeR=
equest(XenServer56Resource.java:59)
>         at com.cloud.hypervisor.xen.resource.XenServer610Resource.execute=
Request(XenServer610Resource.java:106)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(D=
irectAgentAttache.java:216)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable$1=
.run(ManagedContextRunnable.java:49)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable.r=
un(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$ScheduledFutu=
reTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutu=
reTask.run(ScheduledThreadPoolExecutor.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx=
ecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.java:615)
>         at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:37:58,430 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
82:ctx-f29c7e66) Seq 2-1390027718: Response Received:
> 2014-02-10 14:37:58,430 DEBUG [c.c.a.t.Request] (DirectAgent-282:ctx-f29c=
7e66) Seq 2-1390027718: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"det=
ails":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-3=
8-VM does not exist.","wait":0}}] }
> 2014-02-10 14:37:58,430 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-7ab=
7bf75) 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.GetVmStats=
Command: 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 statu=
s.
> 2014-02-10 14:38:00,841 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ct=
x-4d5a8698) HostStatsCollector is running...
> 2014-02-10 14:38:00,849 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-4=
45:ctx-fd874ed4) Seq 1-1759117344: Executing request
> 2014-02-10 14:38:01,073 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-4=
45:ctx-fd874ed4) Seq 1-1759117344: Response Received:
> 2014-02-10 14:38:01,074 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-4d5=
a8698) 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-2=
28:ctx-1cdd1cf1) Seq 2-1390027719: Executing request
> 2014-02-10 14:38:01,267 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
28:ctx-1cdd1cf1) Seq 2-1390027719: Response Received:
> 2014-02-10 14:38:01,267 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-4d5=
a8698) 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-Ha=
ndler-14:null) SeqA 3-45302: Processing Seq 3-45302:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:38:02,787 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-14:null) SeqA 3-45302: Sending Seq 3-45302:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:05,873 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-52c3ab01) Resetting hosts suitable for reconnect
> 2014-02-10 14:38:05,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-52c3ab01) Completed resetting hosts suitable for reconnect
> 2014-02-10 14:38:05,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-52c3ab01) Acquiring hosts for clusters already owned by this ma=
nagement server
> 2014-02-10 14:38:05,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r 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] (ClusteredAgentManage=
r Timer:ctx-52c3ab01) Acquiring hosts for clusters not owned by any managem=
ent server
> 2014-02-10 14:38:05,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-52c3ab01) Completed acquiring hosts for clusters not owned by a=
ny management server
> 2014-02-10 14:38:12,760 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-dc7efcf8) Zone 1 is ready to launch console proxy
> 2014-02-10 14:38:12,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-13:null) SeqA 3-45303: Processing Seq 3-45303:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:38:12,788 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-13:null) SeqA 3-45303: Sending Seq 3-45303:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:22,786 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-15:null) SeqA 3-45304: Processing Seq 3-45304:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:38:22,790 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-15:null) SeqA 3-45304: Sending Seq 3-45304:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"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 statu=
s.
> 2014-02-10 14:38:30,236 DEBUG [c.c.n.ExternalDeviceUsageManagerImpl] (Ext=
ernalNetworkMonitor-1:ctx-710ab70b) External devices stats collector is run=
ning...
> 2014-02-10 14:38:30,298 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPo=
llTask: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] (SnapshotPo=
llTask: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-Ha=
ndler-8:null) SeqA 3-45305: Processing Seq 3-45305:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:38:32,788 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-8:null) SeqA 3-45305: Sending Seq 3-45305:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:35,327 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ct=
x-243b2060) StorageCollector is running...
> 2014-02-10 14:38:35,435 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-243=
b2060) 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-1=
74:ctx-b0ffd04b) Seq 2-1390027720: Executing request
> 2014-02-10 14:38:35,728 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
74:ctx-b0ffd04b) Seq 2-1390027720: Response Received:
> 2014-02-10 14:38:35,728 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-243=
b2060) 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-4=
66:ctx-8a982e3b) Ping from 1(xenserver-2)
> 2014-02-10 14:38:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
74:ctx-89dca536) Seq 1-1759117314: Executing request
> 2014-02-10 14:38:38,182 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
74:ctx-89dca536) Seq 1-1759117314: Response Received:
> 2014-02-10 14:38:38,182 DEBUG [c.c.a.t.Request] (DirectAgent-174:ctx-89dc=
a536) 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-2=
58:ctx-21b81d02) Ping from 2(xenserver-1)
> 2014-02-10 14:38:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-8=
9:ctx-76b6b30c) Seq 2-1390018562: Executing request
> 2014-02-10 14:38:39,086 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-8=
9:ctx-76b6b30c) Seq 2-1390018562: Response Received:
> 2014-02-10 14:38:39,086 DEBUG [c.c.a.t.Request] (DirectAgent-89:ctx-76b6b=
30c) Seq 2-1390018562: Processing:  { Ans: , MgmtId: 214151488957798, via: =
2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_cluster=
Id":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:38:42,756 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-cf975fa4) Zone 1 is ready to launch console proxy
> 2014-02-10 14:38:42,762 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-6:null) SeqA 3-45306: Processing Seq 3-45306:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:38:42,789 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-6:null) SeqA 3-45306: Sending Seq 3-45306:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:47,567 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-3:null) Ping from 4
> 2014-02-10 14:38:52,786 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-7:null) SeqA 3-45307: Processing Seq 3-45307:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:38:52,791 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-7:null) SeqA 3-45307: Sending Seq 3-45307:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:54,987 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-9:null) Ping from 3
> 2014-02-10 14:38:57,786 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-5:null) SeqA 3-45309: Processing Seq 3-45309:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:38:57,790 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-5:null) SeqA 3-45309: Sending Seq 3-45309:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:38:58,431 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ct=
x-419bf9a3) VmStatsCollector is running...
> 2014-02-10 14:38:58,450 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
25:ctx-182ba614) Seq 2-1390027721: Executing request
> 2014-02-10 14:38:58,525 WARN  [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
25: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(Cit=
rixResourceBase.java:7141)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(C=
itrixResourceBase.java:2737)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRe=
quest(CitrixResourceBase.java:493)
>         at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeR=
equest(XenServer56Resource.java:59)
>         at com.cloud.hypervisor.xen.resource.XenServer610Resource.execute=
Request(XenServer610Resource.java:106)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(D=
irectAgentAttache.java:216)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable$1=
.run(ManagedContextRunnable.java:49)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable.r=
un(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$ScheduledFutu=
reTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutu=
reTask.run(ScheduledThreadPoolExecutor.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx=
ecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.java:615)
>         at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:38:58,527 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
25:ctx-182ba614) Seq 2-1390027721: Response Received:
> 2014-02-10 14:38:58,527 DEBUG [c.c.a.t.Request] (DirectAgent-225:ctx-182b=
a614) Seq 2-1390027721: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"det=
ails":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-3=
8-VM does not exist.","wait":0}}] }
> 2014-02-10 14:38:58,527 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-419=
bf9a3) 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.GetVmStats=
Command: 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 statu=
s.
> 2014-02-10 14:39:00,252 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Host=
ReservationReleaseChecker:ctx-4a5d6144) Checking if any host reservation ca=
n be released ...
> 2014-02-10 14:39:00,260 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Host=
ReservationReleaseChecker:ctx-4a5d6144) Cannot release reservation, Found 5=
 VMs Running on host 2
> 2014-02-10 14:39:00,260 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Host=
ReservationReleaseChecker:ctx-4a5d6144) Done running HostReservationRelease=
Checker ...
> 2014-02-10 14:39:00,287 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-59ff3a70) Running Capacity Checker ...
> 2014-02-10 14:39:00,287 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-59ff3a70) recalculating system capacity
> 2014-02-10 14:39:00,288 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-59ff3a70) Executing cpu/ram capacity update
> 2014-02-10 14:39:00,292 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecke=
r:ctx-59ff3a70) Found 0 VMs on host 1
> 2014-02-10 14:39:00,294 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecke=
r:ctx-59ff3a70) Found 0 VM, not running on host 1
> 2014-02-10 14:39:00,295 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecke=
r:ctx-59ff3a70) No need to calibrate cpu capacity, host:1 usedCpu: 0 reserv=
edCpu: 0
> 2014-02-10 14:39:00,295 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecke=
r:ctx-59ff3a70) No need to calibrate memory capacity, host:1 usedMem: 0 res=
ervedMem: 0
> 2014-02-10 14:39:00,303 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecke=
r:ctx-59ff3a70) Found 5 VMs on host 2
> 2014-02-10 14:39:00,312 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecke=
r:ctx-59ff3a70) Found 0 VM, not running on host 2
> 2014-02-10 14:39:00,315 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecke=
r:ctx-59ff3a70) No need to calibrate cpu capacity, host:2 usedCpu: 2500 res=
ervedCpu: 0
> 2014-02-10 14:39:00,315 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecke=
r:ctx-59ff3a70) No need to calibrate memory capacity, host:2 usedMem: 32212=
25472 reservedMem: 0
> 2014-02-10 14:39:00,315 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-59ff3a70) Done executing cpu/ram capacity update
> 2014-02-10 14:39:00,315 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-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:c=
tx-59ff3a70) Done executing storage capacity update
> 2014-02-10 14:39:00,325 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-59ff3a70) Executing capacity updates for public ip and Vlans
> 2014-02-10 14:39:00,340 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-59ff3a70) Done capacity updates for public ip and Vlans
> 2014-02-10 14:39:00,340 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-59ff3a70) Executing capacity updates for private ip
> 2014-02-10 14:39:00,346 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-59ff3a70) Done executing capacity updates for private ip
> 2014-02-10 14:39:00,346 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-59ff3a70) Done recalculating system capacity
> 2014-02-10 14:39:00,364 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:c=
tx-59ff3a70) Done running Capacity Checker ...
> 2014-02-10 14:39:01,267 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ct=
x-b39b0684) HostStatsCollector is running...
> 2014-02-10 14:39:01,276 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-4=
46:ctx-8147a9eb) Seq 1-1759117345: Executing request
> 2014-02-10 14:39:01,500 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-4=
46:ctx-8147a9eb) Seq 1-1759117345: Response Received:
> 2014-02-10 14:39:01,502 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-b39=
b0684) 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-3=
82:ctx-60ff9a26) Seq 2-1390027722: Executing request
> 2014-02-10 14:39:01,694 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
82:ctx-60ff9a26) Seq 2-1390027722: Response Received:
> 2014-02-10 14:39:01,694 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-b39=
b0684) 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-Ha=
ndler-11:null) SeqA 3-45310: Processing Seq 3-45310:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:39:07,792 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-11:null) SeqA 3-45310: Sending Seq 3-45310:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:12,758 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-a32d7ddb) Zone 1 is ready to launch console proxy
> 2014-02-10 14:39:12,764 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-12:null) SeqA 3-45311: Processing Seq 3-45311:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:39:17,792 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-12:null) SeqA 3-45311: Sending Seq 3-45311:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:27,789 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-1:null) SeqA 3-45312: Processing Seq 3-45312:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:39:27,793 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-1:null) SeqA 3-45312: Sending Seq 3-45312:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"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 statu=
s.
> 2014-02-10 14:39:35,729 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ct=
x-cb4dae1d) StorageCollector is running...
> 2014-02-10 14:39:35,838 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-cb4=
dae1d) 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-6=
9:ctx-96573069) Seq 2-1390027723: Executing request
> 2014-02-10 14:39:35,873 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-4664ac95) Resetting hosts suitable for reconnect
> 2014-02-10 14:39:35,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-4664ac95) Completed resetting hosts suitable for reconnect
> 2014-02-10 14:39:35,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-4664ac95) Acquiring hosts for clusters already owned by this ma=
nagement server
> 2014-02-10 14:39:35,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r 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] (ClusteredAgentManage=
r Timer:ctx-4664ac95) Acquiring hosts for clusters not owned by any managem=
ent server
> 2014-02-10 14:39:35,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-4664ac95) Completed acquiring hosts for clusters not owned by a=
ny management server
> 2014-02-10 14:39:36,128 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-6=
9:ctx-96573069) Seq 2-1390027723: Response Received:
> 2014-02-10 14:39:36,128 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-cb4=
dae1d) 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-Ha=
ndler-2:null) SeqA 3-45313: Processing Seq 3-45313:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:39:37,794 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-2:null) SeqA 3-45313: Sending Seq 3-45313:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:37,932 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
8:ctx-e345b6a3) Ping from 1(xenserver-2)
> 2014-02-10 14:39:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-6=
9:ctx-d4555d96) Seq 1-1759117314: Executing request
> 2014-02-10 14:39:38,182 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-6=
9:ctx-d4555d96) Seq 1-1759117314: Response Received:
> 2014-02-10 14:39:38,182 DEBUG [c.c.a.t.Request] (DirectAgent-69:ctx-d4555=
d96) 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-3=
70:ctx-67d244ac) Ping from 2(xenserver-1)
> 2014-02-10 14:39:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
8:ctx-7bf8c480) Seq 2-1390018562: Executing request
> 2014-02-10 14:39:39,036 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
8:ctx-7bf8c480) Seq 2-1390018562: Response Received:
> 2014-02-10 14:39:39,036 DEBUG [c.c.a.t.Request] (DirectAgent-38:ctx-7bf8c=
480) Seq 2-1390018562: Processing:  { Ans: , MgmtId: 214151488957798, via: =
2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_cluster=
Id":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:39:42,760 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-ecc402ab) Zone 1 is ready to launch console proxy
> 2014-02-10 14:39:42,764 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-14:null) Ping from 4
> 2014-02-10 14:39:47,791 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-13:null) SeqA 3-45314: Processing Seq 3-45314:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:39:47,795 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-13:null) SeqA 3-45314: Sending Seq 3-45314:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:52,791 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-15:null) SeqA 3-45315: Processing Seq 3-45315:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:39:52,795 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-15:null) SeqA 3-45315: Sending Seq 3-45315:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:39:54,986 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-8:null) Ping from 3
> 2014-02-10 14:39:58,528 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ct=
x-1d8f4ec4) VmStatsCollector is running...
> 2014-02-10 14:39:58,546 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
51:ctx-505b0ef3) Seq 2-1390027724: Executing request
> 2014-02-10 14:39:58,620 WARN  [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
51: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(Cit=
rixResourceBase.java:7141)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(C=
itrixResourceBase.java:2737)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRe=
quest(CitrixResourceBase.java:493)
>         at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeR=
equest(XenServer56Resource.java:59)
>         at com.cloud.hypervisor.xen.resource.XenServer610Resource.execute=
Request(XenServer610Resource.java:106)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(D=
irectAgentAttache.java:216)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable$1=
.run(ManagedContextRunnable.java:49)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable.r=
un(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$ScheduledFutu=
reTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutu=
reTask.run(ScheduledThreadPoolExecutor.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx=
ecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.java:615)
>         at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:39:58,621 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
51:ctx-505b0ef3) Seq 2-1390027724: Response Received:
> 2014-02-10 14:39:58,621 DEBUG [c.c.a.t.Request] (DirectAgent-151:ctx-505b=
0ef3) Seq 2-1390027724: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"det=
ails":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-3=
8-VM does not exist.","wait":0}}] }
> 2014-02-10 14:39:58,621 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-1d8=
f4ec4) 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.GetVmStats=
Command: 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 statu=
s.
> 2014-02-10 14:40:01,695 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ct=
x-5ce8171a) HostStatsCollector is running...
> 2014-02-10 14:40:01,706 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
48:ctx-a399863d) Seq 1-1759117346: Executing request
> 2014-02-10 14:40:01,930 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
48:ctx-a399863d) Seq 1-1759117346: Response Received:
> 2014-02-10 14:40:01,931 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-5ce=
8171a) 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-1=
75:ctx-14183950) Seq 2-1390027725: Executing request
> 2014-02-10 14:40:02,119 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
75:ctx-14183950) Seq 2-1390027725: Response Received:
> 2014-02-10 14:40:02,119 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-5ce=
8171a) 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-Ha=
ndler-4:null) SeqA 3-45317: Processing Seq 3-45317:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:40:02,797 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-4:null) SeqA 3-45317: Sending Seq 3-45317:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:12,757 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-0d123b57) Zone 1 is ready to launch console proxy
> 2014-02-10 14:40:12,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-6:null) SeqA 3-45318: Processing Seq 3-45318:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:40:12,797 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-6:null) SeqA 3-45318: Sending Seq 3-45318:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:22,793 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-3:null) SeqA 3-45319: Processing Seq 3-45319:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:40:22,797 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-3:null) SeqA 3-45319: Sending Seq 3-45319:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"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 statu=
s.
> 2014-02-10 14:40:32,794 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-7:null) SeqA 3-45320: Processing Seq 3-45320:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:40:32,799 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-7:null) SeqA 3-45320: Sending Seq 3-45320:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:36,129 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ct=
x-c9a87e02) StorageCollector is running...
> 2014-02-10 14:40:36,240 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-c9a=
87e02) 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-1=
14:ctx-bc8e2688) Seq 2-1390027726: Executing request
> 2014-02-10 14:40:36,527 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
14:ctx-bc8e2688) Seq 2-1390027726: Response Received:
> 2014-02-10 14:40:36,527 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-c9a=
87e02) 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-1=
75:ctx-faee3b46) Ping from 1(xenserver-2)
> 2014-02-10 14:40:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
14:ctx-df3f84d6) Seq 1-1759117314: Executing request
> 2014-02-10 14:40:38,182 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
14:ctx-df3f84d6) Seq 1-1759117314: Response Received:
> 2014-02-10 14:40:38,182 DEBUG [c.c.a.t.Request] (DirectAgent-114:ctx-df3f=
84d6) 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-4=
68:ctx-e23894d0) Ping from 2(xenserver-1)
> 2014-02-10 14:40:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
14:ctx-84e13d0b) Seq 2-1390018562: Executing request
> 2014-02-10 14:40:39,054 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
14:ctx-84e13d0b) Seq 2-1390018562: Response Received:
> 2014-02-10 14:40:39,054 DEBUG [c.c.a.t.Request] (DirectAgent-114:ctx-84e1=
3d0b) Seq 2-1390018562: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_cluste=
rId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:40:42,759 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-2945943a) Zone 1 is ready to launch console proxy
> 2014-02-10 14:40:42,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-5:null) SeqA 3-45321: Processing Seq 3-45321:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:40:42,800 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-5:null) SeqA 3-45321: Sending Seq 3-45321:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:47,566 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-11:null) Ping from 4
> 2014-02-10 14:40:52,796 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-12:null) SeqA 3-45322: Processing Seq 3-45322:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:40:52,800 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-12:null) SeqA 3-45322: Sending Seq 3-45322:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:54,986 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-1:null) Ping from 3
> 2014-02-10 14:40:57,796 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-10:null) SeqA 3-45324: Processing Seq 3-45324:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:40:57,800 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-10:null) SeqA 3-45324: Sending Seq 3-45324:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:40:58,622 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ct=
x-dde6856e) VmStatsCollector is running...
> 2014-02-10 14:40:58,640 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
23:ctx-5c36cbe8) Seq 2-1390027727: Executing request
> 2014-02-10 14:40:58,713 WARN  [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
23: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(Cit=
rixResourceBase.java:7141)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(C=
itrixResourceBase.java:2737)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRe=
quest(CitrixResourceBase.java:493)
>         at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeR=
equest(XenServer56Resource.java:59)
>         at com.cloud.hypervisor.xen.resource.XenServer610Resource.execute=
Request(XenServer610Resource.java:106)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(D=
irectAgentAttache.java:216)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable$1=
.run(ManagedContextRunnable.java:49)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable.r=
un(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$ScheduledFutu=
reTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutu=
reTask.run(ScheduledThreadPoolExecutor.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx=
ecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.java:615)
>         at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:40:58,714 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
23:ctx-5c36cbe8) Seq 2-1390027727: Response Received:
> 2014-02-10 14:40:58,715 DEBUG [c.c.a.t.Request] (DirectAgent-123:ctx-5c36=
cbe8) Seq 2-1390027727: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"det=
ails":"com.cloud.utils.exception.CloudRuntimeException: VM with name: i-2-3=
8-VM does not exist.","wait":0}}] }
> 2014-02-10 14:40:58,715 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-dde=
6856e) 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.GetVmStats=
Command: 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 statu=
s.
> 2014-02-10 14:41:02,120 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ct=
x-d640815a) HostStatsCollector is running...
> 2014-02-10 14:41:02,130 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
95:ctx-6f2696ce) Seq 1-1759117347: Executing request
> 2014-02-10 14:41:02,351 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1=
95:ctx-6f2696ce) Seq 1-1759117347: Response Received:
> 2014-02-10 14:41:02,351 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-d64=
0815a) 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-3=
44:ctx-c8b772fa) Seq 2-1390027728: Executing request
> 2014-02-10 14:41:02,541 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
44:ctx-c8b772fa) Seq 2-1390027728: Response Received:
> 2014-02-10 14:41:02,541 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-d64=
0815a) 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] (ClusteredAgentManage=
r Timer:ctx-34737948) Resetting hosts suitable for reconnect
> 2014-02-10 14:41:05,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-34737948) Completed resetting hosts suitable for reconnect
> 2014-02-10 14:41:05,874 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-34737948) Acquiring hosts for clusters already owned by this ma=
nagement server
> 2014-02-10 14:41:05,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r 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] (ClusteredAgentManage=
r Timer:ctx-34737948) Acquiring hosts for clusters not owned by any managem=
ent server
> 2014-02-10 14:41:05,876 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManage=
r Timer:ctx-34737948) Completed acquiring hosts for clusters not owned by a=
ny management server
> 2014-02-10 14:41:07,797 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-2:null) SeqA 3-45325: Processing Seq 3-45325:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:41:07,802 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-2:null) SeqA 3-45325: Sending Seq 3-45325:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:12,754 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-85920355) Zone 1 is ready to launch console proxy
> 2014-02-10 14:41:12,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-14:null) SeqA 3-45326: Processing Seq 3-45326:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:41:17,802 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-14:null) SeqA 3-45326: Sending Seq 3-45326:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:27,808 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-13:null) SeqA 3-45327: Processing Seq 3-45327:  { Cmd , MgmtId: -1, v=
ia: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCom=
mand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}]=
 }
> 2014-02-10 14:41:27,813 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-13:null) SeqA 3-45327: Sending Seq 3-45327:  { Ans: , MgmtId: 2141514=
88957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContr=
olAnswer":{"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 statu=
s.
> 2014-02-10 14:41:36,528 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ct=
x-bb4e55f0) StorageCollector is running...
> 2014-02-10 14:41:36,658 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-bb4=
e55f0) 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-3=
29:ctx-b3c50c53) Seq 2-1390027729: Executing request
> 2014-02-10 14:41:36,949 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
29:ctx-b3c50c53) Seq 2-1390027729: Response Received:
> 2014-02-10 14:41:36,949 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-bb4=
e55f0) 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-Ha=
ndler-8:null) SeqA 3-45328: Processing Seq 3-45328:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:41:37,806 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-8:null) SeqA 3-45328: Sending Seq 3-45328:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:37,932 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
44:ctx-b4d89ed1) Ping from 1(xenserver-2)
> 2014-02-10 14:41:38,089 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
29:ctx-5367de97) Seq 1-1759117314: Executing request
> 2014-02-10 14:41:38,181 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
29:ctx-5367de97) Seq 1-1759117314: Response Received:
> 2014-02-10 14:41:38,181 DEBUG [c.c.a.t.Request] (DirectAgent-329:ctx-5367=
de97) 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-3=
23:ctx-bd019cfc) Ping from 2(xenserver-1)
> 2014-02-10 14:41:38,814 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
29:ctx-e1585c86) Seq 2-1390018562: Executing request
> 2014-02-10 14:41:39,030 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
29:ctx-e1585c86) Seq 2-1390018562: Response Received:
> 2014-02-10 14:41:39,030 DEBUG [c.c.a.t.Request] (DirectAgent-329:ctx-e158=
5c86) Seq 2-1390018562: Processing:  { Ans: , MgmtId: 214151488957798, via:=
 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_cluste=
rId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2014-02-10 14:41:42,751 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro=
xy-1:ctx-9088df57) Zone 1 is ready to launch console proxy
> 2014-02-10 14:41:42,763 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs=
torage-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-Ha=
ndler-4:null) Ping from 4
> 2014-02-10 14:41:47,801 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-6:null) SeqA 3-45329: Processing Seq 3-45329:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:41:47,805 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-6:null) SeqA 3-45329: Sending Seq 3-45329:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:54,986 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-3:null) Ping from 3
> 2014-02-10 14:41:57,801 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-7:null) SeqA 3-45331: Processing Seq 3-45331:  { Cmd , MgmtId: -1, vi=
a: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportComm=
and":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] =
}
> 2014-02-10 14:41:57,805 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha=
ndler-7:null) SeqA 3-45331: Sending Seq 3-45331:  { Ans: , MgmtId: 21415148=
8957798, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentContro=
lAnswer":{"result":true,"wait":0}}] }
> 2014-02-10 14:41:58,716 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ct=
x-4f87ed5b) VmStatsCollector is running...
> 2014-02-10 14:41:58,734 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-9=
9:ctx-87c8824c) Seq 2-1390027730: Executing request
> 2014-02-10 14:41:58,816 WARN  [c.c.a.m.DirectAgentAttache] (DirectAgent-9=
9: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(Cit=
rixResourceBase.java:7141)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(C=
itrixResourceBase.java:2737)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRe=
quest(CitrixResourceBase.java:493)
>         at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeR=
equest(XenServer56Resource.java:59)
>         at com.cloud.hypervisor.xen.resource.XenServer610Resource.execute=
Request(XenServer610Resource.java:106)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(D=
irectAgentAttache.java:216)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable$1=
.run(ManagedContextRunnable.java:49)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt$1.call(DefaultManagedContext.java:56)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.callWithContext(DefaultManagedContext.java:103)
>         at org.apache.cloudstack.managed.context.impl.DefaultManagedConte=
xt.runWithContext(DefaultManagedContext.java:53)
>         at org.apache.cloudstack.managed.context.ManagedContextRunnable.r=
un(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$ScheduledFutu=
reTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutu=
reTask.run(ScheduledThreadPoolExecutor.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx=
ecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.java:615)
>         at java.lang.Thread.run(Thread.java:701)
> 2014-02-10 14:41:58,817 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-9=
9:ctx-87c8824c) Seq 2-1390027730: Response Received:
> 2014-02-10 14:41:58,817 DEBUG [c.c.a.t.Request] (DirectAgent-99:ctx-87c88=
24c) Seq 2-1390027730: Processing:  { Ans: , MgmtId: 214151488957798, via: =
2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"deta=
ils":"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-4f8=
7ed5b) 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.GetVmStats=
Command: 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 statu=
s.
> 2014-02-10 14:42:02,542 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ct=
x-d7879c2b) HostStatsCollector is running...
> 2014-02-10 14:42:02,551 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
3:ctx-15d78667) Seq 1-1759117348: Executing request
> 2014-02-10 14:42:02,773 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-3=
3:ctx-15d78667) Seq 1-1759117348: Response Received:
> 2014-02-10 14:42:02,774 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-d78=
79c2b) 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-2=
90:ctx-6919265f) Seq 2-1390027731: Executing request
> 2014-02-10 14:42:02,961 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-2=
90:ctx-6919265f) Seq 2-1390027731: Response Received:
> 2014-02-10 14:42:02,962 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-d78=
79c2b) 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)