[...]
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/nova/api/openstack/compute/servers.py", line 707, in create
2012-07-16 22:16:03 TRACE nova.api.openstack scheduler_hints=scheduler_hints)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/nova/compute/api.py", line 780, in create
2012-07-16 22:16:03 TRACE nova.api.openstack scheduler_hints=scheduler_hints)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/nova/compute/api.py", line 372, in _create_instance
2012-07-16 22:16:03 TRACE nova.api.openstack context, instance_type, min_count, max_count)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/nova/compute/api.py", line 178, in _check_num_instances_quota
2012-07-16 22:16:03 TRACE nova.api.openstack cores=req_cores, ram=req_ram)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/nova/quota.py", line 695, in reserve
2012-07-16 22:16:03 TRACE nova.api.openstack expire=expire)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/nova/quota.py", line 338, in reserve
2012-07-16 22:16:03 TRACE nova.api.openstack FLAGS.until_refresh, FLAGS.max_age)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/nova/db/api.py", line 1050, in quota_reserve
2012-07-16 22:16:03 TRACE nova.api.openstack until_refresh, max_age)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/nova/db/sqlalchemy/api.py", line 132, in wrapper
2012-07-16 22:16:03 TRACE nova.api.openstack return f(*args, **kwargs)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/nova/db/sqlalchemy/api.py", line 2584, in quota_reserve
2012-07-16 22:16:03 TRACE nova.api.openstack usages = _get_quota_usages(context, session, deltas.keys())
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/nova/db/sqlalchemy/api.py", line 2572, in _get_quota_usages
2012-07-16 22:16:03 TRACE nova.api.openstack with_lockmode('update').\
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/query.py", line 1729, in all
2012-07-16 22:16:03 TRACE nova.api.openstack return list(self)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/query.py", line 1953, in instances
2012-07-16 22:16:03 TRACE nova.api.openstack fetch = cursor.fetchall()
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 2979, in fetchall
2012-07-16 22:16:03 TRACE nova.api.openstack l = self.process_rows(self._fetchall_impl())
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 2948, in _fetchall_impl
2012-07-16 22:16:03 TRACE nova.api.openstack self._non_result()
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 2953, in _non_result
2012-07-16 22:16:03 TRACE nova.api.openstack "This result object does not return rows. "
2012-07-16 22:16:03 TRACE nova.api.openstack ResourceClosedError: This result object does not return rows. It has been closed automatically.
However, the real bug is a deadlock (hidden by the aforementioned SQLAlchemy bug), which should show as an OperationError similar to this:
"Deadlock found when trying to get lock; try restarting transaction"
The problem is a result of the quota_reserve code acquiring the quota_usages lock before the reservations lock, whereas quota_commit and quota_rollback acquire the locks in reverse order.
The quota reservations code acquires SQL locks inconsistently which can result in a deadlock.
Because of a bug in SQLAlchemy (http:// www.sqlalchemy. org/trac/ ticket/ 2536) it can result in this exception:
[...] python2. 6/dist- packages/ nova/api/ openstack/ compute/ servers. py", line 707, in create hints=scheduler _hints) python2. 6/dist- packages/ nova/compute/ api.py" , line 780, in create hints=scheduler _hints) python2. 6/dist- packages/ nova/compute/ api.py" , line 372, in _create_instance python2. 6/dist- packages/ nova/compute/ api.py" , line 178, in _check_ num_instances_ quota python2. 6/dist- packages/ nova/quota. py", line 695, in reserve python2. 6/dist- packages/ nova/quota. py", line 338, in reserve refresh, FLAGS.max_age) python2. 6/dist- packages/ nova/db/ api.py" , line 1050, in quota_reserve python2. 6/dist- packages/ nova/db/ sqlalchemy/ api.py" , line 132, in wrapper python2. 6/dist- packages/ nova/db/ sqlalchemy/ api.py" , line 2584, in quota_reserve usages( context, session, deltas.keys()) python2. 6/dist- packages/ nova/db/ sqlalchemy/ api.py" , line 2572, in _get_quota_usages 'update' ).\ python2. 6/dist- packages/ sqlalchemy/ orm/query. py", line 1729, in all python2. 6/dist- packages/ sqlalchemy/ orm/query. py", line 1953, in instances python2. 6/dist- packages/ sqlalchemy/ engine/ base.py" , line 2979, in fetchall rows(self. _fetchall_ impl()) python2. 6/dist- packages/ sqlalchemy/ engine/ base.py" , line 2948, in _fetchall_impl python2. 6/dist- packages/ sqlalchemy/ engine/ base.py" , line 2953, in _non_result rror: This result object does not return rows. It has been closed automatically.
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack scheduler_
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack scheduler_
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack context, instance_type, min_count, max_count)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack cores=req_cores, ram=req_ram)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack expire=expire)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack FLAGS.until_
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack until_refresh, max_age)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack return f(*args, **kwargs)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack usages = _get_quota_
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack with_lockmode(
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack return list(self)
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack fetch = cursor.fetchall()
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack l = self.process_
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack self._non_result()
2012-07-16 22:16:03 TRACE nova.api.openstack File "/usr/lib/
2012-07-16 22:16:03 TRACE nova.api.openstack "This result object does not return rows. "
2012-07-16 22:16:03 TRACE nova.api.openstack ResourceClosedE
However, the real bug is a deadlock (hidden by the aforementioned SQLAlchemy bug), which should show as an OperationError similar to this:
"Deadlock found when trying to get lock; try restarting transaction"
The problem is a result of the quota_reserve code acquiring the quota_usages lock before the reservations lock, whereas quota_commit and quota_rollback acquire the locks in reverse order.