From 0a574a7949059601beaa6412ce2582e42397f816 Mon Sep 17 00:00:00 2001 From: Matthew Dickinson Date: Thu, 24 Sep 2026 07:52:25 -0600 Subject: [PATCH 1/3] feat(sync): write a backend's own log lines to the worker log An MCP server that declares the `logging` capability sends its log as `notifications/message` on stdout. The stdio client read those lines and dropped them, because it only handled responses, so a backend's own account of a failure never reached the log. McpSession now hands each one to an `onLog` option. The level is mapped from MCP's eight onto debug/info/warn/error, `data` that is not a string is written as JSON, and the line is flattened to one line and capped at 2000 characters. A notification can arrive before the initialize reply. The provider passes the lines to a new optional `IndexRequest.log`, and the worker writes them as `[:] message`, to the log file and to the terminal echo that `sync`, `drain` and `once` already print. Two related fixes to the read loop: a message that has a `method` is never taken as a response, whatever id it carries, and a bare JSON value such as `null` on stdout no longer throws out of the data handler. --- src/index.ts | 2 + src/mcp.ts | 114 ++++++++++++++++- src/provider.ts | 22 ++++ src/providers/mcp-provider.ts | 23 +++- src/worker.ts | 5 + test/cli.test.ts | 40 ++++++ test/mcp.test.ts | 206 +++++++++++++++++++++++++++++- test/provider-backend-log.test.ts | 119 +++++++++++++++++ test/worker.test.ts | 30 ++++- 9 files changed, 552 insertions(+), 9 deletions(-) create mode 100644 test/provider-backend-log.test.ts diff --git a/src/index.ts b/src/index.ts index f342953..735e856 100644 --- a/src/index.ts +++ b/src/index.ts @@ -5,6 +5,8 @@ export { shouldCoalesce } from "./coalesce.js"; export type { CoalesceDecision } from "./coalesce.js"; export { ProviderRegistry } from "./provider.js"; export type { + BackendLogLevel, + BackendLogLine, IndexOutcome, IndexProvider, IndexReason, diff --git a/src/mcp.ts b/src/mcp.ts index 82e5671..f6d36f6 100644 --- a/src/mcp.ts +++ b/src/mcp.ts @@ -22,6 +22,7 @@ */ import { spawn, type ChildProcessWithoutNullStreams } from "node:child_process"; +import type { BackendLogLevel } from "./provider.js"; import { VERSION } from "./version.js"; export interface McpToolResult { @@ -154,6 +155,88 @@ export interface McpClientOptions { timeoutMs?: number; /** See {@link DEFAULT_KILL_AFTER_MS}. */ killAfterMs?: number; + /** + * Receives the backend's log lines, which are otherwise dropped. + * + * A server that declares the `logging` capability sends its log as + * `notifications/message` on stdout — the one channel a stdio client reads — + * and it may do so at any point: before its `initialize` reply, between + * calls, while it shuts down. No `logging/setLevel` is ever sent, so what + * arrives is whatever the backend's own configured level lets through. + * + * Must not throw. If it does, that line is lost and the session carries on. + */ + onLog?: (message: McpLogMessage) => void; +} + +/** A log line a backend sent as an MCP `notifications/message`. */ +export interface McpLogMessage { + level: BackendLogLevel; + /** The backend's name for the logger that wrote it, when it gave one. */ + logger?: string; + /** The message as one bounded line; see {@link parseLogMessage}. */ + text: string; +} + +/** + * MCP's levels are syslog's eight (RFC 5424), finer than anyone reading a sync + * log acts on: `notice` is information, and `critical`, `alert` and + * `emergency` are errors. + */ +const MCP_LOG_LEVELS: ReadonlyMap = new Map([ + ["debug", "debug"], + ["info", "info"], + ["notice", "info"], + ["warning", "warn"], + ["error", "error"], + ["critical", "error"], + ["alert", "error"], + ["emergency", "error"], +]); + +/** + * Longest backend log line kept, in characters. Room for a message followed by + * the JSON context of a storage error; not room for a backend that dumps a + * whole payload into one line to flood a log that is rotated by size. + */ +export const MAX_LOG_LINE = 2_000; + +/** Longest logger name kept. A name, not a message. */ +const MAX_LOGGER_NAME = 100; + +/** + * One line, at most `max` characters. The log is read line by line, and a + * continuation line would carry no timestamp and no label. A cut says how much + * it cut rather than cutting silently. + */ +function oneLine(text: string, max: number): string { + const flat = text.trim().replace(/\s*[\r\n]+\s*/g, " | "); + if (flat.length <= max) return flat; + // Never end on the first half of a surrogate pair. + const cut = /[\uD800-\uDBFF]/.test(flat.charAt(max - 1)) ? max - 1 : max; + return `${flat.slice(0, cut)}… [${flat.length - cut} more chars]`; +} + +/** + * Read a `notifications/message`'s params, or null when there is nothing to log. + * + * `data` may be any JSON value. A string is kept as written and anything else + * is written as JSON. A level outside MCP's eight is logged as info rather than + * dropped: the line is still worth seeing, and guessing it more severe would + * cry wolf. Never throws, whatever the backend sent. + */ +export function parseLogMessage(params: unknown): McpLogMessage | null { + if (typeof params !== "object" || params === null || Array.isArray(params)) return null; + const { level, logger, data } = params as Record; + if (data === undefined) return null; + const text = oneLine(typeof data === "string" ? data : JSON.stringify(data), MAX_LOG_LINE); + if (!text) return null; + const name = typeof logger === "string" ? oneLine(logger, MAX_LOGGER_NAME) : ""; + return { + level: (typeof level === "string" && MCP_LOG_LEVELS.get(level.toLowerCase())) || "info", + ...(name ? { logger: name } : {}), + text, + }; } interface JsonRpcMessage { @@ -309,13 +392,34 @@ export class McpSession { } catch { continue; // Servers may log non-JSON to stdout; ignore rather than die. } - if (typeof msg.id === "number") { - const resolve = this.pending.get(msg.id); - if (resolve) { - this.pending.delete(msg.id); - resolve(msg); + // `null` or `42` is JSON but no message, and reading a field of null throws. + if (typeof msg !== "object" || msg === null) continue; + if (msg.method === undefined) { + if (typeof msg.id === "number") { + const resolve = this.pending.get(msg.id); + if (resolve) { + this.pending.delete(msg.id); + resolve(msg); + } } + } else if (msg.method === "notifications/message") { + this.onLogMessage(msg.params); } + // Anything else with a method — another notification, or a request from + // the server — is ignored. It is never a response, whatever id it carries: + // taking one for the reply to a pending call would answer that call with + // nothing. + } + } + + private onLogMessage(params: unknown): void { + const onLog = this.opts.onLog; + if (!onLog) return; + try { + const message = parseLogMessage(params); + if (message) onLog(message); + } catch { + // A log line is never worth a response: this loop is what delivers them. } } diff --git a/src/provider.ts b/src/provider.ts index bbde2c9..2ed221f 100644 --- a/src/provider.ts +++ b/src/provider.ts @@ -14,6 +14,20 @@ /** Why an index ran, which providers may use to pick a cheaper path. */ export type IndexReason = "hook" | "manual" | "retry"; +/** + * How much one of a backend's own log lines matters. Backends grade more + * finely — MCP has eight levels — and a provider coarsens to these four, the + * distinctions a reader of the log actually acts on. + */ +export type BackendLogLevel = "debug" | "info" | "warn" | "error"; + +/** One line from a backend's own log. */ +export interface BackendLogLine { + level: BackendLogLevel; + /** A single line, already bounded in length: the log is read line by line. */ + message: string; +} + export interface IndexRequest { repoPath: string; /** Force complete re-discovery rather than an incremental update. */ @@ -24,6 +38,14 @@ export interface IndexRequest { * the provider's own session timeout to stop a hung backend. */ signal?: AbortSignal; + /** + * Takes whatever the backend logs while this index runs. The worker writes + * each line to its own log, labelled with the provider's name and the level, + * because a backend's account of a failure — a storage error's reason, a + * warning about one file — is usually more specific than its tool's reply. + * A provider whose backend reports nothing ignores it. + */ + log?: (line: BackendLogLine) => void; } export interface IndexOutcome { diff --git a/src/providers/mcp-provider.ts b/src/providers/mcp-provider.ts index d408539..31319bc 100644 --- a/src/providers/mcp-provider.ts +++ b/src/providers/mcp-provider.ts @@ -39,10 +39,12 @@ import { DEFAULT_TIMEOUT_MS, withMcp, type McpClientOptions, + type McpLogMessage, type McpSession, type McpToolResult, } from "../mcp.js"; import type { + BackendLogLine, IndexOutcome, IndexProvider, IndexRequest, @@ -390,8 +392,14 @@ export class McpIndexProvider implements IndexProvider { * * Set after process.env so an ambient value cannot re-enable it, and before * cfg.env so an operator still can. + * + * `log`, when given, takes the backend's own log lines for the session. */ - private sessionOpts(repoPath: string | undefined, timeoutMs: number | undefined): McpClientOptions { + private sessionOpts( + repoPath: string | undefined, + timeoutMs: number | undefined, + log?: IndexRequest["log"], + ): McpClientOptions { return { command: this.cfg.command, args: this.cfg.args, @@ -399,9 +407,20 @@ export class McpIndexProvider implements IndexProvider { env: { ...process.env, SOCRATICODE_AUTO_RESUME: "off", ...this.cfg.env }, ...(timeoutMs === undefined ? {} : { timeoutMs }), ...(this.cfg.killAfterMs === undefined ? {} : { killAfterMs: this.cfg.killAfterMs }), + ...(log ? { onLog: (m: McpLogMessage) => log(this.logLine(m)) } : {}), }; } + /** + * A backend log message as a line for the worker log, which labels it with + * this provider's name. The backend's own logger name is kept only when it + * says something that label does not. + */ + private logLine(m: McpLogMessage): BackendLogLine { + const from = m.logger && m.logger.toLowerCase() !== this.name.toLowerCase() ? `${m.logger}: ` : ""; + return { level: m.level, message: `${from}${m.text}` }; + } + private async call( repoPath: string, tool: string, @@ -420,7 +439,7 @@ export class McpIndexProvider implements IndexProvider { // finished. Not two: a backend's progress state is per-process, so a // second child sees a backend that has never indexed anything. res = await withMcp( - this.sessionOpts(req.repoPath, this.cfg.timeoutMs), + this.sessionOpts(req.repoPath, this.cfg.timeoutMs, req.log), async (session) => { used = session; const started = await session.callTool(tool, this.repoArgs(req.repoPath)); diff --git a/src/worker.ts b/src/worker.ts index 5b661fc..77c90a1 100644 --- a/src/worker.ts +++ b/src/worker.ts @@ -277,6 +277,7 @@ export class Worker { ); const marker = markerFile(this.opts.paths.processing, job.repoPath); + const backend = provider.name; let result: IndexOutcome; try { try { @@ -288,6 +289,10 @@ export class Worker { repoPath: job.repoPath, full: job.full, reason: job.attempts > 0 ? "retry" : job.hook === "manual" ? "manual" : "hook", + // Everything the backend logs, as it sent it: the backend filters by its + // own configured level, and this log has no level of its own to add a + // second, disagreeing filter. `[name:level]` keeps it greppable both ways. + log: (line) => logger.tag(`${backend}:${line.level}`, line.message), }); } finally { rmSync(marker, { force: true }); diff --git a/test/cli.test.ts b/test/cli.test.ts index 2cd713c..c8d72e0 100644 --- a/test/cli.test.ts +++ b/test/cli.test.ts @@ -590,6 +590,46 @@ describe("sync", () => { expect(second.code).toBe(0); }); + it("prints what the backend logs and keeps it in the log", () => { + // A backend declaring MCP logging sends its log lines as notifications, + // some before it has answered initialize. `sync` is run by hand and from + // scripts whose output is captured, and `drain` from a scheduler, so the + // lines belong on stdout and in the log alike. + const file = path.join(home, "logging-server.mjs"); + writeFileSync( + file, + `const send=(o)=>process.stdout.write(JSON.stringify(o)+"\\n"); + const log=(level,data)=>send({jsonrpc:"2.0",method:"notifications/message",params:{level,logger:"stub",data}}); + log("warning","EXTRA_MAP: ignored invalid entries"); + let buf="";process.stdin.on("data",c=>{buf+=c;let n;while((n=buf.indexOf("\\n"))!==-1){const l=buf.slice(0,n).trim();buf=buf.slice(n+1);if(!l)continue;const m=JSON.parse(l); + if(m.method==="initialize")send({jsonrpc:"2.0",id:m.id,result:{}}); + if(m.method==="tools/call"){log("info",{indexed:1});send({jsonrpc:"2.0",id:m.id,result:{content:[{type:"text",text:"Updated project index"}]}});}}});`, + "utf8", + ); + writeConfig({ + root: home, + providers: [ + { name: "stub", command: process.execPath, args: [file], tools: { update: "u" }, detectFiles: [".stub.json"] }, + ], + }); + const dir = path.join(home, "chatty"); + mkdirSync(dir, { recursive: true }); + git(dir, "init", "-q", "-b", "main"); + git(dir, "config", "user.email", "t@example.com"); + git(dir, "config", "user.name", "Test"); + writeFileSync(path.join(dir, ".stub.json"), '{"projectId":"chatty"}\n', "utf8"); + git(dir, "add", "-A"); + git(dir, "commit", "-q", "-m", "init"); + + const r = cli(["sync", dir]); + expect(r.code).toBe(0); + const log = readFileSync(path.join(state, "sync.log"), "utf8"); + for (const text of [r.out, log]) { + expect(text).toMatch(/ \[stub:warn\] EXTRA_MAP: ignored invalid entries\n/); + expect(text).toMatch(/ \[stub:info\] \{"indexed":1\}\n/); + } + }); + /** * A backend whose first `failures` tool calls report an error, recording each * call and each exit with its pid and time. State lives in a file because every diff --git a/test/mcp.test.ts b/test/mcp.test.ts index dc81ddf..9ddc361 100644 --- a/test/mcp.test.ts +++ b/test/mcp.test.ts @@ -4,7 +4,7 @@ import { tmpdir } from "node:os"; import path from "node:path"; import { afterEach, beforeEach, describe, expect, it } from "vitest"; import { isAlive } from "../src/lock.js"; -import { McpSession, withMcp } from "../src/mcp.js"; +import { MAX_LOG_LINE, McpSession, parseLogMessage, withMcp, type McpLogMessage } from "../src/mcp.js"; let dir: string; beforeEach(() => { @@ -177,6 +177,210 @@ describe("fast failure", () => { }); }); +describe("backend log messages", () => { + // A server declaring the `logging` capability sends its log on stdout as + // `notifications/message`. These used to be read and thrown away, and with + // them the backend's own account of why a sync failed. + + /** A JS expression, for a stub, that sends one log notification. */ + const log = (params: unknown): string => + `send({ jsonrpc: "2.0", method: "notifications/message", params: ${JSON.stringify(params)} });`; + + /** A stub that runs `beforeReply` inside its tools/call handler, then answers "ok". */ + const loggingDuringCall = (beforeReply: string): string => + stubServer(` +function handle(msg) { + if (msg.method === "initialize") return send({ jsonrpc: "2.0", id: msg.id, result: {} }); + if (msg.method === "tools/call") { + ${beforeReply} + return send({ jsonrpc: "2.0", id: msg.id, result: { content: [{ type: "text", text: "ok" }] } }); + } +} +`); + + /** Everything one session logs, and the tool call's result. */ + async function callLogging(server: string): Promise<{ got: McpLogMessage[]; text: string }> { + const got: McpLogMessage[] = []; + const res = await withMcp( + { command: NODE, args: [server], cwd: dir, timeoutMs: 15_000, onLog: (m) => got.push(m) }, + (s) => s.callTool("x", {}), + ); + return { got, text: res.text }; + } + + it("delivers a line sent before the initialize reply, and the handshake still completes", async () => { + // A backend logs while it starts, before it has answered anything: + // SocratiCode 1.15.0 sends two lines ahead of its initialize reply. + const server = stubServer(` +${log({ level: "warning", logger: "stub", data: "config entry ignored" })} +function handle(msg) { + if (msg.method === "initialize") { + ${log({ level: "info", data: "connected" })} + return send({ jsonrpc: "2.0", id: msg.id, result: {} }); + } + if (msg.method === "tools/call") { + ${log({ level: "error", data: "storage said no" })} + return send({ jsonrpc: "2.0", id: msg.id, result: { content: [{ type: "text", text: "ok" }] } }); + } +} +`); + const got: McpLogMessage[] = []; + const session = new McpSession({ command: NODE, args: [server], cwd: dir, onLog: (m) => got.push(m) }); + try { + await session.open(); + expect(got).toEqual([ + { level: "warn", logger: "stub", text: "config entry ignored" }, + { level: "info", text: "connected" }, + ]); + const res = await session.callTool("x", {}); + expect(res).toEqual({ isError: false, text: "ok" }); + expect(got.at(-1)).toEqual({ level: "error", text: "storage said no" }); + } finally { + await session.close(); + } + }); + + it("maps MCP's eight levels onto debug, info, warn and error", async () => { + const sent = ["debug", "info", "notice", "warning", "error", "critical", "alert", "emergency"]; + const { got } = await callLogging(loggingDuringCall(sent.map((level) => log({ level, data: level })).join("\n"))); + expect(got.map((m) => [m.text, m.level])).toEqual([ + ["debug", "debug"], + ["info", "info"], + ["notice", "info"], + ["warning", "warn"], + ["error", "error"], + ["critical", "error"], + ["alert", "error"], + ["emergency", "error"], + ]); + }); + + it("logs a line whose level it does not recognise as info rather than dropping it", async () => { + const { got } = await callLogging( + loggingDuringCall( + [ + log({ level: "WARNING", data: "shouted" }), + log({ level: "verbose", data: "unknown level" }), + log({ data: "no level at all" }), + log({ level: { nested: true }, data: "level is not a string" }), + ].join("\n"), + ), + ); + expect(got.map((m) => [m.text, m.level])).toEqual([ + ["shouted", "warn"], + ["unknown level", "info"], + ["no level at all", "info"], + ["level is not a string", "info"], + ]); + }); + + it("writes data that is not a string as JSON, on one line", async () => { + // `data` may be any JSON value; the log is read line by line. + const { got } = await callLogging( + loggingDuringCall( + [ + log({ level: "error", data: { error: "upsert failed", status: 500 } }), + log({ level: "info", data: 42 }), + log({ level: "info", data: null }), + log({ level: "info", data: false }), + log({ level: "info", data: ["a", 1] }), + log({ level: "error", data: "first line\n at frame one\r\n at frame two\n" }), + ].join("\n"), + ), + ); + expect(got.map((m) => m.text)).toEqual([ + '{"error":"upsert failed","status":500}', + "42", + "null", + "false", + '["a",1]', + "first line | at frame one | at frame two", + ]); + }); + + it("caps an absurdly long line, saying how much it cut", async () => { + const { got } = await callLogging(loggingDuringCall(log({ level: "info", data: "x".repeat(MAX_LOG_LINE + 500) }))); + expect(got).toHaveLength(1); + expect(got[0]!.text).toBe(`${"x".repeat(MAX_LOG_LINE)}… [500 more chars]`); + }); + + it("carries on answering calls whatever arrives on stdout between them", async () => { + // Nothing a backend writes may cost a response: not a malformed + // notification, not a bare JSON value, and not a notification that carries + // the id of the very call waiting for a reply. + const { got, text } = await callLogging( + loggingDuringCall(` +process.stdout.write("null\\n42\\n\\"a string\\"\\n[1,2]\\n"); +send({ jsonrpc: "2.0", method: "notifications/message" }); +send({ jsonrpc: "2.0", method: "notifications/message", params: "just text" }); +send({ jsonrpc: "2.0", method: "notifications/message", params: [1, 2] }); +send({ jsonrpc: "2.0", method: "notifications/message", params: { level: "error" } }); +send({ jsonrpc: "2.0", method: "notifications/message", params: { level: "info", data: " " } }); +send({ jsonrpc: "2.0", id: msg.id, method: "notifications/message", params: { level: "warning", data: "has an id" } }); +send({ jsonrpc: "2.0", id: msg.id, method: "roots/list" }); +send({ jsonrpc: "2.0", method: "notifications/progress", params: { progressToken: 1, progress: 5 } }); +${log({ level: "info", data: "still logging" })}`), + ); + expect(text).toBe("ok"); + expect(got).toEqual([ + { level: "warn", text: "has an id" }, + { level: "info", text: "still logging" }, + ]); + }); + + it("survives a log sink that throws", async () => { + const server = loggingDuringCall(`${log({ level: "info", data: "one" })}\n${log({ level: "info", data: "two" })}`); + const seen: string[] = []; + const res = await withMcp( + { + command: NODE, + args: [server], + cwd: dir, + timeoutMs: 15_000, + onLog: (m) => { + seen.push(m.text); + throw new Error("sink is broken"); + }, + }, + (s) => s.callTool("x", {}), + ); + expect(res).toEqual({ isError: false, text: "ok" }); + expect(seen).toEqual(["one", "two"]); + }); + + it("drops the lines when nobody asked for them, as before", async () => { + const server = loggingDuringCall(log({ level: "error", data: "unheard" })); + const res = await withMcp({ command: NODE, args: [server], cwd: dir, timeoutMs: 15_000 }, (s) => s.callTool("x", {})); + expect(res).toEqual({ isError: false, text: "ok" }); + }); +}); + +describe("parseLogMessage", () => { + it("is null for params that carry nothing to log", () => { + for (const params of [undefined, null, "text", 3, [1], {}, { level: "info" }, { data: "" }, { data: " \n " }]) { + expect(parseLogMessage(params)).toBeNull(); + } + }); + + it("keeps the logger's name, on one bounded line", () => { + expect(parseLogMessage({ level: "info", logger: "indexer", data: "hi" })).toEqual({ + level: "info", + logger: "indexer", + text: "hi", + }); + expect(parseLogMessage({ logger: "a\nb", data: "hi" })?.logger).toBe("a | b"); + expect(parseLogMessage({ logger: "n".repeat(500), data: "hi" })?.logger).toMatch(/^n{100}… \[400 more chars]$/); + expect(parseLogMessage({ logger: 7, data: "hi" })).toEqual({ level: "info", text: "hi" }); + }); + + it("never cuts a character in half", () => { + // "😀" is two UTF-16 units; a cut between them leaves a lone surrogate, + // which is written to the log as a replacement character. + const text = parseLogMessage({ data: `${"x".repeat(MAX_LOG_LINE - 1)}😀tail` })!.text; + expect(text).toBe(`${"x".repeat(MAX_LOG_LINE - 1)}… [6 more chars]`); + }); +}); + describe("failure kinds", () => { // Callers that wait on a backend retry a tool's own error but not a dead or // refusing session, so the two must be told apart. diff --git a/test/provider-backend-log.test.ts b/test/provider-backend-log.test.ts new file mode 100644 index 0000000..f67ba04 --- /dev/null +++ b/test/provider-backend-log.test.ts @@ -0,0 +1,119 @@ +/** + * A backend's own log, carried through an index run. + * + * A tool's reply to a failed index is often just "failed"; the reason — a + * storage error, a file it could not read — is in what the backend logged on + * the way. An MCP backend sends that as `notifications/message`, and the + * provider hands each line to the request's `log`, for the worker log. + */ +import { chmodSync, mkdtempSync, rmSync, writeFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import path from "node:path"; +import { afterEach, beforeEach, describe, expect, it } from "vitest"; +import type { BackendLogLine } from "../src/provider.js"; +import { McpIndexProvider } from "../src/providers/mcp-provider.js"; + +let dir: string; +beforeEach(() => { + dir = mkdtempSync(path.join(tmpdir(), "codeindex-backend-log-")); +}); +afterEach(() => rmSync(dir, { recursive: true, force: true })); + +/** + * A backend that logs as it starts, again during `update`, and once more as it + * shuts down, then answers `update` with `reply` (an error when `failing`). + */ +function loggingBackend(opts: { reply: string; failing: boolean }): string { + const file = path.join(dir, "server.mjs"); + writeFileSync( + file, + ` +const send = (o, done) => process.stdout.write(JSON.stringify(o) + "\\n", done); +const log = (params, done) => send({ jsonrpc: "2.0", method: "notifications/message", params }, done); +log({ level: "info", logger: "stub", data: "starting" }); +// Asked to stop — by end of input or SIGTERM, which arrive together — it logs +// once more, as a backend finishing its shutdown does, and exits once written. +let stopping = false; +const stop = () => { + if (stopping) return; + stopping = true; + log({ level: "info", logger: "stub", data: "shutting down" }, () => process.exit(0)); +}; +process.stdin.on("end", stop); +process.on("SIGTERM", stop); +let buf = ""; +process.stdin.on("data", (c) => { + buf += c; + let n; + while ((n = buf.indexOf("\\n")) !== -1) { + const line = buf.slice(0, n).trim(); + buf = buf.slice(n + 1); + if (!line) continue; + const m = JSON.parse(line); + if (m.method === "initialize") send({ jsonrpc: "2.0", id: m.id, result: {} }); + if (m.method === "tools/call") { + log({ level: "error", logger: "store", data: { error: "upsert rejected", status: 400 } }); + send({ jsonrpc: "2.0", id: m.id, result: { isError: ${opts.failing}, content: [{ type: "text", text: ${JSON.stringify(opts.reply)} }] } }); + } + } +}); +`, + "utf8", + ); + chmodSync(file, 0o755); + return file; +} + +function providerFor(server: string): McpIndexProvider { + return new McpIndexProvider({ + name: "stub", + command: process.execPath, + args: [server], + tools: { update: "u" }, + timeoutMs: 15_000, + }); +} + +describe("a backend's log during an index run", () => { + it("reaches the request's log, from start-up to shutdown", async () => { + const lines: BackendLogLine[] = []; + const out = await providerFor(loggingBackend({ reply: "Added: 1", failing: false })).index({ + repoPath: dir, + full: false, + reason: "manual", + log: (l) => lines.push(l), + }); + + expect(out.status).toBe("ok"); + expect(lines).toEqual([ + // Its logger is the provider's own name, which the label already says. + { level: "info", message: "starting" }, + // A logger the label does not name is kept. + { level: "error", message: 'store: {"error":"upsert rejected","status":400}' }, + // `close()` waits for the backend to exit, so its last words arrive too. + { level: "info", message: "shutting down" }, + ]); + }); + + it("carries the reason a failed run gives only in its log", async () => { + const lines: BackendLogLine[] = []; + const out = await providerFor(loggingBackend({ reply: "Indexing failed", failing: true })).index({ + repoPath: dir, + full: false, + reason: "manual", + log: (l) => lines.push(l), + }); + + expect(out).toMatchObject({ status: "failed", error: "Indexing failed" }); + expect(lines.map((l) => l.message)).toContain('store: {"error":"upsert rejected","status":400}'); + }); + + it("runs as before when the caller takes no log", async () => { + const out = await providerFor(loggingBackend({ reply: "Added: 1", failing: false })).index({ + repoPath: dir, + full: false, + reason: "manual", + }); + expect(out.status).toBe("ok"); + }); +}); diff --git a/test/worker.test.ts b/test/worker.test.ts index f043867..1093101 100644 --- a/test/worker.test.ts +++ b/test/worker.test.ts @@ -2,7 +2,7 @@ import { mkdirSync, mkdtempSync, readdirSync, readFileSync, rmSync, writeFileSyn import { tmpdir } from "node:os"; import path from "node:path"; import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; -import { silentLogger } from "../src/logger.js"; +import { Logger, silentLogger } from "../src/logger.js"; import { resolvePaths } from "../src/paths.js"; import { ProviderRegistry, type IndexOutcome, type IndexProvider } from "../src/provider.js"; import { Queue, jobKey, nowIso } from "../src/queue.js"; @@ -173,6 +173,34 @@ describe("Worker.runJob", () => { }); expect((await w.runJob(enqueue())).outcome).toBe("indexed"); }); + + it("writes the backend's own log lines to the log, labelled with provider and level", async () => { + // The reason a run failed is often only in what the backend logged. + const provider: IndexProvider = { + ...fakeProvider({ status: "failed", summary: "", error: "Indexing failed" }, "backend"), + index: async (req) => { + req.log?.({ level: "info", message: "indexing 3 files" }); + req.log?.({ level: "error", message: 'upsert rejected {"status":400}' }); + return { status: "failed", summary: "", error: "Indexing failed" }; + }, + }; + const paths = resolvePaths(state); + const w = new Worker({ + paths, + registry: new ProviderRegistry().register(provider), + logger: new Logger(paths.log), + maxAttempts: 1, + sleep: async () => {}, + }); + await w.runJob(enqueue()); + + const lines = readFileSync(paths.log, "utf8").split("\n"); + const at = (pattern: RegExp): number => lines.findIndex((l) => pattern.test(l)); + expect(at(/ \[start\] /)).toBeGreaterThanOrEqual(0); + expect(at(/ \[backend:info\] indexing 3 files$/)).toBeGreaterThan(at(/ \[start\] /)); + expect(at(/ \[backend:error\] upsert rejected \{"status":400\}$/)).toBeGreaterThan(at(/ \[backend:info\] /)); + expect(at(/ \[give-up\] .*Indexing failed/)).toBeGreaterThan(at(/ \[backend:error\] /)); + }); }); describe("Worker.run", () => { From 4361510d91c7683098294fa9a2d57530d7b0dc0b Mon Sep 17 00:00:00 2001 From: Matthew Dickinson Date: Thu, 24 Sep 2026 08:02:09 -0600 Subject: [PATCH 2/3] docs: say where a backend's log lines go and how to quiet them --- README.md | 4 +++- docs/extending.md | 23 +++++++++++++++++++++++ docs/socraticode.md | 16 ++++++++++++++++ 3 files changed, 42 insertions(+), 1 deletion(-) diff --git a/README.md b/README.md index 8861e53..263bd81 100644 --- a/README.md +++ b/README.md @@ -143,7 +143,9 @@ in the worker, the abstraction has leaked. root would mean a tree walk on every commit.) Add a directory to `excludePaths` when a new tool appears; no release needed. - **The log is the diagnostic.** Append-only, rotated not truncated, and writing - to it never throws. + to it never throws. It also carries whatever the backend logs during an index + run (MCP `notifications/message`), as `[:]` lines, since a + backend's own account of a failure is usually more specific than its reply. - **`verify` is the one deliberate exception.** Every other command drives a backend through the MCP tools it declares. Integrity has no such tool to call — "which files does this index claim, and which have content?" is answerable diff --git a/docs/extending.md b/docs/extending.md index 4a67abe..698b855 100644 --- a/docs/extending.md +++ b/docs/extending.md @@ -183,6 +183,23 @@ advice, built from your `detectFiles`. invisible to the indexer. If your backend needs configuration, it goes here or in a file the hook path reads directly — never in a shell profile. +**Your backend's log lands in the worker log.** A server that declares the MCP +`logging` capability sends its log lines as `notifications/message`, and every +one it sends during an index run is written to the log, and to the output of +`sync`, `drain` and `once`, as `[:] `. MCP's eight levels +become four: `debug`; `info` (and `notice`); `warn`; `error` (and `critical`, +`alert`, `emergency`). A level it does not recognise is logged as `info`. Data +that is not a string is written as JSON, line breaks become ` | `, and a line is +capped at 2,000 characters, with a note of how much was cut. The backend's +`logger` name is added in front of the message when it differs from the +provider's `name`. + +Nothing is filtered here: codeindex-sync has no verbosity setting of its own, so +the backend's configured log level decides what arrives, and no +`logging/setLevel` is sent to override it. Lines can arrive at any point in a +session, including before the backend answers `initialize`. Only index runs are +logged, so `list`, `doctor` and `cleanup` drop them as before. + ### One thing config cannot describe: integrity `codeindex-sync verify` is the single command that does not go through the @@ -233,6 +250,12 @@ Three rules, each learned from a production failure: everything else is broken. Return `ok: false` with a `remedy` instead. - **Distinguish `busy` from `failed`.** See above. +If your backend keeps a log of its own, pass it on through `req.log`, one line +at a time: `req.log?.({ level: "warn", message: "…" })`, where `level` is +`debug`, `info`, `warn` or `error`. The worker writes it as +`[:] `. Keep each message to one line; the log is read +line by line. + --- ## 2. Add a git-hook handler diff --git a/docs/socraticode.md b/docs/socraticode.md index f66e0db..264a9c6 100644 --- a/docs/socraticode.md +++ b/docs/socraticode.md @@ -426,6 +426,22 @@ reindex clears it: `codeindex-sync sync --full`. or at once for a run whose SocratiCode process had to be killed. `codeindex-sync status` shows them and the last error; `codeindex-sync retry` requeues them, a full reindex still full. +**Why did it fail? Read the `[socraticode:…]` lines.** From 1.15.0, SocratiCode +sends its own log over MCP, and codeindex-sync writes each line to its log and to +the output of `sync`, `drain` and `once`, labelled with the provider's `name` and +the level: + +``` +2026-09-24T13:59:48Z [socraticode:warn] EXTENSION_LANGUAGE_MAP: ignored invalid entries. … {"ignored":[".foo:nolanguage"]} +``` + +The detail behind a one-line `failed —`, such as a storage error's reason or a +warning about one file, is often only there. What arrives is SocratiCode's +choice, set by `SOCRATICODE_LOG_LEVEL` in the provider's `env` block (default +`info`). `warn` keeps only warnings and errors, for when a large reindex's info +lines crowd a log that rotates at 2 MB (`logMaxBytes`), keeping one previous +file as `sync.log.1`. + **`sync` pauses for up to a minute after a failure.** Before it retries, codeindex-sync waits for the previous SocratiCode process to exit, and SocratiCode lets its in-flight batch finish first — for up to 60 seconds. A retry started From 9ff5b976eef43a7f5aacb9507805104d54a7da2d Mon Sep 17 00:00:00 2001 From: Matthew Dickinson Date: Thu, 24 Sep 2026 08:30:12 -0600 Subject: [PATCH 3/3] test(mcp): wait for init to reap the backend behind a non-exec shell The shell dies before its server, so the server is re-parented and reaped by init on init's schedule. Until then its pid still answers `kill(pid, 0)`, and the test's last assertion failed on Linux runners now and then, on main as well as on branches. Poll for up to a second first, as the forwarding-launcher test beside it already does. --- test/mcp.test.ts | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/test/mcp.test.ts b/test/mcp.test.ts index 9ddc361..cf8a790 100644 --- a/test/mcp.test.ts +++ b/test/mcp.test.ts @@ -560,7 +560,11 @@ child.on("exit", (code) => process.exit(code ?? 0)); expect(Date.now() - t0).toBeGreaterThanOrEqual(600); expect(Date.now() - t0).toBeLessThan(5_000); expect(session.forcedKill).toBe(false); - expect(isAlive(Number(readFileSync(pidFile, "utf8")))).toBe(false); + // Gone, but the shell's orphan is init's to reap, not ours: until it is, + // its pid still answers a signal 0. + const backend = Number(readFileSync(pidFile, "utf8")); + for (let i = 0; i < 50 && isAlive(backend); i++) await new Promise((r) => setTimeout(r, 20)); + expect(isAlive(backend)).toBe(false); }); it("signals a backend behind a forwarding launcher once, so its graceful shutdown runs", async () => {