DB Deadlock creating volume

Bug #1343274 reported by Matthew Booth
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Cinder
Fix Released
High
Unassigned

Bug Description

Tempest failure. Full context here: http://logs.openstack.org/49/104149/10/check/check-tempest-dsvm-full/a75743a/

Relevant failure:

2014-07-17 11:54:52.407 25905 ERROR cinder.api.middleware.fault [req-5f7b49a3-fc67-41ff-93c1-389b0bc8da09 d19b002e1df14c949e99ef3d9f19cc1d aacf3cb31f9e47ae84766db0be9ed63f - - -] Caught error: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'INSERT INTO quota_usages (created_at, updated_at, deleted_at, deleted, project_id, resource, in_use, reserved, until_refresh) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s)' (datetime.datetime(2014, 7, 17, 11, 54, 52, 387164), None, None, 0, 'aacf3cb31f9e47ae84766db0be9ed63f', 'gigabytes', 0, 0, None)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault Traceback (most recent call last):
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/api/middleware/fault.py", line 75, in __call__
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault return req.get_response(self.application)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault application, catch_exc_info=False)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault app_iter = application(self.environ, start_response)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 663, in __call__
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault return self.app(env, start_response)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault response = self.app(environ, start_response)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault resp = self.call_func(req, *args, **self.kwargs)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault return self.func(req, *args, **kwargs)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/api/openstack/wsgi.py", line 895, in __call__
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault content_type, body, accept)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/api/openstack/wsgi.py", line 943, in _process_stack
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault action_result = self.dispatch(meth, request, action_args)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/api/openstack/wsgi.py", line 1019, in dispatch
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault return method(req=request, **action_args)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/api/v1/volumes.py", line 386, in create
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault **kwargs)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/volume/api.py", line 210, in create
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault flow_engine.run()
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 89, in run
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault for _state in self.run_iter():
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 137, in run_iter
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault misc.Failure.reraise_if_any(failures.values())
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/taskflow/utils/misc.py", line 681, in reraise_if_any
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault failures[0].reraise()
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/taskflow/utils/misc.py", line 688, in reraise
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault six.reraise(*self._exc_info)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 34, in _execute_task
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault result = task.execute(**arguments)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/volume/flows/api/create_volume.py", line 494, in execute
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault reservations = QUOTAS.reserve(context, **reserve_opts)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/quota.py", line 747, in reserve
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault project_id=project_id)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/quota.py", line 357, in reserve
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault project_id=project_id)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/db/api.py", line 734, in quota_reserve
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault until_refresh, max_age, project_id=project_id)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/db/sqlalchemy/api.py", line 161, in wrapper
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault return f(*args, **kwargs)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/db/sqlalchemy/api.py", line 725, in quota_reserve
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault session=session)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/db/sqlalchemy/api.py", line 143, in wrapper
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault return f(*args, **kwargs)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/db/sqlalchemy/api.py", line 660, in _quota_usage_create
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault quota_usage_ref.save(session=session)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/openstack/common/db/sqlalchemy/models.py", line 49, in save
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault session.flush()
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/openstack/common/db/sqlalchemy/session.py", line 444, in _wrap
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault _raise_if_deadlock_error(e, self.bind.dialect.name)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/openstack/common/db/sqlalchemy/session.py", line 427, in _raise_if_deadlock_error
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault raise exception.DBDeadlock(operational_error)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault DBDeadlock: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'INSERT INTO quota_usages (created_at, updated_at, deleted_at, deleted, project_id, resource, in_use, reserved, until_refresh) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s)' (datetime.datetime(2014, 7, 17, 11, 54, 52, 387164), None, None, 0, 'aacf3cb31f9e47ae84766db0be9ed63f', 'gigabytes', 0, 0, None)
2014-07-17 11:54:52.407 25905 TRACE cinder.api.middleware.fault

Tags: db
Revision history for this message
haruka tanizawa (h-tanizawa) wrote :
Revision history for this message
Matt Riedemann (mriedem) wrote :

In this bug it's doing an INSERT operation, in bug 1294855 it's doing a SELECT operation, so slightly different, but both are failing when dealing with the quota_usages table.

The DB API code there probably needs to be updated based on whatever nova is doing with the same table.

Note that we recently turned on multiple cinder-api workers by default in Juno so that might also indicate why we're seeing it now in Jenkins runs.

http://logs.openstack.org/85/105485/5/gate/gate-tempest-dsvm-full/9fb6aa7/logs/screen-c-api.txt.gz#_2014-07-25_12_24_28_332

Changed in cinder:
status: New → Confirmed
tags: added: db
Changed in cinder:
importance: Undecided → High
Revision history for this message
Matt Riedemann (mriedem) wrote :
Revision history for this message
Matt Riedemann (mriedem) wrote :

Going back 2 weeks in logstash, it appears this creeped up on 7/16.

Revision history for this message
Matt Riedemann (mriedem) wrote :
Revision history for this message
Matt Riedemann (mriedem) wrote :

I'm not seeing much that merged in cinder or tempest on 7/16 that looks related to this, but maybe this change to devstack is playing a part:

https://github.com/openstack-dev/devstack/commit/7062b12b9b91a1eb405d7079c62b62b0de59109f

Revision history for this message
Joe Gordon (jogo) wrote :

looks like this was resolved

Changed in cinder:
status: Confirmed → Fix Committed
Thierry Carrez (ttx)
Changed in cinder:
milestone: none → juno-3
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in cinder:
milestone: juno-3 → 2014.2
Revision history for this message
Shu Shen (shu-shen) wrote :

For whom might be interested or affected and need cherry-pick, the fix appears to be https://review.openstack.org/#/c/111410/. And this might be a duplicate of https://bugs.launchpad.net/nova/+bug/1350466 (which also affects nova).

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.