tempest.api.compute.servers.test_servers_negative fails in periodic-tripleo-ci-centos-8-standalone-full-tempest-api-master

[Arx Cruz]

https://logserver.rdoproject.org/openstack-periodic-integration-main/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-standalone-full-tempest-api-master/f9602c8/logs/undercloud/var/log/tempest/stestr_results.html.gz

ft1.1: setUpClass (tempest.api.compute.servers.test_servers_negative.ServersNegativeTestJSON)testtools.testresult.real._StringException: Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/tempest/test.py", line 188, in setUpClass
    six.reraise(etype, value, trace)
  File "/usr/local/lib/python3.6/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.6/site-packages/tempest/test.py", line 181, in setUpClass
    cls.resource_setup()
  File "/usr/lib/python3.6/site-packages/tempest/api/compute/servers/test_servers_negative.py", line 64, in resource_setup
    cls.client.delete_server(server['id'])
  File "/usr/lib/python3.6/site-packages/tempest/lib/services/compute/servers_client.py", line 158, in delete_server
    resp, body = self.delete("servers/%s" % server_id)
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/rest_client.py", line 329, in delete
    return self.request('DELETE', url, extra_headers, headers, body)
  File "/usr/lib/python3.6/site-packages/tempest/lib/services/compute/base_compute_client.py", line 48, in request
    method, url, extra_headers, headers, body, chunked)
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/rest_client.py", line 702, in request
    self._error_checker(resp, resp_body)
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/rest_client.py", line 879, in _error_checker
    message=message)
tempest.lib.exceptions.ServerFault: Got server fault
Details: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'AttributeError'>

This is a real bug, we need someone from nova to take a look

[Michal Pryc (mpryc)]

Here is possibly actual error from nova-api logs:

2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi [req-f31aa7c0-4954-4f13-81fb-8e1484900ec1 640ec55b7aa04b8ab260838c568ac7f9 eb3802b4c9a94aa99b40144702de9ef7 - default default] Unexpected exception in API method: AttributeError: 'NoneType' object has no attribute 'uuid'
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi Traceback (most recent call last):
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/nova/objects/instance.py", line 655, in destroy
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi hard_delete=hard_delete)
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/nova/db/api.py", line 549, in instance_destroy
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi hard_delete=hard_delete)
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/nova/db/sqlalchemy/api.py", line 179, in wrapper
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi return f(*args, **kwargs)
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/oslo_db/api.py", line 154, in wrapper
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi ectxt.value = e.inner_exc
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi self.force_reraise()
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi six.reraise(self.type_, self.value, self.tb)
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/six.py", line 703, in reraise
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi raise value
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/oslo_db/api.py", line 142, in wrapper
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi return f(*args, **kwargs)
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/nova/db/sqlalchemy/api.py", line 222, in wrapped
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi return f(context, *args, **kwargs)
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/nova/db/sqlalchemy/api.py", line 1166, in instance_destroy
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi raise exception.ConstraintNotMet()
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi nova.exception.ConstraintNotMet: Constraint not met.
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi During handling of the above exception, another exception occurred:
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi
2020-08-24 18:00:07.553 17 ERROR nova.api.openstack.wsgi Traceback (most recent call last):
2020-08-24 18:0...

[Lee Yarwood (lyarwood)]

Which commit of openstack/nova is this based on?

[Lee Yarwood (lyarwood)]

This looks like a race that leads to us hitting an issue introduced by https://review.opendev.org/#/c/702368/

Why we are calling _local_delete_cleanup when instance is None is beyond me tbh.

[Lee Yarwood (lyarwood)]

https://review.opendev.org/750661 should avoid this while we look into an actual fix in Nova.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/750661
Committed: https://git.openstack.org/cgit/openstack/tempest/commit/?id=764069ec10b2c142d6112b6c927f117e4dac7fb8
Submitter: Zuul
Branch: master

commit 764069ec10b2c142d6112b6c927f117e4dac7fb8
Author: Lee Yarwood <email address hidden>
Date: Wed Sep 9 14:51:41 2020 +0100

    compute: Wait until server is ACTIVE before deleting during resource_setup

    Partial-Bug: #1892837
    Change-Id: Ie2671f338dd111bb111d1c2956fbaa2eebb142ce

[Martin Kopec (mkopec)]

Fixed in Tempest by: https://review.opendev.org/750661

[Sylvain Bauza (sylvain-bauza)]

This does sound a race, indeed. Confirming it.

[Sylvain Bauza (sylvain-bauza)]

Marking to Medium priority as we do have a workaround with Tempest.

[Martin Kopec (mkopec)]

Fixed in tempest by https://review.opendev.org/c/openstack/tempest/+/750661/ and released - the change is part of 26.0.0 and 25.0.1 tags

[OpenStack Infra (hudson-openstack)]

Change abandoned by "Lee Yarwood <email address hidden>" on branch: master
Review: https://review.opendev.org/c/openstack/nova/+/748380