yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1350064] Re: Deadlock in quota reservations in security groups tests on old side of grenade (icehouse)

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Thierry Carrez <thierry.carrez+lp@xxxxxxxxx>
Date: Wed, 01 Oct 2014 07:43:33 -0000
Reply-to: Bug 1350064 <1350064@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: nova
       Status: Fix Committed => Fix Released

** Changed in: nova
    Milestone: None => juno-rc1

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

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

Status in OpenStack Compute (Nova):
  Fix Released

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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1350064/+subscriptions
References

[Bug 1350064] [NEW] Deadlock in quota reservations in security groups tests on old side of grenade (icehouse)
From: Matt Riedemann, 2014-07-29