scary traceback if nova-manage db sync is run before nova-manage api_db sync

[Sean Dague]

During gate runs we're running

nova-manage db sync
nova-manage api_db sync

This leads to the following rather scary stack trace:

2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters [req-962d0663-409b-4e1a-8552-52ecb451a165 - -] DBAPIError exception wrapped from (pymysql.err.InternalError) (1049, u"Unknown database 'nova_api'")
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2074, in _wrap_pool_connect
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters return fn()
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 318, in unique_connection
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters return _ConnectionFairy._checkout(self)
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 713, in _checkout
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters fairy = _ConnectionRecord.checkout(pool)
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 480, in checkout
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters rec = pool._do_get()
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 1060, in _do_get
2016-10-06 13:19:15.279 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters self._dec_overflow()
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters compat.reraise(exc_type, exc_value, exc_tb)
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 1057, in _do_get
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters return self._create_connection()
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 323, in _create_connection
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters return _ConnectionRecord(self)
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 449, in __init__
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters self.connection = self.__connect()
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 607, in __connect
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters connection = self.__pool._invoke_creator(self)
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/strategies.py", line 97, in connect
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters return dialect.connect(*cargs, **cparams)
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 385, in connect
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters return self.dbapi.connect(*cargs, **cparams)
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/__init__.py", line 90, in Connect
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters return Connection(*args, **kwargs)
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 688, in __init__
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters self.connect()
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 906, in connect
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters self._request_authentication()
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1114, in _request_authentication
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters auth_packet = self._read_packet()
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 981, in _read_packet
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters packet.check_error()
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 393, in check_error
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters err.raise_mysql_exception(self._data)
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 107, in raise_mysql_exception
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters raise errorclass(errno, errval)
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1049, u"Unknown database 'nova_api'")
2016-10-06 13:19:15.280 | 2016-10-06 13:19:15.277 21612 ERROR oslo_db.sqlalchemy.exc_filters
2016-10-06 13:19:15.280 | ERROR: could not access cell mapping database - has api db been created?

This is pretty scary for admins, but it turns out it's pretty useless and non fatal. While we can fix the gate to do these operations in the other order, it would be nice if we weren't spewing this scary traceback to users.

Ideally we could tell engine fascade about issues we don't care about, so that it wouldn't log behind the scenes for us. The alternative is Nova turning off logging selectively, which is less than ideal as the granularity is going to be different than we might expect.

[Sean Dague (sdague)]

Example gate run - http://logs.openstack.org/60/378560/4/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/b18e638/logs/devstacklog.txt.gz#_2016-10-06_13_19_15_279

[Andrew Laski (alaski)]

This is a result of adding https://review.openstack.org/#/c/274885/25/nova/cmd/manage.py to Nova. It's expected that this might happen, attempting to access the nova_api db before it's created, which is why we "except Exception" and print a simple message explaining what happened.

[Andrew Laski (alaski)]

I was just explaining why it happens. I agree with what Sean wrote that it be nice to be able to squelch the traceback in oslo.db for this case.

[Roman Podoliaka (rpodolyaka)]

https://review.openstack.org/384581

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.db 4.14.0 release.