search

apache / cloudstack

Apache CloudStack is an opensource Infrastructure as a Service (IaaS) cloud computing platform
https://cloudstack.apache.org/
Apache License 2.0
2.13k stars 1.11k forks source link

Can not deploy VM using libvirt-8.0.0 ？ #6635

Closed xuanyuanaosheng closed 2 years ago

xuanyuanaosheng commented 2 years ago
ISSUE TYPE
CLOUDSTACK VERSION
  1. cloudstack-management-4.15.2.0
  2. ceph version:15.2.16
  3. cloudstack agent os version: Oracle Linux Server 8.3
  4. cloudstack-agent-4.15.2.0

The cloudstack env is using the Ceph RBD and local storage as cloudstack cluster primary storage.

The cloudstack cluster TEST work node is eno49 and eno50 to bond0.

 - bond0  --->  bond0.1935 ---> cloudbr0

                         -------> VLAN 1115
 - bond0  ---> cloudbr1 -
                         -------> VLAN 1118

The libvirt version:

# rpm -qa | grep libvirt*
libvirt-daemon-driver-storage-rbd-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-client-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-glib-3.0.0-1.el8.x86_64
libvirt-daemon-driver-storage-disk-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-nodedev-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-storage-iscsi-direct-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-devel-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-storage-core-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-qemu-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-storage-mpath-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-wireshark-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-nwfilter-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-storage-logical-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-lock-sanlock-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-docs-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-secret-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-config-network-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-storage-scsi-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-kvm-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-interface-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-config-nwfilter-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-gobject-3.0.0-1.el8.x86_64
libvirt-daemon-driver-storage-gluster-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-gconfig-3.0.0-1.el8.x86_64
libvirt-dbus-1.3.0-2.module+el8.6.0+20659+3dcf7c70.x86_64
libvirt-libs-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-storage-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
python3-libvirt-6.0.0-1.module+el8.3.0+7860+a7792d29.x86_64
libvirt-daemon-driver-network-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-daemon-driver-storage-iscsi-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64
libvirt-nss-8.0.0-5.2.0.1.module+el8.6.0+20722+b0f1ae3c.x86_64

The Cloudstack manager error log

2022-08-12 12:32:08,563 DEBUG [c.c.a.t.Request] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Seq 76-8001207687977107472: Received:  { Ans: , MgmtId: 345052215515, via: 76(whdckvm006.cn.prod), Ver: v1, Flags: 10, { StopAnswer } }
2022-08-12 12:32:08,583 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Changing active number of nics for network id=234 on -1
2022-08-12 12:32:08,597 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Successfully released network resources for the vm VM[User|i-2-25947-VM]
2022-08-12 12:32:08,597 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Successfully cleaned up resources for the VM VM[User|i-2-25947-VM] in Starting state
2022-08-12 12:32:08,601 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Root volume is ready, need to place VM in volume's cluster
2022-08-12 12:32:08,614 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) DeploymentPlanner allocation algorithm: null
2022-08-12 12:32:08,614 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Trying to allocate a host and storage pools from dc:8, pod:7,cluster:8, requested cpu: 4096, requested ram: (7.91 GB) 8489271296
2022-08-12 12:32:08,614 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Is ROOT volume READY (pool already allocated)?: Yes
2022-08-12 12:32:08,614 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 76
2022-08-12 12:32:08,616 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) The specified host is in avoid set
2022-08-12 12:32:08,616 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Cannot deploy to specified host, returning.
2022-08-12 12:32:08,632 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 76
2022-08-12 12:32:08,636 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) (logid:) Ping from 18(s-286-VM)
2022-08-12 12:32:08,647 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Hosts's actual total CPU: 184800 and CPU after applying overprovisioning: 1108800
2022-08-12 12:32:08,647 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Hosts's actual total RAM: (502.83 GB) 539906072576 and RAM after applying overprovisioning: (2.9463 TB) 3239436615680
2022-08-12 12:32:08,647 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) release cpu from host: 76, old used: 4096,reserved: 0, actual total: 184800, total with overprovisioning: 1108800; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2022-08-12 12:32:08,647 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) release mem from host: 76, old used: (7.91 GB) 8489271296,reserved: (0 bytes) 0, total: (2.9463 TB) 3239436615680; new used: (0 bytes) 0,reserved:(0 bytes) 0; movedfromreserved: false,moveToReserveredfalse
2022-08-12 12:32:08,674 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-25947-VM]Scope=interface com.cloud.dc.DataCenter; id=8
2022-08-12 12:32:08,674 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365 ctx-d0ce22e0) (logid:a4efa0f1) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-25947-VM]Scope=interface com.cloud.dc.DataCenter; id=8
2022-08-12 12:32:08,674 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365) (logid:a4efa0f1) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 25947, job origin: 86364
2022-08-12 12:32:08,674 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365) (logid:a4efa0f1) Unable to complete AsyncJobVO {id:86365, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAABlW3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAACHBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAhzcQB-AAgAAAAAAAAATHBwcHNxAH4ACAAAAAAAAAAHcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345052215515, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Aug 12 12:32:04 CST 2022, removed: null}, job origin:86364
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-25947-VM]Scope=interface com.cloud.dc.DataCenter; id=8
    at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1119)
    at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5502)
    at jdk.internal.reflect.GeneratedMethodAccessor1415.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:5669)
    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:834)
2022-08-12 12:32:08,684 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365) (logid:a4efa0f1) Complete async job-86365, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA3VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0yLTI1OTQ3LVZNXXVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFHNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ACkwADmRlY2xhcmluZ0NsYXNzcQB-AApMAAhmaWxlTmFtZXEAfgAKTAAKbWV0aG9kTmFtZXEAfgAKTAAKbW9kdWxlTmFtZXEAfgAKTAANbW9kdWxlVmVyc2lvbnEAfgAKeHABAAAEX3QAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHBwc3EAfgARAQAAFX5xAH4AE3EAfgAUcQB-ABVxAH4AFnBwc3EAfgARAP____9wdAAwamRrLmludGVybmFsLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3IxNDE1cHQABmludm9rZXBwc3EAfgARAgAAACtwdAAxamRrLmludGVybmFsLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAadAAJamF2YS5iYXNldAAHMTEuMC4xMHNxAH4AEQIAAAI2cHQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-ABpxAH4AHnEAfgAfc3EAfgARAQAAAGtxAH4AE3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnBwc3EAfgARAQAAFiVxAH4AE3EAfgAUcQB-ABVxAH4AJnBwc3EAfgARAQAAAGZxAH4AE3QAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9icHBzcQB-ABEBAAACbHEAfgATdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0cHBzcQB-ABEBAAAAMHEAfgATdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5wcHNxAH4AEQEAAAA3cQB-ABN0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxwcHNxAH4AEQEAAABmcQB-ABN0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADZ0AA9jYWxsV2l0aENvbnRleHRwcHNxAH4AEQEAAAA0cQB-ABNxAH4AOXEAfgA2dAAOcnVuV2l0aENvbnRleHRwcHNxAH4AEQEAAAAtcQB-ABN0ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4AMnEAfgAzcHBzcQB-ABEBAAACOHEAfgATcQB-AC1xAH4ALnEAfgAzcHBzcQB-ABECAAACA3B0AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4AN3EAfgAecQB-AB9zcQB-ABECAAABCHB0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-ADNxAH4AHnEAfgAfc3EAfgARAgAABGhwdAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJxAH4AHnEAfgAfc3EAfgARAgAAAnRwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBIcQB-ADNxAH4AHnEAfgAfc3EAfgARAgAAA0JwdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-ADNxAH4AHnEAfgAfc3IAH2phdmEudXRpbC5Db2xsZWN0aW9ucyRFbXB0eUxpc3R6uBe0PKee3gIAAHhweHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABDvc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4c3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhxAH4AUgAAAAAAAAAIdnIAF2NvbS5jbG91ZC5kYy5EYXRhQ2VudGVyU-gkGtLTtlwCAAB4cAA
2022-08-12 12:32:08,686 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365) (logid:a4efa0f1) Publish async job-86365 complete on message bus
2022-08-12 12:32:08,686 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365) (logid:a4efa0f1) Wake up jobs related to job-86365
2022-08-12 12:32:08,686 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365) (logid:a4efa0f1) Update db status for job-86365
2022-08-12 12:32:08,689 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365) (logid:a4efa0f1) Wake up jobs joined with job-86365 and disjoin all subjobs created from job- 86365
2022-08-12 12:32:08,700 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365) (logid:a4efa0f1) Done executing com.cloud.vm.VmWorkStart for job-86365
2022-08-12 12:32:08,704 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-71:ctx-c5d11def job-86364/job-86365) (logid:a4efa0f1) Remove job-86365 from job monitoring
2022-08-12 12:32:08,718 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364 ctx-13ec6414) (logid:a4efa0f1) Destroying vm VM[User|i-2-25947-VM] as it failed to create on Host with Id:76
2022-08-12 12:32:08,726 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364 ctx-13ec6414) (logid:a4efa0f1) VM state transitted from :Stopped to Error with event: OperationFailedToErrorvm's original host id: null new host id: null host id before state transition: null
2022-08-12 12:32:08,779 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364 ctx-13ec6414) (logid:a4efa0f1) Updating resource Type = volume count for Account = 2 Operation = decreasing Amount = 1
2022-08-12 12:32:08,787 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364 ctx-13ec6414) (logid:a4efa0f1) Updating resource Type = primary_storage count for Account = 2 Operation = decreasing Amount = (40.00 GB) 42949672960
2022-08-12 12:32:08,804 WARN  [c.c.a.AlertManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364 ctx-13ec6414) (logid:a4efa0f1) AlertType:: 8 | dataCenterId:: 8 | podId:: 7 | clusterId:: null | message:: Failed to deploy Vm with Id: 25947, on Host with Id: 76
2022-08-12 12:32:08,806 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) Ping from Routing host 5(scnbe013.cn.prod)
2022-08-12 12:32:08,807 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) Process host VM state report from ping process. host: 5
2022-08-12 12:32:08,813 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364 ctx-13ec6414) (logid:a4efa0f1) Updating resource Type = user_vm count for Account = 2 Operation = decreasing Amount = 1
2022-08-12 12:32:08,827 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364 ctx-13ec6414) (logid:a4efa0f1) Updating resource Type = cpu count for Account = 2 Operation = decreasing Amount = 4
2022-08-12 12:32:08,830 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) Process VM state report. host: 5, number of records in report: 6
2022-08-12 12:32:08,830 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) VM state report. host: 5, vm id: 25824, power state: PowerOn
2022-08-12 12:32:08,833 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) VM state report. host: 5, vm id: 25825, power state: PowerOn
2022-08-12 12:32:08,836 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) VM state report. host: 5, vm id: 25826, power state: PowerOn
2022-08-12 12:32:08,837 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364 ctx-13ec6414) (logid:a4efa0f1) Updating resource Type = memory count for Account = 2 Operation = decreasing Amount = 8096
2022-08-12 12:32:08,839 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) VM state report. host: 5, vm id: 25827, power state: PowerOn
2022-08-12 12:32:08,842 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) VM state report. host: 5, vm id: 25933, power state: PowerOn
2022-08-12 12:32:08,845 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) VM state report. host: 5, vm id: 110, power state: PowerOn
2022-08-12 12:32:08,852 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-12:null) (logid:) Done with process of VM state report. host: 5
2022-08-12 12:32:08,854 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-40:ctx-5a8d5b0a job-86364) (logid:a4efa0f1) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to insufficient capacity
    at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:751)
    at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:243)
    at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:214)
    at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4938)
    at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4464)
    at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4453)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
    at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
    at com.sun.proxy.$Proxy127.startVirtualMachine(Unknown Source)
    at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:686)
    at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
    at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
    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:834)
Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-25947-VM]Scope=interface com.cloud.dc.DataCenter; id=8
    at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1119)
    at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5502)
    at jdk.internal.reflect.GeneratedMethodAccessor1415.invoke(Unknown Source)
    ... 17 more
2022-08-12 12:32:08,857 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364) (logid:a4efa0f1) Complete async job-86364, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Unable to start a VM due to insufficient capacity"}
2022-08-12 12:32:08,858 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364) (logid:a4efa0f1) Publish async job-86364 complete on message bus
2022-08-12 12:32:08,859 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364) (logid:a4efa0f1) Wake up jobs related to job-86364
2022-08-12 12:32:08,859 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364) (logid:a4efa0f1) Update db status for job-86364
2022-08-12 12:32:08,860 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364) (logid:a4efa0f1) Wake up jobs joined with job-86364 and disjoin all subjobs created from job- 86364
2022-08-12 12:32:08,867 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-40:ctx-5a8d5b0a job-86364) (logid:a4efa0f1) Done executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-86364
2022-08-12 12:32:08,868 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-40:ctx-5a8d5b0a job-86364) (logid:a4efa0f1) Remove job-86364 from job monitoring
2022-08-12 12:32:09,348 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) (logid:) Ping from 69(s-25919-VM)
2022-08-12 12:32:09,587 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) Ping from 71(v-25920-VM)
2022-08-12 12:32:10,043 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) (logid:) SeqA 72-10974: Processing Seq 72-10974:  { Cmd , MgmtId: -1, via: 72, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"25921","_loadInfo":"{
  "connections": [
    {
      "id": 6,
      "clientInfo": "",
      "host": "10.26.246.11",
      "port": 5906,
      "tag": "ec3c81f6-4701-4276-8fdb-8cf34d610ddb",
      "createTime": 1660274781795,
      "lastUsedTime": 1660278669208
    },
    {
      "id": 7,
      "clientInfo": "",
      "host": "10.26.246.11",
      "port": 5904,
      "tag": "0e65d2af-8e29-4c50-b2d0-170afcdb9a16",
      "createTime": 1660274912073,
      "lastUsedTime": 1660278669182
    }
  ]
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-08-12 12:32:10,050 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) (logid:) SeqA 72-10974: Sending Seq 72-10974:  { Ans: , MgmtId: 345052215515, via: 72, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }

The cloudstack agent error log:

2022-08-12 12:29:04,107 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:14eb27c4) Trying to fetch storage pool 0edb0e58-6b90-3be
e-8e7b-13007b0f7bf9 from libvirt
2022-08-12 12:29:04,317 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:14eb27c4) Processing agent ready command, agent id = 76
2022-08-12 12:29:04,318 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:14eb27c4) Set agent id 76
2022-08-12 12:29:04,325 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:14eb27c4) Ready command is processed for agent id = 76
2022-08-12 12:29:04,382 INFO  [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:14eb27c4) Processing agent ready command, agent id = 76
2022-08-12 12:29:04,382 INFO  [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:14eb27c4) Set agent id 76
2022-08-12 12:29:04,385 INFO  [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:14eb27c4) Processed new management server list: 10.25.2.173@static
2022-08-12 12:29:04,385 INFO  [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:14eb27c4) Ready command is processed for agent id = 76
2022-08-12 12:34:33,836 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:a4efa0f1) Trying to fetch storage pool 0edb0e58-6b90-3bee-8e7b-13007b0f7bf9 from libvirt
2022-08-12 12:34:34,217 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:a4efa0f1) Trying to fetch storage pool 0edb0e58-6b90-3be
e-8e7b-13007b0f7bf9 from libvirt
2022-08-12 12:34:34,673 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-3:null) (logid:a4efa0f1) Groovy script '/etc/cloudstack/agent/hooks/libv
irt-vm-xml-transformer.groovy' is not available. Transformations will not be applied.
2022-08-12 12:34:34,674 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-3:null) (logid:a4efa0f1) Groovy scripting engine is not initialized. Dat
a transformation skipped.
2022-08-12 12:34:34,687 WARN  [resource.wrapper.LibvirtStartCommandWrapper] (agentRequest-Handler-3:null) (logid:a4efa0f1) LibvirtException 
org.libvirt.LibvirtException: unsupported configuration: VNC password is 22 characters long, only 8 permitted
        at org.libvirt.ErrorHandler.processError(Unknown Source)
        at org.libvirt.ErrorHandler.processError(Unknown Source)
        at org.libvirt.Connect.domainCreateXML(Unknown Source)
        at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.startVM(LibvirtComputingResource.java:1616)
        at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtStartCommandWrapper.execute(LibvirtStartCommandWrapper.java:85)
        at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtStartCommandWrapper.execute(LibvirtStartCommandWrapper.java:45)
        at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78)
        at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1648)
        at com.cloud.agent.Agent.processRequest(Agent.java:661)
        at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1079)
        at com.cloud.utils.nio.Task.call(Task.java:83)
        at com.cloud.utils.nio.Task.call(Task.java:29)
        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:834)
2022-08-12 12:34:34,825 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:a4efa0f1) Trying to fetch storage pool 0edb0e58-6b90-3be
e-8e7b-13007b0f7bf9 from libvirt
2022-08-12 12:34:34,878 INFO  [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:a4efa0f1) No existing libvirtd connection found. Opening a 
new one
2022-08-12 12:34:34,884 WARN  [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:a4efa0f1) Can not find a connection for Instance i-2-25947-
VM. Assuming the default connection.
2022-08-12 12:34:35,272 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-4:null) (logid:a4efa0f1) Groovy script '/etc/cloudstack/agent/hooks/libv
irt-vm-state-change.groovy' is not available. Transformations will not be applied.
2022-08-12 12:34:35,273 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-4:null) (logid:a4efa0f1) Groovy scripting engine is not initialized. Dat
a transformation skipped.

Information already queried:

  1. https://www.mail-archive.com/users@ovirt.org/msg69138.html
  2. https://lists.ovirt.org/archives/list/users@ovirt.org/thread/JU3EGBZWSITTDJSLX3WZBBYZ7MEXZQM7/

Could you please give some advices?

shwstppr commented 2 years ago

@xuanyuanaosheng this seems to have got fixed in 4.17.0 https://github.com/apache/cloudstack/pull/6404

rohityadavcloud commented 2 years ago

@xuanyuanaosheng you can either upgrade to latest 4.17 release (4.17.0.1, 4.17.0.0) or use 4.15 or 4.16 SB customer patches which fixes this libvirt-8 issue, read more - https://www.shapeblue.com/advisory-on-libvirt-8-compatibility-issues-with-cloudstack/