diff --git a/extensions/pi/README.md b/extensions/pi/README.md index 6a2eca7..1c7898a 100644 --- a/extensions/pi/README.md +++ b/extensions/pi/README.md @@ -423,6 +423,9 @@ one — the long-lived server is only killed when a request genuinely stalls. - `MEMPALACE_MCP_TIMEOUT_MS` — tool-call/request timeout. Default `60000`. Kept short on purpose: a *query* taking this long is genuinely wedged. + The one call that is not a query — the feed's `mempalace_mine` — passes its + own deadline (`MEMPALACE_FEED_MINE_TIMEOUT_MS`) down to the transport per + call, so this default does not apply to it (since 2026-09-18; see below). - `MEMPALACE_MCP_INIT_TIMEOUT_MS` — `initialize` + `tools/list` handshake timeout. Default `300000`. Deliberately generous: a genuine first cold-open over virtiofs can legitimately take minutes, and killing a @@ -489,6 +492,26 @@ exceeded five minutes. Check palace size and whether another writer (a host-side feeder, a scheduled `mine`) is holding the write lock, rather than raising the timeout again. +### `feed (tick) failed: mempalace remote request 'tools/call' failed: timed out after 60000ms` + +Same event, different deadline — and the same reassurance: **nothing has been +lost**, the mine continues server-side. + +This is what the previous message turned into after the 2026-09 change, and +it exposed that the change was incomplete. The feed's five-minute deadline was +only *raced* against the call; `callTool()` had no way to carry it, so the +transport's generic per-request timeout (`MEMPALACE_MCP_TIMEOUT_MS`, 60 s) +fired first on every honest 60 s+ mine, and the 300 s was unreachable. On the +stdio transport this was worse than noise: a per-request timeout there kills the +server child, so the mine really was aborted at 60 s. + +Fixed 2026-09-18: `callTool(name, args, { timeoutMs })` passes a per-call +deadline to both transports and the feed uses it for the mine. +`scripts/test-mcp-call-timeout.sh` pins the contract (a plain call still honours +the short default; the override is honoured and is itself a deadline). Seeing +this message on a fixed build means a mine exceeded *five* minutes — treat it as +the previous section says. + ## The `Type.Unsafe` gotcha Earlier versions of this extension registered every MCP tool with diff --git a/extensions/pi/mempalace.ts b/extensions/pi/mempalace.ts index 58d699d..5e21833 100644 --- a/extensions/pi/mempalace.ts +++ b/extensions/pi/mempalace.ts @@ -67,7 +67,9 @@ * child, so pi gets an error instead of hanging and later calls fail fast. * This is a per-REQUEST timeout, not a process-lifetime one — the * long-lived server is only killed when a request genuinely stalls. - * - MEMPALACE_MCP_TIMEOUT_MS tool-call/request timeout (default 60000) + * - MEMPALACE_MCP_TIMEOUT_MS tool-call/request timeout (default 60000); + * the feed's mine carries its own, longer + * deadline (MEMPALACE_FEED_MINE_TIMEOUT_MS) * - MEMPALACE_MCP_INIT_TIMEOUT_MS initialize+tools/list timeout (default 300000) * Set either to 0 to disable (legacy unbounded behavior). * @@ -116,7 +118,13 @@ interface IMcpClient { readonly alive: boolean; onExit: (() => void) | null; start(): Promise; - callTool(name: string, args: Record): Promise; + /** + * `opts.timeoutMs` overrides the transport's generic per-request deadline + * for THIS call only. Callers that knowingly invoke a long server-side job + * (the feed's `mempalace_mine`) pass their own deadline here; everything + * else keeps the short default, which is the wedged-query guard. + */ + callTool(name: string, args: Record, opts?: { timeoutMs?: number }): Promise; ensureAlive(): Promise; stop(): void | Promise; } @@ -372,8 +380,12 @@ class StdioMcpClient implements IMcpClient { }); } - async callTool(name: string, args: Record): Promise { - return this.request("tools/call", { name, arguments: args }); + async callTool(name: string, args: Record, opts?: { timeoutMs?: number }): Promise { + // The per-call override matters MORE here than for the HTTP client: on + // timeout this transport kills the server child, so a generic deadline + // that undercuts a long mine does not merely abandon the wait — it + // aborts the mine. + return this.request("tools/call", { name, arguments: args }, opts?.timeoutMs ?? this.requestTimeoutMs); } /** SIGTERM then SIGKILL grace, for stall recovery. */ @@ -421,6 +433,10 @@ class StdioMcpClient implements IMcpClient { // • per-request AbortController timeout honouring MEMPALACE_MCP_TIMEOUT_MS / // MEMPALACE_MCP_INIT_TIMEOUT_MS, mirroring StdioMcpClient's timeout ethos. // • alive / ensureAlive / onExit to satisfy IMcpClient. +// • callTool() takes an optional per-call `{ timeoutMs }` (IMcpClient +// contract, see there) so the feed's long-running mine is not cut off by +// the generic per-request deadline. Not a protocol change; sync token +// unchanged. // // NOTE: mempalace-mcp --transport http is a SESSIONLESS, stateless JSON-RPC // server (no Mcp-Session-Id, always application/json, Connection: close), so @@ -466,8 +482,8 @@ class RemoteMcpClient implements IMcpClient { this.healthy = true; } - async callTool(name: string, args: Record): Promise { - return this.request("tools/call", { name, arguments: args }); + async callTool(name: string, args: Record, opts?: { timeoutMs?: number }): Promise { + return this.request("tools/call", { name, arguments: args }, { timeoutMs: opts?.timeoutMs }); } /** @@ -941,17 +957,29 @@ export default async function mempalaceExtension(pi: ExtensionAPI) { // after 30000ms" many times per session rather than at most once per // debounce window. lastFeedAt = Date.now(); + // The deadline is passed DOWN to the transport as well as raced + // here. Until 2026-09-18 it was only raced: callTool() had no way + // to carry it, so the transport's generic per-request timeout + // (MEMPALACE_MCP_TIMEOUT_MS, 60 000) fired first on every honest + // 60 s+ mine — "remote request 'tools/call' failed: timed out + // after 60000ms" — and the 300 000 below was unreachable. The + // race stays as the liveness guard for a transport whose timeout + // is disabled (0). await Promise.race([ - client.callTool("mempalace_mine", { - source, - mode: "convos", - wing: feedWing, - // Internal call: it does not pass through the registered tool's - // execute(), so it stamps itself. These ARE this harness's own - // transcripts from this device, so the harness segment is the - // agent (not `miner`) even though the tool is `mine`. - agent: stampProvenance ? `${agentName}@${device}` : agentName, - }), + client.callTool( + "mempalace_mine", + { + source, + mode: "convos", + wing: feedWing, + // Internal call: it does not pass through the registered tool's + // execute(), so it stamps itself. These ARE this harness's own + // transcripts from this device, so the harness segment is the + // agent (not `miner`) even though the tool is `mine`. + agent: stampProvenance ? `${agentName}@${device}` : agentName, + }, + { timeoutMs: feedMineTimeoutMs }, + ), new Promise((_resolve, reject) => setTimeout( () => reject(new Error(`mine timed out after ${feedMineTimeoutMs}ms`)), diff --git a/scripts/test-mcp-call-timeout.sh b/scripts/test-mcp-call-timeout.sh new file mode 100755 index 0000000..d3fab3e --- /dev/null +++ b/scripts/test-mcp-call-timeout.sh @@ -0,0 +1,134 @@ +#!/usr/bin/env bash +# test-mcp-call-timeout.sh — the per-call deadline of RemoteMcpClient in +# extensions/pi/mempalace.ts, and the override that the feed's mine relies on. +# +# WHY THIS EXISTS. The feed tick calls `mempalace_mine` through +# `client.callTool()`. Its own deadline (MEMPALACE_FEED_MINE_TIMEOUT_MS, +# 300 000) was raised in 2026-09 because the mine legitimately takes 30-60 s on +# a shared single-writer palace — but callTool() carried no way to pass that +# deadline down, so the transport's generic per-request timeout +# (MEMPALACE_MCP_TIMEOUT_MS, 60 000) fired first, and operators saw +# feed (tick) failed: mempalace remote request 'tools/call' failed: timed out after 60000ms +# instead of the message the 2026-09 change had aimed at. The outer race was +# unreachable in practice. This harness pins both halves of the contract: +# 1. a plain callTool() still honours the short per-request timeout +# (a query taking that long really is wedged — keep it short); +# 2. callTool(name, args, { timeoutMs }) honours the override, so a long +# server-side job can be given its own, longer, deadline. +# Before the fix, (2) fails: the third argument was silently ignored. +# +# Like test-owed-withdrawal.sh, it runs the SHIPPED text: the class is cut out +# of mempalace.ts by brace matching, type-stripped with node's own stripper, +# and driven against a local JSON-RPC server that delays tools/call. +set -euo pipefail +REPO_ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)" +SRC="${1:-$REPO_ROOT/extensions/pi/mempalace.ts}" +WORK="$(mktemp -d)" +trap 'rm -rf "$WORK"' EXIT +[ -r "$SRC" ] || { echo "FAIL: cannot read $SRC" >&2; exit 2; } + +# ---------------------------------------------------------------- extractor --- +cat >"$WORK/extract.mjs" <<'EXTRACT' +import { readFileSync, writeFileSync } from "node:fs"; +import { stripTypeScriptTypes } from "node:module"; +const src = readFileSync(process.argv[2], "utf8"); + +/** Cut a top-level `const NAME = ...;` out of the source, verbatim. */ +function decl(name) { + const start = src.indexOf(`const ${name} =`); + if (start < 0) throw new Error(`declaration not found: ${name}`); + return src.slice(start, span(start)); +} +/** Cut `class NAME ... { ... }` out of the source, verbatim. */ +function klass(name) { + const start = src.indexOf(`class ${name} `); + if (start < 0) throw new Error(`class not found: ${name}`); + return src.slice(start, span(start, true)); +} +/** End offset of the statement starting at `start` (brace-matched). */ +function span(start, braceOnly = false) { + let depth = 0, inStr = null, sawBrace = false; + for (let i = start; i < src.length; i++) { + const c = src[i], prev = src[i - 1]; + if (inStr) { if (c === inStr && prev !== "\\") inStr = null; continue; } + if (c === '"' || c === "'" || c === "`") { inStr = c; continue; } + if (c === "/" && src[i + 1] === "/") { i = src.indexOf("\n", i); if (i < 0) break; continue; } + if (c === "/" && src[i + 1] === "*") { i = src.indexOf("*/", i) + 1; continue; } + if (c === "{" || c === "(" || c === "[") { depth++; if (c === "{") sawBrace = true; } + else if (c === "}" || c === ")" || c === "]") { depth--; if (braceOnly && sawBrace && depth === 0) return i + 1; } + else if (!braceOnly && c === ";" && depth === 0) return i + 1; + } + throw new Error(`unterminated statement at ${start}`); +} + +const parts = [decl("num"), decl("REMOTE_PROTOCOL_VERSION"), decl("REMOTE_CLIENT_INFO"), klass("RemoteMcpClient")]; +for (const [i, p] of parts.entries()) if (p.length < 30) throw new Error(`extraction ${i} implausibly short: ${p}`); +if (!parts[3].includes("tools/call")) throw new Error("RemoteMcpClient does not mention tools/call"); +const ts = parts.join("\n\n") + "\nexport { RemoteMcpClient };\n"; +writeFileSync(process.argv[3], stripTypeScriptTypes(ts, { mode: "strip" })); +EXTRACT +node --no-warnings "$WORK/extract.mjs" "$SRC" "$WORK/client.mjs" || exit 2 +node --check "$WORK/client.mjs" || { echo "FAIL: extracted client does not parse" >&2; exit 2; } +echo "[extract] pulled RemoteMcpClient from $(basename "$SRC") ($(wc -c <"$WORK/client.mjs") bytes)" + +# ------------------------------------------------------------------ harness --- +cat >"$WORK/run.mjs" <<'RUN' +import { createServer } from "node:http"; +import { RemoteMcpClient } from "./client.mjs"; + +// A sessionless JSON-RPC server like `mempalace-mcp --transport http`: +// initialize / tools/list answer at once; tools/call sleeps SLOW_MS first. +const SLOW_MS = 1500; +const server = createServer((req, res) => { + let body = ""; + req.on("data", (c) => (body += c)); + req.on("end", () => { + const msg = JSON.parse(body); + if (msg.id === undefined) { res.writeHead(202); res.end(); return; } // notification + const reply = (result) => { + res.writeHead(200, { "content-type": "application/json" }); + res.end(JSON.stringify({ jsonrpc: "2.0", id: msg.id, result })); + }; + if (msg.method === "initialize") return reply({ protocolVersion: "2024-11-05", capabilities: {}, serverInfo: { name: "fake", version: "0" } }); + if (msg.method === "tools/list") return reply({ tools: [{ name: "slow", description: "", inputSchema: { type: "object" } }] }); + if (msg.method === "tools/call") return void setTimeout(() => reply({ content: [{ type: "text", text: "done" }] }), SLOW_MS); + reply({}); + }); +}); +await new Promise((r) => server.listen(0, "127.0.0.1", r)); +const url = `http://127.0.0.1:${server.address().port}/mcp`; + +let failures = 0; +const check = (ok, label) => { console.log(`${ok ? "ok " : "FAIL"} ${label}`); if (!ok) failures++; }; + +// Short per-request deadline, deliberately below SLOW_MS. +process.env.MEMPALACE_MCP_TIMEOUT_MS = "400"; +const client = new RemoteMcpClient(url); +await client.start(); +check(client.alive === true, "start(): initialize + tools/list complete, client alive"); + +// 1. A plain call honours the short deadline — this is the wedged-query guard. +let err = null; +const t0 = Date.now(); +try { await client.callTool("slow", {}); } catch (e) { err = e; } +check(err !== null && /timed out after 400ms/.test(err.message), `plain callTool() rejects at the per-request deadline (${err && err.message})`); +check(Date.now() - t0 < SLOW_MS, "…and rejects BEFORE the server would have answered"); +check(client.alive === false, "a timeout marks the client unhealthy (documented side effect; ensureAlive() revives)"); + +// 2. A call with its own deadline outlives the generic one — the feed's mine. +await client.ensureAlive(); +err = null; +let result = null; +try { result = await client.callTool("slow", {}, { timeoutMs: 5000 }); } catch (e) { err = e; } +check(err === null && result && result.content?.[0]?.text === "done", `callTool(name, args, { timeoutMs: 5000 }) waits past the generic deadline and gets the result (${err ? err.message : "ok"})`); + +// 3. The override is itself a deadline, not "no deadline". +err = null; +try { await client.callTool("slow", {}, { timeoutMs: 200 }); } catch (e) { err = e; } +check(err !== null && /timed out after 200ms/.test(err.message), `callTool(..., { timeoutMs: 200 }) rejects at ITS deadline (${err && err.message})`); + +server.close(); +console.log(failures === 0 ? "PASS: all assertions held" : `FAIL: ${failures} assertion(s) failed`); +process.exit(failures === 0 ? 0 : 1); +RUN +cd "$WORK" && node --no-warnings run.mjs