diff --git a/docs/architecture.md b/docs/architecture.md index 19afd576f..6adc5ba82 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -70,8 +70,10 @@ graph LR - `.internal/extra-hosts.json` — CLI-managed, not hand-edited (use `hack internal extra-hosts set/unset/list`) - `.branch/compose..override.yml` (branch builds) - - Everything under `.hack/.internal` is a hack-managed artifact; do not hand-edit generated files - there. + - Everything under `.hack/.internal` is a hack-managed, machine-local artifact; do not hand-edit + or commit generated files there. Newer Hack versions rewrite them (for example + `compose.override.yml`), so a tracked copy leaves the working tree dirty; `hack doctor` + reports tracked files and `hack doctor --fix` untracks them. ## Internal DNS + TLS (containers) @@ -185,6 +187,25 @@ sequenceDiagram NDJSON streaming (`hack logs --json`) emits `start`, `log`, `error`, and `end` events for MCP/TUI consumers. +Snapshots (`hack logs --no-follow`) use Loki by default (`logs.snapshotBackend`). Without +`--since`, a Loki snapshot looks back 24 hours and returns the newest `--tail` entries. If Loki +returns no entries and Loki was not requested explicitly, `hack logs` writes a one-line notice +to stderr and answers from `docker compose logs` instead. Nothing from Loki is written first, +so `--json` output still has one `start`/`end` pair. When Loki was requested explicitly +(`--loki`, `--services`, `--query`, `--since`, `--until`), the empty result stands and the +notice suggests `hack logs --compose`. Follow mode (`hack logs` without `--no-follow`) +does not fall back. + +Short-lived containers: Alloy finds containers by polling Docker every 5 seconds. It includes +exited containers, so a one-shot Compose service (a migration or seed job) is shipped after it +stops, as long as Docker keeps the container. A container that starts, exits and is removed +between two polls (for example `docker compose run --rm`) never reaches Loki; use +`hack logs --compose` or the command's own output for those. Existing installs pick up this +discovery config after `hack global install` rewrites `~/.hack/logging/alloy.alloy` and the +Alloy container restarts (`hack global down` then `hack global up`). On its first start with +this config, Alloy also reads the retained logs of exited Compose containers. Loki rejects +entries older than its sample age limit (one week by default). + Retention: - Loki retention is set in the global Loki config (`~/.hack/logging/loki.yaml`), default `168h` in the template. - Per-project overrides live in `hack.config.json` under `logs.retention_period` and apply when `hack down` prunes logs. diff --git a/docs/guides/candidate-install.md b/docs/guides/candidate-install.md index f417fa166..94f49b3e1 100644 --- a/docs/guides/candidate-install.md +++ b/docs/guides/candidate-install.md @@ -96,9 +96,14 @@ Compose testing shares state with stable Hack: - The candidate reads and writes the same project registry, global configuration and project `.hack/` files as stable `hack`. Stable v4 uses an older registry lock protocol, so do not run stable `hack` and the candidate against the same - home at the same time. Stop one before you start the other. + home at the same time. Stop one before you start the other, including the + stable `hackd` daemon; see + [Stop stable hackd before a Compose run](#stop-stable-hackd-before-a-compose-run). - `hack-next` does not set up the shared global services for you. Install or - change them with stable `hack global` commands. + change them with stable `hack global` commands before the candidate run. +- Both backends write generated files under the project's `.hack/.internal/`. + Keep that directory out of Git; see + [Keep `.hack/.internal/` out of Git](#keep-hackinternal-out-of-git). - To test Compose in isolation instead, set `HACK_HOME` to a separate private directory. That home has no global services, so routing, container DNS and CA trust are not tested. @@ -118,6 +123,54 @@ The bundled `hack-v5` entrypoint follows the same rule for manual bundles: unset selects native and requires `HACK_NATIVE_HOME`; `compose` needs no native home and uses your own Hack home. +### Stop stable hackd before a Compose run + +A Compose candidate run uses the same `~/.hack` as stable Hack, so the stable +`hackd` daemon must not run while the candidate does. Stopping it once is not +enough: stable `hack global up` (v4.2.0) starts `hackd` again whenever it is +stopped, because the stable `daemon.autoStart` setting is on by default. Other +stable commands that talk to `hackd` can also start it again. + +Use this order: + +```sh +hack global up # stable: global services up; also restarts hackd +hack daemon stop # stable: stop hackd after global up, not before +pgrep -fl "hack daemon start" # must print nothing +HACK_RUNTIME_BACKEND=compose "$HOME/.hack-next/bin/hack-next" up --path /absolute/project +``` + +1. Run stable `hack global up` first, so the global Caddy and CoreDNS services run. +2. Then run stable `hack daemon stop`. +3. Then check with `pgrep -fl "hack daemon start"`. If it lists a process, a + stable `hackd` is still running, for example one that its launchd service + restarted. Do not start the candidate until the check prints nothing. + +Run no stable `hack` command against the same `~/.hack` while the candidate run +is active, including `hack global`, `hack status`, `hack doctor` and project +commands. Any of them can start `hackd` again or take the older registry lock. +When you finish, stop the candidate graph with +`HACK_RUNTIME_BACKEND=compose "$HOME/.hack-next/bin/hack-next" down --path /absolute/project`, +then use stable `hack` again. Stable `hack global up` or `hack daemon start` +starts `hackd` again when you need it. + +### Keep `.hack/.internal/` out of Git + +Do not commit a project's `.hack/.internal/` directory. It holds generated, +machine-local files, such as `.hack/.internal/compose.override.yml`, and Hack +rewrites them when project commands such as `up` run. Newer generators, including +candidate bundles, can write different content into those files than older ones. +If a project tracks `.hack/.internal/`, every run of a newer generator leaves its +working tree dirty, and switching between stable Hack and the candidate can make +the files change back and forth. + +Hack's committed `.hack/.gitignore` already ignores `.internal/`, but an ignore +rule does not untrack files that are already committed. Before a candidate run, +run stable `hack doctor` in the project. Its generated-files check lists any +tracked `.hack/.internal/` paths. `hack doctor --fix` removes them from the Git +index with `git rm --cached` and keeps the files on disk; commit that removal. +See [ignore rules](../env.md#ignore-rules-committed-hackgitignore). + ## Upgrade and return to a retained candidate Shared MCP, config compiler and storage witness packages need the matching diff --git a/docs/guides/native-candidate.md b/docs/guides/native-candidate.md index d642a5f26..330e110ed 100644 --- a/docs/guides/native-candidate.md +++ b/docs/guides/native-candidate.md @@ -117,7 +117,12 @@ selects the native backend and the adjacent executor, even if an inherited with your own Hack home and existing global routing services. It needs no `HACK_NATIVE_HOME` and removes the native selectors. Other values refuse with exit code 64. The [candidate installer guide](https://github.com/hack-dance/hack/blob/next/docs/guides/candidate-install.md#test-both-backends) -describes Compose testing and its shared-state limits. It preserves arguments, exit codes and +describes Compose testing and its shared-state limits: run stable `hack global up`, +then stable `hack daemon stop`, confirm `pgrep -fl "hack daemon start"` prints +nothing, and run no stable `hack` command while the candidate uses your Hack home. +Stable `hack global up` (v4.2.0) starts a stopped `hackd` again. Do not commit the +project's generated `.hack/.internal/` directory; newer generators rewrite files +such as `compose.override.yml`. The entrypoint preserves arguments, exit codes and signals through `exec`, and never replaces the installed `hack`. Project-specific native adaptation, dependency and routing selections remain explicit; this entrypoint does not prepare a provider or migrate existing projects. An unversioned local diff --git a/docs/guides/v5-dogfooding.md b/docs/guides/v5-dogfooding.md index 461b72311..fe5f5bef2 100644 --- a/docs/guides/v5-dogfooding.md +++ b/docs/guides/v5-dogfooding.md @@ -40,7 +40,12 @@ These commands do not establish that an arbitrary v4 project can run natively. `HACK_RUNTIME_BACKEND=compose hack-next` runs the same candidate on Compose with your own Hack home, so global routing, DNS and CA trust are checked too. See [Test both backends](candidate-install.md#test-both-backends), including why - stable `hack` must not run against the same home at the same time. + stable `hack` must not run against the same home at the same time. For a Compose + run, use the order in + [Stop stable hackd before a Compose run](candidate-install.md#stop-stable-hackd-before-a-compose-run): + stable `hack global up`, then `hack daemon stop`, then confirm + `pgrep -fl "hack daemon start"` prints nothing. Keep the project's + `.hack/.internal/` directory out of Git. 3. Exercise the project's supported command form: foreground start, readiness, status, finite logs, noninteractive exec, retaining stop and restart. Exercise one-off run only where admitted. For an authored project, check generated public diff --git a/src/backends/log-backend.ts b/src/backends/log-backend.ts index 885b83179..1ea54588e 100644 --- a/src/backends/log-backend.ts +++ b/src/backends/log-backend.ts @@ -1,10 +1,11 @@ +import type { LokiSnapshotOutcome } from "../lib/logs.ts"; import { dockerComposeLogsJson, dockerComposeLogsPlain, dockerComposeLogsPretty, } from "../ui/docker-logs.ts"; import type { LogStreamContext } from "../ui/log-stream.ts"; -import { canReachLoki, lokiLogs } from "../ui/loki-logs.ts"; +import { canReachLoki, lokiLogs, lokiSnapshot } from "../ui/loki-logs.ts"; export type LogBackendName = "compose" | "loki"; export type LogOutputFormat = "plain" | "pretty" | "json"; @@ -50,7 +51,15 @@ export interface LogBackendAvailability { export type ComposeLogBackend = LogBackend; export type LokiLogBackend = LogBackend & - LogBackendAvailability; + LogBackendAvailability & { + /** + * Bounded, non-follow snapshot. With `deferEmpty`, an empty result writes + * nothing and reports `deferred` so the caller can use another backend. + */ + snapshot( + opts: Omit & { readonly deferEmpty: boolean } + ): Promise; + }; export const composeLogBackend: ComposeLogBackend = { name: "compose", @@ -117,4 +126,19 @@ export const lokiLogBackend: LokiLogBackend = { end: opts.end, }); }, + async snapshot(opts) { + return await lokiSnapshot({ + baseUrl: opts.baseUrl, + query: opts.query, + follow: false, + tail: opts.tail, + pretty: opts.format === "pretty", + json: opts.format === "json" ? true : undefined, + showProjectPrefix: opts.showProjectPrefix, + streamContext: opts.streamContext, + start: opts.start, + end: opts.end, + deferEmpty: opts.deferEmpty, + }); + }, }; diff --git a/src/commands/project.ts b/src/commands/project.ts index 05167681c..52ee4991f 100644 --- a/src/commands/project.ts +++ b/src/commands/project.ts @@ -223,6 +223,7 @@ import { buildLogSelector, resolveShouldTryLoki, resolveUseLoki, + runLokiSnapshotWithFallback, } from "../lib/logs.ts"; import { refuseNativeComposeBackendFeatures } from "../lib/native-compose-backend-features.ts"; import { tryNativeComposeCommand } from "../lib/native-compose-command.ts"; @@ -8082,6 +8083,9 @@ async function runLogsWithLoki(opts: { readonly queryOpt: string | undefined; readonly since: string | undefined; readonly until: string | undefined; + readonly wantsLokiExplicit: boolean; + /** Compose snapshot used when an implicit Loki snapshot comes back empty. */ + readonly runCompose: () => Promise; }): Promise { if (isSlimExecutionMode()) { process.stderr.write( @@ -8124,16 +8128,30 @@ async function runLogsWithLoki(opts: { services, }); - return await lokiLogBackend.run({ + const lokiOptions = { baseUrl: opts.baseUrl, query, - follow: opts.follow, tail: opts.tail, format: opts.format, showProjectPrefix: true, streamContext, start: opts.timeRange.start ?? undefined, end: opts.timeRange.end ?? undefined, + }; + if (opts.follow) { + return await lokiLogBackend.run({ ...lokiOptions, follow: true }); + } + + return await runLokiSnapshotWithFallback({ + wantsLokiExplicit: opts.wantsLokiExplicit, + query, + service: opts.positionalService, + runLoki: async ({ deferEmpty }) => + await lokiLogBackend.snapshot({ ...lokiOptions, deferEmpty }), + runCompose: opts.runCompose, + writeNotice: (line) => { + process.stderr.write(`${line}\n`); + }, }); } @@ -8446,6 +8464,22 @@ async function handleLogs({ lokiReachable, }); + const runCompose = async (): Promise => + await runLogsWithCompose({ + project, + projectNameForPrefix, + composeProject: branch ? projectNameForPrefix : undefined, + branch, + json, + follow, + tail, + service: typeof service === "string" ? service : undefined, + profiles, + format, + since: args.options.since, + until: args.options.until, + }); + if (useLoki) { return await runLogsWithLoki({ baseUrl, @@ -8462,24 +8496,13 @@ async function handleLogs({ queryOpt: args.options.query, since: args.options.since, until: args.options.until, + wantsLokiExplicit, + runCompose, }); } // Fallback to docker compose logs when Loki isn't available. - return await runLogsWithCompose({ - project, - projectNameForPrefix, - composeProject: branch ? projectNameForPrefix : undefined, - branch, - json, - follow, - tail, - service: typeof service === "string" ? service : undefined, - profiles, - format, - since: args.options.since, - until: args.options.until, - }); + return await runCompose(); } /** An omitted option stays omitted so native dispatch can distinguish it from an explicit empty list. */ diff --git a/src/lib/logs.ts b/src/lib/logs.ts index 64f31e14a..984de23ab 100644 --- a/src/lib/logs.ts +++ b/src/lib/logs.ts @@ -58,3 +58,118 @@ function quoteLogql(value: string): string { function escapeRegex(value: string): string { return value.replaceAll(/[.*+?^${}()|[\]\\]/g, "\\\\$&"); } + +/** + * Lookback used for a Loki snapshot (`hack logs --no-follow`) when neither + * `--since` nor `--until` bounds the start. + * + * Compose snapshots have no time bound: `docker compose logs --tail N` shows the + * last N lines of every container, including containers that exited long ago. + * A short Loki window made a quiet or already-exited service look empty, so the + * default covers a working day while staying well inside the default 168h + * retention. Older history needs an explicit `--since`. + */ +export const DEFAULT_LOKI_SNAPSHOT_LOOKBACK_MS = 24 * 60 * 60 * 1000; + +export interface LokiQueryWindow { + readonly start: Date; + readonly end: Date; +} + +/** + * Resolve the `[start, end]` range for a Loki `query_range` snapshot. + * + * An explicit start or end always wins; a missing end is `now`, and a missing + * start is {@link DEFAULT_LOKI_SNAPSHOT_LOOKBACK_MS} before the end. + */ +export function resolveLokiQueryWindow(opts: { + readonly start?: Date; + readonly end?: Date; + readonly now: Date; +}): LokiQueryWindow { + const end = opts.end ?? opts.now; + const start = + opts.start ?? new Date(end.getTime() - DEFAULT_LOKI_SNAPSHOT_LOOKBACK_MS); + return { start, end }; +} + +/** Result of one Loki snapshot as reported to {@link runLokiSnapshotWithFallback}. */ +export interface LokiSnapshotOutcome { + readonly exitCode: number; + /** Log entries Loki returned; zero for a failed query. */ + readonly entryCount: number; + /** + * True only when the snapshot was empty and the caller asked to defer empty + * results: nothing was written to stdout, so another backend may answer. + */ + readonly deferred: boolean; +} + +/** + * Run a Loki snapshot and handle an empty result. + * + * Alloy discovers containers by polling Docker, so a one-shot service that + * exits (and is removed) between polls never reaches Loki even though + * `docker compose logs` still shows its output. When Loki was chosen + * implicitly (project default `logs.snapshotBackend`), an empty snapshot falls + * back to the compose backend before any output is written, so stdout carries + * exactly one backend's stream. When Loki was requested explicitly (`--loki`, + * `--services`, `--query`, `--since`, `--until`), the Loki result stands and a + * one-line hint on stderr points at `--compose`. + */ +export async function runLokiSnapshotWithFallback(opts: { + readonly wantsLokiExplicit: boolean; + readonly query: string; + readonly service: string | undefined; + readonly runLoki: (opts: { + readonly deferEmpty: boolean; + }) => Promise; + readonly runCompose: () => Promise; + readonly writeNotice: (line: string) => void; +}): Promise { + if (opts.wantsLokiExplicit) { + const outcome = await opts.runLoki({ deferEmpty: false }); + if (outcome.exitCode === 0 && outcome.entryCount === 0) { + opts.writeNotice( + renderEmptyLokiSnapshotNotice({ + action: "hint", + query: opts.query, + service: opts.service, + }) + ); + } + return outcome.exitCode; + } + + const outcome = await opts.runLoki({ deferEmpty: true }); + if (!outcome.deferred) { + return outcome.exitCode; + } + opts.writeNotice( + renderEmptyLokiSnapshotNotice({ + action: "fallback", + query: opts.query, + service: opts.service, + }) + ); + return await opts.runCompose(); +} + +/** One-line stderr notice for an empty Loki snapshot. */ +export function renderEmptyLokiSnapshotNotice(opts: { + readonly action: "fallback" | "hint"; + readonly query: string; + readonly service: string | undefined; +}): string { + const reason = + "a short-lived container can exit before Alloy discovers it, and older logs sit outside the queried window"; + if (opts.action === "fallback") { + return `Loki returned no log entries for ${opts.query}; showing docker compose logs instead (${reason}).`; + } + const service = (opts.service ?? "").trim(); + const composeCommand = + service.length > 0 + ? `hack logs --compose ${service}` + : "hack logs --compose"; + return `Loki returned no log entries for ${opts.query} (${reason}); try \`${composeCommand}\`.`; +} diff --git a/src/templates.ts b/src/templates.ts index 0c7b447be..69bbdaa27 100644 --- a/src/templates.ts +++ b/src/templates.ts @@ -184,15 +184,50 @@ export function renderGlobalPromtailYaml(): string { return renderGlobalAlloyConfig(); } +/** + * Docker discovery poll interval for the global Alloy config. A container that + * starts, exits and is removed within one interval can still be missed; one + * that exits but is kept (the Compose default) is shipped on the next poll. + */ +export const GLOBAL_ALLOY_DOCKER_REFRESH_INTERVAL = "5s"; + +/** + * Container states Alloy discovers. `exited` is what lets short-lived Compose + * services reach Loki; the others match Docker's default running-only listing. + */ +export const GLOBAL_ALLOY_DOCKER_STATUSES = [ + "running", + "restarting", + "paused", + "exited", +] as const; + export function renderGlobalAlloyConfig(): string { // Docs: // - https://grafana.com/docs/alloy/latest/reference/components/discovery/discovery.docker/ // - https://grafana.com/docs/alloy/latest/reference/components/discovery/discovery.relabel/ // - https://grafana.com/docs/alloy/latest/reference/components/loki/loki.source.docker/ // - https://grafana.com/docs/alloy/latest/reference/components/loki/loki.write/ + // + // Short-lived containers (HACK-1277): discovery.docker polls the Docker API and, + // by default, lists only running containers once a minute. A one-shot Compose + // service that started and exited between two polls was never tailed, so Loki + // had nothing while `docker compose logs` still showed its output. Docker sets + // `all=true` when a `status` filter is present, so exited containers are listed + // too and loki.source.docker reads their retained logs once (it restarts a + // tailer only while the container runs or finished after the last read). The + // poll interval is shortened so a container removed soon after it exits (for + // example `docker compose run --rm`) has a smaller window to be missed. return [ 'discovery.docker "local" {', - ' host = "unix:///var/run/docker.sock"', + ' host = "unix:///var/run/docker.sock"', + ` refresh_interval = "${GLOBAL_ALLOY_DOCKER_REFRESH_INTERVAL}"`, + "", + " // Include exited containers so one-shot services are shipped after they stop.", + " filter {", + ' name = "status"', + ` values = [${GLOBAL_ALLOY_DOCKER_STATUSES.map((status) => `"${status}"`).join(", ")}]`, + " }", "}", "", 'discovery.relabel "docker_compose" {', @@ -224,6 +259,22 @@ export function renderGlobalAlloyConfig(): string { ' source_labels = ["__meta_docker_container_label_com_docker_compose_project"]', ' target_label = "project"', " }", + "", + " // Keep each container's target identity stable when it stops: an exited", + " // container loses its IP, endpoint and published ports. loki.source.docker", + " // keys tailers and read positions by the full label set, so a changed set", + " // would re-read (duplicate) the container's whole log. Nothing below uses", + " // the network or port metadata.", + " rule {", + ' action = "labeldrop"', + ' regex = "__meta_docker_(network|port)_.+"', + " }", + "", + " rule {", + ' action = "replace"', + ' source_labels = ["__meta_docker_container_id"]', + ' target_label = "__address__"', + " }", "}", "", 'loki.source.docker "default" {', diff --git a/src/ui/loki-logs.ts b/src/ui/loki-logs.ts index 39d2da023..a3a9345d1 100644 --- a/src/ui/loki-logs.ts +++ b/src/ui/loki-logs.ts @@ -1,5 +1,9 @@ // biome-ignore-all lint/complexity/noExcessiveCognitiveComplexity: Loki transport helpers intentionally keep query and stream parsing stateful and local. import { isRecord } from "../lib/guards.ts"; +import { + type LokiSnapshotOutcome, + resolveLokiQueryWindow, +} from "../lib/logs.ts"; import { formatPrettyLogLine } from "./log-format.ts"; import { parseLokiLogLine, writeJsonLogLine } from "./log-json.ts"; import type { LogStreamContext } from "./log-stream.ts"; @@ -22,6 +26,12 @@ export interface LokiLogsParams { readonly start?: Date; readonly end?: Date; readonly streamContext?: LogStreamContext; + /** + * Snapshot only: when Loki returns no entries, write nothing (not even the + * NDJSON start/end events) and report `deferred` so the caller can answer + * from another backend. + */ + readonly deferEmpty?: boolean; } type LokiLabelSet = Record; @@ -107,9 +117,54 @@ export async function lokiLogs(opts: LokiLogsParams): Promise { return await lokiTail(opts); } + return (await lokiSnapshot(opts)).exitCode; +} + +/** + * Query a bounded snapshot of Loki logs (`query_range`, newest first, limited + * to `tail` entries) and print it oldest first. + * + * With `deferEmpty`, an empty result writes nothing and returns + * `deferred: true`; see {@link LokiLogsParams.deferEmpty}. + */ +export async function lokiSnapshot( + opts: LokiLogsParams +): Promise { return await lokiQueryRange(opts); } +/** + * Build the Loki `query_range` URL for a snapshot. Pure: the time window comes + * from {@link resolveLokiQueryWindow} with the supplied `now`. + */ +export function buildLokiQueryRangeUrl(opts: { + readonly baseUrl: string; + readonly query: string; + readonly tail: number; + readonly start?: Date; + readonly end?: Date; + readonly now: Date; +}): URL { + const window = resolveLokiQueryWindow({ + start: opts.start, + end: opts.end, + now: opts.now, + }); + const url = new URL( + `${normalizeBaseUrl(opts.baseUrl)}/loki/api/v1/query_range` + ); + url.searchParams.set("query", opts.query); + url.searchParams.set("direction", "BACKWARD"); + url.searchParams.set("limit", String(opts.tail)); + url.searchParams.set("start", toUnixNs(window.start)); + url.searchParams.set("end", toUnixNs(window.end)); + return url; +} + +function toUnixNs(date: Date): string { + return (BigInt(date.getTime()) * 1_000_000n).toString(); +} + function normalizeBaseUrl(baseUrl: string): string { const trimmed = baseUrl.trim().replaceAll(/\/+$/g, ""); return trimmed.length > 0 ? trimmed : "http://127.0.0.1:3100"; @@ -142,20 +197,24 @@ function linePrefix(opts: { return `${project}/${service}`; } -async function lokiQueryRange(opts: LokiLogsParams): Promise { +async function lokiQueryRange( + opts: LokiLogsParams +): Promise { const baseUrl = normalizeBaseUrl(opts.baseUrl); + const failed: LokiSnapshotOutcome = { + exitCode: 1, + entryCount: 0, + deferred: false, + }; - const endDate = opts.end ?? new Date(); - const endNs = BigInt(endDate.getTime()) * 1_000_000n; - const startDate = opts.start ?? new Date(endDate.getTime() - 15 * 60 * 1000); - const startNs = BigInt(startDate.getTime()) * 1_000_000n; - - const url = new URL(`${baseUrl}/loki/api/v1/query_range`); - url.searchParams.set("query", opts.query); - url.searchParams.set("direction", "BACKWARD"); - url.searchParams.set("limit", String(opts.tail)); - url.searchParams.set("start", startNs.toString()); - url.searchParams.set("end", endNs.toString()); + const url = buildLokiQueryRangeUrl({ + baseUrl, + query: opts.query, + tail: opts.tail, + start: opts.start, + end: opts.end, + now: new Date(), + }); let res: Response; try { @@ -182,7 +241,7 @@ async function lokiQueryRange(opts: LokiLogsParams): Promise { process.stderr.write( "Tip: run `hack global install` (or `hack global up`) and ensure Loki is reachable.\n" ); - return 1; + return failed; } if (!res.ok) { if (opts.json && opts.streamContext) { @@ -202,7 +261,7 @@ async function lokiQueryRange(opts: LokiLogsParams): Promise { process.stderr.write( `Failed to query Loki (${res.status}): ${await res.text()}\n` ); - return 1; + return failed; } const json: unknown = await res.json(); @@ -223,7 +282,7 @@ async function lokiQueryRange(opts: LokiLogsParams): Promise { }); } process.stderr.write("Failed to parse Loki query response.\n"); - return 1; + return failed; } if (parsed.status !== "success") { @@ -242,15 +301,10 @@ async function lokiQueryRange(opts: LokiLogsParams): Promise { }); } process.stderr.write(`Loki error: ${parsed.error ?? "unknown error"}\n`); - return 1; + return failed; } const streams = parsed.data?.result ?? []; - if (opts.json && opts.streamContext) { - writeLogStreamEvent({ - event: buildLogStreamStartEvent({ context: opts.streamContext }), - }); - } const entries: Array<{ readonly labels: LokiLabelSet; readonly tsNs: string; @@ -261,6 +315,15 @@ async function lokiQueryRange(opts: LokiLogsParams): Promise { entries.push({ labels: s.stream, tsNs, line }); } } + if (entries.length === 0 && opts.deferEmpty) { + return { exitCode: 0, entryCount: 0, deferred: true }; + } + + if (opts.json && opts.streamContext) { + writeLogStreamEvent({ + event: buildLogStreamStartEvent({ context: opts.streamContext }), + }); + } // query_range BACKWARD returns newest→oldest; print oldest→newest for readability for (const e of entries.reverse()) { @@ -297,7 +360,7 @@ async function lokiQueryRange(opts: LokiLogsParams): Promise { }); } - return 0; + return { exitCode: 0, entryCount: entries.length, deferred: false }; } async function lokiTail(opts: LokiLogsParams): Promise { diff --git a/tests/logs-loki-empty-fallback-cli.test.ts b/tests/logs-loki-empty-fallback-cli.test.ts new file mode 100644 index 000000000..7fa64429c --- /dev/null +++ b/tests/logs-loki-empty-fallback-cli.test.ts @@ -0,0 +1,181 @@ +import { + afterAll, + afterEach, + beforeAll, + beforeEach, + expect, + test, +} from "bun:test"; +import { + chmod, + mkdir, + mkdtemp, + readFile, + realpath, + rm, + writeFile, +} from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join, resolve } from "node:path"; +import { privateCliEnv } from "./helpers/private-cli-env.ts"; + +/** + * HACK-1277: `hack logs --no-follow` reads Loki by default. A one-shot service + * that exited before Alloy discovered it has no Loki entries, while + * `docker compose logs` still has its output. The CLI must answer from compose + * (implicit Loki) or hint at `--compose` (explicit Loki). A stub `docker` and an + * in-process fake Loki stand in for the engine and the global logging stack. + */ +const CLI = resolve(import.meta.dir, "..", "index.ts"); +const COMPOSE_LINE = "migrate-1 | migrations applied (from compose)"; + +const STUB = [ + "#!/bin/sh", + 'printf "%s\\n" "$*" >> "$STUB_CAPTURE/docker-args.log"', + 'if [ "$1" = "compose" ]; then', + ' case " $* " in', + ` *" logs "*) printf "%s\\n" "${COMPOSE_LINE}"; exit 0 ;;`, + " *) exit 0 ;;", + " esac", + "fi", + "exit 0", + "", +].join("\n"); + +let root: string; +let projectRoot: string; +let capture: string; +let lokiStreams: unknown[] = []; +const lokiQueries: string[] = []; +let fakeLoki: ReturnType | null = null; + +beforeAll(() => { + fakeLoki = Bun.serve({ + hostname: "127.0.0.1", + port: 0, + fetch(request) { + const url = new URL(request.url); + if (url.pathname === "/ready") { + return new Response("ready"); + } + if (url.pathname === "/loki/api/v1/query_range") { + lokiQueries.push(url.searchParams.get("query") ?? ""); + return Response.json({ + status: "success", + data: { resultType: "streams", result: lokiStreams }, + }); + } + return new Response("not found", { status: 404 }); + }, + }); +}); + +afterAll(() => { + fakeLoki?.stop(true); +}); + +beforeEach(async () => { + root = await realpath(await mkdtemp(join(tmpdir(), "hack-loki-empty-"))); + projectRoot = join(root, "project"); + capture = join(root, "capture"); + const hackDir = join(projectRoot, ".hack"); + await mkdir(hackDir, { recursive: true }); + await mkdir(capture); + await mkdir(join(root, "bin")); + await writeFile(join(root, "bin", "docker"), STUB); + await chmod(join(root, "bin", "docker"), 0o755); + await writeFile( + join(hackDir, "hack.config.json"), + `${JSON.stringify({ + name: "oneshot", + dev_host: "oneshot.hack", + internal: { dns: false, tls: false }, + })}\n` + ); + await writeFile( + join(hackDir, "docker-compose.yml"), + [ + "services:", + " migrate:", + " image: alpine:3.22", + ' command: ["echo", "migrations applied"]', + "", + ].join("\n") + ); +}); + +afterEach(async () => { + lokiStreams = []; + lokiQueries.length = 0; + await rm(root, { recursive: true, force: true }); +}); + +async function runLogs(args: readonly string[]) { + const child = Bun.spawn([process.execPath, CLI, "logs", ...args], { + cwd: projectRoot, + env: privateCliEnv({ + root, + env: { + PATH: `${join(root, "bin")}:/usr/bin:/bin`, + STUB_CAPTURE: capture, + HACK_NO_INTERACTIVE: "1", + HACK_LOKI_URL: `http://127.0.0.1:${fakeLoki?.port ?? 0}`, + }, + }), + stdin: "ignore", + stdout: "pipe", + stderr: "pipe", + }); + const [exitCode, stdout, stderr] = await Promise.all([ + child.exited, + new Response(child.stdout).text(), + new Response(child.stderr).text(), + ]); + return { exitCode, stdout, stderr }; +} + +async function composeLogsCalls(): Promise { + const log = await readFile(join(capture, "docker-args.log"), "utf8").catch( + () => "" + ); + return log.split("\n").filter((line) => / logs( |$)/.test(line)); +} + +test("implicit Loki snapshot with no entries answers from docker compose logs", async () => { + const result = await runLogs(["--no-follow", "migrate"]); + + expect(result.exitCode).toBe(0); + expect(lokiQueries).toEqual(['{project="oneshot",service="migrate"}']); + expect(result.stderr).toContain( + 'Loki returned no log entries for {project="oneshot",service="migrate"}; showing docker compose logs instead' + ); + expect(result.stdout).toContain("migrations applied (from compose)"); + expect(await composeLogsCalls()).toHaveLength(1); +}, 60_000); + +test("explicit --loki snapshot with no entries hints at --compose and stays on Loki", async () => { + const result = await runLogs(["--loki", "--no-follow", "migrate"]); + + expect(result.exitCode).toBe(0); + expect(lokiQueries).toHaveLength(1); + expect(result.stderr).toContain("try `hack logs --compose migrate`"); + expect(result.stdout).not.toContain("from compose"); + expect(await composeLogsCalls()).toEqual([]); +}, 60_000); + +test("implicit Loki snapshot with entries prints Loki and skips compose", async () => { + lokiStreams = [ + { + stream: { project: "oneshot", service: "migrate" }, + values: [["1792584000000000000", "migrations applied (from loki)"]], + }, + ]; + const result = await runLogs(["--no-follow", "migrate"]); + + expect(result.exitCode).toBe(0); + expect(result.stdout).toContain( + "oneshot/migrate | 2026-10-21T12:00:00.000Z migrations applied (from loki)" + ); + expect(result.stderr).not.toContain("Loki returned no log entries"); + expect(await composeLogsCalls()).toEqual([]); +}, 60_000); diff --git a/tests/loki-short-lived-logs.test.ts b/tests/loki-short-lived-logs.test.ts new file mode 100644 index 000000000..6ffd95393 --- /dev/null +++ b/tests/loki-short-lived-logs.test.ts @@ -0,0 +1,316 @@ +import { afterAll, afterEach, beforeAll, expect, test } from "bun:test"; + +import { + DEFAULT_LOKI_SNAPSHOT_LOOKBACK_MS, + type LokiSnapshotOutcome, + resolveLokiQueryWindow, + runLokiSnapshotWithFallback, +} from "../src/lib/logs.ts"; +import { + GLOBAL_ALLOY_DOCKER_REFRESH_INTERVAL, + renderGlobalAlloyConfig, +} from "../src/templates.ts"; +import { buildLokiQueryRangeUrl, lokiSnapshot } from "../src/ui/loki-logs.ts"; + +// HACK-1277: a one-shot Compose service that exits quickly must not make +// Loki-backed `hack logs` look empty while `docker compose logs` has output. + +const NOW = new Date("2026-10-21T12:00:00.000Z"); + +function ns(date: Date): string { + return (BigInt(date.getTime()) * 1_000_000n).toString(); +} + +test("Loki snapshot window defaults to a 24h lookback ending now", () => { + expect(DEFAULT_LOKI_SNAPSHOT_LOOKBACK_MS).toBe(24 * 60 * 60 * 1000); + const window = resolveLokiQueryWindow({ now: NOW }); + expect(window.end).toEqual(NOW); + expect(window.start).toEqual(new Date("2026-10-20T12:00:00.000Z")); +}); + +test("Loki snapshot window keeps explicit --since and --until", () => { + const since = new Date("2026-10-21T11:00:00.000Z"); + const until = new Date("2026-10-21T11:30:00.000Z"); + expect(resolveLokiQueryWindow({ start: since, now: NOW })).toEqual({ + start: since, + end: NOW, + }); + // --until alone looks back from the given end, not from now. + expect(resolveLokiQueryWindow({ end: until, now: NOW })).toEqual({ + start: new Date("2026-10-20T11:30:00.000Z"), + end: until, + }); +}); + +test("buildLokiQueryRangeUrl covers a service that exited before the old 15m window", () => { + const url = buildLokiQueryRangeUrl({ + baseUrl: "http://127.0.0.1:3100/", + query: '{project="demo",service="migrate"}', + tail: 200, + now: NOW, + }); + expect(`${url.origin}${url.pathname}`).toBe( + "http://127.0.0.1:3100/loki/api/v1/query_range" + ); + expect(url.searchParams.get("query")).toBe( + '{project="demo",service="migrate"}' + ); + expect(url.searchParams.get("direction")).toBe("BACKWARD"); + expect(url.searchParams.get("limit")).toBe("200"); + expect(url.searchParams.get("end")).toBe(ns(NOW)); + // A one-shot that exited 20 minutes ago is inside the queried range. + const exitedAt = new Date(NOW.getTime() - 20 * 60 * 1000); + const start = BigInt(url.searchParams.get("start") ?? "0"); + expect(start < BigInt(ns(exitedAt))).toBe(true); + expect(url.searchParams.get("start")).toBe( + ns(new Date("2026-10-20T12:00:00.000Z")) + ); +}); + +// --- lokiSnapshot against an in-process fake Loki ------------------------- + +let lokiStreams: unknown[] = []; +const lokiRequests: URL[] = []; +let fakeLoki: ReturnType | null = null; +let restoreStdout: () => void = () => undefined; +let stdout = ""; + +beforeAll(() => { + fakeLoki = Bun.serve({ + hostname: "127.0.0.1", + port: 0, + fetch(request) { + const url = new URL(request.url); + lokiRequests.push(url); + return Response.json({ + status: "success", + data: { resultType: "streams", result: lokiStreams }, + }); + }, + }); +}); + +afterAll(() => { + fakeLoki?.stop(true); +}); + +afterEach(() => { + restoreStdout(); + restoreStdout = () => undefined; + lokiStreams = []; + lokiRequests.length = 0; + stdout = ""; +}); + +function captureStdout(): void { + const original = process.stdout.write; + process.stdout.write = ((chunk: string | Uint8Array) => { + stdout += + typeof chunk === "string" ? chunk : new TextDecoder().decode(chunk); + return true; + }) as typeof process.stdout.write; + restoreStdout = () => { + process.stdout.write = original; + }; +} + +function fakeLokiUrl(): string { + return `http://127.0.0.1:${fakeLoki?.port ?? 0}`; +} + +const streamContext = { backend: "loki" as const, follow: false }; + +test("lokiSnapshot defers an empty result without writing any output", async () => { + captureStdout(); + const outcome = await lokiSnapshot({ + baseUrl: fakeLokiUrl(), + query: '{project="demo",service="migrate"}', + follow: false, + tail: 50, + pretty: false, + json: true, + showProjectPrefix: true, + streamContext, + deferEmpty: true, + }); + restoreStdout(); + + expect(outcome).toEqual({ exitCode: 0, entryCount: 0, deferred: true }); + // No NDJSON start/end pair: the fallback backend owns the only stream. + expect(stdout).toBe(""); + expect(lokiRequests).toHaveLength(1); +}); + +test("lokiSnapshot still writes an empty stream when not deferring", async () => { + captureStdout(); + const outcome = await lokiSnapshot({ + baseUrl: fakeLokiUrl(), + query: '{project="demo"}', + follow: false, + tail: 50, + pretty: false, + json: true, + showProjectPrefix: true, + streamContext, + }); + restoreStdout(); + + expect(outcome).toEqual({ exitCode: 0, entryCount: 0, deferred: false }); + const types = stdout + .trim() + .split("\n") + .map((line) => (JSON.parse(line) as { type: string }).type); + expect(types).toEqual(["start", "end"]); +}); + +test("lokiSnapshot prints entries and never defers a non-empty result", async () => { + lokiStreams = [ + { + stream: { project: "demo", service: "migrate" }, + values: [ + [ns(new Date("2026-10-21T11:40:00.002Z")), "migrations done"], + [ns(new Date("2026-10-21T11:40:00.001Z")), "running migrations"], + ], + }, + ]; + captureStdout(); + const outcome = await lokiSnapshot({ + baseUrl: fakeLokiUrl(), + query: '{project="demo",service="migrate"}', + follow: false, + tail: 50, + pretty: false, + showProjectPrefix: true, + deferEmpty: true, + }); + restoreStdout(); + + expect(outcome).toEqual({ exitCode: 0, entryCount: 2, deferred: false }); + expect(stdout).toBe( + [ + "demo/migrate | 2026-10-21T11:40:00.001Z running migrations", + "demo/migrate | 2026-10-21T11:40:00.002Z migrations done", + "", + ].join("\n") + ); +}); + +// --- empty-snapshot fallback policy --------------------------------------- + +function fallbackHarness(outcome: LokiSnapshotOutcome) { + const calls = { + lokiDeferEmpty: [] as boolean[], + compose: 0, + notices: [] as string[], + }; + const run = async (wantsLokiExplicit: boolean, service?: string) => + await runLokiSnapshotWithFallback({ + wantsLokiExplicit, + query: '{project="demo",service="migrate"}', + service, + runLoki: async ({ deferEmpty }) => { + calls.lokiDeferEmpty.push(deferEmpty); + return outcome; + }, + runCompose: async () => { + calls.compose += 1; + return 7; + }, + writeNotice: (line) => { + calls.notices.push(line); + }, + }); + return { calls, run }; +} + +test("implicit Loki snapshot with no entries falls back to compose logs", async () => { + const { calls, run } = fallbackHarness({ + exitCode: 0, + entryCount: 0, + deferred: true, + }); + expect(await run(false, "migrate")).toBe(7); + expect(calls.lokiDeferEmpty).toEqual([true]); + expect(calls.compose).toBe(1); + expect(calls.notices).toHaveLength(1); + expect(calls.notices[0]).toContain("showing docker compose logs instead"); + expect(calls.notices[0]).not.toContain("\n"); +}); + +test("implicit Loki snapshot with entries does not run compose", async () => { + const { calls, run } = fallbackHarness({ + exitCode: 0, + entryCount: 3, + deferred: false, + }); + expect(await run(false)).toBe(0); + expect(calls.compose).toBe(0); + expect(calls.notices).toEqual([]); +}); + +test("explicit Loki snapshot with no entries hints at --compose instead of falling back", async () => { + const { calls, run } = fallbackHarness({ + exitCode: 0, + entryCount: 0, + deferred: false, + }); + expect(await run(true, "migrate")).toBe(0); + expect(calls.lokiDeferEmpty).toEqual([false]); + expect(calls.compose).toBe(0); + expect(calls.notices).toHaveLength(1); + expect(calls.notices[0]).toContain("`hack logs --compose migrate`"); + expect(calls.notices[0]).not.toContain("\n"); +}); + +test("a failed Loki query keeps its exit code and adds no empty-result notice", async () => { + for (const explicit of [true, false]) { + const { calls, run } = fallbackHarness({ + exitCode: 1, + entryCount: 0, + deferred: false, + }); + expect(await run(explicit)).toBe(1); + expect(calls.compose).toBe(0); + expect(calls.notices).toEqual([]); + } +}); + +// --- Alloy discovery config ------------------------------------------------ + +test("Alloy discovers exited Compose containers so one-shot services reach Loki", () => { + const config = renderGlobalAlloyConfig(); + const discovery = config.slice( + config.indexOf('discovery.docker "local" {'), + config.indexOf('discovery.relabel "docker_compose" {') + ); + expect(discovery).toContain( + `refresh_interval = "${GLOBAL_ALLOY_DOCKER_REFRESH_INTERVAL}"` + ); + expect(GLOBAL_ALLOY_DOCKER_REFRESH_INTERVAL).toBe("5s"); + // Docker lists all containers once a status filter is present. + expect(discovery).toMatch( + /filter \{\s+name\s+= "status"\s+values = \["running", "restarting", "paused", "exited"\]\s+\}/ + ); +}); + +test("Alloy keeps a stopped container's target labels stable and still requires a Compose project", () => { + const config = renderGlobalAlloyConfig(); + const relabel = config.slice( + config.indexOf('discovery.relabel "docker_compose" {'), + config.indexOf('loki.source.docker "default" {') + ); + expect(relabel).toContain( + 'source_labels = ["__meta_docker_container_label_com_docker_compose_project"]' + ); + expect(relabel).toContain('action = "keep"'); + expect(relabel).toMatch( + /action = "labeldrop"\s+regex {2}= "__meta_docker_\(network\|port\)_\.\+"/ + ); + expect(relabel).toMatch( + /source_labels = \["__meta_docker_container_id"\]\s+target_label {2}= "__address__"/ + ); + // Stream labels used by `hack logs` selectors are unchanged. + for (const label of ["container", "service", "project"]) { + expect(relabel).toContain(`target_label = "${label}"`); + } +}); diff --git a/tests/native-compose-readiness-bounds.test.ts b/tests/native-compose-readiness-bounds.test.ts new file mode 100644 index 000000000..0ecf99515 --- /dev/null +++ b/tests/native-compose-readiness-bounds.test.ts @@ -0,0 +1,546 @@ +/** + * HACK-1305: pins the Compose startup readiness bounds that #362 (HACK-1279) added in + * `waitNativeComposeStartupOwned` and `queryNativeComposeOwned`: + * + * 1. A readiness timeout never becomes success, even when the post-deadline `settled` + * check finds every member owned and ready. + * 2. The `transient` flag (`first.transient || second.transient || recheck placeholders`, + * latched per observation) runs the `settled` check exactly when the last in-loop + * observation depended on a shape that `settled` refuses. + * 3. Every read that does not opt into `transient` membership keeps the strict behavior: + * strict and saved reads refuse every restart-race shape, and `settled` refuses the + * `running` shapes while still admitting `restarting` shapes exactly as before #362. + * + * The fake Docker serves one scripted scan per inspect call, so each query's first scan + * and recheck are exact. The readiness clock is virtual: `Bun.sleep` (the poll interval) + * advances `Date.now` past the deadline after a chosen number of in-loop observations, so + * the number of observations and the presence of the `settled` query are deterministic. + * No engine, HOME or Docker socket is reached: PATH holds only the fake. + */ +import { afterEach, beforeEach, expect, spyOn, test } from "bun:test"; +import { chmod, mkdtemp, readFile, rm } from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { + assertNativeComposeOwned, + NativeComposeOwnershipError, + type NativeComposeOwnershipObservation, + type NativeComposeOwnershipOptions, + type NativeComposeTopologyPredicate, + nativeComposeOwnershipRefusal, + nativeComposeTopologyPredicate, + observeNativeComposeStartupOwned, + observeSavedNativeComposeOwned, + waitNativeComposeStartupOwned, +} from "../src/lib/native-compose-ownership.ts"; +import { restoreEnv } from "./helpers/env.ts"; + +const PROJECT = "hack-fixture-instance"; +const NETWORK = `${PROJECT}_default`; +const OWNER = "0".repeat(32); +const GENERATION = "a".repeat(32); +const WEB_ID = "c".repeat(64); +const RETRY_ID = "3".repeat(64); +const NETWORK_ID = "d".repeat(64); +const PLACEHOLDER_KEY = `ep-${"9".repeat(64)}`; +/** + * Every query spawns about a dozen cold fake Docker processes, and one scenario runs up to + * sixteen queries. Budget host start-up on a loaded runner, not the product: each query gets + * the largest probe budget, and each test several of them. + */ +const PROBE_TIMEOUT_MS = 60_000; +const TEST_TIMEOUT_MS = 300_000; +/** Far beyond any scenario: only the virtual clock ever passes it. */ +const DEADLINE_MS = 600_000; + +const options: NativeComposeOwnershipOptions = { + composeProject: PROJECT, + runtimeIdentity: PROJECT, + ownerToken: OWNER, + generationIds: [GENERATION], + expectedServices: ["web", "retry"], + expectedNetwork: NETWORK, + timeoutMs: PROBE_TIMEOUT_MS, +}; +/** `retry` is the only selected on-failure service, as in the process-policy fixture. */ +const ON_FAILURE = ["retry"]; + +/** + * How one scan observes `retry` (inspected state, bridge key). `web` is always a running, + * healthy container-ID member. + */ +type RetryScan = + | "member" + | "absent-running" + | "absent-restarting" + | "placeholder-running" + | "placeholder-restarting"; +type Scan = { + readonly container: Record[]; + readonly network: Record[]; +}; +/** One startup query: its first scan, then its recheck. */ +type Query = readonly [RetryScan, RetryScan]; + +let root: string; +let path: string | undefined; +let restoreClock: (() => void) | undefined; + +beforeEach(async () => { + path = process.env.PATH; + root = await mkdtemp(join(tmpdir(), "native-compose-readiness-bounds-")); + process.env.PATH = root; + // Inspect call N of a kind serves scans[N] (clamped to the last scan). `ls` serves the + // fixed inventory, so only inspected state and bridge keys change between scans. + await Bun.write( + join(root, "docker"), + `#!${process.execPath} +import {appendFileSync, existsSync, readFileSync, writeFileSync} from "node:fs"; +const root = ${JSON.stringify(root)}; +const args = process.argv.slice(2); +appendFileSync(root + "/commands", JSON.stringify(args) + "\\n"); +const {scans} = JSON.parse(readFileSync(root + "/fixture.json", "utf8")); +const [kind, action] = args; +if (!["container","volume","network"].includes(kind) || !["ls","inspect"].includes(action) || !args.includes("--format")) { + writeFileSync(root + "/mutated", "unexpected engine mutation"); process.exit(99); +} +if (kind === "volume") process.exit(0); +if (action === "ls") { + for (const row of scans[0][kind]) console.log(JSON.stringify({id: row.id, name: row.name.replace(/^\\//, ""), project: row.project})); + process.exit(0); +} +const counter = root + "/inspects-" + kind; +const count = existsSync(counter) ? Number(readFileSync(counter, "utf8")) : 0; +writeFileSync(counter, String(count + 1)); +const rows = scans[Math.min(count, scans.length - 1)][kind]; +for (const id of args.slice(args.indexOf("--format") + 2)) { + const row = rows.find(row => row.id === id); if (!row) process.exit(1); console.log(JSON.stringify(row)); +} +` + ); + await chmod(join(root, "docker"), 0o700); +}); + +afterEach(async () => { + restoreClock?.(); + restoreClock = undefined; + restoreEnv("PATH", path); + await rm(root, { recursive: true, force: true }); +}); + +function container( + id: string, + service: string, + state: string +): Record { + return { + id, + name: `/${PROJECT}-${service}-1`, + project: PROJECT, + version: "1", + instance: PROJECT, + owner: OWNER, + generation: GENERATION, + service, + oneoff: "False", + state, + exitCode: state === "restarting" ? 17 : 0, + health: service === "web" ? "healthy" : null, + networks: { + [NETWORK]: { + NetworkID: NETWORK_ID, + Aliases: [`${PROJECT}-${service}-1`, service], + }, + }, + }; +} + +function scan(retry: RetryScan): Scan { + const members: Record = { + [WEB_ID]: { Name: `${PROJECT}-web-1` }, + }; + if (retry === "member") { + members[RETRY_ID] = { Name: `${PROJECT}-retry-1` }; + } else if (retry.startsWith("placeholder-")) { + members[PLACEHOLDER_KEY] = { Name: `${PROJECT}-retry-1` }; + } + return { + container: [ + container(WEB_ID, "web", "running"), + container( + RETRY_ID, + "retry", + retry.endsWith("restarting") ? "restarting" : "running" + ), + ], + network: [ + { + id: NETWORK_ID, + name: NETWORK, + project: PROJECT, + version: "1", + instance: PROJECT, + owner: OWNER, + driver: "bridge", + internal: false, + containers: members, + }, + ], + }; +} + +/** Script the queries in call order; the last scan repeats for any further inspect. */ +async function serve(...queries: readonly Query[]): Promise { + await Promise.all( + ["container", "network"].map((kind) => + rm(join(root, `inspects-${kind}`), { force: true }) + ) + ); + await rm(join(root, "commands"), { force: true }); + await Bun.write( + join(root, "fixture.json"), + JSON.stringify({ scans: queries.flat().map(scan) }) + ); +} + +/** Inspect calls so far; a complete query inspects each kind twice (4 calls). */ +async function inspects(): Promise { + if (!(await Bun.file(join(root, "commands")).exists())) { + return 0; + } + return (await readFile(join(root, "commands"), "utf8")) + .trim() + .split("\n") + .filter((line) => (JSON.parse(line) as string[])[1] === "inspect").length; +} + +/** + * Virtual readiness clock: the poll interval (`Bun.sleep`) returns at once, and the + * `observations`-th poll advances `Date.now` past {@link DEADLINE_MS}. The wait then makes + * exactly `observations` in-loop observations. The clock only moves between queries, so + * each query's own probe deadline is unaffected. + */ +function virtualDeadline(observations: number): void { + const realNow = Date.now; + let offset = 0; + let polls = 0; + const now = spyOn(Date, "now").mockImplementation( + () => realNow.call(Date) + offset + ); + const sleep = spyOn(Bun, "sleep").mockImplementation(async () => { + polls++; + if (polls >= observations) { + offset += 2 * DEADLINE_MS; + } + }); + restoreClock = () => { + now.mockRestore(); + sleep.mockRestore(); + }; +} + +async function waitStartup(opts: { + readonly observations: number; + readonly ready?: (state: NativeComposeOwnershipObservation) => boolean; + readonly observed?: NativeComposeOwnershipObservation[]; +}): Promise { + virtualDeadline(opts.observations); + try { + return await waitNativeComposeStartupOwned({ + ownership: options, + restartingServices: ON_FAILURE, + deadline: Date.now() + DEADLINE_MS, + ready: opts.ready ?? (() => true), + observed: (state) => opts.observed?.push(state), + }); + } finally { + restoreClock?.(); + restoreClock = undefined; + } +} + +function expectTopologyRefusal( + error: unknown, + predicate: NativeComposeTopologyPredicate +): void { + expect(error).toBeInstanceOf(NativeComposeOwnershipError); + expect(error).toMatchObject({ code: "E_NATIVE_COMPOSE_OWNERSHIP" }); + expect(nativeComposeOwnershipRefusal(error)).toBe("topology"); + expect(nativeComposeTopologyPredicate(error)).toBe(predicate); + expect(String(error)).not.toContain(PLACEHOLDER_KEY); +} + +async function expectNoEngineMutation(): Promise { + expect(await Bun.file(join(root, "mutated")).exists()).toBe(false); +} + +test( + "the virtual readiness clock makes exactly the chosen number of in-loop observations", + async () => { + // Harness control: an owned, never-ready observation polls until the virtual deadline. + for (const observations of [1, 3]) { + await serve(["member", "member"]); + const observed: NativeComposeOwnershipObservation[] = []; + expect( + await waitStartup({ observations, ready: () => false, observed }) + ).toBeNull(); + expect(observed).toHaveLength(observations); + expect(await inspects()).toBe(4 * observations); + } + await expectNoEngineMutation(); + }, + TEST_TIMEOUT_MS +); + +test( + "a readiness timeout never becomes success, even when the settled check finds the member rejoined", + async () => { + // The last in-loop observation is the restart-backoff race (case 2): `retry` read + // `running` and absent from its bridge. After the deadline the settled check reads + // `retry` rejoined, so its observation is owned and every member is ready. + await serve(["absent-running", "absent-running"], ["member", "member"]); + const observed: NativeComposeOwnershipObservation[] = []; + expect(await waitStartup({ observations: 1, observed })).toBeNull(); + // The settled query ran (two complete queries) but reported nothing as readiness. + expect(await inspects()).toBe(8); + expect(observed).toHaveLength(0); + // The same holds for a case-1 recheck placeholder that has joined by the settled check. + await serve(["member", "placeholder-running"], ["member", "member"]); + expect(await waitStartup({ observations: 1, observed })).toBeNull(); + expect(await inspects()).toBe(8); + expect(observed).toHaveLength(0); + // An owned observation that is never ready times out unready: no settled query, and + // the last unready observation is never returned. + await serve(["member", "member"]); + expect( + await waitStartup({ observations: 2, ready: () => false, observed }) + ).toBeNull(); + expect(observed).toHaveLength(2); + expect(await inspects()).toBe(8); + await expectNoEngineMutation(); + }, + TEST_TIMEOUT_MS +); + +/** + * Each row isolates one disjunct of the query's `transient` flag. In-loop, the startup + * query admits the shape (unready). After the deadline the settled check reads the same + * shape again and refuses with the original predicate after `inspects` calls in total. + */ +const TRANSIENT_TERMS: readonly { + readonly term: string; + readonly query: Query; + readonly predicate: NativeComposeTopologyPredicate; + readonly inspects: number; +}[] = [ + { + // first.transient only: read `running` and absent, then rejoined in the recheck. + term: "first-scan running member without membership", + query: ["absent-running", "member"], + predicate: "live-endpoint-membership", + inspects: 4 + 2, + }, + { + // second.transient only: a member in the first scan, `running` and absent in the recheck. + term: "recheck running member without membership", + query: ["member", "absent-running"], + predicate: "live-endpoint-membership", + inspects: 4 + 4, + }, + { + // Recheck placeholders only: a member in the first scan, then read `restarting` with an + // `ep-` key (case 1). `restarting` sets neither scan's `transient`; only the recheck + // placeholder term does, because settled refuses every recheck placeholder. + term: "recheck placeholder for a restarting member", + query: ["member", "placeholder-restarting"], + predicate: "network-member-id", + inspects: 4 + 4, + }, +]; + +test( + "each transient-flag term alone runs the settled check, which refuses the unchanged shape", + async () => { + for (const row of TRANSIENT_TERMS) { + // In-loop the shape is only unready. + await serve(row.query); + expect( + await observeNativeComposeStartupOwned(options, ON_FAILURE) + ).toBeNull(); + // Past the deadline the settled check reads the same shape and refuses. + await serve(row.query, row.query); + const observed: NativeComposeOwnershipObservation[] = []; + const error = await waitStartup({ observations: 1, observed }).catch( + (caught: unknown) => caught + ); + expect([row.term, nativeComposeTopologyPredicate(error)]).toEqual([ + row.term, + row.predicate, + ]); + expectTopologyRefusal(error, row.predicate); + expect([row.term, await inspects()]).toEqual([row.term, row.inspects]); + expect(observed).toHaveLength(0); + } + await expectNoEngineMutation(); + }, + TEST_TIMEOUT_MS +); + +test( + "restarting-only shapes are not transient: the wait times out unready without a settled check", + async () => { + for (const query of [ + // Restart backoff read `restarting` in both scans. + ["absent-restarting", "absent-restarting"], + // A first-scan placeholder for a `restarting` container that settled also admits; only + // recheck placeholders are transient. + ["placeholder-restarting", "absent-restarting"], + ] as const satisfies readonly Query[]) { + // If a settled check ran, it would read the case-2 race and refuse. + await serve(query, ["absent-running", "absent-running"]); + const observed: NativeComposeOwnershipObservation[] = []; + expect(await waitStartup({ observations: 1, observed })).toBeNull(); + expect([query, await inspects()]).toEqual([query, 4]); + expect(observed).toHaveLength(0); + } + await expectNoEngineMutation(); + }, + TEST_TIMEOUT_MS +); + +test( + "the transient flag follows the last in-loop observation, not an earlier one", + async () => { + // Transient first, then only `restarting` at the deadline: no settled check. A settled + // check would read the case-2 race and refuse. + await serve( + ["absent-running", "absent-running"], + ["absent-restarting", "absent-restarting"], + ["absent-running", "absent-running"] + ); + expect(await waitStartup({ observations: 2 })).toBeNull(); + expect(await inspects()).toBe(8); + // Only `restarting` first, then transient at the deadline: the settled check runs and + // refuses the race it reads. + await serve( + ["absent-restarting", "absent-restarting"], + ["absent-running", "absent-running"], + ["absent-running", "absent-running"] + ); + const error = await waitStartup({ observations: 2 }).catch( + (caught: unknown) => caught + ); + expectTopologyRefusal(error, "live-endpoint-membership"); + expect(await inspects()).toBe(8 + 2); + await expectNoEngineMutation(); + }, + TEST_TIMEOUT_MS +); + +/** Restart-race shapes that only `transient` startup membership keeps unready. */ +const RACE_SHAPES: readonly { + readonly shape: string; + readonly query: Query; + readonly predicate: NativeComposeTopologyPredicate; +}[] = [ + { + shape: "case 2: running and absent in both scans", + query: ["absent-running", "absent-running"], + predicate: "live-endpoint-membership", + }, + { + shape: "running placeholder in the first scan, rejoined in the recheck", + query: ["placeholder-running", "member"], + predicate: "network-member-id", + }, + { + shape: "case 1: member, then a running recheck placeholder", + query: ["member", "placeholder-running"], + predicate: "network-member-id", + }, + { + shape: "case 1: member, then a restarting recheck placeholder", + query: ["member", "placeholder-restarting"], + predicate: "network-member-id", + }, +]; + +test( + "reads that do not opt into transient membership stay strict for every restart-race shape", + async () => { + for (const row of RACE_SHAPES) { + await serve(row.query); + expect( + await observeNativeComposeStartupOwned(options, ON_FAILURE) + ).toBeNull(); + const reads = [ + [ + "settled", + () => + observeNativeComposeStartupOwned(options, ON_FAILURE, { + membership: "settled", + }), + ], + ["strict", () => assertNativeComposeOwned(options)], + ["saved", () => observeSavedNativeComposeOwned(options)], + ] as const; + for (const [read, run] of reads) { + await serve(row.query); + const error = await run().catch((caught: unknown) => caught); + expect([ + row.shape, + read, + nativeComposeTopologyPredicate(error), + ]).toEqual([row.shape, read, row.predicate]); + expectTopologyRefusal(error, row.predicate); + } + } + await expectNoEngineMutation(); + }, + TEST_TIMEOUT_MS +); + +test( + "settled keeps the restarting admission from before #362 while strict and saved refuse it", + async () => { + for (const [query, predicate] of [ + [["absent-restarting", "absent-restarting"], "live-endpoint-membership"], + [["placeholder-restarting", "absent-restarting"], "network-member-id"], + ] as const satisfies readonly [Query, NativeComposeTopologyPredicate][]) { + for (const membership of ["transient", "settled"] as const) { + await serve(query); + expect([ + query, + membership, + await observeNativeComposeStartupOwned(options, ON_FAILURE, { + membership, + }), + ]).toEqual([query, membership, null]); + } + for (const run of [ + () => assertNativeComposeOwned(options), + () => observeSavedNativeComposeOwned(options), + ]) { + await serve(query); + expectTopologyRefusal( + await run().catch((caught: unknown) => caught), + predicate + ); + } + } + // The startup default is `transient`; an unselected service is never admitted. + await serve(["absent-running", "absent-running"]); + expect( + await observeNativeComposeStartupOwned(options, ON_FAILURE) + ).toBeNull(); + await serve(["absent-running", "absent-running"]); + expectTopologyRefusal( + await observeNativeComposeStartupOwned(options, []).catch( + (caught: unknown) => caught + ), + "live-endpoint-membership" + ); + await expectNoEngineMutation(); + }, + TEST_TIMEOUT_MS +);