Bug 1467702 - MergeVDS method failed with 'Virtual machine does not exist'
MergeVDS method failed with 'Virtual machine does not exist'
Status: VERIFIED
Product: ovirt-engine
Classification: oVirt
Component: BLL.Storage (Show other bugs)
4.2.0
Unspecified Unspecified
unspecified Severity medium (vote)
: ovirt-4.2.0
: ---
Assigned To: Ala Hino
Lilach Zitnitski
: Automation
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-07-04 12:41 EDT by Raz Tamir
Modified: 2017-11-06 07:46 EST (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:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Storage
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
rule-engine: ovirt‑4.2+


Attachments (Terms of Use)
engine and vdsm logs (5.86 MB, application/x-gzip)
2017-07-04 12:41 EDT, Raz Tamir
no flags Details

  None (edit)
Description Raz Tamir 2017-07-04 12:41:32 EDT
Created attachment 1294294 [details]
engine and vdsm logs

Description of problem:
After a successful LSM, the live merge operation fails with Engine exception thrown while sending merge command: org.ovirt.engine.core.common.errors.EngineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Virtual machine does not exist: {'vmId': 'f10e059b-0641-4bb1-975f-2c4d131dbc49'}, code = 1 (Failed with error noVM and code 1)

Happened once, so far, as far as I know.

I don't know if this is related but from the vdsm.log, the Live snapshot before the LSM operation should start with freezing the guest and after thaw it - it failed in both operation but the live snapshot succeded:

2017-06-29 15:39:51,700+0300 INFO  (jsonrpc/1) [virt.vm] (vmId='f10e059b-0641-4bb1-975f-2c4d131dbc49') Freezing guest filesystems (vm:3657)
2017-06-29 15:39:51,701+0300 WARN  (jsonrpc/1) [virt.vm] (vmId='f10e059b-0641-4bb1-975f-2c4d131dbc49') Unable to freeze guest filesystems: Guest agent is not responding: QEMU guest agent is not connected (vm:3662)
2017-06-29 15:39:51,701+0300 INFO  (jsonrpc/1) [vdsm.api] FINISH freeze return={'status': {'message': 'Guest agent is not responding: QEMU guest agent is not connected', 'code': 19}} from=::ffff:10.35.69.94,49954, flow_id=disks_syncAction_c23240ca-de09-4c8e (api:52)
2017-06-29 15:39:51,702+0300 INFO  (jsonrpc/1) [virt.vm] (vmId='f10e059b-0641-4bb1-975f-2c4d131dbc49') Taking a live snapshot (drives=vda, memory=True) (vm:3877)
2017-06-29 15:39:51,825+0300 INFO  (jsonrpc/1) [virt.vm] (vmId='f10e059b-0641-4bb1-975f-2c4d131dbc49') Completed live snapshot (vm:3879)
2017-06-29 15:39:51,825+0300 INFO  (jsonrpc/1) [vdsm.api] START thaw() from=::ffff:10.35.69.94,49954, flow_id=disks_syncAction_c23240ca-de09-4c8e (api:46)
2017-06-29 15:39:51,825+0300 INFO  (jsonrpc/1) [virt.vm] (vmId='f10e059b-0641-4bb1-975f-2c4d131dbc49') Thawing guest filesystems (vm:3681)
2017-06-29 15:39:51,826+0300 WARN  (jsonrpc/1) [virt.vm] (vmId='f10e059b-0641-4bb1-975f-2c4d131dbc49') Unable to thaw guest filesystems: Guest agent is not responding: QEMU guest agent is not connected (vm:3686)
2017-06-29 15:39:51,827+0300 INFO  (jsonrpc/1) [vdsm.api] FINISH thaw return={'status': {'message': 'Guest agent is not responding: QEMU guest agent is not connected', 'code': 19}} from=::ffff:10.35.69.94,49954, flow_id=disks_syncAction_c23240ca-de09-4c8e (api:52)



From engine.log:

2017-06-29 15:43:42,466+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-6) [disks_syncAction_c23240ca-de09-4c8e] START, MergeVDSCommand(HostName = host_mixed_1, MergeVDSCommandParameters:{hostId='13b43759-2cb8-44eb-8682-ad2fe5631900', vmId='f10e059b-0641-4bb1-975f-2c4d131dbc49', storagePoolId='bd907a90-1c67-42b5-8d85-7d36608c74c1', storageDomainId='b1789112-86d0-47e2-bb1c-8f4aa69fd112', imageGroupId='acdd7fb8-9dbd-4dd0-bc81-1f28dbc520a2', imageId='01229980-8a03-410e-8056-5dd8e69b813d', baseImageId='72b21d13-d3d3-448b-b476-f8897f298d4b', topImageId='01229980-8a03-410e-8056-5dd8e69b813d', bandwidth='0'}), log id: 64a1f1b5
2017-06-29 15:43:42,470+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-6) [disks_syncAction_c23240ca-de09-4c8e] Failed in 'MergeVDS' method
2017-06-29 15:43:42,481+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-5-thread-6) [disks_syncAction_c23240ca-de09-4c8e] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command MergeVDS failed: Virtual machine does not exist: {'vmId': 'f10e059b-0641-4bb1-975f-2c4d131dbc49'}
2017-06-29 15:43:42,481+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-6) [disks_syncAction_c23240ca-de09-4c8e] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand' return value 'StatusOnlyReturn [status=Status [code=1, message=Virtual machine does not exist: {'vmId': 'f10e059b-0641-4bb1-975f-2c4d131dbc49'}]]'
2017-06-29 15:43:42,481+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-6) [disks_syncAction_c23240ca-de09-4c8e] HostName = host_mixed_1
2017-06-29 15:43:42,481+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-6) [disks_syncAction_c23240ca-de09-4c8e] Command 'MergeVDSCommand(HostName = host_mixed_1, MergeVDSCommandParameters:{hostId='13b43759-2cb8-44eb-8682-ad2fe5631900', vmId='f10e059b-0641-4bb1-975f-2c4d131dbc49', storagePoolId='bd907a90-1c67-42b5-8d85-7d36608c74c1', storageDomainId='b1789112-86d0-47e2-bb1c-8f4aa69fd112', imageGroupId='acdd7fb8-9dbd-4dd0-bc81-1f28dbc520a2', imageId='01229980-8a03-410e-8056-5dd8e69b813d', baseImageId='72b21d13-d3d3-448b-b476-f8897f298d4b', topImageId='01229980-8a03-410e-8056-5dd8e69b813d', bandwidth='0'})' execution failed: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Virtual machine does not exist: {'vmId': 'f10e059b-0641-4bb1-975f-2c4d131dbc49'}, code = 1
2017-06-29 15:43:42,481+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-6) [disks_syncAction_c23240ca-de09-4c8e] FINISH, MergeVDSCommand, log id: 64a1f1b5
2017-06-29 15:43:42,481+03 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-5-thread-6) [disks_syncAction_c23240ca-de09-4c8e] Engine exception thrown while sending merge command: org.ovirt.engine.core.common.errors.EngineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Virtual machine does not exist: {'vmId': 'f10e059b-0641-4bb1-975f-2c4d131dbc49'}, code = 1 (Failed with error noVM and code 1)

from vdsm.log:

2017-06-29 15:43:38,703+0300 ERROR (jsonrpc/1) [api] FINISH destroy error=Virtual machine does not exist: {'vmId': 'f10e059b-0641-4bb1-975f-2c4d131dbc49'} (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/share/vdsm/API.py", line 306, in destroy
    res = self.vm.destroy(gracefulAttempts)
  File "/usr/share/vdsm/API.py", line 134, in vm
    raise exception.NoSuchVM(vmId=self._UUID)
NoSuchVM: Virtual machine does not exist: {'vmId': 'f10e059b-0641-4bb1-975f-2c4d131dbc49'}
2017-06-29 15:43:38,704+0300 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call VM.destroy failed (error 1) in 0.00 seconds (__init__:583)
2017-06-29 15:43:42,468+0300 ERROR (jsonrpc/3) [api] FINISH merge error=Virtual machine does not exist: {'vmId': 'f10e059b-0641-4bb1-975f-2c4d131dbc49'} (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/share/vdsm/API.py", line 670, in merge
    return self.vm.merge(
  File "/usr/share/vdsm/API.py", line 134, in vm
    raise exception.NoSuchVM(vmId=self._UUID)
NoSuchVM: Virtual machine does not exist: {'vmId': 'f10e059b-0641-4bb1-975f-2c4d131dbc49'}
2017-06-29 15:43:42,469+0300 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call VM.merge failed (error 1) in 0.01 seconds (__init__:583)

Version-Release number of selected component (if applicable):
vdsm-4.20.1-89.git2912779.el7.centos.x86_64
ovirt-engine-4.2.0-0.0.master.20170627181935.git9424f9b.el7.centos.noarch
Red Hat Enterprise Linux Server 7.4 Beta

How reproducible:
Don't know - saw it once so far

Steps to Reproduce:
1. Perform LSM
2.
3.

Actual results:


Expected results:


Additional info:
Comment 1 Ala Hino 2017-10-30 03:52:39 EDT
Raz,

Is this a manual test or automation test?
Comment 2 Raz Tamir 2017-10-30 05:11:29 EDT
Ala,

Automation test
Comment 3 Ala Hino 2017-10-30 05:15:43 EDT
(In reply to Raz Tamir from comment #2)
> Ala,
> 
> Automation test

Thanks.

Are you still running this test or it is marked as broken?
If marked as broken, can you please unmark it? I'd like to see whether we still get this error with the latest patches.
Comment 4 Raz Tamir 2017-10-30 05:54:09 EDT
It is not marked as broken as it was observed only once (see description comment #0).

I think we don't see it anymore
Comment 5 Ala Hino 2017-10-30 06:41:12 EDT
(In reply to Raz Tamir from comment #4)
> It is not marked as broken as it was observed only once (see description
> comment #0).
> 
> I think we don't see it anymore

In this case, I'll move the bug to ON_QA and if you see it again, please re-open and provide the bugs. Thanks
Comment 6 Lilach Zitnitski 2017-10-30 12:35:13 EDT
--------------------------------------
Tested with the following code:
----------------------------------------
ovirt-engine-4.2.0-0.0.master.20171027213842.gitded437c.el7.centos.noarch
vdsm-4.20.4-12.git11d6d3d.el7.centos.x86_64

Tested with the following scenario:

Steps to Reproduce:
1. Perform LSM
2. 

Actual results:
LSM test passed with no errors or failures

Expected results:

Moving to VERIFIED!

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