You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Cristian Ciobanu <cr...@istream.today> on 2016/09/19 08:38:02 UTC
No suitable hosts found (ACS 4.5.2 Advanced )
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
RE: No suitable hosts found (ACS 4.5.2 Advanced )
Posted by Cristian Ciobanu <cr...@istream.today>.
Hello,
Thank you, I just fixed this issue, was related to my internal DNS.
Regards,
Cristian
-----Original Message-----
From: Sergey Levitskiy [mailto:Sergey.Levitskiy@autodesk.com]
Sent: Monday, September 19, 2016 3:56 PM
To: users@cloudstack.apache.org
Subject: Re: No suitable hosts found (ACS 4.5.2 Advanced )
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" <cr...@istream.today> 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
Re: No suitable hosts found (ACS 4.5.2 Advanced )
Posted by Sergey Levitskiy <Se...@autodesk.com>.
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" <cr...@istream.today> 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