fix(pi): clear the feed's mine-race timer, so pi -p exits when the mine returns
feedPalace() raced mempalace_mine against a bare setTimeout(reject, feedMineTimeoutMs) and never cleared it. When the mine won (the normal case) the losing 300 000 ms timer stayed referenced. Interactive and RPC mode call process.exit() and never showed 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 for the rest of the five minutes. Measured on tor-ms22 (pi 1.1.0, NODE_OPTIONS=--import probe): - before: PONG at 4 s, exit at 315.1 s. The 300 000 ms timer from mempalace.ts:1144 (created +15.1 s) was the ONLY active resource from +50 s on. - after: PONG at 3 s, exit at 45.2 s, the moment the mine's socket closed. - MEMPALACE_FEED=0: 3.8 s. pi 1.0.0 behaved the same as 1.1.0, so this is not a pi regression. The timer is now cleared in a finally once the race settles. It stays referenced while it runs because it is the liveness guard. scripts/test-feed-exit.sh loads the type-stripped SHIPPED extension under a stub pi with a fake palace in a separate process and fires session_shutdown: - A: the mine answers in 1 s with a 20 s deadline. Node must exit within 3 s of the handler resolving. The pre-fix source FAILS here (19 000 ms). - B: the mine never answers, 2 s deadline. The deadline still ends the wait, and the failure is logged. All five scripts/test-*.sh pass. README Debugging section: the remaining expected wait (one catch-up feed per session, ~45 s here) and MEMPALACE_FEED=0 for scripts that want an instant return.
This commit is contained in:
@@ -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
|
||||
|
||||
+38
-21
@@ -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<typeof setTimeout> | 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`,
|
||||
|
||||
Executable
+150
@@ -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/<ms>), 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
|
||||
Reference in New Issue
Block a user