Bug 1300691 - Error while deleting glance image with ceph backend
Summary: Error while deleting glance image with ceph backend
Keywords:
Status: CLOSED INSUFFICIENT_DATA
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-glance
Version: 7.0 (Kilo)
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
: 7.0 (Kilo)
Assignee: Flavio Percoco
QA Contact: nlevinki
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-01-21 13:18 UTC by shilpa
Modified: 2020-03-11 15:01 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-04-04 13:37:56 UTC
Target Upstream Version:

Attachments (Terms of Use)
Add an attachment (proposed patch, testcase, etc.)

Description shilpa 2016-01-21 13:18:36 UTC 
Description of problem:
While testing Openstack 7.0 with Ceph Hammer, found that I cannot delete some of the glance images that use rbd.

Version-Release number of selected component (if applicable):
openstack-glance-2015.1.2-1.el7ost.noarch
python-glanceclient-0.17.3-1.el7ost.noarch
ceph-0.94.5-2.el7cp.x86_64


How reproducible:
Sometimes

Steps to Reproduce:
1. Configure rbd for glance, nova and cinder. 
2. Create glance images, boot vm, take a vm snapshot, delete vm, delete vm snapshot and try to delete the glance image.
3. While deleting glance image, the error is:

500 Internal Server Error: The server has either erred or is incapable of performing the requested operation. (HTTP 500): Unable to delete image bfb48bfa-cd77-4bd6-86f4-0fe62c9590e8

I confirmed that the vm snap was deleted before deleting glance image.

Actual results:

Found the following logs in glance/api.log

2016-01-21 08:02:17.256 21970 ERROR glance.common.wsgi [req-328c332e-bbac-4767-92a6-bd69677c2c5d ffb1c580e14b467dbf6f2b7f1e032504 71d9b72db9764dbda22dc
115501dd459 - - -] Caught error: The image cannot be deleted because it is in use through the backend store outside of Glance.
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi Traceback (most recent call last):
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance/common/wsgi.py", line 881, in __call__
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     request, **action_args)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance/common/wsgi.py", line 909, in dispatch
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     return method(*args, **kwargs)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance/common/utils.py", line 508, in wrapped
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     return func(self, req, *args, **kwargs)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance/api/v1/images.py", line 1099, in delete
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     {'status': ori_status})
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 85, in __exit__
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     six.reraise(self.type_, self.value, self.tb)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance/api/v1/images.py", line 1095, in delete
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     upload_utils.initiate_deletion(req, loc_data, id)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance/api/v1/upload_utils.py", line 46, in initiate_de
letion
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     id, location_data)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance/common/store_utils.py", line 124, in delete_imag
e_location_from_backend
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     safe_delete_from_backend(context, image_id, location)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance/common/store_utils.py", line 58, in safe_delete_
from_backend
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     ret = store_api.delete_from_backend(location['url'], context=context)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance_store/backend.py", line 290, in delete_from_back
end
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     return store.delete(loc, context=context)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance_store/capabilities.py", line 226, in op_checker
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     return store_op_fun(store, *args, **kwargs)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py", line 451, in delete
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     self._cleanup_image(target_pool, loc.image, loc.snapshot)
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi   File "/usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py", line 329, in _cleanup_im
age
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi     raise exceptions.InUseByStore()
2016-01-21 08:02:17.256 21970 TRACE glance.common.wsgi InUseByStore: The image cannot be deleted because it is in use through the backend store outside
 of Glance.


Additional info:

Seems like it is the same issue as https://bugs.launchpad.net/glance/+bug/1077045.
Comment 2 Sergey Gotliv 2016-01-24 07:15:38 UTC 
@shilpa,

Please, attach Nova and Glance logs and then reopen the case. In general it should be a habit especially if the problem is not 100% percent reproducible.

According to the bug description, GLance's RBD store fails to "unprotect" a snapshot which means that snapshot is in use. I would like to eliminate that obvious possibility before we move forward to investigate more complex options.
Comment 3 Jeremy 2016-03-29 13:46:16 UTC 
I have a customer that seems to be hitting the same issue. However they have slightly different levels of code.
python-glance-2014.2.3-4.el7ost.noarch 
ceph-0.80.8-17.el7cp.x86_64

Here is the trace from controller 003:L
2016-03-28 07:18:39.175 16884 DEBUG glance_store._drivers.rbd [-] snapshot 88e21cc9-e249-4b8e-97b6-b97e9bca0344@snap could not be unprotected because it is in use _cleanup_image /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:325
2016-03-28 07:18:39.186 16884 DEBUG glance_store._drivers.rbd [-] _cleanup_image() failed delete /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:448
2016-03-28 07:18:39.186 16884 TRACE glance_store._drivers.rbd Traceback (most recent call last):
2016-03-28 07:18:39.186 16884 TRACE glance_store._drivers.rbd   File "/usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py", line 446, in delete
2016-03-28 07:18:39.186 16884 TRACE glance_store._drivers.rbd     self._cleanup_image(target_pool, loc.image, loc.snapshot)
2016-03-28 07:18:39.186 16884 TRACE glance_store._drivers.rbd   File "/usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py", line 326, in _cleanup_image
2016-03-28 07:18:39.186 16884 TRACE glance_store._drivers.rbd     raise exceptions.InUseByStore()
2016-03-28 07:18:39.186 16884 TRACE glance_store._drivers.rbd InUseByStore: None
2016-03-28 07:18:39.186 16884 TRACE glance_store._drivers.rbd
2016-03-28 07:18:39.206 16884 DEBUG glance.registry.client.v1.api [-] Updating image metadata for image 88e21cc9-e249-4b8e-97b6-b97e9bca0344... update_image_metadata /usr/lib/python2.7/site-packages/glance/registry/client/v1/api.py:166
2016-03-28 07:18:39.207 16884 DEBUG glance.common.client [-] Constructed URL: http://10.100.91.22:9191/images/88e21cc9-e249-4b8e-97b6-b97e9bca0344 _construct_url /usr/lib/python2.7/site-packages/glance/common/client.py:398
2016-03-28 07:18:39.214 16885 DEBUG glance.registry.client.v1.client [-] Registry request GET /images/35dbddd8-0d68-4cf7-bc34-cda042eb0132 HTTP 200 request id req-e2e305ed-d260-460c-9af7-b769b3b3c6cf do_request /usr/lib/python2.7/site-packages/glance/registry/client/v1/client.py:122
2016-03-28 07:18:39.216 16885 INFO glance.wsgi.server [-] 10.100.91.23 - - [28/Mar/2016 07:18:39] "HEAD /v1/images/35dbddd8-0d68-4cf7-bc34-cda042eb0132 HTTP/1.1" 200 1032 0.313704
2016-03-28 07:18:39.312 16884 DEBUG glance.registry.client.v1.client [-] Registry request PUT /images/88e21cc9-e249-4b8e-97b6-b97e9bca0344 HTTP 200 request id req-9d02831b-599e-4afe-9764-5ba0068666e5 do_request /usr/lib/python2.7/site-packages/glance/registry/client/v1/client.py:122
2016-03-28 07:18:39.368 16884 INFO glance.wsgi.server [-] Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/eventlet/wsgi.py", line 454, in handle_one_response
  result = self.application(self.environ, start_response)
  File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python2.7/site-packages/glance/common/wsgi.py", line 394, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
    application, catch_exc_info=False)
  File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
    app_iter = application(self.environ, start_response)
  File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python2.7/site-packages/osprofiler/web.py", line 99, in __call__
    return request.get_response(self.application)
  File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
    application, catch_exc_info=False)
  File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
    app_iter = application(self.environ, start_response)
  File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token.py", line 823, in __call__
    return self._call_app(env, start_response)
  File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token.py", line 758, in _call_app
    return self._app(env, _fake_start_response)
  File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python2.7/site-packages/glance/common/wsgi.py", line 394, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
    application, catch_exc_info=False)
  File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
    app_iter = application(self.environ, start_response)
  File "/usr/lib/python2.7/site-packages/paste/urlmap.py", line 203, in __call__
    return app(environ, start_response)
  File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
    return resp(environ, start_response)
  File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
    response = self.app(environ, start_response)
  File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
    return resp(environ, start_response)
  File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
    return self.func(req, *args, **kwargs)
 File "/usr/lib/python2.7/site-packages/glance/api/v1/images.py", line 1082, in delete
    {'status': ori_status})
  File "/usr/lib/python2.7/site-packages/glance/openstack/common/excutils.py", line 82, in __exit__
    six.reraise(self.type_, self.value, self.tb)
  File "/usr/lib/python2.7/site-packages/glance/api/v1/images.py", line 1078, in delete
    upload_utils.initiate_deletion(req, loc_data, id)
  File "/usr/lib/python2.7/site-packages/glance/api/v1/upload_utils.py", line 46, in initiate_deletion
    id, location_data)
  File "/usr/lib/python2.7/site-packages/glance/common/store_utils.py", line 124, in delete_image_location_from_backend
    safe_delete_from_backend(context, image_id, location)
  File "/usr/lib/python2.7/site-packages/glance/common/store_utils.py", line 58, in safe_delete_from_backend
    ret = store_api.delete_from_backend(location['url'], context=context)
  File "/usr/lib/python2.7/site-packages/glance_store/backend.py", line 280, in delete_from_backend
    return store.delete(loc, context=context)
  File "/usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py", line 446, in delete
    self._cleanup_image(target_pool, loc.image, loc.snapshot)
  File "/usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py", line 326, in _cleanup_image
    raise exceptions.InUseByStore()
InUseByStore: None
2016-03-28 07:18:39.369 16884 INFO glance.wsgi.server [-] 10.100.91.23 - - [28/Mar/2016 07:18:39] "DELETE /v1/images/88e21cc9-e249-4b8e-97b6-b97e9bca0344 HTTP/1.1" 500 139 0.855919
Note You need to log in before you can comment on or make changes to this bug.