nova-ceph-multistore fails with rbd.OSError: [errno 116] error removing image

[Lee Yarwood]

tempest.api.image.v2.test_images.ImportImagesTest appears to be failing during tearDownClass:

ft1.1: tearDownClass (tempest.api.image.v2.test_images.ImportImagesTest)testtools.testresult.real._StringException: Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/test.py", line 242, in tearDownClass
    six.reraise(etype, value, trace)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/six.py", line 703, in reraise
    raise value
  File "/opt/stack/tempest/tempest/test.py", line 214, in tearDownClass
    teardown()
  File "/opt/stack/tempest/tempest/test.py", line 585, in resource_cleanup
    raise testtools.MultipleExceptions(*cleanup_errors)
testtools.runtest.MultipleExceptions: ((<class 'tempest.lib.exceptions.ServerFault'>, Got server fault
Details: The server has either erred or is incapable of performing the requested operation.<br /><br />

, <traceback object at 0x7f5320ff1488>), (<class 'tempest.lib.exceptions.TimeoutException'>, Request timed out
Details: (ImportImagesTest:tearDownClass) Failed to delete image 6640a1ec-9ae4-4eae-874c-ccacb9600a9d within the required time (300 s)., <traceback object at 0x7f5320fec7c8>))
https://22f684f005ef66b4c705-76c9445dc5d377f059713bef625876b4.ssl.cf1.rackcdn.com/744506/2/check/nova-ceph-multistore/46a4a0f/testr_results.html

With the following trace logged in g-api:

Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi [None req-d47ff0f9-ea09-49c6-9dc1-f9d381aa8fe3 tempest-ImportImagesTest-1392868169 tempest-ImportImagesTest-1392868169] Caught error: [errno 116] error removing image: rbd.OSError: [errno 116] error removing image
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi Traceback (most recent call last):
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/wsgi.py", line 1348, in __call__
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi request, **action_args)
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/wsgi.py", line 1391, in dispatch
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi return method(*args, **kwargs)
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/utils.py", line 416, in wrapped
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi return func(self, req, *args, **kwargs)
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/api/v2/images.py", line 524, in delete
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi image.delete()
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 194, in delete
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi self.base.delete()
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 194, in delete
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi self.base.delete()
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/api/policy.py", line 177, in delete
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi return self.image.delete()
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 194, in delete
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi self.base.delete()
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/location.py", line 442, in delete
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi location)
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/store_utils.py", line 130, in delete_image_location_from_backend
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi safe_delete_from_backend(context, image_id, location)
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/store_utils.py", line 59, in safe_delete_from_backend
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi context=context)
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/glance_store/multi_backend.py", line 509, in delete
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi return store.delete(loc, context=context)
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/glance_store/capabilities.py", line 176, in op_checker
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi return store_op_fun(store, *args, **kwargs)
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/glance_store/_drivers/rbd.py", line 619, in delete
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi self._delete_image(target_pool, loc.image, loc.snapshot)
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/glance_store/_drivers/rbd.py", line 447, in _delete_image
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi rbd.RBD().remove(ioctx, image_name)
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi File "rbd.pyx", line 1281, in rbd.RBD.remove
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi rbd.OSError: [errno 116] error removing image
Aug 03 19:26:50.138467 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: ERROR glance.common.wsgi
Aug 03 19:26:50.141640 ubuntu-bionic-ovh-gra1-0019075348 glance-api[48099]: INFO eventlet.wsgi.server [None req-d47ff0f9-ea09-49c6-9dc1-f9d381aa8fe3 tempest-ImportImagesTest-1392868169 tempest-ImportImagesTest-1392868169] 149.202.185.145,149.202.185.145,149.202.185.145 - - [03/Aug/2020 19:26:50] "DELETE /v2/images/6640a1ec-9ae4-4eae-874c-ccacb9600a9d HTTP/1.1" 500 404 1.030735

https://22f684f005ef66b4c705-76c9445dc5d377f059713bef625876b4.ssl.cf1.rackcdn.com/744506/2/check/nova-ceph-multistore/46a4a0f/controller/logs/screen-g-api.txt

[Lee Yarwood (lyarwood)]

Noticed the same trace last week, FWIW it looks like the only other hit of this:

Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi [None req-32db6b3c-9a3a-4096-9a24-eb277229d52a tempest-ImportImagesTest-1427548021 tempest-ImportImagesTest-1427548021] Caught error: [errno 116] error removing image: rbd.OSError: [errno 116] error removing image
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi Traceback (most recent call last):
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/wsgi.py", line 1348, in __call__
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi request, **action_args)
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/wsgi.py", line 1391, in dispatch
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi return method(*args, **kwargs)
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/utils.py", line 416, in wrapped
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi return func(self, req, *args, **kwargs)
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/api/v2/images.py", line 524, in delete
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi image.delete()
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 194, in delete
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi self.base.delete()
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 194, in delete
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi self.base.delete()
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/api/policy.py", line 177, in delete
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi return self.image.delete()
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 194, in delete
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi self.base.delete()
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/location.py", line 442, in delete
Jul 29 02:51:31.052677 ubuntu-bionic-rax-iad-0018926068 glance-api[48503]: ERROR glance.common.wsgi ...

[Abhishek Kekane (abhishek-kekane)]

Looks like related to race condition;
https://bugs.launchpad.net/glance/+bug/1884596

[Dan Smith (danms)]

Abhi, can you give some more context? Are you thinking that because of the race, we've got another thread still writing to the RBD backend when the first thread in tempest/nova goes to try to delete it?

[Abhishek Kekane (abhishek-kekane)]

Is this issue still valid?

[Abhishek Kekane (abhishek-kekane)]

Not heard anything in recent times about this issue, marking it won't fix at the moment. Please feel free to reopen.