This service will be undergoing maintenance at 00:00 UTC, 2017-10-23 It is expected to last about 30 minutes
Bug 1478712 - Power-off VM via the engine, raise Traceback in the vdsm log
Power-off VM via the engine, raise Traceback in the vdsm log
Status: CLOSED NOTABUG
Product: vdsm
Classification: oVirt
Component: Core (Show other bugs)
4.20.0
x86_64 Linux
medium Severity medium (vote)
: ovirt-4.2.0
: ---
Assigned To: Milan Zamazal
Raz Tamir
: Regression
: 1478715 (view as bug list)
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-08-06 08:27 EDT by Artyom
Modified: 2017-08-28 05:07 EDT (History)
4 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2017-08-24 10:30:43 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Virt
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
rule-engine: ovirt‑4.2+
rule-engine: blocker+


Attachments (Terms of Use)
vdsm log (5.93 MB, text/plain)
2017-08-06 08:27 EDT, Artyom
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 81085 master POST API: Don't log tracebacks on non-existent VMs 2017-08-28 05:01 EDT

  None (edit)
Description Artyom 2017-08-06 08:27:05 EDT
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)
Comment 1 Red Hat Bugzilla Rules Engine 2017-08-07 00:57:27 EDT
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.
Comment 2 Milan Zamazal 2017-08-07 08:46:43 EDT
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.
Comment 3 Tomas Jelinek 2017-08-09 03:41:39 EDT
*** Bug 1478715 has been marked as a duplicate of this bug. ***
Comment 4 Tomas Jelinek 2017-08-24 10:30:43 EDT
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.
Comment 5 Artyom 2017-08-26 16:32:14 EDT
But can we at least catch the Traceback and give a more friendly message, because now this Traceback overflow whole vdsm log.
Comment 6 Milan Zamazal 2017-08-28 05:07:42 EDT
Indeed, we probably needn't to log tracebacks in similar situations, patch posted.

Note You need to log in before you can comment on or make changes to this bug.