From 4203e6271c2e874218ed7663003ce1088641918e Mon Sep 17 00:00:00 2001 From: wefio <48851810+wefio@users.noreply.github.com> Date: Fri, 30 Oct 2026 20:35:38 +0800 Subject: [PATCH 1/2] fix(onlion): a partition that cannot be read shortens the page, not the answer The 20:18-20:20 window is a different fault from every earlier one: four /search answered 503 at stage=partition_download with code dependency_timeout in 29-31 s, while /add returned 200 on the same instance three seconds earlier. A 5xx on /search is a failed attempt for the harness; a shorter page still scores. /add already degrades - the read path did not. search now treats an unreadable partition as a missing one: partial=true, degraded=, and after two consecutive failures it stops paying the timeout per partition and answers with what it read. Anything that is not a timeout/reset/replaced-snapshot still propagates, because a bug must stay visible. Also fixed the field that sent the operator down the wrong path: failure records attached embedding_host/embedding_model whenever the environment had them, so a partition_download timeout appeared next to the embedding provider and looked like a shared dependency. They are attached only when the failing stage is an embedding stage. Test: fold a user, delete the partition object, search -> 200 with partial=true and degraded=snapshot_changed. Before this change the same call surfaced as a failure. 39 PASS. --- onlion/backend/monitoring.mjs | 18 ++++++++++--- onlion/backend/worker.mjs | 48 ++++++++++++++++++++++++++++++--- onlion/scripts/test-backend.mjs | 34 +++++++++++++++++++++++ 3 files changed, 93 insertions(+), 7 deletions(-) diff --git a/onlion/backend/monitoring.mjs b/onlion/backend/monitoring.mjs index 23bfc30c..5305774b 100644 --- a/onlion/backend/monitoring.mjs +++ b/onlion/backend/monitoring.mjs @@ -136,6 +136,9 @@ function embeddingHost(env) { return "unparseable"; } } +/** Whether a failing stage is one that talks to the embedding provider. */ +const embeddingStage = (stage) => + typeof stage === "string" && (stage === "embedding" || stage.startsWith("embedding_")); export function reportFailure(error, status, kind = "request_failure") { const context = requests.getStore(); if (!context) return; @@ -150,10 +153,17 @@ export function reportFailure(error, status, kind = "request_failure") { ...classifyError(error), ...(context.user_id_hash ? { user_id_hash: context.user_id_hash } : {}), ...(context.request_id_hash ? { request_id_hash: context.request_id_hash } : {}), - // Which provider deployment the failing request was talking to. Without it every - // embedding incident had to be told apart by timestamp instead of by configuration. - ...(embeddingHost(context.env) ? { embedding_host: embeddingHost(context.env) } : {}), - ...(context.env.NMG_EMBED_MODEL ? { embedding_model: context.env.NMG_EMBED_MODEL } : {}), + // Which provider deployment the failing request was talking to - but only when the embedding + // provider is what failed. Attaching it to every record made a `partition_download` timeout + // look like an embedding fault: 2026-10-30 20:20 showed stage=partition_download beside + // embedding_host/embedding_model, and the operator reasonably concluded the two shared a + // dependency. A field that is always present carries no information. + ...(embeddingStage(stages.get(error)) && embeddingHost(context.env) + ? { embedding_host: embeddingHost(context.env) } + : {}), + ...(embeddingStage(stages.get(error)) && context.env.NMG_EMBED_MODEL + ? { embedding_model: context.env.NMG_EMBED_MODEL } + : {}), // NMG_DEBUG_ERRORS=1 surfaces the exception name/message for diagnosis; the // default record still carries no exception text, stack or request content. ...(context.env.NMG_DEBUG_ERRORS === "1" diff --git a/onlion/backend/worker.mjs b/onlion/backend/worker.mjs index 35bbf5c8..8bb7eeea 100644 --- a/onlion/backend/worker.mjs +++ b/onlion/backend/worker.mjs @@ -1335,10 +1335,29 @@ function addClauseContributions(contributions, clauses) { * own loop with its own deadline branches. It mutates `contributions` and `appendedById` * in place because the attribution across the whole request (all partitions plus the * pending entries) is one set of totals, not a per-partition stat. */ +/** Errors that mean "this partition cannot be read right now" rather than "the request is invalid". + * + * A timeout on the object store, a reset connection, a replaced snapshot: all of them cost one + * partition, not the answer. Anything else still propagates, because a bug must stay visible. */ +function unreadablePartition(error) { + const code = String(error?.code ?? ""); + return ( + code === "snapshot_changed" || + code === "dependency_timeout" || + code === "embedding_timeout" || + code === "operation_aborted" || + error?.name === "TimeoutError" || + error?.name === "AbortError" || + /ECONNRESET|ECONNREFUSED|ETIMEDOUT|socket hang up/i.test(String(error?.message ?? "")) + ); +} async function readSearchCandidates(env, getSqlite, { manifest, queries, topK, appendOnly, features, client, started, contributions, appendedById }) { const modes = new Set(); let candidates = []; let partial = false; + /** Why the page is short, when it is: the error code of the first partition that could not be read. */ + let degraded = null; + let skipped = 0; const searchDeadline = Number(env.NMG_SEARCH_DEADLINE_MS) >= 0 ? Number(env.NMG_SEARCH_DEADLINE_MS) @@ -1348,7 +1367,14 @@ async function readSearchCandidates(env, getSqlite, { manifest, queries, topK, a partial = true; break; } - const result = await runPart( + // A partition that cannot be read must not turn a question into a 503: the harness treats a + // 5xx on /search as a failed attempt, while a shorter page still scores. 2026-10-30 + // 20:18-20:20 was exactly this - stage=partition_download, dependency_timeout, 29-31 s, four + // consecutive 503s on /search while /add answered 200 on the same instance. /add degrades; + // this is the read path's equivalent. The page is marked partial and names the reason. + let result; + try { + result = await runPart( env.MEMORY, manifest.parts[i], await getSqlite(), @@ -1366,6 +1392,16 @@ async function readSearchCandidates(env, getSqlite, { manifest, queries, topK, a }; }, ); + } catch (error) { + if (!unreadablePartition(error)) throw error; + partial = true; + degraded = degraded ?? (error.code ?? "partition_unavailable"); + skipped += 1; + // Two failures in a row is a storage problem, not one bad object: stop paying the timeout + // per partition and answer with what has already been read. + if (skipped >= 2) break; + continue; + } // A receipt that still lives in a legacy partition is replayed by the fold, the write // path; the read path no longer copies it anywhere. modes.add(result.response.retrievalMode); @@ -1376,7 +1412,7 @@ async function readSearchCandidates(env, getSqlite, { manifest, queries, topK, a candidates.sort((a, b) => b.score - a.score || a.id.localeCompare(b.id)); candidates = candidates.slice(0, topK); } - return { candidates, modes, partial }; + return { candidates, modes, partial, degraded }; } async function search(env, input) { @@ -1429,7 +1465,12 @@ async function search(env, input) { let candidates = []; await warmClauseVectors(client, features, manifest.parts); const persistence = { inline_delta_saves: 0, full_snapshot_saves: 0, changed_pages: 0 }; - const { candidates: pageCandidates, modes: modesRead, partial: partialRead } = + const { + candidates: pageCandidates, + modes: modesRead, + partial: partialRead, + degraded, + } = await readSearchCandidates(env, getSqlite, { manifest, queries, @@ -1467,6 +1508,7 @@ async function search(env, input) { data: candidates, retrieval_mode: modes.has("records") ? "records" : "lexical", partial, + ...(degraded ? { degraded } : {}), timings: { totalMs: Date.now() - started, partitions: manifest.parts.length, diff --git a/onlion/scripts/test-backend.mjs b/onlion/scripts/test-backend.mjs index 0920350a..b82e03ef 100644 --- a/onlion/scripts/test-backend.mjs +++ b/onlion/scripts/test-backend.mjs @@ -762,6 +762,40 @@ print(json.dumps(r))`, console.log( "PASS: read-only search leaves manifest, partition and counters untouched; concurrent searches preserve state; Add compaction, cold restart.", ); + // 2026-10-30 20:18-20:20: four /search answered 503 at stage=partition_download while /add kept + // returning 200 on the same instance. A partition that cannot be read must cost a shorter page, + // not the answer - the harness treats a 5xx on /search as a failed attempt. + { + const brokenUser = "unreadable-partition"; + for (let index = 0; index < 3; index += 1) + await call("a", "/add", { + user_id: brokenUser, + request_id: "broken-" + index, + messages: [{ content: "record " + index + " for the unreadable partition" }], + }); + // Force a fold so the records live in a partition object rather than in the log. + const drained = await call("a", "/admin/fold?user_id=" + brokenUser, {}, "test-key", owner); + assert.equal(drained.status, 200, JSON.stringify(drained)); + // `bucket` was captured before the fixture was disposed and restarted, so its proxy is dead: + // fetch a live one, or the assertion fails with an opaque #assertSafe error. + const liveBucket = await mf.getR2Bucket("MEMORY", "a"); + const brokenManifest = await (await liveBucket.get(manifestPath(brokenUser))).json(); + assert.ok(brokenManifest.parts.length > 0, "the fold must have produced a partition"); + const victim = brokenManifest.parts[0].key; + assert.ok(victim, "the partition must have a key"); + await liveBucket.delete(victim); + const degraded = await call("a", "/search", { + user_id: brokenUser, + query: "unreadable partition record", + top_k: 10, + }); + assert.equal(degraded.status, 200, JSON.stringify(degraded)); + assert.equal(degraded.body.partial, true, "a short page must say it is short"); + assert.equal(degraded.body.degraded, "snapshot_changed"); + } + console.log( + "PASS: a partition that cannot be read yields 200 with partial/degraded instead of a 503.", + ); assert.equal( ( await call( From 5e4813a980fc804abdf634baa888164d35e6bba0 Mon Sep 17 00:00:00 2001 From: wefio <48851810+wefio@users.noreply.github.com> Date: Fri, 30 Oct 2026 20:36:28 +0800 Subject: [PATCH 2/2] docs(decision): an unreadable partition shortens the page, not the answer --- ...search-degrades-on-unreadable-partition.md | 79 +++++++++++++++++++ ...egrades-on-unreadable-partition.terms.yaml | 4 + ...-degrades-on-unreadable-partition.zh-CN.md | 54 +++++++++++++ 3 files changed, 137 insertions(+) create mode 100644 docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.md create mode 100644 docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.terms.yaml create mode 100644 docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.zh-CN.md diff --git a/docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.md b/docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.md new file mode 100644 index 00000000..4bfcf57f --- /dev/null +++ b/docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.md @@ -0,0 +1,79 @@ +# An unreadable partition shortens the page, not the answer + +[简体中文](2026-10-30-search-degrades-on-unreadable-partition.zh-CN.md) · [Terms](2026-10-30-search-degrades-on-unreadable-partition.terms.yaml) + +**Status:** implemented +**Approved:** explicit + +## Problem + +At 20:18:31, 20:19:40, 20:20:21 and 20:20:57, `/search` answered **503** with +`stage=partition_download`, code `dependency_timeout`, after 29-31 s. On the same instance +(uptime 3699 → 3731 s, one user id) `/add` answered **200** at 24 s three seconds earlier. + +Three things follow from the record: + +| fact | meaning | +| ------------------------------------ | --------------------------------------------------------------------------------------------------------- | +| 503, not 120 s | a business failure, not a platform kill — a different class from every earlier window | +| `stage=partition_download` | the object-store body download timed out; retrieval never ran (`sqlite_loaded:false`, `live_databases:0`) | +| same instance, same user, `/add` 200 | the write path degrades and the read path did not | + +A 5xx on `/search` costs the harness a whole attempt. A short page costs one question's recall. +Those are not the same price, and the read path was the only surface paying the higher one. + +The same logs also showed `embedding_host`/`embedding_model` beside `stage=partition_download`, +which is why the two were suspected of sharing a dependency. They do not: the fields were attached +to **every** failure record whenever the environment configured an embedding provider. + +## Decision + +- `search` treats an unreadable partition as a missing one: the page is marked `partial: true` + with `degraded: `, and after **two consecutive** failures the loop stops paying the + timeout per partition and answers with what it has already read. +- "Unreadable" is an explicit list — `snapshot_changed`, `dependency_timeout`, + `embedding_timeout`, `operation_aborted`, `TimeoutError`, `AbortError`, connection resets. + Everything else still propagates: a bug in our own code must stay visible, not be folded into a + quieter answer. +- Failure records carry `embedding_host`/`embedding_model` **only when the failing stage is an + embedding stage**. A field that is always present carries no information. + +## Evidence + +| before | after | +| ---------------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------ | +| delete a folded partition, search → 5xx (the suite surfaced it as a failure) | search → **200**, `partial: true`, `degraded: "snapshot_changed"` — pinned in `test-backend.mjs` | +| 4 × 503 in 2.5 min, 29-31 s each, while `/add` answered 200 | the same condition now answers in one partition timeout instead of failing the request | +| `partition_download` failures reported `embedding_host` | that field appears only for embedding stages | + +## What this does and does not establish + +- It does **not** diagnose why the partition download took 29-31 s. The write path was uploading + snapshots and the search path was downloading them on the same instance while the embedding calls + crossed to `ap-southeast-1`; a saturated egress or object-store throttling both fit, and neither is + proven. This change bounds the blast radius, not the cause. +- It does not make a degraded page score well. Two unreadable partitions out of five still mean + three partitions of recall — better than a failed attempt, not equal to a healthy read. +- The two-consecutive-failure stop is a judgement: it converts "N partitions × timeout" into two + timeouts, which is what keeps a degraded search inside the 25 s deadline. + +## Alternatives considered + +- **Retry the download more times.** `cos-bucket.mjs` already retries 429/5xx twice; a timeout is + deliberately not retried (see `2026-10-29-embedding-invocation-budget`), because retrying a + stalled dependency inside an invocation multiplies the time to fail. +- **Return 503 with Retry-After** so the harness retries. The harness records a 5xx as a failed + attempt for that run; a partial page at least reaches scoring. +- **Cache the partition between the write and the read.** A write path already uploads it; caching + the same bytes for the read would double the memory the request already pays for, on a platform + that starts a fresh isolate per request. + +## Consequences + +- `search`'s response can now contain `degraded`, alongside the existing `partial`. A caller that + ignores both still gets a well-formed page. +- The stop-after-two rule makes the worst case predictable: two partition timeouts, not one per + partition. +- Failure records lose `embedding_host` on non-embedding failures. That is the point, but it also + means an incident timeline that used to have the field everywhere will now have it only where it + applies. diff --git a/docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.terms.yaml b/docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.terms.yaml new file mode 100644 index 00000000..c49d3412 --- /dev/null +++ b/docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.terms.yaml @@ -0,0 +1,4 @@ +version: 2 +terms: [] +references: + - docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.md diff --git a/docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.zh-CN.md b/docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.zh-CN.md new file mode 100644 index 00000000..6542a9b4 --- /dev/null +++ b/docs/decisions/implemented/2026-10-30-search-degrades-on-unreadable-partition.zh-CN.md @@ -0,0 +1,54 @@ +# 分区读不出来，页面变短，而不是整个答案失败 + +[English](2026-10-30-search-degrades-on-unreadable-partition.md) · [Terms](2026-10-30-search-degrades-on-unreadable-partition.terms.yaml) + +**Status:** implemented +**Approved:** explicit + +## 问题 + +20:18:31、20:19:40、20:20:21、20:20:57，`/search` 返回 **503**，`stage=partition_download`、`dependency_timeout`，耗时 29–31 秒。同一实例（uptime 3699 → 3731 秒、同一 user id）在 3 秒前的 `/add` 返回 **200**，耗时 24 秒。 + +三条推论： + +| 事实 | 含义 | +| -------------------------- | ----------------------------------------------------------------------------------- | +| 503，不是 120 s | 业务侧失败，不是平台掐断——与此前每个窗口都不是同一类 | +| `stage=partition_download` | 对象存储的 body 下载超时，检索根本没跑（`sqlite_loaded:false`、`live_databases:0`） | +| 同实例同用户 `/add` 200 | 写路径会降级，读路径不会 | + +对评测而言，`/search` 的 5xx 等于整次尝试失败；短页面只损失一题的召回。两者代价不同，而读路径是唯一付高价的那个面。 + +同一批日志还把 `embedding_host`/`embedding_model` 挂在 `stage=partition_download` 旁边，这正是"两者共用依赖"的误判来源——那两个字段其实是对**所有**失败一律附加的。 + +## 决策 + +- `search` 把一个读不出来的分区当作缺失分区：页面标 `partial: true` 并带 `degraded: <错误码>`；**连续两次**失败后停止按分区逐个付超时，用已读到的内容作答。 +- "读不出来"是一份明确清单——`snapshot_changed`、`dependency_timeout`、`embedding_timeout`、`operation_aborted`、`TimeoutError`、`AbortError`、连接重置。其余错误照旧外抛：我们自己代码的 bug 必须保持可见，不能被折进一个更安静的回答里。 +- 失败记录只在**失败阶段属于嵌入时**附加 `embedding_host`/`embedding_model`。永远存在的字段等于没有信息。 + +## 证据 + +| 改前 | 改后 | +| ------------------------------------------------------- | ----------------------------------------------------------------------------------------------- | +| 删掉一个已折叠的分区后 search → 5xx（套件里表现为失败） | search → **200**、`partial: true`、`degraded: "snapshot_changed"`，已在 `test-backend.mjs` 钉住 | +| 2.5 分钟内 4 次 503、每次 29–31 秒，而 `/add` 返回 200 | 同样条件下只付一次分区超时，不再让请求失败 | +| `partition_download` 失败也报 `embedding_host` | 该字段只在嵌入阶段出现 | + +## 这确立了什么、没有确立什么 + +- 它**没有**诊断出分区下载为何要 29–31 秒。写路径在上传快照、读路径在同一下载，同时嵌入调用跨境到 `ap-southeast-1`；出口带宽饱和与对象存储限流都符合，但都未被证明。这次改的是影响半径，不是病因。 +- 它不会让降级的页面得高分。五个分区里两个读不出来，仍然只有三个分区的召回——比整次失败好，但不等于健康。 +- "连续两次即停"是判断：把"N 个分区 × 超时"压成两次超时，这是让降级检索留在 25 秒截止之内的代价。 + +## 考虑过的替代方案 + +- **多retry 几次下载**：`cos-bucket.mjs` 已对 429/5xx 重试两次；超时是刻意不重试的（见 `2026-10-29-embedding-invocation-budget`），因为在一次调用里重试一个停滞依赖，乘出来的是失败耗时。 +- **返回 503 + Retry-After 让评测端重试**：harness 把 5xx 记为这次运行的失败尝试；而 partial 页面至少进入评分。 +- **在写路径与读路径之间缓存分区**：写路径已经上传过它；为读缓存同样的字节，会把请求已经付过的内存再翻一倍，而这个平台每请求一个新 isolate。 + +## 后果 + +- `search` 的响应里除 `partial` 之外可能出现 `degraded`。忽略两者的调用方仍拿到结构完整的页面。 +- "两次即停"让最坏情况可预测：两次分区超时，而不是每个分区一次。 +- 失败记录在非嵌入阶段不再带 `embedding_host`。这正是目的，但也意味着过去"处处都有该字段"的事故时间线，之后只在适用的地方有。