During the MultiStoresImportTest module in tempest, when we go to clean up images during tearDown, we occasionally get a 500 from the delete, which yields this from the test:
ft1.1: tearDownClass (tempest.api.image.v2.test_images.MultiStoresImportImagesTest)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.8/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 0x7f0d0256bcc0>), (<class 'tempest.lib.exceptions.TimeoutException'>, Request timed out
Details: (MultiStoresImportImagesTest:tearDownClass) Failed to delete image 9c4bba30-c244-4712-9995-86446a38eed8 within the required time (300 s)., <traceback object at 0x7f0d0256a180>))
The corresponding g-api.log message shows that we're failing to delete something from image_properties, I'm guessing because something has changed the image underneath us between fetch and delete.
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi [None req-4d353638-2da8-4a8b-8c6b-fb879b27c90b tempest-MultiStoresImportImagesTest-208757482 tempest-MultiStoresImportImagesTest-208757482] Caught error: UPDATE statement on table 'image_properties' expected to update 1 row(s); 0 were matched.: sqlalchemy.orm.exc.StaleDataError: UPDATE statement on table 'image_properties' expected to update 1 row(s); 0 were matched.
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi Traceback (most recent call last):
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/wsgi.py", line 1347, in __call__
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi action_result = self.dispatch(self.controller, action,
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/wsgi.py", line 1391, in dispatch
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi return method(*args, **kwargs)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/utils.py", line 416, in wrapped
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi return func(self, req, *args, **kwargs)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/api/v2/images.py", line 664, in delete
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi image_repo.remove(image)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 104, in remove
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi result = self.base.remove(base_item)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/notifier.py", line 542, in remove
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi super(ImageRepoProxy, self).remove(image)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 104, in remove
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi result = self.base.remove(base_item)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 104, in remove
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi result = self.base.remove(base_item)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 104, in remove
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi result = self.base.remove(base_item)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi [Previous line repeated 1 more time]
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/__init__.py", line 202, in remove
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi self.db_api.image_update(self.context, image.image_id,
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/api.py", line 160, in image_update
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi image = _image_update(context, values, image_id, purge_props,
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/retrying.py", line 49, in wrapped_f
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi return Retrying(*dargs, **dkw).call(f, *args, **kw)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/retrying.py", line 206, in call
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi return attempt.get(self._wrap_exception)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/retrying.py", line 247, in get
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi six.reraise(self.value[0], self.value[1], self.value[2])
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/six.py", line 703, in reraise
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi raise value
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/retrying.py", line 200, in call
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi attempt = Attempt(fn(*args, **kwargs), attempt_number, False)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/utils.py", line 547, in wrapper
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi return f(*args, **kwargs)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/api.py", line 971, in _image_update
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi _set_properties_for_image(context, image_ref, properties, purge_props,
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/utils.py", line 547, in wrapper
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi return f(*args, **kwargs)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/api.py", line 1130, in _set_properties_for_image
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi image_property_delete(context, prop_ref.name,
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/api.py", line 1190, in image_property_delete
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi prop.delete(session=session)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/models.py", line 93, in delete
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi self.save(session=session)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/models.py", line 73, in save
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi super(GlanceBase, self).save(session or db_api.get_session())
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/oslo_db/sqlalchemy/models.py", line 48, in save
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi session.flush()
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/sqlalchemy/orm/session.py", line 2523, in flush
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi self._flush(objects)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/sqlalchemy/orm/session.py", line 2664, in _flush
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi transaction.rollback(_capture_exception=True)
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/sqlalchemy/util/langhelpers.py", line 68, in __exit__
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi compat.raise_(
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/sqlalchemy/util/compat.py", line 182, in raise_
Sep 30 09:52:44.240675 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi raise exception
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/sqlalchemy/orm/session.py", line 2624, in _flush
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi flush_context.execute()
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/sqlalchemy/orm/unitofwork.py", line 422, in execute
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi rec.execute(self)
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/sqlalchemy/orm/unitofwork.py", line 586, in execute
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi persistence.save_obj(
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/sqlalchemy/orm/persistence.py", line 230, in save_obj
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi _emit_update_statements(
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi File "/usr/local/lib/python3.8/dist-packages/sqlalchemy/orm/persistence.py", line 1025, in _emit_update_statements
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi raise orm_exc.StaleDataError(
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi sqlalchemy.orm.exc.StaleDataError: UPDATE statement on table 'image_properties' expected to update 1 row(s); 0 were matched.
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: ERROR glance.common.wsgi
Sep 30 09:52:44.246466 ubuntu-focal-rax-iad-0020118352 glance-api[94242]: INFO eventlet.wsgi.server [None req-4d353638-2da8-4a8b-8c6b-fb879b27c90b tempest-MultiStoresImportImagesTest-208757482 tempest-MultiStoresImportImagesTest-208757482] 10.209.96.128,10.209.96.128,10.209.96.128 - - [30/Sep/2020 09:52:44] "DELETE /v2/images/9c4bba30-c244-4712-9995-86446a38eed8 HTTP/1.1" 500 404 0.995549
