Add logging to update-db-schema CLI command

Configure Alembic logging in alembic.ini so migrations emit INFO-level
output, and add structured log messages to the update_db_schema command
that report current and target revisions before and after migration.

Author: jonathansick

alembic.ini

@@ -12,3 +12,36 @@ ruff_check.options = check --fix REVISION_SCRIPT_FILENAME
 ruff_format.type = exec
 ruff_format.executable = ruff
 ruff_format.options = format REVISION_SCRIPT_FILENAME
+
+[loggers]
+keys = root,sqlalchemy,alembic
+
+[handlers]
+keys = console
+
+[formatters]
+keys = generic
+
+[logger_root]
+level = WARN
+handlers = console
+
+[logger_sqlalchemy]
+level = WARN
+handlers =
+qualname = sqlalchemy.engine
+
+[logger_alembic]
+level = INFO
+handlers =
+qualname = alembic
+
+[handler_console]
+class = StreamHandler
+args = (sys.stderr,)
+level = NOTSET
+formatter = generic
+
+[formatter_generic]
+format = %(levelname)-5.5s [%(name)s] %(message)s
+datefmt = %H:%M:%S

src/docverse/cli.py

@@ -9,12 +9,17 @@
 
 import click
 import structlog
+from alembic.config import Config
+from alembic.runtime.migration import MigrationContext
+from alembic.script import ScriptDirectory
 from safir.database import (
     create_database_engine,
     is_database_current,
     stamp_database,
 )
 from safir.logging import configure_logging
+from sqlalchemy import Connection
+from sqlalchemy.ext.asyncio import AsyncEngine
 
 from .config import config
 from .database import init_database
@@ -85,12 +90,39 @@ def init(*, alembic_config_path: Path, reset: bool) -> None:
 )
 def update_db_schema(*, alembic_config_path: Path) -> None:
     """Update the SQL database schema."""
+    logger = structlog.get_logger("docverse")
+
+    engine = create_database_engine(
+        config.database_url, config.database_password
+    )
+
+    # Get current and target revisions
+    alembic_config = Config(str(alembic_config_path))
+    alembic_scripts = ScriptDirectory.from_config(alembic_config)
+    head_rev = alembic_scripts.get_current_head()
+    current_rev = asyncio.run(_get_current_revision(engine))
+
+    logger.info(
+        "Starting database schema update",
+        current_revision=current_rev,
+        target_revision=head_rev,
+    )
+
     subprocess.run(
         ["alembic", "upgrade", "head"],
         check=True,
         cwd=str(alembic_config_path.parent),
     )
 
+    new_rev = asyncio.run(_get_current_revision(engine))
+    asyncio.run(engine.dispose())
+
+    logger.info(
+        "Database schema update complete",
+        previous_revision=current_rev,
+        current_revision=new_rev,
+    )
+
 
 @main.command()
 @click.option(
@@ -110,3 +142,18 @@ def validate_db_schema(*, alembic_config_path: Path) -> None:
     ):
         msg = "Database schema is not current"
         raise click.ClickException(msg)
+
+
+async def _get_current_revision(engine: AsyncEngine) -> str | None:
+    """Get the current Alembic revision from the database."""
+
+    def _get_heads(connection: Connection) -> set[str]:
+        context = MigrationContext.configure(connection)
+        return set(context.get_current_heads())
+
+    async with engine.begin() as connection:
+        heads = await connection.run_sync(_get_heads)
+    # Return single revision or comma-joined if multiple heads
+    if not heads:
+        return None
+    return ",".join(sorted(heads))