Cinder

'ResourceClosedError: This result object does not return rows. It has been closed automatically.' even with MySQL-python (1.2.5)

Bug #1430641 reported by Sam Wan
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Cinder
New
Undecided
Unassigned

Bug Description

In our Openstack CI, we met this issue from time to time and we installed the latest MySQL-python package
---------------------------------------------------
# pip list|grep MySQL-python
MySQL-python (1.2.5)
--------------------------------------------------

Detailed cinder TRACE log:
------------------------------
2015-03-09 06:11:37.815 19433 CRITICAL cinder [req-dcc07bbd-8e9b-4a36-b71e-4a118a59d378 - - - - -] ResourceClosedError: This result object does not return rows. It has been closed automatically.
2015-03-09 06:11:37.815 19433 TRACE cinder Traceback (most recent call last):
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/bin/cinder-volume", line 10, in <module>
2015-03-09 06:11:37.815 19433 TRACE cinder sys.exit(main())
2015-03-09 06:11:37.815 19433 TRACE cinder File "/opt/stack/new/cinder/cinder/cmd/volume.py", line 72, in main
2015-03-09 06:11:37.815 19433 TRACE cinder binary='cinder-volume')
2015-03-09 06:11:37.815 19433 TRACE cinder File "/opt/stack/new/cinder/cinder/service.py", line 245, in create
2015-03-09 06:11:37.815 19433 TRACE cinder service_name=service_name)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/opt/stack/new/cinder/cinder/service.py", line 128, in __init__
2015-03-09 06:11:37.815 19433 TRACE cinder *args, **kwargs)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/opt/stack/new/cinder/cinder/volume/manager.py", line 190, in __init__
2015-03-09 06:11:37.815 19433 TRACE cinder context.get_admin_context())
2015-03-09 06:11:37.815 19433 TRACE cinder File "/opt/stack/new/cinder/cinder/volume/manager.py", line 263, in _set_voldb_empty_at_startup_indicator
2015-03-09 06:11:37.815 19433 TRACE cinder vol_entries = self.db.volume_get_all(ctxt, None, 1, filters=None)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/opt/stack/new/cinder/cinder/db/api.py", line 186, in volume_get_all
2015-03-09 06:11:37.815 19433 TRACE cinder sort_dirs=sort_dirs, filters=filters)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/opt/stack/new/cinder/cinder/db/sqlalchemy/api.py", line 159, in wrapper
2015-03-09 06:11:37.815 19433 TRACE cinder return f(*args, **kwargs)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/opt/stack/new/cinder/cinder/db/sqlalchemy/api.py", line 1216, in volume_get_all
2015-03-09 06:11:37.815 19433 TRACE cinder return query.all()
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2320, in all
2015-03-09 06:11:37.815 19433 TRACE cinder return list(self)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2438, in __iter__
2015-03-09 06:11:37.815 19433 TRACE cinder return self._execute_and_instances(context)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2451, in _execute_and_instances
2015-03-09 06:11:37.815 19433 TRACE cinder close_with_result=True)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2442, in _connection_from_session
2015-03-09 06:11:37.815 19433 TRACE cinder **kw)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 854, in connection
2015-03-09 06:11:37.815 19433 TRACE cinder close_with_result=close_with_result)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 858, in _connection_for_bind
2015-03-09 06:11:37.815 19433 TRACE cinder return self.transaction._connection_for_bind(engine)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 322, in _connection_for_bind
2015-03-09 06:11:37.815 19433 TRACE cinder conn = bind.contextual_connect()
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/compat/handle_error.py", line 210, in contextual_connect
2015-03-09 06:11:37.815 19433 TRACE cinder **kwargs)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 85, in __init__
2015-03-09 06:11:37.815 19433 TRACE cinder self.dispatch.engine_connect(self, _branch)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/event/attr.py", line 260, in __call__
2015-03-09 06:11:37.815 19433 TRACE cinder fn(*args, **kw)
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/session.py", line 334, in _connect_ping_listener
2015-03-09 06:11:37.815 19433 TRACE cinder connection.scalar(select([1]))
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 659, in scalar
2015-03-09 06:11:37.815 19433 TRACE cinder return self.execute(object, *multiparams, **params).scalar()
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/result.py", line 857, in scalar
2015-03-09 06:11:37.815 19433 TRACE cinder row = self.first()
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/result.py", line 834, in first
2015-03-09 06:11:37.815 19433 TRACE cinder self._non_result()
2015-03-09 06:11:37.815 19433 TRACE cinder File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/result.py", line 755, in _non_result
2015-03-09 06:11:37.815 19433 TRACE cinder "This result object does not return rows. "
2015-03-09 06:11:37.815 19433 TRACE cinder ResourceClosedError: This result object does not return rows. It has been closed automatically.
2015-03-09 06:11:37.815 19433 TRACE cinder
2015-03-09 06:11:37.903 19476 INFO cinder.openstack.common.service [-] Parent process has died unexpectedly, exiting

Revision history for this message
Jin Liu (jin-t) wrote :

Some idea cross my mind, I saw a test case "test_graceful_fetch_on_non_rows" in sqlalchemy/test/sql/test_query.py as below,
I am guessing whether in your cinder db there are records in table "volumes". Logs you posted looks like querying volumes in volume_get_all, this happens when cinder audit running periodically. Maybe when there are no volumes, we will see such exception logs.

def test_graceful_fetch_on_non_rows(self):
"""test that calling fetchone() etc. on a result that doesn't
        return rows fails gracefully.
"""
        conn = testing.db.connect()
        for meth in ('fetchone', 'fetchall', 'first', 'scalar', 'fetchmany'):
            trans = conn.begin()
            result = conn.execute(users.insert(), user_id=1)
            assert_raises_message(
                exc.ResourceClosedError,
                "This result object does not return rows. "
                "It has been closed automatically.",
                getattr(result, meth),
            )
            trans.rollback()

Revision history for this message
LIU Yulong (dragon889) wrote :

Meet this exception in mitaka cinder.

ENV:
CentOS 7
stable/mitaka
[root@controller-108-202 cinder]# cinder-manage --version
8.0.0
[root@controller-108-202 cinder]# rpm -qa|grep sql
python-sqlalchemy-1.0.11-1.el7.x86_64

Exception logs:
req-10852212-4302-4f9b-b22b-95f1fcfcf6f0
http://paste.openstack.org/show/567108/
http://paste.openstack.org/show/567109/

Revision history for this message
TommyLike (hu-husheng) wrote :

This issue may related to the database pool size and api worker size. For example, this issue can be reproduced by this configuration below(with the wsgi deployment):
```
[default]
osapi_volume_workers = 6
[database]
max_pool_size = 2

```

Revision history for this message
Andras Kovi (akovi) wrote :

I've just ran into a similar issue. It turned out to be a fault in disconnect error detection. Depending on what dialect and connector one uses, disconnect type error may not be found in driver's is_disconnect method. I found that if a disconnection is not detected, then there is a possibility that the connection is left in an inconsistent state and subsequent transactions on the same connection can fail.

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.