cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ghaith Bannoura <gbanno...@etq.com>
Subject RE: Failed to deploy VM Error
Date Thu, 15 Feb 2018 14:53:16 GMT
Hello Dag,

I uploaded it on google Drive the link as below 

https://drive.google.com/open?id=1ewXtKhjZRvxS126_ewifiatmSZlpdBZI



Best Regards,
Ghaith Bannoura

-----Original Message-----
From: Dag Sonstebo [mailto:Dag.Sonstebo@shapeblue.com] 
Sent: Thursday, February 15, 2018 4:15 PM
To: users@cloudstack.apache.org
Subject: Re: Failed to deploy VM Error

Hi Ghait,

I guess you have grep’ed the logs to get the below – in short there’s not enough info here, you go from the start command straight to the failure without any explanation. If you can upload the full logs somewhere they may make more sense.

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

Regards,
Dag Sonstebo
Cloud Architect
ShapeBlue

On 15/02/2018, 13:46, "Ghaith Bannoura" <gbannoura@etq.com> wrote:

    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,
    
    


Dag.Sonstebo@shapeblue.com 
www.shapeblue.com
53 Chandos Place, Covent Garden, London  WC2N 4HSUK
@shapeblue
  
 

Mime
View raw message