yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1445910] Re: icehouse side of gate-grenade-dsvm fails with DB DeadlockError

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: "Davanum Srinivas \(DIMS\)" <davanum@xxxxxxxxx>
Date: Fri, 07 Aug 2015 20:46:46 -0000
Reply-to: Bug 1445910 <1445910@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
No more icehouse? :)

** Changed in: nova
       Status: Confirmed => Won't Fix

-- 
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/1445910

Title:
  icehouse side of gate-grenade-dsvm fails with DB DeadlockError

Status in OpenStack Compute (nova):
  Won't Fix

Bug description:
  http://logs.openstack.org/82/169782/1/gate/gate-grenade-
  dsvm/2a8368a/logs/old/screen-n-api.txt.gz?level=TRACE#_2015-04-19_08_12_21_956

  This was on a stable/juno change on the 'old' side of grenade which
  makes it a bug in stable/icehouse.

  2015-04-19 08:12:21.956 ERROR nova.api.openstack [req-a219c0d8-7673-44bd-ae72-571f8be64b8f SecurityGroupsTestJSON-1312385593 SecurityGroupsTestJSON-980401254] 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, 'a8f89a08d351453aa676a1db6308a0b8')
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack Traceback (most recent call last):
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/api/openstack/__init__.py", line 125, in __call__
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return req.get_response(self.application)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     application, catch_exc_info=False)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return resp(environ, start_response)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/local/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py", line 687, in __call__
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return self.app(env, start_response)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return resp(environ, start_response)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return resp(environ, start_response)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/local/lib/python2.7/dist-packages/routes/middleware.py", line 136, in __call__
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     response = self.app(environ, start_response)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return resp(environ, start_response)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/api/openstack/wsgi.py", line 919, in __call__
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     content_type, body, accept)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/api/openstack/wsgi.py", line 985, in _process_stack
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/api/openstack/wsgi.py", line 1072, in dispatch
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return method(req=request, **action_args)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/api/openstack/compute/contrib/security_groups.py", line 330, in create
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     context, group_name, group_description)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/compute/api.py", line 3627, in create_security_group
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     reservations = QUOTAS.reserve(context, security_groups=1)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/quota.py", line 1270, in reserve
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     user_id=user_id)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/quota.py", line 513, in reserve
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     project_id=project_id, user_id=user_id)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/db/api.py", line 1105, in quota_reserve
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     project_id=project_id, user_id=user_id)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 164, in wrapper
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return f(*args, **kwargs)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 202, in wrapped
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return f(*args, **kwargs)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 3076, in quota_reserve
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     context, session, project_id, user_id)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 3044, in _get_project_user_quota_usages
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     with_lockmode('update').\
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2241, in all
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return list(self)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2353, in __iter__
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     return self._execute_and_instances(context)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2368, in _execute_and_instances
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     result = conn.execute(querycontext.statement, self._params)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 662, in execute
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     params)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 761, in _execute_clauseelement
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     compiled_sql, distilled_params
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 874, in _execute_context
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     context)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1024, in _handle_dbapi_exception
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     exc_info
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 196, in raise_from_cause
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     reraise(type(exception), exception, tb=exc_tb)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 867, in _execute_context
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     context)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 324, in do_execute
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     cursor.execute(statement, parameters)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     self.errorhandler(self, exc, value)
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack     raise errorclass, errorvalue
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack OperationalError: (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, 'a8f89a08d351453aa676a1db6308a0b8')
  2015-04-19 08:12:21.956 11178 TRACE nova.api.openstack 

  Looks like it only shows up on this change, so pretty infrequent:

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

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

[Bug 1445910] [NEW] icehouse side of gate-grenade-dsvm fails with DB DeadlockError
From: Matt Riedemann, 2015-04-19