Re: Error migrate System VMs after upgrageing to 4.17

[vas...@gmx.de]

Hi Slavka,

no, i am not using any kind of custome offerings.

I try to provide a more detailled log this time.
Situation:
v-83-VM was the "broken" consoleproxy. So the following log starts with
it's expunging.
Afterwards the new consoleproxy shall be deployed - v-85-VM.

This first deployment (logid:dcfe0999) fails due to Insufficent address
capacity - which i can't really understand or see in the database, checking
the availeable IPs for systemVMs (given that i might looking up the wrong
tables....).
How ever CS is working as expected trying to deploy the console proxy
(logid:440fd101) Sync job-4288).
That job fails with "Unable to create deployment, no usable volumes found
for the VM: 85".
Afterwards i have another try to start the consoleproxy (job-4289) which
fails for the same reason. And thats how things go on in the log file...


2022-08-29 17:01:16,224 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-35:ctx-29e06f28 job-4286 ctx-442b1cb2) (logid:5fe8559a)
Cleaning up hypervisor data structures (ex. SRs in XenServer) for managed
storage. Data from VM instance {id: "83", name: "v-83-VM", uuid:
"b1d1f9c6-eafe-4527-9335-e649c646aab0", type="ConsoleProxy"}.
2022-08-29 17:01:16,225 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(API-Job-Executor-35:ctx-29e06f28 job-4286 ctx-442b1cb2) (logid:5fe8559a)
Cleaning storage for vm: 83
2022-08-29 17:01:16,233 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-35:ctx-29e06f28 job-4286 ctx-442b1cb2) (logid:5fe8559a)
Expunged VM instance {id: "83", name: "v-83-VM", uuid:
"b1d1f9c6-eafe-4527-9335-e649c646aab0", type="ConsoleProxy"}
2022-08-29 17:01:16,255 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-35:ctx-29e06f28 job-4286 ctx-442b1cb2) (logid:5fe8559a)
Complete async job-4286, jobStatus: SUCCEEDED, resultCode: 0, result:
org.apache.cloudstack.api.response.SystemVmResponse/systemvm/{"id":"b1d1f9c6-eafe-4527-9335-e649c646aab0","systemvmtype":"consoleproxy","zoneid":"48e2e928-3300-43b5-8e3a-d9b358022502","zonename":"xxxxxxxxxx","dns1":"10.129.0.4","dns2":"195.10.195.195","name":"v-83-VM","templateid":"c20799e4-a990-449a-aae6-4b67374c7aff","templatename":"systemvm-kvm-4.17.0","created":"2022-08-29T10:38:26+0200","state":"Stopped","isdynamicallyscalable":"false","hasannotations":"false"}
2022-08-29 17:01:16,256 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-35:ctx-29e06f28 job-4286 ctx-442b1cb2) (logid:5fe8559a)
Publish async job-4286 complete on message bus
2022-08-29 17:01:16,256 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-35:ctx-29e06f28 job-4286 ctx-442b1cb2) (logid:5fe8559a)
Wake up jobs related to job-4286
2022-08-29 17:01:16,256 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-35:ctx-29e06f28 job-4286 ctx-442b1cb2) (logid:5fe8559a)
Update db status for job-4286
2022-08-29 17:01:16,256 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-35:ctx-29e06f28 job-4286 ctx-442b1cb2) (logid:5fe8559a)
Wake up jobs joined with job-4286 and disjoin all subjobs created from job-
4286
2022-08-29 17:01:16,260 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-35:ctx-29e06f28 job-4286) (logid:5fe8559a) Done executing
org.apache.cloudstack.api.command.admin.systemvm.DestroySystemVmCmd for
job-4286
2022-08-29 17:01:16,260 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-35:ctx-29e06f28 job-4286) (logid:5fe8559a) Remove
job-4286 from job monitoring
2022-08-29 17:01:17,691 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-6:ctx-6af18142) (logid:fe263a70) HA health check
task is running...

2022-08-29 17:01:21,694 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-6:ctx-89b1442f) (logid:0efc40b2) HA health check
task is running...
2022-08-29 17:01:25,698 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-5:ctx-62313d05) (logid:7073663f) HA health check
task is running...
2022-08-29 17:01:25,767 DEBUG [c.c.s.StatsCollector]
(secstorage-1:ctx-c80e5a6e) (logid:f8e3eb60) Verifying image storage [1].
Capacity: total=[1 TB], used=[828 GB], threshold=[100.0%].
2022-08-29 17:01:25,773 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-c80e5a6e) (logid:f8e3eb60) Zone [1] is ready to launch
secondary storage VM.
2022-08-29 17:01:26,031 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Zone 1 is ready to launch
console proxy
2022-08-29 17:01:26,031 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Expand console proxy standby
capacity for zone xxxxxxxxxx
2022-08-29 17:01:26,031 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Allocating console proxy
standby capacity for zone [1].
2022-08-29 17:01:26,032 INFO  [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) No stopped console proxy is
available, need to allocate a new console proxy
2022-08-29 17:01:26,033 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Assign console proxy from a
newly started instance for request from data center : 1
2022-08-29 17:01:26,056 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Found existing network
configuration for offering [Network Offering
[1-Public-System-Public-Network]: Network {"id": 200, "name": "null",
"uuid": "1b0bf965-a391-478d-833d-3e37e4a15eb8", "networkofferingid": 1}
2022-08-29 17:01:26,056 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Releasing lock for
Acct[60bddbd5-1d8a-11ec-83ce-525400c9c662-system] -- Account {"id": 1,
"name": "system", "uuid": "60bddbd5-1d8a-11ec-83ce-525400c9c662"}
2022-08-29 17:01:26,064 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Found existing network
configuration for offering [Network Offering
[3-Control-System-Control-Network]: Network {"id": 202, "name": "null",
"uuid": "2af42518-fbf4-4a35-9d6b-370e6ad315c7", "networkofferingid": 3}
2022-08-29 17:01:26,064 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Releasing lock for
Acct[60bddbd5-1d8a-11ec-83ce-525400c9c662-system] -- Account {"id": 1,
"name": "system", "uuid": "60bddbd5-1d8a-11ec-83ce-525400c9c662"}
2022-08-29 17:01:26,069 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Found existing network
configuration for offering [Network Offering
[2-Management-System-Management-Network]: Network {"id": 201, "name":
"null", "uuid": "53711d87-a3c6-4f33-bfce-c30e0de72760",
"networkofferingid": 2}
2022-08-29 17:01:26,069 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Releasing lock for
Acct[60bddbd5-1d8a-11ec-83ce-525400c9c662-system] -- Account {"id": 1,
"name": "system", "uuid": "60bddbd5-1d8a-11ec-83ce-525400c9c662"}
2022-08-29 17:01:26,077 INFO  [c.c.v.VirtualMachineManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) allocating virtual machine
from template:c20799e4-a990-449a-aae6-4b67374c7aff with hostname:v-85-VM
and 3 networks
2022-08-29 17:01:26,079 DEBUG [c.c.v.VirtualMachineManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Allocating entries for VM:
VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"}
2022-08-29 17:01:26,082 DEBUG [c.c.v.VirtualMachineManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Allocating nics for VM
instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"}
2022-08-29 17:01:26,083 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Allocating nic for vm VM
instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} in network
Network {"id": 200, "name": "null", "uuid":
"1b0bf965-a391-478d-833d-3e37e4a15eb8", "networkofferingid": 1} with
requested profile NicProfile
{"broadcastUri":null,"iPv4Address":null,"id":0,"reservationId":null,"vmId":0}
2022-08-29 17:01:26,089 WARN  [c.c.n.IpAddressManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Unable to get ip address in
 zone id=1, vlanId id=[3, 10, 13, 14]
2022-08-29 17:01:26,090 DEBUG [c.c.u.d.T.Transaction]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Rolling back the
transaction: Time = 8 Name =  consoleproxy-1; called by
-TransactionLegacy.rollback:888-TransactionLegacy.removeUpTo:831-TransactionLegacy.close:655-Transaction.execute:38-IpAddressManagerImpl.listAvailablePublicIps:824-IpAddressManagerImpl.fetchNewPublicIp:811-IpAddressManagerImpl.fetchNewPublicIp:803-IpAddressManagerImpl.assignPublicIpAddress:784-PublicNetworkGuru.getIp:125-PublicNetworkGuru.allocate:172-NetworkOrchestrator.allocateNic:973-NetworkOrchestrator$3.addRequestedNicToNicListWithDeviceNumberAndRetrieveDefaultDevice:823
2022-08-29 17:01:26,090 WARN  [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Unable to allocate proxy
[Console VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"}] on zone [1]
due to [Insufficient address capacity].
com.cloud.exception.InsufficientAddressCapacityException: Insufficient
address capacityScope=interface com.cloud.dc.DataCenter; id=1
at
com.cloud.network.IpAddressManagerImpl$2.doInTransaction(IpAddressManagerImpl.java:950)
at
com.cloud.network.IpAddressManagerImpl$2.doInTransaction(IpAddressManagerImpl.java:824)
at com.cloud.utils.db.Transaction.execute(Transaction.java:40)
at
com.cloud.network.IpAddressManagerImpl.listAvailablePublicIps(IpAddressManagerImpl.java:824)
at
com.cloud.network.IpAddressManagerImpl.fetchNewPublicIp(IpAddressManagerImpl.java:811)
at
com.cloud.network.IpAddressManagerImpl.fetchNewPublicIp(IpAddressManagerImpl.java:803)
at
com.cloud.network.IpAddressManagerImpl.assignPublicIpAddress(IpAddressManagerImpl.java:784)
at
com.cloud.network.guru.PublicNetworkGuru.getIp(PublicNetworkGuru.java:125)
at
com.cloud.network.guru.PublicNetworkGuru.allocate(PublicNetworkGuru.java:172)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.allocateNic(NetworkOrchestrator.java:973)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator$3.addRequestedNicToNicListWithDeviceNumberAndRetrieveDefaultDevice(NetworkOrchestrator.java:823)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator$3.doInTransactionWithoutResult(NetworkOrchestrator.java:797)
at
com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTransaction(TransactionCallbackWithExceptionNoReturn.java:25)
at
com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTransaction(TransactionCallbackWithExceptionNoReturn.java:21)
at com.cloud.utils.db.Transaction.execute(Transaction.java:40)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.allocate(NetworkOrchestrator.java:778)
at
com.cloud.vm.VirtualMachineManagerImpl$1.doInTransactionWithoutResult(VirtualMachineManagerImpl.java:478)
at
com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTransaction(TransactionCallbackWithExceptionNoReturn.java:25)
at
com.cloud.utils.db.TransactionCallbackWithExceptionNoReturn.doInTransaction(TransactionCallbackWithExceptionNoReturn.java:21)
at com.cloud.utils.db.Transaction.execute(Transaction.java:40)
at
com.cloud.vm.VirtualMachineManagerImpl.allocate(VirtualMachineManagerImpl.java:469)
at
com.cloud.vm.VirtualMachineManagerImpl.allocate(VirtualMachineManagerImpl.java:528)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.createProxyInstance(ConsoleProxyManagerImpl.java:700)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.startNew(ConsoleProxyManagerImpl.java:572)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:809)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1537)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:167)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:121)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:91)
at
com.cloud.vm.SystemVmLoadScanner$1.runInContext(SystemVmLoadScanner.java:82)
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
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at
java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
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)
2022-08-29 17:01:26,091 WARN  [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Unable to allocate console
proxy standby capacity for zone [1] due to [Unable to allocate proxy
[Console VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"}] on zone [1]
due to [Insufficient address capacity].].
com.cloud.utils.exception.CloudRuntimeException: Unable to allocate proxy
[Console VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"}] on zone [1]
due to [Insufficient address capacity].
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.createProxyInstance(ConsoleProxyManagerImpl.java:704)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.startNew(ConsoleProxyManagerImpl.java:572)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:809)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1537)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:167)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:121)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:91)
at
com.cloud.vm.SystemVmLoadScanner$1.runInContext(SystemVmLoadScanner.java:82)
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
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at
java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
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)
Caused by: com.cloud.exception.InsufficientAddressCapacityException:
Insufficient address capacityScope=interface com.cloud.dc.DataCenter; id=1
at
com.cloud.network.IpAddressManagerImpl$2.doInTransaction(IpAddressManagerImpl.java:950)
at
com.cloud.network.IpAddressManagerImpl$2.doInTransaction(IpAddressManagerImpl.java:824)
at com.cloud.utils.db.Transaction.execute(Transaction.java:40)
... 38 more
2022-08-29 17:01:26,091 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) received console proxy alert
2022-08-29 17:01:26,092 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Console proxy creation
failure, zone: xxxxxxxxxx
2022-08-29 17:01:26,093 WARN  [c.c.a.AlertManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) alertType=[10]
dataCenterId=[1] podId=[null] clusterId=[null] message=[Console proxy
creation failure. zone: xxxxxxxxxx, error details: Unable to allocate proxy
[Console VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"}] on zone [1]
due to [Insufficient address capacity].].
2022-08-29 17:01:26,096 WARN  [c.c.a.AlertManagerImpl]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) No recipients set in global
setting 'alert.email.addresses', skipping sending alert with subject
[Console proxy creation failure. zone: xxxxxxxxxx, error details: Unable to
allocate proxy [Console VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"}] on zone [1]
due to [Insufficient address capacity].] and content [Console proxy
creation failure (zone xxxxxxxxxx)].
2022-08-29 17:01:26,096 WARN  [c.c.v.SystemVmLoadScanner]
(consoleproxy-1:ctx-2d236928) (logid:dcfe0999) Unexpected exception Unable
to allocate proxy [Console VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"}] on zone [1]
due to [Insufficient address capacity].
com.cloud.utils.exception.CloudRuntimeException: Unable to allocate proxy
[Console VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"}] on zone [1]
due to [Insufficient address capacity].
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.createProxyInstance(ConsoleProxyManagerImpl.java:704)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.startNew(ConsoleProxyManagerImpl.java:572)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:809)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1537)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:167)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:121)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:91)
at
com.cloud.vm.SystemVmLoadScanner$1.runInContext(SystemVmLoadScanner.java:82)
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
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at
java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
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)
Caused by: com.cloud.exception.InsufficientAddressCapacityException:
Insufficient address capacityScope=interface com.cloud.dc.DataCenter; id=1
at
com.cloud.network.IpAddressManagerImpl$2.doInTransaction(IpAddressManagerImpl.java:950)
at
com.cloud.network.IpAddressManagerImpl$2.doInTransaction(IpAddressManagerImpl.java:824)
at com.cloud.utils.db.Transaction.execute(Transaction.java:40)
... 38 more
2022-08-29 17:01:29,700 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-5:ctx-994465bd) (logid:1e2822fd) HA health check
task is running...
2022-08-29 17:01:30,444 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-e502832a) (logid:9f124ba7) Found 2 routers to
update status.
2022-08-29 17:01:30,449 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-e502832a) (logid:9f124ba7) Found 1 VPC's to
update Redundant State.
2022-08-29 17:01:30,451 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-e502832a) (logid:9f124ba7) Found 0 networks to
update RvR status.
2022-08-29 17:01:30,459 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-7:ctx-e3616662) (logid:2b499e08) Seq
6-4833769775052102463: Sending  { Cmd , MgmtId: 90520740759984, via:
6(srv-3-comp.aaaaaaaa.bbb), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CheckRouterCommand":{"accessDetails":{"router.name":"r-79-VM","router.ip":"169.254.144.198"},"wait":"30","bypassHostMaintenance":"false"}}]
}
2022-08-29 17:01:30,643 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-12:null) (logid:) Seq 6-4833769775052102463:
Processing:  { Ans: , MgmtId: 90520740759984, via: 6, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.CheckRouterAnswer":{"state":"PRIMARY","result":"true","details":"Status:
PRIMARY
","wait":"0","bypassHostMaintenance":"false"}}] }
2022-08-29 17:01:30,643 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-7:ctx-e3616662) (logid:2b499e08) Seq
6-4833769775052102463: Received:  { Ans: , MgmtId: 90520740759984, via:
6(srv-3-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { CheckRouterAnswer } }
2022-08-29 17:01:30,643 DEBUG [c.c.a.m.AgentManagerImpl]
(RedundantRouterStatusMonitor-7:ctx-e3616662) (logid:2b499e08) Details from
executing class com.cloud.agent.api.CheckRouterCommand: Status: PRIMARY

2022-08-29 17:01:30,655 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-7:ctx-e3616662) (logid:2b499e08) Seq
1-5410793477308947401: Sending  { Cmd , MgmtId: 90520740759984, via:
1(srv-2-comp.aaaaaaaa.bbb), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CheckRouterCommand":{"accessDetails":{"router.name":"r-80-VM","router.ip":"169.254.217.200"},"wait":"30","bypassHostMaintenance":"false"}}]
}
2022-08-29 17:01:30,796 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-7:null) (logid:) Seq 1-5410793477308947401:
Processing:  { Ans: , MgmtId: 90520740759984, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.CheckRouterAnswer":{"state":"BACKUP","result":"true","details":"Status:
BACKUP
","wait":"0","bypassHostMaintenance":"false"}}] }
2022-08-29 17:01:30,796 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-7:ctx-e3616662) (logid:2b499e08) Seq
1-5410793477308947401: Received:  { Ans: , MgmtId: 90520740759984, via:
1(srv-2-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { CheckRouterAnswer } }
2022-08-29 17:01:30,796 DEBUG [c.c.a.m.AgentManagerImpl]
(RedundantRouterStatusMonitor-7:ctx-e3616662) (logid:2b499e08) Details from
executing class com.cloud.agent.api.CheckRouterCommand: Status: BACKUP

2022-08-29 17:01:33,703 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-5:ctx-70bca202) (logid:b332dbe0) HA health check
task is running...
2022-08-29 17:01:34,083 DEBUG [c.c.s.StatsCollector]
(StatsCollector-6:ctx-213e2ecc) (logid:aa0584c9) AutoScaling Monitor is
running...
2022-08-29 17:01:37,707 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-6:ctx-57493517) (logid:5093e75f) HA health check
task is running...
2022-08-29 17:01:38,640 DEBUG [c.c.s.StatsCollector]
(StatsCollector-3:ctx-b503d899) (logid:bcbb4f5c) HostStatsCollector is
running...
2022-08-29 17:01:38,655 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-b503d899) (logid:bcbb4f5c) Seq 1-5410793477308947402:
Received:  { Ans: , MgmtId: 90520740759984, via:
1(srv-2-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2022-08-29 17:01:38,707 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-b503d899) (logid:bcbb4f5c) Seq 5-8959067033723473395:
Received:  { Ans: , MgmtId: 90520740759984, via:
5(srv-4-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2022-08-29 17:01:38,717 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-b503d899) (logid:bcbb4f5c) Seq 6-4833769775052102464:
Received:  { Ans: , MgmtId: 90520740759984, via:
6(srv-3-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2022-08-29 17:01:38,725 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-b503d899) (logid:bcbb4f5c) Seq 7-295548725546192472:
Received:  { Ans: , MgmtId: 90520740759984, via:
7(srv-5-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2022-08-29 17:01:41,709 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-5:ctx-a65ae462) (logid:bc2b7320) HA health check
task is running...
2022-08-29 17:01:45,712 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-2:ctx-05491ace) (logid:b2232c4d) HA health check
task is running...
2022-08-29 17:01:47,019 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-14:null) (logid:) Ping from Routing host
7(srv-5-comp.aaaaaaaa.bbb)

2022-08-29 17:01:49,715 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-2:ctx-7943581c) (logid:504c98ff) HA health check
task is running...
2022-08-29 17:01:51,881 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-13:null) (logid:) Ping from Routing host
1(srv-2-comp.aaaaaaaa.bbb)

2022-08-29 17:01:53,718 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-4:ctx-b11cfa22) (logid:3163613f) HA health check
task is running...
2022-08-29 17:01:53,955 DEBUG [c.c.a.t.Request]
(StatsCollector-4:ctx-c883ff8a) (logid:071b02e7) Seq 1-5410793477308947403:
Received:  { Ans: , MgmtId: 90520740759984, via:
1(srv-2-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2022-08-29 17:01:54,025 DEBUG [c.c.a.t.Request]
(StatsCollector-4:ctx-c883ff8a) (logid:071b02e7) Seq 5-8959067033723473396:
Received:  { Ans: , MgmtId: 90520740759984, via:
5(srv-4-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2022-08-29 17:01:54,096 DEBUG [c.c.a.t.Request]
(StatsCollector-4:ctx-c883ff8a) (logid:071b02e7) Seq 6-4833769775052102465:
Received:  { Ans: , MgmtId: 90520740759984, via:
6(srv-3-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2022-08-29 17:01:54,217 DEBUG [c.c.a.t.Request]
(StatsCollector-4:ctx-c883ff8a) (logid:071b02e7) Seq 7-295548725546192473:
Received:  { Ans: , MgmtId: 90520740759984, via:
7(srv-5-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2022-08-29 17:01:55,765 DEBUG [c.c.s.StatsCollector]
(secstorage-1:ctx-7d9995d7) (logid:e388a8b8) Verifying image storage [1].
Capacity: total=[1 TB], used=[828 GB], threshold=[100.0%].
2022-08-29 17:01:55,771 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-7d9995d7) (logid:e388a8b8) Zone [1] is ready to launch
secondary storage VM.
2022-08-29 17:01:56,033 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) Zone 1 is ready to launch
console proxy
2022-08-29 17:01:56,033 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) Expand console proxy standby
capacity for zone xxxxxxxxxx
2022-08-29 17:01:56,033 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) Allocating console proxy
standby capacity for zone [1].
2022-08-29 17:01:56,034 INFO  [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) Found a stopped console
proxy, starting it. Vm id : 85
2022-08-29 17:01:56,035 DEBUG [c.c.v.VirtualMachineManagerImpl]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) start parameter value of
enterHardwareSetup == <very null> during processing of queued job
2022-08-29 17:01:56,044 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) Sync job-4288 execution on
object VmWorkJobQueue.85
2022-08-29 17:01:56,173 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-e75826b1) (logid:e80fe659) Execute sync-queue
item: SyncQueueItemVO {id:2105, queueId: 2105, contentType: AsyncJob,
contentId: 4288, lastProcessMsid: 90520740759984, lastprocessNumber: 1,
lastProcessTime: Mon Aug 29 17:01:56 CEST 2022, created: Mon Aug 29
17:01:56 CEST 2022}
2022-08-29 17:01:56,174 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-e75826b1) (logid:e80fe659) Schedule queued
job-4288
2022-08-29 17:01:56,179 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288) (logid:7e671dd0) Add
job-4288 into job monitoring
2022-08-29 17:01:56,186 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288) (logid:ba10fec5)
Executing AsyncJobVO: {id:4288, userId: 1, accountId: 1, instanceType:
null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAVXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 90520740759984, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Aug 29 17:01:56 CEST 2022, removed:
null}
2022-08-29 17:01:56,186 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288) (logid:ba10fec5) Run
VM work job: com.cloud.vm.VmWorkStart for VM 85, job origin: 3445
2022-08-29 17:01:56,187 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":85,"handlerName":"VirtualMachineManagerImpl"}
2022-08-29 17:01:56,189 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) orchestrating VM start for 'v-85-VM'
com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d set to null
2022-08-29 17:01:56,196 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} state
transited from [Stopped] to [Starting] with event [StartRequested]. VM's
original host: null, new host: null, host before state transition: null
2022-08-29 17:01:56,196 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Successfully transitioned to start state for VM instance
{id: "85", name: "v-85-VM", uuid: "110d8620-c029-4ca9-9084-210099725a80",
type="ConsoleProxy"} reservation id = 0ab68202-d8be-469c-9b2a-87a55c2dc489
2022-08-29 17:01:56,200 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Deploy avoids pods: null, clusters: null, hosts: null
2022-08-29 17:01:56,202 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) VM start attempt #1
2022-08-29 17:01:56,203 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) DeploymentPlanner allocation algorithm: null
2022-08-29 17:01:56,203 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 500, requested ram: (1.00 GB)
1073741824
2022-08-29 17:01:56,203 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Is ROOT volume READY (pool already allocated)?: No
2022-08-29 17:01:56,212 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Deploy avoids pods: [], clusters: [], hosts: null
2022-08-29 17:01:56,214 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Searching all possible resources under this Zone: 1
2022-08-29 17:01:56,215 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Listing clusters in order of aggregate capacity, that have
(at least one host with) enough CPU and RAM capacity under this Zone: 1
2022-08-29 17:01:56,218 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Removing from the clusterId list these clusters from avoid
set: []
2022-08-29 17:01:56,224 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Checking resources in Cluster: 1 under Pod: 1
2022-08-29 17:01:56,225 INFO  [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5)  Guest VM is requested with
Custom[UEFI] Boot Type false
2022-08-29 17:01:56,225 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Looking for hosts in dc: 1
 pod:1  cluster:1
2022-08-29 17:01:56,226 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) FirstFitAllocator has 4 hosts to
check for allocation: [Host {"id": "5", "name": "srv-4-comp.aaaaaaaa.bbb",
"uuid": "134c625d-15ab-461a-a38d-36fb0b979b5d", "type"="Routing"}, Host
{"id": "7", "name": "srv-5-comp.aaaaaaaa.bbb", "uuid":
"8c753ce1-0253-49c9-9c7f-1f971a719ce6", "type"="Routing"}, Host {"id": "6",
"name": "srv-3-comp.aaaaaaaa.bbb", "uuid":
"6858713b-7e17-46d8-854d-24a13f9c7001", "type"="Routing"}, Host {"id": "1",
"name": "srv-2-comp.aaaaaaaa.bbb", "uuid":
"883f7f62-55f2-42f4-8242-16b6847c4204", "type"="Routing"}]
2022-08-29 17:01:56,232 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Found 4 hosts for allocation
after prioritization: [Host {"id": "5", "name": "srv-4-comp.aaaaaaaa.bbb",
"uuid": "134c625d-15ab-461a-a38d-36fb0b979b5d", "type"="Routing"}, Host
{"id": "7", "name": "srv-5-comp.aaaaaaaa.bbb", "uuid":
"8c753ce1-0253-49c9-9c7f-1f971a719ce6", "type"="Routing"}, Host {"id": "6",
"name": "srv-3-comp.aaaaaaaa.bbb", "uuid":
"6858713b-7e17-46d8-854d-24a13f9c7001", "type"="Routing"}, Host {"id": "1",
"name": "srv-2-comp.aaaaaaaa.bbb", "uuid":
"883f7f62-55f2-42f4-8242-16b6847c4204", "type"="Routing"}]
2022-08-29 17:01:56,232 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Looking for speed=500Mhz,
Ram=1024 MB
2022-08-29 17:01:56,232 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 5, name:
srv-4-comp.aaaaaaaa.bbb, uuid: 134c625d-15ab-461a-a38d-36fb0b979b5d} is KVM
hypervisor type, no max guest limit check needed
2022-08-29 17:01:56,234 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host: 5 has cpu capability
(cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
2022-08-29 17:01:56,234 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 5 has enough
capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
cpuOverprovisioningFactor: 1.0
2022-08-29 17:01:56,235 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
and CPU after applying overprovisioning: 127200
2022-08-29 17:01:56,235 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 116100 , Requested
CPU: 500
2022-08-29 17:01:56,235 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (233.77 GB)
251009040384 , Requested RAM: (1.00 GB) 1073741824
2022-08-29 17:01:56,235 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
available
2022-08-29 17:01:56,235 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
5, used: 11100, reserved: 0, actual total: 127200, total with
overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2022-08-29 17:01:56,235 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
5, used: (16.50 GB) 17716740096, reserved: (0 bytes) 0, total: (250.27 GB)
268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
false , considerReservedCapacity?: true
2022-08-29 17:01:56,235 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
list: 5
2022-08-29 17:01:56,235 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 7, name:
srv-5-comp.aaaaaaaa.bbb, uuid: 8c753ce1-0253-49c9-9c7f-1f971a719ce6} is KVM
hypervisor type, no max guest limit check needed
2022-08-29 17:01:56,238 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host: 7 has cpu capability
(cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
2022-08-29 17:01:56,238 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 7 has enough
capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
cpuOverprovisioningFactor: 1.0
2022-08-29 17:01:56,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
and CPU after applying overprovisioning: 127200
2022-08-29 17:01:56,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 37100 , Requested CPU:
500
2022-08-29 17:01:56,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (176.37 GB)
189373743104 , Requested RAM: (1.00 GB) 1073741824
2022-08-29 17:01:56,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
available
2022-08-29 17:01:56,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
7, used: 90100, reserved: 0, actual total: 127200, total with
overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2022-08-29 17:01:56,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
7, used: (73.90 GB) 79352037376, reserved: (0 bytes) 0, total: (250.27 GB)
268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
false , considerReservedCapacity?: true
2022-08-29 17:01:56,240 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
list: 7
2022-08-29 17:01:56,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 6, name:
srv-3-comp.aaaaaaaa.bbb, uuid: 6858713b-7e17-46d8-854d-24a13f9c7001} is KVM
hypervisor type, no max guest limit check needed
2022-08-29 17:01:56,242 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host: 6 has cpu capability
(cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
2022-08-29 17:01:56,242 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 6 has enough
capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
cpuOverprovisioningFactor: 1.0
2022-08-29 17:01:56,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
and CPU after applying overprovisioning: 127200
2022-08-29 17:01:56,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 84300 , Requested CPU:
500
2022-08-29 17:01:56,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (190.02 GB)
204032835584 , Requested RAM: (1.00 GB) 1073741824
2022-08-29 17:01:56,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
available
2022-08-29 17:01:56,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
6, used: 42900, reserved: 0, actual total: 127200, total with
overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2022-08-29 17:01:56,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
6, used: (60.25 GB) 64692944896, reserved: (0 bytes) 0, total: (250.27 GB)
268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
false , considerReservedCapacity?: true
2022-08-29 17:01:56,244 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
list: 6
2022-08-29 17:01:56,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 1, name:
srv-2-comp.aaaaaaaa.bbb, uuid: 883f7f62-55f2-42f4-8242-16b6847c4204} is KVM
hypervisor type, no max guest limit check needed
2022-08-29 17:01:56,246 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host: 1 has cpu capability
(cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
2022-08-29 17:01:56,246 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 1 has enough
capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
cpuOverprovisioningFactor: 1.0
2022-08-29 17:01:56,247 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
and CPU after applying overprovisioning: 127200
2022-08-29 17:01:56,247 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 79000 , Requested CPU:
500
2022-08-29 17:01:56,247 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (214.02 GB)
229802639360 , Requested RAM: (1.00 GB) 1073741824
2022-08-29 17:01:56,247 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
available
2022-08-29 17:01:56,247 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
1, used: 48200, reserved: 0, actual total: 127200, total with
overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2022-08-29 17:01:56,247 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
1, used: (36.25 GB) 38923141120, reserved: (0 bytes) 0, total: (250.27 GB)
268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
false , considerReservedCapacity?: true
2022-08-29 17:01:56,247 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
list: 1
2022-08-29 17:01:56,247 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a
FirstFitRoutingAllocator) (logid:ba10fec5) Host Allocator returning 4
suitable hosts
2022-08-29 17:01:56,258 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} state
transited from [Starting] to [Stopped] with event [OperationFailed]. VM's
original host: null, new host: null, host before state transition: null
2022-08-29 17:01:56,258 WARN  [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Unable to orchestrate start VM instance {id: "85", name:
"v-85-VM", uuid: "110d8620-c029-4ca9-9084-210099725a80",
type="ConsoleProxy"} due to [Unable to create deployment, no usable volumes
found for the VM: 85].
com.cloud.utils.exception.CloudRuntimeException: Unable to create
deployment, no usable volumes found for the VM: 85
at
com.cloud.deploy.DeploymentPlanningManagerImpl.findSuitablePoolsForVolumes(DeploymentPlanningManagerImpl.java:1569)
at
com.cloud.deploy.DeploymentPlanningManagerImpl.checkClustersforDestination(DeploymentPlanningManagerImpl.java:1217)
at
com.cloud.deploy.DeploymentPlanningManagerImpl.planDeployment(DeploymentPlanningManagerImpl.java:527)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1126)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5315)
at jdk.internal.reflect.GeneratedMethodAccessor945.invoke(Unknown Source)
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:5439)
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)
2022-08-29 17:01:56,259 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Done executing VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":85,"handlerName":"VirtualMachineManagerImpl"}
2022-08-29 17:01:56,260 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Complete async job-4288, jobStatus: FAILED, resultCode: 0,
result:
rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0ANRVbmFibGUgdG8gb3JjaGVzdHJhdGUgc3RhcnQgVk0gaW5zdGFuY2Uge2lkOiAiODUiLCBuYW1lOiAidi04NS1WTSIsIHV1aWQ6ICIxMTBkODYyMC1jMDI5LTRjYTktOTA4NC0yMTAwOTk3MjVhODAiLCB0eXBlPSJDb25zb2xlUHJveHkifSBkdWUgdG8gW1VuYWJsZSB0byBjcmVhdGUgZGVwbG95bWVudCwgbm8gdXNhYmxlIHZvbHVtZXMgZm91bmQgZm9yIHRoZSBWTTogODVdLnVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAE3NyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ABUwADmRlY2xhcmluZ0NsYXNzcQB-AAVMAAhmaWxlTmFtZXEAfgAFTAAKbWV0aG9kTmFtZXEAfgAFTAAKbW9kdWxlTmFtZXEAfgAFTAANbW9kdWxlVmVyc2lvbnEAfgAFeHABAAAUx3QAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHBwc3EAfgAMAP____9wdAAvamRrLmludGVybmFsLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3I5NDVwdAAGaW52b2tlcHBzcQB-AAwCAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABR0AAlqYXZhLmJhc2V0AAcxMS4wLjE2c3EAfgAMAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AFHEAfgAYcQB-ABlzcQB-AAwBAAAAa3EAfgAOdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-AAwBAAAVP3EAfgAOcQB-AA9xAH4AEHEAfgAgcHBzcQB-AAwBAAAAZnEAfgAOdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4ADAEAAAJscQB-AA50AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4ADAEAAAAwcQB-AA50AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgAMAQAAADdxAH4ADnQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgAMAQAAAGZxAH4ADnQAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AMHQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgAMAQAAADRxAH4ADnEAfgAzcQB-ADB0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgAMAQAAAC1xAH4ADnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAscQB-AC1wcHNxAH4ADAEAAAI4cQB-AA5xAH4AJ3EAfgAocQB-AC1wcHNxAH4ADAIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAxcQB-ABhxAH4AGXNxAH4ADAIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4ALXEAfgAYcQB-ABlzcQB-AAwCAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAYcQB-ABlzcQB-AAwCAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEJxAH4ALXEAfgAYcQB-ABlzcQB-AAwCAAADPXB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4ALXEAfgAYcQB-ABlzcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4AAAQmncIAAAAAAAAAAB4
2022-08-29 17:01:56,261 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Publish async job-4288 complete on message bus
2022-08-29 17:01:56,261 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Wake up jobs related to job-4288
2022-08-29 17:01:56,261 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Update db status for job-4288
2022-08-29 17:01:56,262 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288 ctx-2852a95a)
(logid:ba10fec5) Wake up jobs joined with job-4288 and disjoin all subjobs
created from job- 4288
2022-08-29 17:01:56,270 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288) (logid:ba10fec5)
Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 85, job
origin: 3445
2022-08-29 17:01:56,270 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288) (logid:ba10fec5)
Done executing com.cloud.vm.VmWorkStart for job-4288
2022-08-29 17:01:56,272 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-139:ctx-26560f3a job-3445/job-4288) (logid:ba10fec5)
Remove job-4288 from job monitoring
2022-08-29 17:01:56,277 WARN  [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) Unable to allocate console
proxy standby capacity for zone [1] due to [Unable to orchestrate start VM
instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} due to [Unable
to create deployment, no usable volumes found for the VM: 85].].
com.cloud.utils.exception.CloudRuntimeException: Unable to orchestrate
start VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} due to [Unable
to create deployment, no usable volumes found for the VM: 85].
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5319)
at jdk.internal.reflect.GeneratedMethodAccessor945.invoke(Unknown Source)
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:5439)
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)
2022-08-29 17:01:56,277 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) received console proxy alert
2022-08-29 17:01:56,278 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) Console proxy creation
failure, zone: xxxxxxxxxx
2022-08-29 17:01:56,279 WARN  [c.c.a.AlertManagerImpl]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) alertType=[10]
dataCenterId=[1] podId=[null] clusterId=[null] message=[Console proxy
creation failure. zone: xxxxxxxxxx, error details: Unable to orchestrate
start VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} due to [Unable
to create deployment, no usable volumes found for the VM: 85].].
2022-08-29 17:01:56,284 WARN  [c.c.a.AlertManagerImpl]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) No recipients set in global
setting 'alert.email.addresses', skipping sending alert with subject
[Console proxy creation failure. zone: xxxxxxxxxx, error details: Unable to
orchestrate start VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} due to [Unable
to create deployment, no usable volumes found for the VM: 85].] and content
[Console proxy creation failure (zone xxxxxxxxxx)].
2022-08-29 17:01:56,284 WARN  [c.c.v.SystemVmLoadScanner]
(consoleproxy-1:ctx-413f712d) (logid:440fd101) Unexpected exception Unable
to orchestrate start VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} due to [Unable
to create deployment, no usable volumes found for the VM: 85].
com.cloud.utils.exception.CloudRuntimeException: Unable to orchestrate
start VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} due to [Unable
to create deployment, no usable volumes found for the VM: 85].
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5319)
at jdk.internal.reflect.GeneratedMethodAccessor945.invoke(Unknown Source)
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:5439)
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)
2022-08-29 17:01:57,721 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-4:ctx-9528226f) (logid:4512ff9b) HA health check
task is running...
2022-08-29 17:01:59,504 DEBUG [c.c.s.StatsCollector]
(StatsCollector-2:ctx-67cb5761) (logid:0cd67bc8) StorageCollector is
running...
2022-08-29 17:01:59,518 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-2:ctx-67cb5761) (logid:0cd67bc8) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2022-08-29 17:01:59,518 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-2:ctx-67cb5761) (logid:0cd67bc8) We are returning the
default host to execute commands because the command is not of Copy type.
2022-08-29 17:01:59,571 DEBUG [c.c.a.t.Request]
(StatsCollector-2:ctx-67cb5761) (logid:0cd67bc8) Seq
11-7523826127475836583: Received:  { Ans: , MgmtId: 90520740759984, via:
11(s-32-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2022-08-29 17:01:59,574 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-2:ctx-67cb5761) (logid:0cd67bc8) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2022-08-29 17:01:59,574 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-2:ctx-67cb5761) (logid:0cd67bc8) We are returning the
default host to execute commands because the command is not of Copy type.
2022-08-29 17:01:59,615 DEBUG [c.c.a.t.Request]
(StatsCollector-2:ctx-67cb5761) (logid:0cd67bc8) Seq 5-8959067033723473397:
Received:  { Ans: , MgmtId: 90520740759984, via:
5(srv-4-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2022-08-29 17:01:59,624 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-2:ctx-67cb5761) (logid:0cd67bc8) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2022-08-29 17:01:59,624 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-2:ctx-67cb5761) (logid:0cd67bc8) We are returning the
default host to execute commands because the command is not of Copy type.
2022-08-29 17:01:59,653 DEBUG [c.c.a.t.Request]
(StatsCollector-2:ctx-67cb5761) (logid:0cd67bc8) Seq 6-4833769775052102466:
Received:  { Ans: , MgmtId: 90520740759984, via:
6(srv-3-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2022-08-29 17:01:59,979 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) (logid:) Ping from Routing host
5(srv-4-comp.aaaaaaaa.bbb)

2022-08-29 17:02:00,269 DEBUG [c.c.s.StatsCollector]
(StatsCollector-5:ctx-d2b6ffd3) (logid:95201678) DbCollector is running...
2022-08-29 17:02:00,443 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-10041d6f) (logid:9c8fd7f4) Found 2 routers to
update status.
2022-08-29 17:02:00,449 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-10041d6f) (logid:9c8fd7f4) Found 1 VPC's to
update Redundant State.
2022-08-29 17:02:00,450 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-10041d6f) (logid:9c8fd7f4) Found 0 networks to
update RvR status.
2022-08-29 17:02:00,457 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-10:ctx-09a24dce) (logid:da20227f) Seq
6-4833769775052102467: Sending  { Cmd , MgmtId: 90520740759984, via:
6(srv-3-comp.aaaaaaaa.bbb), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CheckRouterCommand":{"accessDetails":{"router.name":"r-79-VM","router.ip":"169.254.144.198"},"wait":"30","bypassHostMaintenance":"false"}}]
}
2022-08-29 17:02:00,599 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-7:null) (logid:) Seq 6-4833769775052102467:
Processing:  { Ans: , MgmtId: 90520740759984, via: 6, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.CheckRouterAnswer":{"state":"PRIMARY","result":"true","details":"Status:
PRIMARY
","wait":"0","bypassHostMaintenance":"false"}}] }
2022-08-29 17:02:00,599 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-10:ctx-09a24dce) (logid:da20227f) Seq
6-4833769775052102467: Received:  { Ans: , MgmtId: 90520740759984, via:
6(srv-3-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { CheckRouterAnswer } }
2022-08-29 17:02:00,599 DEBUG [c.c.a.m.AgentManagerImpl]
(RedundantRouterStatusMonitor-10:ctx-09a24dce) (logid:da20227f) Details
from executing class com.cloud.agent.api.CheckRouterCommand: Status: PRIMARY

2022-08-29 17:02:00,612 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-10:ctx-09a24dce) (logid:da20227f) Seq
1-5410793477308947404: Sending  { Cmd , MgmtId: 90520740759984, via:
1(srv-2-comp.aaaaaaaa.bbb), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CheckRouterCommand":{"accessDetails":{"router.name":"r-80-VM","router.ip":"169.254.217.200"},"wait":"30","bypassHostMaintenance":"false"}}]
}
2022-08-29 17:02:00,748 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-4:null) (logid:) Ping from 11(s-32-VM)
2022-08-29 17:02:00,750 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-1:null) (logid:) Seq 1-5410793477308947404:
Processing:  { Ans: , MgmtId: 90520740759984, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.CheckRouterAnswer":{"state":"BACKUP","result":"true","details":"Status:
BACKUP
","wait":"0","bypassHostMaintenance":"false"}}] }
2022-08-29 17:02:00,750 DEBUG [c.c.a.t.Request]
(RedundantRouterStatusMonitor-10:ctx-09a24dce) (logid:da20227f) Seq
1-5410793477308947404: Received:  { Ans: , MgmtId: 90520740759984, via:
1(srv-2-comp.aaaaaaaa.bbb), Ver: v1, Flags: 10, { CheckRouterAnswer } }
2022-08-29 17:02:00,751 DEBUG [c.c.a.m.AgentManagerImpl]
(RedundantRouterStatusMonitor-10:ctx-09a24dce) (logid:da20227f) Details
from executing class com.cloud.agent.api.CheckRouterCommand: Status: BACKUP

2022-08-29 17:02:01,362 DEBUG [c.c.s.StatsCollector]
(Cluster-Worker-839:ctx-e097a8ab) (logid:3deacf65) StatusUpdate from
90520740759984, json:
{"managementServerHostId":1,"managementServerHostUuid":"5615ca5f-0716-4da1-93ec-31f79fd19bbe","collectionTime":"Aug
29, 2022, 5:02:01
PM","sessions":1,"cpuUtilization":0.0,"totalJvmMemoryBytes":324534272,"freeJvmMemoryBytes":68595424,"maxJvmMemoryBytes":1908932607,"processJvmMemoryBytes":0,"jvmUptime":103760388,"jvmStartTime":1661681560910,"availableProcessors":6,"loadAverage":0.02,"totalInit":139788288,"totalUsed":474791104,"totalCommitted":557662208,"pid":1522332,"jvmName":"1522...@vm-1-cs-mgmt.aaaaaaaa.bbb","jvmVendor":"Ubuntu","jvmVersion":"11.0.16+8-post-Ubuntu-0ubuntu120.04","osDistribution":"Ubuntu
20.04.5
LTS","agentCount":5,"heapMemoryUsed":256775312,"heapMemoryTotal":1908932608,"threadsBlockedCount":0,"threadsDaemonCount":13,"threadsRunnableCount":15,"threadsTerminatedCount":0,"threadsTotalCount":420,"threadsWaitingCount":331,"systemMemoryTotal":8343236608,"systemMemoryFree":2623193088,"systemMemoryUsed":814808,"systemMemoryVirtualSize":7494184960,"logInfo":"/var/log/cloudstack/management/management-server.log
using: 74M\non disk /dev/vda2 mounted on / (14%
full)","systemTotalCpuCycles":15870.180000000002,"systemLoadAverages":[0.02,0.03,0.0],"systemCyclesUsage":[4116569,2615101,2716460424],"dbLocal":false,"usageLocal":false,"systemBootTime":"Jul
8, 2022, 2:35:55 AM","kernelVersion":"5.4.0-121-generic"}
2022-08-29 17:02:01,723 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-4:ctx-7abb1b5d) (logid:2320950d) HA health check
task is running...
2022-08-29 17:02:05,417 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Vm-Operations-Cleanup-1:ctx-e741e208) (logid:3f5129e0) VM Operation Thread
Running
2022-08-29 17:02:05,725 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-4:ctx-8e7f6766) (logid:710cb3b2) HA health check
task is running...
2022-08-29 17:02:08,626 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-11:null) (logid:) Ping from Routing host
6(srv-3-comp.aaaaaaaa.bbb)

2022-08-29 17:02:09,727 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-4:ctx-26a5ff07) (logid:09b3c89a) HA health check
task is running...
2022-08-29 17:02:13,729 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-4:ctx-b4d4e374) (logid:9048c7a7) HA health check
task is running...
2022-08-29 17:02:17,731 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-4:ctx-3db3d208) (logid:7bb73f7b) HA health check
task is running...
2022-08-29 17:02:21,734 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-1:ctx-fca1d248) (logid:1ed5381a) HA health check
task is running...
2022-08-29 17:02:25,737 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-1:ctx-984e2382) (logid:e6c3d724) HA health check
task is running...
2022-08-29 17:02:25,759 DEBUG [c.c.s.StatsCollector]
(secstorage-1:ctx-64c610ed) (logid:6603cd38) Verifying image storage [1].
Capacity: total=[1 TB], used=[828 GB], threshold=[100.0%].
2022-08-29 17:02:25,763 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-64c610ed) (logid:6603cd38) Zone [1] is ready to launch
secondary storage VM.
2022-08-29 17:02:26,029 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-0d1bbbb1) (logid:452c90ec) Zone 1 is ready to launch
console proxy
2022-08-29 17:02:26,029 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-0d1bbbb1) (logid:452c90ec) Expand console proxy standby
capacity for zone xxxxxxxxxx
2022-08-29 17:02:26,029 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-0d1bbbb1) (logid:452c90ec) Allocating console proxy
standby capacity for zone [1].
2022-08-29 17:02:26,030 INFO  [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-0d1bbbb1) (logid:452c90ec) Found a stopped console
proxy, starting it. Vm id : 85
2022-08-29 17:02:26,031 DEBUG [c.c.v.VirtualMachineManagerImpl]
(consoleproxy-1:ctx-0d1bbbb1) (logid:452c90ec) start parameter value of
enterHardwareSetup == <very null> during processing of queued job
2022-08-29 17:02:26,037 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(consoleproxy-1:ctx-0d1bbbb1) (logid:452c90ec) Sync job-4289 execution on
object VmWorkJobQueue.85
2022-08-29 17:02:26,167 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-bba6b89d) (logid:f9aed0eb) Execute sync-queue
item: SyncQueueItemVO {id:2106, queueId: 2105, contentType: AsyncJob,
contentId: 4289, lastProcessMsid: 90520740759984, lastprocessNumber: 2,
lastProcessTime: Mon Aug 29 17:02:26 CEST 2022, created: Mon Aug 29
17:02:26 CEST 2022}
2022-08-29 17:02:26,167 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-bba6b89d) (logid:f9aed0eb) Schedule queued
job-4289
2022-08-29 17:02:26,172 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289) (logid:f919f9b3) Add
job-4289 into job monitoring
2022-08-29 17:02:26,181 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289) (logid:ba10fec5)
Executing AsyncJobVO: {id:4289, userId: 1, accountId: 1, instanceType:
null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAVXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 90520740759984, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Aug 29 17:02:26 CEST 2022, removed:
null}
2022-08-29 17:02:26,181 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289) (logid:ba10fec5) Run
VM work job: com.cloud.vm.VmWorkStart for VM 85, job origin: 3445
2022-08-29 17:02:26,183 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":85,"handlerName":"VirtualMachineManagerImpl"}
2022-08-29 17:02:26,184 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) orchestrating VM start for 'v-85-VM'
com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d set to null
2022-08-29 17:02:26,192 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} state
transited from [Stopped] to [Starting] with event [StartRequested]. VM's
original host: null, new host: null, host before state transition: null
2022-08-29 17:02:26,192 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Successfully transitioned to start state for VM instance
{id: "85", name: "v-85-VM", uuid: "110d8620-c029-4ca9-9084-210099725a80",
type="ConsoleProxy"} reservation id = 24bf955f-96d8-4f4f-ae33-2cae2f3e0425
2022-08-29 17:02:26,198 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Deploy avoids pods: null, clusters: null, hosts: null
2022-08-29 17:02:26,200 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) VM start attempt #1
2022-08-29 17:02:26,203 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) DeploymentPlanner allocation algorithm: null
2022-08-29 17:02:26,203 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 500, requested ram: (1.00 GB)
1073741824
2022-08-29 17:02:26,203 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Is ROOT volume READY (pool already allocated)?: No
2022-08-29 17:02:26,211 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Deploy avoids pods: [], clusters: [], hosts: null
2022-08-29 17:02:26,212 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Searching all possible resources under this Zone: 1
2022-08-29 17:02:26,213 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Listing clusters in order of aggregate capacity, that have
(at least one host with) enough CPU and RAM capacity under this Zone: 1
2022-08-29 17:02:26,216 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Removing from the clusterId list these clusters from avoid
set: []
2022-08-29 17:02:26,221 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Checking resources in Cluster: 1 under Pod: 1
2022-08-29 17:02:26,222 INFO  [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5)  Guest VM is requested with
Custom[UEFI] Boot Type false
2022-08-29 17:02:26,223 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Looking for hosts in dc: 1
 pod:1  cluster:1
2022-08-29 17:02:26,225 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) FirstFitAllocator has 4 hosts to
check for allocation: [Host {"id": "7", "name": "srv-5-comp.aaaaaaaa.bbb",
"uuid": "8c753ce1-0253-49c9-9c7f-1f971a719ce6", "type"="Routing"}, Host
{"id": "1", "name": "srv-2-comp.aaaaaaaa.bbb", "uuid":
"883f7f62-55f2-42f4-8242-16b6847c4204", "type"="Routing"}, Host {"id": "6",
"name": "srv-3-comp.aaaaaaaa.bbb", "uuid":
"6858713b-7e17-46d8-854d-24a13f9c7001", "type"="Routing"}, Host {"id": "5",
"name": "srv-4-comp.aaaaaaaa.bbb", "uuid":
"134c625d-15ab-461a-a38d-36fb0b979b5d", "type"="Routing"}]
2022-08-29 17:02:26,231 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Found 4 hosts for allocation
after prioritization: [Host {"id": "7", "name": "srv-5-comp.aaaaaaaa.bbb",
"uuid": "8c753ce1-0253-49c9-9c7f-1f971a719ce6", "type"="Routing"}, Host
{"id": "1", "name": "srv-2-comp.aaaaaaaa.bbb", "uuid":
"883f7f62-55f2-42f4-8242-16b6847c4204", "type"="Routing"}, Host {"id": "6",
"name": "srv-3-comp.aaaaaaaa.bbb", "uuid":
"6858713b-7e17-46d8-854d-24a13f9c7001", "type"="Routing"}, Host {"id": "5",
"name": "srv-4-comp.aaaaaaaa.bbb", "uuid":
"134c625d-15ab-461a-a38d-36fb0b979b5d", "type"="Routing"}]
2022-08-29 17:02:26,231 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Looking for speed=500Mhz,
Ram=1024 MB
2022-08-29 17:02:26,231 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 7, name:
srv-5-comp.aaaaaaaa.bbb, uuid: 8c753ce1-0253-49c9-9c7f-1f971a719ce6} is KVM
hypervisor type, no max guest limit check needed
2022-08-29 17:02:26,234 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host: 7 has cpu capability
(cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
2022-08-29 17:02:26,234 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 7 has enough
capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
cpuOverprovisioningFactor: 1.0
2022-08-29 17:02:26,236 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
and CPU after applying overprovisioning: 127200
2022-08-29 17:02:26,236 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 37100 , Requested CPU:
500
2022-08-29 17:02:26,236 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (176.37 GB)
189373743104 , Requested RAM: (1.00 GB) 1073741824
2022-08-29 17:02:26,236 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
available
2022-08-29 17:02:26,236 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
7, used: 90100, reserved: 0, actual total: 127200, total with
overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2022-08-29 17:02:26,236 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
7, used: (73.90 GB) 79352037376, reserved: (0 bytes) 0, total: (250.27 GB)
268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
false , considerReservedCapacity?: true
2022-08-29 17:02:26,236 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
list: 7
2022-08-29 17:02:26,236 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 1, name:
srv-2-comp.aaaaaaaa.bbb, uuid: 883f7f62-55f2-42f4-8242-16b6847c4204} is KVM
hypervisor type, no max guest limit check needed
2022-08-29 17:02:26,239 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host: 1 has cpu capability
(cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
2022-08-29 17:02:26,239 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 1 has enough
capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
cpuOverprovisioningFactor: 1.0
2022-08-29 17:02:26,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
and CPU after applying overprovisioning: 127200
2022-08-29 17:02:26,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 79000 , Requested CPU:
500
2022-08-29 17:02:26,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (214.02 GB)
229802639360 , Requested RAM: (1.00 GB) 1073741824
2022-08-29 17:02:26,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
available
2022-08-29 17:02:26,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
1, used: 48200, reserved: 0, actual total: 127200, total with
overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2022-08-29 17:02:26,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
1, used: (36.25 GB) 38923141120, reserved: (0 bytes) 0, total: (250.27 GB)
268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
false , considerReservedCapacity?: true
2022-08-29 17:02:26,240 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
list: 1
2022-08-29 17:02:26,240 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 6, name:
srv-3-comp.aaaaaaaa.bbb, uuid: 6858713b-7e17-46d8-854d-24a13f9c7001} is KVM
hypervisor type, no max guest limit check needed
2022-08-29 17:02:26,243 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host: 6 has cpu capability
(cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
2022-08-29 17:02:26,243 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 6 has enough
capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
cpuOverprovisioningFactor: 1.0
2022-08-29 17:02:26,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
and CPU after applying overprovisioning: 127200
2022-08-29 17:02:26,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 84300 , Requested CPU:
500
2022-08-29 17:02:26,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (190.02 GB)
204032835584 , Requested RAM: (1.00 GB) 1073741824
2022-08-29 17:02:26,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
available
2022-08-29 17:02:26,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
6, used: 42900, reserved: 0, actual total: 127200, total with
overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2022-08-29 17:02:26,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
6, used: (60.25 GB) 64692944896, reserved: (0 bytes) 0, total: (250.27 GB)
268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
false , considerReservedCapacity?: true
2022-08-29 17:02:26,244 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
list: 6
2022-08-29 17:02:26,244 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 5, name:
srv-4-comp.aaaaaaaa.bbb, uuid: 134c625d-15ab-461a-a38d-36fb0b979b5d} is KVM
hypervisor type, no max guest limit check needed
2022-08-29 17:02:26,247 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host: 5 has cpu capability
(cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
2022-08-29 17:02:26,247 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 5 has enough
capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
cpuOverprovisioningFactor: 1.0
2022-08-29 17:02:26,249 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
and CPU after applying overprovisioning: 127200
2022-08-29 17:02:26,249 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 116100 , Requested
CPU: 500
2022-08-29 17:02:26,249 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (233.77 GB)
251009040384 , Requested RAM: (1.00 GB) 1073741824
2022-08-29 17:02:26,249 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
available
2022-08-29 17:02:26,249 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
5, used: 11100, reserved: 0, actual total: 127200, total with
overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2022-08-29 17:02:26,249 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
5, used: (16.50 GB) 17716740096, reserved: (0 bytes) 0, total: (250.27 GB)
268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
false , considerReservedCapacity?: true
2022-08-29 17:02:26,249 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
list: 5
2022-08-29 17:02:26,249 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb
FirstFitRoutingAllocator) (logid:ba10fec5) Host Allocator returning 4
suitable hosts
2022-08-29 17:02:26,260 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} state
transited from [Starting] to [Stopped] with event [OperationFailed]. VM's
original host: null, new host: null, host before state transition: null
2022-08-29 17:02:26,260 WARN  [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Unable to orchestrate start VM instance {id: "85", name:
"v-85-VM", uuid: "110d8620-c029-4ca9-9084-210099725a80",
type="ConsoleProxy"} due to [Unable to create deployment, no usable volumes
found for the VM: 85].
com.cloud.utils.exception.CloudRuntimeException: Unable to create
deployment, no usable volumes found for the VM: 85
at
com.cloud.deploy.DeploymentPlanningManagerImpl.findSuitablePoolsForVolumes(DeploymentPlanningManagerImpl.java:1569)
at
com.cloud.deploy.DeploymentPlanningManagerImpl.checkClustersforDestination(DeploymentPlanningManagerImpl.java:1217)
at
com.cloud.deploy.DeploymentPlanningManagerImpl.planDeployment(DeploymentPlanningManagerImpl.java:527)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1126)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5315)
at jdk.internal.reflect.GeneratedMethodAccessor945.invoke(Unknown Source)
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:5439)
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)
2022-08-29 17:02:26,261 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Done executing VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":85,"handlerName":"VirtualMachineManagerImpl"}
2022-08-29 17:02:26,262 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Complete async job-4289, jobStatus: FAILED, resultCode: 0,
result:
rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0ANRVbmFibGUgdG8gb3JjaGVzdHJhdGUgc3RhcnQgVk0gaW5zdGFuY2Uge2lkOiAiODUiLCBuYW1lOiAidi04NS1WTSIsIHV1aWQ6ICIxMTBkODYyMC1jMDI5LTRjYTktOTA4NC0yMTAwOTk3MjVhODAiLCB0eXBlPSJDb25zb2xlUHJveHkifSBkdWUgdG8gW1VuYWJsZSB0byBjcmVhdGUgZGVwbG95bWVudCwgbm8gdXNhYmxlIHZvbHVtZXMgZm91bmQgZm9yIHRoZSBWTTogODVdLnVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAE3NyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ABUwADmRlY2xhcmluZ0NsYXNzcQB-AAVMAAhmaWxlTmFtZXEAfgAFTAAKbWV0aG9kTmFtZXEAfgAFTAAKbW9kdWxlTmFtZXEAfgAFTAANbW9kdWxlVmVyc2lvbnEAfgAFeHABAAAUx3QAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHBwc3EAfgAMAP____9wdAAvamRrLmludGVybmFsLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3I5NDVwdAAGaW52b2tlcHBzcQB-AAwCAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABR0AAlqYXZhLmJhc2V0AAcxMS4wLjE2c3EAfgAMAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AFHEAfgAYcQB-ABlzcQB-AAwBAAAAa3EAfgAOdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-AAwBAAAVP3EAfgAOcQB-AA9xAH4AEHEAfgAgcHBzcQB-AAwBAAAAZnEAfgAOdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4ADAEAAAJscQB-AA50AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4ADAEAAAAwcQB-AA50AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgAMAQAAADdxAH4ADnQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgAMAQAAAGZxAH4ADnQAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AMHQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgAMAQAAADRxAH4ADnEAfgAzcQB-ADB0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgAMAQAAAC1xAH4ADnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAscQB-AC1wcHNxAH4ADAEAAAI4cQB-AA5xAH4AJ3EAfgAocQB-AC1wcHNxAH4ADAIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAxcQB-ABhxAH4AGXNxAH4ADAIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4ALXEAfgAYcQB-ABlzcQB-AAwCAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAYcQB-ABlzcQB-AAwCAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEJxAH4ALXEAfgAYcQB-ABlzcQB-AAwCAAADPXB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4ALXEAfgAYcQB-ABlzcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4AAAQmncIAAAAAAAAAAB4
2022-08-29 17:02:26,263 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Publish async job-4289 complete on message bus
2022-08-29 17:02:26,263 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Wake up jobs related to job-4289
2022-08-29 17:02:26,263 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Update db status for job-4289
2022-08-29 17:02:26,264 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289 ctx-214097cb)
(logid:ba10fec5) Wake up jobs joined with job-4289 and disjoin all subjobs
created from job- 4289
2022-08-29 17:02:26,269 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289) (logid:ba10fec5)
Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 85, job
origin: 3445
2022-08-29 17:02:26,270 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289) (logid:ba10fec5)
Done executing com.cloud.vm.VmWorkStart for job-4289
2022-08-29 17:02:26,271 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-140:ctx-67320e13 job-3445/job-4289) (logid:ba10fec5)
Remove job-4289 from job monitoring
2022-08-29 17:02:26,277 WARN  [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-0d1bbbb1) (logid:452c90ec) Unable to allocate console
proxy standby capacity for zone [1] due to [Unable to orchestrate start VM
instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} due to [Unable
to create deployment, no usable volumes found for the VM: 85].].
com.cloud.utils.exception.CloudRuntimeException: Unable to orchestrate
start VM instance {id: "85", name: "v-85-VM", uuid:
"110d8620-c029-4ca9-9084-210099725a80", type="ConsoleProxy"} due to [Unable
to create deployment, no usable volumes found for the VM: 85].
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5319)
at jdk.internal.reflect.GeneratedMethodAccessor945.invoke(Unknown Source)
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:5439)
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)
2022-08-29 17:02:26,277 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
(consoleproxy-1:ctx-0d1bbbb1) (logid:452c90ec) received console proxy alert



Am Mo., 29. Aug. 2022 um 16:30 Uhr schrieb Slavka Peleva <
slav...@storpool.com>:

> Thanks, Chris, for the information!
>
> Are you using custom offerings for the system VMs? Can you share more info
> if yes?
>
> About the log, it's not the complete log from where the deployment
> started. The deployment begins a bit earlier than what you shared. Can you
> search the management log for `Sync job-3539 execution on object
> VmWorkJobQueue` to get the `logid` for the volume creation (coloured in
> blue)? And if possible, share the logs with the found log ID
>
> Here is an example from my logs:
>
> 2022-08-29 17:07:49,114 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (consoleproxy-1:ctx-a952a3dc) (logid:89157bb9) Sync job-60484 execution
> on object VmWorkJobQueue.4904
>
> 2022-08-29 17:07:50,816 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-5:ctx-56172581 job-60479/job-60484 ctx-a900986d)
> (logid:95d750ae) Execute VM work job:
> com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":4904,"handlerName":"VirtualMachineManagerImpl"}
> 2022-08-29 17:07:50,817 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-5:ctx-56172581 job-60479/job-60484 ctx-a900986d)
> (logid:95d750ae) orchestrating VM start for 'v-4904-VM'
> com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d set to null
>
>
> On Mon, Aug 29, 2022 at 2:29 PM vas...@gmx.de <vas...@gmx.de> wrote:
>
>> Hi Slavka,
>>
>> thats what i did after your suggestion / informatin and where the error
>> occured.
>> Deleted / Destroyed the consoleproxy and waited till recreation. Which
>> didn't worked throwing the error i pasted above.
>> Sorry for beeing so unspecific.
>>
>> Regards,
>> Chris
>>
>> Am Mo., 29. Aug. 2022 um 12:46 Uhr schrieb Slavka Peleva <
>> slav...@storpool.com>:
>>
>>> Hi Chris,
>>>
>>> I mean to recreate the system VMs by destroying them.
>>>
>>> On Mon, Aug 29, 2022 at 12:38 PM vas...@gmx.de <vas...@gmx.de> wrote:
>>>
>>>> Hi Slavka,
>>>>
>>>> didn't tried to restart the SystemVMs. Reading through the docs i had
>>>> the impression that "live-patching" would be enough for this....
>>>> Anyway - I tried my luck with the console proxy.
>>>>
>>>> Which failed utterly. Not starting as it isn't finding any useable
>>>> storage pool. - logs at the end of the mail.
>>>>
>>>> I tried deploying a VM using the same storage pool which worked
>>>> wonderfully.
>>>> There i noticed that all my custome storage-offerings are unuseable at
>>>> the moment. They are not accepting any custome storage sizes anymore...
>>>> Throwing failures "VM Creation failed. Volume size: -1GB is out of allowed
>>>> tange. Max:3072 Min:1"...
>>>> So this is also currently broken....
>>>>
>>>> 2022-08-29 10:51:56,189 DEBUG [c.c.v.VmWorkJobDispatcher]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539) (logid:ba10fec5) Run
>>>> VM work job: com.cloud.vm.VmWorkStart for VM 83, job origin: 3445
>>>> 2022-08-29 10:51:56,191 DEBUG [c.c.v.VmWorkJobHandlerProxy]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Execute VM work job:
>>>> com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":83,"handlerName":"VirtualMachineManagerImpl"}
>>>> 2022-08-29 10:51:56,192 DEBUG [c.c.v.VirtualMachineManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) orchestrating VM start for 'v-83-VM'
>>>> com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d set to null
>>>> 2022-08-29 10:51:56,198 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) VM instance {id: "83", name: "v-83-VM", uuid:
>>>> "b1d1f9c6-eafe-4527-9335-e649c646aab0", type="ConsoleProxy"} state
>>>> transited from [Stopped] to [Starting] with event [StartRequested]. VM's
>>>> original host: null, new host: null, host before state transition: null
>>>> 2022-08-29 10:51:56,198 DEBUG [c.c.v.VirtualMachineManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Successfully transitioned to start state for VM instance
>>>> {id: "83", name: "v-83-VM", uuid: "b1d1f9c6-eafe-4527-9335-e649c646aab0",
>>>> type="ConsoleProxy"} reservation id = 6641ccc0-bcef-4b1a-a1f7-8dd8000626ad
>>>> 2022-08-29 10:51:56,203 DEBUG [c.c.v.VirtualMachineManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Deploy avoids pods: null, clusters: null, hosts: null
>>>> 2022-08-29 10:51:56,206 DEBUG [c.c.v.VirtualMachineManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) VM start attempt #1
>>>> 2022-08-29 10:51:56,207 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) DeploymentPlanner allocation algorithm: null
>>>> 2022-08-29 10:51:56,207 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Trying to allocate a host and storage pools from dc:1,
>>>> pod:null,cluster:null, requested cpu: 500, requested ram: (1.00 GB)
>>>> 1073741824
>>>> 2022-08-29 10:51:56,207 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Is ROOT volume READY (pool already allocated)?: No
>>>> 2022-08-29 10:51:56,214 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Deploy avoids pods: [], clusters: [], hosts: null
>>>> 2022-08-29 10:51:56,215 DEBUG [c.c.d.FirstFitPlanner]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Searching all possible resources under this Zone: 1
>>>> 2022-08-29 10:51:56,216 DEBUG [c.c.d.FirstFitPlanner]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Listing clusters in order of aggregate capacity, that have
>>>> (at least one host with) enough CPU and RAM capacity under this Zone: 1
>>>> 2022-08-29 10:51:56,219 DEBUG [c.c.d.FirstFitPlanner]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Removing from the clusterId list these clusters from avoid
>>>> set: []
>>>> 2022-08-29 10:51:56,224 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Checking resources in Cluster: 1 under Pod: 1
>>>> 2022-08-29 10:51:56,225 INFO  [c.c.a.m.a.i.FirstFitAllocator]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5)  Guest VM is requested with
>>>> Custom[UEFI] Boot Type false
>>>> 2022-08-29 10:51:56,225 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Looking for hosts in dc: 1
>>>>  pod:1  cluster:1
>>>> 2022-08-29 10:51:56,227 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) FirstFitAllocator has 4 hosts to
>>>> check for allocation: [Host {"id": "7", "name": "srv-5-comp.blabla.blub",
>>>> "uuid": "8c753ce1-0253-49c9-9c7f-1f971a719ce6", "type"="Routing"}, Host
>>>> {"id": "5", "name": "srv-4-comp.blabla.blub", "uuid":
>>>> "134c625d-15ab-461a-a38d-36fb0b979b5d", "type"="Routing"}, Host {"id": "6",
>>>> "name": "srv-3-comp.blabla.blub", "uuid":
>>>> "6858713b-7e17-46d8-854d-24a13f9c7001", "type"="Routing"}, Host {"id": "1",
>>>> "name": "srv-2-comp.blabla.blub", "uuid":
>>>> "883f7f62-55f2-42f4-8242-16b6847c4204", "type"="Routing"}]
>>>> 2022-08-29 10:51:56,233 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Found 4 hosts for allocation
>>>> after prioritization: [Host {"id": "7", "name": "srv-5-comp.blabla.blub",
>>>> "uuid": "8c753ce1-0253-49c9-9c7f-1f971a719ce6", "type"="Routing"}, Host
>>>> {"id": "5", "name": "srv-4-comp.blabla.blub", "uuid":
>>>> "134c625d-15ab-461a-a38d-36fb0b979b5d", "type"="Routing"}, Host {"id": "6",
>>>> "name": "srv-3-comp.blabla.blub", "uuid":
>>>> "6858713b-7e17-46d8-854d-24a13f9c7001", "type"="Routing"}, Host {"id": "1",
>>>> "name": "srv-2-comp.blabla.blub", "uuid":
>>>> "883f7f62-55f2-42f4-8242-16b6847c4204", "type"="Routing"}]
>>>> 2022-08-29 10:51:56,233 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Looking for speed=500Mhz,
>>>> Ram=1024 MB
>>>> 2022-08-29 10:51:56,233 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 7, name:
>>>> srv-5-comp.blabla.blub, uuid: 8c753ce1-0253-49c9-9c7f-1f971a719ce6} is KVM
>>>> hypervisor type, no max guest limit check needed
>>>> 2022-08-29 10:51:56,235 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host: 7 has cpu capability
>>>> (cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
>>>> 2022-08-29 10:51:56,235 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 7 has enough
>>>> capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
>>>> cpuOverprovisioningFactor: 1.0
>>>> 2022-08-29 10:51:56,237 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
>>>> and CPU after applying overprovisioning: 127200
>>>> 2022-08-29 10:51:56,237 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 37100 , Requested CPU:
>>>> 500
>>>> 2022-08-29 10:51:56,237 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (176.37 GB)
>>>> 189373743104 , Requested RAM: (1.00 GB) 1073741824
>>>> 2022-08-29 10:51:56,237 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
>>>> available
>>>> 2022-08-29 10:51:56,237 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
>>>> 7, used: 90100, reserved: 0, actual total: 127200, total with
>>>> overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
>>>> ,considerReservedCapacity?: true
>>>> 2022-08-29 10:51:56,237 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
>>>> 7, used: (73.90 GB) 79352037376, reserved: (0 bytes) 0, total: (250.27 GB)
>>>> 268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
>>>> false , considerReservedCapacity?: true
>>>> 2022-08-29 10:51:56,237 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
>>>> list: 7
>>>> 2022-08-29 10:51:56,237 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 5, name:
>>>> srv-4-comp.blabla.blub, uuid: 134c625d-15ab-461a-a38d-36fb0b979b5d} is KVM
>>>> hypervisor type, no max guest limit check needed
>>>> 2022-08-29 10:51:56,239 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host: 5 has cpu capability
>>>> (cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
>>>> 2022-08-29 10:51:56,239 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 5 has enough
>>>> capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
>>>> cpuOverprovisioningFactor: 1.0
>>>> 2022-08-29 10:51:56,240 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
>>>> and CPU after applying overprovisioning: 127200
>>>> 2022-08-29 10:51:56,240 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 116100 , Requested
>>>> CPU: 500
>>>> 2022-08-29 10:51:56,241 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (233.77 GB)
>>>> 251009040384 , Requested RAM: (1.00 GB) 1073741824
>>>> 2022-08-29 10:51:56,241 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
>>>> available
>>>> 2022-08-29 10:51:56,241 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
>>>> 5, used: 11100, reserved: 0, actual total: 127200, total with
>>>> overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
>>>> ,considerReservedCapacity?: true
>>>> 2022-08-29 10:51:56,241 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
>>>> 5, used: (16.50 GB) 17716740096, reserved: (0 bytes) 0, total: (250.27 GB)
>>>> 268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
>>>> false , considerReservedCapacity?: true
>>>> 2022-08-29 10:51:56,241 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
>>>> list: 5
>>>> 2022-08-29 10:51:56,241 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 6, name:
>>>> srv-3-comp.blabla.blub, uuid: 6858713b-7e17-46d8-854d-24a13f9c7001} is KVM
>>>> hypervisor type, no max guest limit check needed
>>>> 2022-08-29 10:51:56,243 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host: 6 has cpu capability
>>>> (cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
>>>> 2022-08-29 10:51:56,243 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 6 has enough
>>>> capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
>>>> cpuOverprovisioningFactor: 1.0
>>>> 2022-08-29 10:51:56,244 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
>>>> and CPU after applying overprovisioning: 127200
>>>> 2022-08-29 10:51:56,244 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 84300 , Requested CPU:
>>>> 500
>>>> 2022-08-29 10:51:56,244 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (190.02 GB)
>>>> 204032835584 , Requested RAM: (1.00 GB) 1073741824
>>>> 2022-08-29 10:51:56,244 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
>>>> available
>>>> 2022-08-29 10:51:56,244 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
>>>> 6, used: 42900, reserved: 0, actual total: 127200, total with
>>>> overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
>>>> ,considerReservedCapacity?: true
>>>> 2022-08-29 10:51:56,244 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
>>>> 6, used: (60.25 GB) 64692944896, reserved: (0 bytes) 0, total: (250.27 GB)
>>>> 268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
>>>> false , considerReservedCapacity?: true
>>>> 2022-08-29 10:51:56,244 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
>>>> list: 6
>>>> 2022-08-29 10:51:56,244 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host {id: 1, name:
>>>> srv-2-comp.blabla.blub, uuid: 883f7f62-55f2-42f4-8242-16b6847c4204} is KVM
>>>> hypervisor type, no max guest limit check needed
>>>> 2022-08-29 10:51:56,247 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host: 1 has cpu capability
>>>> (cpu:48, speed:2650) to support requested CPU: 1 and requested speed: 500
>>>> 2022-08-29 10:51:56,247 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Checking if host: 1 has enough
>>>> capacity for requested CPU: 500 and requested RAM: (1.00 GB) 1073741824 ,
>>>> cpuOverprovisioningFactor: 1.0
>>>> 2022-08-29 10:51:56,248 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Hosts's actual total CPU: 127200
>>>> and CPU after applying overprovisioning: 127200
>>>> 2022-08-29 10:51:56,248 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Free CPU: 79000 , Requested CPU:
>>>> 500
>>>> 2022-08-29 10:51:56,248 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Free RAM: (214.02 GB)
>>>> 229802639360 , Requested RAM: (1.00 GB) 1073741824
>>>> 2022-08-29 10:51:56,248 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host has enough CPU and RAM
>>>> available
>>>> 2022-08-29 10:51:56,248 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc CPU from host:
>>>> 1, used: 48200, reserved: 0, actual total: 127200, total with
>>>> overprovisioning: 127200; requested cpu:500,alloc_from_last_host?:false
>>>> ,considerReservedCapacity?: true
>>>> 2022-08-29 10:51:56,249 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) STATS: Can alloc MEM from host:
>>>> 1, used: (36.25 GB) 38923141120, reserved: (0 bytes) 0, total: (250.27 GB)
>>>> 268725780480; requested mem: (1.00 GB) 1073741824, alloc_from_last_host?:
>>>> false , considerReservedCapacity?: true
>>>> 2022-08-29 10:51:56,249 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Found a suitable host, adding to
>>>> list: 1
>>>> 2022-08-29 10:51:56,249 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751
>>>> FirstFitRoutingAllocator) (logid:ba10fec5) Host Allocator returning 4
>>>> suitable hosts
>>>> 2022-08-29 10:51:56,260 DEBUG [c.c.c.CapacityManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) VM instance {id: "83", name: "v-83-VM", uuid:
>>>> "b1d1f9c6-eafe-4527-9335-e649c646aab0", type="ConsoleProxy"} state
>>>> transited from [Starting] to [Stopped] with event [OperationFailed]. VM's
>>>> original host: null, new host: null, host before state transition: null
>>>> 2022-08-29 10:51:56,260 WARN  [c.c.v.VirtualMachineManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Unable to orchestrate start VM instance {id: "83", name:
>>>> "v-83-VM", uuid: "b1d1f9c6-eafe-4527-9335-e649c646aab0",
>>>> type="ConsoleProxy"} due to [Unable to create deployment, no usable volumes
>>>> found for the VM: 83].
>>>> com.cloud.utils.exception.CloudRuntimeException: Unable to create
>>>> deployment, no usable volumes found for the VM: 83
>>>> at
>>>> com.cloud.deploy.DeploymentPlanningManagerImpl.findSuitablePoolsForVolumes(DeploymentPlanningManagerImpl.java:1569)
>>>> at
>>>> com.cloud.deploy.DeploymentPlanningManagerImpl.checkClustersforDestination(DeploymentPlanningManagerImpl.java:1217)
>>>> at
>>>> com.cloud.deploy.DeploymentPlanningManagerImpl.planDeployment(DeploymentPlanningManagerImpl.java:527)
>>>> at
>>>> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1126)
>>>> at
>>>> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5315)
>>>> at jdk.internal.reflect.GeneratedMethodAccessor945.invoke(Unknown
>>>> Source)
>>>> 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:5439)
>>>> 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)
>>>> 2022-08-29 10:51:56,262 DEBUG [c.c.v.VmWorkJobHandlerProxy]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Done executing VM work job:
>>>> com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":83,"handlerName":"VirtualMachineManagerImpl"}
>>>> 2022-08-29 10:51:56,263 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Complete async job-3539, jobStatus: FAILED, resultCode: 0,
>>>> result:
>>>> rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0ANRVbmFibGUgdG8gb3JjaGVzdHJhdGUgc3RhcnQgVk0gaW5zdGFuY2Uge2lkOiAiODMiLCBuYW1lOiAidi04My1WTSIsIHV1aWQ6ICJiMWQxZjljNi1lYWZlLTQ1MjctOTMzNS1lNjQ5YzY0NmFhYjAiLCB0eXBlPSJDb25zb2xlUHJveHkifSBkdWUgdG8gW1VuYWJsZSB0byBjcmVhdGUgZGVwbG95bWVudCwgbm8gdXNhYmxlIHZvbHVtZXMgZm91bmQgZm9yIHRoZSBWTTogODNdLnVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAE3NyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ABUwADmRlY2xhcmluZ0NsYXNzcQB-AAVMAAhmaWxlTmFtZXEAfgAFTAAKbWV0aG9kTmFtZXEAfgAFTAAKbW9kdWxlTmFtZXEAfgAFTAANbW9kdWxlVmVyc2lvbnEAfgAFeHABAAAUx3QAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHBwc3EAfgAMAP____9wdAAvamRrLmludGVybmFsLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3I5NDVwdAAGaW52b2tlcHBzcQB-AAwCAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABR0AAlqYXZhLmJhc2V0AAcxMS4wLjE2c3EAfgAMAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AFHEAfgAYcQB-ABlzcQB-AAwBAAAAa3EAfgAOdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-AAwBAAAVP3EAfgAOcQB-AA9xAH4AEHEAfgAgcHBzcQB-AAwBAAAAZnEAfgAOdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4ADAEAAAJscQB-AA50AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4ADAEAAAAwcQB-AA50AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgAMAQAAADdxAH4ADnQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgAMAQAAAGZxAH4ADnQAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AMHQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgAMAQAAADRxAH4ADnEAfgAzcQB-ADB0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgAMAQAAAC1xAH4ADnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAscQB-AC1wcHNxAH4ADAEAAAI4cQB-AA5xAH4AJ3EAfgAocQB-AC1wcHNxAH4ADAIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAxcQB-ABhxAH4AGXNxAH4ADAIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4ALXEAfgAYcQB-ABlzcQB-AAwCAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAYcQB-ABlzcQB-AAwCAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEJxAH4ALXEAfgAYcQB-ABlzcQB-AAwCAAADPXB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4ALXEAfgAYcQB-ABlzcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4AAAQmncIAAAAAAAAAAB4
>>>> 2022-08-29 10:51:56,264 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Publish async job-3539 complete on message bus
>>>> 2022-08-29 10:51:56,264 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Wake up jobs related to job-3539
>>>> 2022-08-29 10:51:56,264 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Update db status for job-3539
>>>> 2022-08-29 10:51:56,266 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539 ctx-073f2751)
>>>> (logid:ba10fec5) Wake up jobs joined with job-3539 and disjoin all subjobs
>>>> created from job- 3539
>>>> 2022-08-29 10:51:56,276 DEBUG [c.c.v.VmWorkJobDispatcher]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539) (logid:ba10fec5) Done
>>>> with run of VM work job: com.cloud.vm.VmWorkStart for VM 83, job origin:
>>>> 3445
>>>> 2022-08-29 10:51:56,276 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539) (logid:ba10fec5) Done
>>>> executing com.cloud.vm.VmWorkStart for job-3539
>>>> 2022-08-29 10:51:56,278 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
>>>> (Work-Job-Executor-58:ctx-dd8fe695 job-3445/job-3539) (logid:ba10fec5)
>>>> Remove job-3539 from job monitoring
>>>> 2022-08-29 10:51:56,285 WARN  [c.c.c.ConsoleProxyManagerImpl]
>>>> (consoleproxy-1:ctx-88c25b3a) (logid:d39faaa7) Unable to allocate console
>>>> proxy standby capacity for zone [1] due to [Unable to orchestrate start VM
>>>> instance {id: "83", name: "v-83-VM", uuid:
>>>> "b1d1f9c6-eafe-4527-9335-e649c646aab0", type="ConsoleProxy"} due to [Unable
>>>> to create deployment, no usable volumes found for the VM: 83].].
>>>> com.cloud.utils.exception.CloudRuntimeException: Unable to orchestrate
>>>> start VM instance {id: "83", name: "v-83-VM", uuid:
>>>> "b1d1f9c6-eafe-4527-9335-e649c646aab0", type="ConsoleProxy"} due to [Unable
>>>> to create deployment, no usable volumes found for the VM: 83].
>>>> at
>>>> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5319)
>>>> at jdk.internal.reflect.GeneratedMethodAccessor945.invoke(Unknown
>>>> Source)
>>>> 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:5439)
>>>> 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)
>>>> 2022-08-29 10:51:56,287 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
>>>> (consoleproxy-1:ctx-88c25b3a) (logid:d39faaa7) received console proxy alert
>>>> 2022-08-29 10:51:56,288 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
>>>> (consoleproxy-1:ctx-88c25b3a) (logid:d39faaa7) Console proxy creation
>>>> failure, zone: blabla
>>>> 2022-08-29 10:51:56,289 WARN  [c.c.a.AlertManagerImpl]
>>>> (consoleproxy-1:ctx-88c25b3a) (logid:d39faaa7) alertType=[10]
>>>> dataCenterId=[1] podId=[null] clusterId=[null] message=[Console proxy
>>>> creation failure. zone: blabla, error details: Unable to orchestrate start
>>>> VM instance {id: "83", name: "v-83-VM", uuid:
>>>> "b1d1f9c6-eafe-4527-9335-e649c646aab0", type="ConsoleProxy"} due to [Unable
>>>> to create deployment, no usable volumes found for the VM: 83].].
>>>>
>>>>
>>>>
>>>>
>>>> Am Mo., 29. Aug. 2022 um 09:40 Uhr schrieb Slavka Peleva
>>>> <slav...@storpool.com.invalid>:
>>>>
>>>>> Hi Chris,
>>>>>
>>>>> Did you recreate the system VMs? In the 4.17 version, the
>>>>> `systemvm.iso` is
>>>>> deprecated. In its place, you should have the file on agents
>>>>> `/usr/share/cloudstack-common/vms/agent.zip`.
>>>>> Can you share the complete log if the system VMs are newly created
>>>>> after
>>>>> the upgrade?
>>>>>
>>>>> Best regards,
>>>>> Slavka
>>>>>
>>>>> On Sun, Aug 28, 2022 at 2:16 PM vas...@gmx.de <vas...@gmx.de> wrote:
>>>>>
>>>>> > Hi everyone,
>>>>> >
>>>>> > faceing some challanges again after upgradeing to 4.17.
>>>>> > Did as explained in the docs.
>>>>> >
>>>>> > Afterwards I am now not able to migrate system VMs to different
>>>>> hosts.
>>>>> > Getting the error
>>>>> > "Exception during migrate: org.libvirt.LibvirtException: Cannot
>>>>> access
>>>>> > storage file '/usr/share/cloudstack-common/vms/systemvm.iso': No
>>>>> such file
>>>>> > or directory"
>>>>> >
>>>>> > Checked the exitstence of the file on the servers:
>>>>> > Mangement-Server has a "systemvm.iso.bak"
>>>>> > Hosts - no "systemvm.iso" at all present.
>>>>> >
>>>>> > Maybe someone has an idea on how to move on with this?
>>>>> >
>>>>> > Regards,
>>>>> > Chris
>>>>> >
>>>>>
>>>>