RBD _delete_backup_snap has unhandled exception

[Liyingjun]

Here is my setup:
rbd backend, Havana.
instance booted from volume, and some snapshots on the instance.

I don't figure out which operation caused this error, but i do think it's bug that cinder do not handle the rbd exception.

2014-05-21 10:16:04.524 22565 ERROR cinder.service [req-cfb8d50d-e0ea-4240-9645-16487dddb455 None None] Unhandled exception
2014-05-21 10:16:04.524 22565 TRACE cinder.service Traceback (most recent call last):
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/cinder/service.py", line 228, in _start_child
2014-05-21 10:16:04.524 22565 TRACE cinder.service self._child_process(wrap.server)
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/cinder/service.py", line 205, in _child_process
2014-05-21 10:16:04.524 22565 TRACE cinder.service launcher.run_server(server)
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/cinder/service.py", line 96, in run_server
2014-05-21 10:16:04.524 22565 TRACE cinder.service server.start()
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/cinder/service.py", line 385, in start
2014-05-21 10:16:04.524 22565 TRACE cinder.service self.manager.init_host()
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 230, in init_host
2014-05-21 10:16:04.524 22565 TRACE cinder.service self.delete_volume(ctxt, volume['id'])
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/cinder/utils.py", line 808, in wrapper
2014-05-21 10:16:04.524 22565 TRACE cinder.service return func(self, *args, **kwargs)
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 302, in delete_volume
2014-05-21 10:16:04.524 22565 TRACE cinder.service {'status': 'error_deleting'})
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2014-05-21 10:16:04.524 22565 TRACE cinder.service self.gen.next()
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 290, in delete_volume
2014-05-21 10:16:04.524 22565 TRACE cinder.service self.driver.delete_volume(volume_ref)
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 591, in delete_volume
2014-05-21 10:16:04.524 22565 TRACE cinder.service self._delete_backup_snaps(client, volume_name)
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 520, in _delete_backup_snaps
2014-05-21 10:16:04.524 22565 TRACE cinder.service rbd_image = self.rbd.Image(client.ioctx, volume_name)
2014-05-21 10:16:04.524 22565 TRACE cinder.service File "/usr/lib/python2.7/dist-packages/rbd.py", line 351, in __init__
2014-05-21 10:16:04.524 22565 TRACE cinder.service raise make_ex(ret, 'error opening image %s at snapshot %s' % (name, snapshot))
2014-05-21 10:16:04.524 22565 TRACE cinder.service ImageNotFound: error opening image volume-4b743fab-60be-4345-b9ca-1fe3c6fed84c at snapshot None
2014-05-21 10:16:04.524 22565 TRACE cinder.service
2014-05-21 10:16:04.545 22558 INFO cinder.service [-] Child 22565 exited with status 2
2014-05-21 10:16:04.545 22558 INFO cinder.service [-] _wait_child 1
2014-05-21 10:16:04.545 22558 INFO cinder.service [-] wait wrap.failed True

[Huang Zhiteng (zhiteng-huang)]

The error looks like related to bug 1322340. But the root cause is different.

[Mike Perez (thingee)]

Winston, it's unrelated..just another place to catch image lookup in rbd.

Liyingiun, which version are you running?

[Mike Perez (thingee)]

Nevermind, reported havana for this issue, my bad.

[Edward Hope-Morley (hopem)]

Huang, looks like this is in part a result of a silly unnecessary and unprotected call to rbd.Image which would fail if e.g. a racey delete had occurred. I'll post a patch to at least remove the duplicate call and add a unit test for _delete_backup_snaps since we do not currently have one.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/100111
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=86643780bc2cf1f7a467a7c65aab64e3110d031e
Submitter: Jenkins
Branch: master

commit 86643780bc2cf1f7a467a7c65aab64e3110d031e
Author: Edward Hope-Morley <email address hidden>
Date: Sun Jun 15 21:30:19 2014 +0100

    Removes unecessary call to rbd.Image

    Removed duplicate and unprotected call to rbd.Image
    in rbd driver which can result in an uncaught exception
    if the rbd image no longer exists.

    Also added unit test for _delete_backup_snaps()

    Closes-Bug: 1323203
    Change-Id: I89eedb0d0276a985b4d496093df2eee2ce067ec1

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/icehouse
Review: https://review.openstack.org/136798

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/136798
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=1d48d01d9db7746972ed7e5f13fb72289dba895b
Submitter: Jenkins
Branch: stable/icehouse

commit 1d48d01d9db7746972ed7e5f13fb72289dba895b
Author: Edward Hope-Morley <email address hidden>
Date: Sun Jun 15 21:30:19 2014 +0100

    Removes unecessary call to rbd.Image

    Removed duplicate and unprotected call to rbd.Image
    in rbd driver which can result in an uncaught exception
    if the rbd image no longer exists.

    Also added unit test for _delete_backup_snaps()

    Closes-Bug: 1323203
    Change-Id: I89eedb0d0276a985b4d496093df2eee2ce067ec1
    (cherry picked from commit 86643780bc2cf1f7a467a7c65aab64e3110d031e)