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