Are you sure it's not yet another dup of the qemu-img bug?

Yes,

This bug is about 'qemu-img info' request

and bug #1526212 is about 'qemu-img create' request

From our side (ovirt) creation a snapshot involves two qemu-img commands:
   a. qemu-img create
   b. qemu-img info

With qemu-img version 2.10 (rhel 7.5), we know that a new unsafe option was added and we have to use it, otherwise (as noticed), our code breaks.

For `qemu-img create`, qemu guys fixed their code so now we don't have to provide -u option, hence the difference from what seen in BZ 1526212.

However, for `qemu-img info` we do have to provide -U (big U, that's not a typo) in order for it to work.

I will update my rhel 7.5 environment and check the latest status of qemu fixes/issues.

We already started to adapt vdsm code to the new changes:
https://gerrit.ovirt.org/supportUnsafeVolumeCreate

The patches are still in-work and too updated. For example, the patch that add -u to `qemu-img create` isn't needed anymore.

Created attachment 1386188 [details]
logs-2

The bug still occurs with the latest build [1], according to steps to reproduce from the bug description.


qemuimg.py +86:

    if unsafe and _supports_option('info', 'U'):
        cmd.append('-U')



vdsm.log:

2018-01-25 17:49:45,008+0200 ERROR (jsonrpc/7) [storage.Dispatcher] FINISH getQemuImageInfo error=Command ['/usr/bin/qemu-img', 'info', '--output', 'json', '-f', 'qcow2', '-U', '/rhev/data-center/mnt/blockSD/582
0c57b-a8fb-4169-9b08-bcf28753c4f6/images/6ed520ab-a9df-4da6-8323-d6a74fb3c17d/c4cb3a27-4d64-43af-8213-ccc0ec4629e4'] failed with rc=1 out='' err="qemu-img: Could not open '/rhev/data-center/mnt/blockSD/5820c57b-
a8fb-4169-9b08-bcf28753c4f6/images/6ed520ab-a9df-4da6-8323-d6a74fb3c17d/c4cb3a27-4d64-43af-8213-ccc0ec4629e4': Could not open '/rhev/data-center/mnt/blockSD/5820c57b-a8fb-4169-9b08-bcf28753c4f6/images/6ed520ab-a
9df-4da6-8323-d6a74fb3c17d/c4cb3a27-4d64-43af-8213-ccc0ec4629e4': No such file or directory\n" (dispatcher:86)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/dispatcher.py", line 73, in wrapper
    result = ctask.prepare(func, *args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 108, in wrapper
    return m(self, *a, **kw)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 1189, in prepare
    raise self.error
Error: Command ['/usr/bin/qemu-img', 'info', '--output', 'json', '-f', 'qcow2', '-U', '/rhev/data-center/mnt/blockSD/5820c57b-a8fb-4169-9b08-bcf28753c4f6/images/6ed520ab-a9df-4da6-8323-d6a74fb3c17d/c4cb3a27-4d64
-43af-8213-ccc0ec4629e4'] failed with rc=1 out='' err="qemu-img: Could not open '/rhev/data-center/mnt/blockSD/5820c57b-a8fb-4169-9b08-bcf28753c4f6/images/6ed520ab-a9df-4da6-8323-d6a74fb3c17d/c4cb3a27-4d64-43af-
8213-ccc0ec4629e4': Could not open '/rhev/data-center/mnt/blockSD/5820c57b-a8fb-4169-9b08-bcf28753c4f6/images/6ed520ab-a9df-4da6-8323-d6a74fb3c17d/c4cb3a27-4d64-43af-8213-ccc0ec4629e4': No such file or directory
\n"



[1]
vdsm-4.20.17-1.el7ev.x86_64
libvirt-3.9.0-7.el7.x86_64
qemu-kvm-rhev-2.10.0-18.el7.x86_64
rhvm-4.2.1.3-0.1.el7.noarch

The is not about RHEL 7.5.
I am able to reproduce also on RHEL 7.5 hosts.
It seems that this might be related to resent changes in the Vm Xml area.
We are still investigating.

Elad,
Can you please confirm that the issue is reproducible also on RHEL 7.4 hosts?

(In reply to Ala Hino from comment #5)
> The is not about RHEL 7.5.
> I am able to reproduce also on RHEL 7.5 hosts.
> It seems that this might be related to resent changes in the Vm Xml area.
> We are still investigating.
> 
> Elad,
> Can you please confirm that the issue is reproducible also on RHEL 7.4 hosts?

So many typos ...
Correction:
The issue is *not* about RHEL 7.5.
I am able to reproduce on RHEL 7.4 hosts as well.

Created attachment 1388988 [details]
logs-7.4

Reproduce with RHEL7.4:

vdsm-4.20.17-1.el7ev.x86_64
libvirt-daemon-3.2.0-14.el7_4.7.x86_64
qemu-kvm-rhev-2.9.0-16.el7_4.14.x86_64



2018-01-31 16:25:38,505+0200 ERROR (jsonrpc/5) [storage.TaskManager.Task] (Task='9b84ab3a-aeb8-4f18-a3fc-8be0390de62d') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in getQemuImageInfo
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 3110, in getQemuImageInfo
    info = vol.getQemuImageInfo()
  File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1442, in getQemuImageInfo
    return self._manifest.getQemuImageInfo()
  File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 283, in getQemuImageInfo
    unsafe=True)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/qemuimg.py", line 91, in info
    out = _run_cmd(cmd)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/qemuimg.py", line 408, in _run_cmd
    raise cmdutils.Error(cmd, rc, out, err)
Error: Command ['/usr/bin/qemu-img', 'info', '--output', 'json', '-f', 'qcow2', u'/rhev/data-center/mnt/blockSD/fca89e97-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8
-ae4b-9f665c92e937'] failed with rc=1 out='' err="qemu-img: Could not open '/rhev/data-center/mnt/blockSD/fca89e97-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8-ae4b-
9f665c92e937': Could not open '/rhev/data-center/mnt/blockSD/fca89e97-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8-ae4b-9f665c92e937': No such file or directory\n"
2018-01-31 16:25:38,506+0200 INFO  (jsonrpc/5) [storage.TaskManager.Task] (Task='9b84ab3a-aeb8-4f18-a3fc-8be0390de62d') aborting: Task is aborted: u'Command [\'/usr/bin/qemu-img\', \'info\', \'--output\', \'json
\', \'-f\', \'qcow2\', u\'/rhev/data-center/mnt/blockSD/fca89e97-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8-ae4b-9f665c92e937\'] failed with rc=1 out=\'\' err="qem
u-img: Could not open \'/rhev/data-center/mnt/blockSD/fca89e97-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8-ae4b-9f665c92e937\': Could not open \'/rhev/data-center/m
nt/blockSD/fca89e97-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8-ae4b-9f665c92e937\': No such file or directory\\n"' - code 100 (task:1181)
2018-01-31 16:25:38,507+0200 ERROR (jsonrpc/5) [storage.Dispatcher] FINISH getQemuImageInfo error=Command ['/usr/bin/qemu-img', 'info', '--output', 'json', '-f', 'qcow2', u'/rhev/data-center/mnt/blockSD/fca89e97
-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8-ae4b-9f665c92e937'] failed with rc=1 out='' err="qemu-img: Could not open '/rhev/data-center/mnt/blockSD/fca89e97-5ca1-
45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8-ae4b-9f665c92e937': Could not open '/rhev/data-center/mnt/blockSD/fca89e97-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4
cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8-ae4b-9f665c92e937': No such file or directory\n" (dispatcher:86)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/dispatcher.py", line 73, in wrapper
    result = ctask.prepare(func, *args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 108, in wrapper
    return m(self, *a, **kw)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 1189, in prepare
    raise self.error
Error: Command ['/usr/bin/qemu-img', 'info', '--output', 'json', '-f', 'qcow2', u'/rhev/data-center/mnt/blockSD/fca89e97-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8
-ae4b-9f665c92e937'] failed with rc=1 out='' err="qemu-img: Could not open '/rhev/data-center/mnt/blockSD/fca89e97-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8-ae4b-
9f665c92e937': Could not open '/rhev/data-center/mnt/blockSD/fca89e97-5ca1-45d3-af17-d468e588f15b/images/178317d2-c43f-4cfe-8f42-d8b7aa6e2426/ea946c67-a523-4ce8-ae4b-9f665c92e937': No such file or directory\n"
2018-01-31 16:25:38,508+0200 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Volume.getQemuImageInfo failed (error 100) in 0.21 seconds (__init__:573)
2018-01-31 16:25:38,729+0200 INFO  (jsonrpc/6) [vdsm.api] START getVolumeInfo(sdUUID=u'fca89e97-5ca1-45d3-af17-d468e588f15b', spUUID=u'6bbc327e-6f30-4429-a696-70b75a49f507', imgUUID=u'6a4deeb2-044b-44d0-88b0-d9d
1ce71c145', volUUID=u'bbb1bc17-4b8f-4acb-82ed-dfa788b06b07', options=None) from=::ffff:10.35.161.8,43388, flow_id=6fa089ce-2846-4c98-baf5-04b2decff659, task_id=a8c6b66b-603f-46c5-a41d-10b4e2e8d8c5 (api:46)
2018-01-31 16:25:38,731+0200 INFO  (jsonrpc/6) [storage.VolumeManifest] Info request: sdUUID=fca89e97-5ca1-45d3-af17-d468e588f15b imgUUID=6a4deeb2-044b-44d0-88b0-d9d1ce71c145 volUUID = bbb1bc17-4b8f-4acb-82ed-df
a788b06b07  (volume:238)

As this issue might be related to recent changes done in Vm Xml area, moving the bug to fromani for further investigations.

Ok, eventually I managed to look into this and found the issue.

When we restore a snapshot, Engine sends the XML with the updated drive informations (this also applies on committed snapshots).

Vdsm updates the drive information with the data from new XML: type, path, format.
However, the drive UUIDs are NOT updated: this is a Vdsm bug.

In the vm.conf based flow this step was done implicitely, now we need to do explicitely, replacing the drive metadata.

It seems Engine sends already what Vdsm needs, so we just need a Vdsm patch.

It seems that the fixes are not included in the latest vdsm build (v4.20.19):

https://gerrit.ovirt.org/gitweb?p=vdsm.git;a=shortlog;h=cdb1914376270dfd105eea3a16f253ecbf5e47c0

For example commit cdb1914376270dfd105eea3a16f253ecbf5e47c0 was merged after v4.20.19

Moving back to MODIFIED

(In reply to Elad from comment #11)
> It seems that the fixes are not included in the latest vdsm build (v4.20.19):
> 
> https://gerrit.ovirt.org/gitweb?p=vdsm.git;a=shortlog;
> h=cdb1914376270dfd105eea3a16f253ecbf5e47c0
> 
> For example commit cdb1914376270dfd105eea3a16f253ecbf5e47c0 was merged after
> v4.20.19
> 
> Moving back to MODIFIED

Could you please point to the change-ids (like I1caadb601c7312e49fbe5c390104c15d61579ca3) you believe are not part of the tag?

AFAICT Tag 4.20.19 looks good and includes all the needed patches: tag 4.20.19 is on top of change-id I1caadb601c7312e49fbe5c390104c15d61579ca3, which is the last of the series.

Tested according to the steps in the description.
Second snapshot creation succeeded after first snapshot restore.

Used:
vdsm-4.20.20-1.el7ev.x86_64
libvirt-3.9.0-14.el7.x86_64
qemu-kvm-rhev-2.10.0-21.el7.x86_64
rhvm-4.2.2.2-0.1.el7.noarch

This bugzilla is included in oVirt 4.2.2 release, published on March 28th 2018.

Since the problem described in this bug report should be
resolved in oVirt 4.2.2 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.