Destroy vm API errors with failure to delete ConfigDrive #7428
Description
ISSUE TYPE
- Bug Report
COMPONENT NAME
API
CLOUDSTACK VERSION
4.16
OS / ENVIRONMENT
Host and Guest running RHEL 8.x on KVM hypervisor
SUMMARY
CAPC creates and deletes VM depending on user requests and configuration. On occasions, the delete API calls is not successful. The API returns success, but the VM does not get deleted. CAPC issues Delete VM call and waits for the VM to be deleted. On debugging the issue more, cloudstack logs show exceptions in deleting config drive for the vm. Cloudstack logs below.
2023-01-14 04:35:34,842 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-118:ctx-8528bb01 job-55****/job-55**** ctx-f09653a3) (logid:******) VM is already stopped: VM instance {id: "5436", name: "i-212-5436-VM", uuid: "****REDACTED******", type="User"}
2023-01-14 00:01:23,150 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-117:ctx-bb191bb8 job-54****) (logid:*****) Unexpected exception while executing org.apache.cloudstack.api.command.user.vm.DestroyVMCmd com.cloud.utils.exception.CloudRuntimeException: Unable to get an answer to handle config drive deletion for vm: i-212-5436-VM on host: 804 at com.cloud.network.element.ConfigDriveNetworkElement.deleteConfigDriveIsoOnHostCache(ConfigDriveNetworkElement.java:577) at com.cloud.network.element.ConfigDriveNetworkElement.deleteConfigDriveIso(ConfigDriveNetworkElement.java:665) at com.cloud.network.element.ConfigDriveNetworkElement.postStateTransitionEvent(ConfigDriveNetworkElement.java:322) at com.cloud.network.element.ConfigDriveNetworkElement.postStateTransitionEvent(ConfigDriveNetworkElement.java:90)
2023-01-14 04:37:45,034 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-10:ctx-32e2ec2b job-55***) (logid:*****) Complete async job-55***, jobStatus: FAILED, resultCode: 530, result: org.apache.cloud
stack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Unable to destroy VM instance {id: "5436", name: "i-212-5436-VM", uuid: "****REDACTED******", type="User"} due to [Unable to transition to a new state from Expunging via DestroyRequested]."}
2023-01-14 04:37:44,952 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:*****) Request:Seq 804-6595240179307385555: { Cmd , MgmtId: ***********, via: 804, Ver: v1, Flags: 100011, [{"com.cloud.a gent.api.HandleConfigDriveIsoCommand":{"isoFile":"configdrive/i-212-5436-VM.iso","create":"false","useHostCacheOnUnsupportedPool":"false","preferHostCache":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2023-01-14 04:37:44,952 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:*****) Processing command: com.cloud.agent.api.HandleConfigDriveIsoCommand
2023-01-14 04:37:44,952 DEBUG [kvm.resource.ComputingResource] (agentRequest-Handler-1:null) (logid:********) ComputingResource routing command to LibvirtComputingResource
2023-01-14 04:37:44,952 DEBUG [resource.wrapper.LibvirtHandleConfigDriveCommandWrapper] (agentRequest-Handler-1:null) (logid:*****) Deleting config drive: configdrive/i-212-5436-VM.iso
2023-01-14 04:37:44,953 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:******) Seq 804-6595240179307385555: { Ans: , MgmtId: ************, via: 804, Ver: v1, Flags: 10, [{"com.cloud.agent.api.HandleConfigDriveIsoAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2023-01-14 04:37:48,212 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:*****) Request:Seq 804-6595240179307385556: { Cmd , MgmtId: ********, via: 804, Ver: v1, Flags: 100011, [{"com.cloud.a gent.api.HandleConfigDriveIsoCommand":{"isoFile":"configdrive/i-212-5436-VM.iso","create":"false","useHostCacheOnUnsupportedPool":"false","preferHostCache":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2023-01-14 04:37:48,212 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:*****) Processing command: com.cloud.agent.api.HandleConfigDriveIsoCommand
2023-01-14 04:37:48,212 DEBUG [kvm.resource.ComputingResource] (agentRequest-Handler-2:null) (logid:*******) ComputingResource routing command to LibvirtComputingResource
2023-01-14 04:37:48,212 DEBUG [resource.wrapper.LibvirtHandleConfigDriveCommandWrapper] (agentRequest-Handler-2:null) (logid:*****) Deleting config drive: configdrive/i-212-5436-VM.iso
2023-01-14 04:37:48,213 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:*******) Seq 804-6595240179307385556: { Ans: , MgmtId: ********, via: 804, Ver: v1, Flags: 10, [{"com.cloud.agent.api.HandleConfigDriveIsoAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
If I request a delete VM on the UI, Cloudstack proceeds to delete the VM properly. API call used by CAPC is destroyVirtualMachine.
STEPS TO REPRODUCE
1 out of every 30-40 destroy VM API hits this issue.