You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Osay Osman Yuuni <oy...@gmail.com> on 2014/03/24 07:20:54 UTC
Instantiated CentOS VMs shutting down
Hi,
I have a CS 4.2.1 installed with XCP 6.1 as hypervisor. I have various
templates (windows 2k12R2, CentOS 6.3, CentOS 6.5, Ubuntu 12.04.3 LTS).
I'm able to instantiate windows and Ubuntu VMs without issues but when I
instantiate the CentOS 6.3 or 6.5 VMs they just die. The VM appears in the
hypervisor and after about a minute it disappears. In the management
server GUI the VM is stopped. When I restart it, it starts but after about
a minute it stops again. I've combed through the management server log but
am unable to pin down what is causing this to happen. Is it that CentOS 6
is unsupported (the default 5.6 template can be instantiated without
issues).
Below is a snippet of the management server log. The only issue I see is
the error "cannot bridge firewall", which to be honest, I don't
understand. Perhaps the more seasoned users can point out something that's
obviously causing the VM to stop?
=======================================
2014-03-24 08:04:41,048 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Hosts's
actual total CPU: 160000 and CPU after applying overprovisioning: 160000
2014-03-24 08:04:41,048 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) We need
to allocate to the last host again, so checking if there is enough reserved
capacity
2014-03-24 08:04:41,048 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Reserved CPU: 0 , Requested CPU: 1500
2014-03-24 08:04:41,048 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Reserved RAM: 0 , Requested RAM: 1073741824
2014-03-24 08:04:41,048 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) STATS:
Failed to alloc resource from host: 1 reservedCpu: 0, requested cpu: 1500,
reservedMem: 0, requested mem: 1073741824
2014-03-24 08:04:41,049 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Host
does not have enough reserved CPU available, cannot allocate to this host.
2014-03-24 08:04:41,049 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) The
last host of this VM does not have enough capacity
2014-03-24 08:04:41,049 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Cannot
choose the last host to deploy this VM
2014-03-24 08:04:41,049 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Searching resources only under specified Cluster: 1
2014-03-24 08:04:41,072 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Checking resources in Cluster: 1 under Pod: 1
2014-03-24 08:04:41,082 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2014-03-24 08:04:41,095 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for
allocation: [Host[-1-Routing]]
2014-03-24 08:04:41,107 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) Found 1 hosts for allocation after
prioritization: [Host[-1-Routing]]
2014-03-24 08:04:41,107 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) Looking for speed=1500Mhz, Ram=1024
2014-03-24 08:04:41,132 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for
requested CPU: 1500 and requested RAM: 1073741824 ,
cpuOverprovisioningFactor: 1.0
2014-03-24 08:04:41,143 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 160000 and CPU after
applying overprovisioning: 160000
2014-03-24 08:04:41,143 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) Free CPU: 157000 , Requested CPU: 1500
2014-03-24 08:04:41,143 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) Free RAM: 537663799296 , Requested RAM: 1073741824
2014-03-24 08:04:41,143 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-03-24 08:04:41,143 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 3000,
reserved: 0, actual total: 160000, total with overprovisioning: 160000;
requested cpu:1500,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-03-24 08:04:41,144 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used:
2550136832, reserved: 0, total: 540213936128; requested mem:
1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-03-24 08:04:41,144 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2014-03-24 08:04:41,144 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2014-03-24 08:04:41,151 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Checking suitable pools for volume (Id, Type): (16,ROOT)
2014-03-24 08:04:41,152 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Volume
has pool already allocated, checking if pool can be reused, poolId: 2
2014-03-24 08:04:41,156 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Planner
need not allocate a pool for this volume since its READY
2014-03-24 08:04:41,157 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Checking suitable pools for volume (Id, Type): (17,DATADISK)
2014-03-24 08:04:41,157 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Volume
has pool already allocated, checking if pool can be reused, poolId: 2
2014-03-24 08:04:41,161 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Planner
need not allocate a pool for this volume since its READY
2014-03-24 08:04:41,162 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Trying
to find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2014-03-24 08:04:41,162 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Checking if host: 1 can access any suitable storage pool for volume: ROOT
2014-03-24 08:04:41,166 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Host: 1
can access pool: 2
2014-03-24 08:04:41,166 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Checking if host: 1 can access any suitable storage pool for volume:
DATADISK
2014-03-24 08:04:41,170 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Host: 1
can access pool: 2
2014-03-24 08:04:41,174 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Found a
potential host id: 1 name: cloudsrv1.afdb.org and associated storage pools
for this VM
2014-03-24 08:04:41,179 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2014-03-24 08:04:41,233 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) VM
state transitted from :Stopped to Starting with event: StartRequestedvm's
original host id: 1 new host id: null host id before state transition: null
2014-03-24 08:04:41,234 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Successfully transitioned to start state for
VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c] reservation id =
e79b6036-20a0-4a9d-a76e-73010097026a
2014-03-24 08:04:41,247 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Trying
to deploy VM, vm has dcId: 1 and podId: 1
2014-03-24 08:04:41,247 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1,
clusterId: 1, hostId: 1, poolId: null
2014-03-24 08:04:41,247 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Deploy
avoids pods: null, clusters: null, hosts: null
2014-03-24 08:04:41,259 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Root
volume is ready, need to place VM in volume's cluster
2014-03-24 08:04:41,293 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Deploy
avoids pods: [], clusters: [], hosts: []
2014-03-24 08:04:41,293 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
DeploymentPlanner allocation algorithm:
com.cloud.deploy.UserDispersingPlanner_EnhancerByCloudStack_b1882cfb@554079b2
2014-03-24 08:04:41,293 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Trying
to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested
cpu: 1500, requested ram: 1073741824
2014-03-24 08:04:41,294 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Is ROOT
volume READY (pool already allocated)?: Yes
2014-03-24 08:04:41,294 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
DeploymentPlan has host_id specified, choosing this host and making no
checks on this host: 1
2014-03-24 08:04:41,300 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Looking
for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2014-03-24 08:04:41,307 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Checking suitable pools for volume (Id, Type): (16,ROOT)
2014-03-24 08:04:41,308 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Volume
has pool already allocated, checking if pool can be reused, poolId: 2
2014-03-24 08:04:41,313 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Planner
need not allocate a pool for this volume since its READY
2014-03-24 08:04:41,314 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Checking suitable pools for volume (Id, Type): (17,DATADISK)
2014-03-24 08:04:41,314 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Volume
has pool already allocated, checking if pool can be reused, poolId: 2
2014-03-24 08:04:41,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Planner
need not allocate a pool for this volume since its READY
2014-03-24 08:04:41,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Trying
to find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2014-03-24 08:04:41,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Checking if host: 1 can access any suitable storage pool for volume: ROOT
2014-03-24 08:04:41,323 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Host: 1
can access pool: 2
2014-03-24 08:04:41,324 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Checking if host: 1 can access any suitable storage pool for volume:
DATADISK
2014-03-24 08:04:41,328 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Host: 1
can access pool: 2
2014-03-24 08:04:41,331 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Found a
potential host id: 1 name: cloudsrv1.afdb.org and associated storage pools
for this VM
2014-03-24 08:04:41,335 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2014-03-24 08:04:41,335 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Deployment found - P0=VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2014-03-24 08:04:41,374 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) VM
state transitted from :Starting to Starting with event: OperationRetryvm's
original host id: 1 new host id: 1 host id before state transition: null
2014-03-24 08:04:41,382 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) VM
starting again on the last host it was stopped on
2014-03-24 08:04:41,414 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Hosts's
actual total CPU: 160000 and CPU after applying overprovisioning: 160000
2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) We are
allocating VM, increasing the used capacity of this host:1
2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Current
Used CPU: 3000 , Free CPU:157000 ,Requested CPU: 1500
2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Current
Used RAM: 2550136832 , Free RAM:537663799296 ,Requested RAM: 1073741824
2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) We are
allocating VM to the last host again, so adjusting the reserved capacity if
it is not less than required
2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Reserved CPU: 0 , Requested CPU: 1500
2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Reserved RAM: 0 , Requested RAM: 1073741824
2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) CPU
STATS after allocation: for host: 1, old used: 3000, old reserved: 0,
actual total: 160000, total with overprovisioning: 160000; new used:4500,
reserved:0; requested cpu:1500,alloc_from_last:true
2014-03-24 08:04:41,416 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) RAM
STATS after allocation: for host: 1, old used: 2550136832, old reserved: 0,
total: 540213936128; new used: 3623878656, reserved: 0; requested mem:
1073741824,alloc_from_last:true
2014-03-24 08:04:41,426 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) VM is
being created in podId: 1
2014-03-24 08:04:41,433 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-4:null) SeqA 2-54055: Processing Seq 2-54055: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-03-24 08:04:41,446 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-4:null) SeqA 2-54055: Sending Seq 2-54055: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-03-24 08:04:41,464 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Network
id=204 is already implemented
2014-03-24 08:04:41,551 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Changing active number of nics for network id=204 on 1
2014-03-24 08:04:41,577 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Asking
VirtualRouter to prepare for
Nic[17-10-e79b6036-20a0-4a9d-a76e-73010097026a-192.168.40.185]
2014-03-24 08:04:41,619 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:job-33
= [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Lock is acquired for network id
204 as a part of router startup in
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2014-03-24 08:04:41,630 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:job-33
= [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Lock is released for network id
204 as a part of router startup in
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2014-03-24 08:04:41,721 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:job-33
= [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Applying dhcp entry in network
Ntwk[204|Guest|6]
2014-03-24 08:04:41,786 DEBUG [agent.transport.Request]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
1-212812146: Sending { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
Flags: 100111,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f4:a0:00:00:0e","vmIpAddress":"192.168.40.185","vmName":"e461c77d-9d39-43f2-94c3-79d00c36315c","defaultRouter":"192.168.40.1","defaultDns":"192.168.40.183","duid":"00:03:00:01:06:f4:a0:00:00:0e","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","
router.name":"r-4-VM","router.ip":"169.254.2.80"},"wait":0}}] }
2014-03-24 08:04:41,788 DEBUG [agent.transport.Request]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
1-212812146: Executing: { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
Flags: 100111,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f4:a0:00:00:0e","vmIpAddress":"192.168.40.185","vmName":"e461c77d-9d39-43f2-94c3-79d00c36315c","defaultRouter":"192.168.40.1","defaultDns":"192.168.40.183","duid":"00:03:00:01:06:f4:a0:00:00:0e","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","
router.name":"r-4-VM","router.ip":"169.254.2.80"},"wait":0}}] }
2014-03-24 08:04:41,789 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-377:null) Seq 1-212812146: Executing request
2014-03-24 08:04:42,782 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-377:null) Seq 1-212812146: Response Received:
2014-03-24 08:04:42,783 DEBUG [agent.transport.Request]
(DirectAgent-377:null) Seq 1-212812146: Processing: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-03-24 08:04:42,784 DEBUG [agent.transport.Request]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
1-212812146: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1,
Flags: 110, { Answer } }
2014-03-24 08:04:42,784 DEBUG [agent.manager.AgentAttache]
(DirectAgent-377:null) Seq 1-212812146: No more commands found
2014-03-24 08:04:42,824 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:job-33
= [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Applying userdata and password
entry in network Ntwk[204|Guest|6]
2014-03-24 08:04:42,866 DEBUG [agent.transport.Request]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
1-212812147: Sending { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
Flags: 100111,
[{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.40.185","vmName":"e461c77d-9d39-43f2-94c3-79d00c36315c","executeInSequence":true,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.2.80","
router.name":"r-4-VM"},"wait":0}}] }
2014-03-24 08:04:42,867 DEBUG [agent.transport.Request]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
1-212812147: Executing: { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
Flags: 100111,
[{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.40.185","vmName":"e461c77d-9d39-43f2-94c3-79d00c36315c","executeInSequence":true,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.2.80","
router.name":"r-4-VM"},"wait":0}}] }
2014-03-24 08:04:42,868 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-264:null) Seq 1-212812147: Executing request
2014-03-24 08:04:43,627 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-264:null) Seq 1-212812147: Response Received:
2014-03-24 08:04:43,628 DEBUG [agent.transport.Request]
(DirectAgent-264:null) Seq 1-212812147: Processing: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-03-24 08:04:43,629 DEBUG [agent.manager.AgentAttache]
(DirectAgent-264:null) Seq 1-212812147: No more commands found
2014-03-24 08:04:43,629 DEBUG [agent.transport.Request]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
1-212812147: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1,
Flags: 110, { Answer } }
2014-03-24 08:04:43,640 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Asking
SecurityGroupProvider to prepare for
Nic[17-10-e79b6036-20a0-4a9d-a76e-73010097026a-192.168.40.185]
2014-03-24 08:04:43,672 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Checking if we need to prepare 2 volumes for
VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
2014-03-24 08:04:43,672 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) No need
to recreate the volume: Vol[16|vm=10|ROOT], since it already has a pool
assigned: 2, adding disk to VM
2014-03-24 08:04:43,677 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) No need
to recreate the volume: Vol[17|vm=10|DATADISK], since it already has a pool
assigned: 2, adding disk to VM
2014-03-24 08:04:43,801 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
===START=== 10.29.128.147 -- GET
command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641076709
2014-03-24 08:04:43,823 DEBUG [agent.transport.Request]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
1-212812148: Sending { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
Flags: 100111,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":10,"name":"i-3-10-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":1500,"maxSpeed":1500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"CentOS
6.4
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"451e1b5f3d5180af","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"true"},"uuid":"e461c77d-9d39-43f2-94c3-79d00c36315c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"f8e6b36d-b48b-42fc-a2d7-f50f922385b5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"ROOT-10","size":32212254720,"path":"48e58db8-0353-411d-9777-6978a36f0c72","volumeId":16,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":16,"hypervisorType":"XenServer"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"387af0d1-3996-46fe-b44c-935c18680a55","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"DATA-10","size":32212254720,"path":"e93ffb66-d328-47d5-87bb-e34145299354","volumeId":17,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":17,"hypervisorType":"XenServer"}},"diskSeq":1,"type":"DATADISK"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":100,"defaultNic":true,"uuid":"c15cb1c8-9d3a-4735-8493-f8c4e3e6840d","ip":"192.168.40.185","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:f4:a0:00:00:0e","dns1":"192.168.40.41","dns2":"192.168.40.42","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true}]},"hostIp":"192.168.40.245","executeInSequence":true,"wait":0}}]
}
2014-03-24 08:04:43,828 DEBUG [agent.transport.Request]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
1-212812148: Executing: { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
Flags: 100111,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":10,"name":"i-3-10-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":1500,"maxSpeed":1500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"CentOS
6.4
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"451e1b5f3d5180af","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"true"},"uuid":"e461c77d-9d39-43f2-94c3-79d00c36315c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"f8e6b36d-b48b-42fc-a2d7-f50f922385b5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"ROOT-10","size":32212254720,"path":"48e58db8-0353-411d-9777-6978a36f0c72","volumeId":16,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":16,"hypervisorType":"XenServer"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"387af0d1-3996-46fe-b44c-935c18680a55","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"DATA-10","size":32212254720,"path":"e93ffb66-d328-47d5-87bb-e34145299354","volumeId":17,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":17,"hypervisorType":"XenServer"}},"diskSeq":1,"type":"DATADISK"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":100,"defaultNic":true,"uuid":"c15cb1c8-9d3a-4735-8493-f8c4e3e6840d","ip":"192.168.40.185","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:f4:a0:00:00:0e","dns1":"192.168.40.41","dns2":"192.168.40.42","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true}]},"hostIp":"192.168.40.245","executeInSequence":true,"wait":0}}]
}
2014-03-24 08:04:43,829 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-419:null) Seq 1-212812148: Executing request
2014-03-24 08:04:43,880 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
===END=== 10.29.128.147 -- GET
command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641076709
2014-03-24 08:04:44,001 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-419:null) 1. The VM i-3-10-VM is in Starting state.
2014-03-24 08:04:44,013 DEBUG [xen.resource.CitrixHelper]
(DirectAgent-419:null) Can't find the guest os: CentOS 6.4 (64-bit) mapping
into XCP's guestOS type, start it as HVM guest
2014-03-24 08:04:44,119 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-419:null) Created VM 62bb9717-c9dd-8c2c-e112-bbbb986265f3 for
i-3-10-VM
2014-03-24 08:04:44,261 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-419:null) VBD f5c8b98c-c4ed-7fb1-6be1-a32b45e538de created for
com.cloud.agent.api.to.DiskTO@5e0fbcd0
2014-03-24 08:04:44,346 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-419:null) VBD 371f106e-7873-59f7-654f-afffae5224ed created for
com.cloud.agent.api.to.DiskTO@5b352bee
2014-03-24 08:04:44,413 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-419:null) VBD 4eb822f9-f4ea-8197-c437-2e2fd39abd2a created for
com.cloud.agent.api.to.DiskTO@7fd74509
2014-03-24 08:04:44,413 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-419:null) Creating VIF for i-3-10-VM on nic
[Nic:Guest-192.168.40.185-vlan://untagged]
2014-03-24 08:04:44,521 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-419:null) Created a vif 0623efa2-46f4-e3b6-7eb6-e0cbd337b588
on 0
2014-03-24 08:04:46,797 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null)
===START=== 10.29.128.147 -- GET
command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641079708
2014-03-24 08:04:46,872 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null)
===END=== 10.29.128.147 -- GET
command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641079708
2014-03-24 08:04:49,797 DEBUG [cloud.api.ApiServlet]
(catalina-exec-24:null) ===START=== 10.29.128.147 -- GET
command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641082708
2014-03-24 08:04:49,863 DEBUG [cloud.api.ApiServlet]
(catalina-exec-24:null) ===END=== 10.29.128.147 -- GET
command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641082708
2014-03-24 08:04:50,828 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-419:null) 2. The VM i-3-10-VM is in Running state.
2014-03-24 08:04:50,828 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-419:null) Seq 1-212812148: Response Received:
2014-03-24 08:04:50,833 DEBUG [agent.transport.Request]
(DirectAgent-419:null) Seq 1-212812148: Processing: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":10,"name":"i-3-10-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":1500,"maxSpeed":1500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"CentOS
6.4
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"451e1b5f3d5180af","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"true"},"uuid":"e461c77d-9d39-43f2-94c3-79d00c36315c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"f8e6b36d-b48b-42fc-a2d7-f50f922385b5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"ROOT-10","size":32212254720,"path":"48e58db8-0353-411d-9777-6978a36f0c72","volumeId":16,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":16,"hypervisorType":"XenServer"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"387af0d1-3996-46fe-b44c-935c18680a55","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"DATA-10","size":32212254720,"path":"e93ffb66-d328-47d5-87bb-e34145299354","volumeId":17,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":17,"hypervisorType":"XenServer"}},"diskSeq":1,"type":"DATADISK"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":100,"defaultNic":true,"uuid":"c15cb1c8-9d3a-4735-8493-f8c4e3e6840d","ip":"192.168.40.185","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:f4:a0:00:00:0e","dns1":"192.168.40.41","dns2":"192.168.40.42","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true}]},"result":true,"wait":0}}]
}
2014-03-24 08:04:50,834 DEBUG [agent.transport.Request]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
1-212812148: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1,
Flags: 110, { StartAnswer } }
2014-03-24 08:04:50,835 DEBUG [agent.manager.AgentAttache]
(DirectAgent-419:null) Seq 1-212812148: No more commands found
2014-03-24 08:04:51,038 DEBUG [network.security.SecurityGroupManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Security Group Mgr v2: scheduling ruleset updates for 1 vms (unique=1),
current queue size=0
2014-03-24 08:04:51,050 DEBUG [network.security.SecurityGroupManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Security Group Mgr v2: done scheduling ruleset updates for 1 vms: num new
jobs=1 num rows insert or updated=1 time taken=11
2014-03-24 08:04:51,067 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) VM
state transitted from :Starting to Running with event:
OperationSucceededvm's original host id: 1 new host id: 1 host id before
state transition: 1
2014-03-24 08:04:51,076 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Start
completed for VM VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
2014-03-24 08:04:51,085 DEBUG [network.security.SecurityGroupManagerImpl]
(SecGrp-Worker-15:null) SecurityGroupManager v2: sending ruleset update for
vm i-3-10-VM:ingress num rules=0:egress num rules=0 num cidrs=0
sig=d41d8cd98f00b204e9800998ecf8427e
2014-03-24 08:04:51,099 DEBUG [agent.transport.Request]
(SecGrp-Worker-15:null) Seq 1-212812149: Sending { Cmd , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.SecurityGroupRulesCmd":{"guestIp":"192.168.40.185","vmName":"i-3-10-VM","guestMac":"06:f4:a0:00:00:0e","signature":"d41d8cd98f00b204e9800998ecf8427e","seqNum":3,"vmId":10,"msId":7063056740127,"ingressRuleSet":[],"egressRuleSet":[],"wait":0}}]
}
2014-03-24 08:04:51,103 DEBUG [agent.transport.Request]
(SecGrp-Worker-15:null) Seq 1-212812149: Executing: { Cmd , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.SecurityGroupRulesCmd":{"guestIp":"192.168.40.185","vmName":"i-3-10-VM","guestMac":"06:f4:a0:00:00:0e","signature":"d41d8cd98f00b204e9800998ecf8427e","seqNum":3,"vmId":10,"msId":7063056740127,"ingressRuleSet":[],"egressRuleSet":[],"wait":0}}]
}
2014-03-24 08:04:51,105 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-191:null) Seq 1-212812149: Executing request
2014-03-24 08:04:51,171 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
Complete async job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ],
jobStatus: 1, resultCode: 0, result:
org.apache.cloudstack.api.response.UserVmResponse@58f440c3
2014-03-24 08:04:51,187 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Done
executing org.apache.cloudstack.api.command.user.vm.StartVMCmd for job-33 =
[ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
2014-03-24 08:04:51,272 WARN [xen.resource.CitrixResourceBase]
(DirectAgent-191:null) Host 192.168.40.245 cannot do bridge firewalling
2014-03-24 08:04:51,273 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-191:null) Seq 1-212812149: Response Received:
2014-03-24 08:04:51,274 DEBUG [agent.transport.Request]
(DirectAgent-191:null) Seq 1-212812149: Processing: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.SecurityGroupRuleAnswer":{"logSequenceNumber":3,"vmId":10,"reason":"CANNOT_BRIDGE_FIREWALL","result":false,"details":"Host
192.168.40.245 cannot do bridge firewalling","wait":0}}] }
2014-03-24 08:04:51,280 DEBUG [network.security.SecurityGroupListener]
(DirectAgent-191:null) Failed to program rule
com.cloud.agent.api.SecurityGroupRuleAnswer into host 1 due to Host
192.168.40.245 cannot do bridge firewalling and updated jobs
2014-03-24 08:04:51,281 DEBUG [network.security.SecurityGroupListener]
(DirectAgent-191:null) Not retrying security group rules for vm 10 on
failure since host 1 cannot do bridge firewalling
2014-03-24 08:04:51,286 DEBUG [network.security.SecurityGroupListener]
(DirectAgent-191:null) Failed to program rule
com.cloud.agent.api.SecurityGroupRuleAnswer into host 1 due to Host
192.168.40.245 cannot do bridge firewalling and updated jobs
2014-03-24 08:04:51,286 DEBUG [network.security.SecurityGroupListener]
(DirectAgent-191:null) Not retrying security group rules for vm 10 on
failure since host 1 cannot do bridge firewalling
2014-03-24 08:04:51,287 DEBUG [agent.manager.AgentAttache]
(DirectAgent-191:null) Seq 1-212812149: No more commands found
2014-03-24 08:04:51,436 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-13:null) SeqA 2-54056: Processing Seq 2-54056: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-03-24 08:04:51,450 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-13:null) SeqA 2-54056: Sending Seq 2-54056: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-03-24 08:04:52,799 DEBUG [cloud.api.ApiServlet]
(catalina-exec-10:null) ===START=== 10.29.128.147 -- GET
command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641085710
2014-03-24 08:04:52,847 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-10:null) Async job-33 = [
0290d97b-4bd9-4509-8bd2-53b16b032f1b ] completed
2014-03-24 08:04:52,881 DEBUG [cloud.api.ApiServlet]
(catalina-exec-10:null) ===END=== 10.29.128.147 -- GET
command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641085710
2014-03-24 08:04:56,435 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-15:null) SeqA 2-54057: Processing Seq 2-54057: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-03-24 08:04:56,450 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-15:null) SeqA 2-54057: Sending Seq 2-54057: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-03-24 08:04:59,805 DEBUG [cloud.server.StatsCollector]
(StatsCollector-2:null) StorageCollector is running...
2014-03-24 08:04:59,944 DEBUG [agent.transport.Request]
(StatsCollector-2:null) Seq 3-143857194: Received: { Ans: , MgmtId:
7063056740127, via: 3, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-03-24 08:04:59,962 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-372:null) Seq 1-212812150: Executing request
2014-03-24 08:05:00,992 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-372:null) Seq 1-212812150: Response Received:
2014-03-24 08:05:00,994 DEBUG [agent.transport.Request]
(StatsCollector-2:null) Seq 1-212812150: Received: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-03-24 08:05:01,477 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2014-03-24 08:05:02,101 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2014-03-24 08:05:03,862 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) VmStatsCollector is running...
2014-03-24 08:05:03,914 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-470:null) Seq 1-212812151: Executing request
2014-03-24 08:05:04,451 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-470:null) Vm cpu utilization 0.01
2014-03-24 08:05:04,451 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-470:null) Vm cpu utilization 0.0
2014-03-24 08:05:04,634 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2014-03-24 08:05:04,639 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2014-03-24 08:05:04,736 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-470:null) Seq 1-212812151: Response Received:
2014-03-24 08:05:04,736 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 1-212812151: Received: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2014-03-24 08:05:06,438 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-10:null) SeqA 2-54058: Processing Seq 2-54058: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-03-24 08:05:06,453 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-10:null) SeqA 2-54058: Sending Seq 2-54058: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-03-24 08:05:11,437 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-14:null) SeqA 2-54059: Processing Seq 2-54059: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-03-24 08:05:11,450 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-14:null) SeqA 2-54059: Sending Seq 2-54059: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-03-24 08:05:15,829 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-2:null) Ping from 2
2014-03-24 08:05:16,438 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-8:null) SeqA 2-54061: Processing Seq 2-54061: { Cmd
, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-03-24 08:05:16,450 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-8:null) SeqA 2-54061: Sending Seq 2-54061: { Ans: ,
MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-03-24 08:05:16,753 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-6:null) Ping from 3
2014-03-24 08:05:16,781 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-372:null) Ping from 1
2014-03-24 08:05:19,529 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-470:null) Seq 1-212795397: Executing request
2014-03-24 08:05:20,130 WARN [xen.resource.CitrixResourceBase]
(DirectAgent-470:null) The VM is now missing marking it as Stopped i-3-10-VM
2014-03-24 08:05:20,131 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-470:null) Seq 1-212795397: Response Received:
2014-03-24 08:05:20,133 DEBUG [agent.transport.Request]
(DirectAgent-470:null) Seq 1-212795397: Processing: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{"i-3-10-VM":{"t":"927ca03c-7756-4d71-8151-ca26e188a14c","u":"Stopped"}},"_isExecuted":false,"result":true,"wait":0}}]
}
2014-03-24 08:05:20,148 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(DirectAgent-470:null) VM i-3-10-VM: cs state = Running and realState =
Stopped
2014-03-24 08:05:20,149 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(DirectAgent-470:null) VM i-3-10-VM: cs state = Running and realState =
Stopped
2014-03-24 08:05:20,149 DEBUG [cloud.ha.HighAvailabilityManagerImpl]
(DirectAgent-470:null) VM does not require investigation so I'm marking it
as Stopped: VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
2014-03-24 08:05:20,149 WARN [apache.cloudstack.alerts]
(DirectAgent-470:null) alertType:: 8 // dataCenterId:: 1 // podId:: 1 //
clusterId:: null // message:: VM (name:
e461c77d-9d39-43f2-94c3-79d00c36315c, id: 10) stopped unexpectedly on host
id:1, availability zone id:1, pod id:1
2014-03-24 08:05:20,180 DEBUG [cloud.ha.HighAvailabilityManagerImpl]
(DirectAgent-470:null) VM is not HA enabled so we're done.
2014-03-24 08:05:20,200 DEBUG [cloud.capacity.CapacityManagerImpl]
(DirectAgent-470:null) VM state transitted from :Running to Stopping with
event: StopRequestedvm's original host id: 1 new host id: 1 host id before
state transition: 1
2014-03-24 08:05:20,213 DEBUG [agent.transport.Request]
(DirectAgent-470:null) Seq 1-212812152: Sending { Cmd , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-10-VM","wait":0}}]
}
2014-03-24 08:05:20,214 DEBUG [agent.transport.Request]
(DirectAgent-470:null) Seq 1-212812152: Executing: { Cmd , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-10-VM","wait":0}}]
}
2014-03-24 08:05:20,215 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-209:null) Seq 1-212812152: Executing request
2014-03-24 08:05:20,423 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-209:null) 9. The VM i-3-10-VM is in Stopping state
2014-03-24 08:05:20,586 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-209:null) 10. The VM i-3-10-VM is in Stopped state
2014-03-24 08:05:20,587 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-209:null) Seq 1-212812152: Response Received:
2014-03-24 08:05:20,588 DEBUG [agent.transport.Request]
(DirectAgent-209:null) Seq 1-212812152: Processing: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","result":true,"details":"Stop
VM i-3-10-VM Succeed","wait":0}}] }
2014-03-24 08:05:20,589 DEBUG [agent.transport.Request]
(DirectAgent-470:null) Seq 1-212812152: Received: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2014-03-24 08:05:20,594 DEBUG [agent.manager.AgentAttache]
(DirectAgent-209:null) Seq 1-212812152: No more commands found
2014-03-24 08:05:20,632 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(DirectAgent-470:null) VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c] is
stopped on the host. Proceeding to release resource held.
2014-03-24 08:05:20,663 DEBUG [cloud.network.NetworkManagerImpl]
(DirectAgent-470:null) Changing active number of nics for network id=204 on
-1
2014-03-24 08:05:20,689 DEBUG [cloud.network.NetworkManagerImpl]
(DirectAgent-470:null) Asking VirtualRouter to release
Nic[17-10-e79b6036-20a0-4a9d-a76e-73010097026a-192.168.40.185]
2014-03-24 08:05:20,700 DEBUG [cloud.network.NetworkManagerImpl]
(DirectAgent-470:null) Asking SecurityGroupProvider to release
Nic[17-10-e79b6036-20a0-4a9d-a76e-73010097026a-192.168.40.185]
2014-03-24 08:05:20,701 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(DirectAgent-470:null) Successfully released network resources for the vm
VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
2014-03-24 08:05:20,701 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(DirectAgent-470:null) Successfully released storage resources for the vm
VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
2014-03-24 08:05:20,874 DEBUG [cloud.capacity.CapacityManagerImpl]
(DirectAgent-470:null) VM state transitted from :Stopping to Stopped with
event: OperationSucceededvm's original host id: 1 new host id: null host id
before state transition: 1
2014-03-24 08:05:20,900 DEBUG [cloud.capacity.CapacityManagerImpl]
(DirectAgent-470:null) Hosts's actual total CPU: 160000 and CPU after
applying overprovisioning: 160000
2014-03-24 08:05:20,901 DEBUG [cloud.capacity.CapacityManagerImpl]
(DirectAgent-470:null) Hosts's actual total RAM: 540213924096 and RAM after
applying overprovisioning: 540213936128
2014-03-24 08:05:20,901 DEBUG [cloud.capacity.CapacityManagerImpl]
(DirectAgent-470:null) release cpu from host: 1, old used: 4500,reserved:
0, actual total: 160000, total with overprovisioning: 160000; new used:
3000,reserved:1500; movedfromreserved: false,moveToReserveredtrue
2014-03-24 08:05:20,901 DEBUG [cloud.capacity.CapacityManagerImpl]
(DirectAgent-470:null) release mem from host: 1, old used:
3623878656,reserved: 0, total: 540213936128; new used:
2550136832,reserved:1073741824; movedfromreserved:
false,moveToReserveredtrue
2014-03-24 08:05:20,962 INFO [cloud.ha.HighAvailabilityManagerImpl]
(DirectAgent-470:null) Schedule vm for HA:
VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
2014-03-24 08:05:20,982 INFO [cloud.ha.HighAvailabilityManagerImpl]
(HA-Worker-0:work-13) Processing HAWork[13-HA-10-Stopped-Scheduled]
2014-03-24 08:05:21,003 INFO [cloud.ha.HighAvailabilityManagerImpl]
(HA-Worker-0:work-13) HA on VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
2014-03-24 08:05:21,019 DEBUG [cloud.ha.HighAvailabilityManagerImpl]
(HA-Worker-0:work-13) VM is not HA enabled so we're done.
2014-03-24 08:05:21,019 INFO [cloud.ha.HighAvailabilityManagerImpl]
(HA-Worker-0:work-13) Completed HAWork[13-HA-10-Stopped-Scheduled]
2014-03-24 08:05:21,023 DEBUG [agent.transport.Request]
(DirectAgent-470:null) Seq 1-212812153: Sending { Cmd , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-10-VM","wait":0}}]
}
2014-03-24 08:05:21,024 DEBUG [agent.transport.Request]
(DirectAgent-470:null) Seq 1-212812153: Executing: { Cmd , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-10-VM","wait":0}}]
}
2014-03-24 08:05:21,024 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-133:null) Seq 1-212812153: Executing request
2014-03-24 08:05:21,383 INFO [xen.resource.CitrixResourceBase]
(DirectAgent-133:null) VM does not exist on
XenServer927ca03c-7756-4d71-8151-ca26e188a14c
2014-03-24 08:05:21,384 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-133:null) Seq 1-212812153: Response Received:
2014-03-24 08:05:21,385 DEBUG [agent.transport.Request]
(DirectAgent-133:null) Seq 1-212812153: Processing: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM does not
exist","wait":0}}] }
2014-03-24 08:05:21,386 DEBUG [agent.transport.Request]
(DirectAgent-470:null) Seq 1-212812153: Received: { Ans: , MgmtId:
7063056740127, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2014-03-24 08:05:21,387 DEBUG [agent.manager.AgentAttache]
(DirectAgent-133:null) Seq 1-212812153: No more commands found
^C
Re: Instantiated CentOS VMs shutting down
Posted by Amogh Vasekar <am...@citrix.com>.
Not yet. AFAIK, that would be the case with 4.2 and 4.3 as well.
Thanks,
Amogh
On 3/24/14 1:48 AM, "Osay Osman Yuuni" <oy...@gmail.com> wrote:
>Was a
>patch applied and where can I find it?
Re: Instantiated CentOS VMs shutting down
Posted by Osay Osman Yuuni <oy...@gmail.com>.
Hi,
I think I found the problem. It appears that the templates based on CentOS
6.3 upward do not work. Once I created a new template based on CentOS 6.2
it worked. The question is whether this is not breaking something. The
actual OS is 6.5 but when creating a template I selected 6.2 and the
instances based on this template stay up while the instance based on a
template that was created using OS type CentOS 6.3 or CentOS 6.4 die with
the error "Can't find the guest os: CentOS 6.4 (64-bit) mapping into XCP's
guestOS type, start it as HVM guest" or similar in the log. I know XCP 6.1
supports guest OS types up to CentOS 6.4 but it looks like CS 4.2.1 does
not. I also saw, in my searches, a jira entry mentioning this. Was a
patch applied and where can I find it?
Regards,
Osay
On 24 March 2014 08:20, Osay Osman Yuuni <oy...@gmail.com> wrote:
> Hi,
> I have a CS 4.2.1 installed with XCP 6.1 as hypervisor. I have various
> templates (windows 2k12R2, CentOS 6.3, CentOS 6.5, Ubuntu 12.04.3 LTS).
> I'm able to instantiate windows and Ubuntu VMs without issues but when I
> instantiate the CentOS 6.3 or 6.5 VMs they just die. The VM appears in the
> hypervisor and after about a minute it disappears. In the management
> server GUI the VM is stopped. When I restart it, it starts but after about
> a minute it stops again. I've combed through the management server log but
> am unable to pin down what is causing this to happen. Is it that CentOS 6
> is unsupported (the default 5.6 template can be instantiated without
> issues).
>
>
> Below is a snippet of the management server log. The only issue I see is
> the error "cannot bridge firewall", which to be honest, I don't
> understand. Perhaps the more seasoned users can point out something that's
> obviously causing the VM to stop?
>
> =======================================
>
> 2014-03-24 08:04:41,048 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Hosts's
> actual total CPU: 160000 and CPU after applying overprovisioning: 160000
> 2014-03-24 08:04:41,048 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) We need
> to allocate to the last host again, so checking if there is enough reserved
> capacity
> 2014-03-24 08:04:41,048 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Reserved CPU: 0 , Requested CPU: 1500
> 2014-03-24 08:04:41,048 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Reserved RAM: 0 , Requested RAM: 1073741824
> 2014-03-24 08:04:41,048 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) STATS:
> Failed to alloc resource from host: 1 reservedCpu: 0, requested cpu: 1500,
> reservedMem: 0, requested mem: 1073741824
> 2014-03-24 08:04:41,049 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Host
> does not have enough reserved CPU available, cannot allocate to this host.
> 2014-03-24 08:04:41,049 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) The
> last host of this VM does not have enough capacity
> 2014-03-24 08:04:41,049 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Cannot
> choose the last host to deploy this VM
> 2014-03-24 08:04:41,049 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Searching resources only under specified Cluster: 1
> 2014-03-24 08:04:41,072 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Checking resources in Cluster: 1 under Pod: 1
> 2014-03-24 08:04:41,082 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
> 2014-03-24 08:04:41,095 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for
> allocation: [Host[-1-Routing]]
> 2014-03-24 08:04:41,107 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) Found 1 hosts for allocation after
> prioritization: [Host[-1-Routing]]
> 2014-03-24 08:04:41,107 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) Looking for speed=1500Mhz, Ram=1024
> 2014-03-24 08:04:41,132 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for
> requested CPU: 1500 and requested RAM: 1073741824 ,
> cpuOverprovisioningFactor: 1.0
> 2014-03-24 08:04:41,143 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) Hosts's actual total CPU: 160000 and CPU after
> applying overprovisioning: 160000
> 2014-03-24 08:04:41,143 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) Free CPU: 157000 , Requested CPU: 1500
> 2014-03-24 08:04:41,143 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) Free RAM: 537663799296 , Requested RAM: 1073741824
> 2014-03-24 08:04:41,143 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2014-03-24 08:04:41,143 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 3000,
> reserved: 0, actual total: 160000, total with overprovisioning: 160000;
> requested cpu:1500,alloc_from_last_host?:false ,considerReservedCapacity?:
> true
> 2014-03-24 08:04:41,144 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used:
> 2550136832, reserved: 0, total: 540213936128; requested mem:
> 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2014-03-24 08:04:41,144 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
> 2014-03-24 08:04:41,144 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
> 2014-03-24 08:04:41,151 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Checking suitable pools for volume (Id, Type): (16,ROOT)
> 2014-03-24 08:04:41,152 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Volume
> has pool already allocated, checking if pool can be reused, poolId: 2
> 2014-03-24 08:04:41,156 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Planner
> need not allocate a pool for this volume since its READY
> 2014-03-24 08:04:41,157 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Checking suitable pools for volume (Id, Type): (17,DATADISK)
> 2014-03-24 08:04:41,157 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Volume
> has pool already allocated, checking if pool can be reused, poolId: 2
> 2014-03-24 08:04:41,161 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Planner
> need not allocate a pool for this volume since its READY
> 2014-03-24 08:04:41,162 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Trying
> to find a potenial host and associated storage pools from the suitable
> host/pool lists for this VM
> 2014-03-24 08:04:41,162 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Checking if host: 1 can access any suitable storage pool for volume: ROOT
> 2014-03-24 08:04:41,166 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Host: 1
> can access pool: 2
> 2014-03-24 08:04:41,166 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Checking if host: 1 can access any suitable storage pool for volume:
> DATADISK
> 2014-03-24 08:04:41,170 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Host: 1
> can access pool: 2
> 2014-03-24 08:04:41,174 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Found a
> potential host id: 1 name: cloudsrv1.afdb.org and associated storage
> pools for this VM
> 2014-03-24 08:04:41,179 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Returning Deployment Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
> 2014-03-24 08:04:41,233 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) VM
> state transitted from :Stopped to Starting with event: StartRequestedvm's
> original host id: 1 new host id: null host id before state transition: null
> 2014-03-24 08:04:41,234 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Successfully transitioned to start state for
> VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c] reservation id =
> e79b6036-20a0-4a9d-a76e-73010097026a
> 2014-03-24 08:04:41,247 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Trying
> to deploy VM, vm has dcId: 1 and podId: 1
> 2014-03-24 08:04:41,247 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1,
> clusterId: 1, hostId: 1, poolId: null
> 2014-03-24 08:04:41,247 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Deploy
> avoids pods: null, clusters: null, hosts: null
> 2014-03-24 08:04:41,259 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Root
> volume is ready, need to place VM in volume's cluster
> 2014-03-24 08:04:41,293 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Deploy
> avoids pods: [], clusters: [], hosts: []
> 2014-03-24 08:04:41,293 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> DeploymentPlanner allocation algorithm:
> com.cloud.deploy.UserDispersingPlanner_EnhancerByCloudStack_b1882cfb@554079b2
> 2014-03-24 08:04:41,293 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Trying
> to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested
> cpu: 1500, requested ram: 1073741824
> 2014-03-24 08:04:41,294 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Is ROOT
> volume READY (pool already allocated)?: Yes
> 2014-03-24 08:04:41,294 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> DeploymentPlan has host_id specified, choosing this host and making no
> checks on this host: 1
> 2014-03-24 08:04:41,300 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Looking
> for suitable pools for this host under zone: 1, pod: 1, cluster: 1
> 2014-03-24 08:04:41,307 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Checking suitable pools for volume (Id, Type): (16,ROOT)
> 2014-03-24 08:04:41,308 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Volume
> has pool already allocated, checking if pool can be reused, poolId: 2
> 2014-03-24 08:04:41,313 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Planner
> need not allocate a pool for this volume since its READY
> 2014-03-24 08:04:41,314 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Checking suitable pools for volume (Id, Type): (17,DATADISK)
> 2014-03-24 08:04:41,314 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Volume
> has pool already allocated, checking if pool can be reused, poolId: 2
> 2014-03-24 08:04:41,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Planner
> need not allocate a pool for this volume since its READY
> 2014-03-24 08:04:41,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Trying
> to find a potenial host and associated storage pools from the suitable
> host/pool lists for this VM
> 2014-03-24 08:04:41,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Checking if host: 1 can access any suitable storage pool for volume: ROOT
> 2014-03-24 08:04:41,323 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Host: 1
> can access pool: 2
> 2014-03-24 08:04:41,324 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Checking if host: 1 can access any suitable storage pool for volume:
> DATADISK
> 2014-03-24 08:04:41,328 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Host: 1
> can access pool: 2
> 2014-03-24 08:04:41,331 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Found a
> potential host id: 1 name: cloudsrv1.afdb.org and associated storage
> pools for this VM
> 2014-03-24 08:04:41,335 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Returning Deployment Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
> 2014-03-24 08:04:41,335 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Deployment found - P0=VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c],
> P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
> 2014-03-24 08:04:41,374 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) VM
> state transitted from :Starting to Starting with event: OperationRetryvm's
> original host id: 1 new host id: 1 host id before state transition: null
> 2014-03-24 08:04:41,382 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) VM
> starting again on the last host it was stopped on
> 2014-03-24 08:04:41,414 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Hosts's
> actual total CPU: 160000 and CPU after applying overprovisioning: 160000
> 2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) We are
> allocating VM, increasing the used capacity of this host:1
> 2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Current
> Used CPU: 3000 , Free CPU:157000 ,Requested CPU: 1500
> 2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Current
> Used RAM: 2550136832 , Free RAM:537663799296 ,Requested RAM: 1073741824
> 2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) We are
> allocating VM to the last host again, so adjusting the reserved capacity if
> it is not less than required
> 2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Reserved CPU: 0 , Requested CPU: 1500
> 2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Reserved RAM: 0 , Requested RAM: 1073741824
> 2014-03-24 08:04:41,415 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) CPU
> STATS after allocation: for host: 1, old used: 3000, old reserved: 0,
> actual total: 160000, total with overprovisioning: 160000; new used:4500,
> reserved:0; requested cpu:1500,alloc_from_last:true
> 2014-03-24 08:04:41,416 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) RAM
> STATS after allocation: for host: 1, old used: 2550136832, old reserved: 0,
> total: 540213936128; new used: 3623878656, reserved: 0; requested mem:
> 1073741824,alloc_from_last:true
> 2014-03-24 08:04:41,426 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) VM is
> being created in podId: 1
> 2014-03-24 08:04:41,433 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-4:null) SeqA 2-54055: Processing Seq 2-54055: { Cmd
> , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
> 2014-03-24 08:04:41,446 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-4:null) SeqA 2-54055: Sending Seq 2-54055: { Ans: ,
> MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-03-24 08:04:41,464 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Network
> id=204 is already implemented
> 2014-03-24 08:04:41,551 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Changing active number of nics for network id=204 on 1
> 2014-03-24 08:04:41,577 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Asking
> VirtualRouter to prepare for
> Nic[17-10-e79b6036-20a0-4a9d-a76e-73010097026a-192.168.40.185]
> 2014-03-24 08:04:41,619 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:job-33
> = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Lock is acquired for network id
> 204 as a part of router startup in
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
> 2014-03-24 08:04:41,630 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:job-33
> = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Lock is released for network id
> 204 as a part of router startup in
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
> 2014-03-24 08:04:41,721 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:job-33
> = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Applying dhcp entry in network
> Ntwk[204|Guest|6]
> 2014-03-24 08:04:41,786 DEBUG [agent.transport.Request]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
> 1-212812146: Sending { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
> Flags: 100111,
> [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f4:a0:00:00:0e","vmIpAddress":"192.168.40.185","vmName":"e461c77d-9d39-43f2-94c3-79d00c36315c","defaultRouter":"192.168.40.1","defaultDns":"192.168.40.183","duid":"00:03:00:01:06:f4:a0:00:00:0e","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","
> router.name":"r-4-VM","router.ip":"169.254.2.80"},"wait":0}}] }
> 2014-03-24 08:04:41,788 DEBUG [agent.transport.Request]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
> 1-212812146: Executing: { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
> Flags: 100111,
> [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f4:a0:00:00:0e","vmIpAddress":"192.168.40.185","vmName":"e461c77d-9d39-43f2-94c3-79d00c36315c","defaultRouter":"192.168.40.1","defaultDns":"192.168.40.183","duid":"00:03:00:01:06:f4:a0:00:00:0e","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","
> router.name":"r-4-VM","router.ip":"169.254.2.80"},"wait":0}}] }
> 2014-03-24 08:04:41,789 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-377:null) Seq 1-212812146: Executing request
> 2014-03-24 08:04:42,782 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-377:null) Seq 1-212812146: Response Received:
> 2014-03-24 08:04:42,783 DEBUG [agent.transport.Request]
> (DirectAgent-377:null) Seq 1-212812146: Processing: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 110,
> [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-03-24 08:04:42,784 DEBUG [agent.transport.Request]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
> 1-212812146: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1,
> Flags: 110, { Answer } }
> 2014-03-24 08:04:42,784 DEBUG [agent.manager.AgentAttache]
> (DirectAgent-377:null) Seq 1-212812146: No more commands found
> 2014-03-24 08:04:42,824 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-26:job-33
> = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Applying userdata and password
> entry in network Ntwk[204|Guest|6]
> 2014-03-24 08:04:42,866 DEBUG [agent.transport.Request]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
> 1-212812147: Sending { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
> Flags: 100111,
> [{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.40.185","vmName":"e461c77d-9d39-43f2-94c3-79d00c36315c","executeInSequence":true,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.2.80","
> router.name":"r-4-VM"},"wait":0}}] }
> 2014-03-24 08:04:42,867 DEBUG [agent.transport.Request]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
> 1-212812147: Executing: { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
> Flags: 100111,
> [{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.40.185","vmName":"e461c77d-9d39-43f2-94c3-79d00c36315c","executeInSequence":true,"accessDetails":{"router.guest.ip":"192.168.40.183","zone.network.type":"Basic","router.ip":"169.254.2.80","
> router.name":"r-4-VM"},"wait":0}}] }
> 2014-03-24 08:04:42,868 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-264:null) Seq 1-212812147: Executing request
> 2014-03-24 08:04:43,627 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-264:null) Seq 1-212812147: Response Received:
> 2014-03-24 08:04:43,628 DEBUG [agent.transport.Request]
> (DirectAgent-264:null) Seq 1-212812147: Processing: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 110,
> [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-03-24 08:04:43,629 DEBUG [agent.manager.AgentAttache]
> (DirectAgent-264:null) Seq 1-212812147: No more commands found
> 2014-03-24 08:04:43,629 DEBUG [agent.transport.Request]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
> 1-212812147: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1,
> Flags: 110, { Answer } }
> 2014-03-24 08:04:43,640 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Asking
> SecurityGroupProvider to prepare for
> Nic[17-10-e79b6036-20a0-4a9d-a76e-73010097026a-192.168.40.185]
> 2014-03-24 08:04:43,672 DEBUG [cloud.storage.VolumeManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Checking if we need to prepare 2 volumes for
> VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
> 2014-03-24 08:04:43,672 DEBUG [cloud.storage.VolumeManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) No need
> to recreate the volume: Vol[16|vm=10|ROOT], since it already has a pool
> assigned: 2, adding disk to VM
> 2014-03-24 08:04:43,677 DEBUG [cloud.storage.VolumeManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) No need
> to recreate the volume: Vol[17|vm=10|DATADISK], since it already has a pool
> assigned: 2, adding disk to VM
> 2014-03-24 08:04:43,801 DEBUG [cloud.api.ApiServlet]
> (catalina-exec-3:null) ===START=== 10.29.128.147 -- GET
> command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641076709
> 2014-03-24 08:04:43,823 DEBUG [agent.transport.Request]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
> 1-212812148: Sending { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
> Flags: 100111,
> [{"com.cloud.agent.api.StartCommand":{"vm":{"id":10,"name":"i-3-10-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":1500,"maxSpeed":1500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"CentOS
> 6.4
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"451e1b5f3d5180af","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"true"},"uuid":"e461c77d-9d39-43f2-94c3-79d00c36315c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"f8e6b36d-b48b-42fc-a2d7-f50f922385b5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"ROOT-10","size":32212254720,"path":"48e58db8-0353-411d-9777-6978a36f0c72","volumeId":16,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":16,"hypervisorType":"XenServer"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"387af0d1-3996-46fe-b44c-935c18680a55","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"DATA-10","size":32212254720,"path":"e93ffb66-d328-47d5-87bb-e34145299354","volumeId":17,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":17,"hypervisorType":"XenServer"}},"diskSeq":1,"type":"DATADISK"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":100,"defaultNic":true,"uuid":"c15cb1c8-9d3a-4735-8493-f8c4e3e6840d","ip":"192.168.40.185","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:f4:a0:00:00:0e","dns1":"192.168.40.41","dns2":"192.168.40.42","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true}]},"hostIp":"192.168.40.245","executeInSequence":true,"wait":0}}]
> }
> 2014-03-24 08:04:43,828 DEBUG [agent.transport.Request]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
> 1-212812148: Executing: { Cmd , MgmtId: 7063056740127, via: 1, Ver: v1,
> Flags: 100111,
> [{"com.cloud.agent.api.StartCommand":{"vm":{"id":10,"name":"i-3-10-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":1500,"maxSpeed":1500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"CentOS
> 6.4
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"451e1b5f3d5180af","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"true"},"uuid":"e461c77d-9d39-43f2-94c3-79d00c36315c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"f8e6b36d-b48b-42fc-a2d7-f50f922385b5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"ROOT-10","size":32212254720,"path":"48e58db8-0353-411d-9777-6978a36f0c72","volumeId":16,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":16,"hypervisorType":"XenServer"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"387af0d1-3996-46fe-b44c-935c18680a55","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"DATA-10","size":32212254720,"path":"e93ffb66-d328-47d5-87bb-e34145299354","volumeId":17,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":17,"hypervisorType":"XenServer"}},"diskSeq":1,"type":"DATADISK"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":100,"defaultNic":true,"uuid":"c15cb1c8-9d3a-4735-8493-f8c4e3e6840d","ip":"192.168.40.185","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:f4:a0:00:00:0e","dns1":"192.168.40.41","dns2":"192.168.40.42","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true}]},"hostIp":"192.168.40.245","executeInSequence":true,"wait":0}}]
> }
> 2014-03-24 08:04:43,829 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-419:null) Seq 1-212812148: Executing request
> 2014-03-24 08:04:43,880 DEBUG [cloud.api.ApiServlet]
> (catalina-exec-3:null) ===END=== 10.29.128.147 -- GET
> command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641076709
> 2014-03-24 08:04:44,001 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-419:null) 1. The VM i-3-10-VM is in Starting state.
> 2014-03-24 08:04:44,013 DEBUG [xen.resource.CitrixHelper]
> (DirectAgent-419:null) Can't find the guest os: CentOS 6.4 (64-bit) mapping
> into XCP's guestOS type, start it as HVM guest
> 2014-03-24 08:04:44,119 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-419:null) Created VM 62bb9717-c9dd-8c2c-e112-bbbb986265f3 for
> i-3-10-VM
> 2014-03-24 08:04:44,261 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-419:null) VBD f5c8b98c-c4ed-7fb1-6be1-a32b45e538de created for
> com.cloud.agent.api.to.DiskTO@5e0fbcd0
> 2014-03-24 08:04:44,346 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-419:null) VBD 371f106e-7873-59f7-654f-afffae5224ed created for
> com.cloud.agent.api.to.DiskTO@5b352bee
> 2014-03-24 08:04:44,413 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-419:null) VBD 4eb822f9-f4ea-8197-c437-2e2fd39abd2a created for
> com.cloud.agent.api.to.DiskTO@7fd74509
> 2014-03-24 08:04:44,413 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-419:null) Creating VIF for i-3-10-VM on nic
> [Nic:Guest-192.168.40.185-vlan://untagged]
> 2014-03-24 08:04:44,521 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-419:null) Created a vif 0623efa2-46f4-e3b6-7eb6-e0cbd337b588
> on 0
> 2014-03-24 08:04:46,797 DEBUG [cloud.api.ApiServlet]
> (catalina-exec-7:null) ===START=== 10.29.128.147 -- GET
> command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641079708
> 2014-03-24 08:04:46,872 DEBUG [cloud.api.ApiServlet]
> (catalina-exec-7:null) ===END=== 10.29.128.147 -- GET
> command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641079708
> 2014-03-24 08:04:49,797 DEBUG [cloud.api.ApiServlet]
> (catalina-exec-24:null) ===START=== 10.29.128.147 -- GET
> command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641082708
> 2014-03-24 08:04:49,863 DEBUG [cloud.api.ApiServlet]
> (catalina-exec-24:null) ===END=== 10.29.128.147 -- GET
> command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641082708
> 2014-03-24 08:04:50,828 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-419:null) 2. The VM i-3-10-VM is in Running state.
> 2014-03-24 08:04:50,828 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-419:null) Seq 1-212812148: Response Received:
> 2014-03-24 08:04:50,833 DEBUG [agent.transport.Request]
> (DirectAgent-419:null) Seq 1-212812148: Processing: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 110,
> [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":10,"name":"i-3-10-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":1500,"maxSpeed":1500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"CentOS
> 6.4
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"451e1b5f3d5180af","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","hypervisortoolsversion":"xenserver61","Message.ReservedCapacityFreed.Flag":"true"},"uuid":"e461c77d-9d39-43f2-94c3-79d00c36315c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"f8e6b36d-b48b-42fc-a2d7-f50f922385b5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"ROOT-10","size":32212254720,"path":"48e58db8-0353-411d-9777-6978a36f0c72","volumeId":16,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":16,"hypervisorType":"XenServer"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"387af0d1-3996-46fe-b44c-935c18680a55","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ba737116-8aa6-3644-a595-383d4dc39ed3","id":2,"poolType":"NetworkFilesystem","host":"192.168.40.71","path":"/fs_nfs1","port":2049}},"name":"DATA-10","size":32212254720,"path":"e93ffb66-d328-47d5-87bb-e34145299354","volumeId":17,"vmName":"i-3-10-VM","accountId":3,"format":"VHD","id":17,"hypervisorType":"XenServer"}},"diskSeq":1,"type":"DATADISK"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":100,"defaultNic":true,"uuid":"c15cb1c8-9d3a-4735-8493-f8c4e3e6840d","ip":"192.168.40.185","netmask":"255.255.255.0","gateway":"192.168.40.1","mac":"06:f4:a0:00:00:0e","dns1":"192.168.40.41","dns2":"192.168.40.42","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true}]},"result":true,"wait":0}}]
> }
> 2014-03-24 08:04:50,834 DEBUG [agent.transport.Request]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Seq
> 1-212812148: Received: { Ans: , MgmtId: 7063056740127, via: 1, Ver: v1,
> Flags: 110, { StartAnswer } }
> 2014-03-24 08:04:50,835 DEBUG [agent.manager.AgentAttache]
> (DirectAgent-419:null) Seq 1-212812148: No more commands found
> 2014-03-24 08:04:51,038 DEBUG [network.security.SecurityGroupManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Security Group Mgr v2: scheduling ruleset updates for 1 vms (unique=1),
> current queue size=0
> 2014-03-24 08:04:51,050 DEBUG [network.security.SecurityGroupManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Security Group Mgr v2: done scheduling ruleset updates for 1 vms: num new
> jobs=1 num rows insert or updated=1 time taken=11
> 2014-03-24 08:04:51,067 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) VM
> state transitted from :Starting to Running with event:
> OperationSucceededvm's original host id: 1 new host id: 1 host id before
> state transition: 1
> 2014-03-24 08:04:51,076 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Start
> completed for VM VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
> 2014-03-24 08:04:51,085 DEBUG [network.security.SecurityGroupManagerImpl]
> (SecGrp-Worker-15:null) SecurityGroupManager v2: sending ruleset update for
> vm i-3-10-VM:ingress num rules=0:egress num rules=0 num cidrs=0
> sig=d41d8cd98f00b204e9800998ecf8427e
> 2014-03-24 08:04:51,099 DEBUG [agent.transport.Request]
> (SecGrp-Worker-15:null) Seq 1-212812149: Sending { Cmd , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 100111,
> [{"com.cloud.agent.api.SecurityGroupRulesCmd":{"guestIp":"192.168.40.185","vmName":"i-3-10-VM","guestMac":"06:f4:a0:00:00:0e","signature":"d41d8cd98f00b204e9800998ecf8427e","seqNum":3,"vmId":10,"msId":7063056740127,"ingressRuleSet":[],"egressRuleSet":[],"wait":0}}]
> }
> 2014-03-24 08:04:51,103 DEBUG [agent.transport.Request]
> (SecGrp-Worker-15:null) Seq 1-212812149: Executing: { Cmd , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 100111,
> [{"com.cloud.agent.api.SecurityGroupRulesCmd":{"guestIp":"192.168.40.185","vmName":"i-3-10-VM","guestMac":"06:f4:a0:00:00:0e","signature":"d41d8cd98f00b204e9800998ecf8427e","seqNum":3,"vmId":10,"msId":7063056740127,"ingressRuleSet":[],"egressRuleSet":[],"wait":0}}]
> }
> 2014-03-24 08:04:51,105 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-191:null) Seq 1-212812149: Executing request
> 2014-03-24 08:04:51,171 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ])
> Complete async job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ],
> jobStatus: 1, resultCode: 0, result:
> org.apache.cloudstack.api.response.UserVmResponse@58f440c3
> 2014-03-24 08:04:51,187 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-26:job-33 = [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]) Done
> executing org.apache.cloudstack.api.command.user.vm.StartVMCmd for job-33 =
> [ 0290d97b-4bd9-4509-8bd2-53b16b032f1b ]
> 2014-03-24 08:04:51,272 WARN [xen.resource.CitrixResourceBase]
> (DirectAgent-191:null) Host 192.168.40.245 cannot do bridge firewalling
> 2014-03-24 08:04:51,273 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-191:null) Seq 1-212812149: Response Received:
> 2014-03-24 08:04:51,274 DEBUG [agent.transport.Request]
> (DirectAgent-191:null) Seq 1-212812149: Processing: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 110,
> [{"com.cloud.agent.api.SecurityGroupRuleAnswer":{"logSequenceNumber":3,"vmId":10,"reason":"CANNOT_BRIDGE_FIREWALL","result":false,"details":"Host
> 192.168.40.245 cannot do bridge firewalling","wait":0}}] }
> 2014-03-24 08:04:51,280 DEBUG [network.security.SecurityGroupListener]
> (DirectAgent-191:null) Failed to program rule
> com.cloud.agent.api.SecurityGroupRuleAnswer into host 1 due to Host
> 192.168.40.245 cannot do bridge firewalling and updated jobs
> 2014-03-24 08:04:51,281 DEBUG [network.security.SecurityGroupListener]
> (DirectAgent-191:null) Not retrying security group rules for vm 10 on
> failure since host 1 cannot do bridge firewalling
> 2014-03-24 08:04:51,286 DEBUG [network.security.SecurityGroupListener]
> (DirectAgent-191:null) Failed to program rule
> com.cloud.agent.api.SecurityGroupRuleAnswer into host 1 due to Host
> 192.168.40.245 cannot do bridge firewalling and updated jobs
> 2014-03-24 08:04:51,286 DEBUG [network.security.SecurityGroupListener]
> (DirectAgent-191:null) Not retrying security group rules for vm 10 on
> failure since host 1 cannot do bridge firewalling
> 2014-03-24 08:04:51,287 DEBUG [agent.manager.AgentAttache]
> (DirectAgent-191:null) Seq 1-212812149: No more commands found
> 2014-03-24 08:04:51,436 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-13:null) SeqA 2-54056: Processing Seq 2-54056: { Cmd
> , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
> 2014-03-24 08:04:51,450 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-13:null) SeqA 2-54056: Sending Seq 2-54056: { Ans: ,
> MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-03-24 08:04:52,799 DEBUG [cloud.api.ApiServlet]
> (catalina-exec-10:null) ===START=== 10.29.128.147 -- GET
> command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641085710
> 2014-03-24 08:04:52,847 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-10:null) Async job-33 = [
> 0290d97b-4bd9-4509-8bd2-53b16b032f1b ] completed
> 2014-03-24 08:04:52,881 DEBUG [cloud.api.ApiServlet]
> (catalina-exec-10:null) ===END=== 10.29.128.147 -- GET
> command=queryAsyncJobResult&jobId=0290d97b-4bd9-4509-8bd2-53b16b032f1b&response=json&sessionkey=bNFqqGTaBxPjbmygj7Q60bFZHOs%3D&_=1395641085710
> 2014-03-24 08:04:56,435 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-15:null) SeqA 2-54057: Processing Seq 2-54057: { Cmd
> , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
> 2014-03-24 08:04:56,450 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-15:null) SeqA 2-54057: Sending Seq 2-54057: { Ans: ,
> MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-03-24 08:04:59,805 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-2:null) StorageCollector is running...
> 2014-03-24 08:04:59,944 DEBUG [agent.transport.Request]
> (StatsCollector-2:null) Seq 3-143857194: Received: { Ans: , MgmtId:
> 7063056740127, via: 3, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-03-24 08:04:59,962 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-372:null) Seq 1-212812150: Executing request
> 2014-03-24 08:05:00,992 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-372:null) Seq 1-212812150: Response Received:
> 2014-03-24 08:05:00,994 DEBUG [agent.transport.Request]
> (StatsCollector-2:null) Seq 1-212812150: Received: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-03-24 08:05:01,477 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is ready to launch secondary storage VM
> 2014-03-24 08:05:02,101 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is ready to launch console proxy
> 2014-03-24 08:05:03,862 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-1:null) VmStatsCollector is running...
> 2014-03-24 08:05:03,914 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-470:null) Seq 1-212812151: Executing request
> 2014-03-24 08:05:04,451 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-470:null) Vm cpu utilization 0.01
> 2014-03-24 08:05:04,451 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-470:null) Vm cpu utilization 0.0
> 2014-03-24 08:05:04,634 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers to update status.
> 2014-03-24 08:05:04,639 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2014-03-24 08:05:04,736 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-470:null) Seq 1-212812151: Response Received:
> 2014-03-24 08:05:04,736 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 1-212812151: Received: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2014-03-24 08:05:06,438 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-10:null) SeqA 2-54058: Processing Seq 2-54058: { Cmd
> , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
> 2014-03-24 08:05:06,453 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-10:null) SeqA 2-54058: Sending Seq 2-54058: { Ans: ,
> MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-03-24 08:05:11,437 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-14:null) SeqA 2-54059: Processing Seq 2-54059: { Cmd
> , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
> 2014-03-24 08:05:11,450 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-14:null) SeqA 2-54059: Sending Seq 2-54059: { Ans: ,
> MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-03-24 08:05:15,829 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-2:null) Ping from 2
> 2014-03-24 08:05:16,438 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-8:null) SeqA 2-54061: Processing Seq 2-54061: { Cmd
> , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
> 2014-03-24 08:05:16,450 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-8:null) SeqA 2-54061: Sending Seq 2-54061: { Ans: ,
> MgmtId: 7063056740127, via: 2, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-03-24 08:05:16,753 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-6:null) Ping from 3
> 2014-03-24 08:05:16,781 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-372:null) Ping from 1
> 2014-03-24 08:05:19,529 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-470:null) Seq 1-212795397: Executing request
> 2014-03-24 08:05:20,130 WARN [xen.resource.CitrixResourceBase]
> (DirectAgent-470:null) The VM is now missing marking it as Stopped i-3-10-VM
> 2014-03-24 08:05:20,131 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-470:null) Seq 1-212795397: Response Received:
> 2014-03-24 08:05:20,133 DEBUG [agent.transport.Request]
> (DirectAgent-470:null) Seq 1-212795397: Processing: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{"i-3-10-VM":{"t":"927ca03c-7756-4d71-8151-ca26e188a14c","u":"Stopped"}},"_isExecuted":false,"result":true,"wait":0}}]
> }
> 2014-03-24 08:05:20,148 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (DirectAgent-470:null) VM i-3-10-VM: cs state = Running and realState =
> Stopped
> 2014-03-24 08:05:20,149 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (DirectAgent-470:null) VM i-3-10-VM: cs state = Running and realState =
> Stopped
> 2014-03-24 08:05:20,149 DEBUG [cloud.ha.HighAvailabilityManagerImpl]
> (DirectAgent-470:null) VM does not require investigation so I'm marking it
> as Stopped: VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
> 2014-03-24 08:05:20,149 WARN [apache.cloudstack.alerts]
> (DirectAgent-470:null) alertType:: 8 // dataCenterId:: 1 // podId:: 1 //
> clusterId:: null // message:: VM (name:
> e461c77d-9d39-43f2-94c3-79d00c36315c, id: 10) stopped unexpectedly on host
> id:1, availability zone id:1, pod id:1
> 2014-03-24 08:05:20,180 DEBUG [cloud.ha.HighAvailabilityManagerImpl]
> (DirectAgent-470:null) VM is not HA enabled so we're done.
> 2014-03-24 08:05:20,200 DEBUG [cloud.capacity.CapacityManagerImpl]
> (DirectAgent-470:null) VM state transitted from :Running to Stopping with
> event: StopRequestedvm's original host id: 1 new host id: 1 host id before
> state transition: 1
> 2014-03-24 08:05:20,213 DEBUG [agent.transport.Request]
> (DirectAgent-470:null) Seq 1-212812152: Sending { Cmd , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 100111,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-10-VM","wait":0}}]
> }
> 2014-03-24 08:05:20,214 DEBUG [agent.transport.Request]
> (DirectAgent-470:null) Seq 1-212812152: Executing: { Cmd , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 100111,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-10-VM","wait":0}}]
> }
> 2014-03-24 08:05:20,215 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-209:null) Seq 1-212812152: Executing request
> 2014-03-24 08:05:20,423 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-209:null) 9. The VM i-3-10-VM is in Stopping state
> 2014-03-24 08:05:20,586 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-209:null) 10. The VM i-3-10-VM is in Stopped state
> 2014-03-24 08:05:20,587 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-209:null) Seq 1-212812152: Response Received:
> 2014-03-24 08:05:20,588 DEBUG [agent.transport.Request]
> (DirectAgent-209:null) Seq 1-212812152: Processing: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 110,
> [{"com.cloud.agent.api.StopAnswer":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true;timeoffset:0","result":true,"details":"Stop
> VM i-3-10-VM Succeed","wait":0}}] }
> 2014-03-24 08:05:20,589 DEBUG [agent.transport.Request]
> (DirectAgent-470:null) Seq 1-212812152: Received: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
> 2014-03-24 08:05:20,594 DEBUG [agent.manager.AgentAttache]
> (DirectAgent-209:null) Seq 1-212812152: No more commands found
> 2014-03-24 08:05:20,632 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (DirectAgent-470:null) VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c] is
> stopped on the host. Proceeding to release resource held.
> 2014-03-24 08:05:20,663 DEBUG [cloud.network.NetworkManagerImpl]
> (DirectAgent-470:null) Changing active number of nics for network id=204 on
> -1
> 2014-03-24 08:05:20,689 DEBUG [cloud.network.NetworkManagerImpl]
> (DirectAgent-470:null) Asking VirtualRouter to release
> Nic[17-10-e79b6036-20a0-4a9d-a76e-73010097026a-192.168.40.185]
> 2014-03-24 08:05:20,700 DEBUG [cloud.network.NetworkManagerImpl]
> (DirectAgent-470:null) Asking SecurityGroupProvider to release
> Nic[17-10-e79b6036-20a0-4a9d-a76e-73010097026a-192.168.40.185]
> 2014-03-24 08:05:20,701 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (DirectAgent-470:null) Successfully released network resources for the vm
> VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
> 2014-03-24 08:05:20,701 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (DirectAgent-470:null) Successfully released storage resources for the vm
> VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
> 2014-03-24 08:05:20,874 DEBUG [cloud.capacity.CapacityManagerImpl]
> (DirectAgent-470:null) VM state transitted from :Stopping to Stopped with
> event: OperationSucceededvm's original host id: 1 new host id: null host id
> before state transition: 1
> 2014-03-24 08:05:20,900 DEBUG [cloud.capacity.CapacityManagerImpl]
> (DirectAgent-470:null) Hosts's actual total CPU: 160000 and CPU after
> applying overprovisioning: 160000
> 2014-03-24 08:05:20,901 DEBUG [cloud.capacity.CapacityManagerImpl]
> (DirectAgent-470:null) Hosts's actual total RAM: 540213924096 and RAM after
> applying overprovisioning: 540213936128
> 2014-03-24 08:05:20,901 DEBUG [cloud.capacity.CapacityManagerImpl]
> (DirectAgent-470:null) release cpu from host: 1, old used: 4500,reserved:
> 0, actual total: 160000, total with overprovisioning: 160000; new used:
> 3000,reserved:1500; movedfromreserved: false,moveToReserveredtrue
> 2014-03-24 08:05:20,901 DEBUG [cloud.capacity.CapacityManagerImpl]
> (DirectAgent-470:null) release mem from host: 1, old used:
> 3623878656,reserved: 0, total: 540213936128; new used:
> 2550136832,reserved:1073741824; movedfromreserved:
> false,moveToReserveredtrue
> 2014-03-24 08:05:20,962 INFO [cloud.ha.HighAvailabilityManagerImpl]
> (DirectAgent-470:null) Schedule vm for HA:
> VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
> 2014-03-24 08:05:20,982 INFO [cloud.ha.HighAvailabilityManagerImpl]
> (HA-Worker-0:work-13) Processing HAWork[13-HA-10-Stopped-Scheduled]
> 2014-03-24 08:05:21,003 INFO [cloud.ha.HighAvailabilityManagerImpl]
> (HA-Worker-0:work-13) HA on VM[User|e461c77d-9d39-43f2-94c3-79d00c36315c]
> 2014-03-24 08:05:21,019 DEBUG [cloud.ha.HighAvailabilityManagerImpl]
> (HA-Worker-0:work-13) VM is not HA enabled so we're done.
> 2014-03-24 08:05:21,019 INFO [cloud.ha.HighAvailabilityManagerImpl]
> (HA-Worker-0:work-13) Completed HAWork[13-HA-10-Stopped-Scheduled]
> 2014-03-24 08:05:21,023 DEBUG [agent.transport.Request]
> (DirectAgent-470:null) Seq 1-212812153: Sending { Cmd , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 100111,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-10-VM","wait":0}}]
> }
> 2014-03-24 08:05:21,024 DEBUG [agent.transport.Request]
> (DirectAgent-470:null) Seq 1-212812153: Executing: { Cmd , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 100111,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-10-VM","wait":0}}]
> }
> 2014-03-24 08:05:21,024 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-133:null) Seq 1-212812153: Executing request
> 2014-03-24 08:05:21,383 INFO [xen.resource.CitrixResourceBase]
> (DirectAgent-133:null) VM does not exist on
> XenServer927ca03c-7756-4d71-8151-ca26e188a14c
> 2014-03-24 08:05:21,384 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-133:null) Seq 1-212812153: Response Received:
> 2014-03-24 08:05:21,385 DEBUG [agent.transport.Request]
> (DirectAgent-133:null) Seq 1-212812153: Processing: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 110,
> [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM does not
> exist","wait":0}}] }
> 2014-03-24 08:05:21,386 DEBUG [agent.transport.Request]
> (DirectAgent-470:null) Seq 1-212812153: Received: { Ans: , MgmtId:
> 7063056740127, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
> 2014-03-24 08:05:21,387 DEBUG [agent.manager.AgentAttache]
> (DirectAgent-133:null) Seq 1-212812153: No more commands found
> ^C
>
>
>