diff --git a/apps/desktop/src/backend/DesktopBackendManager.test.ts b/apps/desktop/src/backend/DesktopBackendManager.test.ts index 3126d12a2e938..e96e036b0c88b 100644 --- a/apps/desktop/src/backend/DesktopBackendManager.test.ts +++ b/apps/desktop/src/backend/DesktopBackendManager.test.ts @@ -5,6 +5,11 @@ import { type DesktopBackendBootstrap as DesktopBackendBootstrapValue, DesktopTelemetryControlMessage, } from "@t3tools/contracts"; +import { + DATABASE_MIGRATION_PROGRESS_MESSAGE, + DATABASE_MIGRATIONS_FINISHED_MESSAGE, + DATABASE_MIGRATIONS_STARTED_MESSAGE, +} from "@t3tools/shared/databaseMigrationLog"; import { assert, describe, it } from "@effect/vitest"; import * as Deferred from "effect/Deferred"; import * as Duration from "effect/Duration"; @@ -688,12 +693,21 @@ describe("DesktopBackendManager", () => { Effect.scoped( Effect.gen(function* () { const reports = yield* Queue.unbounded(); - const startInstance = (status: Ref.Ref, onReady?: Effect.Effect) => + const startInstance = ( + status: Ref.Ref, + onReady?: Effect.Effect, + stdout = "", + ) => makeTestInstance({ spawnerLayer: Layer.succeed( ChildProcessSpawner.ChildProcessSpawner, ChildProcessSpawner.make(() => - Effect.succeed(makeProcess({ exitCode: Effect.never })), + Effect.succeed( + makeProcess({ + exitCode: Effect.never, + stdout: Stream.make(new TextEncoder().encode(stdout)), + }), + ), ), ), httpClientLayer: layerHttpClient((request) => @@ -712,7 +726,30 @@ describe("DesktopBackendManager", () => { yield* Deferred.await(ready); assert.isTrue(Option.isNone(yield* Queue.poll(reports))); - yield* startInstance(yield* Ref.make(503)); + const migratingStatus = yield* Ref.make(503); + const migrated = yield* Deferred.make(); + yield* startInstance( + migratingStatus, + Deferred.succeed(migrated, undefined).pipe(Effect.asVoid), + // Enough progress lines that the start line scrolls out of the output tail. + `INFO ${DATABASE_MIGRATIONS_STARTED_MESSAGE}\n` + + Array.from( + { length: 80 }, + (_, index) => + `INFO ${DATABASE_MIGRATION_PROGRESS_MESSAGE} migration=${index}_Migration progress="${index + 1} of 80"\n`, + ).join(""), + ); + yield* TestClock.adjust(Duration.minutes(10)); + assert.isTrue(Option.isNone(yield* Queue.poll(reports))); + yield* Ref.set(migratingStatus, 200); + yield* TestClock.adjust(Duration.millis(100)); + yield* Deferred.await(migrated); + + yield* startInstance( + yield* Ref.make(503), + undefined, + `${DATABASE_MIGRATIONS_STARTED_MESSAGE}\n${DATABASE_MIGRATIONS_FINISHED_MESSAGE}\n`, + ); yield* TestClock.adjust(Duration.seconds(179)); assert.isTrue(Option.isNone(yield* Queue.poll(reports))); yield* TestClock.adjust(Duration.seconds(1)); diff --git a/apps/desktop/src/backend/DesktopBackendManager.ts b/apps/desktop/src/backend/DesktopBackendManager.ts index d24b2f52f295c..970ff2001d399 100644 --- a/apps/desktop/src/backend/DesktopBackendManager.ts +++ b/apps/desktop/src/backend/DesktopBackendManager.ts @@ -25,6 +25,7 @@ import { DesktopTelemetryControlMessage, type DesktopTelemetryControlMessage as DesktopTelemetryControlMessageValue, } from "@t3tools/contracts"; +import { isRunningDatabaseMigrations } from "@t3tools/shared/databaseMigrationLog"; import { waitForHttpReady as waitForHttpReadyShared } from "@t3tools/shared/httpReadiness"; import * as DesktopObservability from "../app/DesktopObservability.ts"; @@ -971,6 +972,12 @@ export const makeBackendInstance = Effect.fn("makeBackendInstance")(function* ( }), onReadinessFailure: Effect.fn("desktop.backendInstance.onReadinessFailure")( function* (error) { + if (isRunningDatabaseMigrations(yield* Ref.get(outputTail))) { + yield* logInstanceWarning("backend is still migrating its database; waiting", { + error: error.message, + }); + return; + } yield* logInstanceWarning("backend readiness check failed during bootstrap", { error: error.message, }); diff --git a/apps/server/src/persistence/Migrations.ts b/apps/server/src/persistence/Migrations.ts index 8b33ba60f8e9a..d89297bd7aeb0 100644 --- a/apps/server/src/persistence/Migrations.ts +++ b/apps/server/src/persistence/Migrations.ts @@ -1,6 +1,11 @@ import * as Migrator from "effect/sql/Migrator"; import * as Effect from "effect/Effect"; import * as SqlClient from "effect/sql/SqlClient"; +import { + DATABASE_MIGRATION_PROGRESS_MESSAGE, + DATABASE_MIGRATIONS_FINISHED_MESSAGE, + DATABASE_MIGRATIONS_STARTED_MESSAGE, +} from "@t3tools/shared/databaseMigrationLog"; import { reconcileV2PreviewMigration } from "./reconcileV2PreviewMigration.ts"; import Migration0001 from "./Migrations/001_OrchestrationEvents.ts"; @@ -262,6 +267,8 @@ export interface RunMigrationsOptions { export const runMigrations = Effect.fn("runMigrations")(function* ({ toMigrationInclusive, }: RunMigrationsOptions = {}) { + // The desktop waits past its readiness budget until the finished line follows this one. + if (yield* hasPendingMigrations()) yield* Effect.log(DATABASE_MIGRATIONS_STARTED_MESSAGE); const includesV2 = toMigrationInclusive === undefined || toMigrationInclusive >= FIRST_V2_MIGRATION_ID; const previewMigrations = includesV2 ? yield* reconcileV2PreviewMigration() : []; @@ -288,7 +295,7 @@ export const runMigrations = Effect.fn("runMigrations")(function* ({ const executedMigrations: Array = [...previewMigrations]; for (const [index, [id, name]] of pending.entries()) { if (latestRecordedId > 0) { - yield* Effect.log("Upgrading database").pipe( + yield* Effect.log(DATABASE_MIGRATION_PROGRESS_MESSAGE).pipe( Effect.annotateLogs({ migration: `${id}_${name}`, progress: `${index + 1} of ${pending.length}`, @@ -300,7 +307,7 @@ export const runMigrations = Effect.fn("runMigrations")(function* ({ const migrations = executedMigrations.map(([id, name]) => `${id}_${name}`); yield* migrations.length === 0 ? Effect.logDebug("Database schema is current") - : Effect.log("Migrations ran successfully").pipe(Effect.annotateLogs({ migrations })); + : Effect.log(DATABASE_MIGRATIONS_FINISHED_MESSAGE).pipe(Effect.annotateLogs({ migrations })); const recorded = yield* sql<{ readonly migration_id: number; diff --git a/packages/shared/package.json b/packages/shared/package.json index f5f769236f906..9df772f66d238 100644 --- a/packages/shared/package.json +++ b/packages/shared/package.json @@ -367,6 +367,10 @@ "types": "./src/testing/symlinks.ts", "import": "./src/testing/symlinks.ts" }, + "./databaseMigrationLog": { + "types": "./src/databaseMigrationLog.ts", + "import": "./src/databaseMigrationLog.ts" + }, "./httpReadiness": { "types": "./src/httpReadiness.ts", "import": "./src/httpReadiness.ts" diff --git a/packages/shared/src/databaseMigrationLog.ts b/packages/shared/src/databaseMigrationLog.ts new file mode 100644 index 0000000000000..7adc4e4a6c84c --- /dev/null +++ b/packages/shared/src/databaseMigrationLog.ts @@ -0,0 +1,14 @@ +// The server logs these around pending migrations; the desktop reads them from its output tail, +// which keeps only the last few thousand characters, so each progress line also marks a running upgrade. +export const DATABASE_MIGRATIONS_STARTED_MESSAGE = "Running database migrations"; +export const DATABASE_MIGRATION_PROGRESS_MESSAGE = "Upgrading database"; +export const DATABASE_MIGRATIONS_FINISHED_MESSAGE = "Migrations ran successfully"; + +export function isRunningDatabaseMigrations(output: string): boolean { + return ( + Math.max( + output.lastIndexOf(DATABASE_MIGRATIONS_STARTED_MESSAGE), + output.lastIndexOf(DATABASE_MIGRATION_PROGRESS_MESSAGE), + ) > output.lastIndexOf(DATABASE_MIGRATIONS_FINISHED_MESSAGE) + ); +}