rotate backups failed because of image in use

[Wangpan]

This issue similar to https://bugs.launchpad.net/nova/+bug/1634773,

Reproduce steps:
1. create an instance with system disk in rbd backend, named Instance-for-backup
2. create the first backup of this instance, such as: nova backup Instance-for-backup backup-1 daily 2
3. create a new instance with this backup-1 snapshot image, such as: nova boot --flavor m1.tiny --image backup-1 ...
4. then create the second backup of Instance-for-backup, CLI is similar as step 2
5. finally we create the third backup, we expect the backup-1 image should be rotated out by nova, but it doesn't, and nova-compute report an exception in it's log:

2017-11-28 16:29:16.361 4154 DEBUG nova.compute.manager [req-56a39c62-2010-4004-aaac-9c3e2669ee4d af175a5930e2470c8725e742bab1ad
7c 0e5bcf89990c455882649ed88b32e27d - - -] [instance: 00bce146-5408-4c33-bc11-7458f847eb19] Rotating out 52 backups _rotate_back
ups /usr/lib/python2.7/site-packages/nova/compute/manager.py:3262
2017-11-28 16:29:16.361 4154 DEBUG nova.compute.manager [req-56a39c62-2010-4004-aaac-9c3e2669ee4d af175a5930e2470c8725e742bab1ad
7c 0e5bcf89990c455882649ed88b32e27d - - -] [instance: 00bce146-5408-4c33-bc11-7458f847eb19] Deleting image 9a993e71-71ca-490e-b3
cb-0b4dca2e574c _rotate_backups /usr/lib/python2.7/site-packages/nova/compute/manager.py:3267
2017-11-28 16:29:19.280 4154 DEBUG oslo_concurrency.lockutils [req-56a39c62-2010-4004-aaac-9c3e2669ee4d af175a5930e2470c8725e742
bab1ad7c 0e5bcf89990c455882649ed88b32e27d - - -] Lock "compute_resources" acquired by "nova.compute.resource_tracker.update_usag
e" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:270
2017-11-28 16:29:19.353 4154 DEBUG oslo_concurrency.lockutils [req-56a39c62-2010-4004-aaac-9c3e2669ee4d af175a5930e2470c8725e742
bab1ad7c 0e5bcf89990c455882649ed88b32e27d - - -] Lock "compute_resources" released by "nova.compute.resource_tracker.update_usag
e" :: held 0.074s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:282
2017-11-28 16:29:19.354 4154 INFO nova.compute.manager [req-56a39c62-2010-4004-aaac-9c3e2669ee4d af175a5930e2470c8725e742bab1ad7
c 0e5bcf89990c455882649ed88b32e27d - - -] [instance: 00bce146-5408-4c33-bc11-7458f847eb19] Successfully reverted task state from
 None on failure for instance.
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher [req-56a39c62-2010-4004-aaac-9c3e2669ee4d af175a5930e2470c8725e
742bab1ad7c 0e5bcf89990c455882649ed88b32e27d - - -] Exception during message handling: 409 Conflict: Image 9a993e71-71ca-490e-b3
cb-0b4dca2e574c could not be deleted because it is in use: The image cannot be deleted because it is in use through the backend
store outside of Glance. (HTTP 409)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dis
patcher.py", line 138, in _dispatch_and_reply
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher incoming.message))
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dis
patcher.py", line 185, in _dispatch
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dis
patcher.py", line 127, in _do_dispatch
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher result = func(ctxt, **new_args)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/exception.py", li
ne 110, in wrapped
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher payload)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py
", line 220, in __exit__
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher self.force_reraise()
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py
", line 196, in force_reraise
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/exception.py", line 89, in wrapped
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher return f(self, context, *args, **kw)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 359, in decorated_function
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher LOG.warning(msg, e, instance=instance)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher self.force_reraise()
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 328, in decorated_function
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 387, in decorated_function
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher kwargs['instance'], e, sys.exc_info())
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher self.force_reraise()
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 375, in decorated_function
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 3124, in backup_instance
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher self._rotate_backups(context, instance, backup_type, rotation)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 387, in decorated_function
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher kwargs['instance'], e, sys.exc_info())
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher self.force_reraise()
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 375, in decorated_function
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 3269, in _rotate_backups
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher self.image_api.delete(context, image_id)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/image/api.py", line 141, in delete
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher return session.delete(context, image_id)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/image/glance.py", line 499, in delete
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher self._client.call(context, 1, 'delete', image_id)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/image/glance.py", line 250, in call
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher result = getattr(client.images, method)(*args, **kwargs)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/glanceclient/v1/images.py", line 291, in delete
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher resp, body = self.client.delete(url)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/glanceclient/common/http.py", line 287, in delete
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher return self._request('DELETE', url, **kwargs)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/glanceclient/common/http.py", line 267, in _request
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher resp, body_iter = self._handle_response(resp)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/glanceclient/common/http.py", line 83, in _handle_response
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher raise exc.from_response(resp, resp.content)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher HTTPConflict: 409 Conflict: Image 9a993e71-71ca-490e-b3cb-0b4dca2e574c could not be deleted because it is in use: The image cannot be deleted because it is in use through the backend store outside of Glance. (HTTP 409)
2017-11-28 16:29:19.361 4154 ERROR oslo_messaging.rpc.dispatcher

[Wangpan (aspirer)]

The reason may be that, rbd image can not be deleted if it is in use by an instance, because it is a rbd snap, and an instance system disk is a cloned volume from the snap in rbd pool, if we call glance to delete the snap, "HTTPConflict: 409 Conflict: Image 9a993e71-71ca-490e-b3cb-0b4dca2e574c could not be deleted because it is in use: The image cannot be deleted because it is in use through the backend store outside of Glance. (HTTP 409)" will be returned.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/523395
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=3e766e5bd429c6119c077b8be02360ae1e1ec8bd
Submitter: Zuul
Branch: master

commit 3e766e5bd429c6119c077b8be02360ae1e1ec8bd
Author: Wangpan <email address hidden>
Date: Tue Nov 28 19:48:21 2017 +0800

    Handle glance exception during rotating instance backup

    Glance image backends may return HTTPConflict in many cases
    during deleting image, for example, an rbd image is used for
    booting a new instance, or rbd image has snapshot(s).

    If user have already backed up instance to few numbers and then
    execute backup api with rotation 1, then nova will delete the
    previously created images exceeding rotation limit.
    During deleting these images, if the first one of the backup
    images are deleted failed with HTTPConflict or other exceptions,
    all images exceeding rotation limit will be left over.

    This patch handles ImageDeleteConflict and all other exceptions
    during deleting backup images, logs a message and continues
    deleting all of the remaining images.

    Closes-Bug: #1734838

    Change-Id: Ie8091fe3e0e4275717ddc50166345f1c9df4b889

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 17.0.0.0b3 development milestone.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/533439
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=43c42b6f691b0c97a1ef626d29a7d08a9a240f4f
Submitter: Zuul
Branch: stable/pike

commit 43c42b6f691b0c97a1ef626d29a7d08a9a240f4f
Author: Wangpan <email address hidden>
Date: Tue Nov 28 19:48:21 2017 +0800

    Handle glance exception during rotating instance backup

    Glance image backends may return HTTPConflict in many cases
    during deleting image, for example, an rbd image is used for
    booting a new instance, or rbd image has snapshot(s).

    If user have already backed up instance to few numbers and then
    execute backup api with rotation 1, then nova will delete the
    previously created images exceeding rotation limit.
    During deleting these images, if the first one of the backup
    images are deleted failed with HTTPConflict or other exceptions,
    all images exceeding rotation limit will be left over.

    This patch handles ImageDeleteConflict and all other exceptions
    during deleting backup images, logs a message and continues
    deleting all of the remaining images.

    Closes-Bug: #1734838

    Change-Id: Ie8091fe3e0e4275717ddc50166345f1c9df4b889
    (cherry picked from commit 3e766e5bd429c6119c077b8be02360ae1e1ec8bd)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 16.1.1 release.