test_create_backup fails due to unexpected image number

[Ken'ichi Ohmichi]

test_create_backup failed with the following traceback:

Traceback (most recent call last):
  File "tempest/api/compute/servers/test_server_actions.py", line 298, in test_create_backup
    self.assertEqual(2, len(image_list))
  File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 324, in assertEqual
    self.assertThat(observed, matcher, message)
  File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 414, in assertThat
    raise MismatchError(matchee, matcher, mismatch, verbose)
MismatchError: 2 != 3

This test expects the gotten backup image number should be 2 which is limited with a rotation.
However, we could get 3 images and the test failed.

The log are
* http://logs.openstack.org/65/63365/5/check/check-tempest-dsvm-postgres-full/996c8f9/
* http://logs.openstack.org/65/63365/5/gate/gate-tempest-dsvm-postgres-full/4880d61/

[Matt Riedemann (mriedem)]

Hit this here also:

http://logs.openstack.org/72/60272/7/gate/gate-tempest-dsvm-full/c7151fd/console.html

Is this really a tempest bug or a nova bug, since it's coming from a compute test (or maybe a glance bug?).

We need an e-r query fingerprint for this also.

[Matt Riedemann (mriedem)]

13 hits in 7 days:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiRkFJTDogdGVtcGVzdC5hcGkuY29tcHV0ZS5zZXJ2ZXJzLnRlc3Rfc2VydmVyX2FjdGlvbnMuU2VydmVyQWN0aW9uc1Rlc3RKU09OLnRlc3RfY3JlYXRlX2JhY2t1cFwiIEFORCBmaWxlbmFtZTpcImNvbnNvbGUuaHRtbFwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxMzkwNTc4MTcwMzAxfQ==

[David Kranz (david-kranz)]

This seems to be a duplicate of https://bugs.launchpad.net/nova/+bug/1269192. I'm not sure how the nova team wants to adjust these two tickets to reflect that.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/68950

[Matt Riedemann (mriedem)]

David, thanks, I duped the nova one to this one since I have a related patch up for this one, and I think this is most likely a race issue in the way the tempest test is written more than a nova/glance bug.

[David Kranz (david-kranz)]

So I looked carefully at this test and don't think there is a race in tempest. What I do see is that at line 289 we wait for the first image to have been deleted, then immediately make the call to list images. So I would point the first finger at a race condition in glance where it responds to image get with NotFound at the same moment where the image is still being return as part of a list call.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/68950
Committed: https://git.openstack.org/cgit/openstack/tempest/commit/?id=e699f82050be6e3b50f7d814f2a8f60ba0832876
Submitter: Jenkins
Branch: master

commit e699f82050be6e3b50f7d814f2a8f60ba0832876
Author: Matt Riedemann <email address hidden>
Date: Fri Jan 24 08:11:42 2014 -0800

    Add more descriptive assertion message for test_create_backup

    In order to fingerprint the failure for gate race bug 1267326 in
    elastic-recheck, the assertion message needs to be specific to the test
    case that's failing. We have to do something like this until we have
    multi-line query support in elastic-recheck.

    Also makes the backup names more specific.

    Related-Bug: #1267326

    Change-Id: I4cf4a3409eedf64f928ae7b0ff4a660c116b89bc

[Matt Riedemann (mriedem)]

Now that we have a more descriptive fail message, we can use this as the new query:

message:"Unexpected number of images for" AND message:"test_create_backup; was the oldest backup not yet deleted? Image list:" and filename:"console.html"

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiVW5leHBlY3RlZCBudW1iZXIgb2YgaW1hZ2VzIGZvclwiIEFORCBtZXNzYWdlOlwidGVzdF9jcmVhdGVfYmFja3VwOyB3YXMgdGhlIG9sZGVzdCBiYWNrdXAgbm90IHlldCBkZWxldGVkPyBJbWFnZSBsaXN0OlwiIGFuZCBmaWxlbmFtZTpcImNvbnNvbGUuaHRtbFwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiIxNzI4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxMzkwNjc0NTA3Mjg4fQ==

[Matt Riedemann (mriedem)]

elastic-recheck query patch: https://review.openstack.org/#/c/69144/

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/69369

[David Kranz (david-kranz)]

I get the work-around but why is this not a bug in glance?

[Ken'ichi Ohmichi (oomichi)]

Hi David,

OK, I have added glance to this report and will write the details related to glance.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/69369
Committed: https://git.openstack.org/cgit/openstack/tempest/commit/?id=06d37cfbcf387fac74f558a2c6a1c66c33b6d9f2
Submitter: Jenkins
Branch: master

commit 06d37cfbcf387fac74f558a2c6a1c66c33b6d9f2
Author: Ken'ichi Ohmichi <email address hidden>
Date: Tue Jan 28 07:55:46 2014 +0900

    Specify 'active' status for deleting situations

    The test creates 3 backups with the rotation 2 and checks that
    2 backups exist with getting its image list. test_create_backup
    fails sometimes due to the existence of 3 backups.

    Glance v1 delete_image API changes an image's status to 'deleted'
    then the deleted flag to 'true'. If getting a list between the
    status change and the delete flag change, we can get a list including
    the deleting backup also like the following:

    {"images": [
      {"status": "deleted", "name": "backup-1-tempest-438772029",
       "deleted": false, ..},
      {"status": "active", "name": "backup-2-tempest-2111479443",
       "deleted": false, ..},

    To avoid this situation, this patch adds the status 'active' to the
    calls which get the backup list.

    Change-Id: I59966534a8eb1430604cada1f64b8c8df46a5f17
    Closes-Bug: #1267326

[Ken'ichi Ohmichi (oomichi)]

test_create_backup checks the delete of a server backup by getting an image detail through glance v1 API, that waits for HTTP 404(Not Found) response.
After that, the test gets an image list through glance v1 "get an image list" API.
The API returns a response including the deleting image like the following,

 {"images": [
      {"status": "deleted", "name": "backup-1-tempest-438772029", "deleted": false, ..},
      {"status": "active", "name": "backup-2-tempest-2111479443", "deleted": false, ..},
      ...
 }

This behavior seems inconsistent from the API viewpoint.
If an image is deleting, the "get an image detail" API returns "Not Found" response.
but the "get an image list" API returns a response including it.

Can we fix this behavior?

http://logs.openstack.org/36/69236/2/check/check-tempest-dsvm-postgres-full/0b4120d/logs/tempest.txt.gz