nova api_db sync fails remove unused build_requests columns

[Eli Tarrago]

Description
===========
During an upgrade from xena to yoga, I followed upgrade steps using openstack-ansible to upgrade nova. During this time i was met with the following log message:

alembic.runtime.migration [-] Running upgrade d67eeaabee36 -> b30f573d3377, Remove unused build_requests columns

And the python exception:

/openstack/venvs/nova-25.2.1.dev3/bin/nova-manage api_db sync
Modules with known eventlet monkey patching issues were imported prior to eventlet monkey patching: urllib3. This warning can usually be ignored if the caller is only importing and not executing nova code.
An error has occurred:
Traceback (most recent call last):
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1802, in _execute_context
    self.dialect.do_execute(
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 732, in do_execute
    cursor.execute(statement, parameters)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/cursors.py", line 148, in execute
    result = self._query(query)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/cursors.py", line 310, in _query
    conn.query(q)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/connections.py", line 548, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/connections.py", line 775, in _read_query_result
    result.read()
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/connections.py", line 1156, in read
    first_packet = self.connection._read_packet()
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/connections.py", line 725, in _read_packet
    packet.raise_for_error()
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/protocol.py", line 221, in raise_for_error
    err.raise_mysql_exception(self._data)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/err.py", line 143, in raise_mysql_exception
    raise errorclass(errno, errval)
pymysql.err.OperationalError: (1091, "Can't DROP COLUMN `vm_state`; check that it exists")

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/nova/cmd/manage.py", line 3402, in main
    ret = fn(*fn_args, **fn_kwargs)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/nova/cmd/manage.py", line 612, in sync
    return migration.db_sync(version, database='api')
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/nova/db/migration.py", line 154, in db_sync
    _upgrade_alembic(engine, config, version)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/nova/db/migration.py", line 109, in _upgrade_alembic
    alembic_api.upgrade(config, version or 'head')
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/alembic/command.py", line 320, in upgrade
    script.run_env()
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/alembic/script/base.py", line 563, in run_env
    util.load_python_file(self.dir, "env.py")
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/alembic/util/pyfiles.py", line 92, in load_python_file
    module = load_module_py(module_id, path)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/alembic/util/pyfiles.py", line 108, in load_module_py
    spec.loader.exec_module(module) # type: ignore
  File "<frozen importlib._bootstrap_external>", line 848, in exec_module
  File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/nova/db/api/migrations/env.py", line 117, in <module>
    run_migrations_online()
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/nova/db/api/migrations/env.py", line 111, in run_migrations_online
    context.run_migrations()
  File "<string>", line 8, in run_migrations
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/alembic/runtime/environment.py", line 851, in run_migrations
    self.get_context().run_migrations(**kw)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/alembic/runtime/migration.py", line 620, in run_migrations
    step.migration_fn(**kw)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/nova/db/api/migrations/versions/b30f573d3377_remove_unused_build_requests_columns.py", line 45, in upgrade
    batch_op.drop_column('request_spec_id')
  File "/usr/lib/python3.8/contextlib.py", line 120, in __exit__
    next(self.gen)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/alembic/operations/base.py", line 374, in batch_alter_table
    impl.flush()
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/alembic/operations/batch.py", line 108, in flush
    fn(*arg, **kw)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/alembic/ddl/impl.py", line 329, in drop_column
    self._exec(base.DropColumn(table_name, column, schema=schema))
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/alembic/ddl/impl.py", line 193, in _exec
    return conn.execute(construct, multiparams)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1289, in execute
    return meth(self, multiparams, params, _EMPTY_EXECUTION_OPTS)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/sqlalchemy/sql/ddl.py", line 80, in _execute_on_connection
    return connection._execute_ddl(
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1381, in _execute_ddl
    ret = self._execute_context(
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1845, in _execute_context
    self._handle_dbapi_exception(
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 2024, in _handle_dbapi_exception
    util.raise_(newraise, with_traceback=exc_info[2], from_=e)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 207, in raise_
    raise exception
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1802, in _execute_context
    self.dialect.do_execute(
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 732, in do_execute
    cursor.execute(statement, parameters)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/cursors.py", line 148, in execute
    result = self._query(query)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/cursors.py", line 310, in _query
    conn.query(q)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/connections.py", line 548, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/connections.py", line 775, in _read_query_result
    result.read()
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/connections.py", line 1156, in read
    first_packet = self.connection._read_packet()
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/connections.py", line 725, in _read_packet
    packet.raise_for_error()
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/protocol.py", line 221, in raise_for_error
    err.raise_mysql_exception(self._data)
  File "/openstack/venvs/nova-25.2.1.dev3/lib/python3.8/site-packages/pymysql/err.py", line 143, in raise_mysql_exception
    raise errorclass(errno, errval)
sqlalchemy.exc.OperationalError: (pymysql.err.OperationalError) (1091, "Can't DROP COLUMN `vm_state`; check that it exists")
[SQL: ALTER TABLE build_requests DROP COLUMN vm_state]

Steps to reproduce
==================
I was able to reproduce this bug by dropping the entire nova database, creating a nova database and running /openstack/venvs/nova-25.2.1.dev3/bin/nova-manage api_db sync

Expected result
===============
I expect nova-manage to test if build_requests is present before attempting to alter/drop it.

Actual result
=============
The python module reports the exception mentioned above.

Environment
===============
Nova: 25.0.2
Openstack: Yoga
Mariadb: 10.6.11
Hypervisor: libvert+kvm
Storage Type: ceph
Network: Neutron

[sean mooney (sean-k-mooney)]

so we are chating about htis on irc right now and we belive the issues is that while the
"nova" table was dropped that is the nova cell1 db

https://github.com/openstack/openstack-ansible-os_nova/blob/stable/yoga/defaults/main.yml#L93
https://github.com/openstack/openstack-ansible-os_nova/blob/abac462dc218b08656b56c57e5a401aa639a0f0b/tasks/main.yml#L69-L80

not the nova api db which is named nova_api

https://github.com/openstack/openstack-ansible-os_nova/blob/stable/yoga/defaults/main.yml#L93

[Balazs Gibizer (balazs-gibizer)]

> "Can't DROP COLUMN `vm_state`; check that it exists")
[SQL: ALTER TABLE build_requests DROP COLUMN vm_state]

As far as I see this is a bug in the DB migration code introduced in yoga: https://review.opendev.org/c/openstack/nova/+/812145/2/nova/db/api/migrations/versions/b30f573d3377_remove_unused_build_requests_columns.py#31

This tries to drop the vm_state from the build_requests. But vm_state column only exists there if the DB schema was created in older than Newton nova version as after the commit https://review.opendev.org/c/openstack/nova/+/305953/10/nova/db/sqlalchemy/api_models.py#174 (merged in Newton) the column is not added to the table any more.

[Eli Tarrago (divisible9026)]

Good Morning,

I upgraded a second environment and hit the same issue as below. During the first time, we chalked it up to being a non-production test environment that missed a step along the way.

Yesterday, My QA environment hit the same issue.

If anyone else is encountering this issue. My current resolution is to perform the following command `mysqldump nova_api build_requests` and an environment that has not been upgraded (or has been upgraded). Copy pasting that into the mysql command line and restoring the table.

From: <email address hidden> <email address hidden> on behalf of Balazs Gibizer <email address hidden>
Date: Wednesday, April 12, 2023 at 6:16 AM
To: Tarrago, Eli (RIS-BCT) <email address hidden>
Subject: [Bug 2008716] Re: nova api_db sync fails remove unused build_requests columns
[You don't often get email from <email address hidden>. Learn why this is important at https://aka.ms/LearnAboutSenderIdentification ]

*** External email: use caution ***

> "Can't DROP COLUMN `vm_state`; check that it exists")
[SQL: ALTER TABLE build_requests DROP COLUMN vm_state]

As far as I see this is a bug in the DB migration code introduced in
yoga:
https://nam11.safelinks.protection.outlook.com/?url=https%3A%2F%2Freview.opendev.org%2Fc%2Fopenstack%2Fnova%2F%2B%2F812145%2F2%2Fnova%2Fdb%2Fapi%2Fmigrations%2Fversions%2Fb30f573d3377_remove_unused_build_requests_columns.py%2331&data=05%7C01%7Celi.tarrago%40lexisnexisrisk.com%7C1bbe0ae9721a458a967e08db3b3efd5d%7C9274ee3f94254109a27f9fb15c10675d%7C0%7C0%7C638168913960042878%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=T8A12Lyf%2BQBE%2BGAw8ZKLVfRoj8%2Bk17oowI6xZ16vDZE%3D&reserved=0<https://review.opendev.org/c/openstack/nova/+/812145/2/nova/db/api/migrations/versions/b30f573d3377_remove_unused_build_requests_columns.py#31>

This tries to drop the vm_state from the build_requests. But vm_state
column only exists there if the DB schema was created in older than
Newton nova version as after the commit
https://nam11.safelinks.protection.outlook.com/?url=https%3A%2F%2Freview.opendev.org%2Fc%2Fopenstack%2Fnova%2F%2B%2F305953%2F10%2Fnova%2Fdb%2Fsqlalchemy%2Fapi_models.py%23174&data=05%7C01%7Celi.tarrago%40lexisnexisrisk.com%7C1bbe0ae9721a458a967e08db3b3efd5d%7C9274ee3f94254109a27f9fb15c10675d%7C0%7C0%7C638168913960042878%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=hrzVceXn42B9lQGlvY8AfP%2BMHbi%2BCsZjtJjzLAIfym0%3D&reserved=0<https://review.opendev.org/c/openstack/nova/+/305953/10/nova/db/sqlalchemy/api_models.py#174>
(merged in Newton) the column is not added to the table any more.

--
You received this bug notification because you are subscribed to the bug
report.
https://nam11.safelinks.protection.outlook.com/?url=https%3A%2F%2Fbugs.launchpad.net%2Fbugs%2F2008716&data=05%7C01%7Celi.tarrago%40lexisnexisrisk.com%7C1bbe0ae9721a458a967e08db3b3efd5d%7C9274ee3f94254109a27f9fb15c10675d%7C0%7C0%7C638168913960042878%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=CF0wNDWpO5YPoFZsx1HI9Y5d6S8S...

[melanie witt (melwitt)]

I was not able to reproduce this issue in a local devstack using stable/yoga at 273831716780090677215ba70168bb74a2dae814:

$ cat bug-2008716-nova.conf
[api_database]
connection = mysql+pymysql://root:a@127.0.0.1/nova_api_2008716?charset=utf8

mysql> drop database nova_api_2008716;
Query OK, 32 rows affected (0.21 sec)

mysql> create database nova_api_2008716;
Query OK, 1 row affected (0.01 sec)

mysql> quit;
Bye

$ nova-manage --config-file bug-2008716-nova.conf api_db sync
Modules with known eventlet monkey patching issues were imported prior to eventlet monkey patching: urllib3. This warning can usually be ignored if the caller is only importing and not executing nova code.
/usr/lib/python3/dist-packages/secretstorage/dhcrypto.py:15: CryptographyDeprecationWarning: int_from_bytes is deprecated, use int.from_bytes instead
  from cryptography.utils import int_from_bytes
/usr/lib/python3/dist-packages/secretstorage/util.py:19: CryptographyDeprecationWarning: int_from_bytes is deprecated, use int.from_bytes instead
  from cryptography.utils import int_from_bytes
2023-10-18 20:43:18.921 26615 INFO alembic.runtime.migration [-] Context impl MySQLImpl.
2023-10-18 20:43:18.922 26615 INFO alembic.runtime.migration [-] Will assume non-transactional DDL.
2023-10-18 20:43:18.946 26615 INFO alembic.runtime.migration [-] Running upgrade -> d67eeaabee36, Initial version
2023-10-18 20:43:20.423 26615 INFO alembic.runtime.migration [-] Running upgrade d67eeaabee36 -> b30f573d3377, Remove unused build_requests columns

mysql> show columns from nova_api_2008716.build_requests;
+-----------------------+--------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra |
+-----------------------+--------------+------+-----+---------+----------------+
| created_at | datetime | YES | | NULL | |
| updated_at | datetime | YES | | NULL | |
| id | int | NO | PRI | NULL | auto_increment |
| project_id | varchar(255) | NO | MUL | NULL | |
| instance_uuid | varchar(36) | YES | UNI | NULL | |
| instance | mediumtext | YES | | NULL | |
| block_device_mappings | mediumtext | YES | | NULL | |
| tags | text | YES | | NULL | |
+-----------------------+--------------+------+-----+---------+----------------+
8 rows in set (0.01 sec)

[melanie witt (melwitt)]

I'm setting this to Incomplete based on the fact that 1) I was not able to reproduce the issue using what I understood from the 'Steps to reproduce' shown in the bug report and 2) upgrade CI jobs such as nova-grenade-multinode on the stable/yoga branch which perform upgrades from Xena to Yoga are passing and successfully executing upgrades.

There must be more going on here and I'm not sure whether it's related to Nova itself. If there is more information you can provide to help us reproduce this, please add another comment.

[Launchpad Janitor (janitor)]

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]