OpenStack Compute (nova)

Deadlock in quota reservations in security groups tests on old side of grenade (icehouse)

Bug #1350064 reported by Matt Riedemann
22
This bug affects 4 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Medium
Unassigned
OpenStack Compute (nova) 2014.2 "juno"

Bug Description

http://logs.openstack.org/60/109660/7/check/check-grenade-dsvm-partial-ncpu/deb4b82/logs/old/screen-n-api.txt.gz#_2014-07-28_19_59_01_933

2014-07-28 19:59:01.933 ERROR nova.api.openstack [req-6907415f-1dd8-4bb3-9e63-d007c5afc6a7 SecurityGroupsTestAdminXML-687258929 SecurityGroupsTestAdminXML-417284851] Caught error: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'SELECT quota_usages.created_at AS quota_usages_created_at, quota_usages.updated_at AS quota_usages_updated_at, quota_usages.deleted_at AS quota_usages_deleted_at, quota_usages.deleted AS quota_usages_deleted, quota_usages.id AS quota_usages_id, quota_usages.project_id AS quota_usages_project_id, quota_usages.user_id AS quota_usages_user_id, quota_usages.resource AS quota_usages_resource, quota_usages.in_use AS quota_usages_in_use, quota_usages.reserved AS quota_usages_reserved, quota_usages.until_refresh AS quota_usages_until_refresh \nFROM quota_usages \nWHERE quota_usages.deleted = %s AND quota_usages.project_id = %s FOR UPDATE' (0, 'ed64e6649d0840d5b9bb61189e50a675')
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack Traceback (most recent call last):
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/api/openstack/__init__.py", line 125, in __call__
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return req.get_response(self.application)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack application, catch_exc_info=False)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack app_iter = application(self.environ, start_response)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return resp(environ, start_response)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 663, in __call__
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return self.app(env, start_response)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return resp(environ, start_response)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return resp(environ, start_response)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack response = self.app(environ, start_response)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return resp(environ, start_response)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return self.func(req, *args, **kwargs)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/api/openstack/wsgi.py", line 917, in __call__
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack content_type, body, accept)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/api/openstack/wsgi.py", line 983, in _process_stack
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack action_result = self.dispatch(meth, request, action_args)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/api/openstack/wsgi.py", line 1070, in dispatch
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return method(req=request, **action_args)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/api/openstack/compute/contrib/security_groups.py", line 330, in create
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack context, group_name, group_description)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/compute/api.py", line 3595, in create_security_group
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack reservations = QUOTAS.reserve(context, security_groups=1)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/quota.py", line 1270, in reserve
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack user_id=user_id)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/quota.py", line 513, in reserve
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack project_id=project_id, user_id=user_id)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/db/api.py", line 1105, in quota_reserve
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack project_id=project_id, user_id=user_id)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 164, in wrapper
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return f(*args, **kwargs)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 202, in wrapped
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return f(*args, **kwargs)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 3066, in quota_reserve
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack context, session, project_id, user_id)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 3034, in _get_project_user_quota_usages
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack with_lockmode('update').\
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2241, in all
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return list(self)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2353, in __iter__
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack return self._execute_and_instances(context)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2368, in _execute_and_instances
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack result = conn.execute(querycontext.statement, self._params)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 662, in execute
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack params)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 761, in _execute_clauseelement
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack compiled_sql, distilled_params
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 874, in _execute_context
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack context)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1024, in _handle_dbapi_exception
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack exc_info
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 196, in raise_from_cause
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack reraise(type(exception), exception, tb=exc_tb)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 867, in _execute_context
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack context)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 324, in do_execute
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack cursor.execute(statement, parameters)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack self.errorhandler(self, exc, value)
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2014-07-28 19:59:01.933 2641 TRACE nova.api.openstack raise errorclass, errorvalue

Looks like when this fails it's in the partial grenade jobs in the old side of grenade, so we haven't gotten to the upgrade (if I understand grenade correctly) so could just be a latent bug in icehouse.

It does look like it's racing in concurrent tests because it's the xml tests that are failing, which could be due to running smoke tests in grenade, but sdague would know more about that or would implications it has in how the tests run.

Here is a reasonable logstash query:

message:"SecurityGroupsTestAdminXML" AND message:"Deadlock found when trying to get lock; try restarting transaction" AND tags:"screen-n-api.txt" AND (build_name:"check-grenade-dsvm-partial-ncpu" OR build_name:"gate-grenade-dsvm-partial-ncpu")

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiRGVhZGxvY2sgZm91bmQgd2hlbiB0cnlpbmcgdG8gZ2V0IGxvY2s7IHRyeSByZXN0YXJ0aW5nIHRyYW5zYWN0aW9uXCIgQU5EIHRhZ3M6XCJzY3JlZW4tbi1hcGkudHh0XCIgQU5EIChidWlsZF9uYW1lOlwiY2hlY2stZ3JlbmFkZS1kc3ZtLXBhcnRpYWwtbmNwdVwiIE9SIGJ1aWxkX25hbWU6XCJnYXRlLWdyZW5hZGUtZHN2bS1wYXJ0aWFsLW5jcHVcIikiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0MDY2NzEzOTM3MDcsIm1vZGUiOiIiLCJhbmFseXplX2ZpZWxkIjoiIn0=

That shows 12 hits in 7 days.

This could be related to bug 1297590 and there is history in bug 1193199.

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

e-r query: https://review.openstack.org/#/c/110481/

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

looks like this is happening on partial-ncpu only

Revision history for this message
Vish Ishaya (vishvananda) wrote :

pretty sure this is bug 1283987

Revision history for this message
Vish Ishaya (vishvananda) wrote :

Fixing this will probably require backporting https://review.openstack.org/#/c/105891/ to stable/icehouse which could be quite tricky

Tracy Jones (tjones-i)
tags: added: testing
Revision history for this message
Joe Gordon (jogo) wrote :

I see no hits for this bug anymore, so it looks like it has been fixed.

Changed in nova:
status: New → Fix Committed
importance: Undecided → Medium
Thierry Carrez (ttx)
Changed in nova:
milestone: none → juno-rc1
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in nova:
milestone: juno-rc1 → 2014.2
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Subscribing...

Other bug subscribers

Remote bug watches

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