sqlalchemy replies with ResourceClosedError in case of concurrent allocations of IP addresses or volume creations

[Vladimir Popovski]

It seems like usage of sqlalchemy's
    with_lockmode('update').
causes ResourceClosedError exception if there are several concurrent requests to update the DB.

We've seen it with volume creations, when volume_allocate_iscsi_target() returned it and I've succeeded to reproduce it with multiple concurrent euca-allocate-address & euca-release-address calls.

2011-09-23 22:07:24,355 ERROR nova.api [3a5ae61d-4e6a-4701-9180-ef6c49a76c61 diego nubeblog] Unexpected error raised: ResourceClosedError This result object does not return rows. It has been closed automatically.
[u'Traceback (most recent call last):\n', u' File "/mnt/share/s-cloud-Vlad/nova/rpc/impl_kombu.py", line 620, in _process_data\n rval = node_func(context=ctxt, **node_args)\n', u' File "/mnt/share/s-cloud-Vlad/nova/network/manager.py", line 279, in allocate_floating_ip\n project_id)\n', u' File "/mnt/share/s-cloud-Vlad/nova/db/api.py", line 232, in floating_ip_allocate_address\n return IMPL.floating_ip_allocate_address(context, project_id)\n', u' File "/mnt/share/s-cloud-Vlad/nova/db/sqlalchemy/api.py", line 119, in wrapper\n return f(*args, **kwargs)\n', u' File "/mnt/share/s-cloud-Vlad/nova/db/sqlalchemy/api.py", line 500, in floating_ip_allocate_address\n with_lockmode(\'update\').\\\n', u' File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 1535, in first\n ret = list(self[0:1])\n', u' File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 1444, in __getitem__\n return list(res)\n', u' File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 1708, in instances\n fetch = cursor.fetchall()\n', u' File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2493, in fetchall\n l = self.process_rows(self._fetchall_impl())\n', u' File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2462, in _fetchall_impl\n self._non_result()\n', u' File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2467, in _non_result\n "This result object does not return rows. "\n', u'ResourceClosedError: This result object does not return rows. It has been closed automatically.\n']
(nova.api): TRACE: Traceback (most recent call last):
(nova.api): TRACE: File "/mnt/share/s-cloud-Vlad/nova/api/ec2/__init__.py", line 398, in __call__
(nova.api): TRACE: result = api_request.invoke(context)
(nova.api): TRACE: File "/mnt/share/s-cloud-Vlad/nova/api/ec2/apirequest.py", line 78, in invoke
(nova.api): TRACE: result = method(context, **args)
(nova.api): TRACE: File "/mnt/share/s-cloud-Vlad/nova/api/ec2/cloud.py", line 1302, in allocate_address
(nova.api): TRACE: public_ip = self.network_api.allocate_floating_ip(context)
(nova.api): TRACE: File "/mnt/share/s-cloud-Vlad/nova/network/api.py", line 61, in allocate_floating_ip
(nova.api): TRACE: 'args': {'project_id': context.project_id}})
(nova.api): TRACE: File "/mnt/share/s-cloud-Vlad/nova/rpc/__init__.py", line 45, in call
(nova.api): TRACE: return get_impl().call(context, topic, msg)
(nova.api): TRACE: File "/mnt/share/s-cloud-Vlad/nova/rpc/impl_kombu.py", line 739, in call
(nova.api): TRACE: rv = list(rv)
(nova.api): TRACE: File "/mnt/share/s-cloud-Vlad/nova/rpc/impl_kombu.py", line 703, in __iter__
(nova.api): TRACE: raise result
(nova.api): TRACE: RemoteError: ResourceClosedError This result object does not return rows. It has been closed automatically.

or
2011-09-20 04:25:20,515 WARNING nova.volume.manager [-] Volume creation failed with traceback: <traceback object at 0x3c55878>

2011-09-20 04:25:20,643 ERROR nova.rpc [-] Exception during message handling
(nova.rpc): TRACE: Traceback (most recent call last):
(nova.rpc): TRACE: File "/mnt/share/s-cloud-Vlad/nova/rpc/impl_kombu.py", line 620, in _process_data
(nova.rpc): TRACE: rval = node_func(context=ctxt, **node_args)
(nova.rpc): TRACE: File "/mnt/share/s-cloud-Vlad/nova/volume/manager.py", line 140, in create_volume
(nova.rpc): TRACE: raise exc_info
(nova.rpc): TRACE: ResourceClosedError
(nova.rpc): TRACE:

There are several other places in db.sqlalchemy.api where with_lockmode('update') is used and it might be potentially dangerous.

The workaround for it might be to use @utils.synchronized on top of db.sqlalchemy.api methods.

Just in case, the sqlalchemy version we are using is 0.6.4. I'm not sure if newer 0.7.2 may have the same issue or not.

[Vish Ishaya (vishvananda)]

I don't remember seeing this before, and I'm wondering if there is a try catch that is getting missed in the db code because of the interaction with eventlet. Some things to try:

diff -r f30a2fa65f30 eventlet/hubs/hub.py
--- a/eventlet/hubs/hub.py Wed Jun 08 23:47:26 2011 -0700
+++ b/eventlet/hubs/hub.py Sat Sep 24 04:51:22 2011 -0700
@@ -173,7 +173,7 @@
                 cur.parent = self.greenlet
         except ValueError:
             pass # gets raised if there is a greenlet parent cycle
- clear_sys_exc_info()
+ #clear_sys_exc_info()
         return self.greenlet.switch()

     def squelch_exception(self, fileno, exc_info):

And:

https://bitbucket.org/which_linden/eventlet/pull-request/1/fix-broken-expiration-timer-for

Can you see if any of those make a difference. It would also be great to have a very simple repro case for this error to aid in testing.

[bastichelaar (bas-t)]

I just applied the fix ov bug #83851, but this doesnt solve this bug. The output when I fire up 20 instances at once:

2011-10-06 14:10:47,105 DEBUG nova.network.manager [034ad047-cc1b-48af-a00f-75b8091b8333 None None] Leased IP |10.0.0.12
ERROR nova.rpc [-] Exception during message handling
(nova.rpc): TRACE: Traceback (most recent call last):
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 620, in _process_data
(nova.rpc): TRACE: rval = node_func(context=ctxt, **node_args)
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/nova/network/manager.py", line 221, in allocate_for_instance
(nova.rpc): TRACE: ips = super(FloatingIP, self).allocate_for_instance(context, **kwargs)
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/nova/network/manager.py", line 444, in allocate_for_instance
(nova.rpc): TRACE: requested_networks=requested_networks)
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/nova/network/manager.py", line 171, in _allocate_fixed_ip
(nova.rpc): TRACE: vpn=vpn, address=address)
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/nova/network/manager.py", line 615, in allocate_fixed_ip
(nova.rpc): TRACE: instance_id)
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/nova/db/api.py", line 347, in fixed_ip_associate_pool
(nova.rpc): TRACE: instance_id, host)
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 101, in wrapper
(nova.rpc): TRACE: return f(*args, **kwargs)
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 724, in fixed_ip_association
(nova.rpc): TRACE: with_lockmode('update').\
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 1652, in first
(nova.rpc): TRACE: ret = list(self[0:1])
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 1560, in __getitem__
(nova.rpc): TRACE: return list(res)
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 1823, in instances
(nova.rpc): TRACE: fetch = cursor.fetchall()
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2528, in fetchall
(nova.rpc): TRACE: l = self.process_rows(self._fetchall_impl())
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2497, in _fetchall_impl
(nova.rpc): TRACE: self._non_result()
(nova.rpc): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2502, in _non_result
(nova.rpc): TRACE: "This result object does not return rows. "
(nova.rpc): TRACE: ResourceClosedError: This result object does not return rows. It has been closed automatically.
(nova.rpc): TRACE: