Tempest test: "test_create_second_image_when_first_image_is_being_saved" failing in featureset020 periodic job

[yatin]

1 Tempest test(test_create_second_image_when_first_image_is_being_saved) is failing in featureset020 master periodic job.

Failure logs:-
https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/3f97360/undercloud/home/jenkins/tempest/tempest.html.gz
https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/3f97360/undercloud/home/jenkins/tempest_output.log.txt.gz#_2018-01-23_07_27_56

For comparison logs of job which passed this test:-
https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/60f5231/undercloud/home/jenkins/tempest_output.log.txt.gz#_2018-01-20_10_59_44_536
https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/5937f4f/undercloud/home/jenkins/tempest_output.log.txt.gz#_2018-01-20_16_01_49_345
https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/f4445e9/undercloud/home/jenkins/tempest_output.log.txt.gz#_2018-01-19_10_58_02_075

The test tries to create an image from server twice: 1st should pass(return 202) and 2nd should return 409(as server task state is image_pending_upload).

In the failing job 2nd try also return 202 so the test is failing.
The thing i noted is that 2nd request in failing job is taking 4+second while in passing jobs it takes less than .5 seconds, so it might be related to some performance.

[Alan Pevec (apevec)]

This is a race that failing negative testcase [1] is supposed to catch
# Disallow creating another image when first image is being saved
and failing test taking longer is an indication that another image is created when it should not.

[1] https://git.openstack.org/cgit/openstack/tempest/tree/tempest/api/compute/images/test_images_oneserver_negative.py#n96

[yatin (yatinkarel)]

Update: Failed tempest test in last run of fs20 passed:- https://review.rdoproject.org/jenkins/job/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/607

[melanie witt (melwitt)]

Agreed, test_create_second_image_when_first_image_is_being_saved appears brittle as it expects the first image is still busy being created when the second image create is attempted and expects to fail the second image create.

If there is unexpected delay in the CI environment between the first image create and the second image create attempt, the second image create will succeed if the first image has already finished.

[Alex Schultz (alex-schultz)]

Since this is not currently failing consistently I think it's a High bug. If it starts failing consistently we need to figure out a plan to address it and should raid the priority.

[wes hayutin (weshayutin)]

The quality of this tests is still uncertain. It has passed the last three attempts where tempest was executed [1]. It passed twice on the 20th and once on the 21st.

If this test fails in tempest again it will be moved to the skip list [2]

[1] https://review.rdoproject.org/jenkins/job/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-queens/
[2] https://github.com/openstack/tripleo-quickstart-extras/blob/master/roles/validate-tempest/vars/tempest_skip_queens.yml

[yatin (yatinkarel)]

Seeing the failure in fs20 queens last run:- https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-queens/165b64e/undercloud/home/jenkins/tempest/tempest.html.gz

1st image create request:- https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-queens/165b64e/overcloud-controller-0/var/log/containers/nova/nova-api.log.txt.gz#_2018-04-17_01_18_54_018 time: 0.266061

Request in middle of both the image create requests.
Possibly culprit:- https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-queens/165b64e/overcloud-controller-0/var/log/containers/nova/nova-api.log.txt.gz#_2018-04-17_01_18_58_701 time: 4.679591. This /os-interface task took 4.679591 sec so in this time image should have successfully created.

2nd image create request:- https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-queens/165b64e/overcloud-controller-0/var/log/containers/nova/nova-api.log.txt.gz#_2018-04-17_01_18_58_992 time: 0.290046

So need to find why tempest waited to fire the above second request. These two image request should be too quick to get the test succeeded.

[yatin (yatinkarel)]

Seen again:- https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-queens/f7a11fa/undercloud/home/jenkins/tempest/tempest.html.gz

1st Request:- https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-queens/f7a11fa/overcloud-controller-0/var/log/containers/nova/nova-api.log.txt.gz#_2018-05-02_01_12_46_021

middle request that takes time:- https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-queens/f7a11fa/overcloud-controller-0/var/log/containers/nova/nova-api.log.txt.gz#_2018-05-02_01_12_49_897 3.874891
Good to find why this request is taking around 4 seconds, is this expected.

2nd request:- https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-queens/f7a11fa/overcloud-controller-0/var/log/containers/nova/nova-api.log.txt.gz#_2018-05-02_01_12_50_111