runtime: an app hook's intentional business refusal is logged as ERROR with a stack trace, twice per refused action

Filing class: ① product defect (operator-visible) — reach: public door, measured on 18.1.0 with objectstack-ai/hotclm main (pnpm demo:zh); the two log calls are unchanged on objectstack main. Reader: the runtime lane (packages/runtime/src/sandbox/body-runner.ts).

Symptom

A user presses an action the app's state machine refuses on purpose — e.g. hotclm's 发起签署 without a clean version, answered 422 INVALID_STATE "A current clean version is required before signing.". The server log gets two ERROR lines with full stacks for that one ordinary refusal:

ERROR [BodyRunner] sandboxed hook threw {"hook":"contract_state_machine","error":{"message":"hook 'contract_state_machine' threw: Error: A current clean version is required before signing.","stack":"SandboxError: …
ERROR [BodyRunner] sandboxed action threw {"action":"start_signing","error":{"message":"action 'start_signing' threw: SandboxError: hook 'contract_state_machine' threw: …","stack":"…

In one 40-minute browser pass, 6 of the server's ERROR lines were these; none was a fault. An operator watching for ERROR cannot tell a refused click from a crashed hook.

Why

body-runner.ts:454 and :562 log every throw from a sandboxed hook/action at error and rethrow; the HTTP layer already maps the same throw to a 4xx business refusal. The action-level line repeats the hook-level one.

Expected

A throw the dispatcher answers as a 4xx (a business refusal) logs once, at info/warn without a stack; a throw that becomes a 5xx keeps error with its stack.

Dedupe: objectstack issues (2,000 most recently updated, all states) grepped for BodyRunner, sandboxed (hook|action) threw, business refusal … log — hits #25952, #24561, #24423, none about the log level.

Filed from the hotclm browser regression pass (2026-10-26).

Triage: first grade — `bug` · `priority:p2` · `domain:server` · `area:devpath` · `pm:queue` · triage seat · `session_01AavokzJ5DndAwitDXvKy4U` · 2026-10-26T14:53Z

⛔ Not a claim, ⛔ not a dispatch.

p2: an intentional business refusal is logged as ERROR with a stack, twice per refused action. That buries real errors and trips error-rate alerts in production. Log a refusal at info or warn, once, with the hook, action, code and status, and keep ERROR for a hook that actually throws. Same file as i18n: an app hook's business refusal has no translation key — a zh-CN user reads "A current clean version is required before signing." in English #26170 (body-runner.ts).

Generated by Claude Code

Claim: PM loop round 8 · card thread
Session: session_01R1q2xdtYgU6FKrZ7LgjPCC (the seat); the card thread is session_018jZoq6nbK2HEZ8a7BnDwG7
Account: os-project-manager (the seat's linked user; the card's assignee)
Branch: claude/project-thread-6lh3me (the card thread's harness-pinned branch; it names no issue, so this claim is the identity record)
Worktree: the card thread's own container checkout
Domain: domain:server
Seat: domain:server#1
Ruling-ref: triage first grade (2026-10-26T14:53Z). Log a business refusal (a throw the dispatcher answers as a 4xx) once, at info or warn, without a stack, naming the hook or action, the code and the status. A fault (5xx) keeps ERROR with its stack. Classify with the dispatcher's own 4xx predicate; ⛔ no second classifier. Every throw is still rethrown. Intake under 「p1 p2 处理完了，就可以处理 p3」 does not apply: this card is p2.
File surface: packages/runtime/src/sandbox/body-runner.ts (the two catch sites and a shared helper) plus its tests. ⛔ No packages/spec/** (stop on breach; explain in the report)
Container & model: S, mode:thread, default model and effort (set at thread open)
Clause-②: no
Metadata-protocol: none
Responsibility: one refused action writes two ERROR lines with stacks (body-runner.ts hook catch and action catch)
Thread-read: none
Premise: holds (read 2026-10-26T15:52Z at origin/main fbb75998ba: card open, unassigned, pm:queue, no claim; both catch sites still log at error)
Serial constraints cleared: no open PR touches body-runner.ts. #26170 (domain:spec, undispatched) will touch the same file later, so this diff stays at the catch sites; the dev re-measures before pr_create

Claim amendment: PM loop round 8 · card thread (supersedes 6420510502 by widening the file surface by one file; everything else stands)
Session: session_01R1q2xdtYgU6FKrZ7LgjPCC (the seat); the card thread is session_018jZoq6nbK2HEZ8a7BnDwG7
Account: os-project-manager (the seat's linked user; the card's assignee)
Branch: claude/project-thread-6lh3me (the card thread's harness-pinned branch; it names no issue, so this claim is the identity record)
Worktree: the card thread's own container checkout
Domain: domain:server
Seat: domain:server#1
Ruling-ref: triage first grade (2026-10-26T14:53Z). Log a business refusal (a throw the dispatcher answers as a 4xx) once, at info or warn, without a stack, naming the hook or action, the code and the status. A fault (5xx) keeps ERROR with its stack. Classify with the dispatcher's own 4xx predicate; ⛔ no second classifier. Every throw is still rethrown.
File surface: packages/runtime/src/sandbox/body-runner.ts (the two catch sites and a shared helper) and packages/runtime/src/sandbox/quickjs-runner.ts (about 15 lines: a module-level WeakSet marking a nested refusal relayed unchanged by the pump loop, read through isRelayedSandboxRefusal(), not exported from the package index; the seat agreed 2026-10-26T15:58Z, because only the runner still knows the throw is relayed and body-runner may not pattern-strip .message), plus their tests. ⛔ No packages/spec/** (stop on breach; explain in the report)
Container & model: S, mode:thread, default model and effort (set at thread open)
Clause-②: no
Metadata-protocol: none
Responsibility: one refused action writes two ERROR lines with stacks (body-runner.ts hook catch and action catch)
Thread-read: none
Premise: holds (read 2026-10-26T15:58Z at origin/main e6dfeb08fd: card open, pm:dispatched, assignee os-project-manager, this seat's claim the newest; the dev reproduced red first on main)
Serial constraints cleared: no open PR touches body-runner.ts or quickjs-runner.ts. #26170 (domain:spec, undispatched) will touch the same file later, so this diff stays at the catch sites; the dev re-measures before pr_create

os-dev-report

{
  "issue": 26153,
  "status": "done",
  "branch": "claude/project-thread-6lh3me",
  "pr": "https://github.com/objectstack-ai/objectstack/pull/26249",
  "session": "session_018jZoq6nbK2HEZ8a7BnDwG7",
  "premise_still_valid": true,
  "summary": "Both BodyRunner catches now call one helper, logBodyThrow. A throw whose mapDataError status is under 500 logs one info line ('[BodyRunner] sandboxed hook refused' / 'action refused') with appId, hook or action, the declared code, the status and the message, and no error object, so no stack. A 5xx keeps the old error line with the error. The outer catch writes nothing for a nested refusal relayed unchanged across the VM hop. That fact exists only in the runner's pump loop, so quickjs-runner.ts records such errors in a module WeakSet and exports isRelayedSandboxRefusal(); it is not re-exported from the package entry (claim amendment 6420650570). Repeated FAULTS: both lines are kept (hook and action), as before. Every throw is still rethrown, and no wire byte changes.",
  "tests": "Red first on main fbb75998: body-throw-log-level.test.ts 3 failed / 7 passed. The nested case recorded error '[BodyRunner] sandboxed hook threw' plus error '[BodyRunner] sandboxed action threw', both with stacks. After the fix: 10/10. Ablation: the relay-skip line deleted via scripts/ablation-replace.mjs (anchor 1 to 0, blob bfd61dd8ec74 to 43513b2871d9) reds only the nested case (1 failed / 9 passed); restored, git diff HEAD empty. The test imports src, so no dist leg. Final head a1db083d (rebased onto origin/main df8aac41, which moved mapDataError and the actions catch for #26031): runtime dep closure build, then pnpm --filter @objectstack/runtime typecheck and test: 457/457 files, 7422 passed, 19 skipped, lock VERDICT command-exit 0. eslint --no-inline-config on the 3 touched files: exit 0.",
  "gates": "Local, head a1db083d: dispatch-gates --commands derived 65; all 65 run with exit 0 (first pass on fbb75998 needed git fetch --unshallow for the check-plugin-teardown-shape self-test; check:dual-build-cjs-loads measured on the rebased head after the closure build); --ran: 65 run, 0 NOT-MEASURED, 0 UNRUN. CI check-runs on a1db083d at report time: 24 total, 21 in_progress, 1 success, 2 skipped, 0 failed.",
  "dogfood_battery": "n/a: no ! in the PR title and no (narrowing) arm",
  "mcp_calls": "0. No MCP GitHub calls; card, comments, PR and check-runs were read over public REST.",
  "api_writes": "2: pr_create via fleet-write relay (run 40363387279, PR #26249, read back 5342/5342 bytes and assignee os-project-manager), plus this os-dev-report comment via post-stamped on #26153. git push is not counted.",
  "open_questions": [],
  "out_of_scope_findings": [
    "carrier: none. Noted in Acceptance notes, not filed: a sandbox body throwing a 4xx-arm code with a DECLARED 5xx status is answered 4xx by /data and 5xx by /actions. That is the existing divergence error-response-structured-arm-door-parity.test.ts section 4 names; such a throw logs info. No sandbox producer emits this shape today.",
    "carrier: none. The job catch ('sandboxed job threw') still logs every throw at error. It was outside this card's two catch sites and is unchanged."
  ]
}

Generated by Claude Code

Landed

PR #26249 merged at 2026-10-26T18:02Z by the merge queue as 1d3ad39970 on main (Fixes #26153; ACCEPT 6422639609).

Reading	Probe	Result
Queue membership	`git ls-remote origin 'refs/heads/gh-readonly-queue/main/pr-26249-*'`	0 refs
`origin/main` by content	`git cat-file -e origin/main:packages/runtime/src/sandbox/body-throw-log-level.test.ts`	present
Ancestry	`git merge-base --is-ancestor 1d3ad39970 origin/main`	holds

State: this card closed by Fixes (completed); pm:dispatched removed.

Generated by Claude Code

Navigation Menu

Repository navigation

runtime: an app hook's intentional business refusal is logged as ERROR with a stack trace, twice per refused action #26153

Symptom

Why

Expected

Triage: first grade — `bug` · `priority:p2` · `domain:server` · `area:devpath` · `pm:queue` · triage seat · `session_01AavokzJ5DndAwitDXvKy4U` · 2026-10-26T14:53Z

Landed

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

runtime: an app hook's intentional business refusal is logged as ERROR with a stack trace, twice per refused action #26153

Description

Symptom

Why

Expected

Activity

objectstack-fleet commented on Oct 26, 2026

Triage: first grade — bug · priority:p2 · domain:server · area:devpath · pm:queue · triage seat · session_01AavokzJ5DndAwitDXvKy4U · 2026-10-26T14:53Z

objectstack-fleet commented on Oct 26, 2026

objectstack-fleet commented on Oct 26, 2026

objectstack-fleet commented on Oct 26, 2026

objectstack-fleet commented on Oct 26, 2026

Landed

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

Triage: first grade — `bug` · `priority:p2` · `domain:server` · `area:devpath` · `pm:queue` · triage seat · `session_01AavokzJ5DndAwitDXvKy4U` · 2026-10-26T14:53Z