Glance

Caught error: UPDATE statement on table 'image_properties' expected to update 1 row(s); 0 were matched

Bug #1895173 reported by Lee Yarwood on 2020-09-10

This bug affects 2 people

Affects		Status	Importance	Assigned to	Milestone
	Glance	Fix Released	Medium	Dan Smith

Bug Description

tearDownClass (tempest.api.image.v2.test_images.ImportImagesTest)

https://32e87445f1b3f9b72fad-889023abcee881d48f07f1c8f07a15d7.ssl.cf2.rackcdn.com/749304/2/check/nova-ceph-multistore/03c5041/testr_results.html

  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 0x7ff36844c388>), (<class 'tempest.lib.exceptions.TimeoutException'>, Request timed out
Details: (ImportImagesTest:tearDownClass) Failed to delete image 286e8f52-2d10-4605-a086-30b3d64fe284 within the required time (300 s)., <traceback object at 0x7ff368a48208>))
https://zuul.opendev.org/t/openstack/build/03c5041a95064d6c8320dfb4a8ccd528/log/controller/logs/screen-g-api.txt#21361

Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi [None req-d49277db-83c2-472e-a9c6-084b46e95d07 tempest-ImportImagesTest-1047019480 tempest-ImportImagesTest-1047019480] 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 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi Traceback (most recent call last):
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/wsgi.py", line 1348, in __call__
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi request, **action_args)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/wsgi.py", line 1391, in dispatch
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi return method(*args, **kwargs)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/utils.py", line 416, in wrapped
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi return func(self, req, *args, **kwargs)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/api/v2/images.py", line 664, in delete
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi image_repo.remove(image)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 104, in remove
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi result = self.base.remove(base_item)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/notifier.py", line 542, in remove
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi super(ImageRepoProxy, self).remove(image)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 104, in remove
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi result = self.base.remove(base_item)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 104, in remove
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi result = self.base.remove(base_item)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/domain/proxy.py", line 104, in remove
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi result = self.base.remove(base_item)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi [Previous line repeated 1 more time]
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/__init__.py", line 204, in remove
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi purge_props=True)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/api.py", line 161, in image_update
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi from_state=from_state, atomic_props=atomic_props)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/retrying.py", line 49, in wrapped_f
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi return Retrying(*dargs, **dkw).call(f, *args, **kw)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/retrying.py", line 206, in call
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi return attempt.get(self._wrap_exception)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/retrying.py", line 247, in get
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi six.reraise(self.value[0], self.value[1], self.value[2])
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/six.py", line 703, in reraise
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi raise value
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/retrying.py", line 200, in call
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi attempt = Attempt(fn(*args, **kwargs), attempt_number, False)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/utils.py", line 547, in wrapper
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi return f(*args, **kwargs)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/api.py", line 972, in _image_update
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi atomic_props, session)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/common/utils.py", line 547, in wrapper
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi return f(*args, **kwargs)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/api.py", line 1131, in _set_properties_for_image
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi image_ref.id, session=session)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/api.py", line 1190, in image_property_delete
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi prop.delete(session=session)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/models.py", line 93, in delete
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi self.save(session=session)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/opt/stack/glance/glance/db/sqlalchemy/models.py", line 73, in save
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi super(GlanceBase, self).save(session or db_api.get_session())
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/oslo_db/sqlalchemy/models.py", line 48, in save
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi session.flush()
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/session.py", line 2523, in flush
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi self._flush(objects)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/session.py", line 2664, in _flush
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi transaction.rollback(_capture_exception=True)
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/langhelpers.py", line 69, in __exit__
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi exc_value, with_traceback=exc_tb,
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 182, in raise_
Sep 10 14:27:15.924967 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi raise exception
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/session.py", line 2624, in _flush
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi flush_context.execute()
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/unitofwork.py", line 422, in execute
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi rec.execute(self)
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/unitofwork.py", line 589, in execute
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi uow,
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/persistence.py", line 236, in save_obj
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi update,
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/persistence.py", line 1028, in _emit_update_statements
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi % (table.description, len(records), rows)
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi sqlalchemy.orm.exc.StaleDataError: UPDATE statement on table 'image_properties' expected to update 1 row(s); 0 were matched.
Sep 10 14:27:15.930499 ubuntu-bionic-ovh-gra1-0019749715 glance-api[48306]: ERROR glance.common.wsgi

Revision history for this message

Abhishek Kekane (abhishek-kekane) wrote on 2021-03-29:

Is this issue still valid, would like to mark it as Won't fix if its not reproducible any more.

Revision history for this message

Dan Smith (danms) wrote on 2021-03-29:

Here's an example from a couple days ago:

https://3358148dd61163c40ee5-fed9d885f48c89b65645af8cb1093bc8.ssl.cf5.rackcdn.com/783026/2/check/nova-ceph-multistore/a288fa1/controller/logs/screen-g-api.txt

So it would appear that it still happens occasionally. There's a socket.gaierror earlier in the logs, which might indicate that something about the environment isn't right, but I haven't looked closely.

Revision history for this message

Dan Smith (danms) wrote on 2021-03-29:

Hoping to address this with this patch:

https://review.opendev.org/c/openstack/glance/+/783668

Abhishek Kekane (abhishek-kekane) on 2021-03-30

Changed in glance:
assignee:	nobody → Abhishek Kekane (abhishek-kekane)
assignee:	Abhishek Kekane (abhishek-kekane) → Dan Smith (danms)
importance:	Undecided → Medium
status:	New → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2021-07-22: Fix merged to glance (master)

Reviewed: https://review.opendev.org/c/openstack/glance/+/783668
Committed: https://opendev.org/openstack/glance/commit/7779c20198c4ee09ee2c31ba0f5752151331abaf
Submitter: "Zuul (22348)"
Branch: master

commit 7779c20198c4ee09ee2c31ba0f5752151331abaf
Author: Dan Smith <email address hidden>
Date: Mon Mar 29 08:07:41 2021 -0700

Ignore stale image property removal

    Occasionally we fail to delete a property from an image and get a
    StaleDataError from SQLAlchemy. It looks like maybe we are just racing
    with another operation to delete a single property (i.e. a race
    between image delete and the end of an import cleanup).

    This ignores that "can't delete because it is already deleted" error
    and logs to debug about the situation for later auditing and
    confirmation.

Change-Id: Ida5bc659b7481fa0a7f3926a54520628a7a4c406
Closes-Bug: #1895173