Image goes to saving state when we delete instance just after taking snapshot and remain the state forever

Bug #1555065 reported by Prateek Arora on 2016-03-09
40
This bug affects 12 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Low
Prateek Arora
Newton
Low
Chuck Short

Bug Description

Steps to reproduce

1) nova image-create test test-img & nova delete test

where test is the name of the instance

I get the following message

[stack@localhost compute]$ nova image-create test test-img & nova delete test
[1] 2506
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'nova.exception.UnexpectedDeletingTaskStateError'> (HTTP 500) (Request-ID: req-f699c746-0b29-4d84-b258-c8233d5b7a42)
Request to delete server test has been accepted.
[1]+ Exit 1 nova image-create test test-img

In the nova api logs i can see the following stacktrace

'c59f52ce-b51f-433e-81b0-099e3b65b0a3', '89ba4861-99e2-4376-8015-3f5ac02538d0']^[[00m ^[[00;33mfrom (pid=12399) reserve /opt/stack/nova/nova/quota.py:1345^[[00m
2016-03-09 02:04:25.304 ^[[01;31mERROR nova.api.openstack.extensions [^[[01;36mreq-f699c746-0b29-4d84-b258-c8233d5b7a42 ^[[00;36madmin admin^[[01;31m] ^[[01;35m^[[01;31mUnexpected exception in API method^[[00m
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00mTraceback (most recent call last):
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/api/openstack/extensions.py", line 478, in wrapped
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return f(*args, **kwargs)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/api/openstack/common.py", line 391, in inner
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return f(*args, **kwargs)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/api/validation/__init__.py", line 73, in wrapper
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return func(*args, **kwargs)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/api/validation/__init__.py", line 73, in wrapper
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return func(*args, **kwargs)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/api/openstack/compute/servers.py", line 1113, in _action_create_image
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m extra_properties=metadata)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/compute/api.py", line 169, in wrapped
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return func(self, context, target, *args, **kwargs)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/compute/api.py", line 186, in _wrapped
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return fn(self, context, instance, *args, **kwargs)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/compute/api.py", line 139, in inner
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return f(self, context, instance, *args, **kw)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/compute/api.py", line 2238, in snapshot
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m instance.save(expected_task_state=[None])
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 223, in wrapper
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return fn(self, *args, **kwargs)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/objects/instance.py", line 694, in save
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m columns_to_join=_expected_cols(expected_attrs))
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/db/api.py", line 805, in instance_update_and_get_original
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m expected=expected)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 229, in wrapper
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return f(*args, **kwargs)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 148, in wrapper
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m ectxt.value = e.inner_exc
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m self.force_reraise()
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m six.reraise(self.type_, self.value, self.tb)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 138, in wrapper
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return f(*args, **kwargs)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 300, in wrapped
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m return f(context, *args, **kwargs)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 2707, in instance_update_and_get_original
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m context, instance_uuid, values, expected, original=instance_ref))
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 2843, in _instance_update
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m raise exc(**exc_props)
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00mUnexpectedDeletingTaskStateError: Conflict updating instance 74940cbc-3947-434c-93ce-9489faa78073. Expected: {'task_state': [None]}. Actual: {'task_state': u'deleting'}
^[[01;31m2016-03-09 02:04:25.304 TRACE nova.api.openstack.extensions ^[[01;35m^[[00m
2016-03-09 02:04:25.311 ^[[00;36mINFO nova.api.openstack.wsgi [^[[01;36mreq-f699c746-0b29-4d84-b258-c8233d5b7a42 ^[[00;36madmin admin^[[00;36m] ^[[01;35m^[[00;36mHTTP 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.UnexpectedDeletingTaskStateError'>^[[00m

Prateek Arora (parora) on 2016-03-09
Changed in nova:
assignee: nobody → Prateek Arora (parora)
Prateek Arora (parora) on 2016-03-09
Changed in nova:
assignee: Prateek Arora (parora) → nobody
assignee: nobody → Prateek Arora (parora)

Adding "api" tag because of HTTP status code 500.
Adding "compute" as I think this is the layer which should handle
the "UnexpectedDeletingTaskStateError" raised from the db layer.

tags: added: api compute
Changed in nova:
status: New → Confirmed
Prateek Arora (parora) on 2016-03-11
Changed in nova:
status: Confirmed → In Progress

Change abandoned by Matt Riedemann (<email address hidden>) on branch: master
Review: https://review.openstack.org/294513

Changed in nova:
assignee: Prateek Arora (parora) → Matt Riedemann (mriedem)

Reviewed: https://review.openstack.org/294513
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=d8e695cb900ad71996e6cf970894bc2e3f2df8b4
Submitter: Jenkins
Branch: master

commit d8e695cb900ad71996e6cf970894bc2e3f2df8b4
Author: Prateek Arora <email address hidden>
Date: Fri Mar 18 06:46:43 2016 -0400

    Delete traces of in-progress snapshot on VM being deleted

    When user tries to create snapshot of instance and at the same time
    if another request tries to delete the instance, at that time image
    goes in saving status for forever because of race between instance
    delete and snapshot requests.

    Caught exceptions(InstanceNotFound and UnexpectedDeletingTaskStateError)
    in except block and deleting the image which got stuck in saving state.

    Closes-Bug: #1555065
    Change-Id: If0b918dc951030e6b6ffba147443225e0e4a370a

Changed in nova:
status: In Progress → Fix Released
Matt Riedemann (mriedem) on 2016-10-10
Changed in nova:
assignee: Matt Riedemann (mriedem) → Prateek Arora (parora)
importance: Undecided → Medium
importance: Medium → Low

Change abandoned by Chuck Short (<email address hidden>) on branch: stable/newton
Review: https://review.openstack.org/384353

This issue was fixed in the openstack/nova 15.0.0.0b1 development milestone.

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

Other bug subscribers