cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Nik Martin <nik.mar...@nfinausa.com>
Subject Re: Cryptic Error creating VM from ISO
Date Thu, 02 Aug 2012 15:01:24 GMT
On 08/02/2012 09:14 AM, Gijsbert Janssen van Doorn wrote:
> What kind of OS did you select for this ISO. Also installing XCP on top of XenServer doesn't sound like something that
> will work like expected (hypervisor on hypervisor).
>
> The "Expunging" VM's should be removed within 24 hours (depending on you cleanup settings in the Global Settings).
>
I dug around online and the best I could tell is that XCP is built on 
top of Centos x86_64, so I chose Centos 6 x86_64.  That was my first 
suspicion when it failed, but the log didn't really give me that 
definitively.
>
> -----Original Message-----
> From: Nik Martin [mailto:nik.martin@nfinausa.com]
> Sent: donderdag 2 augustus 2012 16:04
> To: cloudstack-users@incubator.apache.org
> Subject: Re: Cryptic Error creating VM from ISO
>
> On 08/01/2012 11:41 PM, Nitin Mehta wrote:
>> Nik - Can you please check on the hypervisor as well if you see any reason why this is failing ?
>> BTW which hypervisor are you using and is this ISO guest OS supported by the hypervisor version you are using ?
>>
>> Thanks,
>> -Nitin
>>
>
> The HV is Xenserver 6.2 patched to current. I just created a VM using
> the same offering, but using a Centos 6.02 DVD iso, and it worked
> perfectly.
>
> Here is the output from var/log/messages on the HV  when trying to
> create a VM with the XCP (Xen Cloud Platform) iso image:
>
> Aug  2 08:58:25 hv1 kernel: svc: failed to register lockdv1 RPC service
> (errno 97).
> Aug  2 08:58:26 hv1 kernel: svc: failed to register lockdv1 RPC service
> (errno 97).
> Aug  2 08:58:27 hv1 tapdisk[31978]: tapdisk-control: init, 10 x 4k buffers
> Aug  2 08:58:27 hv1 tapdisk[31978]: I/O queue driver: lio
> Aug  2 08:58:27 hv1 tapdisk[31978]: tapdisk-log: started, level 0
> Aug  2 08:58:27 hv1 tapdisk[31978]: block-aio
> open('/var/run/sr-mount/cdd49fd7-b7fd-0247-e277-2c8e4530a976/205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso')
> Aug  2 08:58:27 hv1 tapdisk[31978]:
> open(/var/run/sr-mount/cdd49fd7-b7fd-0247-e277-2c8e4530a976/205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso)
> with O_DIRECT
> Aug  2 08:58:27 hv1 tapdisk[31978]: Image size:  	pre sector_shift
> [379250688] 	post sector_shift [740724]
> Aug  2 08:58:27 hv1 tapdisk[31978]: opened image
> /var/run/sr-mount/cdd49fd7-b7fd-0247-e277-2c8e4530a976/205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso
> (1 users, state: 0x00000003, type: 0, ro)
> Aug  2 08:58:27 hv1 tapdisk[31978]: VBD CHAIN:
> Aug  2 08:58:27 hv1 tapdisk[31978]:
> /var/run/sr-mount/cdd49fd7-b7fd-0247-e277-2c8e4530a976/205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso:
> type:aio(0) storage:n/a(-1)
> Aug  2 08:58:27 hv1 tapdisk[31978]: bdev: capacity=740724
> sector_size=512/512 flags=0
> Aug  2 08:58:27 hv1 kernel: block tde: sector-size: 512/512 capacity: 740724
> Aug  2 08:58:27 hv1 kernel: blkback: event-channel 65
> Aug  2 08:58:27 hv1 kernel: blkback: ring-ref 8
> Aug  2 08:58:27 hv1 kernel: blkback: protocol 1 (x86_32-abi)
> Aug  2 08:58:27 hv1 kernel: blkfront: xvda: barriers enabled
> Aug  2 08:58:27 hv1 kernel:  xvda: unknown partition table
> Aug  2 08:58:27 hv1 vbd.uevent[add](backend/vbd/0/51712): wrote
> /xapi/0/hotplug/vbd/51712/hotplug = 'online'
> Aug  2 08:58:27 hv1 vbd.uevent[add](backend/vbd/0/51712): wrote
> backend/vbd/0/51712/hotplug-status = 'connected'
> Aug  2 08:58:28 hv1 ELILOADER: Traceback (most recent call last):
> Aug  2 08:58:28 hv1 ELILOADER:   File "/usr/bin/eliloader", line 909, in
> ?     sys.exit(main())
> Aug  2 08:58:28 hv1 ELILOADER:   File "/usr/bin/eliloader", line 899, in
> main     handle_first_boot(vm, img, args, other_config)
> Aug  2 08:58:28 hv1 ELILOADER:   File "/usr/bin/eliloader", line 718, in
> handle_first_boot     kernel, ramdisk = rhel_first_boot_handler(vm,
> repo_url)
> Aug  2 08:58:28 hv1 ELILOADER:   File "/usr/bin/eliloader", line 493, in
> rhel_first_boot_handler     raise InvalidSource, "Unable to access a
> required file in the specified repository: %s." % e.name
> Aug  2 08:58:28 hv1 ELILOADER: InvalidSource: Unable to access a
> required file in the specified repository:
> file:///tmp/cdrom-repo-ocZrAO/isolinux/vmlinuz.
> Aug  2 08:58:28 hv1 fe: 32027 (/usr/bin/eliloader -q --default_args=
> --extra_args=graphical utf8 --vm=cbc638...) exitted with code 1
> Aug  2 08:58:28 hv1 multipathd: xvda: remove path (operator)
> Aug  2 08:58:28 hv1 multipathd: xvda: spurious uevent, path not in pathvec
> Aug  2 08:58:28 hv1 vbd.uevent[remove](backend/vbd/0/51712): removed
> /xapi/0/hotplug/vbd/51712/hotplug
> Aug  2 08:58:28 hv1 vbd.uevent[remove](backend/vbd/0/51712): removed
> backend/vbd/0/51712/hotplug-status
> Aug  2 08:58:29 hv1 tapdisk[31978]: closed image
> /var/run/sr-mount/cdd49fd7-b7fd-0247-e277-2c8e4530a976/205-2-bd987063-a037-3a5f-9796-f0d5ddee3c31.iso
> (0 users, state: 0x00000002, type: 0)
> Aug  2 08:58:29 hv1 tapdisk[31978]: tapdisk-log: closing after 0 errors
> Aug  2 08:58:29 hv1 tapdisk[31978]: tapdisk-syslog: 11 messages, 909
> bytes, xmits: 12, failed: 0, dropped: 0
> Aug  2 08:58:29 hv1 tapdisk[31978]: tapdisk-control: draining 1 connections
> Aug  2 08:58:29 hv1 tapdisk[31978]: tapdisk-control: done
> Aug  2 08:58:29 hv1 xapi: [error|hv1|372223|Async.VM.start_on
> R:15a23795dd78|xapi] Vmops.start_paused caught: INVALID_SOURCE: [ Unable
> to access a required file in the specified repository:
> file:///tmp/cdrom-repo-ocZrAO/isolinux/vmlinuz.; ;  ]
>
>
>
>> -----Original Message-----
>> From: Nik Martin [mailto:nik.martin@nfinausa.com]
>> Sent: Thursday, August 02, 2012 3:38 AM
>> To: cloudstack-users@incubator.apache.org
>> Subject: Cryptic Error creating VM from ISO
>>
>>     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
>>
>
>


-- 
Regards,

Nik

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

Mime
View raw message