diff --git a/docs/decisions/implemented/2026-10-30-body-deadline-and-stage.md b/docs/decisions/implemented/2026-10-30-body-deadline-and-stage.md new file mode 100644 index 00000000..1618e9a2 --- /dev/null +++ b/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. diff --git a/docs/decisions/implemented/2026-10-30-body-deadline-and-stage.terms.yaml b/docs/decisions/implemented/2026-10-30-body-deadline-and-stage.terms.yaml new file mode 100644 index 00000000..bc9be61d --- /dev/null +++ b/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 diff --git a/docs/decisions/implemented/2026-10-30-body-deadline-and-stage.zh-CN.md b/docs/decisions/implemented/2026-10-30-body-deadline-and-stage.zh-CN.md new file mode 100644 index 00000000..e5156007 --- /dev/null +++ b/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` 行则说明请求根本没到我们这里。 diff --git a/onlion/backend/diagnostics.mjs b/onlion/backend/diagnostics.mjs index 91eff8cf..8b451183 100644 --- a/onlion/backend/diagnostics.mjs +++ b/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) { diff --git a/onlion/backend/worker.mjs b/onlion/backend/worker.mjs index 698f6175..35bbf5c8 100644 --- a/onlion/backend/worker.mjs +++ b/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,7 +2003,7 @@ 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) }); @@ -1992,14 +2011,14 @@ async function adminRouteDispatcher(request, env, url, path) { 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); diff --git a/onlion/package.json b/onlion/package.json index 322dda94..462df8ab 100644 --- a/onlion/package.json +++ b/onlion/package.json @@ -18,7 +18,7 @@ "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", @@ -26,7 +26,8 @@ "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", diff --git a/onlion/scripts/test-edgeone-package.mjs b/onlion/scripts/test-edgeone-package.mjs new file mode 100644 index 00000000..2b390f15 --- /dev/null +++ b/onlion/scripts/test-edgeone-package.mjs @@ -0,0 +1,89 @@ +/* eslint-disable no-console -- deliberate test output */ +/* Pins the EdgeOne packaging contract and the two loader facts that were learned the hard way. + * + * Why this exists: on 2026-10-30 the shipped bundle deferred **both** wasm modules behind a + * factory. `callbacks.wasm` is imported by the generated loader as a real `WebAssembly.Module`, + * so `new WebAssembly.Instance(fn, ...)` threw inside `runSQLite3PostLoadInit` and every `/search` + * that needed SQLite answered 503 in 75-150 ms - while `/add` kept working, because the accept + * never touches SQLite. `npm run verify` could not see it: Miniflare runs the wrangler build, which + * never executes this plugin. The endpoint found it. + * + * So the assertions are about the artefacts this build produces, not about the source: + * 1. `callbacks.wasm` is inlined as an eager `new WebAssembly.Module(...)`; + * 2. `sqlite3.wasm` is inlined behind a factory, so a request that never reads a partition does + * not decode or compile 1.5 MiB; + * 3. both modules actually compile from the bytes in the bundle, which is what the loader does; + * 4. the OPFS VFS installers are gated off through `globalThis.sqlite3ApiConfig`, the only place + * the loader reads that setting (`init()`'s argument is ignored - tried, silently inert). + * + * No network, no Miniflare: esbuild + V8. + */ +import assert from "node:assert/strict"; +import fs from "node:fs"; +import path from "node:path"; +import { execFileSync } from "node:child_process"; + +const root = process.cwd(); +const outDir = path.join(root, "dist/edgeone"); +const bundle = path.join(outDir, "cloud-functions/[[default]].js"); + +console.log("building the EdgeOne function for the packaging assertions…"); +execFileSync(process.execPath, [path.join(root, "scripts/build-edgeone.mjs")], { + cwd: root, + stdio: "inherit", +}); +const source = fs.readFileSync(bundle, "utf8"); + +// 1. callbacks.wasm: eager module, because the generated loader imports it as one. +assert.match( + source, + /var callbacks_default = new WebAssembly\.Module\(Buffer\.from\(/, + "callbacks.wasm must stay an eager WebAssembly.Module: the loader does new WebAssembly.Instance(callbacksModule, ...)", +); +assert.doesNotMatch( + source, + /function compiledWasm\(\).*callbacks/s, + "callbacks.wasm must not be wrapped in the lazy factory", +); + +// 2. sqlite3.wasm: lazy factory, and the bytes are still in the bundle (no filesystem dependency). +assert.match( + source, + /function compiledWasm\d*\(\) \{\s*compiled\d* \?\?= new WebAssembly\.Module\(Buffer\.from\(encodedBytes\d*, "base64"\)\);\s*return compiled\d*;\s*\}/, + "sqlite3.wasm must be compiled on first use, not at module scope", +); + +// 3. Both inline payloads must still be real wasm: compile them the way the bundle does. +const base64Payloads = [...source.matchAll(/Buffer\.from\((?:"([A-Za-z0-9+/=]{200,})"|encodedBytes\d*), "base64"\)/g)] + .map((match) => match[1]) + .filter(Boolean); +assert.ok( + base64Payloads.length >= 1, + "expected at least one inline base64 wasm payload in the bundle", +); +for (const payload of base64Payloads) { + const module = new WebAssembly.Module(Buffer.from(payload, "base64")); + assert.ok( + WebAssembly.Module.exports(module).length > 0, + "an inline wasm payload compiled but exports nothing", + ); +} + +// 4. The OPFS gate must be set where the loader reads it. +assert.match( + source, + /globalThis\.sqlite3ApiConfig\s*=\s*\{/, + "the OpfsVfs installers are gated on globalThis.sqlite3ApiConfig; init()'s argument is ignored", +); +assert.match( + source, + /vfs:\s*\{\s*opfs:\s*true\s*,\s*"opfs-wl":\s*true\s*\}/, + "OPFS and opfs-wl must be disabled, not attempted", +); + +// 5. And the entry still exports the handler the platform scans for. +assert.match(source, /export \{[\s\S]{0,200}onRequest/, "the built entry must export onRequest"); + +console.log( + "PASS: EdgeOne packaging — callbacks.wasm eager, sqlite3.wasm lazy, both wasm payloads compile, OPFS gated off, onRequest exported.", +);