test_stacks fails in tearDownClass - Conflict: An object with that identifier already exists

[Matt Riedemann]

http://logs.openstack.org/75/107875/2/check/check-tempest-dsvm-postgres-full/e599a6e/console.html

2014-07-18 16:23:08.843 | tearDownClass (tempest.api.orchestration.stacks.test_stacks.StacksTestJSON)
2014-07-18 16:23:08.843 | ---------------------------------------------------------------------------
2014-07-18 16:23:08.843 |
2014-07-18 16:23:08.843 | Captured traceback:
2014-07-18 16:23:08.843 | ~~~~~~~~~~~~~~~~~~~
2014-07-18 16:23:08.843 | Traceback (most recent call last):
2014-07-18 16:23:08.843 | File "tempest/api/orchestration/base.py", line 138, in tearDownClass
2014-07-18 16:23:08.843 | cls._clear_stacks()
2014-07-18 16:23:08.843 | File "tempest/api/orchestration/base.py", line 82, in _clear_stacks
2014-07-18 16:23:08.844 | cls.client.delete_stack(stack_identifier)
2014-07-18 16:23:08.844 | File "tempest/services/orchestration/json/orchestration_client.py", line 142, in delete_stack
2014-07-18 16:23:08.844 | return self.delete("stacks/%s" % str(stack_identifier))
2014-07-18 16:23:08.844 | File "tempest/common/rest_client.py", line 224, in delete
2014-07-18 16:23:08.844 | return self.request('DELETE', url, extra_headers, headers, body)
2014-07-18 16:23:08.844 | File "tempest/common/rest_client.py", line 430, in request
2014-07-18 16:23:08.844 | resp, resp_body)
2014-07-18 16:23:08.844 | File "tempest/common/rest_client.py", line 484, in _error_checker
2014-07-18 16:23:08.844 | raise exceptions.Conflict(resp_body)
2014-07-18 16:23:08.844 | Conflict: An object with that identifier already exists
2014-07-18 16:23:08.845 | Details: {u'title': u'Conflict', u'explanation': u'There was a conflict when trying to complete your request.', u'code': 409, u'error': {u'message': u'Stack heat-1063480592 already has an action (DELETE) in progress.', u'traceback': u'Traceback (most recent call last):\n\n File "/opt/stack/new/heat/heat/engine/service.py", line 63, in wrapped\n return func(self, ctx, *args, **kwargs)\n\n File "/opt/stack/new/heat/heat/engine/service.py", line 781, in delete_stack\n stack.delete)\n\n File "/opt/stack/new/heat/heat/engine/service.py", line 113, in start_with_lock\n with lock.thread_lock(stack.id):\n\n File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__\n return self.gen.next()\n\n File "/opt/stack/new/heat/heat/engine/stack_lock.py", line 136, in thread_lock\n self.release(stack_id)\n\n File "/opt/stack/new/heat/heat/openstack/common/excutils.py", line 82, in __exit__\n six.reraise(self.type_, self.value, self.tb)\n\n File "/opt/stack/new/heat/heat/engine/stack_lock.py", line 132, in thread_lock\n self.acquire()\n\n File "/opt/stack/new/heat/heat/engine/stack_lock.py", line 81, in acquire\n action=self.stack.action)\n\nActionInProgress: Stack heat-1063480592 already has an action (DELETE) in progress.\n', u'type': u'ActionInProgress'}}

The error is in the heat-api log here:

http://logs.openstack.org/75/107875/2/check/check-tempest-dsvm-postgres-full/e599a6e/logs/screen-h-api.txt.gz#_2014-07-18_16_08_27_238

We can't fingerprint on that in logstash because it's not at INFO level or higher.

4 hits in 2 weeks, check queue only I guess but multiple changes, all failures:

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

[Matt Riedemann (mriedem)]

e-r query: https://review.openstack.org/#/c/108203/

[Steven Hardy (shardy)]

This is probably because we start a delete in the test, but don't wait for it to complete:

https://github.com/openstack/tempest/blob/master/tempest/api/orchestration/stacks/test_stacks.py#L66

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

commit 6149e1a24f159303d2c3ec412a64a8a9c5030260
Author: Steven Hardy <email address hidden>
Date: Thu Jul 24 14:51:25 2014 +0100

    orchestration: tolerate NotFound in wait_for_stack_status

    When waiting for a stack to transition to DELETE_COMPLETE status
    it's possible to either get that status, or a NotFound exception
    so catch the exception and return in that case, to avoid needing
    try/except around the wait, or risking races in tests which wait
    for DELETE_COMPLETE without a try/except (test_volumes.py)

    Change-Id: I4ded172db3c8969075365a0dc6b60d8e3e7db71d
    Partial-Bug: #1344989

[OpenStack Infra (hudson-openstack)]

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

commit 93eddccb31a5e46a24261c32c434e493b6123c4b
Author: Steven Hardy <email address hidden>
Date: Thu Jul 24 15:03:33 2014 +0100

    orchestration api test_stacks wait for deletion

    Wait for delete to complete after triggering it, so we avoid
    a conflict exception when the test _clear_stacks cleanup tries
    to delete it again.

    Change-Id: I64065ad8444d814e2cd7f162b869a2f8eedb1fad
    Closes-Bug: #1344989