nova-api-os-compute fails with mysql command out of sync error

[Brad Marshall]

I've been deploying the 16.04 charms to Mitaka on Trusty using the cloud archive, and have run into an odd issue. It appears that there is some problems with nova-api-os-compute, it throws an error about connecting to the database:

2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool [req-c359fc24-2918-47f7-bf79-ef4015c5ff02 - - - - -] Exception during reset or similar
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool Traceback (most recent call last):
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 636, in _finalize_fairy
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool fairy._reset(pool)
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 774, in _reset
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool self._reset_agent.rollback()
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1563, in rollback
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool self._do_rollback()
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1601, in _do_rollback
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool self.connection._rollback_impl()
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 670, in _rollback_impl
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool self._handle_dbapi_exception(e, None, None, None, None)
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool util.raise_from_cause(newraise, exc_info)
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool reraise(type(exception), exception, tb=exc_tb)
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 668, in _rollback_impl
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool self.engine.dialect.do_rollback(self.connection)
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/sqlalchemy/dialects/mysql/base.py", line 2526, in do_rollback
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool dbapi_connection.rollback()
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 763, in rollback
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool self._read_ok_packet()
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 739, in _read_ok_packet
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool raise err.OperationalError(2014, "Command Out of Sync")
2016-08-09 06:44:48.357 63984 ERROR sqlalchemy.pool.QueuePool DBConnectionError: (pymysql.err.OperationalError) (2014, 'Command Out of Sync')

After some searching around I found a reference in LP#1400492 about python-mysqldb 1.2.3 (which is provided by trusty) causing this issue. I grabbed a copy of the wily package (latest version I could easily find that would install without a problem), installed it and restarted the services, and the error disappeared. It appears that it still can reoccur, but its happening much less frequently.

$ dpkg-query -W nova-api-os-compute
nova-api-os-compute 2:13.0.0-0ubuntu5~cloud0

$ lsb_release -rd
Description: Ubuntu 14.04.5 LTS
Release: 14.04

# Version of python-mysqldb tested
$ dpkg-query -W python-mysqldb
python-mysqldb 1.3.4-2

Using the trusty-mitaka cloud archive.

[James Page (james-page)]

nova will be using pymysql in Mitaka, which is at version 0.7.2-1~cloud0 in the UCA; so if we have a problem its most likely to be in this part of the dependency chain rather than mysqldb.

[James Page (james-page)]

(pymysql.err.OperationalError)

[Corey Bryant (corey.bryant)]

It may be useful to turn debug and verbose config options on to see where we are in nova-api-os-compute at the time of failure. It looks like this error can occur when sharing sqlalchemy objects among threads, so it could possibly be a bug in nova.

[James Page (james-page)]

Brad

I'd like to see if this might be resolved by a bump in point release version of pymysql; if I update via a standalone PPA, could you install and see if that helps things?

Cheers

James

[Launchpad Janitor (janitor)]

[Expired for Ubuntu Cloud Archive because there has been no activity for 60 days.]