Hello,
Asynchronous creating VM bring to "Unable to start VM on Host[-1-Routing]
due to failed to get free memory". After that I see ERROR:
InsufficientServerCapacityException.
In previous messages I see large amount of free resources:
2019-07-24 04:50:45,443 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6)
(logid:b6e33d80) Current Used CPU: 115708 , Free CPU:76356 ,Requested CPU:
512
2019-07-24 04:50:45,443 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6)
(logid:b6e33d80) Current Used RAM: 122003914752 , Free RAM:145667670016
,Requested RAM: 536870912
2019-07-24 04:50:45,443 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6)
(logid:b6e33d80) CPU STATS after allocation: for host: 1, old used: 115708,
old reserved: 1536, actual total: 193600, total with overprovisioning:
193600; new used:116220, reserved:1536; requested
cpu:512,alloc_from_last:false
2019-07-24 04:50:45,443 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6)
(logid:b6e33d80) RAM STATS after allocation: for host: 1, old used:
122003914752, old reserved: 1610612736, total: 269282197504; new used:
122540785664, reserved: 1610612736; requested mem:
536870912,alloc_from_last:false
How it possible?
Thanks in advance for the help,
Dmitry.
2019-07-24 04:50:41,492 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443) (logid:b6e33d80) Executing AsyncJobVO {id:2281443, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 328404, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"apikey":"xRZ8vfHekftVn43EKETrcVlgJu-Vcd7c47-GjsiEIlGhF-D428h5HruTGaN21uDuNsYTsB-NTW8QCTJM8sz2yQ","iptonetworklist[0].networkid":"ff6f6044-c55f-44c0-bf67-66cbf9382b16","signature":"erAgp0qDQtLEM6bi9r7vlbDU8AY\u003d","httpmethod":"GET","templateid":"4c94a2ef-c2fe-4479-af88-03fa3595fbb4","ctxAccountId":"2","uuid":"d94ac4ca-80af-4dc2-b4f9-44d4bfb485a1","cmdEventType":"VM.CREATE","startvm":"True","serviceofferingid":"620073b7-fde4-4eae-8680-e17badfa7585","response":"json","ctxUserId":"2","hypervisor":"KVM","iptonetworklist[1].networkid":"59c2e9e8-8525-47a6-85c8-08d97b3c3cb8","name":"redistr-200-61594-smoke-gre-90-ee02954c","zoneid":"d103e528-c0b0-471e-ad55-2b99c47c4dee","ctxStartEventId":"5705532","id":"328404","ctxDetails":"{\"interface com.cloud.offering.ServiceOffering\":\"620073b7-fde4-4eae-8680-e17badfa7585\",\"interface com.cloud.dc.DataCenter\":\"d103e528-c0b0-471e-ad55-2b99c47c4dee\",\"interface com.cloud.vm.VirtualMachine\":\"d94ac4ca-80af-4dc2-b4f9-44d4bfb485a1\",\"interface com.cloud.template.VirtualMachineTemplate\":\"4c94a2ef-c2fe-4479-af88-03fa3595fbb4\"}"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038011117232, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2019-07-24 04:50:41,564 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:50:41,573 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=248958
2019-07-24 04:50:41,577 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:50:41,578 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=248958
2019-07-24 04:50:41,588 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) DeploymentPlanner allocation algorithm: null
2019-07-24 04:50:41,589 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 512, requested ram: 536870912
2019-07-24 04:50:41,589 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Is ROOT volume READY (pool already allocated)?: No
2019-07-24 04:50:41,596 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Deploy avoids pods: [], clusters: [], hosts: []
2019-07-24 04:50:41,597 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Searching all possible resources under this Zone: 1
2019-07-24 04:50:41,598 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2019-07-24 04:50:41,601 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Removing from the clusterId list these clusters from avoid set: []
2019-07-24 04:50:41,611 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Checking resources in Cluster: 1 under Pod: 1
2019-07-24 04:50:41,611 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Looking for hosts in dc: 1 pod:1 cluster:1
2019-07-24 04:50:41,613 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) FirstFitAllocator has 2 hosts to check for allocation: [Host[-1-Routing], Host[-5-Routing]]
2019-07-24 04:50:41,619 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Found 2 hosts for allocation after prioritization: [Host[-1-Routing], Host[-5-Routing]]
2019-07-24 04:50:41,619 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Looking for speed=512Mhz, Ram=512
2019-07-24 04:50:41,629 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Host: 1 has cpu capability (cpu:88, speed:2200) to support requested CPU: 1 and requested speed: 512
2019-07-24 04:50:41,630 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Checking if host: 1 has enough capacity for requested CPU: 512 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2019-07-24 04:50:41,631 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Hosts's actual total CPU: 193600 and CPU after applying overprovisioning: 193600
2019-07-24 04:50:41,631 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Free CPU: 76356 , Requested CPU: 512
2019-07-24 04:50:41,631 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Free RAM: 145667670016 , Requested RAM: 536870912
2019-07-24 04:50:41,631 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Host has enough CPU and RAM available
2019-07-24 04:50:41,631 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) STATS: Can alloc CPU from host: 1, used: 117244, reserved: 0, actual total: 193600, total with overprovisioning: 193600; requested cpu:512,alloc_from_last_host?:false ,considerReservedCapacity?: true
2019-07-24 04:50:41,631 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) STATS: Can alloc MEM from host: 1, used: 123614527488, reserved: 0, total: 269282197504; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2019-07-24 04:50:41,631 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Found a suitable host, adding to list: 1
2019-07-24 04:50:41,641 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Host: 5 has cpu capability (cpu:28, speed:2200) to support requested CPU: 1 and requested speed: 512
2019-07-24 04:50:41,641 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Checking if host: 5 has enough capacity for requested CPU: 512 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2019-07-24 04:50:41,643 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Hosts's actual total CPU: 61600 and CPU after applying overprovisioning: 61600
2019-07-24 04:50:41,643 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Free CPU: 3840 , Requested CPU: 512
2019-07-24 04:50:41,643 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Free RAM: 5458247680 , Requested RAM: 536870912
2019-07-24 04:50:41,643 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Host has enough CPU and RAM available
2019-07-24 04:50:41,643 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) STATS: Can alloc CPU from host: 5, used: 57760, reserved: 0, actual total: 61600, total with overprovisioning: 61600; requested cpu:512,alloc_from_last_host?:false ,considerReservedCapacity?: true
2019-07-24 04:50:41,643 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) STATS: Can alloc MEM from host: 5, used: 60666413056, reserved: 0, total: 66124660736; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2019-07-24 04:50:41,643 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Found a suitable host, adding to list: 5
2019-07-24 04:50:41,643 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82 FirstFitRoutingAllocator) (logid:b6e33d80) Host Allocator returning 2 suitable hosts
2019-07-24 04:50:41,646 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Checking suitable pools for volume (Id, Type): (275741,ROOT)
2019-07-24 04:50:41,646 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) We need to allocate new storagepool for this volume
2019-07-24 04:50:41,647 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Calling StoragePoolAllocators to find suitable pools
2019-07-24 04:50:41,648 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2019-07-24 04:50:41,648 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) ClusterScopeStoragePoolAllocator looking for storage pool
2019-07-24 04:50:41,648 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored.
2019-07-24 04:50:41,649 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Found pools matching tags: []
2019-07-24 04:50:41,650 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) No storage pools available for shared volume allocation, returning
2019-07-24 04:50:41,650 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) ZoneWideStoragePoolAllocator to find storage pool
2019-07-24 04:50:41,653 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Checking if storage pool is suitable, name: null ,poolId: 1
2019-07-24 04:50:41,654 INFO [c.c.s.StorageManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2019-07-24 04:50:41,655 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Checking pool 1 for storage, totalSize: 1197350060032, usedBytes: 439484416000, usedPct: 0.3670475583291443, disable threshold: 0.85
2019-07-24 04:50:41,655 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Destination pool id: 1
2019-07-24 04:50:42,097 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Pool ID for the volume with ID 275741 is null
2019-07-24 04:50:42,102 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Found storage pool EmPrime of type NetworkFilesystem with overprovisioning factor 100
2019-07-24 04:50:42,102 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Total over provisioned capacity calculated is 100 * 1197350060032
2019-07-24 04:50:42,102 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Total capacity of the pool EmPrime with ID 1 is 119735006003200
2019-07-24 04:50:42,103 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Checking pool: 1 for storage allocation , maxSize : 119735006003200, totalAllocatedSize : 39868169082864, askingSize : 5368709120, allocated disable threshold: 0.85
2019-07-24 04:50:42,104 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2019-07-24 04:50:42,104 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2019-07-24 04:50:42,104 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Host: 1 can access pool: 1
2019-07-24 04:50:42,105 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Found a potential host id: 1 name: test.emzior and associated storage pools for this VM
2019-07-24 04:50:42,106 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(275741|ROOT-->Pool(1))]
2019-07-24 04:50:42,560 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Sync job-2281455 execution on object VmWorkJobQueue.328404
2019-07-24 04:50:43,301 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Executing AsyncJobVO {id:2281455, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAUC1HQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038011117232, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed Jul 24 04:50:42 MSK 2019}
2019-07-24 04:50:43,301 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Run VM work job: com.cloud.vm.VmWorkStart for VM 328404, job origin: 2281443
2019-07-24 04:50:43,302 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":1,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":328404,"handlerName":"VirtualMachineManagerImpl"}
2019-07-24 04:50:43,310 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) 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
2019-07-24 04:50:43,311 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Successfully transitioned to start state for VM[User|i-2-328404-VM] reservation id = 6187b7b7-3de4-4b7e-abff-d87cdd1723ee
2019-07-24 04:50:44,491 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null
2019-07-24 04:50:44,491 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Deploy avoids pods: null, clusters: null, hosts: null
2019-07-24 04:50:44,504 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) DeploymentPlanner allocation algorithm: null
2019-07-24 04:50:44,505 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 512, requested ram: 536870912
2019-07-24 04:50:44,505 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Is ROOT volume READY (pool already allocated)?: No
2019-07-24 04:50:44,505 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2019-07-24 04:50:44,506 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2019-07-24 04:50:44,511 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Checking suitable pools for volume (Id, Type): (275741,ROOT)
2019-07-24 04:50:44,511 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) We need to allocate new storagepool for this volume
2019-07-24 04:50:44,514 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Calling StoragePoolAllocators to find suitable pools
2019-07-24 04:50:44,514 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2019-07-24 04:50:44,514 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) ClusterScopeStoragePoolAllocator looking for storage pool
2019-07-24 04:50:44,515 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored.
2019-07-24 04:50:44,517 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Found pools matching tags: []
2019-07-24 04:50:44,518 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) No storage pools available for shared volume allocation, returning
2019-07-24 04:50:44,521 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) ZoneWideStoragePoolAllocator to find storage pool
2019-07-24 04:50:44,526 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Checking if storage pool is suitable, name: null ,poolId: 1
2019-07-24 04:50:44,528 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2019-07-24 04:50:44,532 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Checking pool 1 for storage, totalSize: 1197350060032, usedBytes: 439484416000, usedPct: 0.3670475583291443, disable threshold: 0.85
2019-07-24 04:50:44,533 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Destination pool id: 1
2019-07-24 04:50:44,978 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Pool ID for the volume with ID 275741 is null
2019-07-24 04:50:44,982 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Found storage pool EmPrime of type NetworkFilesystem with overprovisioning factor 100
2019-07-24 04:50:44,982 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Total over provisioned capacity calculated is 100 * 1197350060032
2019-07-24 04:50:44,982 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Total capacity of the pool EmPrime with ID 1 is 119735006003200
2019-07-24 04:50:44,983 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Checking pool: 1 for storage allocation , maxSize : 119735006003200, totalAllocatedSize : 39868169082864, askingSize : 5368709120, allocated disable threshold: 0.85
2019-07-24 04:50:44,983 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2019-07-24 04:50:44,983 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2019-07-24 04:50:44,984 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Host: 1 can access pool: 1
2019-07-24 04:50:44,985 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Found a potential host id: 1 name: test.emzior and associated storage pools for this VM
2019-07-24 04:50:44,986 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(275741|ROOT-->Pool(1))]
2019-07-24 04:50:44,986 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Deployment found - P0=VM[User|i-2-328404-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(275741|ROOT-->Pool(1))]
2019-07-24 04:50:45,378 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2019-07-24 04:50:45,442 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Hosts's actual total CPU: 193600 and CPU after applying overprovisioning: 193600
2019-07-24 04:50:45,442 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) We are allocating VM, increasing the used capacity of this host:1
2019-07-24 04:50:45,443 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Current Used CPU: 115708 , Free CPU:76356 ,Requested CPU: 512
2019-07-24 04:50:45,443 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Current Used RAM: 122003914752 , Free RAM:145667670016 ,Requested RAM: 536870912
2019-07-24 04:50:45,443 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) CPU STATS after allocation: for host: 1, old used: 115708, old reserved: 1536, actual total: 193600, total with overprovisioning: 193600; new used:116220, reserved:1536; requested cpu:512,alloc_from_last:false
2019-07-24 04:50:45,443 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) RAM STATS after allocation: for host: 1, old used: 122003914752, old reserved: 1610612736, total: 269282197504; new used: 122540785664, reserved: 1610612736; requested mem: 536870912,alloc_from_last:false
2019-07-24 04:50:45,516 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Network id=74035 is already implemented
2019-07-24 04:50:45,525 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:50:45,530 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Changing active number of nics for network id=74035 on 1
2019-07-24 04:50:45,571 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Asking VirtualRouter to prepare for Nic[655481-328404-null-10.12.85.248]
2019-07-24 04:50:45,589 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:50:45,590 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) CONFIG DHCP FOR SUBNETS RULES
2019-07-24 04:50:45,600 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:50:45,603 DEBUG [o.a.c.n.t.AdvancedNetworkTopology] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) APPLYING VPC DHCP ENTRY RULES
2019-07-24 04:50:45,603 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Applying dhcp entry in network Ntwk[74035|Guest|19]
2019-07-24 04:50:45,663 DEBUG [c.c.a.t.Request] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Seq 1-6442399266953530310: Sending { Cmd , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"1e:00:6f:01:50:fe","vmIpAddress":"10.12.85.248","vmName":"redistr-200-61594-smoke-gre-90-ee02954c","defaultRouter":"10.12.0.1","defaultDns":"10.12.0.10","duid":"00:03:00:01:1e:00:6f:01:50:fe","isDefault":true,"executeInSequence":false,"accessDetails":{"router.name":"r-317955-VM","router.guest.ip":"10.12.0.10","router.ip":"169.254.3.174","zone.network.type":"Advanced"},"wait":0}}] }
2019-07-24 04:50:47,186 DEBUG [c.c.a.t.Request] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Seq 1-6442399266953530310: Received: { Ans: , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 10, { GroupAnswer } }
2019-07-24 04:50:47,190 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:50:47,193 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Network id=248958 is already implemented
2019-07-24 04:50:47,233 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=248958
2019-07-24 04:50:47,237 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Changing active number of nics for network id=248958 on 1
2019-07-24 04:50:47,286 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=248958
2019-07-24 04:50:47,299 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) template 217 is already in store:1, type:Image
2019-07-24 04:50:47,302 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) template 217 is already in store:1, type:Primary
2019-07-24 04:50:47,400 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type VOLUME
2019-07-24 04:50:47,407 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) getCommandHostDelegation: class org.apache.cloudstack.storage.command.CopyCommand
2019-07-24 04:50:47,407 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) We are returning the default host to execute commands because the target hypervisor of the source data is not XenServer.
2019-07-24 04:50:47,410 DEBUG [c.c.a.t.Request] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Seq 1-6442399266953530314: Waiting for Seq 6442399266953530313 Scheduling: { Cmd , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"4c94a2ef-c2fe-4479-af88-03fa3595fbb4","origUrl":"http://10.10.12.174/userdata/db0c6fb1-174a-4ca6-9b17-60ac4fd29624.qcow2","uuid":"4c94a2ef-c2fe-4479-af88-03fa3595fbb4","id":217,"format":"QCOW2","accountId":2,"checksum":"edfd3de6c263acfffaa27b90f51b3940","hvm":true,"displayText":"copy2-From-10.13.189.115","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"fd3b865c-7d22-33d8-a6cc-6a2ccbfebb87","id":1,"poolType":"NetworkFilesystem","host":"172.16.12.253","path":"/export/primary","port":2049,"url":"NetworkFilesystem://172.16.12.253/export/primary/?ROLE=Primary&STOREUUID=fd3b865c-7d22-33d8-a6cc-6a2ccbfebb87","isManaged":false}},"name":"217-2-a88a02be-5d79-3f37-ade8-c1ed333ea654","size":5368709120,"hypervisorType":"KVM","bootable":false,"uniqueName":"217-2-a88a02be-5d79-3f37-ade8-c1ed333ea654","directDownload":false}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"02906048-781f-4c6e-9357-c6e47b208518","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"fd3b865c-7d22-33d8-a6cc-6a2ccbfebb87","id":1,"poolType":"NetworkFilesystem","host":"172.16.12.253","path":"/export/primary","port":2049,"url":"NetworkFilesystem://172.16.12.253/export/primary/?ROLE=Primary&STOREUUID=fd3b865c-7d22-33d8-a6cc-6a2ccbfebb87","isManaged":false}},"name":"ROOT-328404","size":5368709120,"volumeId":275741,"vmName":"i-2-328404-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":275741,"deviceId":0,"hypervisorType":"KVM"}},"executeInSequence":true,"options":{},"options2":{},"wait":0}}] }
2019-07-24 04:50:47,761 DEBUG [c.c.a.t.Request] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Seq 1-6442399266953530314: Received: { Ans: , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 110, { CopyCmdAnswer } }
2019-07-24 04:50:48,204 DEBUG [c.c.a.t.Request] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Seq 1-6442399266953530315: Sending { Cmd , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":328404,"name":"i-2-328404-VM","type":"User","cpus":1,"minSpeed":512,"maxSpeed":512,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Ubuntu 12.04 (64-bit)","platformEmulator":"Ubuntu 12.04","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"EYwkYgks899KTBiLcnFTkA","params":{"deployvm":"true"},"uuid":"d94ac4ca-80af-4dc2-b4f9-44d4bfb485a1","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"02906048-781f-4c6e-9357-c6e47b208518","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"fd3b865c-7d22-33d8-a6cc-6a2ccbfebb87","id":1,"poolType":"NetworkFilesystem","host":"172.16.12.253","path":"/export/primary","port":2049,"url":"NetworkFilesystem://172.16.12.253/export/primary/?ROLE=Primary&STOREUUID=fd3b865c-7d22-33d8-a6cc-6a2ccbfebb87","isManaged":false}},"name":"ROOT-328404","size":5368709120,"path":"02906048-781f-4c6e-9357-c6e47b208518","volumeId":275741,"vmName":"i-2-328404-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":275741,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"02906048-781f-4c6e-9357-c6e47b208518","type":"ROOT","_details":{"storageHost":"172.16.12.253","managed":"false","storagePort":"2049","volumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false,"bootable":false,"directDownload":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"3ede7cff-4662-48d3-bd54-c8bd1562646f","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"uuid":"ff6f6044-c55f-44c0-bf67-66cbf9382b16","ip":"10.12.85.248","netmask":"255.255.0.0","gateway":"10.12.0.1","mac":"1e:00:6f:01:50:fe","dns1":"10.10.12.8","dns2":"10.10.12.47","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://3","isolationUri":"vlan://3","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":1,"networkRateMbps":1024,"defaultNic":false,"pxeDisable":false,"nicUuid":"668f1635-59ed-4fd3-8ed0-cc772aeccfad","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"uuid":"59c2e9e8-8525-47a6-85c8-08d97b3c3cb8","ip":"10.200.1.150","netmask":"255.255.255.0","gateway":"10.200.1.1","mac":"02:00:7a:9d:00:02","dns1":"10.10.12.8","dns2":"10.10.12.47","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://806","isolationUri":"vlan://806","isSecurityGroupEnabled":false,"name":"cloudbr0"}],"guestOsDetails":{}},"hostIp":"10.10.12.10","executeInSequence":false,"wait":0}}] }
2019-07-24 04:50:49,754 DEBUG [c.c.a.t.Request] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Seq 1-6442399266953530315: Received: { Ans: , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 10, { StartAnswer } }
2019-07-24 04:50:50,165 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Unable to start VM on Host[-1-Routing] due to failed to get free memory
2019-07-24 04:50:50,229 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Cleaning up resources for the vm VM[User|i-2-328404-VM] in Starting state
2019-07-24 04:50:50,240 DEBUG [c.c.a.t.Request] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Seq 1-6442399266953530316: Sending { Cmd , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"volumesToDisconnect":[],"vmName":"i-2-328404-VM","executeInSequence":false,"wait":0}}] }
2019-07-24 04:50:50,471 DEBUG [c.c.a.t.Request] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Seq 1-6442399266953530316: Received: { Ans: , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 10, { StopAnswer } }
2019-07-24 04:50:50,479 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Changing active number of nics for network id=74035 on -1
2019-07-24 04:50:50,622 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=248958
2019-07-24 04:50:50,625 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Changing active number of nics for network id=248958 on -1
2019-07-24 04:50:58,237 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Successfully released network resources for the vm VM[User|i-2-328404-VM]
2019-07-24 04:50:58,237 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Successfully cleanued up resources for the vm VM[User|i-2-328404-VM] in Starting state
2019-07-24 04:50:58,240 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Root volume is ready, need to place VM in volume's cluster
2019-07-24 04:50:58,248 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) DeploymentPlanner allocation algorithm: null
2019-07-24 04:50:58,248 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 512, requested ram: 536870912
2019-07-24 04:50:58,248 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Is ROOT volume READY (pool already allocated)?: Yes
2019-07-24 04:50:58,248 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2019-07-24 04:50:58,249 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) The specified host is in avoid set
2019-07-24 04:50:58,249 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Cannot deploy to specified host, returning.
2019-07-24 04:51:01,941 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2019-07-24 04:51:03,579 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Hosts's actual total CPU: 193600 and CPU after applying overprovisioning: 193600
2019-07-24 04:51:03,579 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Hosts's actual total RAM: 269282197504 and RAM after applying overprovisioning: 269282197504
2019-07-24 04:51:03,579 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) release cpu from host: 1, old used: 116732,reserved: 1024, actual total: 193600, total with overprovisioning: 193600; new used: 116220,reserved:1024; movedfromreserved: false,moveToReserveredfalse
2019-07-24 04:51:03,579 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) release mem from host: 1, old used: 123077656576,reserved: 1610612736, total: 269282197504; new used: 122540785664,reserved:1610612736; movedfromreserved: false,moveToReserveredfalse
2019-07-24 04:51:04,540 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-328404-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2019-07-24 04:51:04,541 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455 ctx-52b48ca6) (logid:b6e33d80) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-328404-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2019-07-24 04:51:04,541 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 328404, job origin: 2281443
2019-07-24 04:51:04,542 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Unable to complete AsyncJobVO {id:2281455, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAUC1HQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038011117232, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed Jul 24 04:50:42 MSK 2019}, job origin:2281443
2019-07-24 04:51:04,544 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Complete async job-2281455, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA4VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0yLTMyODQwNC1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABRzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AAp4cAAABDN0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRzcQB-ABEAABNJcQB-ABNxAH4AFHEAfgAVc3EAfgAR_____3QAJnN1bi5yZWZsZWN0LkdlbmVyYXRlZE1ldGhvZEFjY2Vzc29yMzUxcHQABmludm9rZXNxAH4AEQAAACt0AChzdW4ucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABlzcQB-ABEAAAHydAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AGXNxAH4AEQAAAGt0ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JzcQB-ABEAABPscQB-ABNxAH4AFHEAfgAjc3EAfgARAAAAZnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9ic3EAfgARAAACRXQAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHNxAH4AEQAAADF0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnNxAH4AEQAAADh0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxzcQB-ABEAAABndABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgAzdAAPY2FsbFdpdGhDb250ZXh0c3EAfgARAAAANXEAfgA2cQB-ADN0AA5ydW5XaXRoQ29udGV4dHNxAH4AEQAAAC50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4AL3EAfgAwc3EAfgARAAACEXEAfgAqcQB-ACtxAH4AMHNxAH4AEQAAAf90AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4ANHNxAH4AEQAAAQp0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-ADBzcQB-ABEAAAR9dAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJzcQB-ABEAAAJwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBFcQB-ADBzcQB-ABEAAALsdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-ADBzcgAmamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUxpc3T8DyUxteyOEAIAAUwABGxpc3RxAH4ADHhyACxqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlQ29sbGVjdGlvbhlCAIDLXvceAgABTAABY3QAFkxqYXZhL3V0aWwvQ29sbGVjdGlvbjt4cHNyABNqYXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHEAfgBReHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABDvc3EAfgBQAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHEAfgBTAAAAAAAAAAF2cgAXY29tLmNsb3VkLmRjLkRhdGFDZW50ZXJjQfdzv5V8swIAAHhwAA
2019-07-24 04:51:04,545 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Publish async job-2281455 complete on message bus
2019-07-24 04:51:04,546 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Wake up jobs related to job-2281455
2019-07-24 04:51:04,546 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Update db status for job-2281455
2019-07-24 04:51:05,398 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Wake up jobs joined with job-2281455 and disjoin all subjobs created from job- 2281455
2019-07-24 04:51:05,459 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Done executing com.cloud.vm.VmWorkStart for job-2281455
2019-07-24 04:51:05,467 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-82:ctx-8d1155a3 job-2281443/job-2281455) (logid:b6e33d80) Remove job-2281455 from job monitoring
2019-07-24 04:51:05,962 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Sync job-2281494 execution on object VmWorkJobQueue.328404
2019-07-24 04:51:07,802 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494) (logid:b6e33d80) Executing AsyncJobVO {id:2281494, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAUC1HQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 14038011117232, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed Jul 24 04:51:05 MSK 2019}
2019-07-24 04:51:07,802 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494) (logid:b6e33d80) Run VM work job: com.cloud.vm.VmWorkStart for VM 328404, job origin: 2281443
2019-07-24 04:51:07,803 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":328404,"handlerName":"VirtualMachineManagerImpl"}
2019-07-24 04:51:07,813 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) 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
2019-07-24 04:51:07,814 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Successfully transitioned to start state for VM[User|i-2-328404-VM] reservation id = 65ec0395-97f3-4c9c-ba68-fc377edf7d3b
2019-07-24 04:51:07,959 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Deploy avoids pods: null, clusters: null, hosts: null
2019-07-24 04:51:07,962 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Root volume is ready, need to place VM in volume's cluster
2019-07-24 04:51:07,962 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Vol[275741|vm=328404|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: null , and clusterId: null
2019-07-24 04:51:07,970 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) DeploymentPlanner allocation algorithm: null
2019-07-24 04:51:07,970 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 512, requested ram: 536870912
2019-07-24 04:51:07,970 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Is ROOT volume READY (pool already allocated)?: Yes
2019-07-24 04:51:07,976 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Deploy avoids pods: [], clusters: [], hosts: []
2019-07-24 04:51:07,977 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Searching all possible resources under this Zone: 1
2019-07-24 04:51:07,978 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2019-07-24 04:51:07,982 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Removing from the clusterId list these clusters from avoid set: []
2019-07-24 04:51:07,997 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Checking resources in Cluster: 1 under Pod: 1
2019-07-24 04:51:07,997 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Looking for hosts in dc: 1 pod:1 cluster:1
2019-07-24 04:51:07,999 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) FirstFitAllocator has 2 hosts to check for allocation: [Host[-1-Routing], Host[-5-Routing]]
2019-07-24 04:51:08,006 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Found 2 hosts for allocation after prioritization: [Host[-1-Routing], Host[-5-Routing]]
2019-07-24 04:51:08,006 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Looking for speed=512Mhz, Ram=512
2019-07-24 04:51:08,016 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Host: 1 has cpu capability (cpu:88, speed:2200) to support requested CPU: 1 and requested speed: 512
2019-07-24 04:51:08,016 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Checking if host: 1 has enough capacity for requested CPU: 512 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2019-07-24 04:51:08,017 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Hosts's actual total CPU: 193600 and CPU after applying overprovisioning: 193600
2019-07-24 04:51:08,017 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Free CPU: 76868 , Requested CPU: 512
2019-07-24 04:51:08,018 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Free RAM: 146204540928 , Requested RAM: 536870912
2019-07-24 04:51:08,018 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Host has enough CPU and RAM available
2019-07-24 04:51:08,018 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) STATS: Can alloc CPU from host: 1, used: 116220, reserved: 512, actual total: 193600, total with overprovisioning: 193600; requested cpu:512,alloc_from_last_host?:false ,considerReservedCapacity?: true
2019-07-24 04:51:08,018 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) STATS: Can alloc MEM from host: 1, used: 122540785664, reserved: 536870912, total: 269282197504; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2019-07-24 04:51:08,018 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Found a suitable host, adding to list: 1
2019-07-24 04:51:08,027 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Host: 5 has cpu capability (cpu:28, speed:2200) to support requested CPU: 1 and requested speed: 512
2019-07-24 04:51:08,027 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Checking if host: 5 has enough capacity for requested CPU: 512 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2019-07-24 04:51:08,028 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Hosts's actual total CPU: 61600 and CPU after applying overprovisioning: 61600
2019-07-24 04:51:08,028 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Free CPU: -768 , Requested CPU: 512
2019-07-24 04:51:08,029 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Free RAM: 626409472 , Requested RAM: 536870912
2019-07-24 04:51:08,029 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) STATS: Failed to alloc resource from host: 5 reservedCpu: 0, used cpu: 62368, requested cpu: 512, actual total cpu: 61600, total cpu with overprovisioning: 61600, reservedMem: 0, used Mem: 65498251264, requested mem: 536870912, total Mem:66124660736 ,considerReservedCapacity?: true
2019-07-24 04:51:08,029 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Host does not have enough CPU available, cannot allocate to this host.
2019-07-24 04:51:08,029 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Not using host 5; host has cpu capability? true, host has capacity?false
2019-07-24 04:51:08,029 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1 FirstFitRoutingAllocator) (logid:b6e33d80) Host Allocator returning 1 suitable hosts
2019-07-24 04:51:08,031 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Checking suitable pools for volume (Id, Type): (275741,ROOT)
2019-07-24 04:51:08,031 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Volume has pool already allocated, checking if pool can be reused, poolId: 1
2019-07-24 04:51:08,035 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Planner need not allocate a pool for this volume since its READY
2019-07-24 04:51:08,035 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2019-07-24 04:51:08,035 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2019-07-24 04:51:08,036 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Host: 1 can access pool: 1
2019-07-24 04:51:08,037 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Found a potential host id: 1 name: test.emzior and associated storage pools for this VM
2019-07-24 04:51:08,038 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2019-07-24 04:51:08,038 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Deployment found - P0=VM[User|i-2-328404-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2019-07-24 04:51:08,194 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2019-07-24 04:51:08,202 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Hosts's actual total CPU: 193600 and CPU after applying overprovisioning: 193600
2019-07-24 04:51:08,202 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) We are allocating VM, increasing the used capacity of this host:1
2019-07-24 04:51:08,202 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Current Used CPU: 116220 , Free CPU:77380 ,Requested CPU: 512
2019-07-24 04:51:08,202 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Current Used RAM: 122540785664 , Free RAM:146741411840 ,Requested RAM: 536870912
2019-07-24 04:51:08,202 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) CPU STATS after allocation: for host: 1, old used: 116220, old reserved: 0, actual total: 193600, total with overprovisioning: 193600; new used:116732, reserved:0; requested cpu:512,alloc_from_last:false
2019-07-24 04:51:08,202 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) RAM STATS after allocation: for host: 1, old used: 122540785664, old reserved: 0, total: 269282197504; new used: 123077656576, reserved: 0; requested mem: 536870912,alloc_from_last:false
2019-07-24 04:51:09,033 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Network id=74035 is already implemented
2019-07-24 04:51:09,042 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:51:09,045 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Changing active number of nics for network id=74035 on 1
2019-07-24 04:51:09,087 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Asking VirtualRouter to prepare for Nic[655481-328404-null-10.12.85.248]
2019-07-24 04:51:09,105 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:51:09,107 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) CONFIG DHCP FOR SUBNETS RULES
2019-07-24 04:51:09,116 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:51:09,118 DEBUG [o.a.c.n.t.AdvancedNetworkTopology] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) APPLYING VPC DHCP ENTRY RULES
2019-07-24 04:51:09,118 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Applying dhcp entry in network Ntwk[74035|Guest|19]
2019-07-24 04:51:09,178 DEBUG [c.c.a.t.Request] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Seq 1-6442399266953530323: Sending { Cmd , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"1e:00:6f:01:50:fe","vmIpAddress":"10.12.85.248","vmName":"redistr-200-61594-smoke-gre-90-ee02954c","defaultRouter":"10.12.0.1","defaultDns":"10.12.0.10","duid":"00:03:00:01:1e:00:6f:01:50:fe","isDefault":true,"executeInSequence":false,"accessDetails":{"router.name":"r-317955-VM","router.guest.ip":"10.12.0.10","router.ip":"169.254.3.174","zone.network.type":"Advanced"},"wait":0}}] }
2019-07-24 04:51:10,817 DEBUG [c.c.a.t.Request] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Seq 1-6442399266953530323: Received: { Ans: , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 10, { GroupAnswer } }
2019-07-24 04:51:10,821 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:51:10,825 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Network id=248958 is already implemented
2019-07-24 04:51:14,759 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=248958
2019-07-24 04:51:14,765 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Changing active number of nics for network id=248958 on 1
2019-07-24 04:51:14,819 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=248958
2019-07-24 04:51:14,825 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) No need to recreate the volume: Vol[275741|vm=328404|ROOT], since it already has a pool assigned: 1, adding disk to VM
2019-07-24 04:51:21,725 DEBUG [c.c.a.t.Request] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Seq 1-6442399266953530328: Sending { Cmd , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":328404,"name":"i-2-328404-VM","type":"User","cpus":1,"minSpeed":512,"maxSpeed":512,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Ubuntu 12.04 (64-bit)","platformEmulator":"Ubuntu 12.04","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"EYwkYgks899KTBiLcnFTkA","params":{"deployvm":"true","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"d94ac4ca-80af-4dc2-b4f9-44d4bfb485a1","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"02906048-781f-4c6e-9357-c6e47b208518","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"fd3b865c-7d22-33d8-a6cc-6a2ccbfebb87","id":1,"poolType":"NetworkFilesystem","host":"172.16.12.253","path":"/export/primary","port":2049,"url":"NetworkFilesystem://172.16.12.253/export/primary/?ROLE=Primary&STOREUUID=fd3b865c-7d22-33d8-a6cc-6a2ccbfebb87","isManaged":false}},"name":"ROOT-328404","size":5368709120,"path":"02906048-781f-4c6e-9357-c6e47b208518","volumeId":275741,"vmName":"i-2-328404-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":275741,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"02906048-781f-4c6e-9357-c6e47b208518","type":"ROOT","_details":{"storageHost":"172.16.12.253","managed":"false","storagePort":"2049","volumeSize":"5368709120"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false,"bootable":false,"directDownload":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"3ede7cff-4662-48d3-bd54-c8bd1562646f","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"uuid":"ff6f6044-c55f-44c0-bf67-66cbf9382b16","ip":"10.12.85.248","netmask":"255.255.0.0","gateway":"10.12.0.1","mac":"1e:00:6f:01:50:fe","dns1":"10.10.12.8","dns2":"10.10.12.47","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://3","isolationUri":"vlan://3","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":1,"networkRateMbps":1024,"defaultNic":false,"pxeDisable":false,"nicUuid":"668f1635-59ed-4fd3-8ed0-cc772aeccfad","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"uuid":"59c2e9e8-8525-47a6-85c8-08d97b3c3cb8","ip":"10.200.1.150","netmask":"255.255.255.0","gateway":"10.200.1.1","mac":"02:00:7a:9d:00:02","dns1":"10.10.12.8","dns2":"10.10.12.47","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://806","isolationUri":"vlan://806","isSecurityGroupEnabled":false,"name":"cloudbr0"}],"guestOsDetails":{}},"hostIp":"10.10.12.10","executeInSequence":false,"wait":0}}] }
2019-07-24 04:52:14,606 DEBUG [c.c.a.t.Request] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Seq 1-6442399266953530328: Received: { Ans: , MgmtId: 14038011117232, via: 1(test.emzior), Ver: v1, Flags: 10, { StartAnswer } }
2019-07-24 04:52:15,721 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) VM state transitted from :Starting to Running with event: OperationSucceededvm's original host id: 1 new host id: 1 host id before state transition: 1
2019-07-24 04:52:15,733 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:52:15,743 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=248958
2019-07-24 04:52:15,747 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=74035
2019-07-24 04:52:15,748 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Service SecurityGroup is not supported in the network id=248958
2019-07-24 04:52:15,838 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Start completed for VM VM[User|i-2-328404-VM]
2019-07-24 04:52:15,839 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Done executing VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":328404,"handlerName":"VirtualMachineManagerImpl"}
2019-07-24 04:52:15,839 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Complete async job-2281494, jobStatus: SUCCEEDED, resultCode: 0, result: null
2019-07-24 04:52:15,840 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Publish async job-2281494 complete on message bus
2019-07-24 04:52:15,841 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Wake up jobs related to job-2281494
2019-07-24 04:52:15,841 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Update db status for job-2281494
2019-07-24 04:52:15,842 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494 ctx-2421c2d1) (logid:b6e33d80) Wake up jobs joined with job-2281494 and disjoin all subjobs created from job- 2281494
2019-07-24 04:52:15,894 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494) (logid:b6e33d80) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 328404, job origin: 2281443
2019-07-24 04:52:15,895 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494) (logid:b6e33d80) Done executing com.cloud.vm.VmWorkStart for job-2281494
2019-07-24 04:52:15,900 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-329:ctx-cb5659a4 job-2281443/job-2281494) (logid:b6e33d80) Remove job-2281494 from job monitoring
2019-07-24 04:52:15,991 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Complete async job-2281443, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmResponse/virtualmachine/{"id":"d94ac4ca-80af-4dc2-b4f9-44d4bfb485a1","name":"redistr-200-61594-smoke-gre-90-ee02954c","displayname":"redistr-200-61594-smoke-gre-90-ee02954c","account":"admin","userid":"d9d37bcd-87a1-11e9-a390-0cc47aaa7eb0","username":"admin","domainid":"b2bc6a86-87a1-11e9-a390-0cc47aaa7eb0","domain":"ROOT","created":"2019-07-24T04:50:39+0300","state":"Running","haenable":false,"zoneid":"d103e528-c0b0-471e-ad55-2b99c47c4dee","zonename":"EmZone","hostid":"232a4e94-4179-4d7a-9690-8928abd25837","hostname":"test.emzior","templateid":"4c94a2ef-c2fe-4479-af88-03fa3595fbb4","templatename":"copy2-From-10.13.189.115","templatedisplaytext":"copy2-From-10.13.189.115","passwordenabled":false,"serviceofferingid":"620073b7-fde4-4eae-8680-e17badfa7585","serviceofferingname":"cap-name-ccf8e75f-66ba-4e36-9041","cpunumber":1,"cpuspeed":512,"memory":512,"guestosid":"b3f19d4c-87a1-11e9-a390-0cc47aaa7eb0","rootdeviceid":0,"rootdevicetype":"ROOT","securitygroup":[],"nic":[{"id":"3ede7cff-4662-48d3-bd54-c8bd1562646f","networkid":"ff6f6044-c55f-44c0-bf67-66cbf9382b16","networkname":"shared2","netmask":"255.255.0.0","gateway":"10.12.0.1","ipaddress":"10.12.85.248","isolationuri":"vlan://3","broadcasturi":"vlan://3","traffictype":"Guest","type":"Shared","isdefault":true,"macaddress":"1e:00:6f:01:50:fe","secondaryip":[],"extradhcpoption":[]},{"id":"668f1635-59ed-4fd3-8ed0-cc772aeccfad","networkid":"59c2e9e8-8525-47a6-85c8-08d97b3c3cb8","networkname":"redistr-200-61594-smoke-gre-90-0","netmask":"255.255.255.0","gateway":"10.200.1.1","ipaddress":"10.200.1.150","isolationuri":"vlan://806","broadcasturi":"vlan://806","traffictype":"Guest","type":"Isolated","isdefault":false,"macaddress":"02:00:7a:9d:00:02","secondaryip":[],"extradhcpoption":[]}],"hypervisor":"KVM","instancename":"i-2-328404-VM","details":{"Message.ReservedCapacityFreed.Flag":"false"},"affinitygroup":[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":164,"tags":[],"jobid":"b6e33d80-a1da-4169-bef6-86cdb2f991f1","jobstatus":0}
2019-07-24 04:52:15,992 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Publish async job-2281443 complete on message bus
2019-07-24 04:52:15,992 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Wake up jobs related to job-2281443
2019-07-24 04:52:15,992 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Update db status for job-2281443
2019-07-24 04:52:15,993 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443 ctx-5eb33e82) (logid:b6e33d80) Wake up jobs joined with job-2281443 and disjoin all subjobs created from job- 2281443
2019-07-24 04:52:16,026 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-166:ctx-aa138dbf job-2281443) (logid:b6e33d80) Done executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-2281443
2019-07-24 04:52:16,026 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-166:ctx-aa138dbf job-2281443) (logid:b6e33d80) Remove job-2281443 from job monitoring
