Created attachment 1309649 [details] vdsm log Description of problem: Power-off VM via the engine, raise Traceback in the vdsm log 2017-08-06 15:19:44,002+0300 ERROR (jsonrpc/3) [api] FINISH destroy error=Virtual machine does not exist: {'vmId': u'4854aff0-263e-43e9-ac83-6e55f5d49ef7'} (api:119) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 117, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/API.py", line 301, in destroy res = self.vm.destroy(gracefulAttempts) File "/usr/lib/python2.7/site-packages/vdsm/API.py", line 129, in vm raise exception.NoSuchVM(vmId=self._UUID) NoSuchVM: Virtual machine does not exist: {'vmId': u'4854aff0-263e-43e9-ac83-6e55f5d49ef7'} Version-Release number of selected component (if applicable): vdsm-4.20.1-269.git4afc67d.el7.centos.x86_64 How reproducible: Always Steps to Reproduce: 1. Start VM via the engine 2. Wait until the VM will have state UP 3. Power-off the VM Actual results: Power-off action succeeded and VM destroyed, but I can see Traceback under the vdsm.log Expected results: Power-off action succeeded and VM destroyed without any Traceback in vdsm log Additional info: Looks like VDSM runs two concurrent JSON requests to destroy VDSM, I checked the VDSM log in 4.1 and I can see, two destroy commands outputs for the same VM 2017-08-06 15:13:01,209+0300 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call VM.destroy succeeded in 3.25 seconds (__init__:539) 2017-08-06 15:13:03,242+0300 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call VM.destroy failed (error 1) in 0.00 seconds (__init__:539)
This bug report has Keywords: Regression or TestBlocker. Since no regressions or test blockers are allowed between releases, it is also being identified as a blocker for this release. Please resolve ASAP.
I think what happens here is: Engine calls Destroy to power off the VM. Vdsm destroys the VM and sends an event to Engine about the VM being down. Then Engine calls another Destroy on the VM and that raises the exception since the VM has already been destroyed by the first Destroy call. I'm not sure which of the actions is superfluous and should be avoided to prevent the error.
*** Bug 1478715 has been marked as a duplicate of this bug. ***
This is actually not a bug. When the monitoring realizes that the VM has been turned to down, first thing it does is to call destroy on it to make sure it will get cleaned up properly. It is indeed redundant in this case but does not cause any harm (other than an ugly looking error in log). But in other cases (such as shutdown from inside of guest) this destroy needs to be called to make sure the VM will not appear back again as an external VM. We could theoretically exclude this call to destroy in some cases but it would complicate the code and would risk regressions. Since the outcome is not harmful at all, I will close this bug. If it is for some reason an important issue for you, please feel free to reopen it.
But can we at least catch the Traceback and give a more friendly message, because now this Traceback overflow whole vdsm log.
Indeed, we probably needn't to log tracebacks in similar situations, patch posted.