ImagesTestJSON.test_delete_saving_image can wait for image status SAVING when the snapshot is already ACTIVE

[Matt Riedemann]

Test failed here:

http://logs.openstack.org/40/521640/9/check/legacy-tempest-dsvm-py35/64a4b15/job-output.txt.gz#_2017-12-11_20_57_38_640544

It times out waiting for the snapshot image status to be SAVING so it can delete the image while nova is uploading the image, however, by the time it checks for the image status, the image is already ACTIVE. Nova is using live snapshot in this scenario so the image snapshot and upload is actually pretty fast, but there is also a weird 3 second gap between the time Tempest issues the createImage action to the server and when it checks the image status.

Tempest logs:

a) create image

b'2017-12-11 20:31:45,434 29413 INFO [tempest.lib.common.rest_client] Request (ImagesTestJSON:test_delete_saving_image): 202 POST https://166.78.99.121/compute/v2.1/servers/e30c5e27-aa86-4f6f-8c9b-489823a1419b/action 0.693s'

b) start checking image status (already active)

b'2017-12-11 20:31:48,083 29413 INFO [tempest.lib.common.rest_client] Request (ImagesTestJSON:test_delete_saving_image): 200 GET https://166.78.99.121/compute/v2.1/images/4965a0f8-4e88-41b5-b0f3-330cc145e264 2.647s'

nova-compute logs:

Dec 11 20:31:45.692437 ubuntu-xenial-rax-ord-0001370055 nova-compute[22493]: INFO nova.virt.libvirt.driver [None req-c0bd6ca6-09f4-4466-b6e2-ff873ce2a4b4 service nova] [instance: e30c5e27-aa86-4f6f-8c9b-489823a1419b] Beginning live snapshot process

Dec 11 20:31:46.481816 ubuntu-xenial-rax-ord-0001370055 nova-compute[22493]: INFO nova.virt.libvirt.driver [None req-c0bd6ca6-09f4-4466-b6e2-ff873ce2a4b4 service nova] [instance: e30c5e27-aa86-4f6f-8c9b-489823a1419b] Snapshot extracted, beginning image upload

Dec 11 20:31:47.291345 ubuntu-xenial-rax-ord-0001370055 nova-compute[22493]: INFO nova.virt.libvirt.driver [None req-c0bd6ca6-09f4-4466-b6e2-ff873ce2a4b4 service nova] [instance: e30c5e27-aa86-4f6f-8c9b-489823a1419b] Snapshot image upload complete

--

As we can see, the image upload is already complete by the time Tempest starts checking the image status.

[Matt Riedemann (mriedem)]

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22ImagesTestJSON%3Atest_delete_saving_image)%20Image%5C%22%20AND%20message%3A%5C%22failed%20to%20reach%20SAVING%20state%20(current%20state%20ACTIVE)%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d

[melanie witt (melwitt)]

I took a look at this bug today after I saw a gate failure because of it. In the tempest code, I didn't see what could be causing the 3 second delay between the request for the image creation and the GET of the image. So, I didn't see any way to fix the bug.

Can anyone give me a pointer?