Hello Serge, Check these snippets from your logs. Line 61: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-454-VM]Scope=interface Line 66: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-454-VM]Scope=interface Line 72: (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115) (logid:a9f8cbaf) Unable to complete AsyncJobVO {id:1115, userId: 1, accountId: 1, Line 80: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-454-VM]Scope=interface Line 134: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-454-VM]Scope=interface Line 175: (secstorage-1:ctx-694f5c71) (logid:a34366a8) Unable to start secondary storage vm for standby capacity, vm id : 454, will recycle it and start a new one
It seems the system cannot create the secondary VM thus the zone/pods/clusters are not functional. Check the hypervisor logs at "/var/log/cloud/cloud.log and let us know what you see there. Usually the cause of this issue is that primary storage cannot utilized (either not mounted or something else) on the hypervisor for usage. Best regards, Jordan -----Original Message----- From: Serge Byishimo <sergebyish...@gmail.com> Sent: Wednesday, May 19, 2021 6:49 PM To: users@cloudstack.apache.org Subject: I Need Help 🙏🏼 [X] This message came from outside your organization Cloudstack: 4.15 OS: Centos 8 Two computers: one for the Management Server and the other for the Host Primary and Secondary storage is on the host and connected to the management through NFS, 2021-05-19 11:20:39,924 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8 FirstFitRoutingAllocator) (logid:a9f8cbaf) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]] 2021-05-19 11:20:39,924 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8 FirstFitRoutingAllocator) (logid:a9f8cbaf) Looking for speed=500Mhz, Ram=512 MB 2021-05-19 11:20:39,924 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8 FirstFitRoutingAllocator) (logid:a9f8cbaf) Host name: srvr2.cloud.priv, hostId: 1 is in avoid set, skipping this and trying other available hosts 2021-05-19 11:20:39,924 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8 FirstFitRoutingAllocator) (logid:a9f8cbaf) Host Allocator returning 0 suitable hosts 2021-05-19 11:20:39,924 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) No suitable hosts found 2021-05-19 11:20:39,924 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) No suitable hosts found under this Cluster: 1 2021-05-19 11:20:39,927 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) Could not find suitable Deployment Destination for this VM under any clusters, returning. 2021-05-19 11:20:39,930 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) Searching resources only under specified Pod: 1 2021-05-19 11:20:39,934 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) Listing clusters in order of aggregate capacity, that have (at least one host with) enough CPU and RAM capacity under this Pod: 1 2021-05-19 11:20:39,942 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) Removing from the clusterId list these clusters from avoid set: [1] 2021-05-19 11:20:39,947 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) No clusters found after removing disabled clusters and clusters in avoid list, returning. 2021-05-19 11:20:39,974 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) 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-05-19 11:20:39,997 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) Hosts's actual total CPU: 43200 and CPU after applying overprovisioning: 43200 2021-05-19 11:20:39,997 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) Hosts's actual total RAM: (61.57 GB) 66114236416 and RAM after applying overprovisioning: (61.57 GB) 66114236416 2021-05-19 11:20:39,997 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 43200, total with overprovisioning: 43200; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse 2021-05-19 11:20:39,998 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) release mem from host: 1, old used: (1.50 GB) 1610612736,reserved: (0 bytes) 0, total: (61.57 GB) 66114236416; new used: (1.00 GB) 1073741824,reserved:(0 bytes) 0; movedfromreserved: false,moveToReserveredfalse 2021-05-19 11:20:40,011 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-454-VM]Scope=interface com.cloud.dc.DataCenter; id=1 2021-05-19 11:20:40,012 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115 ctx-9c8114c8) (logid:a9f8cbaf) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-454-VM]Scope=interface com.cloud.dc.DataCenter; id=1 2021-05-19 11:20:40,012 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115) (logid:a9f8cbaf) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 454, job origin: 1107 2021-05-19 11:20:40,012 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115) (logid:a9f8cbaf) Unable to complete AsyncJobVO {id:1115, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAABxnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 114477775508155, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed May 19 11:10:39 EDT 2021, removed: null}, job origin:1107 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-454-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:829) 2021-05-19 11:20:40,028 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115) (logid:a9f8cbaf) Publish async job-1115 complete on message bus 2021-05-19 11:20:40,029 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115) (logid:a9f8cbaf) Wake up jobs related to job-1115 2021-05-19 11:20:40,029 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115) (logid:a9f8cbaf) Update db status for job-1115 2021-05-19 11:20:40,032 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115) (logid:a9f8cbaf) Wake up jobs joined with job-1115 and disjoin all subjobs created from job- 1115 2021-05-19 11:20:40,052 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115) (logid:a9f8cbaf) Done executing com.cloud.vm.VmWorkStart for job-1115 2021-05-19 11:20:40,061 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-8:ctx-e9ad7a77 job-1107/job-1115) (logid:a9f8cbaf) Remove job-1115 from job monitoring 2021-05-19 11:20:40,076 WARN [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Exception while trying to start secondary storage vm com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-454-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:829) 2021-05-19 11:20:40,078 INFO [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Unable to start secondary storage vm for standby capacity, vm id : 454, will recycle it and start a new one 2021-05-19 11:20:40,107 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Sync job-1118 execution on object VmWorkJobQueue.454 2021-05-19 11:20:40,831 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-e4f9bd44) (logid:7bc61078) Execute sync-queue item: SyncQueueItemVO {id:1061, queueId: 1056, contentType: AsyncJob, contentId: 1118, lastProcessMsid: 114477775508155, lastprocessNumber: 3, lastProcessTime: Wed May 19 11:20:40 EDT 2021, created: Wed May 19 11:20:40 EDT 2021} 2021-05-19 11:20:40,833 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-e4f9bd44) (logid:7bc61078) Schedule queued job-1118 2021-05-19 11:20:40,848 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118) (logid:e7375fc2) Add job-1118 into job monitoring 2021-05-19 11:20:40,859 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118) (logid:a9f8cbaf) Executing AsyncJobVO {id:1118, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo: rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAABxnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 114477775508155, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed May 19 11:20:40 EDT 2021, removed: null} 2021-05-19 11:20:40,860 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118) (logid:a9f8cbaf) Run VM work job: com.cloud.vm.VmWorkStop for VM 454, job origin: 1107 2021-05-19 11:20:40,865 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118 ctx-53c5dc81) (logid:a9f8cbaf) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":454,"handlerName":"VirtualMachineManagerImpl"} 2021-05-19 11:20:40,872 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118 ctx-53c5dc81) (logid:a9f8cbaf) VM is already stopped: VM[SecondaryStorageVm|s-454-VM] 2021-05-19 11:20:40,872 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118 ctx-53c5dc81) (logid:a9f8cbaf) Done executing VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":454,"handlerName":"VirtualMachineManagerImpl"} 2021-05-19 11:20:40,875 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118 ctx-53c5dc81) (logid:a9f8cbaf) Complete async job-1118, jobStatus: SUCCEEDED, resultCode: 0, result: null 2021-05-19 11:20:40,877 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118 ctx-53c5dc81) (logid:a9f8cbaf) Publish async job-1118 complete on message bus 2021-05-19 11:20:40,877 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118 ctx-53c5dc81) (logid:a9f8cbaf) Wake up jobs related to job-1118 2021-05-19 11:20:40,877 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118 ctx-53c5dc81) (logid:a9f8cbaf) Update db status for job-1118 2021-05-19 11:20:40,880 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118 ctx-53c5dc81) (logid:a9f8cbaf) Wake up jobs joined with job-1118 and disjoin all subjobs created from job- 1118 2021-05-19 11:20:40,902 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118) (logid:a9f8cbaf) Done with run of VM work job: com.cloud.vm.VmWorkStop for VM 454, job origin: 1107 2021-05-19 11:20:40,902 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118) (logid:a9f8cbaf) Done executing com.cloud.vm.VmWorkStop for job-1118 2021-05-19 11:20:40,907 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-11:ctx-fad73038 job-1107/job-1118) (logid:a9f8cbaf) Remove job-1118 from job monitoring 2021-05-19 11:20:40,942 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) VM state transitted from :Stopped to Expunging with event: ExpungeOperationvm's original host id: null new host id: null host id before state transition: null 2021-05-19 11:20:40,953 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Destroying vm VM[SecondaryStorageVm|s-454-VM] 2021-05-19 11:20:40,953 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Cleaning up NICS 2021-05-19 11:20:40,953 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Cleaning network for vm: 454 2021-05-19 11:20:40,977 DEBUG [c.c.n.g.PublicNetworkGuru] (secstorage-1:ctx-694f5c71) (logid:a34366a8) public network deallocate network: networkId: 200, ip: 209.150.129.37 2021-05-19 11:20:40,996 DEBUG [c.c.n.g.PublicNetworkGuru] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Deallocated nic: NicProfile[442-454-null-null-null] 2021-05-19 11:20:41,004 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Removed nic id=442 2021-05-19 11:20:41,007 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Revoving nic secondary ip entry ... 2021-05-19 11:20:41,031 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Removed nic id=443 2021-05-19 11:20:41,033 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Revoving nic secondary ip entry ... 2021-05-19 11:20:41,061 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Removed nic id=444 2021-05-19 11:20:41,063 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Revoving nic secondary ip entry ... 2021-05-19 11:20:41,065 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Cleaning up hypervisor data structures (ex. SRs in XenServer) for managed storage 2021-05-19 11:20:41,067 DEBUG [o.a.c.e.o.VolumeOrchestrator] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Cleaning storage for vm: 454 2021-05-19 11:20:41,125 DEBUG [o.a.c.s.v.VolumeServiceImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Marking volume that was never created as destroyed: Vol[148|vm=454|ROOT] 2021-05-19 11:20:41,151 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Expunged VM[SecondaryStorageVm|s-454-VM] 2021-05-19 11:20:41,164 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-694f5c71) (logid:a34366a8) received secondary storage vm alert 2021-05-19 11:20:41,167 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Secondary Storage Vm creation failure, zone: Zone1 2021-05-19 11:20:41,169 WARN [c.c.a.AlertManagerImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) AlertType:: 19 | dataCenterId:: 1 | podId:: null | clusterId:: null | message:: Secondary Storage Vm creation failure. zone: Zone1, error details: null 2021-05-19 11:20:41,184 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-694f5c71) (logid:a34366a8) Primary secondary storage is not even started, wait until next turn 2021-05-19 11:20:41,223 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Zone 1 is ready to launch secondary storage VM 2021-05-19 11:20:41,231 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) No running secondary storage vms found in datacenter id=1, starting one 2021-05-19 11:20:41,240 INFO [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) No stopped secondary storage vm is available, need to allocate a new secondary storage vm 2021-05-19 11:20:41,246 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Assign secondary storage vm from a newly started instance for request from data center : 1 2021-05-19 11:20:41,282 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Found existing network configuration for offering [Network Offering [1-Public-System-Public-Network]: Ntwk[200|Public|1] 2021-05-19 11:20:41,282 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Releasing lock for Acct[5c42e60b-b7b3-11eb-b5c5-681def24d2bb-system] 2021-05-19 11:20:41,306 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Found existing network configuration for offering [Network Offering [3-Control-System-Control-Network]: Ntwk[202|Control|3] 2021-05-19 11:20:41,306 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Releasing lock for Acct[5c42e60b-b7b3-11eb-b5c5-681def24d2bb-system] 2021-05-19 11:20:41,328 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Found existing network configuration for offering [Network Offering [2-Management-System-Management-Network]: Ntwk[201|Management|2] 2021-05-19 11:20:41,329 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Releasing lock for Acct[5c42e60b-b7b3-11eb-b5c5-681def24d2bb-system] 2021-05-19 11:20:41,368 INFO [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) allocating virtual machine from template:7ed2a89e-9cac-492c-b252-3bffd238c898 with hostname:s-456-VM and 3 networks 2021-05-19 11:20:41,374 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Allocating entries for VM: VM[SecondaryStorageVm|s-456-VM] 2021-05-19 11:20:41,378 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Allocating nics for VM[SecondaryStorageVm|s-456-VM] 2021-05-19 11:20:41,382 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Allocating nic for vm VM[SecondaryStorageVm|s-456-VM] in network Ntwk[200|Public|1] with requested profile NicProfile[0-0-null-null-null] 2021-05-19 11:20:41,443 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Allocating nic for vm VM[SecondaryStorageVm|s-456-VM] in network Ntwk[202|Control|3] with requested profile null 2021-05-19 11:20:41,459 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Allocating nic for vm VM[SecondaryStorageVm|s-456-VM] in network Ntwk[201|Management|2] with requested profile null 2021-05-19 11:20:41,479 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Allocating disks for VM[SecondaryStorageVm|s-456-VM] 2021-05-19 11:20:41,479 INFO [o.a.c.e.o.VolumeOrchestrator] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) adding disk object ROOT-456 to s-456-VM 2021-05-19 11:20:41,498 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Allocation completed for VM: VM[SecondaryStorageVm|s-456-VM] 2021-05-19 11:20:41,504 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) received secondary storage vm alert 2021-05-19 11:20:41,507 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) New secondary storage vm created, zone: Zone1, secStorageVm: s-456-VM, public IP: null, private IP: null 2021-05-19 11:20:41,536 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (secstorage-1:ctx-03019fb4) (logid:d8dc459d) Sync job-1119 execution on object VmWorkJobQueue.456 2021-05-19 11:20:42,297 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-8e6bdaef) (logid:6494d66f) StorageCollector is running... 2021-05-19 11:20:42,311 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-8e6bdaef) (logid:6494d66f) There is no secondary storage VM for secondary storage host Secondary1 2021-05-19 11:20:42,317 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-2:ctx-8e6bdaef) (logid:6494d66f) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2021-05-19 11:20:42,317 DEBUG [c.c.h.XenServerGuru] (StatsCollector-2:ctx-8e6bdaef) (logid:6494d66f) We are returning the default host to execute commands because the command is not of Copy type. 2021-05-19 11:20:42,383 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-8e6bdaef) (logid:6494d66f) Seq 1-4873457746768298101: Received: { Ans: , MgmtId: 114477775508155, via: 1(srvr2.cloud.priv), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2021-05-19 11:20:42,388 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-2:ctx-8e6bdaef) (logid:6494d66f) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2021-05-19 11:20:42,388 DEBUG [c.c.h.XenServerGuru] (StatsCollector-2:ctx-8e6bdaef) (logid:6494d66f) We are returning the default host to execute commands because the command is not of Copy type. 2021-05-19 11:20:42,482 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-8e6bdaef) (logid:6494d66f) Seq 1-4873457746768298102: Received: { Ans: , MgmtId: 114477775508155, via: 1(srvr2.cloud.priv), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2021-05-19 11:20:42,836 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-d8a66dc4) (logid:f85fb5ce) Execute sync-queue item: SyncQueueItemVO {id:1062, queueId: 1062, contentType: AsyncJob, contentId: 1119, lastProcessMsid: 114477775508155, lastprocessNumber: 1, lastProcessTime: Wed May 19 11:20:42 EDT 2021, created: Wed May 19 11:20:41 EDT 2021} 2021-05-19 11:20:42,840 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-d8a66dc4) (logid:f85fb5ce) Schedule queued job-1119 2021-05-19 11:20:42,857 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119) (logid:432ff131) Add job-1119 into job monitoring 2021-05-19 11:20:42,869 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119) (logid:a9f8cbaf) Executing AsyncJobVO {id:1119, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAByHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 114477775508155, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed May 19 11:20:41 EDT 2021, removed: null} 2021-05-19 11:20:42,870 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119) (logid:a9f8cbaf) Run VM work job: com.cloud.vm.VmWorkStart for VM 456, job origin: 1107 2021-05-19 11:20:42,877 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":456,"handlerName":"VirtualMachineManagerImpl"} 2021-05-19 11:20:42,904 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) 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-05-19 11:20:42,904 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Successfully transitioned to start state for VM[SecondaryStorageVm|s-456-VM] reservation id = cd31b3d1-30e6-49a2-b27c-3e2983fda982 2021-05-19 11:20:42,921 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Deploy avoids pods: null, clusters: null, hosts: null 2021-05-19 11:20:42,932 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) DeploymentPlanner allocation algorithm: null 2021-05-19 11:20:42,932 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: (512.00 MB) 536870912 2021-05-19 11:20:42,932 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Is ROOT volume READY (pool already allocated)?: No 2021-05-19 11:20:42,935 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Deploy avoids pods: null, clusters: null, hosts: null 2021-05-19 11:20:42,942 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Searching all possible resources under this Zone: 1 2021-05-19 11:20:42,950 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Listing clusters in order of aggregate capacity, that have (at least one host with) enough CPU and RAM capacity under this Zone: 1 2021-05-19 11:20:42,988 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking resources in Cluster: 1 under Pod: 1 2021-05-19 11:20:42,995 INFO [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Guest VM is requested with Cusotm[UEFI] Boot Type false 2021-05-19 11:20:42,995 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Looking for hosts in dc: 1 pod:1 cluster:1 2021-05-19 11:20:43,004 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]] 2021-05-19 11:20:43,023 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]] 2021-05-19 11:20:43,023 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Looking for speed=500Mhz, Ram=512 MB 2021-05-19 11:20:43,049 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Host: 1 has cpu capability (cpu:12, speed:3600) to support requested CPU: 1 and requested speed: 500 2021-05-19 11:20:43,050 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0 2021-05-19 11:20:43,058 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Hosts's actual total CPU: 43200 and CPU after applying overprovisioning: 43200 2021-05-19 11:20:43,058 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Free CPU: 42700 , Requested CPU: 500 2021-05-19 11:20:43,058 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Free RAM: (60.57 GB) 65040494592 , Requested RAM: (512.00 MB) 536870912 2021-05-19 11:20:43,058 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Host has enough CPU and RAM available 2021-05-19 11:20:43,058 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) STATS: Can alloc CPU from host: 1, used: 500, reserved: 0, actual total: 43200, total with overprovisioning: 43200; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true 2021-05-19 11:20:43,059 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) STATS: Can alloc MEM from host: 1, used: (1.00 GB) 1073741824, reserved: (0 bytes) 0, total: (61.57 GB) 66114236416; requested mem: (512.00 MB) 536870912, alloc_from_last_host?: false , considerReservedCapacity?: true 2021-05-19 11:20:43,059 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Found a suitable host, adding to list: 1 2021-05-19 11:20:43,059 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d FirstFitRoutingAllocator) (logid:a9f8cbaf) Host Allocator returning 1 suitable hosts 2021-05-19 11:20:43,065 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking suitable pools for volume (Id, Type): (150,ROOT) 2021-05-19 11:20:43,065 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) We need to allocate new storagepool for this volume 2021-05-19 11:20:43,067 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Calling StoragePoolAllocators to find suitable pools 2021-05-19 11:20:43,074 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) System VMs will use shared storage for zone id=1 2021-05-19 11:20:43,075 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) LocalStoragePoolAllocator trying to find storage pool to fit the vm 2021-05-19 11:20:43,075 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) ClusterScopeStoragePoolAllocator looking for storage pool 2021-05-19 11:20:43,075 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools will be ignored. 2021-05-19 11:20:43,077 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Found pools matching tags: [Pool[3|NetworkFilesystem], Pool[5|NetworkFilesystem]] 2021-05-19 11:20:43,081 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking if storage pool is suitable, name: null ,poolId: 3 2021-05-19 11:20:43,085 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Storage pool null (3) does not supply IOPS capacity, assuming enough capacity 2021-05-19 11:20:43,088 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking pool 3 for storage, totalSize: 75125227520, usedBytes: 5206179840, usedPct: 0.06930002093656222, disable threshold: 0.85 2021-05-19 11:20:43,088 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Destination pool id: 3 2021-05-19 11:20:43,127 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Pool ID for the volume with ID 150 is null 2021-05-19 11:20:43,142 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Found storage pool Primary1 of type NetworkFilesystem with over-provisioning factor 2 2021-05-19 11:20:43,142 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Total over-provisioned capacity calculated is 2 * (69.97 GB) 75125227520 2021-05-19 11:20:43,142 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Total capacity of the pool Primary1 with ID 3 is (139.93 GB) 150250455040 2021-05-19 11:20:43,145 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking pool: 3 for storage allocation , maxSize : (139.93 GB) 150250455040, totalAllocatedSize : (192.04 KB) 196648, askingSize : (0 bytes) 0, allocated disable threshold: 0.85 2021-05-19 11:20:43,147 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking if storage pool is suitable, name: null ,poolId: 5 2021-05-19 11:20:43,152 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Storage pool null (5) does not supply IOPS capacity, assuming enough capacity 2021-05-19 11:20:43,156 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking pool 5 for storage, totalSize: 1278522425344, usedBytes: 79691776, usedPct: 6.233115228976768E-5, disable threshold: 0.85 2021-05-19 11:20:43,156 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Destination pool id: 5 2021-05-19 11:20:43,194 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Pool ID for the volume with ID 150 is null 2021-05-19 11:20:43,209 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Found storage pool Primary2 of type NetworkFilesystem with over-provisioning factor 2 2021-05-19 11:20:43,209 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Total over-provisioned capacity calculated is 2 * (1.1628 TB) 1278522425344 2021-05-19 11:20:43,209 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Total capacity of the pool Primary2 with ID 5 is (2.3256 TB) 2557044850688 2021-05-19 11:20:43,212 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking pool: 5 for storage allocation , maxSize : (2.3256 TB) 2557044850688, totalAllocatedSize : (192.04 KB) 196648, askingSize : (0 bytes) 0, allocated disable threshold: 0.85 2021-05-19 11:20:43,212 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) ClusterScopeStoragePoolAllocator returning 2 suitable storage pools 2021-05-19 11:20:43,213 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2021-05-19 11:20:43,214 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking if host: 1 can access any suitable storage pool for volume: ROOT 2021-05-19 11:20:43,217 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Host: 1 can access pool: 3 2021-05-19 11:20:43,219 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Found a potential host id: 1 name: srvr2.cloud.priv and associated storage pools for this VM 2021-05-19 11:20:43,222 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) 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(150|ROOT-->Pool(3))] 2021-05-19 11:20:43,222 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Deployment found - P0=VM[SecondaryStorageVm|s-456-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(150|ROOT-->Pool(3))] 2021-05-19 11:20:43,248 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) 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-05-19 11:20:43,273 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Hosts's actual total CPU: 43200 and CPU after applying overprovisioning: 43200 2021-05-19 11:20:43,273 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) We are allocating VM, increasing the used capacity of this host:1 2021-05-19 11:20:43,273 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Current Used CPU: 500 , Free CPU:42700 ,Requested CPU: 500 2021-05-19 11:20:43,273 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Current Used RAM: (1.00 GB) 1073741824 , Free RAM:(60.57 GB) 65040494592 ,Requested RAM: (512.00 MB) 536870912 2021-05-19 11:20:43,273 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) CPU STATS after allocation: for host: 1, old used: 500, old reserved: 0, actual total: 43200, total with overprovisioning: 43200; new used:1000, reserved:0; requested cpu:500,alloc_from_last:false 2021-05-19 11:20:43,274 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) RAM STATS after allocation: for host: 1, old used: (1.00 GB) 1073741824, old reserved: (0 bytes) 0, total: (61.57 GB) 66114236416; new used: (1.50 GB) 1610612736, reserved: (0 bytes) 0; requested mem: (512.00 MB) 536870912,alloc_from_last:false 2021-05-19 11:20:43,279 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Host: 1 has cpu capability (cpu:12, speed:3600) to support requested CPU: 1 and requested speed: 500 2021-05-19 11:20:43,279 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0 2021-05-19 11:20:43,283 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Hosts's actual total CPU: 43200 and CPU after applying overprovisioning: 43200 2021-05-19 11:20:43,283 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) We need to allocate to the last host again, so checking if there is enough reserved capacity 2021-05-19 11:20:43,283 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Reserved CPU: 0 , Requested CPU: 500 2021-05-19 11:20:43,284 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Reserved RAM: (0 bytes) 0 , Requested RAM: (512.00 MB) 536870912 2021-05-19 11:20:43,284 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) STATS: Failed to alloc resource from host: 1 reservedCpu: 0, requested cpu: 500, reservedMem: (0 bytes) 0, requested mem: (512.00 MB) 536870912 2021-05-19 11:20:43,284 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Host does not have enough reserved CPU available, cannot allocate to this host. 2021-05-19 11:20:43,284 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: (512.00 MB) 536870912 , cpuOverprovisioningFactor: 1.0 2021-05-19 11:20:43,288 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Hosts's actual total CPU: 43200 and CPU after applying overprovisioning: 43200 2021-05-19 11:20:43,288 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Free CPU: 42700 , Requested CPU: 500 2021-05-19 11:20:43,288 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Free RAM: (60.57 GB) 65040494592 , Requested RAM: (512.00 MB) 536870912 2021-05-19 11:20:43,288 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Host has enough CPU and RAM available 2021-05-19 11:20:43,288 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) STATS: Can alloc CPU from host: 1, used: 500, reserved: 0, actual total: 43200, total with overprovisioning: 43200; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true 2021-05-19 11:20:43,288 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) STATS: Can alloc MEM from host: 1, used: (1.00 GB) 1073741824, reserved: (0 bytes) 0, total: (61.57 GB) 66114236416; requested mem: (512.00 MB) 536870912, alloc_from_last_host?: false , considerReservedCapacity?: true 2021-05-19 11:20:43,314 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Network id=200 is already implemented 2021-05-19 11:20:43,361 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Network id=202 is already implemented 2021-05-19 11:20:43,876 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Reserved NIC for s-456-VM [ipv4:169.254.24.222 netmask:255.255.0.0 gateway:169.254.0.1] 2021-05-19 11:20:43,900 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Network id=201 is already implemented 2021-05-19 11:20:43,929 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Releasing ip address for instance=450 2021-05-19 11:20:43,946 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) Allocated a nic NicProfile[450-456-cd31b3d1-30e6-49a2-b27c-3e2983fda982-192.168.1.110-null] for VM[SecondaryStorageVm|s-456-VM] 2021-05-19 11:20:44,005 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) template 3 is already in store:3, type:Image 2021-05-19 11:20:44,093 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type VOLUME 2021-05-19 11:20:44,188 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-12:ctx-4ea8304f job-1107/job-1119 ctx-9a34e22d) (logid:a9f8cbaf) getCommandHostDelegation: class org.apache.cloudstack.storage.command.CopyCommand