MetadataCopyFailure: Failed to copy metadata to volume: Glance metadata cannot be updated, key signature_verified exists for volume id <volume id>

[Eric Miller]

CentOS 7.6
Kolla Ansible 7.0.2 deployment

Steps to reproduce:
1) Add "enable_force_upload = True" to [DEFAULT] section of cinder.conf to allow clone of in-use volume to an image, restarting all Cinder containers.

2) Create an image from an in-use volume: openstack image create --disk-format qcow2 --force --volume 7b434a13-025c-4e8a-9718-bcb5d75cae18 TestImage

In our case, the VM is powered down, but the volume is attached to this VM, so the volume status is "in-use".

3) Deploy image to new volume with: openstack volume create --image TestImage --size 50 TestVolume

4) Status shows as "creating" for a while, then "downloading" for a bit. Note that we are not using Ceph storage for this test. So, when the "creating" status is shown, the image is being copied to the compute node temporarily. The compute node has enough disk space for this process. Then, the download occurs, where the image is decompressed and written to the volume, after which the cinder-volume log indicates this was successful and that the "temporary image is deleted".

5) The metadata error occurs and the volume status is set to "error":
MetadataCopyFailure: Failed to copy metadata to volume: Glance metadata cannot be updated, key signature_verified exists for volume id 5846f529-ff3a-4d5f-bd01-0860dbb9bcf6

The respective cinder-volume log entries are at the end of this message (no lines were removed - just spaced out for clarity) starting at the point in time where image->volume copy process succeeded.

The volume image metadata property of the original "in-use" volume (from Step 2 above) that was imported to an image is:
| id | 7b434a13-025c-4e8a-9718-bcb5d75cae18
| volume_image_metadata | {u'checksum': u'2a291147d0e8157d0a06097f46b32791', u'min_ram': u'0', u'disk_format': u'qcow2', u'image_name': u'TestImage', u'image_id': u'9eb38b7e-35e0-4465-b074-fb2de78990dd', u'signature_verified': u'False', u'container_format': u'bare', u'min_disk': u'0', u'size': u'9635037184'}

The properties of the resulting image (from Step 2 above) are:
| id | 3b56e3c1-02c3-4713-9248-d1581f1f7221
| properties | locations='[{u'url': u'rbd://e7b5693b-800d-49fd-a483-d184e1ebb376/images/3b56e3c1-02c3-4713-9248-d1581f1f7221/snap', u'metadata': {}}]', os_hash_algo='sha512', os_hash_value='ee09c60599dbc00f44409bd7f15ae5b720bf23e8d9c48c8d19028cf947a8e10a4f3d750815e78dfe0fb15395b6d7c9a874981b62233840971073ff6268c7eda7', os_hidden='False', signature_verified='False' |

The volume image metadata property of the newly created, error'd, image is:
| id | 5846f529-ff3a-4d5f-bd01-0860dbb9bcf6 |
| volume_image_metadata | {u'signature_verified': u'False'} |

Since it appears that the signature_verified property already exists in the target volume, I thought this might cause the error since the source image has this property also.

So, I unset this property on the image using:
openstack image unset --property signature_verified 3b56e3c1-02c3-4713-9248-d1581f1f7221

and the process succeeded!

This seems like a bug somewhere in the metadata property cloning process. I would expect all volume_image_metadata to be over-written without error during a clone.

Eric

2019-04-06 00:21:28.734 137 DEBUG cinder.volume.flows.manager.create_volume [req-2b67aef2-a543-48b4-b5f8-b19ecef9fe0d f6f81f8e87994ca785b746af4f39f6ee 6baee5fa402b4850a313b7d55d7b1aba - edcea72f06da4d5a879427b35649ffa2 edcea72f06da4d5a879427b35649ffa2] Downloaded image 3b56e3c1-02c3-4713-9248-d1581f1f7221 ((None, [{u'url': u'rbd://e7b5693b-800d-49fd-a483-d184e1ebb376/images/3b56e3c1-02c3-4713-9248-d1581f1f7221/snap', u'metadata': {}}])) to volume 5846f529-ff3a-4d5f-bd01-0860dbb9bcf6 successfully. _copy_image_to_volume /var/lib/kolla/venv/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py:557

2019-04-06 00:21:29.769 137 DEBUG cinder.image.image_utils [req-2b67aef2-a543-48b4-b5f8-b19ecef9fe0d f6f81f8e87994ca785b746af4f39f6ee 6baee5fa402b4850a313b7d55d7b1aba - edcea72f06da4d5a879427b35649ffa2 edcea72f06da4d5a879427b35649ffa2] Temporary image 3b56e3c1-02c3-4713-9248-d1581f1f7221 for user f6f81f8e87994ca785b746af4f39f6ee is deleted. fetch /var/lib/kolla/venv/lib/python2.7/site-packages/cinder/image/image_utils.py:824

2019-04-06 00:21:29.769 137 DEBUG cinder.volume.flows.manager.create_volume [req-2b67aef2-a543-48b4-b5f8-b19ecef9fe0d f6f81f8e87994ca785b746af4f39f6ee 6baee5fa402b4850a313b7d55d7b1aba - edcea72f06da4d5a879427b35649ffa2 edcea72f06da4d5a879427b35649ffa2] Marking volume 5846f529-ff3a-4d5f-bd01-0860dbb9bcf6 as bootable. _enable_bootable_flag /var/lib/kolla/venv/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py:476

2019-04-06 00:21:29.775 137 DEBUG cinder.volume.flows.manager.create_volume [req-2b67aef2-a543-48b4-b5f8-b19ecef9fe0d f6f81f8e87994ca785b746af4f39f6ee 6baee5fa402b4850a313b7d55d7b1aba - edcea72f06da4d5a879427b35649ffa2 edcea72f06da4d5a879427b35649ffa2] Copying metadata from image 3b56e3c1-02c3-4713-9248-d1581f1f7221 to 5846f529-ff3a-4d5f-bd01-0860dbb9bcf6. _handle_bootable_volume_glance_meta /var/lib/kolla/venv/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py:432

2019-04-06 00:21:29.776 137 DEBUG cinder.volume.flows.manager.create_volume [req-2b67aef2-a543-48b4-b5f8-b19ecef9fe0d f6f81f8e87994ca785b746af4f39f6ee 6baee5fa402b4850a313b7d55d7b1aba - edcea72f06da4d5a879427b35649ffa2 edcea72f06da4d5a879427b35649ffa2] Creating volume glance metadata for volume 5846f529-ff3a-4d5f-bd01-0860dbb9bcf6 backed by image 3b56e3c1-02c3-4713-9248-d1581f1f7221 with: {'container_format': u'bare', 'min_ram': 0, 'disk_format': u'qcow2', 'image_name': u'Win2019_20190405', 'image_id': u'3b56e3c1-02c3-4713-9248-d1581f1f7221', u'signature_verified': u'False', 'checksum': u'29eebf5c7f1bad94c751ebdb8e9d615e', 'min_disk': 0, 'size': 13862240256}. _capture_volume_image_metadata /var/lib/kolla/venv/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py:591

2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume [req-2b67aef2-a543-48b4-b5f8-b19ecef9fe0d f6f81f8e87994ca785b746af4f39f6ee 6baee5fa402b4850a313b7d55d7b1aba - edcea72f06da4d5a879427b35649ffa2 edcea72f06da4d5a879427b35649ffa2] Failed updating volume 5846f529-ff3a-4d5f-bd01-0860dbb9bcf6 metadata using the provided image 3b56e3c1-02c3-4713-9248-d1581f1f7221 metadata: GlanceMetadataExists: Glance metadata cannot be updated, key signature_verified exists for volume id 5846f529-ff3a-4d5f-bd01-0860dbb9bcf6

2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume Traceback (most recent call last):
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume File "/var/lib/kolla/venv/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py", line 434, in _handle_bootable_volume_glance_meta
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume image_id, image_meta)
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume File "/var/lib/kolla/venv/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py", line 593, in _capture_volume_image_metadata
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume volume_metadata)
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume File "/var/lib/kolla/venv/lib/python2.7/site-packages/cinder/db/api.py", line 971, in volume_glance_metadata_bulk_create
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume metadata)
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume File "/var/lib/kolla/venv/lib/python2.7/site-packages/cinder/db/sqlalchemy/api.py", line 183, in wrapper
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume return f(*args, **kwargs)
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume File "/var/lib/kolla/venv/lib/python2.7/site-packages/cinder/db/sqlalchemy/api.py", line 198, in wrapper
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume return f(context, volume_id, *args, **kwargs)
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume File "/var/lib/kolla/venv/lib/python2.7/site-packages/cinder/db/sqlalchemy/api.py", line 5042, in volume_glance_metadata_bulk_create
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume volume_id=volume_id)
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume GlanceMetadataExists: Glance metadata cannot be updated, key signature_verified exists for volume id 5846f529-ff3a-4d5f-bd01-0860dbb9bcf6
2019-04-06 00:21:29.792 137 ERROR cinder.volume.flows.manager.create_volume
2019-04-06 00:21:29.796 137 WARNING cinder.volume.manager [req-2b67aef2-a543-48b4-b5f8-b19ecef9fe0d f6f81f8e87994ca785b746af4f39f6ee 6baee5fa402b4850a313b7d55d7b1aba - edcea72f06da4d5a879427b35649ffa2 edcea72f06da4d5a879427b35649ffa2] Task 'cinder.volume.flows.manager.create_volume.CreateVolumeFromSpecTask;volume:create' (e01844d0-4736-4762-89ff-93338d70f38b) transitioned into state 'FAILURE' from state 'RUNNING'

[Eric Harney (eharney)]

I wonder if this is the full scenario:

1) Create a volume from an image A, set "signature_verified" on the volume (A).
2) Upload volume A to Glance from Cinder, creating image B, and copy along the "signature_verified" flag with the metadata.
3) Create volume B from image B, and fail because "signature_verified" is already set from the Glance metadata instead of the verification process.

Does this match with your scenario?

[Eric Miller (erickmiller)]

Sorry, I haven't had a chance to review this again - will try to review and provide feedback on Eric Harney's response soon.

Eric

[Brian Rosmaita (brian-rosmaita)]

I'm pretty sure that Eric is right. What's happening is that when CONF.verify_glance_signatures != 'disabled', the signature_verification flag is written directly to the cinder DB. Later, in the normal flow, all of the image_metadata is written to the DB, and since the db API doesn't allow updating, if there's also a signature_verification present from the actual image metadata, that's causing the exception.

There are a few ways to address this.

(1) I'm not sure why the verification code is writing directly to the DB instead of just updating the image_metadata dict that's being passed around, and letting the signature_verification flag be written to the DB when the entire image_metadata is written. So we could do that.

(2) The DB API could be changed to allow updates. (It's really the sqlalchemy implementation that's not allowing updates; there's nothing specifically about that in the abstract DB API.) On the other hand, there are probably good reasons why it was implemented like this (for example, to make sure there's an accurate record of the image metadata at the time the image was consumed), so this is probably not a good idea.

(3) The signature_verification flag could be stored in with the volume metadata instead of the image metadata.

(4) We could filter image properties on upload from Glance. Nova has a non_inheritable_image_properties config option; we could do something like that:

    cfg.ListOpt('non_inheritable_image_properties',
        default=['cache_in_nova', 'bittorrent',
                 'img_signature_hash_method', 'img_signature',
                 'img_signature_key_type', 'img_signature_certificate_uuid'],

Looking at the default value makes me think we should definitely do this, because the img_* put on an image created from a volume that was created from an image will be incorrect. The downside of this config is that it's easy for an operator to mess with the list and possibly break things, but it seems to have worked OK for Nova, and there's a precedent for it.

Another reason to do this is that Glance has property protections; there may be image properties that operators don't want end users to be able to modify, so this would allow them to be screened out. Again, operators would already be familiar with this from Nova.

(5) We could filter image properties on download from Glance. This would allow us to remove any properties cinder uses, like signature_verified, that would cause problems in our code. This would eliminate the operator-error aspect of (4), but isn't as flexible.

[Brian Rosmaita (brian-rosmaita)]

I think that although (1) would fix this issue, (4) is probably a better way to go. (It looks like (1) would work, but it could be one of those things where there's an issue you don't find until later. I looked at the original implementation, and when the signature_verification flag was introduced to the patch, it was in the current format of writing directly to the DB. So I don't know whether that was a design decision forced by necessity or choice.)

[yenai (yenai2008)]

I think the reason for these problems is：
There are multiple entries for creating data:
  1) _create_from_image_cache_or_download(create signature_verified)
  2) _handle_bootable_volume_glance_meta(create from glance)
Actually, we should do it just in _handle_bootable_volume_glance_meta,
this is the correct and initial design idea.

So, in the method _create_from_image_cache_or_download, what we need is just check(
verify_glance_signatures is enabled). In _handle_bootable_volume_glance_meta, we do
the creating job:
  1) verify_glance_signatures is enabled, set or update signature_verified from glance
     image metadata.
  2) verify_glance_signatures is disabled, we should pop signature_verified if exist.

[Eric Miller (erickmiller)]

Another situation that caused a signature_verified issue:

1) Login as admin
2) Upload an ISO image to Glance
3) Set the image to "shared"
4) Use "image add project" to share the ISO with a given project
5) Login as the project admin
6) Accept the image (image set --accept, which does not appear to be documented)
7) Create a volume from the ISO (openstack volume create --image <shared_iso_image>)

This results in the volume having an "error" status.

The cinder logs include:

File "/var/lib/kolla/venv/lib/python2.7/site-packages/cinder/db/sqlalchemy/api.py", line 5042, in volume_glance_metadata_bulk_create\n volume_id=volume_id)\n', u'GlanceMetadataExists: Glance metadata cannot be updated, key signature_verified exists for volume id 29d4812b-7773-41f5-a75d-b818cd696de9\n'

The volume has the following property:
volume_image_metadata | {u'signature_verified': u'False'}

but the image does NOT have this property.

I'm not sure if this is a result of the same issue, but thought I would mention it. This seems like it may be a permissions issue on the shared image, which could become a problem for any image that is shared and deployed as a volume by the image consumer.

Eric

[Kyle Pericak (kpericak)]

Unsure if this is welcome here, but this page shows up when you google this error and I figured it might help someone.

I was able to work around this by removing the metadata property:

1. Create an image from a volume
2. The signature_verified=False property gets added to the image
3. Now you can't create volumes from this image
4. openstack image unset --property signature_verified <image ID>
5. Now you **can** create volumes from this image

[Mark Goddard (mgoddard)]

I hit this when using encrypted volumes. I had a misconfiguration of Barbican/Hashicorp Vault that meant that tokens expired after 10 uses. This allowed me to create 3 volumes successfully, followed by one that failed halfway through the creation. When retrying the creation flow, Cinder hits the metadata already exists issue.

I proposed https://review.opendev.org/c/openstack/cinder/+/764045 as a fairly simple fix, to allow idempotent specification of metadata, while still preventing changes.

[Dave McCowan (dave-mccowan)]

I also am affected by this bug. Kyle's workaround in #7 works for me.

[Sofia Enriquez (lsofia-enriquez)]

Fix related to this case https://review.opendev.org/c/openstack/cinder/+/812685

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/cinder/+/896584