The documentation text flag should only be set after 'doc text' field is provided. Please provide the documentation text and set the flag to '?' again.

VDSM log on issue:
2021-03-18 13:49:17,066+0300 INFO  (jsonrpc/2) [api.host] START getStats() from=::ffff:10.195.6.134,51248 (api:48)
2021-03-18 13:49:17,085+0300 INFO  (jsonrpc/2) [vdsm.api] START repoStats(domains=()) from=::ffff:10.195.6.134,51248, task_id=f71b3bf9-0a18-4ac9-be88-e5eacdd5eafb (api:48)
2021-03-18 13:49:17,085+0300 INFO  (jsonrpc/2) [vdsm.api] FINISH repoStats return={'a8ff2546-f8af-4edb-90ca-1bcdb4c262be': {'code': 0, 'lastCheck': '0.7', 'delay': '0.00580853', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '75ce2254-35ad-44fa-adeb-e8dfbc4ba4fa': {'code': 0, 'lastCheck': '2.1', 'delay': '0.00342767', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=::ffff:10.195.6.134,51248, task_id=f71b3bf9-0a18-4ac9-be88-e5eacdd5eafb (api:54)
2021-03-18 13:49:17,085+0300 INFO  (jsonrpc/2) [vdsm.api] START multipath_health() from=::ffff:10.195.6.134,51248, task_id=1ead6065-dbd9-4dbe-bc5f-05e8eec74ea8 (api:48)
2021-03-18 13:49:17,085+0300 INFO  (jsonrpc/2) [vdsm.api] FINISH multipath_health return={} from=::ffff:10.195.6.134,51248, task_id=1ead6065-dbd9-4dbe-bc5f-05e8eec74ea8 (api:54)
2021-03-18 13:49:17,089+0300 INFO  (jsonrpc/2) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=::ffff:10.195.6.134,51248 (api:54)
2021-03-18 13:49:18,396+0300 INFO  (jsonrpc/3) [api.host] START getAllVmStats() from=::1,45388 (api:48)
2021-03-18 13:49:18,397+0300 INFO  (jsonrpc/3) [api.host] FINISH getAllVmStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': (suppressed)} from=::1,45388 (api:54)
2021-03-18 13:49:18,401+0300 INFO  (jsonrpc/1) [api.host] START getAllVmIoTunePolicies() from=::1,45388 (api:48)
2021-03-18 13:49:18,401+0300 INFO  (jsonrpc/1) [api.host] FINISH getAllVmIoTunePolicies return={'status': {'code': 0, 'message': 'Done'}, 'io_tune_policies_dict': {'5255b072-53a8-492d-9cfa-248ce9886b64': {'policy': [], 'current_values': [{'name': 'sda', 'path': '/rhev/data-center/mnt/glusterfs-test.mgmt.tensor.ru:_var_local_rhv-test-storage/a8ff2546-f8af-4edb-90ca-1bcdb4c262be/images/b5ed61dc-8008-4ba7-ac19-7077a636db3d/1d07b75d-40ce-4be9-a7d6-0fed5dd12aff', 'ioTune': {'total_bytes_sec': 0, 'read_bytes_sec': 0, 'write_bytes_sec': 0, 'total_iops_sec': 0, 'write_iops_sec': 0, 'read_iops_sec': 0}}, {'name': 'sdb', 'path': '/rhev/data-center/mnt/glusterSD/sds0101:_gv0/75ce2254-35ad-44fa-adeb-e8dfbc4ba4fa/images/d71cf39d-9b0e-49bb-88c6-3a3a515c18e4/9612572d-1a85-410c-a888-992184d08284', 'ioTune': {'total_bytes_sec': 0, 'read_bytes_sec': 0, 'write_bytes_sec': 0, 'total_iops_sec': 0, 'write_iops_sec': 0, 'read_iops_sec': 0}}]}}} from=::1,45388 (api:54)
2021-03-18 13:49:25,700+0300 WARN  (periodic/0) [virt.periodic.VmDispatcher] could not run <class 'vdsm.virt.periodic.BlockjobMonitor'> on ['5255b072-53a8-492d-9cfa-248ce9886b64'] (periodic:289)
2021-03-18 13:49:25,702+0300 INFO  (qgapoller/0) [vds] Failed to get guest info for vm=5255b072-53a8-492d-9cfa-248ce9886b64, error: Guest agent is not responding: QEMU guest agent is not connected (qemuguestagent:414)
2021-03-18 13:49:26,224+0300 INFO  (jsonrpc/4) [api.host] START getAllVmStats() from=::ffff:10.195.6.134,51248 (api:48)
2021-03-18 13:49:26,224+0300 WARN  (jsonrpc/4) [virt.vmstats] Missing stat: 'net.0.rx.errs' for vm 5255b072-53a8-492d-9cfa-248ce9886b64 (vmstats:490)
2021-03-18 13:49:26,224+0300 WARN  (jsonrpc/4) [virt.vmstats] Missing stat: 'net.0.rx.bytes' for vm 5255b072-53a8-492d-9cfa-248ce9886b64 (vmstats:490)
2021-03-18 13:49:26,225+0300 INFO  (jsonrpc/4) [api.host] FINISH getAllVmStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': (suppressed)} from=::ffff:10.195.6.134,51248 (api:54)

For RHV assistance please open a support case

moving to upstream

Hi Mikhail,

Can you please add the engine and VDSM versions?

Nir, can you please have a look?

qemu aborting is qemu bug, or an issue with storage.

Kevin, should be move the bug to qemu?

(In reply to Mikhail Gusev from comment #0)
> After start disk migration between storage domains (NFS -> GlusterFS), qemu
> process was killed by SIGABRT. No errors in vdsm log. 

Based on the rest of the description, I guess you mean live storage migration
(moving disk between storage domains when the vm is running).

> RHV Manager did not know about this, and status of virtual machine was "UP". 
> The migration process endlessly cannot complete. Uncompleted tasks: "Merging
> snapshots (<UNKNOWN> into <UNKNOWN>) of disk <UNKNOWN>" "Cloning image's
> structure" "Migrating Disk" "Removing Snapshot test-vm-01_Disk1
> Auto-generated for Live Storage Migration of VM"

This sounds like engine bug, it will be better to file engine bug for this.

> Stack trace in attachment
> 
> Problem occurs only to live migrate "Non os" disks NFS Domain to GlusterFS
> domain and only to Disperse-Distribute gluster volume 
> Migration GlusterFS -> NFS and migration OS disks NFS Domain to GlusterFS
> domain and migrations to Replica gluster volume wokrs fine

I don't know if we support Disperse-Distribute gluster disks. I know that 
replica 3 or replica 2 + arbiter are supported configurations.

It looks like we have 2 issues:
- qemu aborts - should be handled by qemu developers, may be caused
  by gluster issue, but qemu should not abort because of runtime errors.
- engine not handling the flow - should be handled by ovirt-engine

I don't see an issue in vdsm.

Regarding the attached logs - please provide full vdsm and engine
logs, and the complete core dump. The traceback from abrt report
is not useful.

(In reply to Nir Soffer from comment #7)
> Kevin, should be move the bug to qemu?

If QEMU aborts, there is a QEMU bug involved. Whether or not there is an additional bug in the management layer is something you would have to tell.

Specifically, this looks like completion of the mirror job tries to remove the mirror-top node and this fails with some locking problem. In theory, removing this node shouldn't require any permissions that weren't already taken before, so there shouldn't even be an attempt to lock something. A reproducer on the QEMU level or at least a core dump would be helpful if you're moving the bug to qemu-kvm.

I can reproduce something like the given stack trace as follows:

$ qemu-img create -f raw src.img 64M
Formatting 'src.img', fmt=raw size=67108864
$ qemu-img create -f raw tgt.img 64M
Formatting 'tgt.img', fmt=raw size=67108864

$ qemu-system-x86_64 \
    -blockdev file,node-name=source,filename=src.img \
    -blockdev file,node-name=target,filename=tgt.img \
    -device virtio-blk,drive=source \
    -qmp stdio
{"QMP": {"version": {"qemu": {"micro": 0, "minor": 2, "major": 5}, "package": ""}, "capabilities": ["oob"]}}

{"execute":"qmp_capabilities"}
{"return": {}}

{"execute":"blockdev-mirror","arguments":{"job-id":"mirror","device":"source","target":"target","sync":"full","filter-node-name":"mirror-top"}}
{"timestamp": {"seconds": 1616518637, "microseconds": 489079}, "event": "JOB_STATUS_CHANGE", "data": {"status": "created", "id": "mirror"}}
{"timestamp": {"seconds": 1616518637, "microseconds": 489180}, "event": "JOB_STATUS_CHANGE", "data": {"status": "running", "id": "mirror"}}
{"return": {}}
{"timestamp": {"seconds": 1616518637, "microseconds": 490552}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "mirror"}}
{"timestamp": {"seconds": 1616518637, "microseconds": 490594}, "event": "BLOCK_JOB_READY", "data": {"device": "mirror", "len": 67108864, "offset": 67108864, "speed": 0, "type": "mirror"}}


Then, in another shell:

$ qemu-io -f raw src.img
>


Back to QMP:

{"execute":"block-job-cancel","arguments":{"device":"mirror"}}
{"return": {}}
{"timestamp": {"seconds": 1616518653, "microseconds": 675887}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "mirror"}}
{"timestamp": {"seconds": 1616518653, "microseconds": 675926}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "mirror"}}
Unexpected error in raw_check_lock_bytes() at ../qemu-5.2.0/block/file-posix.c:908:
qemu-system-x86_64: Failed to get shared "write" lock
[1]    110029 abort (core dumped)  qemu-system-x86_64 -blockdev file,node-name=source,filename=src.img -blockdev


Stack trace is the same mirror_exit_common() -> bdrv_replace_node() -> bdrv_check_perm() -> raw_check_lock_bytes() as in comment 0.

The problem in this case is that the mirror filter node doesn’t take proper permissions, so the image file can freely be used by other qemu processes while the job is running.  If they still access the file when the job completes, the VM will crash because it wants its permissions back.

I don’t know whether that’s cause for the crash described in comment 0.  It seems plausible.  But it would require some other process to open the image file while the mirror job is running, which I would have thought to be unlikely.  On the other hand, the stack trace only leaves the conclusion that exactly that is happening: Some other process holds locks on the file when mirror completes (or raw_check_lock_bytes() wouldn’t give an error).


I think applying https://lists.nongnu.org/archive/html/qemu-block/2021-02/msg00933.html would fix at least what I’ve described here, because it makes the mirror job retain all permissions it needs while it’s running, so you cannot do the “launch qemu-io concurrently in another shell” step.  (qemu-io will give an error that it can’t take the locks it needs.)

Max

Do we have a QEMU bug that we can track using this bug?

We should probably create a separate QEMU bug report then to backport the fix that Max mentioned.

However, if a second process accessing the image at the same time is the reason, we have a management layer bug as well because that shouldn't happen. Once we fix QEMU, trying to access the image from the second process will fail because locking will prevent this. So we should probably use this bug for the RHV part.

The next step would then be verifying that the image is indeed opened twice by RHV, and finding out why this happens.

(In reply to Kevin Wolf from comment #13)
> The next step would then be verifying that the image is indeed opened twice
> by RHV, and finding out why this happens.

We never access active images with "qemu-img convert" or qemu-nbd.

What happens in live storage migration:

1. ovirt creates a live snapshot

    src: A <- B (top)

2. ovirt creates the target image chain on the destination storage

    dst: A <- B (top)

3. vdsm starts blockCopy in libvirt for the active image
4. qemu starts mirroring data from top image to destination

    qemu: mirror src:A to dst:A

    libvirt should make sure dst:B is not opened by qemu since
    this image is used by vdsm at this point.
 
5. vdsm copy image A on src to image A on dst

    vdsm: copy src:B to dst:B with qemu-img convert

6. when copying B finish and mirroring A is ready, vdsm ask libvirt
   to pivot from src:A to dst:A

   at this point qemu should open dst:B.

So at no point we have qemu-img convert writing to an image opened by qemu.

I think this issue is most likey related to gluster Disperse-Distribute
volumes. I don't know if they are supported and tested. Replica 3 volumes
and Replica 2 + arbiter are supported configurations.

You mean a gluster bug related to file locking? So that maybe it would fail an attempt to lock the image even though the image isn't actually locked by anyone? Or it doesn't unlock the file when we drop the lock and then the old lock prevents us from taking a new one?

If there is nobody else who could be taking a lock, I guess a bug in the file locking mechanism itself is the only other option.

I think this issue is likely an unexpected behavior when using gluster
Disperse-Distribute volumes, so it should be handled by gluster team.

Update from Sahina:
> We do not support Disperse volumes in oVirt for storing VM images.

So the question is how vdsm enabled working with unsupported volume
type. We may need to improve validation when connecting to gluster
storage domain.

In the past we added code to warn about unsupported replica count, we
probably need to warn or reject volume with unsupported types.
https://github.com/oVirt/vdsm/blob/6688ebfc0aaec8ea50d54a749d42950386dcda49/lib/vdsm/storage/storageServer.py#L288

Ritesh, can you implement this validation?

Kevin, can you file the qemu bug related to comment 11?
I don't fully understand the issue to create a good bug.

I raised PR for this to handle this in vdsm

https://github.com/oVirt/vdsm/pull/22

@Nir Can you review.

(In reply to Ritesh Chikatwar from comment #20)
> I raised PR for this to handle this in vdsm
> 
> https://github.com/oVirt/vdsm/pull/22
> 
> @Nir Can you review.

Please submit the patch to - https://gerrit.ovirt.org/

The GitHub repository is a mirror of Gerrit and shouldn't be used for enhancements.

(In reply to Eyal Shenitzky from comment #21)
> (In reply to Ritesh Chikatwar from comment #20)
> > I raised PR for this to handle this in vdsm
> > 
> > https://github.com/oVirt/vdsm/pull/22
> > 
> > @Nir Can you review.
> 
> Please submit the patch to - https://gerrit.ovirt.org/
i Did
> 
> The GitHub repository is a mirror of Gerrit and shouldn't be used for
> enhancements.

(In reply to Eyal Shenitzky from comment #12)
> Do we have a QEMU bug that we can track using this bug?

As was said, we should probably open a new bug.  So:

(In reply to Nir Soffer from comment #19)
> Kevin, can you file the qemu bug related to comment 11?

I’ve created https://bugzilla.redhat.com/show_bug.cgi?id=1947772.

Can you pls elaborate on this issue?
What is exactly the issue? what is the fix? How can I reproduce the issue and test the fix? 
Thanks

While trying to make use of disperse gluster volume as storage domain in ovirt-4.4.6, this is still allowed.
Warning message is logged in /var/log/vdsm.log as expected.

<snip>
2021-05-17 11:23:38,299+0000 WARN  (jsonrpc/7) [storage.StorageServer.MountConnection] Unsupported volume type, volume: 'dispvol', volume type: 'DISPERSE'. Please use the replicate type.To recover existing migrate it to supported type. (storageServer:306)
</snip>

The change to disallow storage domain creation with disperse gluster volume is tracked as part of the
bug - https://bugzilla.redhat.com/show_bug.cgi?id=1951894

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