fix(onlion): a stalled request body cannot hold an invocation; slow reports name their stage

docs/decisions/implemented/2026-10-30-body-deadline-and-stage.md

@@ -0,0 +1,71 @@
+# A stalled request body cannot hold an invocation, and slow reports name their stage
+
+[简体中文](2026-10-30-body-deadline-and-stage.zh-CN.md) · [Terms](2026-10-30-body-deadline-and-stage.terms.yaml)
+
+**Status:** implemented
+**Approved:** explicit
+
+## Problem
+
+The 19:34-19:50 window has twelve kills at the 120 s ceiling, and they split on memory:
+
+| group | memory                   | rows                   | reading                                                                                                         |
+| ----- | ------------------------ | ---------------------- | --------------------------------------------------------------------------------------------------------------- |
+| X     | 601-667 MB               | 7, inside 153 s        | business logic ran; the embedding chain (already addressed by the per-invocation breaker and the fold deadline) |
+| Y     | **51.3359 MB, constant** | 5, spread over 9.4 min | memory never moved - the invocation was still waiting for its **request body**                                  |
+
+`readJson` awaited `reader.read()` with **no deadline of its own**. A client that stops
+uploading halfway (or an edge that holds the connection) therefore occupies the entire invocation
+budget, allocates nothing, and is killed at 120 s with no trace of what it wanted. The platform's own
+per-invocation memory figure is the only fingerprint, and it says "nothing ever happened".
+
+The second problem is diagnostic: every 120 s kill so far needed a code read to say where it was.
+The 60 s slow report carries memory, queue state and the last embedding call, but not the stage the
+isolate is sitting in.
+
+## Decision
+
+- `readJson(request, env)` gives the body `BODY_TIMEOUT_MS` (30 s, `NMG_BODY_TIMEOUT_MS`), cancels
+  the stream and answers `408 request_body_timeout`. Thirty seconds is generous for the 6 MiB limit
+  and leaves most of the invocation for the work the body asked for.
+- `diagnostics.mjs` tracks `activeStage`: the name of the measured stage currently executing, set
+  and restored around `measure`/`measureSync`, exposed as `currentStage()`. The slow-request line
+  reports it as `stage_isolate`.
+
+## Evidence
+
+| before                                                     | after                                                                             |
+| ---------------------------------------------------------- | --------------------------------------------------------------------------------- |
+| 5 rows at 120 s with memory frozen at the runtime baseline | the body read fails at 30 s with `408 request_body_timeout` and a stage of `null` |
+| a 120 s kill names only memory and the last embedding call | the 60 s self-report names the stage the isolate was inside                       |
+
+## What this does and does not establish
+
+- It does not prove those five rows were stalled uploads. Memory that never moves is consistent with
+  it, not proof: an edge-side wait that never reaches the handler would look the same and would leave
+  **no** `nmg_request` line at all. The stage field plus the absence of a request line is what
+  distinguishes the two next window.
+- The X group is untouched here. Its mechanism (embedding timeouts, single-instance serialization)
+  is documented in `2026-10-30-embedding-breaker` and `postmortem/0006`; the remaining lever there
+  is the provider and the harness concurrency.
+- `stage_isolate` is exact on this platform (fresh isolate per request) and approximate if an isolate
+  is ever reused for concurrent requests, which is why the field names the isolate rather than the
+  request.
+
+## Alternatives considered
+
+- **Rely on the platform's 120 s kill.** That is what happens today: a stalled body turns one
+  request into a full-budget orphan and tells us nothing.
+- **Read the body with a `Promise.race` timeout instead of a deadline check.** A race leaves the
+  reader pumping into a dead promise; checking before each read and cancelling the stream is the
+  version that actually releases the connection.
+- **Infer the X/Y groups from memory alone.** Memory is a fingerprint, not evidence: a request that
+  is killed during its first provider call and one killed while waiting for a body differ by more
+  than a number, which is why the stage field is part of this change.
+
+## Consequences
+
+- A stalled upload now costs 30 s and returns a clear 408 instead of consuming the invocation.
+- Log lines gain one string per slow request; nothing per ordinary request changes.
+- The next 120 s window is diagnosable: `stage_isolate` says what the isolate was doing, and a
+  missing `nmg_request` line says the request never reached us at all.

docs/decisions/implemented/2026-10-30-body-deadline-and-stage.terms.yaml

@@ -0,0 +1,4 @@
+version: 2
+terms: []
+references:
+  - docs/decisions/implemented/2026-10-30-body-deadline-and-stage.md

docs/decisions/implemented/2026-10-30-body-deadline-and-stage.zh-CN.md

@@ -0,0 +1,49 @@
+# 停滞的请求体不能占满一次调用；慢请求自报要写清阶段
+
+[English](2026-10-30-body-deadline-and-stage.md) · [Terms](2026-10-30-body-deadline-and-stage.terms.yaml)
+
+**Status:** implemented
+**Approved:** explicit
+
+## 问题
+
+19:34–19:50 窗口有 12 条 120 s 超时，按内存分成两组：
+
+| 组  | 内存                 | 条数                  | 判读                                                       |
+| --- | -------------------- | --------------------- | ---------------------------------------------------------- |
+| X   | 601–667 MB           | 7 条，集中在 153 秒内 | 进了业务逻辑；embedding 链（已由按调用熔断与折叠截止处理） |
+| Y   | **51.3359 MB，恒定** | 5 条，分散在 9.4 分钟 | 内存从未增长——调用一直在等**请求体**                       |
+
+`readJson` 里 `await reader.read()` **没有任何截止时间**。客户端传一半就停（或边缘把连接挂住），于是整段调用预算被一个还没到达的 body 占住，不分配内存，最后在 120 s 被杀，什么线索都不留。平台给出的每调用内存是唯一指纹，而它说的是"什么都没发生"。
+
+第二个问题是可观测性：到目前为止每次 120 s 被杀都要读代码才知道卡在哪。60 s 慢请求自报有内存、队列状态和最近一次嵌入调用，但没有"当前阶段"。
+
+## 决策
+
+- `readJson(request, env)` 给请求体 `BODY_TIMEOUT_MS`（30 秒，`NMG_BODY_TIMEOUT_MS` 可改），超时取消流并返回 `408 request_body_timeout`。对 6 MiB 上限而言 30 秒很宽裕，剩下的时间留给 body 要求做的工作。
+- `diagnostics.mjs` 维护 `activeStage`：当前正在执行的测量阶段名，在 `measure`/`measureSync` 前后设置与恢复，通过 `currentStage()` 暴露。慢请求行把它记为 `stage_isolate`。
+
+## 证据
+
+| 改前                                 | 改后                                                                       |
+| ------------------------------------ | -------------------------------------------------------------------------- |
+| 5 条 120 s、内存贴着运行时基线不动   | 请求体读取在 30 秒失败，返回 `408 request_body_timeout`，此时阶段为 `null` |
+| 120 s 被杀只能看到内存和最近一次嵌入 | 60 s 自报里写明 isolate 当时所在的阶段                                     |
+
+## 这确立了什么、没有确立什么
+
+- 它**没有证明**那五条就是停滞的上传。内存不动与之相符，但只是相符：如果是边缘侧的等待根本没进 handler，表现一样，而且会**完全没有** `nmg_request` 行。下一次窗口里，"有阶段字段/没有请求行"正是区分两者的依据。
+- X 组在这里未处理。其机制（嵌入超时、单实例串行）记录在 `2026-10-30-embedding-breaker` 与 `postmortem/0006`；那一侧剩下的杠杆是提供商与评测端并发。
+- `stage_isolate` 在本平台（每请求一个新 isolate）是精确的；若某个 isolate 被复用给并发请求则只是近似——这正是字段名叫 isolate 而不是 request 的原因。
+
+## 考虑过的替代方案
+
+- **依赖平台的 120 s 掐断**：这正是现状——停滞的 body 把一次请求变成占满预算的孤儿，而且不留信息。
+- **用 `Promise.race` 超时读体**：race 只是把一个还在往死掉的 promise 里灌数据的 reader 留在后台；逐次读前检查并 `cancel()` 才是真正释放连接的写法。
+- **只靠内存推断 X/Y 两组**：内存是指纹不是证据；被杀死在第一次提供商调用里的请求，与等待 body 的请求，差别不止一个数字——所以这次一并加了阶段字段。
+
+## 后果
+
+- 停滞的上传现在只花 30 秒并返回清晰的 408，不再吃掉整次调用。
+- 日志每条慢请求多一个字符串；普通请求没有变化。
+- 下一个 120 s 窗口可诊断：`stage_isolate` 说明 isolate 在做什么，而缺少 `nmg_request` 行则说明请求根本没到我们这里。

onlion/backend/diagnostics.mjs

@@ -1,13 +1,35 @@
 import {observedStage} from './monitoring.mjs';
 import { AsyncLocalStorage } from 'node:async_hooks';
 const profiles = new AsyncLocalStorage();
+/** The stage this isolate is currently inside.
+ *
+ *  The 60 s slow-request line reported memory, queue state and the last embedding call, and every
+ *  120 s kill in the 2026-10-30 windows still needed a code read to say where it was. One string
+ *  assignment per measured stage fixes that: a fresh isolate per request on this platform means
+ *  there is no cross-request ambiguity, and a reused one only makes it approximate, which the log
+ *  says explicitly by naming the field `stage_isolate`.
+ */
+let activeStage = null;
+export const currentStage = () => activeStage;
 function timedMeasure(name, operation) {
   const profile = profiles.getStore();
-  if (!profile) return operation();
+  if (!profile) {
+    const prior = activeStage;
+    activeStage = name;
+    return (async () => {
+      try {
+        return await operation();
+      } finally {
+        activeStage = prior;
+      }
+    })();
+  }
   return (async()=>{
     const start = performance.now();
+    const prior = activeStage;
+    activeStage = name;
     try { return await operation(); }
-    finally { profile[name] = (profile[name] || 0) + performance.now() - start; }
+    finally { activeStage = prior; profile[name] = (profile[name] || 0) + performance.now() - start; }
   })();
 }
 function timedMeasureSync(name, operation) {

onlion/backend/worker.mjs

@@ -24,6 +24,7 @@ import {
   requestAccepted,
   requestStarted,
   requestFinished,
+  currentStage,
 } from "./diagnostics.mjs";
 import init from "../sqlite-wasm/worker-loader.mjs";
 import compiledSqlite from "../sqlite-wasm/sqlite3.wasm";
@@ -87,6 +88,14 @@ import {
 } from "./query-chunks.mjs";
 const MAX_DATABASE_BYTES = USER_LIMIT;
 const MAX_BODY_BYTES = 6 * 1024 * 1024;
+/** How long one request may spend receiving its body.
+ *
+ *  The platform kills an invocation at 120 s, so a body that never completes used to occupy the
+ *  whole budget and then die with nothing to show - the 51.3359 MB constant rows of the
+ *  2026-10-30 19:34-19:50 window, which never allocated because the handler was still waiting for
+ *  the upload. Thirty seconds is generous for 6 MiB and leaves the rest of the window for the work
+ *  the body asked for. */
+const BODY_TIMEOUT_MS = 30_000;
 /** Payload caps are sized against the platform request body, not against a single
  *  global character budget. The benchmark contract states there is no global
  *  character cap and that an unsupported payload should get a clear 4xx, so a cap
@@ -218,15 +227,24 @@ function authenticate(request, env) {
       "A valid Token, Bearer, or X-API-Key credential is required",
     );
 }
-async function readJson(request) {
+async function readJson(request, env) {
   if (Number(request.headers.get("content-length")) > MAX_BODY_BYTES)
     throw new HttpError(413, "request_too_large", "Request limit is 6 MiB");
   if (!request.body) throw new HttpError(400, "invalid_json", "JSON body required");
+  // Nothing below this line has a deadline of its own, so this is the only place that can give a
+  // stalled upload one instead of holding the invocation to the platform ceiling.
+  const deadline =
+    Date.now() +
+    (Number(env?.NMG_BODY_TIMEOUT_MS) > 0 ? Number(env.NMG_BODY_TIMEOUT_MS) : BODY_TIMEOUT_MS);
   const reader = request.body.getReader();
   const chunks = [];
   let length = 0;
   try {
     while (true) {
+      if (Date.now() > deadline) {
+        await reader.cancel().catch(() => {});
+        throw new HttpError(408, "request_body_timeout", "Request body did not arrive in time");
+      }
       const { done, value } = await reader.read();
       if (done) break;
       length += value.length;
@@ -1266,6 +1284,7 @@ function watchSlowRequest(env, context, started) {
         route: context.route,
         elapsed_ms: Date.now() - started,
         add_mode: env.NMG_ADD_MODE ?? null,
+        stage_isolate: currentStage(),
         queue: queueStatus(),
         // A killed invocation carries none of this, so the report has to be written while
         // the request is still alive: memory, how many requests this instance has served,
@@ -1700,7 +1719,7 @@ async function reclaimAllRoute(request, env, path) {
     throw new HttpError(503, "storage_unavailable", "Persistent storage binding missing");
   if (request.method === "GET") return json(await reclamationStatus(env.MEMORY));
   if (request.method === "POST") {
-    const input = await readJson(request);
+    const input = await readJson(request, env);
     if (input.confirm !== "ALL_MEMORY")
       throw new HttpError(
         400,
@@ -1800,7 +1819,7 @@ async function selfTestRoute(request, env, _url, path) {
   if (path !== "/diagnostics/self-test" || request.method !== "POST") return undefined;
   assertSelfTestAccess(request, env);
   env = { ...env, MEMORY: await memoryBucket(env.MEMORY) };
-  const input = await readJson(request);
+  const input = await readJson(request, env);
   if (Object.keys(input).some((k) => !["op", "persistence", "repetitions"].includes(k)))
     throw new HttpError(
       400,
@@ -1984,22 +2003,22 @@ async function adminRoute(request, env, url, path) {
 }
 async function adminRouteDispatcher(request, env, url, path) {
   if (path === "/admin/statistics" && request.method === "POST") {
-    const input = await readJson(request);
+    const input = await readJson(request, env);
     if (typeof input.enabled !== "boolean")
       throw new HttpError(400, "invalid_request", "enabled must be boolean");
     return json({ load: setStatistics(input.enabled) });
   }
   if (path === "/admin/capacity" && request.method === "GET")
     return json(await capacityReport(env, textField(url.searchParams.get("user_id"), "user_id")));
   if (path === "/admin/reset" && request.method === "POST")
-    return json(await reset(env, await readJson(request)));
+    return json(await reset(env, await readJson(request, env)));
   if (path === "/admin/key" && request.method === "GET") return json({ api_key: env.NMG_API_KEY });
   if (path === "/admin/status" && request.method === "GET") return adminStatusResponse(env);
   return adminDiagnosticsRoute(request, env, path);
 }
 async function adminDiagnosticsRoute(request, env, path) {
   if (path === "/admin/diagnostics/search" && request.method === "POST") {
-    const input = await readJson(request);
+    const input = await readJson(request, env);
     return json(await diagnosticSearch(env, input));
   }
   if (path === "/admin/diagnostics/seed" && request.method === "POST") {
@@ -2021,7 +2040,7 @@ async function adminDiagnosticsRoute(request, env, path) {
 }
 async function searchRoute(request, env, _url, path) {
   if (path !== "/search" || request.method !== "POST") return undefined;
-  const input = await readJson(request);
+  const input = await readJson(request, env);
   if (request.headers.get("x-nmg-profile") === "1") {
     const { result, ...diagnostics } = await profileSearch(() => search(env, input));
     return json({ ...result, diagnostics });
@@ -2046,7 +2065,7 @@ async function memoryApiRoute(request, env, url, path) {
   if (!env.MEMORY)
     throw new HttpError(503, "storage_unavailable", "Persistent storage binding missing");
   if ((path === "/reclaim" || path === "/reclaim/user") && request.method === "POST") {
-    const input = await readJson(request),
+    const input = await readJson(request, env),
       userId = textField(input.user_id, "user_id"),
       requestId = textField(input.request_id, "request_id", 128);
     const result = await reset(env, {
@@ -2070,7 +2089,7 @@ async function memoryApiRoute(request, env, url, path) {
 }
 async function resetRoute(request, env, path) {
   if (path !== "/reset" || request.method !== "POST") return undefined;
-  return json(await reset(env, await readJson(request)));
+  return json(await reset(env, await readJson(request, env)));
 }
 async function capacityRoute(request, env, url, path) {
   if (path !== "/capacity" || request.method !== "GET") return undefined;
@@ -2109,7 +2128,7 @@ async function foldRoute(request, env, url, path) {
 }
 async function addRoute(request, env, path) {
   if ((path !== "/add" && path !== "/remember") || request.method !== "POST") return undefined;
-  const input = await readJson(request);
+  const input = await readJson(request, env);
   if (addMode(env) !== "log") return json(await add(env, input));
   const startedAt = Date.now();
   const accepted = await acceptAdd(env, input);

onlion/package.json

@@ -18,15 +18,16 @@
     "test:worker-media": "node scripts/test-multimodal-worker.mjs",
     "test:cos": "node scripts/test-cos-bucket.mjs",
     "test:edgeone": "node scripts/test-edgeone-worker.mjs",
-    "verify": "npm run build && npm run check && npm run test:temporal && npm run test:media && npm run test:backend && npm run test:append-log && npm run test:manifest-pending && npm run test:add-log && npm run test:page-delta && npm run test:extractive && npm run test:mem && npm run test:worker-media",
+    "verify": "npm run build && npm run check && npm run test:temporal && npm run test:media && npm run test:backend && npm run test:append-log && npm run test:manifest-pending && npm run test:add-log && npm run test:page-delta && npm run test:extractive && npm run test:mem && npm run test:worker-media && npm run test:edgeone-package",
     "generate:callbacks": "node scripts/generate-callbacks.mjs",
     "smoke:edgeone": "node scripts/smoke-edgeone.mjs",
     "test:add-log": "node scripts/test-add-log-mode.mjs",
     "test:append-log": "node scripts/test-append-log.mjs",
     "test:manifest-pending": "node scripts/test-manifest-pending.mjs",
     "test:page-delta": "node scripts/test-page-delta.mjs",
     "test:extractive": "node --experimental-transform-types scripts/test-extractive-summaries.mjs",
-    "test:mem": "node scripts/test-mem-trace.mjs"
+    "test:mem": "node scripts/test-mem-trace.mjs",
+    "test:edgeone-package": "node scripts/test-edgeone-package.mjs"
   },
   "devDependencies": {
     "@types/node": "24.12.4",