raise 500 in test_resize_server_negative_invalid_state

Bug #1741220 reported by Yikun Jiang
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Undecided
Yikun Jiang

Bug Description

Description
===========

We reproduce this bug in https://review.openstack.org/#/c/530429

In test_resize_server_negative_invalid_state
1. first, the confirm resize action are recorded:
https://github.com/openstack/nova/blob/2fc5d27332023a68e0a3977305a594f061f99cc8/nova/compute/api.py#L1950
2. and then a delete action are recorded.

the import thing is: the delete action and the resize action have SAME instance uuid and same requst id.

But when we get the action in here:
https://github.com/openstack/nova/blob/2fc5d27332023a68e0a3977305a594f061f99cc8/nova/db/sqlalchemy/api.py#L5755-L5756
it assume that we can get the only one action by different instance uuid and request_id.

We want to record the terminate_event on delete action, unfortunately, we get the wrong confirm-resize action first.

I think this problem has always existed, but after we add the index, the order of we get action is changed. so, this bug are exposed.

Steps to reproduce
==================
1. add index:
https://review.openstack.org/#/c/530429/
2. run test
nosetests -svx nova.tests.functional.test_servers:ServersTest.test_resize_server_negative_invalid_state

Logs & Configs
==============
Traceback (most recent call last):
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 163, in _process_incoming
    res = self.dispatcher.dispatch(message)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 220, in dispatch
    return self._do_dispatch(endpoint, method, ctxt, args)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 190, in _do_dispatch
    result = func(ctxt, **new_args)
  File "nova/exception_wrapper.py", line 76, in wrapped
    function_name, call_dict, binary)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
    self.force_reraise()
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
    six.reraise(self.type_, self.value, self.tb)
  File "nova/exception_wrapper.py", line 67, in wrapped
    return f(self, context, *args, **kw)
  File "nova/compute/manager.py", line 186, in decorated_function
    "Error: %s", e, instance=instance)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
    self.force_reraise()
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
    six.reraise(self.type_, self.value, self.tb)
  File "nova/compute/manager.py", line 156, in decorated_function
    return function(self, context, *args, **kwargs)
  File "nova/compute/utils.py", line 911, in decorated_function
    return function(self, context, *args, **kwargs)
  File "nova/compute/utils.py", line 889, in __exit__
    exc_tb=exc_tb, want_result=False)
  File "nova/objects/base.py", line 308, in wrapper
    return fn.__get__(None, obj)(*args, **kwargs)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 184, in wrapper
    result = fn(cls, context, *args, **kwargs)
  File "nova/objects/instance_action.py", line 185, in event_finish_with_failure
    db_event = db.action_event_finish(context, values)
  File "nova/db/api.py", line 1906, in action_event_finish
    return IMPL.action_event_finish(context, values)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_db/api.py", line 147, in wrapper
    ectxt.value = e.inner_exc
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
    self.force_reraise()
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
    six.reraise(self.type_, self.value, self.tb)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_db/api.py", line 135, in wrapper
    return f(*args, **kwargs)
  File "nova/db/sqlalchemy/api.py", line 253, in wrapped
    return f(context, *args, **kwargs)
  File "nova/db/sqlalchemy/api.py", line 5845, in action_event_finish
    event=values['event'])
InstanceActionEventNotFound: Event compute_terminate_instance not found for action id 3
2017-12-29 06:45:21,779 ERROR [nova.api.openstack.wsgi] Unexpected exception in API method
Traceback (most recent call last):
  File "nova/api/openstack/wsgi.py", line 803, in wrapped
    return f(*args, **kwargs)
  File "nova/api/openstack/compute/servers.py", line 831, in delete
    self._delete(req.environ['nova.context'], req, id)
  File "nova/api/openstack/compute/servers.py", line 685, in _delete
    self.compute_api.delete(context, instance)
  File "nova/compute/api.py", line 201, in inner
    return function(self, context, instance, *args, **kwargs)
  File "nova/compute/api.py", line 209, in _wrapped
    return fn(self, context, instance, *args, **kwargs)
  File "nova/compute/api.py", line 149, in inner
    return f(self, context, instance, *args, **kw)
  File "nova/compute/api.py", line 2111, in delete
    self._delete_instance(context, instance)
  File "nova/compute/api.py", line 2102, in _delete_instance
    task_state=task_states.DELETING)
  File "nova/compute/api.py", line 1897, in _delete
    cb(context, instance, bdms)
  File "nova/compute/api.py", line 2065, in _do_delete
    delete_type='delete')
  File "nova/compute/rpcapi.py", line 1041, in terminate_instance
    reservations=reservations)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 174, in call
    retry=self.retry)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_messaging/transport.py", line 131, in _send
    timeout=timeout, retry=retry)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_fake.py", line 219, in send
    return self._send(target, ctxt, message, wait_for_reply, timeout)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_fake.py", line 206, in _send
    raise failure
InstanceActionEventNotFound: Event compute_terminate_instance not found for action id 3
2017-12-29 06:45:21,780 INFO [nova.api.openstack.wsgi] HTTP exception thrown: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'nova.exception.InstanceActionEventNotFound'>
2017-12-29 06:45:21,782 INFO [nova.api.openstack.requestlog] 127.0.0.1 "DELETE /v2.1/6f70656e737461636b20342065766572/servers/f39a6060-4612-4855-8de1-8b9aa9d12df3" status: 500 len: 216 microversion: 2.1 time: 0.607800
2017-12-29 06:45:22,001 WARNING [nova.service] Service killed that has no database entry
}}}

Traceback (most recent call last):
  File "nova/tests/functional/test_servers.py", line 702, in test_resize_server_negative_invalid_state
    self._delete_server(created_server_id)
  File "nova/tests/functional/test_servers.py", line 102, in _delete_server
    self.api.delete_server(server_id)
  File "nova/tests/functional/api/client.py", line 286, in delete_server
    return self.api_delete('/servers/%s' % server_id)
  File "nova/tests/functional/api/client.py", line 239, in api_delete
    return APIResponse(self.api_request(relative_uri, **kwargs))
  File "nova/tests/functional/api/client.py", line 202, in api_request
    response=response)
nova.tests.functional.api.client.OpenStackApiException: Unexpected status code: {"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 'nova.exception.InstanceActionEventNotFound'>"}}

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

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

Changed in nova:
assignee: nobody → Yikun Jiang (yikunkero)
status: New → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/531117
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=b933847cbbf03ffb0ea6762ae60bca9ad92bc1e3
Submitter: Zuul
Branch: master

commit b933847cbbf03ffb0ea6762ae60bca9ad92bc1e3
Author: Yikun Jiang <email address hidden>
Date: Thu Jan 4 17:50:54 2018 +0800

    Fix 500 in test_resize_server_negative_invalid_state

    In some case(such as, delete a confirmResize server), the
    actions maybe have same instance_uuid and request_id. When
    we record the event we should get the last created action,
    otherwise, we would find the wrong action, and we can't find
    the specific event using this wrong action id. Finally, raise
    a 500 error due to the error of InstanceActionEventNotFound.

    So, if more than one actions with same instance uuid and request
    id are exists. we should choice the last created action id as
    event record action id.

    This change fixes this by sorting action by desc(created_at, id)
    and get back the last created action.

    Change-Id: Ie6efee14d4b4d25a73dc23f0649a56bfa724c492
    Closes-Bug: #1741220

Changed in nova:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/nova 17.0.0.0rc1

This issue was fixed in the openstack/nova 17.0.0.0rc1 release candidate.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.