[SRU] cinder-volume fails on start when rbd pool contains partially deleted images

[Mykola Golub]

[Impact]

 * Cinder-volume service gets marked as down when rbd pool contains partially deleted images

[Test Case]

1) Use this bundle (pastebin: http://paste.ubuntu.com/p/XxJPcs7YX9/)
2) Force a volume deletion

root@juju-30736a-1698786-cinder-0:/home/ubuntu# rbd -p cinder-ceph info volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
rbd image 'volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04':
 size 10240 MB in 2560 objects
 order 22 (4096 kB objects)
 block_name_prefix: rbd_data.10f96b8b4567
 format: 2
 features: layering, exclusive-lock, object-map, fast-diff, deep-flatten
 flags:
root@juju-30736a-1698786-cinder-0:/home/ubuntu# rados -p cinder-ceph rm rbd_id.volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
root@juju-30736a-1698786-cinder-0:/home/ubuntu# rbd -p cinder-ceph info volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
rbd: error opening image volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04: (2) No such file or directory

3) Wait for a few seconds. The following exception gets raised and the cinder-volume
service gets reported as down.

2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd [req-21a9da64-4d10-4c75-b5fd-4bb3328d6057 - - - - -] error opening rbd image volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd Traceback (most recent call last):
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 131, in __init__
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd read_only=read_only)
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd File "rbd.pyx", line 1061, in rbd.Image.__init__ (/build/ceph-eXkpH5/ceph-10.2.11/src/build/rbd.c:9939)
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd ImageNotFound: error opening image volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04 at snapshot None
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd

[Regression Potential]

 * Minor backport, added a new exception to the try block.

[Other Info]

If `rbd_remove` image operation fails by some reason [*] the image being deleted may be left in a state, when its data and part of metadata (rbd_header object) is deleted, but it still has an entry in rbd_directory object. As a result the image is seen in `rbd_list` output but `open` fails.

To calculate rbd pool capacity the cinder-volume scans the pool images using `rbd_list` and then tries to get images size by opening every image. If there is such a partially removed image this causes cinder-volume failure like below:

2017-06-15 17:47:58.045 26352 ERROR cinder.volume.drivers.rbd [req-caa6f7fa-23c2-4972-b48a-264bcec6dbb1 - - - - -] error opening rbd image volume-099313f9-2f6f-4e86-9b46-8da16b138090
2017-06-15 17:47:58.045 26352 ERROR cinder.volume.drivers.rbd Traceback (most recent call last):
2017-06-15 17:47:58.045 26352 ERROR cinder.volume.drivers.rbd File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 119, in __init__
2017-06-15 17:47:58.045 26352 ERROR cinder.volume.drivers.rbd read_only=read_only)
2017-06-15 17:47:58.045 26352 ERROR cinder.volume.drivers.rbd File "rbd.pyx", line 1061, in rbd.Image.__init__ (/build/ceph-25Z60r/ceph-10.2.7/src/build/rbd.c:9939)
2017-06-15 17:47:58.045 26352 ERROR cinder.volume.drivers.rbd ImageNotFound: error opening image volume-099313f9-2f6f-4e86-9b46-8da16b138090 at snapshot None
2017-06-15 17:47:58.045 26352 ERROR cinder.volume.drivers.rbd
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service [req-caa6f7fa-23c2-4972-b48a-264bcec6dbb1 - - - - -] Error starting thread.
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service Traceback (most recent call last):
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/oslo_service/service.py", line 722, in run_service
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service service.start()
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/cinder/service.py", line 241, in start
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service service_id=Service.service_id)
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 442, in init_host
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service self.driver.init_capabilities()
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/cinder/volume/driver.py", line 719, in init_capabilities
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service stats = self.get_volume_stats(True)
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 432, in get_volume_stats
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service self._update_volume_stats()
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 418, in _update_volume_stats
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service self._get_usage_info()
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 365, in _get_usage_info
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service with RBDVolumeProxy(self, t, read_only=True) as v:
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 119, in __init__
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service read_only=read_only)
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service File "rbd.pyx", line 1061, in rbd.Image.__init__ (/build/ceph-25Z60r/ceph-10.2.7/src/build/rbd.c:9939)
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service ImageNotFound: error opening image volume-099313f9-2f6f-4e86-9b46-8da16b138090 at snapshot None
2017-06-15 17:47:58.050 26352 ERROR oslo_service.service

[*] Situations when `rbd_remove` fails leaving partially removed image linked in rbd_directory is not avoidable in general case. The operation involves scanning and removing many objects and can't be atomic. It may be interrupted by many different reasons: user intervention, client crash, network or Ceph cluster error. For this reason removal from rbd_directory is done as the last operation so users could still see such images and could complete the removal by rerunning `rbd remove`.

Note, if `rbd_remove` fails for some reason it should return an error, so this can be detected.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[Ivan Kolodyazhny (e0ne)]

From conversation with Mykola Golub:

"To test the fix you can make a broken (partially deleted) image easily though, using this procedure:
choose an image from `rbd -p volumes ls` or create a new one. Let's say its name is $VOLUME;
Delete the object rbd_id.$VOLUME from volumes pool using the command: `rados -p volumes rm rbd_id.$VOLUME`;
Check it is broken running: `rbd -p volumes info $VOLUME`."

[Jon Bernard (jbernard)]

I just pushed a rebase to master so jenkins would be happy, I didn't mean to take it over - feel free to reassign.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Ivan Kolodyazhny (<email address hidden>) on branch: master
Review: https://review.openstack.org/476079
Reason: https://review.openstack.org/#/c/475400/ is merged

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/475400
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=3e7b9ba546c8cac7bac2ed3d9d985cad0d166313
Submitter: Jenkins
Branch: master

commit 3e7b9ba546c8cac7bac2ed3d9d985cad0d166313
Author: Ivan Kolodyazhny <email address hidden>
Date: Mon Jun 19 17:17:04 2017 +0300

    Do not fail if RBD image is broken

    Change-Id: I78e552998e822fff37fb2c7cf890ebab65d9291f
    Closes-Bug: #1698786

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/508873

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/508873
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=225618bf0ca38d70f45c1aa97acd491cce43e8a1
Submitter: Jenkins
Branch: stable/pike

commit 225618bf0ca38d70f45c1aa97acd491cce43e8a1
Author: Ivan Kolodyazhny <email address hidden>
Date: Mon Jun 19 17:17:04 2017 +0300

    Do not fail if RBD image is broken

    Change-Id: I78e552998e822fff37fb2c7cf890ebab65d9291f
    Closes-Bug: #1698786
    (cherry picked from commit 3e7b9ba546c8cac7bac2ed3d9d985cad0d166313)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 12.0.0.0b1 development milestone.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 11.0.1 release.

[melanie witt (melwitt)]

I think this bug got re-introduced by this change that moved the try-except block for the ImageNotFound from ceph:

  https://review.openstack.org/#/c/486734/4/cinder/volume/drivers/rbd.py@381

[Kevin Tibi (ktibi)]

Yes I have again this bug in last pike version.

error opening rbd image volume-7616f030-e608-411a-be61-743ce634b91a: ImageNotFound: error opening image volume-7616f030-e608-411a-be61-743ce634b91a at snapshot None
2018-07-12 10:41:34.794 33 ERROR cinder.volume.drivers.rbd Traceback (most recent call last):
2018-07-12 10:41:34.794 33 ERROR cinder.volume.drivers.rbd File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/rbd.py", line 127, in __init__
2018-07-12 10:41:34.794 33 ERROR cinder.volume.drivers.rbd read_only=read_only)
2018-07-12 10:41:34.794 33 ERROR cinder.volume.drivers.rbd File "rbd.pyx", line 1061, in rbd.Image.__init__ (rbd.c:8652)
2018-07-12 10:41:34.794 33 ERROR cinder.volume.drivers.rbd ImageNotFound: error opening image volume-7616f030-e608-411a-be61-743ce634b91a at snapshot None
2018-07-12 10:41:34.794 33 ERROR cinder.volume.drivers.rbd

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/612741
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=9e8c45892205e54313cd414a3102aea5b5b199f4
Submitter: Zuul
Branch: master

commit 9e8c45892205e54313cd414a3102aea5b5b199f4
Author: Dmitriy Rabotjagov <email address hidden>
Date: Tue Oct 23 19:16:59 2018 +0300

    Handle rbd.OSError on broken RBD image

    With Rocky, cinder-volume began to fail again with another error type.
    This patch adds rbd.OSError type for exception block of
    _get_usage_info method.

    Change-Id: I93b8afeddae18d098fe926a3219811cc8c8d9b63
    Closes-Bug: 1698786

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/614171

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/614171
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=71c99a85a0cc9ad4217428b316a13d3aa19ce1eb
Submitter: Zuul
Branch: stable/rocky

commit 71c99a85a0cc9ad4217428b316a13d3aa19ce1eb
Author: Dmitriy Rabotjagov <email address hidden>
Date: Tue Oct 23 19:16:59 2018 +0300

    Handle rbd.OSError on broken RBD image

    With Rocky, cinder-volume began to fail again with another error type.
    This patch adds rbd.OSError type for exception block of
    _get_usage_info method.

    Change-Id: I93b8afeddae18d098fe926a3219811cc8c8d9b63
    Closes-Bug: 1698786
    (cherry picked from commit 9e8c45892205e54313cd414a3102aea5b5b199f4)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 13.0.2 release.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/queens
Review: https://review.openstack.org/625960

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/625965

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/625960
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=3e174a0c4b574b3f53b5683852756b95c9a112fc
Submitter: Zuul
Branch: stable/queens

commit 3e174a0c4b574b3f53b5683852756b95c9a112fc
Author: Dmitriy Rabotjagov <email address hidden>
Date: Tue Oct 23 19:16:59 2018 +0300

    Handle rbd.OSError on broken RBD image

    With Rocky, cinder-volume began to fail again with another error type.
    This patch adds rbd.OSError type for exception block of
    _get_usage_info method.

    Change-Id: I93b8afeddae18d098fe926a3219811cc8c8d9b63
    Closes-Bug: 1698786
    (cherry picked from commit 9e8c45892205e54313cd414a3102aea5b5b199f4)
    (cherry picked from commit 71c99a85a0cc9ad4217428b316a13d3aa19ce1eb)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/625965
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=5e4d7e5e986f7a7076632f1cef2c8195fdcc0824
Submitter: Zuul
Branch: stable/pike

commit 5e4d7e5e986f7a7076632f1cef2c8195fdcc0824
Author: Dmitriy Rabotjagov <email address hidden>
Date: Tue Oct 23 19:16:59 2018 +0300

    Handle rbd.OSError on broken RBD image

    With Rocky, cinder-volume began to fail again with another error type.
    This patch adds rbd.OSError type for exception block of
    _get_usage_info method.

    Change-Id: I93b8afeddae18d098fe926a3219811cc8c8d9b63
    Closes-Bug: 1698786
    (cherry picked from commit 9e8c45892205e54313cd414a3102aea5b5b199f4)
    (cherry picked from commit 71c99a85a0cc9ad4217428b316a13d3aa19ce1eb)
    (cherry picked from commit 3e174a0c4b574b3f53b5683852756b95c9a112fc)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 12.0.5 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 11.2.0 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 14.0.0.0rc1 release candidate.

[Jorge Niedbalski (niedbalski)]

Hello,

I am able to reproduce this problem on a xenial-ocata cloud.

1) Use this bundle (pastebin: http://paste.ubuntu.com/p/XxJPcs7YX9/)
2) Force a volume deletion

root@juju-30736a-1698786-cinder-0:/home/ubuntu# rbd -p cinder-ceph info volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
rbd image 'volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04':
 size 10240 MB in 2560 objects
 order 22 (4096 kB objects)
 block_name_prefix: rbd_data.10f96b8b4567
 format: 2
 features: layering, exclusive-lock, object-map, fast-diff, deep-flatten
 flags:
root@juju-30736a-1698786-cinder-0:/home/ubuntu# rados -p cinder-ceph rm rbd_id.volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
root@juju-30736a-1698786-cinder-0:/home/ubuntu# rbd -p cinder-ceph info volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
rbd: error opening image volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04: (2) No such file or directory

3) Wait for a few seconds. The following exception gets raised and the cinder-volume
service gets reported as down.

2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd [req-21a9da64-4d10-4c75-b5fd-4bb3328d6057 - - - - -] error opening rbd image volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd Traceback (most recent call last):
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/rbd.py", line 131, in __init__
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd read_only=read_only)
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd File "rbd.pyx", line 1061, in rbd.Image.__init__ (/build/ceph-eXkpH5/ceph-10.2.11/src/build/rbd.c:9939)
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd ImageNotFound: error opening image volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04 at snapshot None
2020-02-10 20:42:47.491 14050 ERROR cinder.volume.drivers.rbd

[Corey Bryant (corey.bryant)]

Thanks Jorge. Triaged for Ubuntu on stable/ocata. This is fixed on stable/pike but not stable/ocata.

[Corey Bryant (corey.bryant)]

Hello Mykola, or anyone else affected,

Accepted cinder into ocata-proposed. The package will build now and be available in the Ubuntu Cloud Archive in a few hours, and then in the -proposed repository.

Please help us by testing this new package. To enable the -proposed repository:

  sudo add-apt-repository cloud-archive:ocata-proposed
  sudo apt-get update

Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-ocata-needed to verification-ocata-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-ocata-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Jorge Niedbalski (niedbalski)]

Hello Corey,

I've verified that the current ocata-proposed package solves the issue.

1) Use this bundle (pastebin: http://paste.ubuntu.com/p/XxJPcs7YX9/)
2) Forced a volume deletion
root@juju-30736a-1698786-cinder-0:/home/ubuntu# rados -p cinder-ceph rm rbd_id.volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
root@juju-30736a-1698786-cinder-0:/home/ubuntu# rbd -p cinder-ceph info volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
rbd: error opening image volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04: (2) No such file or directory

3) Wait for a few seconds. The exception is logged but service doesn't raises
the exception, therefore agent remains up.

Thank you for fixing.

[Corey Bryant (corey.bryant)]

The verification of the Stable Release Update for cinder has completed successfully and the package has now been released to -updates. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

[Corey Bryant (corey.bryant)]

This bug was fixed in the package cinder - 2:10.0.8-0ubuntu1~cloud2
---------------

 cinder (2:10.0.8-0ubuntu1~cloud2) xenial-ocata; urgency=medium
 .
   * Backport: Handle rbd.OSError on broken RBD image (LP: #1698786).
     - d/p/Handle-rbd.OSError-on-broken-RBD-image.patch

[Jorge Niedbalski (niedbalski)]

@corey.bryant,

I am seeing a regression in my lab with a fresh install + using the
 -updates package 10.0.8-0ubuntu1~cloud2 when used with python-rbd 10.2.11, when the get_usage_info is invoked, is raising the no attribute 'OSError' exception.
This version instead has the generic IOError (https://github.com/ceph/ceph/blob/v10.2.11/src/pybind/rbd/rbd.pyx#L335) class.

I am proposing a new debdiff that uses IOError (https://github.com/ceph/ceph/blob/master/src/pybind/rbd/rbd.pyx#L854), that is also available on 10.2.11 (https://github.com/ceph/ceph/blob/v10.2.11/src/pybind/rbd/rbd.pyx#L335)

[Jorge Niedbalski (niedbalski)]

Apparently, one of the co-located charms was configured with the wrong origin
a newer version of python-rbd 12.2.3 that has the OSError backport on it and that's why we didn't catch it earlier.