OpenStack Compute (nova)

Quota leakage issue

Bug #1297590 reported by Aaron Rosen
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
New
Undecided
Unassigned

Bug Description

In our havana cloud if one deletes a large number of instances at once ~200 the instances get deleted but the quota is never restored back to 0. The following exception is raise on the nova-api node:

2014-03-25 17:35:06.024 24528 DEBUG nova.quota [req-a94c090b-ea52-4314-a368-108bc615424e cherkasj 37af63b6867d4fe38ac312ca626ce186] Rolled back reservations ['c869b47a-8d6f-4f05-b909-eff006856692', '50cf4dc3-1922-419e-9760-b82f9dcf889c', '4c380ba5-1b99-4f6b-83c4-506416538c41'] rollback /usr/lib/python2.7/dist-packages/nova/quota.py:1322
2014-03-25 17:35:06.025 24528 ERROR nova.api.openstack [req-a94c090b-ea52-4314-a368-108bc615424e cherkasj 37af63b6867d4fe38ac312ca626ce186] Caught error: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') None None
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack Traceback (most recent call last):
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/api/openstack/__init__.py", line 119, in __call__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     return req.get_response(self.application)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1296, in send
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     application, catch_exc_info=False)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1260, in call_application
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     return resp(environ, start_response)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py", line 539, in __call__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     return self.app(env, start_response)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     return resp(environ, start_response)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     return resp(environ, start_response)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     response = self.app(environ, start_response)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     return resp(environ, start_response)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line 938, in __call__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     content_type, body, accept)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line 997, in _process_stack
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line 1078, in dispatch
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     return method(req=request, **action_args)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/api/openstack/compute/servers.py", line 920, in create
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     legacy_bdm=legacy_bdm)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/hooks.py", line 105, in inner
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 1222, in create
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     legacy_bdm=legacy_bdm)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 876, in _create_instance
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     block_device_mapping)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 781, in _provision_instances
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     QUOTAS.rollback(context, quota_reservations)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 762, in _provision_instances
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     num_instances, i)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 1155, in create_db_entry_for_new_instance
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     instance_type, image, block_device_mapping)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 1047, in _populate_instance_for_bdm
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     instance_type, instance_uuid, mapping)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 963, in _update_block_device_mapping
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     legacy=False)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/db/api.py", line 1160, in block_device_mapping_update_or_create
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     return IMPL.block_device_mapping_update_or_create(context, values, legacy)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 3520, in block_device_mapping_update_or_create
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     return result
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 447, in __exit__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     self.rollback()
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 58, in __exit__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     compat.reraise(exc_type, exc_value, exc_tb)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 444, in __exit__
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     self.commit()
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 358, in commit
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     t[1].commit()
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1195, in commit
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     self._do_commit()
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1226, in _do_commit
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     self.connection._commit_impl()
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 491, in _commit_impl
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     self._handle_dbapi_exception(e, None, None, None, None)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1024, in _handle_dbapi_exception
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     exc_info
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 195, in raise_from_cause
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     reraise(type(exception), exception, tb=exc_tb)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 488, in _commit_impl
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     self.engine.dialect.do_commit(self.connection)
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack   File "/usr/lib/python2.7/dist-packages/sqlalchemy/dialects/mysql/base.py", line 1961, in do_commit
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack     dbapi_connection.commit()
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack OperationalError: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') None None
2014-03-25 17:35:06.025 24528 TRACE nova.api.openstack
2014-03-25 17:35:06.036 24528 INFO nova.api.openstack [req-a94c090b-ea52-4314-a368-108bc615424e cherkasj 37af63b6867d4fe38ac312ca626ce186] http://10.34.210.70:8774/v2/37af63b6867d4fe38ac312ca626ce186/servers returned with HTTP 500
2014-03-25 17:35:06.038 24528 DEBUG nova.api.openstack.wsgi [req-a94c090b-ea52-4314-a368-108bc615424e cherkasj 37af63b6867d4fe38ac312ca626ce186] Returning 500 to user: The server has either erred or is incapable of performing the requested operation. __call__ /usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py:1224
2014-03-25 17:35:06.039 24528 INFO nova.osapi_compute.wsgi.server [req-a94c090b-ea52-4314-a368-108bc615424e cherkasj 37af63b6867d4fe38ac312ca626ce186] 10.34.208.21,10.34.208.11 "POST /v2/37af63b6867d4fe38ac312ca626ce186/servers HTTP/1.1" status: 500 len: 335 time: 22.9382100

2014-03-25 17:35:06.287 24529 INFO nova.metadata.wsgi.server [-] (24529) accepted ('10.34.208.11', 41143)

Tags: db quotas
Aaron Rosen (arosen)
tags: added: db
Matt Riedemann (mriedem)
tags: added: quotas
Revision history for this message
Matt Riedemann (mriedem) wrote :

Seeing a similar deadlock on the old side of grenade which would be stable/icehouse now:

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

This is in a security group test but I'm not sure that matters.

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

There should be a retry on deadlock via bug 1193199 which is pretty old.

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

Opened bug 1350064 for the grenade race.

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

Other bug subscribers

Remote bug watches

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