From 23a70913c3b1e470ef98f8fe0baccbfb0eeb272c Mon Sep 17 00:00:00 2001 From: badcuban <108198679+badcuban@users.noreply.github.com> Date: Sun, 6 Sep 2026 00:42:36 -0400 Subject: [PATCH] fix(desktop): a slow database migration no longer counts as a failed start The desktop kills a backend that has not answered its readiness probe within 60 seconds of a first launch. The SQLite driver is synchronous, so a backend inside a long migration statement cannot answer anything, and it looked exactly like a hung process: the run was killed, the migration transaction rolled back, and "Try Again" repeated the same work forever. That is how nightly .275 bricked startup on large databases (#234). The server now logs each migration as it starts and finishes, with its duration, using two message prefixes shared through contracts. At the readiness deadline the desktop reads its captured backend output: if a "Running migration" line has no matching "Finished migration" line, it keeps probing without a deadline and shows a small info box saying which database update is running, with Keep Waiting and Quit. The box closes on its own when the backend answers or the run ends. Without an unfinished migration the 60-second kill is unchanged. Message boxes now receive the fiber's abort signal, so an interrupted dialog closes instead of lingering. --- .../src/backend/DesktopBackendManager.test.ts | 99 +++++++++++++- .../src/backend/DesktopBackendManager.ts | 128 +++++++++++++++--- apps/desktop/src/electron/ElectronDialog.ts | 5 +- .../src/window/DesktopStartupFailurePrompt.ts | 47 ++++++- apps/server/src/persistence/Migrations.ts | 36 ++++- packages/contracts/src/desktopBootstrap.ts | 14 ++ 6 files changed, 306 insertions(+), 23 deletions(-) diff --git a/apps/desktop/src/backend/DesktopBackendManager.test.ts b/apps/desktop/src/backend/DesktopBackendManager.test.ts index 835c500ff..61c3a1777 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 05c46600d..221b538c2 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 172974f48..9171b38c3 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 7f3126036..6aa4b5508 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 258844f8b..9b7a34c12 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 92073487d..f85cbf400 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 ";