diff --git a/extensions/pi/README.md b/extensions/pi/README.md index 95bedfa..1117cc3 100644 --- a/extensions/pi/README.md +++ b/extensions/pi/README.md @@ -567,6 +567,33 @@ 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. +### `pi -p` prints its answer, then takes minutes to exit + +Print mode (`pi -p`, `--mode json`) does not call `process.exit()` the way +interactive and RPC mode do: it returns and waits for node's event loop to +empty. Until 2026-10-13 the feed raced its mine against a bare `setTimeout` +that nothing cleared, so when the mine won (the normal case) the losing +`MEMPALACE_FEED_MINE_TIMEOUT_MS` timer kept node alive for the rest of its +five minutes. Measured on tor-ms22, a `pi -p` printed `PONG` at 4 s and exited +at 315 s, which is the timer's creation at 15 s plus 300 s. From 35 s after the +mine returned until exit, that timer was the only live resource. Interactive +sessions were never affected. The hang predates pi 1.1.0 (pi 1.0.0 behaved the +same), and `pi-task`/`fork` children were never affected because they run +`--no-extensions`. + +Fixed 2026-10-13: the timer is cleared when the race settles. +`scripts/test-feed-exit.sh` pins it. Node must exit within 3 s of +`session_shutdown` resolving, both when the mine answers and when it times +out. Before the fix the first case held node for the whole deadline. + +**What is still expected.** The first settled turn of every session runs a +catch-up feed (`lastFeedAt` starts at 0), and `session_shutdown` waits for it. +A `pi -p` therefore still exits only after one full feed: measured at 45 s on +tor-ms22, of which `--prepare` took 11 s and the mine 31 s. A script that +wants `pi -p` to return at once, and does not need this run's transcript +filed now, sets `MEMPALACE_FEED=0`. The next interactive session's feed picks +up the transcript, if it qualifies. + ## 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 c6b5b7b..1d92542 100644 --- a/extensions/pi/mempalace.ts +++ b/extensions/pi/mempalace.ts @@ -1123,28 +1123,45 @@ export default async function mempalaceExtension(pi: ExtensionAPI) { // 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, - }, - { timeoutMs: feedMineTimeoutMs }, - ), - new Promise((_resolve, reject) => - setTimeout( - () => reject(new Error(`mine timed out after ${feedMineTimeoutMs}ms`)), - feedMineTimeoutMs, + // + // The race's timer MUST be cleared when the race settles (finally, + // below). Until 2026-10-13 it was a bare setTimeout that nothing + // cleared, so when the mine WON — the normal case — the losing + // timer stayed referenced for the rest of feedMineTimeoutMs. In + // interactive and RPC mode pi calls process.exit() and nobody saw + // it; print mode (`pi -p`, `--mode json`) returns and waits for an + // empty event loop, so every `pi -p` on a devbox printed its answer + // and then idled until the 300 s deadline (measured on tor-ms22: the + // only live resource from the mine's return to exit). Kept ref'd on + // purpose while it runs: it is the liveness guard. + // scripts/test-feed-exit.sh pins both halves. + let raceTimer: ReturnType | undefined; + try { + 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, + }, + { timeoutMs: feedMineTimeoutMs }, ), - ), - ]); + new Promise((_resolve, reject) => { + raceTimer = setTimeout( + () => reject(new Error(`mine timed out after ${feedMineTimeoutMs}ms`)), + feedMineTimeoutMs, + ); + }), + ]); + } finally { + clearTimeout(raceTimer); + } } catch (err) { process.stderr.write( `[mempalace ext] feed (${reason}) failed: ${(err as Error).message}\n`, diff --git a/scripts/test-feed-exit.sh b/scripts/test-feed-exit.sh new file mode 100755 index 0000000..0a8e500 --- /dev/null +++ b/scripts/test-feed-exit.sh @@ -0,0 +1,150 @@ +#!/usr/bin/env bash +# test-feed-exit.sh — once the feed's mine has settled, the pi extension in +# extensions/pi/mempalace.ts must leave NOTHING behind that keeps node alive. +# +# WHY THIS EXISTS. `pi -p` (print mode, also `--mode json`) does not call +# process.exit(): it returns from main() and lets node exit when the event loop +# is empty. Interactive and RPC mode call process.exit() and never noticed. The +# feed raced its mine against a bare +# new Promise((_, reject) => setTimeout(reject, feedMineTimeoutMs)) +# whose timer was never cleared. When the mine won the race (the normal case, +# 30-60 s), the losing 300 000 ms timer stayed referenced, so every `pi -p` on a +# devbox printed its answer and then sat idle for the rest of those 5 minutes. +# Measured on tor-ms22 2026-10-13: the 300 000 ms timer from mempalace.ts was the +# ONLY active resource from 35 s after the mine returned until exit at ~316 s. +# +# Like test-mcp-call-timeout.sh, it runs the SHIPPED text: the whole extension +# is type-stripped with node's own stripper (the `typebox` import is replaced by +# a stub) and loaded under a stub pi. A fake feed helper prints MINE_SOURCE, and +# a local JSON-RPC server (in a SEPARATE process, so it cannot hold the driver's +# event loop) answers the mine. The driver fires session_shutdown, which awaits +# the feed, and then simply returns. The harness measures how long node takes to +# exit after that. +# A. mine answers in 1 s, deadline 20 s: node must exit right after the +# handler resolves. Before the fix it lived until the 20 s deadline. +# B. mine never answers, deadline 2 s: the deadline is still a liveness +# guard; the handler resolves at about 2 s and node exits. +set -euo pipefail +REPO_ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)" +SRC="${1:-$REPO_ROOT/extensions/pi/mempalace.ts}" +WORK="$(mktemp -d)" +SERVER_PID="" +cleanup() { [ -n "$SERVER_PID" ] && kill "$SERVER_PID" 2>/dev/null; rm -rf "$WORK"; } +trap cleanup 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"; +let src = readFileSync(process.argv[2], "utf8"); +const imp = 'import { Type } from "typebox";'; +if (!src.includes(imp)) throw new Error(`expected import line not found: ${imp}`); +src = src.replace(imp, 'const Type = { Unsafe: (s) => s, Object: () => ({}) };'); +if (!src.includes("feedPalace")) throw new Error("extension does not mention feedPalace"); +writeFileSync(process.argv[3], stripTypeScriptTypes(src, { mode: "strip" })); +EXTRACT +node --no-warnings "$WORK/extract.mjs" "$SRC" "$WORK/ext.mjs" || exit 2 +node --check "$WORK/ext.mjs" || { echo "FAIL: stripped extension does not parse" >&2; exit 2; } +echo "[extract] type-stripped $(basename "$SRC") ($(wc -c <"$WORK/ext.mjs") bytes)" + +# ------------------------------------------------------------ fake feed bin --- +cat >"$WORK/fake-feed" <<'FEED' +#!/bin/sh +echo "MINE_SOURCE=/nonexistent/fake-stage" +FEED +chmod +x "$WORK/fake-feed" + +# ----------------------------------------------------------- fake palace ------ +# Sessionless JSON-RPC like `mempalace-mcp --transport http`. The mine's delay +# is set per case through a tiny control endpoint (GET /delay/), so one +# server serves both cases. +cat >"$WORK/server.mjs" <<'SERVER' +import { createServer } from "node:http"; +import { appendFileSync } from "node:fs"; +let mineDelay = 1000; +const server = createServer((req, res) => { + if (req.url.startsWith("/delay/")) { mineDelay = Number(req.url.slice(7)); res.end("ok"); return; } + 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; } + const reply = (result) => { + if (res.destroyed) return; + res.writeHead(200, { "content-type": "application/json", connection: "close" }); + 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: "mempalace_mine", description: "", inputSchema: { type: "object" } }] }); + if (msg.method === "tools/call") { + appendFileSync(process.env.CALL_LOG, `${msg.params?.name} source=${msg.params?.arguments?.source}\n`); + return void setTimeout(() => reply({ content: [{ type: "text", text: "mined" }] }), mineDelay); + } + reply({}); + }); +}); +server.listen(0, "127.0.0.1", () => console.log(server.address().port)); +SERVER +CALL_LOG="$WORK/calls.log" node "$WORK/server.mjs" >"$WORK/port" & +SERVER_PID=$! +for _ in $(seq 50); do [ -s "$WORK/port" ] && break; sleep 0.1; done +PORT="$(cat "$WORK/port")" +[ -n "$PORT" ] || { echo "FAIL: fake palace did not start" >&2; exit 2; } + +# ------------------------------------------------------------------ driver ---- +# Loads the extension under a stub pi, fires session_shutdown, prints when the +# handler resolved, then RETURNS. Anything still referenced keeps node alive. +cat >"$WORK/driver.mjs" <<'DRIVER' +const t0 = Date.now(); +const handlers = {}; +const pi = new Proxy({}, { + get: (_t, k) => k === "on" ? (ev, fn) => { (handlers[ev] ||= []).push(fn); } : () => {}, +}); +const { default: ext } = await import("./ext.mjs"); +await ext(pi); +if (!handlers.session_shutdown) { console.log("NO_SHUTDOWN_HANDLER"); process.exitCode = 3; } +else { + for (const fn of handlers.session_shutdown) await fn({ type: "session_shutdown", reason: "quit" }, {}); + console.log(`HANDLER_RESOLVED_MS=${Date.now() - t0}`); +} +process.on("exit", () => console.log(`EXIT_MS=${Date.now() - t0}`)); +DRIVER + +failures=0 +check() { if [ "$1" = 0 ]; then echo "ok $2"; else echo "FAIL $2"; failures=$((failures + 1)); fi; } + +run_case() { # $1 mine delay ms, $2 feed mine timeout ms -> sets HANDLER EXIT RC + curl -fsS "http://127.0.0.1:$PORT/delay/$1" >/dev/null + : >"$WORK/calls.log" + set +e + out="$(cd "$WORK" && env -u MEMPALACE_REMOTE_TOKEN -u MEMPALACE_PI_DEVICE \ + MEMPALACE_REMOTE_URL="http://127.0.0.1:$PORT/mcp" MEMPALACE_FEED=1 \ + MEMPALACE_FEED_BIN="$WORK/fake-feed" MEMPALACE_FEED_MINE_TIMEOUT_MS="$2" \ + timeout 60 node --no-warnings driver.mjs 2>"$WORK/driver.err")" + RC=$? + set -e + HANDLER="$(printf '%s\n' "$out" | sed -n 's/^HANDLER_RESOLVED_MS=//p')" + EXIT="$(printf '%s\n' "$out" | sed -n 's/^EXIT_MS=//p')" + MINES="$(grep -c '^mempalace_mine source=/nonexistent/fake-stage' "$WORK/calls.log" || true)" +} + +# A. normal case: the mine wins the race. +run_case 1000 20000 +echo "[A] rc=$RC handler=${HANDLER:-?}ms exit=${EXIT:-?}ms mines=$MINES" +check "$([ "$RC" = 0 ] && echo 0 || echo 1)" "A: driver exits cleanly (rc=$RC)" +check "$([ "$MINES" = 1 ] && echo 0 || echo 1)" "A: shutdown really mined the staged source once (not a vacuous pass)" +check "$([ -n "$HANDLER" ] && [ "$HANDLER" -ge 900 ] && [ "$HANDLER" -lt 10000 ] && echo 0 || echo 1)" "A: session_shutdown awaited the 1 s mine (${HANDLER:-?} ms)" +check "$([ -n "$EXIT" ] && [ -n "$HANDLER" ] && [ $((EXIT - HANDLER)) -lt 3000 ] && echo 0 || echo 1)" \ + "A: node exits within 3 s of the handler resolving ($(( ${EXIT:-0} - ${HANDLER:-0} )) ms; the 20 s mine deadline must not hold it)" + +# B. wedged palace: the deadline must still end the wait. +run_case 60000 2000 +echo "[B] rc=$RC handler=${HANDLER:-?}ms exit=${EXIT:-?}ms mines=$MINES" +check "$([ "$RC" = 0 ] && echo 0 || echo 1)" "B: driver exits cleanly (rc=$RC)" +check "$([ -n "$HANDLER" ] && [ "$HANDLER" -ge 1900 ] && [ "$HANDLER" -lt 10000 ] && echo 0 || echo 1)" "B: session_shutdown gives up at the 2 s deadline (${HANDLER:-?} ms)" +check "$(grep -q 'feed (shutdown) failed: .*2000ms' "$WORK/driver.err" && echo 0 || echo 1)" "B: the timeout is reported on stderr" +check "$([ -n "$EXIT" ] && [ -n "$HANDLER" ] && [ $((EXIT - HANDLER)) -lt 3000 ] && echo 0 || echo 1)" \ + "B: node exits within 3 s of the handler resolving ($(( ${EXIT:-0} - ${HANDLER:-0} )) ms; the 60 s server delay must not hold it)" + +if [ "$failures" = 0 ]; then echo "PASS: all assertions held"; else echo "FAIL: $failures assertion(s) failed"; exit 1; fi