weizhouapache commented on issue #5347:
URL: https://github.com/apache/cloudstack/issues/5347#issuecomment-902696372
> @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 !
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscr...@cloudstack.apache.org
For queries about this service, please contact Infrastructure at:
us...@infra.apache.org
