diff --git a/AGENTS.md b/AGENTS.md index a942f2355..ebe4931c9 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -900,6 +900,10 @@ Two naming layers — MCP (JSON wire format) and TypeScript (internal): `src/__tests__/runs-as-root.ts`. CI runs it as a normal user. To run these tests from a root shell, such as a cloud session, use `npm run test:as-nobody`; it takes the same arguments as `vitest run`. +- Vitest prints a test's console output, `src/logger.ts`'s lines included, + only when that test fails (`silent: "passed-only"`, with the log lines + routed to the console by `src/__tests__/helpers/route-log-lines-to-console.ts`). + To see a passing test's output, run `npm test -- --silent=false`. - Tests read as a behavioral spec: one focused `it()` per behavior, named so a failure identifies the regressed behavior without reading the body, and matching what is asserted. For every guard or invariant, diff --git a/src/__tests__/helpers/route-log-lines-to-console.ts b/src/__tests__/helpers/route-log-lines-to-console.ts new file mode 100644 index 000000000..f3eb1185d --- /dev/null +++ b/src/__tests__/helpers/route-log-lines-to-console.ts @@ -0,0 +1,58 @@ +/** + * Vitest setup file that keeps src/logger.ts's lines out of passing tests' output. + * - The logger writes each JSON line straight to process.stdout or + * process.stderr, which vitest prints for every test. + * - This wrapper sends those lines through console instead, so vitest files + * each line under the test that wrote it, and `silent: "passed-only"` prints + * the line only when that test fails. + * - A test that spies on process.stdout.write puts its spy in front of the + * wrapper, so the spy still sees every line it asserts on. + * - Under vitest's default isolation, each test file runs in its own process, + * so the wrappers last until that process exits and need no restore. + */ + +/** Every line src/logger.ts writes opens with its timestamp field. */ +const LOG_LINE_START = '{"timestamp":' + +type WriteCallback = (error?: Error | null) => void + +type StreamWrite = ( + chunk: Uint8Array | string, + encodingOrCallback?: BufferEncoding | WriteCallback, + callback?: WriteCallback, +) => boolean + +export const createLogLineRoutingWrite = ( + stream: Pick, + logToConsole: (line: string) => void, +): StreamWrite => { + const originalWrite = stream.write.bind(stream) + + return (chunk, encodingOrCallback, callback) => { + // src/logger.ts passes neither an encoding nor a callback, so a write that + // carries one is never a log line. logger.test.ts pins this write shape. + const isLogLine = + typeof chunk === "string" && + chunk.startsWith(LOG_LINE_START) && + !encodingOrCallback && + !callback + + if (isLogLine) { + // The logger's line ends in a newline, and console adds its own. + logToConsole(chunk.trimEnd()) + return true + } + + // The callback sits second or third in write's overloads, so each position + // needs its own call to type-check. Node handles both calls the same way. + if (typeof encodingOrCallback === "function") return originalWrite(chunk, encodingOrCallback) + return originalWrite(chunk, encodingOrCallback, callback) + } +} + +// vitest captures console per test, unlike process.stdout, and its console never +// writes to process.stdout, so a routed line cannot loop back through the wrapper. +// eslint-disable-next-line no-console +process.stdout.write = createLogLineRoutingWrite(process.stdout, (line) => console.log(line)) +// eslint-disable-next-line no-console +process.stderr.write = createLogLineRoutingWrite(process.stderr, (line) => console.error(line)) diff --git a/src/__tests__/logger.test.ts b/src/__tests__/logger.test.ts index 7344bad56..03b9d7db7 100644 --- a/src/__tests__/logger.test.ts +++ b/src/__tests__/logger.test.ts @@ -1523,3 +1523,25 @@ describe("logger child lazy props", () => { ]) }) }) + +// The test setup file helpers/route-log-lines-to-console.ts sends a write to +// the console only when it has this shape. A write of any other shape goes to +// the stream, so passing tests would print every log line again. +describe("console write shape", () => { + it("writes each line as one string that opens with its timestamp field, with no encoding or callback", () => { + const stdoutSpy = vi.spyOn(process.stdout, "write").mockImplementation(() => true) + const stderrSpy = vi.spyOn(process.stderr, "write").mockImplementation(() => true) + onTestFinished(() => { + stdoutSpy.mockRestore() + stderrSpy.mockRestore() + }) + + logger.info("shape probe info") + logger.error("shape probe error") + + expect(stdoutSpy).toHaveBeenCalledTimes(1) + expect(stdoutSpy).toHaveBeenCalledWith(expect.stringMatching(/^\{"timestamp":/)) + expect(stderrSpy).toHaveBeenCalledTimes(1) + expect(stderrSpy).toHaveBeenCalledWith(expect.stringMatching(/^\{"timestamp":/)) + }) +}) diff --git a/src/__tests__/route-log-lines-to-console.test.ts b/src/__tests__/route-log-lines-to-console.test.ts new file mode 100644 index 000000000..0b2da5faf --- /dev/null +++ b/src/__tests__/route-log-lines-to-console.test.ts @@ -0,0 +1,107 @@ +import { describe, expect, it, onTestFinished, vi } from "vitest" + +import { createLogLineRoutingWrite } from "./helpers/route-log-lines-to-console.js" + +type WriteCallback = (error?: Error | null) => void + +/** A line in the shape src/logger.ts writes, trailing newline included. */ +const LOG_LINE = '{"timestamp":"2026-11-12T21:00:00.000-05:00","level":"info","message":"probe"}\n' + +/** LOG_LINE as the console receives it. */ +const ROUTED_LOG_LINE = + '{"timestamp":"2026-11-12T21:00:00.000-05:00","level":"info","message":"probe"}' + +const writeCallback: WriteCallback = () => undefined + +const createRoutingWrite = () => { + // The stub returns false, which a real stream returns when the caller should + // wait, so a wrapper that returns true instead of the stream's result fails. + const streamWrite = vi.fn<(...writeArgs: unknown[]) => boolean>(() => false) + const logToConsole = vi.fn<(line: string) => void>() + const routingWrite = createLogLineRoutingWrite({ write: streamWrite }, logToConsole) + + return { streamWrite, logToConsole, routingWrite } +} + +describe("createLogLineRoutingWrite", () => { + it("sends a log line to the console without its trailing newline and never to the stream", () => { + const { streamWrite, logToConsole, routingWrite } = createRoutingWrite() + + expect(routingWrite(LOG_LINE)).toBe(true) + expect(logToConsole).toHaveBeenCalledTimes(1) + expect(logToConsole).toHaveBeenCalledWith(ROUTED_LOG_LINE) + expect(streamWrite).not.toHaveBeenCalled() + }) + + type PassThroughCase = { + label: string + chunk: Uint8Array | string + encodingOrCallback?: BufferEncoding | WriteCallback + callback?: WriteCallback + expectedStreamArgs: ReadonlyArray + } + + const passThroughCases: ReadonlyArray = [ + { + label: "text that does not open with a timestamp field", + chunk: "plain output\n", + expectedStreamArgs: ["plain output\n", undefined, undefined], + }, + { + label: "a log line written as bytes", + chunk: Buffer.from(LOG_LINE), + expectedStreamArgs: [Buffer.from(LOG_LINE), undefined, undefined], + }, + { + label: "a log line with an encoding", + chunk: LOG_LINE, + encodingOrCallback: "utf8", + expectedStreamArgs: [LOG_LINE, "utf8", undefined], + }, + { + label: "a log line with a callback in second place", + chunk: LOG_LINE, + encodingOrCallback: writeCallback, + expectedStreamArgs: [LOG_LINE, writeCallback], + }, + { + label: "a log line with an encoding and a callback", + chunk: LOG_LINE, + encodingOrCallback: "utf8", + callback: writeCallback, + expectedStreamArgs: [LOG_LINE, "utf8", writeCallback], + }, + ] + + it.each(passThroughCases)( + "passes $label to the stream and returns the stream's result", + ({ chunk, encodingOrCallback, callback, expectedStreamArgs }) => { + const { streamWrite, logToConsole, routingWrite } = createRoutingWrite() + + expect(routingWrite(chunk, encodingOrCallback, callback)).toBe(false) + expect(streamWrite).toHaveBeenCalledTimes(1) + expect(streamWrite).toHaveBeenCalledWith(...expectedStreamArgs) + expect(logToConsole).not.toHaveBeenCalled() + }, + ) +}) + +describe("the routing the setup file installs", () => { + const installedRoutingCases = [ + { label: "process.stdout to console.log", stream: process.stdout, consoleMethod: "log" }, + { label: "process.stderr to console.error", stream: process.stderr, consoleMethod: "error" }, + ] as const + + it.each(installedRoutingCases)( + "sends a log line written to $label", + ({ stream, consoleMethod }) => { + const consoleSpy = vi.spyOn(console, consoleMethod).mockImplementation(() => undefined) + onTestFinished(() => consoleSpy.mockRestore()) + + stream.write(LOG_LINE) + + expect(consoleSpy).toHaveBeenCalledTimes(1) + expect(consoleSpy).toHaveBeenCalledWith(ROUTED_LOG_LINE) + }, + ) +}) diff --git a/vitest.config.ts b/vitest.config.ts index 73542a0ad..6b5f6fd07 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -13,5 +13,10 @@ export default defineConfig({ // Tests that assert on real log lines must not inherit a developer's // LOG_LEVEL or LOG_DIR, which would hide those lines or write to a real log folder. env: { LOG_LEVEL: "info", LOG_DIR: "none" }, + // src/logger.ts writes thousands of lines across the suite, which would bury + // a run's failures. The setup file sends each line through console, and + // `silent: "passed-only"` prints a test's console output only when it fails. + setupFiles: ["src/__tests__/helpers/route-log-lines-to-console.ts"], + silent: "passed-only", }, })