ImageLocationsTest.test_replace_location fails intermittently

[Sylvain Bauza]

Saw a new gate failure happening a couple of times :

https://opensearch.logs.openstack.org/_dashboards/app/discover?security_tenant=global#/?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-7d,to:now))&_a=(columns:!(filename),filters:!(('$state':(store:appState),meta:(alias:!n,disabled:!f,index:'94869730-aea8-11ec-9e6a-83741af3fdcd',key:filename,negate:!f,params:(query:job-output.txt),type:phrase),query:(match_phrase:(filename:job-output.txt)))),index:'94869730-aea8-11ec-9e6a-83741af3fdcd',interval:auto,query:(language:kuery,query:test_replace_location),sort:!())

Example of a failed run :
2023-02-02 22:20:18.197006 | controller | ==============================
2023-02-02 22:20:18.197030 | controller | Failed 1 tests - output below:
2023-02-02 22:20:18.197050 | controller | ==============================
2023-02-02 22:20:18.197071 | controller |
2023-02-02 22:20:18.197095 | controller | tempest.api.image.v2.test_images.ImageLocationsTest.test_replace_location[id-bf6e0009-c039-4884-b498-db074caadb10]
2023-02-02 22:20:18.197115 | controller | ------------------------------------------------------------------------------------------------------------------
2023-02-02 22:20:18.197134 | controller |
2023-02-02 22:20:18.197152 | controller | Captured traceback:
2023-02-02 22:20:18.197171 | controller | ~~~~~~~~~~~~~~~~~~~
2023-02-02 22:20:18.197190 | controller | Traceback (most recent call last):
2023-02-02 22:20:18.197212 | controller |
2023-02-02 22:20:18.197234 | controller | File "/opt/stack/tempest/tempest/api/image/v2/test_images.py", line 875, in test_replace_location
2023-02-02 22:20:18.197254 | controller | image = self._check_set_multiple_locations()
2023-02-02 22:20:18.197273 | controller |
2023-02-02 22:20:18.197292 | controller | File "/opt/stack/tempest/tempest/api/image/v2/test_images.py", line 847, in _check_set_multiple_locations
2023-02-02 22:20:18.197311 | controller | image = self._check_set_location()
2023-02-02 22:20:18.197329 | controller |
2023-02-02 22:20:18.197351 | controller | File "/opt/stack/tempest/tempest/api/image/v2/test_images.py", line 820, in _check_set_location
2023-02-02 22:20:18.197372 | controller | self.client.update_image(image['id'], [
2023-02-02 22:20:18.197391 | controller |
2023-02-02 22:20:18.197410 | controller | File "/opt/stack/tempest/tempest/lib/services/image/v2/images_client.py", line 40, in update_image
2023-02-02 22:20:18.197429 | controller | resp, body = self.patch('images/%s' % image_id, data, headers)
2023-02-02 22:20:18.197447 | controller |
2023-02-02 22:20:18.197465 | controller | File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 346, in patch
2023-02-02 22:20:18.197490 | controller | return self.request('PATCH', url, extra_headers, headers, body)
2023-02-02 22:20:18.197513 | controller |
2023-02-02 22:20:18.197533 | controller | File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 720, in request
2023-02-02 22:20:18.197552 | controller | self._error_checker(resp, resp_body)
2023-02-02 22:20:18.197571 | controller |
2023-02-02 22:20:18.197590 | controller | File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 831, in _error_checker
2023-02-02 22:20:18.197612 | controller | raise exceptions.BadRequest(resp_body, resp=resp)
2023-02-02 22:20:18.197633 | controller |
2023-02-02 22:20:18.197655 | controller | tempest.lib.exceptions.BadRequest: Bad request
2023-02-02 22:20:18.197674 | controller | Details: b'400 Bad Request\n\nThe Store URI was malformed.\n\n '
2023-02-02 22:20:18.197692 | controller |
2023-02-02 22:20:18.197711 | controller |
2023-02-02 22:20:18.197729 | controller | Captured pythonlogging:
2023-02-02 22:20:18.197748 | controller | ~~~~~~~~~~~~~~~~~~~~~~~
2023-02-02 22:20:18.197774 | controller | 2023-02-02 22:01:06,773 114933 INFO [tempest.lib.common.rest_client] Request (ImageLocationsTest:test_replace_location): 201 POST https://10.210.193.38/image/v2/images 1.036s
2023-02-02 22:20:18.197798 | controller | 2023-02-02 22:01:06,774 114933 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
2023-02-02 22:20:18.198218 | controller | Body: {"container_format": "bare", "disk_format": "raw"}
2023-02-02 22:20:18.198250 | controller | Response - Headers: {'date': 'Thu, 02 Feb 2023 22:01:06 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-length': '626', 'content-type': 'application/json', 'location': 'http://10.210.193.38:19292/v2/images/36bc7732-dfbd-4d63-871d-ff84b0be764e', 'openstack-image-import-methods': 'glance-direct,web-download,copy-image', 'openstack-image-store-ids': 'cheap,robust,web,os_glance_staging_store,os_glance_tasks_store', 'x-openstack-request-id': 'req-f0d0376e-9e9a-4e82-a528-643f1912004c', 'connection': 'close', 'status': '201', 'content-location': 'https://10.210.193.38/image/v2/images'}
2023-02-02 22:20:18.198293 | controller | Body: b'{"name": null, "disk_format": "raw", "container_format": "bare", "visibility": "shared", "size": null, "virtual_size": null, "status": "queued", "checksum": null, "protected": false, "min_ram": 0, "min_disk": 0, "owner": "73e1de12154c44f183f5dfdde1c91b85", "os_hidden": false, "os_hash_algo": null, "os_hash_value": null, "id": "36bc7732-dfbd-4d63-871d-ff84b0be764e", "created_at": "2023-02-02T22:01:07Z", "updated_at": "2023-02-02T22:01:07Z", "locations": [], "tags": [], "self": "/v2/images/36bc7732-dfbd-4d63-871d-ff84b0be764e", "file": "/v2/images/36bc7732-dfbd-4d63-871d-ff84b0be764e/file", "schema": "/v2/schemas/image"}'
2023-02-02 22:20:18.198314 | controller | 2023-02-02 22:01:06,898 114933 INFO [tempest.lib.common.rest_client] Request (ImageLocationsTest:test_replace_location): 400 PATCH https://10.210.193.38/image/v2/images/36bc7732-dfbd-4d63-871d-ff84b0be764e 0.123s
2023-02-02 22:20:18.198337 | controller | 2023-02-02 22:01:06,898 114933 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/openstack-images-v2.0-json-patch', 'X-Auth-Token': '<omitted>'}
2023-02-02 22:20:18.198357 | controller | Body: [{"add": "/locations/-", "value": {"metadata": {"foo": "bar"}, "url": "http://download.cirros-cloud.net/0.3.1/cirros-0.3.1-x86_64-uec.tar.gz"}}]
2023-02-02 22:20:18.198763 | controller | Response - Headers: {'date': 'Thu, 02 Feb 2023 22:01:06 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-length': '50', 'content-type': 'text/plain; charset=UTF-8', 'x-openstack-request-id': 'req-5aa720a8-575c-4f78-9f51-00d7daa21f4e', 'connection': 'close', 'status': '400', 'content-location': 'https://10.210.193.38/image/v2/images/36bc7732-dfbd-4d63-871d-ff84b0be764e'}
2023-02-02 22:20:18.198796 | controller | Body: b'400 Bad Request\n\nThe Store URI was malformed.\n\n '
2023-02-02 22:20:18.198818 | controller |

https://zuul.opendev.org/t/openstack/build/bc7699718de14023b3142c78a6e9f10c

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/872982

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/tempest/+/872982
Committed: https://opendev.org/openstack/tempest/commit/81ed09c058808910ba25dda8a742c3a3b33b1ab1
Submitter: "Zuul (22348)"
Branch: master

commit 81ed09c058808910ba25dda8a742c3a3b33b1ab1
Author: Dan Smith <email address hidden>
Date: Tue Feb 7 08:49:55 2023 -0800

    Retry glance add/update locations on BadRequest

    If glance is unable to fetch the http image URL we give it due to
    transient network problems, we currently fail the test because it
    does not retry itself and we get a BadRequest. Because such problems
    can happen in a CI run due to network interruptions, this adds a
    retry loop on that condition when we go to add a location. If we fail
    to add the location for some legit reason related to our actual
    location URI or other parts of the request, all the retries will
    fail and we'll still catch the problem.

    Change-Id: I944eb076c9f9056200dc193b52f2004038a6942f
    Related-Bug: #2004641
    Related-Bug: #1999800
    Related-Bug: #2006473

[Lukas Piwowarski (lukas-piwowarski)]

I'm moving this to "Confirmed" for now. The fix proposed by Dan seems to work. The test run 70 times in the last 7 days and did not fail a single time [1]. Let's give it a week and if we do not encounter the issue again we can close this.

[1] https://opensearch.logs.openstack.org/_dashboards/app/dashboards?security_tenant=global#/view/a2282980-4327-11ed-8b28-cdde0c7cf02f?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-7d,to:now))&_a=(description:'',filters:!(),fullScreenMode:!f,options:(hidePanelTitles:!f,useMargins:!t),query:(language:kuery,query:'test_name.keyword:%22tempest.api.image.v2.test_images.ImageLocationsTest.test_replace_location%22'),timeRestore:!f,title:'Subunit%20-%20Test%20Results',viewMode:view)

[Martin Kopec (mkopec)]

I didn't see that the job would fail because of the mentioned test the whole month (July). I consider this fixed by https://review.opendev.org/c/openstack/tempest/+/872982

[Martin Kopec (mkopec)]

This seems to be duplicate of https://bugs.launchpad.net/glance/+bug/1999800
I'll close this, it seems it got fixed by the change in tempest - https://review.opendev.org/c/openstack/tempest/+/872982
Feel free to reopen and retriage if felt otherwise.

[Martin Kopec (mkopec)]

This hasn't occurred again for some time now.
I'll close this, it seems it got fixed by the change in tempest - https://review.opendev.org/c/openstack/tempest/+/872982
Feel free to reopen and retriage if felt otherwise.