From bccc3b2356edfb00794ad4a59e7741a40bbae38f Mon Sep 17 00:00:00 2001 From: Dimitri Kennedy Date: Fri, 23 Oct 2026 01:18:20 -0400 Subject: [PATCH 1/2] fix(logs): persist Alloy positions, release SIGINT handlers and carry every selector in Loki hints Follow-ups to #417 for Loki-backed `hack logs` (HACK-1379). - The global logging compose gives Alloy a named `alloy-data` volume at `/var/lib/alloy/data` and repeats `--storage.path` there, so read positions survive a recreated container instead of re-reading every retained log. - `lokiTail` removes its SIGINT listener when the socket closes, so repeated follows in one process no longer pile up listeners. - Empty-snapshot and empty-follow hints carry `--tail`, `--profile`, `--pretty`, `--json` and a single service, and name `--services`, `--query`, `--since` and `--until` when the compose backend cannot apply them. - The empty-follow notice timer is injectable; tests drive it by hand and prove the tail keeps following after the notice. - The template comment and docs/architecture.md state Alloy v1.12.0's exact reopen condition (`State.Running || finished.Unix() >= target.Last()`). Refs HACK-1379 Co-Authored-By: Claude Fable 5.1 --- docs/architecture.md | 54 ++-- src/backends/log-backend.ts | 14 +- src/commands/project.ts | 24 +- src/lib/logs.ts | 116 +++++-- src/templates.ts | 62 +++- src/ui/loki-logs.ts | 36 ++- tests/global-command.test.ts | 51 +++ tests/logs-loki-empty-fallback-cli.test.ts | 56 +++- tests/loki-short-lived-logs.test.ts | 346 +++++++++++++++++++-- 9 files changed, 660 insertions(+), 99 deletions(-) diff --git a/docs/architecture.md b/docs/architecture.md index 066dd741..66ba0f45 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -193,11 +193,14 @@ returns no entries and Loki was not requested explicitly, `hack logs` writes a o 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 --no-follow`, keeping any `--path`, `--project`, -`--branch` and service you gave. Follow mode (`hack logs` without `--no-follow`) does not -fall back. When Loki is the follow backend (`logs.followBackend: loki`, or `--loki`) and no -entry arrives within 8 seconds, `hack logs` writes a one-line stderr notice that suggests -`hack logs --compose` and keeps following. +notice suggests `hack logs --compose --no-follow` with every selector you gave that the +compose backend accepts: `--path`, `--project`, `--branch`, `--tail`, `--profile`, `--pretty`, +`--json` and a single service. `--query`, `--since`, `--until` and more than one service have +no compose equivalent, so the notice names them instead of dropping them. Follow mode +(`hack logs` without `--no-follow`) does not fall back. When Loki is the follow backend +(`logs.followBackend: loki`, or `--loki`) and no entry arrives within 8 seconds, `hack logs` +writes the same kind of one-line stderr notice, suggesting `hack logs --compose`, and keeps +following. 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 @@ -207,20 +210,33 @@ between two polls (for example `docker compose run --rm`) never reaches Loki; us discovery config after `hack global install` rewrites `~/.hack/logging/alloy.alloy` and the Alloy container restarts (`hack global down` then `hack global up`). -Alloy keeps its read positions inside its own container (there is no positions volume). Each -time the Alloy container is recreated, for example by `hack global down` then -`hack global up`, it reads the retained logs of all exited Compose -containers again and can send entries that Loki already holds. Loki rejects entries older than -its sample age limit (one week by default). - -Exited containers have a polling cost. In Alloy v1.12.0, `loki.source.docker` checks each -discovered container on a fixed 5-second timer. It reopens an exited container's log when the -container finished after the last log line Alloy shipped from it. That is true for a container -that never logged anything, and for one whose last line was shipped before it exited, so such -a container is reopened every 5 seconds (two container inspect calls and one logs call) for as -long as Docker keeps it. Docker discovery does not expose a container's state or exit time, so -the config cannot skip old exited containers. Remove them (`hack down` or -`docker compose down`) to stop the checks. Each reopen also makes Alloy log a +Alloy keeps its read positions (`positions.yml`) under `--storage.path`, which the logging +compose maps to the named volume `alloy-data`. `hack global down` then `hack global up` +recreates the Alloy container but keeps the volume, so Alloy resumes each container's log +after the last line it shipped instead of reading all retained logs again. A position is a +whole second and Docker's `since` filter includes that second, so lines from the last second +Alloy read can be sent again. `hack global logs-reset` removes the volume together with Loki's +data (`docker compose down -v`); the next start reads the retained logs from the beginning, +which matches the emptied Loki. Installs made before this volume existed pick it up after +`hack global install` rewrites `~/.hack/logging/docker-compose.yml` and the stack restarts. +Loki rejects entries older than its sample age limit (one week by default). + +Exited containers have a polling cost. In Alloy v1.12.0 +(`internal/component/loki/source/docker/runner.go`), `loki.source.docker` inspects each +discovered container on a fixed 5-second timer and reopens its log when the container is +running, or when `finished.Unix() >= target.Last()`: the container's `State.FinishedAt`, in +whole seconds (0 if it cannot be parsed), is at or after the wall-clock second at which Alloy +last processed a line from that container. `Last()` is set to the current time after each +line (`dockertarget/target.go`), starts at 0 when the target is created, and is not stored in +the positions file. The comparison is against Alloy's own read time, not the timestamp of the +shipped line. So a container that logged its last line and then exited is reopened every +5 seconds (two container inspect calls and one logs call) for as long as Docker keeps it, and +so is one Alloy has read no line from since the target was created (it logged nothing, or +the positions file already covered its lines). A container is left alone only after Alloy has +read a line from it and that read came after the container finished, for example a one-shot +service that exited before Alloy discovered it. Docker discovery does not expose a container's +state or exit time, so the config cannot skip old exited containers. Remove them (`hack down` +or `docker compose down`) to stop the checks. Each reopen also makes Alloy log a "finished transferring logs" info line. Alloy runs as a Compose service, so it would ship that line into Loki every 5 seconds per container. The Alloy config sets `logging { level = "warn" }`, so only Alloy's warnings and errors are written and shipped. diff --git a/src/backends/log-backend.ts b/src/backends/log-backend.ts index 7ec700c0..fc1d73c9 100644 --- a/src/backends/log-backend.ts +++ b/src/backends/log-backend.ts @@ -5,7 +5,12 @@ import { dockerComposeLogsPretty, } from "../ui/docker-logs.ts"; import type { LogStreamContext } from "../ui/log-stream.ts"; -import { canReachLoki, lokiLogs, lokiSnapshot } from "../ui/loki-logs.ts"; +import { + canReachLoki, + type LokiLogsParams, + lokiLogs, + lokiSnapshot, +} from "../ui/loki-logs.ts"; export type LogBackendName = "compose" | "loki"; export type LogOutputFormat = "plain" | "pretty" | "json"; @@ -38,11 +43,8 @@ export interface LokiLogOptions { readonly start?: Date; readonly end?: Date; readonly streamContext?: LogStreamContext; - /** Follow only; see `LokiLogsParams.noEntriesNotice`. */ - readonly noEntriesNotice?: { - readonly afterMs: number; - readonly notify: () => void; - }; + /** Follow only; see {@link LokiLogsParams.noEntriesNotice}. */ + readonly noEntriesNotice?: LokiLogsParams["noEntriesNotice"]; } export interface LogBackend { diff --git a/src/commands/project.ts b/src/commands/project.ts index 697e74ee..b801775b 100644 --- a/src/commands/project.ts +++ b/src/commands/project.ts @@ -223,6 +223,7 @@ import { noteBrowserTargetsForLocalNetworkHint } from "../lib/local-network-hint import { buildLogSelector, LOKI_FOLLOW_EMPTY_NOTICE_DELAY_MS, + type LogsCommandSelectors, type LogsCommandTarget, renderEmptyLokiFollowNotice, resolveShouldTryLoki, @@ -8129,6 +8130,10 @@ async function runLogsWithLoki(opts: { readonly wantsLokiExplicit: boolean; /** Project selection repeated in suggested `hack logs --compose` commands. */ readonly target: LogsCommandTarget; + /** `--tail` as passed; undefined when the user left the default. */ + readonly tailOpt: number | undefined; + readonly profiles: readonly string[]; + readonly pretty: boolean; /** Compose snapshot used when an implicit Loki snapshot comes back empty. */ readonly runCompose: () => Promise; }): Promise { @@ -8172,6 +8177,18 @@ async function runLogsWithLoki(opts: { projectNameForPrefix: opts.projectNameForPrefix, services, }); + // Every selector the user passed, so an empty-result hint suggests the same + // selection on the compose backend (HACK-1379). + const selectors: LogsCommandSelectors = { + services, + tail: opts.tailOpt, + profiles: opts.profiles, + pretty: opts.pretty, + json: opts.json, + query: opts.queryOpt, + since: opts.since, + until: opts.until, + }; const lokiOptions = { baseUrl: opts.baseUrl, @@ -8193,8 +8210,8 @@ async function runLogsWithLoki(opts: { process.stderr.write( `${renderEmptyLokiFollowNotice({ query, - service: opts.positionalService, target: opts.target, + selectors, })}\n` ); }, @@ -8205,8 +8222,8 @@ async function runLogsWithLoki(opts: { return await runLokiSnapshotWithFallback({ wantsLokiExplicit: opts.wantsLokiExplicit, query, - service: opts.positionalService, target: opts.target, + selectors, runLoki: async ({ deferEmpty }) => await lokiLogBackend.snapshot({ ...lokiOptions, deferEmpty }), runCompose: opts.runCompose, @@ -8563,6 +8580,9 @@ async function handleLogs({ project: args.options.project, branch: args.options.branch, }, + tailOpt: args.options.tail, + profiles, + pretty: args.options.pretty === true, runCompose, }); } diff --git a/src/lib/logs.ts b/src/lib/logs.ts index 1143d668..e4442366 100644 --- a/src/lib/logs.ts +++ b/src/lib/logs.ts @@ -148,6 +148,33 @@ export interface LogsCommandTarget { readonly branch?: string; } +/** + * Everything else the user gave `hack logs` that selects or shapes its output, + * repeated in a suggested `hack logs --compose` command. Each field is set only + * when the user passed it. `--services`, `--query`, `--since` and `--until` + * are Loki-only (`--compose` refuses them), and the compose backend reads one + * service or all of them, so a selector the suggestion cannot apply is named + * in {@link ComposeLogsSuggestion.omitted} instead of being dropped silently. + */ +export interface LogsCommandSelectors { + /** Services from `--services` plus the positional, deduplicated, in order. */ + readonly services?: readonly string[]; + readonly tail?: number; + readonly profiles?: readonly string[]; + readonly pretty?: boolean; + readonly json?: boolean; + readonly query?: string; + readonly since?: string; + readonly until?: string; +} + +/** A `hack logs --compose` command and the selectors it could not carry. */ +export interface ComposeLogsSuggestion { + readonly command: string; + /** Selectors with no compose equivalent, rendered as the user passed them. */ + readonly omitted: readonly string[]; +} + /** * Run a Loki snapshot and handle an empty result. * @@ -163,8 +190,8 @@ export interface LogsCommandTarget { export async function runLokiSnapshotWithFallback(opts: { readonly wantsLokiExplicit: boolean; readonly query: string; - readonly service: string | undefined; readonly target: LogsCommandTarget; + readonly selectors: LogsCommandSelectors; readonly runLoki: (opts: { readonly deferEmpty: boolean; }) => Promise; @@ -178,8 +205,8 @@ export async function runLokiSnapshotWithFallback(opts: { renderEmptyLokiSnapshotNotice({ action: "hint", query: opts.query, - service: opts.service, target: opts.target, + selectors: opts.selectors, }) ); } @@ -194,8 +221,8 @@ export async function runLokiSnapshotWithFallback(opts: { renderEmptyLokiSnapshotNotice({ action: "fallback", query: opts.query, - service: opts.service, target: opts.target, + selectors: opts.selectors, }) ); return await opts.runCompose(); @@ -208,18 +235,18 @@ const EMPTY_LOKI_REASON = export function renderEmptyLokiSnapshotNotice(opts: { readonly action: "fallback" | "hint"; readonly query: string; - readonly service: string | undefined; readonly target: LogsCommandTarget; + readonly selectors: LogsCommandSelectors; }): string { if (opts.action === "fallback") { return `Loki returned no log entries for ${opts.query}; showing docker compose logs instead (${EMPTY_LOKI_REASON}).`; } - const composeCommand = renderComposeLogsCommand({ + const suggestion = renderComposeLogsSuggestion({ follow: false, - service: opts.service, target: opts.target, + selectors: opts.selectors, }); - return `Loki returned no log entries for ${opts.query} (${EMPTY_LOKI_REASON}); try \`${composeCommand}\`.`; + return `Loki returned no log entries for ${opts.query} (${EMPTY_LOKI_REASON}); try \`${suggestion.command}\`.${renderOmittedSelectors(suggestion)}`; } /** @@ -238,27 +265,44 @@ export const LOKI_FOLLOW_EMPTY_NOTICE_DELAY_MS = 8000; */ export function renderEmptyLokiFollowNotice(opts: { readonly query: string; - readonly service: string | undefined; readonly target: LogsCommandTarget; + readonly selectors: LogsCommandSelectors; }): string { - const composeCommand = renderComposeLogsCommand({ + const suggestion = renderComposeLogsSuggestion({ follow: true, - service: opts.service, target: opts.target, + selectors: opts.selectors, }); - return `Loki has sent no log entries for ${opts.query} yet (${EMPTY_LOKI_REASON}); still following. Try \`${composeCommand}\`.`; + return `Loki has sent no log entries for ${opts.query} yet (${EMPTY_LOKI_REASON}); still following. Try \`${suggestion.command}\`.${renderOmittedSelectors(suggestion)}`; +} + +function renderOmittedSelectors(suggestion: ComposeLogsSuggestion): string { + if (suggestion.omitted.length === 0) { + return ""; + } + return ` The compose backend has no equivalent for ${formatList(suggestion.omitted)}.`; +} + +function formatList(items: readonly string[]): string { + if (items.length <= 1) { + return items.join(""); + } + return `${items.slice(0, -1).join(", ")} and ${items.at(-1) ?? ""}`; } /** * Render the `hack logs --compose` command that matches the current - * invocation: the same follow mode, project selection and service. A value is + * invocation: the same follow mode, project selection and every selector the + * compose backend accepts (`--tail`, `--profile`, `--pretty`, `--json` and a + * single service). A selector it cannot apply (`--query`, `--since`, + * `--until`, or more than one service) is listed in `omitted`. A value is * single-quoted for POSIX shells when it has characters outside a safe set. */ -export function renderComposeLogsCommand(opts: { +export function renderComposeLogsSuggestion(opts: { readonly follow: boolean; - readonly service: string | undefined; readonly target: LogsCommandTarget; -}): string { + readonly selectors: LogsCommandSelectors; +}): ComposeLogsSuggestion { const words = ["hack", "logs", "--compose"]; if (!opts.follow) { words.push("--no-follow"); @@ -274,11 +318,45 @@ export function renderComposeLogsCommand(opts: { words.push(flag, quoteShellWord(trimmed)); } } - const service = (opts.service ?? "").trim(); - if (service.length > 0) { - words.push(quoteShellWord(service)); + const selectors = opts.selectors; + if (selectors.tail !== undefined) { + words.push("--tail", String(selectors.tail)); + } + const profiles = trimmedWords(selectors.profiles); + if (profiles.length > 0) { + words.push("--profile", quoteShellWord(profiles.join(","))); + } + if (selectors.pretty) { + words.push("--pretty"); + } + if (selectors.json) { + words.push("--json"); + } + + const omitted: string[] = []; + const services = trimmedWords(selectors.services); + if (services.length === 1) { + words.push(quoteShellWord(services[0] ?? "")); + } else if (services.length > 1) { + omitted.push(`--services ${quoteShellWord(services.join(","))}`); } - return words.join(" "); + const lokiOnly = [ + ["--query", selectors.query], + ["--since", selectors.since], + ["--until", selectors.until], + ] as const; + for (const [flag, value] of lokiOnly) { + if (value !== undefined) { + omitted.push(`${flag} ${quoteShellWord(value)}`); + } + } + return { command: words.join(" "), omitted }; +} + +function trimmedWords(values: readonly string[] | undefined): string[] { + return (values ?? []) + .map((value) => value.trim()) + .filter((value) => value.length > 0); } const SHELL_SAFE_WORD = /^[A-Za-z0-9_@%+=:,./-]+$/; diff --git a/src/templates.ts b/src/templates.ts index 5f8cacb0..7578fedd 100644 --- a/src/templates.ts +++ b/src/templates.ts @@ -144,8 +144,9 @@ export function renderGlobalLoggingCompose(): string { " image: grafana/alloy:v1.12.0", " volumes:", " - /var/run/docker.sock:/var/run/docker.sock", + ` - ${GLOBAL_ALLOY_DATA_VOLUME}:${GLOBAL_ALLOY_STORAGE_PATH}`, ` - ./${GLOBAL_ALLOY_FILENAME}:/etc/alloy/config.alloy:ro`, - " command: run /etc/alloy/config.alloy", + ` command: run --storage.path=${GLOBAL_ALLOY_STORAGE_PATH} /etc/alloy/config.alloy`, " networks:", ` - ${DEFAULT_LOGGING_NETWORK}`, "", @@ -175,10 +176,31 @@ export function renderGlobalLoggingCompose(): string { "volumes:", " loki-data:", " grafana-data:", + ` ${GLOBAL_ALLOY_DATA_VOLUME}:`, "", ].join("\n"); } +/** + * Named volume that holds Alloy's component data, above all the + * `loki.source.docker` positions file (`positions.yml`). Without it the + * positions live in the container's writable layer, so every recreated Alloy + * container (`hack global down` then `hack global up`, or an image change) + * read every retained container log again and could resend entries Loki + * already held. `docker compose down` keeps named volumes; + * `hack global logs-reset` (`down -v`) removes it together with Loki's data. + */ +export const GLOBAL_ALLOY_DATA_VOLUME = "alloy-data"; + +/** + * Alloy's `--storage.path` inside the container: the directory the official + * image creates for it and names in its default command. The image's default + * command is replaced to point at the mounted config, so the flag is repeated + * explicitly; without it Alloy falls back to `data-alloy/` under its working + * directory, outside the volume. + */ +export const GLOBAL_ALLOY_STORAGE_PATH = "/var/lib/alloy/data"; + // Back-compat alias (internal). Promtail has been replaced by Grafana Alloy. export function renderGlobalPromtailYaml(): string { return renderGlobalAlloyConfig(); @@ -226,19 +248,35 @@ export function renderGlobalAlloyConfig(): string { // shortened so a container removed soon after it exits (for example // `docker compose run --rm`) has a smaller window to be missed. // - // Cost (Alloy v1.12.0): loki.source.docker checks every target on a fixed 5s - // timer and reopens an exited container's log when the container finished - // after the last line it shipped (always true for a container that logged - // nothing). Such a container costs two inspect calls and one logs call every - // 5s for as long as Docker keeps it. Discovery exposes no container state or - // exit time, so the config cannot age these out; removing the containers - // (`hack down`, `docker compose down`) ends it. Each reopen also logs an info - // line ("finished transferring logs"); Alloy runs as a Compose service, so - // that line would be shipped into Loki every 5s per container. The `logging` + // Cost (Alloy v1.12.0, internal/component/loki/source/docker/runner.go): + // loki.source.docker inspects every target on a fixed 5s timer and reopens + // the container's log when `State.Running` is true or + // `finished.Unix() >= target.Last()`, where `finished` is the container's + // `State.FinishedAt` (0 when unparsable) and `Last()` is the wall-clock unix + // second at which Alloy last processed a line from that container + // (dockertarget/target.go stores `time.Now()` after each line). `Last()` + // starts at 0 when the target is created and is not kept in the positions + // file, so the comparison is against Alloy's own read time, not the shipped + // line's timestamp. An exited container is therefore reopened every 5s when + // it finished at or after Alloy's last read of it (the usual case: it logged + // its last line and then exited) or when Alloy has read no line from it since + // the target was created (a container that logged nothing, or one whose lines + // the positions file already covers). It is left alone only after Alloy has + // read a line from it and that read came after the container finished. Each + // reopen costs two inspect calls and one logs call for as long as Docker + // keeps the container. Discovery exposes no container state or exit time, so + // the config cannot age these out; removing the containers (`hack down`, + // `docker compose down`) ends it. Each reopen also logs an info line + // ("finished transferring logs"); Alloy runs as a Compose service, so that + // line would be shipped into Loki every 5s per container. The `logging` // block keeps Alloy's own output at warn and above. // - // Read positions live in the Alloy container's writable layer (no volume), so - // a recreated Alloy container reads every retained log again. + // Read positions are written under `--storage.path`, which the logging + // compose maps to the GLOBAL_ALLOY_DATA_VOLUME volume, so a recreated Alloy + // container resumes after the last line it shipped instead of reading every + // retained log again. A position is a whole second and Docker's `since` + // includes that second, so lines from the last second Alloy read can be sent + // again. return [ "logging {", ` level = "${GLOBAL_ALLOY_LOG_LEVEL}"`, diff --git a/src/ui/loki-logs.ts b/src/ui/loki-logs.ts index eb095aef..c0240c83 100644 --- a/src/ui/loki-logs.ts +++ b/src/ui/loki-logs.ts @@ -39,9 +39,23 @@ export interface LokiLogsParams { readonly noEntriesNotice?: { readonly afterMs: number; readonly notify: () => void; + /** + * Schedules `fn` after `afterMs` and returns a cancel function. Defaults + * to `setTimeout`/`clearTimeout`; tests inject a hand-driven timer so the + * notice and its cancellation are checked without real delays. + */ + readonly schedule?: NoticeScheduler; }; } +/** Schedules `fn` after `afterMs`; the returned function cancels it. */ +export type NoticeScheduler = (fn: () => void, afterMs: number) => () => void; + +const defaultNoticeScheduler: NoticeScheduler = (fn, afterMs) => { + const handle = setTimeout(fn, afterMs); + return () => clearTimeout(handle); +}; + type LokiLabelSet = Record; export async function canReachLoki(opts: { @@ -387,11 +401,11 @@ async function lokiTail(opts: LokiLogsParams): Promise { let closed = false; let exitCode = 0; - let noEntriesTimer: ReturnType | undefined; + let cancelNoEntriesTimer: (() => void) | undefined; const clearNoEntriesTimer = () => { - if (noEntriesTimer !== undefined) { - clearTimeout(noEntriesTimer); - noEntriesTimer = undefined; + if (cancelNoEntriesTimer !== undefined) { + cancelNoEntriesTimer(); + cancelNoEntriesTimer = undefined; } }; @@ -408,9 +422,13 @@ async function lokiTail(opts: LokiLogsParams): Promise { } }; - process.once("SIGINT", () => { + // Removed again when the socket closes: a follow that ends normally must not + // leave its handler behind, or repeated follows in one process pile up + // SIGINT listeners (HACK-1379). + const onSigint = () => { stop(); - }); + }; + process.once("SIGINT", onSigint); ws.addEventListener("error", () => { exitCode = 1; @@ -427,9 +445,10 @@ async function lokiTail(opts: LokiLogsParams): Promise { const noEntriesNotice = opts.noEntriesNotice; if (noEntriesNotice) { + const schedule = noEntriesNotice.schedule ?? defaultNoticeScheduler; ws.addEventListener("open", () => { - noEntriesTimer = setTimeout(() => { - noEntriesTimer = undefined; + cancelNoEntriesTimer = schedule(() => { + cancelNoEntriesTimer = undefined; if (!closed) { noEntriesNotice.notify(); } @@ -489,6 +508,7 @@ async function lokiTail(opts: LokiLogsParams): Promise { ws.addEventListener("close", () => { closed = true; clearNoEntriesTimer(); + process.off("SIGINT", onSigint); resolve(); }); }); diff --git a/tests/global-command.test.ts b/tests/global-command.test.ts index 5d2d0490..c51538ff 100644 --- a/tests/global-command.test.ts +++ b/tests/global-command.test.ts @@ -505,6 +505,57 @@ test("global down runs docker compose down when files exist", async () => { ).toBe(true); }); +test("global down keeps the logging stack's named volumes", async () => { + // HACK-1379: Alloy's read positions live in the `alloy-data` volume (next to + // `loki-data` and `grafana-data`). A plain `docker compose down` keeps named + // volumes; only `hack global logs-reset` passes `-v`. A `down` here that + // removed volumes would make every `global down`/`up` re-read all retained + // container logs into a wiped Loki. + const caddyCompose = join( + tempDir!, + GLOBAL_HACK_DIR_NAME, + GLOBAL_CADDY_DIR_NAME, + GLOBAL_CADDY_COMPOSE_FILENAME + ); + const loggingCompose = join( + tempDir!, + GLOBAL_HACK_DIR_NAME, + GLOBAL_LOGGING_DIR_NAME, + GLOBAL_LOGGING_COMPOSE_FILENAME + ); + await writeComposeFile(caddyCompose); + await writeComposeFile(loggingCompose); + + const { runCli } = await import("../src/cli/run.ts"); + expect(await runCli(["global", "down"])).toBe(0); + const loggingDown = runCalls.filter( + (call) => call.includes(loggingCompose) && call.includes("down") + ); + expect(loggingDown).toHaveLength(1); + expect(loggingDown[0]).toEqual([ + "docker", + "compose", + "-f", + loggingCompose, + "down", + ]); + for (const call of loggingDown) { + expect(call).not.toContain("-v"); + expect(call).not.toContain("--volumes"); + } + + runCalls.length = 0; + expect(await runCli(["global", "up"])).toBe(0); + const loggingUp = runCalls.filter( + (call) => call.includes(loggingCompose) && call.includes("up") + ); + expect(loggingUp).toHaveLength(1); + for (const call of loggingUp) { + expect(call).not.toContain("-V"); + expect(call).not.toContain("--renew-anon-volumes"); + } +}); + test("global up fails when compose files are missing", async () => { const { runCli } = await import("../src/cli/run.ts"); const code = await runCli(["global", "up"]); diff --git a/tests/logs-loki-empty-fallback-cli.test.ts b/tests/logs-loki-empty-fallback-cli.test.ts index 743412f6..8cad3aa3 100644 --- a/tests/logs-loki-empty-fallback-cli.test.ts +++ b/tests/logs-loki-empty-fallback-cli.test.ts @@ -228,6 +228,56 @@ test("explicit --loki snapshot hint repeats --path and --branch", async () => { expect(await composeLogsCalls()).toEqual([]); }, 60_000); +// HACK-1379: the hint carries every selector the user passed, and names the +// ones `--compose` cannot apply instead of dropping them. +test("explicit --loki snapshot hint carries --tail and --profile and names --services and --since", async () => { + const result = await runLogs([ + "--loki", + "--no-follow", + "--services", + "api,migrate", + "--tail", + "5", + "--since", + "15m", + "--profile", + "jobs", + "migrate", + ]); + + expect(result.exitCode).toBe(0); + expect(lokiQueries).toEqual([ + '{project="oneshot",service=~"^(api|migrate)$"}', + ]); + expect(result.stderr).toContain( + "try `hack logs --compose --no-follow --tail 5 --profile jobs`. The compose backend has no equivalent for --services api,migrate and --since 15m." + ); + expect(await composeLogsCalls()).toEqual([]); +}, 60_000); + +test("explicit --loki snapshot hint turns a single --services value into the positional and keeps --json", async () => { + const result = await runLogs([ + "--loki", + "--no-follow", + "--services", + "migrate", + "--json", + ]); + + expect(result.exitCode).toBe(0); + expect(lokiQueries).toEqual(['{project="oneshot",service="migrate"}']); + expect(result.stderr).toContain( + "try `hack logs --compose --no-follow --json migrate`." + ); + expect(result.stderr).not.toContain("no equivalent"); + const types = result.stdout + .trim() + .split("\n") + .map((line) => (JSON.parse(line) as { type: string }).type); + expect(types).toEqual(["start", "end"]); + expect(await composeLogsCalls()).toEqual([]); +}, 60_000); + test("Loki follow backend notices an empty tail on stderr and keeps following", async () => { await writeFile( join(projectRoot, ".hack", "hack.config.json"), @@ -238,7 +288,8 @@ test("Loki follow backend notices an empty tail on stderr and keeps following", logs: { follow_backend: "loki" }, })}\n` ); - const child = spawnLogs(["migrate"], { cwd: projectRoot }); + // `--tail` is a selector the follow hint must carry (HACK-1379). + const child = spawnLogs(["--tail", "5", "migrate"], { cwd: projectRoot }); const stdoutText = new Response(child.stdout).text(); const reader = child.stderr.getReader(); const decoder = new TextDecoder(); @@ -276,7 +327,8 @@ test("Loki follow backend notices an empty tail on stderr and keeps following", expect(stderr).toContain( 'Loki has sent no log entries for {project="oneshot",service="migrate"} yet' ); - expect(stderr).toContain("Try `hack logs --compose migrate`."); + expect(stderr).toContain("Try `hack logs --compose --tail 5 migrate`."); + expect(stderr).not.toContain("no equivalent"); expect(stderr.match(/Loki has sent no log entries/g)).toHaveLength(1); expect(await stdoutText).toBe(""); expect(await composeLogsCalls()).toEqual([]); diff --git a/tests/loki-short-lived-logs.test.ts b/tests/loki-short-lived-logs.test.ts index 74092a96..d8e25439 100644 --- a/tests/loki-short-lived-logs.test.ts +++ b/tests/loki-short-lived-logs.test.ts @@ -3,22 +3,27 @@ import { afterAll, afterEach, beforeAll, expect, test } from "bun:test"; import { DEFAULT_LOKI_SNAPSHOT_LOOKBACK_MS, LOKI_FOLLOW_EMPTY_NOTICE_DELAY_MS, + type LogsCommandSelectors, type LogsCommandTarget, type LokiSnapshotOutcome, - renderComposeLogsCommand, + renderComposeLogsSuggestion, renderEmptyLokiFollowNotice, resolveLokiQueryWindow, runLokiSnapshotWithFallback, } from "../src/lib/logs.ts"; import { + GLOBAL_ALLOY_DATA_VOLUME, GLOBAL_ALLOY_DOCKER_REFRESH_INTERVAL, GLOBAL_ALLOY_LOG_LEVEL, + GLOBAL_ALLOY_STORAGE_PATH, renderGlobalAlloyConfig, + renderGlobalLoggingCompose, } from "../src/templates.ts"; import { buildLokiQueryRangeUrl, lokiLogs, lokiSnapshot, + type NoticeScheduler, } from "../src/ui/loki-logs.ts"; // HACK-1277: a one-shot Compose service that exits quickly must not make @@ -215,12 +220,15 @@ function fallbackHarness( compose: 0, notices: [] as string[], }; - const run = async (wantsLokiExplicit: boolean, service?: string) => + const run = async ( + wantsLokiExplicit: boolean, + selectors: LogsCommandSelectors = {} + ) => await runLokiSnapshotWithFallback({ wantsLokiExplicit, query: '{project="demo",service="migrate"}', - service, target, + selectors, runLoki: async ({ deferEmpty }) => { calls.lokiDeferEmpty.push(deferEmpty); return outcome; @@ -242,7 +250,7 @@ test("implicit Loki snapshot with no entries falls back to compose logs", async entryCount: 0, deferred: true, }); - expect(await run(false, "migrate")).toBe(7); + expect(await run(false, { services: ["migrate"] })).toBe(7); expect(calls.lokiDeferEmpty).toEqual([true]); expect(calls.compose).toBe(1); expect(calls.notices).toHaveLength(1); @@ -267,7 +275,7 @@ test("explicit Loki snapshot with no entries hints at --compose instead of falli entryCount: 0, deferred: false, }); - expect(await run(true, "migrate")).toBe(0); + expect(await run(true, { services: ["migrate"] })).toBe(0); expect(calls.lokiDeferEmpty).toEqual([false]); expect(calls.compose).toBe(0); expect(calls.notices).toHaveLength(1); @@ -283,41 +291,129 @@ test("explicit Loki snapshot hint keeps --path, --project and --branch", async ( { exitCode: 0, entryCount: 0, deferred: false }, { path: "./my app", project: "demo", branch: "feat-x" } ); - expect(await run(true, "migrate")).toBe(0); + expect(await run(true, { services: ["migrate"] })).toBe(0); expect(calls.notices[0]).toContain( "try `hack logs --compose --no-follow --path './my app' --project demo --branch feat-x migrate`." ); }); -test("renderComposeLogsCommand matches follow mode and quotes unsafe words", () => { +// HACK-1379: the hint carries every selector, not only the project target. +test("explicit Loki snapshot hint carries --tail, --profile, --pretty and --json", async () => { + const { calls, run } = fallbackHarness( + { exitCode: 0, entryCount: 0, deferred: false }, + { project: "demo" } + ); expect( - renderComposeLogsCommand({ follow: true, service: undefined, target: {} }) - ).toBe("hack logs --compose"); + await run(true, { + services: ["migrate"], + tail: 50, + profiles: ["jobs", "debug"], + pretty: true, + json: false, + }) + ).toBe(0); + expect(calls.notices[0]).toEndWith( + "try `hack logs --compose --no-follow --project demo --tail 50 --profile jobs,debug --pretty migrate`." + ); + expect(calls.notices[0]).not.toContain("--json"); + expect(calls.notices[0]).not.toContain("\n"); +}); + +test("explicit Loki snapshot hint names --services, --since, --until and --query it cannot carry", async () => { + const { calls, run } = fallbackHarness({ + exitCode: 0, + entryCount: 0, + deferred: false, + }); expect( - renderComposeLogsCommand({ + await run(true, { + services: ["api", "www"], + json: true, + query: '{project="demo"} |= "boom"', + since: "15m", + until: "5m", + }) + ).toBe(0); + // Two services cannot become one positional; the command shows all services + // and the notice says which selectors were not applied. + expect(calls.notices[0]).toEndWith( + 'try `hack logs --compose --no-follow --json`. The compose backend has no equivalent for --services api,www, --query \'{project="demo"} |= "boom"\', --since 15m and --until 5m.' + ); + expect(calls.notices[0]).not.toContain("\n"); +}); + +test("renderComposeLogsSuggestion matches follow mode, quotes unsafe words and reports omitted selectors", () => { + expect( + renderComposeLogsSuggestion({ follow: true, target: {}, selectors: {} }) + ).toEqual({ command: "hack logs --compose", omitted: [] }); + expect( + renderComposeLogsSuggestion({ follow: false, - service: " web ", target: { path: " ", branch: "it's" }, + selectors: { services: [" web "], profiles: [" ", "a b"] }, + }) + ).toEqual({ + command: + "hack logs --compose --no-follow --branch 'it'\\''s' --profile 'a b' web", + omitted: [], + }); + // A single service from --services is the same selection as the positional. + expect( + renderComposeLogsSuggestion({ + follow: false, + target: {}, + selectors: { services: ["api"], tail: 5, since: "2026-10-21T10:00:00Z" }, }) - ).toBe("hack logs --compose --no-follow --branch 'it'\\''s' web"); + ).toEqual({ + command: "hack logs --compose --no-follow --tail 5 api", + omitted: ["--since 2026-10-21T10:00:00Z"], + }); + expect( + renderComposeLogsSuggestion({ + follow: true, + target: {}, + selectors: { services: ["api", "www", "api"], until: "now" }, + }) + ).toEqual({ + command: "hack logs --compose", + omitted: ["--services api,www,api", "--until now"], + }); }); test("follow notice suggests a following compose command for the same target", () => { const notice = renderEmptyLokiFollowNotice({ query: '{project="demo--feat-x",service="api"}', - service: "api", target: { branch: "feat-x" }, + selectors: { services: ["api"] }, }); expect(notice).toContain( 'Loki has sent no log entries for {project="demo--feat-x",service="api"} yet' ); expect(notice).toContain("still following"); - expect(notice).toContain("Try `hack logs --compose --branch feat-x api`."); + expect(notice).toEndWith("Try `hack logs --compose --branch feat-x api`."); expect(notice).not.toContain("--no-follow"); expect(notice).not.toContain("\n"); expect(LOKI_FOLLOW_EMPTY_NOTICE_DELAY_MS).toBe(8000); }); +test("follow notice carries every selector and names the ones compose cannot apply", () => { + const notice = renderEmptyLokiFollowNotice({ + query: '{project="demo",service=~"^(api|www)$"}', + target: { project: "demo" }, + selectors: { + services: ["api", "www"], + tail: 20, + profiles: ["jobs"], + json: true, + since: "1h", + }, + }); + expect(notice).toEndWith( + "Try `hack logs --compose --project demo --tail 20 --profile jobs --json`. The compose backend has no equivalent for --services api,www and --since 1h." + ); + expect(notice).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({ @@ -384,6 +480,36 @@ test("Alloy keeps its own component logs at warn so per-poll info lines stay out expect(config.match(/^logging \{/gm)).toHaveLength(1); }); +test("Alloy keeps its read positions in a named volume so a recreated container does not re-read every log", () => { + // HACK-1379: positions lived in the container's writable layer, so every + // `hack global down`/`up` re-read all retained container logs into Loki. + expect(GLOBAL_ALLOY_DATA_VOLUME).toBe("alloy-data"); + expect(GLOBAL_ALLOY_STORAGE_PATH).toBe("/var/lib/alloy/data"); + const compose = Bun.YAML.parse(renderGlobalLoggingCompose()) as { + services: Record< + string, + { command?: string; volumes?: string[]; image?: string } + >; + volumes: Record; + }; + const alloy = compose.services.alloy; + expect(alloy?.image).toBe("grafana/alloy:v1.12.0"); + expect(alloy?.volumes).toContain("alloy-data:/var/lib/alloy/data"); + // The image's default command carries --storage.path; ours replaces the + // command, so the flag must be repeated or positions land outside the volume. + expect(alloy?.command).toBe( + "run --storage.path=/var/lib/alloy/data /etc/alloy/config.alloy" + ); + expect(Object.keys(compose.volumes)).toEqual([ + "loki-data", + "grafana-data", + "alloy-data", + ]); + // Each named volume is declared once and left unconfigured (Compose default + // driver), so `docker compose down` keeps it and `down -v` removes it. + expect(compose.volumes["alloy-data"]).toBeNull(); +}); + // --- Loki follow: notice when nothing arrives ------------------------------- type TailSocket = { close: () => void; send: (data: string) => void }; @@ -439,7 +565,64 @@ async function waitFor( } } -test("Loki follow reports once when the tail stays empty and keeps following", async () => { +/** + * A hand-driven notice timer (HACK-1379): the test decides when the delay + * elapses, so no assertion depends on a real timer racing the socket. + */ +function manualNoticeTimer() { + const state = { + scheduled: 0, + afterMs: undefined as number | undefined, + cancelled: false, + pending: undefined as (() => void) | undefined, + }; + const schedule: NoticeScheduler = (fn, afterMs) => { + state.scheduled += 1; + state.afterMs = afterMs; + state.cancelled = false; + state.pending = fn; + return () => { + state.cancelled = true; + state.pending = undefined; + }; + }; + // Elapse the delay; a cancelled timer, like a cleared setTimeout, never fires. + const fire = () => { + const fn = state.pending; + state.pending = undefined; + if (fn && !state.cancelled) { + fn(); + } + }; + return { schedule, fire, state }; +} + +function tailMessage(service: string, line: string): string { + return JSON.stringify({ + streams: [ + { + stream: { project: "demo", service }, + values: [[ns(new Date("2026-10-21T11:59:00.000Z")), line]], + }, + ], + }); +} + +function trackSettled(promise: Promise): { readonly settled: boolean } { + const state = { settled: false }; + promise.then( + () => { + state.settled = true; + }, + () => { + state.settled = true; + } + ); + return state; +} + +test("Loki follow reports once when the tail stays empty and keeps following afterwards", async () => { + const timer = manualNoticeTimer(); await withFakeLokiTail( () => undefined, async ({ baseUrl, sockets }) => { @@ -453,38 +636,48 @@ test("Loki follow reports once when the tail stays empty and keeps following", a pretty: false, showProjectPrefix: true, noEntriesNotice: { - afterMs: 30, + afterMs: LOKI_FOLLOW_EMPTY_NOTICE_DELAY_MS, notify: () => { notices += 1; }, + schedule: timer.schedule, }, }); - await waitFor(() => notices > 0, "the empty-follow notice"); - // Still connected after the notice; the timer does not repeat. - await Bun.sleep(120); + const exitState = trackSettled(exit); + await waitFor(() => timer.state.scheduled > 0, "the notice timer"); + expect(timer.state.afterMs).toBe(LOKI_FOLLOW_EMPTY_NOTICE_DELAY_MS); + expect(notices).toBe(0); + timer.fire(); expect(notices).toBe(1); + // The tail is still open after the notice: an entry that arrives later + // is printed, and the follow has not ended on its own. expect(sockets).toHaveLength(1); + sockets[0]?.send(tailMessage("migrate", "after the notice")); + await waitFor( + () => stdout.includes("after the notice"), + "the entry sent after the notice" + ); + expect(exitState.settled).toBe(false); + // The timer is armed once; a later entry does not re-arm it. + timer.fire(); + expect(notices).toBe(1); + expect(timer.state.scheduled).toBe(1); for (const socket of sockets) { socket.close(); } expect(await exit).toBe(0); restoreStdout(); - expect(stdout).toBe(""); + expect(stdout).toBe( + "demo/migrate | 2026-10-21T11:59:00.000Z after the notice\n" + ); } ); }); test("Loki follow stays quiet when an entry arrives before the notice delay", async () => { - const message = JSON.stringify({ - streams: [ - { - stream: { project: "demo", service: "api" }, - values: [[ns(new Date("2026-10-21T11:59:00.000Z")), "hello"]], - }, - ], - }); + const timer = manualNoticeTimer(); await withFakeLokiTail( - (socket) => socket.send(message), + (socket) => socket.send(tailMessage("api", "hello")), async ({ baseUrl, sockets }) => { let notices = 0; captureStdout(); @@ -496,14 +689,20 @@ test("Loki follow stays quiet when an entry arrives before the notice delay", as pretty: false, showProjectPrefix: true, noEntriesNotice: { - afterMs: 60, + afterMs: LOKI_FOLLOW_EMPTY_NOTICE_DELAY_MS, notify: () => { notices += 1; }, + schedule: timer.schedule, }, }); await waitFor(() => stdout.includes("hello"), "the streamed entry"); - await Bun.sleep(200); + // The first entry cancelled the timer, so elapsing the delay now is a + // no-op, exactly as a cleared setTimeout would be. + expect(timer.state.scheduled).toBe(1); + expect(timer.state.cancelled).toBe(true); + timer.fire(); + expect(notices).toBe(0); for (const socket of sockets) { socket.close(); } @@ -514,3 +713,88 @@ test("Loki follow stays quiet when an entry arrives before the notice delay", as } ); }); + +test("Loki follow uses a real timer for the notice when none is injected", async () => { + await withFakeLokiTail( + () => undefined, + async ({ baseUrl, sockets }) => { + let notices = 0; + captureStdout(); + const exit = lokiLogs({ + baseUrl, + query: '{project="demo",service="migrate"}', + follow: true, + tail: 10, + pretty: false, + showProjectPrefix: true, + noEntriesNotice: { + afterMs: 20, + notify: () => { + notices += 1; + }, + }, + }); + // Only a lower bound on timing: the notice must arrive, however loaded + // the machine is. + await waitFor(() => notices > 0, "the empty-follow notice"); + expect(sockets).toHaveLength(1); + for (const socket of sockets) { + socket.close(); + } + expect(await exit).toBe(0); + restoreStdout(); + expect(notices).toBe(1); + expect(stdout).toBe(""); + } + ); +}); + +// --- Loki follow: SIGINT handling -------------------------------------------- + +async function followUntilServerCloses(baseUrl: string): Promise { + return await lokiLogs({ + baseUrl, + query: '{project="demo",service="api"}', + follow: true, + tail: 10, + pretty: false, + showProjectPrefix: true, + }); +} + +test("a Loki follow that closes normally removes its SIGINT listener", async () => { + // HACK-1379: `process.once("SIGINT")` per follow was never removed on a + // normal close, so repeated follows in one process piled up listeners + // (MaxListenersExceededWarning after ten). + const before = process.listenerCount("SIGINT"); + await withFakeLokiTail( + (socket) => socket.close(), + async ({ baseUrl }) => { + for (let i = 0; i < 12; i += 1) { + expect(await followUntilServerCloses(baseUrl)).toBe(0); + expect(process.listenerCount("SIGINT")).toBe(before); + } + } + ); +}); + +test("SIGINT closes an open Loki follow and leaves no listener behind", async () => { + const before = process.listenerCount("SIGINT"); + await withFakeLokiTail( + () => undefined, + async ({ baseUrl, sockets }) => { + captureStdout(); + const exit = followUntilServerCloses(baseUrl); + const exitState = trackSettled(exit); + await waitFor(() => sockets.length === 1, "the tail socket"); + expect(process.listenerCount("SIGINT")).toBe(before + 1); + expect(exitState.settled).toBe(false); + // Dispatch the event in-process; no signal is raised. + process.emit("SIGINT"); + expect(await exit).toBe(0); + restoreStdout(); + expect(process.listenerCount("SIGINT")).toBe(before); + expect(stdout).toBe(""); + } + ); +}); From bb7c930418da52f7b46b89c77f63b979d4c6e8fa Mon Sep 17 00:00:00 2001 From: Dimitri Kennedy Date: Fri, 23 Oct 2026 10:54:06 -0400 Subject: [PATCH 2/2] docs(logs): state which kept containers Alloy reopens and what each poll costs Alloy v1.12.0 reopens an exited container's log when `finished.Unix() >= target.Last()`. A reopen reads from the position second, which Docker includes, so it reads the last line again and moves `Last()` past the finish time. Only a container that never logged a line is reopened every 5 seconds; one that logged, or whose lines the positions file covers, is reopened once and then stays closed. Every discovered container still costs one inspect call per poll. Refs HACK-1379 Co-Authored-By: Claude Opus 5.5 --- docs/architecture.md | 48 +++++++++++++++---------- src/templates.ts | 54 +++++++++++++++++------------ tests/loki-short-lived-logs.test.ts | 7 ++-- 3 files changed, 65 insertions(+), 44 deletions(-) diff --git a/docs/architecture.md b/docs/architecture.md index 66ba0f45..eebd6904 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -221,24 +221,36 @@ which matches the emptied Loki. Installs made before this volume existed pick it `hack global install` rewrites `~/.hack/logging/docker-compose.yml` and the stack restarts. Loki rejects entries older than its sample age limit (one week by default). -Exited containers have a polling cost. In Alloy v1.12.0 -(`internal/component/loki/source/docker/runner.go`), `loki.source.docker` inspects each -discovered container on a fixed 5-second timer and reopens its log when the container is -running, or when `finished.Unix() >= target.Last()`: the container's `State.FinishedAt`, in -whole seconds (0 if it cannot be parsed), is at or after the wall-clock second at which Alloy -last processed a line from that container. `Last()` is set to the current time after each -line (`dockertarget/target.go`), starts at 0 when the target is created, and is not stored in -the positions file. The comparison is against Alloy's own read time, not the timestamp of the -shipped line. So a container that logged its last line and then exited is reopened every -5 seconds (two container inspect calls and one logs call) for as long as Docker keeps it, and -so is one Alloy has read no line from since the target was created (it logged nothing, or -the positions file already covered its lines). A container is left alone only after Alloy has -read a line from it and that read came after the container finished, for example a one-shot -service that exited before Alloy discovered it. Docker discovery does not expose a container's -state or exit time, so the config cannot skip old exited containers. Remove them (`hack down` -or `docker compose down`) to stop the checks. Each reopen also makes Alloy log a -"finished transferring logs" info line. Alloy runs as a Compose service, so it would ship that -line into Loki every 5 seconds per container. The Alloy config sets +Kept containers have a polling cost. In Alloy v1.12.0 +(`internal/component/loki/source/docker/runner.go`), `loki.source.docker` calls container +inspect on every discovered container every 5 seconds, running or exited, for as long as +Docker keeps it. After that call it reopens the container's log (one more inspect call and one +logs call) when the container is running and its log is not already open, or when +`finished.Unix() >= target.Last()`. `finished` is the container's `State.FinishedAt` in whole +seconds (0 if it cannot be parsed). `Last()` is the wall-clock second at which Alloy last +processed a line from that container: `dockertarget/target.go` sets it to the current time +after each line, it starts at 0 when the target is created, and it is not stored in the +positions file. A reopen asks Docker for the lines since the container's position, which is a +whole second, and Docker includes that second. So a reopen of a container that logged +anything reads at least its last line again, and `Last()` moves past the container's finish +time. For an exited container this means: + +- A container that never logged a line keeps `Last()` at 0, so it is reopened every + 5 seconds for as long as Docker keeps it. +- A container whose last line Alloy read in or before the second the container finished (it + logged and then exited while Alloy followed it), or one whose lines the positions file + already covers (for example after Alloy restarts), is reopened once. That reopen sends the + lines from its last logged second again, and then the container is not reopened. If the + reopen happens within the second the container finished, there is one more reopen. +- A container whose last line Alloy read in a later second than the one the container + finished in, for example a one-shot service that exited before Alloy discovered it, is not + reopened. + +Docker discovery does not expose a container's state or exit time, so the config cannot skip +old exited containers. Remove them (`hack down` or `docker compose down`) to stop the inspect +calls. Each reopen also makes Alloy log a "finished transferring logs" info line. Alloy runs +as a Compose service, so it would ship those lines into Loki: one per reopen, and one every +5 seconds for each kept container that never logged a line. The Alloy config sets `logging { level = "warn" }`, so only Alloy's warnings and errors are written and shipped. Retention: diff --git a/src/templates.ts b/src/templates.ts index 7578fedd..c5659359 100644 --- a/src/templates.ts +++ b/src/templates.ts @@ -227,8 +227,9 @@ export const GLOBAL_ALLOY_DOCKER_STATUSES = [ /** * Minimum level of Alloy's own log output. Alloy's container is itself a * Compose service that Alloy ships to Loki, so info-level component logs (a - * "finished transferring logs" line per kept exited container every 5 seconds) - * would grow Loki without bound. + * "finished transferring logs" line on every log reopen, which repeats every + * 5 seconds for each kept exited container that never logged a line) would + * grow Loki without bound. */ export const GLOBAL_ALLOY_LOG_LEVEL = "warn"; @@ -249,27 +250,34 @@ export function renderGlobalAlloyConfig(): string { // `docker compose run --rm`) has a smaller window to be missed. // // Cost (Alloy v1.12.0, internal/component/loki/source/docker/runner.go): - // loki.source.docker inspects every target on a fixed 5s timer and reopens - // the container's log when `State.Running` is true or - // `finished.Unix() >= target.Last()`, where `finished` is the container's - // `State.FinishedAt` (0 when unparsable) and `Last()` is the wall-clock unix - // second at which Alloy last processed a line from that container - // (dockertarget/target.go stores `time.Now()` after each line). `Last()` - // starts at 0 when the target is created and is not kept in the positions - // file, so the comparison is against Alloy's own read time, not the shipped - // line's timestamp. An exited container is therefore reopened every 5s when - // it finished at or after Alloy's last read of it (the usual case: it logged - // its last line and then exited) or when Alloy has read no line from it since - // the target was created (a container that logged nothing, or one whose lines - // the positions file already covers). It is left alone only after Alloy has - // read a line from it and that read came after the container finished. Each - // reopen costs two inspect calls and one logs call for as long as Docker - // keeps the container. Discovery exposes no container state or exit time, so - // the config cannot age these out; removing the containers (`hack down`, - // `docker compose down`) ends it. Each reopen also logs an info line - // ("finished transferring logs"); Alloy runs as a Compose service, so that - // line would be shipped into Loki every 5s per container. The `logging` - // block keeps Alloy's own output at warn and above. + // loki.source.docker calls ContainerInspect on every discovered target every + // 5s, running or exited, for as long as Docker keeps the container. It then + // reopens the log (one more inspect call and one logs call) when + // `res.State.Running || finished.Unix() >= t.target.Last()` and the log is + // not already open. `finished` is `State.FinishedAt` in whole seconds (0 + // when unparsable). `Last()` is the wall-clock unix second at which Alloy + // last processed a line from the container (dockertarget/target.go stores + // `time.Now()` after each line); it starts at 0 when the target is created + // and is not kept in the positions file. A reopen asks Docker for lines + // `since` the position, a whole second that Docker includes, so it reads at + // least the container's last line again and moves `Last()` past `finished`. + // For an exited container: + // - one that never logged a line keeps `Last()` at 0 and is reopened every + // 5s for as long as Docker keeps it; + // - one whose last line Alloy read in or before the second it finished (it + // logged and then exited while followed), or whose lines the positions + // file already covers (after an Alloy restart), is reopened once, resends + // its last logged second, and then stays closed (a second reopen happens + // only when the first falls within the second the container finished); + // - one whose last line Alloy read in a later second than it finished in + // is not reopened. + // Discovery exposes no container state or exit time, so the config cannot + // age kept containers out; removing them (`hack down`, + // `docker compose down`) ends the inspect calls. Each reopen also logs an + // info line ("finished transferring logs"); Alloy runs as a Compose service, + // so those lines would be shipped into Loki, one every 5s for each kept + // container that never logged. The `logging` block keeps Alloy's own output + // at warn and above. // // Read positions are written under `--storage.path`, which the logging // compose maps to the GLOBAL_ALLOY_DATA_VOLUME volume, so a recreated Alloy diff --git a/tests/loki-short-lived-logs.test.ts b/tests/loki-short-lived-logs.test.ts index d8e25439..e8e04dfc 100644 --- a/tests/loki-short-lived-logs.test.ts +++ b/tests/loki-short-lived-logs.test.ts @@ -468,9 +468,10 @@ test("Alloy keeps a stopped container's target labels stable and still requires }); test("Alloy keeps its own component logs at warn so per-poll info lines stay out of Loki", () => { - // HACK-1364: loki.source.docker logs "finished transferring logs" at info - // every 5s for each kept exited container, and Alloy's own container is a - // Compose service it ships to Loki. + // HACK-1364: loki.source.docker logs "finished transferring logs" at info on + // every log reopen, every 5s for each kept exited container that never + // logged a line, and Alloy's own container is a Compose service it ships to + // Loki. expect(GLOBAL_ALLOY_LOG_LEVEL).toBe("warn"); const config = renderGlobalAlloyConfig(); expect(config).toMatch(