All,

I have finally successfully configured Cloud Platform trial version and ready to create VM to build a test offering however when I try to create a VM as root or as a user I'm getting the following message: Unable to create a deployment for VM

Please see below some log messages from the Management Server. I need some help please

2013-12-27 18:26:30,534 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null) ===START===  192.168.168.250 -- GET  command=listNetworks&trafficType=Guest&zoneId=00fac1a6-c3a5-4c53-a3ff-d9930e0c46bf&response=json&sessionkey=AelDWfiHsmTfwtNjtk5BRrkv5As%3D&_=1388186780711
2013-12-27 18:26:30,559 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null) ===END===  192.168.168.250 -- GET  command=listNetworks&trafficType=Guest&zoneId=00fac1a6-c3a5-4c53-a3ff-d9930e0c46bf&response=json&sessionkey=AelDWfiHsmTfwtNjtk5BRrkv5As%3D&_=1388186780711
2013-12-27 18:26:30,741 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===START===  192.168.168.250 -- GET  command=listSecurityGroups&response=json&sessionkey=AelDWfiHsmTfwtNjtk5BRrkv5As%3D&domainid=11f9580c-b37e-4718-acd9-d065505cdcbb&account=cwilliams391&_=1388186780915
2013-12-27 18:26:30,760 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-24:null) Access granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] to Domain:3/Net-IT/ by AffinityGroupAccessChecker_EnhancerByCloudStack_6bdbded2
2013-12-27 18:26:30,762 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-24:null) Access to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:30,767 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===END===  192.168.168.250 -- GET  command=listSecurityGroups&response=json&sessionkey=AelDWfiHsmTfwtNjtk5BRrkv5As%3D&domainid=11f9580c-b37e-4718-acd9-d065505cdcbb&account=cwilliams391&_=1388186780915
2013-12-27 18:26:34,579 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-2098: Processing Seq 3-2098:  { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2013-12-27 18:26:34,641 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-2098: Sending Seq 3-2098:  { Ans: , MgmtId: 132129486677709, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-27 18:26:38,841 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-27 18:26:39,240 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-27 18:26:39,580 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-2099: Processing Seq 3-2099:  { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2013-12-27 18:26:39,702 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
2013-12-27 18:26:39,704 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-27 18:26:39,707 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-2099: Sending Seq 3-2099:  { Ans: , MgmtId: 132129486677709, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-27 18:26:39,733 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
2013-12-27 18:26:39,734 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-27 18:26:43,105 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===START===  192.168.168.250 -- GET  command=deployVirtualMachine&zoneId=00fac1a6-c3a5-4c53-a3ff-d9930e0c46bf&templateId=6915198c-6f19-11e3-96c8-8a8910b55ba7&hypervisor=XenServer&serviceOfferingId=127bbf46-af57-4de9-a08f-b6411e5a4697&diskOfferingId=557e5531-d5ff-400e-b699-d8a356899e1b&securitygroupids=909108f0-3735-4cb4-bed5-09414f20096c&displayname=carl&name=carl&response=json&sessionkey=AelDWfiHsmTfwtNjtk5BRrkv5As%3D&_=1388186793283
2013-12-27 18:26:43,114 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-11:null) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2013-12-27 18:26:43,118 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-11:null) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2013-12-27 18:26:43,121 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-11:null) InfrastructureEntity name is:com.cloud.offering.DiskOffering
2013-12-27 18:26:43,123 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-11:null) ControlledEntity name is:com.cloud.network.security.SecurityGroup
2013-12-27 18:26:43,125 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-11:null) Access to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,127 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-11:null) Access to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,128 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-11:null) Access to com.cloud.network.security.SecurityGroupVO$$EnhancerByCGLIB$$6edf5bbc@43e651d3 granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,131 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-11:null) Access to Tmpl[5-VHD-centos56-x86_64-xen granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,132 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-11:null) Access to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,138 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-11:null) Access to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,164 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-11:null) Access to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,164 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-11:null) Access to com.cloud.network.security.SecurityGroupVO$$EnhancerByCGLIB$$6edf5bbc@42dfab8e granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,306 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-11:null) Allocating in the DB for vm
2013-12-27 18:26:43,323 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-11:null) Allocating entries for VM: VM[User|carl]
2013-12-27 18:26:43,324 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-11:null) Allocating nics for VM[User|carl]
2013-12-27 18:26:43,324 DEBUG [cloud.network.NetworkManagerImpl] (catalina-exec-11:null) Allocating nic for vm VM[User|carl] in network Ntwk[204|Guest|6] with requested profile NicProfile[0-0-null-null-null
2013-12-27 18:26:43,333 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-11:null) Allocating disks for VM[User|carl]
2013-12-27 18:26:43,352 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-11:null) Allocation completed for VM: VM[User|carl]
2013-12-27 18:26:43,352 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-11:null) Successfully allocated DB entry for VM[User|carl]
2013-12-27 18:26:43,724 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-11:null) submit async job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ], details: AsyncJobVO {id:35, userId: 7, accountId: 7, sessionKey: null, instanceType: VirtualMachine, instanceId: 16, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator: null, cmdInfo: {"sessionkey":"AelDWfiHsmTfwtNjtk5BRrkv5As\u003d","cmdEventType":"VM.CREATE","ctxUserId":"7","serviceOfferingId":"127bbf46-af57-4de9-a08f-b6411e5a4697","httpmethod":"GET","securitygroupids":"909108f0-3735-4cb4-bed5-09414f20096c","zoneId":"00fac1a6-c3a5-4c53-a3ff-d9930e0c46bf","id":"16","templateId":"6915198c-6f19-11e3-96c8-8a8910b55ba7","response":"json","hypervisor":"XenServer","name":"carl","diskOfferingId":"557e5531-d5ff-400e-b699-d8a356899e1b","_":"1388186793283","ctxAccountId":"7","ctxStartEventId":"164","displayname":"carl"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 132129486677709, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-12-27 18:26:43,725 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]
2013-12-27 18:26:43,727 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===END===  192.168.168.250 -- GET  command=deployVirtualMachine&zoneId=00fac1a6-c3a5-4c53-a3ff-d9930e0c46bf&templateId=6915198c-6f19-11e3-96c8-8a8910b55ba7&hypervisor=XenServer&serviceOfferingId=127bbf46-af57-4de9-a08f-b6411e5a4697&diskOfferingId=557e5531-d5ff-400e-b699-d8a356899e1b&securitygroupids=909108f0-3735-4cb4-bed5-09414f20096c&displayname=carl&name=carl&response=json&sessionkey=AelDWfiHsmTfwtNjtk5BRrkv5As%3D&_=1388186793283
2013-12-27 18:26:43,730 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2013-12-27 18:26:43,732 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2013-12-27 18:26:43,734 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) InfrastructureEntity name is:com.cloud.offering.DiskOffering
2013-12-27 18:26:43,736 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) ControlledEntity name is:com.cloud.network.security.SecurityGroup
2013-12-27 18:26:43,738 DEBUG [cloud.user.AccountManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Access to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,740 DEBUG [cloud.user.AccountManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Access to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,741 DEBUG [cloud.user.AccountManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Access to com.cloud.network.security.SecurityGroupVO$$EnhancerByCGLIB$$6edf5bbc@59f4de28 granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,743 DEBUG [cloud.user.AccountManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Access to Tmpl[5-VHD-centos56-x86_64-xen granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,805 DEBUG [cloud.user.AccountManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Access to VM[User|carl] granted to Acct[0dc1060b-a112-46d8-816f-d963b0435abc-cwilliams391] by DomainChecker_EnhancerByCloudStack_851647cd
2013-12-27 18:26:43,846 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Deploy avoids pods: [], clusters: [], hosts: [2]
2013-12-27 18:26:43,847 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_7c41c31e@5c1130f8
2013-12-27 18:26:43,847 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
2013-12-27 18:26:43,847 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Is ROOT volume READY (pool already allocated)?: No
2013-12-27 18:26:43,847 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Searching all possible resources under this Zone: 1
2013-12-27 18:26:43,848 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2013-12-27 18:26:43,850 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Removing from the clusterId list these clusters from avoid set: []
2013-12-27 18:26:43,855 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking resources in Cluster: 1 under Pod: 1
2013-12-27 18:26:43,856 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
2013-12-27 18:26:43,859 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-2-Routing], Host[-1-Routing]]
2013-12-27 18:26:43,861 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-2-Routing], Host[-1-Routing]]
2013-12-27 18:26:43,861 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2013-12-27 18:26:43,861 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Host name: xenserver-PHL1, hostId: 2 is in avoid set, skipping this and trying other available hosts
2013-12-27 18:26:43,865 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2013-12-27 18:26:43,866 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Hosts's actual total CPU: 44800 and CPU after applying overprovisioning: 44800
2013-12-27 18:26:43,866 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Free CPU: 44300 , Requested CPU: 1000
2013-12-27 18:26:43,866 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Free RAM: 130644566016 , Requested RAM: 1073741824
2013-12-27 18:26:43,866 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-12-27 18:26:43,866 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 500, reserved: 0, actual total: 44800, total with overprovisioning: 44800; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-27 18:26:43,866 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 268435456, reserved: 0, total: 130913001472; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-27 18:26:43,866 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2013-12-27 18:26:43,866 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2013-12-27 18:26:43,868 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking suitable pools for volume (Id, Type): (26,ROOT)
2013-12-27 18:26:43,868 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) We need to allocate new storagepool for this volume
2013-12-27 18:26:43,868 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Calling StoragePoolAllocators to find suitable pools
2013-12-27 18:26:43,869 DEBUG [storage.allocator.LocalStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2013-12-27 18:26:43,869 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) ClusterScopeStoragePoolAllocator looking for storage pool
2013-12-27 18:26:43,869 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Looking for pools in dc: 1  pod:1  cluster:1
2013-12-27 18:26:43,872 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking if storage pool is suitable, name: null ,poolId: 3
2013-12-27 18:26:43,874 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool 3 for storage, totalSize: 48769794048, usedBytes: 6404702208, usedPct: 0.13132518463572743, disable threshold: 0.85
2013-12-27 18:26:43,883 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool: 3 for volume allocation [Vol[26|vm=16|ROOT]], maxSize : 97539588096, totalAllocatedSize : 4194304000, askingSize : 21474836480, allocated disable threshold: 0.85
2013-12-27 18:26:43,883 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2013-12-27 18:26:43,883 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking suitable pools for volume (Id, Type): (27,DATADISK)
2013-12-27 18:26:43,883 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) We need to allocate new storagepool for this volume
2013-12-27 18:26:43,884 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Calling StoragePoolAllocators to find suitable pools
2013-12-27 18:26:43,884 DEBUG [storage.allocator.LocalStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2013-12-27 18:26:43,884 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) ClusterScopeStoragePoolAllocator looking for storage pool
2013-12-27 18:26:43,884 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Looking for pools in dc: 1  pod:1  cluster:1
2013-12-27 18:26:43,886 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking if storage pool is suitable, name: null ,poolId: 3
2013-12-27 18:26:43,889 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool 3 for storage, totalSize: 48769794048, usedBytes: 6404702208, usedPct: 0.13132518463572743, disable threshold: 0.85
2013-12-27 18:26:43,894 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool: 3 for volume allocation [Vol[27|vm=16|DATADISK]], maxSize : 97539588096, totalAllocatedSize : 4194304000, askingSize : 21474836480, allocated disable threshold: 0.85
2013-12-27 18:26:43,895 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2013-12-27 18:26:43,895 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-12-27 18:26:43,895 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2013-12-27 18:26:43,895 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Host: 1 can access pool: 3
2013-12-27 18:26:43,897 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool 3 for storage, totalSize: 48769794048, usedBytes: 6404702208, usedPct: 0.13132518463572743, disable threshold: 0.85
2013-12-27 18:26:43,905 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool: 3 for volume allocation [Vol[26|vm=16|ROOT]], maxSize : 97539588096, totalAllocatedSize : 4194304000, askingSize : 21474836480, allocated disable threshold: 0.85
2013-12-27 18:26:43,905 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking if host: 1 can access any suitable storage pool for volume: DATADISK
2013-12-27 18:26:43,906 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Host: 1 can access pool: 3
2013-12-27 18:26:43,907 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool 3 for storage, totalSize: 48769794048, usedBytes: 6404702208, usedPct: 0.13132518463572743, disable threshold: 0.85
2013-12-27 18:26:43,913 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool: 3 for volume allocation [Vol[27|vm=16|DATADISK]], maxSize : 97539588096, totalAllocatedSize : 4194304000, askingSize : 21474836480, allocated disable threshold: 0.85
2013-12-27 18:26:43,913 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Found a potential host id: 1 name: xenserver-PHL2 and associated storage pools for this VM
2013-12-27 18:26:43,914 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) 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(27|DATADISK-->Pool(3), Volume(26|ROOT-->Pool(3))]
2013-12-27 18:26:43,981 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) 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
2013-12-27 18:26:43,981 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Successfully transitioned to start state for VM[User|carl] reservation id = c156fe25-8658-4782-a3b9-4d9138b80414
2013-12-27 18:26:44,033 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Trying to deploy VM, vm has dcId: 1 and podId: null
2013-12-27 18:26:44,033 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null
2013-12-27 18:26:44,033 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Deploy avoids pods: null, clusters: null, hosts: null
2013-12-27 18:26:44,042 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Deploy avoids pods: [], clusters: [], hosts: [2]
2013-12-27 18:26:44,042 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_7c41c31e@5c1130f8
2013-12-27 18:26:44,042 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
2013-12-27 18:26:44,042 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Is ROOT volume READY (pool already allocated)?: No
2013-12-27 18:26:44,042 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2013-12-27 18:26:44,043 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2013-12-27 18:26:44,044 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking suitable pools for volume (Id, Type): (26,ROOT)
2013-12-27 18:26:44,044 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) We need to allocate new storagepool for this volume
2013-12-27 18:26:44,045 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Calling StoragePoolAllocators to find suitable pools
2013-12-27 18:26:44,046 DEBUG [storage.allocator.LocalStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2013-12-27 18:26:44,046 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) ClusterScopeStoragePoolAllocator looking for storage pool
2013-12-27 18:26:44,046 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Looking for pools in dc: 1  pod:1  cluster:1
2013-12-27 18:26:44,049 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking if storage pool is suitable, name: null ,poolId: 3
2013-12-27 18:26:44,051 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool 3 for storage, totalSize: 48769794048, usedBytes: 6404702208, usedPct: 0.13132518463572743, disable threshold: 0.85
2013-12-27 18:26:44,060 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool: 3 for volume allocation [Vol[26|vm=16|ROOT]], maxSize : 97539588096, totalAllocatedSize : 4194304000, askingSize : 21474836480, allocated disable threshold: 0.85
2013-12-27 18:26:44,060 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2013-12-27 18:26:44,060 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking suitable pools for volume (Id, Type): (27,DATADISK)
2013-12-27 18:26:44,060 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) We need to allocate new storagepool for this volume
2013-12-27 18:26:44,060 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Calling StoragePoolAllocators to find suitable pools
2013-12-27 18:26:44,060 DEBUG [storage.allocator.LocalStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2013-12-27 18:26:44,060 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) ClusterScopeStoragePoolAllocator looking for storage pool
2013-12-27 18:26:44,060 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Looking for pools in dc: 1  pod:1  cluster:1
2013-12-27 18:26:44,063 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking if storage pool is suitable, name: null ,poolId: 3
2013-12-27 18:26:44,065 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool 3 for storage, totalSize: 48769794048, usedBytes: 6404702208, usedPct: 0.13132518463572743, disable threshold: 0.85
2013-12-27 18:26:44,071 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool: 3 for volume allocation [Vol[27|vm=16|DATADISK]], maxSize : 97539588096, totalAllocatedSize : 4194304000, askingSize : 21474836480, allocated disable threshold: 0.85
2013-12-27 18:26:44,071 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2013-12-27 18:26:44,071 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-12-27 18:26:44,071 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2013-12-27 18:26:44,072 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Host: 1 can access pool: 3
2013-12-27 18:26:44,073 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool 3 for storage, totalSize: 48769794048, usedBytes: 6404702208, usedPct: 0.13132518463572743, disable threshold: 0.85
2013-12-27 18:26:44,082 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool: 3 for volume allocation [Vol[26|vm=16|ROOT]], maxSize : 97539588096, totalAllocatedSize : 4194304000, askingSize : 21474836480, allocated disable threshold: 0.85
2013-12-27 18:26:44,082 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking if host: 1 can access any suitable storage pool for volume: DATADISK
2013-12-27 18:26:44,082 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Host: 1 can access pool: 3
2013-12-27 18:26:44,083 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool 3 for storage, totalSize: 48769794048, usedBytes: 6404702208, usedPct: 0.13132518463572743, disable threshold: 0.85
2013-12-27 18:26:44,089 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Checking pool: 3 for volume allocation [Vol[27|vm=16|DATADISK]], maxSize : 97539588096, totalAllocatedSize : 4194304000, askingSize : 21474836480, allocated disable threshold: 0.85
2013-12-27 18:26:44,090 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Found a potential host id: 1 name: xenserver-PHL2 and associated storage pools for this VM
2013-12-27 18:26:44,090 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-12-27 18:26:44,090 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) 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(27|DATADISK-->Pool(3), Volume(26|ROOT-->Pool(3))]
2013-12-27 18:26:44,090 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Deployment found  - P0=VM[User|carl], 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(27|DATADISK-->Pool(3), Volume(26|ROOT-->Pool(3))]
2013-12-27 18:26:44,154 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 4-1417543939: Received:  { Ans: , MgmtId: 132129486677709, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-27 18:26:44,160 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-182:null) Seq 1-327090720: Executing request
2013-12-27 18:26:44,165 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) 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
2013-12-27 18:26:44,174 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Hosts's actual total CPU: 44800 and CPU after applying overprovisioning: 44800
2013-12-27 18:26:44,174 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) We are allocating VM, increasing the used capacity of this host:1
2013-12-27 18:26:44,174 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Current Used CPU: 500 , Free CPU:44300 ,Requested CPU: 1000
2013-12-27 18:26:44,174 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Current Used RAM: 268435456 , Free RAM:130644566016 ,Requested RAM: 1073741824
2013-12-27 18:26:44,174 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) CPU STATS after allocation: for host: 1, old used: 500, old reserved: 0, actual total: 44800, total with overprovisioning: 44800; new used:1500, reserved:0; requested cpu:1000,alloc_from_last:false
2013-12-27 18:26:44,174 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) RAM STATS after allocation: for host: 1, old used: 268435456, old reserved: 0, total: 130913001472; new used: 1342177280, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2013-12-27 18:26:44,266 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) VM is being created in podId: 1
2013-12-27 18:26:44,274 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Network id=204 is already implemented
2013-12-27 18:26:44,344 DEBUG [db.Transaction.Transaction] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Rolling back the transaction: Time = 7 Name =  -AsyncJobManagerImpl$1.run:494-Executors$RunnableAdapter.call:471-FutureTask.run:262-ThreadPoolExecutor.runWorker:1145-ThreadPoolExecutor$Worker.run:615-Thread.run:744; called by -Transaction.rollback:897-Transaction.removeUpTo:840-Transaction.close:664-TransactionContextBuilder.interceptException:63-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:133-NetworkManagerImpl.assignPublicIpAddress:376-DirectPodBasedNetworkGuru.getIp:186-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-DirectPodBasedNetworkGuru.reserve:153-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-NetworkManagerImpl.prepareNic:2166-NetworkManagerImpl.prepare:2136
2013-12-27 18:26:44,344 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Insufficient capacity
com.cloud.exception.InsufficientAddressCapacityException: Insufficient address capacityScope=interface com.cloud.dc.Pod; id=1
        at com.cloud.network.NetworkManagerImpl.fetchNewPublicIp(NetworkManagerImpl.java:472)
        at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
        at com.cloud.network.NetworkManagerImpl.assignPublicIpAddress(NetworkManagerImpl.java:376)
        at com.cloud.network.guru.DirectPodBasedNetworkGuru.getIp(DirectPodBasedNetworkGuru.java:186)
        at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
        at com.cloud.network.guru.DirectPodBasedNetworkGuru.reserve(DirectPodBasedNetworkGuru.java:153)
        at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
        at com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2166)
        at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2136)
        at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:886)
        at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
        at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
        at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3442)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3002)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2988)
        at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
        at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
        at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
        at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)
2013-12-27 18:26:44,401 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Cleaning up resources for the vm VM[User|carl] in Starting state
2013-12-27 18:26:44,403 DEBUG [agent.transport.Request] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Seq 1-327090721: Sending  { Cmd , MgmtId: 132129486677709, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-7-16-VM","wait":0}}] }
2013-12-27 18:26:44,403 DEBUG [agent.transport.Request] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Seq 1-327090721: Executing:  { Cmd , MgmtId: 132129486677709, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-7-16-VM","wait":0}}] }
2013-12-27 18:26:44,403 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-185:null) Seq 1-327090721: Executing request
2013-12-27 18:26:44,422 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-182:null) Seq 1-327090720: Response Received:
2013-12-27 18:26:44,422 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-327090720: Received:  { Ans: , MgmtId: 132129486677709, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-27 18:26:44,484 INFO  [xen.resource.CitrixResourceBase] (DirectAgent-185:null) VM does not exist on XenServerabf38ca8-e00f-40e6-89da-0e4794ee75b9
2013-12-27 18:26:44,484 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-185:null) Seq 1-327090721: Response Received:
2013-12-27 18:26:44,484 DEBUG [agent.transport.Request] (DirectAgent-185:null) Seq 1-327090721: Processing:  { Ans: , MgmtId: 132129486677709, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM does not exist","wait":0}}] }
2013-12-27 18:26:44,484 DEBUG [agent.manager.AgentAttache] (DirectAgent-185:null) Seq 1-327090721: No more commands found
2013-12-27 18:26:44,484 DEBUG [agent.transport.Request] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Seq 1-327090721: Received:  { Ans: , MgmtId: 132129486677709, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-12-27 18:26:44,548 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Asking VirtualRouter to release Nic[21-16-c156fe25-8658-4782-a3b9-4d9138b80414-null]
2013-12-27 18:26:44,551 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Asking SecurityGroupProvider to release Nic[21-16-c156fe25-8658-4782-a3b9-4d9138b80414-null]
2013-12-27 18:26:44,551 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Successfully released network resources for the vm VM[User|carl]
2013-12-27 18:26:44,551 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Successfully cleanued up resources for the vm VM[User|carl] in Starting state
2013-12-27 18:26:44,558 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Deploy avoids pods: [1], clusters: [], hosts: [1, 2]
2013-12-27 18:26:44,558 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_7c41c31e@5c1130f8
2013-12-27 18:26:44,558 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
2013-12-27 18:26:44,558 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Is ROOT volume READY (pool already allocated)?: No
2013-12-27 18:26:44,558 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2013-12-27 18:26:44,560 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) The specified host is in avoid set
2013-12-27 18:26:44,560 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Cannnot deploy to specified host, returning.
2013-12-27 18:26:44,658 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) 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
2013-12-27 18:26:44,666 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Hosts's actual total CPU: 44800 and CPU after applying overprovisioning: 44800
2013-12-27 18:26:44,666 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Hosts's actual total RAM: 130913004096 and RAM after applying overprovisioning: 130913001472
2013-12-27 18:26:44,666 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) release cpu from host: 1, old used: 1500,reserved: 0, actual total: 44800, total with overprovisioning: 44800; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-27 18:26:44,666 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) release mem from host: 1, old used: 1342177280,reserved: 0, total: 130913001472; new used: 268435456,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-27 18:26:44,891 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) 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
2013-12-27 18:26:44,891 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Successfully transitioned to start state for VM[User|carl] reservation id = a8378d70-f35e-47f2-94e8-fcbf1c963565
2013-12-27 18:26:44,941 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Trying to deploy VM, vm has dcId: 1 and podId: 1
2013-12-27 18:26:44,941 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Deploy avoids pods: [1], clusters: [], hosts: [1, 2]
2013-12-27 18:26:44,949 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Deploy avoids pods: [1], clusters: [], hosts: [1, 2]
2013-12-27 18:26:44,950 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_7c41c31e@5c1130f8
2013-12-27 18:26:44,950 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 1000, requested ram: 1073741824
2013-12-27 18:26:44,950 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Is ROOT volume READY (pool already allocated)?: No
2013-12-27 18:26:44,950 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Searching resources only under specified Pod: 1
2013-12-27 18:26:44,950 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) The specified pod is in avoid set, returning.
2013-12-27 18:26:45,035 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: null
2013-12-27 18:26:45,081 DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Destroying vm VM[User|carl] as it failed to create on Host with Id:null
2013-12-27 18:26:45,235 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) 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
2013-12-27 18:26:45,442 WARN  [apache.cloudstack.alerts] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ])  alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Failed to deploy Vm with Id: 16, on Host with Id: null
2013-12-27 18:26:45,726 INFO  [user.vm.DeployVMCmd] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|carl]Scope=interface com.cloud.dc.DataCenter; id=1
2013-12-27 18:26:45,727 INFO  [user.vm.DeployVMCmd] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Unable to create a deployment for VM[User|carl]
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|carl]Scope=interface com.cloud.dc.DataCenter; id=1
        at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:841)
        at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
        at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
        at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3442)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3002)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2988)
        at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
        at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
        at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
        at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)
2013-12-27 18:26:45,729 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-35:job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ]) Complete async job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ], jobStatus: 2, resultCode: 530, result: Error Code: 533 Error text: Unable to create a deployment for VM[User|carl]
2013-12-27 18:26:46,532 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) Ping from 4
2013-12-27 18:26:46,915 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===START===  192.168.168.250 -- GET  command=queryAsyncJobResult&jobId=e1ebce9d-18d7-4cf0-98de-22399a6ec49e&response=json&sessionkey=AelDWfiHsmTfwtNjtk5BRrkv5As%3D&_=1388186797093
2013-12-27 18:26:46,928 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-22:null) Async job-35 = [ e1ebce9d-18d7-4cf0-98de-22399a6ec49e ] completed
2013-12-27 18:26:46,932 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===END===  192.168.168.250 -- GET  command=queryAsyncJobResult&jobId=e1ebce9d-18d7-4cf0-98de-22399a6ec49e&response=json&sessionkey=AelDWfiHsmTfwtNjtk5BRrkv5As%3D&_=1388186797093
2013-12-27 18:26:47,047 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===START===  192.168.168.250 -- GET  command=listVirtualMachines&id=0ad3abc4-b171-4fe3-81e2-f069a365a900&response=json&sessionkey=AelDWfiHsmTfwtNjtk5BRrkv5As%3D&_=1388186797186
2013-12-27 18:26:47,076 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===END===  192.168.168.250 -- GET  command=listVirtualMachines&id=0ad3abc4-b171-4fe3-81e2-f069a365a900&response=json&sessionkey=AelDWfiHsmTfwtNjtk5BRrkv5As%3D&_=1388186797186
2013-12-27 18:26:49,580 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-2100: Processing Seq 3-2100:  { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2013-12-27 18:26:49,617 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-2100: Sending Seq 3-2100:  { Ans: , MgmtId: 132129486677709, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }