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
