keystone does not retry on deadlock Transactions [500 Error] in identity backend

[Adam Young]

Description of problem:
DBDeadlock: (pymysql.err.InternalError) (1213, u'Deadlock found when trying to get lock; try restarting transaction')

The above error is a retry-able error, but there is no evidence that keystone really did a retry before throwing a 500.

2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi [req-c7dba8f5-9269-4c6f-b3e2-9a6c43b6cf0b a8377c6c4d05430d92ac661a2319cc95 c24adc59b2d0490c930d0270a1faecb5 - default default] (pymysql.err.InternalError) (1213, u'Deadlock found when trying to get lock; try restarting transaction')
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi Traceback (most recent call last):
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 225, in __call__
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi result = method(req, **params)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/oslo_log/versionutils.py", line 174, in wrapped
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi return func_or_cls(*args, **kwargs)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/controllers.py", line 164, in delete_user
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi self.identity_api.delete_user(user_id, initiator)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/manager.py", line 124, in wrapped
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi __ret_val = __f(*args, **kwargs)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 416, in wrapper
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi return f(self, *args, **kwargs)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 426, in wrapper
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi return f(self, *args, **kwargs)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 990, in delete_user
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi driver.delete_user(entity_id)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/backends/sql.py", line 277, in delete_user
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi session.delete(ref)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi self.gen.next()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 875, in _transaction_scope
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi yield resource
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi self.gen.next()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 522, in _session
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi self._end_session_transaction(self.session)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 543, in _end_session_transaction
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi session.commit()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 813, in commit
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi self.transaction.commit()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 396, in commit
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi t[1].commit()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1574, in commit
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi self._do_commit()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1605, in _do_commit
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi self.connection._commit_impl()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 690, in _commit_impl
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi self._handle_dbapi_exception(e, None, None, None, None)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi util.raise_from_cause(newraise, exc_info)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi reraise(type(exception), exception, tb=exc_tb)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 688, in _commit_impl
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi self.engine.dialect.do_commit(self.connection)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2514, in do_commit
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi dbapi_connection.commit()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 719, in commit
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi self._read_ok_packet()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 698, in _read_ok_packet
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi pkt = self._read_packet()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 906, in _read_packet
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi packet.check_error()
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 367, in check_error
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi err.raise_mysql_exception(self._data)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/err.py", line 120, in raise_mysql_exception
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi _check_mysql_exception(errinfo)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/pymysql/err.py", line 115, in _check_mysql_exception
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi raise InternalError(errno, errorvalue)
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi DBDeadlock: (pymysql.err.InternalError) (1213, u'Deadlock found when trying to get lock; try restarting transaction')
2016-11-12 08:55:10.995 13952 ERROR keystone.common.wsgi

[Boris Bobrov (bbobrov)]

https://review.openstack.org/#/c/344924/ -- the patched fixed a similar issue, something like this should be done for identity backend too

[Samuel de Medeiros Queiroz (samueldmq)]

From the logs it is clear it was a call to delete_user.

I wonder if we should address a more general fix to all operations that need to acquire locks (write operations). From the fix Boris linked, it was an operation related to revocation events. In this case it was a delete user. Tomorrow it is going to be something different.

[Adam Young (ayoung)]

CLosing as a duplicate.

[Samuel de Medeiros Queiroz (samueldmq)]

In the other bug (https://bugs.launchpad.net/keystone/+bug/1604862), the logs show it was also related to delete_user. This one may just be a duplicate of the other bug if you do not have Newton code.

[Boris Bobrov (bbobrov)]

This is not a duplicate, the retrying code should be added to the identity driver

[Samuel de Medeiros Queiroz (samueldmq)]

Perhaps we cannot get more information from the original reporter. Neither reproduce the issue.

[Steve Martinelli (stevemar)]

We could add "@oslo_db_api.wrap_db_retry(retry_on_deadlock=True)" to "delete_user" and wrap this up quickly. Are there any other spots that need to be deadlock friendly?

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/416872

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/416872
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=e439476c1e434587122053a5c02c9ee4908e8b7c
Submitter: Jenkins
Branch: master

commit e439476c1e434587122053a5c02c9ee4908e8b7c
Author: jolie <email address hidden>
Date: Wed Jan 4 17:37:34 2017 +0800

    Retry on deadlock Transactions in backend

    Keystone does not retry on deadlock Transactions [500 Error] in
    identity backend. Add wrapper for delete_user method.

    Change-Id: I47b5aaf630505cbb08be332c0fbd54d8f56564af
    Closes-Bug:#1648542

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/keystone 11.0.0.0b3 development milestone.