abdelouahabb opened a new issue #4810: URL: https://github.com/apache/cloudstack/issues/4810
``` - Cloudstack 4.15 - Ubuntu 18.04.5 - Virt Manager 3.2 (nested on Ubuntu 20.04) ``` Everything was installed, secondary storage works (same machine), uploaded the template as in the tutorial `/usr/share/cloudstack-common/scripts/storage/secondary/cloud-install-sys-tmplt -m /export/secondary -f systemvmtemplate-4.15.0-kvm.qcow2.bz2 -h kvm -F` But cant make it run   Here is the full log (launched it just when pressing run) ``` }","wait":"0"}}] } 2021-03-13 02:39:50,615 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-6708c44a) (logid:ea60923b) Snapshot scheduler.poll is being called at 2021-03-13 01:39:50 GMT 2021-03-13 02:39:50,616 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-6708c44a) (logid:ea60923b) Got 0 snapshots to be executed at 2021-03-13 01:39:50 GMT 2021-03-13 02:39:50,676 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) (logid:) SeqA 2-288: Sending Seq 2-288: { Ans: , MgmtId: 191528580652610, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0"}}] } 2021-03-13 02:39:50,799 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) Ping from Routing host 1(alien.akham.local) 2021-03-13 02:39:50,799 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) Process host VM state report from ping process. host: 1 2021-03-13 02:39:50,805 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) Process VM state report. host: 1, number of records in report: 2 2021-03-13 02:39:50,805 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) VM state report. host: 1, vm id: 1, power state: PowerOn 2021-03-13 02:39:50,810 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) VM state report. host: 1, vm id: 2, power state: PowerOn 2021-03-13 02:39:50,815 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) Done with process of VM state report. host: 1 2021-03-13 02:39:56,737 DEBUG [c.c.a.ApiServlet] (qtp182531396-13:ctx-c25be67a) (logid:9fac86d2) ===START=== 192.168.122.1 -- GET zoneid=3ea197d5-827e-4563-91e8-d23fd3075f2f&podid=5c1abf4e-4113-425d-8f33-fe330f1a64b6&clusterid=e1d74192-1b02-40b4-8361-fe60593839fb&templateid=a628f943-821d-11eb-ac45-525400644510&serviceofferingid=2ba8f0f1-a25a-4c7e-8ca7-5620e19ae353&affinitygroupids=&iptonetworklist[0].networkid=21dba76c-2744-4b80-945a-9de7d426e134&command=deployVirtualMachine&response=json 2021-03-13 02:39:56,752 DEBUG [c.c.a.ApiServer] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:39:56,797 DEBUG [c.c.u.AccountManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Access granted to Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin] to org.apache.cloudstack.quota.vo.ServiceOfferingVO$$EnhancerByCGLIB$$fc0b01ab@4765e5a1 by AffinityGroupAccessChecker 2021-03-13 02:39:56,798 DEBUG [c.c.u.AccountManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Access granted to Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin] to null by AffinityGroupAccessChecker 2021-03-13 02:39:56,826 DEBUG [c.c.n.NetworkModelImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Service SecurityGroup is not supported in the network id=204 2021-03-13 02:39:56,918 DEBUG [c.c.v.UserVmManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Allocating in the DB for vm 2021-03-13 02:39:56,941 INFO [c.c.v.VirtualMachineManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) allocating virtual machine from template:a628f943-821d-11eb-ac45-525400644510 with hostname:i-2-6-VM and 1 networks 2021-03-13 02:39:56,949 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Allocating entries for VM: VM[User|i-2-6-VM] 2021-03-13 02:39:56,951 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Allocating nics for VM[User|i-2-6-VM] 2021-03-13 02:39:56,954 DEBUG [o.a.c.e.o.NetworkOrchestrator] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Allocating nic for vm VM[User|i-2-6-VM] in network Ntwk[204|Guest|8] with requested profile NicProfile[0-0-null-null-null] 2021-03-13 02:39:57,084 DEBUG [c.c.n.NetworkModelImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Service SecurityGroup is not supported in the network id=204 2021-03-13 02:39:57,087 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Allocating disks for VM[User|i-2-6-VM] 2021-03-13 02:39:57,087 INFO [o.a.c.e.o.VolumeOrchestrator] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) adding disk object ROOT-6 to i-2-6-VM 2021-03-13 02:39:57,107 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Updating resource Type = volume count for Account = 2 Operation = increasing Amount = 1 2021-03-13 02:39:57,113 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Updating resource Type = primary_storage count for Account = 2 Operation = increasing Amount = (8.00 GB) 8589934592 2021-03-13 02:39:57,119 DEBUG [c.c.v.VirtualMachineManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Allocation completed for VM: VM[User|i-2-6-VM] 2021-03-13 02:39:57,119 DEBUG [c.c.v.UserVmManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Successfully allocated DB entry for VM[User|i-2-6-VM] 2021-03-13 02:39:57,122 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Updating resource Type = user_vm count for Account = 2 Operation = increasing Amount = 1 2021-03-13 02:39:57,126 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Updating resource Type = cpu count for Account = 2 Operation = increasing Amount = 1 2021-03-13 02:39:57,136 DEBUG [c.c.r.ResourceLimitManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Updating resource Type = memory count for Account = 2 Operation = increasing Amount = 512 2021-03-13 02:39:57,300 DEBUG [c.c.n.NetworkModelImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Service SecurityGroup is not supported in the network id=204 2021-03-13 02:39:57,312 DEBUG [c.c.n.NetworkModelImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) Service SecurityGroup is not supported in the network id=204 2021-03-13 02:39:57,554 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-7:ctx-35226f21 job-61) (logid:33013db9) Add job-61 into job monitoring 2021-03-13 02:39:57,559 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61) (logid:fc577e10) Executing AsyncJobVO {id:61, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 6, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"iptonetworklist[0].networkid":"21dba76c-2744-4b80-945a-9de7d426e134","httpmethod":"GET","clusterid":"e1d74192-1b02-40b4-8361-fe60593839fb","templateid":"a628f943-821d-11eb-ac45-525400644510","ctxAccountId":"2","uuid":"9e47cc57-c25a-4b28-a9a8-34b46709283a","cmdEventType":"VM.CREATE","serviceofferingid":"2ba8f0f1-a25a-4c7e-8ca7-5620e19ae353","response":"json","ctxUserId":"2","zoneid":"3ea197d5-827e-4563-91e8-d23fd3075f2f","ctxStartEventId":"144","id":"6","ctxDetails":"{\"interface com.cloud.org.Cluster\":\"e1d74192-1b02-40b4-8361-fe60593839fb\",\"interface com.cloud.offering.ServiceOffering\":\"2ba8f0f1-a25a-4c7e-8ca7-5620e19ae353\",\"interface com.cloud.dc.Pod\":\"5c1abf4e-4113-425d-8f33 -fe330f1a64b6\",\"interface com.cloud.dc.DataCenter\":\"3ea197d5-827e-4563-91e8-d23fd3075f2f\",\"interface com.cloud.vm.VirtualMachine\":\"9e47cc57-c25a-4b28-a9a8-34b46709283a\",\"interface com.cloud.template.VirtualMachineTemplate\":\"a628f943-821d-11eb-ac45-525400644510\"}","podid":"5c1abf4e-4113-425d-8f33-fe330f1a64b6","affinitygroupids":""}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 191528580652610, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null} 2021-03-13 02:39:57,563 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) submit async job-61, details: AsyncJobVO {id:61, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 6, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"iptonetworklist[0].networkid":"21dba76c-2744-4b80-945a-9de7d426e134","httpmethod":"GET","clusterid":"e1d74192-1b02-40b4-8361-fe60593839fb","templateid":"a628f943-821d-11eb-ac45-525400644510","ctxAccountId":"2","uuid":"9e47cc57-c25a-4b28-a9a8-34b46709283a","cmdEventType":"VM.CREATE","serviceofferingid":"2ba8f0f1-a25a-4c7e-8ca7-5620e19ae353","response":"json","ctxUserId":"2","zoneid":"3ea197d5-827e-4563-91e8-d23fd3075f2f","ctxStartEventId":"144","id":"6","ctxDetails":"{\"interface com.cloud.org.Cluster\":\"e1d74192-1b02-40b4-8361-fe60593839fb\",\"interface com.cloud.offering.ServiceOffering\":\"2ba8f0f1-a25a-4c7e-8ca7-5620e19ae353\",\"interface com.cloud.dc.Pod\":\" 5c1abf4e-4113-425d-8f33-fe330f1a64b6\",\"interface com.cloud.dc.DataCenter\":\"3ea197d5-827e-4563-91e8-d23fd3075f2f\",\"interface com.cloud.vm.VirtualMachine\":\"9e47cc57-c25a-4b28-a9a8-34b46709283a\",\"interface com.cloud.template.VirtualMachineTemplate\":\"a628f943-821d-11eb-ac45-525400644510\"}","podid":"5c1abf4e-4113-425d-8f33-fe330f1a64b6","affinitygroupids":""}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 191528580652610, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null} 2021-03-13 02:39:57,566 DEBUG [c.c.a.ApiServlet] (qtp182531396-13:ctx-c25be67a ctx-44b49ac4) (logid:9fac86d2) ===END=== 192.168.122.1 -- GET zoneid=3ea197d5-827e-4563-91e8-d23fd3075f2f&podid=5c1abf4e-4113-425d-8f33-fe330f1a64b6&clusterid=e1d74192-1b02-40b4-8361-fe60593839fb&templateid=a628f943-821d-11eb-ac45-525400644510&serviceofferingid=2ba8f0f1-a25a-4c7e-8ca7-5620e19ae353&affinitygroupids=&iptonetworklist[0].networkid=21dba76c-2744-4b80-945a-9de7d426e134&command=deployVirtualMachine&response=json 2021-03-13 02:39:57,605 DEBUG [c.c.a.ApiServlet] (qtp182531396-20:ctx-4167bab2) (logid:0d562a41) ===START=== 192.168.122.1 -- GET jobId=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:39:57,626 DEBUG [c.c.a.ApiServer] (qtp182531396-20:ctx-4167bab2 ctx-a68ec37f) (logid:0d562a41) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:39:57,756 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Service SecurityGroup is not supported in the network id=204 2021-03-13 02:39:57,767 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Service SecurityGroup is not supported in the network id=204 2021-03-13 02:39:57,771 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Destination Cluster to deploy the VM is specified, specifying a deployment plan to deploy the VM 2021-03-13 02:39:57,809 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) DeploymentPlanner allocation algorithm: null 2021-03-13 02:39:57,810 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) 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-03-13 02:39:57,810 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Is ROOT volume READY (pool already allocated)?: No 2021-03-13 02:39:57,811 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Deploy avoids pods: [], clusters: [], hosts: [] 2021-03-13 02:39:57,818 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Searching resources only under specified Cluster: 1 2021-03-13 02:39:57,848 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Checking resources in Cluster: 1 under Pod: 1 2021-03-13 02:39:57,860 INFO [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Guest VM is requested with Cusotm[UEFI] Boot Type false 2021-03-13 02:39:57,861 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Looking for hosts in dc: 1 pod:1 cluster:1 2021-03-13 02:39:57,877 DEBUG [c.c.a.ApiServlet] (qtp182531396-20:ctx-4167bab2 ctx-a68ec37f) (logid:0d562a41) ===END=== 192.168.122.1 -- GET jobId=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:39:57,885 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]] 2021-03-13 02:39:57,906 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]] 2021-03-13 02:39:57,907 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Looking for speed=500Mhz, Ram=512 MB 2021-03-13 02:39:57,930 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Host: 1 has cpu capability (cpu:2, speed:1995) to support requested CPU: 1 and requested speed: 500 2021-03-13 02:39:57,931 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0 2021-03-13 02:39:57,937 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Hosts's actual total CPU: 3990 and CPU after applying overprovisioning: 3990 2021-03-13 02:39:57,938 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Free CPU: 2990 , Requested CPU: 500 2021-03-13 02:39:57,938 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Free RAM: (5.20 GB) 5583081472 , Requested RAM: (512.00 MB) 536870912 2021-03-13 02:39:57,938 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Host has enough CPU and RAM available 2021-03-13 02:39:57,938 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) STATS: Can alloc CPU from host: 1, used: 1000, reserved: 0, actual total: 3990, total with overprovisioning: 3990; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true 2021-03-13 02:39:57,939 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) STATS: Can alloc MEM from host: 1, used: (1.50 GB) 1610612736, reserved: (0 bytes) 0, total: (6.70 GB) 7193694208; requested mem: (512.00 MB) 536870912, alloc_from_last_host?: false , considerReservedCapacity?: true 2021-03-13 02:39:57,940 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Found a suitable host, adding to list: 1 2021-03-13 02:39:57,940 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89 FirstFitRoutingAllocator) (logid:fc577e10) Host Allocator returning 1 suitable hosts 2021-03-13 02:39:57,944 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Checking suitable pools for volume (Id, Type): (8,ROOT) 2021-03-13 02:39:57,944 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) We need to allocate new storagepool for this volume 2021-03-13 02:39:57,947 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Calling StoragePoolAllocators to find suitable pools 2021-03-13 02:39:57,951 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) LocalStoragePoolAllocator trying to find storage pool to fit the vm 2021-03-13 02:39:57,952 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) ClusterScopeStoragePoolAllocator looking for storage pool 2021-03-13 02:39:57,952 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored. 2021-03-13 02:39:57,956 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Found pools matching tags: [] 2021-03-13 02:39:57,957 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) No storage pools available for shared volume allocation, returning 2021-03-13 02:39:57,957 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) ZoneWideStoragePoolAllocator to find storage pool 2021-03-13 02:39:57,972 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Checking if storage pool is suitable, name: null ,poolId: 1 2021-03-13 02:39:57,975 INFO [c.c.s.StorageManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity 2021-03-13 02:39:57,978 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Checking pool 1 for storage, totalSize: 25760366592, usedBytes: 12988710912, usedPct: 0.5042129686164367, disable threshold: 0.85 2021-03-13 02:39:57,978 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Destination pool id: 1 2021-03-13 02:39:58,018 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Pool ID for the volume with ID 8 is null 2021-03-13 02:39:58,030 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Found storage pool primaire of type NetworkFilesystem with over-provisioning factor 2 2021-03-13 02:39:58,030 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Total over-provisioned capacity calculated is 2 * (23.99 GB) 25760366592 2021-03-13 02:39:58,031 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Total capacity of the pool primaire with ID 1 is (47.98 GB) 51520733184 2021-03-13 02:39:58,034 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Checking pool: 1 for storage allocation , maxSize : (47.98 GB) 51520733184, totalAllocatedSize : (8.00 GB) 8590131240, askingSize : (8.00 GB) 8589934592, allocated disable threshold: 0.85 2021-03-13 02:39:58,035 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2021-03-13 02:39:58,037 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Checking if host: 1 can access any suitable storage pool for volume: ROOT 2021-03-13 02:39:58,039 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Host: 1 can access pool: 1 2021-03-13 02:39:58,040 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Found a potential host id: 1 name: alien.akham.local and associated storage pools for this VM 2021-03-13 02:39:58,041 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) 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(8|ROOT-->Pool(1))] 2021-03-13 02:39:58,105 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-2effa202) (logid:7ae771b5) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:39:58,119 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-2effa202 ctx-653d41af) (logid:7ae771b5) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:39:58,159 DEBUG [c.c.a.ApiServlet] (qtp182531396-20:ctx-59960ce2) (logid:91312d59) ===START=== 192.168.122.1 -- GET jobid=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:39:58,197 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-2effa202 ctx-653d41af) (logid:7ae771b5) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:39:58,202 DEBUG [c.c.a.ApiServer] (qtp182531396-20:ctx-59960ce2 ctx-f66d5483) (logid:91312d59) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:39:58,291 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Sync job-62 execution on object VmWorkJobQueue.6 2021-03-13 02:39:58,379 DEBUG [c.c.a.ApiServlet] (qtp182531396-20:ctx-59960ce2 ctx-f66d5483) (logid:91312d59) ===END=== 192.168.122.1 -- GET jobid=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:39:59,998 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9aa7e8bd) (logid:5547837f) Execute sync-queue item: SyncQueueItemVO {id:17, queueId: 22, contentType: AsyncJob, contentId: 62, lastProcessMsid: 191528580652610, lastprocessNumber: 1, lastProcessTime: Sat Mar 13 02:39:59 CET 2021, created: Sat Mar 13 02:39:58 CET 2021} 2021-03-13 02:40:00,000 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9aa7e8bd) (logid:5547837f) Schedule queued job-62 2021-03-13 02:40:00,093 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:41dc08b6) Add job-62 into job monitoring 2021-03-13 02:40:00,105 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Executing AsyncJobVO {id:62, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFq YXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 191528580652610, completeMsid: null, lastUpdated: null, lastPolled: null, created: Sat Mar 13 02:39:58 CET 2021, removed: null} 2021-03-13 02:40:00,106 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Run VM work job: com.cloud.vm.VmWorkStart for VM 6, job origin: 61 2021-03-13 02:40:00,110 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":1,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":6,"handlerName":"VirtualMachineManagerImpl"} 2021-03-13 02:40:00,123 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) 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-03-13 02:40:00,123 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Successfully transitioned to start state for VM[User|i-2-6-VM] reservation id = e4a30dc3-7460-4848-a2f4-2241b626ebc2 2021-03-13 02:40:00,233 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null 2021-03-13 02:40:00,235 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Deploy avoids pods: null, clusters: null, hosts: null 2021-03-13 02:40:00,248 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) DeploymentPlanner allocation algorithm: null 2021-03-13 02:40:00,248 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) 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-03-13 02:40:00,248 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Is ROOT volume READY (pool already allocated)?: No 2021-03-13 02:40:00,248 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1 2021-03-13 02:40:00,250 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1 2021-03-13 02:40:00,257 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Checking suitable pools for volume (Id, Type): (8,ROOT) 2021-03-13 02:40:00,257 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) We need to allocate new storagepool for this volume 2021-03-13 02:40:00,259 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Calling StoragePoolAllocators to find suitable pools 2021-03-13 02:40:00,261 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) LocalStoragePoolAllocator trying to find storage pool to fit the vm 2021-03-13 02:40:00,261 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) ClusterScopeStoragePoolAllocator looking for storage pool 2021-03-13 02:40:00,261 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored. 2021-03-13 02:40:00,262 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Found pools matching tags: [] 2021-03-13 02:40:00,263 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) No storage pools available for shared volume allocation, returning 2021-03-13 02:40:00,263 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) ZoneWideStoragePoolAllocator to find storage pool 2021-03-13 02:40:00,269 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Checking if storage pool is suitable, name: null ,poolId: 1 2021-03-13 02:40:00,272 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity 2021-03-13 02:40:00,276 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Checking pool 1 for storage, totalSize: 25760366592, usedBytes: 12988710912, usedPct: 0.5042129686164367, disable threshold: 0.85 2021-03-13 02:40:00,276 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Destination pool id: 1 2021-03-13 02:40:00,296 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Pool ID for the volume with ID 8 is null 2021-03-13 02:40:00,302 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Found storage pool primaire of type NetworkFilesystem with over-provisioning factor 2 2021-03-13 02:40:00,302 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Total over-provisioned capacity calculated is 2 * (23.99 GB) 25760366592 2021-03-13 02:40:00,302 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Total capacity of the pool primaire with ID 1 is (47.98 GB) 51520733184 2021-03-13 02:40:00,304 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Checking pool: 1 for storage allocation , maxSize : (47.98 GB) 51520733184, totalAllocatedSize : (8.00 GB) 8590131240, askingSize : (8.00 GB) 8589934592, allocated disable threshold: 0.85 2021-03-13 02:40:00,304 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2021-03-13 02:40:00,306 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Checking if host: 1 can access any suitable storage pool for volume: ROOT 2021-03-13 02:40:00,308 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Host: 1 can access pool: 1 2021-03-13 02:40:00,309 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Found a potential host id: 1 name: alien.akham.local and associated storage pools for this VM 2021-03-13 02:40:00,311 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) 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(8|ROOT-->Pool(1))] 2021-03-13 02:40:00,311 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Deployment found - P0=VM[User|i-2-6-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(8|ROOT-->Pool(1))] 2021-03-13 02:40:00,446 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) 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-03-13 02:40:00,464 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Hosts's actual total CPU: 3990 and CPU after applying overprovisioning: 3990 2021-03-13 02:40:00,464 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) We are allocating VM, increasing the used capacity of this host:1 2021-03-13 02:40:00,464 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Current Used CPU: 1000 , Free CPU:2990 ,Requested CPU: 500 2021-03-13 02:40:00,464 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Current Used RAM: (1.50 GB) 1610612736 , Free RAM:(5.20 GB) 5583081472 ,Requested RAM: (512.00 MB) 536870912 2021-03-13 02:40:00,464 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) CPU STATS after allocation: for host: 1, old used: 1000, old reserved: 0, actual total: 3990, total with overprovisioning: 3990; new used:1500, reserved:0; requested cpu:500,alloc_from_last:false 2021-03-13 02:40:00,465 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) RAM STATS after allocation: for host: 1, old used: (1.50 GB) 1610612736, old reserved: (0 bytes) 0, total: (6.70 GB) 7193694208; new used: (2.00 GB) 2147483648, reserved: (0 bytes) 0; requested mem: (512.00 MB) 536870912,alloc_from_last:false 2021-03-13 02:40:00,467 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Host: 1 has cpu capability (cpu:2, speed:1995) to support requested CPU: 1 and requested speed: 500 2021-03-13 02:40:00,468 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0 2021-03-13 02:40:00,470 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Hosts's actual total CPU: 3990 and CPU after applying overprovisioning: 3990 2021-03-13 02:40:00,470 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) We need to allocate to the last host again, so checking if there is enough reserved capacity 2021-03-13 02:40:00,470 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Reserved CPU: 0 , Requested CPU: 500 2021-03-13 02:40:00,470 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Reserved RAM: (0 bytes) 0 , Requested RAM: (512.00 MB) 536870912 2021-03-13 02:40:00,470 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) STATS: Failed to alloc resource from host: 1 reservedCpu: 0, requested cpu: 500, reservedMem: (0 bytes) 0, requested mem: (512.00 MB) 536870912 2021-03-13 02:40:00,470 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Host does not have enough reserved CPU available, cannot allocate to this host. 2021-03-13 02:40:00,470 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0 2021-03-13 02:40:00,475 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Hosts's actual total CPU: 3990 and CPU after applying overprovisioning: 3990 2021-03-13 02:40:00,475 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Free CPU: 2990 , Requested CPU: 500 2021-03-13 02:40:00,475 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Free RAM: (5.20 GB) 5583081472 , Requested RAM: (512.00 MB) 536870912 2021-03-13 02:40:00,475 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Host has enough CPU and RAM available 2021-03-13 02:40:00,475 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) STATS: Can alloc CPU from host: 1, used: 1000, reserved: 0, actual total: 3990, total with overprovisioning: 3990; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true 2021-03-13 02:40:00,475 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) STATS: Can alloc MEM from host: 1, used: (1.50 GB) 1610612736, reserved: (0 bytes) 0, total: (6.70 GB) 7193694208; requested mem: (512.00 MB) 536870912, alloc_from_last_host?: false , considerReservedCapacity?: true 2021-03-13 02:40:00,547 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) SeqA 2-289: Processing Seq 2-289: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{ "connections": [] }","wait":"0"}}] } 2021-03-13 02:40:00,634 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) SeqA 2-289: Sending Seq 2-289: { Ans: , MgmtId: 191528580652610, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0"}}] } 2021-03-13 02:40:00,649 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-b573bca1) (logid:4edf6f87) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,660 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-b573bca1 ctx-2724ec5f) (logid:4edf6f87) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:00,667 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Lock is acquired for network id 204 as a part of network implement 2021-03-13 02:40:00,667 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Asking ExternalGuestNetworkGuru to implement Ntwk[204|Guest|8] 2021-03-13 02:40:00,709 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-b573bca1 ctx-2724ec5f) (logid:4edf6f87) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,717 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-6257f85d) (logid:199fe977) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,732 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-6257f85d ctx-45b2a63a) (logid:199fe977) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:00,771 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-6257f85d ctx-45b2a63a) (logid:199fe977) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,779 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-23756e1c) (logid:d06ccf0b) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,793 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-23756e1c ctx-f55e3c48) (logid:d06ccf0b) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:00,800 DEBUG [c.c.u.d.T.Transaction] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Rolling back the transaction: Time = 1 Name = Work-Job-Executor-17; called by -TransactionLegacy.rollback:888-TransactionLegacy.removeUpTo:831-TransactionLegacy.close:655-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:95-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:212-$Proxy56.take:-1-DataCenterDaoImpl.allocateVnet:212-NativeMethodAccessorImpl.invoke0:-2-NativeMethodAccessorImpl.invoke:62 2021-03-13 02:40:00,801 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Cleaning up because we're unable to implement the network Ntwk[204|Guest|8] 2021-03-13 02:40:00,823 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-23756e1c ctx-f55e3c48) (logid:d06ccf0b) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,829 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-8c936a47) (logid:02d36d8e) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,843 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-8c936a47 ctx-cd6d9dad) (logid:02d36d8e) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:00,881 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-8c936a47 ctx-cd6d9dad) (logid:02d36d8e) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,885 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-56bb6ed0) (logid:ed156650) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,900 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-56bb6ed0 ctx-753a97eb) (logid:ed156650) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:00,936 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-56bb6ed0 ctx-753a97eb) (logid:ed156650) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,941 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-3cd760cf) (logid:6c1af701) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:00,948 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Lock is acquired for network Ntwk[204|Guest|8] as a part of network shutdown 2021-03-13 02:40:00,952 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Sending network shutdown to VirtualRouter 2021-03-13 02:40:00,953 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-3cd760cf ctx-aa323fba) (logid:6c1af701) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:00,954 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Network id=204 is shutdown successfully, cleaning up corresponding resources now. 2021-03-13 02:40:00,997 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-3cd760cf ctx-aa323fba) (logid:6c1af701) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:01,001 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-228e2f43) (logid:534ac29d) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:01,011 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-228e2f43 ctx-13d5d091) (logid:534ac29d) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:01,044 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-228e2f43 ctx-13d5d091) (logid:534ac29d) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:01,144 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-af247a57) (logid:af859b32) ===START=== 192.168.122.1 -- GET jobId=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:40:01,154 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-af247a57 ctx-f492479c) (logid:af859b32) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:01,182 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Lock is released for network Ntwk[204|Guest|8] as a part of network shutdown 2021-03-13 02:40:01,487 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-af247a57 ctx-f492479c) (logid:af859b32) ===END=== 192.168.122.1 -- GET jobId=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:40:01,612 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Lock is released for network id 204 as a part of network implement 2021-03-13 02:40:01,612 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Insufficient capacity com.cloud.exception.InsufficientVirtualNetworkCapacityException: Unable to allocate vnet as a part of network Ntwk[204|Guest|8] implement Scope=interface com.cloud.dc.DataCenter; id=1 at com.cloud.network.guru.GuestNetworkGuru.allocateVnet(GuestNetworkGuru.java:296) at com.cloud.network.guru.GuestNetworkGuru.implement(GuestNetworkGuru.java:325) at com.cloud.network.guru.ExternalGuestNetworkGuru.implement(ExternalGuestNetworkGuru.java:136) at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:1237) at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:1176) at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1767) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1149) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5464) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5631) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) 2021-03-13 02:40:01,725 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Cleaning up resources for the vm VM[User|i-2-6-VM] in Starting state 2021-03-13 02:40:01,734 DEBUG [c.c.a.t.Request] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Seq 1-4466163455467978844: Sending { Cmd , MgmtId: 191528580652610, via: 1(alien.akham.local), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeCleanup":"false","forceStop":"false","volumesToDisconnect":[],"vmName":"i-2-6-VM","executeInSequence":"false","wait":"0"}}] } 2021-03-13 02:40:01,934 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-862a0107) (logid:fddcd6cc) ===START=== 192.168.122.1 -- GET jobid=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:40:01,945 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-862a0107 ctx-621311c0) (logid:fddcd6cc) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:01,964 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-862a0107 ctx-621311c0) (logid:fddcd6cc) ===END=== 192.168.122.1 -- GET jobid=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:40:02,055 DEBUG [c.c.a.t.Request] (AgentManager-Handler-14:null) (logid:) Seq 1-4466163455467978844: Processing: { Ans: , MgmtId: 191528580652610, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":"true","wait":"0"}}] } 2021-03-13 02:40:02,055 DEBUG [c.c.a.t.Request] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Seq 1-4466163455467978844: Received: { Ans: , MgmtId: 191528580652610, via: 1(alien.akham.local), Ver: v1, Flags: 10, { StopAnswer } } 2021-03-13 02:40:02,270 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Successfully released network resources for the vm VM[User|i-2-6-VM] 2021-03-13 02:40:02,270 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Successfully cleaned up resources for the VM VM[User|i-2-6-VM] in Starting state 2021-03-13 02:40:02,281 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) DeploymentPlanner allocation algorithm: null 2021-03-13 02:40:02,282 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) 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-03-13 02:40:02,282 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Is ROOT volume READY (pool already allocated)?: No 2021-03-13 02:40:02,282 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1 2021-03-13 02:40:02,284 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) The specified host is in avoid set 2021-03-13 02:40:02,284 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Cannot deploy to specified host, returning. 2021-03-13 02:40:02,463 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) 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-03-13 02:40:02,475 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Hosts's actual total CPU: 3990 and CPU after applying overprovisioning: 3990 2021-03-13 02:40:02,475 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Hosts's actual total RAM: (6.70 GB) 7193694208 and RAM after applying overprovisioning: (6.70 GB) 7193694208 2021-03-13 02:40:02,475 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) release cpu from host: 1, old used: 1500,reserved: 0, actual total: 3990, total with overprovisioning: 3990; new used: 1000,reserved:0; movedfromreserved: false,moveToReserveredfalse 2021-03-13 02:40:02,480 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) release mem from host: 1, old used: (2.00 GB) 2147483648,reserved: (0 bytes) 0, total: (6.70 GB) 7193694208; new used: (1.50 GB) 1610612736,reserved:(0 bytes) 0; movedfromreserved: false,moveToReserveredfalse 2021-03-13 02:40:02,801 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-8f03e622) (logid:fd441d53) AutoScaling Monitor is running... 2021-03-13 02:40:02,871 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-6-VM]Scope=interface com.cloud.dc.DataCenter; id=1 2021-03-13 02:40:02,871 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62 ctx-25941f70) (logid:fc577e10) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-6-VM]Scope=interface com.cloud.dc.DataCenter; id=1 2021-03-13 02:40:02,871 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 6, job origin: 61 2021-03-13 02:40:02,872 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Unable to complete AsyncJobVO {id:62, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAABnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyA BFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 191528580652610, completeMsid: null, lastUpdated: null, lastPolled: null, created: Sat Mar 13 02:39:58 CET 2021, removed: null}, job origin:61 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-6-VM]Scope=interface com.cloud.dc.DataCenter; id=1 at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1110) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5464) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5631) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) 2021-03-13 02:40:02,886 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Complete async job-62, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAAzVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9 yIFZNW1VzZXJ8aS0yLTYtVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAVc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAKTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AApMAAptb2R1bGVOYW1lcQB-AApMAA1tb2R1bGVWZXJzaW9ucQB-AAp4cAEAAARWdAADYXBwdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0cHBzcQB-ABEBAAAVWHEAfgATcQB-ABRxAH4AFXEAfgAWcHBzcQB-ABEC_____nB0AC1qZGsuaW50ZXJuYWwucmVmbGVjdC5OYXRpdmVNZXRob2RBY2Nlc3NvckltcGx0AB1OYXRpdmVNZXRob2RBY2Nlc3NvckltcGwuamF2YXQAB2ludm9rZTB0AAlqYXZhLmJhc2V0AAcxMS4wLjEwc3EAfgARAgAAAD5wcQB-ABlxAH4AGnQABmludm9rZXEAfgAccQB-AB1zcQB-ABECAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-AB9xAH4AHHEAfgAdc3EAfgARAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AH3EAfgAccQB-AB1zcQB-ABEB AAAAa3EAfgATdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-ABEBAAAV_3EAfgATcQB-ABRxAH4AFXEAfgApcHBzcQB-ABEBAAAAZnEAfgATdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4AEQEAAAJscQB-ABN0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4AEQEAAAAwcQB-ABN0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgARAQAAADdxAH4AE3QAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgARAQAAAGZxAH4AE3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AOXQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgARAQAAADRxAH4AE3EAfgA8cQB-ADl0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgARAQAAA C1xAH4AE3QAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgA1cQB-ADZwcHNxAH4AEQEAAAI4cQB-ABNxAH4AMHEAfgAxcQB-ADZwcHNxAH4AEQIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA6cQB-ABxxAH4AHXNxAH4AEQIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4ANnEAfgAccQB-AB1zcQB-ABECAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAccQB-AB1zcQB-ABECAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEtxAH4ANnEAfgAccQB-AB1zcQB-ABECAAADQnB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4ANnEAfgAccQB-AB1zcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleH EAfgBVAAAAAAAAAAF2cgAXY29tLmNsb3VkLmRjLkRhdGFDZW50ZXJT6CQa0tO2XAIAAHhwAA 2021-03-13 02:40:02,888 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Publish async job-62 complete on message bus 2021-03-13 02:40:02,888 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Wake up jobs related to job-62 2021-03-13 02:40:02,888 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Update db status for job-62 2021-03-13 02:40:02,891 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Wake up jobs joined with job-62 and disjoin all subjobs created from job- 62 2021-03-13 02:40:03,117 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Done executing com.cloud.vm.VmWorkStart for job-62 2021-03-13 02:40:03,120 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-17:ctx-3d84aa87 job-61/job-62) (logid:fc577e10) Remove job-62 from job monitoring 2021-03-13 02:40:03,238 ERROR [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) VM VM[User|i-2-6-VM] unexpectedly went to Stopped state 2021-03-13 02:40:03,241 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Destroying vm VM[User|i-2-6-VM] as it failed to create on Host with Id:null 2021-03-13 02:40:03,511 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) 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-03-13 02:40:03,753 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Updating resource Type = volume count for Account = 2 Operation = decreasing Amount = 1 2021-03-13 02:40:03,840 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Updating resource Type = primary_storage count for Account = 2 Operation = decreasing Amount = (8.00 GB) 8589934592 2021-03-13 02:40:04,001 WARN [c.c.a.AlertManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) AlertType:: 8 | dataCenterId:: 1 | podId:: 1 | clusterId:: null | message:: Failed to deploy Vm with Id: 6, on Host with Id: null 2021-03-13 02:40:04,272 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Updating resource Type = user_vm count for Account = 2 Operation = decreasing Amount = 1 2021-03-13 02:40:04,342 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Updating resource Type = cpu count for Account = 2 Operation = decreasing Amount = 1 2021-03-13 02:40:04,465 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Updating resource Type = memory count for Account = 2 Operation = decreasing Amount = 512 2021-03-13 02:40:04,516 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-00229df3) (logid:5c86bd38) ===START=== 192.168.122.1 -- GET jobId=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:40:04,528 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-00229df3 ctx-20f48249) (logid:5c86bd38) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:04,556 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-91f1e703) (logid:fe98011c) HostStatsCollector is running... 2021-03-13 02:40:04,573 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-91f1e703) (logid:fe98011c) Seq 1-4466163455467978845: Received: { Ans: , MgmtId: 191528580652610, via: 1(alien.akham.local), Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2021-03-13 02:40:04,648 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-00229df3 ctx-20f48249) (logid:5c86bd38) ===END=== 192.168.122.1 -- GET jobId=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:40:04,693 WARN [o.a.c.a.c.u.v.DeployVMCmd] (API-Job-Executor-7:ctx-35226f21 job-61 ctx-a49f2c89) (logid:fc577e10) Exception: com.cloud.exception.ConcurrentOperationException: Failed to deploy VM VM[User|i-2-6-VM] at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4436) at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4417) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) at com.sun.proxy.$Proxy124.startVirtualMachine(Unknown Source) at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:681) at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156) at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) 2021-03-13 02:40:04,701 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61) (logid:fc577e10) Complete async job-61, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Failed to deploy VM VM[User|i-2-6-VM]"} 2021-03-13 02:40:04,707 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61) (logid:fc577e10) Publish async job-61 complete on message bus 2021-03-13 02:40:04,708 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61) (logid:fc577e10) Wake up jobs related to job-61 2021-03-13 02:40:04,708 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61) (logid:fc577e10) Update db status for job-61 2021-03-13 02:40:04,710 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61) (logid:fc577e10) Wake up jobs joined with job-61 and disjoin all subjobs created from job- 61 2021-03-13 02:40:04,877 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-35226f21 job-61) (logid:fc577e10) Done executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-61 2021-03-13 02:40:04,878 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-7:ctx-35226f21 job-61) (logid:fc577e10) Remove job-61 from job monitoring 2021-03-13 02:40:05,544 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) (logid:) SeqA 2-290: Processing Seq 2-290: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{ "connections": [] }","wait":"0"}}] } 2021-03-13 02:40:05,632 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) (logid:) SeqA 2-290: Sending Seq 2-290: { Ans: , MgmtId: 191528580652610, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0"}}] } 2021-03-13 02:40:05,936 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-db1cf474) (logid:30c61c7a) ===START=== 192.168.122.1 -- GET jobid=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:40:05,947 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-db1cf474 ctx-4c694b12) (logid:30c61c7a) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:06,080 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-db1cf474 ctx-4c694b12) (logid:30c61c7a) ===END=== 192.168.122.1 -- GET jobid=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:40:07,660 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-667a81ca) (logid:6f109c13) ===START=== 192.168.122.1 -- GET jobId=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:40:07,671 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-667a81ca ctx-26be4899) (logid:6f109c13) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:07,892 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-62196bf6) (logid:fcc92295) Found 0 routers to update status. 2021-03-13 02:40:07,893 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-62196bf6) (logid:fcc92295) Found 0 VPC's to update Redundant State. 2021-03-13 02:40:07,896 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-62196bf6) (logid:fcc92295) Found 0 networks to update RvR status. 2021-03-13 02:40:08,181 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-667a81ca ctx-26be4899) (logid:6f109c13) ===END=== 192.168.122.1 -- GET jobId=fc577e10-9d35-48d2-a29c-35d4b768bf9a&command=queryAsyncJobResult&response=json 2021-03-13 02:40:08,244 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-1dd50ce6) (logid:4b97bec5) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:08,257 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-1dd50ce6 ctx-76139b89) (logid:4b97bec5) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:08,701 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-1dd50ce6 ctx-76139b89) (logid:4b97bec5) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:08,705 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-16b5968b) (logid:774dd519) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:08,716 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-16b5968b ctx-c2019165) (logid:774dd519) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:08,890 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-3743aea3) (logid:ac8623af) StorageCollector is running... 2021-03-13 02:40:08,903 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-3:ctx-3743aea3) (logid:ac8623af) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2021-03-13 02:40:08,903 DEBUG [c.c.h.XenServerGuru] (StatsCollector-3:ctx-3743aea3) (logid:ac8623af) We are returning the default host to execute commands because the command is not of Copy type. 2021-03-13 02:40:08,992 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-3743aea3) (logid:ac8623af) Seq 3-4114882684533080146: Received: { Ans: , MgmtId: 191528580652610, via: 3(s-2-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2021-03-13 02:40:08,996 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-3:ctx-3743aea3) (logid:ac8623af) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2021-03-13 02:40:08,996 DEBUG [c.c.h.XenServerGuru] (StatsCollector-3:ctx-3743aea3) (logid:ac8623af) We are returning the default host to execute commands because the command is not of Copy type. 2021-03-13 02:40:09,067 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-3743aea3) (logid:ac8623af) Seq 1-4466163455467978846: Received: { Ans: , MgmtId: 191528580652610, via: 1(alien.akham.local), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2021-03-13 02:40:09,189 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-16b5968b ctx-c2019165) (logid:774dd519) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,192 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-dd51abbd) (logid:f96f9d3f) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,205 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-dd51abbd ctx-e63e1c66) (logid:f96f9d3f) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,304 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-dd51abbd ctx-e63e1c66) (logid:f96f9d3f) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,309 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-aa5b5ecd) (logid:04f826b0) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,326 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-aa5b5ecd ctx-9d6bcce0) (logid:04f826b0) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,367 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-aa5b5ecd ctx-9d6bcce0) (logid:04f826b0) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,374 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-657c21f6) (logid:935f42a4) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,382 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-657c21f6 ctx-49d9f0f0) (logid:935f42a4) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,439 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-657c21f6 ctx-49d9f0f0) (logid:935f42a4) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,444 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-563a359b) (logid:83fe23f7) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,457 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-563a359b ctx-86696946) (logid:83fe23f7) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,502 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-563a359b ctx-86696946) (logid:83fe23f7) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,508 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-7c9af809) (logid:b51a15b8) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,514 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-7c9af809 ctx-5b5d6cc7) (logid:b51a15b8) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,559 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-7c9af809 ctx-5b5d6cc7) (logid:b51a15b8) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,562 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-6b6f56e8) (logid:0d24ec79) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,575 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-6b6f56e8 ctx-9a56dc76) (logid:0d24ec79) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,642 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-6b6f56e8 ctx-9a56dc76) (logid:0d24ec79) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,648 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-d1a0ec24) (logid:4aeaf81b) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,660 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-d1a0ec24 ctx-bc2d7a4b) (logid:4aeaf81b) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,696 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Running Capacity Checker ... 2021-03-13 02:40:09,697 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) recalculating system capacity 2021-03-13 02:40:09,697 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Executing cpu/ram capacity update 2021-03-13 02:40:09,708 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-d1a0ec24 ctx-bc2d7a4b) (logid:4aeaf81b) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,712 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Found 2 VMs on host 1 2021-03-13 02:40:09,712 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-ac81b38f) (logid:700f17fa) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,714 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Found 0 VMs are Migrating from host 1 2021-03-13 02:40:09,725 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-ac81b38f ctx-7d91e031) (logid:700f17fa) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,727 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Found 0 VM, not running on host 1 2021-03-13 02:40:09,732 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) No need to calibrate cpu capacity, host:1 usedCpuCore: 2 reservedCpuCore: 0 2021-03-13 02:40:09,737 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) No need to calibrate cpu capacity, host:1 usedCpu: 1000 reservedCpu: 0 2021-03-13 02:40:09,737 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) No need to calibrate memory capacity, host:1 usedMem: (1.50 GB) 1610612736 reservedMem: (0 bytes) 0 2021-03-13 02:40:09,764 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-ac81b38f ctx-7d91e031) (logid:700f17fa) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,770 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-5c482710) (logid:220501b2) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,790 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-5c482710 ctx-500d826c) (logid:220501b2) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,835 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Done executing cpu/ram capacity update 2021-03-13 02:40:09,835 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Executing storage capacity update 2021-03-13 02:40:09,837 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-5c482710 ctx-500d826c) (logid:220501b2) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,842 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-abb11194) (logid:9c3ca49c) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,850 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Found storage pool primaire of type NetworkFilesystem with overprovisioning factor 2 2021-03-13 02:40:09,850 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Total over provisioned capacity calculated is 2 * (23.99 GB) 25760366592 2021-03-13 02:40:09,850 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Total over provisioned capacity of the pool primaire id: 1 is (47.98 GB) 51520733184 2021-03-13 02:40:09,853 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Successfully set Capacity - (47.98 GB) 51520733184 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 1, PodId null 2021-03-13 02:40:09,853 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Done executing storage capacity update 2021-03-13 02:40:09,853 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Executing capacity updates for public ip and Vlans 2021-03-13 02:40:09,862 DEBUG [c.c.a.ApiServer] (qtp182531396-19:ctx-abb11194 ctx-a51c7e7e) (logid:9c3ca49c) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,894 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Done capacity updates for public ip and Vlans 2021-03-13 02:40:09,895 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Executing capacity updates for private ip 2021-03-13 02:40:09,914 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Done executing capacity updates for private ip 2021-03-13 02:40:09,914 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Done recalculating system capacity 2021-03-13 02:40:09,932 DEBUG [c.c.a.ApiServlet] (qtp182531396-19:ctx-abb11194 ctx-a51c7e7e) (logid:9c3ca49c) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,939 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-213c92e8) (logid:abd1f7ca) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:09,952 DEBUG [c.c.a.ApiServer] (qtp182531396-18:ctx-213c92e8 ctx-e47a9929) (logid:abd1f7ca) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:09,964 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-885cc344) (logid:a4f75530) Done running Capacity Checker ... 2021-03-13 02:40:09,997 DEBUG [c.c.a.ApiServlet] (qtp182531396-18:ctx-213c92e8 ctx-e47a9929) (logid:abd1f7ca) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:10,002 DEBUG [c.c.a.ApiServlet] (qtp182531396-17:ctx-34867a76) (logid:fb61f7e2) ===START=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:10,014 DEBUG [c.c.a.ApiServer] (qtp182531396-17:ctx-34867a76 ctx-21de2e7c) (logid:fb61f7e2) CIDRs from which account 'Acct[ed2c36a7-821e-11eb-ac45-525400644510-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2021-03-13 02:40:10,043 DEBUG [c.c.a.ApiServlet] (qtp182531396-17:ctx-34867a76 ctx-21de2e7c) (logid:fb61f7e2) ===END=== 192.168.122.1 -- GET listall=true&page=1&pagesize=20&command=listVirtualMachinesMetrics&response=json 2021-03-13 02:40:10,544 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) (logid:) SeqA 2-291: Processing Seq 2-291: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{ "connections": [] }","wait":"0"}}] } 2021-03-13 02:40:10,670 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) (logid:) SeqA 2-291: Sending Seq 2-291: { Ans: , MgmtId: 191528580652610, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0"}}] } 2021-03-13 02:40:12,073 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) (logid:) Ping from 2(v-1-VM) 2021-03-13 02:40:12,973 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-8901c747) (logid:8ccbb48b) Zone 1 is ready to launch console proxy 2021-03-13 02:40:13,080 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-e4d48f5c) (logid:4facccdb) Zone 1 is ready to launch secondary storage VM 2021-03-13 02:40:15,587 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) (logid:) SeqA 2-293: Processing Seq 2-293: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{ "connections": [] }","wait":"0"}}] } 2021-03-13 02:40:15,667 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) (logid:) SeqA 2-293: Sending Seq 2-293: { Ans: , MgmtId: 191528580652610, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0"}}] } 2021-03-13 02:40:15,766 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-9:null) (logid:) Ping from 3(s-2-VM) 2021-03-13 02:40:16,771 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-6d8cb677) (logid:8437efa2) Checking if any host reservation can be released ... 2021-03-13 02:40:16,783 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-6d8cb677) (logid:8437efa2) Cannot release reservation, Found 2 VMs Running on host 1 2021-03-13 02:40:16,783 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-6d8cb677) (logid:8437efa2) Done running HostReservationReleaseChecker ... 2021-03-13 02:40:20,547 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) (logid:) SeqA 2-294: Processing Seq 2-294: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{ "connections": [] }","wait":"0"}}] } 2021-03-13 02:40:20,644 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) (logid:) SeqA 2-294: Sending Seq 2-294: { Ans: , MgmtId: 191528580652610, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0"}}] } ``` ---------------------------------------------------------------- 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: us...@infra.apache.org
