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:
[email protected]
