Hi Chris,
The deployment fails because CS cannot find a free IP address to allocate
for the system VM. Can you check if you explicitly added a range for the
system VMs, or you can check with this `select * from user_ip_address where
forsystemvms = 1;` If you don't have any ranges, you can get free IPs
with `SELECT
* FROM cloud.user_ip_address where allocated IS NULL AND removed IS NULL;`
. To get the exact query executed by CS, you need to increase the log level
to TRACE.
Best regards,
Slavka
On Mon, Aug 29, 2022 at 8:03 PM vas...@gmx.de <vas...@gmx.de> wrote:
> 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
>>>>>> >
>>>>>>
>>>>>
