Cannot delete volume in Destroy state not attached to Instance

[kricud]

ISSUE TYPE

• Bug Report

COMPONENT NAME

UI

CLOUDSTACK VERSION

4.15.1

CONFIGURATION

OS / ENVIRONMENT

SUMMARY

Can’t delete volume in Destroy state not attached to Instance

STEPS TO REPRODUCE

I have approximately 500~ of them in Destroy state. I have randomly tried to delete 10~ 
and they all are producing error that it can’t be done. Common thing for them all is that they don’t 
have VM Name associated with them.

EXPECTED RESULTS

Volume gets deleted

ACTUAL RESULTS

Volume is not deleted

[weizhouapache]

@kricud
are the volumes attached to vms which have been expunged ?

[weizhouapache]

linked to #4902

[kricud]

@weizhouapache no
There as some dinosaurs in list from 2014/15

[weizhouapache]

@kricud
this looks like not normal states.
are you able to find some logs when the vms (for example id=30613) were destroyed ?

we can fix the bug in future release.
if you can make sure that vms are expunged and want to delete the volumes for now , you can update the instance_id to NULL in volumes table in database for these volumes. then you should be able to delete the volumes.

[slavkap]

@weizhouapache, if this could help you I was able to reproduce the issue. Probably there are different scenarios, but here is mine:
I've tried on a zone with one KVM hypervisor

steps to reproduce:

• deploy VM
• stop the VM
• stop the hypervisor
• the VR is still running in UI and before the health check destroy the VM with expunge=true

I took the most important thing out of the log:

./vmops.log:2825614:2021-08-20 15:25:06,299 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973) (logid:c39d8401) Executing AsyncJobVO {id:73973, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 5251, cmd: org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin, cmdInfo: {"response":"json","ctxUserId":"2","expunge":"true","httpmethod":"GET","ctxStartEventId":"141616","id":"031fa342-95b9-4b1b-89d8-8012981db2ad","volumeids":"","ctxDetails":"{"interface com.cloud.vm.VirtualMachine":"031fa342-95b9-4b1b-89d8-8012981db2ad"}","ctxAccountId":"2","uuid":"031fa342-95b9-4b1b-89d8-8012981db2ad","cmdEventType":"VM.DESTROY","_":"1629461485053"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2199191159196, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
./vmops.log:2825617:2021-08-20 15:25:06,315 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Checking if there are any ongoing snapshots on the ROOT volumes associated with VM with ID 5251
./vmops.log:2825618:2021-08-20 15:25:06,316 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Found 1 no. of volumes of type ROOT for vm with VM ID 5251
./vmops.log:2825619:2021-08-20 15:25:06,316 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Checking status of snapshots for Volume with Volume Id: 8854
./vmops.log:2825620:2021-08-20 15:25:06,317 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) The count of ongoing Snapshots for VM with ID 5251 and disk type ROOT is 0
./vmops.log:2825621:2021-08-20 15:25:06,317 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Found no ongoing snapshots on volume of type ROOT, for the vm with id 5251
./vmops.log:2825640:2021-08-20 15:25:07,160 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Destroying vm VM[User|i-2-5251-VM], expunge flag on
./vmops.log:2825669:2021-08-20 15:25:09,135 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-13:ctx-d75f058d job-73973/job-73975) (logid:c39d8401) Executing AsyncJobVO {id:73975, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo: rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAUg3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2199191159196, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Aug 20 15:25:07 EEST 2021, removed: null}
./vmops.log:2825670:2021-08-20 15:25:09,135 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-13:ctx-d75f058d job-73973/job-73975) (logid:c39d8401) Run VM work job: com.cloud.vm.VmWorkStop for VM 5251, job origin: 73973
./vmops.log:2825671:2021-08-20 15:25:09,137 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-13:ctx-d75f058d job-73973/job-73975 ctx-a1010988) (logid:c39d8401) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":5251,"handlerName":"VirtualMachineManagerImpl"}
./vmops.log:2825672:2021-08-20 15:25:09,139 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-13:ctx-d75f058d job-73973/job-73975 ctx-a1010988) (logid:c39d8401) VM is already stopped: VM[User|i-2-5251-VM]
./vmops.log:2825719:2021-08-20 15:25:11,159 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) VM state transitted from :Stopped to Destroyed with event: DestroyRequestedvm's original host id: 7 new host id: null host id before state transition: null
./vmops.log:2825723:2021-08-20 15:25:11,164 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) release mem from host: 7, old used: (1.75 GB) 1879048192,reserved: (512.00 MB) 536870912, total: (10.57 GB) 11354652672; new used: (1.75 GB) 1879048192,reserved:(0 bytes) 0; movedfromreserved: true,moveToReserveredfalse
./vmops.log:2825724:2021-08-20 15:25:11,169 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) VM state transitted from :Destroyed to Expunging with event: ExpungeOperationvm's original host id: 7 new host id: null host id before state transition: null
./vmops.log:2825725:2021-08-20 15:25:11,178 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Updating resource Type = user_vm count for Account = 2 Operation = decreasing Amount = 1
./vmops.log:2825726:2021-08-20 15:25:11,182 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Updating resource Type = cpu count for Account = 2 Operation = decreasing Amount = 1
./vmops.log:2825727:2021-08-20 15:25:11,187 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Updating resource Type = memory count for Account = 2 Operation = decreasing Amount = 512
./vmops.log:2825736:2021-08-20 15:25:13,137 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-15:ctx-024388a4 job-73973/job-73977) (logid:c39d8401) Run VM work job: com.cloud.vm.VmWorkStop for VM 5251, job origin: 73973
./vmops.log:2825738:2021-08-20 15:25:13,140 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-15:ctx-024388a4 job-73973/job-73977 ctx-64e7ce6e) (logid:c39d8401) Stopped called on VM[User|i-2-5251-VM] but the state is Expunging
./vmops.log:2825748:2021-08-20 15:25:13,157 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) VM state transitted from :Expunging to Expunging with event: ExpungeOperationvm's original host id: 7 new host id: null host id before state transition: null
./vmops.log:2825749:2021-08-20 15:25:13,161 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Destroying vm VM[User|i-2-5251-VM]
./vmops.log:2825750:2021-08-20 15:25:13,161 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Cleaning up NICS
./vmops.log:2825751:2021-08-20 15:25:13,161 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Cleaning network for vm: 5251
./vmops.log:2825752:2021-08-20 15:25:13,174 DEBUG [o.a.c.n.t.BasicNetworkTopology] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) REMOVING DHCP ENTRY RULE
./vmops.log:2825753:2021-08-20 15:25:13,175 DEBUG [o.a.c.n.t.BasicNetworkTopology] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Applying dhcp entry in network Ntwk[209|Guest|6]
./vmops.log:2825754:2021-08-20 15:25:13,193 WARN [o.a.c.n.t.BasicNetworkTopology] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Unable to apply dhcp entry on disconnected router r-5191-VM
./vmops.log:2825802:2021-08-20 15:25:13,203 DEBUG [o.a.c.n.t.BasicNetworkTopology] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Unable to apply dhcp entry on disconnected router r-5191-VM(5191)
./vmops.log:2825803:2021-08-20 15:25:13,203 ERROR [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Failed to remove dhcp-dns entry due to:
./vmops.log:2825845:2021-08-20 15:25:13,223 DEBUG [c.c.n.g.DirectNetworkGuru] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Deallocate network: networkId: 209, ip: 10.2.24.149
./vmops.log:2825846:2021-08-20 15:25:13,231 DEBUG [c.c.n.g.DirectNetworkGuru] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) remove nic 6683 secondary ip
./vmops.log:2825847:2021-08-20 15:25:13,234 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Removed nic id=6683
./vmops.log:2825848:2021-08-20 15:25:13,235 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Revoving nic secondary ip entry ...
./vmops.log:2825849:2021-08-20 15:25:13,236 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Cleaning up hypervisor data structures (ex. SRs in XenServer) for managed storage
./vmops.log:2825850:2021-08-20 15:25:13,243 DEBUG [o.a.c.e.o.VolumeOrchestrator] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Cleaning storage for vm: 5251
./vmops.log:2825851:2021-08-20 15:25:13,255 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Updating resource Type = volume count for Account = 2 Operation = decreasing Amount = 1
./vmops.log:2825852:2021-08-20 15:25:13,258 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Updating resource Type = primary_storage count for Account = 2 Operation = decreasing Amount = (8.00 GB) 8589934592
./vmops.log:2825853:2021-08-20 15:25:13,297 ERROR [o.a.c.s.d.d.CloudStackPrimaryDataStoreDriverImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) No remote endpoint to send DeleteCommand, check if host or ssvm is down?
./vmops.log:2825857:2021-08-20 15:25:13,303 WARN [o.a.c.s.d.ObjectInDataStoreManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@e2f71ca), no need to delete from object in store ref table
./vmops.log:2825859:2021-08-20 15:25:13,305 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Expunged VM[User|i-2-5251-VM]
./vmops.log:2825860:2021-08-20 15:25:13,305 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Starting cleaning up vm VM[User|i-2-5251-VM] resources...
./vmops.log:2825861:2021-08-20 15:25:13,309 INFO [c.c.n.s.SecurityGroupManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Disassociated 1 network groups from uservm 5251
./vmops.log:2825862:2021-08-20 15:25:13,312 DEBUG [c.c.n.s.SecurityGroupManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Security group mappings are removed successfully for vm id=5251
./vmops.log:2825863:2021-08-20 15:25:13,320 DEBUG [c.c.n.f.FirewallManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) No firewall rules are found for vm id=5251
./vmops.log:2825864:2021-08-20 15:25:13,324 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Firewall rules are removed successfully as a part of vm id=5251 expunge
./vmops.log:2825865:2021-08-20 15:25:13,326 DEBUG [c.c.n.r.RulesManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) No port forwarding rules are found for vm id=5251
./vmops.log:2825866:2021-08-20 15:25:13,326 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Port forwarding rules are removed successfully as a part of vm id=5251 expunge
./vmops.log:2825867:2021-08-20 15:25:13,327 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Removed vm id=5251 from all load balancers as a part of expunge process
./vmops.log:2825868:2021-08-20 15:25:13,328 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Successfully cleaned up vm VM[User|i-2-5251-VM] resources as a part of expunge process
./vmops.log:2825869:2021-08-20 15:25:13,339 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Complete async job-73973, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmResponse/null/{"securitygroup":[],"nic":[],"affinitygroup":[],"tags":[]}

[weizhouapache]

@weizhouapache, if this could help you I was able to reproduce the issue. Probably there are different scenarios, but here is mine:
I've tried on a zone with one KVM hypervisor

steps to reproduce:

• deploy VM
• stop the VM
• stop the hypervisor
• the VR is still running in UI and before the health check destroy the VM with expunge=true

I took the most important thing out of the log:

./vmops.log:2825614:2021-08-20 15:25:06,299 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973) (logid:c39d8401) Executing AsyncJobVO {id:73973, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 5251, cmd: org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin, cmdInfo: {"response":"json","ctxUserId":"2","expunge":"true","httpmethod":"GET","ctxStartEventId":"141616","id":"031fa342-95b9-4b1b-89d8-8012981db2ad","volumeids":"","ctxDetails":"{"interface com.cloud.vm.VirtualMachine":"031fa342-95b9-4b1b-89d8-8012981db2ad"}","ctxAccountId":"2","uuid":"031fa342-95b9-4b1b-89d8-8012981db2ad","cmdEventType":"VM.DESTROY","_":"1629461485053"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2199191159196, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
./vmops.log:2825617:2021-08-20 15:25:06,315 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Checking if there are any ongoing snapshots on the ROOT volumes associated with VM with ID 5251
./vmops.log:2825618:2021-08-20 15:25:06,316 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Found 1 no. of volumes of type ROOT for vm with VM ID 5251
./vmops.log:2825619:2021-08-20 15:25:06,316 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Checking status of snapshots for Volume with Volume Id: 8854
./vmops.log:2825620:2021-08-20 15:25:06,317 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) The count of ongoing Snapshots for VM with ID 5251 and disk type ROOT is 0
./vmops.log:2825621:2021-08-20 15:25:06,317 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Found no ongoing snapshots on volume of type ROOT, for the vm with id 5251
./vmops.log:2825640:2021-08-20 15:25:07,160 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Destroying vm VM[User|i-2-5251-VM], expunge flag on
./vmops.log:2825669:2021-08-20 15:25:09,135 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-13:ctx-d75f058d job-73973/job-73975) (logid:c39d8401) Executing AsyncJobVO {id:73975, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo: rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAUg3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2199191159196, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Aug 20 15:25:07 EEST 2021, removed: null}
./vmops.log:2825670:2021-08-20 15:25:09,135 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-13:ctx-d75f058d job-73973/job-73975) (logid:c39d8401) Run VM work job: com.cloud.vm.VmWorkStop for VM 5251, job origin: 73973
./vmops.log:2825671:2021-08-20 15:25:09,137 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-13:ctx-d75f058d job-73973/job-73975 ctx-a1010988) (logid:c39d8401) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":5251,"handlerName":"VirtualMachineManagerImpl"}
./vmops.log:2825672:2021-08-20 15:25:09,139 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-13:ctx-d75f058d job-73973/job-73975 ctx-a1010988) (logid:c39d8401) VM is already stopped: VM[User|i-2-5251-VM]
./vmops.log:2825719:2021-08-20 15:25:11,159 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) VM state transitted from :Stopped to Destroyed with event: DestroyRequestedvm's original host id: 7 new host id: null host id before state transition: null
./vmops.log:2825723:2021-08-20 15:25:11,164 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) release mem from host: 7, old used: (1.75 GB) 1879048192,reserved: (512.00 MB) 536870912, total: (10.57 GB) 11354652672; new used: (1.75 GB) 1879048192,reserved:(0 bytes) 0; movedfromreserved: true,moveToReserveredfalse
./vmops.log:2825724:2021-08-20 15:25:11,169 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) VM state transitted from :Destroyed to Expunging with event: ExpungeOperationvm's original host id: 7 new host id: null host id before state transition: null
./vmops.log:2825725:2021-08-20 15:25:11,178 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Updating resource Type = user_vm count for Account = 2 Operation = decreasing Amount = 1
./vmops.log:2825726:2021-08-20 15:25:11,182 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Updating resource Type = cpu count for Account = 2 Operation = decreasing Amount = 1
./vmops.log:2825727:2021-08-20 15:25:11,187 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Updating resource Type = memory count for Account = 2 Operation = decreasing Amount = 512
./vmops.log:2825736:2021-08-20 15:25:13,137 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-15:ctx-024388a4 job-73973/job-73977) (logid:c39d8401) Run VM work job: com.cloud.vm.VmWorkStop for VM 5251, job origin: 73973
./vmops.log:2825738:2021-08-20 15:25:13,140 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-15:ctx-024388a4 job-73973/job-73977 ctx-64e7ce6e) (logid:c39d8401) Stopped called on VM[User|i-2-5251-VM] but the state is Expunging
./vmops.log:2825748:2021-08-20 15:25:13,157 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) VM state transitted from :Expunging to Expunging with event: ExpungeOperationvm's original host id: 7 new host id: null host id before state transition: null
./vmops.log:2825749:2021-08-20 15:25:13,161 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Destroying vm VM[User|i-2-5251-VM]
./vmops.log:2825750:2021-08-20 15:25:13,161 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Cleaning up NICS
./vmops.log:2825751:2021-08-20 15:25:13,161 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Cleaning network for vm: 5251
./vmops.log:2825752:2021-08-20 15:25:13,174 DEBUG [o.a.c.n.t.BasicNetworkTopology] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) REMOVING DHCP ENTRY RULE
./vmops.log:2825753:2021-08-20 15:25:13,175 DEBUG [o.a.c.n.t.BasicNetworkTopology] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Applying dhcp entry in network Ntwk[209|Guest|6]
./vmops.log:2825754:2021-08-20 15:25:13,193 WARN [o.a.c.n.t.BasicNetworkTopology] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Unable to apply dhcp entry on disconnected router r-5191-VM
./vmops.log:2825802:2021-08-20 15:25:13,203 DEBUG [o.a.c.n.t.BasicNetworkTopology] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Unable to apply dhcp entry on disconnected router r-5191-VM(5191)
./vmops.log:2825803:2021-08-20 15:25:13,203 ERROR [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Failed to remove dhcp-dns entry due to:
./vmops.log:2825845:2021-08-20 15:25:13,223 DEBUG [c.c.n.g.DirectNetworkGuru] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Deallocate network: networkId: 209, ip: 10.2.24.149
./vmops.log:2825846:2021-08-20 15:25:13,231 DEBUG [c.c.n.g.DirectNetworkGuru] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) remove nic 6683 secondary ip
./vmops.log:2825847:2021-08-20 15:25:13,234 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Removed nic id=6683
./vmops.log:2825848:2021-08-20 15:25:13,235 DEBUG [o.a.c.e.o.NetworkOrchestrator] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Revoving nic secondary ip entry ...
./vmops.log:2825849:2021-08-20 15:25:13,236 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Cleaning up hypervisor data structures (ex. SRs in XenServer) for managed storage
./vmops.log:2825850:2021-08-20 15:25:13,243 DEBUG [o.a.c.e.o.VolumeOrchestrator] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Cleaning storage for vm: 5251
./vmops.log:2825851:2021-08-20 15:25:13,255 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Updating resource Type = volume count for Account = 2 Operation = decreasing Amount = 1
./vmops.log:2825852:2021-08-20 15:25:13,258 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Updating resource Type = primary_storage count for Account = 2 Operation = decreasing Amount = (8.00 GB) 8589934592
./vmops.log:2825853:2021-08-20 15:25:13,297 ERROR [o.a.c.s.d.d.CloudStackPrimaryDataStoreDriverImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) No remote endpoint to send DeleteCommand, check if host or ssvm is down?
./vmops.log:2825857:2021-08-20 15:25:13,303 WARN [o.a.c.s.d.ObjectInDataStoreManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@e2f71ca), no need to delete from object in store ref table
./vmops.log:2825859:2021-08-20 15:25:13,305 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Expunged VM[User|i-2-5251-VM]
./vmops.log:2825860:2021-08-20 15:25:13,305 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Starting cleaning up vm VM[User|i-2-5251-VM] resources...
./vmops.log:2825861:2021-08-20 15:25:13,309 INFO [c.c.n.s.SecurityGroupManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Disassociated 1 network groups from uservm 5251
./vmops.log:2825862:2021-08-20 15:25:13,312 DEBUG [c.c.n.s.SecurityGroupManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Security group mappings are removed successfully for vm id=5251
./vmops.log:2825863:2021-08-20 15:25:13,320 DEBUG [c.c.n.f.FirewallManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) No firewall rules are found for vm id=5251
./vmops.log:2825864:2021-08-20 15:25:13,324 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Firewall rules are removed successfully as a part of vm id=5251 expunge
./vmops.log:2825865:2021-08-20 15:25:13,326 DEBUG [c.c.n.r.RulesManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) No port forwarding rules are found for vm id=5251
./vmops.log:2825866:2021-08-20 15:25:13,326 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Port forwarding rules are removed successfully as a part of vm id=5251 expunge
./vmops.log:2825867:2021-08-20 15:25:13,327 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Removed vm id=5251 from all load balancers as a part of expunge process
./vmops.log:2825868:2021-08-20 15:25:13,328 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Successfully cleaned up vm VM[User|i-2-5251-VM] resources as a part of expunge process
./vmops.log:2825869:2021-08-20 15:25:13,339 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:ctx-9584d93a job-73973 ctx-665e8981) (logid:c39d8401) Complete async job-73973, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmResponse/null/{"securitygroup":[],"nic":[],"affinitygroup":[],"tags":[]}

@slavkap nice, thanks for your info !

[weizhouapache]

@slavkap @kricud
I am able to reproduce the issue, following the steps provided by @slavkap

(I did not shutdown the host, but stop all cloudstack-agent instead).

[slavkap]

that's great, @weizhouapache :)

[kricud]

I’m confirming that all volume in Destroy state are from kvm.
I’m confident that all ACS servers and agents on all hosts where running when I did testing of this problem.
I will use suggestion from @weizhouapache deal with it.