openstack team mailing list archive

[Vladimir Popovski <vladimir@xxxxxxxxxxxxxxxxx>]

Alex et al,



I’ve succeeded to reproduce this problem by issuing multiple concurrent
euca-allocate-address & euca-release-address calls.



Here is one of traces from nova-api.log:



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.





The problem seems to be related to .with_lockmode('update') functionality of
sqlalchemy. It seems to raise ResourceClosedError exception if several
threads are trying to perform the same operation on the DB instead of
waiting on it.



Regards,

-Vladimir





*From:* Alex Lyakas [mailto:alex@xxxxxxxxxxxxxxxxx]
*Sent:* Wednesday, September 21, 2011 5:27 AM
*To:* openstack@xxxxxxxxxxxxxxxxxxx
*Cc:* Yair Hershko; Vladimir Popovsky
*Subject:* volume_allocate_iscsi_target in db/sqlalchemy/api.py hits
ResourceClosedError



Greetings everybody,

in one of our tests we occasionally hit

ResourceClosedError when executing the volume_allocate_iscsi_target:



2011-09-20 04:25:20,515 DEBUG nova.volume.driver [-]
volume_allocate_iscsi_target failed for volume volume-0000114c from
(pid=23701) create_export /mnt/share/s-cloud-Vlad/nova/volume/driver.py:959



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:



In one of the tests it happened at the same time on three different compute
nodes.

Can anybody pls advise how to investigate the root cause of this problem?
The MySQL server logs do not show anything useful at the time of the
problem.



Thanks,

  Alex.