LVM Cinder - error deleting snapshot when disk/partition is full

[Salvador Fuentes]

Cinder cannot delete snapshot entrance in its database when it is in error state due to insufficient space.

1. Created 5 volumes of 3 GB each.
# cinder list
------------------------------------------------------------------------------------------
ID Status Name Size Volume Type Bootable Attached to
------------------------------------------------------------------------------------------
838316c1-bd15-412d-bee4-3184cc8c1a48 available fourthVol 3 None false
84696b98-44f5-4f9d-a449-d6cdb1a12ed1 available secondVol 3 None false
92a4c907-8383-4467-b14d-b563b7dce67d available fifthVol 3 None false
a8f5849f-b92b-44bd-8a62-839dec203bb6 available thirdVol 3 None false
e2cb558d-b604-4269-81f0-b6b520102343 deleting firstVol 3 None false
------------------------------------------------------------------------------------------

2. Created a snapshot of volume: secondVol:
# cinder snapshot-create secondVol --name snap-secondVol
-------------------------------------------------+
Property Value
-------------------------------------------------+
created_at 2015-06-30T17:18:01.311798
description None
id 17710692-48cf-48d6-8185-2047a86cae45
metadata {}
name snap-secondVol
size 3
status creating
volume_id 84696b98-44f5-4f9d-a449-d6cdb1a12ed1
-------------------------------------------------+
# cinder snapshot-list
--------------------------------------------------------------------------------------------------
ID Volume ID Status Name Size
--------------------------------------------------------------------------------------------------
17710692-48cf-48d6-8185-2047a86cae45 84696b98-44f5-4f9d-a449-d6cdb1a12ed1 error snap-secondVol 3

--------------------------------------------------------------------------------------------------
It is in error state since it does not fit in the available space.

3. Tried to delete snapshot volume
# cinder snapshot-delete snap-secondVol

Actual Result:
# cinder snapshot-list
----------------------------------------------------------------------------------------------------------
ID Volume ID Status Name Size
----------------------------------------------------------------------------------------------------------
17710692-48cf-48d6-8185-2047a86cae45 84696b98-44f5-4f9d-a449-d6cdb1a12ed1 error_deleting snap-secondVol 3
----------------------------------------------------------------------------------------------------------

Could not delete snapshot since it cannot find its logical volume

From logs:
2015-06-30 17:20:51.374 23802 ERROR oslo_messaging.rpc.dispatcher [req-a0d1dc40-6d9e-496d-b386-c04d79370bdc df53b164e37b4d26a5f3f980be2400dd 514e94069ff7427f934bb3be19e8a099 - - -] Exception during message handling: Unexpected error while running command.
Command: None
Exit code: -
Stdout: u'Unexpected error while running command.\nCommand: sudo cinder-rootwrap /usr/share/cinder/rootwrap.conf env LC_ALL=C lvs --noheadings --unit=g -o vg_name,name,size --nosuffix cinder-volumes/_snapshot-17710692-48cf-48d6-8185-2047a86cae45\nExit code: 5\nStdout: u\'\'\nStderr: u\' Failed to find logical volume "cinder-volumes/_snapshot-17710692-48cf-48d6-8185-2047a86cae45"\\n\''
Stderr: None
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher executor_callback))
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher executor_callback)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 130, in _do_dispatch
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher result = func(ctxt, **new_args)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 105, in wrapper
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 179, in lso_inner1
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher return lso_inner2(inst, context, snapshot, **kwargs)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line 445, in inner
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 178, in lso_inner2
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher return f(*_args, **_kwargs)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 725, in delete_snapshot
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher snapshot.save()
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 85, in _exit_
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 715, in delete_snapshot
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher self.driver.delete_snapshot(snapshot)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 105, in wrapper
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/lvm.py", line 355, in delete_snapshot
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher if self._volume_not_present(self._escape_snapshot(snapshot['name'])):
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/lvm.py", line 105, in _volume_not_present
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher return self.vg.get_volume(volume_name) is None
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/brick/local_dev/lvm.py", line 311, in get_volume
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher ref_list = self.get_volumes(name)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/brick/local_dev/lvm.py", line 303, in get_volumes
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher lv_name)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/brick/local_dev/lvm.py", line 285, in get_lv_info
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher out = None
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 85, in _exit_
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/brick/local_dev/lvm.py", line 277, in get_lv_info
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher run_as_root=True)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py", line 233, in execute
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher cmd=sanitized_cmd)
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher ProcessExecutionError: Unexpected error while running command.
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher Command: sudo cinder-rootwrap /usr/share/cinder/rootwrap.conf env LC_ALL=C lvs --noheadings --unit=g -o vg_name,name,size --nosuffix cinder-volumes/_snapshot-17710692-48cf-48d6-8185-2047a86cae45
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher Exit code: 5
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher Stdout: u''
2015-06-30 17:20:51.374 23802 TRACE oslo_messaging.rpc.dispatcher Stderr: u' Failed to find logical volume "cinder-volumes/_snapshot-17710692-48cf-48d6-8185-2047a86cae45"\n'
Expected Result:
Although logical volume was not created, cinder should be able to delete the volume from its database.

[Alberto Murillo (powerbsd-o)]

Since LVM2 2.102.112, The error message returned changed from/to
One or more specified logical volume(s) not found. to
Failed to find logical volume \"%s/%s\"

Writing a patch to look for the new message

[Alberto Murillo (powerbsd-o)]

Patch in review: https://review.openstack.org/197338

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/kilo
Review: https://review.openstack.org/200626

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/200626
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=08ff005c403047250f9e4ccf6d6f71d531f69c86
Submitter: Jenkins
Branch: stable/kilo

commit 08ff005c403047250f9e4ccf6d6f71d531f69c86
Author: Mitsuhiro Tanino <email address hidden>
Date: Fri Jul 10 11:37:24 2015 -0400

    Update expected error message from lvs

    drivers/lvm.py uses _volume_not_present() to avoid deleting a snapshot
    when it does not exist in the lvm backend. This functions uses brick/
    local_dev/lvm.py get_lv_info() which expects "not found" as error message.

    Since LVM2 2.102.112, The error message returned by lvs changed
    From:
        One or more specified logical volume(s) not found
    To:
        Failed to find logical volume \"%s/%s\"

    Change-Id: I032a916666918b07d00983a42f10dd8efc17ee8b
    Closes-Bug: #1470218
    (cherry picked from commit a0e2f994ff44db495eb4ccb1fad9d132ec994ce9)
      Additional comment:
          If volume_type is thin and there is no thin pool for VG,
          cinder-volume fails to start up due to the error of checking lv.
          Backporting this fix is useful for user who uses LVM2 2.102.112
          or later.