Hello All,
I have ACS 4.92 using Xenserver 6.5 , I faced a problem that I can't create new
instance with error "Failed to deploy VM VM[User|" , I searched for the log
and I can't find the root cause , can you please advice what is the problem ,
the job related for it as per below
Please note that there is enough resources to create the instance
2018-02-15 14:27:37,384 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663) (logid:4a6ba1f0) Add job-12663
into job monitoring
2018-02-15 14:27:37,391 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663) (logid:945782ed) Executing
AsyncJobVO {id:12663, userId: 2, accountId: 2, instanceType: VirtualMachine,
instanceId: 755, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"serviceofferingid":"d3a0dd84-db21-4651-a281-34126f22bccd","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"dfde112b-8700-4dae-be97-e5a6a0af5ebd","httpmethod":"GET","templateid":"5a807661-4b1a-4f8a-96dc-1830c1df9f73","response":"json","id":"755","ctxDetails":"{\"interface
com.cloud.template.VirtualMachineTemplate\":\"5a807661-4b1a-4f8a-96dc-1830c1df9f73\",\"interface
com.cloud.offering.ServiceOffering\":\"d3a0dd84-db21-4651-a281-34126f22bccd\",\"interface
com.cloud.dc.DataCenter\":\"dfde112b-8700-4dae-be97-e5a6a0af5ebd\",\"interface
com.cloud.vm.VirtualMachine\":\"c19e77dd-d886-4851-8234-124a6efda216\",\"interface
com.cloud.projects.Project\":\"9bc07529-8ea9-4edc-8d16-dad871a59b63\"}","hypervisor":"XenServer","name":"Linux0","iptonetworklist[0].networkid":"8ee795fd-005a-4f51-99cb-5d3959f95a90","projectid":"9bc07529-8ea9-4edc-8d16-dad871a59b63","_":"1518697660619","uuid":"c19e77dd-d886-4851-8234-124a6efda216","ctxAccountId":"2","ctxStartEventId":"26056","displayname":"Linux0"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 279900894633337, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2018-02-15 14:27:37,398 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(catalina-exec-4:ctx-14eb635d ctx-f1f3abe6) (logid:e5c2a54c) submit async
job-12663, details: AsyncJobVO {id:12663, userId: 2, accountId: 2,
instanceType: VirtualMachine, instanceId: 755, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"serviceofferingid":"d3a0dd84-db21-4651-a281-34126f22bccd","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"dfde112b-8700-4dae-be97-e5a6a0af5ebd","httpmethod":"GET","templateid":"5a807661-4b1a-4f8a-96dc-1830c1df9f73","response":"json","id":"755","ctxDetails":"{\"interface
com.cloud.template.VirtualMachineTemplate\":\"5a807661-4b1a-4f8a-96dc-1830c1df9f73\",\"interface
com.cloud.offering.ServiceOffering\":\"d3a0dd84-db21-4651-a281-34126f22bccd\",\"interface
com.cloud.dc.DataCenter\":\"dfde112b-8700-4dae-be97-e5a6a0af5ebd\",\"interface
com.cloud.vm.VirtualMachine\":\"c19e77dd-d886-4851-8234-124a6efda216\",\"interface
com.cloud.projects.Project\":\"9bc07529-8ea9-4edc-8d16-dad871a59b63\"}","hypervisor":"XenServer","name":"Linux0","iptonetworklist[0].networkid":"8ee795fd-005a-4f51-99cb-5d3959f95a90","projectid":"9bc07529-8ea9-4edc-8d16-dad871a59b63","_":"1518697660619","uuid":"c19e77dd-d886-4851-8234-124a6efda216","ctxAccountId":"2","ctxStartEventId":"26056","displayname":"Linux0"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 279900894633337, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2018-02-15 14:27:37,428 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Service SecurityGroup is not supported in the network id=204
2018-02-15 14:27:37,431 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Service SecurityGroup is not supported in the network id=204
2018-02-15 14:27:37,442 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Deploy avoids pods: [], clusters: [], hosts: []
2018-02-15 14:27:37,442 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@5cc91e40
2018-02-15 14:27:37,442 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null,
requested cpu: 1000, requested ram: 4294967296
2018-02-15 14:27:37,442 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed) Is
ROOT volume READY (pool already allocated)?: No
2018-02-15 14:27:37,442 DEBUG [c.c.d.FirstFitPlanner]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Searching all possible resources under this Zone: 1
2018-02-15 14:27:37,443 DEBUG [c.c.d.FirstFitPlanner]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Listing clusters in order of aggregate capacity, that have (atleast one host
with) enough CPU and RAM capacity under this Zone: 1
2018-02-15 14:27:37,446 DEBUG [c.c.d.FirstFitPlanner]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Removing from the clusterId list these clusters from avoid set: []
2018-02-15 14:27:37,472 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Checking resources in Cluster: 2 under Pod: 1
2018-02-15 14:27:37,472 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Looking for hosts in dc: 1 pod:1
cluster:2
2018-02-15 14:27:37,474 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) FirstFitAllocator has 1 hosts to
check for allocation: [Host[-4-Routing]]
2018-02-15 14:27:37,478 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Found 1 hosts for allocation after
prioritization: [Host[-4-Routing]]
2018-02-15 14:27:37,478 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Looking for speed=1000Mhz, Ram=4096
2018-02-15 14:27:37,485 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Host: 4 has cpu capability (cpu:16,
speed:2394) to support requested CPU: 1 and requested speed: 1000
2018-02-15 14:27:37,485 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Checking if host: 4 has enough
capacity for requested CPU: 1000 and requested RAM: 4294967296 ,
cpuOverprovisioningFactor: 1.0
2018-02-15 14:27:37,486 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Hosts's actual total CPU: 38304 and
CPU after applying overprovisioning: 38304
2018-02-15 14:27:37,486 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Free CPU: 32304 , Requested CPU: 1000
2018-02-15 14:27:37,486 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Free RAM: 29488480256 , Requested
RAM: 4294967296
2018-02-15 14:27:37,486 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Host has enough CPU and RAM available
2018-02-15 14:27:37,486 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) STATS: Can alloc CPU from host: 4,
used: 6000, reserved: 0, actual total: 38304, total with overprovisioning:
38304; requested cpu:1000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2018-02-15 14:27:37,486 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) STATS: Can alloc MEM from host: 4,
used: 17179869184, reserved: 0, total: 46668349440; requested mem:
4294967296,alloc_from_last_host?:false ,considerReservedCapacity?: true
2018-02-15 14:27:37,486 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Found a suitable host, adding to
list: 4
2018-02-15 14:27:37,486 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8
FirstFitRoutingAllocator) (logid:945782ed) Host Allocator returning 1 suitable
hosts
2018-02-15 14:27:37,488 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Checking suitable pools for volume (Id, Type): (800,ROOT)
2018-02-15 14:27:37,488 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed) We
need to allocate new storagepool for this volume
2018-02-15 14:27:37,490 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Calling StoragePoolAllocators to find suitable pools
2018-02-15 14:27:37,490 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2018-02-15 14:27:37,492 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Checking if storage pool is suitable, name: null ,poolId: 2
2018-02-15 14:27:37,494 INFO [c.c.s.StorageManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Storage pool null (2) does not supply IOPS capacity, assuming enough capacity
2018-02-15 14:27:37,496 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Checking pool 2 for storage, totalSize: 1189156487168, usedBytes: 422337052672,
usedPct: 0.355156833629024, disable threshold: 0.95
2018-02-15 14:27:37,513 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Found storage pool CSJOHQAZ02 Local Storage of type LVM
2018-02-15 14:27:37,513 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Total capacity of the pool CSJOHQAZ02 Local Storage id: 2 is 1189156487168
2018-02-15 14:27:37,514 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Checking pool: 2 for volume allocation [Vol[800|vm=755|ROOT]], maxSize :
1189156487168, totalAllocatedSize : 443832860672, askingSize : 21474836480,
allocated disable threshold: 0.95
2018-02-15 14:27:37,515 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
LocalStoragePoolAllocator returning 1 suitable storage pools
2018-02-15 14:27:37,515 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Trying to find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2018-02-15 14:27:37,515 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Checking if host: 4 can access any suitable storage pool for volume: ROOT
2018-02-15 14:27:37,516 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Host: 4 can access pool: 2
2018-02-15 14:27:37,516 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Found a potential host id: 4 name: CSJOHQAZ02 and associated storage pools for
this VM
2018-02-15 14:27:37,517 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(2)-Host(4)-Storage(Volume(800|ROOT-->Pool(2))]
2018-02-15 14:27:37,534 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed) Sync
job-12664 execution on object VmWorkJobQueue.755
2018-02-15 14:27:38,698 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:bf616f40) Add
job-12664 into job monitoring
2018-02-15 14:27:38,706 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed)
Executing AsyncJobVO {id:12664, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAC83QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAJzcQB-AAgAAAAAAAAABHBwcHNxAH4ACAAAAAAAAAABcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 279900894633337, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Thu Feb 15 14:27:37 EET 2018}
2018-02-15 14:27:38,706 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed) Run VM
work job: com.cloud.vm.VmWorkStart for VM 755, job origin: 12663
2018-02-15 14:27:38,708 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":2,"hostId":4,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":755,"handlerName":"VirtualMachineManagerImpl"}
2018-02-15 14:27:38,717 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) 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
2018-02-15 14:27:38,717 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Successfully transitioned to start state for
VM[User|i-12-755-VM] reservation id = fb5b8f9c-cc1b-4a2f-97a1-68cd736515b6
2018-02-15 14:27:38,718 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Trying to deploy VM, vm has dcId: 1 and podId: null
2018-02-15 14:27:38,719 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) advanceStart: DeploymentPlan is provided, using dcId:1, podId:
1, clusterId: 2, hostId: 4, poolId: null
2018-02-15 14:27:38,719 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Deploy avoids pods: null, clusters: null, hosts: null
2018-02-15 14:27:38,728 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Deploy avoids pods: [], clusters: [], hosts: []
2018-02-15 14:27:38,729 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@5cc91e40
2018-02-15 14:27:38,729 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:2, requested cpu: 1000, requested ram: 4294967296
2018-02-15 14:27:38,729 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Is ROOT volume READY (pool already allocated)?: No
2018-02-15 14:27:38,729 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) DeploymentPlan has host_id specified, choosing this host and
making no checks on this host: 4
2018-02-15 14:27:38,730 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Looking for suitable pools for this host under zone: 1, pod:
1, cluster: 2
2018-02-15 14:27:38,733 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Checking suitable pools for volume (Id, Type): (800,ROOT)
2018-02-15 14:27:38,733 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) We need to allocate new storagepool for this volume
2018-02-15 14:27:38,734 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Calling StoragePoolAllocators to find suitable pools
2018-02-15 14:27:38,735 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) LocalStoragePoolAllocator trying to find storage pool to fit
the vm
2018-02-15 14:27:38,737 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Checking if storage pool is suitable, name: null ,poolId: 2
2018-02-15 14:27:38,738 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Storage pool null (2) does not supply IOPS capacity, assuming
enough capacity
2018-02-15 14:27:38,740 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Checking pool 2 for storage, totalSize: 1189156487168,
usedBytes: 422337052672, usedPct: 0.355156833629024, disable threshold: 0.95
2018-02-15 14:27:38,746 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Found storage pool CSJOHQAZ02 Local Storage of type LVM
2018-02-15 14:27:38,746 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Total capacity of the pool CSJOHQAZ02 Local Storage id: 2 is
1189156487168
2018-02-15 14:27:38,747 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Checking pool: 2 for volume allocation [Vol[800|vm=755|ROOT]],
maxSize : 1189156487168, totalAllocatedSize : 443832860672, askingSize :
21474836480, allocated disable threshold: 0.95
2018-02-15 14:27:38,747 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Found suitable local storage pool 2, adding to list
2018-02-15 14:27:38,747 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) LocalStoragePoolAllocator returning 1 suitable storage pools
2018-02-15 14:27:38,747 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Trying to find a potenial host and associated storage pools
from the suitable host/pool lists for this VM
2018-02-15 14:27:38,747 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Checking if host: 4 can access any suitable storage pool for
volume: ROOT
2018-02-15 14:27:38,748 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Host: 4 can access pool: 2
2018-02-15 14:27:38,748 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Found a potential host id: 4 name: CSJOHQAZ02 and associated
storage pools for this VM
2018-02-15 14:27:38,749 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(2)-Host(4)-Storage(Volume(800|ROOT-->Pool(2))]
2018-02-15 14:27:38,749 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Deployment found - P0=VM[User|i-12-755-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(2)-Host(4)-Storage(Volume(800|ROOT-->Pool(2))]
2018-02-15 14:27:38,766 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) VM state transitted from :Starting to Starting with event:
OperationRetryvm's original host id: null new host id: 4 host id before state
transition: null
2018-02-15 14:27:38,771 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Hosts's actual total CPU: 38304 and CPU after applying
overprovisioning: 38304
2018-02-15 14:27:38,771 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) We are allocating VM, increasing the used capacity of this
host:4
2018-02-15 14:27:38,771 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Current Used CPU: 6000 , Free CPU:32304 ,Requested CPU: 1000
2018-02-15 14:27:38,771 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Current Used RAM: 17179869184 , Free RAM:29488480256
,Requested RAM: 4294967296
2018-02-15 14:27:38,771 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) CPU STATS after allocation: for host: 4, old used: 6000, old
reserved: 0, actual total: 38304, total with overprovisioning: 38304; new
used:7000, reserved:0; requested cpu:1000,alloc_from_last:false
2018-02-15 14:27:38,772 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) RAM STATS after allocation: for host: 4, old used:
17179869184, old reserved: 0, total: 46668349440; new used: 21474836480,
reserved: 0; requested mem: 4294967296,alloc_from_last:false
2018-02-15 14:27:38,774 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) VM is being created in podId: 1
2018-02-15 14:27:38,781 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Network id=204 is already implemented
2018-02-15 14:27:38,787 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:27:38,790 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Changing active number of nics for network id=204 on 1
2018-02-15 14:27:38,795 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Asking VirtualRouter to prepare for
Nic[735-755-null-192.168.124.116]
2018-02-15 14:27:38,810 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:27:38,812 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) CONFIG DHCP FOR SUBNETS RULES
2018-02-15 14:27:38,822 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:27:38,823 DEBUG [o.a.c.n.t.AdvancedNetworkTopology]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) APPLYING VPC DHCP ENTRY RULES
2018-02-15 14:27:38,823 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Applying dhcp entry in network Ntwk[204|Guest|7]
2018-02-15 14:27:38,842 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 13-2847119389428467483: Sending { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f1:64:00:04:0d","vmIpAddress":"192.168.124.116","vmName":"Linux0","defaultRouter":"192.168.124.1","defaultDns":"192.168.124.101","duid":"00:03:00:01:06:f1:64:00:04:0d","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"192.168.124.180","router.ip":"169.254.2.33","router.name":"r-430-VM"},"wait":0}}]
}
2018-02-15 14:27:38,842 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 13-2847119389428467483: Executing: { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f1:64:00:04:0d","vmIpAddress":"192.168.124.116","vmName":"Linux0","defaultRouter":"192.168.124.1","defaultDns":"192.168.124.101","duid":"00:03:00:01:06:f1:64:00:04:0d","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"192.168.124.180","router.ip":"169.254.2.33","router.name":"r-430-VM"},"wait":0}}]
}
2018-02-15 14:27:42,725 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 13-2847119389428467483: Received: { Ans: , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 10, { GroupAnswer } }
2018-02-15 14:27:42,733 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:27:42,735 DEBUG [o.a.c.n.t.AdvancedNetworkTopology]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) APPLYING VPC USERDATA RULES
2018-02-15 14:27:42,735 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Applying userdata and password entry in network
Ntwk[204|Guest|7]
2018-02-15 14:27:42,749 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 13-2847119389428467484: Sending { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}}]
}
2018-02-15 14:27:42,750 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 13-2847119389428467484: Executing: { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}}]
}
2018-02-15 14:27:55,661 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 13-2847119389428467484: Received: { Ans: , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 10, { GroupAnswer,
GroupAnswer } }
2018-02-15 14:27:55,662 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:27:55,664 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Checking if we need to prepare 1 volumes for
VM[User|i-12-755-VM]
2018-02-15 14:27:55,670 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) template 407 is already in store:1, type:Image
2018-02-15 14:27:55,672 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) template 407 is already in store:2, type:Primary
2018-02-15 14:27:55,687 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) copyAsync inspecting src type TEMPLATE copyAsync inspecting
dest type VOLUME
2018-02-15 14:27:55,695 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.CopyCommand
2018-02-15 14:27:55,696 DEBUG [c.c.h.XenServerGuru]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.CopyCommand
2018-02-15 14:27:55,698 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 4-7650771341972519533: Sending { Cmd , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"f9891d65-f34c-4f54-b9fc-eb961f34dde5","uuid":"5a807661-4b1a-4f8a-96dc-1830c1df9f73","id":407,"format":"VHD","accountId":12,"hvm":true,"displayText":"linux
6","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"68996ac2-f860-a1aa-0a7b-e820d47ba19b","id":2,"poolType":"LVM","host":"192.168.120.11","path":"lvm","port":0,"url":"LVM://192.168.120.11/lvm/?ROLE=Primary&STOREUUID=68996ac2-f860-a1aa-0a7b-e820d47ba19b"}},"name":"dd021204-4319-4ee3-988a-99a4eb5fe991","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0b828762-662a-41c8-9e5a-ae579773cb1c","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"68996ac2-f860-a1aa-0a7b-e820d47ba19b","id":2,"poolType":"LVM","host":"192.168.120.11","path":"lvm","port":0,"url":"LVM://192.168.120.11/lvm/?ROLE=Primary&STOREUUID=68996ac2-f860-a1aa-0a7b-e820d47ba19b"}},"name":"ROOT-755","size":21474836480,"volumeId":800,"vmName":"i-12-755-VM","accountId":12,"format":"VHD","provisioningType":"THIN","id":800,"deviceId":0,"hypervisorType":"XenServer"}},"executeInSequence":true,"options":{},"options2":{},"wait":0}}]
}
2018-02-15 14:27:55,698 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 4-7650771341972519533: Executing: { Cmd , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"f9891d65-f34c-4f54-b9fc-eb961f34dde5","uuid":"5a807661-4b1a-4f8a-96dc-1830c1df9f73","id":407,"format":"VHD","accountId":12,"hvm":true,"displayText":"linux
6","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"68996ac2-f860-a1aa-0a7b-e820d47ba19b","id":2,"poolType":"LVM","host":"192.168.120.11","path":"lvm","port":0,"url":"LVM://192.168.120.11/lvm/?ROLE=Primary&STOREUUID=68996ac2-f860-a1aa-0a7b-e820d47ba19b"}},"name":"dd021204-4319-4ee3-988a-99a4eb5fe991","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0b828762-662a-41c8-9e5a-ae579773cb1c","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"68996ac2-f860-a1aa-0a7b-e820d47ba19b","id":2,"poolType":"LVM","host":"192.168.120.11","path":"lvm","port":0,"url":"LVM://192.168.120.11/lvm/?ROLE=Primary&STOREUUID=68996ac2-f860-a1aa-0a7b-e820d47ba19b"}},"name":"ROOT-755","size":21474836480,"volumeId":800,"vmName":"i-12-755-VM","accountId":12,"format":"VHD","provisioningType":"THIN","id":800,"deviceId":0,"hypervisorType":"XenServer"}},"executeInSequence":true,"options":{},"options2":{},"wait":0}}]
}
2018-02-15 14:27:57,036 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 4-7650771341972519533: Received: { Ans: , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 110, { CopyCmdAnswer } }
2018-02-15 14:27:57,101 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 4-7650771341972519534: Sending { Cmd , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":755,"name":"i-12-755-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":1000,"maxSpeed":1000,"minRam":4294967296,"maxRam":4294967296,"arch":"x86_64","os":"Red
Hat Enterprise Linux 6.5 (64-bit)","platformEmulator":"Red Hat Enterprise
Linux 6
(64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"usywgVWnVawf4y-7O95nDA","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true","hypervisortoolsversion":"xenserver56","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"c19e77dd-d886-4851-8234-124a6efda216","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0b828762-662a-41c8-9e5a-ae579773cb1c","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"68996ac2-f860-a1aa-0a7b-e820d47ba19b","id":2,"poolType":"LVM","host":"192.168.120.11","path":"lvm","port":0,"url":"LVM://192.168.120.11/lvm/?ROLE=Primary&STOREUUID=68996ac2-f860-a1aa-0a7b-e820d47ba19b"}},"name":"ROOT-755","size":21474836480,"path":"7c33ebfa-1297-4e42-99a6-4c44513d8ed8","volumeId":800,"vmName":"i-12-755-VM","accountId":12,"format":"VHD","provisioningType":"THIN","id":800,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"7c33ebfa-1297-4e42-99a6-4c44513d8ed8","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"192.168.120.11","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":1024,"defaultNic":true,"pxeDisable":false,"nicUuid":"58e74763-6cb4-4e83-ae2d-10133eecbfce","uuid":"8ee795fd-005a-4f51-99cb-5d3959f95a90","ip":"192.168.124.116","netmask":"255.255.252.0","gateway":"192.168.124.1","mac":"06:f1:64:00:04:0d","dns1":"192.168.30.2","dns2":"192.168.30.3","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://240","isolationUri":"vlan://240","isSecurityGroupEnabled":false,"name":"MGMT"}],"vcpuMaxLimit":16},"hostIp":"192.168.120.11","executeInSequence":false,"wait":0}}]
}
2018-02-15 14:27:57,101 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 4-7650771341972519534: Executing: { Cmd , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":755,"name":"i-12-755-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":1000,"maxSpeed":1000,"minRam":4294967296,"maxRam":4294967296,"arch":"x86_64","os":"Red
Hat Enterprise Linux 6.5 (64-bit)","platformEmulator":"Red Hat Enterprise
Linux 6
(64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"usywgVWnVawf4y-7O95nDA","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true","hypervisortoolsversion":"xenserver56","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"c19e77dd-d886-4851-8234-124a6efda216","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0b828762-662a-41c8-9e5a-ae579773cb1c","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"68996ac2-f860-a1aa-0a7b-e820d47ba19b","id":2,"poolType":"LVM","host":"192.168.120.11","path":"lvm","port":0,"url":"LVM://192.168.120.11/lvm/?ROLE=Primary&STOREUUID=68996ac2-f860-a1aa-0a7b-e820d47ba19b"}},"name":"ROOT-755","size":21474836480,"path":"7c33ebfa-1297-4e42-99a6-4c44513d8ed8","volumeId":800,"vmName":"i-12-755-VM","accountId":12,"format":"VHD","provisioningType":"THIN","id":800,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"7c33ebfa-1297-4e42-99a6-4c44513d8ed8","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"192.168.120.11","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":1024,"defaultNic":true,"pxeDisable":false,"nicUuid":"58e74763-6cb4-4e83-ae2d-10133eecbfce","uuid":"8ee795fd-005a-4f51-99cb-5d3959f95a90","ip":"192.168.124.116","netmask":"255.255.252.0","gateway":"192.168.124.1","mac":"06:f1:64:00:04:0d","dns1":"192.168.30.2","dns2":"192.168.30.3","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://240","isolationUri":"vlan://240","isSecurityGroupEnabled":false,"name":"MGMT"}],"vcpuMaxLimit":16},"hostIp":"192.168.120.11","executeInSequence":false,"wait":0}}]
}
2018-02-15 14:27:58,248 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 4-7650771341972519534: Received: { Ans: , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 10, { StartAnswer } }
2018-02-15 14:27:58,252 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Unable to start VM on Host[-4-Routing] due to Unable to start
i-12-755-VM due to
2018-02-15 14:27:58,258 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Cleaning up resources for the vm VM[User|i-12-755-VM] in
Starting state
2018-02-15 14:27:58,261 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 4-7650771341972519535: Sending { Cmd , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-12-755-VM","executeInSequence":false,"wait":0}}]
}
2018-02-15 14:27:58,261 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 4-7650771341972519535: Executing: { Cmd , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-12-755-VM","executeInSequence":false,"wait":0}}]
}
2018-02-15 14:27:58,266 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Seq 4-7650771341972519535: Received: { Ans: , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 10, { StopAnswer } }
2018-02-15 14:27:58,272 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Changing active number of nics for network id=204 on -1
2018-02-15 14:27:58,279 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Successfully released network resources for the vm
VM[User|i-12-755-VM]
2018-02-15 14:27:58,279 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Successfully cleanued up resources for the vm
VM[User|i-12-755-VM] in Starting state
2018-02-15 14:27:58,281 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Root volume is ready, need to place VM in volume's cluster
2018-02-15 14:27:58,289 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Deploy avoids pods: [], clusters: [], hosts: [4]
2018-02-15 14:27:58,290 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@5cc91e40
2018-02-15 14:27:58,290 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:2, requested cpu: 1000, requested ram: 4294967296
2018-02-15 14:27:58,290 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Is ROOT volume READY (pool already allocated)?: Yes
2018-02-15 14:27:58,290 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) DeploymentPlan has host_id specified, choosing this host and
making no checks on this host: 4
2018-02-15 14:27:58,291 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) The specified host is in avoid set
2018-02-15 14:27:58,291 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Cannot deploy to specified host, returning.
2018-02-15 14:27:58,300 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) VM state transitted from :Starting to Stopped with event:
OperationFailedvm's original host id: null new host id: null host id before
state transition: 4
2018-02-15 14:27:58,305 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Hosts's actual total CPU: 38304 and CPU after applying
overprovisioning: 38304
2018-02-15 14:27:58,305 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Hosts's actual total RAM: 46668350336 and RAM after applying
overprovisioning: 46668349440
2018-02-15 14:27:58,305 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) release cpu from host: 4, old used: 7000,reserved: 0, actual
total: 38304, total with overprovisioning: 38304; new used: 6000,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2018-02-15 14:27:58,305 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) release mem from host: 4, old used: 21474836480,reserved: 0,
total: 46668349440; new used: 17179869184,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2018-02-15 14:27:58,317 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-12-755-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2018-02-15 14:27:58,322 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664 ctx-adcded8b)
(logid:945782ed) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-12-755-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2018-02-15 14:27:58,322 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed) Done
with run of VM work job: com.cloud.vm.VmWorkStart for VM 755, job origin: 12663
2018-02-15 14:27:58,322 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed) Unable
to complete AsyncJobVO {id:12664, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAC83QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAJzcQB-AAgAAAAAAAAABHBwcHNxAH4ACAAAAAAAAAABcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 279900894633337, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Thu Feb 15 14:27:37 EET 2018}, job origin:12663
2018-02-15 14:27:58,324 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed)
Complete async job-12664, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA2VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0xMi03NTUtVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAUc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AApMAAhmaWxlTmFtZXEAfgAKTAAKbWV0aG9kTmFtZXEAfgAKeHAAAAO9dAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0c3EAfgARAAAR_XEAfgATcQB-ABRxAH4AFXNxAH4AEf____90ACZzdW4ucmVmbGVjdC5HZW5lcmF0ZWRNZXRob2RBY2Nlc3NvcjMzOHB0AAZpbnZva2VzcQB-ABEAAAArdAAoc3VuLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAZc3EAfgARAAACXnQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-ABlzcQB-ABEAAABrdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9ic3EAfgARAAASnnEAfgATcQB-ABRxAH4AI3NxAH4AEQAAAGZ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4AEQAAAip0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-ABEAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-ABEAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgARAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AM3QAD2NhbGxXaXRoQ29udGV4dHNxAH4AEQAAADVxAH4ANnEAfgAzdAAOcnVuV2l0aENvbnRleHRzcQB-ABEAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-AC9xAH4AMHNxAH4AEQAAAfZxAH4AKnEAfgArcQB-ADBzcQB-ABEAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ADRzcQB-ABEAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAwc3EAfgARAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgARAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ARXEAfgAwc3EAfgARAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAwc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAx4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AUXhzcgARamF2YS5sYW5nLkludGVnZXIS4qCk94GHOAIAAUkABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAQ73NxAH4AUAAAAAB3BAAAAAB4c3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhxAH4AUwAAAAAAAAABdnIAF2NvbS5jbG91ZC5kYy5EYXRhQ2VudGVysvEK66fneL4CAAB4cAA
2018-02-15 14:27:58,325 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed)
Publish async job-12664 complete on message bus
2018-02-15 14:27:58,325 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed) Wake
up jobs related to job-12664
2018-02-15 14:27:58,325 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed) Update
db status for job-12664
2018-02-15 14:27:58,326 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed) Wake
up jobs joined with job-12664 and disjoin all subjobs created from job- 12664
2018-02-15 14:27:58,333 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed) Done
executing com.cloud.vm.VmWorkStart for job-12664
2018-02-15 14:27:58,334 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-75:ctx-135d49a0 job-12663/job-12664) (logid:945782ed) Remove
job-12664 from job monitoring
2018-02-15 14:27:58,350 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed) Sync
job-12665 execution on object VmWorkJobQueue.755
2018-02-15 14:27:58,700 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665) (logid:c45621f4) Add
job-12665 into job monitoring
2018-02-15 14:27:58,709 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665) (logid:945782ed)
Executing AsyncJobVO {id:12665, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAC83QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 279900894633337, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Thu Feb 15 14:27:58 EET 2018}
2018-02-15 14:27:58,709 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665) (logid:945782ed) Run VM
work job: com.cloud.vm.VmWorkStart for VM 755, job origin: 12663
2018-02-15 14:27:58,716 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":755,"handlerName":"VirtualMachineManagerImpl"}
2018-02-15 14:27:58,725 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) 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
2018-02-15 14:27:58,726 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Successfully transitioned to start state for
VM[User|i-12-755-VM] reservation id = cb4150b7-20cc-446d-8e69-34b0113585ef
2018-02-15 14:27:58,728 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Trying to deploy VM, vm has dcId: 1 and podId: 1
2018-02-15 14:27:58,728 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Deploy avoids pods: null, clusters: null, hosts: null
2018-02-15 14:27:58,740 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Root volume is ready, need to place VM in volume's cluster
2018-02-15 14:27:58,740 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Vol[800|vm=755|ROOT] is READY, changing deployment plan to use
this pool's dcId: 1 , podId: 1 , and clusterId: 2
2018-02-15 14:27:58,749 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Deploy avoids pods: [], clusters: [], hosts: []
2018-02-15 14:27:58,750 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@5cc91e40
2018-02-15 14:27:58,750 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:2, requested cpu: 1000, requested ram: 4294967296
2018-02-15 14:27:58,750 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Is ROOT volume READY (pool already allocated)?: Yes
2018-02-15 14:27:58,750 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Searching resources only under specified Cluster: 2
2018-02-15 14:27:58,761 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking resources in Cluster: 2 under Pod: 1
2018-02-15 14:27:58,761 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Looking for hosts in dc: 1 pod:1
cluster:2
2018-02-15 14:27:58,764 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) FirstFitAllocator has 1 hosts to
check for allocation: [Host[-4-Routing]]
2018-02-15 14:27:58,773 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Found 1 hosts for allocation after
prioritization: [Host[-4-Routing]]
2018-02-15 14:27:58,773 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Looking for speed=1000Mhz, Ram=4096
2018-02-15 14:27:58,780 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host: 4 has cpu capability (cpu:16,
speed:2394) to support requested CPU: 1 and requested speed: 1000
2018-02-15 14:27:58,780 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Checking if host: 4 has enough
capacity for requested CPU: 1000 and requested RAM: 4294967296 ,
cpuOverprovisioningFactor: 1.0
2018-02-15 14:27:58,781 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Hosts's actual total CPU: 38304 and
CPU after applying overprovisioning: 38304
2018-02-15 14:27:58,782 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Free CPU: 32304 , Requested CPU: 1000
2018-02-15 14:27:58,782 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Free RAM: 29488480256 , Requested
RAM: 4294967296
2018-02-15 14:27:58,782 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host has enough CPU and RAM available
2018-02-15 14:27:58,782 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) STATS: Can alloc CPU from host: 4,
used: 6000, reserved: 0, actual total: 38304, total with overprovisioning:
38304; requested cpu:1000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2018-02-15 14:27:58,782 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) STATS: Can alloc MEM from host: 4,
used: 17179869184, reserved: 0, total: 46668349440; requested mem:
4294967296,alloc_from_last_host?:false ,considerReservedCapacity?: true
2018-02-15 14:27:58,782 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Found a suitable host, adding to
list: 4
2018-02-15 14:27:58,782 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host Allocator returning 1 suitable
hosts
2018-02-15 14:27:58,784 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking suitable pools for volume (Id, Type): (800,ROOT)
2018-02-15 14:27:58,784 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Volume has pool already allocated, checking if pool can be
reused, poolId: 2
2018-02-15 14:27:58,785 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Planner need not allocate a pool for this volume since its
READY
2018-02-15 14:27:58,785 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Trying to find a potenial host and associated storage pools
from the suitable host/pool lists for this VM
2018-02-15 14:27:58,785 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking if host: 4 can access any suitable storage pool for
volume: ROOT
2018-02-15 14:27:58,786 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Host: 4 can access pool: 2
2018-02-15 14:27:58,787 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Found a potential host id: 4 name: CSJOHQAZ02 and associated
storage pools for this VM
2018-02-15 14:27:58,788 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(2)-Host(4)-Storage()]
2018-02-15 14:27:58,788 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Deployment found - P0=VM[User|i-12-755-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(2)-Host(4)-Storage()]
2018-02-15 14:27:58,800 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) VM state transitted from :Starting to Starting with event:
OperationRetryvm's original host id: null new host id: 4 host id before state
transition: null
2018-02-15 14:27:58,805 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Hosts's actual total CPU: 38304 and CPU after applying
overprovisioning: 38304
2018-02-15 14:27:58,805 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) We are allocating VM, increasing the used capacity of this
host:4
2018-02-15 14:27:58,805 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Current Used CPU: 6000 , Free CPU:32304 ,Requested CPU: 1000
2018-02-15 14:27:58,805 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Current Used RAM: 17179869184 , Free RAM:29488480256
,Requested RAM: 4294967296
2018-02-15 14:27:58,805 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) CPU STATS after allocation: for host: 4, old used: 6000, old
reserved: 0, actual total: 38304, total with overprovisioning: 38304; new
used:7000, reserved:0; requested cpu:1000,alloc_from_last:false
2018-02-15 14:27:58,805 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) RAM STATS after allocation: for host: 4, old used:
17179869184, old reserved: 0, total: 46668349440; new used: 21474836480,
reserved: 0; requested mem: 4294967296,alloc_from_last:false
2018-02-15 14:27:58,808 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) VM is being created in podId: 1
2018-02-15 14:27:58,816 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Network id=204 is already implemented
2018-02-15 14:27:58,823 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:27:58,826 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Changing active number of nics for network id=204 on 1
2018-02-15 14:27:58,832 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Asking VirtualRouter to prepare for
Nic[735-755-null-192.168.124.116]
2018-02-15 14:27:58,847 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:27:58,849 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) CONFIG DHCP FOR SUBNETS RULES
2018-02-15 14:27:58,859 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:27:58,861 DEBUG [o.a.c.n.t.AdvancedNetworkTopology]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) APPLYING VPC DHCP ENTRY RULES
2018-02-15 14:27:58,861 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Applying dhcp entry in network Ntwk[204|Guest|7]
2018-02-15 14:27:58,879 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467485: Sending { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f1:64:00:04:0d","vmIpAddress":"192.168.124.116","vmName":"Linux0","defaultRouter":"192.168.124.1","defaultDns":"192.168.124.101","duid":"00:03:00:01:06:f1:64:00:04:0d","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"192.168.124.180","router.ip":"169.254.2.33","router.name":"r-430-VM"},"wait":0}}]
}
2018-02-15 14:27:58,880 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467485: Executing: { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f1:64:00:04:0d","vmIpAddress":"192.168.124.116","vmName":"Linux0","defaultRouter":"192.168.124.1","defaultDns":"192.168.124.101","duid":"00:03:00:01:06:f1:64:00:04:0d","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"192.168.124.180","router.ip":"169.254.2.33","router.name":"r-430-VM"},"wait":0}}]
}
2018-02-15 14:28:02,719 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467485: Received: { Ans: , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 10, { GroupAnswer } }
2018-02-15 14:28:02,729 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:28:02,731 DEBUG [o.a.c.n.t.AdvancedNetworkTopology]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) APPLYING VPC USERDATA RULES
2018-02-15 14:28:02,731 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Applying userdata and password entry in network
Ntwk[204|Guest|7]
2018-02-15 14:28:02,747 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467486: Sending { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}}]
}
2018-02-15 14:28:02,748 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467486: Executing: { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}}]
}
2018-02-15 14:28:15,786 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467486: Received: { Ans: , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 10, { GroupAnswer,
GroupAnswer } }
2018-02-15 14:28:15,792 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:28:15,794 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking if we need to prepare 1 volumes for
VM[User|i-12-755-VM]
2018-02-15 14:28:15,794 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) No need to recreate the volume: Vol[800|vm=755|ROOT], since it
already has a pool assigned: 2, adding disk to VM
2018-02-15 14:28:15,846 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 4-7650771341972519540: Sending { Cmd , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":755,"name":"i-12-755-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":1000,"maxSpeed":1000,"minRam":4294967296,"maxRam":4294967296,"arch":"x86_64","os":"Red
Hat Enterprise Linux 6.5 (64-bit)","platformEmulator":"Red Hat Enterprise
Linux 6
(64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"usywgVWnVawf4y-7O95nDA","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true","hypervisortoolsversion":"xenserver56","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"c19e77dd-d886-4851-8234-124a6efda216","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0b828762-662a-41c8-9e5a-ae579773cb1c","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"68996ac2-f860-a1aa-0a7b-e820d47ba19b","id":2,"poolType":"LVM","host":"192.168.120.11","path":"lvm","port":0,"url":"LVM://192.168.120.11/lvm/?ROLE=Primary&STOREUUID=68996ac2-f860-a1aa-0a7b-e820d47ba19b"}},"name":"ROOT-755","size":21474836480,"path":"7c33ebfa-1297-4e42-99a6-4c44513d8ed8","volumeId":800,"vmName":"i-12-755-VM","accountId":12,"format":"VHD","provisioningType":"THIN","id":800,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"7c33ebfa-1297-4e42-99a6-4c44513d8ed8","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"192.168.120.11","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":1024,"defaultNic":true,"pxeDisable":false,"nicUuid":"58e74763-6cb4-4e83-ae2d-10133eecbfce","uuid":"8ee795fd-005a-4f51-99cb-5d3959f95a90","ip":"192.168.124.116","netmask":"255.255.252.0","gateway":"192.168.124.1","mac":"06:f1:64:00:04:0d","dns1":"192.168.30.2","dns2":"192.168.30.3","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://240","isolationUri":"vlan://240","isSecurityGroupEnabled":false,"name":"MGMT"}],"vcpuMaxLimit":16},"hostIp":"192.168.120.11","executeInSequence":false,"wait":0}}]
}
2018-02-15 14:28:15,846 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 4-7650771341972519540: Executing: { Cmd , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":755,"name":"i-12-755-VM","bootloader":"PyGrub","type":"User","cpus":1,"minSpeed":1000,"maxSpeed":1000,"minRam":4294967296,"maxRam":4294967296,"arch":"x86_64","os":"Red
Hat Enterprise Linux 6.5 (64-bit)","platformEmulator":"Red Hat Enterprise
Linux 6
(64-bit)","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"usywgVWnVawf4y-7O95nDA","params":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true","hypervisortoolsversion":"xenserver56","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"c19e77dd-d886-4851-8234-124a6efda216","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0b828762-662a-41c8-9e5a-ae579773cb1c","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"68996ac2-f860-a1aa-0a7b-e820d47ba19b","id":2,"poolType":"LVM","host":"192.168.120.11","path":"lvm","port":0,"url":"LVM://192.168.120.11/lvm/?ROLE=Primary&STOREUUID=68996ac2-f860-a1aa-0a7b-e820d47ba19b"}},"name":"ROOT-755","size":21474836480,"path":"7c33ebfa-1297-4e42-99a6-4c44513d8ed8","volumeId":800,"vmName":"i-12-755-VM","accountId":12,"format":"VHD","provisioningType":"THIN","id":800,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"XenServer"}},"diskSeq":0,"path":"7c33ebfa-1297-4e42-99a6-4c44513d8ed8","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"192.168.120.11","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":1024,"defaultNic":true,"pxeDisable":false,"nicUuid":"58e74763-6cb4-4e83-ae2d-10133eecbfce","uuid":"8ee795fd-005a-4f51-99cb-5d3959f95a90","ip":"192.168.124.116","netmask":"255.255.252.0","gateway":"192.168.124.1","mac":"06:f1:64:00:04:0d","dns1":"192.168.30.2","dns2":"192.168.30.3","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://240","isolationUri":"vlan://240","isSecurityGroupEnabled":false,"name":"MGMT"}],"vcpuMaxLimit":16},"hostIp":"192.168.120.11","executeInSequence":false,"wait":0}}]
}
2018-02-15 14:28:17,022 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 4-7650771341972519540: Received: { Ans: , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 10, { StartAnswer } }
2018-02-15 14:28:17,025 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Unable to start VM on Host[-4-Routing] due to Unable to start
i-12-755-VM due to
2018-02-15 14:28:17,028 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Cleaning up resources for the vm VM[User|i-12-755-VM] in
Starting state
2018-02-15 14:28:17,031 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 4-7650771341972519541: Sending { Cmd , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-12-755-VM","executeInSequence":false,"wait":0}}]
}
2018-02-15 14:28:17,031 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 4-7650771341972519541: Executing: { Cmd , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-12-755-VM","executeInSequence":false,"wait":0}}]
}
2018-02-15 14:28:17,037 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 4-7650771341972519541: Received: { Ans: , MgmtId:
279900894633337, via: 4(CSJOHQAZ02), Ver: v1, Flags: 10, { StopAnswer } }
2018-02-15 14:28:17,043 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Changing active number of nics for network id=204 on -1
2018-02-15 14:28:17,049 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Successfully released network resources for the vm
VM[User|i-12-755-VM]
2018-02-15 14:28:17,049 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Successfully cleanued up resources for the vm
VM[User|i-12-755-VM] in Starting state
2018-02-15 14:28:17,051 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Root volume is ready, need to place VM in volume's cluster
2018-02-15 14:28:17,051 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Vol[800|vm=755|ROOT] is READY, changing deployment plan to use
this pool's dcId: 1 , podId: 1 , and clusterId: 2
2018-02-15 14:28:17,059 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Deploy avoids pods: [], clusters: [], hosts: [4]
2018-02-15 14:28:17,059 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@5cc91e40
2018-02-15 14:28:17,060 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:2, requested cpu: 1000, requested ram: 4294967296
2018-02-15 14:28:17,060 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Is ROOT volume READY (pool already allocated)?: Yes
2018-02-15 14:28:17,060 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Searching resources only under specified Cluster: 2
2018-02-15 14:28:17,071 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking resources in Cluster: 2 under Pod: 1
2018-02-15 14:28:17,071 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Looking for hosts in dc: 1 pod:1
cluster:2
2018-02-15 14:28:17,073 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) FirstFitAllocator has 1 hosts to
check for allocation: [Host[-4-Routing]]
2018-02-15 14:28:17,077 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Found 1 hosts for allocation after
prioritization: [Host[-4-Routing]]
2018-02-15 14:28:17,077 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Looking for speed=1000Mhz, Ram=4096
2018-02-15 14:28:17,077 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host name: CSJOHQAZ02, hostId: 4 is
in avoid set, skipping this and trying other available hosts
2018-02-15 14:28:17,077 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host Allocator returning 0 suitable
hosts
2018-02-15 14:28:17,077 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) No suitable hosts found
2018-02-15 14:28:17,077 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) No suitable hosts found under this Cluster: 2
2018-02-15 14:28:17,078 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Could not find suitable Deployment Destination for this VM
under any clusters, returning.
2018-02-15 14:28:17,078 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Searching resources only under specified Cluster: 2
2018-02-15 14:28:17,079 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) The specified cluster is in avoid set, returning.
2018-02-15 14:28:17,087 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Deploy avoids pods: [], clusters: [2], hosts: [4]
2018-02-15 14:28:17,088 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@5cc91e40
2018-02-15 14:28:17,088 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:null, requested cpu: 1000, requested ram: 4294967296
2018-02-15 14:28:17,088 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Is ROOT volume READY (pool already allocated)?: No
2018-02-15 14:28:17,088 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Searching resources only under specified Pod: 1
2018-02-15 14:28:17,088 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Listing clusters in order of aggregate capacity, that have
(atleast one host with) enough CPU and RAM capacity under this Pod: 1
2018-02-15 14:28:17,091 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Removing from the clusterId list these clusters from avoid
set: [2]
2018-02-15 14:28:17,115 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking resources in Cluster: 3 under Pod: 1
2018-02-15 14:28:17,115 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Looking for hosts in dc: 1 pod:1
cluster:3
2018-02-15 14:28:17,117 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) FirstFitAllocator has 1 hosts to
check for allocation: [Host[-5-Routing]]
2018-02-15 14:28:17,121 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Found 1 hosts for allocation after
prioritization: [Host[-5-Routing]]
2018-02-15 14:28:17,121 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Looking for speed=1000Mhz, Ram=4096
2018-02-15 14:28:17,127 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host: 5 has cpu capability (cpu:16,
speed:2394) to support requested CPU: 1 and requested speed: 1000
2018-02-15 14:28:17,127 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Checking if host: 5 has enough
capacity for requested CPU: 1000 and requested RAM: 4294967296 ,
cpuOverprovisioningFactor: 1.0
2018-02-15 14:28:17,129 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Hosts's actual total CPU: 38304 and
CPU after applying overprovisioning: 38304
2018-02-15 14:28:17,129 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Free CPU: 30304 , Requested CPU: 1000
2018-02-15 14:28:17,129 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Free RAM: 36501356544 , Requested
RAM: 4294967296
2018-02-15 14:28:17,129 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host has enough CPU and RAM available
2018-02-15 14:28:17,129 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) STATS: Can alloc CPU from host: 5,
used: 8000, reserved: 0, actual total: 38304, total with overprovisioning:
38304; requested cpu:1000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2018-02-15 14:28:17,129 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) STATS: Can alloc MEM from host: 5,
used: 25769803776, reserved: 0, total: 62271160320; requested mem:
4294967296,alloc_from_last_host?:false ,considerReservedCapacity?: true
2018-02-15 14:28:17,129 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Found a suitable host, adding to
list: 5
2018-02-15 14:28:17,129 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host Allocator returning 1 suitable
hosts
2018-02-15 14:28:17,131 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking suitable pools for volume (Id, Type): (800,ROOT)
2018-02-15 14:28:17,131 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) We need to allocate new storagepool for this volume
2018-02-15 14:28:17,133 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Calling StoragePoolAllocators to find suitable pools
2018-02-15 14:28:17,133 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) LocalStoragePoolAllocator trying to find storage pool to fit
the vm
2018-02-15 14:28:17,135 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking if storage pool is suitable, name: null ,poolId: 3
2018-02-15 14:28:17,137 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Storage pool null (3) does not supply IOPS capacity, assuming
enough capacity
2018-02-15 14:28:17,138 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking pool 3 for storage, totalSize: 1189156487168,
usedBytes: 874189422592, usedPct: 0.7351340483992141, disable threshold: 0.95
2018-02-15 14:28:17,144 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Found storage pool CSJOHQAZ03 Local Storage of type LVM
2018-02-15 14:28:17,144 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Total capacity of the pool CSJOHQAZ03 Local Storage id: 3 is
1189156487168
2018-02-15 14:28:17,145 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking pool: 3 for volume allocation [Vol[800|vm=755|ROOT]],
maxSize : 1189156487168, totalAllocatedSize : 1326255702016, askingSize : 0,
allocated disable threshold: 0.95
2018-02-15 14:28:17,145 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Insufficient un-allocated capacity on: 3 for volume
allocation: [Vol[800|vm=755|ROOT]] since its allocated percentage:
1.11529114656264 has crossed the allocated
pool.storage.allocated.capacity.disablethreshold: 0.95, skipping this pool
2018-02-15 14:28:17,145 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) LocalStoragePoolAllocator returning 0 suitable storage pools
2018-02-15 14:28:17,145 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) ClusterScopeStoragePoolAllocator looking for storage pool
2018-02-15 14:28:17,145 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) ZoneWideStoragePoolAllocator to find storage pool
2018-02-15 14:28:17,145 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) No suitable pools found for volume: Vol[800|vm=755|ROOT] under
cluster: 3
2018-02-15 14:28:17,145 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) No suitable pools found
2018-02-15 14:28:17,145 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) No suitable storagePools found under this Cluster: 3
2018-02-15 14:28:17,148 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking resources in Cluster: 5 under Pod: 1
2018-02-15 14:28:17,148 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Looking for hosts in dc: 1 pod:1
cluster:5
2018-02-15 14:28:17,150 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) FirstFitAllocator has 1 hosts to
check for allocation: [Host[-7-Routing]]
2018-02-15 14:28:17,152 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Found 1 hosts for allocation after
prioritization: [Host[-7-Routing]]
2018-02-15 14:28:17,152 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Looking for speed=1000Mhz, Ram=4096
2018-02-15 14:28:17,156 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host: 7 has cpu capability (cpu:24,
speed:1900) to support requested CPU: 1 and requested speed: 1000
2018-02-15 14:28:17,156 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Checking if host: 7 has enough
capacity for requested CPU: 1000 and requested RAM: 4294967296 ,
cpuOverprovisioningFactor: 1.0
2018-02-15 14:28:17,157 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Hosts's actual total CPU: 45600 and
CPU after applying overprovisioning: 45600
2018-02-15 14:28:17,157 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Free CPU: 34600 , Requested CPU: 1000
2018-02-15 14:28:17,157 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Free RAM: 36733681664 , Requested
RAM: 4294967296
2018-02-15 14:28:17,157 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host has enough CPU and RAM available
2018-02-15 14:28:17,157 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) STATS: Can alloc CPU from host: 7,
used: 11000, reserved: 0, actual total: 45600, total with overprovisioning:
45600; requested cpu:1000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2018-02-15 14:28:17,157 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) STATS: Can alloc MEM from host: 7,
used: 25501368320, reserved: 0, total: 62235049984; requested mem:
4294967296,alloc_from_last_host?:false ,considerReservedCapacity?: true
2018-02-15 14:28:17,157 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Found a suitable host, adding to
list: 7
2018-02-15 14:28:17,157 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760
FirstFitRoutingAllocator) (logid:945782ed) Host Allocator returning 1 suitable
hosts
2018-02-15 14:28:17,159 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking suitable pools for volume (Id, Type): (800,ROOT)
2018-02-15 14:28:17,159 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) We need to allocate new storagepool for this volume
2018-02-15 14:28:17,160 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Calling StoragePoolAllocators to find suitable pools
2018-02-15 14:28:17,160 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) LocalStoragePoolAllocator trying to find storage pool to fit
the vm
2018-02-15 14:28:17,162 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking if storage pool is suitable, name: null ,poolId: 5
2018-02-15 14:28:17,163 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Storage pool null (5) does not supply IOPS capacity, assuming
enough capacity
2018-02-15 14:28:17,164 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking pool 5 for storage, totalSize: 2389599846400,
usedBytes: 568558878720, usedPct: 0.23793058054324454, disable threshold: 0.95
2018-02-15 14:28:17,169 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Found storage pool CSJOHQAZ05 Local Storage of type LVM
2018-02-15 14:28:17,169 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Total capacity of the pool CSJOHQAZ05 Local Storage id: 5 is
2389599846400
2018-02-15 14:28:17,170 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking pool: 5 for volume allocation [Vol[800|vm=755|ROOT]],
maxSize : 2389599846400, totalAllocatedSize : 754609815552, askingSize : 0,
allocated disable threshold: 0.95
2018-02-15 14:28:17,171 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) LocalStoragePoolAllocator returning 1 suitable storage pools
2018-02-15 14:28:17,171 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Trying to find a potenial host and associated storage pools
from the suitable host/pool lists for this VM
2018-02-15 14:28:17,171 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking if host: 7 can access any suitable storage pool for
volume: ROOT
2018-02-15 14:28:17,171 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Host: 7 can access pool: 5
2018-02-15 14:28:17,172 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Found a potential host id: 7 name: CSJOHQAZ05 and associated
storage pools for this VM
2018-02-15 14:28:17,173 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(5)-Host(7)-Storage(Volume(800|ROOT-->Pool(5))]
2018-02-15 14:28:17,173 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Deployment found - P0=VM[User|i-12-755-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(5)-Host(7)-Storage(Volume(800|ROOT-->Pool(5))]
2018-02-15 14:28:17,185 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) VM state transitted from :Starting to Starting with event:
OperationRetryvm's original host id: null new host id: 7 host id before state
transition: 4
2018-02-15 14:28:17,191 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Hosts's actual total CPU: 38304 and CPU after applying
overprovisioning: 38304
2018-02-15 14:28:17,191 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Hosts's actual total RAM: 46668350336 and RAM after applying
overprovisioning: 46668349440
2018-02-15 14:28:17,191 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) release cpu from host: 4, old used: 7000,reserved: 0, actual
total: 38304, total with overprovisioning: 38304; new used: 6000,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2018-02-15 14:28:17,191 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) release mem from host: 4, old used: 21474836480,reserved: 0,
total: 46668349440; new used: 17179869184,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2018-02-15 14:28:17,201 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Hosts's actual total CPU: 45600 and CPU after applying
overprovisioning: 45600
2018-02-15 14:28:17,201 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) We are allocating VM, increasing the used capacity of this
host:7
2018-02-15 14:28:17,201 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Current Used CPU: 11000 , Free CPU:34600 ,Requested CPU: 1000
2018-02-15 14:28:17,201 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Current Used RAM: 25501368320 , Free RAM:36733681664
,Requested RAM: 4294967296
2018-02-15 14:28:17,201 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) CPU STATS after allocation: for host: 7, old used: 11000, old
reserved: 0, actual total: 45600, total with overprovisioning: 45600; new
used:12000, reserved:0; requested cpu:1000,alloc_from_last:false
2018-02-15 14:28:17,201 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) RAM STATS after allocation: for host: 7, old used:
25501368320, old reserved: 0, total: 62235049984; new used: 29796335616,
reserved: 0; requested mem: 4294967296,alloc_from_last:false
2018-02-15 14:28:17,204 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) VM is being created in podId: 1
2018-02-15 14:28:17,212 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Network id=204 is already implemented
2018-02-15 14:28:17,218 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:28:17,221 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Changing active number of nics for network id=204 on 1
2018-02-15 14:28:17,228 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Asking VirtualRouter to prepare for
Nic[735-755-null-192.168.124.116]
2018-02-15 14:28:17,243 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:28:17,245 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) CONFIG DHCP FOR SUBNETS RULES
2018-02-15 14:28:17,254 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:28:17,256 DEBUG [o.a.c.n.t.AdvancedNetworkTopology]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) APPLYING VPC DHCP ENTRY RULES
2018-02-15 14:28:17,256 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Applying dhcp entry in network Ntwk[204|Guest|7]
2018-02-15 14:28:17,274 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467491: Sending { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f1:64:00:04:0d","vmIpAddress":"192.168.124.116","vmName":"Linux0","defaultRouter":"192.168.124.1","defaultDns":"192.168.124.101","duid":"00:03:00:01:06:f1:64:00:04:0d","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"192.168.124.180","router.ip":"169.254.2.33","router.name":"r-430-VM"},"wait":0}}]
}
2018-02-15 14:28:17,274 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467491: Executing: { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:f1:64:00:04:0d","vmIpAddress":"192.168.124.116","vmName":"Linux0","defaultRouter":"192.168.124.1","defaultDns":"192.168.124.101","duid":"00:03:00:01:06:f1:64:00:04:0d","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"192.168.124.180","router.ip":"169.254.2.33","router.name":"r-430-VM"},"wait":0}}]
}
2018-02-15 14:28:21,215 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467491: Received: { Ans: , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 10, { GroupAnswer } }
2018-02-15 14:28:21,225 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:28:21,226 DEBUG [o.a.c.n.t.AdvancedNetworkTopology]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) APPLYING VPC USERDATA RULES
2018-02-15 14:28:21,227 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Applying userdata and password entry in network
Ntwk[204|Guest|7]
2018-02-15 14:28:21,248 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467492: Sending { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}}]
}
2018-02-15 14:28:21,249 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467492: Executing: { Cmd , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.124.116","vmName":"Linux0","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-430-VM","router.ip":"169.254.2.33","router.guest.ip":"192.168.124.180"},"wait":0}}]
}
2018-02-15 14:28:33,681 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 13-2847119389428467492: Received: { Ans: , MgmtId:
279900894633337, via: 13(CSJOHQAZ09), Ver: v1, Flags: 10, { GroupAnswer,
GroupAnswer } }
2018-02-15 14:28:33,698 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Service SecurityGroup is not supported in the network id=204
2018-02-15 14:28:33,700 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Checking if we need to prepare 1 volumes for
VM[User|i-12-755-VM]
2018-02-15 14:28:33,701 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Mismatch in storage pool Pool[5|LVM] assigned by
deploymentPlanner and the one associated with volume Vol[800|vm=755|ROOT]
2018-02-15 14:28:33,701 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Local volume Vol[800|vm=755|ROOT] cannot be recreated on
storagepool Pool[5|LVM] assigned by deploymentPlanner
2018-02-15 14:28:33,704 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Cleaning up resources for the vm VM[User|i-12-755-VM] in
Starting state
2018-02-15 14:28:33,707 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 7-6421007168723663279: Sending { Cmd , MgmtId:
279900894633337, via: 7(CSJOHQAZ05), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-12-755-VM","executeInSequence":false,"wait":0}}]
}
2018-02-15 14:28:33,707 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 7-6421007168723663279: Executing: { Cmd , MgmtId:
279900894633337, via: 7(CSJOHQAZ05), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-12-755-VM","executeInSequence":false,"wait":0}}]
}
2018-02-15 14:28:33,716 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Seq 7-6421007168723663279: Received: { Ans: , MgmtId:
279900894633337, via: 7(CSJOHQAZ05), Ver: v1, Flags: 10, { StopAnswer } }
2018-02-15 14:28:33,722 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Changing active number of nics for network id=204 on -1
2018-02-15 14:28:33,728 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Successfully released network resources for the vm
VM[User|i-12-755-VM]
2018-02-15 14:28:33,728 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Successfully cleanued up resources for the vm
VM[User|i-12-755-VM] in Starting state
2018-02-15 14:28:33,736 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) VM state transitted from :Starting to Stopped with event:
OperationFailedvm's original host id: null new host id: null host id before
state transition: 7
2018-02-15 14:28:33,741 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Hosts's actual total CPU: 45600 and CPU after applying
overprovisioning: 45600
2018-02-15 14:28:33,741 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Hosts's actual total RAM: 62235048448 and RAM after applying
overprovisioning: 62235049984
2018-02-15 14:28:33,741 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) release cpu from host: 7, old used: 12000,reserved: 0, actual
total: 45600, total with overprovisioning: 45600; new used: 11000,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2018-02-15 14:28:33,741 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) release mem from host: 7, old used: 29796335616,reserved: 0,
total: 62235049984; new used: 25501368320,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2018-02-15 14:28:33,751 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Caught CloudRuntimeException, returning job failed
2018-02-15 14:28:33,751 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Done executing VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":755,"handlerName":"VirtualMachineManagerImpl"}
2018-02-15 14:28:33,751 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Complete async job-12665, jobStatus: FAILED, resultCode: 0,
result: null
2018-02-15 14:28:33,752 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Publish async job-12665 complete on message bus
2018-02-15 14:28:33,752 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Wake up jobs related to job-12665
2018-02-15 14:28:33,752 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Update db status for job-12665
2018-02-15 14:28:33,753 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665 ctx-6bdf2760)
(logid:945782ed) Wake up jobs joined with job-12665 and disjoin all subjobs
created from job- 12665
2018-02-15 14:28:33,763 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665) (logid:945782ed) Done
with run of VM work job: com.cloud.vm.VmWorkStart for VM 755, job origin: 12663
2018-02-15 14:28:33,763 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665) (logid:945782ed) Done
executing com.cloud.vm.VmWorkStart for job-12665
2018-02-15 14:28:33,767 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-76:ctx-88e2074c job-12663/job-12665) (logid:945782ed) Remove
job-12665 from job monitoring
2018-02-15 14:28:33,768 ERROR [c.c.v.UserVmManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed) VM
VM[User|i-12-755-VM] unexpectedly went to Stopped state
2018-02-15 14:28:33,770 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Destroying vm VM[User|i-12-755-VM] as it failed to create on Host with Id:null
2018-02-15 14:28:33,782 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed) 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
2018-02-15 14:28:33,819 DEBUG [c.c.u.AccountManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Access granted to Acct[3db210e4-e8b8-11e6-a049-fe9181659d79-admin] to Domain:1/
by AffinityGroupAccessChecker
2018-02-15 14:28:33,824 WARN [o.a.c.alerts] (API-Job-Executor-72:ctx-e21cd7f5
job-12663 ctx-54d3b6a8) (logid:945782ed) alertType:: 8 // dataCenterId:: 1 //
podId:: 1 // clusterId:: null // message:: Failed to deploy Vm with Id: 755, on
Host with Id: null
2018-02-15 14:28:33,849 WARN [o.a.c.a.c.a.v.DeployVMCmdByAdmin]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663 ctx-54d3b6a8) (logid:945782ed)
Exception:
2018-02-15 14:28:33,850 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663) (logid:945782ed) Complete async
job-12663, jobStatus: FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed
to deploy VM VM[User|i-12-755-VM]"}
2018-02-15 14:28:33,851 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663) (logid:945782ed) Publish async
job-12663 complete on message bus
2018-02-15 14:28:33,851 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663) (logid:945782ed) Wake up jobs
related to job-12663
2018-02-15 14:28:33,851 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663) (logid:945782ed) Update db status
for job-12663
2018-02-15 14:28:33,852 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663) (logid:945782ed) Wake up jobs
joined with job-12663 and disjoin all subjobs created from job- 12663
2018-02-15 14:28:33,855 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663) (logid:945782ed) Done executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-12663
2018-02-15 14:28:33,855 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-72:ctx-e21cd7f5 job-12663) (logid:945782ed) Remove job-12663
from job monitoring
Best Regards,
