You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cloudstack.apache.org by GitBox <gi...@apache.org> on 2021/01/20 08:05:19 UTC
[GitHub] [cloudstack] rp- opened a new issue #4599: Unable to start KVM instance after upgrade to 4.15.0
rp- opened a new issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599
<!--
Verify first that your issue/request is not already reported on GitHub.
Also test if the latest release and master branch are affected too.
Always add information AFTER of these HTML comments, but no need to delete the comments.
-->
##### ISSUE TYPE
<!-- Pick one below and delete the rest -->
* Bug Report
##### COMPONENT NAME
<!--
Categorize the issue, e.g. API, VR, VPN, UI, etc.
-->
~~~
Executor
~~~
##### CLOUDSTACK VERSION
<!--
New line separated list of affected versions, commit ID for issues on master branch.
-->
~~~
4.15.0
~~~
##### CONFIGURATION
<!--
Information about the configuration if relevant, e.g. basic network, advanced networking, etc. N/A otherwise
-->
basic network, simple test install
##### OS / ENVIRONMENT
<!--
Information about the environment if relevant, N/A otherwise
-->
Centos 7.9
##### SUMMARY
<!-- Explain the problem/feature briefly -->
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
<!--
For bugs, show exactly how to reproduce the problem, using a minimal test-case. Use Screenshots if accurate.
For new features, show how the feature would be used.
-->
Here is the job log, which I assume is the start of the instance
<!-- Paste example playbooks or commands between quotes below -->
~~~
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.Servic
eOffering\":\"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-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyA
BFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, 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-AAVMAA5kZWNsYXJpbmdDbGFzc3EAfgAFTAAIZmlsZU5hbWVxAH4ABUwACm1ldGhvZE5hbWVxAH4ABUwACm1vZHVsZU5
hbWVxAH4ABUwADW1vZHVsZVZlcnNpb25xAH4ABXhwAQAAFV10AANhcHB0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRwcHNxAH4ADAL____-cHQALWpkay5pbnRlcm5hbC5yZWZsZWN0Lk5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHQACWphdmEuYmFzZXQACDExLjAuOS4xc3EAfgAMAgAAAD5wcQB-ABNxAH4AFHQABmludm9rZXEAfgAWcQB-ABdzcQB-AAwCAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABlxAH4AFnEAfgAXc3EAfgAMAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AGXEAfgAWcQB-ABdzcQB-AAwBAAAAa3EAfgAOdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-AAwBAAAV_3EAfgAOcQB-AA9xAH4AEHEAfgAjcHBzcQB-AAwBAAAAZnEAfgAOdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4ADAEAAAJscQB-AA50AD9vcmcuYXBhY2hlLmNsb3Vkc3Rh
Y2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4ADAEAAAAwcQB-AA50AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgAMAQAAADdxAH4ADnQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgAMAQAAAGZxAH4ADnQAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AM3QAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgAMAQAAADRxAH4ADnEAfgA2cQB-ADN0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgAMAQAAAC1xAH4ADnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAvcQB-ADBwcHNxAH4ADAEAAAI4cQB-AA5xAH4AKnEAfgArcQB-ADBwcHNxAH4ADAIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA0cQB-ABZxAH4AF3NxAH4ADAIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0A
A9GdXR1cmVUYXNrLmphdmFxAH4AMHEAfgAWcQB-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
~~~
<!-- You can also paste gist.github.com links for larger files -->
##### EXPECTED RESULTS
<!-- What did you expect to happen when running the steps above? -->
~~~
Started/Running VM instance
~~~
##### ACTUAL RESULTS
<!-- What actually happened? -->
<!-- Paste verbatim command output between quotes below -->
~~~
Stopped instance, with an error event, that don't tell the user much.
~~~
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] rp- commented on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
rp- commented on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763537066
:/
```
mysql> select id, state, download_state from template_store_ref where template_id=207;
+----+-----------+----------------+
| id | state | download_state |
+----+-----------+----------------+
| 11 | Allocated | NULL |
+----+-----------+----------------+
1 row in set (0.00 sec)
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] weizhouapache commented on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
weizhouapache commented on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763506274
> systemvm-kvm-4.15.0
@rp-
could you check database to see if the template (id=207) is systemvm-kvm-4.15.0 and what the state is ?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] shwstppr commented on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
shwstppr commented on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763535864
@rp- you might have to check template state in image store,
`select * from template_store_ref where template_id=207\G;`
It should have state=Ready and download_state=DOWNLOADED
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] weizhouapache commented on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
weizhouapache commented on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763430006
@rp-
the log shows
```
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
```
it looks like the systemvm template for VR is not ready or removed.
please change global config "router.template.kvm" to a correct value, restart mgt server, and retry.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] rp- edited a comment on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
rp- edited a comment on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763636418
Thanks I finally fixed my installation.
The ultimate problem was, that a upgrade+reboot and some network configure script destroyed my `cloudbr0` and so started VM's weren't able to access any outside network. So SSVM could never download the image.
I fixed the network and restarted the cloud-management server and `cloud.service` in the SSVM.
From a user perspective it would be nice if I could see if the template image was correctly downloaded, or maybe see some error from the download manager.
I just saw the the VR wasn't startet, and all other systemvm were "Green".
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] rp- closed issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
rp- closed issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] shwstppr edited a comment on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
shwstppr edited a comment on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763535864
@rp- you might have to check template state in image/secondary store,
`select * from template_store_ref where template_id=207\G;`
It should have state=Ready and download_state=DOWNLOADED
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] rp- commented on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
rp- commented on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763636418
Thanks I finally fixed my installation.
The ultimate problem was, that a upgrade+reboot and some network configure script destroyed my `cloudbr0` and so started VM's weren't able to access any outside network. So SSVM could never download the image.
I fixed the network and restarted the cloud-management server and `cloud.service` in the SSVM.
From a user perspective it would be nice if I could see if the template image was correctly downloaded, or maybe see some error from the download manager.
I just saw the the VR wasn't startet, and all other systemvm where "Green".
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] rp- commented on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
rp- commented on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763440348
The `systemvm-kvm-4.15.0` is Active and correctly set in: `router.template.kvm`, but the VR cannot start it seems:
```
2021-01-20 08:47:35,213 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp1074389766-21:ctx-8bd2063b ctx-e8bd7bea) (logid:1d8f1e7b) submit async job-150, details: AsyncJobVO {id:150, userId: 2, accountId: 2, instanceType: DomainRouter, instanceId: 4, cmd: org.apache.cloudstack.api.command.admin.router.StartRouterCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"57","id":"88f887c1-97cc-4bf4-9815-24d84e8bd83a","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"88f887c1-97cc-4bf4-9815-24d84e8bd83a\"}","ctxAccountId":"2","uuid":"88f887c1-97cc-4bf4-9815-24d84e8bd83a","cmdEventType":"ROUTER.START"}, 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 08:47:35,217 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-1:ctx-796675ae job-150) (logid:3a652fb3) Add job-150 into job monitoring
2021-01-20 08:47:35,220 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-796675ae job-150) (logid:b566c8a5) Executing AsyncJobVO {id:150, userId: 2, accountId: 2, instanceType: DomainRouter, instanceId: 4, cmd: org.apache.cloudstack.api.command.admin.router.StartRouterCmd, cmdInfo: {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"57","id":"88f887c1-97cc-4bf4-9815-24d84e8bd83a","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"88f887c1-97cc-4bf4-9815-24d84e8bd83a\"}","ctxAccountId":"2","uuid":"88f887c1-97cc-4bf4-9815-24d84e8bd83a","cmdEventType":"ROUTER.START"}, 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 08:47:35,735 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-1:ctx-796675ae job-150 ctx-15d8adb1) (logid:b566c8a5) Starting network Ntwk[204|Guest|6]...
2021-01-20 08:47:35,742 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-1:ctx-796675ae job-150 ctx-15d8adb1) (logid:b566c8a5) Network id=204 is already implemented
2021-01-20 08:47:35,743 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-1:ctx-796675ae job-150 ctx-15d8adb1) (logid:b566c8a5) Starting network Ntwk[202|Control|3]...
2021-01-20 08:47:35,746 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-1:ctx-796675ae job-150 ctx-15d8adb1) (logid:b566c8a5) Network id=202 is already implemented
2021-01-20 08:47:35,749 DEBUG [c.c.n.r.NetworkHelperImpl] (API-Job-Executor-1:ctx-796675ae job-150 ctx-15d8adb1) (logid:b566c8a5) Starting router VM[DomainRouter|r-4-VM]
2021-01-20 08:47:36,201 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-796675ae job-150 ctx-15d8adb1) (logid:b566c8a5) Sync job-151 execution on object VmWorkJobQueue.4
2021-01-20 08:47:39,176 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151) (logid:f6e52f2f) Add job-151 into job monitoring
2021-01-20 08:47:39,182 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151) (logid:b566c8a5) Executing AsyncJobVO {id:151, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AA5SZXN0YXJ0Tm
V0d29ya3QAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2199193903112, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed Jan 20 08:47:36 UTC 2021, removed: null}
2021-01-20 08:47:39,185 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151) (logid:b566c8a5) Run VM work job: com.cloud.vm.VmWorkStart for VM 4, job origin: 150
2021-01-20 08:47:39,188 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"RestartNetwork":"rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE"},"userId":2,"accountId":2,"vmId":4,"handlerName":"VirtualMachineManagerImpl"}
2021-01-20 08:47:39,214 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) 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 08:47:39,214 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Successfully transitioned to start state for VM[DomainRouter|r-4-VM] reservation id = 4c3a34ea-3d21-4b63-8f9d-5d79f121c723
2021-01-20 08:47:39,405 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Deploy avoids pods: null, clusters: null, hosts: null
2021-01-20 08:47:39,421 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) DeploymentPlanner allocation algorithm: null
2021-01-20 08:47:39,427 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) 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 08:47:39,427 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Is ROOT volume READY (pool already allocated)?: No
2021-01-20 08:47:39,428 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Deploy avoids pods: [], clusters: [], hosts: []
2021-01-20 08:47:39,429 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) This VM has last host_id specified, trying to choose the same host: 1
2021-01-20 08:47:39,445 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Host: 1 has cpu capability (cpu:2, speed:2194) to support requested CPU: 1 and requested speed: 500
2021-01-20 08:47:39,448 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (256.00 MB) 268435456 , cpuOverprovisioningFactor: 1.0
2021-01-20 08:47:39,460 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 08:47:39,460 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) We need to allocate to the last host again, so checking if there is enough reserved capacity
2021-01-20 08:47:39,461 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Reserved CPU: 500 , Requested CPU: 500
2021-01-20 08:47:39,461 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Reserved RAM: (256.00 MB) 268435456 , Requested RAM: (256.00 MB) 268435456
2021-01-20 08:47:39,461 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Host has enough CPU and RAM available
2021-01-20 08:47:39,469 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) STATS: Can alloc CPU from host: 1, used: 0, reserved: 500, actual total: 4388, total with overprovisioning: 4388; requested cpu:500,alloc_from_last_host?:true ,considerReservedCapacity?: true
2021-01-20 08:47:39,476 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) STATS: Can alloc MEM from host: 1, used: (0 bytes) 0, reserved: (256.00 MB) 268435456, total: (2.70 GB) 2899542016; requested mem: (256.00 MB) 268435456, alloc_from_last_host?: true , considerReservedCapacity?: true
2021-01-20 08:47:39,476 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) The last host of this VM is UP and has enough capacity
2021-01-20 08:47:39,477 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Now checking for suitable pools under zone: 1, pod: 1, cluster: 1
2021-01-20 08:47:39,481 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Checking suitable pools for volume (Id, Type): (14,ROOT)
2021-01-20 08:47:39,481 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) We need to allocate new storagepool for this volume
2021-01-20 08:47:39,482 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Calling StoragePoolAllocators to find suitable pools
2021-01-20 08:47:39,485 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) System VMs will use shared storage for zone id=1
2021-01-20 08:47:39,486 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2021-01-20 08:47:39,486 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) ClusterScopeStoragePoolAllocator looking for storage pool
2021-01-20 08:47:39,488 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored.
2021-01-20 08:47:39,489 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Found pools matching tags: [Pool[1|NetworkFilesystem]]
2021-01-20 08:47:39,491 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Checking if storage pool is suitable, name: null ,poolId: 1
2021-01-20 08:47:39,493 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
2021-01-20 08:47:39,501 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Checking pool 1 for storage, totalSize: 32198098944, usedBytes: 3653763072, usedPct: 0.11347760246201945, disable threshold: 0.85
2021-01-20 08:47:39,501 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Destination pool id: 1
2021-01-20 08:47:39,527 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Pool ID for the volume with ID 14 is null
2021-01-20 08:47:39,533 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Found storage pool default of type NetworkFilesystem with over-provisioning factor 2
2021-01-20 08:47:39,533 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Total over-provisioned capacity calculated is 2 * (29.99 GB) 32198098944
2021-01-20 08:47:39,533 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Total capacity of the pool default with ID 1 is (59.97 GB) 64396197888
2021-01-20 08:47:39,538 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) 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 08:47:39,538 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2021-01-20 08:47:39,538 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2021-01-20 08:47:39,539 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2021-01-20 08:47:39,543 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Host: 1 can access pool: 1
2021-01-20 08:47:39,544 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Found a potential host id: 1 name: cloudstack-comp1.linbit and associated storage pools for this VM
2021-01-20 08:47:39,544 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) 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 08:47:39,544 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) 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 08:47:39,757 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) 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 08:47:39,757 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) VM starting again on the last host it was stopped on
2021-01-20 08:47:39,768 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 08:47:39,768 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) We are allocating VM, increasing the used capacity of this host:1
2021-01-20 08:47:39,772 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Current Used CPU: 0 , Free CPU:3888 ,Requested CPU: 500
2021-01-20 08:47:39,772 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Current Used RAM: (0 bytes) 0 , Free RAM:(2.45 GB) 2631106560 ,Requested RAM: (256.00 MB) 268435456
2021-01-20 08:47:39,773 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
2021-01-20 08:47:39,773 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Reserved CPU: 500 , Requested CPU: 500
2021-01-20 08:47:39,773 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Reserved RAM: (256.00 MB) 268435456 , Requested RAM: (256.00 MB) 268435456
2021-01-20 08:47:39,781 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) CPU STATS after allocation: for host: 1, old used: 0, old reserved: 500, actual total: 4388, total with overprovisioning: 4388; new used:500, reserved:0; requested cpu:500,alloc_from_last:true
2021-01-20 08:47:39,789 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) RAM STATS after allocation: for host: 1, old used: (0 bytes) 0, old reserved: (256.00 MB) 268435456, total: (2.70 GB) 2899542016; new used: (256.00 MB) 268435456, reserved: (0 bytes) 0; requested mem: (256.00 MB) 268435456,alloc_from_last:true
2021-01-20 08:47:39,791 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Host: 1 has cpu capability (cpu:2, speed:2194) to support requested CPU: 1 and requested speed: 500
2021-01-20 08:47:39,791 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (256.00 MB) 268435456 , cpuOverprovisioningFactor: 1.0
2021-01-20 08:47:39,793 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 08:47:39,793 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) We need to allocate to the last host again, so checking if there is enough reserved capacity
2021-01-20 08:47:39,793 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Reserved CPU: 500 , Requested CPU: 500
2021-01-20 08:47:39,793 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Reserved RAM: (256.00 MB) 268435456 , Requested RAM: (256.00 MB) 268435456
2021-01-20 08:47:39,793 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Host has enough CPU and RAM available
2021-01-20 08:47:39,793 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) STATS: Can alloc CPU from host: 1, used: 0, reserved: 500, actual total: 4388, total with overprovisioning: 4388; requested cpu:500,alloc_from_last_host?:true ,considerReservedCapacity?: true
2021-01-20 08:47:39,793 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) STATS: Can alloc MEM from host: 1, used: (0 bytes) 0, reserved: (256.00 MB) 268435456, total: (2.70 GB) 2899542016; requested mem: (256.00 MB) 268435456, alloc_from_last_host?: true , considerReservedCapacity?: true
2021-01-20 08:47:40,556 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Asking SecurityGroupProvider to prepare for Nic[8-4-4c3a34ea-3d21-4b63-8f9d-5d79f121c723-10.43.232.144]
2021-01-20 08:47:40,560 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Asking VirtualRouter to prepare for Nic[8-4-4c3a34ea-3d21-4b63-8f9d-5d79f121c723-10.43.232.144]
2021-01-20 08:47:41,802 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Reserved NIC for r-4-VM [ipv4:169.254.254.111 netmask:255.255.0.0 gateway:169.254.0.1]
2021-01-20 08:47:42,221 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) can't find ready template: 207 for data center 1
2021-01-20 08:47:42,484 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Cleaning up resources for the vm VM[DomainRouter|r-4-VM] in Starting state
2021-01-20 08:47:42,490 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Seq 1-2176927469880213520: 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 08:47:42,661 DEBUG [c.c.a.t.Request] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Seq 1-2176927469880213520: Received: { Ans: , MgmtId: 2199193903112, via: 1(cloudstack-comp1.linbit), Ver: v1, Flags: 10, { StopAnswer } }
2021-01-20 08:47:42,671 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Successfully updated user statistics as a part of domR VM[DomainRouter|r-4-VM] reboot/stop
2021-01-20 08:47:43,156 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Asking SecurityGroupProvider to release NicProfile[8-4-4c3a34ea-3d21-4b63-8f9d-5d79f121c723-10.43.232.144-vlan://untagged]
2021-01-20 08:47:43,156 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Asking VirtualRouter to release NicProfile[8-4-4c3a34ea-3d21-4b63-8f9d-5d79f121c723-10.43.232.144-vlan://untagged]
2021-01-20 08:47:43,328 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Released nic: NicProfile[9-4-null-null-null]
2021-01-20 08:47:43,643 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Successfully released network resources for the vm VM[DomainRouter|r-4-VM]
2021-01-20 08:47:43,643 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Successfully cleaned up resources for the VM VM[DomainRouter|r-4-VM] in Starting state
2021-01-20 08:47:44,643 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) 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 08:47:44,654 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Hosts's actual total CPU: 4388 and CPU after applying overprovisioning: 4388
2021-01-20 08:47:44,654 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Hosts's actual total RAM: (2.70 GB) 2899542016 and RAM after applying overprovisioning: (2.70 GB) 2899542016
2021-01-20 08:47:44,665 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) 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 08:47:44,675 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) release mem from host: 1, old used: (256.00 MB) 268435456,reserved: (0 bytes) 0, total: (2.70 GB) 2899542016; new used: (0 bytes) 0,reserved:(0 bytes) 0; movedfromreserved: false,moveToReserveredfalse
2021-01-20 08:47:45,233 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Caught CloudRuntimeException, returning job failed com.cloud.utils.exception.CloudRuntimeException: can't find ready template: 207 for data center 1
2021-01-20 08:47:45,247 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Done executing VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"RestartNetwork":"rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE"},"userId":2,"accountId":2,"vmId":4,"handlerName":"VirtualMachineManagerImpl"}
2021-01-20 08:47:45,256 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Complete async job-151, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0ABtVbmFibGUgdG8gc3RhcnQgVk0gaW5zdGFuY2V1cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABRzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAAhCAAZmb3JtYXRJAApsaW5lTnVtYmVyTAAPY2xhc3NMb2FkZXJOYW1lcQB-AAVMAA5kZWNsYXJpbmdDbGFzc3EAfgAFTAAIZmlsZU5hbWVxAH4ABUwACm1ldGhvZE5hbWVxAH4ABUwACm1vZHVsZU5h
bWVxAH4ABUwADW1vZHVsZVZlcnNpb25xAH4ABXhwAQAAFV10AANhcHB0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRwcHNxAH4ADAL____-cHQALWpkay5pbnRlcm5hbC5yZWZsZWN0Lk5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHQACWphdmEuYmFzZXQACDExLjAuOS4xc3EAfgAMAgAAAD5wcQB-ABNxAH4AFHQABmludm9rZXEAfgAWcQB-ABdzcQB-AAwCAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABlxAH4AFnEAfgAXc3EAfgAMAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AGXEAfgAWcQB-ABdzcQB-AAwBAAAAa3EAfgAOdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-AAwBAAAV_3EAfgAOcQB-AA9xAH4AEHEAfgAjcHBzcQB-AAwBAAAAZnEAfgAOdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4ADAEAAAJscQB-AA50AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY
2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4ADAEAAAAwcQB-AA50AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgAMAQAAADdxAH4ADnQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgAMAQAAAGZxAH4ADnQAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AM3QAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgAMAQAAADRxAH4ADnEAfgA2cQB-ADN0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgAMAQAAAC1xAH4ADnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAvcQB-ADBwcHNxAH4ADAEAAAI4cQB-AA5xAH4AKnEAfgArcQB-ADBwcHNxAH4ADAIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA0cQB-ABZxAH4AF3NxAH4ADAIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA
9GdXR1cmVUYXNrLmphdmFxAH4AMHEAfgAWcQB-ABdzcQB-AAwCAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAWcQB-ABdzcQB-AAwCAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEVxAH4AMHEAfgAWcQB-ABdzcQB-AAwCAAADQnB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AMHEAfgAWcQB-ABdzcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4AAAQmncIAAAAAAAAAAB4
2021-01-20 08:47:45,257 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Publish async job-151 complete on message bus
2021-01-20 08:47:45,257 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Wake up jobs related to job-151
2021-01-20 08:47:45,257 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Update db status for job-151
2021-01-20 08:47:45,348 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151 ctx-b797539d) (logid:b566c8a5) Wake up jobs joined with job-151 and disjoin all subjobs created from job- 151
2021-01-20 08:47:45,732 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151) (logid:b566c8a5) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 4, job origin: 150
2021-01-20 08:47:45,732 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151) (logid:b566c8a5) Done executing com.cloud.vm.VmWorkStart for job-151
2021-01-20 08:47:45,736 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-1:ctx-f942d49a job-150/job-151) (logid:b566c8a5) Remove job-151 from job monitoring
2021-01-20 08:47:47,419 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-1:ctx-796675ae job-150) (logid:b566c8a5) Unexpected exception while executing org.apache.cloudstack.api.command.admin.router.StartRouterCmd
2021-01-20 08:47:47,435 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-796675ae job-150) (logid:b566c8a5) Complete async job-150, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Unable to start VM instance"}
2021-01-20 08:47:47,436 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-796675ae job-150) (logid:b566c8a5) Publish async job-150 complete on message bus
2021-01-20 08:47:47,436 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-796675ae job-150) (logid:b566c8a5) Wake up jobs related to job-150
2021-01-20 08:47:47,436 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-796675ae job-150) (logid:b566c8a5) Update db status for job-150
2021-01-20 08:47:47,437 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-796675ae job-150) (logid:b566c8a5) Wake up jobs joined with job-150 and disjoin all subjobs created from job- 150
2021-01-20 08:47:47,744 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-796675ae job-150) (logid:b566c8a5) Done executing org.apache.cloudstack.api.command.admin.router.StartRouterCmd for job-150
2021-01-20 08:47:47,744 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-1:ctx-796675ae job-150) (logid:b566c8a5) Remove job-150 from job monitoring
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] shwstppr commented on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
shwstppr commented on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763577862
@rp- did you allow CloudStack to download new systemvm template before upgrading the packages? Or do you see any error in management server or ssvm logs for template download?
If your systemvms are still in running state, you may try restarting cloud service inside SSVM to reattempt template download in the secondary store.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] weizhouapache commented on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
weizhouapache commented on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763589353
> :/
>
> ```
> mysql> select id, state, download_state from template_store_ref where template_id=207;
> +----+-----------+----------------+
> | id | state | download_state |
> +----+-----------+----------------+
> | 11 | Allocated | NULL |
> +----+-----------+----------------+
> 1 row in set (0.00 sec)
> ```
@rp-
apparently template is not downloaded successfully.
please follow @shwstppr 's suggestion.
another option is, register the template again, and click 'Direct Download' if mgt server can connect to download.cloudstack.org.
it does not require SSVM to be up and running.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [cloudstack] rp- commented on issue #4599: Unable to start KVM instance after upgrade to 4.15.0
Posted by GitBox <gi...@apache.org>.
rp- commented on issue #4599:
URL: https://github.com/apache/cloudstack/issues/4599#issuecomment-763526869
```
mysql> select id, unique_name, name, state from vm_template WHERE id=207;
+-----+--------------------------------------------+---------------------+--------+
| id | unique_name | name | state |
+-----+--------------------------------------------+---------------------+--------+
| 207 | 207-2-f6604a5c-c311-3faa-943a-577915956ba5 | systemvm-kvm-4.15.0 | Active |
+-----+--------------------------------------------+---------------------+--------+
1 row in set (0.00 sec)
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org