OpenStack Compute (nova)

DBDeadlock in delete_instance

Bug #1342086 reported by Joe Gordon on 2014-07-15

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Compute (nova)	Fix Released	Undecided	Joe Gordon	OpenStack Compute (nova) 2014.2 "juno"

Bug Description

2014-07-15 11:11:59.993 ERROR nova.api.openstack [req-cc826bd5-7d9a-491d-bdde-c64a70a0a630 TelemetryNotificationAPITestXML-21795205 TelemetryNotificationAPITestXML-1445201375] Caught error: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'UPDATE instances SET updated_at=updated_at, deleted_at=%s, deleted=id WHERE instances.deleted = %s AND instances.uuid = %s AND instances.host IS NULL' (datetime.datetime(2014, 7, 15, 11, 11, 59, 979427), 0, 'bbb916b2-9854-4c5e-9687-515352f3e4df')
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack Traceback (most recent call last):
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/__init__.py", line 125, in __call__
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return req.get_response(self.application)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack application, catch_exc_info=False)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack app_iter = application(self.environ, start_response)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return resp(environ, start_response)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 661, in __call__
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return self._app(env, start_response)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return resp(environ, start_response)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return resp(environ, start_response)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack response = self.app(environ, start_response)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return resp(environ, start_response)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return self.func(req, *args, **kwargs)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 906, in __call__
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack content_type, body, accept)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 972, in _process_stack
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack action_result = self.dispatch(meth, request, action_args)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 1056, in dispatch
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return method(req=request, **action_args)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/compute/servers.py", line 1201, in delete
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack self._delete(req.environ['nova.context'], req, id)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/compute/servers.py", line 1030, in _delete
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack self.compute_api.delete(context, instance)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 192, in wrapped
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return func(self, context, target, *args, **kwargs)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 182, in inner
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return function(self, context, instance, *args, **kwargs)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 209, in _wrapped
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return fn(self, context, instance, *args, **kwargs)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 163, in inner
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return f(self, context, instance, *args, **kw)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 1719, in delete
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack self._delete_instance(context, instance)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 1709, in _delete_instance
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack task_state=task_states.DELETING)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 1543, in _delete
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack user_id=user_id)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 82, in __exit__
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack six.reraise(self.type_, self.value, self.tb)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 1480, in _delete
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack instance.destroy()
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/objects/base.py", line 196, in wrapper
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return fn(self, ctxt, *args, **kwargs)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/objects/instance.py", line 358, in destroy
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack constraint=constraint)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/db/api.py", line 664, in instance_destroy
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack rv = IMPL.instance_destroy(context, instance_uuid, constraint)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 164, in wrapper
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack return f(*args, **kwargs)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 1688, in instance_destroy
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack count = query.soft_delete()
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/openstack/common/db/sqlalchemy/session.py", line 694, in soft_delete
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack synchronize_session=synchronize_session)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2690, in update
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack update_op.exec_()
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 816, in exec_
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack self._do_exec()
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 913, in _do_exec
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack update_stmt, params=self.query._params)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/openstack/common/db/sqlalchemy/session.py", line 444, in _wrap
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack _raise_if_deadlock_error(e, self.bind.dialect.name)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/openstack/common/db/sqlalchemy/session.py", line 427, in _raise_if_deadlock_error
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack raise exception.DBDeadlock(operational_error)
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack DBDeadlock: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'UPDATE instances SET updated_at=updated_at, deleted_at=%s, deleted=id WHERE instances.deleted = %s AND instances.uuid = %s AND instances.host IS NULL' (datetime.datetime(2014, 7, 15, 11, 11, 59, 979427), 0, 'bbb916b2-9854-4c5e-9687-515352f3e4df')
2014-07-15 11:11:59.993 20784 TRACE nova.api.openstack

http://logs.openstack.org/62/100162/3/check/check-tempest-dsvm-full/77badd4/logs/screen-n-api.txt.gz?level=INFO#_2014-07-15_11_11_59_993

Discovered in the check queue.

query: message:"Deadlock found when trying to get lock" AND message:"UPDATE instances SET" AND NOT tags:"console.html"

9 hits in last 10 days.

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-07-15: Fix proposed to nova (master)

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

Changed in nova:
assignee:	nobody → Joe Gordon (jogo)
status:	New → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-07-17: Fix merged to nova (master)

Reviewed: https://review.openstack.org/107025
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=44f8f1e93f21275311d1eab0c93a2834395c2365
Submitter: Jenkins
Branch: master

commit 44f8f1e93f21275311d1eab0c93a2834395c2365
Author: Joe Gordon <email address hidden>
Date: Tue Jul 15 14:19:01 2014 +0200

Retry db.api.instance_destroy on deadlock

    Update the instance_destroy method of the sqlalchemy db API to retry if
    it fails because of a deadlock. The decorator that handles this was
    introduced in I0293c62d2dd5ac036445bc639cabbd05ba016e83.

This patch does not include a unit test for this bug, as deadlocks are
very hard to reproduce.

Change-Id: I570d91e892a6e1ff4b3cdb8cf81acc483649835e
Closes-Bug: #1342086

Changed in nova:
status:	In Progress → Fix Committed

Russell Bryant (russellb) on 2014-07-23

Changed in nova:
milestone:	none → juno-2
status:	Fix Committed → Fix Released

Thierry Carrez (ttx) on 2014-10-16

Changed in nova:
milestone:	juno-2 → 2014.2

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

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