Image stays in Saving State if any error occurs while snapshotting an instance

This can be reproduced as follows:
1. Boot a VM
2. Wait till active
3. Snapshot the VM
4. Before snapshot comes to active, delete the vm

2012-10-09 16:41:50 ERROR nova.openstack.common.rpc.amqp [-] Exception during message handling
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/openstack/common/rpc/amqp.py", line 275, in _process_data
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 117, in wrapped
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 92, in wrapped
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 210, in decorated_function
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp instance_uuid, e, sys.exc_info())
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 199, in decorated_function
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1140, in snapshot_instance
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp self.driver.snapshot(context, instance, image_id)
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 117, in wrapped
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 92, in wrapped
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-10-09 16:41:50 TRACE nova.openstack.common.rpc.amqp Fi...

Hi Arathi,

Couple of things here.:

In the case you describe above... did the instance being snapshotted go into an ERROR state? If so I think Nova is doing the correctly thing here.

I do agree that we could do better about reporting this type of errors back to the user. Ideally we'd keep track of more fine grained error messages so that the user might better understand what the initial cause of the error was. There are a couple Nova features dealing with this that might get implemented in the future. In the scope of this ticket however I think Nova is mostly doing things correctly.

---

From a Glance prospective there is actually an image scrubber feature that already exists and is meant to help cleanup images in an itermittent state. If we need to do anything to cleanup images stuck in a 'SAVING' state I think perhaps the right place for that code to go is there. Have a look at the Glance API's scrub_time, delayed_delete, and the associated glance-scrubber bin file.

Hi Dan,

Currently, nova is not making snapshot into 'ERROR' state if any error occurs, snapshot stays in 'SAVING' state.

In your comment above, you mentioned that there are a couple of Nova features dealing with this implementation in the future. Could you please brief me on that or point me to the documentation of those features, so that i can decide whether a fix should be proposed for this ticket.

Thanks

Yes failed snapshots should be moved into error and the intermediate snap deleted if this is not occurring.

Since this is Medium priority and unassigned, I'm moving it off of the grizzly-rc1 blocker list and into the "nice to have for grizzly" list (tagged with grizzly-rc-potential).

I found the status of image should be one of 'active', 'saving', 'queued', 'killed', 'pending_delete', 'deleted' in glance. And if some exceptions in transferring data when uploading image, the image will be in status 'killed'.

So IMHO, if snapshoting failed, the image be 'killed' will be OK.

BTW, in general glance will not show killed images. If we decide to make broken image to 'killed', we should firstly show killed images in glance.

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

This is very close to bug 991941 and bug 1143659... could you make sure your fix addresses those cases as well ? Also check proposed fix at https://review.openstack.org/24820 is compatible with yours...

bug 9911941 is caused by stop nova-compute when do snapshotting.

this bug(1064386) and bug 1143659 are similar. Both of them is some errors occur when do libvirt.snapshot(). But the former is the instance disappear when do snapshotting, the latter is more general exception happened when do snapshotting. IMHO, the former is special case of the latter.

The two (1064386, 1143659) will conflict, so we should merge one, the manual rebase the other on it.

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

Moving back to Triaged since it was Triaged before.

It seem this happens on RHOS as well. It breaks the Tempest test_list_image_filters time to time. I think I have reproduced the problem by having a VM foo and then doing two snapshots simultaneously:

nova image-create foo foo-img --show& nova image-create foo foo-img2 --show

check the reproducer attachement for more info

The issue seems to be fixed

nova image-create test test-img & nova delete test
[1] 16828
ERROR (Conflict): Cannot 'createImage' instance 772e51a5-be40-4cf1-ad74-06850b2154a6 while it is in task_state deleting (HTTP 409) (Request-ID: req-7d95863d-cb52-4f45-9e2d-889d94e570f4)
Request to delete server test has been accepted.
[1]+ Exit 1 nova image-create test test-img

This bug shuld be closed as such.

While on the same setup, i see this

[stack@localhost devstack]$ nova image-create test test-img & nova delete test

Request to delete server test has been accepted.
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-6d9fb33b-26af-429f-91d6-7e222ff88cf8)

Can you please confirm whether you still see the issue ?

While the bug is reproducible the stack trace is different from what the original bug mentions

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...

The following bug tries fixing the above problem in nova api while the case is already handled in manager

https://review.openstack.org/#/c/294513/

Hi Prateek, I saw that no activity has taken place on your submitted change. It looks like you submitted it pretty close to the Summit so the team may have been busy and it got overlooked. If you would like reviews on your fix, please bring it to the attention of the team in the #openstack-nova irc channel. I will bring it to the attention to the bugs team during our meeting next week as well.

Thanks Augustina, I would do that in the channel as well, and maybe you can get in some reviews as well and perhaps review yourself too.