diff --git a/docs/cli.md b/docs/cli.md index 562f7509..c4781377 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -209,27 +209,45 @@ Hack scans `.npmrc`, `.yarnrc.yml`, and `bunfig.toml` for `${VAR}` credential re with `E_ENV_KEY_MISSING` when the selected Hack overlay cannot supply them. Values are never printed. -Detached Compose startup has a 90-second budget by default. For a slow first -install or container launch, set the host CLI environment explicitly: +Detached Compose startup runs in two phases, each with its own budget: + +| Phase | Compose invocation | Default | Variable | Range (ms) | +| --- | --- | --- | --- | --- | +| Image build/pull and container creation | `up --no-start` | 30 minutes | `HACK_COMPOSE_IMAGE_TIMEOUT_MS` | 1,000–14,400,000 | +| Start and dependency wait | `up -d --no-build` | 90 seconds | `HACK_COMPOSE_STARTUP_TIMEOUT_MS` | 1,000–3,600,000 | + +A first-time build or a large image pull therefore does not consume the start +budget. Raise the budget for the phase that was hit, on the host CLI invocation +rather than in a container's environment: ```sh +# Slow first build or pull of a large image +HACK_COMPOSE_IMAGE_TIMEOUT_MS=3600000 hack up --detach +# Slow container start or a dependency that is slow to become healthy HACK_COMPOSE_STARTUP_TIMEOUT_MS=300000 hack up --detach HACK_COMPOSE_STARTUP_TIMEOUT_MS=300000 hack restart ``` -The value must be an integer from 1,000 to 3,600,000 milliseconds; detached startup -and restart reject invalid values before project preparation or teardown. Full and service-scoped -startup/restart use the same setting. The startup phase notice and -`E_STARTUP_TIMEOUT` message report the effective budget. It covers each detached -Compose invocation, including image/container launch and dependency waiting, not -lifecycle hooks or an end-to-end application readiness deadline. A restart repair -attempt has its own invocation budget and is reported separately. Foreground -`up` stays unbounded; `down` retains its separate 90-second limit. - -On timeout, Hack terminates the owned Compose process group. Containers may still -be running: inspect `hack ps` and `hack logs` before retrying. Raising the budget -does not fix a failed installer or prove readiness. Set this on the host invocation, -not merely in a container's environment. +Detached startup and restart reject invalid values before project preparation or +teardown. Full and service-scoped startup/restart use the same settings. The +startup notice reports both effective budgets. On expiry, `E_STARTUP_TIMEOUT` +names the phase that was hit, its budget, and the variable that raises it; with +`--json`, `error.detail` carries `composePhase` (`images` or `start`), +`budgetMs`, and `budgetEnv`. The start budget covers container start and Compose +`depends_on` waiting, not lifecycle hooks or an end-to-end application readiness +deadline. A restart repair attempt has its own budgets and is reported +separately. Foreground `up` stays a single unbounded Compose invocation; `down` +retains its separate 90-second limit. + +On timeout, Hack terminates the owned Compose process group of that phase. After an +image-phase timeout no container was started by that attempt, but containers may +have been created or recreated. After a start-phase timeout containers may still be +running. Inspect `hack ps` and `hack logs` before retrying. Raising a budget does not +fix a failed installer or prove readiness. + +Services with `pull_policy: always` still pull again in the start phase because +Compose applies that policy on every `up`; such pulls count against the start +budget. To share dependency data only across worktrees with the same lockfile/runtime fingerprint, label the bootstrap service with a logical top-level Compose volume: @@ -292,7 +310,8 @@ be mistaken for a ready one. No project lifecycle hook or unrelated dependency i A failed installer leaves existing consumer containers untouched; JSON lifecycle commands return `E_DEPENDENCY_BOOTSTRAP_FAILED`. Each initializer in detached scoped `up` and targeted `restart` uses the configured `HACK_COMPOSE_STARTUP_TIMEOUT_MS` budget and reports `E_STARTUP_TIMEOUT` on expiry. -The subsequent Compose launch has its own equal budget. Consumer `run` and foreground +That budget also covers any installer image pull or build, because `run` acquires +the image itself. The subsequent Compose launch has its own phased budgets. Consumer `run` and foreground scoped `up` retain a separate ten-minute initializer deadline. ## Branch instances and linked worktrees diff --git a/src/backends/runtime-backend.ts b/src/backends/runtime-backend.ts index b08a9248..76c047ec 100644 --- a/src/backends/runtime-backend.ts +++ b/src/backends/runtime-backend.ts @@ -1,5 +1,7 @@ import { + type ComposeStartupPhase, DEFAULT_COMPOSE_STARTUP_TIMEOUT_MS, + resolveComposeImageTimeoutMs, resolveComposeStartupTimeoutMs, } from "../lib/compose-startup-budget.ts"; import { withDependencyStartupProgress } from "../lib/dependency-startup-progress.ts"; @@ -39,7 +41,15 @@ export interface RuntimeUpOptions extends RuntimeBaseOptions { readonly services: readonly string[]; }; readonly detach: boolean; + /** Detached `start` phase budget (container start and dependency wait). */ readonly startupTimeoutMs?: number; + /** Detached `images` phase budget (image build/pull and container creation). */ + readonly imageTimeoutMs?: number; + /** + * Called before each detached phase begins, so a caller can attribute a + * non-zero exit (including the 124 deadline) to the phase that produced it. + */ + readonly onStartupPhase?: (phase: ComposeStartupPhase) => void; readonly services?: readonly string[]; readonly noDeps?: boolean; readonly forceRecreate?: boolean; @@ -85,26 +95,52 @@ function buildComposeArgs(opts: RuntimeBaseOptions): string[] { export const composeRuntimeBackend: RuntimeBackend = { name: "compose", async up(opts) { - const cmd = [ - ...buildComposeArgs(opts), - "up", - ...(opts.detach ? ["-d"] : []), - ...(opts.noDeps ? ["--no-deps"] : []), - ...(opts.forceRecreate ? ["--force-recreate"] : []), - ...(opts.services ?? []), - ]; if (opts.detach) { + const budgetEnv = { ...process.env, ...opts.env }; const startupTimeoutMs = resolveComposeStartupTimeoutMs({ startupTimeoutMs: opts.startupTimeoutMs, - env: { ...process.env, ...opts.env }, + env: budgetEnv, }); - const launch = () => + const imageTimeoutMs = resolveComposeImageTimeoutMs({ + imageTimeoutMs: opts.imageTimeoutMs, + env: budgetEnv, + }); + const scope = [ + ...(opts.noDeps ? ["--no-deps"] : []), + ...(opts.services ?? []), + ]; + const runPhase = (cmd: readonly string[], timeoutMs: number) => run(cmd, { cwd: opts.cwd, env: opts.env, stdout: opts.routeStdoutToStderr ? "stderr" : "inherit", - timeoutMs: startupTimeoutMs, + timeoutMs, }); + // Image build/pull can take far longer than starting containers, so it + // runs (with container creation/recreation) under its own budget. The + // start invocation then only starts the prepared containers and waits on + // Compose dependency conditions; --no-build keeps it from rebuilding. + const launch = async () => { + opts.onStartupPhase?.("images"); + const prepared = await runPhase( + [ + ...buildComposeArgs(opts), + "up", + "--no-start", + ...(opts.forceRecreate ? ["--force-recreate"] : []), + ...scope, + ], + imageTimeoutMs + ); + if (prepared !== 0) { + return prepared; + } + opts.onStartupPhase?.("start"); + return await runPhase( + [...buildComposeArgs(opts), "up", "-d", "--no-build", ...scope], + startupTimeoutMs + ); + }; const progress = opts.dependencyProgress; if (!progress) { return await launch(); @@ -129,6 +165,13 @@ export const composeRuntimeBackend: RuntimeBackend = { }); } + const cmd = [ + ...buildComposeArgs(opts), + "up", + ...(opts.noDeps ? ["--no-deps"] : []), + ...(opts.forceRecreate ? ["--force-recreate"] : []), + ...(opts.services ?? []), + ]; const env = mergeSpawnEnv(opts.env); const proc = Bun.spawn(cmd, { cwd: opts.cwd, diff --git a/src/commands/project.ts b/src/commands/project.ts index 073ce8ee..96b1756b 100644 --- a/src/commands/project.ts +++ b/src/commands/project.ts @@ -154,7 +154,14 @@ import { import { withComposeServiceEnvFingerprints } from "../lib/compose-env-fingerprint.ts"; import { renderManagedComposeEnvOverride } from "../lib/compose-managed-env.ts"; import { + type ComposeStartupBudgets, + type ComposeStartupFailure, + type ComposeStartupPhase, + composeStartupFailure, + DEFAULT_COMPOSE_IMAGE_TIMEOUT_MS, DEFAULT_COMPOSE_STARTUP_TIMEOUT_MS, + describeComposeStartupBudgets, + resolveComposeImageTimeoutMs, resolveComposeStartupTimeoutMs, } from "../lib/compose-startup-budget.ts"; import { @@ -912,36 +919,59 @@ function startupSnapshotIsIncomplete(opts: { } function reportComposeStartupBudget(opts: { - readonly startupTimeoutMs: number; + readonly budgets: ComposeStartupBudgets; readonly detach: boolean; readonly repair?: boolean; }): void { if (opts.detach) { logger.step({ - message: `Compose ${opts.repair ? "repair" : "startup"}: launch and dependency wait (budget ${opts.startupTimeoutMs} ms)`, + message: `Compose ${opts.repair ? "repair" : "startup"}: ${describeComposeStartupBudgets(opts.budgets)}`, }); } } -function composeStartupFailure( - code: number, - action: string, - startupTimeoutMs: number -): { - readonly code: "E_COMPOSE_FAILED" | "E_STARTUP_TIMEOUT"; - readonly message: string; -} { - return code === 124 +/** Resolve both detached Compose budgets before any project side effect. */ +function resolveDetachedComposeBudgets(detach: boolean): ComposeStartupBudgets { + return detach ? { - code: "E_STARTUP_TIMEOUT", - message: `${action} exceeded its detached Compose startup budget of ${startupTimeoutMs} ms (HACK_COMPOSE_STARTUP_TIMEOUT_MS). The Compose process group was terminated; inspect hack ps and hack logs before retrying. Containers may still be running. This limit covers Compose launch and dependency waiting, not lifecycle hooks or application readiness.`, + imageTimeoutMs: resolveComposeImageTimeoutMs(), + startupTimeoutMs: resolveComposeStartupTimeoutMs(), } : { - code: "E_COMPOSE_FAILED", - message: `${action} failed (exit ${code})`, + imageTimeoutMs: DEFAULT_COMPOSE_IMAGE_TIMEOUT_MS, + startupTimeoutMs: DEFAULT_COMPOSE_STARTUP_TIMEOUT_MS, }; } +/** + * Record the last detached Compose phase the backend entered, so a failure is + * attributed to it. A backend that never reports a phase is treated as `start`. + */ +function trackComposeStartupPhase(): { + readonly onStartupPhase: (phase: ComposeStartupPhase) => void; + readonly phase: () => ComposeStartupPhase; +} { + let current: ComposeStartupPhase = "start"; + return { + onStartupPhase: (phase) => { + current = phase; + }, + phase: () => current, + }; +} + +function composeStartupFailureDetail(opts: { + readonly failure: ComposeStartupFailure; + readonly exitCode: number; +}): Record { + return { + exitCode: opts.exitCode, + composePhase: opts.failure.phase, + budgetMs: opts.failure.budgetMs, + budgetEnv: opts.failure.budgetEnv, + }; +} + /** * Emit the `--json` envelope for a lifecycle command and map it to the * standard 0/1 exit semantics. @@ -5244,9 +5274,8 @@ async function runUpCommand({ readonly startedAtMs?: number; }): Promise { const detach = args.options.detach || json; - const startupTimeoutMs = detach - ? resolveComposeStartupTimeoutMs() - : DEFAULT_COMPOSE_STARTUP_TIMEOUT_MS; + const budgets = resolveDetachedComposeBudgets(detach); + const { startupTimeoutMs } = budgets; let project: Awaited>; try { project = await resolveProjectForArgs({ @@ -5497,7 +5526,7 @@ async function runUpCommand({ ...(runtimeMetadataOverride ? [runtimeMetadataOverride] : []), ...envOverrides.composeFiles, ]; - reportComposeStartupBudget({ startupTimeoutMs, detach }); + reportComposeStartupBudget({ budgets, detach }); const bootstrapCode = await bootstrapDependencyCaches({ timeoutMs: detach ? startupTimeoutMs : undefined, services: cacheBootstrapServices, @@ -5521,6 +5550,7 @@ async function runUpCommand({ logger.error({ message: failure.message }); return bootstrapCode; } + const upPhase = trackComposeStartupPhase(); const upCode = await composeRuntimeBackend.up({ dependencyProgress: resolveDependencyCacheProgress({ cache: dependencyCache, @@ -5528,6 +5558,8 @@ async function runUpCommand({ baseProject: baseProjectName, }), startupTimeoutMs, + imageTimeoutMs: budgets.imageTimeoutMs, + onStartupPhase: upPhase.onStartupPhase, composeFiles: composeFilesWithEnv, composeProject: composeProjectName, profiles, @@ -5544,28 +5576,23 @@ async function runUpCommand({ projectDir: project.projectDir, composeProject: lifecycleComposeProject, }); + const failure = composeStartupFailure({ + code: upCode, + action: "docker compose up", + phase: upPhase.phase(), + budgets, + }); if (json) { - const failure = composeStartupFailure( - upCode, - "docker compose up", - startupTimeoutMs - ); return emitLifecycleResult({ result: errorResult({ code: failure.code, message: failure.message, - detail: { exitCode: upCode }, + detail: composeStartupFailureDetail({ failure, exitCode: upCode }), }), exitCode: upCode, }); } - logger.error({ - message: composeStartupFailure( - upCode, - "docker compose up", - startupTimeoutMs - ).message, - }); + logger.error({ message: failure.message }); return upCode; } @@ -6250,7 +6277,7 @@ async function runRestartDownPhase(opts: { } async function runRestartUpPhase(opts: { - readonly startupTimeoutMs: number; + readonly budgets: ComposeStartupBudgets; readonly project: Awaited>; readonly cfg: Awaited>; readonly baseProjectName: string; @@ -6265,6 +6292,7 @@ async function runRestartUpPhase(opts: { }): Promise<{ readonly code: number; readonly phase: "compose" | "lifecycle"; + readonly composePhase?: ComposeStartupPhase; }> { await maybeSyncOauthAliasesInCompose({ project: opts.project }); @@ -6380,16 +6408,19 @@ async function runRestartUpPhase(opts: { ...envOverrides.composeFiles, ]; reportComposeStartupBudget({ - startupTimeoutMs: opts.startupTimeoutMs, + budgets: opts.budgets, detach: opts.detach === true, }); + const upPhase = trackComposeStartupPhase(); const upCode = await composeRuntimeBackend.up({ dependencyProgress: resolveDependencyCacheProgress({ cache: dependencyCache, project: opts.composeProjectName, baseProject: opts.baseProjectName, }), - startupTimeoutMs: opts.startupTimeoutMs, + startupTimeoutMs: opts.budgets.startupTimeoutMs, + imageTimeoutMs: opts.budgets.imageTimeoutMs, + onStartupPhase: upPhase.onStartupPhase, composeFiles: composeFilesWithEnv, composeProject: opts.composeProjectName, profiles: opts.profiles, @@ -6401,7 +6432,7 @@ async function runRestartUpPhase(opts: { }); if (upCode !== 0) { reportComposeStartupBudget({ - startupTimeoutMs: opts.startupTimeoutMs, + budgets: opts.budgets, detach: true, repair: true, }); @@ -6411,7 +6442,8 @@ async function runRestartUpPhase(opts: { project: opts.composeProjectName, baseProject: opts.baseProjectName, }), - startupTimeoutMs: opts.startupTimeoutMs, + startupTimeoutMs: opts.budgets.startupTimeoutMs, + imageTimeoutMs: opts.budgets.imageTimeoutMs, composeFiles: composeFilesWithEnv, composeProject: opts.composeProjectName, profiles: opts.profiles, @@ -6437,7 +6469,7 @@ async function runRestartUpPhase(opts: { composeProject: opts.lifecycleComposeProject, }); } - return { code: upCode, phase: "compose" }; + return { code: upCode, phase: "compose", composePhase: upPhase.phase() }; } const upAfter = await runLifecycleCommands({ @@ -6490,7 +6522,7 @@ type TargetedServiceRestartResult = * individual Compose service. */ async function runTargetedServiceRestart(opts: { - readonly startupTimeoutMs: number; + readonly budgets: ComposeStartupBudgets; readonly project: Awaited>; readonly cfg: Awaited>; readonly baseProjectName: string; @@ -6572,7 +6604,7 @@ async function runTargetedServiceRestart(opts: { ...envOverrides.composeFiles, ]; const bootstrapCode = await bootstrapDependencyCaches({ - timeoutMs: opts.startupTimeoutMs, + timeoutMs: opts.budgets.startupTimeoutMs, services: cacheBootstrapServices, composeFiles: composeFilesWithEnv, composeProject: opts.composeProjectName, @@ -6583,7 +6615,7 @@ async function runTargetedServiceRestart(opts: { if (bootstrapCode !== 0) { const failure = dependencyCacheBootstrapFailure({ code: bootstrapCode, - timeoutMs: opts.startupTimeoutMs, + timeoutMs: opts.budgets.startupTimeoutMs, }); return { ok: false, @@ -6595,16 +6627,19 @@ async function runTargetedServiceRestart(opts: { }; } reportComposeStartupBudget({ - startupTimeoutMs: opts.startupTimeoutMs, + budgets: opts.budgets, detach: true, }); + const upPhase = trackComposeStartupPhase(); const code = await composeRuntimeBackend.up({ dependencyProgress: resolveDependencyCacheProgress({ cache: dependencyCache, project: opts.composeProjectName, baseProject: opts.baseProjectName, }), - startupTimeoutMs: opts.startupTimeoutMs, + startupTimeoutMs: opts.budgets.startupTimeoutMs, + imageTimeoutMs: opts.budgets.imageTimeoutMs, + onStartupPhase: upPhase.onStartupPhase, composeFiles: composeFilesWithEnv, composeProject: opts.composeProjectName, profiles: opts.profiles, @@ -6630,11 +6665,12 @@ async function runTargetedServiceRestart(opts: { outcome: code === 0 ? "applied" : "unknown", }); if (code !== 0) { - const failure = composeStartupFailure( + const failure = composeStartupFailure({ code, - "Targeted service restart", - opts.startupTimeoutMs - ); + action: "Targeted service restart", + phase: upPhase.phase(), + budgets: opts.budgets, + }); return { ok: false, code, @@ -6800,7 +6836,7 @@ async function runRestartCommand({ readonly json: boolean; readonly startedAtMs?: number; }): Promise { - const startupTimeoutMs = resolveComposeStartupTimeoutMs(); + const budgets = resolveDetachedComposeBudgets(true); const project = await resolveProjectForArgs({ ctx, pathOpt: args.options.path, @@ -6860,7 +6896,7 @@ async function runRestartCommand({ }); if (requestedServices.length > 0) { const result = await runTargetedServiceRestart({ - startupTimeoutMs, + budgets, project, cfg, baseProjectName, @@ -6960,7 +6996,7 @@ async function runRestartCommand({ }); const upOutcome = await runRestartUpPhase({ - startupTimeoutMs, + budgets, project, cfg, baseProjectName, @@ -6978,7 +7014,12 @@ async function runRestartCommand({ if (upCode !== 0) { const failure = upOutcome.phase === "compose" - ? composeStartupFailure(upCode, "Restart up phase", startupTimeoutMs) + ? composeStartupFailure({ + code: upCode, + action: "Restart up phase", + phase: upOutcome.composePhase ?? "start", + budgets, + }) : { code: "E_LIFECYCLE_FAILED" as const, message: `Restart lifecycle hook failed (exit ${upCode})`, @@ -6991,7 +7032,12 @@ async function runRestartCommand({ result: errorResult({ code: failure.code, message: failure.message, - detail: { exitCode: upCode, phase: "up" }, + detail: { + ...("phase" in failure + ? composeStartupFailureDetail({ failure, exitCode: upCode }) + : { exitCode: upCode }), + phase: "up", + }, }), exitCode: upCode, }); diff --git a/src/lib/compose-startup-budget.ts b/src/lib/compose-startup-budget.ts index 93d635b7..a811968e 100644 --- a/src/lib/compose-startup-budget.ts +++ b/src/lib/compose-startup-budget.ts @@ -1,40 +1,159 @@ import { CliUsageError } from "../cli/command.ts"; +/** Default budget for starting containers and waiting on Compose dependencies. */ export const DEFAULT_COMPOSE_STARTUP_TIMEOUT_MS = 90_000; -const MIN_STARTUP_TIMEOUT_MS = 1000; +/** Default budget for image build/pull and container creation before start. */ +export const DEFAULT_COMPOSE_IMAGE_TIMEOUT_MS = 1_800_000; +export const COMPOSE_STARTUP_TIMEOUT_ENV = "HACK_COMPOSE_STARTUP_TIMEOUT_MS"; +export const COMPOSE_IMAGE_TIMEOUT_ENV = "HACK_COMPOSE_IMAGE_TIMEOUT_MS"; +const MIN_TIMEOUT_MS = 1000; const MAX_STARTUP_TIMEOUT_MS = 3_600_000; +const MAX_IMAGE_TIMEOUT_MS = 14_400_000; const INTEGER_TEXT = /^[0-9]+$/; -/** Total detached Compose invocation budget, not a readiness or per-phase guarantee. */ +/** + * Detached Compose startup runs as two bounded invocations, each in its own + * owned process group that is terminated (exit 124) when its budget expires: + * - `images`: `up --no-start` builds or pulls missing images and creates or + * recreates containers without starting them. Bounded by + * {@link resolveComposeImageTimeoutMs}. + * - `start`: `up -d --no-build` starts containers and waits for Compose + * `depends_on` conditions. Bounded by {@link resolveComposeStartupTimeoutMs}. + * Image acquisition therefore never consumes the start/dependency-wait budget, + * while a genuine hang in either phase is still terminated. + */ +export type ComposeStartupPhase = "images" | "start"; + +/** + * Budget for the `start` phase of detached Compose startup: container start + * and dependency waiting. It excludes image build/pull and is not an + * application readiness guarantee. + */ export function resolveComposeStartupTimeoutMs( opts: { readonly startupTimeoutMs?: number; readonly env?: Readonly>; } = {} ): number { - const configured = (opts.env ?? process.env).HACK_COMPOSE_STARTUP_TIMEOUT_MS; - let timeout = opts.startupTimeoutMs; + return resolveBudget({ + explicit: opts.startupTimeoutMs, + configured: (opts.env ?? process.env)[COMPOSE_STARTUP_TIMEOUT_ENV], + fallback: DEFAULT_COMPOSE_STARTUP_TIMEOUT_MS, + max: MAX_STARTUP_TIMEOUT_MS, + invalid: () => + new CliUsageError( + `Compose startup timeout must be an integer from ${MIN_TIMEOUT_MS} to ${MAX_STARTUP_TIMEOUT_MS} milliseconds (${COMPOSE_STARTUP_TIMEOUT_ENV})` + ), + }); +} + +/** Budget for the `images` phase: image build/pull and container creation. */ +export function resolveComposeImageTimeoutMs( + opts: { + readonly imageTimeoutMs?: number; + readonly env?: Readonly>; + } = {} +): number { + return resolveBudget({ + explicit: opts.imageTimeoutMs, + configured: (opts.env ?? process.env)[COMPOSE_IMAGE_TIMEOUT_ENV], + fallback: DEFAULT_COMPOSE_IMAGE_TIMEOUT_MS, + max: MAX_IMAGE_TIMEOUT_MS, + invalid: () => + new CliUsageError( + `Compose image build/pull timeout must be an integer from ${MIN_TIMEOUT_MS} to ${MAX_IMAGE_TIMEOUT_MS} milliseconds (${COMPOSE_IMAGE_TIMEOUT_ENV})` + ), + }); +} + +function resolveBudget(opts: { + readonly explicit: number | undefined; + readonly configured: string | undefined; + readonly fallback: number; + readonly max: number; + readonly invalid: () => CliUsageError; +}): number { + let timeout = opts.explicit; if (timeout === undefined) { - if (configured === undefined) { - return DEFAULT_COMPOSE_STARTUP_TIMEOUT_MS; + if (opts.configured === undefined) { + return opts.fallback; } - if (!INTEGER_TEXT.test(configured)) { - throw invalidBudget(); + if (!INTEGER_TEXT.test(opts.configured)) { + throw opts.invalid(); } - timeout = Number(configured); + timeout = Number(opts.configured); } if ( !Number.isSafeInteger(timeout) || - timeout < MIN_STARTUP_TIMEOUT_MS || - timeout > MAX_STARTUP_TIMEOUT_MS + timeout < MIN_TIMEOUT_MS || + timeout > opts.max ) { - throw invalidBudget(); + throw opts.invalid(); } return timeout; } -function invalidBudget(): CliUsageError { - return new CliUsageError( - "Compose startup timeout must be an integer from 1000 to 3600000 milliseconds (HACK_COMPOSE_STARTUP_TIMEOUT_MS)" - ); +export interface ComposeStartupBudgets { + readonly startupTimeoutMs: number; + readonly imageTimeoutMs: number; +} + +const PHASE_LABEL: Readonly> = { + images: "image build/pull and container creation", + start: "start and dependency wait", +}; + +/** One-line summary of both detached phases and their effective budgets. */ +export function describeComposeStartupBudgets( + budgets: ComposeStartupBudgets +): string { + return `${PHASE_LABEL.images} (budget ${budgets.imageTimeoutMs} ms, ${COMPOSE_IMAGE_TIMEOUT_ENV}), then ${PHASE_LABEL.start} (budget ${budgets.startupTimeoutMs} ms, ${COMPOSE_STARTUP_TIMEOUT_ENV})`; +} + +export interface ComposeStartupFailure { + readonly code: "E_COMPOSE_FAILED" | "E_STARTUP_TIMEOUT"; + readonly message: string; + readonly phase: ComposeStartupPhase; + readonly budgetMs: number; + readonly budgetEnv: string; +} + +/** + * Map a detached Compose exit code to the CLI failure contract. Exit 124 is + * the owned process-group deadline; its message names the phase that hit it, + * the effective budget, and the host variable that raises it. + */ +export function composeStartupFailure(opts: { + readonly code: number; + readonly action: string; + readonly phase: ComposeStartupPhase; + readonly budgets: ComposeStartupBudgets; +}): ComposeStartupFailure { + const images = opts.phase === "images"; + const budgetMs = images + ? opts.budgets.imageTimeoutMs + : opts.budgets.startupTimeoutMs; + const budgetEnv = images + ? COMPOSE_IMAGE_TIMEOUT_ENV + : COMPOSE_STARTUP_TIMEOUT_ENV; + const phaseLabel = PHASE_LABEL[opts.phase]; + if (opts.code !== 124) { + return { + code: "E_COMPOSE_FAILED", + message: `${opts.action} failed (exit ${opts.code}) during Compose ${phaseLabel}`, + phase: opts.phase, + budgetMs, + budgetEnv, + }; + } + const message = images + ? `${opts.action} exceeded its Compose image build/pull budget of ${budgetMs} ms (phase: ${phaseLabel}). Raise it with ${budgetEnv}= on the host invocation (max ${MAX_IMAGE_TIMEOUT_MS}); it is separate from ${COMPOSE_STARTUP_TIMEOUT_ENV}. The Compose process group was terminated before this attempt started containers; containers may have been created or recreated but not started. Inspect hack ps before retrying.` + : `${opts.action} exceeded its detached Compose startup budget of ${budgetMs} ms (phase: ${phaseLabel}). Raise it with ${budgetEnv}= on the host invocation (max ${MAX_STARTUP_TIMEOUT_MS}). The Compose process group was terminated; inspect hack ps and hack logs before retrying. Containers may still be running. Image build/pull is not counted against this budget, and it does not cover lifecycle hooks or application readiness.`; + return { + code: "E_STARTUP_TIMEOUT", + message, + phase: opts.phase, + budgetMs, + budgetEnv, + }; } diff --git a/src/lib/dependency-cache-bootstrap.ts b/src/lib/dependency-cache-bootstrap.ts index a5b73546..403f1e8f 100644 --- a/src/lib/dependency-cache-bootstrap.ts +++ b/src/lib/dependency-cache-bootstrap.ts @@ -2,6 +2,7 @@ import { composeRuntimeBackend, type RuntimeBaseOptions, } from "../backends/runtime-backend.ts"; +import { COMPOSE_STARTUP_TIMEOUT_ENV } from "./compose-startup-budget.ts"; const BOOTSTRAP_TIMEOUT_MS = 600_000; @@ -44,7 +45,10 @@ export function dependencyCacheBootstrapFailure(opts: { return opts.code === 124 ? { code: "E_STARTUP_TIMEOUT", - message: `Dependency cache initialization exceeded its startup budget of ${opts.timeoutMs ?? BOOTSTRAP_TIMEOUT_MS} ms; consumers were not changed`, + message: + opts.timeoutMs === undefined + ? `Dependency cache initialization exceeded its startup budget of ${BOOTSTRAP_TIMEOUT_MS} ms (phase: dependency cache initialization; fixed for foreground and consumer runs); consumers were not changed` + : `Dependency cache initialization exceeded its startup budget of ${opts.timeoutMs} ms (phase: dependency cache initialization, including any installer image pull; raise ${COMPOSE_STARTUP_TIMEOUT_ENV}= on the host invocation); consumers were not changed`, } : { code: "E_DEPENDENCY_BOOTSTRAP_FAILED", diff --git a/tests/compose-startup-budget.test.ts b/tests/compose-startup-budget.test.ts index 4b5635e4..20964cb7 100644 --- a/tests/compose-startup-budget.test.ts +++ b/tests/compose-startup-budget.test.ts @@ -1,6 +1,8 @@ import { expect, test } from "bun:test"; import { + DEFAULT_COMPOSE_IMAGE_TIMEOUT_MS, DEFAULT_COMPOSE_STARTUP_TIMEOUT_MS, + resolveComposeImageTimeoutMs, resolveComposeStartupTimeoutMs, } from "../src/lib/compose-startup-budget.ts"; @@ -58,3 +60,33 @@ test("startup budget rejects malformed or out-of-bounds settings without echoing ).toThrow(); } }); + +test("image build/pull budget is separate, defaults to 30 minutes and allows up to 4 hours", () => { + expect(resolveComposeImageTimeoutMs({ env: {} })).toBe( + DEFAULT_COMPOSE_IMAGE_TIMEOUT_MS + ); + expect(DEFAULT_COMPOSE_IMAGE_TIMEOUT_MS).toBe(1_800_000); + // The startup budget never sizes the image phase, and vice versa. + expect( + resolveComposeImageTimeoutMs({ + env: { HACK_COMPOSE_STARTUP_TIMEOUT_MS: "1000" }, + }) + ).toBe(1_800_000); + expect( + resolveComposeStartupTimeoutMs({ + env: { HACK_COMPOSE_IMAGE_TIMEOUT_MS: "14400000" }, + }) + ).toBe(DEFAULT_COMPOSE_STARTUP_TIMEOUT_MS); + expect( + resolveComposeImageTimeoutMs({ + env: { HACK_COMPOSE_IMAGE_TIMEOUT_MS: "14400000" }, + }) + ).toBe(14_400_000); + for (const value of ["999", "14400001", "1e6", "private-input"]) { + expect(() => + resolveComposeImageTimeoutMs({ + env: { HACK_COMPOSE_IMAGE_TIMEOUT_MS: value }, + }) + ).toThrow("HACK_COMPOSE_IMAGE_TIMEOUT_MS"); + } +}); diff --git a/tests/compose-startup-phases.test.ts b/tests/compose-startup-phases.test.ts new file mode 100644 index 00000000..9c595da0 --- /dev/null +++ b/tests/compose-startup-phases.test.ts @@ -0,0 +1,226 @@ +import { afterEach, expect, test } from "bun:test"; +import { chmod, mkdtemp, readFile, rm, writeFile } from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { composeRuntimeBackend } from "../src/backends/runtime-backend.ts"; +import { + type ComposeStartupPhase, + composeStartupFailure, +} from "../src/lib/compose-startup-budget.ts"; + +/** + * Stub `docker` that models Compose image handling without a Docker engine: + * any `up` without `--no-build` "builds" missing images (sleeping + * STUB_BUILD_SECONDS, then marking them present); `up --no-build` refuses when + * images are missing; `up -d` then "starts" containers, and with + * STUB_START_HANG=1 waits forever on a grandchild like a dependency that never + * becomes healthy. It records each argv and the hanging grandchild's pid. + */ +const STUB_DOCKER = `#!/bin/sh +[ "$1" = warmup ] && exit 0 +dir="$(dirname "$0")" +echo "$*" >> "$dir/calls.log" +no_build=0; no_start=0; detach=0 +for arg in "$@"; do + case "$arg" in + --no-build) no_build=1 ;; + --no-start) no_start=1 ;; + -d) detach=1 ;; + esac +done +if [ ! -f "$dir/images-ready" ]; then + if [ "$no_build" = 1 ]; then + echo "image missing" >&2 + exit 17 + fi + sleep "$STUB_BUILD_SECONDS" + if [ "$STUB_BUILD_HANG" = 1 ]; then + sleep 30 & + echo $! > "$dir/hang.pid" + wait + fi + : > "$dir/images-ready" +fi +if [ "$no_start" = 1 ] || [ "$detach" = 0 ]; then + exit 0 +fi +if [ "$STUB_START_HANG" = 1 ]; then + sleep 30 & + echo $! > "$dir/hang.pid" + wait +fi +exit 0 +`; + +const dirs: string[] = []; + +afterEach(async () => { + for (const dir of dirs.splice(0)) { + await rm(dir, { recursive: true, force: true }); + } +}); + +async function stubCompose(opts: { + readonly buildSeconds: number; + readonly buildHang?: boolean; + readonly startHang?: boolean; +}) { + const dir = await mkdtemp(join(tmpdir(), "hack-compose-phases-")); + dirs.push(dir); + await writeFile(join(dir, "docker"), STUB_DOCKER); + await chmod(join(dir, "docker"), 0o700); + // Execute the new script once outside any deadline: the first exec of a + // freshly written executable can be slow (for example, macOS policy scans) + // and must not be charged to the 1 s budgets under test. + expect(Bun.spawnSync([join(dir, "docker"), "warmup"]).exitCode).toBe(0); + return { + dir, + env: { + // The stub shadows any engine client; no socket or HOME is reachable. + PATH: `${dir}:/usr/bin:/bin`, + HOME: dir, + DOCKER_HOST: `unix://${join(dir, "no-engine.sock")}`, + STUB_BUILD_SECONDS: String(opts.buildSeconds), + STUB_BUILD_HANG: opts.buildHang ? "1" : "0", + STUB_START_HANG: opts.startHang ? "1" : "0", + }, + }; +} + +async function detachedUp(opts: { + readonly dir: string; + readonly env: Record; + readonly startupTimeoutMs: number; + readonly imageTimeoutMs: number; +}) { + const phases: ComposeStartupPhase[] = []; + const started = Date.now(); + const code = await composeRuntimeBackend.up({ + composeFiles: ["compose.yml"], + composeProject: "phases", + cwd: opts.dir, + env: opts.env, + detach: true, + startupTimeoutMs: opts.startupTimeoutMs, + imageTimeoutMs: opts.imageTimeoutMs, + routeStdoutToStderr: true, + onStartupPhase: (phase) => { + phases.push(phase); + }, + }); + const calls = (await readFile(join(opts.dir, "calls.log"), "utf8")) + .trim() + .split("\n"); + return { code, phases, calls, elapsedMs: Date.now() - started }; +} + +function processExists(pid: number): boolean { + try { + process.kill(pid, 0); + return true; + } catch { + return false; + } +} + +async function expectProcessGone(pid: number): Promise { + const deadline = Date.now() + 4000; + while (processExists(pid) && Date.now() < deadline) { + await Bun.sleep(50); + } + expect(processExists(pid)).toBe(false); +} + +test("a first-time build longer than the startup budget still starts", async () => { + // Build takes 1.6 s; the start/dependency-wait budget is only 1 s. + const stub = await stubCompose({ buildSeconds: 1.6 }); + const result = await detachedUp({ + ...stub, + startupTimeoutMs: 1000, + imageTimeoutMs: 10_000, + }); + + expect(result.code).toBe(0); + expect(result.phases).toEqual(["images", "start"]); + expect(result.calls).toEqual([ + "compose -p phases -f compose.yml up --no-start", + "compose -p phases -f compose.yml up -d --no-build", + ]); +}, 15_000); + +test("a genuine readiness hang still times out in the named start phase", async () => { + const stub = await stubCompose({ buildSeconds: 0, startHang: true }); + const result = await detachedUp({ + ...stub, + startupTimeoutMs: 1000, + imageTimeoutMs: 10_000, + }); + + expect(result.code).toBe(124); + expect(result.phases).toEqual(["images", "start"]); + // Bounded by the 1 s start budget, not the 10 s image budget. + expect(result.elapsedMs).toBeLessThan(5000); + // The owned process group, including the hanging grandchild, is terminated. + const hangPid = Number(await readFile(join(stub.dir, "hang.pid"), "utf8")); + await expectProcessGone(hangPid); + + const failure = composeStartupFailure({ + code: result.code, + action: "docker compose up", + phase: result.phases.at(-1) ?? "start", + budgets: { startupTimeoutMs: 1000, imageTimeoutMs: 10_000 }, + }); + expect(failure.code).toBe("E_STARTUP_TIMEOUT"); + expect(failure.message).toContain( + "startup budget of 1000 ms (phase: start and dependency wait)" + ); + expect(failure.message).toContain( + "Raise it with HACK_COMPOSE_STARTUP_TIMEOUT_MS=" + ); +}, 15_000); + +test("a hung image build times out in the named image phase without starting", async () => { + const stub = await stubCompose({ buildSeconds: 0, buildHang: true }); + const result = await detachedUp({ + ...stub, + startupTimeoutMs: 60_000, + imageTimeoutMs: 1000, + }); + + expect(result.code).toBe(124); + expect(result.phases).toEqual(["images"]); + expect(result.calls).toEqual([ + "compose -p phases -f compose.yml up --no-start", + ]); + expect(result.elapsedMs).toBeLessThan(5000); + const hangPid = Number(await readFile(join(stub.dir, "hang.pid"), "utf8")); + await expectProcessGone(hangPid); + + const failure = composeStartupFailure({ + code: result.code, + action: "docker compose up", + phase: result.phases.at(-1) ?? "start", + budgets: { startupTimeoutMs: 60_000, imageTimeoutMs: 1000 }, + }); + expect(failure.code).toBe("E_STARTUP_TIMEOUT"); + expect(failure.message).toContain( + "image build/pull budget of 1000 ms (phase: image build/pull and container creation)" + ); + expect(failure.message).toContain( + "Raise it with HACK_COMPOSE_IMAGE_TIMEOUT_MS=" + ); +}, 15_000); + +test("non-timeout failures keep E_COMPOSE_FAILED and name the phase", () => { + const failure = composeStartupFailure({ + code: 17, + action: "docker compose up", + phase: "images", + budgets: { startupTimeoutMs: 90_000, imageTimeoutMs: 1_800_000 }, + }); + expect(failure).toMatchObject({ + code: "E_COMPOSE_FAILED", + message: + "docker compose up failed (exit 17) during Compose image build/pull and container creation", + }); +}); diff --git a/tests/project-up-startup-state.test.ts b/tests/project-up-startup-state.test.ts index f2524eaf..c7148f5f 100644 --- a/tests/project-up-startup-state.test.ts +++ b/tests/project-up-startup-state.test.ts @@ -33,6 +33,9 @@ const psEnvs: Array> | undefined> = []; const upDetachSelections: Array = []; const upStartupTimeouts: Array = []; let upExitCode = 0; +/** Detached phases the mocked backend reports before returning upExitCode. */ +let upReportedPhases: readonly ("images" | "start")[] = []; +const upImageTimeouts: Array = []; let downCalls = 0; const upServiceSelections: Array = []; const tempDirs = new Set(); @@ -89,7 +92,11 @@ const runtimeBackendMock = await registerScopedModuleMock({ upEnvs.push(opts.env); upServiceSelections.push(opts.services); upStartupTimeouts.push(opts.startupTimeoutMs); + upImageTimeouts.push(opts.imageTimeoutMs); upDetachSelections.push(opts.detach); + for (const phase of upReportedPhases) { + opts.onStartupPhase?.(phase); + } return upExitCode; }, down: async () => { @@ -156,8 +163,11 @@ beforeAll(() => { loggerMock.activate(); }); +const originalImageTimeout = process.env.HACK_COMPOSE_IMAGE_TIMEOUT_MS; + beforeEach(() => { Reflect.deleteProperty(process.env, "HACK_COMPOSE_STARTUP_TIMEOUT_MS"); + Reflect.deleteProperty(process.env, "HACK_COMPOSE_IMAGE_TIMEOUT_MS"); }); afterEach(async () => { @@ -171,6 +181,9 @@ afterEach(async () => { upStartupTimeouts.length = 0; upDetachSelections.length = 0; upExitCode = 0; + upReportedPhases = []; + upImageTimeouts.length = 0; + restoreEnv("HACK_COMPOSE_IMAGE_TIMEOUT_MS", originalImageTimeout); downCalls = 0; if (originalStartupTimeout === undefined) { Reflect.deleteProperty(process.env, "HACK_COMPOSE_STARTUP_TIMEOUT_MS"); @@ -664,6 +677,92 @@ for (const action of ["up", "restart", "scoped restart"] as const) { }); } +for (const action of ["up", "restart", "scoped restart"] as const) { + const run = (projectRoot: string) => + action === "up" + ? runDetachedUp({ projectRoot }) + : runRestart({ + projectRoot, + ...(action === "scoped restart" ? { services: ["api"] } : {}), + }); + + test(`${action} forwards a separate image build/pull budget to Compose`, async () => { + process.env.HACK_COMPOSE_IMAGE_TIMEOUT_MS = "2400000"; + const projectRoot = await createProject(); + psRows.push( + JSON.stringify({ Service: "api", State: "running", ExitCode: 0 }) + ); + + expect(await run(projectRoot)).toBe(0); + expect(upImageTimeouts).toEqual([2_400_000]); + expect(upStartupTimeouts).toEqual([90_000]); + }); + + test(`${action} names the image phase and its variable when image build/pull times out`, async () => { + process.env.HACK_COMPOSE_IMAGE_TIMEOUT_MS = "2400000"; + upReportedPhases = ["images"]; + upExitCode = 124; + const projectRoot = await createProject(); + + expect(await run(projectRoot)).toBe(124); + const errors = errorMessages.join("\n"); + expect(errors).toContain( + "image build/pull budget of 2400000 ms (phase: image build/pull and container creation)" + ); + expect(errors).toContain("HACK_COMPOSE_IMAGE_TIMEOUT_MS="); + }); + + test(`${action} names the start phase when dependency wait times out after a build`, async () => { + upReportedPhases = ["images", "start"]; + upExitCode = 124; + const projectRoot = await createProject(); + + expect(await run(projectRoot)).toBe(124); + const errors = errorMessages.join("\n"); + expect(errors).toContain( + "startup budget of 90000 ms (phase: start and dependency wait)" + ); + expect(errors).toContain("HACK_COMPOSE_STARTUP_TIMEOUT_MS="); + expect(errors).not.toContain("HACK_COMPOSE_IMAGE_TIMEOUT_MS="); + }); + + test(`${action} rejects an invalid image budget before hooks or backend effects`, async () => { + process.env.HACK_COMPOSE_IMAGE_TIMEOUT_MS = "soon"; + const projectRoot = await createProject({ + lifecycleCommand: "touch image-budget-hook-ran", + }); + + await expect(run(projectRoot)).rejects.toThrow( + "HACK_COMPOSE_IMAGE_TIMEOUT_MS" + ); + expect( + await Bun.file(resolve(projectRoot, "image-budget-hook-ran")).exists() + ).toBe(false); + expect(upComposeContents).toEqual([]); + expect(downCalls).toBe(0); + }); +} + +test("up JSON reports the timed-out Compose phase and its budget", async () => { + upReportedPhases = ["images"]; + upExitCode = 124; + const projectRoot = await createProject(); + const result = await runJsonUp({ projectRoot }); + expect(result.exitCode).toBe(124); + expect(JSON.parse(result.stdout)).toMatchObject({ + ok: false, + error: { + code: "E_STARTUP_TIMEOUT", + detail: { + exitCode: 124, + composePhase: "images", + budgetMs: 1_800_000, + budgetEnv: "HACK_COMPOSE_IMAGE_TIMEOUT_MS", + }, + }, + }); +}); + test("foreground up ignores an invalid detached startup budget", async () => { process.env.HACK_COMPOSE_STARTUP_TIMEOUT_MS = "invalid"; const projectRoot = await createProject(); diff --git a/tests/runtime-backend.test.ts b/tests/runtime-backend.test.ts index 7370336c..5106dc71 100644 --- a/tests/runtime-backend.test.ts +++ b/tests/runtime-backend.test.ts @@ -94,7 +94,7 @@ test("composeRuntimeBackend.up builds compose args with profiles and detach", as cwd: "/tmp", }); - expect(runCalls[0]).toEqual([ + const base = [ "docker", "compose", "-p", @@ -105,8 +105,11 @@ test("composeRuntimeBackend.up builds compose args with profiles and detach", as "b.yml", "--profile", "ops", - "up", - "-d", + ]; + // Image build/pull and container creation, then start and dependency wait. + expect(runCalls).toEqual([ + [...base, "up", "--no-start"], + [...base, "up", "-d", "--no-build"], ]); }); @@ -123,19 +126,26 @@ test("composeRuntimeBackend.up targets services without dependencies", async () cwd: "/tmp", }); - expect(runCalls[0]).toEqual([ + const base = [ "docker", "compose", "-p", "myproj", "-f", "docker-compose.yml", - "up", - "-d", - "--no-deps", - "--force-recreate", - "chat-q", - "sim-runner", + ]; + // Recreation happens once, in the image phase; the start phase only starts. + expect(runCalls).toEqual([ + [ + ...base, + "up", + "--no-start", + "--force-recreate", + "--no-deps", + "chat-q", + "sim-runner", + ], + [...base, "up", "-d", "--no-build", "--no-deps", "chat-q", "sim-runner"], ]); }); @@ -404,11 +414,19 @@ test("detached startup uses selected budget and down keeps its fixed budget", as env: { HACK_COMPOSE_STARTUP_TIMEOUT_MS: "600000" }, }; await backend.up({ ...base, detach: true }); - expect(runOpts[0]?.timeoutMs).toBe(600_000); - await backend.up({ ...base, detach: true, startupTimeoutMs: 120_000 }); - expect(runOpts[1]?.timeoutMs).toBe(120_000); + // The image phase keeps its own default; only the start phase uses this. + expect(runOpts.map((opts) => opts.timeoutMs)).toEqual([1_800_000, 600_000]); + await backend.up({ + ...base, + detach: true, + startupTimeoutMs: 120_000, + imageTimeoutMs: 2_400_000, + }); + expect(runOpts.slice(2).map((opts) => opts.timeoutMs)).toEqual([ + 2_400_000, 120_000, + ]); await backend.down(base); - expect(runOpts[2]?.timeoutMs).toBe(90_000); + expect(runOpts[4]?.timeoutMs).toBe(90_000); }); test("invalid startup budget refuses before invoking Compose", async () => {