Race in test_image_glance_direct_import test for task transitioning to 'success'

[Ghanshyam Mann]

test_image_glance_direct_import failing for task stuck in processing state. I am seeing this failure multiple times today.

https://zuul.opendev.org/t/openstack/build/782dfe932de044a8a3b8557f750eaf25

https://zuul.openstack.org/builds?job_name=nova-ceph-multistore

Test failure traceback:

ft1.1: tempest.api.image.v2.test_images.ImportImagesTest.test_image_glance_direct_import[id-32ca0c20-e16f-44ac-8590-07869c9b4cc2]testtools.testresult.real._StringException: pythonlogging:'': {{{
2021-04-29 23:16:05,987 108390 INFO [tempest.lib.common.rest_client] Request (ImportImagesTest:test_image_glance_direct_import): 201 POST https://10.209.65.45/image/v2/images 0.047s
2021-04-29 23:16:05,987 108390 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"name": "tempest-image-1218822914", "container_format": "ami", "disk_format": "ami", "visibility": "private", "ramdisk_id": "00000000-1111-2222-3333-444455556666"}
    Response - Headers: {'date': 'Thu, 29 Apr 2021 23:16:05 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-length': '702', 'content-type': 'application/json', 'location': 'http://10.209.65.45:19292/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c', 'openstack-image-import-methods': 'glance-direct,web-download,copy-image', 'openstack-image-store-ids': 'cheap,robust', 'x-openstack-request-id': 'req-e1da164c-e6c1-4cd4-83e5-621f23057f2c', 'connection': 'close', 'status': '201', 'content-location': 'https://10.209.65.45/image/v2/images'}
        Body: b'{"ramdisk_id": "00000000-1111-2222-3333-444455556666", "name": "tempest-image-1218822914", "disk_format": "ami", "container_format": "ami", "visibility": "private", "size": null, "virtual_size": null, "status": "queued", "checksum": null, "protected": false, "min_ram": 0, "min_disk": 0, "owner": "03817cf7497c495b89228259cafbae80", "os_hidden": false, "os_hash_algo": null, "os_hash_value": null, "id": "e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "created_at": "2021-04-29T23:16:06Z", "updated_at": "2021-04-29T23:16:06Z", "locations": [], "tags": [], "self": "/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "file": "/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/file", "schema": "/v2/schemas/image"}'
2021-04-29 23:16:06,096 108390 INFO [tempest.lib.common.rest_client] Request (ImportImagesTest:test_image_glance_direct_import): 204 PUT https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/stage 0.107s
2021-04-29 23:16:06,096 108390 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/octet-stream', 'X-Auth-Token': '<omitted>'}
        Body: <callable_iterator object at 0x7fb7e67cebe0>
    Response - Headers: {'date': 'Thu, 29 Apr 2021 23:16:06 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'text/html; charset=UTF-8', 'x-openstack-request-id': 'req-7cf0ee09-7eb4-4a3a-a83e-72bde45ed46e', 'connection': 'close', 'status': '204', 'content-location': 'https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/stage'}
        Body: b''
2021-04-29 23:16:06,129 108390 INFO [tempest.lib.common.rest_client] Request (ImportImagesTest:test_image_glance_direct_import): 200 GET https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c 0.032s
2021-04-29 23:16:06,129 108390 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Thu, 29 Apr 2021 23:16:06 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-length': '705', 'content-type': 'application/json', 'x-openstack-request-id': 'req-42089312-7efe-41f6-9a5f-54285cae3c08', 'connection': 'close', 'status': '200', 'content-location': 'https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c'}
        Body: b'{"ramdisk_id": "00000000-1111-2222-3333-444455556666", "name": "tempest-image-1218822914", "disk_format": "ami", "container_format": "ami", "visibility": "private", "size": null, "virtual_size": null, "status": "uploading", "checksum": null, "protected": false, "min_ram": 0, "min_disk": 0, "owner": "03817cf7497c495b89228259cafbae80", "os_hidden": false, "os_hash_algo": null, "os_hash_value": null, "id": "e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "created_at": "2021-04-29T23:16:06Z", "updated_at": "2021-04-29T23:16:06Z", "locations": [], "tags": [], "self": "/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "file": "/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/file", "schema": "/v2/schemas/image"}'
2021-04-29 23:16:06,983 108390 INFO [tempest.lib.common.rest_client] Request (ImportImagesTest:test_image_glance_direct_import): 202 POST https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/import 0.853s
2021-04-29 23:16:06,983 108390 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"method": {"name": "glance-direct"}, "all_stores": true}
    Response - Headers: {'date': 'Thu, 29 Apr 2021 23:16:06 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'text/html; charset=UTF-8', 'content-length': '0', 'x-openstack-request-id': 'req-794e68ce-a24a-4f9b-a4e0-aac8f37e18c9', 'connection': 'close', 'status': '202', 'content-location': 'https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/import'}
        Body: b''
2021-04-29 23:16:07,017 108390 INFO [tempest.lib.common.rest_client] Request (ImportImagesTest:test_image_glance_direct_import): 200 GET https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c 0.033s
2021-04-29 23:16:07,017 108390 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Thu, 29 Apr 2021 23:16:07 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-length': '770', 'content-type': 'application/json', 'x-openstack-request-id': 'req-c6ad5fd4-a507-459a-b36f-6220d6ff2306', 'connection': 'close', 'status': '200', 'content-location': 'https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c'}
        Body: b'{"os_glance_import_task": "cb9394df-61cd-4460-93b5-50419f3eb92d", "ramdisk_id": "00000000-1111-2222-3333-444455556666", "name": "tempest-image-1218822914", "disk_format": "ami", "container_format": "ami", "visibility": "private", "size": null, "virtual_size": null, "status": "uploading", "checksum": null, "protected": false, "min_ram": 0, "min_disk": 0, "owner": "03817cf7497c495b89228259cafbae80", "os_hidden": false, "os_hash_algo": null, "os_hash_value": null, "id": "e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "created_at": "2021-04-29T23:16:06Z", "updated_at": "2021-04-29T23:16:06Z", "locations": [], "tags": [], "self": "/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "file": "/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/file", "schema": "/v2/schemas/image"}'
2021-04-29 23:16:08,072 108390 INFO [tempest.lib.common.rest_client] Request (ImportImagesTest:test_image_glance_direct_import): 200 GET https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c 0.054s
2021-04-29 23:16:08,073 108390 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Thu, 29 Apr 2021 23:16:08 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-length': '1274', 'content-type': 'application/json', 'x-openstack-request-id': 'req-de349fdc-a162-4eee-8c1a-2f14beb81747', 'connection': 'close', 'status': '200', 'content-location': 'https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c'}
        Body: b'{"os_glance_failed_import": "", "os_glance_importing_to_stores": "", "os_glance_import_task": "cb9394df-61cd-4460-93b5-50419f3eb92d", "ramdisk_id": "00000000-1111-2222-3333-444455556666", "name": "tempest-image-1218822914", "disk_format": "ami", "container_format": "ami", "visibility": "private", "size": 1024, "virtual_size": 1024, "status": "active", "checksum": "cdf9e5b09167bfa1c4a346c6d0c26649", "protected": false, "min_ram": 0, "min_disk": 0, "owner": "03817cf7497c495b89228259cafbae80", "os_hidden": false, "os_hash_algo": "sha512", "os_hash_value": "69b3bcadcf2c9210edadd0702826862fb24b0291061bc0e5f86111c244684c06b2a4f0dedc127e06595b86a56e2166f558a49cc8c99b5401981969b84bf3b25c", "id": "e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "created_at": "2021-04-29T23:16:06Z", "updated_at": "2021-04-29T23:16:08Z", "locations": [{"url": "file:///opt/stack/data/glance/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "metadata": {"store": "cheap"}}, {"url": "rbd://6c6e1f6d-fa2f-4946-9625-92ec727580f9/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/snap", "metadata": {"store": "robust"}}], "tags": [], "self": "/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "file": "/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/file", "schema": "/v2/schemas/image", "stores": "cheap,robust"}'
2021-04-29 23:16:08,082 108390 INFO [tempest.lib.common.rest_client] Request (ImportImagesTest:test_image_glance_direct_import): 300 GET https://10.209.65.45/image/ 0.009s
2021-04-29 23:16:08,082 108390 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json'}
        Body: None
    Response - Headers: {'date': 'Thu, 29 Apr 2021 23:16:08 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'application/json', 'content-length': '1432', 'connection': 'close', 'status': '300', 'content-location': 'https://10.209.65.45/image/'}
        Body: b'{"versions": [{"id": "v2.12", "status": "CURRENT", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.11", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.10", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.9", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.8", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.7", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.6", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.5", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.4", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.3", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.2", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.1", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}, {"id": "v2.0", "status": "SUPPORTED", "links": [{"rel": "self", "href": "https://10.209.65.45/image/v2/"}]}]}'
2021-04-29 23:16:08,121 108390 INFO [tempest.lib.common.rest_client] Request (ImportImagesTest:test_image_glance_direct_import): 200 GET https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/tasks 0.038s
2021-04-29 23:16:08,122 108390 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Thu, 29 Apr 2021 23:16:08 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'application/json', 'content-length': '670', 'x-openstack-request-id': 'req-29395d6a-4f77-4a98-9ac9-f7d43cf35064', 'connection': 'close', 'status': '200', 'content-location': 'https://10.209.65.45/image/v2/images/e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c/tasks'}
        Body: b'{"tasks": [{"id": "cb9394df-61cd-4460-93b5-50419f3eb92d", "type": "api_image_import", "status": "processing", "owner": "03817cf7497c495b89228259cafbae80", "expires_at": null, "created_at": "2021-04-29T23:16:06.000000", "updated_at": "2021-04-29T23:16:08.000000", "deleted_at": null, "deleted": false, "image_id": "e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "request_id": "req-794e68ce-a24a-4f9b-a4e0-aac8f37e18c9", "user_id": "914944377cf04485bb22af2420543224", "input": {"image_id": "e7b9a4fb-5ff4-4b23-9cfe-f39dd41f986c", "import_req": {"method": {"name": "glance-direct"}, "all_stores": true}, "backend": ["cheap", "robust"]}, "result": null, "message": "Copied 0 MiB"}]}'
}}}

Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/api/image/v2/test_images.py", line 113, in test_image_glance_direct_import
    self.assertEqual('success', task['status'])
  File "/opt/stack/tempest/.tox/tempest/lib/python3.8/site-packages/testtools/testcase.py", line 415, in assertEqual
    self.assertThat(observed, matcher, message)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.8/site-packages/testtools/testcase.py", line 502, in assertThat
    raise mismatch_error
testtools.matchers._impl.MismatchError: 'success' != 'processing'

[Ghanshyam Mann (ghanshyammann)]

It seems glance task is transitioned to success correctly
- https://zuul.opendev.org/t/openstack/build/85c8131c56f34259bc509692f4be53bb/log/controller/logs/screen-g-api.txt#22480

[Ghanshyam Mann (ghanshyammann)]

It looks like a race between glance moving the task to success and tempest fetching it.

Temepst fetching task to check the status:

    Response - Headers: {'date': 'Thu, 29 Apr 2021 22:45:11 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'application/json', 'content-length': '670', 'x-openstack-request-id': 'req-39d37671-e013-4c64-9bb6-a6853d11852c', 'connection': 'close', 'status': '200', 'content-location': 'https://198.72.124.57/image/v2/images/54c8602c-3c42-4a7f-a08e-4a275126ad01/tasks'}
        Body: b'{"tasks": [{"id": "c160f70d-84ae-401f-8eaf-4578ffc83a0a", "type": "api_image_import", "status": "processing", "owner": "27eb3a8a0a184ed988ab1e8326ce3b97", "expires_at": null, "created_at": "2021-04-29T22:45:10.000000", "updated_at": "2021-04-29T22:45:11.000000", "deleted_at": null, "deleted": false, "image_id": "54c8602c-3c42-4a7f-a08e-4a275126ad01", "request_id": "req-d6f5549a-6844-4510-a206-8a1af3cbc76e", "user_id": "aa935c73f9dc46a68508d13057b25b7c", "input": {"image_id": "54c8602c-3c42-4a7f-a08e-4a275126ad01", "import_req": {"method": {"name": "glance-direct"}, "all_stores": true}, "backend": ["cheap", "robust"]}, "result": null, "message": "Copied 0 MiB"}]}'
}}}

glance moved the task to 'Success'

Apr 29 22:45:11.750215 ubuntu-focal-inap-mtl01-0024446767 glance-api[103800]: DEBUG glance.async_.taskflow_executor [-] Task 'api_image_import-CompleteTask-c160f70d-84ae-401f-8eaf-4578ffc83a0a' (b853ae06-e58f-4f08-84d9-3308b2cd2702) transitioned into state 'SUCCESS' from state 'RUNNING' with result 'None' {{(pid=103800) _task_receiver /usr/local/lib/python3.8/dist-packages/taskflow/listeners/logging.py:178}}

We can wait for task transition in Tempest to avoid this.

[OpenStack Infra (hudson-openstack)]

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

[Ghanshyam Mann (ghanshyammann)]

fixing here https://review.opendev.org/c/openstack/tempest/+/788856

[OpenStack Infra (hudson-openstack)]

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

commit b15b58e964a61fd580c506689c62e949a8f6956a
Author: Ghanshyam Mann <email address hidden>
Date: Thu Apr 29 19:45:29 2021 -0500

    Add wait to check the import task status

    Once Glance finish the import operation(change image status
    to active), it move the task to 'success' state but in between of
    image become active and task is transitioning to 'success', tempest
    try to check the task status and race condition happen.

    Adding waiter method in test for task status check.

    Closes-Bug: #1926671
    Change-Id: I960b80314f1b0926eca33af830bc827f31cbeda6

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/tempest train-last release.