yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1741220] [NEW] raise 500 in test_resize_server_negative_invalid_state

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Yikun Jiang <yikunkero@xxxxxxxxx>
Date: Thu, 04 Jan 2018 09:46:49 -0000
Reply-to: Bug 1741220 <1741220@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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'>"}}

** Affects: nova
     Importance: Undecided
     Assignee: Yikun Jiang (yikunkero)
         Status: In Progress

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1741220

Title:
  raise 500 in test_resize_server_negative_invalid_state

Status in OpenStack Compute (nova):
  In Progress

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'>"}}

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1741220/+subscriptions
Follow ups

[Bug 1741220] Re: raise 500 in test_resize_server_negative_invalid_state
From: OpenStack Infra, 2018-02-08