Looks similar to bug 1597019 and and bug 1788464, Benny please note they might be duplicates

Created attachment 1694377 [details]
Logs

Happened again in our automation runs.
ovirt-engine-4.4.1.1-0.5.el8ev.noarch
vdsm-4.40.18-1.el8ev.x86_64

Attaching logs.

(In reply to Evelina Shames from comment #2)
> Created attachment 1694377 [details]
> Logs
> 
> Happened again in our automation runs.
> ovirt-engine-4.4.1.1-0.5.el8ev.noarch
> vdsm-4.40.18-1.el8ev.x86_64
> 
> Attaching logs.

please provide libvirt and qemu logs as well

Created attachment 1694379 [details]
Libvirt-logs

the vdsm log does not contain the error

Created attachment 1694384 [details]
vdsm-logs

(In reply to Benny Zlotnik from comment #5)
> the vdsm log does not contain the error

I'll add all vdsm logs that we have, the environment is not available anymore.

Created attachment 1694385 [details]
vdsm-logs

Created attachment 1694386 [details]
vdsm-logs

Lately we have many tests failing on this.

How reproducible:
~50%

Reproduction steps that I managed to reproduce the issue with:
1. Create a VM from template (RHEL 8.2)
2. Create 4 disks and add them to the VM:
- VirtIO-SCSI Thin
- VirtIO-SCSI Preallocated
- VirtIO Thin
- VirtIO Preallocated
3. Run the VM
4. Move all the VM disks concurrently to different iSCSI storage domain.
--> Do this several times, one of the attempts will fail.

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.

does this still reproduce with the same frequency in 4.4.3/8.3?

(In reply to Evelina Shames from comment #9)
> Lately we have many tests failing on this.
> 
> How reproducible:
> ~50%
> 
> Reproduction steps that I managed to reproduce the issue with:
> 1. Create a VM from template (RHEL 8.2)
> 2. Create 4 disks and add them to the VM:
> - VirtIO-SCSI Thin
> - VirtIO-SCSI Preallocated
> - VirtIO Thin
> - VirtIO Preallocated
> 3. Run the VM
> 4. Move all the VM disks concurrently to different iSCSI storage domain.
> --> Do this several times, one of the attempts will fail.

Reproduced again with these steps on:
vdsm-4.40.31-1.el8ev.x86_64
ovirt-engine-4.4.3.3-0.19.el8ev

Attaching engine, vdsm, libvirt and qemu logs.
let me know if you need anything else.

Created attachment 1717528 [details]
Logs_debug

(In reply to Evelina Shames from comment #13)
> Created attachment 1717528 [details]
> Logs_debug

Are these the right logs?
I only see this error:
VolumeImageHasChildren: Cannot delete volume which has children (non-ethical): [u'sdUUID: b182c581-4be4-4e5c-a65d-eebad47a6c23', u'imgUUID: b9a07815-d165-4a9d-87b3-e439d8e03ac8', u'volUUID: e2ba36c4-95cf-4589-9545-9659001e501f']

which is not related, and there are libvirt and qemu logs

Created attachment 1717572 [details]
full_logs_debug

(In reply to Benny Zlotnik from comment #14)
> (In reply to Evelina Shames from comment #13)
> > Created attachment 1717528 [details]
> > Logs_debug
> 
> Are these the right logs?
> I only see this error:
> VolumeImageHasChildren: Cannot delete volume which has children
> (non-ethical): [u'sdUUID: b182c581-4be4-4e5c-a65d-eebad47a6c23', u'imgUUID:
> b9a07815-d165-4a9d-87b3-e439d8e03ac8', u'volUUID:
> e2ba36c4-95cf-4589-9545-9659001e501f']
> 
> which is not related, and there are libvirt and qemu logs

Ohh sorry...
Attached this time the right logs.

I see the error is:
2020-09-29 15:44:31,784+0300 ERROR (jsonrpc/7) [virt.vm] (vmId='f3e3bba8-7bf8-4965-95a2-450d910af819') Unable to stop the replication for the drive: sdb (vm:4159)
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/virt/vm.py", line 4156, in diskReplicateFinish
    self._dom.blockJobAbort(drive.name, blockJobFlags)
  File "/usr/lib/python3.6/site-packages/vdsm/virt/virdomain.py", line 101, in f
    ret = attr(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdsm/common/libvirtconnection.py", line 131, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdsm/common/function.py", line 94, in wrapper
    return func(inst, *args, **kwargs)
  File "/usr/lib64/python3.6/site-packages/libvirt.py", line 888, in blockJobAbort
    if ret == -1: raise libvirtError ('virDomainBlockJobAbort() failed', dom=self)
libvirt.libvirtError: internal error: unable to execute QEMU command 'blockdev-add': Image is not in qcow2 format

Which is different than the original error in the bug

The most recent getInfo response I found on the relevant volume show that it is qcow2 (which it has to be since it's a snapshot)
2020-09-29 15:44:38,373+0300 INFO  (jsonrpc/2) [vdsm.api] START getVolumeInfo(sdUUID='98bce80e-1a06-4322-9f47-a83573e84cd4', spUUID='db771b4e-c7c3-4593-ae63-ce6c946604c2', imgUUID='8619d42c-e4b4-47a8-8ae7-7e780a079127', volUUID='a8161202-7494-46b3-beae-7fb763b5a855', options=None) from=::ffff:10.35.162.6,38426, flow_id=1d10eac4-e3bb-492e-a573-76f0280cf1bc, task_id=0a3b7feb-4b6b-48d2-864f-f8ad78b815c7 (api:48)

2020-09-29 15:44:38,411+0300 INFO  (jsonrpc/2) [storage.VolumeManifest] 98bce80e-1a06-4322-9f47-a83573e84cd4/8619d42c-e4b4-47a8-8ae7-7e780a079127/a8161202-7494-46b3-beae-7fb763b5a855 info is {'uuid': 'a8161202-7494-46b3-beae-7fb763b5a855', 'type': 'SPARSE', 'format': 'COW', 'disktype': 'DATA', 'voltype': 'LEAF', 'capacity': '5368709120', 'parent': 'fa566c2d-c807-4b6e-bb49-f68e8dcdc929', 'description': '', 'pool': '', 'domain': '98bce80e-1a06-4322-9f47-a83573e84cd4', 'image': '8619d42c-e4b4-47a8-8ae7-7e780a079127', 'ctime': '1601383375', 'mtime': '0', 'legality': 'LEGAL', 'generation': 0, 'apparentsize': '3221225472', 'truesize': '3221225472', 'status': 'OK', 'lease': {'path': '/dev/98bce80e-1a06-4322-9f47-a83573e84cd4/leases', 'offset': 116391936, 'owners': [], 'version': None}, 'children': []} (volume:277)

So I'm not sure if it's the original issue or something else. It could be an issue with libvirt.

Evelina, is it possible to abort the operation via automation when this is hit so the volume is not removed, allowing us to analyze it with `qemu-img info` and additional tools?

(In reply to Benny Zlotnik from comment #17)
> I see the error is:
> 2020-09-29 15:44:31,784+0300 ERROR (jsonrpc/7) [virt.vm]
> (vmId='f3e3bba8-7bf8-4965-95a2-450d910af819') Unable to stop the replication
> for the drive: sdb (vm:4159)
> Traceback (most recent call last):
>   File "/usr/lib/python3.6/site-packages/vdsm/virt/vm.py", line 4156, in
> diskReplicateFinish
>     self._dom.blockJobAbort(drive.name, blockJobFlags)
>   File "/usr/lib/python3.6/site-packages/vdsm/virt/virdomain.py", line 101,
> in f
>     ret = attr(*args, **kwargs)
>   File "/usr/lib/python3.6/site-packages/vdsm/common/libvirtconnection.py",
> line 131, in wrapper
>     ret = f(*args, **kwargs)
>   File "/usr/lib/python3.6/site-packages/vdsm/common/function.py", line 94,
> in wrapper
>     return func(inst, *args, **kwargs)
>   File "/usr/lib64/python3.6/site-packages/libvirt.py", line 888, in
> blockJobAbort
>     if ret == -1: raise libvirtError ('virDomainBlockJobAbort() failed',
> dom=self)
> libvirt.libvirtError: internal error: unable to execute QEMU command
> 'blockdev-add': Image is not in qcow2 format
> 
> Which is different than the original error in the bug
> 
> The most recent getInfo response I found on the relevant volume show that it
> is qcow2 (which it has to be since it's a snapshot)
> 2020-09-29 15:44:38,373+0300 INFO  (jsonrpc/2) [vdsm.api] START
> getVolumeInfo(sdUUID='98bce80e-1a06-4322-9f47-a83573e84cd4',
> spUUID='db771b4e-c7c3-4593-ae63-ce6c946604c2',
> imgUUID='8619d42c-e4b4-47a8-8ae7-7e780a079127',
> volUUID='a8161202-7494-46b3-beae-7fb763b5a855', options=None)
> from=::ffff:10.35.162.6,38426, flow_id=1d10eac4-e3bb-492e-a573-76f0280cf1bc,
> task_id=0a3b7feb-4b6b-48d2-864f-f8ad78b815c7 (api:48)
> 
> 2020-09-29 15:44:38,411+0300 INFO  (jsonrpc/2) [storage.VolumeManifest]
> 98bce80e-1a06-4322-9f47-a83573e84cd4/8619d42c-e4b4-47a8-8ae7-7e780a079127/
> a8161202-7494-46b3-beae-7fb763b5a855 info is {'uuid':
> 'a8161202-7494-46b3-beae-7fb763b5a855', 'type': 'SPARSE', 'format': 'COW',
> 'disktype': 'DATA', 'voltype': 'LEAF', 'capacity': '5368709120', 'parent':
> 'fa566c2d-c807-4b6e-bb49-f68e8dcdc929', 'description': '', 'pool': '',
> 'domain': '98bce80e-1a06-4322-9f47-a83573e84cd4', 'image':
> '8619d42c-e4b4-47a8-8ae7-7e780a079127', 'ctime': '1601383375', 'mtime': '0',
> 'legality': 'LEGAL', 'generation': 0, 'apparentsize': '3221225472',
> 'truesize': '3221225472', 'status': 'OK', 'lease': {'path':
> '/dev/98bce80e-1a06-4322-9f47-a83573e84cd4/leases', 'offset': 116391936,
> 'owners': [], 'version': None}, 'children': []} (volume:277)
> 
> So I'm not sure if it's the original issue or something else. It could be an
> issue with libvirt.
> 
> Evelina, is it possible to abort the operation via automation when this is
> hit so the volume is not removed, allowing us to analyze it with `qemu-img
> info` and additional tools?
I'll try to do that and let you know.

Summary on findings so far:
1. Root cause still unclear, a possible workaround (which is needed anyway) is to not perform teardown when running copy_data as part of LSM.
This works when copy_data and the VM run on the same host. I believe all the failures observed in this bug happen in this layout.

2. Another issue I found while forcing copy_data and the VM to run on different hosts is that a first successful LSM is followed by a failure when moving back to the original SD. This failures seems to by an incorrect read of a backing file of the snapshot when starting blockCopy (the failure in 1 happens when pivoting), and loks like this:
2020-10-21 14:06:57,501+0300 INFO  (jsonrpc/7) [virt.vm] (vmId='0bf6345f-5128-4803-bde2-a34c1b8f5b39') failed start drive replication libvirtError("Cannot access backing file '/rhev/data-center/mnt/blockSD/bc024016-bea8-4e0c-af1f-1a24c93b170e/images/03d348df-19f6-4737-883c-7a6da09607eb/5a8bd998-3002-4f4d-97b7-f30e553bc233' of storage file '/rhev/data-center/mnt/blockSD/bc024016-bea8-4e0c-af1f-1a24c93b170e/images/03d348df-19f6-4737-883c-7a6da09607eb/19b8ecda-69a9-480a-98ae-77a0898ce011' (as uid:107, gid:107): No such file or directory",) (vm:4065)

However, 5a8bd998-3002-4f4d-97b7-f30e553bc233 is not the backing file of 19b8ecda-69a9-480a-98ae-77a0898ce011, 5a8bd998-3002-4f4d-97b7-f30e553bc233 is the backing file of another volume in another disk participating in the LSM. `qemu-img info 19b8ecda-69a9-480a-98ae-77a0898ce011` shows the correct backing file as well `virsh dumpxml`

I am currently investigating why an incorrect backing file is seen and implementing the workaround.

Should be deliver this in 4.4.3? This is a regression compared with earlier
versions.

Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.

*** Bug 1788464 has been marked as a duplicate of this bug. ***

(In reply to Evelina Shames from comment #9)
> Lately we have many tests failing on this.
> 
> How reproducible:
> ~50%
> 
> Reproduction steps that I managed to reproduce the issue with:
> 1. Create a VM from template (RHEL 8.2)
> 2. Create 4 disks and add them to the VM:
> - VirtIO-SCSI Thin
> - VirtIO-SCSI Preallocated
> - VirtIO Thin
> - VirtIO Preallocated
> 3. Run the VM
> 4. Move all the VM disks concurrently to different iSCSI storage domain.
> --> Do this several times, one of the attempts will fail.

Verified on rhv-4.4.4-3 with the above steps several times + we didn't see it in our last automation runs.

Moving to 'Verified'.

This bugzilla is included in oVirt 4.4.4 release, published on December 21st 2020.

Since the problem described in this bug report should be resolved in oVirt 4.4.4 release, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.

*** Bug 1899360 has been marked as a duplicate of this bug. ***

The needinfo request[s] on this closed bug have been removed as they have been unresolved for 365 days