From 9ac9cf980831b901221d60679a3a67c05cb9178f Mon Sep 17 00:00:00 2001 From: Badcuban <108198679+badcuban@users.noreply.github.com> Date: Fri, 13 Nov 2026 16:35:41 -0500 Subject: [PATCH] fix(desktop): a slow start gets more time and a notice, not "couldn't start" On a first start the app waited 60 seconds for its backend, then killed it and showed "couldn't start", unless a database migration was visibly running. In the field that fired on Windows with the backend alive but slow (2 of 92 installs in 30 days): one start printed nothing for a minute, the next took 15 seconds to check its database, and the third came up fine. Killing it only made the user start the same slow work again. A backend still alive at the deadline now gets a "still starting" notice (Keep Waiting / Quit) and four more minutes. If that runs out too it is given up on as before, and the report names the whole wait. A migration found running at a deadline still keeps the wait going, and the two notices share one slot, so only one is ever up. Where the notice holds the app until answered (macOS), the longer wait starts once it has been, so time spent behind the box does not count. Nothing changes after the app has been ready once, or for a backend that crashes. The first start of each app session also reports how long it took (desktop.backend.started: startupMs, attempts, slowStart), under the same consent as the startup failure report. There was no measure of startup time, so the deadlines were guesses. --- apps/desktop/src/app/DesktopCrashReport.ts | 63 +++- .../src/backend/DesktopBackendManager.test.ts | 321 +++++++++++++++++- .../src/backend/DesktopBackendManager.ts | 148 ++++++-- .../src/window/DesktopStartupFailurePrompt.ts | 43 ++- docs/telemetry.md | 3 + 5 files changed, 531 insertions(+), 47 deletions(-) diff --git a/apps/desktop/src/app/DesktopCrashReport.ts b/apps/desktop/src/app/DesktopCrashReport.ts index d0b144467..3abd247c5 100644 --- a/apps/desktop/src/app/DesktopCrashReport.ts +++ b/apps/desktop/src/app/DesktopCrashReport.ts @@ -1,10 +1,11 @@ /** - * DesktopCrashReport - anonymous startup-failure telemetry for the desktop - * shell. + * DesktopCrashReport - anonymous startup telemetry for the desktop shell. * - * The server owns regular usage analytics, but when the backend never boots - * there is no server to report anything — so the shell sends one sanitized - * event itself. It honors the same consent as the server (`settings.json` + * The server owns regular usage analytics, but two things about startup only + * the shell knows: that the backend never booted (there is no server to say + * so), and how long it took to answer, measured from the moment the shell + * started it. The shell sends one sanitized event for each itself. It honors + * the same consent as the server (`settings.json` * `usageAnalyticsEnabled`, `THREADLINES_TELEMETRY_ENABLED` override, silence * in throwaway runs), reuses * the same anonymous install id file, and never sends raw paths: everything @@ -67,9 +68,25 @@ export interface DesktopStartupFailureReport { readonly outputTail: string; } +/** How a start that reached readiness went; see reportBackendStarted. */ +export interface DesktopBackendStartedReport { + /** From starting the backend process to its first healthy answer. */ + readonly startupMs: number; + /** 1 when the first process made it; more when earlier ones died first. */ + readonly attempts: number; + /** Whether it outlasted the readiness deadline and got the "still starting" notice. */ + readonly slowStart: boolean; +} + export interface DesktopCrashReportShape { /** Best-effort: resolves void on success and on any failure alike. */ readonly reportStartupFailure: (report: DesktopStartupFailureReport) => Effect.Effect; + /** + * How long the app's first start of the backend took. The readiness + * deadline is a guess until this says what starts really cost in the field. + * Best-effort, like reportStartupFailure. + */ + readonly reportBackendStarted: (report: DesktopBackendStartedReport) => Effect.Effect; } export class DesktopCrashReport extends Context.Service< @@ -139,7 +156,8 @@ const makeDesktopCrashReport = Effect.gen(function* () { return persisted ? Option.some(hashIdentifier(generated)) : Option.none(); }); - const reportStartupFailure: DesktopCrashReportShape["reportStartupFailure"] = (report) => + /** Sends one event when telemetry is allowed and the install can be named. */ + const sendEvent = (event: string, properties: Record) => Effect.gen(function* () { // Same env overrides the server's AnalyticsService honors. const posthogKey = process.env.THREADLINES_POSTHOG_KEY?.trim() || bundledPosthogKey.trim(); @@ -165,13 +183,11 @@ const makeDesktopCrashReport = Effect.gen(function* () { const identifier = yield* getIdentifier; if (Option.isNone(identifier)) return; - const scrub = (text: string) => - redactSecrets(scrubUserPaths(text, environment.homeDirectory)); const payload = { api_key: posthogKey, batch: [ { - event: "desktop.backend.startup_failed", + event, distinct_id: identifier.value, properties: { $process_person_profile: false, @@ -179,11 +195,7 @@ const makeDesktopCrashReport = Effect.gen(function* () { arch: environment.processArch, threadlinesVersion: environment.appVersion, clientType: "desktop-app", - failureKind: report.failureKind, - attempts: report.attempts, - exitCode: Option.getOrNull(report.lastExitCode), - reason: scrub(report.lastReason), - outputTail: scrub(truncateTail(report.outputTail)), + ...properties, }, timestamp: new Date().toISOString(), }, @@ -196,6 +208,17 @@ const makeDesktopCrashReport = Effect.gen(function* () { Effect.flatMap(HttpClientResponse.filterStatusOk), Effect.asVoid, ); + }); + + const scrub = (text: string) => redactSecrets(scrubUserPaths(text, environment.homeDirectory)); + + const reportStartupFailure: DesktopCrashReportShape["reportStartupFailure"] = (report) => + sendEvent("desktop.backend.startup_failed", { + failureKind: report.failureKind, + attempts: report.attempts, + exitCode: Option.getOrNull(report.lastExitCode), + reason: scrub(report.lastReason), + outputTail: scrub(truncateTail(report.outputTail)), }).pipe( Effect.catch((error) => Effect.logDebug("startup failure crash report not sent", { cause: error }), @@ -203,7 +226,17 @@ const makeDesktopCrashReport = Effect.gen(function* () { Effect.withSpan("desktop.crashReport.reportStartupFailure"), ); - return DesktopCrashReport.of({ reportStartupFailure }); + const reportBackendStarted: DesktopCrashReportShape["reportBackendStarted"] = (report) => + sendEvent("desktop.backend.started", { + startupMs: Math.round(report.startupMs), + attempts: report.attempts, + slowStart: report.slowStart, + }).pipe( + Effect.catch((error) => Effect.logDebug("backend start report not sent", { cause: error })), + Effect.withSpan("desktop.crashReport.reportBackendStarted"), + ); + + return DesktopCrashReport.of({ reportStartupFailure, reportBackendStarted }); }); export const layer = Layer.effect(DesktopCrashReport, makeDesktopCrashReport); diff --git a/apps/desktop/src/backend/DesktopBackendManager.test.ts b/apps/desktop/src/backend/DesktopBackendManager.test.ts index 81650ea67..f4d90d6db 100644 --- a/apps/desktop/src/backend/DesktopBackendManager.test.ts +++ b/apps/desktop/src/backend/DesktopBackendManager.test.ts @@ -25,6 +25,7 @@ import { ChildProcess, ChildProcessSpawner } from "effect/process"; import * as DesktopBackendManager from "./DesktopBackendManager.ts"; import * as DesktopBackendConfiguration from "./DesktopBackendConfiguration.ts"; import * as DesktopDatabaseRecovery from "./DesktopDatabaseRecovery.ts"; +import * as DesktopCrashReport from "../app/DesktopCrashReport.ts"; import * as DesktopObservability from "../app/DesktopObservability.ts"; import * as DesktopState from "../app/DesktopState.ts"; import * as DesktopStartupFailurePrompt from "../window/DesktopStartupFailurePrompt.ts"; @@ -115,6 +116,7 @@ function makeManagerLayer(input: { readonly config?: DesktopBackendManager.DesktopBackendStartConfig; readonly startupFailurePrompt?: Partial; readonly databaseRecovery?: Partial; + readonly crashReport?: Partial; readonly entryExists?: boolean; }) { return DesktopBackendManager.layer.pipe( @@ -140,9 +142,15 @@ function makeManagerLayer(input: { handle: () => Effect.die("unexpected startup failure prompt"), notifyDatabaseRecovery: () => Effect.void, notifyMigrationInProgress: () => Effect.die("unexpected migration notice"), + notifyStillStarting: Effect.die("unexpected still-starting notice"), migrationNoticeClosesItself: true, ...input.startupFailurePrompt, }), + Layer.succeed(DesktopCrashReport.DesktopCrashReport, { + reportStartupFailure: () => Effect.void, + reportBackendStarted: () => Effect.void, + ...input.crashReport, + }), Layer.succeed(DesktopDatabaseRecovery.DesktopDatabaseRecovery, { completePendingRecovery: Effect.succeed(Option.none()), recover: () => Effect.succeed(Option.none()), @@ -925,11 +933,15 @@ describe("DesktopBackendManager", () => { ), ); + const stillStartingNotices = yield* Ref.make(0); const managerLayer = makeManagerLayer({ spawnerLayer, httpClientLayer: httpClientLayer(() => Effect.never), startupFailurePrompt: { handle: (report) => Queue.offer(promptReports, report).pipe(Effect.as("quit" as const)), + notifyStillStarting: Ref.update(stillStartingNotices, (count) => count + 1).pipe( + Effect.andThen(Effect.never), + ), }, }); @@ -939,12 +951,20 @@ describe("DesktopBackendManager", () => { assert.equal(yield* Queue.take(starts), 1); // The 60s readiness budget elapses without a single healthy answer. + // The process is still alive, so it is told apart from a crash: a + // notice, and more time. yield* TestClock.adjust(Duration.minutes(1)); + assert.equal(yield* Ref.get(stillStartingNotices), 1); + assert.equal(yield* Queue.size(promptReports), 0); + // The longer wait runs out as well, and now it is a failure. The + // report names the whole wait, not its last stretch. + yield* TestClock.adjust(Duration.minutes(4)); const report = yield* Queue.take(promptReports); assert.equal(report.failureKind, "readiness-timeout"); assert.equal(report.attempts, 1); - assert.include(report.lastReason, "Timed out"); + assert.include(report.lastReason, "Timed out waiting 300000ms"); + assert.equal(yield* Ref.get(stillStartingNotices), 1); assert.include(report.outputTail, "EADDRINUSE"); assert.include(report.outputTail, "node exited"); @@ -955,6 +975,305 @@ describe("DesktopBackendManager", () => { }), ); + it.effect( + "keeps a slow first start alive past the deadline, says so, and opens when it answers", + () => + Effect.gen(function* () { + const noticeShown = yield* Deferred.make(); + const noticeClosed = yield* Deferred.make(); + const windowOpened = yield* Deferred.make(); + const answersReadiness = yield* Ref.make(false); + const terminations = yield* Ref.make(0); + const failurePrompts = yield* Ref.make(0); + const startReports = + yield* Queue.unbounded(); + + 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({ + // What the field reports looked like: migrations long done, + // then silence. + stdout: Stream.make( + new TextEncoder().encode( + "[14:57:03.975] INFO (#34): Running all migrations...\n" + + "[14:57:04.083] INFO (#34): Migrations ran successfully\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: { + handle: () => + Ref.update(failurePrompts, (count) => count + 1).pipe(Effect.as("quit" as const)), + notifyStillStarting: Deferred.succeed(noticeShown, void 0).pipe( + Effect.andThen( + Effect.never.pipe( + Effect.onInterrupt(() => + Deferred.succeed(noticeClosed, void 0).pipe(Effect.asVoid), + ), + ), + ), + ), + }, + crashReport: { + reportBackendStarted: (report) => Queue.offer(startReports, report).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; + + // A minute in, alive and silent: not killed, and the wait gets a face. + yield* TestClock.adjust(Duration.minutes(1)); + yield* Deferred.await(noticeShown); + assert.equal(yield* Ref.get(terminations), 0); + assert.equal(yield* Ref.get(failurePrompts), 0); + + // It answers a minute and a half later. The window opens, the notice + // closes itself, and nobody was asked to try again. + yield* TestClock.adjust(Duration.seconds(90)); + 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.equal(yield* Ref.get(failurePrompts), 0); + assert.isTrue((yield* manager.snapshot).ready); + + // And how long it took is reported, marked as a slow start. + const report = yield* Queue.take(startReports); + assert.equal(report.slowStart, true); + assert.equal(report.attempts, 1); + assert.isAtLeast(report.startupMs, 150_000); + assert.isAtMost(report.startupMs, 153_000); + }).pipe(Effect.provide(Layer.merge(TestClock.layer(), managerLayer))); + }), + ); + + it.effect( + "swaps the still-starting notice for the migration one when a slow start turns out to be migrating", + () => + Effect.gen(function* () { + const output = yield* Queue.unbounded(); + const stillStartingClosed = yield* Deferred.make(); + const migrationNotices = yield* Queue.unbounded(); + const terminations = yield* Ref.make(0); + const failurePrompts = 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.fromQueue(output), + exitCode: Deferred.await(closed).pipe(Effect.as(ChildProcessSpawner.ExitCode(0))), + kill: () => close, + }); + }), + ), + ); + + const managerLayer = makeManagerLayer({ + spawnerLayer, + httpClientLayer: httpClientLayer(() => Effect.never), + startupFailurePrompt: { + handle: () => + Ref.update(failurePrompts, (count) => count + 1).pipe(Effect.as("quit" as const)), + notifyStillStarting: Effect.never.pipe( + Effect.onInterrupt(() => + Deferred.succeed(stillStartingClosed, void 0).pipe(Effect.asVoid), + ), + ), + notifyMigrationInProgress: (info) => + Queue.offer(migrationNotices, info.migrationId).pipe(Effect.andThen(Effect.never)), + }, + }); + + yield* Effect.gen(function* () { + const manager = yield* DesktopBackendManager.DesktopBackendManager; + yield* manager.start; + + // Nothing printed in the first minute: it reads as a slow start. + yield* TestClock.adjust(Duration.minutes(1)); + assert.equal(yield* Queue.size(migrationNotices), 0); + + // Then it gets going, and what it gets going on is a long migration. + yield* Queue.offer( + output, + new TextEncoder().encode( + "[00:01:30.000] INFO (#42): Running migration 50_ProjectionTranscriptEventSequence (50 of 51)\n", + ), + ); + + // At the longer deadline it is busy, not stuck: the notice now says + // what is really happening, alone on screen, and nothing is killed. + yield* TestClock.adjust(Duration.minutes(4)); + assert.equal(yield* Queue.take(migrationNotices), 50); + yield* Deferred.await(stillStartingClosed); + assert.equal(yield* Ref.get(terminations), 0); + assert.equal(yield* Ref.get(failurePrompts), 0); + }).pipe(Effect.provide(Layer.merge(TestClock.layer(), managerLayer))); + }), + ); + + it.effect("starts the longer wait only once a notice that holds the app has been answered", () => + Effect.gen(function* () { + // As on macOS, where the box holds the main process until answered. + const noticeShown = yield* Deferred.make(); + const answerKeepWaiting = yield* Deferred.make(); + const windowOpened = yield* Deferred.make(); + const answersReadiness = yield* Ref.make(false); + const terminations = yield* Ref.make(0); + const failurePrompts = 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({ + 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: { + migrationNoticeClosesItself: false, + handle: () => + Ref.update(failurePrompts, (count) => count + 1).pipe(Effect.as("quit" as const)), + notifyStillStarting: Deferred.succeed(noticeShown, void 0).pipe( + Effect.andThen(Deferred.await(answerKeepWaiting)), + ), + }, + desktopWindow: { + handleBackendReady: Deferred.succeed(windowOpened, void 0).pipe(Effect.asVoid), + }, + }); + + yield* Effect.gen(function* () { + const manager = yield* DesktopBackendManager.DesktopBackendManager; + yield* manager.start; + yield* TestClock.adjust(Duration.minutes(1)); + yield* Deferred.await(noticeShown); + + // The box sits unanswered for far longer than the extra wait. The + // backend got ready behind it; that time must not count against it. + yield* Ref.set(answersReadiness, true); + yield* TestClock.adjust(Duration.minutes(10)); + assert.equal(yield* Ref.get(terminations), 0); + assert.equal(yield* Ref.get(failurePrompts), 0); + + // Answered: the checks run again and find it ready. + yield* Deferred.succeed(answerKeepWaiting, void 0); + yield* TestClock.adjust(Duration.seconds(2)); + yield* Deferred.await(windowOpened); + assert.equal(yield* Ref.get(terminations), 0); + assert.equal(yield* Ref.get(failurePrompts), 0); + }).pipe(Effect.provide(Layer.merge(TestClock.layer(), managerLayer))); + }), + ); + + it.effect("closes the still-starting notice when the slow backend dies under it", () => + Effect.gen(function* () { + const noticeShown = yield* Deferred.make(); + const noticeClosed = yield* Deferred.make(); + const crash = yield* Deferred.make(); + const starts = yield* Ref.make(0); + + const spawnerLayer = Layer.succeed( + ChildProcessSpawner.ChildProcessSpawner, + ChildProcessSpawner.make(() => + Ref.updateAndGet(starts, (count) => count + 1).pipe( + Effect.map((start) => + makeProcess({ + // The first process hangs, then crashes; later ones just hang. + exitCode: (start === 1 ? Deferred.await(crash) : Effect.never).pipe( + Effect.as(ChildProcessSpawner.ExitCode(1)), + ), + }), + ), + ), + ), + ); + + const managerLayer = makeManagerLayer({ + spawnerLayer, + httpClientLayer: httpClientLayer(() => Effect.never), + startupFailurePrompt: { + notifyStillStarting: Deferred.succeed(noticeShown, void 0).pipe( + Effect.andThen( + Effect.never.pipe( + Effect.onInterrupt(() => + Deferred.succeed(noticeClosed, void 0).pipe(Effect.asVoid), + ), + ), + ), + ), + }, + }); + + yield* Effect.gen(function* () { + const manager = yield* DesktopBackendManager.DesktopBackendManager; + yield* manager.start; + yield* TestClock.adjust(Duration.minutes(1)); + yield* Deferred.await(noticeShown); + + // The process exits on its own: its notice goes with it, and the + // ordinary restart takes over. + yield* Deferred.succeed(crash, void 0); + yield* Deferred.await(noticeClosed); + yield* TestClock.adjust(Duration.seconds(1)); + assert.equal(yield* Ref.get(starts), 2); + }).pipe(Effect.provide(Layer.merge(TestClock.layer(), managerLayer))); + }), + ); + // A first start whose backend sits in migration 50 of 51 until the test // lets it answer readiness, with the notice and window recorded. const makeMigratingBackend = (closesItself: boolean) => diff --git a/apps/desktop/src/backend/DesktopBackendManager.ts b/apps/desktop/src/backend/DesktopBackendManager.ts index 84ac0ebf7..3ec4032c3 100644 --- a/apps/desktop/src/backend/DesktopBackendManager.ts +++ b/apps/desktop/src/backend/DesktopBackendManager.ts @@ -48,7 +48,16 @@ const MAX_STARTUP_ATTEMPTS = 3; const OUTPUT_TAIL_MAX_CHARS = 8_192; // How long a finished process's output drains may lag its exit. const DRAIN_FLUSH_TIMEOUT = Duration.seconds(1); +// How long the report of a finished start may take before it is dropped. +const START_REPORT_TIMEOUT = Duration.seconds(3); const DEFAULT_BACKEND_READINESS_TIMEOUT = Duration.minutes(1); +// A backend still alive at that deadline, with no window yet, is usually slow +// rather than stuck: a cold start on a busy Windows machine (a scan of the +// freshly updated app, a disk at full load) has taken more than a minute with +// the process healthy throughout, and killing it only made the user start the +// same slow work again. So it gets a visible "still starting" notice and this +// much longer before the run is given up on. +const SLOW_START_EXTRA_WAIT = Duration.minutes(4); // A normal backend answers within a couple of seconds, and every poll gap is // time the window could already be loading, so probe often at first. Past // that the backend is migrating or wedged, and a slower pace is plenty. @@ -118,10 +127,14 @@ 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. + * What to do when a readiness deadline passes: give up on this run, drop the + * deadline and keep probing until the backend answers or the process dies, or + * set one more deadline and be asked again when it passes too. */ -export type BackendReadinessTimeoutDecision = "give-up" | "keep-waiting"; +export type BackendReadinessTimeoutDecision = + | "give-up" + | "keep-waiting" + | { readonly waitAgainFor: Duration.Duration }; interface RunBackendProcessOptions extends DesktopBackendStartConfig { readonly readinessTimeout?: Duration.Duration; @@ -400,18 +413,28 @@ const runBackendProcess = Effect.fn("runBackendProcess")(function* ( 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, + const awaitReadyWithin = ( + timeout: Duration.Duration, + ): Effect.Effect => + awaitReady(timeout).pipe( + Effect.catch((error) => + ( + options.onReadinessTimeout?.(error) ?? + Effect.succeed("give-up") + ).pipe( + Effect.flatMap((decision) => { + if (decision === "give-up") return Effect.void; + // "keep-waiting" drops the deadline rather than the probe: if the + // process dies meanwhile, the exit path below ends the run anyway. + if (decision === "keep-waiting") { + return awaitReady(Duration.infinity).pipe(Effect.ignore); + } + return awaitReadyWithin(decision.waitAgainFor); + }), ), ), - ), + ); + yield* awaitReadyWithin(options.readinessTimeout ?? DEFAULT_BACKEND_READINESS_TIMEOUT).pipe( Effect.forkScoped, ); @@ -434,6 +457,7 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio const desktopWindow = yield* DesktopWindow.DesktopWindow; const startupFailurePrompt = yield* DesktopStartupFailurePrompt.DesktopStartupFailurePrompt; const databaseRecovery = yield* DesktopDatabaseRecovery.DesktopDatabaseRecovery; + const crashReport = yield* DesktopCrashReport.DesktopCrashReport; const spawner = yield* ChildProcessSpawner.ChildProcessSpawner; const httpClient = yield* HttpClient.HttpClient; const state = yield* Ref.make(initialState); @@ -577,6 +601,13 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio const stdoutDecoder = new TextDecoder(); const stderrDecoder = new TextDecoder(); const readinessTimeoutRef = yield* Ref.make(Option.none()); + // When this run's process started (on the clock that never jumps), + // for how long the start took; how long readiness has been waited for + // across its deadlines; and whether the "still starting" notice has + // had its turn. + const startedAtRef = yield* Ref.make(Option.none()); + const readinessWaitedMsRef = yield* Ref.make(0); + const stillStartingShownRef = yield* Ref.make(false); // The "still migrating" dialog belongs to this run. A watcher fiber // shows it once a migration has kept the first startup busy for // MIGRATION_NOTICE_DELAY, and holds it open; readiness and the run @@ -611,6 +642,9 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio }); } }); + // One slot for whichever waiting notice this run has up: the + // migration watcher (and its dialog), or the "still starting" notice. + // Never two at once. const migrationNoticeRef = yield* Ref.make(Option.none>()); const closeMigrationNotice = Ref.getAndSet( migrationNoticeRef, @@ -809,6 +843,7 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio ...run, pid: Option.some(pid), })); + yield* Ref.set(startedAtRef, Option.some(yield* Clock.monotonicTimeNanos)); yield* backendOutputLog.writeSessionBoundary({ phase: "START", details: `pid=${pid} port=${config.bootstrap.port} cwd=${config.cwd}`, @@ -818,7 +853,7 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio yield* Ref.set(migrationNoticeRef, Option.some(noticeFiber)); }), onReady: Effect.fn("desktop.backendManager.onReady")(function* () { - const { isCurrentRun, recoveryNotice } = yield* Ref.modify( + const { isCurrentRun, recoveryNotice, firstStart } = yield* Ref.modify( state, ( latest, @@ -826,6 +861,8 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio { readonly isCurrentRun: boolean; readonly recoveryNotice: Option.Option; + /** Set for the app session's first readiness: how many processes it took. */ + readonly firstStart: Option.Option<{ readonly attempts: number }>; }, BackendManagerState, ] => { @@ -836,6 +873,7 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio isCurrentRun: false, recoveryNotice: Option.none(), + firstStart: Option.none(), }, latest, ] as const; @@ -845,6 +883,9 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio { isCurrentRun: true, recoveryNotice: latest.pendingDatabaseRecoveryNotice, + firstStart: latest.everReady + ? Option.none() + : Option.some({ attempts: latest.restartAttempt + 1 }), }, { ...latest, @@ -863,6 +904,23 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio yield* closeMigrationNotice; yield* Ref.set(desktopState.backendReady, true); + // How long the first start took, so the deadlines above can be + // judged against real machines. Beside the window, never before it. + const startedAt = yield* Ref.get(startedAtRef); + if (Option.isSome(firstStart) && Option.isSome(startedAt)) { + yield* Effect.forkIn( + crashReport + .reportBackendStarted({ + startupMs: Number( + ((yield* Clock.monotonicTimeNanos) - startedAt.value) / 1_000_000n, + ), + attempts: firstStart.value.attempts, + slowStart: yield* Ref.get(stillStartingShownRef), + }) + .pipe(Effect.timeoutOption(START_REPORT_TIMEOUT), Effect.asVoid), + parentScope, + ); + } yield* desktopWindow.handleBackendReady.pipe( Effect.catch((error) => logBackendManagerError("failed to open main window after backend readiness", { @@ -881,15 +939,16 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio ); } }), - // 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 + // Four ways a deadline can pass, and only the last 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, unless the - // migration watcher already did. 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. + // migration watcher already did. A process that is alive and not + // migrating at the first deadline is most often just slow, so it + // gets a notice and one longer deadline. One that has used that + // up too is alive but unresponsive: 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", { @@ -899,6 +958,11 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio if (latest.everReady) { return "keep-waiting" as const; } + const waitedMs = yield* Ref.updateAndGet( + readinessWaitedMsRef, + (waited) => waited + error.timeoutMs, + ); + const stillStartingShown = yield* Ref.get(stillStartingShownRef); const migration = findMigrationInProgress(yield* Ref.get(outputTailRef)); if (Option.isSome(migration)) { yield* logBackendManagerInfo("backend still migrating at readiness deadline", { @@ -906,19 +970,53 @@ const makeDesktopBackendManager = Effect.fn("makeDesktopBackendManager")(functio migrationName: migration.value.name, totalMigrations: migration.value.total, }); - if (!startupFailurePrompt.migrationNoticeClosesItself) { + // The watcher has already said so where its box closes itself, + // unless the "still starting" notice took its place. + if (!startupFailurePrompt.migrationNoticeClosesItself || stillStartingShown) { + yield* closeMigrationNotice; + // In the run's scope, like the watcher: a notice put up as + // the run ends must end with it, not sit over the next run. const noticeFiber = yield* Effect.forkIn( startupFailurePrompt.notifyMigrationInProgress({ migrationId: migration.value.id, totalMigrations: migration.value.total, }), - parentScope, + runScope, ); yield* Ref.set(migrationNoticeRef, Option.some(noticeFiber)); } return "keep-waiting" as const; } - yield* Ref.set(readinessTimeoutRef, Option.some(error)); + if (!stillStartingShown) { + yield* Ref.set(stillStartingShownRef, true); + yield* logBackendManagerInfo( + "backend alive but not ready at the readiness deadline; waiting longer", + { waitedMs, extraWaitMs: Duration.toMillis(SLOW_START_EXTRA_WAIT) }, + ); + // In place of the migration watcher: one notice at a time. + yield* closeMigrationNotice; + if (startupFailurePrompt.migrationNoticeClosesItself) { + const noticeFiber = yield* Effect.forkIn( + startupFailurePrompt.notifyStillStarting, + runScope, + ); + yield* Ref.set(migrationNoticeRef, Option.some(noticeFiber)); + } else { + // A box that holds the main process holds the readiness + // checks and the timers with it. Started beside the longer + // wait, it would let that wait run out unseen while the box + // sat open, and a backend that got ready meanwhile would be + // killed the moment it was answered. So the longer wait + // starts once it has been. + yield* startupFailurePrompt.notifyStillStarting; + } + return { waitAgainFor: SLOW_START_EXTRA_WAIT }; + } + // The whole wait, not just its last stretch, is what failed. + yield* Ref.set( + readinessTimeoutRef, + Option.some(new BackendTimeoutError({ url: error.url, timeoutMs: waitedMs })), + ); const run = Option.getOrUndefined(latest.active); if (run?.id === runId) { yield* Effect.forkIn(closeRun(run), parentScope); diff --git a/apps/desktop/src/window/DesktopStartupFailurePrompt.ts b/apps/desktop/src/window/DesktopStartupFailurePrompt.ts index 8ac070ab3..8f164b2ce 100644 --- a/apps/desktop/src/window/DesktopStartupFailurePrompt.ts +++ b/apps/desktop/src/window/DesktopStartupFailurePrompt.ts @@ -32,7 +32,7 @@ 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; +const WAITING_QUIT_BUTTON_INDEX = 1; export type DesktopStartupFailureAction = "retry" | "quit"; @@ -57,10 +57,17 @@ export interface DesktopStartupFailurePromptShape { readonly totalMigrations: number; }) => Effect.Effect; /** - * Whether interrupting notifyMigrationInProgress closes its box. Not on - * macOS: a message box with no parent window runs there as a synchronous - * modal that ignores the abort signal (see Electron's dialog docs), so it - * holds the main process, readiness checks included, until it is answered. + * Tells the user the backend is alive but slow to answer on a first + * startup, so the wait has a face and a way out. Closes itself when + * interrupted, like the migration notice. Never fails. + */ + readonly notifyStillStarting: Effect.Effect; + /** + * Whether interrupting a waiting notice (migration, still starting) closes + * its box. Not on macOS: a message box with no parent window runs there as a + * synchronous modal that ignores the abort signal (see Electron's dialog + * docs), so it holds the main process, readiness checks included, until it + * is answered. */ readonly migrationNoticeClosesItself: boolean; } @@ -237,16 +244,40 @@ const makeDesktopStartupFailurePrompt = Effect.gen(function* () { cancelId: KEEP_WAITING_BUTTON_INDEX, noLink: true, }); - if (result.response === MIGRATION_QUIT_BUTTON_INDEX) { + if (result.response === WAITING_QUIT_BUTTON_INDEX) { yield* electronApp.quit; } }).pipe(Effect.catchCause(() => Effect.void)), ); + const notifyStillStarting: DesktopStartupFailurePromptShape["notifyStillStarting"] = Effect.gen( + function* () { + // Owned by the backend manager like the migration notice: readiness or + // the run ending interrupts this fiber, which closes the box. + const result = yield* electronDialog.showMessageBox({ + type: "info", + title: `${environment.displayName} is still starting`, + message: `${environment.displayName} is still starting`, + detail: `Its background service is taking longer than usual. This can happen right after an update or when the computer is busy. ${environment.displayName} opens on its own once it's ready.\n\nQuitting now is safe.`, + buttons: ["Keep Waiting", "Quit"], + defaultId: KEEP_WAITING_BUTTON_INDEX, + cancelId: KEEP_WAITING_BUTTON_INDEX, + noLink: true, + }); + if (result.response === WAITING_QUIT_BUTTON_INDEX) { + yield* electronApp.quit; + } + }, + ).pipe( + Effect.catchCause(() => Effect.void), + Effect.withSpan("desktop.startupFailurePrompt.notifyStillStarting"), + ); + return DesktopStartupFailurePrompt.of({ handle, notifyDatabaseRecovery, notifyMigrationInProgress, + notifyStillStarting, migrationNoticeClosesItself: environment.platform !== "darwin", }); }); diff --git a/docs/telemetry.md b/docs/telemetry.md index 6bf1a8e53..42905b2c4 100644 --- a/docs/telemetry.md +++ b/docs/telemetry.md @@ -11,6 +11,9 @@ Settings. Threadlines sends product and reliability events such as: - app/server startup heartbeat; +- in the desktop app, how long its background service took to answer after + the app started it, in milliseconds, how many tries that took, and whether + it was slow enough to show the "still starting" notice; - whether each coding agent (Codex, Claude, and the other supported agents) is turned on, installed, and signed in (yes, no, or unknown), and whether its startup check timed out. Community agents are answered together, as whether