diff --git a/docs/guides/agent-first-setup.md b/docs/guides/agent-first-setup.md index 38153a50a..1d5159371 100644 --- a/docs/guides/agent-first-setup.md +++ b/docs/guides/agent-first-setup.md @@ -59,11 +59,15 @@ completed operations or delete persistent project data. These controls do not re the number of servers for clients that remain connected. MCP command results capture at most 8 MiB of combined stdout/stderr bytes before -text decoding. This also bounds log tails with oversized or newline-free messages. -Exceeding the budget stops the command and returns an error with -`outputTruncated: true`; parsed `data` is omitted so a prefix cannot masquerade as -a complete result. Run the equivalent CLI command when full output is needed. -The budget bounds captured bytes, not total process memory or JSON response size. +text decoding. For tools other than the log tools, exceeding the budget stops the +command and returns an error with `outputTruncated: true`; parsed `data` is omitted +so a prefix cannot masquerade as a complete result. The log tools +(`hack.project.logs.tail` and `hack.project.logs.snapshot`) use the same budget, +but reaching it is a cutoff: the result is `ok: true` with `outputTruncated: true`, +`data.cutoff` set to the `bytes` bound, and the events parsed before the cut. See +[MCP logs contract](../reference/mcp-logs.md). Run the equivalent CLI command when +full output is needed. The budget bounds captured bytes, not total process memory +or JSON response size. Each MCP session captures its launch working directory and environment. Project registry selection, command execution and audit-file locations use that snapshot; diff --git a/docs/reference.md b/docs/reference.md index 99645b049..64c7e50a5 100644 --- a/docs/reference.md +++ b/docs/reference.md @@ -27,3 +27,4 @@ - [Extensions](./extensions.md) - [Creating an extension](./guides/create-extension.md) - [Integrations](./integrations.md) +- [MCP logs contract](./reference/mcp-logs.md) — cutoff versus backend failure for the MCP log tools, and the cursor/handle decision diff --git a/docs/reference/mcp-logs.md b/docs/reference/mcp-logs.md new file mode 100644 index 000000000..a734b9277 --- /dev/null +++ b/docs/reference/mcp-logs.md @@ -0,0 +1,102 @@ +# MCP logs contract + +This page covers the `hack.project.logs.tail` and `hack.project.logs.snapshot` +MCP tools. Both tools run `hack logs --json` once per call and return the stream +events they collected. When a shell is available, use `hack logs` directly. + +## Outcomes + +Each call ends in exactly one outcome. + +| Outcome | `ok` | `isError` | `data.cutoff` | `error` | +| --- | --- | --- | --- | --- | +| Complete: the backend ended the stream and exited 0 | `true` | absent | `null` | absent | +| Cutoff: the server stopped at one of its bounds | `true` | absent | set | absent | +| Backend failure | `false` | `true` | `null` | `backend_error` | + +A cutoff is a success. The collected events are valid. The stream simply +continued past the bound. `data.cutoff` is `{ "bound": ..., "limit": ... }`: + +- `events`: `maxEvents` log events were collected (tail only). Only + `type: "log"` events count. `start`, `heartbeat`, `error` and `end` events + are returned in `data.events` but do not use up the limit. +- `time`: the collection window ended. For tail this is `maxMs`. For snapshot + it is the fixed 120 second command timeout. +- `bytes`: stdout plus stderr reached the 8 MiB capture limit. + `outputTruncated` is `true`, and `data` still carries every event parsed + before the cut. The cut never splits a UTF-8 code point. A trailing partial + line can be present in `stdout`, but it is never parsed as an event. + +After a cutoff, the server stopped the child process, so `exitCode` is often +non-zero. Use `ok` and `data.cutoff` to read the result, not `exitCode`. +`data.stop_reason` (tail only) keeps its earlier values: `eof`, `max_events`, +`timeout`, `output_limit`, `cancelled` or `interrupted`. + +A backend failure is not a truncated success. It is reported when the stream +contains an `error` event or an `end` event with a reason other than `eof` or +`closed`, or when the child exits non-zero at the end of the stream. The error +is closed: `code` is `E_UNEXPECTED`, `reason` is `backend_error`, and `message` +is fixed text that never repeats backend output, caller input or the query. +Raw `stdout` and `stderr` are still returned, as they are for other tools. + +Failure evidence counts only before the server stops the child. A child that +writes `error` or `end` events, or exits non-zero, in response to the server's +own stop signal still produces a cutoff. The byte bound is an exception for +events: every retained byte was written before the child was signalled, and +nothing after the cut is parsed, so an `error` or failing `end` event in the +returned prefix is still a backend failure. For the `events` and `time` bounds, +an `error` event that the backend wrote just before the stop but that the server +read after it is reported as a cutoff. The server cannot tell it apart from an +event written in response to the stop. + +## Reconnects and repeated calls + +The server keeps no log state between calls. Every call starts a new backend +stream: + +- A repeated call does not replay events from an earlier call, and it does not + continue after the earlier call's last event. +- A cancelled request, or a session that closes mid-call, stops the backend + process group. The interrupted call's events are not delivered later, to this + session or to a reconnected one. + +To continue a stream approximately, call again with `since` set to the last +event's `ts`. `since` selects the Loki backend and cannot be combined with +`compose`. Expect overlap at the boundary and remove duplicates on the client. + +## Decision: no handles, cursors or idempotency keys (no-go) + +Status: no-go for now (HACK-1134). This decision adds no cursor implementation. + +We considered three additions: + +- A stream handle, so a later call can attach to a running tail. +- A resume cursor, so a later call can continue after the last returned event. +- An idempotency key, so a retried call returns the same result. + +Reasons for no-go: + +1. **The backends have no exact cursor.** Hack's compose path accepts only + `tail`, and `docker compose logs` itself offers only timestamp filters that + can repeat or skip lines with the same timestamp. The lifecycle log + companion is a file tail. Loki selects by time range, and its timestamps + are not unique. A cursor would promise gapless, duplicate-free resume that + Hack cannot deliver, least of all for the default compose backend. +2. **A handle needs state that does not survive the common reconnect.** A + stdio MCP client reconnects by starting a new `hack mcp serve` process, so + in-memory handles are lost. Keeping them on disk under `HACK_HOME` would add + retained log data, plus ownership, expiry and cleanup rules. Logs can hold + secrets, so that retention is a risk. +3. **Idempotency adds nothing to a read.** Both tools are read-only and + annotated `readOnlyHint`. A retry is already safe. It returns current data + rather than a replay, and that is the documented behavior above. +4. **Bounded calls already cover the need.** Agents call tail with a small + window, read `data.cutoff`, and call again with `since` when they need more. + +Revisit this decision (go) only when all of these are true: + +- A backend exposes a stable, monotonic position, such as a daemon-owned log + index. +- Hack has a daemon-owned buffer with defined retention, ownership and secret + handling. +- A real agent workflow shows that `since` overlap is not good enough. diff --git a/src/mcp/logs-contract.ts b/src/mcp/logs-contract.ts new file mode 100644 index 000000000..e2145cd34 --- /dev/null +++ b/src/mcp/logs-contract.ts @@ -0,0 +1,139 @@ +/** + * Result contract for the MCP `hack.project.logs.tail` and + * `hack.project.logs.snapshot` tools. + * + * A collection ends in exactly one outcome: + * - `complete`: the backend reached end of stream and exited 0. + * - `cutoff`: the MCP server stopped collection at one of its own bounds. This + * is a success; `data.cutoff` names the bound and its effective limit. + * - `backend_error`: the log backend reported failure (a stream `error` event, + * a failing `end` event, or a non-zero exit the server did not cause). This + * is a closed error, never a truncated success. + * - `cancelled`: the request was aborted or the session closed; nothing is + * kept for a later request (see docs/reference/mcp-logs.md). + * + * Failure evidence counts only while collection is still running. Once the + * server stops the command for a bound, a later `error`/`end` event or a + * signal exit status is a consequence of that stop, not a backend failure. + * The byte bound is the exception for events: the retained prefix was written + * before the child was signalled and nothing after the cut is parsed, so an + * `error` or failing `end` event inside that prefix is still a failure. + */ + +/** Why collection stopped, as reported in `data.stop_reason`. */ +export type McpLogStopReason = + | "eof" + | "max_events" + | "timeout" + | "output_limit" + | "cancelled" + | "interrupted"; + +/** The bound that ended a successful, incomplete collection. */ +export type McpLogCutoff = { + /** `events` counts `type: "log"` events only; `bytes` is the shared stdout + * plus stderr capture budget; `time` is the collection window. */ + readonly bound: "events" | "bytes" | "time"; + readonly limit: number; +}; + +export type McpLogOutcome = + | { readonly kind: "complete" } + | { readonly kind: "cutoff"; readonly cutoff: McpLogCutoff } + | { readonly kind: "backend_error" } + | { readonly kind: "cancelled" }; + +/** Closed post-spawn failure. The message is fixed and never repeats backend + * output, caller input or query text. */ +export const MCP_LOG_BACKEND_ERROR = Object.freeze({ + code: "E_UNEXPECTED", + reason: "backend_error", + message: "Log backend failed. Run 'hack logs' for details.", +} as const); + +/** End reasons written by the CLI's JSON stream for a normal end of stream. */ +const CLEAN_END_REASONS: ReadonlySet = new Set(["eof", "closed"]); + +/** Classify one parsed `hack logs --json` stream event. */ +export function observeLogStreamEvent(event: Record): { + readonly isLog: boolean; + readonly backendFailure: boolean; +} { + const type = event.type; + if (type === "log") { + return { isLog: true, backendFailure: false }; + } + if (type === "error") { + return { isLog: false, backendFailure: true }; + } + if (type === "end") { + const reason = event.reason; + return { + isLog: false, + backendFailure: + typeof reason === "string" && !CLEAN_END_REASONS.has(reason), + }; + } + return { isLog: false, backendFailure: false }; +} + +/** + * Decide the outcome of a finished collection. Backend failure evidence wins + * over a cutoff; a non-zero exit after a server-initiated stop is ignored. + */ +export function classifyLogCollection(opts: { + readonly stopReason: McpLogStopReason; + readonly exitCode: number; + readonly backendFailureObserved: boolean; + readonly limits: { + readonly maxEvents?: number; + readonly timeMs: number; + readonly bytes: number; + }; +}): McpLogOutcome { + if (opts.backendFailureObserved) { + return { kind: "backend_error" }; + } + switch (opts.stopReason) { + case "cancelled": + case "interrupted": + return { kind: "cancelled" }; + case "max_events": + return { + kind: "cutoff", + cutoff: { bound: "events", limit: opts.limits.maxEvents ?? 0 }, + }; + case "timeout": + return { + kind: "cutoff", + cutoff: { bound: "time", limit: opts.limits.timeMs }, + }; + case "output_limit": + return { + kind: "cutoff", + cutoff: { bound: "bytes", limit: opts.limits.bytes }, + }; + case "eof": + return opts.exitCode === 0 + ? { kind: "complete" } + : { kind: "backend_error" }; + default: { + const unreachable: never = opts.stopReason; + return unreachable; + } + } +} + +/** Narrow a lifetime stop reason to the closed set the logs contract reports. */ +export function toLogStopReason(reason: string): McpLogStopReason { + switch (reason) { + case "max_events": + case "timeout": + case "output_limit": + case "cancelled": + case "interrupted": + return reason; + default: + return "interrupted"; + } +} diff --git a/src/mcp/output-budget.ts b/src/mcp/output-budget.ts index 2c706f7f0..61bab29e2 100644 --- a/src/mcp/output-budget.ts +++ b/src/mcp/output-budget.ts @@ -3,10 +3,18 @@ export const MCP_OUTPUT_LIMIT_BYTES = 8 * 1024 * 1024; /** Share one byte budget across command output streams, before decoding or line * buffering. Over-budget data is drained without retention while the owner stops * the command. Exact-limit output is valid; an additional byte triggers the limit. + * + * With `codePointSafe`, a stream never ends on a cut through a UTF-8 code point: + * an incomplete trailing sequence is held until its next chunk arrives, and the + * limit cut backs off to the preceding code point boundary. Bytes are charged + * to the budget when they arrive, so the limit decision is unchanged; only the + * retained prefix can be up to three bytes shorter. Source bytes that are + * themselves invalid UTF-8 are passed through untouched at stream end. */ export function createMcpOutputBudget(opts: { readonly onLimit: () => void; readonly maxBytes?: number; + readonly codePointSafe?: boolean; }): { readonly exceeded: () => boolean; readonly wrap: ( @@ -18,28 +26,40 @@ export function createMcpOutputBudget(opts: { throw new RangeError("MCP output budget must be a positive integer"); } let exceeded = false; + /** Charge a chunk to the shared budget; returns the accepted byte count. */ + const charge = (size: number): number => { + const accepted = Math.min(remaining, size); + remaining -= accepted; + if (accepted < size && !exceeded) { + exceeded = true; + opts.onLimit(); + } + return accepted; + }; return { exceeded: () => exceeded, wrap: (stream) => { const reader = stream.getReader(); + const retain = + opts.codePointSafe === true + ? createCodePointRetainer() + : BYTE_EXACT_RETAINER; return new ReadableStream({ async pull(controller) { while (true) { const { done, value } = await reader.read(); if (done) { reader.releaseLock(); + const rest = retain.flush(); + if (rest.byteLength > 0) { + controller.enqueue(rest); + } controller.close(); return; } - const accepted = Math.min(remaining, value.byteLength); - remaining -= accepted; - if (accepted < value.byteLength && !exceeded) { - exceeded = true; - opts.onLimit(); - } - if (accepted > 0) { - // Do not keep a reference to a larger discarded backing buffer. - controller.enqueue(value.slice(0, accepted)); + const kept = retain.take(value, charge(value.byteLength)); + if (kept.byteLength > 0) { + controller.enqueue(kept); return; } } @@ -52,3 +72,78 @@ export function createMcpOutputBudget(opts: { }, }; } + +/** Decides which accepted bytes of one stream are emitted now. */ +type Retainer = { + /** `accepted` is the prefix of `chunk` charged to the budget. */ + readonly take: (chunk: Uint8Array, accepted: number) => Uint8Array; + readonly flush: () => Uint8Array; +}; + +const EMPTY = new Uint8Array(0); + +const BYTE_EXACT_RETAINER: Retainer = { + // Copy so a larger discarded backing buffer is not kept alive. + take: (chunk, accepted) => (accepted > 0 ? chunk.slice(0, accepted) : EMPTY), + flush: () => EMPTY, +}; + +function createCodePointRetainer(): Retainer { + /** Accepted bytes of an incomplete trailing code point. */ + let held = EMPTY; + return { + take: (chunk, accepted) => { + const candidate = concatBytes(held, chunk.subarray(0, accepted)); + const keep = candidate.byteLength - incompleteUtf8TailLength(candidate); + // After a cut this stream retains nothing more, so a partial code point + // is dropped instead of being held for a continuation. + held = accepted < chunk.byteLength ? EMPTY : candidate.slice(keep); + return keep > 0 ? candidate.slice(0, keep) : EMPTY; + }, + flush: () => { + const rest = held; + held = EMPTY; + return rest; + }, + }; +} + +/** + * Number of trailing bytes that start a UTF-8 sequence the buffer does not + * complete (0-3). An invalid lead byte or an over-long continuation run counts + * as complete, so malformed input is never held back indefinitely. + */ +export function incompleteUtf8TailLength(bytes: Uint8Array): number { + const end = bytes.byteLength; + for (let back = 1; back <= Math.min(4, end); back += 1) { + const byte = bytes[end - back] ?? 0; + if ((byte & 0xc0) === 0x80) { + continue; + } + return back < utf8SequenceLength(byte) ? back : 0; + } + return 0; +} + +function utf8SequenceLength(lead: number): number { + if ((lead & 0xe0) === 0xc0) { + return 2; + } + if ((lead & 0xf0) === 0xe0) { + return 3; + } + if ((lead & 0xf8) === 0xf0) { + return 4; + } + return 1; +} + +function concatBytes(head: Uint8Array, tail: Uint8Array): Uint8Array { + if (head.byteLength === 0) { + return tail; + } + const joined = new Uint8Array(head.byteLength + tail.byteLength); + joined.set(head, 0); + joined.set(tail, head.byteLength); + return joined; +} diff --git a/src/mcp/server.ts b/src/mcp/server.ts index b3dcefcc2..e9376c87f 100644 --- a/src/mcp/server.ts +++ b/src/mcp/server.ts @@ -34,7 +34,19 @@ import { import { readLinesFromStream } from "../ui/lines.ts"; import type { McpCommandAdmission } from "./command-admission.ts"; import { superviseMcpCommand } from "./command-lifetime.ts"; -import { createMcpOutputBudget } from "./output-budget.ts"; +import { + classifyLogCollection, + MCP_LOG_BACKEND_ERROR, + type McpLogCutoff, + type McpLogOutcome, + type McpLogStopReason, + observeLogStreamEvent, + toLogStopReason, +} from "./logs-contract.ts"; +import { + createMcpOutputBudget, + MCP_OUTPUT_LIMIT_BYTES, +} from "./output-budget.ts"; import { captureMcpSessionContext, type McpSessionContext, @@ -136,11 +148,13 @@ type ToolResultPayload = HackCommandResult & { readonly data?: unknown; /** Present (and false) only on refusals returned before any child spawned. */ readonly spawned?: false; - readonly error?: { - readonly code: McpRefusalCode; - readonly reason: McpRefusalReason; - readonly message: string; - }; + readonly error?: + | { + readonly code: McpRefusalCode; + readonly reason: McpRefusalReason; + readonly message: string; + } + | typeof MCP_LOG_BACKEND_ERROR; }; type ProjectArgsResolution = @@ -205,8 +219,8 @@ const toolOutputSchema = { spawned: z.literal(false).optional(), error: z .object({ - code: z.enum(["E_USAGE", "E_PROJECT_NOT_FOUND"]), - reason: z.enum(MCP_REFUSAL_REASONS), + code: z.enum(["E_USAGE", "E_PROJECT_NOT_FOUND", "E_UNEXPECTED"]), + reason: z.enum([...MCP_REFUSAL_REASONS, MCP_LOG_BACKEND_ERROR.reason]), message: z.string(), }) .optional(), @@ -700,18 +714,20 @@ function registerTools(opts: { ...buildLogSelectionArgs(input), ]; - const result = await runHackCommand({ + const result = await runHackLogCollect({ context: opts.context, signal: extra.signal, tool: "hack.project.logs.snapshot", args, + timeoutMs: DEFAULT_CMD_TIMEOUT_MS, }); - return buildToolResult({ + return buildLogToolResult({ result, data: { - events: parseJsonLines(result.stdout), - count: countJsonLines(result.stdout), + events: result.events, + count: result.events.length, + cutoff: cutoffOf(result.outcome), limits: { tail: input.tail ?? null }, }, }); @@ -730,7 +746,8 @@ function registerTools(opts: { ...logSelectionInput, maxEvents: boundedLimitInput({ ceiling: MCP_INPUT_CEILINGS.maxEvents, - description: "Max events to collect", + description: + "Max type:log events to collect; start, heartbeat, error and end events do not count", }).optional(), maxMs: boundedLimitInput({ ceiling: MCP_INPUT_CEILINGS.maxMs, @@ -758,26 +775,21 @@ function registerTools(opts: { const maxEvents = input.maxEvents ?? DEFAULT_LOG_TAIL_EVENTS; const maxMs = input.maxMs ?? DEFAULT_LOG_TAIL_MS; - const result = await runHackLogTail({ + const result = await runHackLogCollect({ context: opts.context, signal: extra.signal, tool: "hack.project.logs.tail", args, maxEvents, - maxMs, + timeoutMs: maxMs, }); - return buildToolResult({ - result: { - ...(result.outputTruncated ? { outputTruncated: true } : {}), - command: result.command, - exitCode: result.exitCode, - stdout: result.stdout, - stderr: result.stderr, - }, + return buildLogToolResult({ + result, data: { events: result.events, count: result.events.length, + cutoff: cutoffOf(result.outcome), stop_reason: result.stopReason, duration_ms: result.durationMs, limits: { tail: input.tail ?? null, maxEvents, maxMs }, @@ -1057,10 +1069,48 @@ function buildToolResult(opts: { }; } +/** + * Logs tools result. Unlike {@link buildToolResult}, success follows the + * collection outcome rather than the child's exit status: a cutoff is `ok` + * with `data.cutoff` set (the server stopped the child, so `exitCode` may be + * non-zero), and `data` is kept after the byte bound so partial events + * survive. A backend failure is `ok: false` with the closed `backend_error`. + */ +function buildLogToolResult(opts: { + readonly result: HackLogCollection; + readonly data: Record; +}): CallToolResult { + const { result } = opts; + const ok = + result.outcome.kind === "complete" || result.outcome.kind === "cutoff"; + const payload: ToolResultPayload = { + ok, + command: result.command, + exitCode: result.exitCode, + stdout: result.stdout, + stderr: result.stderr, + ...(result.outputTruncated ? { outputTruncated: true } : {}), + data: opts.data, + ...(result.outcome.kind === "backend_error" + ? { error: MCP_LOG_BACKEND_ERROR } + : {}), + }; + + return { + content: [{ type: "text", text: JSON.stringify(payload, null, 2) }], + structuredContent: payload, + ...(ok ? {} : { isError: true }), + }; +} + +function cutoffOf(outcome: McpLogOutcome): McpLogCutoff | null { + return outcome.kind === "cutoff" ? outcome.cutoff : null; +} + /** * Typed refusal for a request rejected before any child process exists. * `spawned: false` is a guarantee: every caller returns before - * `runHackCommand`/`runHackLogTail`, so no argv, audit line or mutation occurs. + * `runHackCommand`/`runHackLogCollect`, so no argv, audit line or mutation occurs. * `stderr` repeats the message for clients reading the earlier contract. * The message is the reason's fixed text from {@link MCP_REFUSALS}; only * `invalid_arguments` may pass its schema-key-only summary instead. @@ -1360,24 +1410,34 @@ async function runHackCommand(opts: { : await work(); } -async function runHackLogTail(opts: { - readonly context: McpSessionContext; - readonly signal: AbortSignal; - readonly tool: string; - readonly args: readonly string[]; - readonly maxEvents: number; - readonly maxMs: number; -}): Promise<{ +type HackLogCollection = { readonly outputTruncated?: boolean; readonly command: string; readonly exitCode: number; readonly stdout: string; readonly stderr: string; readonly events: readonly Record[]; - readonly stopReason: string; + readonly stopReason: McpLogStopReason; readonly durationMs: number; -}> { - const work = async () => { + readonly outcome: McpLogOutcome; +}; + +/** + * Run `hack logs --json` and collect its stream events under the contract in + * `logs-contract.ts`. `maxEvents` counts `type: "log"` events only; `timeoutMs` + * bounds the whole collection; the shared byte budget cuts on a UTF-8 code + * point boundary. Nothing outlives the call: a later call, in this session or + * a reconnected one, starts a new backend stream (no cursor, no replay). + */ +async function runHackLogCollect(opts: { + readonly context: McpSessionContext; + readonly signal: AbortSignal; + readonly tool: string; + readonly args: readonly string[]; + readonly maxEvents?: number; + readonly timeoutMs: number; +}): Promise { + const work = async (): Promise => { const invocation = await resolveHackInvocation(opts.context); opts.signal.throwIfAborted(); const cmd = [invocation.bin, ...invocation.args, ...opts.args]; @@ -1390,39 +1450,55 @@ async function runHackLogTail(opts: { stderr: "pipe", }); - const { maxEvents, maxMs } = opts; + const { maxEvents } = opts; const start = Date.now(); const events: Record[] = []; const stdoutLines: string[] = []; const stderrLines: string[] = []; - let stopReason = "eof"; + let stopReason: McpLogStopReason = "eof"; + // Set once a server stop can have reached the child. Later failure events + // may describe that stop. A byte cut is the exception: the retained prefix + // was written before the child was signalled, and nothing is retained after + // it, so failure evidence in that prefix still counts. + let failureEvidenceClosed = false; + let logCount = 0; + let backendFailureObserved = false; const lifetime = superviseMcpCommand({ proc, signal: opts.signal, - timeoutMs: maxMs, + timeoutMs: opts.timeoutMs, onStop: (reason) => { - stopReason = reason; + stopReason = toLogStopReason(reason); + if (stopReason !== "output_limit") { + failureEvidenceClosed = true; + } }, }); const output = createMcpOutputBudget({ + codePointSafe: true, onLimit: () => lifetime.stop("output_limit"), }); + /** Record one stream event; true once the log-event bound is reached. */ + const recordEvent = (event: Record): boolean => { + events.push(event); + const observed = observeLogStreamEvent(event); + if (observed.backendFailure && !failureEvidenceClosed) { + backendFailureObserved = true; + } + if (observed.isLog) { + logCount += 1; + } + return maxEvents !== undefined && logCount >= maxEvents; + }; const stdoutTask = (async () => { for await (const line of readLinesFromStream(output.wrap(proc.stdout))) { stdoutLines.push(line); - const trimmed = line.trim(); - if (trimmed.length === 0) { - continue; - } - const parsed = parseJsonLine(trimmed); - if (parsed) { - events.push(parsed); - } - if (events.length >= maxEvents) { + const parsed = parseJsonLine(line.trim()); + if (parsed && recordEvent(parsed)) { lifetime.stop("max_events"); break; } @@ -1443,7 +1519,6 @@ async function runHackLogTail(opts: { } if (output.exceeded()) { - exitCode = 1; stderrLines.push( "MCP output exceeded the 8 MiB capture limit; use the CLI for full output." ); @@ -1465,6 +1540,16 @@ async function runHackLogTail(opts: { ...(output.exceeded() ? { outputTruncated: true } : {}), stopReason, durationMs: Date.now() - start, + outcome: classifyLogCollection({ + stopReason, + exitCode, + backendFailureObserved, + limits: { + ...(maxEvents === undefined ? {} : { maxEvents }), + timeMs: opts.timeoutMs, + bytes: MCP_OUTPUT_LIMIT_BYTES, + }, + }), }; }; return opts.context.admission @@ -1491,17 +1576,6 @@ function parseJson(text: string): Record | null { } } -function parseJsonLines(text: string): Record[] { - const events: Record[] = []; - for (const line of text.split("\n")) { - const parsed = parseJsonLine(line.trim()); - if (parsed) { - events.push(parsed); - } - } - return events; -} - function parseJsonLine(line: string): Record | null { if (line.length === 0) { return null; @@ -1514,16 +1588,6 @@ function parseJsonLine(line: string): Record | null { } } -function countJsonLines(text: string): number { - let count = 0; - for (const line of text.split("\n")) { - if (parseJsonLine(line.trim())) { - count += 1; - } - } - return count; -} - function joinLines(lines: readonly string[]): string { if (lines.length === 0) { return ""; diff --git a/tests/mcp-lifetime.test.ts b/tests/mcp-lifetime.test.ts index 8109ff3ce..4a7787f61 100644 --- a/tests/mcp-lifetime.test.ts +++ b/tests/mcp-lifetime.test.ts @@ -197,7 +197,15 @@ test("MCP log-tail timeout stops a command that ignores SIGTERM and returns a re }); await waitFor(() => messages.some((item) => item.id === 2)); expect(messages.find((item) => item.id === 2)).toMatchObject({ - result: { structuredContent: { data: { stop_reason: "timeout" } } }, + result: { + structuredContent: { + ok: true, + data: { + stop_reason: "timeout", + cutoff: { bound: "time", limit: 1000 }, + }, + }, + }, }); expect(alive(fixture.childPid ?? 0)).toBe(false); expect(fixture.proc.exitCode).toBeNull(); @@ -217,10 +225,21 @@ for (const tool of ["hack.projects.list", "hack.project.logs.tail"]) { const { fixture, send, messages } = await startFixture({ tool, output }); await waitFor(() => messages.some((item) => item.id === 2)); const result = messages.find((item) => item.id === 2)?.result; - expect(result?.isError).toBe(true); expect(result?.structuredContent?.outputTruncated).toBe(true); - expect(result?.structuredContent?.ok).toBe(false); - expect(result?.structuredContent?.data).toBeUndefined(); + if (tool === "hack.project.logs.tail") { + // HACK-1134: the byte bound is a cutoff (success with partial data), + // not a failure; see docs/reference/mcp-logs.md. + expect(result?.isError).toBeUndefined(); + expect(result?.structuredContent?.ok).toBe(true); + expect(result?.structuredContent?.data).toMatchObject({ + cutoff: { bound: "bytes", limit: 8 * 1024 * 1024 }, + stop_reason: "output_limit", + }); + } else { + expect(result?.isError).toBe(true); + expect(result?.structuredContent?.ok).toBe(false); + expect(result?.structuredContent?.data).toBeUndefined(); + } expect(result?.structuredContent?.stderr).toContain( "8 MiB capture limit" ); diff --git a/tests/mcp-logs-contract.test.ts b/tests/mcp-logs-contract.test.ts new file mode 100644 index 000000000..9902603ff --- /dev/null +++ b/tests/mcp-logs-contract.test.ts @@ -0,0 +1,760 @@ +import { afterEach, expect, test } from "bun:test"; +import { + chmod, + mkdir, + mkdtemp, + readFile, + rm, + writeFile, +} from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; + +import { Client } from "@modelcontextprotocol/sdk/client/index.js"; +import { InMemoryTransport } from "@modelcontextprotocol/sdk/inMemory.js"; + +import { + classifyLogCollection, + MCP_LOG_BACKEND_ERROR, + type McpLogStopReason, + observeLogStreamEvent, +} from "../src/mcp/logs-contract.ts"; +import { + createMcpOutputBudget, + incompleteUtf8TailLength, + MCP_OUTPUT_LIMIT_BYTES, +} from "../src/mcp/output-budget.ts"; +import { createMcpServer } from "../src/mcp/server.ts"; + +// --------------------------------------------------------------------------- +// HACK-1134: logs.tail / logs.snapshot separate a cutoff (success, data.cutoff) +// from a backend failure (closed backend_error), cut output on a UTF-8 code +// point boundary, and never replay events across calls or reconnects. +// +// Every fixture is a temp root with its own HOME, HACK_HOME and registry; the +// hack binary is a stub selected by HACK_MCP_COMMAND, so no Docker/OrbStack +// socket, agent client config or real home directory is touched. +// --------------------------------------------------------------------------- + +const LIMITS = { maxEvents: 2, timeMs: 1000, bytes: 64 } as const; + +test("only type:log events count toward maxEvents; error and failing end events are failures", () => { + expect(observeLogStreamEvent({ type: "log", entry: {} })).toEqual({ + isLog: true, + backendFailure: false, + }); + for (const type of ["start", "heartbeat", undefined]) { + expect(observeLogStreamEvent({ type })).toEqual({ + isLog: false, + backendFailure: false, + }); + } + expect(observeLogStreamEvent({ type: "error", message: "x" })).toEqual({ + isLog: false, + backendFailure: true, + }); + for (const reason of ["eof", "closed", undefined]) { + expect(observeLogStreamEvent({ type: "end", reason }).backendFailure).toBe( + false + ); + } + for (const reason of ["error", "exit:1", "exit:125"]) { + expect(observeLogStreamEvent({ type: "end", reason }).backendFailure).toBe( + true + ); + } +}); + +test("each stop reason maps to exactly one outcome and failure evidence wins", () => { + const classify = ( + stopReason: McpLogStopReason, + exitCode: number, + backendFailureObserved = false + ) => + classifyLogCollection({ + stopReason, + exitCode, + backendFailureObserved, + limits: LIMITS, + }); + expect(classify("eof", 0)).toEqual({ kind: "complete" }); + expect(classify("eof", 1)).toEqual({ kind: "backend_error" }); + // A server-initiated stop is a cutoff even though the child exits non-zero. + expect(classify("max_events", 143)).toEqual({ + kind: "cutoff", + cutoff: { bound: "events", limit: 2 }, + }); + expect(classify("timeout", 137)).toEqual({ + kind: "cutoff", + cutoff: { bound: "time", limit: 1000 }, + }); + expect(classify("output_limit", 143)).toEqual({ + kind: "cutoff", + cutoff: { bound: "bytes", limit: 64 }, + }); + expect(classify("cancelled", 143)).toEqual({ kind: "cancelled" }); + expect(classify("interrupted", 143)).toEqual({ kind: "cancelled" }); + for (const stopReason of [ + "eof", + "max_events", + "timeout", + "output_limit", + ] as const) { + expect(classify(stopReason, 0, true)).toEqual({ kind: "backend_error" }); + } + expect(Object.isFrozen(MCP_LOG_BACKEND_ERROR)).toBe(true); +}); + +test("incomplete UTF-8 tails are measured for 2-, 3- and 4-byte sequences", () => { + const bytes = (text: string) => new TextEncoder().encode(text); + expect(incompleteUtf8TailLength(bytes(""))).toBe(0); + expect(incompleteUtf8TailLength(bytes("ab"))).toBe(0); + for (const char of ["é", "€", "😀"]) { + const encoded = bytes(`a${char}`); + expect(incompleteUtf8TailLength(encoded)).toBe(0); + for (let drop = 1; drop < encoded.byteLength - 1; drop += 1) { + expect( + incompleteUtf8TailLength(encoded.subarray(0, encoded.byteLength - drop)) + ).toBe(encoded.byteLength - 1 - drop); + } + } + // Malformed input is never held back: stray continuations, bad leads. + expect(incompleteUtf8TailLength(new Uint8Array([0x80, 0x80, 0x80]))).toBe(0); + expect(incompleteUtf8TailLength(new Uint8Array([0x61, 0xff]))).toBe(0); +}); + +function chunkedStream(chunks: readonly Uint8Array[]) { + return new ReadableStream({ + start(controller) { + for (const chunk of chunks) { + controller.enqueue(chunk); + } + controller.close(); + }, + }); +} + +async function readAll(stream: ReadableStream) { + return new Uint8Array(await new Response(stream).arrayBuffer()); +} + +test("code-point-safe capture never ends on a split code point at the byte limit", async () => { + const text = "a😀😀😀"; + const encoded = new TextEncoder().encode(text); + for (let maxBytes = 1; maxBytes < encoded.byteLength; maxBytes += 1) { + const safe = createMcpOutputBudget({ + maxBytes, + codePointSafe: true, + onLimit: () => undefined, + }); + const kept = await readAll(safe.wrap(chunkedStream([encoded]))); + expect(safe.exceeded()).toBe(true); + expect(kept.byteLength).toBeLessThanOrEqual(maxBytes); + expect(new TextDecoder("utf-8", { fatal: true }).decode(kept)).toBe( + text.slice(0, 1 + 2 * Math.floor((maxBytes - 1) / 4)) + ); + } +}); + +test("negative control: the byte-exact default capture does split a code point", async () => { + const encoded = new TextEncoder().encode("a😀"); + const exact = createMcpOutputBudget({ + maxBytes: 3, + onLimit: () => undefined, + }); + const kept = await readAll(exact.wrap(chunkedStream([encoded]))); + expect(kept.byteLength).toBe(3); + expect(new TextDecoder().decode(kept)).toContain("�"); +}); + +test("code-point-safe capture joins sequences split across chunks and keeps exact-limit output", async () => { + const encoded = new TextEncoder().encode("é€😀"); + const chunks = [...encoded].map((byte) => new Uint8Array([byte])); + let stops = 0; + const budget = createMcpOutputBudget({ + maxBytes: encoded.byteLength, + codePointSafe: true, + onLimit: () => { + stops += 1; + }, + }); + const kept = await readAll(budget.wrap(chunkedStream(chunks))); + expect(new TextDecoder("utf-8", { fatal: true }).decode(kept)).toBe("é€😀"); + expect(budget.exceeded()).toBe(false); + expect(stops).toBe(0); +}); + +test("code-point-safe capture shares one budget and drops a held partial sequence once cut", async () => { + const budget = createMcpOutputBudget({ + maxBytes: 4, + codePointSafe: true, + onLimit: () => undefined, + }); + const euro = new TextEncoder().encode("€"); + // First stream ends after two of the euro's three bytes, consuming 3 bytes. + const first = await readAll( + budget.wrap(chunkedStream([new Uint8Array([0x61]), euro.subarray(0, 2)])) + ); + // Source bytes that are themselves incomplete pass through at stream end. + expect([...first]).toEqual([0x61, ...euro.subarray(0, 2)]); + const second = await readAll(budget.wrap(chunkedStream([euro]))); + expect(second.byteLength).toBe(0); + expect(budget.exceeded()).toBe(true); +}); + +// --------------------------------------------------------------------------- +// In-process MCP sessions against a scripted log backend. +// --------------------------------------------------------------------------- + +type Scenario = + | "clean" + | "heartbeats" + | "follow" + | "backend-error" + | "exit-end" + | "nonzero-exit" + | "error-after-stop" + | "bytes-utf8" + | "error-in-byte-cut" + | "sequenced"; + +type LogsFixture = { + readonly root: string; + readonly stubDir: string; + readonly connect: () => Promise; +}; + +const CANARY = "LOGS-CANARY-QUERY-ECHO"; +const fixtureRoots: string[] = []; +const fixtureClients: Client[] = []; + +afterEach(async () => { + await Promise.all( + fixtureClients.splice(0).map(async (mcp) => { + try { + await mcp.close(); + } catch { + /* already closed */ + } + }) + ); + for (const root of fixtureRoots.splice(0)) { + for (const pid of await readStubPids(join(root, "stub"))) { + try { + process.kill(pid, "SIGKILL"); + } catch { + /* already stopped */ + } + } + await rm(root, { recursive: true, force: true }); + } +}); + +const STUB_SOURCE = String.raw` +import { appendFileSync, existsSync, readFileSync, writeFileSync } from "node:fs"; +const dir = process.env.HACK_TEST_STUB_DIR; +const scenario = process.env.HACK_TEST_LOG_SCENARIO; +const counter = dir + "/invocations"; +const n = (existsSync(counter) ? Number(readFileSync(counter, "utf8")) : 0) + 1; +writeFileSync(counter, String(n)); +appendFileSync(dir + "/pids", process.pid + "\n"); +const line = (event) => + JSON.stringify({ ts: "2026-01-01T00:00:00.000Z", backend: "compose", ...event }) + "\n"; +const emit = (event) => process.stdout.write(line(event)); +const log = (message) => emit({ type: "log", entry: { message } }); +const hang = () => setInterval(() => {}, 1000); +emit({ type: "start", follow: true }); +switch (scenario) { + case "clean": + log("one"); + log("two"); + emit({ type: "end", reason: "eof" }); + break; + case "heartbeats": + emit({ type: "heartbeat" }); + log("one"); + emit({ type: "heartbeat" }); + emit({ type: "heartbeat" }); + log("two"); + log("three"); + hang(); + break; + case "follow": + log("one"); + hang(); + break; + case "backend-error": + log("one"); + emit({ type: "error", message: "Loki error: " + process.env.HACK_TEST_CANARY }); + emit({ type: "end", reason: "error" }); + process.stderr.write("Loki error: " + process.env.HACK_TEST_CANARY + "\n"); + process.exitCode = 1; + break; + case "exit-end": + log("one"); + emit({ type: "end", reason: "exit:1" }); + break; + case "nonzero-exit": + process.stderr.write("compose failed\n"); + process.exitCode = 1; + break; + case "error-after-stop": { + log("one"); + const timer = hang(); + process.on("SIGTERM", () => { + clearInterval(timer); + emit({ type: "error", message: "terminated" }); + emit({ type: "end", reason: "error" }); + process.exitCode = 1; + }); + break; + } + case "bytes-utf8": { + log("one"); + log("two"); + const written = Buffer.byteLength(line({ type: "start", follow: true })) + + Buffer.byteLength(line({ type: "log", entry: { message: "one" } })) + + Buffer.byteLength(line({ type: "log", entry: { message: "two" } })); + // Pad so the 8 MiB cut lands three bytes into a four-byte code point. + const pad = (5 - (written % 4)) % 4; + process.stdout.write("a".repeat(pad) + "😀".repeat(2_400_000)); + hang(); + break; + } + case "error-in-byte-cut": { + log("one"); + const limit = 8 * 1024 * 1024; + const written = Buffer.byteLength(line({ type: "start", follow: true })) + + Buffer.byteLength(line({ type: "log", entry: { message: "one" } })); + const failure = line({ type: "error", message: "backend failed" }); + // One write: filler, an error event ending 8 bytes before the limit, and + // bytes past the limit. The error is read in the same chunk as the cut. + const filler = "x".repeat(limit - written - Buffer.byteLength(failure) - 9); + process.stdout.write(filler + "\n" + failure + "z".repeat(1024 * 1024)); + hang(); + break; + } + case "sequenced": { + let seq = 0; + setInterval(() => { + log("inv-" + n + "-seq-" + seq); + appendFileSync(dir + "/emitted-" + n, seq + "\n"); + seq += 1; + }, 10); + break; + } + default: + process.exitCode = 2; +} +`; + +async function startLogsFixture(scenario: Scenario): Promise { + const root = await mkdtemp(join(tmpdir(), "hack-mcp-logs-")); + fixtureRoots.push(root); + const project = join(root, "repo"); + const projectDir = join(project, ".hack"); + const registryDir = join(root, "registry"); + const stubDir = join(root, "stub"); + await mkdir(projectDir, { recursive: true }); + await mkdir(registryDir); + await mkdir(stubDir); + await writeFile(join(projectDir, "docker-compose.yml"), "services: {}\n"); + await writeFile( + join(projectDir, "hack.config.json"), + JSON.stringify({ name: "demo" }) + ); + await writeFile( + join(registryDir, "projects.json"), + JSON.stringify({ + version: 1, + projects: [ + { + id: "demo", + createdAt: "2026-01-01T00:00:00Z", + name: "demo", + repoRoot: project, + projectDirName: ".hack", + projectDir, + }, + ], + }) + ); + const stub = join(root, "hack-stub"); + await writeFile(stub, `#!${process.execPath}\n${STUB_SOURCE}`); + await chmod(stub, 0o755); + const env: Record = { + ...process.env, + HOME: root, + HACK_HOME: join(root, "state"), + HACK_GLOBAL_CONFIG_PATH: join(registryDir, "config.json"), + HACK_MCP_COMMAND: stub, + HACK_TEST_STUB_DIR: stubDir, + HACK_TEST_LOG_SCENARIO: scenario, + HACK_TEST_CANARY: CANARY, + }; + // Each connect is a fresh session, as a client reconnecting to Hack gets. + const connect = async (): Promise => { + const server = createMcpServer({ cwd: project, env }); + const client = new Client({ name: "hack-mcp-logs", version: "1" }); + fixtureClients.push(client); + const [clientTransport, serverTransport] = + InMemoryTransport.createLinkedPair(); + await server.connect(serverTransport); + await client.connect(clientTransport); + return client; + }; + return { root, stubDir, connect }; +} + +type LogsPayload = { + readonly ok: boolean; + readonly exitCode: number; + readonly stdout: string; + readonly stderr: string; + readonly outputTruncated?: boolean; + readonly error?: { code: string; reason: string; message: string }; + readonly data: { + readonly events: readonly Record[]; + readonly count: number; + readonly cutoff: { bound: string; limit: number } | null; + readonly stop_reason?: string; + }; +}; + +async function callLogs(opts: { + readonly client: Client; + readonly tool: "hack.project.logs.tail" | "hack.project.logs.snapshot"; + readonly args?: Record; + readonly signal?: AbortSignal; +}): Promise<{ isError: boolean; payload: LogsPayload; text: string }> { + const result = await opts.client.callTool( + { + name: opts.tool, + arguments: { projectName: "demo", ...opts.args }, + }, + undefined, + opts.signal ? { signal: opts.signal } : undefined + ); + const content = result.content as Array<{ type: string; text?: string }>; + return { + isError: result.isError === true, + payload: result.structuredContent as LogsPayload, + text: content.map((item) => item.text ?? "").join(""), + }; +} + +function logMessages(events: readonly Record[]): string[] { + return events + .filter((event) => event.type === "log") + .map((event) => { + const entry = event.entry as { message?: unknown } | undefined; + return String(entry?.message); + }); +} + +async function readStubPids(stubDir: string): Promise { + const text = await readFile(join(stubDir, "pids"), "utf8").catch(() => ""); + return text + .split("\n") + .filter((value) => value.length > 0) + .map(Number); +} + +async function readEmitted(stubDir: string, invocation: number) { + const text = await readFile( + join(stubDir, `emitted-${invocation}`), + "utf8" + ).catch(() => ""); + return text.split("\n").filter((value) => value.length > 0).length; +} + +function alive(pid: number): boolean { + try { + process.kill(pid, 0); + return true; + } catch { + return false; + } +} + +async function waitFor(check: () => boolean | Promise): Promise { + const end = Date.now() + 8000; + while (!(await check())) { + if (Date.now() >= end) { + throw new Error("Timed out waiting for logs fixture"); + } + await Bun.sleep(20); + } +} + +test("a clean end of stream is complete: ok with a null cutoff for tail and snapshot", async () => { + const fixture = await startLogsFixture("clean"); + const client = await fixture.connect(); + for (const tool of [ + "hack.project.logs.tail", + "hack.project.logs.snapshot", + ] as const) { + const { isError, payload } = await callLogs({ client, tool }); + expect(isError).toBe(false); + expect(payload.ok).toBe(true); + expect(payload.exitCode).toBe(0); + expect(payload.error).toBeUndefined(); + expect(payload.data.cutoff).toBeNull(); + expect(logMessages(payload.data.events)).toEqual(["one", "two"]); + expect(payload.data.count).toBe(payload.data.events.length); + } +}); + +test("maxEvents counts log events only and its cutoff is a success", async () => { + const fixture = await startLogsFixture("heartbeats"); + const client = await fixture.connect(); + const { isError, payload } = await callLogs({ + client, + tool: "hack.project.logs.tail", + args: { maxEvents: 2, maxMs: 10_000 }, + }); + expect(isError).toBe(false); + expect(payload.ok).toBe(true); + expect(payload.data.cutoff).toEqual({ bound: "events", limit: 2 }); + expect(payload.data.stop_reason).toBe("max_events"); + expect(logMessages(payload.data.events)).toEqual(["one", "two"]); + // start + 3 heartbeats are returned but did not consume the event budget. + expect(payload.data.events.map((event) => event.type)).toEqual([ + "start", + "heartbeat", + "log", + "heartbeat", + "heartbeat", + "log", + ]); + for (const pid of await readStubPids(fixture.stubDir)) { + await waitFor(() => !alive(pid)); + } +}); + +// The stub must start and emit its first log before the window closes. Bun +// startup is far below this even on a loaded host; a shorter window flakes. +const TIME_WINDOW_MS = 2000; + +test("the collection window cutoff is a success even though the child is signalled", async () => { + const fixture = await startLogsFixture("follow"); + const client = await fixture.connect(); + const { isError, payload } = await callLogs({ + client, + tool: "hack.project.logs.tail", + args: { maxMs: TIME_WINDOW_MS }, + }); + expect(isError).toBe(false); + expect(payload.ok).toBe(true); + expect(payload.exitCode).not.toBe(0); + expect(payload.data.cutoff).toEqual({ bound: "time", limit: TIME_WINDOW_MS }); + expect(logMessages(payload.data.events)).toEqual(["one"]); +}); + +test("failure events after a server-initiated stop do not turn a cutoff into an error", async () => { + const fixture = await startLogsFixture("error-after-stop"); + const client = await fixture.connect(); + const { isError, payload } = await callLogs({ + client, + tool: "hack.project.logs.tail", + args: { maxMs: TIME_WINDOW_MS }, + }); + // The stub did report error/end(error) in response to SIGTERM ... + expect(payload.data.events.map((event) => event.type)).toEqual([ + "start", + "log", + "error", + "end", + ]); + // ... yet the outcome is the time cutoff the server caused. + expect(isError).toBe(false); + expect(payload.ok).toBe(true); + expect(payload.data.cutoff).toEqual({ bound: "time", limit: TIME_WINDOW_MS }); +}); + +for (const [scenario, label] of [ + ["backend-error", "an error event"], + ["exit-end", "a failing end event"], + ["nonzero-exit", "a non-zero exit at end of stream"], +] as const) { + test(`${label} is a closed backend_error, not a truncated success`, async () => { + const fixture = await startLogsFixture(scenario); + const client = await fixture.connect(); + for (const tool of [ + "hack.project.logs.tail", + "hack.project.logs.snapshot", + ] as const) { + const { isError, payload } = await callLogs({ client, tool }); + expect(isError).toBe(true); + expect(payload.ok).toBe(false); + expect(payload.error).toEqual({ + code: "E_UNEXPECTED", + reason: "backend_error", + message: MCP_LOG_BACKEND_ERROR.message, + }); + expect(payload.data.cutoff).toBeNull(); + expect(payload.outputTruncated).toBeUndefined(); + // The closed diagnostic never repeats backend text or caller input. + expect(payload.error?.message).not.toContain(CANARY); + } + }); +} + +test("the byte cutoff returns earlier events and never splits a code point", async () => { + const fixture = await startLogsFixture("bytes-utf8"); + const client = await fixture.connect(); + const { isError, payload } = await callLogs({ + client, + tool: "hack.project.logs.tail", + args: { maxMs: 30_000 }, + }); + expect(isError).toBe(false); + expect(payload.ok).toBe(true); + expect(payload.outputTruncated).toBe(true); + expect(payload.data.cutoff).toEqual({ + bound: "bytes", + limit: MCP_OUTPUT_LIMIT_BYTES, + }); + expect(payload.data.stop_reason).toBe("output_limit"); + expect(logMessages(payload.data.events)).toEqual(["one", "two"]); + expect(payload.stdout).not.toContain("�"); + const lastLine = payload.stdout.trimEnd().split("\n").at(-1) ?? ""; + expect(lastLine.endsWith("😀")).toBe(true); + // The cut backed off the three bytes of the split emoji, and no more. + expect(Buffer.byteLength(payload.stdout)).toBe( + MCP_OUTPUT_LIMIT_BYTES - 3 + 1 + ); + expect(payload.stderr).toContain("8 MiB capture limit"); + for (const pid of await readStubPids(fixture.stubDir)) { + await waitFor(() => !alive(pid)); + } +}, 30_000); + +test("an error event read in the same chunk as the byte cut is still a backend_error", async () => { + const fixture = await startLogsFixture("error-in-byte-cut"); + const client = await fixture.connect(); + const { isError, payload } = await callLogs({ + client, + tool: "hack.project.logs.tail", + args: { maxMs: 30_000 }, + }); + // The error event sits inside the retained prefix, which the child wrote + // before it was signalled, so it is real failure evidence, not a cutoff. + expect(payload.outputTruncated).toBe(true); + expect(payload.data.stop_reason).toBe("output_limit"); + expect(payload.data.events.map((event) => event.type)).toEqual([ + "start", + "log", + "error", + ]); + expect(isError).toBe(true); + expect(payload.ok).toBe(false); + expect(payload.error).toEqual({ + code: "E_UNEXPECTED", + reason: "backend_error", + message: MCP_LOG_BACKEND_ERROR.message, + }); + expect(payload.data.cutoff).toBeNull(); + for (const pid of await readStubPids(fixture.stubDir)) { + await waitFor(() => !alive(pid)); + } +}, 30_000); + +test("consecutive tail calls each start a new stream: no cursor, no replay", async () => { + const fixture = await startLogsFixture("sequenced"); + const client = await fixture.connect(); + const first = await callLogs({ + client, + tool: "hack.project.logs.tail", + args: { maxEvents: 3, maxMs: 10_000 }, + }); + const second = await callLogs({ + client, + tool: "hack.project.logs.tail", + args: { maxEvents: 3, maxMs: 10_000 }, + }); + expect(logMessages(first.payload.data.events)).toEqual([ + "inv-1-seq-0", + "inv-1-seq-1", + "inv-1-seq-2", + ]); + // The second call neither repeats the first call's events nor resumes + // after them; it is an independent read of the backend. + expect(logMessages(second.payload.data.events)).toEqual([ + "inv-2-seq-0", + "inv-2-seq-1", + "inv-2-seq-2", + ]); +}); + +test("a disconnect mid-tail stops the backend and a reconnected session never sees its events", async () => { + const fixture = await startLogsFixture("sequenced"); + const disconnected = await fixture.connect(); + const pending = callLogs({ + client: disconnected, + tool: "hack.project.logs.tail", + args: { maxEvents: 10_000, maxMs: 30_000 }, + }); + const settled = pending.then( + () => "resolved" as const, + () => "rejected" as const + ); + await waitFor(async () => (await readEmitted(fixture.stubDir, 1)) >= 3); + const [firstPid] = await readStubPids(fixture.stubDir); + expect(alive(firstPid ?? 0)).toBe(true); + + await disconnected.close(); + expect(await settled).toBe("rejected"); + await waitFor(() => !alive(firstPid ?? 0)); + const emittedBeforeClose = await readEmitted(fixture.stubDir, 1); + expect(emittedBeforeClose).toBeGreaterThanOrEqual(3); + + const reconnected = await fixture.connect(); + const { isError, payload } = await callLogs({ + client: reconnected, + tool: "hack.project.logs.tail", + args: { maxEvents: 3, maxMs: 10_000 }, + }); + expect(isError).toBe(false); + expect(payload.data.cutoff).toEqual({ bound: "events", limit: 3 }); + expect(logMessages(payload.data.events)).toEqual([ + "inv-2-seq-0", + "inv-2-seq-1", + "inv-2-seq-2", + ]); + expect(payload.stdout).not.toContain("inv-1-"); + // The interrupted stream produced nothing after its session closed. + expect(await readEmitted(fixture.stubDir, 1)).toBe(emittedBeforeClose); +}, 30_000); + +test("a cancelled tail stops its backend and the same session's retry starts fresh", async () => { + const fixture = await startLogsFixture("sequenced"); + const client = await fixture.connect(); + const controller = new AbortController(); + const pending = callLogs({ + client, + tool: "hack.project.logs.tail", + args: { maxEvents: 10_000, maxMs: 30_000 }, + signal: controller.signal, + }); + const settled = pending.then( + () => "resolved" as const, + () => "rejected" as const + ); + await waitFor(async () => (await readEmitted(fixture.stubDir, 1)) >= 3); + const [firstPid] = await readStubPids(fixture.stubDir); + controller.abort(); + expect(await settled).toBe("rejected"); + await waitFor(() => !alive(firstPid ?? 0)); + + const retry = await callLogs({ + client, + tool: "hack.project.logs.tail", + args: { maxEvents: 2, maxMs: 10_000 }, + }); + expect(retry.payload.ok).toBe(true); + expect(logMessages(retry.payload.data.events)).toEqual([ + "inv-2-seq-0", + "inv-2-seq-1", + ]); +}, 30_000);