Hi,
The logs show
2023-11-15 23:00:13,172 WARN [resource.wrapper.LibvirtStartCommandWrapper]
(agentRequest-Handler-3:null) (logid:456eabd2) LibvirtException
org.libvirt.LibvirtException: internal error: Only 1 IDE controller is
supported
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:1816)
How many volumes/nics does the vm have ? Can you list the vm settings ?
-Wei
On Thu, 16 Nov 2023 at 08:06, Jeremy Hansen <jer...@skidrow.la.invalid>
wrote:
> I’m having an issue with a specific VM being unable to start and I’m not
> quite sure why or how it got in this state.
>
> cloudstack 4.18.1.0
>
> Management log:
>
> 2023-11-15 22:56:44,938 ERROR [c.c.a.ApiAsyncJobDispatcher]
> (API-Job-Executor-1:ctx-fc2bc1f9 job-78702) (logid:a3519842) Unexpected
> exception while executing
> org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin
> com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM
> [cc216a54-5d5b-4ec2-a178-474ff957e53f] due to [Unable to create a
> deployment for VM instance
> {"id":218,"instanceName":"i-4-218-VM","type":"User","uuid":"cc216a54-5d5b-4ec2-a178-474ff957e53f"}].
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:841)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:258)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:214)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5401)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5251)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3179)
> 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:52)
> 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.$Proxy185.startVirtualMachine(Unknown Source)
> at
> org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(StartVMCmd.java:181)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:163)
> at
> com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:112)
> 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)
> Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable
> to create a deployment for VM instance
> {"id":218,"instanceName":"i-4-218-VM","type":"User","uuid":"cc216a54-5d5b-4ec2-a178-474ff957e53f"}Scope=interface
> com.cloud.dc.DataCenter; id=1
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1226)
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5412)
> at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method)
> ... 18 more
>
> Compute node logs:
>
> ==> agent.log <==
> 2023-11-15 23:00:10,017 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:10,200 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:10,377 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:10,528 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:10,822 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:11,071 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:11,250 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:11,418 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:11,587 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:11,756 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:12,092 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:12,100 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:12,386 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:12,436 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:12,603 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:12,751 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:12,952 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Attempting to create storage
> pool 611ef480-1caa-3e50-a6a0-c3d666dfd52f (NetworkFilesystem) in libvirt
> 2023-11-15 23:00:12,954 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Found existing defined
> storage pool 611ef480-1caa-3e50-a6a0-c3d666dfd52f, using it.
> 2023-11-15 23:00:12,954 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Trying to fetch storage pool
> 611ef480-1caa-3e50-a6a0-c3d666dfd52f from libvirt
> 2023-11-15 23:00:12,973 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:13,070 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:13,076 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:13,084 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:13,143 WARN [kvm.resource.LibvirtKvmAgentHook]
> (agentRequest-Handler-3:null) (logid:456eabd2) Groovy script
> '/etc/cloudstack/agent/hooks/libvirt-vm-xml-transformer.groovy' is not
> available. Transformations will not be applied.
> 2023-11-15 23:00:13,143 WARN [kvm.resource.LibvirtKvmAgentHook]
> (agentRequest-Handler-3:null) (logid:456eabd2) Groovy scripting engine is
> not initialized. Data transformation skipped.
> 2023-11-15 23:00:13,172 WARN
> [resource.wrapper.LibvirtStartCommandWrapper]
> (agentRequest-Handler-3:null) (logid:456eabd2) LibvirtException
> org.libvirt.LibvirtException: internal error: Only 1 IDE controller is
> supported
> 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:1816)
> at
> com.cloud.hypervisor.kvm.resource.wrapper.LibvirtStartCommandWrapper.execute(LibvirtStartCommandWrapper.java:89)
> at
> com.cloud.hypervisor.kvm.resource.wrapper.LibvirtStartCommandWrapper.execute(LibvirtStartCommandWrapper.java:49)
> at
> com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1848)
> at com.cloud.agent.Agent.processRequest(Agent.java:662)
> at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1082)
> 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:829)
> 2023-11-15 23:00:13,190 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:13,241 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:13,247 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:13,300 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) (logid:456eabd2) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:13,399 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:13,576 INFO [kvm.resource.LibvirtConnection]
> (agentRequest-Handler-5:null) (logid:456eabd2) No existing libvirtd
> connection found. Opening a new one
> 2023-11-15 23:00:13,578 WARN [kvm.resource.LibvirtConnection]
> (agentRequest-Handler-5:null) (logid:456eabd2) Can not find a connection
> for Instance i-4-218-VM. Assuming the default connection.
> 2023-11-15 23:00:13,586 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
> 2023-11-15 23:00:13,747 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
>
> ==> security_group.log <==
> 2023-11-15 23:00:13,762 - Executing command: destroy_network_rules_for_vm
> 2023-11-15 23:00:13,763 - iptables-save | awk
> '/BF(.*)physdev-is-bridged(.*)i-4-218-def/ { sub(/-A/, "-D", $1) ; print }'
> 2023-11-15 23:00:13,775 - ip6tables-save | awk
> '/BF(.*)physdev-is-bridged(.*)i-4-218-def/ { sub(/-A/, "-D", $1) ; print }'
> 2023-11-15 23:00:13,787 - ebtables -t nat -L PREROUTING | grep i-4-218-VM
> 2023-11-15 23:00:13,800 - Command exited non-zero: ebtables -t nat -L
> PREROUTING | grep i-4-218-VM
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'ebtables -t nat -L PREROUTING |
> grep i-4-218-VM' returned non-zero exit status 1.
> 2023-11-15 23:00:13,803 - ebtables -t nat -L POSTROUTING | grep i-4-218-VM
> 2023-11-15 23:00:13,816 - Command exited non-zero: ebtables -t nat -L
> POSTROUTING | grep i-4-218-VM
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'ebtables -t nat -L POSTROUTING |
> grep i-4-218-VM' returned non-zero exit status 1.
> 2023-11-15 23:00:13,816 - ebtables -t nat -F i-4-218-VM-in
> 2023-11-15 23:00:13,827 - Command exited non-zero: ebtables -t nat -F
> i-4-218-VM-in
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'ebtables -t nat -F i-4-218-VM-in'
> returned non-zero exit status 1.
> 2023-11-15 23:00:13,828 - Ignoring failure to delete ebtables chain for vm
> i-4-218-VM
> 2023-11-15 23:00:13,828 - ebtables -t nat -F i-4-218-VM-out
> 2023-11-15 23:00:13,840 - Command exited non-zero: ebtables -t nat -F
> i-4-218-VM-out
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'ebtables -t nat -F i-4-218-VM-out'
> returned non-zero exit status 1.
> 2023-11-15 23:00:13,840 - Ignoring failure to delete ebtables chain for vm
> i-4-218-VM
> 2023-11-15 23:00:13,840 - ebtables -t nat -F i-4-218-VM-in-ips
> 2023-11-15 23:00:13,852 - Command exited non-zero: ebtables -t nat -F
> i-4-218-VM-in-ips
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'ebtables -t nat -F
> i-4-218-VM-in-ips' returned non-zero exit status 1.
> 2023-11-15 23:00:13,853 - Ignoring failure to delete ebtables chain for vm
> i-4-218-VM
> 2023-11-15 23:00:13,853 - ebtables -t nat -F i-4-218-VM-out-ips
> 2023-11-15 23:00:13,864 - Command exited non-zero: ebtables -t nat -F
> i-4-218-VM-out-ips
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'ebtables -t nat -F
> i-4-218-VM-out-ips' returned non-zero exit status 1.
> 2023-11-15 23:00:13,864 - Ignoring failure to delete ebtables chain for vm
> i-4-218-VM
> 2023-11-15 23:00:13,864 - ebtables -t nat -F i-4-218-VM-in-src
> 2023-11-15 23:00:13,875 - Command exited non-zero: ebtables -t nat -F
> i-4-218-VM-in-src
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'ebtables -t nat -F
> i-4-218-VM-in-src' returned non-zero exit status 1.
> 2023-11-15 23:00:13,876 - Ignoring failure to delete ebtables chain for vm
> i-4-218-VM
> 2023-11-15 23:00:13,876 - ebtables -t nat -F i-4-218-VM-out-dst
> 2023-11-15 23:00:13,887 - Command exited non-zero: ebtables -t nat -F
> i-4-218-VM-out-dst
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'ebtables -t nat -F
> i-4-218-VM-out-dst' returned non-zero exit status 1.
> 2023-11-15 23:00:13,888 - Ignoring failure to delete ebtables chain for vm
> i-4-218-VM
> 2023-11-15 23:00:13,888 - iptables -F i-4-218-def
> 2023-11-15 23:00:13,896 - Command exited non-zero: iptables -F i-4-218-def
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'iptables -F i-4-218-def' returned
> non-zero exit status 1.
> 2023-11-15 23:00:13,897 - Ignoring failure to flush chain: i-4-218-def
> 2023-11-15 23:00:13,897 - iptables -F i-4-218-VM
> 2023-11-15 23:00:13,906 - Command exited non-zero: iptables -F i-4-218-VM
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'iptables -F i-4-218-VM' returned
> non-zero exit status 1.
> 2023-11-15 23:00:13,907 - Ignoring failure to flush chain: i-4-218-VM
> 2023-11-15 23:00:13,907 - iptables -F i-4-218-VM-eg
> 2023-11-15 23:00:13,915 - Command exited non-zero: iptables -F
> i-4-218-VM-eg
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'iptables -F i-4-218-VM-eg'
> returned non-zero exit status 1.
> 2023-11-15 23:00:13,916 - Ignoring failure to flush chain: i-4-218-VM-eg
> 2023-11-15 23:00:13,916 - iptables -X i-4-218-def
>
> ==> agent.log <==
> 2023-11-15 23:00:13,916 INFO [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) (logid:5281116a) Trying to fetch storage pool
> b221bcf2-819c-37c7-b007-bf7749ab468b from libvirt
>
> ==> security_group.log <==
> 2023-11-15 23:00:13,925 - Command exited non-zero: iptables -X i-4-218-def
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'iptables -X i-4-218-def' returned
> non-zero exit status 1.
> 2023-11-15 23:00:13,925 - Ignoring failure to delete chain: i-4-218-def
> 2023-11-15 23:00:13,926 - iptables -X i-4-218-VM
> 2023-11-15 23:00:13,934 - Command exited non-zero: iptables -X i-4-218-VM
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'iptables -X i-4-218-VM' returned
> non-zero exit status 1.
> 2023-11-15 23:00:13,935 - Ignoring failure to delete chain: i-4-218-VM
> 2023-11-15 23:00:13,935 - iptables -X i-4-218-VM-eg
> 2023-11-15 23:00:13,943 - Command exited non-zero: iptables -X
> i-4-218-VM-eg
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'iptables -X i-4-218-VM-eg'
> returned non-zero exit status 1.
> 2023-11-15 23:00:13,944 - Ignoring failure to delete chain: i-4-218-VM-eg
> 2023-11-15 23:00:13,944 - ipset -F i-4-218-VM
> 2023-11-15 23:00:13,951 - Command exited non-zero: ipset -F i-4-218-VM
> Traceback (most recent call last):
> File
> "/usr/share/cloudstack-common/scripts/vm/network/security_group.py", line
> 53, in execute
> return check_output(cmd, shell=True).decode()
> File "/usr/lib64/python3.9/subprocess.py", line 424, in check_output
> return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
> File "/usr/lib64/python3.9/subprocess.py", line 528, in run
> raise CalledProcessError(retcode, process.args,
> subprocess.CalledProcessError: Command 'ipset -F i-4-218-VM' returned
> non-zero exit status 1.
> 2023-11-15 23:00:13,952 - Ignoring failure to delete ipset i-4-218-VM
> 2023-11-15 23:00:13,952 - Failed to delete rule log file
> /var/run/cloud/i-4-218-VM.log
> 2023-11-15 23:00:13,952 - Failed to delete rule log file
> /var/run/cloud/i-4-218-VM.ip
>
> Any clues on how to debug this? All my other instances are working fine.
> I’ve restarted libvirtd, agent, management.
>
> Thanks
> -jeremy
>
>
>
>
