yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1840291] [NEW] keystone does not retry on DbDeadlock [HTTP 500] for delete_credential_for_user

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Rabi Mishra <1840291@xxxxxxxxxxxxxxxxxx>
Date: Thu, 15 Aug 2019 16:14:35 -0000
Reply-to: Bug 1840291 <1840291@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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

** Affects: keystone
     Importance: Undecided
     Assignee: Rabi Mishra (rabi)
         Status: In Progress

** Changed in: keystone
     Assignee: (unassigned) => Rabi Mishra (rabi)

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Identity (keystone).
https://bugs.launchpad.net/bugs/1840291

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

Status in OpenStack Identity (keystone):
  In Progress

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

To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1840291/+subscriptions
Follow ups

[Bug 1840291] Re: keystone does not retry on DbDeadlock [HTTP 500] for delete_credential_for_user
From: OpenStack Infra, 2019-08-20