fix(feed): the mine's deadline never reached the transport; 60 s cut it off

The 2026-09 change raised MEMPALACE_FEED_MINE_TIMEOUT_MS to 300 000 and raced it against client.callTool("mempalace_mine"). But callTool() had no way to carry a deadline, so every call went out under the transport's generic per-request timeout (MEMPALACE_MCP_TIMEOUT_MS, 60 000), which fired first on every honest 60 s+ mine. Operators saw feed (tick) failed: mempalace remote request 'tools/call' failed: timed out after 60000ms instead of the message the change had aimed at, and the 300 s was unreachable. On stdio it was worse than noise: that transport kills the server child on timeout, so the mine was actually aborted at 60 s. callTool(name, args, { timeoutMs }) now passes a per-call deadline to both transports; feedPalace() uses it for the mine. Plain calls keep the short default — a query taking 60 s is still wedged. The Promise.race stays as the liveness guard for a transport with its timeout disabled (0). scripts/test-mcp-call-timeout.sh cuts RemoteMcpClient out of the shipped file (as test-owed-withdrawal.sh does for the mailbox predicates), drives it against a local JSON-RPC server that delays tools/call, and asserts: plain call rejects at the generic deadline; the override outlives it; the override is itself a deadline. Fails on the previous commit (2 of 6), passes here. Vendored-copy delta noted in the header; protocol untouched, sync token unchanged (check-mcp-client-sync.sh passes against pi-extensions).
2026-09-18 17:04:59 +02:00
parent dab989b068
commit 817b3a82b7
3 changed files with 201 additions and 16 deletions
@@ -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
@@ -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<void>;
-	callTool(name: string, args: Record<string, unknown>): Promise<any>;
+	/**
+	 * `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<string, unknown>, opts?: { timeoutMs?: number }): Promise<any>;
 	ensureAlive(): Promise<boolean>;
 	stop(): void | Promise<void>;
 }
@@ -372,8 +380,12 @@ class StdioMcpClient implements IMcpClient {
 		});
 	}

-	async callTool(name: string, args: Record<string, unknown>): Promise<any> {
-		return this.request("tools/call", { name, arguments: args });
+	async callTool(name: string, args: Record<string, unknown>, opts?: { timeoutMs?: number }): Promise<any> {
+		// 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<string, unknown>): Promise<any> {
-		return this.request("tools/call", { name, arguments: args });
+	async callTool(name: string, args: Record<string, unknown>, opts?: { timeoutMs?: number }): Promise<any> {
+		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`)),
@@ -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