OperationalError: (pymysql.err.OperationalError) (2014, 'Command Out of Sync')

[HouMing Wang]

OpenStack Mitaka Release

RPM package info:
python2-oslo-db-4.7.1-1.el7.noarch
python-sqlalchemy-1.0.11-1.el7.x86_64
python2-PyMySQL-0.7.9-2.el7.noarch

Error Info：
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters [req-0d328586-22bd-4cbc-b607-90c1f5246d01 a ddd - - -] DB exception wrapped.
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters context)
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters cursor.execute(statement, parameters)
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 166, in execute
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters result = self._query(query)
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 322, in _query
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters conn.query(q)
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 841, in query
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1029, in _read_query_result
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters result.read()
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1312, in read
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters first_packet = self.connection._read_packet()
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 971, in _read_packet
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters packet_header = self._read_bytes(4)
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1006, in _read_bytes
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters if len(data) < num_bytes:
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters TypeError: object of type 'NoneType' has no len()
2017-06-20 13:50:05.702 2700241 ERROR oslo_db.sqlalchemy.exc_filters
2017-06-20 13:50:05.711 2700241 ERROR wsme.api [req-0d328586-22bd-4cbc-b607-90c1f5246d01 a ddd - - -] Server-side error: "(pymysql.err.OperationalError) (2014, 'Command Out of Sync')". Detail:
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/wsmeext/pecan.py", line 84, in callfunction
result = f(self, *args, **kwargs)
File "/usr/lib/python2.7/site-packages/magnum/api/controllers/v1/bay.py", line 306, in get_one
File "/usr/lib/python2.7/site-packages/magnum/api/utils.py", line 96, in get_resource
File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 181, in wrapper
result = fn(cls, context, *args, **kwargs)
File "/usr/lib/python2.7/site-packages/magnum/objects/bay.py", line 137, in get_by_uuid
File "/usr/lib/python2.7/site-packages/magnum/objects/bay.py", line 91, in _from_db_object
File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 181, in wrapper
result = fn(cls, context, *args, **kwargs)
File "/usr/lib/python2.7/site-packages/magnum/objects/baymodel.py", line 133, in get_by_uuid
File "/usr/lib/python2.7/site-packages/magnum/db/sqlalchemy/api.py", line 311, in get_baymodel_by_uuid
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2693, in one
ret = list(self)
...
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
context)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1334, in _handle_dbapi_exception
self._autorollback()
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 791, in _autorollback
self._root._rollback_impl()
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 670, in _rollback_impl
self._handle_dbapi_exception(e, None, None, None, None)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1266, in _handle_dbapi_exception
exc_info
File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
reraise(type(exception), exception, tb=exc_tb)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 668, in _rollback_impl
self.engine.dialect.do_rollback(self.connection)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2526, in do_rollback
dbapi_connection.rollback()
File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 778, in rollback
self._read_ok_packet()
File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 754, in _read_ok_packet
raise err.OperationalError(2014, "Command Out of Sync")
OperationalError: (pymysql.err.OperationalError) (2014, 'Command Out of Sync')

[Mike Bayer (zzzeek)]

this is not inherently a bug in oslo.db. this has to do when specific failure conditions occur within MySQL, and then SQLAlchemy's attempt to "autorollback" the transaction also fail. However, "autorollback" shouldn't be happening here because it means the ORM Session is being used in autocommit mode without a transaction, which is strongly recommended against and would not occur if oslo.db's usual enginefacade system were being used.

[Mike Bayer (zzzeek)]

additional info using SQLAlchemy 1.1.7 or greater will show as a warning under Py2K, which hopefully Magnum should be directing into the logs, as per http://docs.sqlalchemy.org/en/latest/changelog/changelog_11.html#change-34dc3f48c4597e8b0bb377c94fd6359a.

I've confirmed Magnum is still using the legacy enginefacade, however is emitting session.begin(). Current master of magnum does not have this method so this is specific to a specific legacy version of magnum.

[ChangBo Guo(gcb) (glongwave)]

Update: magnum-api use werkzeug to run WSGI application [1] and run with more than one workers.
There is no error when workers equals 1, and raise error when workers>1. I dig werkzeug little.
find werkzeug will launch new process for each request, that means it will try to connect the database for each request. That's not the right way to use oslo.db

    workers = CONF.api.workers
    if not workers:
        workers = processutils.get_worker_count()
    LOG.info('Server will handle each request in a new process up to'
             ' %s concurrent processes', workers)
    serving.run_simple(host, port, app, processes=workers,
                       ssl_context=_get_ssl_configs(use_ssl))

[1]https://github.com/openstack/magnum/blob/master/magnum/cmd/api.py

[Ben Nemec (bnemec)]

This was opened against mitaka, which is now out of support. Is it still a problem in current versions of the projects involved?

[Launchpad Janitor (janitor)]

[Expired for oslo.db because there has been no activity for 60 days.]