On first time running keystone-manage db_sync, when oslo.db is initializing the migrate_version table, the database restarted unexpectedly. The following error log is produced:
Traceback (most recent call last):
File "/bin/keystone-manage", line 10, in <module>
sys.exit(main())
File "/usr/lib/python2.7/site-packages/keystone/cmd/manage.py", line 46, in main
cli.main(argv=sys.argv, config_files=config_files)
File "/usr/lib/python2.7/site-packages/keystone/cmd/cli.py", line 1010, in main
CONF.command.cmd_class.main()
File "/usr/lib/python2.7/site-packages/keystone/cmd/cli.py", line 389, in main
migration_helpers.sync_database_to_version(extension, version)
File "/usr/lib/python2.7/site-packages/keystone/common/sql/migration_helpers.py", line 209, in sync_database_to_version
_sync_common_repo(version)
File "/usr/lib/python2.7/site-packages/keystone/common/sql/migration_helpers.py", line 135, in _sync_common_repo
init_version=init_version, sanity_check=False)
File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/migration.py", line 74, in db_sync
current_version = db_version(engine, abs_path, init_version)
File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/migration.py", line 132, in db_version
db_version_control(engine, abs_path, version=init_version)
File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/migration.py", line 153, in db_version_control
versioning_api.version_control(engine, repository, version)
File "<string>", line 2, in version_control
File "/usr/lib/python2.7/site-packages/migrate/versioning/util/__init__.py", line 160, in with_engine
return f(*a, **kw)
File "/usr/lib/python2.7/site-packages/migrate/versioning/api.py", line 250, in version_control
ControlledSchema.create(engine, repository, version)
File "/usr/lib/python2.7/site-packages/migrate/versioning/schema.py", line 144, in create
return cls(engine, repository)
File "/usr/lib/python2.7/site-packages/migrate/versioning/schema.py", line 33, in __init__
self.load()
File "/usr/lib/python2.7/site-packages/migrate/versioning/schema.py", line 54, in load
exceptions.DatabaseNotControlledError(str(exc)), tb)
File "/usr/lib/python2.7/site-packages/migrate/versioning/schema.py", line 45, in load
self.table = Table(tname, self.meta, autoload=True)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/schema.py", line 416, in __new__
metadata._remove_table(name, schema)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
compat.reraise(exc_type, exc_value, exc_tb)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/schema.py", line 411, in __new__
table._init(name, metadata, *args, **kw)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/schema.py", line 484, in _init
self._autoload(metadata, autoload_with, include_columns)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/schema.py", line 508, in _autoload
self, include_columns, exclude_columns
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1972, in run_callable
return conn.run_callable(callable_, *args, **kwargs)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1477, in run_callable
return callable_(self, *args, **kwargs)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 364, in reflecttable
return insp.reflecttable(table, include_columns, exclude_columns)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/reflection.py", line 563, in reflecttable
table_name, schema, **table.dialect_kwargs):
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/reflection.py", line 369, in get_columns
**kw)
File "<string>", line 2, in get_columns
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/reflection.py", line 54, in cache
ret = fn(self, con, *args, **kw)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/postgresql/base.py", line 2405, in get_columns
info_cache=kw.get('info_cache'))
File "<string>", line 2, in get_table_oid
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/reflection.py", line 54, in cache
ret = fn(self, con, *args, **kw)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/postgresql/base.py", line 2300, in get_table_oid
c = connection.execute(s, table_name=table_name, schema=schema)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute
return meth(self, multiparams, params)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
compiled_sql, distilled_params
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 1337, in _handle_dbapi_exception
util.raise_from_cause(newraise, 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 1139, in _execute_context
context)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute
cursor.execute(statement, parameters)
DatabaseNotControlledError: (psycopg2.OperationalError) server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
Next time when the db_sync command is run again, it fail forever with the following error:
Traceback (most recent call last):
File "/bin/keystone-manage", line 10, in <module>
sys.exit(main())
File "/usr/lib/python2.7/site-packages/keystone/cmd/manage.py", line 46, in main
cli.main(argv=sys.argv, config_files=config_files)
File "/usr/lib/python2.7/site-packages/keystone/cmd/cli.py", line 1010, in main
CONF.command.cmd_class.main()
File "/usr/lib/python2.7/site-packages/keystone/cmd/cli.py", line 389, in main
migration_helpers.sync_database_to_version(extension, version)
File "/usr/lib/python2.7/site-packages/keystone/common/sql/migration_helpers.py", line 209, in sync_database_to_version
_sync_common_repo(version)
File "/usr/lib/python2.7/site-packages/keystone/common/sql/migration_helpers.py", line 135, in _sync_common_repo
init_version=init_version, sanity_check=False)
File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/migration.py", line 74, in db_sync
current_version = db_version(engine, abs_path, init_version)
File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/migration.py", line 137, in db_version
"The database is not under version control, but has "
DbMigrationError: The database is not under version control, but has tables. Please stamp the current version of the schema manually.
We checked the keystone database, only the MIGRATE_VERSION table is created but has no rows.
Oslo.db or sqlalchemy-migrate should consider such abnormal scenario and make sure the db_sync command can work normally when retried.
The version of oslo.db is 4.6.0 and sqlalchemy-migrate is 0.10.0
This looks like an issue with sqlalchemy-migrate, so I'm adding that project to the bug. I'll leave oslo.db on it in case it turns out I'm wrong though.