Skip to content

fix(runtime): serve the hook/action ['log'] capability from a logger that exists (#7448) - #7660

Merged
os-help merged 1 commit into
mainfrom
claude/issue-7448-hook-ctx-log-observability
Aug 11, 2026
Merged

fix(runtime): serve the hook/action ['log'] capability from a logger that exists (#7448)#7660
os-help merged 1 commit into
mainfrom
claude/issue-7448-hook-ctx-log-observability

Conversation

@os-help

Copy link
Copy Markdown
Collaborator

Fixes#7448

Diagnosis — it is (a): the context arrives with no logger at all

Not "on the showcase boot path" — on every path. engineCtx.logger is a key that no producer writes and no schema declares.

Anchor (re-measured on main @ 245d1dc)Finding
packages/runtime/src/sandbox/body-runner.ts:339log: engineCtx?.logger — the hook wiring
packages/runtime/src/sandbox/body-runner.ts:377log: actionCtx?.logger — the action wiring
packages/spec/src/data/hook.zod.ts:334 (HookContextSchema)declares nologgergrep -c logger over the file returns 0
packages/objectql/src/engine.ts:6832, 6972, 7825, 8857all four const hookContext: HookContext = {…} assembly sites — none writes a logger key
packages/runtime/src/domains/actions.ts:330 and packages/runtime/src/action-execution.ts:1044both action-context literals — neither writes a logger key

The divergence point the card asked for:packages/objectql/src/engine.ts:1874. That is where the engine hands its own logger to the BodyRunner —

constmerged={ ...(opts??{}),logger: this.logger}asany;// → body-runner opts.logger

— and there is no counterpart on the per-invocation context. So opts.logger (body-runner.ts:74, [BodyRunner] hook fired) resolves to the engine's real Logger, while engineCtx.logger (:339) reads a key nobody ever set. One logger, one undefined, from the same object graph. That is the whole of the divergence.

Downstream it becomes silent rather than fatal at packages/runtime/src/sandbox/quickjs-runner.ts:646:

ctx.log?.[level]?.(msg,data);// optional call on an absent host seam

The capability gate passes, the VM-side ctx.log.info exists, the body runs to completion and returns normally — and the line goes nowhere. Exactly the "cannot tell did not run from ran and logged into the void" shape the card names.

This is the third limb of this shape removed from this same file, not the first: doc/previousDoc (#5906) and session.user (#6316) were also keys no producer ever wrote, deleted rather than left as a second de-facto contract (Prime Directive #12).

Reproduction — showcase, --log-level debug, before → after

Booted the way QA run #7439 did (pnpm dev -- --fresh -p <port> --log-level debug), signed in as the seeded admin, and PATCHed a showcase_task from done: falsetrue to fire showcase_audit_task_completion (whose body is ctx.log.info('task completed: ' + …), capabilities ['log']).

BEFORE (the two source files reverted to origin/main, @objectstack/runtime rebuilt):

2026-08-11T09:55:55.836Z DEBUG [BodyRunner] hook fired {"appId":"com.example.showcase","hook":"showcase_normalize_task_title"}
2026-08-11T09:55:55.851Z DEBUG [BodyRunner] hook fired {"appId":"com.example.showcase","hook":"showcase_audit_task_completion"}
$ grep -c "task completed" /tmp/showcase-before.log
0

The hook fires, does not throw — and the line it emits is absent from the entire debug log. That is the measurement.

AFTER:

2026-08-11T09:54:36.165Z DEBUG [BodyRunner] hook fired {"appId":"com.example.showcase","hook":"showcase_audit_task_completion"}
2026-08-11T09:54:36.294Z INFO [hook 'showcase_audit_task_completion'] task completed: Ingest pipeline

The fix, and why this shape follows from the cause

The cause is a read of a key nobody writes, so the fix is to read the source that exists — not to add a fallback behind the dead one.

  1. Serve the capability from opts.logger. It is the engine's own Logger, passed by all four construction sites in app-plugin.ts (logger: ctx.logger), and it is the very logger whose [BodyRunner] hook fired was already observable in the same QA run. So "why does this reach the process log stream when the current wiring does not" has a measured answer rather than an argued one: it is the stream the run already proved reachable.
  2. Delete the engineCtx.logger / actionCtx.logger limbs instead of keeping them as a preferred source (engineCtx?.logger ?? …). Under PD Add comprehensive test suite for Zod schema validation #12 a key no producer writes and no schema declares is not a contract to accommodate. The alternative — declaring logger on HookContextSchema — would widen the metadata contract to re-supply, per invocation, something the runner already holds for the lifetime of the bind.
  3. Attribute the line.[hook '<name>'] / [action '<name>'] prefix, because an author running many hooks otherwise cannot tell which one spoke, and the BodyRunner is the only layer that knows. The message body is untouched, so task completed: … still matches as a substring.
  4. Dispatch error through the real contract.Logger.error is (message, error, meta) — three args (packages/spec/src/contracts/logger.ts:36). Passing the body's data second lands a meta object in the Error slot, where ConsoleLogger/JsonLogger read error.message/error.stack as undefined and drop every field. Same trap hook-wrappers.ts documents for HookDiagnosticsLogger; the test asserts against a three-arg double so a regression here shows up as a lost meta, not as a silent pass.

Both call sites are covered

Hook (:339) and action (:377) both go through one buildBodyLogSurface(opts, origin). The action path needed the identical fix for the identical reason — neither of its two context assembly sites writes logger either — and its test is in the same file.

Second defect in the same capability, found by the reproduction

The VM bridge read the optional data argument with vm.getString, which applies JS string coercion inside the VM. So ctx.log.info('msg', { code: 'E1' }) arrived at the host as the literal string "[object Object]", which safeJsonParse then failed to parse and returned verbatim — every structured field of every body log call was lost. Now vm.dump, the marshalling every other host-call bridge in that file already uses (ctx.api's argHandles.map((h) => vm.dump(h))). In scope because it is the payload half of the same declared surface: fixing the destination while leaving the payload mangled would be half a fix.

When the capability genuinely cannot be served

The closing condition is either it works, or the author is told it cannot. With no logger on the factory at all, working is off the table, so this takes the told branch: warn once per invocation, naming the body and the remedy.

It deliberately does not fall back to console. That would override a decision belonging to the host — a Logger carries the level threshold, formatting and sinks the host chose — and a host running at warn would start receiving body info lines on an unfiltered second stream it never configured. No production path reaches this branch (all four app-plugin.ts sites pass ctx.logger), so it is a diagnostic for embedders constructing the factory directly. Once per invocation rather than once per call, so a chatty body cannot bury the rest of the log.

Verification

The new test asserts observability — what the host logger actually received after a real QuickJS body ran — not that the wiring is non-null. A null-check test would pass on a logger that drops the level, which is the wrong oracle for an observability defect.

Fails without the change (all 5, on unmodified source):

 FAIL src/sandbox/body-log-capability.test.ts > emits the body's info line on the logger the factory was constructed with
FAIL src/sandbox/body-log-capability.test.ts > emits warn and error levels too, and keeps the body's data out of the Error slot
FAIL src/sandbox/body-log-capability.test.ts > attributes the line to the emitting hook
FAIL src/sandbox/body-log-capability.test.ts > warns once, naming the hook, when the capability cannot be served
FAIL src/sandbox/body-log-capability.test.ts > [action] emits the body's log line on the factory logger
Test Files 1 failed (1)
Tests 5 failed (5)

Note the action case failed at the log assertion while expect(value).toEqual({ ok: true }) passed — the body ran to completion and logged into the void.

Targeted test, with the change:

$ pnpm --filter @objectstack/runtime exec vitest run src/sandbox/body-log-capability.test.ts
Test Files 1 passed (1)
Tests 5 passed (5)
Duration 1.38s

ESLint (changed files):

$ npx eslint packages/runtime/src/sandbox/body-runner.ts \
packages/runtime/src/sandbox/quickjs-runner.ts \
packages/runtime/src/sandbox/body-log-capability.test.ts
ESLINT EXIT CODE: 0
--- output (empty = clean) ---
(no findings)

TypeScript:

$ pnpm --filter @objectstack/runtime typecheck
> @objectstack/runtime@17.0.0-rc.6 typecheck
> tsc --noEmit
typecheck exit=0

Full runtime suite (regression):

$ pnpm --filter @objectstack/runtime test
Test Files 128 passed (128)
Tests 2021 passed (2021)
Duration 65.99s

pnpm build also green end to end (71/71 tasks) — that is the build both showcase boots above ran against.

Scope

Confined to packages/runtime/src/sandbox/ (body-runner.ts, quickjs-runner.ts, one new test) plus a changeset. No contact with the three live regions in this wave — rest-server.ts (#7603, #7566), package-routes.ts (#7563), the 400-envelope work (#7543). The diagnosis reached into packages/objectql/src/engine.ts and packages/spec/src/data/hook.zod.ts to establish that nobody writes the key, but neither needed changing: the correct logger was already in the BodyRunner's hand.

No content/docs/releases/ edit; the changeset is the release-notes input. No docs/adr/** contact.


Generated by Claude Code

…r that exists (#7448)
A body declaring `['log']` and calling `ctx.log.info(...)` ran to completion,
returned normally, and produced nothing. QA run #7439 measured it on the
showcase at `--log-level debug`: `[BodyRunner] hook fired` appeared while the
body's own `task completed: ...` line did not.
Cause: `body-runner.ts` wired the capability to `engineCtx?.logger` (hooks) and
`actionCtx?.logger` (actions) — a key no producer writes. `HookContextSchema`
declares no `logger`; ObjectQL's engine builds all four of its HookContexts
without one; neither action-context assembly site writes one. So `ctx.log` was
`undefined` on every path and the VM bridge's `ctx.log?.[level]?.(...)`
optional-called into nothing. The BodyRunner's own diagnostics stayed visible
because they use `opts.logger`, which every construction site supplies.
Serve the capability from `opts.logger` instead — the engine's own Logger,
passed by all four app-plugin sites — and delete the dead context limbs rather
than keep them as a second de-facto contract (as #5906 and #6316 did in this
same file). Lines carry their origin so an author can tell which body spoke,
and `error` goes through the Logger contract's real `(message, error, meta)`
signature so structured data no longer lands in the `Error` slot.
Also fix the payload half of the same capability: the VM bridge read the
optional `data` argument with `vm.getString`, which coerces inside the VM, so
an object arrived as the literal "[object Object]". Use `vm.dump`, the
marshalling every other host-call bridge in that file already uses.
With no logger at all (no production path, but reachable for embedders) the
capability warns once per invocation naming the body and the remedy, rather
than degrading silently. It does not fall back to `console`, which would
override the host's chosen level threshold, formatting and sinks.
@vercel

vercelBot commented Aug 11, 2026

Copy link
Copy Markdown

The latest updates on your projects. Learn more about Vercel for GitHub.

1 Skipped Deployment
ProjectDeploymentActionsUpdated (UTC)
objectstackIgnoredIgnoredAug 11, 2026 9:59am

Request Review

@github-actions

Copy link
Copy Markdown
Contributor

📓 Docs Drift Check

This PR changes 1 package(s): @objectstack/runtime.

20 hand-written doc(s) reference the affected code and may need an implementation-accuracy re-verification:

  • content/docs/api/client-sdk.mdx(via packages/runtime)
  • content/docs/api/index.mdx(via @objectstack/runtime)
  • content/docs/api/wire-format.mdx(via @objectstack/runtime)
  • content/docs/automation/hook-bodies.mdx(via @objectstack/runtime)
  • content/docs/concepts/metadata-lifecycle.mdx(via @objectstack/runtime)
  • content/docs/concepts/north-star.mdx(via packages/runtime)
  • content/docs/data-modeling/drivers.mdx(via @objectstack/runtime)
  • content/docs/deployment/index.mdx(via @objectstack/runtime)
  • content/docs/deployment/production-readiness.mdx(via @objectstack/runtime)
  • content/docs/deployment/single-project-mode.mdx(via @objectstack/runtime)
  • content/docs/deployment/vercel.mdx(via @objectstack/runtime)
  • content/docs/getting-started/your-first-project.mdx(via @objectstack/runtime)
  • content/docs/kernel/cluster.mdx(via @objectstack/runtime)
  • content/docs/permissions/authentication.mdx(via @objectstack/runtime)
  • content/docs/permissions/authorization.mdx(via packages/runtime)
  • content/docs/permissions/system-context.mdx(via packages/runtime)
  • content/docs/plugins/packages.mdx(via @objectstack/runtime)
  • content/docs/protocol/kernel/http-protocol.mdx(via @objectstack/runtime)
  • content/docs/protocol/kernel/index.mdx(via @objectstack/runtime)
  • content/docs/protocol/kernel/lifecycle.mdx(via @objectstack/runtime)

2 release-owned page(s) also reference the affected code. These are read-only:

  • content/docs/releases/implementation-status.mdx(via @objectstack/runtime)
  • content/docs/releases/v17.mdx(via @objectstack/runtime)

content/docs/releases/ is RELEASE-OWNED (AGENTS.md "Documentation Guardrails"): release
notes are written centrally at release time, and a code PR that edits them is the exact PR
that guardrail exists to stop. They are still audited — read-only. If one of them is actually
wrong, file an issue or open a dedicated docs-only PR; do not edit it here.

Advisory only. To re-verify, run the docs-accuracy-audit workflow scoped to these files:
node scripts/docs-audit/affected-docs.mjs origin/main → pass the list as args.docs.

@os-helpClaude

Copy link
Copy Markdown
CollaboratorAuthor

Adjacent finding filed, not fixed here: #7661ctx.log.debug is matched by the CLI capability extractor (extract-hook-body.ts:56) and listed in content/docs/automation/hook-bodies.mdx:317, but the VM installs only info/warn/error (quickjs-runner.ts:639), so a body calling it throws TypeError: not a function. Measured, not read off the source.

Kept out of this PR deliberately: #7448 is about the three installed methods producing nothing, whereas that is a fourth method that does not exist — and closing it is an enforce-or-remove capability-surface decision (the crypto.hash / #4391 shape), not a bug fix.


Generated by Claude Code

@os-help
os-help marked this pull request as ready for review August 11, 2026 10:40
@os-help
os-help added this pull request to the merge queueAug 11, 2026
@github-merge-queue
github-merge-queueBot removed this pull request from the merge queue due to failed status checks Aug 11, 2026
@github-actions

Copy link
Copy Markdown
Contributor

⛔ merge queue 构建失败 — 先分诊,再决定要不要重排

队列构建 31483342423 红了。队列跑的是全量套件(PR 侧 CI 只跑 affected 子集),
所以失败的测试可能在本 PR 没碰过的包里 —— 那不是重排能修的。每次盲目重排都会让排在后面的所有 PR 重建一轮。

失败的 job(日志抽取,best effort):

  • Test Core (1/3) — 失败步骤: Run this shard's tests

    �[41m�[1m FAIL �[22m�[49m src/security/operation-private-keys.pin.test.ts�[2m > �[22mthe `__` operation-private-key convention has one owner (#7284)�[2m > �[22mis declared in exactly one file, and tha
    

历史信号:

  • 本 PR 过去 24h 无队列失败记录(首次)。
  • 过去 24h 队列共有 0 个失败构建(不含本次)。

分诊清单:

  1. 失败测试在本 PR 改动的包里 → 真回归,修 PR。
  2. 失败测试与本 PR 无关 → 在其他 PR 的同类评论里搜同名测试;出现过 ⇒ flaky 实锤,开 issue 修/隔离那条测试。修好前重排只会再烧一轮全队列。
  3. 两者都不是 → 可能与同组 PR 语义冲突;等前面的 PR 落地或失败出队后再重排一次即可,不要连续重排。

Generated by Claude Code · merge-queue-triage workflow (#4859)

@os-help
os-help added this pull request to the merge queueAug 11, 2026
@github-merge-queue
github-merge-queueBot removed this pull request from the merge queue due to failed status checks Aug 11, 2026
@github-actions

Copy link
Copy Markdown
Contributor

⛔ merge queue 构建失败 — 先分诊,再决定要不要重排

队列构建 31485726120 红了。队列跑的是全量套件(PR 侧 CI 只跑 affected 子集),
所以失败的测试可能在本 PR 没碰过的包里 —— 那不是重排能修的。每次盲目重排都会让排在后面的所有 PR 重建一轮。

失败的 job(日志抽取,best effort):

  • Test Core (1/3) — 失败步骤: Run this shard's tests

    �[41m�[1m FAIL �[22m�[49m src/security/operation-private-keys.pin.test.ts�[2m > �[22mthe `__` operation-private-key convention has one owner (#7284)�[2m > �[22mis declared in exactly one file, and tha
    

历史信号:

  • ⚠️本 PR 过去 24h 已在队列失败 1 次(不含本次)。 内容未变而反复失败 ⇒ 高度怀疑 flaky 测试或与同组 PR 的语义冲突,重排不解决。
  • 过去 24h 队列共有 1 个失败构建(不含本次)。

分诊清单:

  1. 失败测试在本 PR 改动的包里 → 真回归,修 PR。
  2. 失败测试与本 PR 无关 → 在其他 PR 的同类评论里搜同名测试;出现过 ⇒ flaky 实锤,开 issue 修/隔离那条测试。修好前重排只会再烧一轮全队列。
  3. 两者都不是 → 可能与同组 PR 语义冲突;等前面的 PR 落地或失败出队后再重排一次即可,不要连续重排。

Generated by Claude Code · merge-queue-triage workflow (#4859)

@os-help
os-help added this pull request to the merge queueAug 11, 2026
Merged via the queue into main with commit 7674859Aug 11, 2026
26 checks passed
@os-help
os-help deleted the claude/issue-7448-hook-ctx-log-observability branch August 11, 2026 12:59
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

documentationImprovements or additions to documentationsize/mteststooling

Projects

None yet

2 participants

@os-help@claude