Error running nova-install.yml during N->O upgrade due to table permissions

[James Denton]

OS: Ubuntu 16.04
OpenStack Release: Newton 14.0.5 (to ocata/stable)

When running setup-openstack.yml during N->O upgrade, the following error was observed:

TASK [os_nova : Perform a Nova API DB sync] ************************************
Wednesday 22 February 2017 16:04:28 -0500 (0:00:03.199) 0:19:19.811 ****
fatal: [infra01-cluster2_nova_api_os_compute_container-bd6b4287]: FAILED! => {"changed": false, "cmd": ["/openstack/venvs/nova-15.0.0/bin/nova-manage", "--config-file", "/etc/nova/nova.conf", "api_db", "sync"], "delta": "0:00:04.982117", "end": "2017-02-22 16:04:33.525682", "failed": true, "rc": 1, "start": "2017-02-22 16:04:28.543565", "stderr": "", "stdout": "An error has occurred:\nTraceback (most recent call last):\n File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/cmd/manage.py\", line 1594, in main\n ret = fn(*fn_args, **fn_kwargs)\n File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/cmd/manage.py\", line 809, in sync\n return migration.db_sync(version, database='api')\n File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/migration.py\", line 26, in db_sync\n return IMPL.db_sync(version=version, database=database, context=context)\n File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/sqlalchemy/migration.py\", line 57, in db_sync\n repository, version)\n File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/migrate/versioning/api.py\", line 186, in upgrade\n return _migrate(url, repository, version, upgrade=True, err=err, **opts)\n File \"<decorator-gen-15>\", line 2, in _migrate\n File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/migrate/versioning/util/__init__.py\", line 160, in with_engine\n return f(*a, **kw)\n File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/migrate/versioning/api.py\", line 366, in _migrate\n schema.runchange(ver, change, changeset.step)\n File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/migrate/versioning/schema.py\", line 93, in runchange\n change.run(self.engine, step)\n File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/migrate/versioning/script/py.py\", line 148, in run\n script_func(engine)\n File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/sqlalchemy/api_migrations/migrate_repo/versions/030_require_cell_setup.py\", line 44, in upgrade\n raise exception.ValidationError(detail=msg)\nValidationError: Cell mappings are not created, but required for Ocata. Please run nova-manage cell_v2 simple_cell_setup before continuing.", "stdout_lines": ["An error has occurred:", "Traceback (most recent call last):", " File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/cmd/manage.py\", line 1594, in main", " ret = fn(*fn_args, **fn_kwargs)", " File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/cmd/manage.py\", line 809, in sync", " return migration.db_sync(version, database='api')", " File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/migration.py\", line 26, in db_sync", " return IMPL.db_sync(version=version, database=database, context=context)", " File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/sqlalchemy/migration.py\", line 57, in db_sync", " repository, version)", " File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/migrate/versioning/api.py\", line 186, in upgrade", " return _migrate(url, repository, version, upgrade=True, err=err, **opts)", " File \"<decorator-gen-15>\", line 2, in _migrate", " File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/migrate/versioning/util/__init__.py\", line 160, in with_engine", " return f(*a, **kw)", " File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/migrate/versioning/api.py\", line 366, in _migrate", " schema.runchange(ver, change, changeset.step)", " File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/migrate/versioning/schema.py\", line 93, in runchange", " change.run(self.engine, step)", " File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/migrate/versioning/script/py.py\", line 148, in run", " script_func(engine)", " File \"/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/sqlalchemy/api_migrations/migrate_repo/versions/030_require_cell_setup.py\", line 44, in upgrade", " raise exception.ValidationError(detail=msg)", "ValidationError: Cell mappings are not created, but required for Ocata. Please run nova-manage cell_v2 simple_cell_setup before continuing."], "warnings": []}

I hopped into one of the containers to run the nova-manage command, and experience another error:

root@infra01-cluster2-nova-api-os-compute-container-bd6b4287:~# /openstack/venvs/nova-15.0.0/bin/nova-manage --config-file /etc/nova/nova.conf cell_v2 simple_cell_setup
Cell0 is already setup
An error has occurred:
Traceback (most recent call last):
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/cmd/manage.py", line 1594, in main
    ret = fn(*fn_args, **fn_kwargs)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/cmd/manage.py", line 1108, in simple_cell_setup
    migration.db_sync(None, context=ctxt)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/migration.py", line 26, in db_sync
    return IMPL.db_sync(version=version, database=database, context=context)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/sqlalchemy/migration.py", line 53, in db_sync
    current_version = db_version(database, context=context)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/sqlalchemy/migration.py", line 66, in db_version
    return versioning_api.db_version(get_engine(database, context=context),
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/sqlalchemy/migration.py", line 41, in get_engine
    return db_session.get_engine(context=context)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 149, in get_engine
    return ctxt_mgr.get_legacy_facade().get_engine(use_slave=use_slave)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 707, in get_legacy_facade
    return self._factory.get_legacy_facade()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 261, in get_legacy_facade
    self._start()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 403, in _start
    engine_args, maker_args)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 427, in _setup_for_connection
    sql_connection=sql_connection, **engine_kwargs)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/oslo_db/sqlalchemy/engines.py", line 155, in create_engine
    test_conn = _test_connection(engine, max_retries, retry_interval)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/oslo_db/sqlalchemy/engines.py", line 331, in _test_connection
    return engine.connect()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 2018, in connect
    return self._connection_cls(self, **kwargs)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 72, in __init__
    if connection is not None else engine.raw_connection()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 2104, in raw_connection
    self.pool.unique_connection, _connection)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 2078, in _wrap_pool_connect
    e, dialect, self)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1401, in _handle_dbapi_exception_noconnection
    util.raise_from_cause(newraise, exc_info)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 2074, in _wrap_pool_connect
    return fn()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/pool.py", line 318, in unique_connection
    return _ConnectionFairy._checkout(self)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/pool.py", line 713, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/pool.py", line 480, in checkout
    rec = pool._do_get()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/pool.py", line 1060, in _do_get
    self._dec_overflow()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
    compat.reraise(exc_type, exc_value, exc_tb)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/pool.py", line 1057, in _do_get
    return self._create_connection()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/pool.py", line 323, in _create_connection
    return _ConnectionRecord(self)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/pool.py", line 449, in __init__
    self.connection = self.__connect()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/pool.py", line 607, in __connect
    connection = self.__pool._invoke_creator(self)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/engine/strategies.py", line 97, in connect
    return dialect.connect(*cargs, **cparams)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 385, in connect
    return self.dbapi.connect(*cargs, **cparams)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/pymysql/__init__.py", line 90, in Connect
    return Connection(*args, **kwargs)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/pymysql/connections.py", line 688, in __init__
    self.connect()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/pymysql/connections.py", line 906, in connect
    self._request_authentication()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/pymysql/connections.py", line 1114, in _request_authentication
    auth_packet = self._read_packet()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/pymysql/connections.py", line 981, in _read_packet
    packet.check_error()
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/pymysql/connections.py", line 393, in check_error
    err.raise_mysql_exception(self._data)
  File "/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/pymysql/err.py", line 107, in raise_mysql_exception
    raise errorclass(errno, errval)
OperationalError: (pymysql.err.OperationalError) (1044, u"Access denied for user 'nova'@'%' to database 'nova_cell0'")

I observed that nova_cell0 was created in mysql, but the nova user had no permissions on it:

MariaDB [nova_cell0]> show tables;
Empty set (0.00 sec)

MariaDB [(none)]> show grants for nova;
+-----------------------------------------------------------------------------------------------------+
| Grants for nova@% |
+-----------------------------------------------------------------------------------------------------+
| GRANT USAGE ON *.* TO 'nova'@'%' IDENTIFIED BY PASSWORD '*E14D4B18610218826B26FD7563435E7FAD7B9CBA' |
| GRANT ALL PRIVILEGES ON `nova`.* TO 'nova'@'%' |
+-----------------------------------------------------------------------------------------------------+
2 rows in set (0.01 sec)

MariaDB [(none)]> GRANT ALL PRIVILEGES ON `nova_cell0`.* TO 'nova'@'%'
    -> ;
Query OK, 0 rows affected (0.00 sec)

I ran nova-manage with the following parameters:

root@infra01-cluster2-nova-api-os-compute-container-bd6b4287:~# /openstack/venvs/nova-15.0.0/bin/nova-manage --config-file /etc/nova/nova.conf cell_v2 simple_cell_setup

Cell0 is already setup
/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/pymysql/cursors.py:166: Warning: (1831, u'Duplicate index `block_device_mapping_instance_uuid_virtual_name_device_name_idx`. This is deprecated and will be disallowed in a future release.')
  result = self._query(query)
/openstack/venvs/nova-15.0.0/lib/python2.7/site-packages/pymysql/cursors.py:166: Warning: (1831, u'Duplicate index `uniq_instances0uuid`. This is deprecated and will be disallowed in a future release.')
  result = self._query(query)
root@infra01-cluster2-nova-api-os-compute-container-bd6b4287:~# mysql
Welcome to the MariaDB monitor. Commands end with ; or \g.
Your MariaDB connection id is 2189
Server version: 10.1.21-MariaDB-1~xenial mariadb.org binary distribution

Copyright (c) 2000, 2016, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> use nova_cell0
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
MariaDB [nova_cell0]> show tables;
+--------------------------------------------+
| Tables_in_nova_cell0 |
+--------------------------------------------+
| agent_builds |
| aggregate_hosts |
| aggregate_metadata |
| aggregates |
| allocations |
| block_device_mapping |
| bw_usage_cache |
| cells |
| certificates |
| compute_nodes |
| console_auth_tokens |
| console_pools |
| consoles |
| dns_domains |
| fixed_ips |
| floating_ips |
| instance_actions |
| instance_actions_events |
| instance_extra |
| instance_faults |
| instance_group_member |
| instance_group_policy |
| instance_groups |
| instance_id_mappings |
| instance_info_caches |
| instance_metadata |
| instance_system_metadata |
| instance_type_extra_specs |
| instance_type_projects |
| instance_types |
| instances |
| inventories |
| key_pairs |
| migrate_version |
| migrations |
| networks |
| pci_devices |
| project_user_quotas |
| provider_fw_rules |
| quota_classes |
| quota_usages |
| quotas |
| reservations |
| resource_provider_aggregates |
| resource_providers |
| s3_images |
| security_group_default_rules |
| security_group_instance_association |
| security_group_rules |
| security_groups |
| services |
| shadow_agent_builds |
| shadow_aggregate_hosts |
| shadow_aggregate_metadata |
| shadow_aggregates |
| shadow_block_device_mapping |
| shadow_bw_usage_cache |
| shadow_cells |
| shadow_certificates |
| shadow_compute_nodes |
| shadow_console_pools |
| shadow_consoles |
| shadow_dns_domains |
| shadow_fixed_ips |
| shadow_floating_ips |
| shadow_instance_actions |
| shadow_instance_actions_events |
| shadow_instance_extra |
| shadow_instance_faults |
| shadow_instance_group_member |
| shadow_instance_group_policy |
| shadow_instance_groups |
| shadow_instance_id_mappings |
| shadow_instance_info_caches |
| shadow_instance_metadata |
| shadow_instance_system_metadata |
| shadow_instance_type_extra_specs |
| shadow_instance_type_projects |
| shadow_instance_types |
| shadow_instances |
| shadow_key_pairs |
| shadow_migrate_version |
| shadow_migrations |
| shadow_networks |
| shadow_pci_devices |
| shadow_project_user_quotas |
| shadow_provider_fw_rules |
| shadow_quota_classes |
| shadow_quota_usages |
| shadow_quotas |
| shadow_reservations |
| shadow_s3_images |
| shadow_security_group_default_rules |
| shadow_security_group_instance_association |
| shadow_security_group_rules |
| shadow_security_groups |
| shadow_services |
| shadow_snapshot_id_mappings |
| shadow_snapshots |
| shadow_task_log |
| shadow_virtual_interfaces |
| shadow_volume_id_mappings |
| shadow_volume_usage_cache |
| snapshot_id_mappings |
| snapshots |
| tags |
| task_log |
| virtual_interfaces |
| volume_id_mappings |
| volume_usage_cache |
+--------------------------------------------+
110 rows in set (0.00 sec)

Now, the task completed successfully.

[James Denton (james-denton)]

It seems that at some point during the run, the grant is lost, resulting in issues running certain Nova commands like 'nova list' after the upgrade is complete:

root@infra01-cluster2-utility-container-c58c7ad8:~# nova list
/usr/local/lib/python2.7/dist-packages/requests/packages/urllib3/connectionpool.py:843: InsecureRequestWarning: Unverified HTTPS request is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings
  InsecureRequestWarning)
/usr/local/lib/python2.7/dist-packages/novaclient/client.py:278: UserWarning: The 'tenant_id' argument is deprecated in Ocata and its use may result in errors in future releases. As 'project_id' is provided, the 'tenant_id' argument will be ignored.
  warnings.warn(msg)
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'sqlalchemy.exc.OperationalError'> (HTTP 500) (Request-ID: req-f4e37d91-a41c-4611-9854-d532742dba38)
root@infra01-cluster2-utility-container-c58c7ad8:~# nova list
/usr/local/lib/python2.7/dist-packages/requests/packages/urllib3/connectionpool.py:843: InsecureRequestWarning: Unverified HTTPS request is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings
  InsecureRequestWarning)
/usr/local/lib/python2.7/dist-packages/novaclient/client.py:278: UserWarning: The 'tenant_id' argument is deprecated in Ocata and its use may result in errors in future releases. As 'project_id' is provided, the 'tenant_id' argument will be ignored.
  warnings.warn(msg)
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'sqlalchemy.exc.OperationalError'> (HTTP 500) (Request-ID: req-b17ae152-9548-4870-a289-b059b0b3f9d2)

Restoring the grant resolves the issue.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/439691

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/ocata
Review: https://review.openstack.org/440679

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/439691
Committed: https://git.openstack.org/cgit/openstack/openstack-ansible-os_nova/commit/?id=ea6e67375d9d946136cd1981b446025674ff23f0
Submitter: Jenkins
Branch: master

commit ea6e67375d9d946136cd1981b446025674ff23f0
Author: Andy McCrae <email address hidden>
Date: Wed Mar 1 16:17:07 2017 +0000

    Adjust ordering for nova_db_setup

    Running an api_db sync on an existing cluster without cells, for example
    in an N->O upgrade requires the cells to have been setup.

    Changing the ordering to setup the cells first before running the api_db
    sync will resolve this.

    However, in a greenfield deploy we require the api_db sync to happen
    before we can create a cell. We should test to see if the api_db version
    is 0 (it hasn't been setup yet) and then run the api_db sync if it
    hasn't, otherwise skip to create the cell.

    Closes-Bug: #1667127
    Change-Id: If3fff46dd581294ef44cad0a1626b68229bca060

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/440679
Committed: https://git.openstack.org/cgit/openstack/openstack-ansible-os_nova/commit/?id=ac004fdf9cfa9c91532ed53cdb80b65fcf1f1636
Submitter: Jenkins
Branch: stable/ocata

commit ac004fdf9cfa9c91532ed53cdb80b65fcf1f1636
Author: Andy McCrae <email address hidden>
Date: Wed Mar 1 16:17:07 2017 +0000

    Adjust ordering for nova_db_setup

    Running an api_db sync on an existing cluster without cells, for example
    in an N->O upgrade requires the cells to have been setup.

    Changing the ordering to setup the cells first before running the api_db
    sync will resolve this.

    However, in a greenfield deploy we require the api_db sync to happen
    before we can create a cell. We should test to see if the api_db version
    is 0 (it hasn't been setup yet) and then run the api_db sync if it
    hasn't, otherwise skip to create the cell.

    Closes-Bug: #1667127
    Change-Id: If3fff46dd581294ef44cad0a1626b68229bca060

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/openstack-ansible-os_nova 15.0.0.0rc2 release candidate.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/openstack-ansible-os_nova 16.0.0.0b1 development milestone.