cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Nik Martin <nik.mar...@nfinausa.com>
Subject Cryptic Error creating VM from ISO
Date Wed, 01 Aug 2012 22:07:56 GMT
  I had a request to upload an ISO of XCP for a developer to test some 
API work he's doing.  So I download the 1.5 XCP beta and add it to CS. 
When I try to craete a VM from the XCP ISO, it fails with a very cryptic 
"Unable to create a deployment for VM[User|i-2-135-VM]"

The log shows many varied errors, but none of them give a definitive 
answer.  Worse, when the VM creation fails, CS doesn;t clean uo after 
itself, and now I have 10 or 12 VMs in state "Expunging".  I can create 
VMs using other templates but with the same service offerings as I'm 
trying to create the XCP VM with.  Most errors I see are about not 
enough resources, but there are plenty of resources, and as I said, 
using the same service offering with other templates works fine.




2012-08-01 16:44:19,841 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) VBD c0e05d8b-bda3-49b4-400b-043c1945744f created 
for 
Vol[135|ISO|nfs://172.16.5.2/export/secondary/template/tmpl/2/205//205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso|0]
2012-08-01 16:44:19,841 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Creating VIF for i-2-135-VM on nic 
[Nic:Guest-10.1.1.220-vlan://510]
2012-08-01 16:44:19,841 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Looking for network named guest_pub
2012-08-01 16:44:19,896 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Found a network called guest_pub on 
host=172.16.5.5;  Network=620948b7-4081-53df-a370-a28868e52c19; 
pif=c2847562-742c-3f95-71ff-a8f63ca6330f
2012-08-01 16:44:19,923 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Creating VLAN 510 on host 172.16.5.5 on device eth1
2012-08-01 16:44:19,960 DEBUG [agent.manager.AgentManagerImpl] 
(AgentManager-Handler-15:null) Ping from 19
2012-08-01 16:44:20,102 DEBUG [agent.manager.AgentManagerImpl] 
(AgentManager-Handler-1:null) Ping from 18
2012-08-01 16:44:20,919 DEBUG [cloud.server.StatsCollector] 
(StatsCollector-1:null) VmStatsCollector is running...
2012-08-01 16:44:20,937 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-48:null) Seq 16-479526995: Executing request
2012-08-01 16:44:21,162 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) VLAN is created for 510.  The uuid is 
b0763cac-7c7d-4486-2279-57896801f370
2012-08-01 16:44:21,199 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Created a vif 
d2c4ec16-920a-35fc-4e0b-e77f7a2f1e10 on 0
2012-08-01 16:44:21,340 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-170:null) Ping from 17
2012-08-01 16:44:21,447 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-48:null) Vm cpu utilization 0.0125
2012-08-01 16:44:21,447 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-48:null) Vm cpu utilization 0.0125
2012-08-01 16:44:21,447 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-48:null) Vm cpu utilization 0.011250000000000001
2012-08-01 16:44:21,447 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-48:null) Seq 16-479526995: Response Received:
2012-08-01 16:44:21,447 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-48:null) Cleanup succeeded. Details null
2012-08-01 16:44:21,447 DEBUG [agent.transport.Request] 
(StatsCollector-1:null) Seq 16-479526995: Received:  { Ans: , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2012-08-01 16:44:21,447 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(StatsCollector-1:null) Cleanup succeeded. Details null
2012-08-01 16:44:21,460 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-457:null) Ping from 16
2012-08-01 16:44:25,944 DEBUG 
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 
2 is ready to launch secondary storage VM
2012-08-01 16:44:26,038 DEBUG 
[cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 
2 is ready to launch console proxy
2012-08-01 16:44:26,232 DEBUG 
[network.router.VirtualNetworkApplianceManagerImpl] 
(RouterStatusMonitor-1:null) Found 2 routers.
2012-08-01 16:44:26,269 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Task failed! Task record:                 uuid: 
4995c5df-3d6a-548f-3feb-257dbfed99a6
              created: Wed Aug 01 16:44:21 CDT 2012
             finished: Wed Aug 01 16:44:27 CDT 2012
2012-08-01 16:44:26,284 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Unable to start VM(i-2-135-VM) on 
host(3624054e-b343-4786-95c7-d82d2aad0044) due to Task failed! Task 
record:                 uuid: 4995c5df-3d6a-548f-3feb-257dbfed99a6
              created: Wed Aug 01 16:44:21 CDT 2012
             finished: Wed Aug 01 16:44:27 CDT 2012
              created: Wed Aug 01 16:44:21 CDT 2012
             finished: Wed Aug 01 16:44:27 CDT 2012
2012-08-01 16:44:26,294 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Catch Exception: class 
com.cloud.utils.exception.CloudRuntimeException due to 
com.cloud.utils.exception.CloudRuntimeException: Unable to start 
VM(i-2-135-VM) on host(3624054e-b343-4786-95c7-d82d2aad0044) due to Task 
failed! Task record:                 uuid: 
4995c5df-3d6a-548f-3feb-257dbfed99a6
              created: Wed Aug 01 16:44:21 CDT 2012
             finished: Wed Aug 01 16:44:27 CDT 2012
              created: Wed Aug 01 16:44:21 CDT 2012
             finished: Wed Aug 01 16:44:27 CDT 2012
2012-08-01 16:44:26,295 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Unable to start i-2-135-VM due to
              created: Wed Aug 01 16:44:21 CDT 2012
             finished: Wed Aug 01 16:44:27 CDT 2012
2012-08-01 16:44:26,360 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Unable to clean up VBD due to
2012-08-01 16:44:26,375 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Unable to clean up VBD due to
2012-08-01 16:44:26,390 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) Unable to cleanup VIF
2012-08-01 16:44:27,731 INFO  [xen.resource.XenServer56Resource] 
(DirectAgent-374:null) Catch com.xensource.xenapi.Types$InvalidValue: 
failed to destory VLAN eth1 on host 3624054e-b343-4786-95c7-d82d2aad0044 
due to The value given is invalid
2012-08-01 16:44:27,731 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-374:null) The VM is in stopped state, detected problem 
during startup : i-2-135-VM
2012-08-01 16:44:27,731 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-374:null) Seq 17-2018508893: Response Received:
2012-08-01 16:44:27,731 DEBUG [agent.transport.Request] 
(DirectAgent-374:null) Seq 17-2018508893: Processing:  { Ans: , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 110, 
[{"StartAnswer":{"vm":{"id":135,"name":"i-2-135-VM","bootloader":"CD","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"CentOS 
6.0 
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"a88cf66d4a6d9df","params":{},"disks":[{"id":147,"name":"ROOT-135","mountPoint":"/iqn.2012-01.com.nfinausa:san01/1","path":"ff2e7337-72fa-4fa0-8195-14ae5de1ecef","size":21474836480,"type":"ROOT","storagePoolType":"IscsiLUN","storagePoolUuid":"776299a8-a770-30f7-9f6b-8c422790f5b7","deviceId":0},{"id":135,"name":"Xen 
Cloud Platform 
1.5","path":"nfs://172.16.5.2/export/secondary/template/tmpl/2/205//205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3,"guestOsType":"CentOS 
6.0 
(64-bit)"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.1.1.220","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:3d:fc:00:0b","dns1":"8.8.8.8","dns2":"","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://510","isolationUri":"vlan://510","isSecurityGroupEnabled":false,"name":"guest_pub"}]},"result":false,"details":"Unable 
to start i-2-135-VM due to ","wait":0}}] }
2012-08-01 16:44:27,732 WARN  [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-374:null) Cleanup failed due to Unable to start i-2-135-VM 
due to
2012-08-01 16:44:27,732 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 17-2018508893: Received:  { Ans: , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 110, { StartAnswer } }
2012-08-01 16:44:27,732 DEBUG [agent.manager.AgentAttache] 
(DirectAgent-374:null) Seq 17-2018508893: No more commands found
2012-08-01 16:44:27,732 WARN  [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Cleanup failed due to Unable to start 
i-2-135-VM due to
2012-08-01 16:44:27,739 INFO  [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Unable to start VM on Host[-17-Routing] due to 
Unable to start i-2-135-VM due to
2012-08-01 16:44:27,742 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Cleaning up resources for the vm 
VM[User|i-2-135-VM] in Starting state
2012-08-01 16:44:27,744 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 17-2018508894: Sending  { Cmd , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 100111, 
[{"StopCommand":{"isProxy":false,"vmName":"i-2-135-VM","wait":0}}] }
2012-08-01 16:44:27,744 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 17-2018508894: Executing:  { Cmd , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 100111, 
[{"StopCommand":{"isProxy":false,"vmName":"i-2-135-VM","wait":0}}] }
2012-08-01 16:44:27,744 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-383:null) Seq 17-2018508894: Executing request
2012-08-01 16:44:27,911 INFO  [xen.resource.CitrixResourceBase] 
(DirectAgent-383:null) VM does not exist on 
XenServer3624054e-b343-4786-95c7-d82d2aad0044
2012-08-01 16:44:27,911 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-383:null) Seq 17-2018508894: Response Received:
2012-08-01 16:44:27,911 DEBUG [agent.transport.Request] 
(DirectAgent-383:null) Seq 17-2018508894: Processing:  { Ans: , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 110, 
[{"StopAnswer":{"vncPort":0,"bytesSent":0,"bytesReceived":0,"result":true,"details":"VM 
does not exist","wait":0}}] }
2012-08-01 16:44:27,911 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-383:null) Cleanup succeeded. Details VM does not exist
2012-08-01 16:44:27,911 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 17-2018508894: Received:  { Ans: , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 110, { StopAnswer } }
2012-08-01 16:44:27,911 DEBUG [agent.manager.AgentAttache] 
(DirectAgent-383:null) Seq 17-2018508894: No more commands found
2012-08-01 16:44:27,911 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Cleanup succeeded. Details VM does not exist
2012-08-01 16:44:27,920 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Service SecurityGroup is not supported in the 
network id=211
2012-08-01 16:44:27,931 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Changing active number of nics for network 
id=211 on -1
2012-08-01 16:44:27,933 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Successfully cleanued up resources for the vm 
VM[User|i-2-135-VM] in Starting state
2012-08-01 16:44:27,935 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Root volume is ready, need to place VM in 
volume's cluster
2012-08-01 16:44:27,935 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Vol[147|vm=135|ROOT] is READY, changing 
deployment plan to use this pool's dcId: 2 , podId: 1 , and clusterId: 1
2012-08-01 16:44:27,936 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) DeploymentPlanner allocation algorithm: random
2012-08-01 16:44:27,936 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Trying to allocate a host and storage pools 
from dc:2, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
2012-08-01 16:44:27,936 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Is ROOT volume READY (pool already allocated)?: Yes
2012-08-01 16:44:27,936 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Searching resources only under specified Cluster: 1
2012-08-01 16:44:27,941 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Checking resources in Cluster: 1 under Pod: 1
2012-08-01 16:44:27,941 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Calling HostAllocators to find suitable hosts
2012-08-01 16:44:27,941 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Looking for hosts in 
dc: 2  pod:1  cluster:1
2012-08-01 16:44:27,943 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) FirstFitAllocator has 
3 hosts to check for allocation: [Host[-17-Routing], Host[-13-Routing], 
Host[-16-Routing]]
2012-08-01 16:44:27,946 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Found 3 hosts for 
allocation after prioritization: [Host[-17-Routing], Host[-13-Routing], 
Host[-16-Routing]]
2012-08-01 16:44:27,946 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Looking for 
speed=1000Mhz, Ram=1024
2012-08-01 16:44:27,946 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Host name: hv3, 
hostId: 17 is in avoid set, skipping this and trying other available hosts
2012-08-01 16:44:27,948 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Checking if host: 13 
has enough capacity for requested CPU: 1000 and requested RAM: 
1073741824 , cpuOverprovisioningFactor: 1.0
2012-08-01 16:44:27,949 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Hosts's actual total 
CPU: 57456 and CPU after applying overprovisioning: 57456
2012-08-01 16:44:27,949 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Free CPU: 55956 , 
Requested CPU: 1000
2012-08-01 16:44:27,949 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Free RAM: 96761591552 
, Requested RAM: 1073741824
2012-08-01 16:44:27,949 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Host has enough CPU 
and RAM available
2012-08-01 16:44:27,949 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) STATS: Can alloc CPU 
from host: 13, used: 1500, reserved: 0, actual total: 57456, total with 
overprovisioning: 57456; requested cpu:1000,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:27,950 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) STATS: Can alloc MEM 
from host: 13, used: 1476395008, reserved: 0, total: 98237986560; 
requested mem: 1073741824,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:27,950 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Found a suitable host, 
adding to list: 13
2012-08-01 16:44:27,951 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Checking if host: 16 
has enough capacity for requested CPU: 1000 and requested RAM: 
1073741824 , cpuOverprovisioningFactor: 1.0
2012-08-01 16:44:27,953 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Hosts's actual total 
CPU: 57456 and CPU after applying overprovisioning: 57456
2012-08-01 16:44:27,953 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Free CPU: 33456 , 
Requested CPU: 1000
2012-08-01 16:44:27,953 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Free RAM: 74722373184 
, Requested RAM: 1073741824
2012-08-01 16:44:27,953 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Host has enough CPU 
and RAM available
2012-08-01 16:44:27,953 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) STATS: Can alloc CPU 
from host: 16, used: 24000, reserved: 0, actual total: 57456, total with 
overprovisioning: 57456; requested cpu:1000,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:27,953 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) STATS: Can alloc MEM 
from host: 16, used: 25769803776, reserved: 0, total: 100492176960; 
requested mem: 1073741824,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:27,953 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Found a suitable host, 
adding to list: 16
2012-08-01 16:44:27,953 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Host Allocator 
returning 2 suitable hosts
2012-08-01 16:44:27,954 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Checking suitable pools for volume (Id, Type): 
(147,ROOT)
2012-08-01 16:44:27,954 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Volume is in READY state and has pool already 
allocated, checking if pool can be reused, poolId: 204
2012-08-01 16:44:27,955 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Planner need not allocate a pool for this 
volume since its READY
2012-08-01 16:44:27,955 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Trying to find a potenial host and associated 
storage pools from the suitable host/pool lists for this VM
2012-08-01 16:44:27,955 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Checking if host: 13 can access any suitable 
storage pool for volume: ROOT
2012-08-01 16:44:27,956 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Host: 13 can access pool: 204
2012-08-01 16:44:27,956 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Found a potential host id: 13 name: hv1 and 
associated storage pools for this VM
2012-08-01 16:44:27,957 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Returning Deployment Destination: 
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] 
: Dest[Zone(2)-Pod(1)-Cluster(1)-Host(13)-Storage()]
2012-08-01 16:44:27,957 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Deployment found  - P0=VM[User|i-2-135-VM], 
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] 
: Dest[Zone(2)-Pod(1)-Cluster(1)-Host(13)-Storage()]
2012-08-01 16:44:27,962 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) VM state transitted from :Starting to Starting 
with event: OperationRetryvm's original host id: null new host id: 13 
host id before state transition: 17
2012-08-01 16:44:27,965 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) Hosts's actual total CPU: 57456 and CPU after 
applying overprovisioning: 57456
2012-08-01 16:44:27,965 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) release cpu from host: 17, old used: 
1000,reserved: 0, actual total: 57456, total with overprovisioning: 
57456; new used: 0,reserved:0; movedfromreserved: 
false,moveToReserveredfalse
2012-08-01 16:44:27,965 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) release mem from host: 17, old used: 
1073741824,reserved: 0, total: 98958404160; new used: 0,reserved:0; 
movedfromreserved: false,moveToReserveredfalse
2012-08-01 16:44:27,971 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) Hosts's actual total CPU: 57456 and CPU after 
applying overprovisioning: 57456
2012-08-01 16:44:27,971 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) We are allocating VM, increasing the used 
capacity of this host:13
2012-08-01 16:44:27,971 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) Current Used CPU: 1500 , Free CPU:55956 
,Requested CPU: 1000
2012-08-01 16:44:27,971 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) Current Used RAM: 1476395008 , Free 
RAM:96761591552 ,Requested RAM: 1073741824
2012-08-01 16:44:27,971 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) CPU STATS after allocation: for host: 13, old 
used: 1500, old reserved: 0, actual total: 57456, total with 
overprovisioning: 57456; new used:2500, reserved:0; requested 
cpu:1000,alloc_from_last:false
2012-08-01 16:44:27,971 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) RAM STATS after allocation: for host: 13, old 
used: 1476395008, old reserved: 0, total: 98237986560; new used: 
2550136832, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2012-08-01 16:44:27,974 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) VM is being started in podId: 1
2012-08-01 16:44:27,977 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Network id=211 is already implemented
2012-08-01 16:44:27,985 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Service SecurityGroup is not supported in the 
network id=211
2012-08-01 16:44:27,991 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Changing active number of nics for network 
id=211 on 1
2012-08-01 16:44:27,994 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking JuniperSRX to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:27,996 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking Netscaler to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:27,999 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking F5BigIp to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:28,002 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking VirtualRouter to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:28,008 DEBUG 
[network.router.VirtualNetworkApplianceManagerImpl] 
(Job-Executor-8:job-206) Starting a router for Ntwk[211|Guest|7] in 
datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$22635440@2
2012-08-01 16:44:28,019 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Service SecurityGroup is not supported in the 
network id=211
2012-08-01 16:44:28,021 DEBUG 
[network.router.VirtualNetworkApplianceManagerImpl] 
(Job-Executor-8:job-206) Applying dhcp entry in network Ntwk[211|Guest|7]
2012-08-01 16:44:28,033 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643298: Sending  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"routing.DhcpEntryCommand":{"vmMac":"02:00:3d:fc:00:0b","vmIpAddress":"10.1.1.220","vmName":"XCP","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.name":"r-126-VM","router.ip":"169.254.2.97"},"wait":0}}] 
}
2012-08-01 16:44:28,033 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643298: Executing:  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"routing.DhcpEntryCommand":{"vmMac":"02:00:3d:fc:00:0b","vmIpAddress":"10.1.1.220","vmName":"XCP","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.name":"r-126-VM","router.ip":"169.254.2.97"},"wait":0}}] 
}
2012-08-01 16:44:28,033 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-104:null) Seq 13-1102643298: Executing request
2012-08-01 16:44:30,455 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-104:null) Seq 13-1102643298: Response Received:
2012-08-01 16:44:30,455 DEBUG [agent.transport.Request] 
(DirectAgent-104:null) Seq 13-1102643298: Processing:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 110, 
[{"Answer":{"result":true,"wait":0}}] }
2012-08-01 16:44:30,455 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-104:null) Cleanup succeeded. Details null
2012-08-01 16:44:30,455 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643298: Received:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 110, { Answer } }
2012-08-01 16:44:30,455 DEBUG [agent.manager.AgentAttache] 
(DirectAgent-104:null) Seq 13-1102643298: No more commands found
2012-08-01 16:44:30,455 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Cleanup succeeded. Details null
2012-08-01 16:44:30,465 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Service SecurityGroup is not supported in the 
network id=211
2012-08-01 16:44:30,467 DEBUG 
[network.router.VirtualNetworkApplianceManagerImpl] 
(Job-Executor-8:job-206) Applying userdata and password entry in network 
Ntwk[211|Guest|7]
2012-08-01 16:44:30,480 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643299: Sending  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.1.1.220","vmName":"XCP","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.97","router.name":"r-126-VM"},"wait":0}},{"routing.VmDataCommand":{"vmIpAddress":"10.1.1.220","vmName":"XCP","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.97","router.name":"r-126-VM"},"wait":0}}] 
}
2012-08-01 16:44:30,481 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643299: Executing:  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.1.1.220","vmName":"XCP","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.97","router.name":"r-126-VM"},"wait":0}},{"routing.VmDataCommand":{"vmIpAddress":"10.1.1.220","vmName":"XCP","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.97","router.name":"r-126-VM"},"wait":0}}] 
}
2012-08-01 16:44:30,481 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-428:null) Seq 13-1102643299: Executing request
2012-08-01 16:44:34,029 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-58:null) Ping from 13
2012-08-01 16:44:34,961 DEBUG [agent.manager.AgentManagerImpl] 
(AgentManager-Handler-13:null) Ping from 19
2012-08-01 16:44:35,106 DEBUG [agent.manager.AgentManagerImpl] 
(AgentManager-Handler-3:null) Ping from 18
2012-08-01 16:44:36,299 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-138:null) Ping from 17
2012-08-01 16:44:36,773 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-320:null) Ping from 16
2012-08-01 16:44:38,337 DEBUG [cloud.server.StatsCollector] 
(StatsCollector-2:null) StorageCollector is running...
2012-08-01 16:44:38,404 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(AgentManager-Handler-4:null) Cleanup succeeded. Details null
2012-08-01 16:44:38,404 DEBUG [agent.transport.Request] 
(StatsCollector-2:null) Seq 19-380633146: Received:  { Ans: , MgmtId: 
130577622632, via: 19, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-08-01 16:44:38,404 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(StatsCollector-2:null) Cleanup succeeded. Details null
2012-08-01 16:44:38,411 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-266:null) Seq 16-479526996: Executing request
2012-08-01 16:44:39,078 DEBUG [cloud.server.StatsCollector] 
(StatsCollector-3:null) HostStatsCollector is running...
2012-08-01 16:44:39,089 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-464:null) Seq 13-1102643300: Executing request
2012-08-01 16:44:39,305 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-464:null) Seq 13-1102643300: Response Received:
2012-08-01 16:44:39,305 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-464:null) Cleanup succeeded. Details null
2012-08-01 16:44:39,305 DEBUG [agent.transport.Request] 
(StatsCollector-3:null) Seq 13-1102643300: Received:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-08-01 16:44:39,305 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(StatsCollector-3:null) Cleanup succeeded. Details null
2012-08-01 16:44:39,310 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-336:null) Seq 16-479526997: Executing request
2012-08-01 16:44:39,326 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-266:null) Seq 16-479526996: Response Received:
2012-08-01 16:44:39,326 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-266:null) Cleanup succeeded. Details null
2012-08-01 16:44:39,326 DEBUG [agent.transport.Request] 
(StatsCollector-2:null) Seq 16-479526996: Received:  { Ans: , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-08-01 16:44:39,326 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(StatsCollector-2:null) Cleanup succeeded. Details null
2012-08-01 16:44:39,700 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-336:null) Seq 16-479526997: Response Received:
2012-08-01 16:44:39,700 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-336:null) Cleanup succeeded. Details null
2012-08-01 16:44:39,700 DEBUG [agent.transport.Request] 
(StatsCollector-3:null) Seq 16-479526997: Received:  { Ans: , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-08-01 16:44:39,700 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(StatsCollector-3:null) Cleanup succeeded. Details null
2012-08-01 16:44:39,705 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-334:null) Seq 17-2018508895: Executing request
2012-08-01 16:44:40,091 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-334:null) Seq 17-2018508895: Response Received:
2012-08-01 16:44:40,091 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-334:null) Cleanup succeeded. Details null
2012-08-01 16:44:40,091 DEBUG [agent.transport.Request] 
(StatsCollector-3:null) Seq 17-2018508895: Received:  { Ans: , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-08-01 16:44:40,091 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(StatsCollector-3:null) Cleanup succeeded. Details null
2012-08-01 16:44:41,955 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-428:null) Seq 13-1102643299: Response Received:
2012-08-01 16:44:41,955 DEBUG [agent.transport.Request] 
(DirectAgent-428:null) Seq 13-1102643299: Processing:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 110, 
[{"Answer":{"result":true,"wait":0}},{"Answer":{"result":true,"wait":0}}] }
2012-08-01 16:44:41,955 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-428:null) Cleanup succeeded. Details null
2012-08-01 16:44:41,955 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643299: Received:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 110, { Answer, Answer } }
2012-08-01 16:44:41,955 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-428:null) Cleanup succeeded. Details null
2012-08-01 16:44:41,955 DEBUG [agent.manager.AgentAttache] 
(DirectAgent-428:null) Seq 13-1102643299: No more commands found
2012-08-01 16:44:41,955 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Cleanup succeeded. Details null
2012-08-01 16:44:41,955 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Cleanup succeeded. Details null
2012-08-01 16:44:41,955 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking Ovs to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:41,955 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking ExternalDhcpServer to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:41,961 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking BareMetal to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:41,961 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking SecurityGroupProvider to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:41,964 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Service SecurityGroup is not supported in the 
network id=211
2012-08-01 16:44:41,965 DEBUG [cloud.storage.StorageManagerImpl] 
(Job-Executor-8:job-206) Checking if we need to prepare 1 volumes for 
VM[User|i-2-135-VM]
2012-08-01 16:44:41,965 DEBUG [cloud.storage.StorageManagerImpl] 
(Job-Executor-8:job-206) No need to recreate the volume: 
Vol[147|vm=135|ROOT], since it already has a pool assigned: 204, adding 
disk to VM
2012-08-01 16:44:41,978 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643301: Sending  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"StartCommand":{"vm":{"id":135,"name":"i-2-135-VM","bootloader":"CD","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"CentOS 
6.0 
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"a88cf66d4a6d9df","params":{},"disks":[{"id":147,"name":"ROOT-135","mountPoint":"/iqn.2012-01.com.nfinausa:san01/1","path":"ff2e7337-72fa-4fa0-8195-14ae5de1ecef","size":21474836480,"type":"ROOT","storagePoolType":"IscsiLUN","storagePoolUuid":"776299a8-a770-30f7-9f6b-8c422790f5b7","deviceId":0},{"id":135,"name":"Xen 
Cloud Platform 
1.5","path":"nfs://172.16.5.2/export/secondary/template/tmpl/2/205//205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3,"guestOsType":"CentOS 
6.0 
(64-bit)"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.1.1.220","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:3d:fc:00:0b","dns1":"8.8.8.8","dns2":"","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://510","isolationUri":"vlan://510","isSecurityGroupEnabled":false,"name":"guest_pub"}]},"wait":0}}] 
}
2012-08-01 16:44:41,978 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643301: Executing:  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"StartCommand":{"vm":{"id":135,"name":"i-2-135-VM","bootloader":"CD","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"CentOS 
6.0 
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"a88cf66d4a6d9df","params":{},"disks":[{"id":147,"name":"ROOT-135","mountPoint":"/iqn.2012-01.com.nfinausa:san01/1","path":"ff2e7337-72fa-4fa0-8195-14ae5de1ecef","size":21474836480,"type":"ROOT","storagePoolType":"IscsiLUN","storagePoolUuid":"776299a8-a770-30f7-9f6b-8c422790f5b7","deviceId":0},{"id":135,"name":"Xen 
Cloud Platform 
1.5","path":"nfs://172.16.5.2/export/secondary/template/tmpl/2/205//205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3,"guestOsType":"CentOS 
6.0 
(64-bit)"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.1.1.220","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:3d:fc:00:0b","dns1":"8.8.8.8","dns2":"","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://510","isolationUri":"vlan://510","isSecurityGroupEnabled":false,"name":"guest_pub"}]},"wait":0}}] 
}
2012-08-01 16:44:41,978 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-445:null) Seq 13-1102643301: Executing request
2012-08-01 16:44:42,076 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) 1. The VM i-2-135-VM is in Starting state.
2012-08-01 16:44:42,125 DEBUG [xen.resource.XenServer56FP1Resource] 
(DirectAgent-445:null) Created VM 464cd918-debd-d6c0-8e53-ccaf2b63bfea 
for i-2-135-VM
2012-08-01 16:44:42,182 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) VBD d0be6eda-340d-9935-bef5-9313fe15d94d created 
for Vol[147|ROOT|ff2e7337-72fa-4fa0-8195-14ae5de1ecef|21474836480]
2012-08-01 16:44:43,353 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) VBD 13c50150-9614-4a32-fbd4-d0489ab57c76 created 
for 
Vol[135|ISO|nfs://172.16.5.2/export/secondary/template/tmpl/2/205//205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso|0]
2012-08-01 16:44:43,353 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Creating VIF for i-2-135-VM on nic 
[Nic:Guest-10.1.1.220-vlan://510]
2012-08-01 16:44:43,353 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Looking for network named guest_pub
2012-08-01 16:44:43,401 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Found a network called guest_pub on 
host=172.16.5.3;  Network=620948b7-4081-53df-a370-a28868e52c19; 
pif=817e2173-007b-0f73-5a0b-122e53dc83fb
2012-08-01 16:44:43,417 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Found a network called 
VLAN-620948b7-4081-53df-a370-a28868e52c19-510 on host=172.16.5.3; 
Network=a7fa9542-0ebb-71fd-e1fd-68980917b92b; 
pif=a7e75661-4223-06be-3ecd-064dedcf72db
2012-08-01 16:44:43,443 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Created a vif 
fbd12fe6-7fad-eea0-dde4-08cdac23da34 on 0
2012-08-01 16:44:46,498 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Task failed! Task record:                 uuid: 
4b457405-4527-777c-862c-9430899bb447
              created: Wed Aug 01 16:44:43 CDT 2012
             finished: Wed Aug 01 16:44:46 CDT 2012
2012-08-01 16:44:46,508 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Unable to start VM(i-2-135-VM) on 
host(e0e2c7af-8adb-49d7-bae5-51dcdb43aa16) due to Task failed! Task 
record:                 uuid: 4b457405-4527-777c-862c-9430899bb447
              created: Wed Aug 01 16:44:43 CDT 2012
             finished: Wed Aug 01 16:44:46 CDT 2012
              created: Wed Aug 01 16:44:43 CDT 2012
             finished: Wed Aug 01 16:44:46 CDT 2012
2012-08-01 16:44:46,516 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Catch Exception: class 
com.cloud.utils.exception.CloudRuntimeException due to 
com.cloud.utils.exception.CloudRuntimeException: Unable to start 
VM(i-2-135-VM) on host(e0e2c7af-8adb-49d7-bae5-51dcdb43aa16) due to Task 
failed! Task record:                 uuid: 
4b457405-4527-777c-862c-9430899bb447
              created: Wed Aug 01 16:44:43 CDT 2012
             finished: Wed Aug 01 16:44:46 CDT 2012
              created: Wed Aug 01 16:44:43 CDT 2012
             finished: Wed Aug 01 16:44:46 CDT 2012
2012-08-01 16:44:46,516 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Unable to start i-2-135-VM due to
              created: Wed Aug 01 16:44:43 CDT 2012
             finished: Wed Aug 01 16:44:46 CDT 2012
2012-08-01 16:44:46,588 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Unable to clean up VBD due to
2012-08-01 16:44:46,604 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Unable to clean up VBD due to
2012-08-01 16:44:46,619 WARN  [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) Unable to cleanup VIF
2012-08-01 16:44:46,656 INFO  [xen.resource.XenServer56Resource] 
(DirectAgent-445:null) Catch com.xensource.xenapi.Types$VifInUse: failed 
to destory VLAN eth1 on host e0e2c7af-8adb-49d7-bae5-51dcdb43aa16 due to 
Network has active VIFs
2012-08-01 16:44:46,656 DEBUG [xen.resource.CitrixResourceBase] 
(DirectAgent-445:null) The VM is in stopped state, detected problem 
during startup : i-2-135-VM
2012-08-01 16:44:46,656 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-445:null) Seq 13-1102643301: Response Received:
2012-08-01 16:44:46,656 DEBUG [agent.transport.Request] 
(DirectAgent-445:null) Seq 13-1102643301: Processing:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 110, 
[{"StartAnswer":{"vm":{"id":135,"name":"i-2-135-VM","bootloader":"CD","type":"User","cpus":1,"speed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"CentOS 
6.0 
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"a88cf66d4a6d9df","params":{},"disks":[{"id":147,"name":"ROOT-135","mountPoint":"/iqn.2012-01.com.nfinausa:san01/1","path":"ff2e7337-72fa-4fa0-8195-14ae5de1ecef","size":21474836480,"type":"ROOT","storagePoolType":"IscsiLUN","storagePoolUuid":"776299a8-a770-30f7-9f6b-8c422790f5b7","deviceId":0},{"id":135,"name":"Xen 
Cloud Platform 
1.5","path":"nfs://172.16.5.2/export/secondary/template/tmpl/2/205//205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3,"guestOsType":"CentOS 
6.0 
(64-bit)"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"ip":"10.1.1.220","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:3d:fc:00:0b","dns1":"8.8.8.8","dns2":"","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://510","isolationUri":"vlan://510","isSecurityGroupEnabled":false,"name":"guest_pub"}]},"result":false,"details":"Unable 
to start i-2-135-VM due to ","wait":0}}] }
2012-08-01 16:44:46,656 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643301: Received:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 110, { StartAnswer } }
2012-08-01 16:44:46,657 WARN  [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Cleanup failed due to Unable to start 
i-2-135-VM due to
2012-08-01 16:44:46,657 WARN  [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-445:null) Cleanup failed due to Unable to start i-2-135-VM 
due to
2012-08-01 16:44:46,658 DEBUG [agent.manager.AgentAttache] 
(DirectAgent-445:null) Seq 13-1102643301: No more commands found
2012-08-01 16:44:46,661 INFO  [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Unable to start VM on Host[-13-Routing] due to 
Unable to start i-2-135-VM due to
2012-08-01 16:44:46,664 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Cleaning up resources for the vm 
VM[User|i-2-135-VM] in Starting state
2012-08-01 16:44:46,665 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643302: Sending  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"StopCommand":{"isProxy":false,"vmName":"i-2-135-VM","wait":0}}] }
2012-08-01 16:44:46,665 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643302: Executing:  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"StopCommand":{"isProxy":false,"vmName":"i-2-135-VM","wait":0}}] }
2012-08-01 16:44:46,665 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-27:null) Seq 13-1102643302: Executing request
2012-08-01 16:44:46,758 INFO  [xen.resource.CitrixResourceBase] 
(DirectAgent-27:null) VM does not exist on 
XenServere0e2c7af-8adb-49d7-bae5-51dcdb43aa16
2012-08-01 16:44:46,758 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-27:null) Seq 13-1102643302: Response Received:
2012-08-01 16:44:46,759 DEBUG [agent.transport.Request] 
(DirectAgent-27:null) Seq 13-1102643302: Processing:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 110, 
[{"StopAnswer":{"vncPort":0,"bytesSent":0,"bytesReceived":0,"result":true,"details":"VM 
does not exist","wait":0}}] }
2012-08-01 16:44:46,759 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-27:null) Cleanup succeeded. Details VM does not exist
2012-08-01 16:44:46,759 DEBUG [agent.manager.AgentAttache] 
(DirectAgent-27:null) Seq 13-1102643302: No more commands found
2012-08-01 16:44:46,759 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643302: Received:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 110, { StopAnswer } }
2012-08-01 16:44:46,759 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Cleanup succeeded. Details VM does not exist
2012-08-01 16:44:46,768 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Service SecurityGroup is not supported in the 
network id=211
2012-08-01 16:44:46,775 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Changing active number of nics for network 
id=211 on -1
2012-08-01 16:44:46,778 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Successfully cleanued up resources for the vm 
VM[User|i-2-135-VM] in Starting state
2012-08-01 16:44:46,780 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Root volume is ready, need to place VM in 
volume's cluster
2012-08-01 16:44:46,780 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Vol[147|vm=135|ROOT] is READY, changing 
deployment plan to use this pool's dcId: 2 , podId: 1 , and clusterId: 1
2012-08-01 16:44:46,781 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) DeploymentPlanner allocation algorithm: random
2012-08-01 16:44:46,781 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Trying to allocate a host and storage pools 
from dc:2, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
2012-08-01 16:44:46,781 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Is ROOT volume READY (pool already allocated)?: Yes
2012-08-01 16:44:46,781 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Searching resources only under specified Cluster: 1
2012-08-01 16:44:46,786 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Checking resources in Cluster: 1 under Pod: 1
2012-08-01 16:44:46,786 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Calling HostAllocators to find suitable hosts
2012-08-01 16:44:46,786 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Looking for hosts in 
dc: 2  pod:1  cluster:1
2012-08-01 16:44:46,788 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) FirstFitAllocator has 
3 hosts to check for allocation: [Host[-13-Routing], Host[-17-Routing], 
Host[-16-Routing]]
2012-08-01 16:44:46,791 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Found 3 hosts for 
allocation after prioritization: [Host[-13-Routing], Host[-17-Routing], 
Host[-16-Routing]]
2012-08-01 16:44:46,791 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Looking for 
speed=1000Mhz, Ram=1024
2012-08-01 16:44:46,791 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Host name: hv1, 
hostId: 13 is in avoid set, skipping this and trying other available hosts
2012-08-01 16:44:46,791 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Host name: hv3, 
hostId: 17 is in avoid set, skipping this and trying other available hosts
2012-08-01 16:44:46,793 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Checking if host: 16 
has enough capacity for requested CPU: 1000 and requested RAM: 
1073741824 , cpuOverprovisioningFactor: 1.0
2012-08-01 16:44:46,795 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Hosts's actual total 
CPU: 57456 and CPU after applying overprovisioning: 57456
2012-08-01 16:44:46,795 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Free CPU: 33456 , 
Requested CPU: 1000
2012-08-01 16:44:46,795 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Free RAM: 74722373184 
, Requested RAM: 1073741824
2012-08-01 16:44:46,795 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Host has enough CPU 
and RAM available
2012-08-01 16:44:46,795 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) STATS: Can alloc CPU 
from host: 16, used: 24000, reserved: 0, actual total: 57456, total with 
overprovisioning: 57456; requested cpu:1000,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:46,795 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) STATS: Can alloc MEM 
from host: 16, used: 25769803776, reserved: 0, total: 100492176960; 
requested mem: 1073741824,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:46,795 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Found a suitable host, 
adding to list: 16
2012-08-01 16:44:46,795 DEBUG [allocator.impl.FirstFitAllocator] 
(Job-Executor-8:job-206 FirstFitRoutingAllocator) Host Allocator 
returning 1 suitable hosts
2012-08-01 16:44:46,796 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Checking suitable pools for volume (Id, Type): 
(147,ROOT)
2012-08-01 16:44:46,796 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Volume is in READY state and has pool already 
allocated, checking if pool can be reused, poolId: 204
2012-08-01 16:44:46,797 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Planner need not allocate a pool for this 
volume since its READY
2012-08-01 16:44:46,797 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Trying to find a potenial host and associated 
storage pools from the suitable host/pool lists for this VM
2012-08-01 16:44:46,797 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Checking if host: 16 can access any suitable 
storage pool for volume: ROOT
2012-08-01 16:44:46,798 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Host: 16 can access pool: 204
2012-08-01 16:44:46,798 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Found a potential host id: 16 name: hv2 and 
associated storage pools for this VM
2012-08-01 16:44:46,799 DEBUG [cloud.deploy.FirstFitPlanner] 
(Job-Executor-8:job-206) Returning Deployment Destination: 
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] 
: Dest[Zone(2)-Pod(1)-Cluster(1)-Host(16)-Storage()]
2012-08-01 16:44:46,799 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Deployment found  - P0=VM[User|i-2-135-VM], 
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] 
: Dest[Zone(2)-Pod(1)-Cluster(1)-Host(16)-Storage()]
2012-08-01 16:44:46,804 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) VM state transitted from :Starting to Starting 
with event: OperationRetryvm's original host id: null new host id: 16 
host id before state transition: 13
2012-08-01 16:44:46,807 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) Hosts's actual total CPU: 57456 and CPU after 
applying overprovisioning: 57456
2012-08-01 16:44:46,807 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) release cpu from host: 13, old used: 
2500,reserved: 0, actual total: 57456, total with overprovisioning: 
57456; new used: 1500,reserved:0; movedfromreserved: 
false,moveToReserveredfalse
2012-08-01 16:44:46,807 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) release mem from host: 13, old used: 
2550136832,reserved: 0, total: 98237986560; new used: 
1476395008,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-08-01 16:44:46,813 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) Hosts's actual total CPU: 57456 and CPU after 
applying overprovisioning: 57456
2012-08-01 16:44:46,813 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) We are allocating VM, increasing the used 
capacity of this host:16
2012-08-01 16:44:46,813 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) Current Used CPU: 24000 , Free CPU:33456 
,Requested CPU: 1000
2012-08-01 16:44:46,813 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) Current Used RAM: 25769803776 , Free 
RAM:74722373184 ,Requested RAM: 1073741824
2012-08-01 16:44:46,814 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) CPU STATS after allocation: for host: 16, old 
used: 24000, old reserved: 0, actual total: 57456, total with 
overprovisioning: 57456; new used:25000, reserved:0; requested 
cpu:1000,alloc_from_last:false
2012-08-01 16:44:46,814 DEBUG [cloud.capacity.CapacityManagerImpl] 
(Job-Executor-8:job-206) RAM STATS after allocation: for host: 16, old 
used: 25769803776, old reserved: 0, total: 100492176960; new used: 
26843545600, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2012-08-01 16:44:46,817 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) VM is being started in podId: 1
2012-08-01 16:44:46,819 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Network id=211 is already implemented
2012-08-01 16:44:46,828 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Service SecurityGroup is not supported in the 
network id=211
2012-08-01 16:44:46,833 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Changing active number of nics for network 
id=211 on 1
2012-08-01 16:44:46,836 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking JuniperSRX to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:46,839 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking Netscaler to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:46,842 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking F5BigIp to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:46,846 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Asking VirtualRouter to prepare for 
Nic[469-135-28c5f2c5-110c-4de4-98f4-fe96866a2f0d-10.1.1.220]
2012-08-01 16:44:46,852 DEBUG 
[network.router.VirtualNetworkApplianceManagerImpl] 
(Job-Executor-8:job-206) Starting a router for Ntwk[211|Guest|7] in 
datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$22635440@2
2012-08-01 16:44:46,862 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Service SecurityGroup is not supported in the 
network id=211
2012-08-01 16:44:46,864 DEBUG 
[network.router.VirtualNetworkApplianceManagerImpl] 
(Job-Executor-8:job-206) Applying dhcp entry in network Ntwk[211|Guest|7]
2012-08-01 16:44:46,875 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643303: Sending  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"routing.DhcpEntryCommand":{"vmMac":"02:00:3d:fc:00:0b","vmIpAddress":"10.1.1.220","vmName":"XCP","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.name":"r-126-VM","router.ip":"169.254.2.97"},"wait":0}}] 
}
2012-08-01 16:44:46,875 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643303: Executing:  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"routing.DhcpEntryCommand":{"vmMac":"02:00:3d:fc:00:0b","vmIpAddress":"10.1.1.220","vmName":"XCP","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.name":"r-126-VM","router.ip":"169.254.2.97"},"wait":0}}] 
}
2012-08-01 16:44:46,876 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-15:null) Seq 13-1102643303: Executing request
2012-08-01 16:44:49,024 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-42:null) Ping from 13
2012-08-01 16:44:49,285 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-15:null) Seq 13-1102643303: Response Received:
2012-08-01 16:44:49,285 DEBUG [agent.transport.Request] 
(DirectAgent-15:null) Seq 13-1102643303: Processing:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 110, 
[{"Answer":{"result":true,"wait":0}}] }
2012-08-01 16:44:49,285 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-15:null) Cleanup succeeded. Details null
2012-08-01 16:44:49,285 DEBUG [agent.manager.AgentAttache] 
(DirectAgent-15:null) Seq 13-1102643303: No more commands found
2012-08-01 16:44:49,285 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643303: Received:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 110, { Answer } }
2012-08-01 16:44:49,285 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(Job-Executor-8:job-206) Cleanup succeeded. Details null
2012-08-01 16:44:49,292 DEBUG [cloud.network.NetworkManagerImpl] 
(Job-Executor-8:job-206) Service SecurityGroup is not supported in the 
network id=211
2012-08-01 16:44:49,295 DEBUG 
[network.router.VirtualNetworkApplianceManagerImpl] 
(Job-Executor-8:job-206) Applying userdata and password entry in network 
Ntwk[211|Guest|7]
2012-08-01 16:44:49,307 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643304: Sending  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.1.1.220","vmName":"XCP","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.97","router.name":"r-126-VM"},"wait":0}},{"routing.VmDataCommand":{"vmIpAddress":"10.1.1.220","vmName":"XCP","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.97","router.name":"r-126-VM"},"wait":0}}] 
}
2012-08-01 16:44:49,307 DEBUG [agent.transport.Request] 
(Job-Executor-8:job-206) Seq 13-1102643304: Executing:  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100111, 
[{"routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.1.1.220","vmName":"XCP","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.97","router.name":"r-126-VM"},"wait":0}},{"routing.VmDataCommand":{"vmIpAddress":"10.1.1.220","vmName":"XCP","accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.97","router.name":"r-126-VM"},"wait":0}}] 
}
2012-08-01 16:44:49,307 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-169:null) Seq 13-1102643304: Executing request
2012-08-01 16:44:49,921 DEBUG [agent.manager.AgentManagerImpl] 
(AgentManager-Handler-5:null) Ping from 19
2012-08-01 16:44:50,102 DEBUG [agent.manager.AgentManagerImpl] 
(AgentManager-Handler-6:null) Ping from 18
2012-08-01 16:44:51,308 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-430:null) Ping from 17
2012-08-01 16:44:51,682 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-419:null) Ping from 16
2012-08-01 16:44:55,945 DEBUG 
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 
2 is ready to launch secondary storage VM
2012-08-01 16:44:56,037 DEBUG 
[cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 
2 is ready to launch console proxy
2012-08-01 16:44:56,231 DEBUG 
[network.router.VirtualNetworkApplianceManagerImpl] 
(RouterStatusMonitor-1:null) Found 2 routers.
2012-08-01 16:44:58,092 INFO  [agent.manager.AgentMonitor] 
(AgentMonitor:null) Found the following agents behind on ping: [19, 13, 
18, 17, 16]
2012-08-01 16:44:58,094 DEBUG [cloud.host.Status] (AgentMonitor:null) 
Ping timeout for host 19, do invstigation
2012-08-01 16:44:58,097 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-10:null) Investigating why host 19 has disconnected with 
event PingTimeout
2012-08-01 16:44:58,097 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-10:null) checking if agent (19) is alive
2012-08-01 16:44:58,098 DEBUG [cloud.host.Status] (AgentMonitor:null) 
Ping timeout for host 13, do invstigation
2012-08-01 16:44:58,100 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-12:null) Investigating why host 13 has disconnected with 
event PingTimeout
2012-08-01 16:44:58,100 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-12:null) checking if agent (13) is alive
2012-08-01 16:44:58,100 DEBUG [agent.transport.Request] 
(AgentTaskPool-10:null) Seq 19-380633147: Sending  { Cmd , MgmtId: 
130577622632, via: 19, Ver: v1, Flags: 100011, 
[{"CheckHealthCommand":{"wait":50}}] }
2012-08-01 16:44:58,101 DEBUG [cloud.host.Status] (AgentMonitor:null) 
Ping timeout for host 18, do invstigation
2012-08-01 16:44:58,103 DEBUG [agent.transport.Request] 
(AgentTaskPool-12:null) Seq 13-1102643305: Sending  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100011, 
[{"CheckHealthCommand":{"wait":50}}] }
2012-08-01 16:44:58,103 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-16:null) Investigating why host 18 has disconnected with 
event PingTimeout
2012-08-01 16:44:58,103 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-16:null) checking if agent (18) is alive
2012-08-01 16:44:58,103 DEBUG [agent.transport.Request] 
(AgentTaskPool-12:null) Seq 13-1102643305: Executing:  { Cmd , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 100011, 
[{"CheckHealthCommand":{"wait":50}}] }
2012-08-01 16:44:58,103 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-218:null) Seq 13-1102643305: Executing request
2012-08-01 16:44:58,104 DEBUG [cloud.host.Status] (AgentMonitor:null) 
Ping timeout for host 17, do invstigation
2012-08-01 16:44:58,106 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-11:null) Investigating why host 17 has disconnected with 
event PingTimeout
2012-08-01 16:44:58,106 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-11:null) checking if agent (17) is alive
2012-08-01 16:44:58,107 DEBUG [cloud.host.Status] (AgentMonitor:null) 
Ping timeout for host 16, do invstigation
2012-08-01 16:44:58,107 DEBUG [agent.transport.Request] 
(AgentTaskPool-16:null) Seq 18-202899485: Sending  { Cmd , MgmtId: 
130577622632, via: 18, Ver: v1, Flags: 100011, 
[{"CheckHealthCommand":{"wait":50}}] }
2012-08-01 16:44:58,109 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-3:null) Investigating why host 16 has disconnected with 
event PingTimeout
2012-08-01 16:44:58,109 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-3:null) checking if agent (16) is alive
2012-08-01 16:44:58,109 DEBUG [agent.transport.Request] 
(AgentTaskPool-11:null) Seq 17-2018508896: Sending  { Cmd , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 100011, 
[{"CheckHealthCommand":{"wait":50}}] }
2012-08-01 16:44:58,109 DEBUG [agent.transport.Request] 
(AgentTaskPool-11:null) Seq 17-2018508896: Executing:  { Cmd , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 100011, 
[{"CheckHealthCommand":{"wait":50}}] }
2012-08-01 16:44:58,109 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-411:null) Seq 17-2018508896: Executing request
2012-08-01 16:44:58,111 DEBUG [agent.transport.Request] 
(AgentTaskPool-3:null) Seq 16-479526998: Sending  { Cmd , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 100011, 
[{"CheckHealthCommand":{"wait":50}}] }
2012-08-01 16:44:58,112 DEBUG [agent.transport.Request] 
(AgentTaskPool-3:null) Seq 16-479526998: Executing:  { Cmd , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 100011, 
[{"CheckHealthCommand":{"wait":50}}] }
2012-08-01 16:44:58,114 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-129:null) Seq 16-479526998: Executing request
2012-08-01 16:44:58,143 DEBUG [agent.transport.Request] 
(AgentManager-Handler-7:null) Seq 19-380633147: Processing:  { Ans: , 
MgmtId: 130577622632, via: 19, Ver: v1, Flags: 10, 
[{"CheckHealthAnswer":{"result":true,"details":"resource is 
alive","wait":0}}] }
2012-08-01 16:44:58,144 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(AgentManager-Handler-7:null) Cleanup succeeded. Details resource is alive
2012-08-01 16:44:58,144 DEBUG [agent.transport.Request] 
(AgentTaskPool-10:null) Seq 19-380633147: Received:  { Ans: , MgmtId: 
130577622632, via: 19, Ver: v1, Flags: 10, { CheckHealthAnswer } }
2012-08-01 16:44:58,144 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(AgentTaskPool-10:null) Cleanup succeeded. Details resource is alive
2012-08-01 16:44:58,144 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-10:null) Details from executing class 
com.cloud.agent.api.CheckHealthCommand: resource is alive
2012-08-01 16:44:58,144 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-10:null) agent (19) responded to checkHeathCommand, 
reporting that agent is Up
2012-08-01 16:44:58,144 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-10:null) The state determined is Up
2012-08-01 16:44:58,144 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-10:null) Agent is determined to be up and running
2012-08-01 16:44:58,144 DEBUG [cloud.host.Status] 
(AgentTaskPool-10:null) Transition:[Resource state = Enabled, Agent 
event = Ping, Host id = 19, name = s-121-VM]
2012-08-01 16:44:58,150 DEBUG [cloud.host.Status] 
(AgentTaskPool-10:null) Agent status update: [id = 19; name = s-121-VM; 
old status = Up; event = Ping; new status = Up; old update count = 79; 
new update count = 80]
2012-08-01 16:44:58,151 DEBUG [agent.transport.Request] 
(AgentManager-Handler-8:null) Seq 18-202899485: Processing:  { Ans: , 
MgmtId: 130577622632, via: 18, Ver: v1, Flags: 10, 
[{"CheckHealthAnswer":{"result":true,"details":"resource is 
alive","wait":0}}] }
2012-08-01 16:44:58,151 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(AgentManager-Handler-8:null) Cleanup succeeded. Details resource is alive
2012-08-01 16:44:58,152 DEBUG [agent.transport.Request] 
(AgentTaskPool-16:null) Seq 18-202899485: Received:  { Ans: , MgmtId: 
130577622632, via: 18, Ver: v1, Flags: 10, { CheckHealthAnswer } }
2012-08-01 16:44:58,152 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(AgentTaskPool-16:null) Cleanup succeeded. Details resource is alive
2012-08-01 16:44:58,152 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-16:null) Details from executing class 
com.cloud.agent.api.CheckHealthCommand: resource is alive
2012-08-01 16:44:58,152 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-16:null) agent (18) responded to checkHeathCommand, 
reporting that agent is Up
2012-08-01 16:44:58,152 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-16:null) The state determined is Up
2012-08-01 16:44:58,152 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-16:null) Agent is determined to be up and running
2012-08-01 16:44:58,152 DEBUG [cloud.host.Status] 
(AgentTaskPool-16:null) Transition:[Resource state = Enabled, Agent 
event = Ping, Host id = 18, name = v-122-VM]
2012-08-01 16:44:58,155 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-218:null) Seq 13-1102643305: Response Received:
2012-08-01 16:44:58,155 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-411:null) Seq 17-2018508896: Response Received:
2012-08-01 16:44:58,156 DEBUG [agent.transport.Request] 
(DirectAgent-218:null) Seq 13-1102643305: Processing:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 10, 
[{"CheckHealthAnswer":{"result":true,"details":"resource is 
alive","wait":0}}] }
2012-08-01 16:44:58,156 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-218:null) Cleanup succeeded. Details resource is alive
2012-08-01 16:44:58,156 DEBUG [agent.transport.Request] 
(DirectAgent-411:null) Seq 17-2018508896: Processing:  { Ans: , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 10, 
[{"CheckHealthAnswer":{"result":true,"details":"resource is 
alive","wait":0}}] }
2012-08-01 16:44:58,156 DEBUG [agent.transport.Request] 
(AgentTaskPool-12:null) Seq 13-1102643305: Received:  { Ans: , MgmtId: 
130577622632, via: 13, Ver: v1, Flags: 10, { CheckHealthAnswer } }
2012-08-01 16:44:58,156 DEBUG [agent.transport.Request] 
(AgentTaskPool-11:null) Seq 17-2018508896: Received:  { Ans: , MgmtId: 
130577622632, via: 17, Ver: v1, Flags: 10, { CheckHealthAnswer } }
2012-08-01 16:44:58,156 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(AgentTaskPool-11:null) Cleanup succeeded. Details resource is alive
2012-08-01 16:44:58,156 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-11:null) Details from executing class 
com.cloud.agent.api.CheckHealthCommand: resource is alive
2012-08-01 16:44:58,156 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-11:null) agent (17) responded to checkHeathCommand, 
reporting that agent is Up
2012-08-01 16:44:58,156 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-11:null) The state determined is Up
2012-08-01 16:44:58,156 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-11:null) Agent is determined to be up and running
2012-08-01 16:44:58,156 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-411:null) Cleanup succeeded. Details resource is alive
2012-08-01 16:44:58,156 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(AgentTaskPool-12:null) Cleanup succeeded. Details resource is alive
2012-08-01 16:44:58,156 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-12:null) Details from executing class 
com.cloud.agent.api.CheckHealthCommand: resource is alive
2012-08-01 16:44:58,156 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-12:null) agent (13) responded to checkHeathCommand, 
reporting that agent is Up
2012-08-01 16:44:58,156 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-12:null) The state determined is Up
2012-08-01 16:44:58,156 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-12:null) Agent is determined to be up and running
2012-08-01 16:44:58,158 DEBUG [cloud.host.Status] 
(AgentTaskPool-16:null) Agent status update: [id = 18; name = v-122-VM; 
old status = Up; event = Ping; new status = Up; old update count = 103; 
new update count = 104]
2012-08-01 16:44:58,158 DEBUG [cloud.host.Status] 
(AgentTaskPool-11:null) Transition:[Resource state = Enabled, Agent 
event = Ping, Host id = 17, name = hv3]
2012-08-01 16:44:58,162 DEBUG [cloud.host.Status] 
(AgentTaskPool-11:null) Agent status update: [id = 17; name = hv3; old 
status = Up; event = Ping; new status = Up; old update count = 955; new 
update count = 956]
2012-08-01 16:44:58,162 DEBUG [cloud.host.Status] 
(AgentTaskPool-12:null) Transition:[Resource state = Enabled, Agent 
event = Ping, Host id = 13, name = hv1]
2012-08-01 16:44:58,163 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-129:null) Seq 16-479526998: Response Received:
2012-08-01 16:44:58,163 DEBUG [agent.transport.Request] 
(DirectAgent-129:null) Seq 16-479526998: Processing:  { Ans: , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 10, 
[{"CheckHealthAnswer":{"result":true,"details":"resource is 
alive","wait":0}}] }
2012-08-01 16:44:58,163 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-129:null) Cleanup succeeded. Details resource is alive
2012-08-01 16:44:58,163 DEBUG [agent.transport.Request] 
(AgentTaskPool-3:null) Seq 16-479526998: Received:  { Ans: , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 10, { CheckHealthAnswer } }
2012-08-01 16:44:58,163 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(AgentTaskPool-3:null) Cleanup succeeded. Details resource is alive
2012-08-01 16:44:58,164 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-3:null) Details from executing class 
com.cloud.agent.api.CheckHealthCommand: resource is alive
2012-08-01 16:44:58,164 DEBUG [agent.manager.AgentManagerImpl] 
(AgentTaskPool-3:null) agent (16) responded to checkHeathCommand, 
reporting that agent is Up
2012-08-01 16:44:58,164 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-3:null) The state determined is Up
2012-08-01 16:44:58,164 INFO  [agent.manager.AgentManagerImpl] 
(AgentTaskPool-3:null) Agent is determined to be up and running
2012-08-01 16:44:58,167 DEBUG [cloud.host.Status] 
(AgentTaskPool-12:null) Agent status update: [id = 13; name = hv1; old 
status = Up; event = Ping; new status = Up; old update count = 1914; new 
update count = 1915]
2012-08-01 16:44:58,167 DEBUG [cloud.host.Status] (AgentTaskPool-3:null) 
Transition:[Resource state = Enabled, Agent event = Ping, Host id = 16, 
name = hv2]
2012-08-01 16:44:58,171 DEBUG [cloud.host.Status] (AgentTaskPool-3:null) 
Agent status update: [id = 16; name = hv2; old status = Up; event = 
Ping; new status = Up; old update count = 936; new update count = 937]
2012-08-01 16:44:59,257 INFO  [cloud.ha.HighAvailabilityManagerImpl] 
(HA-Worker-2:work-110) Processing HAWork[110-HA-124-Stopped-Scheduled]
2012-08-01 16:44:59,261 INFO  [cloud.ha.HighAvailabilityManagerImpl] 
(HA-Worker-2:work-110) HA on VM[DomainRouter|r-124-VM]
2012-08-01 16:44:59,269 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) VM state transitted from :Stopped to Starting 
with event: StartRequestedvm's original host id: 13 new host id: null 
host id before state transition: null
2012-08-01 16:44:59,269 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) Successfully transitioned to start state for 
VM[DomainRouter|r-124-VM] reservation id = 
10b7874f-8f09-4a00-8f51-3a9375c7e1a7
2012-08-01 16:44:59,273 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) Trying to deploy VM, vm has dcId: 2 and podId: 1
2012-08-01 16:44:59,274 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) Deploy avoids pods: null, clusters: null, hosts: null
2012-08-01 16:44:59,276 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) Root volume is ready, need to place VM in 
volume's cluster
2012-08-01 16:44:59,276 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) Vol[132|vm=124|ROOT] is READY, changing 
deployment plan to use this pool's dcId: 2 , podId: 1 , and clusterId: 1
2012-08-01 16:44:59,277 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) DeploymentPlanner allocation algorithm: random
2012-08-01 16:44:59,277 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Trying to allocate a host and storage pools from 
dc:2, pod:1,cluster:1, requested cpu: 500, requested ram: 134217728
2012-08-01 16:44:59,277 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Is ROOT volume READY (pool already allocated)?: Yes
2012-08-01 16:44:59,277 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) This VM has last host_id specified, trying to 
choose the same host: 13
2012-08-01 16:44:59,278 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) Checking if host: 13 has enough capacity for 
requested CPU: 500 and requested RAM: 134217728 , 
cpuOverprovisioningFactor: 1.0
2012-08-01 16:44:59,280 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) Hosts's actual total CPU: 57456 and CPU after 
applying overprovisioning: 57456
2012-08-01 16:44:59,280 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) We need to allocate to the last host again, so 
checking if there is enough reserved capacity
2012-08-01 16:44:59,280 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) Reserved CPU: 0 , Requested CPU: 500
2012-08-01 16:44:59,280 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) Reserved RAM: 0 , Requested RAM: 134217728
2012-08-01 16:44:59,280 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) STATS: Failed to alloc resource from host: 13 
reservedCpu: 0, requested cpu: 500, reservedMem: 0, requested mem: 134217728
2012-08-01 16:44:59,280 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) Host does not have enough reserved CPU available, 
cannot allocate to this host.
2012-08-01 16:44:59,280 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) The last host of this VM does not have enough 
capacity
2012-08-01 16:44:59,280 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Cannot choose the last host to deploy this VM
2012-08-01 16:44:59,280 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Searching resources only under specified Cluster: 1
2012-08-01 16:44:59,285 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Checking resources in Cluster: 1 under Pod: 1
2012-08-01 16:44:59,285 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Calling HostAllocators to find suitable hosts
2012-08-01 16:44:59,285 DEBUG [allocator.impl.FirstFitAllocator] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Looking for hosts in dc: 
2  pod:1  cluster:1
2012-08-01 16:44:59,286 DEBUG [allocator.impl.FirstFitAllocator] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) FirstFitAllocator has 3 
hosts to check for allocation: [Host[-16-Routing], Host[-17-Routing], 
Host[-13-Routing]]
2012-08-01 16:44:59,289 DEBUG [allocator.impl.FirstFitAllocator] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Found 3 hosts for 
allocation after prioritization: [Host[-16-Routing], Host[-17-Routing], 
Host[-13-Routing]]
2012-08-01 16:44:59,289 DEBUG [allocator.impl.FirstFitAllocator] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Looking for 
speed=500Mhz, Ram=128
2012-08-01 16:44:59,290 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Checking if host: 16 has 
enough capacity for requested CPU: 500 and requested RAM: 134217728 , 
cpuOverprovisioningFactor: 1.0
2012-08-01 16:44:59,292 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Hosts's actual total 
CPU: 57456 and CPU after applying overprovisioning: 57456
2012-08-01 16:44:59,292 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Free CPU: 32456 , 
Requested CPU: 500
2012-08-01 16:44:59,292 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Free RAM: 73648631360 , 
Requested RAM: 134217728
2012-08-01 16:44:59,292 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Host has enough CPU and 
RAM available
2012-08-01 16:44:59,292 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) STATS: Can alloc CPU 
from host: 16, used: 25000, reserved: 0, actual total: 57456, total with 
overprovisioning: 57456; requested cpu:500,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:59,292 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) STATS: Can alloc MEM 
from host: 16, used: 26843545600, reserved: 0, total: 100492176960; 
requested mem: 134217728,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:59,292 DEBUG [allocator.impl.FirstFitAllocator] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Found a suitable host, 
adding to list: 16
2012-08-01 16:44:59,293 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Checking if host: 17 has 
enough capacity for requested CPU: 500 and requested RAM: 134217728 , 
cpuOverprovisioningFactor: 1.0
2012-08-01 16:44:59,295 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Hosts's actual total 
CPU: 57456 and CPU after applying overprovisioning: 57456
2012-08-01 16:44:59,295 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Free CPU: 57456 , 
Requested CPU: 500
2012-08-01 16:44:59,295 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Free RAM: 98958404160 , 
Requested RAM: 134217728
2012-08-01 16:44:59,295 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Host has enough CPU and 
RAM available
2012-08-01 16:44:59,295 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) STATS: Can alloc CPU 
from host: 17, used: 0, reserved: 0, actual total: 57456, total with 
overprovisioning: 57456; requested cpu:500,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:59,295 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) STATS: Can alloc MEM 
from host: 17, used: 0, reserved: 0, total: 98958404160; requested mem: 
134217728,alloc_from_last_host?:false ,considerReservedCapacity?: true
2012-08-01 16:44:59,295 DEBUG [allocator.impl.FirstFitAllocator] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Found a suitable host, 
adding to list: 17
2012-08-01 16:44:59,296 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Checking if host: 13 has 
enough capacity for requested CPU: 500 and requested RAM: 134217728 , 
cpuOverprovisioningFactor: 1.0
2012-08-01 16:44:59,298 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Hosts's actual total 
CPU: 57456 and CPU after applying overprovisioning: 57456
2012-08-01 16:44:59,298 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Free CPU: 55956 , 
Requested CPU: 500
2012-08-01 16:44:59,298 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Free RAM: 96761591552 , 
Requested RAM: 134217728
2012-08-01 16:44:59,298 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Host has enough CPU and 
RAM available
2012-08-01 16:44:59,298 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) STATS: Can alloc CPU 
from host: 13, used: 1500, reserved: 0, actual total: 57456, total with 
overprovisioning: 57456; requested cpu:500,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:59,298 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) STATS: Can alloc MEM 
from host: 13, used: 1476395008, reserved: 0, total: 98237986560; 
requested mem: 134217728,alloc_from_last_host?:false 
,considerReservedCapacity?: true
2012-08-01 16:44:59,298 DEBUG [allocator.impl.FirstFitAllocator] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Found a suitable host, 
adding to list: 13
2012-08-01 16:44:59,298 DEBUG [allocator.impl.FirstFitAllocator] 
(HA-Worker-2:work-110 FirstFitRoutingAllocator) Host Allocator returning 
3 suitable hosts
2012-08-01 16:44:59,299 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Checking suitable pools for volume (Id, Type): 
(132,ROOT)
2012-08-01 16:44:59,299 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Volume is in READY state and has pool already 
allocated, checking if pool can be reused, poolId: 204
2012-08-01 16:44:59,300 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Planner need not allocate a pool for this volume 
since its READY
2012-08-01 16:44:59,300 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Trying to find a potenial host and associated 
storage pools from the suitable host/pool lists for this VM
2012-08-01 16:44:59,300 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Checking if host: 16 can access any suitable 
storage pool for volume: ROOT
2012-08-01 16:44:59,300 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Host: 16 can access pool: 204
2012-08-01 16:44:59,300 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Found a potential host id: 16 name: hv2 and 
associated storage pools for this VM
2012-08-01 16:44:59,301 DEBUG [cloud.deploy.FirstFitPlanner] 
(HA-Worker-2:work-110) Returning Deployment Destination: 
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] 
: Dest[Zone(2)-Pod(1)-Cluster(1)-Host(16)-Storage()]
2012-08-01 16:44:59,301 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) Deployment found  - P0=VM[DomainRouter|r-124-VM], 
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] 
: Dest[Zone(2)-Pod(1)-Cluster(1)-Host(16)-Storage()]
2012-08-01 16:44:59,305 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) VM state transitted from :Starting to Starting 
with event: OperationRetryvm's original host id: 13 new host id: 16 host 
id before state transition: null
2012-08-01 16:44:59,310 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) Hosts's actual total CPU: 57456 and CPU after 
applying overprovisioning: 57456
2012-08-01 16:44:59,310 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) We are allocating VM, increasing the used 
capacity of this host:16
2012-08-01 16:44:59,310 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) Current Used CPU: 25000 , Free CPU:32456 
,Requested CPU: 500
2012-08-01 16:44:59,310 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) Current Used RAM: 26843545600 , Free 
RAM:73648631360 ,Requested RAM: 134217728
2012-08-01 16:44:59,310 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) CPU STATS after allocation: for host: 16, old 
used: 25000, old reserved: 0, actual total: 57456, total with 
overprovisioning: 57456; new used:25500, reserved:0; requested 
cpu:500,alloc_from_last:false
2012-08-01 16:44:59,310 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) RAM STATS after allocation: for host: 16, old 
used: 26843545600, old reserved: 0, total: 100492176960; new used: 
26977763328, reserved: 0; requested mem: 134217728,alloc_from_last:false
2012-08-01 16:44:59,313 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) VM is being started in podId: 1
2012-08-01 16:44:59,315 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Network id=204 is already implemented
2012-08-01 16:44:59,331 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking JuniperSRX to prepare for 
Nic[454-124-null-172.16.15.190]
2012-08-01 16:44:59,331 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking Netscaler to prepare for 
Nic[454-124-null-172.16.15.190]
2012-08-01 16:44:59,331 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking F5BigIp to prepare for 
Nic[454-124-null-172.16.15.190]
2012-08-01 16:44:59,331 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking VirtualRouter to prepare for 
Nic[454-124-null-172.16.15.190]
2012-08-01 16:44:59,331 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking Ovs to prepare for 
Nic[454-124-null-172.16.15.190]
2012-08-01 16:44:59,331 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking ExternalDhcpServer to prepare for 
Nic[454-124-null-172.16.15.190]
2012-08-01 16:44:59,331 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking BareMetal to prepare for 
Nic[454-124-null-172.16.15.190]
2012-08-01 16:44:59,331 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking SecurityGroupProvider to prepare for 
Nic[454-124-null-172.16.15.190]
2012-08-01 16:44:59,332 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Network id=206 is already implemented
2012-08-01 16:44:59,349 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking JuniperSRX to prepare for 
Nic[456-124-10b7874f-8f09-4a00-8f51-3a9375c7e1a7-169.254.0.230]
2012-08-01 16:44:59,349 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking Netscaler to prepare for 
Nic[456-124-10b7874f-8f09-4a00-8f51-3a9375c7e1a7-169.254.0.230]
2012-08-01 16:44:59,349 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking F5BigIp to prepare for 
Nic[456-124-10b7874f-8f09-4a00-8f51-3a9375c7e1a7-169.254.0.230]
2012-08-01 16:44:59,349 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking VirtualRouter to prepare for 
Nic[456-124-10b7874f-8f09-4a00-8f51-3a9375c7e1a7-169.254.0.230]
2012-08-01 16:44:59,349 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking Ovs to prepare for 
Nic[456-124-10b7874f-8f09-4a00-8f51-3a9375c7e1a7-169.254.0.230]
2012-08-01 16:44:59,350 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking ExternalDhcpServer to prepare for 
Nic[456-124-10b7874f-8f09-4a00-8f51-3a9375c7e1a7-169.254.0.230]
2012-08-01 16:44:59,350 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking BareMetal to prepare for 
Nic[456-124-10b7874f-8f09-4a00-8f51-3a9375c7e1a7-169.254.0.230]
2012-08-01 16:44:59,350 DEBUG [cloud.network.NetworkManagerImpl] 
(HA-Worker-2:work-110) Asking SecurityGroupProvider to prepare for 
Nic[456-124-10b7874f-8f09-4a00-8f51-3a9375c7e1a7-169.254.0.230]
2012-08-01 16:44:59,351 DEBUG [cloud.storage.StorageManagerImpl] 
(HA-Worker-2:work-110) Checking if we need to prepare 1 volumes for 
VM[DomainRouter|r-124-VM]
2012-08-01 16:44:59,351 DEBUG [cloud.storage.StorageManagerImpl] 
(HA-Worker-2:work-110) No need to recreate the volume: 
Vol[132|vm=124|ROOT], since it already has a pool assigned: 204, adding 
disk to VM
2012-08-01 16:44:59,354 ERROR [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) Failed to start instance VM[DomainRouter|r-124-VM]
2012-08-01 16:44:59,357 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) Cleaning up resources for the vm 
VM[DomainRouter|r-124-VM] in Starting state
2012-08-01 16:44:59,358 DEBUG [agent.transport.Request] 
(HA-Worker-2:work-110) Seq 16-479526999: Sending  { Cmd , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 100111, 
[{"StopCommand":{"isProxy":false,"vmName":"r-124-VM","wait":0}}] }
2012-08-01 16:44:59,358 DEBUG [agent.transport.Request] 
(HA-Worker-2:work-110) Seq 16-479526999: Executing:  { Cmd , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 100111, 
[{"StopCommand":{"isProxy":false,"vmName":"r-124-VM","wait":0}}] }
2012-08-01 16:44:59,358 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-122:null) Seq 16-479526999: Executing request
2012-08-01 16:44:59,522 INFO  [xen.resource.CitrixResourceBase] 
(DirectAgent-122:null) VM does not exist on 
XenServer1d86d063-10b3-41c2-a681-3ce3ce78760a
2012-08-01 16:44:59,522 DEBUG [agent.manager.DirectAgentAttache] 
(DirectAgent-122:null) Seq 16-479526999: Response Received:
2012-08-01 16:44:59,522 DEBUG [agent.transport.Request] 
(DirectAgent-122:null) Seq 16-479526999: Processing:  { Ans: , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 110, 
[{"StopAnswer":{"vncPort":0,"bytesSent":0,"bytesReceived":0,"result":true,"details":"VM 
does not exist","wait":0}}] }
2012-08-01 16:44:59,522 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(DirectAgent-122:null) Cleanup succeeded. Details VM does not exist
2012-08-01 16:44:59,523 DEBUG [agent.manager.AgentAttache] 
(DirectAgent-122:null) Seq 16-479526999: No more commands found
2012-08-01 16:44:59,523 DEBUG [agent.transport.Request] 
(HA-Worker-2:work-110) Seq 16-479526999: Received:  { Ans: , MgmtId: 
130577622632, via: 16, Ver: v1, Flags: 110, { StopAnswer } }
2012-08-01 16:44:59,523 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) Cleanup succeeded. Details VM does not exist
2012-08-01 16:44:59,526 DEBUG 
[network.router.VirtualNetworkApplianceManagerImpl] 
(HA-Worker-2:work-110) Successfully updated user statistics as a part of 
domR VM[DomainRouter|r-124-VM] reboot/stop
2012-08-01 16:44:59,544 DEBUG [cloud.vm.VirtualMachineManagerImpl] 
(HA-Worker-2:work-110) Successfully cleanued up resources for the vm 
VM[DomainRouter|r-124-VM] in Starting state
2012-08-01 16:44:59,551 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) VM state transitted from :Starting to Stopped 
with event: OperationFailedvm's original host id: 13 new host id: null 
host id before state transition: 16
2012-08-01 16:44:59,554 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) Hosts's actual total CPU: 57456 and CPU after 
applying overprovisioning: 57456
2012-08-01 16:44:59,554 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) release cpu from host: 16, old used: 
25500,reserved: 0, actual total: 57456, total with overprovisioning: 
57456; new used: 25000,reserved:0; movedfromreserved: 
false,moveToReserveredfalse
2012-08-01 16:44:59,554 DEBUG [cloud.capacity.CapacityManagerImpl] 
(HA-Worker-2:work-110) release mem from host: 16, old used: 
26977763328,reserved: 0, total: 100492176960; new used: 
26843545600,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-08-01 16:44:59,557 WARN  [cloud.ha.HighAvailabilityManagerImpl] 
(HA-Worker-2:work-110) Unable to restart VM[DomainRouter|r-124-VM] due 
to Resource [Host:16] is unreachable: Host 16: Unable to start instance 
due to null
2012-08-01 16:44:59,561 INFO  [cloud.ha.HighAvailabilityManagerImpl] 
(HA-Worker-2:work-110) Rescheduling HAWork[110-HA-124-Stopped-Scheduled] 
to try again at Wed Aug 01 16:46:00 CDT 2012
[root@control1 /]#

-- 
Regards,

Nik

Nik Martin
VP Business Development
Nfina Technologies, Inc.
+1.251.243.0043 x1003
Relentless Reliability

Mime
View raw message