[codex] Improve deploy migration logging

.github/workflows/deploy-web-stack.yml

@@ -385,7 +385,16 @@ jobs:
         run: |
           migration_output_file="$RUNNER_TEMP/migrate.log"
           migration_container="${STACK_NAME}_migrate_${GITHUB_RUN_ID}_${GITHUB_RUN_ATTEMPT}"
+          migration_log_pid=""
+          stop_migration_log_stream() {
+            if [ -n "$migration_log_pid" ] && kill -0 "$migration_log_pid" >/dev/null 2>&1; then
+              kill "$migration_log_pid" >/dev/null 2>&1 || true
+              wait "$migration_log_pid" >/dev/null 2>&1 || true
+            fi
+            migration_log_pid=""
+          }
           cleanup_migration_container() {
+            stop_migration_log_stream
             timeout 60s docker rm -f "$migration_container" >/dev/null 2>&1 || true
           }
           trap cleanup_migration_container EXIT
@@ -399,6 +408,10 @@ jobs:
             "ghcr.io/asherlc/dofek:${IMAGE_TAG}" \
             -euc 'export DATABASE_URL="postgres://health:${POSTGRES_PASSWORD}@db:5432/health"; export CLICKHOUSE_URL="http://default:${CLICKHOUSE_PASSWORD_ENCODED}@clickhouse:8123"; exec node --experimental-transform-types --enable-source-maps --disable-warning=ExperimentalWarning src/db/run-migrate.ts'
 
+          echo "Streaming migration container logs..."
+          docker logs --follow "$migration_container" &
+          migration_log_pid=$!
+
           migration_timeout_seconds=3300
           migration_start_seconds=$SECONDS
           while true; do
@@ -437,6 +450,7 @@ jobs:
             sleep 15
           done
 
+          stop_migration_log_stream
           timeout 60s docker logs "$migration_container" >"$migration_output_file" 2>&1 || true
           if [ "$migration_exit_code" -eq 0 ]; then
             echo "Migration succeeded."

docs/production-incident-baseline.md

@@ -3391,3 +3391,57 @@ documented late-data refresh strategy.
 - Evaluate a ClickHouse materialized view or scheduled read model if RHR query
   latency rises under dashboard load.
 - Assign an analytics owner and review the mitigation by 2026-05-21.
+
+## 2026-05-08: Production Migration Log Blind Spot
+
+### Symptoms
+
+The production deploy workflow reached `Run migrations` and printed only
+periodic status lines like `Migration still running after 219s...`.
+
+### User Impact
+
+The deploy was blocked before the swarm rollout. Operators could not tell from
+the GitHub Actions log whether the migration was making progress, waiting on a
+lock, or stuck in ClickHouse work.
+
+### Evidence
+
+The migration container `dofek_migrate_25537950441_1` was still running. Its
+logs showed the last visible migration step was
+`Applying: 0017_drop_derived_resting_heart_rate.sql`. Postgres activity showed
+`DROP VIEW IF EXISTS fitness.derived_resting_heart_rate;` waiting on a relation
+lock while three long-running old-web queries continued reading
+`fitness.derived_resting_heart_rate`.
+
+### Root Cause
+
+The workflow started the migration container in detached mode and only fetched
+container logs after completion or timeout. That hid useful live progress and
+lock-wait context during long-running migrations.
+
+### Fix or Mitigation
+
+Stream migration container logs with `docker logs --follow` while polling the
+container state. Add explicit Postgres and ClickHouse migration phase logs,
+including pending migration counts, advisory-lock acquisition, ClickHouse
+migration IDs, and metric-stream backfill ranges.
+
+### Remaining Risk
+
+The improved logging does not prevent DDL from waiting behind long-running app
+queries. Future destructive migrations should use expand/contract or
+post-deploy sequencing so old app versions stop referencing the object before
+the migration drops it.
+
+### Follow-Up Work
+
+- Owner: Asher. Merge the deploy workflow log-streaming and migration phase-log
+  fix by 2026-05-09.
+- Owner: Asher. Document the migration lock investigation steps and
+  expand/contract rule in the deploy runbook by 2026-05-15.
+- Owner: Asher. Review long-running dashboard and personalization queries that
+  still use Postgres read paths and move analytics-heavy work to ClickHouse
+  where the required read models already exist by 2026-05-22.
+- Owner: Asher. Add a workflow test or shellcheck-style coverage for detached
+  migration container log streaming by 2026-05-22.

src/db/clickhouse-migrations.ts

@@ -1,5 +1,6 @@
 import { Client, escapeIdentifier } from "pg";
 import { z } from "zod";
+import { logger } from "../logger.ts";
 import {
   buildClickHouseBootstrapStatements,
   type ClickHouseCommandClient,
@@ -202,6 +203,7 @@ ORDER BY id`,
       continue;
     }
 
+    logger.info(`[migrate] Applying ClickHouse migration: ${migration.id}`);
     if ("statements" in migration) {
       for (const statement of migration.statements) {
         await runClickHouseMigrationStatement(client, statement);
@@ -212,6 +214,7 @@ ORDER BY id`,
     await client.command({
       query: `INSERT INTO analytics.schema_migrations (id) VALUES (${migrationId})`,
     });
+    logger.info(`[migrate] Applied ClickHouse migration: ${migration.id}`);
     appliedCount += 1;
   }
 
@@ -329,9 +332,13 @@ async function backfillNativeMetricStream(
   client: ClickHouseCommandClient,
   postgresConnectionString: string,
 ): Promise<void> {
+  logger.info("[migrate] Waiting for ClickHouse postgres_fitness.metric_stream table");
   await waitForClickHouseTable(client, "postgres_fitness", "metric_stream");
   const timescaleChunks = await fetchMetricStreamBackfillChunks(postgresConnectionString);
   const backfillRanges = timescaleChunks.flatMap(splitMetricStreamBackfillChunk);
+  logger.info(
+    `[migrate] ClickHouse metric_stream backfill has ${backfillRanges.length} range(s) from ${timescaleChunks.length} Timescale chunk(s)`,
+  );
   if (backfillRanges.length === 0) {
     return;
   }
@@ -348,7 +355,7 @@ ENGINE = MergeTree
 ORDER BY (lower_bound, upper_bound)`,
   });
 
-  for (const backfillRange of backfillRanges) {
+  for (const [rangeIndex, backfillRange] of backfillRanges.entries()) {
     if (
       await isMetricStreamBackfillChunkComplete(
         client,
@@ -358,6 +365,9 @@ ORDER BY (lower_bound, upper_bound)`,
     ) {
       continue;
     }
+    logger.info(
+      `[migrate] Backfilling ClickHouse metric_stream range ${rangeIndex + 1}/${backfillRanges.length}: ${backfillRange.lowerBound.toISOString()} to ${backfillRange.upperBound.toISOString()}`,
+    );
     await client.command({
       query: buildMetricStreamBackfillStatement(
         postgresMetricStreamSource,
@@ -370,6 +380,7 @@ ORDER BY (lower_bound, upper_bound)`,
 VALUES (${clickHouseDateTimeLiteral(backfillRange.lowerBound)}, ${clickHouseDateTimeLiteral(backfillRange.upperBound)})`,
     });
   }
+  logger.info("[migrate] ClickHouse metric_stream backfill complete");
 }
 
 function splitMetricStreamBackfillChunk(

src/db/migrate.ts

@@ -56,9 +56,12 @@ export async function runMigrations(databaseUrl: string, migrationsDir?: string)
   let lockAcquired = false;
 
   try {
+    logger.info("[migrate] Connecting to Postgres");
     await client.connect();
+    logger.info("[migrate] Waiting for Postgres migration advisory lock");
     await client.query("SELECT pg_advisory_lock($1)", [MIGRATION_LOCK_KEY]);
     lockAcquired = true;
+    logger.info("[migrate] Acquired Postgres migration advisory lock");
 
     await client.query("CREATE SCHEMA IF NOT EXISTS health");
     await client.query("CREATE SCHEMA IF NOT EXISTS drizzle");
@@ -82,6 +85,9 @@ export async function runMigrations(databaseUrl: string, migrationsDir?: string)
     );
     const applied = appliedResult.rows;
     const appliedSet = new Set(applied.map((row) => row.hash));
+    logger.info(
+      `[migrate] Found ${files.length} Postgres migration file(s), ${appliedSet.size} already applied`,
+    );
 
     // Detect in-place edits to already-applied migration files
     for (const row of applied) {
@@ -146,6 +152,7 @@ export async function runMigrations(databaseUrl: string, migrationsDir?: string)
     }
 
     let count = 0;
+    logger.info(`[migrate] ${pendingFiles.length} pending Postgres migration(s)`);
     for (const file of pendingFiles) {
       logger.info(`[migrate] Applying: ${file}`);
       const content = readFileSync(join(dir, file), "utf-8");

src/db/run-migrate.test.ts

@@ -104,7 +104,7 @@ describe("run-migrate main()", () => {
     );
     expect(clickHouseClient.close).toHaveBeenCalled();
     expect(mockLogger.info).toHaveBeenCalledWith(
-      expect.stringContaining("1 ClickHouse migration(s) applied"),
+      expect.stringContaining("ClickHouse migrations complete — 1 migration(s) applied"),
     );
   });
 

src/db/run-migrate.ts

@@ -15,15 +15,19 @@ export async function main(): Promise<void> {
     throw new Error("CLICKHOUSE_URL environment variable is required");
   }
 
+  logger.info("[migrate] Starting Postgres migrations");
   const count = await runMigrations(databaseUrl);
-  logger.info(`[migrate] Done — ${count} migration(s) applied`);
+  logger.info(`[migrate] Postgres migrations complete — ${count} migration(s) applied`);
 
+  logger.info("[migrate] Starting ClickHouse migrations");
   const clickHouseClient = createClickHouseClientFromEnv(process.env, {
     requestTimeoutMs: CLICKHOUSE_MIGRATION_REQUEST_TIMEOUT_MS,
   });
   try {
     const clickHouseCount = await runClickHouseMigrations(clickHouseClient, databaseUrl);
-    logger.info(`[migrate] Done — ${clickHouseCount} ClickHouse migration(s) applied`);
+    logger.info(
+      `[migrate] ClickHouse migrations complete — ${clickHouseCount} migration(s) applied`,
+    );
   } finally {
     await clickHouseClient.close?.();
   }