Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
70 changes: 49 additions & 21 deletions docs/architecture.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -207,22 +210,47 @@ 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
"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
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).

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:
Expand Down
14 changes: 8 additions & 6 deletions src/backends/log-backend.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -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<Options> {
Expand Down
24 changes: 22 additions & 2 deletions src/commands/project.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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<number>;
}): Promise<number> {
Expand Down Expand Up @@ -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,
Expand All @@ -8193,8 +8210,8 @@ async function runLogsWithLoki(opts: {
process.stderr.write(
`${renderEmptyLokiFollowNotice({
query,
service: opts.positionalService,
target: opts.target,
selectors,
})}\n`
);
},
Expand All @@ -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,
Expand Down Expand Up @@ -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,
});
}
Expand Down
116 changes: 97 additions & 19 deletions src/lib/logs.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*
Expand All @@ -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<LokiSnapshotOutcome>;
Expand All @@ -178,8 +205,8 @@ export async function runLokiSnapshotWithFallback(opts: {
renderEmptyLokiSnapshotNotice({
action: "hint",
query: opts.query,
service: opts.service,
target: opts.target,
selectors: opts.selectors,
})
);
}
Expand All @@ -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();
Expand All @@ -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)}`;
}

/**
Expand All @@ -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");
Expand All @@ -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_@%+=:,./-]+$/;
Expand Down
Loading
Loading