[Bug 1698786] Re: cinder-volume fails on start when rbd pool contains partially deleted images

Mon Feb 10 20:44:23 UTC 2020

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 at 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 at juju-30736a-1698786-cinder-0:/home/ubuntu# rados -p cinder-ceph rm rbd_id.volume-ad50fecd-bc7e-47a7-81d8-9a48ff996a04
root at 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 

** Also affects: cloud-archive
   Importance: Undecided
       Status: New

-- 
You received this bug notification because you are a member of Ubuntu
OpenStack, which is subscribed to Ubuntu Cloud Archive.
https://bugs.launchpad.net/bugs/1698786

Title:
  cinder-volume fails on start when rbd pool contains partially deleted
  images

Status in Cinder:
  Fix Released
Status in Ubuntu Cloud Archive:
  Invalid
Status in Ubuntu Cloud Archive ocata series:
  Triaged

Bug description:
  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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/cinder/+bug/1698786/+subscriptions