Unable to start KVM instance after upgrade to 4.15.0 #4599
Description
ISSUE TYPE
- Bug Report
COMPONENT NAME
Executor
CLOUDSTACK VERSION
4.15.0
CONFIGURATION
basic network, simple test install
OS / ENVIRONMENT
Centos 7.9
SUMMARY
After the upgrade from 4.14.0, I'm not able anymore to start any instance.
First I tried my old alpine install, then deleted it and created a new instance, booting the alpine iso.
Always leading instance to go into STOPPED state. The UI just gives an ERROR event, without much
information whats wrong.
STEPS TO REPRODUCE
Here is the job log, which I assume is the start of the instance
2021-01-20 07:22:28,820 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-8:ctx-8241bbe7 job-143) (logid:14147538) Add job-143 into job monitoring
2021-01-20 07:22:28,824 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp1074389766-356:ctx-434497de ctx-f0d7a32b) (logid:9912dda1) submit async job-143, details: AsyncJobVO {id:143, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 9, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"httpmethod":"GET","clusterid":"a416643c-1fb7-4275-96da-ac508ddc20bc","templateid":"b194a3af-834c-49e6-b587-7f0329519873","ctxAccountId":"2","uuid":"d73587cf-95e3-454f-819f-bcfb75bb6e4f","cmdEventType":"VM.CREATE","diskofferingid":"7fc3221f-b417-4a1e-8f06-c7d0222d0055","serviceofferingid":"98f51d25-2337-4731-be1b-7fb6079b1d03","response":"json","ctxUserId":"2","hypervisor":"KVM","zoneid":"d201748c-6d87-4d52-98a6-72d954102fdf","ctxStartEventId":"48","id":"9","ctxDetails":"{\"interface com.cloud.template.VirtualMachineTemplate\":\"b194a3af-834c-49e6-b587-7f0329519873\",\"interface com.cloud.vm.VirtualMachine\":\"d73587cf-95e3-454f-819f-bcfb75bb6e4f\",\"interface com.cloud.offering.ServiceOffering\":\"98f51d25-2337-4731-be1b-7fb6079b1d03\",\"interface com.cloud.offering.DiskOffering\":\"7fc3221f-b417-4a1e-8f06-c7d0222d0055\",\"interface com.cloud.dc.Pod\":\"c892289e-b0f7-4f5e-8eca-12de54407ee6\",\"interface com.cloud.org.Cluster\":\"a416643c-1fb7-4275-96da-ac508ddc20bc\",\"interface com.cloud.dc.DataCenter\":\"d201748c-6d87-4d52-98a6-72d954102fdf\"}","podid":"c892289e-b0f7-4f5e-8eca-12de54407ee6","affinitygroupids":""}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2199193903112, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2021-01-20 07:22:28,825 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143) (logid:bf354ff9) Executing AsyncJobVO {id:143, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 9, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"httpmethod":"GET","clusterid":"a416643c-1fb7-4275-96da-ac508ddc20bc","templateid":"b194a3af-834c-49e6-b587-7f0329519873","ctxAccountId":"2","uuid":"d73587cf-95e3-454f-819f-bcfb75bb6e4f","cmdEventType":"VM.CREATE","diskofferingid":"7fc3221f-b417-4a1e-8f06-c7d0222d0055","serviceofferingid":"98f51d25-2337-4731-be1b-7fb6079b1d03","response":"json","ctxUserId":"2","hypervisor":"KVM","zoneid":"d201748c-6d87-4d52-98a6-72d954102fdf","ctxStartEventId":"48","id":"9","ctxDetails":"{\"interface com.cloud.template.VirtualMachineTemplate\":\"b194a3af-834c-49e6-b587-7f0329519873\",\"interface com.cloud.vm.VirtualMachine\":\"d73587cf-95e3-454f-819f-bcfb75bb6e4f\",\"interface com.cloud.offering.ServiceOffering\":\"98f51d25-2337-4731-be1b-7fb6079b1d03\",\"interface com.cloud.offering.DiskOffering\":\"7fc3221f-b417-4a1e-8f06-c7d0222d0055\",\"interface com.cloud.dc.Pod\":\"c892289e-b0f7-4f5e-8eca-12de54407ee6\",\"interface com.cloud.org.Cluster\":\"a416643c-1fb7-4275-96da-ac508ddc20bc\",\"interface com.cloud.dc.DataCenter\":\"d201748c-6d87-4d52-98a6-72d954102fdf\"}","podid":"c892289e-b0f7-4f5e-8eca-12de54407ee6","affinitygroupids":""}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2199193903112, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2021-01-20 07:22:29,502 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Destination Cluster to deploy the VM is specified, specifying a deployment plan to deploy the VM
2021-01-20 07:22:29,517 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) DeploymentPlanner allocation algorithm: null
2021-01-20 07:22:29,517 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: (512.00 MB) 536870912
2021-01-20 07:22:29,517 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Is ROOT volume READY (pool already allocated)?: No
2021-01-20 07:22:29,518 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Deploy avoids pods: [], clusters: [], hosts: []
2021-01-20 07:22:29,520 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Searching resources only under specified Cluster: 1
2021-01-20 07:22:29,528 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Checking resources in Cluster: 1 under Pod: 1
2021-01-20 07:22:29,531 INFO [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Guest VM is requested with Cusotm[UEFI] Boot Type false
2021-01-20 07:22:29,531 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Looking for hosts in dc: 1 pod:1 cluster:1
2021-01-20 07:22:29,535 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) FirstFitAllocator has 3 hosts to check for allocation: [Host[-1-Routing], Host[-5-Routing], Host[-4-Routing]]
2021-01-20 07:22:29,542 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Found 3 hosts for allocation after prioritization: [Host[-1-Routing], Host[-5-Routing], Host[-4-Routing]]
2021-01-20 07:22:29,542 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Looking for speed=500Mhz, Ram=512 MB
2021-01-20 07:22:29,548 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Host: 1 has cpu capability (cpu:2, speed:2194) to support requested CPU: 1 and requested speed: 500
2021-01-20 07:22:29,548 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0
2021-01-20 07:22:29,550 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:29,550 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Free CPU: 4388 , Requested CPU: 500
2021-01-20 07:22:29,550 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Free RAM: (2.70 GB) 2899542016 , Requested RAM: (512.00 MB) 536870912
2021-01-20 07:22:29,550 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Host has enough CPU and RAM available
2021-01-20 07:22:29,550 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) STATS: Can alloc CPU from host: 1, used: 0, reserved: 0, actual total: 4388, total with overprovisioning: 4388; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2021-01-20 07:22:29,550 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) STATS: Can alloc MEM from host: 1, used: (0 bytes) 0, reserved: (0 bytes) 0, total: (2.70 GB) 2899542016; requested mem: (512.00 MB) 536870912, alloc_from_last_host?: false , considerReservedCapacity?: true
2021-01-20 07:22:29,550 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Found a suitable host, adding to list: 1
2021-01-20 07:22:29,556 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Host: 5 has cpu capability (cpu:2, speed:2194) to support requested CPU: 1 and requested speed: 500
2021-01-20 07:22:29,556 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Checking if host: 5 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0
2021-01-20 07:22:29,558 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:29,558 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Free CPU: 3388 , Requested CPU: 500
2021-01-20 07:22:29,558 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Free RAM: (1.20 GB) 1288929280 , Requested RAM: (512.00 MB) 536870912
2021-01-20 07:22:29,558 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Host has enough CPU and RAM available
2021-01-20 07:22:29,558 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) STATS: Can alloc CPU from host: 5, used: 1000, reserved: 0, actual total: 4388, total with overprovisioning: 4388; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2021-01-20 07:22:29,558 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) STATS: Can alloc MEM from host: 5, used: (1.50 GB) 1610612736, reserved: (0 bytes) 0, total: (2.70 GB) 2899542016; requested mem: (512.00 MB) 536870912, alloc_from_last_host?: false , considerReservedCapacity?: true
2021-01-20 07:22:29,558 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Found a suitable host, adding to list: 5
2021-01-20 07:22:29,565 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Host: 4 has cpu capability (cpu:2, speed:2194) to support requested CPU: 1 and requested speed: 500
2021-01-20 07:22:29,565 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Checking if host: 4 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0
2021-01-20 07:22:29,567 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:29,567 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Free CPU: 4388 , Requested CPU: 500
2021-01-20 07:22:29,567 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Free RAM: (2.70 GB) 2899550208 , Requested RAM: (512.00 MB) 536870912
2021-01-20 07:22:29,567 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Host has enough CPU and RAM available
2021-01-20 07:22:29,567 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) STATS: Can alloc CPU from host: 4, used: 0, reserved: 0, actual total: 4388, total with overprovisioning: 4388; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2021-01-20 07:22:29,567 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) STATS: Can alloc MEM from host: 4, used: (0 bytes) 0, reserved: (0 bytes) 0, total: (2.70 GB) 2899550208; requested mem: (512.00 MB) 536870912, alloc_from_last_host?: false , considerReservedCapacity?: true
2021-01-20 07:22:29,567 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Found a suitable host, adding to list: 4
2021-01-20 07:22:29,567 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85 FirstFitRoutingAllocator) (logid:bf354ff9) Host Allocator returning 3 suitable hosts
2021-01-20 07:22:29,570 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Checking suitable pools for volume (Id, Type): (17,ROOT)
2021-01-20 07:22:29,570 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) We need to allocate new storagepool for this volume
2021-01-20 07:22:29,571 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Calling StoragePoolAllocators to find suitable pools
2021-01-20 07:22:29,572 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2021-01-20 07:22:29,572 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) ClusterScopeStoragePoolAllocator looking for storage pool
2021-01-20 07:22:29,572 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored.
2021-01-20 07:22:29,574 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Found pools matching tags: [Pool[1|NetworkFilesystem]]
2021-01-20 07:22:29,576 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Checking if storage pool is suitable, name: null ,poolId: 1
2021-01-20 07:22:29,578 INFO [c.c.s.StorageManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2021-01-20 07:22:29,580 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Checking pool 1 for storage, totalSize: 32198098944, usedBytes: 3653763072, usedPct: 0.11347760246201945, disable threshold: 0.85
2021-01-20 07:22:29,580 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Destination pool id: 1
2021-01-20 07:22:29,589 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Pool ID for the volume with ID 17 is null
2021-01-20 07:22:29,592 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Found storage pool default of type NetworkFilesystem with over-provisioning factor 2
2021-01-20 07:22:29,592 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Total over-provisioned capacity calculated is 2 * (29.99 GB) 32198098944
2021-01-20 07:22:29,592 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Total capacity of the pool default with ID 1 is (59.97 GB) 64396197888
2021-01-20 07:22:29,593 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Checking pool: 1 for storage allocation , maxSize : (59.97 GB) 64396197888, totalAllocatedSize : (8.91 GB) 9563407360, askingSize : (5.00 GB) 5368709120, allocated disable threshold: 0.85
2021-01-20 07:22:29,593 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2021-01-20 07:22:29,593 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2021-01-20 07:22:29,594 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2021-01-20 07:22:29,595 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Host: 1 can access pool: 1
2021-01-20 07:22:30,185 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Found a potential host id: 1 name: cloudstack-comp1.linbit and associated storage pools for this VM
2021-01-20 07:22:30,187 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(17|ROOT-->Pool(1))]
2021-01-20 07:22:31,656 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Sync job-144 execution on object VmWorkJobQueue.9
2021-01-20 07:22:35,590 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144) (logid:7abfb537) Add job-144 into job monitoring
2021-01-20 07:22:35,595 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144) (logid:bf354ff9) Executing AsyncJobVO {id:144, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAACXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2199193903112, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed Jan 20 07:22:31 UTC 2021, removed: null}
2021-01-20 07:22:35,596 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144) (logid:bf354ff9) Run VM work job: com.cloud.vm.VmWorkStart for VM 9, job origin: 143
2021-01-20 07:22:35,597 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":1,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":9,"handlerName":"VirtualMachineManagerImpl"}
2021-01-20 07:22:35,605 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) 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
2021-01-20 07:22:35,606 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Successfully transitioned to start state for VM[User|i-2-9-VM] reservation id = 384fb78f-08aa-4902-98d7-b077d2a92732
2021-01-20 07:22:35,828 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null
2021-01-20 07:22:35,830 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Deploy avoids pods: null, clusters: null, hosts: null
2021-01-20 07:22:35,838 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) DeploymentPlanner allocation algorithm: null
2021-01-20 07:22:35,838 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: (512.00 MB) 536870912
2021-01-20 07:22:35,838 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Is ROOT volume READY (pool already allocated)?: No
2021-01-20 07:22:35,838 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2021-01-20 07:22:35,839 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2021-01-20 07:22:35,842 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking suitable pools for volume (Id, Type): (17,ROOT)
2021-01-20 07:22:35,842 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) We need to allocate new storagepool for this volume
2021-01-20 07:22:35,843 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Calling StoragePoolAllocators to find suitable pools
2021-01-20 07:22:35,844 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2021-01-20 07:22:35,844 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) ClusterScopeStoragePoolAllocator looking for storage pool
2021-01-20 07:22:35,844 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored.
2021-01-20 07:22:35,845 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Found pools matching tags: [Pool[1|NetworkFilesystem]]
2021-01-20 07:22:35,847 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking if storage pool is suitable, name: null ,poolId: 1
2021-01-20 07:22:35,848 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2021-01-20 07:22:35,851 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking pool 1 for storage, totalSize: 32198098944, usedBytes: 3653763072, usedPct: 0.11347760246201945, disable threshold: 0.85
2021-01-20 07:22:35,851 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Destination pool id: 1
2021-01-20 07:22:35,860 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Pool ID for the volume with ID 17 is null
2021-01-20 07:22:35,864 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Found storage pool default of type NetworkFilesystem with over-provisioning factor 2
2021-01-20 07:22:35,864 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Total over-provisioned capacity calculated is 2 * (29.99 GB) 32198098944
2021-01-20 07:22:35,864 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Total capacity of the pool default with ID 1 is (59.97 GB) 64396197888
2021-01-20 07:22:35,865 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking pool: 1 for storage allocation , maxSize : (59.97 GB) 64396197888, totalAllocatedSize : (8.91 GB) 9563407360, askingSize : (5.00 GB) 5368709120, allocated disable threshold: 0.85
2021-01-20 07:22:35,865 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2021-01-20 07:22:35,865 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2021-01-20 07:22:35,866 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2021-01-20 07:22:35,866 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host: 1 can access pool: 1
2021-01-20 07:22:35,867 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Found a potential host id: 1 name: cloudstack-comp1.linbit and associated storage pools for this VM
2021-01-20 07:22:35,868 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(17|ROOT-->Pool(1))]
2021-01-20 07:22:35,868 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Deployment found - P0=VM[User|i-2-9-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(17|ROOT-->Pool(1))]
2021-01-20 07:22:36,138 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) 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
2021-01-20 07:22:36,146 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:36,146 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) We are allocating VM, increasing the used capacity of this host:1
2021-01-20 07:22:36,146 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Current Used CPU: 0 , Free CPU:4388 ,Requested CPU: 500
2021-01-20 07:22:36,146 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Current Used RAM: (0 bytes) 0 , Free RAM:(2.70 GB) 2899542016 ,Requested RAM: (512.00 MB) 536870912
2021-01-20 07:22:36,146 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) CPU STATS after allocation: for host: 1, old used: 0, old reserved: 0, actual total: 4388, total with overprovisioning: 4388; new used:500, reserved:0; requested cpu:500,alloc_from_last:false
2021-01-20 07:22:36,146 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) RAM STATS after allocation: for host: 1, old used: (0 bytes) 0, old reserved: (0 bytes) 0, total: (2.70 GB) 2899542016; new used: (512.00 MB) 536870912, reserved: (0 bytes) 0; requested mem: (512.00 MB) 536870912,alloc_from_last:false
2021-01-20 07:22:36,148 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host: 1 has cpu capability (cpu:2, speed:2194) to support requested CPU: 1 and requested speed: 500
2021-01-20 07:22:36,148 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0
2021-01-20 07:22:36,149 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:36,149 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) We need to allocate to the last host again, so checking if there is enough reserved capacity
2021-01-20 07:22:36,149 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Reserved CPU: 0 , Requested CPU: 500
2021-01-20 07:22:36,149 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Reserved RAM: (0 bytes) 0 , Requested RAM: (512.00 MB) 536870912
2021-01-20 07:22:36,149 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) STATS: Failed to alloc resource from host: 1 reservedCpu: 0, requested cpu: 500, reservedMem: (0 bytes) 0, requested mem: (512.00 MB) 536870912
2021-01-20 07:22:36,149 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host does not have enough reserved CPU available, cannot allocate to this host.
2021-01-20 07:22:36,149 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0
2021-01-20 07:22:36,151 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:36,151 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Free CPU: 4388 , Requested CPU: 500
2021-01-20 07:22:36,151 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Free RAM: (2.70 GB) 2899542016 , Requested RAM: (512.00 MB) 536870912
2021-01-20 07:22:36,151 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host has enough CPU and RAM available
2021-01-20 07:22:36,151 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) STATS: Can alloc CPU from host: 1, used: 0, reserved: 0, actual total: 4388, total with overprovisioning: 4388; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2021-01-20 07:22:36,151 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) STATS: Can alloc MEM from host: 1, used: (0 bytes) 0, reserved: (0 bytes) 0, total: (2.70 GB) 2899542016; requested mem: (512.00 MB) 536870912, alloc_from_last_host?: false , considerReservedCapacity?: true
2021-01-20 07:22:36,884 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Network id=204 is already implemented
2021-01-20 07:22:37,453 DEBUG [c.c.n.g.DirectPodBasedNetworkGuru] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) No IPv6 CIDR configured for VLAN 1
2021-01-20 07:22:37,806 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Changing active number of nics for network id=204 on 1
2021-01-20 07:22:38,073 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Asking VirtualRouter to prepare for Nic[19-9-384fb78f-08aa-4902-98d7-b077d2a92732-10.43.232.189]
2021-01-20 07:22:38,084 DEBUG [c.c.n.r.NetworkHelperImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Starting router VM[DomainRouter|r-4-VM]
2021-01-20 07:22:38,317 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 1 new host id: null host id before state transition: null
2021-01-20 07:22:38,317 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Successfully transitioned to start state for VM[DomainRouter|r-4-VM] reservation id = c548a3bb-79de-4285-a068-45ceddcc86d5
2021-01-20 07:22:38,562 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Deploy avoids pods: null, clusters: null, hosts: null
2021-01-20 07:22:38,573 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) DeploymentPlanner allocation algorithm: null
2021-01-20 07:22:38,574 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: (256.00 MB) 268435456
2021-01-20 07:22:38,574 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Is ROOT volume READY (pool already allocated)?: No
2021-01-20 07:22:38,574 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Deploy avoids pods: [], clusters: [], hosts: []
2021-01-20 07:22:38,575 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) This VM has last host_id specified, trying to choose the same host: 1
2021-01-20 07:22:38,582 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host: 1 has cpu capability (cpu:2, speed:2194) to support requested CPU: 1 and requested speed: 500
2021-01-20 07:22:38,582 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (256.00 MB) 268435456 , cpuOverprovisioningFactor: 1.0
2021-01-20 07:22:38,584 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:38,584 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) We need to allocate to the last host again, so checking if there is enough reserved capacity
2021-01-20 07:22:38,584 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Reserved CPU: 0 , Requested CPU: 500
2021-01-20 07:22:38,584 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Reserved RAM: (0 bytes) 0 , Requested RAM: (256.00 MB) 268435456
2021-01-20 07:22:38,584 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) STATS: Failed to alloc resource from host: 1 reservedCpu: 0, requested cpu: 500, reservedMem: (0 bytes) 0, requested mem: (256.00 MB) 268435456
2021-01-20 07:22:38,584 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host does not have enough reserved CPU available, cannot allocate to this host.
2021-01-20 07:22:38,584 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (256.00 MB) 268435456 , cpuOverprovisioningFactor: 1.0
2021-01-20 07:22:38,586 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:38,586 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Free CPU: 3888 , Requested CPU: 500
2021-01-20 07:22:38,586 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Free RAM: (2.20 GB) 2362671104 , Requested RAM: (256.00 MB) 268435456
2021-01-20 07:22:38,586 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host has enough CPU and RAM available
2021-01-20 07:22:38,586 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) STATS: Can alloc CPU from host: 1, used: 500, reserved: 0, actual total: 4388, total with overprovisioning: 4388; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2021-01-20 07:22:38,586 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) STATS: Can alloc MEM from host: 1, used: (512.00 MB) 536870912, reserved: (0 bytes) 0, total: (2.70 GB) 2899542016; requested mem: (256.00 MB) 268435456, alloc_from_last_host?: false , considerReservedCapacity?: true
2021-01-20 07:22:38,586 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) The last host of this VM is UP and has enough capacity
2021-01-20 07:22:38,586 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Now checking for suitable pools under zone: 1, pod: 1, cluster: 1
2021-01-20 07:22:38,590 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking suitable pools for volume (Id, Type): (14,ROOT)
2021-01-20 07:22:38,590 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) We need to allocate new storagepool for this volume
2021-01-20 07:22:38,590 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Calling StoragePoolAllocators to find suitable pools
2021-01-20 07:22:38,593 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) System VMs will use shared storage for zone id=1
2021-01-20 07:22:38,593 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2021-01-20 07:22:38,593 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) ClusterScopeStoragePoolAllocator looking for storage pool
2021-01-20 07:22:38,593 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored.
2021-01-20 07:22:38,594 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Found pools matching tags: [Pool[1|NetworkFilesystem]]
2021-01-20 07:22:38,595 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking if storage pool is suitable, name: null ,poolId: 1
2021-01-20 07:22:38,596 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2021-01-20 07:22:38,597 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking pool 1 for storage, totalSize: 32198098944, usedBytes: 3653763072, usedPct: 0.11347760246201945, disable threshold: 0.85
2021-01-20 07:22:38,597 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Destination pool id: 1
2021-01-20 07:22:38,610 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Pool ID for the volume with ID 14 is null
2021-01-20 07:22:38,614 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Found storage pool default of type NetworkFilesystem with over-provisioning factor 2
2021-01-20 07:22:38,614 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Total over-provisioned capacity calculated is 2 * (29.99 GB) 32198098944
2021-01-20 07:22:38,614 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Total capacity of the pool default with ID 1 is (59.97 GB) 64396197888
2021-01-20 07:22:38,615 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking pool: 1 for storage allocation , maxSize : (59.97 GB) 64396197888, totalAllocatedSize : (8.91 GB) 9563407360, askingSize : (1.95 GB) 2097152000, allocated disable threshold: 0.85
2021-01-20 07:22:38,615 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2021-01-20 07:22:38,615 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2021-01-20 07:22:38,616 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2021-01-20 07:22:38,617 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host: 1 can access pool: 1
2021-01-20 07:22:38,617 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Found a potential host id: 1 name: cloudstack-comp1.linbit and associated storage pools for this VM
2021-01-20 07:22:38,617 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) 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(14|ROOT-->Pool(1))]
2021-01-20 07:22:38,617 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Deployment found - P0=VM[DomainRouter|r-4-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(14|ROOT-->Pool(1))]
2021-01-20 07:22:38,855 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 1 new host id: 1 host id before state transition: null
2021-01-20 07:22:38,855 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) VM starting again on the last host it was stopped on
2021-01-20 07:22:38,863 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:38,863 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) We are allocating VM, increasing the used capacity of this host:1
2021-01-20 07:22:38,863 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Current Used CPU: 500 , Free CPU:3888 ,Requested CPU: 500
2021-01-20 07:22:38,863 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Current Used RAM: (512.00 MB) 536870912 , Free RAM:(2.20 GB) 2362671104 ,Requested RAM: (256.00 MB) 268435456
2021-01-20 07:22:38,864 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
2021-01-20 07:22:38,864 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Reserved CPU: 0 , Requested CPU: 500
2021-01-20 07:22:38,864 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Reserved RAM: (0 bytes) 0 , Requested RAM: (256.00 MB) 268435456
2021-01-20 07:22:38,864 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) CPU STATS after allocation: for host: 1, old used: 500, old reserved: 0, actual total: 4388, total with overprovisioning: 4388; new used:1000, reserved:0; requested cpu:500,alloc_from_last:true
2021-01-20 07:22:38,864 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) RAM STATS after allocation: for host: 1, old used: (512.00 MB) 536870912, old reserved: (0 bytes) 0, total: (2.70 GB) 2899542016; new used: (768.00 MB) 805306368, reserved: (0 bytes) 0; requested mem: (256.00 MB) 268435456,alloc_from_last:true
2021-01-20 07:22:38,865 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host: 1 has cpu capability (cpu:2, speed:2194) to support requested CPU: 1 and requested speed: 500
2021-01-20 07:22:38,865 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (256.00 MB) 268435456 , cpuOverprovisioningFactor: 1.0
2021-01-20 07:22:38,866 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:38,866 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) We need to allocate to the last host again, so checking if there is enough reserved capacity
2021-01-20 07:22:38,866 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Reserved CPU: 0 , Requested CPU: 500
2021-01-20 07:22:38,866 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Reserved RAM: (0 bytes) 0 , Requested RAM: (256.00 MB) 268435456
2021-01-20 07:22:38,866 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) STATS: Failed to alloc resource from host: 1 reservedCpu: 0, requested cpu: 500, reservedMem: (0 bytes) 0, requested mem: (256.00 MB) 268435456
2021-01-20 07:22:38,866 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host does not have enough reserved CPU available, cannot allocate to this host.
2021-01-20 07:22:38,866 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (256.00 MB) 268435456 , cpuOverprovisioningFactor: 1.0
2021-01-20 07:22:38,868 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:38,868 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Free CPU: 3888 , Requested CPU: 500
2021-01-20 07:22:38,868 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Free RAM: (2.20 GB) 2362671104 , Requested RAM: (256.00 MB) 268435456
2021-01-20 07:22:38,868 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Host has enough CPU and RAM available
2021-01-20 07:22:38,868 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) STATS: Can alloc CPU from host: 1, used: 500, reserved: 0, actual total: 4388, total with overprovisioning: 4388; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2021-01-20 07:22:38,868 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) STATS: Can alloc MEM from host: 1, used: (512.00 MB) 536870912, reserved: (0 bytes) 0, total: (2.70 GB) 2899542016; requested mem: (256.00 MB) 268435456, alloc_from_last_host?: false , considerReservedCapacity?: true
2021-01-20 07:22:39,616 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Asking VirtualRouter to prepare for Nic[8-4-c548a3bb-79de-4285-a068-45ceddcc86d5-10.43.232.144]
2021-01-20 07:22:39,620 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Asking SecurityGroupProvider to prepare for Nic[8-4-c548a3bb-79de-4285-a068-45ceddcc86d5-10.43.232.144]
2021-01-20 07:22:40,665 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Reserved NIC for r-4-VM [ipv4:169.254.0.233 netmask:255.255.0.0 gateway:169.254.0.1]
2021-01-20 07:22:41,023 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) can't find ready template: 207 for data center 1
2021-01-20 07:22:41,512 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Cleaning up resources for the vm VM[DomainRouter|r-4-VM] in Starting state
2021-01-20 07:22:41,517 DEBUG [c.c.a.t.Request] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Seq 1-2372552578694132286: Sending { Cmd , MgmtId: 2199193903112, via: 1(cloudstack-comp1.linbit), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeCleanup":"false","controlIp":"169.254.2.147","forceStop":"false","volumesToDisconnect":[],"vmName":"r-4-VM","executeInSequence":"false","wait":"0"}}] }
2021-01-20 07:22:41,696 DEBUG [c.c.a.t.Request] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Seq 1-2372552578694132286: Received: { Ans: , MgmtId: 2199193903112, via: 1(cloudstack-comp1.linbit), Ver: v1, Flags: 10, { StopAnswer } }
2021-01-20 07:22:41,700 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Successfully updated user statistics as a part of domR VM[DomainRouter|r-4-VM] reboot/stop
2021-01-20 07:22:41,879 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Asking VirtualRouter to release NicProfile[8-4-c548a3bb-79de-4285-a068-45ceddcc86d5-10.43.232.144-vlan://untagged]
2021-01-20 07:22:41,879 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Asking SecurityGroupProvider to release NicProfile[8-4-c548a3bb-79de-4285-a068-45ceddcc86d5-10.43.232.144-vlan://untagged]
2021-01-20 07:22:41,882 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Released nic: NicProfile[9-4-null-null-null]
2021-01-20 07:22:42,119 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Successfully released network resources for the vm VM[DomainRouter|r-4-VM]
2021-01-20 07:22:42,119 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Successfully cleaned up resources for the VM VM[DomainRouter|r-4-VM] in Starting state
2021-01-20 07:22:42,912 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 1 new host id: null host id before state transition: 1
2021-01-20 07:22:42,919 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:42,919 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total RAM: (2.70 GB) 2899542016 and RAM after applying overprovisioning: (2.70 GB) 2899542016
2021-01-20 07:22:42,919 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 4388, total with overprovisioning: 4388; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2021-01-20 07:22:42,919 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) release mem from host: 1, old used: (768.00 MB) 805306368,reserved: (0 bytes) 0, total: (2.70 GB) 2899542016; new used: (512.00 MB) 536870912,reserved:(0 bytes) 0; movedfromreserved: false,moveToReserveredfalse
2021-01-20 07:22:44,004 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Cleaning up resources for the vm VM[User|i-2-9-VM] in Starting state
2021-01-20 07:22:44,009 DEBUG [c.c.a.t.Request] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Seq 1-2372552578694132287: Sending { Cmd , MgmtId: 2199193903112, via: 1(cloudstack-comp1.linbit), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeCleanup":"false","forceStop":"false","volumesToDisconnect":[],"vmName":"i-2-9-VM","executeInSequence":"false","wait":"0"}}] }
2021-01-20 07:22:44,215 DEBUG [c.c.a.t.Request] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Seq 1-2372552578694132287: Received: { Ans: , MgmtId: 2199193903112, via: 1(cloudstack-comp1.linbit), Ver: v1, Flags: 10, { StopAnswer } }
2021-01-20 07:22:44,739 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Changing active number of nics for network id=204 on -1
2021-01-20 07:22:46,271 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Asking VirtualRouter to release NicProfile[19-9-384fb78f-08aa-4902-98d7-b077d2a92732-10.43.232.189-vlan://untagged]
2021-01-20 07:22:46,271 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Asking SecurityGroupProvider to release NicProfile[19-9-384fb78f-08aa-4902-98d7-b077d2a92732-10.43.232.189-vlan://untagged]
2021-01-20 07:22:46,271 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Successfully released network resources for the vm VM[User|i-2-9-VM]
2021-01-20 07:22:46,271 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Successfully cleaned up resources for the VM VM[User|i-2-9-VM] in Starting state
2021-01-20 07:22:47,999 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) 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
2021-01-20 07:22:48,007 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 07:22:48,007 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Hosts's actual total RAM: (2.70 GB) 2899542016 and RAM after applying overprovisioning: (2.70 GB) 2899542016
2021-01-20 07:22:48,007 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) release cpu from host: 1, old used: 500,reserved: 0, actual total: 4388, total with overprovisioning: 4388; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2021-01-20 07:22:48,007 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) release mem from host: 1, old used: (512.00 MB) 536870912,reserved: (0 bytes) 0, total: (2.70 GB) 2899542016; new used: (0 bytes) 0,reserved:(0 bytes) 0; movedfromreserved: false,moveToReserveredfalse
2021-01-20 07:22:49,187 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Caught CloudRuntimeException, returning job failed com.cloud.utils.exception.CloudRuntimeException: can't find ready template: 207 for data center 1
2021-01-20 07:22:49,188 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Done executing VM work job: com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":1,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":9,"handlerName":"VirtualMachineManagerImpl"}
2021-01-20 07:22:49,189 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Complete async job-144, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0ABtVbmFibGUgdG8gc3RhcnQgVk0gaW5zdGFuY2V1cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABRzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAAhCAAZmb3JtYXRJAApsaW5lTnVtYmVyTAAPY2xhc3NMb2FkZXJOYW1lcQB-AAVMAA5kZWNsYXJpbmdDbGFzc3EAfgAFTAAIZmlsZU5hbWVxAH4ABUwACm1ldGhvZE5hbWVxAH4ABUwACm1vZHVsZU5hbWVxAH4ABUwADW1vZHVsZVZlcnNpb25xAH4ABXhwAQAAFV10AANhcHB0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRwcHNxAH4ADAL____-cHQALWpkay5pbnRlcm5hbC5yZWZsZWN0Lk5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHQACWphdmEuYmFzZXQACDExLjAuOS4xc3EAfgAMAgAAAD5wcQB-ABNxAH4AFHQABmludm9rZXEAfgAWcQB-ABdzcQB-AAwCAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABlxAH4AFnEAfgAXc3EAfgAMAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AGXEAfgAWcQB-ABdzcQB-AAwBAAAAa3EAfgAOdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-AAwBAAAV_3EAfgAOcQB-AA9xAH4AEHEAfgAjcHBzcQB-AAwBAAAAZnEAfgAOdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4ADAEAAAJscQB-AA50AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4ADAEAAAAwcQB-AA50AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgAMAQAAADdxAH4ADnQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgAMAQAAAGZxAH4ADnQAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AM3QAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgAMAQAAADRxAH4ADnEAfgA2cQB-ADN0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgAMAQAAAC1xAH4ADnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAvcQB-ADBwcHNxAH4ADAEAAAI4cQB-AA5xAH4AKnEAfgArcQB-ADBwcHNxAH4ADAIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA0cQB-ABZxAH4AF3NxAH4ADAIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AMHEAfgAWcQB-ABdzcQB-AAwCAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAWcQB-ABdzcQB-AAwCAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEVxAH4AMHEAfgAWcQB-ABdzcQB-AAwCAAADQnB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AMHEAfgAWcQB-ABdzcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4AAAQmncIAAAAAAAAAAB4
2021-01-20 07:22:49,190 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Publish async job-144 complete on message bus
2021-01-20 07:22:49,190 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Wake up jobs related to job-144
2021-01-20 07:22:49,190 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Update db status for job-144
2021-01-20 07:22:49,191 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144 ctx-7d56fdaa) (logid:bf354ff9) Wake up jobs joined with job-144 and disjoin all subjobs created from job- 144
2021-01-20 07:22:49,818 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144) (logid:bf354ff9) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 9, job origin: 143
2021-01-20 07:22:49,818 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144) (logid:bf354ff9) Done executing com.cloud.vm.VmWorkStart for job-144
2021-01-20 07:22:49,819 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-27:ctx-24cdb43a job-143/job-144) (logid:bf354ff9) Remove job-144 from job monitoring
2021-01-20 07:22:50,089 ERROR [c.c.v.UserVmManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) VM VM[User|i-2-9-VM] unexpectedly went to Stopped state
2021-01-20 07:22:50,097 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Destroying vm VM[User|i-2-9-VM] as it failed to create on Host with Id:null
2021-01-20 07:22:50,697 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) 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
2021-01-20 07:22:52,313 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Updating resource Type = volume count for Account = 2 Operation = decreasing Amount = 1
2021-01-20 07:22:52,995 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Updating resource Type = primary_storage count for Account = 2 Operation = decreasing Amount = (5.00 GB) 5368709120
2021-01-20 07:22:53,767 WARN [c.c.a.AlertManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) AlertType:: 8 | dataCenterId:: 1 | podId:: 1 | clusterId:: null | message:: Failed to deploy Vm with Id: 9, on Host with Id: null
2021-01-20 07:22:54,049 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Updating resource Type = user_vm count for Account = 2 Operation = decreasing Amount = 1
2021-01-20 07:22:54,496 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Updating resource Type = cpu count for Account = 2 Operation = decreasing Amount = 1
2021-01-20 07:22:55,441 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Updating resource Type = memory count for Account = 2 Operation = decreasing Amount = 512
2021-01-20 07:22:56,010 WARN [o.a.c.a.c.u.v.DeployVMCmd] (API-Job-Executor-8:ctx-8241bbe7 job-143 ctx-54d38a85) (logid:bf354ff9) Exception:
2021-01-20 07:22:56,012 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143) (logid:bf354ff9) Complete async job-143, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Failed to deploy VM VM[User|i-2-9-VM]"}
2021-01-20 07:22:56,013 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143) (logid:bf354ff9) Publish async job-143 complete on message bus
2021-01-20 07:22:56,013 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143) (logid:bf354ff9) Wake up jobs related to job-143
2021-01-20 07:22:56,013 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143) (logid:bf354ff9) Update db status for job-143
2021-01-20 07:22:56,014 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143) (logid:bf354ff9) Wake up jobs joined with job-143 and disjoin all subjobs created from job- 143
2021-01-20 07:22:56,572 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-8241bbe7 job-143) (logid:bf354ff9) Done executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-143
2021-01-20 07:22:56,572 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-8:ctx-8241bbe7 job-143) (logid:bf354ff9) Remove job-143 from job monitoring
EXPECTED RESULTS
Started/Running VM instance
ACTUAL RESULTS
Stopped instance, with an error event, that don't tell the user much.