Skip to content

Commit a75ddba

Browse files
fix(rest): a hook's onError abort is no longer logged as an unhandled error (#27690)
<!-- claude-projects-attribution: {"github_login":"os-sales"} --> _Requested by **Sales** · [project thread](https://claude.ai/code/project/chan_01D5bWFY3rFzgJcytD5gD4Uu?thread=cmsg_01D5bWFY3rFzgJcytD5gD4UuPMZ8BHWtPf6nBTp51qSM64)_ Refs #27508 (log half) Clause-②: no Metadata-protocol: none Skills-docs: none ## 维护者速读 - **改了什么**:hook 以 `onError: 'abort'`(默认)抛出业务错误中止写入时,服务端不再把它记成 `[REST] Unhandled error`;线上应答(400、正文、信封)一个字节都不变。 - **为什么改**:这是路由已经答复给调用方的拒绝,不是故障;运维在 error 日志里分不清「有意中止」和「真崩溃」。分诊裁定只做日志这一半,错误码那一半另走 spec 车道。 - **风险与回滚**:只影响日志判定,不动应答;豁免只认「沙箱体抛出、非崩溃、未声明 code、4xx」的拒绝,崩溃和其他来源的无码 4xx 照旧记录。回滚即 revert 本 PR。 - **先看**:`packages/rest/src/error-response.ts` 的 `isSandboxBodyRefusal` 与 `logUnexpectedRouteError` 调用处;`packages/rest/src/rest-declared-client-refusal-log.test.ts` 新增的 describe 块。 - **两分钟验证**:`pnpm --filter @objectstack/rest exec vitest run src/rest-declared-client-refusal-log.test.ts`,预期 16 条全绿(其中 hook 中止两扇门都无 Unhandled 行,三条对照照旧记录)。 - **需要你做的**:无,席位落地。 ## What changes - `packages/rest/src/error-response.ts`: a new predicate, `isSandboxBodyRefusal`, joins the three reads `logUnexpectedRouteError` already makes. It is true when all three hold: 1. the answer is in the 4xx band; 2. the error carries a sandboxed body's business sentence (`sandboxBusinessMessage`: `innerMessage` set, and not a native-error crash); and 3. the body declared no code (`resolveThrownHttpError(...).declaredCode` is absent). This is read off the thrown error, not the answer, so a code the door itself adds to an undeclared abort later does not make the abort loud again. - Nothing on the wire moves. `resolveErrorResponse`, `mapDataError` and `packages/types` are untouched. The ADR-0112 ledger is not touched and no code is minted; that half belongs to the spec lane. - Operators keep a line for each abort: the BodyRunner already logs every body refusal at `info` (`[BodyRunner] sandboxed hook refused`). The error-level line removed here was the second line for one ordinary refusal. - Docblocks on `isExpectedRouteError` and `isDeclaredClientRefusal` that said the sandbox unwrap's un-coded 400 "is still logged" now point at the new read. - Changeset: `@objectstack/rest` patch. ## Tests - `packages/rest/src/rest-declared-client-refusal-log.test.ts`. The standing control "an un-coded business-rule 400 (a sandboxed hook refusal) logs" pinned the old verdict, so it moves into a new block that pins what triage ruled. It goes through the real route handlers (`POST /api/v1/data/:object` through `mapDataError` + `logUnexpectedRouteError`, and `PUT /api/v1/meta/:type/:name` through `handleRouteError`): - a hook abort answers exactly `{ error: 'boom abort', object: 'qa_media' }` at 400 on the data door and `{ error: 'boom abort' }` at 400 on the meta door, both `toEqual`, and logs no `[REST] Unhandled error` line; - CONTROL: a genuine `TypeError` at the same door is a 500 and is logged, checked by identity; - CONTROL: an un-coded 400 from a producer that is not a sandboxed body is still logged; - CONTROL: a sandboxed body that threw an unregistered code is still logged; - the existing loud controls are unchanged, including the sandbox crash that declared a 4xx envelope (500, logged) and the registered code on an undeclared status. - `packages/qa/dogfood/test/object-hook-lifecycle-scratch.dogfood.test.ts` acceptance[6] is the real door with a real QuickJS `SandboxError`: a `beforeInsert` hook declared `onError: 'abort'` throws. It now also asserts the exact body `{ error, object }` and that the request logs no `[REST] Unhandled error` line. <details><summary>Ablation 1: unit route pin (remove the call-site exemption, then restore)</summary> `scripts/ablation-replace.mjs`, with the anchor on the `&& !isSandboxBodyRefusal(error, resolved)` call-site line, at head `2e4954fd`: ``` ablation-replace: ok mutation landed: anchor 1 -> 0, blob 10b6ede -> 416dfa06aa9b × POST /data/:object answers the same code-less 400 and prints no "[REST] Unhandled error" 13ms × the handleRouteError door agrees: same answer it always gave, no unhandled line 3ms AssertionError: expected [ [ '[REST] Unhandled error:', …(1) ] ] to have a length of +0 but got 1 Tests 2 failed | 14 passed (16) ablation-replace: ok restored: blob == HEAD (10b6ede) and `git diff HEAD` is empty ``` Both tests fail only at the log assertion. Their status and exact-body assertions come first and pass under the ablation, which is the pre-change logic. So the wire answer is the same as before. </details> <details><summary>Ablation 2: real-door dogfood pin (mutate, rebuild rest dist, preflight, run, restore, rebuild, preflight)</summary> ``` ablation-replace: ok mutation landed: anchor 1 -> 0, blob e019a04 -> fcf8c33d2a68 MUTATE-BUILD-EXIT=0 ✓ dist/: marker absent from all 6 built files -- the artifact the suite consumes no longer carries it. MUTATED-RUN-EXIT=1 × acceptance[6], negative[0]: a throwing beforeInsert under abort refuses the POST and lands no row 150ms AssertionError: expected [ Array(1) ] to have a length of +0 but got 1 Tests 1 failed | 3 passed (4) ablation-replace: ok restored: blob == HEAD (e019a04) and `git diff HEAD` is empty RESTORE-BUILD-EXIT=0 ✓ dist/: marker present in 2 built files ✓ tree: working tree clean against HEAD ``` This ran at `17713e7b`. The later commit `2e4954fd` changes only condition 3 of the predicate, not the call-site anchor; ablation 1 was re-run on it. </details> ## Acceptance notes - **Scope of the marker.** `SandboxError` carries no body kind, so a sandboxed action's code-less business refusal answered at a data door is quiet too. It is the same shape and the same answer. A message-prefix read (`hook '…' threw:`) would tell the two apart, but that would be a text heuristic, so it was not used. - **Overlap with the code half.** The open draft #27667 (the spec-lane card for the code half) edits the same test file. It changes the control this PR moves (it asserts `HOOK_ABORTED` and "still logs"), so a text conflict in `rest-declared-client-refusal-log.test.ts` is expected for whichever PR lands second. The predicate reads the thrown error's code, not the answer's, so a door-assigned `HOOK_ABORTED` keeps the abort quiet. When that PR rebases, its "still logs" line should become "quiet". - The undeclared-code-under-a-catalogue case (`undeclaredHookRefusalAtRun`) becomes a `SandboxError` with no `innerMessage`. That is the sandbox's own fault (500), so it stays loud, unchanged. ## Verification All local readings below are at head `2e4954fd` unless noted. <details><summary>Package tests, typecheck, lint</summary> - `pnpm --filter @objectstack/rest test`: `Test Files 336 passed (336)`, `Tests 6602 passed | 326 skipped (6928)`, exit 0. - `pnpm --filter @objectstack/rest typecheck`: exit 0. - `pnpm --filter @objectstack/dogfood exec vitest run --maxWorkers=2 test/object-hook-lifecycle-scratch.dogfood.test.ts`: `Tests 4 passed (4)`, exit 0. - eslint (`--no-inline-config`) on `packages/rest` and the dogfood test file: exit 0. </details> <details><summary>Derived gate families</summary> `node scripts/pm/dispatch-gates.mjs --commands --repo objectstack-ai/objectstack` derived 64 families at the final change set. Each was run with its exit code captured before any pipe, and all 64 exited 0. The run was split across a container restart: the families not yet run were re-run at the same head, `2e4954fd`. `check:type-check-debt` was run whole under the verify lock after a queue timeout gave it PREREQUISITE NOT MET (exit 3). Its re-run exited 0. `check:dual-build-cjs-loads` exited 0 once a full build had run, after an earlier PREREQUISITE NOT MET (exit 3). Reconciliation, `--ran`: ``` Run reconciliation — 64 derived, 64 run, 0 NOT-MEASURED, 0 UNRUN. ✓ dispatch-gates --ran: 64 derived famil(ies) accounted for — 64 run, 0 NOT-MEASURED (a DERIVED zero — all 64 recorded an exit code and none of them is 3). ``` The full dogfood battery is not derived: there is no `!` in the title and no `(narrowing)` arm. The repo-wide `pnpm lint` and the rest of the farm are left to CI. </details> --- _Generated by [Claude Code](https://claude.ai/code/session_01L6bhgUCizoYWQVJWjhdR6F)_ 🤖 Generated with [Claude Code](https://claude.com/claude-code) https://claude.ai/code/session_01L6bhgUCizoYWQVJWjhdR6F --------- Co-authored-by: Claude <noreply@anthropic.com>
1 parent bfdaba4 commit a75ddba

4 files changed

Lines changed: 141 additions & 18 deletions

File tree

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,12 @@
1+
---
2+
'@objectstack/rest': patch
3+
---
4+
5+
fix(rest): a sandboxed hook's code-less `onError: 'abort'` refusal is no longer logged as `[REST] Unhandled error`
6+
7+
Clause-②: no
8+
Metadata-protocol: none
9+
10+
A hook that aborts its write with a business `throw` (`onError: 'abort'`, the default) is a refusal the route already answered: the data door replies with the hook's own sentence at 400. The server still printed `[REST] Unhandled error: SandboxError` and a stack for every such abort, beside the BodyRunner's own `sandboxed hook refused` line, so operators reading the error log could not tell an intended abort from a crash.
11+
12+
The route log now recognises that refusal by the sandbox marker every door already reads (the body's unwrapped sentence, which a crash never has) on a 4xx answer from a body that threw no code, and stays quiet for it. Nothing changes on the wire: status, body and envelope are byte-identical. A sandbox crash, a plain un-coded 4xx from any other producer, and a sandboxed body that threw a code (judged as a coded refusal, as before) are still logged.

‎packages/qa/dogfood/test/object-hook-lifecycle-scratch.dogfood.test.ts‎

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -119,9 +119,20 @@ describe('records-forms.object-hook-lifecycle — the scratch hook variants over
119119

120120
it('acceptance[6], negative[0]: a throwing beforeInsert under abort refuses the POST and lands no row', async () => {
121121
expect(await stack.rows(ABORT, { name: 'ohl-abort' })).toHaveLength(0);
122-
const res = await call('POST', `/data/${ABORT}`, { name: 'ohl-abort' });
122+
const log = captureLog();
123+
let res: Answer;
124+
try {
125+
res = await call('POST', `/data/${ABORT}`, { name: 'ohl-abort' });
126+
} finally {
127+
log.restore();
128+
}
123129
expect(res.status, res.text).toBe(400);
124130
expect(res.text).toContain(ABORT_MSG);
131+
// [#27508] The abort is a refusal the route answered: the wire answer is
132+
// the hook's own sentence, code-less, exactly as before, and the server
133+
// does not log it as an unhandled error.
134+
expect(res.json).toEqual({ error: ABORT_MSG, object: ABORT });
135+
expect(log.matching('[REST] Unhandled error')).toHaveLength(0);
125136
expect(await stack.rows(ABORT, { name: 'ohl-abort' })).toHaveLength(0);
126137
});
127138

‎packages/rest/src/error-response.ts‎

Lines changed: 63 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -866,9 +866,10 @@ function isExpectedQueryRejection(body: Record<string, unknown> | undefined): bo
866866
* 500, which this predicate cannot treat as expected at all
867867
* (`isExpectedDataStatus` names 502/503 and nothing else in the 5xx band), so
868868
* the handler bug is loud STRUCTURALLY rather than by this sentence. The
869-
* narrowness still matters for what remains in the un-coded 4xx band — the
870-
* sandbox unwraps' business-rule 400s — and for the next author tempted to
871-
* simplify the predicate down to a status range.
869+
* narrowness still matters for what remains in the un-coded 4xx band — every
870+
* producer's un-coded 4xx beside the sandbox unwraps' business-rule 400s, which
871+
* are quiet only by their own marker read ({@link isSandboxBodyRefusal}) — and
872+
* for the next author tempted to simplify the predicate down to a status range.
872873
*
873874
* [#4886] Every route catch now decides through this one function. Before, the
874875
* metadata family logged unconditionally — the designer's `?state=draft` probe
@@ -926,9 +927,10 @@ export function isExpectedRouteError(status: number, body: Record<string, unknow
926927
* `resolveThrownHttpError`, the one rule every door reads (`status` or
927928
* `statusCode`, or the 400 a validation-shaped throw declares by shape).
928929
* A status the DOOR supplied is not a declaration: the sandbox unwrap's
929-
* default 400 fails here, so the un-coded business-rule 400s the predicate
930-
* above stays narrow for are still logged, and so is a registered code that
931-
* arrived with no status (half an envelope).
930+
* default 400 fails here, and so does a registered code that arrived with
931+
* no status (half an envelope). The un-coded business-rule 400 a sandboxed
932+
* body's refusal answers is quiet by its OWN read instead —
933+
* {@link isSandboxBodyRefusal} — not by this one.
932934
* 3. **The producer's own code is the wire `code`.** That holds exactly when
933935
* the spelling is a member of `StandardErrorCode` ∪ the ADR-0112 ledger —
934936
* anything else is demoted to `declaredCode` beside a status-derived `code`
@@ -957,6 +959,55 @@ function isDeclaredClientRefusal(
957959
&& resolved.body?.code === thrown.declaredCode;
958960
}
959961

962+
/**
963+
* [#27508] Is this answer a sandboxed body's own REFUSAL — a hook aborting the
964+
* write under `onError: 'abort'` (the default) with a business `throw` — that
965+
* the route delivered to the caller as the un-coded 4xx it always answers?
966+
*
967+
* Triage ruled the log half on its own: "an undeclared hook `onError` abort is
968+
* a refusal the route answered", so it is not logged as `[REST] Unhandled
969+
* error`. The code half (whether such an abort should carry a ledgered
970+
* ADR-0112 code) is a separate spec-lane decision, so this changes NOTHING on
971+
* the wire: status, body and envelope are exactly what
972+
* {@link resolveErrorResponse} already answered.
973+
*
974+
* The recognition is the marker every door already reads, ⛔ not a message
975+
* pattern: {@link sandboxBusinessMessage} answers the unwrapped sentence only
976+
* for a sandbox ORIGIN (`innerMessage` set — the runner's own faults leave it
977+
* unset) that is not a CRASH (a native-error sentence is declined). The
978+
* operator keeps a line for it: the BodyRunner logs every body refusal at
979+
* `info` (`sandboxed hook refused`), so the error-level line removed here was
980+
* the second line for one ordinary refusal.
981+
*
982+
* The three conditions, each keeping the exemption off a genuine fault:
983+
*
984+
* 1. **The answer is in the 4xx band.** A crash is answered
985+
* `UNCLASSIFIED_FAULT`'s 500 and never reaches here; a declared 5xx keeps
986+
* its own `refusal: true` rule.
987+
* 2. **A sandboxed body's business sentence** ({@link sandboxBusinessMessage}).
988+
* A plain un-coded 4xx from any other producer — a handler that set
989+
* `status: 400` and nothing else — fails here and stays loud.
990+
* 3. **The body declared no code** — `declaredCode` from
991+
* `resolveThrownHttpError`, the same read {@link isDeclaredClientRefusal}
992+
* makes. A body that threw a code is judged by that predicate like every
993+
* other producer, so a code the ledger does not know, or a registered code
994+
* on a status the producer did not declare, is still logged exactly as
995+
* before. ⛔ Read off the THROWN error, not the answer: a code the door
996+
* itself adds to an undeclared abort's answer is the door's, not the
997+
* body's, and does not turn this refusal back into a logged fault.
998+
*
999+
* The marker carries no body KIND, so a sandboxed action's code-less business
1000+
* refusal at a data door is quiet too: the same refusal, the same answer.
1001+
*/
1002+
function isSandboxBodyRefusal(
1003+
error: any,
1004+
resolved: { status: number; body: Record<string, unknown> },
1005+
): boolean {
1006+
if (resolved.status < 400 || resolved.status >= 500) return false;
1007+
return sandboxBusinessMessage(error) !== undefined
1008+
&& resolveThrownHttpError(error, resolved.status).declaredCode === undefined;
1009+
}
1010+
9601011
/**
9611012
* Log "[REST] Unhandled error" only when `resolved` is a genuine fault. For
9621013
* catch blocks that must emit their own response shape (the CRUD handlers that
@@ -985,11 +1036,16 @@ function isDeclaredClientRefusal(
9851036
* band is already the caller's — `ApiErrorSchema.refusal`'s own table says the
9861037
* field is "redundant on a 4xx". Two declarations, one per band, each read off
9871038
* the thrown error; neither is a list of codes or of statuses.
1039+
*
1040+
* [#27508] And a sandboxed body's un-coded business refusal — a hook's
1041+
* `onError: 'abort'` — is a refusal the route answered:
1042+
* {@link isSandboxBodyRefusal}. Log only; the wire answer is untouched.
9881043
*/
9891044
export function logUnexpectedRouteError(error: any, resolved: { status: number; body: Record<string, unknown> }): void {
9901045
if (!isExpectedRouteError(resolved.status, resolved.body)
9911046
&& declaredRefusalMessage(error) === undefined
992-
&& !isDeclaredClientRefusal(error, resolved)) {
1047+
&& !isDeclaredClientRefusal(error, resolved)
1048+
&& !isSandboxBodyRefusal(error, resolved)) {
9931049
logError('[REST] Unhandled error:', error);
9941050
return;
9951051
}

‎packages/rest/src/rest-declared-client-refusal-log.test.ts‎

Lines changed: 54 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -214,16 +214,6 @@ describe('[#23932] controls that stay LOUD — the verdict is not "any 4xx"', ()
214214
}
215215
});
216216

217-
it('an un-coded business-rule 400 (a sandboxed hook refusal) logs', async () => {
218-
const hookRefusal = Object.assign(new Error("hook 'guard' threw: Error: Opportunity is closed."), {
219-
innerMessage: 'Opportunity is closed.',
220-
});
221-
for (const res of await expectLoudAtBothDoors(hookRefusal)) {
222-
expect(res.statusCode).toBe(400);
223-
expect(res.body.code).toBeUndefined();
224-
}
225-
});
226-
227217
it('a declared 400 with no code (half an envelope) logs', async () => {
228218
const uncoded = Object.assign(new Error('bad input'), { status: 400 });
229219
for (const res of await expectLoudAtBothDoors(uncoded)) {
@@ -270,6 +260,60 @@ describe('[#23932] controls that stay LOUD — the verdict is not "any 4xx"', ()
270260
});
271261
});
272262

263+
describe('[#27508] a hook `onError: abort` is a refusal the route answered — quiet, wire unchanged', () => {
264+
/**
265+
* The card's reproduction: a sandboxed `beforeInsert` hook declared
266+
* `onError: 'abort'` throws `boom abort`. The runner raises a `SandboxError`
267+
* (`.message` the debug wrapper, `.innerMessage` the hook's own sentence)
268+
* and the abort policy rethrows it unchanged, so this is the exact value
269+
* both doors catch.
270+
*/
271+
const hookAbort = () => Object.assign(new Error("hook 'qa_abort' threw: Error: boom abort"), {
272+
name: 'SandboxError',
273+
innerMessage: 'boom abort',
274+
});
275+
276+
it('POST /data/:object answers the same code-less 400 and prints no "[REST] Unhandled error"', async () => {
277+
const res = await postRecord(serverRejecting(hookAbort()));
278+
expect(res.statusCode).toBe(400);
279+
expect(res.body).toEqual({ error: 'boom abort', object: 'qa_media' });
280+
expect(unhandledLogs()).toHaveLength(0);
281+
});
282+
283+
it('the handleRouteError door agrees: same answer it always gave, no unhandled line', async () => {
284+
const res = await putMeta(serverRejecting(hookAbort()));
285+
expect(res.statusCode).toBe(400);
286+
expect(res.body).toEqual({ error: 'boom abort' });
287+
expect(unhandledLogs()).toHaveLength(0);
288+
});
289+
290+
it('CONTROL — a genuine unexpected error at the same door is still logged, by identity', async () => {
291+
const bug = new TypeError("Cannot read properties of undefined (reading 'name')");
292+
const res = await postRecord(serverRejecting(bug));
293+
expect(res.statusCode).toBe(500);
294+
expect(unhandledLogs()).toHaveLength(1);
295+
expect(unhandledLogs()[0][1]).toBe(bug);
296+
});
297+
298+
it('CONTROL — an un-coded 400 from a producer that is NOT a sandboxed body is still logged', async () => {
299+
const uncoded = Object.assign(new Error('bad input'), { status: 400 });
300+
const res = await postRecord(serverRejecting(uncoded));
301+
expect(res.statusCode).toBe(400);
302+
expect(res.body.code).toBeUndefined();
303+
expect(unhandledLogs()).toHaveLength(1);
304+
});
305+
306+
it('CONTROL — a sandboxed body that threw an UNREGISTERED code is judged as a coded refusal and still logged', async () => {
307+
const coded = Object.assign(new Error("hook 'qa_abort' threw: Error: nope"), {
308+
name: 'SandboxError', innerMessage: 'nope', code: 'QA_NOT_A_REGISTERED_CODE', status: 400,
309+
});
310+
const res = await postRecord(serverRejecting(coded));
311+
expect(res.statusCode).toBe(400);
312+
expect(res.body.declaredCode).toBe('QA_NOT_A_REGISTERED_CODE');
313+
expect(unhandledLogs()).toHaveLength(1);
314+
});
315+
});
316+
273317
describe('[#23932] a control that stays QUIET — the existing expected outcomes', () => {
274318
it('VALIDATION_FAILED 400 and a structured 404 still print nothing', async () => {
275319
const validation = Object.assign(new Error('bad'), { code: 'VALIDATION_FAILED', status: 400 });

0 commit comments

Comments
 (0)