Abhinandan:
Attaching the management log for one of the failed attempts, earlier today ...
Do you need other information?
Evan
-----Original Message-----
From: Evan Miller
Sent: Wednesday, July 25, 2012 8:38 PM
To: cloudstack-users@incubator.apache.org
Subject: RE: Cannot add vm to any host in any cluster - error: "Unable to apply
dhcp entry on router" - still completely blocked
I can ssh without error to the system vm from only one of the XenServers that
is having trouble adding VMs. That particular XenServer was setup as part of
the CSMS Basic Network Setup. Here are the good results:
[root@xenserver1-cs .ssh]# ssh -p 3922 -i /root/.ssh/id_rsa.cloud 169.254.0.227
Linux v-2-VM 2.6.32-5-686-bigmem #1 SMP Mon Jan 16 16:42:05 UTC 2012 i686
The programs included with the Debian GNU/Linux system are free software; the
exact distribution terms for each program are described in the individual files
in /usr/share/doc/*/copyright.
Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent permitted by
applicable law.
Last login: Thu Jul 26 03:27:37 2012 from 169.254.0.1 Linux v-2-VM
2.6.32-5-686-bigmem #1 SMP Mon Jan 16 16:42:05 UTC 2012 i686
The programs included with the Debian GNU/Linux system are free software; the
exact distribution terms for each program are described in the individual files
in /usr/share/doc/*/copyright.
Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent permitted by
applicable law.
root@v-2-VM:~#
AND
Here are the bad results of the XenServer Host that was added after CSMS Basic
Network Setup:
[root@xenserver03 .ssh]# ssh -p 3922 -i /root/.ssh/id_rsa.cloud 169.254.0.227
ssh: connect to host 169.254.0.227 port 3922: No route to host
[root@xenserver03 .ssh]#
For the problematic xenserver03, its known_hosts file is empty.
While, for the successful xenserver1-cs, its known_hosts file contains entries
for:
CSMS Server,
two 169.254.*.* ip addresses.
Regards,
Evan
-----Original Message-----
From: Abhinandan Prateek [mailto:abhinandan.prat...@citrix.com]
Sent: Wednesday, July 25, 2012 7:56 PM
To: cloudstack-users@incubator.apache.org
Subject: RE: Cannot add vm to any host in any cluster - error: "Unable to apply
dhcp entry on router" - still completely blocked
Evan,
There was a type in the command:
ssh -p 3922 -i /root/.ssh/id_rsa.cloud <rvm link local ip>
# a i not an I, I guess outlook capitalized the i and got overlooked.
You need to run this on the host (hypervisor) where CS created the RVM for the
account that is giving you trouble. This is just to ensure that the path taken
by CS to pass control commands(dhcp is one of them) to RVM is good.
-abhi
>-----Original Message-----
>From: Evan Miller [mailto:evan.mil...@citrix.com]
>Sent: Thursday, July 26, 2012 5:15 AM
>To: cloudstack-users@incubator.apache.org
>Subject: RE: Cannot add vm to any host in any cluster - error: "Unable
>to apply dhcp entry on router" - still completely blocked
>
>Abhinandan:
>
>I don't understand which ip and which host you are talking about in
>your
>comment:
>
>To check try logging into RVM using ssh keys from the host on which it
>resides (ssh -p 3922 -I /root/.ssh/id_rsa.cloud <rvm link local ip>).
>
>At any rate, I tried this from the XenServer that is unable to add the VM:
>
>[root@xenserver1-cs .ssh]# ssh -p 3922 -I /root/.ssh/id_rsa.cloud
>169.254.0.227 no support for smartcards.
>The authenticity of host '169.254.0.227 (169.254.0.227)' can't be established.
>RSA key fingerprint is 58:de:8b:d7:2b:8e:01:2e:cd:f4:58:86:27:e4:94:39.
>Are you sure you want to continue connecting (yes/no)? yes
>Warning: Permanently added '169.254.0.227' (RSA) to the list of known hosts.
>Permission denied (publickey).
>[root@xenserver1-cs .ssh]#
>
>I assumed the RVM's ip address is the Link Local Address (169.254.0.227)?
>If not correct, please advise.
>
>What next?
>
>Note:
>Before trying the above, I uninstalled CSMS 3.0.2.1 and (part of?) the
>database using install.sh. Then, I re-ran the Basic Network Setup from
>the GUI. The above DHCP problem still persists.
>
>Please help. I am still completely blocked.
>
>Evan
>
>-----Original Message-----
>From: Abhinandan Prateek [mailto:abhinandan.prat...@citrix.com]
>Sent: Monday, July 23, 2012 9:11 PM
>To: cloudstack-users@incubator.apache.org
>Subject: RE: Cannot add vm to any host in any cluster - error: "Unable
>to apply dhcp entry on router"
>
>Another issue can be that the ssh keys are not programmed correctly
>either on the host or the routerVm, due to which the dhcp script fails.
>To check try logging into RVM using ssh keys from the host on which it
>resides (ssh -p 3922 -I /root/.ssh/id_rsa.cloud <rvm link local ip>).
>If this fails, check the configuration table for ssh.publickey and
>ssh.privatekey.
>
>-abhi
>
>>-----Original Message-----
>>From: Evan Miller [mailto:evan.mil...@citrix.com]
>>Sent: Tuesday, July 24, 2012 8:29 AM
>>To: cloudstack-users@incubator.apache.org
>>Subject: RE: Cannot add vm to any host in any cluster - error: "Unable
>>to apply dhcp entry on router"
>>
>>Can someone please answer follow-up questions from early this morning?
>>
>>My CSMS Server is not adding any VMs.
>>I am *completely* blocked by:
>>
>>Unable to apply dhcp entry on router
>>
>>
>>Regards,
>>Evan
>>
>>-----Original Message-----
>>From: Evan Miller [mailto:evan.mil...@citrix.com]
>>Sent: Monday, July 23, 2012 5:48 AM
>>To: cloudstack-users@incubator.apache.org
>>Subject: RE: Cannot add vm to any host in any cluster - error: "Unable
>>to apply dhcp entry on router"
>>
>>How to do all of those router changes from the GUI?
>>If not from the GUI, which API commands should be executed?
>>More details would be helpful.
>>
>>Regards,
>>Evan
>>
>>
>>
>>-----Original Message-----
>>From: Rajesh Battala [mailto:rajesh.batt...@citrix.com]
>>Sent: Sunday, July 22, 2012 7:06 PM
>>To: cloudstack-users@incubator.apache.org
>>Subject: RE: Cannot add vm to any host in any cluster - error: "Unable
>>to apply dhcp entry on router"
>>
>>Evan,
>>Did you check the status of the VR?. Is DHCP service is running in the VR?
>>Please check those services.
>>Sometimes I had observed DHCP service will fail to start on a particular eth.
>>Quick workaround is restart VR , check the DHCP service and then try
>>to create the instances.
>>
>>Thanks
>>Rajesh Battala
>>
>>From: Evan Miller [mailto:evan.mil...@citrix.com]
>>Sent: Sunday, July 22, 2012 12:51 AM
>>To: cloudstack-users@incubator.apache.org
>>Subject: Cannot add vm to any host in any cluster - error: "Unable to
>>apply dhcp entry on router"
>>
>>Running CloudStack Management Server:
>> v3.0.2.1
>>On:
>> [root@cumulus management]# uname -a
>> Linux cumulus.eng.citrite.net 2.6.32-220.el6.x86_64 #1 SMP Tue Dec 6
>>19:48:22 GMT 2011 x86_64 x86_64 x86_64 GNU/Linux
>> [root@cumulus management]#
>>Hypervisor :
>> XenServer v6.02
>>
>>Hi:
>>
>>I can't add any VMs to any hosts in my 3 cluster, two host cloud.
>>
>>In one attempt, the GUI basically says:
>>
>> Unable to create a deployment for VM[User|i-2-7-VM]
>>
>>Here is small part of the attached management log snippet.
>>
>>2012-07-21 10:49:25,568 DEBUG [agent.manager.AgentAttache]
>>(DirectAgent-
>>62:null) Seq 1-564527128: No more commands found
>>2012-07-21 10:49:25,568 INFO [cloud.vm.VirtualMachineManagerImpl]
>>(Job-
>>Executor-1:job-11) Unable to contact resource.
>>com.cloud.exception.ResourceUnavailableException: Resource [Pod:1] is
>>unreachable: Unable to apply dhcp entry on router
>> at
>>com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRule
>s
>>(VirtualNetworkApplianceManagerImpl.java:2802)
>> at
>>com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhc
>p
>>Entry(VirtualNetworkApplianceManagerImpl.java:2089)
>> at
>>com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRo
>ut
>>erElement.java:738)
>> at
>>com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManag
>e
>>rImpl.java:1792)
>> at
>>com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.ja
>v
>>a:1887)
>> at
>>com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineMa
>n
>>agerImpl.java:741)
>> at
>>com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerIm
>p
>>l.java:461)
>> at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerI
>m
>>pl.java:2580)
>> at
>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerI
>m
>>pl.java:2517)
>> at
>>com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java
>>:32
>)
>> at
>>com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:317)
>> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:132)
>> at
>>com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:4
>2
>>7)
>> at
>>java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>> at
>>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.j
>>a
>>va
>>:1110)
>> at
>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.
>>j
>>av
>>a:603)
>> at java.lang.Thread.run(Thread.java:679)
>>
>>How should this be fixed?
>>Can the problem be fixed from the GUI?
>>Please advise.
>>
>>Regards,
>>
>>Evan Miller
>>
>>Citrix Systems. Inc.
>>Desktop and Cloud Engineering Infrastructure
>>4988 Great America Parkway
>>Santa Clara, CA 95054
2012-07-25 17:03:06,246 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-6:null) submit async job-14, details: AsyncJobVO {id:14, userId:
2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 8,
cmd: com.cloud.api.commands.DeployVMCmd, cmdOriginator: null, cmdInfo:
{"id":"8","response":"json","templateId":"2ae4711a-54bd-4df6-a63c-4878ee2aa821","sessionkey":"EiG/su+C413BDRJdIUaa7+9JIr0\u003d","ctxUserId":"2","hypervisor":"XenServer","diskOfferingId":"1e078c12-fed2-4b02-99ca-1574a30d939d","serviceOfferingId":"76ff573a-eba8-48d6-bf91-5dd61532ae46","_":"1343260984899","ctxAccountId":"2","ctxStartEventId":"86","zoneId":"cfd3d564-fcda-4ff7-802f-2b2e862f5ae9"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 207375654364,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2012-07-25 17:03:06,248 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-6:job-14) Executing com.cloud.api.commands.DeployVMCmd for job-14
2012-07-25 17:03:06,315 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) VM state transitted from :Stopped to Starting with
event: StartRequestedvm's original host id: null new host id: null host id
before state transition: null
2012-07-25 17:03:06,315 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-6:job-14) Successfully transitioned to start state for
VM[User|i-2-8-VM] reservation id = f8c8e2ce-5de0-492a-b01f-175d213b7e10
2012-07-25 17:03:06,364 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-6:job-14) Trying to deploy VM, vm has dcId: 1 and podId: null
2012-07-25 17:03:06,365 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-6:job-14) Deploy avoids pods: null, clusters: null, hosts: null
2012-07-25 17:03:06,367 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) DeploymentPlanner allocation algorithm: random
2012-07-25 17:03:06,367 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
2012-07-25 17:03:06,367 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Is ROOT volume READY (pool already allocated)?: No
2012-07-25 17:03:06,367 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Searching all possible resources under this Zone: 1
2012-07-25 17:03:06,368 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Listing clusters in order of aggregate capacity, that
have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2012-07-25 17:03:06,369 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) CPUOverprovisioningFactor considered: 1.0
2012-07-25 17:03:06,379 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Checking resources in Cluster: 3 under Pod: 1
2012-07-25 17:03:06,379 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Calling HostAllocators to find suitable hosts
2012-07-25 17:03:06,379 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:3
2012-07-25 17:03:06,381 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts
to check for allocation: [Host[-5-Routing]]
2012-07-25 17:03:06,383 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Found 1 hosts for allocation
after prioritization: [Host[-5-Routing]]
2012-07-25 17:03:06,383 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Looking for speed=500Mhz,
Ram=512
2012-07-25 17:03:06,385 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Checking if host: 5 has enough
capacity for requested CPU: 500 and requested RAM: 536870912 ,
cpuOverprovisioningFactor: 1.0
2012-07-25 17:03:06,388 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Hosts's actual total CPU: 4256
and CPU after applying overprovisioning: 4256
2012-07-25 17:03:06,388 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Free CPU: 4256 , Requested
CPU: 500
2012-07-25 17:03:06,388 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Free RAM: 3775234176 ,
Requested RAM: 536870912
2012-07-25 17:03:06,388 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Host has enough CPU and RAM
available
2012-07-25 17:03:06,388 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 5, used: 0, reserved: 0, actual total: 4256, total with overprovisioning:
4256; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2012-07-25 17:03:06,388 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 5, used: 0, reserved: 0, total: 3775234176; requested mem:
536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2012-07-25 17:03:06,388 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Found a suitable host, adding
to list: 5
2012-07-25 17:03:06,388 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Host Allocator returning 1
suitable hosts
2012-07-25 17:03:06,390 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Checking suitable pools for volume (Id, Type): (8,ROOT)
2012-07-25 17:03:06,390 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) We need to allocate new storagepool for this volume
2012-07-25 17:03:06,390 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Calling StoragePoolAllocators to find suitable pools
2012-07-25 17:03:06,391 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-6:job-14) Looking for pools in dc: 1 pod:1 cluster:3
2012-07-25 17:03:06,392 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-6:job-14) No storage pools available for allocation, returning
2012-07-25 17:03:06,392 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) No suitable pools found for volume: Vol[8|vm=8|ROOT]
under cluster: 3
2012-07-25 17:03:06,392 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) No suitable pools found
2012-07-25 17:03:06,392 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) No suitable storagePools found under this Cluster: 3
2012-07-25 17:03:06,393 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Checking resources in Cluster: 1 under Pod: 1
2012-07-25 17:03:06,393 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Calling HostAllocators to find suitable hosts
2012-07-25 17:03:06,393 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2012-07-25 17:03:06,395 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts
to check for allocation: [Host[-1-Routing]]
2012-07-25 17:03:06,397 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Found 1 hosts for allocation
after prioritization: [Host[-1-Routing]]
2012-07-25 17:03:06,398 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Looking for speed=500Mhz,
Ram=512
2012-07-25 17:03:06,399 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Checking if host: 1 has enough
capacity for requested CPU: 500 and requested RAM: 536870912 ,
cpuOverprovisioningFactor: 1.0
2012-07-25 17:03:06,402 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Hosts's actual total CPU: 3732
and CPU after applying overprovisioning: 3732
2012-07-25 17:03:06,402 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Free CPU: 2232 , Requested
CPU: 500
2012-07-25 17:03:06,402 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Free RAM: 2298778688 ,
Requested RAM: 536870912
2012-07-25 17:03:06,402 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Host has enough CPU and RAM
available
2012-07-25 17:03:06,402 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 1, used: 1500, reserved: 0, actual total: 3732, total with
overprovisioning: 3732; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2012-07-25 17:03:06,402 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 1, used: 1476395008, reserved: 0, total: 3775173696; requested mem:
536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2012-07-25 17:03:06,402 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Found a suitable host, adding
to list: 1
2012-07-25 17:03:06,402 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Host Allocator returning 1
suitable hosts
2012-07-25 17:03:06,404 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Checking suitable pools for volume (Id, Type): (8,ROOT)
2012-07-25 17:03:06,404 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) We need to allocate new storagepool for this volume
2012-07-25 17:03:06,404 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Calling StoragePoolAllocators to find suitable pools
2012-07-25 17:03:06,404 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-6:job-14) Looking for pools in dc: 1 pod:1 cluster:1
2012-07-25 17:03:06,405 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-6:job-14) FirstFitStoragePoolAllocator has 1 pools to check for
allocation
2012-07-25 17:03:06,405 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-6:job-14) Checking if storage pool is suitable, name: LS_PRIMARY1
,poolId: 200
2012-07-25 17:03:06,405 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-6:job-14) Is localStorageAllocationNeeded? false
2012-07-25 17:03:06,406 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-6:job-14) Is storage pool shared? true
2012-07-25 17:03:06,406 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-6:job-14) Attempting to look for pool 200 for storage, totalSize:
104586543104, usedBytes: 19305857024, usedPct: 0.18459217076141826, disable
threshold: 0.85
2012-07-25 17:03:06,408 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-6:job-14) Attempting to look for pool 200 for storage, maxSize :
209173086208, totalAllocatedSize : 7007691264, askingSize : 21474836480,
allocated disable threshold: 0.85
2012-07-25 17:03:06,408 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-6:job-14) FirstFitStoragePoolAllocator returning 1 suitable
storage pools
2012-07-25 17:03:06,408 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Checking suitable pools for volume (Id, Type):
(9,DATADISK)
2012-07-25 17:03:06,408 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) We need to allocate new storagepool for this volume
2012-07-25 17:03:06,408 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Calling StoragePoolAllocators to find suitable pools
2012-07-25 17:03:06,409 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-6:job-14) Looking for pools in dc: 1 pod:1 cluster:1
2012-07-25 17:03:06,411 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-6:job-14) FirstFitStoragePoolAllocator has 1 pools to check for
allocation
2012-07-25 17:03:06,411 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-6:job-14) Checking if storage pool is suitable, name: LS_PRIMARY1
,poolId: 200
2012-07-25 17:03:06,411 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-6:job-14) Is localStorageAllocationNeeded? false
2012-07-25 17:03:06,411 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-6:job-14) Is storage pool shared? true
2012-07-25 17:03:06,412 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-6:job-14) Attempting to look for pool 200 for storage, totalSize:
104586543104, usedBytes: 19305857024, usedPct: 0.18459217076141826, disable
threshold: 0.85
2012-07-25 17:03:06,414 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-6:job-14) Attempting to look for pool 200 for storage, maxSize :
209173086208, totalAllocatedSize : 7007691264, askingSize : 5368709120,
allocated disable threshold: 0.85
2012-07-25 17:03:06,414 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-6:job-14) FirstFitStoragePoolAllocator returning 1 suitable
storage pools
2012-07-25 17:03:06,414 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Trying to find a potenial host and associated storage
pools from the suitable host/pool lists for this VM
2012-07-25 17:03:06,414 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Checking if host: 1 can access any suitable storage
pool for volume: ROOT
2012-07-25 17:03:06,415 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Host: 1 can access pool: 200
2012-07-25 17:03:06,415 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Checking if host: 1 can access any suitable storage
pool for volume: DATADISK
2012-07-25 17:03:06,416 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Host: 1 can access pool: 200
2012-07-25 17:03:06,416 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Found a potential host id: 1 name: xenserver1-cs and
associated storage pools for this VM
2012-07-25 17:03:06,419 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(8|ROOT-->Pool(200),
Volume(9|DATADISK-->Pool(200))]
2012-07-25 17:03:06,419 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-6:job-14) Deployment found - P0=VM[User|i-2-8-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(8|ROOT-->Pool(200),
Volume(9|DATADISK-->Pool(200))]
2012-07-25 17:03:06,514 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) VM state transitted from :Starting to Starting with
event: OperationRetryvm's original host id: null new host id: 1 host id before
state transition: null
2012-07-25 17:03:06,521 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) Hosts's actual total CPU: 3732 and CPU after applying
overprovisioning: 3732
2012-07-25 17:03:06,521 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) We are allocating VM, increasing the used capacity of
this host:1
2012-07-25 17:03:06,521 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) Current Used CPU: 1500 , Free CPU:2232 ,Requested CPU:
500
2012-07-25 17:03:06,521 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) Current Used RAM: 1476395008 , Free RAM:2298778688
,Requested RAM: 536870912
2012-07-25 17:03:06,521 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) CPU STATS after allocation: for host: 1, old used:
1500, old reserved: 0, actual total: 3732, total with overprovisioning: 3732;
new used:2000, reserved:0; requested cpu:500,alloc_from_last:false
2012-07-25 17:03:06,521 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) RAM STATS after allocation: for host: 1, old used:
1476395008, old reserved: 0, total: 3775173696; new used: 2013265920, reserved:
0; requested mem: 536870912,alloc_from_last:false
2012-07-25 17:03:06,590 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-6:job-14) VM is being started in podId: 1
2012-07-25 17:03:06,593 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-6:job-14) Network id=204 is already implemented
2012-07-25 17:03:06,725 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-6:job-14) Changing active number of nics for network id=204 on 1
2012-07-25 17:03:06,774 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-6:job-14) Asking JuniperSRX to prepare for
Nic[14-8-f8c8e2ce-5de0-492a-b01f-175d213b7e10-10.217.5.215]
2012-07-25 17:03:06,777 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-6:job-14) Asking Netscaler to prepare for
Nic[14-8-f8c8e2ce-5de0-492a-b01f-175d213b7e10-10.217.5.215]
2012-07-25 17:03:06,781 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-6:job-14) Asking F5BigIp to prepare for
Nic[14-8-f8c8e2ce-5de0-492a-b01f-175d213b7e10-10.217.5.215]
2012-07-25 17:03:06,784 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-6:job-14) Asking VirtualRouter to prepare for
Nic[14-8-f8c8e2ce-5de0-492a-b01f-175d213b7e10-10.217.5.215]
2012-07-25 17:03:06,793 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-6:job-14)
Starting a router for Ntwk[204|Guest|5] in
datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$2bf9ba9f@1
2012-07-25 17:03:06,808 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-6:job-14)
Applying dhcp entry in network Ntwk[204|Guest|5]
2012-07-25 17:03:06,823 DEBUG [agent.transport.Request] (Job-Executor-6:job-14)
Seq 1-1019806242: Sending { Cmd , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 100111,
[{"routing.DhcpEntryCommand":{"vmMac":"06:a9:14:00:00:10","vmIpAddress":"10.217.5.215","vmName":"bca8cc1c-9d85-490e-bcb4-75026d563617","defaultRouter":"10.217.5.1","defaultDns":"10.217.5.216","accessDetails":{"router.guest.ip":"10.217.5.216","zone.network.type":"Basic","router.name":"r-5-VM","router.ip":"169.254.1.78"},"wait":0}}]
}
2012-07-25 17:03:06,823 DEBUG [agent.transport.Request] (Job-Executor-6:job-14)
Seq 1-1019806242: Executing: { Cmd , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 100111,
[{"routing.DhcpEntryCommand":{"vmMac":"06:a9:14:00:00:10","vmIpAddress":"10.217.5.215","vmName":"bca8cc1c-9d85-490e-bcb4-75026d563617","defaultRouter":"10.217.5.1","defaultDns":"10.217.5.216","accessDetails":{"router.guest.ip":"10.217.5.216","zone.network.type":"Basic","router.name":"r-5-VM","router.ip":"169.254.1.78"},"wait":0}}]
}
2012-07-25 17:03:18,433 DEBUG [agent.transport.Request] (Job-Executor-6:job-14)
Seq 1-1019806242: Received: { Ans: , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 110, { Answer } }
2012-07-25 17:03:18,435 WARN [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-6:job-14) Cleanup failed due to DhcpEntry failed
2012-07-25 17:03:18,436 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-6:job-14) Unable to contact resource.
2012-07-25 17:03:18,508 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-6:job-14) Cleaning up resources for the vm VM[User|i-2-8-VM] in
Starting state
2012-07-25 17:03:18,510 DEBUG [agent.transport.Request] (Job-Executor-6:job-14)
Seq 1-1019806244: Sending { Cmd , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-8-VM","wait":0}}]
}
2012-07-25 17:03:18,510 DEBUG [agent.transport.Request] (Job-Executor-6:job-14)
Seq 1-1019806244: Executing: { Cmd , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-8-VM","wait":0}}]
}
2012-07-25 17:03:18,632 DEBUG [agent.transport.Request] (Job-Executor-6:job-14)
Seq 1-1019806244: Received: { Ans: , MgmtId: 207375654364, via: 1, Ver: v1,
Flags: 110, { StopAnswer } }
2012-07-25 17:03:18,632 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-6:job-14) Cleanup succeeded. Details VM does not exist
2012-07-25 17:03:18,707 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-6:job-14) Changing active number of nics for network id=204 on -1
2012-07-25 17:03:18,767 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-6:job-14) Successfully cleanued up resources for the vm
VM[User|i-2-8-VM] in Starting state
2012-07-25 17:03:18,769 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) DeploymentPlanner allocation algorithm: random
2012-07-25 17:03:18,769 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
2012-07-25 17:03:18,769 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Is ROOT volume READY (pool already allocated)?: No
2012-07-25 17:03:18,769 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Searching all possible resources under this Zone: 1
2012-07-25 17:03:18,771 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Listing clusters in order of aggregate capacity, that
have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2012-07-25 17:03:18,771 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) CPUOverprovisioningFactor considered: 1.0
2012-07-25 17:03:18,774 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Removing from the clusterId list these clusters from
avoid set: [3]
2012-07-25 17:03:18,779 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Checking resources in Cluster: 1 under Pod: 1
2012-07-25 17:03:18,779 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Calling HostAllocators to find suitable hosts
2012-07-25 17:03:18,779 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2012-07-25 17:03:18,781 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts
to check for allocation: [Host[-1-Routing]]
2012-07-25 17:03:18,783 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Found 1 hosts for allocation
after prioritization: [Host[-1-Routing]]
2012-07-25 17:03:18,783 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Looking for speed=500Mhz,
Ram=512
2012-07-25 17:03:18,783 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Host name: xenserver1-cs,
hostId: 1 is in avoid set, skipping this and trying other available hosts
2012-07-25 17:03:18,783 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-6:job-14 FirstFitRoutingAllocator) Host Allocator returning 0
suitable hosts
2012-07-25 17:03:18,783 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) No suitable hosts found
2012-07-25 17:03:18,783 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) No suitable hosts found under this Cluster: 1
2012-07-25 17:03:18,783 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-6:job-14) Could not find suitable Deployment Destination for this
VM under any clusters, returning.
2012-07-25 17:03:18,885 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) VM state transitted from :Starting to Stopped with
event: OperationFailedvm's original host id: null new host id: null host id
before state transition: 1
2012-07-25 17:03:18,889 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) Hosts's actual total CPU: 3732 and CPU after applying
overprovisioning: 3732
2012-07-25 17:03:18,889 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) release cpu from host: 1, old used: 2000,reserved: 0,
actual total: 3732, total with overprovisioning: 3732; new used:
1500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-07-25 17:03:18,889 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) release mem from host: 1, old used:
2013265920,reserved: 0, total: 3775173696; new used: 1476395008,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2012-07-25 17:03:19,038 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-6:job-14) VM state transitted from :Stopped to Error with event:
OperationFailedToErrorvm's original host id: null new host id: null host id
before state transition: null
2012-07-25 17:03:19,725 INFO [api.commands.DeployVMCmd]
(Job-Executor-6:job-14)
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-8-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2012-07-25 17:03:19,726 WARN [cloud.api.ApiDispatcher] (Job-Executor-6:job-14)
class com.cloud.api.ServerApiException : Unable to create a deployment for
VM[User|i-2-8-VM]
2012-07-25 17:03:19,726 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-6:job-14) Complete async job-14, jobStatus: 2, resultCode: 530,
result: com.cloud.api.response.ExceptionResponse@77e29212
2012-07-25 17:03:21,290 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-22:null) Async job-14 completed
