nova.tests.integrated.test_servers.ServersTest.test_deferred_delete occasionally fails

[Joe Gordon]

Triggered when trying to merge something into nova trunk on June 20th.

Traceback (most recent call last):
  File "/home/jenkins/workspace/gate-nova-python27/nova/tests/integrated/test_servers.py", line 184, in test_deferred_delete
    self._wait_for_deletion(created_server_id)
  File "/home/jenkins/workspace/gate-nova-python27/nova/tests/integrated/test_servers.py", line 269, in _wait_for_deletion
    self.assertFalse(found_server)
  File "/usr/lib/python2.7/unittest/case.py", line 414, in assertFalse
    raise self.failureException(msg)
AssertionError: {u'OS-EXT-STS:task_state': None, u'addresses': {}, u'links': [{u'href': u'http://127.0.0.1:57188/v2/openstack/servers/489ffc95-7148-4cb7-a115-789ce6d640dc', u'rel': u'self'}, {u'href': u'http://127.0.0.1:57188/openstack/servers/489ffc95-7148-4cb7-a115-789ce6d640dc', u'rel': u'bookmark'}], u'image': {u'id': u'70a599e0-31e7-49b7-b260-868f441e862b', u'links': [{u'href': u'http://127.0.0.1:57188/openstack/images/70a599e0-31e7-49b7-b260-868f441e862b', u'rel': u'bookmark'}]}, u'OS-EXT-STS:vm_state': u'soft-delete', u'OS-EXT-SRV-ATTR:instance_name': u'instance-00000001', u'OS-SRV-USG:launched_at': u'2013-06-20T23:09:09.618686', u'flavor': {u'id': u'1', u'links': [{u'href': u'http://127.0.0.1:57188/openstack/flavors/1', u'rel': u'bookmark'}]}, u'id': u'489ffc95-7148-4cb7-a115-789ce6d640dc', u'security_groups': [{u'name': u'default'}], u'user_id': u'fake', u'OS-DCF:diskConfig': u'AUTO', u'accessIPv4': u'', u'accessIPv6': u'', u'OS-EXT-STS:power_state': 1, u'OS-EXT-AZ:availability_zone': u'nova', u'config_drive': u'', u'status': u'DELETED', u'updated': u'2013-06-20T23:09:09Z', u'hostId': u'8cc1c0ac8a7a24eac4c2a57a5f9a9ff6f745b85d94878e96e3c35e82', u'OS-EXT-SRV-ATTR:host': u'c9057303c465432a94c486b9ed9a3636', u'OS-SRV-USG:terminated_at': None, u'key_name': None, u'OS-EXT-SRV-ATTR:hypervisor_hostname': u'fake-mini', u'name': u'server9JW55NSB', u'created': u'2013-06-20T23:09:09Z', u'tenant_id': u'openstack', u'metadata': {}} is not false

http://logs.openstack.org/33595/3/gate/gate-nova-python27/25424/testr_results.html.gz

[Joe Gordon (jogo)]

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

shows at least 40 hits

[John Garbutt (johngarbutt)]

Made this high, because it does seem to happen a lot on some of my changes in the gate, but I can't get it to fail on my dev box.

[Mathew Odden (locke105)]

Hitting this pretty often with my change in Gerrit: https://review.openstack.org/#/c/30479/

[Matt Riedemann (mriedem)]

I tried changing the retries to 100 (rather than 50) for just the test_deferred_delete in my development environment but it didn't fix the problem, so maybe more complicated than just increasing the timeout.

[Jakub Ružička (jruzicka)]

I hit this with https://review.openstack.org/28330 but I don't think it's related to the change.

Looks like it takes too long to terminate an instance for some reason.

Aside from failing unit tests, I think this may also make devstack exercises fail as they wait for instance termination as well.

[Matt Riedemann (mriedem)]

I have a hunch that this might be related to bug 1196255. I'm posting a fix for that now.

[Christopher Yeoh (cyeoh-0)]

FWIW the following two changesets of mine cause this test to fail consistently in the gate:

https://review.openstack.org/#/c/34828/
https://review.openstack.org/#/c/34829/

But I can't get it to fail on my local development machine at all - where testr runs 4 processes in parallel for the unitests so its not a simple parallel test issue. The interesting thing about the first changeset is that it doesn't change much at all - it is just a copy of v2 files to the v3 area, along with the unitests. So the image metadata unittests are run twice, but there is no difference in the tests. I'd guess that its somehow causing the tests to be run in a slightly different order on the gate machines which exacerbates the problem.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/35359
Committed: http://github.com/openstack/nova/commit/8b2ddad07abc74464a8ee7e28241adabf909cf3c
Submitter: Jenkins
Branch: master

commit 8b2ddad07abc74464a8ee7e28241adabf909cf3c
Author: Dan Smith <email address hidden>
Date: Tue Jul 2 11:37:15 2013 -0700

    Make test_deferred_delete() be deterministic

    This makes the test_deferred_delete test deterministic in its
    execution. Since it depends on periodic task scheduling and
    a somewhat unknown amount of time before the state change
    polling loop will give up, it has been failing a lot lately.

    This enforces a run of the specific task needed, as well as
    ensures that time appears to have elapsed sufficiently to
    justify a reclaim.

    Fixes bug 1193167

    Change-Id: Ideaf8abd19b10e018d284085309fe63282fa4b82