libvirt.libvirtError: Requested operation is not valid: format of backing image %s of image %s was not specified in the image metadata (See https://libvirt.org/kbase/backing_chains.html for troubleshooting)

[Lee Yarwood]

The following was discovered using Fedora 30 and a virt-preview job in the below change:

zuul: Add the fedora-latest-virt-preview job to the experimental queue
https://review.opendev.org/#/c/704573/

Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [None req-7efa9e8b-3c21-4787-8b47-54cab5fe3756 tempest-AggregatesAdminTestJSON-76056319 tempest-AggregatesAdminTestJSON-76056319] [instance: 543723fb-3afc-460c-9139-809bcacd1840] Instance failed to spawn: libvirt.libvirtError: Requested operation is not valid: format of backing image '/opt/stack/data/nova/instances/_base/8e0569aaf1cbdb522514c3dc9d0fa8fad6f78c50' of image '/opt/stack/data/nova/instances/543723fb-3afc-460c-9139-809bcacd1840/disk' was not specified in the image metadata (See https://libvirt.org/kbase/backing_chains.html for troubleshooting)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] Traceback (most recent call last):
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/opt/stack/nova/nova/compute/manager.py", line 2604, in _build_resources
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] yield resources
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/opt/stack/nova/nova/compute/manager.py", line 2377, in _build_and_run_instance
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] block_device_info=block_device_info)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3399, in spawn
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] power_on=power_on)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 6193, in _create_domain_and_network
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] destroy_disks_on_failure)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] self.force_reraise()
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] six.reraise(self.type_, self.value, self.tb)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/six.py", line 703, in reraise
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] raise value
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 6165, in _create_domain_and_network
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] post_xml_callback=post_xml_callback)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 6106, in _create_domain
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] guest.launch(pause=pause)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/opt/stack/nova/nova/virt/libvirt/guest.py", line 142, in launch
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] self._encoded_xml, errors='ignore')
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] self.force_reraise()
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] six.reraise(self.type_, self.value, self.tb)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/six.py", line 703, in reraise
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] raise value
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/opt/stack/nova/nova/virt/libvirt/guest.py", line 137, in launch
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] return self._domain.createWithFlags(flags)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/eventlet/tpool.py", line 190, in doit
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] result = proxy_call(self._autowrap, f, *args, **kwargs)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/eventlet/tpool.py", line 148, in proxy_call
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] rv = execute(f, *args, **kwargs)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/eventlet/tpool.py", line 129, in execute
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] six.reraise(c, e, tb)
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/six.py", line 703, in reraise
Feb 19 16:45:21.405351 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] raise value
Feb 19 16:45:21.407911 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib/python3.7/site-packages/eventlet/tpool.py", line 83, in tworker
Feb 19 16:45:21.407911 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] rv = meth(*args, **kwargs)
Feb 19 16:45:21.407911 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] File "/usr/local/lib64/python3.7/site-packages/libvirt.py", line 1265, in createWithFlags
Feb 19 16:45:21.407911 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] if ret == -1: raise libvirtError ('virDomainCreateWithFlags() failed', dom=self)
Feb 19 16:45:21.407911 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840] libvirt.libvirtError: Requested operation is not valid: format of backing image '/opt/stack/data/nova/instances/_base/8e0569aaf1cbdb522514c3dc9d0fa8fad6f78c50' of image '/opt/stack/data/nova/instances/543723fb-3afc-460c-9139-809bcacd1840/disk' was not specified in the image metadata (See https://libvirt.org/kbase/backing_chains.html for troubleshooting)
Feb 19 16:45:21.407911 fedora-30-rax-ord-0014691277 nova-compute[2019]: ERROR nova.compute.manager [instance: 543723fb-3afc-460c-9139-809bcacd1840]

As shown above Libvirt v6.0.0 [1] will now fail to launch a domain when using -blockdev if a given qcow2 disk does not have a `backing file format` defined in its metadata.

There are some discussions upstream around relaxing this slightly [2] but for now any attempt to launch an instance using qcow2 disks will fail as Nova does not populate this value when creating the disk.

Nova needs to at a minimum start populating this field and depending on the outcome of the thread upstream in Libvirt also potentially handle the upgrade case where we may need to rebase existing disks in order to update the metadata.

[1] https://github.com/libvirt/libvirt/commit/3615e8b39badf2a526996a69dc91a92b04cf262e
[2] https://www.redhat.com/archives/libvir-list/2020-February/msg00616.html

[Launchpad Janitor (janitor)]

This bug was fixed in the package nova - 2:21.0.0~b2~git2020021008.1fcd74730d-0ubuntu4

---------------
nova (2:21.0.0~b2~git2020021008.1fcd74730d-0ubuntu4) focal; urgency=medium

  * d/p/libvirt-provide-backing-file-format-creating-qcow2.patch: Without this
    patch, domains (instances) can't be launched with libvirt 6.0.0. Picked
    from https://review.opendev.org/#/c/708745/ (LP: #1864020).

 -- Corey Bryant <email address hidden> Thu, 27 Feb 2020 09:05:50 -0500

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/708745
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=0cfe9c81e3fe4d268c9949c6b8e873abab94a407
Submitter: Zuul
Branch: master

commit 0cfe9c81e3fe4d268c9949c6b8e873abab94a407
Author: Lee Yarwood <email address hidden>
Date: Wed Feb 19 20:39:54 2020 +0000

    libvirt: Provide the backing file format when creating qcow2 disks

    Libvirt v6.0.0 [1] will now fail to launch a domain when using qcow2
    disks where the backing file format is not recorded in the qcow2
    metadata.

    There are some discussions upstream around relaxing this slightly [2]
    but for now any attempt to launch an instance using qcow2 disks will
    fail as Nova does not populate this value when creating the disk.

    Nova needs to at a minimum start populating this field and depending on
    the outcome of the thread upstream in Libvirt also potentially handle
    the upgrade case where we may need to rebase existing disks in order to
    update the metadata.

    For now this change simply adds the backing_fmt option to the qemu-img
    command line used to create these disks.

    [1] https://github.com/libvirt/libvirt/commit/3615e8b39badf2a526996a69dc91a92b04cf262e
    [2] https://www.redhat.com/archives/libvir-list/2020-February/msg00616.html

    Partial-Bug: #1864020
    Change-Id: I77ebada015f6522a300be4fa043fb8676458402b

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/train
Review: https://review.opendev.org/710788

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/stein
Review: https://review.opendev.org/710790

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/710788
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=7fd41e9b8c0f0f9cbccd63fbdbcc863de7db50f5
Submitter: Zuul
Branch: stable/train

commit 7fd41e9b8c0f0f9cbccd63fbdbcc863de7db50f5
Author: Lee Yarwood <email address hidden>
Date: Wed Feb 19 20:39:54 2020 +0000

    libvirt: Provide the backing file format when creating qcow2 disks

    Libvirt v6.0.0 [1] will now fail to launch a domain when using qcow2
    disks where the backing file format is not recorded in the qcow2
    metadata.

    There are some discussions upstream around relaxing this slightly [2]
    but for now any attempt to launch an instance using qcow2 disks will
    fail as Nova does not populate this value when creating the disk.

    Nova needs to at a minimum start populating this field and depending on
    the outcome of the thread upstream in Libvirt also potentially handle
    the upgrade case where we may need to rebase existing disks in order to
    update the metadata.

    For now this change simply adds the backing_fmt option to the qemu-img
    command line used to create these disks.

    [1] https://github.com/libvirt/libvirt/commit/3615e8b39badf2a526996a69dc91a92b04cf262e
    [2] https://www.redhat.com/archives/libvir-list/2020-February/msg00616.html

    Partial-Bug: #1864020
    Change-Id: I77ebada015f6522a300be4fa043fb8676458402b
    (cherry picked from commit 0cfe9c81e3fe4d268c9949c6b8e873abab94a407)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/710790
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=f5bc2c7ae45d83d90770a3e55bac0ae2465a8775
Submitter: Zuul
Branch: stable/stein

commit f5bc2c7ae45d83d90770a3e55bac0ae2465a8775
Author: Lee Yarwood <email address hidden>
Date: Wed Feb 19 20:39:54 2020 +0000

    libvirt: Provide the backing file format when creating qcow2 disks

    Libvirt v6.0.0 [1] will now fail to launch a domain when using qcow2
    disks where the backing file format is not recorded in the qcow2
    metadata.

    There are some discussions upstream around relaxing this slightly [2]
    but for now any attempt to launch an instance using qcow2 disks will
    fail as Nova does not populate this value when creating the disk.

    Nova needs to at a minimum start populating this field and depending on
    the outcome of the thread upstream in Libvirt also potentially handle
    the upgrade case where we may need to rebase existing disks in order to
    update the metadata.

    For now this change simply adds the backing_fmt option to the qemu-img
    command line used to create these disks.

    [1] https://github.com/libvirt/libvirt/commit/3615e8b39badf2a526996a69dc91a92b04cf262e
    [2] https://www.redhat.com/archives/libvir-list/2020-February/msg00616.html

    Partial-Bug: #1864020
    Change-Id: I77ebada015f6522a300be4fa043fb8676458402b
    (cherry picked from commit 0cfe9c81e3fe4d268c9949c6b8e873abab94a407)
    (cherry picked from commit 7fd41e9b8c0f0f9cbccd63fbdbcc863de7db50f5)

[György Szombathelyi (gyurco)]

And what about existing images? E.g. resize fails on old images after upgrading libvirt.

[Shi Yan (yanshi-403)]

We are using the ussuri nova, which already includes the above patch, but still have the problem to start the instance.

trace logs are as following:

=========================
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/oslo_messaging/rpc/server.py", line 165, in _process_incoming
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/oslo_messaging/rpc/dispatcher.py", line 276, in dispatch
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/oslo_messaging/rpc/dispatcher.py", line 196, in _do_dispatch
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/nova/exception_wrapper.py", line 79, in wrapped
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server function_name, call_dict, binary, tb)
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server self.force_reraise()
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb)
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/six.py", line 703, in reraise
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server raise value
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/nova/exception_wrapper.py", line 69, in wrapped
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server return f(self, context, *args, **kw)
                                          2021-05-18 10:05:32.386 144075 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/nova/compute/manager.py", lin...