yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1850694] [NEW] shelve doesn't handle UnexpectedTaskStateError

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Artom Lifshitz <notartom@xxxxxxxxx>
Date: Wed, 30 Oct 2019 18:21:25 -0000
Reply-to: Bug 1850694 <1850694@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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

Shelving a server expects its task state to be None. If it's not None
(for example, if attempting to shelve a server that's already being
shelved), we get a UnexpectedTaskStateError from the database layer and
return a 500 to the user. A 409 would be more appropriate.

Steps to reproduce
==================

1. Send multiple shelve requests in quick succession.

Expected result
===============

The initial request should be accepted, the rest should return 409.

Actual result
=============

Error 500 for all requests except the first.

Environment
===========

This was reported on OSP13 (Queens) originally [1].

Logs & Configs
==============

2019-05-28 03:18:48.530 26 INFO nova.osapi_compute.wsgi.server [req-1437e513-3e32-4243-8f5d-1a7e17c111df 3ff59a48497842e7a716a03a17e5bf8b 493b17f3b02b4f9ea6e71b1ae4c5ac5d - e4c6faf4dfb04f2da40c0595f1a424c7 e4c6faf4dfb04f2da40c0595f1a424c7] 10.101.4.137,10.101.4.1 "POST /v2.1/493b17f3b02b4f9ea6e71b1ae4c5ac5d/servers/f905b880-9caa-465e-93c5-fffe9192c825/action HTTP/1.1" status: 500 len: 622 time: 0.1237578
2019-05-28 03:18:48.529 26 INFO nova.api.openstack.wsgi [req-1437e513-3e32-4243-8f5d-1a7e17c111df 3ff59a48497842e7a716a03a17e5bf8b 493b17f3b02b4f9ea6e71b1ae4c5ac5d - e4c6faf4dfb04f2da40c0595f1a424c7 e4c6faf4dfb04f2da40c0595f1a424c7] 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.UnexpectedTaskStateError'>
2019-05-28 03:18:48.529 26 DEBUG nova.api.openstack.wsgi [req-1437e513-3e32-4243-8f5d-1a7e17c111df 3ff59a48497842e7a716a03a17e5bf8b 493b17f3b02b4f9ea6e71b1ae4c5ac5d - e4c6faf4dfb04f2da40c0595f1a424c7 e4c6faf4dfb04f2da40c0595f1a424c7] Returning 500 to user: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'nova.exception.UnexpectedTaskStateError'> __call__ /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:1064
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi [req-1437e513-3e32-4243-8f5d-1a7e17c111df 3ff59a48497842e7a716a03a17e5bf8b 493b17f3b02b4f9ea6e71b1ae4c5ac5d - e4c6faf4dfb04f2da40c0595f1a424c7 e4c6faf4dfb04f2da40c0595f1a424c7] Unexpected exception in API method: UnexpectedTaskStateError: Conflict updating instance f905b880-9caa-465e-93c5-fffe9192c825. Expected: {'task_state': [None]}. Actual: {'task_state': u'shelving'}
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi Traceback (most recent call last):
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 788, in wrapped
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return f(*args, **kwargs)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/shelve.py", line 43, in _shelve
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     self.compute_api.shelve(context, instance)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 204, in inner
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return function(self, context, instance, *args, **kwargs)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 152, in inner
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return f(self, context, instance, *args, **kw)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 3518, in shelve
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     instance.save(expected_task_state=[None])
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 226, in wrapper
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return fn(self, *args, **kwargs)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/objects/instance.py", line 826, in save
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     columns_to_join=_expected_cols(expected_attrs))
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 890, in instance_update_and_get_original
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     expected=expected)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 169, in wrapper
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return f(*args, **kwargs)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 147, in wrapper
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     ectxt.value = e.inner_exc
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     self.force_reraise()
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     six.reraise(self.type_, self.value, self.tb)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 135, in wrapper
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return f(*args, **kwargs)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 240, in wrapped
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return f(context, *args, **kwargs)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2737, in instance_update_and_get_original
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     context, instance_uuid, values, expected, original=instance_ref))
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2878, in _instance_update
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     raise exc(**exc_props)
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi UnexpectedTaskStateError: Conflict updating instance f905b880-9caa-465e-93c5-fffe9192c825. Expected: {'task_state': [None]}. Actual: {'task_state': u'shelving'}
2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi

Additional Info
===============

This is obviously minor, as the difference between a 500 and a 409 is
purely semantic, but we're being told this is an SLA thing. An SLA
defines 5xx as being "down", while 4xx is user error and therefore "up".

[1] https://bugzilla.redhat.com/show_bug.cgi?id=1718171

** Affects: nova
     Importance: Undecided
     Assignee: Artom Lifshitz (notartom)
         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/1850694

Title:
  shelve doesn't handle UnexpectedTaskStateError

Status in OpenStack Compute (nova):
  In Progress

Bug description:
  Description
  ===========

  Shelving a server expects its task state to be None. If it's not None
  (for example, if attempting to shelve a server that's already being
  shelved), we get a UnexpectedTaskStateError from the database layer
  and return a 500 to the user. A 409 would be more appropriate.

  Steps to reproduce
  ==================

  1. Send multiple shelve requests in quick succession.

  Expected result
  ===============

  The initial request should be accepted, the rest should return 409.

  Actual result
  =============

  Error 500 for all requests except the first.

  Environment
  ===========

  This was reported on OSP13 (Queens) originally [1].

  Logs & Configs
  ==============

  2019-05-28 03:18:48.530 26 INFO nova.osapi_compute.wsgi.server [req-1437e513-3e32-4243-8f5d-1a7e17c111df 3ff59a48497842e7a716a03a17e5bf8b 493b17f3b02b4f9ea6e71b1ae4c5ac5d - e4c6faf4dfb04f2da40c0595f1a424c7 e4c6faf4dfb04f2da40c0595f1a424c7] 10.101.4.137,10.101.4.1 "POST /v2.1/493b17f3b02b4f9ea6e71b1ae4c5ac5d/servers/f905b880-9caa-465e-93c5-fffe9192c825/action HTTP/1.1" status: 500 len: 622 time: 0.1237578
  2019-05-28 03:18:48.529 26 INFO nova.api.openstack.wsgi [req-1437e513-3e32-4243-8f5d-1a7e17c111df 3ff59a48497842e7a716a03a17e5bf8b 493b17f3b02b4f9ea6e71b1ae4c5ac5d - e4c6faf4dfb04f2da40c0595f1a424c7 e4c6faf4dfb04f2da40c0595f1a424c7] 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.UnexpectedTaskStateError'>
  2019-05-28 03:18:48.529 26 DEBUG nova.api.openstack.wsgi [req-1437e513-3e32-4243-8f5d-1a7e17c111df 3ff59a48497842e7a716a03a17e5bf8b 493b17f3b02b4f9ea6e71b1ae4c5ac5d - e4c6faf4dfb04f2da40c0595f1a424c7 e4c6faf4dfb04f2da40c0595f1a424c7] Returning 500 to user: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
  <class 'nova.exception.UnexpectedTaskStateError'> __call__ /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:1064
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi [req-1437e513-3e32-4243-8f5d-1a7e17c111df 3ff59a48497842e7a716a03a17e5bf8b 493b17f3b02b4f9ea6e71b1ae4c5ac5d - e4c6faf4dfb04f2da40c0595f1a424c7 e4c6faf4dfb04f2da40c0595f1a424c7] Unexpected exception in API method: UnexpectedTaskStateError: Conflict updating instance f905b880-9caa-465e-93c5-fffe9192c825. Expected: {'task_state': [None]}. Actual: {'task_state': u'shelving'}
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi Traceback (most recent call last):
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 788, in wrapped
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return f(*args, **kwargs)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/shelve.py", line 43, in _shelve
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     self.compute_api.shelve(context, instance)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 204, in inner
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return function(self, context, instance, *args, **kwargs)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 152, in inner
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return f(self, context, instance, *args, **kw)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 3518, in shelve
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     instance.save(expected_task_state=[None])
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 226, in wrapper
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return fn(self, *args, **kwargs)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/objects/instance.py", line 826, in save
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     columns_to_join=_expected_cols(expected_attrs))
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 890, in instance_update_and_get_original
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     expected=expected)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 169, in wrapper
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return f(*args, **kwargs)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 147, in wrapper
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     ectxt.value = e.inner_exc
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     self.force_reraise()
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     six.reraise(self.type_, self.value, self.tb)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 135, in wrapper
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return f(*args, **kwargs)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 240, in wrapped
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     return f(context, *args, **kwargs)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2737, in instance_update_and_get_original
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     context, instance_uuid, values, expected, original=instance_ref))
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2878, in _instance_update
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi     raise exc(**exc_props)
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi UnexpectedTaskStateError: Conflict updating instance f905b880-9caa-465e-93c5-fffe9192c825. Expected: {'task_state': [None]}. Actual: {'task_state': u'shelving'}
  2019-05-28 03:18:48.523 26 ERROR nova.api.openstack.wsgi

  Additional Info
  ===============

  This is obviously minor, as the difference between a 500 and a 409 is
  purely semantic, but we're being told this is an SLA thing. An SLA
  defines 5xx as being "down", while 4xx is user error and therefore
  "up".

  [1] https://bugzilla.redhat.com/show_bug.cgi?id=1718171

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

[Bug 1850694] Fix included in openstack/nova queens-eol
From: OpenStack Infra, 2022-11-11
[Bug 1850694] Re: shelve doesn't handle UnexpectedTaskStateError
From: Matt Riedemann, 2019-11-02
[Bug 1850694] Re: shelve doesn't handle UnexpectedTaskStateError
From: OpenStack Infra, 2019-11-01