USSURI periodic ovb fs35 fails tempest "computeFault": {"code": 500, "message": "Unexpected API Error

[Marios Andreou]

At [1][2] the periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri fails during tempest tests with trace like

    (tempest.api.compute.servers.test_delete_server.DeleteServersTestJSON
     test_delete_server_while_in_building_state[id-9e6e0c87-3352-42f7-9faf-5d6210dbd159])

        Body: b'{"computeFault": {"code": 500, "message": "Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.\\n<class \'AttributeError\'>"}}'
}}}
        Traceback (most recent call last):
          File "/usr/lib/python3.6/site-packages/tempest/api/compute/servers/test_delete_server.py", line 43, in test_delete_server_while_in_building_state
            self.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 314, 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 687, in request
            self._error_checker(resp, resp_body)
          File "/usr/lib/python3.6/site-packages/tempest/lib/common/rest_client.py", line 864, 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 blocks the Ussuri integration promotion pipeline (current-tripleo) [3][4]. Digging a bit at the nova api log [5] you can see:

        2020-08-09 17:52:05.482 19 ERROR oslo.messaging._drivers.impl_rabbit [-] [cd0d7ebd-530f-44b7-a9b4-d46adc86ee2a] AMQP server on undercloud.ctlplane.localdomain:5672 is unreachable: <RecoverableConnectionError: unknown error>. Trying again in 1 seconds.: amqp.exceptions.RecoverableConnectionError: <RecoverableConnectionError: unknown error>
        2020-08-09 17:52:05.483 19 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 104] Connection reset by peer

[1] https://logserver.rdoproject.org/openstack-periodic-integration-stable1/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri/45d7fc9/logs/undercloud/var/log/tempest/stestr_results.html.gz
[2] https://logserver.rdoproject.org/openstack-periodic-integration-stable1/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri/0a45ef9/logs/undercloud/var/log/tempest/stestr_results.html.gz
[3] https://github.com/rdo-infra/ci-config/blob/6c71fee284d225f463b68fbe066856b0ddb522c6/ci-scripts/dlrnapi_promoter/config/CentOS-8/ussuri.ini#L45
[4] http://38.145.34.55/config/CentOS-8/ussuri.ini
[5] https://logserver.rdoproject.org/openstack-periodic-integration-stable1/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri/0a45ef9/logs/undercloud/var/log/containers/nova/nova-api.log.txt.gz

[chandan kumar (chkumar246)]

From API logs,

https://logserver.rdoproject.org/openstack-periodic-integration-stable1/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri/45d7fc9/logs/overcloud-controller-1/var/log/containers/nova/nova-api.log.txt.gz

2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi [req-1305def1-184b-4e3e-9397-a033898bdeb5 9a28aa13588843d7a85454243e67b2f7 0a253617f3f146f3bceaf87cbced627f - default default] Unexpected exception in API method: AttributeError: 'NoneType' object has no attribute 'uuid'
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi Traceback (most recent call last):
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/nova/objects/instance.py", line 655, in destroy
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi hard_delete=hard_delete)
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/nova/db/api.py", line 549, in instance_destroy
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi hard_delete=hard_delete)
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/nova/db/sqlalchemy/api.py", line 179, in wrapper
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi return f(*args, **kwargs)
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/oslo_db/api.py", line 154, in wrapper
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi ectxt.value = e.inner_exc
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi self.force_reraise()
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi six.reraise(self.type_, self.value, self.tb)
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/six.py", line 703, in reraise
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi raise value
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/oslo_db/api.py", line 142, in wrapper
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi return f(*args, **kwargs)
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/nova/db/sqlalchemy/api.py", line 222, in wrapped
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi return f(context, *args, **kwargs)
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi File "/usr/lib/python3.6/site-packages/nova/db/sqlalchemy/api.py", line 1166, in instance_destroy
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi raise exception.ConstraintNotMet()
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi nova.exception.ConstraintNotMet: Constraint not met.
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi
2020-08-09 23:54:13.408 11 ERROR nova.api.openstack.wsgi During ...

[Marios Andreou (marios-b)]

related skip there if we really decide to do that

        * [ussuri]test_delete_server_while_in_building_state in skip list
        * Change-Id: Ie4df164ea4895aba4bf4b8cba71770f1578a2962
        * https://review.opendev.org/#/c/745500/1

[Marios Andreou (marios-b)]

so since we saw the 2 fails in the description, we've had 3 green runs (yesterday) in the stable-1 pipeline with green tempest

        * https://logserver.rdoproject.org/openstack-periodic-integration-stable1/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri/7a52806/
        * https://logserver.rdoproject.org/openstack-periodic-integration-stable1/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri/37338b0/
        * https://logserver.rdoproject.org/openstack-periodic-integration-stable1/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri/fda7d87/
        * https://logserver.rdoproject.org/openstack-periodic-integration-stable1/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri/fda7d87/logs/undercloud/var/log/tempest/stestr_results.html.gz

Not sure yet... was it fixed by something else we don't know about? Is it some kind of race and we'll see it again?

[Marios Andreou (marios-b)]

and since comment #3 2 more green runs there

        * https://logserver.rdoproject.org/openstack-periodic-integration-stable1/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri/d41c918/logs/undercloud/var/log/tempest/stestr_results.html.gz
        * https://logserver.rdoproject.org/openstack-periodic-integration-stable1/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-ussuri/dfd9f70/logs/undercloud/var/log/tempest/stestr_results.html.gz

Whatever it was it is no longer happening. I'm going to close this out we can revisit if we see the issue again.