OpenStack Identity (keystone)

keystone does not retry on DbDeadlock [HTTP 500] for delete_credential_for_user

Bug #1840291 reported by Rabi Mishra on 2019-08-15

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Identity (keystone)	Fix Released	Medium	Rabi Mishra

Bug Description

traceback:

We do have it for identity backend via
https://github.com/openstack/keystone/commit/e439476c1e434587122053a5c02c9ee4908e8b7c, but not for credential backend.

2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi [req-b30e30a8-14fe-477f-b805-56a4d6e51ffc 725e044907004e1a87ab05c037ac6c50 - 65521f17cdd6481dac039783ff582a57 65521f17cdd6481dac039783ff582a57
-] (pymysql.err.InternalError) (1205, u'Lock wait timeout exceeded; try restarting transaction') [SQL: u'DELETE FROM credential WHERE credential.user_id = %(user_id_1)s'] [parameters: {u'user_id_1':
u'd7830b696f8b49ce86770ba7b97b64fc'}] (Background on this error at: http://sqlalche.me/e/2j85): DBDeadlock: (pymysql.err.InternalError) (1205, u'Lock wait timeout exceeded; try restarting transaction'
) [SQL: u'DELETE FROM credential WHERE credential.user_id = %(user_id_1)s'] [parameters: {u'user_id_1': u'd7830b696f8b49ce86770ba7b97b64fc'}] (Background on this error at: http://sqlalche.me/e/2j85)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi Traceback (most recent call last):
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 226, in __call__
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi result = method(req, **params)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/controller.py", line 82, in inner
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi return f(self, request, *args, **kwargs)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/controllers.py", line 121, in delete_user
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi user_id, initiator=request.audit_initiator
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/manager.py", line 116, in wrapped
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi __ret_val = __f(*args, **kwargs)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 416, in wrapper
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi return f(self, *args, **kwargs)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 426, in wrapper
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi return f(self, *args, **kwargs)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 1143, in delete_user
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi PROVIDERS.credential_api.delete_credentials_for_user(user_id)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/credential/backends/sql.py", line 103, in delete_credentials_for_user
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi query.delete()
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 3236, in delete
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi delete_op.exec_()
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 1325, in exec_
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi self._do_exec()
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 1517, in _do_exec
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi self._execute_stmt(delete_stmt)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 1332, in _execute_stmt
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi mapper=self.mapper)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 1176, in execute
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi bind, close_with_result=True).execute(clause, params or {})
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 948, in execute
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi return meth(self, multiparams, params)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi return connection._execute_clauseelement(self, multiparams, params)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi compiled_sql, distilled_params
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi context)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1409, in _handle_dbapi_exception
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi util.raise_from_cause(newraise, exc_info)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi reraise(type(exception), exception, tb=exc_tb, cause=cause)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi context)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 507, in do_execute
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi cursor.execute(statement, parameters)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 166, in execute
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi result = self._query(query)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 322, in _query
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi conn.query(q)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 856, in query
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1057, in _read_query_result
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi result.read()
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1340, in read
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi first_packet = self.connection._read_packet()
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1014, in _read_packet
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi packet.check_error()
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 393, in check_error
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi err.raise_mysql_exception(self._data)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/err.py", line 107, in raise_mysql_exception
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi raise errorclass(errno, errval)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi DBDeadlock: (pymysql.err.InternalError) (1205, u'Lock wait timeout exceeded; try restarting transaction') [SQL: u'DELETE FROM credential WHERE credential.user_id = %(user_id_1)s'] [parameters: {u'user_id_1': u'd7830b696f8b49ce86770ba7b97b64fc'}] (Background on this error at: http://sqlalche.me/e/2j85)
2019-08-14 03:34:15.264 199385 ERROR keystone.common.wsgi

Tags:

Rabi Mishra (rabi) on 2019-08-15

Changed in keystone:
assignee:	nobody → Rabi Mishra (rabi)

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-08-15: Fix proposed to keystone (master)

Fix proposed to branch: master
Review: https://review.opendev.org/676733

Changed in keystone:
status:	New → In Progress

Colleen Murphy (krinkle) on 2019-08-16

Changed in keystone:
importance:	Undecided → Medium

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-08-20: Fix merged to keystone (master)

Reviewed: https://review.opendev.org/676733
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=e989bd0637629b0fb15976186b0941fec0f13b25
Submitter: Zuul
Branch: master

commit e989bd0637629b0fb15976186b0941fec0f13b25
Author: Rabi Mishra <email address hidden>
Date: Thu Aug 15 21:23:46 2019 +0530

Add retry for DBDeadlock in credential delete

Adds oslo.db retry wrapper to delete_credential_for_user method.

Change-Id: Ib9e161411f0985785eec46c51d721ef7421ee090
Closes-Bug: #1840291

Changed in keystone:
status:	In Progress → Fix Released

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-08-20: Fix proposed to keystone (stable/stein)

Fix proposed to branch: stable/stein
Review: https://review.opendev.org/677397

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-09-03: Fix merged to keystone (stable/stein)

Reviewed: https://review.opendev.org/677397
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=52ef61868930fcccbabe91f27a805211abebde84
Submitter: Zuul
Branch: stable/stein

commit 52ef61868930fcccbabe91f27a805211abebde84
Author: Rabi Mishra <email address hidden>
Date: Thu Aug 15 21:23:46 2019 +0530

Add retry for DBDeadlock in credential delete

Adds oslo.db retry wrapper to delete_credential_for_user method.

    Change-Id: Ib9e161411f0985785eec46c51d721ef7421ee090
    Closes-Bug: #1840291
    (cherry picked from commit e989bd0637629b0fb15976186b0941fec0f13b25)

tags:

added: in-stable-stein

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-09-06: Fix proposed to keystone (stable/rocky)

Fix proposed to branch: stable/rocky
Review: https://review.opendev.org/680570

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-09-06: Fix proposed to keystone (stable/queens)

Fix proposed to branch: stable/queens
Review: https://review.opendev.org/680572

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-09-27: Fix included in openstack/keystone 16.0.0.0rc1

This issue was fixed in the openstack/keystone 16.0.0.0rc1 release candidate.

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-10-18: Fix merged to keystone (stable/rocky)

Reviewed: https://review.opendev.org/680570
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=09547696f2bb952f29b5dc95cbb572b9d1d0b72b
Submitter: Zuul
Branch: stable/rocky

commit 09547696f2bb952f29b5dc95cbb572b9d1d0b72b
Author: Rabi Mishra <email address hidden>
Date: Thu Aug 15 21:23:46 2019 +0530

Add retry for DBDeadlock in credential delete

Adds oslo.db retry wrapper to delete_credential_for_user method.

    Change-Id: Ib9e161411f0985785eec46c51d721ef7421ee090
    Closes-Bug: #1840291
    (cherry picked from commit e989bd0637629b0fb15976186b0941fec0f13b25)

tags:

added: in-stable-rocky

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-10-19: Fix merged to keystone (stable/queens)

Reviewed: https://review.opendev.org/680572
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=686d52930bd1d9f10bcad265f2282ebe2055fd93
Submitter: Zuul
Branch: stable/queens

commit 686d52930bd1d9f10bcad265f2282ebe2055fd93
Author: Rabi Mishra <email address hidden>
Date: Thu Aug 15 21:23:46 2019 +0530

Add retry for DBDeadlock in credential delete

Adds oslo.db retry wrapper to delete_credential_for_user method.

    Change-Id: Ib9e161411f0985785eec46c51d721ef7421ee090
    Closes-Bug: #1840291
    (cherry picked from commit e989bd0637629b0fb15976186b0941fec0f13b25)