test_snapshot_volume_backed_multiattach not waiting for volume snapshot to become available

[Lee Yarwood]

tempest.api.compute.volumes.test_attach_volume.AttachVolumeMultiAttachTest.test_snapshot_volume_backed_multiattach is failing often as an underlying volume snapshot is still being taken when the test attempts to delete the volume:

https://zuul.opendev.org/t/openstack/build/fce6478a6842495f851b8c88336f0049/log/job-output.txt#64744

The following request is made to delete the volume at the end of the test:

10286 Dec 08 13:56:34.163872 ubuntu-focal-ovh-bhs1-0022113429 <email address hidden>[92924]: INFO cinder.api.openstack.wsgi [None req-e74dc838-d1ca-4f1e-a741-62266bfecc25 tempest-AttachVolumeMultiAttachTest-780655361 tempest-AttachVolumeMultiAttachTest-780655361] DELETE https://158.69.67.122/volume/v3/70c0b89a31a4419988bd36cdf626152e/volumes/2fde1d85-5e48-457f-ac6d-aa8ac73cc0dc?cascade=True

However c-vol is still processing an earlier request to create a snapshot after returning 200 to the caller (n-api in this case):

Dec 08 13:56:28.615832 ubuntu-focal-ovh-bhs1-0022113429 <email address hidden>[92925]: INFO cinder.api.v2.snapshots [req-e04e85aa-0735-4eb4-999b-8e72023fdfdb req-af2715d8-d0e6-4d9a-ae53-6061734887ac tempest-AttachVolumeMultiAttachTest-780655361 tempest-AttachVolumeMultiAttachTest-780655361] Create snapshot from volume 2fde1d85-5e48-457f-ac6d-aa8ac73cc0dc
10226 Dec 08 13:56:28.665637 ubuntu-focal-ovh-bhs1-0022113429 <email address hidden>[92925]: DEBUG cinder.quota [req-e04e85aa-0735-4eb4-999b-8e72023fdfdb req-af2715d8-d0e6-4d9a-ae53-6061734887ac tempest-AttachVolumeMultiAttachTest-780655361 tempest-AttachVolumeMultiAttachTest-780655361] Created reservations ['3fe60e31-2929-4e25-a29e-53eb70b6a587', '36d86826-1078-4dc4-b0e3-c6f5db6eb707', '13fa4f93-2ccb-498b-9048-8e9395ff613a', '1664e826-6210-4d0d-801e-df0029d8484f'] {{(pid=92925) reserve /opt/stack/cinder/cinder/quota.py:1036}}
10227 Dec 08 13:56:28.754630 ubuntu-focal-ovh-bhs1-0022113429 <email address hidden>[92925]: INFO cinder.volume.api [req-e04e85aa-0735-4eb4-999b-8e72023fdfdb req-af2715d8-d0e6-4d9a-ae53-6061734887ac tempest-AttachVolumeMultiAttachTest-780655361 tempest-AttachVolumeMultiAttachTest-780655361] Snapshot force create request issued successfully.
10228 Dec 08 13:56:28.755094 ubuntu-focal-ovh-bhs1-0022113429 <email address hidden>[92925]: INFO cinder.api.openstack.wsgi [req-e04e85aa-0735-4eb4-999b-8e72023fdfdb req-af2715d8-d0e6-4d9a-ae53-6061734887ac tempest-AttachVolumeMultiAttachTest-780655361 tempest-AttachVolumeMultiAttachTest-780655361] https://158.69.67.122/volume/v3/70c0b89a31a4419988bd36cdf626152e/snapshots returned with HTTP 202

4710 Dec 08 13:56:28.850442 ubuntu-focal-ovh-bhs1-0022113432 cinder-volume[55011]: DEBUG oslo_concurrency.processutils [req-e04e85aa-0735-4eb4-999b-8e72023fdfdb req-af2715d8-d0e6-4d9a-ae53-6061734887ac tempest-AttachVolumeMultiAttachTest-780655361 None] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvs --noheadings --unit=g -o vg_name,name,size --nosuffix stack-volumes-lvmdriver-1/volume-2fde1d85-5e48-457f-ac6d-aa8ac73cc0dc {{(pid=55011) execute /usr/local/lib/pyth on3.8/dist-packages/oslo_concurrency/processutils.py:384}}
[..]
4715 Dec 08 13:56:29.284790 ubuntu-focal-ovh-bhs1-0022113432 cinder-volume[55011]: DEBUG oslo_concurrency.processutils [req-e04e85aa-0735-4eb4-999b-8e72023fdfdb req-af2715d8-d0e6-4d9a-ae53-6061734887ac tempest-AttachVolumeMultiAttachTest-780655361 None] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvcreate --name _snapshot-cc035a07-0c78-4baf-ac64-9e57ad417057 --snapshot stack-volumes-lvmdriver-1/volume-2fde1d85-5e48-457f-ac6d-aa8ac73cc0dc {{(pid=55011) execute /us r/local/lib/python3.8/dist-packages/oslo_concurrency/processutils.py:384}}
[..]
4749 Dec 08 13:56:36.455593 ubuntu-focal-ovh-bhs1-0022113432 cinder-volume[55011]: DEBUG oslo_concurrency.processutils [req-e04e85aa-0735-4eb4-999b-8e72023fdfdb req-af2715d8-d0e6-4d9a-ae53-6061734887ac tempest-AttachVolumeMultiAttachTest-780655361 None] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvcreate --name _snapshot-cc035a07-0c78-4baf-ac64-9e57ad417057 --snapshot stack-volumes-lvmdriver-1/volume-2fde1d85-5e48-457f-ac6d-aa8ac73cc0dc" returned: 0 in 7.171s {{(pid=55011) execute /usr/local/lib/python3.8/dist-packages/oslo_concurrency/processutils.py:422}}

This leads to c-api returning 400 to the request to delete the volume:

10296 Dec 08 13:56:34.221682 ubuntu-focal-ovh-bhs1-0022113429 <email address hidden>[92924]: INFO cinder.api.openstack.wsgi [None req-e74dc838-d1ca-4f1e-a741-62266bfecc25 tempest-AttachVolumeMultiAttachTest-780655361 tempest-AttachVolumeMultiAttachTest-780655361] https://158.69.67.122/volume/v3/70c0b89a31a4419988bd36cdf626152e/volumes/2fde1d85-5e48-457f-ac6d-aa8ac73cc0dc?cascade=True returned with HTTP 400

The test needs to wait until the volume snapshot is available.

[Lee Yarwood (lyarwood)]

https://review.opendev.org/c/openstack/tempest/+/767165

[Martin Kopec (mkopec)]

any updates?

[OpenStack Infra (hudson-openstack)]

Change abandoned by "Lee Yarwood <email address hidden>" on branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/767165

[Lukas Piwowarski (lukas-piwowarski)]

Judging from the long inactivity, there is nobody who is working on this right now (In Progress -> Confirmed).

We run the mentioned test in the tempest-full-centos-9-strem job and it seems that it passes without any error. I checked even the job mentioned in the bug description and even there the test passes without any error (nova-next = the link). Although this does not mean that the race condition is not there.