diff --git a/apps/desktop/src/backend/DesktopBackendManager.test.ts b/apps/desktop/src/backend/DesktopBackendManager.test.ts index 835c500f..61c3a177 100644 --- a/apps/desktop/src/backend/DesktopBackendManager.test.ts +++ b/apps/desktop/src/backend/DesktopBackendManager.test.ts @@ -138,6 +138,7 @@ function makeManagerLayer(input: { Layer.succeed(DesktopStartupFailurePrompt.DesktopStartupFailurePrompt, { handle: () => Effect.die("unexpected startup failure prompt"), notifyDatabaseRecovery: () => Effect.void, + notifyMigrationInProgress: () => Effect.die("unexpected migration notice"), ...input.startupFailurePrompt, }), Layer.succeed(DesktopDatabaseRecovery.DesktopDatabaseRecovery, { @@ -868,9 +869,14 @@ describe("DesktopBackendManager", () => { return makeProcess({ // The fatal cause lands on stdout, like the server's Effect // logger; stderr carries a secondary line. Both must reach - // the crash-report tail. + // the crash-report tail. The migration that ran here already + // reported finishing, so it must not buy this run more time. stdout: Stream.make( - new TextEncoder().encode("[FATAL] EADDRINUSE: port already bound\n"), + new TextEncoder().encode( + "[00:00:01.100] INFO (#42): Running migration 50_ProjectionTranscriptEventSequence (50 of 51)\n" + + "[00:00:09.244] INFO (#42): Finished migration 50_ProjectionTranscriptEventSequence in 8s 144ms\n" + + "[FATAL] EADDRINUSE: port already bound\n", + ), ), stderr: Stream.make(new TextEncoder().encode("node exited\n")), exitCode: Deferred.await(closed).pipe(Effect.as(ChildProcessSpawner.ExitCode(143))), @@ -910,6 +916,95 @@ describe("DesktopBackendManager", () => { }), ); + it.effect( + "keeps waiting and shows the migration notice when the backend is mid-migration at the readiness deadline", + () => + Effect.gen(function* () { + const noticeInfo = yield* Queue.unbounded<{ + readonly migrationId: number; + readonly totalMigrations: number; + }>(); + const noticeClosed = yield* Deferred.make(); + const windowOpened = yield* Deferred.make(); + const answersReadiness = yield* Ref.make(false); + const terminations = yield* Ref.make(0); + + const spawnerLayer = Layer.succeed( + ChildProcessSpawner.ChildProcessSpawner, + ChildProcessSpawner.make(() => + Effect.gen(function* () { + const scope = yield* Scope.Scope; + const closed = yield* Deferred.make(); + const close = Ref.update(terminations, (count) => count + 1).pipe( + Effect.andThen(Deferred.succeed(closed, void 0)), + Effect.asVoid, + ); + yield* Scope.addFinalizer(scope, close); + return makeProcess({ + stdout: Stream.make( + new TextEncoder().encode( + "[00:00:01.000] INFO (#42): Running all migrations...\n", + ), + new TextEncoder().encode( + "[00:00:01.100] INFO (#42): Running migration 50_ProjectionTranscriptEventSequence (50 of 51)\n", + ), + ), + exitCode: Deferred.await(closed).pipe(Effect.as(ChildProcessSpawner.ExitCode(0))), + kill: () => close, + }); + }), + ), + ); + + const managerLayer = makeManagerLayer({ + spawnerLayer, + httpClientLayer: httpClientLayer((request) => + Effect.flatMap(Ref.get(answersReadiness), (ready) => + ready ? Effect.succeed(responseForRequest(request, 200)) : Effect.never, + ), + ), + startupFailurePrompt: { + notifyMigrationInProgress: (info) => + Queue.offer(noticeInfo, info).pipe( + Effect.andThen( + Effect.never.pipe( + Effect.onInterrupt(() => + Deferred.succeed(noticeClosed, void 0).pipe(Effect.asVoid), + ), + ), + ), + ), + }, + desktopWindow: { + handleBackendReady: Deferred.succeed(windowOpened, void 0).pipe(Effect.asVoid), + }, + }); + + yield* Effect.gen(function* () { + const manager = yield* DesktopBackendManager.DesktopBackendManager; + yield* manager.start; + + // The 60s budget elapses while migration 50 of 51 is still running. + // The backend is busy, not hung, so it must survive the deadline. + yield* TestClock.adjust(Duration.minutes(1)); + assert.deepEqual(yield* Queue.take(noticeInfo), { + migrationId: 50, + totalMigrations: 51, + }); + assert.equal(yield* Ref.get(terminations), 0); + + // Once the migration finishes the backend answers, and the notice + // closes itself instead of outliving the wait. + yield* Ref.set(answersReadiness, true); + yield* TestClock.adjust(Duration.seconds(2)); + yield* Deferred.await(windowOpened); + yield* Deferred.await(noticeClosed); + assert.equal(yield* Ref.get(terminations), 0); + assert.isTrue((yield* manager.snapshot).ready); + }).pipe(Effect.provide(Layer.merge(TestClock.layer(), managerLayer))); + }), + ); + it.effect("keeps restarting without a prompt once the backend has been ready", () => Effect.gen(function* () { const starts = yield* Queue.unbounded(); diff --git a/apps/desktop/src/backend/DesktopBackendManager.ts b/apps/desktop/src/backend/DesktopBackendManager.ts index 05c46600..221b538c 100644 --- a/apps/desktop/src/backend/DesktopBackendManager.ts +++ b/apps/desktop/src/backend/DesktopBackendManager.ts @@ -23,6 +23,8 @@ import { hideWindowsConsole } from "@threadlines/shared/childProcess"; import { DESKTOP_LAUNCH_ID_HEADER, DesktopBackendBootstrap, + MIGRATION_FINISHED_LOG_PREFIX, + MIGRATION_RUNNING_LOG_PREFIX, type DesktopBackendBootstrap as DesktopBackendBootstrapValue, } from "@threadlines/contracts"; @@ -104,17 +106,61 @@ class BackendProcessSpawnError extends Data.TaggedError("BackendProcessSpawnErro type BackendProcessError = BackendProcessBootstrapEncodeError | BackendProcessSpawnError; +/** + * What to do when the readiness deadline passes: give up on this run, or drop + * the deadline and keep probing until the backend answers or the process dies. + */ +export type BackendReadinessTimeoutDecision = "give-up" | "keep-waiting"; + interface RunBackendProcessOptions extends DesktopBackendStartConfig { readonly readinessTimeout?: Duration.Duration; readonly onStarted?: (pid: number) => Effect.Effect; readonly onReady?: () => Effect.Effect; - readonly onReadinessFailure?: (error: BackendTimeoutError) => Effect.Effect; + readonly onReadinessTimeout?: ( + error: BackendTimeoutError, + ) => Effect.Effect; readonly onOutput?: ( streamName: BackendProcessOutputStream, chunk: Uint8Array, ) => Effect.Effect; } +export interface BackendMigrationInProgress { + readonly id: number; + readonly name: string; + readonly total: number; +} + +const MIGRATION_RUNNING_PATTERN = new RegExp( + `${MIGRATION_RUNNING_LOG_PREFIX}(\\d+)_(\\S+) \\((?:\\d+) of (\\d+)\\)`, +); + +/** + * Reads the backend's captured output for a migration that started and has not + * reported finishing. The SQLite driver is synchronous, so nothing else is + * logged while a long statement runs: the last unfinished "Running migration" + * line is the whole story. Lines carry the server's pretty-logger prefix, so + * the match is anywhere in the line. + */ +export function findMigrationInProgress( + outputTail: string, +): Option.Option { + const lines = DesktopStartupFailurePrompt.stripAnsiEscapes(outputTail).split(/\r?\n/); + for (let index = lines.length - 1; index >= 0; index -= 1) { + const match = lines[index]?.match(MIGRATION_RUNNING_PATTERN); + const id = match?.[1]; + const name = match?.[2]; + const total = match?.[3]; + if (id === undefined || name === undefined || total === undefined) { + continue; + } + const finishedMarker = `${MIGRATION_FINISHED_LOG_PREFIX}${id}_${name}`; + const finished = lines.slice(index + 1).some((line) => line.includes(finishedMarker)); + return finished ? Option.none() : Option.some({ id: Number(id), name, total: Number(total) }); + } + return Option.none(); +} + export interface DesktopBackendSnapshot { readonly desiredRunning: boolean; readonly ready: boolean; @@ -135,8 +181,11 @@ export class DesktopBackendManager extends Context.Service< DesktopBackendManagerShape >()("threadlines/desktop/BackendManager") {} -const { logWarning: logBackendManagerWarning, logError: logBackendManagerError } = - DesktopObservability.makeComponentLogger("desktop-backend-manager"); +const { + logInfo: logBackendManagerInfo, + logWarning: logBackendManagerWarning, + logError: logBackendManagerError, +} = DesktopObservability.makeComponentLogger("desktop-backend-manager"); interface ActiveBackendRun { readonly id: number; @@ -328,13 +377,22 @@ const runBackendProcess = Effect.fn("runBackendProcess")(function* ( yield* drainBackendOutput("stderr", handle.stderr, onOutput).pipe(Effect.forkScoped), ); } - yield* waitForHttpReady( - options.httpBaseUrl, - options.readinessTimeout ?? DEFAULT_BACKEND_READINESS_TIMEOUT, - options.bootstrap.desktopLaunchId, - ).pipe( - Effect.tap(() => options.onReady?.() ?? Effect.void), - Effect.catch((error) => options.onReadinessFailure?.(error) ?? Effect.void), + const awaitReady = (timeout: Duration.Duration) => + waitForHttpReady(options.httpBaseUrl, timeout, options.bootstrap.desktopLaunchId).pipe( + Effect.tap(() => options.onReady?.() ?? Effect.void), + ); + yield* awaitReady(options.readinessTimeout ?? DEFAULT_BACKEND_READINESS_TIMEOUT).pipe( + Effect.catch((error) => + (options.onReadinessTimeout?.(error) ?? Effect.succeed("give-up" as const)).pipe( + // "keep-waiting" drops the deadline rather than the probe: if the + // process dies meanwhile, the exit path below ends the run anyway. + Effect.flatMap((decision) => + decision === "keep-waiting" + ? awaitReady(Duration.infinity).pipe(Effect.ignore) + : Effect.void, + ), + ), + ), Effect.forkScoped, ); @@ -500,6 +558,20 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio const stdoutDecoder = new TextDecoder(); const stderrDecoder = new TextDecoder(); const readinessTimeoutRef = yield* Ref.make(Option.none()); + // The "still migrating" dialog belongs to this run: readiness and the + // run ending both close it. + const migrationNoticeRef = yield* Ref.make(Option.none>()); + const closeMigrationNotice = Ref.getAndSet( + migrationNoticeRef, + Option.none>(), + ).pipe( + Effect.flatMap( + Option.match({ + onNone: () => Effect.void, + onSome: (fiber) => Fiber.interrupt(fiber).pipe(Effect.asVoid), + }), + ), + ); const runIdOption = yield* Ref.modify(state, (latest) => latest.intentGeneration === startIntentGeneration && latest.desiredRunning ? ([ @@ -528,6 +600,7 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio exitCode: Option.Option, flushOutput: Effect.Effect, ) { + yield* closeMigrationNotice; const restartAfterRecovery = yield* mutex.withPermits(1)( Effect.gen(function* () { const { isCurrentRun, nextState, pid } = yield* Ref.modify( @@ -735,6 +808,7 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio return; } + yield* closeMigrationNotice; yield* Ref.set(desktopState.backendReady, true); yield* desktopWindow.handleBackendReady.pipe( Effect.catch((error) => @@ -754,24 +828,46 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio ); } }), - onReadinessFailure: (error) => + // Three ways the deadline can pass, and only one of them is a + // failure. Once a window exists, an unresponsive restart is visible + // and recoverable, so keep probing quietly. Before the first window + // a migration still running is healthy work that a kill would only + // make restart from zero, so keep probing and say so. Anything else + // is a process that is alive but unresponsive and would sit + // invisible forever: mark the run and kill it so finalizeRun + // surfaces the failure instead of scheduling a restart. + onReadinessTimeout: (error) => Effect.gen(function* () { yield* logBackendManagerWarning("backend readiness check failed during bootstrap", { error: error.message, }); const latest = yield* Ref.get(state); if (latest.everReady) { - return; + return "keep-waiting" as const; + } + const migration = findMigrationInProgress(yield* Ref.get(outputTailRef)); + if (Option.isSome(migration)) { + yield* logBackendManagerInfo("backend still migrating at readiness deadline", { + migrationId: migration.value.id, + migrationName: migration.value.name, + totalMigrations: migration.value.total, + }); + const noticeFiber = yield* Effect.forkIn( + startupFailurePrompt.notifyMigrationInProgress({ + migrationId: migration.value.id, + totalMigrations: migration.value.total, + }), + parentScope, + ); + yield* Ref.set(migrationNoticeRef, Option.some(noticeFiber)); + return "keep-waiting" as const; } - // Before the first readiness there is no window: a process that - // is alive but unresponsive would sit invisible forever. Mark - // the run and kill it so finalizeRun surfaces the failure - // instead of scheduling a restart. yield* Ref.set(readinessTimeoutRef, Option.some(error)); const run = Option.getOrUndefined(latest.active); if (run?.id === runId) { yield* Effect.forkIn(closeRun(run), parentScope); } + return "give-up" as const; }), onOutput: (streamName, chunk) => backendOutputLog.writeOutputChunk(streamName, chunk).pipe( diff --git a/apps/desktop/src/electron/ElectronDialog.ts b/apps/desktop/src/electron/ElectronDialog.ts index 172974f4..9171b38c 100644 --- a/apps/desktop/src/electron/ElectronDialog.ts +++ b/apps/desktop/src/electron/ElectronDialog.ts @@ -74,7 +74,10 @@ const make = ElectronDialog.of({ }); return result.response === CONFIRM_BUTTON_INDEX; }), - showMessageBox: (options) => Effect.promise(() => Electron.dialog.showMessageBox(options)), + // Interrupting the fiber aborts the signal, which closes the box as if the + // user had cancelled it, so a dialog never outlives the work that showed it. + showMessageBox: (options) => + Effect.promise((signal) => Electron.dialog.showMessageBox({ ...options, signal })), showErrorBox: (title, content) => Effect.sync(() => { Electron.dialog.showErrorBox(title, content); diff --git a/apps/desktop/src/window/DesktopStartupFailurePrompt.ts b/apps/desktop/src/window/DesktopStartupFailurePrompt.ts index 7f312603..6aa4b550 100644 --- a/apps/desktop/src/window/DesktopStartupFailurePrompt.ts +++ b/apps/desktop/src/window/DesktopStartupFailurePrompt.ts @@ -31,6 +31,8 @@ const TRY_AGAIN_BUTTON_INDEX = 0; const OPEN_LOGS_BUTTON_INDEX = 1; const QUIT_BUTTON_INDEX = 2; const OPEN_RECOVERY_FOLDER_BUTTON_INDEX = 1; +const KEEP_WAITING_BUTTON_INDEX = 0; +const MIGRATION_QUIT_BUTTON_INDEX = 1; export type DesktopStartupFailureAction = "retry" | "quit"; @@ -45,6 +47,14 @@ export interface DesktopStartupFailurePromptShape { ) => Effect.Effect; /** Shows where the damaged database was preserved after startup recovers. */ readonly notifyDatabaseRecovery: (result: DesktopDatabaseRecoveryResult) => Effect.Effect; + /** + * Tells the user a database migration is still running at the readiness + * deadline. Closes itself when interrupted. Never fails. + */ + readonly notifyMigrationInProgress: (info: { + readonly migrationId: number; + readonly totalMigrations: number; + }) => Effect.Effect; } export class DesktopStartupFailurePrompt extends Context.Service< @@ -52,9 +62,12 @@ export class DesktopStartupFailurePrompt extends Context.Service< DesktopStartupFailurePromptShape >()("threadlines/desktop/StartupFailurePrompt") {} +/** Drops the colour codes the server's pretty logger writes around its output. */ +export const stripAnsiEscapes = (text: string): string => + text.replaceAll("\u001b", "").replace(/\[[0-9;]*m/g, ""); + function extractStartupFailureCause(outputTail: string): string | undefined { - const normalized = outputTail.replaceAll("\u001b", "").replace(/\[[0-9;]*m/g, ""); - const lines = normalized + const lines = stripAnsiEscapes(outputTail) .split(/\r?\n/) .map((line) => line.trim()) .filter((line) => line.length > 0); @@ -194,7 +207,35 @@ const makeDesktopStartupFailurePrompt = Effect.gen(function* () { }).pipe(Effect.catchCause(() => Effect.void)), ); - return DesktopStartupFailurePrompt.of({ handle, notifyDatabaseRecovery }); + const notifyMigrationInProgress: DesktopStartupFailurePromptShape["notifyMigrationInProgress"] = + Effect.fn("desktop.startupFailurePrompt.notifyMigrationInProgress")((info) => + Effect.gen(function* () { + // The backend owns this dialog's lifetime: when it finally answers, or + // the run ends, the manager interrupts this fiber and the box closes + // by itself (see ElectronDialog.showMessageBox) instead of leaving a + // stale notice on screen. An interrupted fiber never reaches the + // response check below, so a closed box is never read as a choice. + const result = yield* electronDialog.showMessageBox({ + type: "info", + title: `${environment.displayName} is updating its data`, + message: `${environment.displayName} is updating its data`, + detail: `Database update ${info.migrationId} of ${info.totalMigrations} is still running. Large histories can take several minutes, and ${environment.displayName} opens on its own when it finishes.\n\nQuitting now is safe. The update starts over next time.`, + buttons: ["Keep Waiting", "Quit"], + defaultId: KEEP_WAITING_BUTTON_INDEX, + cancelId: KEEP_WAITING_BUTTON_INDEX, + noLink: true, + }); + if (result.response === MIGRATION_QUIT_BUTTON_INDEX) { + yield* electronApp.quit; + } + }).pipe(Effect.catchCause(() => Effect.void)), + ); + + return DesktopStartupFailurePrompt.of({ + handle, + notifyDatabaseRecovery, + notifyMigrationInProgress, + }); }); export const layer = Layer.effect(DesktopStartupFailurePrompt, makeDesktopStartupFailurePrompt); diff --git a/apps/server/src/persistence/Migrations.ts b/apps/server/src/persistence/Migrations.ts index 258844f8..9b7a34c1 100644 --- a/apps/server/src/persistence/Migrations.ts +++ b/apps/server/src/persistence/Migrations.ts @@ -8,7 +8,13 @@ * ensuring the database schema is always up-to-date before the application starts. */ +import { + MIGRATION_FINISHED_LOG_PREFIX, + MIGRATION_RUNNING_LOG_PREFIX, +} from "@threadlines/contracts"; import * as Migrator from "effect/unstable/sql/Migrator"; +import * as Duration from "effect/Duration"; +import * as SqlClient from "effect/unstable/sql/SqlClient"; import * as Layer from "effect/Layer"; import * as Effect from "effect/Effect"; @@ -129,12 +135,40 @@ export const migrationEntries = [ [51, "ProjectionThreadsBlockingUserInput", Migration0051], ] as const; +/** Highest id in the full registry, so the "n of total" count is the real total. */ +const latestMigrationId = migrationEntries.reduce((latest, [id]) => Math.max(latest, id), 0); + +/** + * Wraps one migration so a slow one is attributable in the logs. The SQLite + * driver is synchronous, so a long statement freezes the whole backend: without + * these lines a busy process looks exactly like a hung one, both in support + * logs and to the desktop's readiness watchdog, which reads them back out of + * the backend's stdout. + */ +const withMigrationLogging = ( + id: number, + name: string, + migration: Effect.Effect, +) => + Effect.gen(function* () { + yield* Effect.log( + `${MIGRATION_RUNNING_LOG_PREFIX}${id}_${name} (${id} of ${latestMigrationId})`, + ); + const [duration] = yield* Effect.timed(migration); + yield* Effect.log( + `${MIGRATION_FINISHED_LOG_PREFIX}${id}_${name} in ${Duration.format(duration)}`, + ); + }); + export const makeMigrationLoader = (throughId?: number) => Migrator.fromRecord( Object.fromEntries( migrationEntries .filter(([id]) => throughId === undefined || id <= throughId) - .map(([id, name, migration]) => [`${id}_${name}`, migration]), + .map(([id, name, migration]) => [ + `${id}_${name}`, + withMigrationLogging(id, name, migration), + ]), ), ); diff --git a/packages/contracts/src/desktopBootstrap.ts b/packages/contracts/src/desktopBootstrap.ts index 92073487..f85cbf40 100644 --- a/packages/contracts/src/desktopBootstrap.ts +++ b/packages/contracts/src/desktopBootstrap.ts @@ -26,3 +26,17 @@ export const DesktopBackendBootstrap = Schema.Struct({ export type DesktopBackendBootstrap = typeof DesktopBackendBootstrap.Type; export const DESKTOP_LAUNCH_ID_HEADER = "x-threadlines-desktop-launch-id"; + +/** + * Prefixes of the per-migration log lines the server writes while the database + * schema is being updated. The desktop reads them out of the backend's captured + * output to tell a slow migration apart from a hung process, so the server and + * the desktop share these constants instead of matching on a literal that could + * drift on one side only. + * + * Full line shapes: + * - `Running migration 50_ProjectionTranscriptEventSequence (50 of 51)` + * - `Finished migration 50_ProjectionTranscriptEventSequence in 8s 144ms` + */ +export const MIGRATION_RUNNING_LOG_PREFIX = "Running migration "; +export const MIGRATION_FINISHED_LOG_PREFIX = "Finished migration ";