Your allocator works fine. The problem is that your SSVM can’t import OVA into vcenter or it can’t download OVA from URL ‘http://download.cloud.com/releases/2.2.0/CentOS5.3-x86_64.ova’ Check if SSVM can communicate to vcenter over TCP/443. Check if there is an error in vcenter when you submit the deploy job. Also check SSVM log by executing this from management server: sudo ssh -i /var/cloudstack/management/.ssh/id_rsa -p 3922 root@IP_OF_SSVM cat /var/log/cloud.log
On 9/19/16, 1:38 AM, "Cristian Ciobanu" <[email protected]> wrote: Hello All, I'm working on a ACS 4.5.2 with VMware 5.5 using Advanced networking setup ( local storage), I don't have any issue till my first VM deploy, please see my logs. - I don't see any issue for Proxy console, SSVM, Router, I also run the test on ssvm "for check ssvm" no issue found. ============================================================================ ============================================================ U4IsCAAB4cAAAEO9zcQB-AFAAAAAAdwQAAAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgA BSgAFdmFsdWV4cQB-AFMAAAAAAAAAAXZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlcrLxCuun53i -AgAAeHAA management-server.log:2016-09-19 03:53:34,771 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-64:ctx-97809d3f job-115/job-116) Publish async job-116 complete on message bus management-server.log:2016-09-19 03:53:34,771 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-64:ctx-97809d3f job-115/job-116) Wake up jobs related to job-116 management-server.log:2016-09-19 03:53:34,771 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-64:ctx-97809d3f job-115/job-116) Update db status for job-116 management-server.log:2016-09-19 03:53:34,772 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-64:ctx-97809d3f job-115/job-116) Wake up jobs joined with job-116 and disjoin all subjobs created from job- 116 management-server.log:2016-09-19 03:53:34,775 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-64:ctx-97809d3f job-115/job-116) Done executing com.cloud.vm.VmWorkStart for job-116 management-server.log:2016-09-19 03:53:34,775 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-64:ctx-97809d3f job-115/job-116) Remove job-116 from job monitoring management-server.log:2016-09-19 03:53:34,783 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-45:ctx-e9ced335 job-115 ctx-77ab93c4) Sync job-118 execution on object VmWorkJobQueue.17 management-server.log:2016-09-19 03:53:34,803 WARN [o.a.c.f.j.i.AsyncJobMonitor] (Timer-1:ctx-137019e3) Task (job-115) has been pending for 135 seconds management-server.log:2016-09-19 03:53:35,940 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Add job-118 into job monitoring management-server.log:2016-09-19 03:53:35,945 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Executing AsyncJobVO {id:118, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9p ZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAlj bHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQA EkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB- AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01h cDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAE SgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAC AAAAAAAAAAIAAAAAAAAAEXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBw cHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNo b2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gz QmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345048629065, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Sep 19 03:53:34 EDT 2016} management-server.log:2016-09-19 03:53:35,946 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Run VM work job: com.cloud.vm.VmWorkStart for VM 17, job origin: 115 management-server.log:2016-09-19 03:53:35,947 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmV kX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":17,"handlerName":"VirtualMac hineManagerImpl"} management-server.log:2016-09-19 03:53:35,952 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) 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 management-server.log:2016-09-19 03:53:35,952 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Successfully transitioned to start state for VM[User|i-2-17-VM] reservation id = 44b41991-1b70-4668-9c46-6baef3f27f2d management-server.log:2016-09-19 03:53:35,954 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Trying to deploy VM, vm has dcId: 1 and podId: 1 management-server.log:2016-09-19 03:53:35,954 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Deploy avoids pods: null, clusters: null, hosts: null management-server.log:2016-09-19 03:53:35,960 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Deploy avoids pods: [], clusters: [], hosts: [] management-server.log:2016-09-19 03:53:35,960 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@4a7a3b82 management-server.log:2016-09-19 03:53:35,960 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 536870912 management-server.log:2016-09-19 03:53:35,960 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Is ROOT volume READY (pool already allocated)?: No management-server.log:2016-09-19 03:53:35,961 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Searching resources only under specified Pod: 1 management-server.log:2016-09-19 03:53:35,961 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1 management-server.log:2016-09-19 03:53:35,962 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Removing from the clusterId list these clusters from avoid set: [] management-server.log:2016-09-19 03:53:35,966 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Checking resources in Cluster: 1 under Pod: 1 management-server.log:2016-09-19 03:53:35,966 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1 management-server.log:2016-09-19 03:53:35,968 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]] management-server.log:2016-09-19 03:53:35,970 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]] management-server.log:2016-09-19 03:53:35,970 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512 management-server.log:2016-09-19 03:53:35,974 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:8, speed:2399) to support requested CPU: 1 and requested speed: 500 management-server.log:2016-09-19 03:53:35,974 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 2.0 management-server.log:2016-09-19 03:53:35,975 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Hosts's actual total CPU: 19192 and CPU after applying overprovisioning: 38384 management-server.log:2016-09-19 03:53:35,975 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Free CPU: 36384 , Requested CPU: 500 management-server.log:2016-09-19 03:53:35,975 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Free RAM: 66356494336 , Requested RAM: 536870912 management-server.log:2016-09-19 03:53:35,975 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Host has enough CPU and RAM available management-server.log:2016-09-19 03:53:35,975 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 2000, reserved: 0, actual total: 19192, total with overprovisioning: 38384; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true management-server.log:2016-09-19 03:53:35,975 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 2147483648, reserved: 0, total: 68503977984; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true management-server.log:2016-09-19 03:53:35,975 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Found a suitable host, adding to list: 1 management-server.log:2016-09-19 03:53:35,975 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts management-server.log:2016-09-19 03:53:35,977 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Checking suitable pools for volume (Id, Type): (17,ROOT) management-server.log:2016-09-19 03:53:35,977 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) We need to allocate new storagepool for this volume management-server.log:2016-09-19 03:53:35,977 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Calling StoragePoolAllocators to find suitable pools management-server.log:2016-09-19 03:53:35,977 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) LocalStoragePoolAllocator trying to find storage pool to fit the vm management-server.log:2016-09-19 03:53:35,978 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Checking if storage pool is suitable, name: null ,poolId: 1 management-server.log:2016-09-19 03:53:35,979 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity management-server.log:2016-09-19 03:53:35,980 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Checking pool 1 for storage, totalSize: 1992327954432, usedBytes: 9364832256, usedPct: 0.004700447150363783, disable threshold: 0.85 management-server.log:2016-09-19 03:53:35,983 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Found storage pool nsMyVMwareHOST.xxx-xxx-xx.net Local Storage of type VMFS with overprovisioning factor 2 management-server.log:2016-09-19 03:53:35,983 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Total over provisioned capacity calculated is 2 * 1992327954432 management-server.log:2016-09-19 03:53:35,983 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Total capacity of the pool nsMyVMwareHOST.xxx-xxx-xx.net Local Storage id: 1 is 3984655908864 management-server.log:2016-09-19 03:53:35,984 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Checking pool: 1 for volume allocation [Vol[17|vm=17|ROOT]], maxSize : 3984655908864, totalAllocatedSize : 6291456000, askingSize : 2147483648, allocated disable threshold: 0.85 management-server.log:2016-09-19 03:53:35,984 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) LocalStoragePoolAllocator returning 1 suitable storage pools management-server.log:2016-09-19 03:53:35,984 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM management-server.log:2016-09-19 03:53:35,984 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Checking if host: 1 can access any suitable storage pool for volume: ROOT management-server.log:2016-09-19 03:53:35,985 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Host: 1 can access pool: 1 management-server.log:2016-09-19 03:53:35,985 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Found a potential host id: 1 name: nsMyVMwareHOST.xxx-xxx-xx.net and associated storage pools for this VM management-server.log:2016-09-19 03:53:35,985 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) 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(17|ROOT-->Pool(1))] management-server.log:2016-09-19 03:53:35,985 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Deployment found - P0=VM[User|i-2-17-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(17|ROOT-->Pool(1))] management-server.log:2016-09-19 03:53:35,995 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) 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 management-server.log:2016-09-19 03:53:35,999 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Hosts's actual total CPU: 19192 and CPU after applying overprovisioning: 38384 management-server.log:2016-09-19 03:53:35,999 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) We are allocating VM, increasing the used capacity of this host:1 management-server.log:2016-09-19 03:53:35,999 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Current Used CPU: 2000 , Free CPU:36384 ,Requested CPU: 500 management-server.log:2016-09-19 03:53:35,999 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Current Used RAM: 2147483648 , Free RAM:66356494336 ,Requested RAM: 536870912 management-server.log:2016-09-19 03:53:35,999 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) CPU STATS after allocation: for host: 1, old used: 2000, old reserved: 0, actual total: 19192, total with overprovisioning: 38384; new used:2500, reserved:0; requested cpu:500,alloc_from_last:false management-server.log:2016-09-19 03:53:35,999 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) RAM STATS after allocation: for host: 1, old used: 2147483648, old reserved: 0, total: 68503977984; new used: 2684354560, reserved: 0; requested mem: 536870912,alloc_from_last:false management-server.log:2016-09-19 03:53:36,001 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) VM is being created in podId: 1 management-server.log:2016-09-19 03:53:36,002 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Network id=207 is already implemented management-server.log:2016-09-19 03:53:36,008 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Service SecurityGroup is not supported in the network id=207 management-server.log:2016-09-19 03:53:36,010 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Changing active number of nics for network id=207 on 1 management-server.log:2016-09-19 03:53:36,012 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Asking VirtualRouter to prepare for Nic[27-17-44b41991-1b70-4668-9c46-6baef3f27f2d-10.1.1.2] management-server.log:2016-09-19 03:53:36,018 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Lock is acquired for network id 207 as a part of router startup 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(17|ROOT-->Pool(1))] management-server.log:2016-09-19 03:53:36,020 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Lock is released for network id 207 as a part of router startup 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(17|ROOT-->Pool(1))] management-server.log:2016-09-19 03:53:36,023 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Service SecurityGroup is not supported in the network id=207 management-server.log:2016-09-19 03:53:36,029 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Service SecurityGroup is not supported in the network id=207 management-server.log:2016-09-19 03:53:36,032 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Applying dhcp entry in network Ntwk[207|Guest|8] management-server.log:2016-09-19 03:53:36,040 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 1-2058989454638450055: Sending { Cmd , MgmtId: 345048629065, via: 1(nsMyVMwareHOST.xxx-xxx-xx.net), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:5c:d5:00:09 ","vmIpAddress":"10.1.1.2","vmName":"VM-7757bae6-2844-43b4-8ce8-02afd0baed2a ","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02: 00:5c:d5:00:09","isDefault":true,"executeInSequence":false,"accessDetails":{ "zone.network.type":"Advanced","router.guest.ip":"10.1.1.1","router.ip":"172 .20.0.196","router.name":"r-13-VM"},"wait":0}}] } management-server.log:2016-09-19 03:53:36,041 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 1-2058989454638450055: Executing: { Cmd , MgmtId: 345048629065, via: 1(nsMyVMwareHOST.xxx-xxx-xx.net), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:5c:d5:00:09 ","vmIpAddress":"10.1.1.2","vmName":"VM-7757bae6-2844-43b4-8ce8-02afd0baed2a ","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02: 00:5c:d5:00:09","isDefault":true,"executeInSequence":false,"accessDetails":{ "zone.network.type":"Advanced","router.guest.ip":"10.1.1.1","router.ip":"172 .20.0.196","router.name":"r-13-VM"},"wait":0}}] } management-server.log:2016-09-19 03:53:36,041 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-229:ctx-885aee83 nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: DhcpEntryCommand) Use router's private IP for SSH control. IP : 172.20.0.196 management-server.log:2016-09-19 03:53:36,041 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-229:ctx-885aee83 nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: DhcpEntryCommand) Run command on VR: 172.20.0.196, script: edithosts.sh with args: -m 02:00:5c:d5:00:09 -4 10.1.1.2 -h VM-7757bae6-2844-43b4-8ce8-02afd0baed2a -d 10.1.1.1 -n 10.1.1.1 management-server.log:2016-09-19 03:53:36,255 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-229:ctx-885aee83 nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: DhcpEntryCommand) edithosts.sh execution result: true management-server.log:2016-09-19 03:53:36,257 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 1-2058989454638450055: Received: { Ans: , MgmtId: 345048629065, via: 1, Ver: v1, Flags: 10, { Answer } } management-server.log:2016-09-19 03:53:36,259 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Service SecurityGroup is not supported in the network id=207 management-server.log:2016-09-19 03:53:36,261 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Applying userdata and password entry in network Ntwk[207|Guest|8] management-server.log:2016-09-19 03:53:36,269 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 1-2058989454638450056: Sending { Cmd , MgmtId: 345048629065, via: 1(nsMyVMwareHOST.xxx-xxx-xx.net), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"10.1.1. 2","vmName":"VM-7757bae6-2844-43b4-8ce8-02afd0baed2a","executeInSequence":fa lse,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-13-VM", "router.ip":"172.20.0.196","router.guest.ip":"10.1.1.1"},"wait":0}},{"com.cl oud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.2","vmName":"VM- 7757bae6-2844-43b4-8ce8-02afd0baed2a","executeInSequence":false,"accessDetai ls":{"zone.network.type":"Advanced","router.name":"r-13-VM","router.ip":"172 .20.0.196","router.guest.ip":"10.1.1.1"},"wait":0}}] } management-server.log:2016-09-19 03:53:36,270 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 1-2058989454638450056: Executing: { Cmd , MgmtId: 345048629065, via: 1(nsMyVMwareHOST.xxx-xxx-xx.net), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"10.1.1. 2","vmName":"VM-7757bae6-2844-43b4-8ce8-02afd0baed2a","executeInSequence":fa lse,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-13-VM", "router.ip":"172.20.0.196","router.guest.ip":"10.1.1.1"},"wait":0}},{"com.cl oud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.2","vmName":"VM- 7757bae6-2844-43b4-8ce8-02afd0baed2a","executeInSequence":false,"accessDetai ls":{"zone.network.type":"Advanced","router.name":"r-13-VM","router.ip":"172 .20.0.196","router.guest.ip":"10.1.1.1"},"wait":0}}] } management-server.log:2016-09-19 03:53:36,270 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-458:ctx-b33ce6a9 nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: SavePasswordCommand) Use router's private IP for SSH control. IP : 172.20.0.196 management-server.log:2016-09-19 03:53:36,271 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-458:ctx-b33ce6a9 nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: SavePasswordCommand) Run command on VR: 172.20.0.196, script: savepassword.sh with args: -v 10.1.1.2 -p saved_password management-server.log:2016-09-19 03:53:36,452 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-458:ctx-b33ce6a9 nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: SavePasswordCommand) savepassword.sh execution result: true management-server.log:2016-09-19 03:53:36,453 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-458:ctx-b33ce6a9 nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: VmDataCommand) Use router's private IP for SSH control. IP : 172.20.0.196 management-server.log:2016-09-19 03:53:36,454 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-458:ctx-b33ce6a9 nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: VmDataCommand) Run command on VR: 172.20.0.196, script: vmdata.py with args: -d eyIxMC4xLjEuMiI6W1sidXNlcmRhdGEiLCJ1c2VyLWRhdGEiLG51bGxdLFsibWV0YWRhdGEiLCJz ZXJ2aWNlLW9mZmVyaW5nIiwiU21hbGwgSW5zdGFuY2UiXSxbIm1ldGFkYXRhIiwiYXZhaWxhYmls aXR5LXpvbmUiLCJBTVMtWk9ORS0wMSJdLFsibWV0YWRhdGEiLCJsb2NhbC1pcHY0IiwiMTAuMS4x LjIiXSxbIm1ldGFkYXRhIiwibG9jYWwtaG9zdG5hbWUiLCJWTS03NzU3YmFlNi0yODQ0LTQzYjQt OGNlOC0wMmFmZDBiYWVkMmEiXSxbIm1ldGFkYXRhIiwicHVibGljLWlwdjQiLCIxNDkuNTYuMTY0 LjM2Il0sWyJtZXRhZGF0YSIsInB1YmxpYy1ob3N0bmFtZSIsIjE0OS41Ni4xNjQuMzYiXSxbIm1l dGFkYXRhIiwiaW5zdGFuY2UtaWQiLCI3NzU3YmFlNi0yODQ0LTQzYjQtOGNlOC0wMmFmZDBiYWVk MmEiXSxbIm1ldGFkYXRhIiwidm0taWQiLCI3NzU3YmFlNi0yODQ0LTQzYjQtOGNlOC0wMmFmZDBi YWVkMmEiXSxbIm1ldGFkYXRhIiwicHVibGljLWtleXMiLG51bGxdLFsibWV0YWRhdGEiLCJjbG91 ZC1pZGVudGlmaWVyIiwiQ2xvdWRTdGFjay17ZDYxNGRlMGQtNzM1OS00OWViLWIyNWEtNWNmYzZk YWQ5ZTI3fSJdXX0= management-server.log:2016-09-19 03:53:36,649 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-458:ctx-b33ce6a9 nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: VmDataCommand) vmdata.py execution result: true management-server.log:2016-09-19 03:53:36,651 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 1-2058989454638450056: Received: { Ans: , MgmtId: 345048629065, via: 1, Ver: v1, Flags: 10, { Answer, Answer } } management-server.log:2016-09-19 03:53:36,651 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Service SecurityGroup is not supported in the network id=207 management-server.log:2016-09-19 03:53:36,652 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Checking if we need to prepare 1 volumes for VM[User|i-2-17-VM] management-server.log:2016-09-19 03:53:36,655 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) template 7 is already in store:1, type:Image management-server.log:2016-09-19 03:53:36,656 DEBUG [o.a.c.s.d.PrimaryDataStoreImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Not found (templateId:7poolId:1) in template_spool_ref, persisting it management-server.log:2016-09-19 03:53:36,659 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) template 7 is already in store:1, type:Primary management-server.log:2016-09-19 03:53:36,659 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Found template centos53-x64 in storage pool 1 with VMTemplateStoragePool id: 13 management-server.log:2016-09-19 03:53:36,660 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Acquire lock on VMTemplateStoragePool 13 with timeout 3600 seconds management-server.log:2016-09-19 03:53:36,660 INFO [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) lock is acquired for VMTemplateStoragePool 13 management-server.log:2016-09-19 03:53:36,674 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type TEMPLATE management-server.log:2016-09-19 03:53:36,685 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 3-5867345889533625014: Sending { Cmd , MgmtId: 345048629065, via: 3(s-1-VM), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache. cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/1/7/93482cae- 314b-3b74-992a-4e02d313e2a3.ova","origUrl":"http://download.cloud.com/releas es/2.2.0/CentOS5.3-x86_64.ova","uuid":"e30d03ae-7dde-11e6-afcd-005056803f49" ,"id":7,"format":"OVA","accountId":1,"checksum":"f6f881b7f2292948d8494db837f e0f47","hvm":false,"displayText":"CentOS 5.3(64-bit) no GUI (vSphere)","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://1 72.20.0.2/home/secondary","_role":"Image"}},"name":"centos53-x64","hyperviso rType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObject TO":{"origUrl":"http://download.cloud.com/releases/2.2.0/CentOS5.3-x86_64.ov a","uuid":"e30d03ae-7dde-11e6-afcd-005056803f49","id":7,"format":"OVA","acco untId":1,"checksum":"f6f881b7f2292948d8494db837fe0f47","hvm":false,"displayT ext":"CentOS 5.3(64-bit) no GUI (vSphere)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataSt oreTO":{"uuid":"a7deda1f-33e5-401b-a760-b469582c1e4c","id":1,"poolType":"VMF S","host":"VMFS datastore: datastore-118","path":"datastore-118","port":0,"url":"VMFS://VMFS datastore: datastore-118/datastore-118/?ROLE=Primary&STOREUUID=a7deda1f-33e5-401b-a760- b469582c1e4c"}},"name":"centos53-x64","hypervisorType":"VMware"}},"executeIn Sequence":true,"options":{},"wait":10800}}] } management-server.log:2016-09-19 03:54:34,804 WARN [o.a.c.f.j.i.AsyncJobMonitor] (Timer-1:ctx-2498d21f) Task (job-115) has been pending for 195 seconds management-server.log:2016-09-19 03:54:39,792 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 3-5867345889533625014: Received: { Ans: , MgmtId: 345048629065, via: 3, Ver: v1, Flags: 110, { CopyCmdAnswer } } management-server.log:2016-09-19 03:54:39,798 INFO [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) releasing lock for VMTemplateStoragePool 13 management-server.log:2016-09-19 03:54:39,798 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Unable to create Vol[17|vm=17|ROOT]:Failed to create a Vmware context, check the management server logs or the ssvm log for details management-server.log:2016-09-19 03:54:39,798 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Unable to contact resource. management-server.log:2016-09-19 03:54:39,800 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Cleaning up resources for the vm VM[User|i-2-17-VM] in Starting state management-server.log:2016-09-19 03:54:39,802 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 1-2058989454638450060: Sending { Cmd , MgmtId: 345048629065, via: 1(nsMyVMwareHOST.xxx-xxx-xx.net), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":tru e,"checkBeforeCleanup":false,"vmName":"i-2-17-VM","wait":0}}] } management-server.log:2016-09-19 03:54:39,802 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 1-2058989454638450060: Executing: { Cmd , MgmtId: 345048629065, via: 1(nsMyVMwareHOST.xxx-xxx-xx.net), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":tru e,"checkBeforeCleanup":false,"vmName":"i-2-17-VM","wait":0}}] } management-server.log:2016-09-19 03:54:39,803 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-460:ctx-9fff909c nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: StopCommand) Executing resource StopCommand: {"isProxy":false,"executeInSequence":true,"checkBeforeCleanup":false,"vmName ":"i-2-17-VM","wait":0} management-server.log:2016-09-19 03:54:39,821 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-460:ctx-9fff909c nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: StopCommand) find VM i-2-17-VM on host management-server.log:2016-09-19 03:54:39,821 INFO [c.c.h.v.m.HostMO] (DirectAgent-460:ctx-9fff909c nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: StopCommand) VM i-2-17-VM not found in host cache management-server.log:2016-09-19 03:54:39,821 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-460:ctx-9fff909c nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: StopCommand) load VM cache on host management-server.log:2016-09-19 03:54:39,832 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-460:ctx-9fff909c nsMyVMwareHOST.xxx-xxx-xx.net, job-115/job-118, cmd: StopCommand) VM i-2-17-VM is no longer in vSphere management-server.log:2016-09-19 03:54:39,833 DEBUG [c.c.a.t.Request] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Seq 1-2058989454638450060: Received: { Ans: , MgmtId: 345048629065, via: 1, Ver: v1, Flags: 110, { StopAnswer } } management-server.log:2016-09-19 03:54:39,837 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Service SecurityGroup is not supported in the network id=207 management-server.log:2016-09-19 03:54:39,839 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Changing active number of nics for network id=207 on -1 management-server.log:2016-09-19 03:54:39,842 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Asking VirtualRouter to release NicProfile[27-17-44b41991-1b70-4668-9c46-6baef3f27f2d-10.1.1.2-null management-server.log:2016-09-19 03:54:39,842 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Successfully released network resources for the vm VM[User|i-2-17-VM] management-server.log:2016-09-19 03:54:39,842 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Successfully cleanued up resources for the vm VM[User|i-2-17-VM] in Starting state management-server.log:2016-09-19 03:54:39,847 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Deploy avoids pods: [], clusters: [], hosts: [1] management-server.log:2016-09-19 03:54:39,847 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@4a7a3b82 management-server.log:2016-09-19 03:54:39,848 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 536870912 management-server.log:2016-09-19 03:54:39,848 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Is ROOT volume READY (pool already allocated)?: No management-server.log:2016-09-19 03:54:39,848 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Searching resources only under specified Pod: 1 management-server.log:2016-09-19 03:54:39,848 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1 management-server.log:2016-09-19 03:54:39,849 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Removing from the clusterId list these clusters from avoid set: [] management-server.log:2016-09-19 03:54:39,853 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Checking resources in Cluster: 1 under Pod: 1 management-server.log:2016-09-19 03:54:39,853 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1 management-server.log:2016-09-19 03:54:39,855 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]] management-server.log:2016-09-19 03:54:39,857 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]] management-server.log:2016-09-19 03:54:39,857 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512 management-server.log:2016-09-19 03:54:39,857 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Host name: nsMyVMwareHOST.xxx-xxx-xx.net, hostId: 1 is in avoid set, skipping this and trying other available hosts management-server.log:2016-09-19 03:54:39,857 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts management-server.log:2016-09-19 03:54:39,857 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) No suitable hosts found management-server.log:2016-09-19 03:54:39,857 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) No suitable hosts found under this Cluster: 1 management-server.log:2016-09-19 03:54:39,858 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Could not find suitable Deployment Destination for this VM under any clusters, returning. management-server.log:2016-09-19 03:54:39,858 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Searching resources only under specified Pod: 1 management-server.log:2016-09-19 03:54:39,858 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1 management-server.log:2016-09-19 03:54:39,859 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Removing from the clusterId list these clusters from avoid set: [1] management-server.log:2016-09-19 03:54:39,860 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) No clusters found after removing disabled clusters and clusters in avoid list, returning. management-server.log:2016-09-19 03:54:39,864 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) 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 management-server.log:2016-09-19 03:54:39,867 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Hosts's actual total CPU: 19192 and CPU after applying overprovisioning: 38384 management-server.log:2016-09-19 03:54:39,867 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Hosts's actual total RAM: 34251988992 and RAM after applying overprovisioning: 68503977984 management-server.log:2016-09-19 03:54:39,867 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) release cpu from host: 1, old used: 2500,reserved: 0, actual total: 19192, total with overprovisioning: 38384; new used: 2000,reserved:0; movedfromreserved: false,moveToReserveredfalse management-server.log:2016-09-19 03:54:39,867 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) release mem from host: 1, old used: 2684354560,reserved: 0, total: 68503977984; new used: 2147483648,reserved:0; movedfromreserved: false,moveToReserveredfalse management-server.log:2016-09-19 03:54:39,874 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-17-VM]Scope=interface com.cloud.dc.DataCenter; id=1 management-server.log:2016-09-19 03:54:39,875 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118 ctx-acb9e21f) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-17-VM]Scope=interface com.cloud.dc.DataCenter; id=1 management-server.log:2016-09-19 03:54:39,875 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 17, job origin: 115 management-server.log:2016-09-19 03:54:39,875 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Unable to complete AsyncJobVO {id:118, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9p ZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAlj bHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQA EkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB- AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01h cDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAE SgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAC AAAAAAAAAAIAAAAAAAAAEXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBw cHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNo b2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gz QmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345048629065, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Sep 19 03:53:34 EDT 2016}, job origin:115 management-server.log:2016-09-19 03:54:39,876 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Complete async job-118, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhj ZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4 Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBM amF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQu ZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZh L2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5s YW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMA BEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZh L2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVu dDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA0VW5h YmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0yLTE3LVZNXXVyAB5bTGph dmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFHNyABtqYXZhLmxhbmcu U3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIABEkACmxpbmVOdW1iZXJMAA5kZWNsYXJpbmdDbGFz c3EAfgAKTAAIZmlsZU5hbWVxAH4ACkwACm1ldGhvZE5hbWVxAH4ACnhwAAADs3QAJmNvbS5jbG91 ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1w bC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHNxAH4AEQAAEYFxAH4AE3EAfgAUcQB-ABVzcQB-ABH_ ____dAAmc3VuLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3IzODBwdAAGaW52b2tlc3EA fgARAAAAK3QAKHN1bi5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxl Z2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AGXNxAH4AEQAAAl50ABhqYXZhLmxhbmcu cmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAZc3EAfgARAAAAa3QAImNvbS5jbG91ZC52 bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hh bmRsZVZtV29ya0pvYnNxAH4AEQAAEh1xAH4AE3EAfgAUcQB-ACNzcQB-ABEAAABndAAgY29tLmNs b3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZy dW5Kb2JzcQB-ABEAAAIZdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmlt cGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVu SW5Db250ZXh0c3EAfgARAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRl eHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZh dAADcnVuc3EAfgARAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQu aW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZh dAAEY2FsbHNxAH4AEQAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0 LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADN0AA9jYWxsV2l0aENvbnRleHRzcQB-ABEA AAA1cQB-ADZxAH4AM3QADnJ1bldpdGhDb250ZXh0c3EAfgARAAAALnQAPG9yZy5hcGFjaGUuY2xv dWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAvcQB-ADBz cQB-ABEAAAHucQB-ACpxAH4AK3EAfgAwc3EAfgARAAAB13QALmphdmEudXRpbC5jb25jdXJyZW50 LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA0c3EAfgARAAAB BnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4A MHNxAH4AEQAABHl0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdU aHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4AEQAAAmd0AC5qYXZhLnV0aWwu Y29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEVxAH4AMHNxAH4AEQAAAul0 ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AMHNyACZqYXZhLnV0aWwuQ29sbGVj dGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAMeHIALGphdmEudXRp bC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGph dmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkA BHNpemV4cAAAAAB3BAAAAAB4cQB-AFF4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJ AAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcQB-AFAAAAAAdwQA AAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cQB-AFMAAAAAAAAAAXZy ABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlcrLxCuun53i-AgAAeHAA management-server.log:2016-09-19 03:54:39,877 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Publish async job-118 complete on message bus management-server.log:2016-09-19 03:54:39,877 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Wake up jobs related to job-118 management-server.log:2016-09-19 03:54:39,877 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Update db status for job-118 management-server.log:2016-09-19 03:54:39,877 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Wake up jobs joined with job-118 and disjoin all subjobs created from job- 118 management-server.log:2016-09-19 03:54:39,880 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Done executing com.cloud.vm.VmWorkStart for job-118 management-server.log:2016-09-19 03:54:39,881 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-65:ctx-5592b640 job-115/job-118) Remove job-118 from job monitoring management-server.log:2016-09-19 03:54:39,886 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-45:ctx-e9ced335 job-115 ctx-77ab93c4) Destroying vm VM[User|i-2-17-VM] as it failed to create on Host with Id:null management-server.log:2016-09-19 03:54:39,889 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-45:ctx-e9ced335 job-115 ctx-77ab93c4) 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 management-server.log:2016-09-19 03:54:39,905 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-45:ctx-e9ced335 job-115 ctx-77ab93c4) Access granted to Acct[f928b8cc-7dde-11e6-afcd-005056803f49-admin] to Domain:1/ by AffinityGroupAccessChecker management-server.log:2016-09-19 03:54:39,909 WARN [o.a.c.alerts] (API-Job-Executor-45:ctx-e9ced335 job-115 ctx-77ab93c4) alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Failed to deploy Vm with Id: 17, on Host with Id: null management-server.log:2016-09-19 03:54:39,920 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-45:ctx-e9ced335 job-115) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin management-server.log:2016-09-19 03:54:39,921 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-45:ctx-e9ced335 job-115) Complete async job-115, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"er rorcode":530,"errortext":"Unable to start a VM due to insufficient capacity"} management-server.log:2016-09-19 03:54:39,921 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-45:ctx-e9ced335 job-115) Publish async job-115 complete on message bus management-server.log:2016-09-19 03:54:39,922 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-45:ctx-e9ced335 job-115) Wake up jobs related to job-115 management-server.log:2016-09-19 03:54:39,922 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-45:ctx-e9ced335 job-115) Update db status for job-115 management-server.log:2016-09-19 03:54:39,922 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-45:ctx-e9ced335 job-115) Wake up jobs joined with job-115 and disjoin all subjobs created from job- 115 management-server.log:2016-09-19 03:54:39,924 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-45:ctx-e9ced335 job-115) Done executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-115 management-server.log:2016-09-19 03:54:39,924 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-45:ctx-e9ced335 job-115) Remove job-115 from job monitoring Regards, Cristian
