System VMs SSH available only through the hypervisor.
You can read more about it here ->
http://docs.cloudstack.apache.org/en/latest/adminguide/systemvm.html#accessing-system-vms
On the hypervisor host 192.168.1.7 what do you see in /var/log/cloud/cloud.log
Any issues reported?
Regards,
Jordan
From: Serge Byishimo <sergebyish...@gmail.com>
Sent: Thursday, May 20, 2021 9:55 AM
To: users@cloudstack.apache.org
Subject: Re: I Need Help ππΌ
[X]This message came from outside your organization
Thank you Yordan,
I have 6TB of primary storage available on the dashboard,
But one of the problem I have is I canβt SSH through the SystemVMs to see that
log, Iβm thinking It might a networking Issue, so let me show you my
configuration :
I have 2 computers : 1st management server, 2nd Host
They are on a private network, they donβt have public IP addresses, so I was
confused when cloudstack kept asking me about public IP addresses
1st computer :
ifconfig :
[root@srvr1 ~]# ifconfig
eno1: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet 192.168.1.8 netmask 255.255.255.0 broadcast 192.168.1.255
inet6 fe80::7a31:44f5:6cbd:f97e prefixlen 64 scopeid 0x20<link>
ether 68:1d:ef:24:d2:bb txqueuelen 1000 (Ethernet)
RX packets 683346 bytes 450075162 (429.2 MiB)
RX errors 0 dropped 31958 overruns 0 frame 0
TX packets 483540 bytes 464984616 (443.4 MiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
lo: flags=73<UP,LOOPBACK,RUNNING> mtu 65536
inet 127.0.0.1 netmask 255.0.0.0
inet6 ::1 prefixlen 128 scopeid 0x10<host>
loop txqueuelen 1000 (Local Loopback)
RX packets 11164675 bytes 2804166400 (2.6 GiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 11164675 bytes 2804166400 (2.6 GiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
[root@srvr1 ~]#
[root@srvr1 ~]# cat /etc/sysconfig/network-scripts/ifcfg-cloudbr0
DEVICE=cloudbr0
TYPE=Bridge
ONBOOT=yes
BOOTPROTO=static
IPV6INIT=no
IPV6_AUTOCONF=no
DELAY=5
IPADDR=192.168.1.8
GATEWAY=192.168.1.1
NETMASK=255.255.255.0
DNS1=8.8.8.8
DNS2=8.8.4.4
STP=yes
USERCTL=no
NM_CONTROLLED=no
[root@srvr1 ~]#
[root@srvr1 ~]# cat /etc/sysconfig/network-scripts/ifcfg-eno1
TYPE=Ethernet
BOOTPRO=static
NAME=eno1
UUID=7dad60c5-e259-4fb9-9f5a-aac0ec29435f
DEVICE=eno1
ONBOOT=yes
IPADDR-192.168.1.8
PREFIX=24
GATEWAY=192.168.1.1
USRCTL=no
BRIDGE=cloudbr0
[root@srvr1 ~]#
2nd computer :
The 2nd computer has 2 NICs :
[root@srvr2 ~]# ifconfig
cloud0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet 169.254.0.1 netmask 255.255.0.0 broadcast 0.0.0.0
inet6 fe80::f89d:edff:fe9c:e90b prefixlen 64 scopeid 0x20<link>
ether fa:9d:ed:9c:e9:0b txqueuelen 1000 (Ethernet)
RX packets 0 bytes 0 (0.0 B)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 1401 bytes 59862 (58.4 KiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
cloudbr0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet 192.168.1.7 netmask 255.255.255.0 broadcast 192.168.1.255
inet6 fe80::8040:8dff:fe57:4eb8 prefixlen 64 scopeid 0x20<link>
ether d0:50:99:81:89:f5 txqueuelen 1000 (Ethernet)
RX packets 220463 bytes 19759124 (18.8 MiB)
RX errors 0 dropped 22054 overruns 0 frame 0
TX packets 620 bytes 55228 (53.9 KiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
cloudbr1: flags=4099<UP,BROADCAST,MULTICAST> mtu 1500
ether 32:7c:82:bc:0f:ce txqueuelen 1000 (Ethernet)
RX packets 0 bytes 0 (0.0 B)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 0 bytes 0 (0.0 B)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
enp0s25: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
ether d0:50:99:81:89:f5 txqueuelen 1000 (Ethernet)
RX packets 250164 bytes 33642066 (32.0 MiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 37371 bytes 2409704 (2.2 MiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
device interrupt 20 memory 0xfb200000-fb220000
enp3s0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet 192.168.1.60 netmask 255.255.255.0 broadcast 192.168.1.255
inet6 fe80::6a1a:9d26:8975:480c prefixlen 64 scopeid 0x20<link>
ether 68:05:ca:c6:6e:9d txqueuelen 1000 (Ethernet)
RX packets 618625 bytes 444641389 (424.0 MiB)
RX errors 0 dropped 22070 overruns 0 frame 0
TX packets 178295 bytes 28986719 (27.6 MiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
device interrupt 18 memory 0xfb1c0000-fb1e0000
lo: flags=73<UP,LOOPBACK,RUNNING> mtu 65536
inet 127.0.0.1 netmask 255.0.0.0
inet6 ::1 prefixlen 128 scopeid 0x10<host>
loop txqueuelen 1000 (Local Loopback)
RX packets 88970 bytes 20756782 (19.7 MiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 88970 bytes 20756782 (19.7 MiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
[root@srvr2 ~]#
[root@srvr2 ~]# cat /etc/sysconfig/network-scripts/ifcfg-cloudbr0
DEVICE=cloudbr0
TYPE=Bridge
ONBOOT=yes
BOOTPROTO=none
IPV6INIT=no
DELAY=5
IPADDR=192.168.1.7
GATEWAY=192.168.1.1
NETMASK=255.255.255.0
STP=yes
BRIDGING_OPTS=priority=32768
PROXY_METHOD=none
BROWSER_ONLY=no
PREFIX=24
DEFROUTE=yes
IPV4_FAILURE_FATAL=no
NAME="Bridge cloudbr0"
UUID=d4b789ba-7321-548d-dabd-5c4150da0266
[root@srvr2 ~]#
[root@srvr2 ~]#
[root@srvr2 ~]# cat /etc/sysconfig/network-scripts/ifcfg-cloudbr1
DEVICE=cloudbr1
TYPE=Bridge
ONBOOT=yes
BOOTPROTO=none
IPV6INIT=no
IPV6_AUTOCONF=no
DELAY=5
STP=yes
[root@srvr2 ~]#
[root@srvr2 ~]# cat /etc/sysconfig/network-scripts/ifcfg-enp0s25
TYPE=Ethernet
NAME=enp0s25
UUID=93380612-3b97-4a34-ab9f-042b751cc468
DEVICE=enp0s25
ONBOOT=yes
BRIDGE=cloudbr0
# cat /etc/sysconfig/network-scripts/enp0s25.200
DEVICE=enp0s25.200
ONBOOT=yes
HOTPLUG=no
BOOTPROTO=none
TYPE=Ethernet
VLAN=yes
BRIDGE=cloudbr1
[Screen Shot 2021-05-20 at 08.52.21.png]
[Screen Shot 2021-05-20 at 08.52.47.png]
[Screen Shot 2021-05-20 at 08.53.12.png]
[Screen Shot 2021-05-20 at 08.53.18.png]
I need help figuring out what I did wrong!
On Thu, May 20, 2021 at 8:30 AM Yordan Kostov
<yord...@nsogroup.com<mailto:yord...@nsogroup.com>> wrote:
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<mailto:sergebyish...@gmail.com>>
Sent: Wednesday, May 19, 2021 6:49 PM
To: users@cloudstack.apache.org<mailto: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
--
Byishimo Shema Serge
Kigali, Rwanda
Tel: +250 786 076 106
www.serge.works<https://urldefense.com/v3/__http:/www.serge.works__;!!A6UyJA!1fIpYgsV56uJuSScO5lKRMmbQoBUqNIhFAFn2Wv56QmGWGyiD2Ox2kmqZIl_d1MtJjNNpvr8ImTg$>
