dbmanage sync fails to run

[Billy Olsen]

The SQLAlchemy scripts for Caracal watcher fails to run due to errors in the generated SQL migrations.

This occurs when the `watcher db-manage sync` scripts are run to create the database or migrate the database.

Patches have been merged recently upstream -https://review.opendev.org/c/openstack/watcher/+/918500

Example stack trace below:

2024-06-01 16:58:29.918774 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 INFO [alembic.runtime.migration] Context impl SQLiteImpl.
2024-06-01 16:58:29.918801 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 INFO [alembic.runtime.migration] Will assume non-transactional DDL.
2024-06-01 16:58:29.918830 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 INFO [alembic.runtime.migration] Running upgrade -> 001, ocata release
2024-06-01 16:58:29.918852 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 INFO [alembic.runtime.migration] Running upgrade 001 -> 0f6042416884, Add apscheduler_jobs table to store background jobs
2024-06-01 16:58:29.919273 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 INFO [alembic.runtime.migration] Running upgrade 0f6042416884 -> d098df6021e2, Add cron support for audit table
2024-06-01 16:58:29.919326 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 CRITI [python-watcher] Unhandled error
2024-06-01 16:58:29.919361 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 Traceback (most recent call last):
2024-06-01 16:58:29.919390 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1910, in _execute_context
2024-06-01 16:58:29.919416 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 self.dialect.do_execute(
2024-06-01 16:58:29.919837 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/sqlalchemy/engine/default.py", line 736, in do_execute
2024-06-01 16:58:29.919866 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 cursor.execute(statement, parameters)
2024-06-01 16:58:29.919881 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 sqlite3.OperationalError: near "ALTER": syntax error
2024-06-01 16:58:29.919905 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60
2024-06-01 16:58:29.919922 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 The above exception was the direct cause of the following exception:
2024-06-01 16:58:29.919936 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60
2024-06-01 16:58:29.921865 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 Traceback (most recent call last):
2024-06-01 16:58:29.921930 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/bin/watcher-db-manage", line 10, in <module>
2024-06-01 16:58:29.921963 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 sys.exit(main())
2024-06-01 16:58:29.921984 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/watcher/cmd/dbmanage.py", line 157, in main
2024-06-01 16:58:29.921998 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 CONF.command.func()
2024-06-01 16:58:29.922539 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/watcher/cmd/dbmanage.py", line 38, in upgrade
2024-06-01 16:58:29.922659 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 migration.upgrade(CONF.command.revision)
2024-06-01 16:58:29.922699 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/watcher/db/migration.py", line 36, in upgrade
2024-06-01 16:58:29.922731 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 return get_backend().upgrade(version)
2024-06-01 16:58:29.922763 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/watcher/db/sqlalchemy/migration.py", line 57, in upgrade
2024-06-01 16:58:29.922794 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 alembic.command.upgrade(config, revision)
2024-06-01 16:58:29.923468 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/command.py", line 403, in upgrade
2024-06-01 16:58:29.923523 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 script.run_env()
2024-06-01 16:58:29.923570 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/script/base.py", line 583, in run_env
2024-06-01 16:58:29.923587 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 util.load_python_file(self.dir, "env.py")
2024-06-01 16:58:29.923601 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/util/pyfiles.py", line 95, in load_python_file
2024-06-01 16:58:29.923752 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 module = load_module_py(module_id, path)
2024-06-01 16:58:29.923779 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/util/pyfiles.py", line 113, in load_module_py
2024-06-01 16:58:29.923793 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 spec.loader.exec_module(module) # type: ignore
2024-06-01 16:58:29.923807 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "<frozen importlib._bootstrap_external>", line 883, in exec_module
2024-06-01 16:58:29.923821 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
2024-06-01 16:58:29.924427 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/watcher/db/sqlalchemy/alembic/env.py", line 54, in <module>
2024-06-01 16:58:29.924457 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 run_migrations_online()
2024-06-01 16:58:29.924473 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/watcher/db/sqlalchemy/alembic/env.py", line 51, in run_migrations_online
2024-06-01 16:58:29.924488 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 context.run_migrations()
2024-06-01 16:58:29.924502 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "<string>", line 8, in run_migrations
2024-06-01 16:58:29.925251 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/runtime/environment.py", line 948, in run_migrations
2024-06-01 16:58:29.925318 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 self.get_context().run_migrations(**kw)
2024-06-01 16:58:29.925363 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/runtime/migration.py", line 627, in run_migrations
2024-06-01 16:58:29.925422 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 step.migration_fn(**kw)
2024-06-01 16:58:29.925451 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/watcher/db/sqlalchemy/alembic/versions/d098df6021e2_cron_support_for_audit.py", line 17, in upgrade
2024-06-01 16:58:29.925912 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 op.alter_column('audits', 'interval', existing_type=sa.String(36),
2024-06-01 16:58:29.925943 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "<string>", line 8, in alter_column
2024-06-01 16:58:29.925974 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "<string>", line 3, in alter_column
2024-06-01 16:58:29.925992 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/operations/ops.py", line 1943, in alter_column
2024-06-01 16:58:29.926011 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 return operations.invoke(alt)
2024-06-01 16:58:29.926467 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/operations/base.py", line 445, in invoke
2024-06-01 16:58:29.926520 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 return fn(self, operation)
2024-06-01 16:58:29.926557 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/operations/toimpl.py", line 53, in alter_column
2024-06-01 16:58:29.926657 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 operations.impl.alter_column(
2024-06-01 16:58:29.926693 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/ddl/impl.py", line 241, in alter_column
2024-06-01 16:58:29.926723 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 self._exec(
2024-06-01 16:58:29.927343 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/alembic/ddl/impl.py", line 207, in _exec
2024-06-01 16:58:29.927404 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 return conn.execute(construct, multiparams)
2024-06-01 16:58:29.927431 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1385, in execute
2024-06-01 16:58:29.927456 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 return meth(self, multiparams, params, _EMPTY_EXECUTION_OPTS)
2024-06-01 16:58:29.927481 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/sqlalchemy/sql/ddl.py", line 80, in _execute_on_connection
2024-06-01 16:58:29.927945 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 return connection._execute_ddl(
2024-06-01 16:58:29.928006 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1477, in _execute_ddl
2024-06-01 16:58:29.928082 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 ret = self._execute_context(
2024-06-01 16:58:29.928116 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1953, in _execute_context
2024-06-01 16:58:29.928146 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 self._handle_dbapi_exception(
2024-06-01 16:58:29.928629 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 2132, in _handle_dbapi_exception
2024-06-01 16:58:29.928670 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 util.raise_(newraise, with_traceback=exc_info[2], from_=e)
2024-06-01 16:58:29.928700 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/sqlalchemy/util/compat.py", line 211, in raise_
2024-06-01 16:58:29.928734 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 raise exception
2024-06-01 16:58:29.928760 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1910, in _execute_context
2024-06-01 16:58:29.929397 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 self.dialect.do_execute(
2024-06-01 16:58:29.929457 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 File "/usr/lib/python3/dist-packages/sqlalchemy/engine/default.py", line 736, in do_execute
2024-06-01 16:58:29.929526 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 cursor.execute(statement, parameters)
2024-06-01 16:58:29.929565 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) near "ALTER": syntax error
2024-06-01 16:58:29.929591 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 [SQL: ALTER TABLE audits ALTER COLUMN interval DROP NOT NULL]
2024-06-01 16:58:29.929615 | focal-medium | 2024-06-01 16:58:29 [ERROR] unit-watcher-0.log: 2024-06-01 16:58:17 WARNING unit.watcher/0.shared-db-relation-changed logger.go:60 (Background on this error at: https://sqlalche.me/e/14/e3q8)

[James Page (james-page)]

Digging into this further as the autopkgtests for this package validate the db migrations against MySQL so I'm surprised they fail.