Hi!!
I just installed a new environment (CS 4.5.2 and XenServer 6.5.0). I
deployed an VM normaly, but some hours after I tryed to deploy new one, and
it shows me the following error message :
015-10-14 16:10:50,059 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Invocatio
n exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-14-VM
]Scope=interface com.cloud.dc.DataCenter; id=1
The entrire log of this job is attached.The picture of my dashboard
(attached too) shows that I have resources available. My storage primiray
and secondary is external NFS.
Can you help me?
Thanks!
--
Luciano Castro
2015-10-14 16:10:47,718 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-7:ctx-8b1eb798 job-98) Add job-98 into job monitoring
2015-10-14 16:10:47,722 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(catalina-exec-11:ctx-e09b5da8 ctx-b1522851) submit async job-98, details:
AsyncJobVO {id:98, userId: 2, accountId: 2, instanceType: VirtualMachine,
instanceId: 14, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"serviceofferingid":"e981305e-a639-4d07-aa31-9676fbb88844","keyboard":"us","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"e5ea8f38-52d2-43fe-bfe7-f0278de063a5","httpmethod":"GET","templateid":"63260fe4-e2a2-4664-8139-ac3e8423d061","response":"json","id":"14","ctxDetails":"{\"com.cloud.template.VirtualMachineTemplate\":\"63260fe4-e2a2-4664-8139-ac3e8423d061\",\"com.cloud.vm.VirtualMachine\":\"579c50d7-b811-4687-9d16-85ac1443a0a1\",\"com.cloud.dc.DataCenter\":\"e5ea8f38-52d2-43fe-bfe7-f0278de063a5\",\"com.cloud.offering.ServiceOffering\":\"e981305e-a639-4d07-aa31-9676fbb88844\"}","hypervisor":"XenServer","name":"teste","iptonetworklist[0].networkid":"f91a257d-50ea-41fc-9c80-59f3b2d7cea5","_":"1444839003562","uuid":"579c50d7-b811-4687-9d16-85ac1443a0a1","ctxAccountId":"2","ctxStartEventId":"156","displayname":"teste"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 345049550998, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2015-10-14 16:10:47,726 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98) Executing AsyncJobVO {id:98, userId:
2, accountId: 2, instanceType: VirtualMachine, instanceId: 14, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"serviceofferingid":"e981305e-a639-4d07-aa31-9676fbb88844","keyboard":"us","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"e5ea8f38-52d2-43fe-bfe7-f0278de063a5","httpmethod":"GET","templateid":"63260fe4-e2a2-4664-8139-ac3e8423d061","response":"json","id":"14","ctxDetails":"{\"com.cloud.template.VirtualMachineTemplate\":\"63260fe4-e2a2-4664-8139-ac3e8423d061\",\"com.cloud.vm.VirtualMachine\":\"579c50d7-b811-4687-9d16-85ac1443a0a1\",\"com.cloud.dc.DataCenter\":\"e5ea8f38-52d2-43fe-bfe7-f0278de063a5\",\"com.cloud.offering.ServiceOffering\":\"e981305e-a639-4d07-aa31-9676fbb88844\"}","hypervisor":"XenServer","name":"teste","iptonetworklist[0].networkid":"f91a257d-50ea-41fc-9c80-59f3b2d7cea5","_":"1444839003562","uuid":"579c50d7-b811-4687-9d16-85ac1443a0a1","ctxAccountId":"2","ctxStartEventId":"156","displayname":"teste"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 345049550998, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2015-10-14 16:10:47,754 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Service SecurityGroup is
not supported in the network id=204
2015-10-14 16:10:47,758 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Service SecurityGroup is
not supported in the network id=204
2015-10-14 16:10:47,772 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Deploy avoids pods: [],
clusters: [], hosts: []
2015-10-14 16:10:47,773 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) DeploymentPlanner
allocation algorithm: com.cloud.deploy.FirstFitPlanner@3c2dbd50
2015-10-14 16:10:47,773 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Trying to allocate a host
and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500,
requested ram: 536870912
2015-10-14 16:10:47,773 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Is ROOT volume READY
(pool already allocated)?: No
2015-10-14 16:10:47,773 DEBUG [c.c.d.FirstFitPlanner]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Searching all possible
resources under this Zone: 1
2015-10-14 16:10:47,774 DEBUG [c.c.d.FirstFitPlanner]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Listing clusters in order
of aggregate capacity, that have (atleast one host with) enough CPU and RAM
capacity under this Zone: 1
2015-10-14 16:10:47,776 DEBUG [c.c.d.FirstFitPlanner]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Removing from the
clusterId list these clusters from avoid set: []
2015-10-14 16:10:47,784 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Checking resources in
Cluster: 1 under Pod: 1
2015-10-14 16:10:47,786 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Looking for hosts in dc: 1 pod:1 cluster:1
2015-10-14 16:10:47,788 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2015-10-14 16:10:47,792 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2015-10-14 16:10:47,792 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Looking for speed=500Mhz, Ram=512
2015-10-14 16:10:47,799 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Host: 1 has cpu capability (cpu:24, speed:2926) to support requested CPU: 1 and
requested speed: 500
2015-10-14 16:10:47,799 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Checking if host: 1 has enough capacity for requested CPU: 500 and requested
RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2015-10-14 16:10:47,801 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Hosts's actual total CPU: 70224 and CPU after applying overprovisioning: 70224
2015-10-14 16:10:47,801 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Free CPU: 68724 , Requested CPU: 500
2015-10-14 16:10:47,801 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Free RAM: 126961049600 , Requested RAM: 536870912
2015-10-14 16:10:47,801 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Host has enough CPU and RAM available
2015-10-14 16:10:47,801 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
STATS: Can alloc CPU from host: 1, used: 1500, reserved: 0, actual total:
70224, total with overprovisioning: 70224; requested
cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-10-14 16:10:47,801 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
STATS: Can alloc MEM from host: 1, used: 1879048192, reserved: 0, total:
128840097792; requested mem: 536870912,alloc_from_last_host?:false
,considerReservedCapacity?: true
2015-10-14 16:10:47,801 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Found a suitable host, adding to list: 1
2015-10-14 16:10:47,801 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08 FirstFitRoutingAllocator)
Host Allocator returning 1 suitable hosts
2015-10-14 16:10:47,804 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Checking suitable pools
for volume (Id, Type): (15,ROOT)
2015-10-14 16:10:47,804 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) We need to allocate new
storagepool for this volume
2015-10-14 16:10:47,805 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Calling
StoragePoolAllocators to find suitable pools
2015-10-14 16:10:47,805 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) LocalStoragePoolAllocator
trying to find storage pool to fit the vm
2015-10-14 16:10:47,805 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08)
ClusterScopeStoragePoolAllocator looking for storage pool
2015-10-14 16:10:47,805 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Looking for pools in dc:
1 pod:1 cluster:1
2015-10-14 16:10:47,806 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Found pools matching
tags: [Pool[1|NetworkFilesystem]]
2015-10-14 16:10:47,808 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Checking if storage pool
is suitable, name: null ,poolId: 1
2015-10-14 16:10:47,810 INFO [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Storage pool null (1)
does not supply IOPS capacity, assuming enough capacity
2015-10-14 16:10:47,811 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Checking pool 1 for
storage, totalSize: 429496729600, usedBytes: 11947999232, usedPct:
0.027818603515625, disable threshold: 0.85
2015-10-14 16:10:47,816 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Found storage pool
NFS-VMs of type NetworkFilesystem with overprovisioning factor 2
2015-10-14 16:10:47,816 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Total over provisioned
capacity calculated is 2 * 429496729600
2015-10-14 16:10:47,816 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Total capacity of the
pool NFS-VMs id: 1 is 858993459200
2015-10-14 16:10:47,845 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Checking pool: 1 for
volume allocation [Vol[15|vm=14|ROOT]], maxSize : 858993459200,
totalAllocatedSize : 18510442496, askingSize : 8589934592, allocated disable
threshold: 0.85
2015-10-14 16:10:47,845 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08)
ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2015-10-14 16:10:47,845 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Trying to find a potenial
host and associated storage pools from the suitable host/pool lists for this VM
2015-10-14 16:10:47,846 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Checking if host: 1 can
access any suitable storage pool for volume: ROOT
2015-10-14 16:10:47,848 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Host: 1 can access pool: 1
2015-10-14 16:10:47,849 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Found a potential host
id: 1 name: opencloud-xen01-mia.tpn.terra.com and associated storage pools for
this VM
2015-10-14 16:10:47,852 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) 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(15|ROOT-->Pool(1))]
2015-10-14 16:10:47,874 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Sync job-99 execution on
object VmWorkJobQueue.14
2015-10-14 16:10:49,635 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Add job-99 into job monitoring
2015-10-14 16:10:49,641 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Executing AsyncJobVO {id:99,
userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAADnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 345049550998, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Wed Oct 14 16:10:47 UTC 2015}
2015-10-14 16:10:49,641 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Run VM work job:
com.cloud.vm.VmWorkStart for VM 14, job origin: 98
2015-10-14 16:10:49,643 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Execute VM work
job:
com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":1,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":14,"handlerName":"VirtualMachineManagerImpl"}
2015-10-14 16:10:49,650 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) 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
2015-10-14 16:10:49,650 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Successfully
transitioned to start state for VM[User|i-2-14-VM] reservation id =
cb8d88fa-3fc5-4429-823d-53d9636edb79
2015-10-14 16:10:49,653 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Trying to deploy
VM, vm has dcId: 1 and podId: null
2015-10-14 16:10:49,653 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) advanceStart:
DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 1,
poolId: null
2015-10-14 16:10:49,653 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Deploy avoids
pods: null, clusters: null, hosts: null
2015-10-14 16:10:49,663 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Deploy avoids
pods: [], clusters: [], hosts: []
2015-10-14 16:10:49,664 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@3c2dbd50
2015-10-14 16:10:49,664 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Trying to
allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu:
500, requested ram: 536870912
2015-10-14 16:10:49,664 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Is ROOT volume
READY (pool already allocated)?: No
2015-10-14 16:10:49,664 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) DeploymentPlan
has host_id specified, choosing this host and making no checks on this host: 1
2015-10-14 16:10:49,665 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Looking for
suitable pools for this host under zone: 1, pod: 1, cluster: 1
2015-10-14 16:10:49,669 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Checking
suitable pools for volume (Id, Type): (15,ROOT)
2015-10-14 16:10:49,669 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) We need to
allocate new storagepool for this volume
2015-10-14 16:10:49,670 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Calling
StoragePoolAllocators to find suitable pools
2015-10-14 16:10:49,670 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49)
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2015-10-14 16:10:49,670 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49)
ClusterScopeStoragePoolAllocator looking for storage pool
2015-10-14 16:10:49,670 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Looking for
pools in dc: 1 pod:1 cluster:1
2015-10-14 16:10:49,671 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Found pools
matching tags: [Pool[1|NetworkFilesystem]]
2015-10-14 16:10:49,675 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Checking if
storage pool is suitable, name: null ,poolId: 1
2015-10-14 16:10:49,677 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Storage pool
null (1) does not supply IOPS capacity, assuming enough capacity
2015-10-14 16:10:49,678 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Checking pool 1
for storage, totalSize: 429496729600, usedBytes: 11947999232, usedPct:
0.027818603515625, disable threshold: 0.85
2015-10-14 16:10:49,684 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Found storage
pool NFS-VMs of type NetworkFilesystem with overprovisioning factor 2
2015-10-14 16:10:49,684 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Total over
provisioned capacity calculated is 2 * 429496729600
2015-10-14 16:10:49,684 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Total capacity
of the pool NFS-VMs id: 1 is 858993459200
2015-10-14 16:10:49,685 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Checking pool: 1
for volume allocation [Vol[15|vm=14|ROOT]], maxSize : 858993459200,
totalAllocatedSize : 18510442496, askingSize : 8589934592, allocated disable
threshold: 0.85
2015-10-14 16:10:49,685 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49)
ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2015-10-14 16:10:49,685 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Trying to find a
potenial host and associated storage pools from the suitable host/pool lists
for this VM
2015-10-14 16:10:49,685 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Checking if
host: 1 can access any suitable storage pool for volume: ROOT
2015-10-14 16:10:49,686 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Host: 1 can
access pool: 1
2015-10-14 16:10:49,686 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Found a
potential host id: 1 name: opencloud-xen01-mia.tpn.terra.com and associated
storage pools for this VM
2015-10-14 16:10:49,687 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) 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(15|ROOT-->Pool(1))]
2015-10-14 16:10:49,687 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Deployment found
- P0=VM[User|i-2-14-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(15|ROOT-->Pool(1))]
2015-10-14 16:10:49,697 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) 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
2015-10-14 16:10:49,704 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Hosts's actual
total CPU: 70224 and CPU after applying overprovisioning: 70224
2015-10-14 16:10:49,704 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) We are
allocating VM, increasing the used capacity of this host:1
2015-10-14 16:10:49,704 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Current Used
CPU: 1500 , Free CPU:68724 ,Requested CPU: 500
2015-10-14 16:10:49,704 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Current Used
RAM: 1879048192 , Free RAM:126961049600 ,Requested RAM: 536870912
2015-10-14 16:10:49,704 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) CPU STATS after
allocation: for host: 1, old used: 1500, old reserved: 0, actual total: 70224,
total with overprovisioning: 70224; new used:2000, reserved:0; requested
cpu:500,alloc_from_last:false
2015-10-14 16:10:49,704 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) RAM STATS after
allocation: for host: 1, old used: 1879048192, old reserved: 0, total:
128840097792; new used: 2415919104, reserved: 0; requested mem:
536870912,alloc_from_last:false
2015-10-14 16:10:49,708 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) VM is being
created in podId: 1
2015-10-14 16:10:49,715 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Network id=204
is already implemented
2015-10-14 16:10:49,723 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Service
SecurityGroup is not supported in the network id=204
2015-10-14 16:10:49,726 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Changing active
number of nics for network id=204 on 1
2015-10-14 16:10:49,732 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Asking
VirtualRouter to prepare for Nic[40-14-null-10.253.118.170]
2015-10-14 16:10:49,741 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Lock is acquired
for network id 204 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(15|ROOT-->Pool(1))]
2015-10-14 16:10:49,744 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Lock is released
for network id 204 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(15|ROOT-->Pool(1))]
2015-10-14 16:10:49,751 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Service
SecurityGroup is not supported in the network id=204
2015-10-14 16:10:49,762 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Service
SecurityGroup is not supported in the network id=204
2015-10-14 16:10:49,766 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Applying dhcp
entry in network Ntwk[204|Guest|7]
2015-10-14 16:10:49,780 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Seq
1-3035426148847714756: Sending { Cmd , MgmtId: 345049550998, via:
1(opencloud-xen01-mia.tpn.terra.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f8:cc:00:00:21","vmIpAddress":"10.253.118.170","vmName":"teste","defaultRouter":"10.253.118.161","defaultDns":"10.253.118.165","duid":"00:03:00:01:06:f8:cc:00:00:21","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.253.118.165","router.ip":"169.254.2.236","router.name":"r-11-VM"},"wait":0}}]
}
2015-10-14 16:10:49,780 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Seq
1-3035426148847714756: Executing: { Cmd , MgmtId: 345049550998, via:
1(opencloud-xen01-mia.tpn.terra.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f8:cc:00:00:21","vmIpAddress":"10.253.118.170","vmName":"teste","defaultRouter":"10.253.118.161","defaultDns":"10.253.118.165","duid":"00:03:00:01:06:f8:cc:00:00:21","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.253.118.165","router.ip":"169.254.2.236","router.name":"r-11-VM"},"wait":0}}]
}
2015-10-14 16:10:49,976 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Seq
1-3035426148847714756: Received: { Ans: , MgmtId: 345049550998, via: 1, Ver:
v1, Flags: 10, { Answer } }
2015-10-14 16:10:49,977 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Unable to
contact resource.
2015-10-14 16:10:49,981 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Cleaning up
resources for the vm VM[User|i-2-14-VM] in Starting state
2015-10-14 16:10:49,984 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Seq
1-3035426148847714757: Sending { Cmd , MgmtId: 345049550998, via:
1(opencloud-xen01-mia.tpn.terra.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-14-VM","wait":0}}]
}
2015-10-14 16:10:49,984 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Seq
1-3035426148847714757: Executing: { Cmd , MgmtId: 345049550998, via:
1(opencloud-xen01-mia.tpn.terra.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-14-VM","wait":0}}]
}
2015-10-14 16:10:49,990 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Seq
1-3035426148847714757: Received: { Ans: , MgmtId: 345049550998, via: 1, Ver:
v1, Flags: 10, { StopAnswer } }
2015-10-14 16:10:49,996 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Changing active
number of nics for network id=204 on -1
2015-10-14 16:10:50,005 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Successfully
released network resources for the vm VM[User|i-2-14-VM]
2015-10-14 16:10:50,005 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Successfully
cleanued up resources for the vm VM[User|i-2-14-VM] in Starting state
2015-10-14 16:10:50,015 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Deploy avoids
pods: [], clusters: [], hosts: [1]
2015-10-14 16:10:50,015 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) DataCenter id =
'1' provided is in avoid set, DeploymentPlanner cannot allocate the VM,
returning.
2015-10-14 16:10:50,038 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) 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
2015-10-14 16:10:50,044 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Hosts's actual
total CPU: 70224 and CPU after applying overprovisioning: 70224
2015-10-14 16:10:50,044 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Hosts's actual
total RAM: 128840098944 and RAM after applying overprovisioning: 128840097792
2015-10-14 16:10:50,044 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) release cpu from
host: 1, old used: 2000,reserved: 0, actual total: 70224, total with
overprovisioning: 70224; new used: 1500,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2015-10-14 16:10:50,044 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) release mem from
host: 1, old used: 2415919104,reserved: 0, total: 128840097792; new used:
1879048192,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-10-14 16:10:50,059 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Invocation
exception, caused by: com.cloud.exception.InsufficientServerCapacityException:
Unable to create a deployment for VM[User|i-2-14-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2015-10-14 16:10:50,059 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99 ctx-dabe5d49) Rethrow
exception com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-14-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2015-10-14 16:10:50,059 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Done with run of VM work job:
com.cloud.vm.VmWorkStart for VM 14, job origin: 98
2015-10-14 16:10:50,059 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Unable to complete AsyncJobVO
{id:99, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAADnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 345049550998, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Wed Oct 14 16:10:47 UTC 2015}, job origin:98
2015-10-14 16:10:50,063 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Complete async job-99,
jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA0VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0yLTE0LVZNXXVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFXNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIABEkACmxpbmVOdW1iZXJMAA5kZWNsYXJpbmdDbGFzc3EAfgAKTAAIZmlsZU5hbWVxAH4ACkwACm1ldGhvZE5hbWVxAH4ACnhwAAADs3QAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHNxAH4AEQAAEYFxAH4AE3EAfgAUcQB-ABVzcQB-ABH____-dAAkc3VuLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2Uwc3EAfgARAAAAOXEAfgAYcQB-ABl0AAZpbnZva2VzcQB-ABEAAAArdAAoc3VuLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAcc3EAfgARAAACXnQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-ABxzcQB-ABEAAABrdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9ic3EAfgARAAASHXEAfgATcQB-ABRxAH4AJnNxAH4AEQAAAGd0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4AEQAAAhl0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-ABEAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-ABEAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgARAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4ANnQAD2NhbGxXaXRoQ29udGV4dHNxAH4AEQAAADVxAH4AOXEAfgA2dAAOcnVuV2l0aENvbnRleHRzcQB-ABEAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ADJxAH4AM3NxAH4AEQAAAe5xAH4ALXEAfgAucQB-ADNzcQB-ABEAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ADdzcQB-ABEAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAzc3EAfgARAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgARAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ASHEAfgAzc3EAfgARAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAzc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAx4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AVHhzcgARamF2YS5sYW5nLkludGVnZXIS4qCk94GHOAIAAUkABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAQ73NxAH4AUwAAAAB3BAAAAAB4c3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhxAH4AVgAAAAAAAAABdnIAF2NvbS5jbG91ZC5kYy5EYXRhQ2VudGVysvEK66fneL4CAAB4cAA
2015-10-14 16:10:50,064 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Publish async job-99 complete
on message bus
2015-10-14 16:10:50,064 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Wake up jobs related to job-99
2015-10-14 16:10:50,065 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Update db status for job-99
2015-10-14 16:10:50,066 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Wake up jobs joined with
job-99 and disjoin all subjobs created from job- 99
2015-10-14 16:10:50,073 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Done executing
com.cloud.vm.VmWorkStart for job-99
2015-10-14 16:10:50,075 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-14:ctx-d83f147a job-98/job-99) Remove job-99 from job
monitoring
2015-10-14 16:10:50,090 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Sync job-100 execution on
object VmWorkJobQueue.14
2015-10-14 16:10:51,636 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Add job-100 into job
monitoring
2015-10-14 16:10:51,643 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Executing AsyncJobVO
{id:100, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAADnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 345049550998, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Wed Oct 14 16:10:50 UTC 2015}
2015-10-14 16:10:51,644 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Run VM work job:
com.cloud.vm.VmWorkStart for VM 14, job origin: 98
2015-10-14 16:10:51,645 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Execute VM work
job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":14,"handlerName":"VirtualMachineManagerImpl"}
2015-10-14 16:10:51,654 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) 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
2015-10-14 16:10:51,655 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Successfully
transitioned to start state for VM[User|i-2-14-VM] reservation id =
77479648-ae72-4e3b-81c8-96dd9747754e
2015-10-14 16:10:51,658 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Trying to
deploy VM, vm has dcId: 1 and podId: 1
2015-10-14 16:10:51,658 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Deploy avoids
pods: null, clusters: null, hosts: null
2015-10-14 16:10:51,669 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Deploy avoids
pods: [], clusters: [], hosts: []
2015-10-14 16:10:51,670 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@3c2dbd50
2015-10-14 16:10:51,670 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Trying to
allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu:
500, requested ram: 536870912
2015-10-14 16:10:51,670 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Is ROOT volume
READY (pool already allocated)?: No
2015-10-14 16:10:51,670 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Searching
resources only under specified Pod: 1
2015-10-14 16:10:51,670 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Listing
clusters in order of aggregate capacity, that have (atleast one host with)
enough CPU and RAM capacity under this Pod: 1
2015-10-14 16:10:51,673 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Removing from
the clusterId list these clusters from avoid set: []
2015-10-14 16:10:51,680 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Checking
resources in Cluster: 1 under Pod: 1
2015-10-14 16:10:51,680 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2015-10-14 16:10:51,683 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for
allocation: [Host[-1-Routing]]
2015-10-14 16:10:51,688 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization:
[Host[-1-Routing]]
2015-10-14 16:10:51,688 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
2015-10-14 16:10:51,695 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:24, speed:2926) to
support requested CPU: 1 and requested speed: 500
2015-10-14 16:10:51,695 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested
CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2015-10-14 16:10:51,697 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Hosts's actual total CPU: 70224 and CPU after
applying overprovisioning: 70224
2015-10-14 16:10:51,697 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Free CPU: 68724 , Requested CPU: 500
2015-10-14 16:10:51,697 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Free RAM: 126961049600 , Requested RAM: 536870912
2015-10-14 16:10:51,697 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-10-14 16:10:51,697 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 1500,
reserved: 0, actual total: 70224, total with overprovisioning: 70224; requested
cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-10-14 16:10:51,697 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 1879048192,
reserved: 0, total: 128840097792; requested mem:
536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-10-14 16:10:51,697 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2015-10-14 16:10:51,697 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17
FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2015-10-14 16:10:51,700 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Checking
suitable pools for volume (Id, Type): (15,ROOT)
2015-10-14 16:10:51,700 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) We need to
allocate new storagepool for this volume
2015-10-14 16:10:51,701 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Calling
StoragePoolAllocators to find suitable pools
2015-10-14 16:10:51,701 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17)
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2015-10-14 16:10:51,701 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17)
ClusterScopeStoragePoolAllocator looking for storage pool
2015-10-14 16:10:51,701 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Looking for
pools in dc: 1 pod:1 cluster:1
2015-10-14 16:10:51,702 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Found pools
matching tags: [Pool[1|NetworkFilesystem]]
2015-10-14 16:10:51,704 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Checking if
storage pool is suitable, name: null ,poolId: 1
2015-10-14 16:10:51,707 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Storage pool
null (1) does not supply IOPS capacity, assuming enough capacity
2015-10-14 16:10:51,708 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Checking pool 1
for storage, totalSize: 429496729600, usedBytes: 11947999232, usedPct:
0.027818603515625, disable threshold: 0.85
2015-10-14 16:10:51,712 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Found storage
pool NFS-VMs of type NetworkFilesystem with overprovisioning factor 2
2015-10-14 16:10:51,712 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Total over
provisioned capacity calculated is 2 * 429496729600
2015-10-14 16:10:51,712 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Total capacity
of the pool NFS-VMs id: 1 is 858993459200
2015-10-14 16:10:51,713 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Checking pool:
1 for volume allocation [Vol[15|vm=14|ROOT]], maxSize : 858993459200,
totalAllocatedSize : 18510442496, askingSize : 8589934592, allocated disable
threshold: 0.85
2015-10-14 16:10:51,713 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17)
ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2015-10-14 16:10:51,713 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Trying to find
a potenial host and associated storage pools from the suitable host/pool lists
for this VM
2015-10-14 16:10:51,713 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Checking if
host: 1 can access any suitable storage pool for volume: ROOT
2015-10-14 16:10:51,714 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Host: 1 can
access pool: 1
2015-10-14 16:10:51,714 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Found a
potential host id: 1 name: opencloud-xen01-mia.tpn.terra.com and associated
storage pools for this VM
2015-10-14 16:10:51,715 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) 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(15|ROOT-->Pool(1))]
2015-10-14 16:10:51,715 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Deployment
found - P0=VM[User|i-2-14-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(15|ROOT-->Pool(1))]
2015-10-14 16:10:51,723 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) 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
2015-10-14 16:10:51,730 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Hosts's actual
total CPU: 70224 and CPU after applying overprovisioning: 70224
2015-10-14 16:10:51,730 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) We are
allocating VM, increasing the used capacity of this host:1
2015-10-14 16:10:51,730 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Current Used
CPU: 1500 , Free CPU:68724 ,Requested CPU: 500
2015-10-14 16:10:51,730 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Current Used
RAM: 1879048192 , Free RAM:126961049600 ,Requested RAM: 536870912
2015-10-14 16:10:51,730 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) CPU STATS after
allocation: for host: 1, old used: 1500, old reserved: 0, actual total: 70224,
total with overprovisioning: 70224; new used:2000, reserved:0; requested
cpu:500,alloc_from_last:false
2015-10-14 16:10:51,730 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) RAM STATS after
allocation: for host: 1, old used: 1879048192, old reserved: 0, total:
128840097792; new used: 2415919104, reserved: 0; requested mem:
536870912,alloc_from_last:false
2015-10-14 16:10:51,734 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) VM is being
created in podId: 1
2015-10-14 16:10:51,741 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Network id=204
is already implemented
2015-10-14 16:10:51,749 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Service
SecurityGroup is not supported in the network id=204
2015-10-14 16:10:51,752 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Changing active
number of nics for network id=204 on 1
2015-10-14 16:10:51,758 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Asking
VirtualRouter to prepare for Nic[40-14-null-10.253.118.170]
2015-10-14 16:10:51,767 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Lock is
acquired for network id 204 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(15|ROOT-->Pool(1))]
2015-10-14 16:10:51,770 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Lock is
released for network id 204 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(15|ROOT-->Pool(1))]
2015-10-14 16:10:51,777 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Service
SecurityGroup is not supported in the network id=204
2015-10-14 16:10:51,788 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Service
SecurityGroup is not supported in the network id=204
2015-10-14 16:10:51,792 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Applying dhcp
entry in network Ntwk[204|Guest|7]
2015-10-14 16:10:51,808 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Seq
1-3035426148847714758: Sending { Cmd , MgmtId: 345049550998, via:
1(opencloud-xen01-mia.tpn.terra.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f8:cc:00:00:21","vmIpAddress":"10.253.118.170","vmName":"teste","defaultRouter":"10.253.118.161","defaultDns":"10.253.118.165","duid":"00:03:00:01:06:f8:cc:00:00:21","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.253.118.165","router.ip":"169.254.2.236","router.name":"r-11-VM"},"wait":0}}]
}
2015-10-14 16:10:51,808 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Seq
1-3035426148847714758: Executing: { Cmd , MgmtId: 345049550998, via:
1(opencloud-xen01-mia.tpn.terra.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f8:cc:00:00:21","vmIpAddress":"10.253.118.170","vmName":"teste","defaultRouter":"10.253.118.161","defaultDns":"10.253.118.165","duid":"00:03:00:01:06:f8:cc:00:00:21","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.253.118.165","router.ip":"169.254.2.236","router.name":"r-11-VM"},"wait":0}}]
}
2015-10-14 16:10:51,993 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Seq
1-3035426148847714758: Received: { Ans: , MgmtId: 345049550998, via: 1, Ver:
v1, Flags: 10, { Answer } }
2015-10-14 16:10:51,993 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Unable to
contact resource.
2015-10-14 16:10:51,999 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Cleaning up
resources for the vm VM[User|i-2-14-VM] in Starting state
2015-10-14 16:10:52,004 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Seq
1-3035426148847714759: Sending { Cmd , MgmtId: 345049550998, via:
1(opencloud-xen01-mia.tpn.terra.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-14-VM","wait":0}}]
}
2015-10-14 16:10:52,004 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Seq
1-3035426148847714759: Executing: { Cmd , MgmtId: 345049550998, via:
1(opencloud-xen01-mia.tpn.terra.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-14-VM","wait":0}}]
}
2015-10-14 16:10:52,010 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Seq
1-3035426148847714759: Received: { Ans: , MgmtId: 345049550998, via: 1, Ver:
v1, Flags: 10, { StopAnswer } }
2015-10-14 16:10:52,020 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Changing active
number of nics for network id=204 on -1
2015-10-14 16:10:52,028 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Successfully
released network resources for the vm VM[User|i-2-14-VM]
2015-10-14 16:10:52,029 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Successfully
cleanued up resources for the vm VM[User|i-2-14-VM] in Starting state
2015-10-14 16:10:52,040 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Deploy avoids
pods: [], clusters: [], hosts: [1]
2015-10-14 16:10:52,040 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) DataCenter id =
'1' provided is in avoid set, DeploymentPlanner cannot allocate the VM,
returning.
2015-10-14 16:10:52,052 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) 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
2015-10-14 16:10:52,065 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Hosts's actual
total CPU: 70224 and CPU after applying overprovisioning: 70224
2015-10-14 16:10:52,065 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Hosts's actual
total RAM: 128840098944 and RAM after applying overprovisioning: 128840097792
2015-10-14 16:10:52,066 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) release cpu
from host: 1, old used: 2000,reserved: 0, actual total: 70224, total with
overprovisioning: 70224; new used: 1500,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2015-10-14 16:10:52,066 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) release mem
from host: 1, old used: 2415919104,reserved: 0, total: 128840097792; new used:
1879048192,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-10-14 16:10:52,093 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Invocation
exception, caused by: com.cloud.exception.InsufficientServerCapacityException:
Unable to create a deployment for VM[User|i-2-14-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2015-10-14 16:10:52,094 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100 ctx-1f409f17) Rethrow
exception com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-14-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2015-10-14 16:10:52,095 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Done with run of VM work
job: com.cloud.vm.VmWorkStart for VM 14, job origin: 98
2015-10-14 16:10:52,095 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Unable to complete
AsyncJobVO {id:100, userId: 2, accountId: 2, instanceType: null, instanceId:
null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAADnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 345049550998, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Wed Oct 14 16:10:50 UTC 2015}, job origin:98
2015-10-14 16:10:52,100 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Complete async job-100,
jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA0VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0yLTE0LVZNXXVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFXNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIABEkACmxpbmVOdW1iZXJMAA5kZWNsYXJpbmdDbGFzc3EAfgAKTAAIZmlsZU5hbWVxAH4ACkwACm1ldGhvZE5hbWVxAH4ACnhwAAADs3QAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHNxAH4AEQAAEYFxAH4AE3EAfgAUcQB-ABVzcQB-ABH____-dAAkc3VuLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2Uwc3EAfgARAAAAOXEAfgAYcQB-ABl0AAZpbnZva2VzcQB-ABEAAAArdAAoc3VuLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAcc3EAfgARAAACXnQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-ABxzcQB-ABEAAABrdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9ic3EAfgARAAASHXEAfgATcQB-ABRxAH4AJnNxAH4AEQAAAGd0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4AEQAAAhl0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-ABEAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-ABEAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgARAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4ANnQAD2NhbGxXaXRoQ29udGV4dHNxAH4AEQAAADVxAH4AOXEAfgA2dAAOcnVuV2l0aENvbnRleHRzcQB-ABEAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ADJxAH4AM3NxAH4AEQAAAe5xAH4ALXEAfgAucQB-ADNzcQB-ABEAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ADdzcQB-ABEAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAzc3EAfgARAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgARAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ASHEAfgAzc3EAfgARAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAzc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAx4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AVHhzcgARamF2YS5sYW5nLkludGVnZXIS4qCk94GHOAIAAUkABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAQ73NxAH4AUwAAAAB3BAAAAAB4c3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhxAH4AVgAAAAAAAAABdnIAF2NvbS5jbG91ZC5kYy5EYXRhQ2VudGVysvEK66fneL4CAAB4cAA
2015-10-14 16:10:52,103 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Publish async job-100
complete on message bus
2015-10-14 16:10:52,103 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Wake up jobs related to
job-100
2015-10-14 16:10:52,103 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Update db status for job-100
2015-10-14 16:10:52,107 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Wake up jobs joined with
job-100 and disjoin all subjobs created from job- 100
2015-10-14 16:10:52,122 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Done executing
com.cloud.vm.VmWorkStart for job-100
2015-10-14 16:10:52,127 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-15:ctx-4c20cd60 job-98/job-100) Remove job-100 from job
monitoring
2015-10-14 16:10:52,149 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Destroying vm
VM[User|i-2-14-VM] as it failed to create on Host with Id:null
2015-10-14 16:10:52,177 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) 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
2015-10-14 16:10:52,233 DEBUG [c.c.u.AccountManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98 ctx-0282cd08) Access granted to
Acct[fe030623-71df-11e5-b2aa-0050568e5096-admin] to Domain:1/ by
AffinityGroupAccessChecker
2015-10-14 16:10:52,249 WARN [o.a.c.alerts] (API-Job-Executor-7:ctx-8b1eb798
job-98 ctx-0282cd08) alertType:: 8 // dataCenterId:: 1 // podId:: 1 //
clusterId:: null // message:: Failed to deploy Vm with Id: 14, on Host with Id:
null
2015-10-14 16:10:52,312 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-7:ctx-8b1eb798 job-98) Unexpected exception while executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
2015-10-14 16:10:52,315 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98) Complete async job-98, jobStatus:
FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable
to start a VM due to insufficient capacity"}
2015-10-14 16:10:52,318 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98) Publish async job-98 complete on
message bus
2015-10-14 16:10:52,318 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98) Wake up jobs related to job-98
2015-10-14 16:10:52,318 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98) Update db status for job-98
2015-10-14 16:10:52,321 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98) Wake up jobs joined with job-98 and
disjoin all subjobs created from job- 98
2015-10-14 16:10:52,333 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-8b1eb798 job-98) Done executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-98
2015-10-14 16:10:52,333 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-7:ctx-8b1eb798 job-98) Remove job-98 from job monitoring
