I'm testing CloudStack to see how it compares to vCloud Director from VMWare, I've successfully installed and a single managment server and configured it to use a previously configured vCenter Cluster, I can see my VMWare hosts and storages, the system VMs are running and when I try to deploy a VM using the CentOS template that comes with CloudStack, a router Virtual appliance is started but I get an error message saying that the vm could not be deployed.

I've checked the logs and saw some error messages about SSH authentication to the router:


2012-02-21 16:53:48,672 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-21:null) Allocating in the DB for vm
2012-02-21 16:53:48,703 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-21:null) Allocating in the DB for vm
2012-02-21 16:53:48,709 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-21:null) Allocating entries for VM: VM[User|i-2-5-VM]
2012-02-21 16:53:48,712 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-21:null) Allocating nics for VM[User|i-2-5-VM]
2012-02-21 16:53:48,732 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-21:null) Allocaing disks for VM[User|i-2-5-VM]
2012-02-21 16:53:48,740 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-21:null) Allocation completed for VM: VM[User|i-2-5-VM]
2012-02-21 16:53:48,746 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-21:null) Successfully allocated DB entry for VM[User|i-2-5-VM]
2012-02-21 16:53:48,785 WARN [network.security.SecurityGroupManagerImpl] (catalina-exec-21:null) User vm 5 is not security group enabled, can't add it to security group
2012-02-21 16:53:48,879 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-21:null) submit async job-5, details: AsyncJobVO {id:5, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 5, cmd: com.cloud.api.commands.DeployVMCmd, cmdOriginator: null, cmdInfo: {"sessionkey":"hIyR0tnhh7ml8KODRH4q+PuqEgI\u003d","ctxUserId":"2","serviceOfferingId":"1","zoneId":"1","response":"json","templateId":"7","id":"5","networkIds":"204","hypervisor":"VMware","_":"1329843211621","ctxAccountId":"2","ctxStartEventId":"20","displayname":"blabla"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 143317480168, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2012-02-21 16:53:48,881 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-1:job-5) Executing com.cloud.api.commands.DeployVMCmd for job-5
2012-02-21 16:53:48,923 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) 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-02-21 16:53:48,924 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-5) Successfully transitioned to start state for VM[User|i-2-5-VM] reservation id = 4110f4b5-1e9d-4575-a0ab-b8d14af89520
2012-02-21 16:53:48,956 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-5) Trying to deploy VM, vm has dcId: 1 and podId: null
2012-02-21 16:53:48,956 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-5) Deploy avoids pods: null, clusters: null, hosts: null
2012-02-21 16:53:48,958 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) In FirstFitPlanner:: plan
2012-02-21 16:53:48,958 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
2012-02-21 16:53:48,958 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Is ROOT volume READY (pool already allocated)?: No
2012-02-21 16:53:48,958 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Searching all possible resources under this Zone: 1
2012-02-21 16:53:48,958 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2012-02-21 16:53:48,959 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) CPUOverprovisioningFactor considered: 1.0
2012-02-21 16:53:48,962 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Applying UserConcentratedPod heuristic for account: 2
2012-02-21 16:53:48,963 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) List of pods to be considered, after applying UserConcentratedPod heuristic: []
2012-02-21 16:53:48,964 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Checking resources in Cluster: 1 under Pod: 1
2012-02-21 16:53:48,964 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Calling HostAllocators to find suitable hosts
2012-02-21 16:53:48,964 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2012-02-21 16:53:48,966 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-1-Routing], Host[-2-Routing]]
2012-02-21 16:53:48,968 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-1-Routing], Host[-2-Routing]]
2012-02-21 16:53:48,968 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
2012-02-21 16:53:48,968 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2012-02-21 16:53:48,969 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Hosts's actual total CPU: 11332 and CPU after applying overprovisioning: 11332
2012-02-21 16:53:48,969 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Free CPU: 9832 , Requested CPU: 500
2012-02-21 16:53:48,969 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Free RAM: 9260265472 , Requested RAM: 536870912
2012-02-21 16:53:48,969 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2012-02-21 16:53:48,969 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 1500, reserved: 0, actual total: 11332, total with overprovisioning: 11332; requested cpu:500,alloc_from_last_host?:false
2012-02-21 16:53:48,969 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 1476395008, reserved: 0, total: 10736660480; requested mem: 536870912,alloc_from_last_host?:false
2012-02-21 16:53:48,969 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2012-02-21 16:53:48,969 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Checking if host: 2 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2012-02-21 16:53:48,971 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Hosts's actual total CPU: 11332 and CPU after applying overprovisioning: 11332
2012-02-21 16:53:48,971 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Free CPU: 11332 , Requested CPU: 500
2012-02-21 16:53:48,971 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Free RAM: 10736660480 , Requested RAM: 536870912
2012-02-21 16:53:48,971 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2012-02-21 16:53:48,971 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 2, used: 0, reserved: 0, actual total: 11332, total with overprovisioning: 11332; requested cpu:500,alloc_from_last_host?:false
2012-02-21 16:53:48,971 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 2, used: 0, reserved: 0, total: 10736660480; requested mem: 536870912,alloc_from_last_host?:false
2012-02-21 16:53:48,971 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Found a suitable host, adding to list: 2
2012-02-21 16:53:48,971 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Host Allocator returning 2 suitable hosts
2012-02-21 16:53:48,972 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Checking suitable pools for volume (Id, Type): (5,ROOT)
2012-02-21 16:53:48,972 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) We need to allocate new storagepool for this volume
2012-02-21 16:53:48,973 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Calling StoragePoolAllocators to find suitable pools
2012-02-21 16:53:48,973 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-1:job-5) Looking for pools in dc: 1 pod:1 cluster:1
2012-02-21 16:53:48,974 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-1:job-5) FirstFitStoragePoolAllocator has 1 pools to check for allocation
2012-02-21 16:53:48,974 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-1:job-5) Checking if storage pool is suitable, name: VMDAta ,poolId: 200
2012-02-21 16:53:48,975 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-1:job-5) Is localStorageAllocationNeeded? false
2012-02-21 16:53:48,975 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-1:job-5) Is storage pool shared? true
2012-02-21 16:53:48,975 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-1:job-5) Attempting to look for pool 200 for storage, totalSize: 643976658944, usedBytes: 59612594176, usedPct: 0.09256949510212589, threshold: 0.85
2012-02-21 16:53:48,984 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-1:job-5) Attempting to look for pool 200 for storage, maxSize : 6.4397666E11, totalSize : 2556472832, askingSize : 2147483648
2012-02-21 16:53:48,984 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-1:job-5) FirstFitStoragePoolAllocator returning 1 suitable storage pools
2012-02-21 16:53:48,984 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2012-02-21 16:53:48,984 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2012-02-21 16:53:48,985 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Host: 1 can access pool: 200
2012-02-21 16:53:48,985 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Found a potential host id: 1 name: 10.39.31.105 and associated storage pools for this VM
2012-02-21 16:53:48,986 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) 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(5|ROOT-->Pool(200))]
2012-02-21 16:53:48,987 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-5) Deployment found - P0=VM[User|i-2-5-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(5|ROOT-->Pool(200))]
2012-02-21 16:53:49,046 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) 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-02-21 16:53:49,049 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) Hosts's actual total CPU: 11332 and CPU after applying overprovisioning: 11332
2012-02-21 16:53:49,049 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) We are allocating VM, increasing the used capacity of this host:1
2012-02-21 16:53:49,049 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) Current Used CPU: 1500 , Free CPU:9832 ,Requested CPU: 500
2012-02-21 16:53:49,049 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) Current Used RAM: 1476395008 , Free RAM:9260265472 ,Requested RAM: 536870912
2012-02-21 16:53:49,049 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) CPU STATS after allocation: for host: 1, old used: 1500, old reserved: 0, actual total: 11332, total with overprovisioning: 11332; new used:2000, reserved:0; requested cpu:500,alloc_from_last:false
2012-02-21 16:53:49,049 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) RAM STATS after allocation: for host: 1, old used: 1476395008, old reserved: 0, total: 10736660480; new used: 2013265920, reserved: 0; requested mem: 536870912,alloc_from_last:false
2012-02-21 16:53:49,076 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-5) VM is being started in podId: 1
2012-02-21 16:53:49,079 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-5) Network id=204 is already implemented
2012-02-21 16:53:49,083 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-5) Changing active number of nics for network id=204 on 1
2012-02-21 16:53:49,112 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-5) Asking ExternalFirewall to prepare for Nic[10-5-null-10.39.40.152]
2012-02-21 16:53:49,112 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-5) Asking ExternalLoadBalancer to prepare for Nic[10-5-null-10.39.40.152]
2012-02-21 16:53:49,112 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-5) Asking DomainRouter to prepare for Nic[10-5-null-10.39.40.152]
2012-02-21 16:53:49,112 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-5) Asking Dhcp to prepare for Nic[10-5-null-10.39.40.152]
2012-02-21 16:53:49,114 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-1:job-5) Starting a dhcp server for Ntwk[204|Guest|7] in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(5|ROOT-->Pool(200))]
2012-02-21 16:53:49,124 DEBUG [agent.transport.Request] (Job-Executor-1:job-5) Seq 1-1793916974: Sending { Cmd , MgmtId: 143317480168, via: 1, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:93:58:00:00:19","vmIpAddress":"10.39.40.152","vmName":"i-2-5-VM","accessDetails":{"router.guest.ip":"10.39.40.150","zone.network.type":"Advanced","router.ip":"10.39.31.153","router.name":"r-4-VM"},"wait":0}},{"routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.39.40.152","vmName":"i-2-5-VM","accessDetails":{"router.guest.ip":"10.39.40.150","zone.network.type":"Advanced","router.ip":"10.39.31.153","router.name":"r-4-VM"},"wait":0}},{"routing.VmDataCommand":{"vmIpAddress":"10.39.40.152","vmName":"i-2-5-VM","accessDetails":{"router.guest.ip":"10.39.40.150","zone.network.type":"Advanced","router.ip":"10.39.31.153","router.name":"r-4-VM"},"wait":0}}] }
2012-02-21 16:53:49,125 DEBUG [agent.transport.Request] (Job-Executor-1:job-5) Seq 1-1793916974: Executing: { Cmd , MgmtId: 143317480168, via: 1, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:93:58:00:00:19","vmIpAddress":"10.39.40.152","vmName":"i-2-5-VM","accessDetails":{"router.guest.ip":"10.39.40.150","zone.network.type":"Advanced","router.ip":"10.39.31.153","router.name":"r-4-VM"},"wait":0}},{"routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.39.40.152","vmName":"i-2-5-VM","accessDetails":{"router.guest.ip":"10.39.40.150","zone.network.type":"Advanced","router.ip":"10.39.31.153","router.name":"r-4-VM"},"wait":0}},{"routing.VmDataCommand":{"vmIpAddress":"10.39.40.152","vmName":"i-2-5-VM","accessDetails":{"router.guest.ip":"10.39.40.150","zone.network.type":"Advanced","router.ip":"10.39.31.153","router.name":"r-4-VM"},"wait":0}}] }
2012-02-21 16:53:49,125 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-38:null) Seq 1-1793916974: Executing request
2012-02-21 16:53:49,126 INFO [vmware.resource.VmwareResource] (DirectAgent-38:10.39.31.105) Executing resource DhcpEntryCommand: {"vmMac":"06:93:58:00:00:19","vmIpAddress":"10.39.40.152","vmName":"i-2-5-VM","accessDetails":{"router.guest.ip":"10.39.40.150","zone.network.type":"Advanced","router.ip":"10.39.31.153","router.name":"r-4-VM"},"wait":0}
2012-02-21 16:53:49,127 DEBUG [vmware.resource.VmwareResource] (DirectAgent-38:10.39.31.105) Run command on domR 10.39.31.153, /root/edithosts.sh 06:93:58:00:00:19 10.39.40.152 i-2-5-VM
2012-02-21 16:53:49,127 DEBUG [vmware.resource.VmwareResource] (DirectAgent-38:10.39.31.105) Use router's private IP for SSH control. IP : 10.39.31.153
2012-02-21 16:53:49,345 ERROR [vmware.resource.SshHelper] (DirectAgent-38:10.39.31.105) Failed to authentication SSH user root on host 10.39.31.153
2012-02-21 16:53:49,346 ERROR [vmware.resource.VmwareResource] (DirectAgent-38:10.39.31.105) DhcpEntryCommand failed due to Exception: java.lang.Exception
Message: Failed to authentication SSH user root on host 10.39.31.153

2012-02-21 16:53:49,347 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-38:null) Seq 1-1793916974: Cancelling because one of the answers is false and it is stop on error.
2012-02-21 16:53:49,347 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-38:null) Seq 1-1793916974: Response Received:
2012-02-21 16:53:49,347 DEBUG [agent.transport.Request] (DirectAgent-38:null) Seq 1-1793916974: Processing: { Ans: , MgmtId: 143317480168, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"DhcpEntryCommand failed due to Exception: java.lang.Exception\nMessage: Failed to authentication SSH user root on host 10.39.31.153\n","wait":0}}] }
2012-02-21 16:53:49,347 WARN [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-38:null) Cleanup failed due to DhcpEntryCommand failed due to Exception: java.lang.Exception
Message: Failed to authentication SSH user root on host 10.39.31.153
for com.cloud.agent.api.Answer
2012-02-21 16:53:49,347 DEBUG [agent.transport.Request] (Job-Executor-1:job-5) Seq 1-1793916974: Received: { Ans: , MgmtId: 143317480168, via: 1, Ver: v1, Flags: 110, { Answer } }
2012-02-21 16:53:49,347 DEBUG [agent.manager.AgentAttache] (DirectAgent-38:null) Seq 1-1793916974: No more commands found
2012-02-21 16:53:49,347 WARN [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-5) Cleanup failed due to DhcpEntryCommand failed due to Exception: java.lang.Exception
Message: Failed to authentication SSH user root on host 10.39.31.153
for com.cloud.agent.api.Answer
2012-02-21 16:53:49,348 ERROR [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-1:job-5) Unable to set dhcp entry for VM[User|i-2-5-VM] on domR: r-4-VM due to DhcpEntryCommand failed due to Exception: java.lang.Exception
Message: Failed to authentication SSH user root on host 10.39.31.153

2012-02-21 16:53:49,348 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-5) Unable to contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is unreachable: Unable to set dhcp entry for VM[User|i-2-5-VM] due to DhcpEntryCommand failed due to Exception: java.lang.Exception
Message: Failed to authentication SSH user root on host 10.39.31.153

at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.addVirtualMachineIntoNetwork(VirtualNetworkApplianceManagerImpl.java:1992)
at com.cloud.network.element.DhcpElement.prepare(DhcpElement.java:137)
at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:1314)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:743)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2722)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2659)
at com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:37)
at com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:323)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:131)
at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:430)
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.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:636)
2012-02-21 16:53:49,382 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-5) Cleaning up resources for the vm VM[User|i-2-5-VM] in Starting state
2012-02-21 16:53:49,384 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-1:job-5) Changing active number of nics for network id=204 on -1
2012-02-21 16:53:49,406 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-1:job-5) Successfully cleanued up resources for the vm VM[User|i-2-5-VM] in Starting state
2012-02-21 16:53:49,407 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) In FirstFitPlanner:: plan
2012-02-21 16:53:49,407 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
2012-02-21 16:53:49,407 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Is ROOT volume READY (pool already allocated)?: No
2012-02-21 16:53:49,407 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Searching all possible resources under this Zone: 1
2012-02-21 16:53:49,407 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2012-02-21 16:53:49,407 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) CPUOverprovisioningFactor considered: 1.0
2012-02-21 16:53:49,410 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Applying UserConcentratedPod heuristic for account: 2
2012-02-21 16:53:49,410 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) List of pods to be considered, after applying UserConcentratedPod heuristic: []
2012-02-21 16:53:49,410 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Checking resources in Cluster: 1 under Pod: 1
2012-02-21 16:53:49,411 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Calling HostAllocators to find suitable hosts
2012-02-21 16:53:49,411 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2012-02-21 16:53:49,412 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-2-Routing], Host[-1-Routing]]
2012-02-21 16:53:49,413 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-2-Routing], Host[-1-Routing]]
2012-02-21 16:53:49,413 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
2012-02-21 16:53:49,413 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Host name: 10.39.31.106, hostId: 2 is in avoid set, skipping this and trying other available hosts
2012-02-21 16:53:49,413 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Host name: 10.39.31.105, hostId: 1 is in avoid set, skipping this and trying other available hosts
2012-02-21 16:53:49,413 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-1:job-5 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2012-02-21 16:53:49,413 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) No suitable hosts found
2012-02-21 16:53:49,413 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) No suitable hosts found under this Cluster: 1
2012-02-21 16:53:49,413 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-1:job-5) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2012-02-21 16:53:49,460 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) 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-02-21 16:53:49,462 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) Hosts's actual total CPU: 11332 and CPU after applying overprovisioning: 11332
2012-02-21 16:53:49,462 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) release cpu from host: 1, old used: 2000,reserved: 0, actual total: 11332, total with overprovisioning: 11332; new used: 1500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-02-21 16:53:49,462 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) release mem from host: 1, old used: 2013265920,reserved: 0, total: 10736660480; new used: 1476395008,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-02-21 16:53:49,533 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-1:job-5) 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-02-21 16:53:49,653 INFO [api.commands.DeployVMCmd] (Job-Executor-1:job-5) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-5-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2012-02-21 16:53:49,654 WARN [cloud.api.ApiDispatcher] (Job-Executor-1:job-5) class com.cloud.api.ServerApiException : Unable to create a deployment for VM[User|i-2-5-VM]
2012-02-21 16:53:49,654 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-1:job-5) Complete async job-5, jobStatus: 2, resultCode: 530, result: com.cloud.api.response.ExceptionResponse@744c2cdd
2012-02-21 16:53:55,660 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-02-21 16:53:55,742 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-02-21 16:53:56,077 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-02-21 16:53:58,902 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-22:null) Async job-5 completed
2012-02-21 16:53:59,402 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) Ping from 4
2012-02-21 16:53:59,963 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) Ping from 5
2012-02-21 16:54:10,568 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2012-02-21 16:54:15,392 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-96:null) Ping from 1
2012-02-21 16:54:25,660 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-02-21 16:54:25,740 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-02-21 16:54:26,076 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-02-21 16:54:32,784 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2012-02-21 16:54:32,789 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-109:null) Seq 1-1793916975: Executing request
2012-02-21 16:54:33,262 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-109:null) Seq 1-1793916975: Response Received:
2012-02-21 16:54:33,262 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-1793916975: Received: { Ans: , MgmtId: 143317480168, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-02-21 16:54:33,262 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-109:null) Cleanup succeeded. Details null
2012-02-21 16:54:33,262 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-1:null) Cleanup succeeded. Details null
2012-02-21 16:54:33,266 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-51:null) Seq 2-728236063: Executing request
2012-02-21 16:54:33,715 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-51:null) Seq 2-728236063: Response Received:
2012-02-21 16:54:33,715 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-51:null) Cleanup succeeded. Details null
2012-02-21 16:54:33,715 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-728236063: Received: { Ans: , MgmtId: 143317480168, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-02-21 16:54:33,715 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-1:null) Cleanup succeeded. Details null
2012-02-21 16:54:35,592 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2012-02-21 16:54:35,653 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-7:null) Cleanup succeeded. Details null
2012-02-21 16:54:35,653 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 4-46137376: Received: { Ans: , MgmtId: 143317480168, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-02-21 16:54:35,653 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-1:null) Cleanup succeeded. Details null
2012-02-21 16:54:35,656 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-129:null) Seq 2-728236064: Executing request
2012-02-21 16:54:36,527 DEBUG [vmware.resource.VmwareResource] (DirectAgent-129:10.39.31.106) Datastore summary info, storageId: 047f4302-ca78-3baa-8e59-0adbdd320586, localPath: /WIT-DC/VMData, poolType: VMFS, capacity: 643976658944, free: 584364064768, used: 59612594176

I've done some extra debugging.

Used nmap to find where ssh was running and tryed:

# ssh -p3922 This e-mail address is being protected from spambots. You need JavaScript enabled to view it
Permission denied (publickey).

there seams to ave been some problem with the ssh keys generation.
Is there a way for me to fix this?

You need to pass it the key.


ssh This e-mail address is being protected from spambots. You need JavaScript enabled to view it -p 3922 -i /root/ssh/id_rsa.cloud (you'll have to find the id_rsa.cloud somewhere on hypervisor or on the management server)

This may only work from certain hosts or use the link local ip from the hypervisor.

I've found the rsa file and tried:

ssh -i /usr/lib64/cloud/agent/scripts/vm/systemvm/id_rsa.cloud -p 3922 This e-mail address is being protected from spambots. You need JavaScript enabled to view it

first I got:


@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
@ WARNING: UNPROTECTED PRIVATE KEY FILE! @
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
Permissions 0644 for '/usr/lib64/cloud/agent/scripts/vm/systemvm/id_rsa.cloud' are too open.
It is recommended that your private key files are NOT accessible by others.
This private key will be ignored.
bad permissions: ignore key: /usr/lib64/cloud/agent/scripts/vm/systemvm/id_rsa.cloud
Permission denied (publickey).


then I've modified the file permissions and got:

# ssh -i /usr/lib64/cloud/agent/scripts/vm/systemvm/id_rsa.cloud -p 3922 This e-mail address is being protected from spambots. You need JavaScript enabled to view it
Permission denied (publickey).

Could this be the issue?

DEBUG [cloud.server.ConfigurationServerImpl] (main:null) Files /var/lib/cloud/management/.ssh/id_rsa and /usr/lib64/cloud/agent/scripts/vm/systemvm/id_rsa.cloud differ

For XenServer or KVM: # ssh –i /root/.ssh/id_rsa.cloud –p 3922 root@link-local-ip
For VMware: # ssh -i /var/lib/cloud/management/.ssh/id_rsa.cloud –p 3922 root@private-ip

You must execute this command from hosts where you have hypervisors