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

[Sam Wan]

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

[Jin Liu (jin-t)]

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()

[LIU Yulong (dragon889)]

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/

[TommyLike (hu-husheng)]

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

```

[Andras Kovi (akovi)]

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.