From 01cc1b2f9997ce7fa6e6f7446da58599223d5842 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 11 Aug 2026 09:52:46 +0000 Subject: [PATCH] fix(runtime): serve the hook/action `['log']` capability from a logger that exists (#7448) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- .../hook-body-log-capability-observable.md | 44 +++++ .../src/sandbox/body-log-capability.test.ts | 172 ++++++++++++++++++ packages/runtime/src/sandbox/body-runner.ts | 119 +++++++++++- .../runtime/src/sandbox/quickjs-runner.ts | 12 +- 4 files changed, 340 insertions(+), 7 deletions(-) create mode 100644 .changeset/hook-body-log-capability-observable.md create mode 100644 packages/runtime/src/sandbox/body-log-capability.test.ts diff --git a/.changeset/hook-body-log-capability-observable.md b/.changeset/hook-body-log-capability-observable.md new file mode 100644 index 0000000000..fd6ed3b0cd --- /dev/null +++ b/.changeset/hook-body-log-capability-observable.md @@ -0,0 +1,44 @@ +--- +"@objectstack/runtime": patch +--- + +fix(runtime): a hook/action body's `ctx.log` output reaches the host log stream (#7448) + +A body that declared the `['log']` capability and called `ctx.log.info(…)` ran to +completion, returned normally, and produced **nothing** — an author could not tell +"my hook did not run" apart from "my hook ran and logged into the void". QA run +#7439 measured it on the showcase at `--log-level debug`: `[BodyRunner] hook fired` +appeared, while the `task completed: …` line the body itself emitted 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, and neither action-context assembly site (`domains/actions.ts`, +`action-execution.ts`) writes one either. So `ctx.log` was `undefined` on every +path, and the VM bridge forwards through `ctx.log?.[level]?.(…)` — an optional call +on an absent seam. The BodyRunner's own diagnostics were visible throughout because +they use a different logger (`opts.logger`), which every construction site does +supply. + +**Fix.** The capability is now served from `opts.logger` — the engine's own +`Logger`, handed to the factory by all four `app-plugin.ts` sites, and the same one +whose `[BodyRunner] hook fired` was already observable. The dead `engineCtx.logger` / +`actionCtx.logger` limbs are removed rather than kept as a second de-facto contract, +matching the `doc`/`previousDoc` (#5906) and `session.user` (#6316) removals in this +file. Lines are prefixed with their origin (`[hook 'showcase_audit_task_completion'] +task completed: …`) so an author running many hooks can tell which one spoke, and +`error` is dispatched through the `Logger` contract's real `(message, error, meta)` +signature so a body's structured data no longer lands in the `Error` slot and lose +every field. + +**Second defect, same capability.** The VM bridge read the optional `data` argument +with `vm.getString`, which coerces inside the VM — so `ctx.log.info('msg', { code: +'E1' })` arrived at the host as the literal string `"[object Object]"` and every +structured field was lost. It now uses `vm.dump`, the marshalling every other +host-call bridge in that file already uses. + +When a BodyRunner is constructed with no logger at all — no production path, but +reachable for embedders — the capability no longer degrades silently: it warns once +per invocation, naming the body and the remedy. It deliberately does not fall back +to `console`, which would override the level threshold, formatting and sinks the +host chose and start a second, unfiltered log stream it never configured. diff --git a/packages/runtime/src/sandbox/body-log-capability.test.ts b/packages/runtime/src/sandbox/body-log-capability.test.ts new file mode 100644 index 0000000000..d687e59a29 --- /dev/null +++ b/packages/runtime/src/sandbox/body-log-capability.test.ts @@ -0,0 +1,172 @@ +// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#7448] The `['log']` capability must reach the host log stream. + * + * These tests assert OBSERVABILITY, not wiring. A null-check ("`ctx.log` is + * not undefined") passes on a surface that swallows every call, which is the + * exact defect #7448 recorded: QA run #7439 saw `[BodyRunner] hook fired` at + * `--log-level debug` while the `ctx.log.info('task completed: …')` the body + * emitted never appeared anywhere. So every assertion here is on what the + * HOST LOGGER RECEIVED after a real QuickJS body ran. + * + * The captured logger is a `Logger`-contract double: `error` takes + * `(message, error, meta)`, so a body's `data` landing in the `error` slot + * would show up here as a lost `meta` rather than passing silently — the + * shape-dispatch trap `hook-wrappers.ts` documents for `HookDiagnosticsLogger`. + */ + +import { describe, it, expect } from 'vitest'; +import { hookBodyRunnerFactory, actionBodyRunnerFactory } from './body-runner.js'; +import { QuickJSScriptRunner } from './quickjs-runner.js'; + +interface Line { + level: 'debug' | 'info' | 'warn' | 'error'; + message: string; + error?: Error; + meta?: Record; +} + +/** A `Logger`-contract double — note `error`'s three-arg signature. */ +function captureLogger() { + const lines: Line[] = []; + return { + lines, + debug: (message: string, meta?: any) => { lines.push({ level: 'debug', message, meta }); }, + info: (message: string, meta?: any) => { lines.push({ level: 'info', message, meta }); }, + warn: (message: string, meta?: any) => { lines.push({ level: 'warn', message, meta }); }, + error: (message: string, error?: Error, meta?: any) => { + lines.push({ level: 'error', message, error, meta }); + }, + }; +} + +describe('[#7448] hook body ctx.log reaches the host log stream', () => { + const runner = new QuickJSScriptRunner(); + + it('emits the body\'s info line on the logger the factory was constructed with', async () => { + const logger = captureLogger(); + const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger }); + // The showcase's own `showcase_audit_task_completion` body, verbatim. + const fn = factory({ + name: 'showcase_audit_task_completion', + object: 'showcase_task', + events: ['afterUpdate'], + body: { + language: 'js', + source: + "var r = ctx.result || ctx.input || {}; ctx.log.info('task completed: ' + (r.title || r.id || 'unknown'));", + capabilities: ['log'], + }, + } as any); + expect(typeof fn).toBe('function'); + + await fn!({ input: {}, result: { title: 'Ship the thing' } } as any); + + // The oracle QA run #7439 could not capture: the NAMED line, at info. + const emitted = logger.lines.filter((l) => l.message.includes('task completed: Ship the thing')); + expect(emitted.length).toBe(1); + expect(emitted[0].level).toBe('info'); + }); + + it('emits warn and error levels too, and keeps the body\'s data out of the Error slot', async () => { + const logger = captureLogger(); + const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger }); + const fn = factory({ + name: 'showcase_warn_over_budget', + object: 'showcase_project', + events: ['afterUpdate'], + body: { + language: 'js', + source: + "ctx.log.warn('project over budget: Apollo'); " + + "ctx.log.error('hard fail', { code: 'E1', spent: 120, tags: ['a', 'b'], at: { deep: true } });", + capabilities: ['log'], + }, + } as any); + + await fn!({ input: {} } as any); + + const warned = logger.lines.find((l) => l.message.includes('project over budget: Apollo')); + expect(warned?.level).toBe('warn'); + + const errored = logger.lines.find((l) => l.message.includes('hard fail')); + expect(errored?.level).toBe('error'); + // `Logger.error` is `(message, error, meta)`. The body's data belongs in + // `meta`; landing it in `error` is how a diagnostic loses every field. + expect(errored?.error).toBeUndefined(); + // Structured data must cross the VM boundary as a VALUE. Before #7448 the + // bridge read it with `vm.getString`, so this arrived as the string + // `"[object Object]"` and every field below was gone. + expect(errored?.meta).toEqual({ code: 'E1', spent: 120, tags: ['a', 'b'], at: { deep: true } }); + }); + + it('attributes the line to the emitting hook', async () => { + const logger = captureLogger(); + const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger }); + const fn = factory({ + name: 'showcase_audit_task_completion', + object: 'showcase_task', + events: ['afterUpdate'], + body: { language: 'js', source: "ctx.log.info('hello');", capabilities: ['log'] }, + } as any); + + await fn!({ input: {} } as any); + + const line = logger.lines.find((l) => l.message.includes('hello')); + expect(line).toBeDefined(); + // An author running ten hooks has to be able to tell which one spoke. + expect(line!.message).toContain('showcase_audit_task_completion'); + }); + + it('warns once, naming the hook, when the capability cannot be served', async () => { + // No logger at all — the one shape where `['log']` genuinely cannot work. + // It must not be silent about that; `console.warn` is the only stream left. + const warnings: string[] = []; + const original = console.warn; + console.warn = (...args: any[]) => { warnings.push(args.map(String).join(' ')); }; + try { + const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase' }); + const fn = factory({ + name: 'silent_hook', + object: 'showcase_task', + events: ['afterUpdate'], + body: { language: 'js', source: "ctx.log.info('a'); ctx.log.info('b');", capabilities: ['log'] }, + } as any); + await fn!({ input: {} } as any); + } finally { + console.warn = original; + } + + const capabilityWarnings = warnings.filter((w) => w.includes('ctx.log output is discarded')); + expect(capabilityWarnings.length).toBe(1); // once per body, not once per call + expect(capabilityWarnings[0]).toContain('silent_hook'); + }); +}); + +describe('[#7448] action body ctx.log reaches the host log stream', () => { + const runner = new QuickJSScriptRunner(); + + it('emits the body\'s log line on the factory logger', async () => { + const logger = captureLogger(); + const factory = actionBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger }); + const fn = factory({ + name: 'recalculate_totals', + object: 'showcase_project', + type: 'script', + body: { + language: 'js', + source: "ctx.log.info('recalculated: ' + ctx.input.n); return { ok: true };", + capabilities: ['log'], + }, + } as any); + expect(typeof fn).toBe('function'); + + const value = await fn!({ params: { n: 3 } } as any); + expect(value).toEqual({ ok: true }); + + const line = logger.lines.find((l) => l.message.includes('recalculated: 3')); + expect(line?.level).toBe('info'); + expect(line!.message).toContain('recalculate_totals'); + }); +}); diff --git a/packages/runtime/src/sandbox/body-runner.ts b/packages/runtime/src/sandbox/body-runner.ts index 2a6e7bf01b..ee20a29432 100644 --- a/packages/runtime/src/sandbox/body-runner.ts +++ b/packages/runtime/src/sandbox/body-runner.ts @@ -49,6 +49,92 @@ interface FactoryOptions { logger?: any; } +/** + * Build the `['log']` capability surface for one body invocation (#7448). + * + * ## Why this is not `engineCtx?.logger` + * + * It was, at `:339` (hooks) and `:377` (actions), and that key is written by + * nobody. `HookContextSchema` (`packages/spec/src/data/hook.zod.ts`) declares + * no `logger`, and ObjectQL's engine — the sole producer of a HookContext — + * builds all four of them (`engine.ts` `beforeFind` / `find` / `update` / + * `delete` assembly sites) without one. Both action-context assembly sites + * (`../domains/actions.ts` REST `/actions`, `../action-execution.ts` MCP + * `run_action`) likewise write no `logger`. So `ctx.log` resolved `undefined` + * on EVERY path, and `installCtx` (`quickjs-runner.ts`) forwards through + * `ctx.log?.[level]?.(…)` — an 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. QA run #7439 saw + * exactly that: `[BodyRunner] hook fired` at `--log-level debug` with the + * body's own `ctx.log.info('task completed: …')` absent. + * + * That is the third limb of this shape removed from this 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). The remedy is the same — read the source that exists. + * `opts.logger` is the engine's own `Logger`, handed to the factory by all four + * construction sites in `../app-plugin.ts` (`logger: ctx.logger`), and it is + * the very logger whose `[BodyRunner] hook fired` WAS observable in the same + * QA run. Adding a `logger` to `HookContextSchema` instead would widen the + * metadata contract to re-supply, per invocation, something the runner already + * holds for the lifetime of the bind. + * + * ## Why absence warns rather than falling back to `console` + * + * A declared capability must not silently produce nothing — either it works or + * the author is told it cannot. When the factory was constructed with no logger + * at all, working is not on the table, so this takes the told branch. Routing + * to `console` instead would override a decision that belongs 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 the + * warning — all four `../app-plugin.ts` sites pass `ctx.logger` — so it is a + * diagnostic for embedders that construct the factory directly, and it fires + * once per invocation rather than once per call so a chatty body cannot bury + * the rest of the log. + */ +function buildBodyLogSurface( + opts: FactoryOptions, + origin: { kind: 'hook' | 'action'; name: string }, +): ScriptContext['log'] { + const logger = opts.logger; + const label = `[${origin.kind} '${origin.name}']`; + + if (!logger) { + let warned = false; + const warnOnce = () => { + if (warned) return; + warned = true; + console.warn( + `[BodyRunner] ${origin.kind} '${origin.name}' (app '${opts.appId}') declares the 'log' ` + + `capability, but this BodyRunner was constructed without a logger — ctx.log output is ` + + `discarded. Pass \`logger\` to ${origin.kind}BodyRunnerFactory({ … }). See #7448.`, + ); + }; + return { info: warnOnce, warn: warnOnce, error: warnOnce }; + } + + // `Logger.meta` is a `Record` (`packages/spec/src/contracts/logger.ts`); a + // body may pass anything JSON-serialisable, so non-objects are carried under + // a `data` key rather than dropped on the floor. + const toMeta = (data: unknown): Record | undefined => { + if (data === undefined || data === null) return undefined; + if (typeof data === 'object' && !Array.isArray(data)) return data as Record; + return { data }; + }; + + return { + info: (msg: string, data?: unknown) => logger.info?.(`${label} ${msg}`, toMeta(data)), + warn: (msg: string, data?: unknown) => logger.warn?.(`${label} ${msg}`, toMeta(data)), + // ⚠️ `Logger.error` is `(message, error, meta)` — THREE args, and the body's + // `data` is the third. Passing it second lands a meta object in the `Error` + // slot, where `ConsoleLogger`/`JsonLogger` read `error.message`/`error.stack` + // as `undefined` and drop every field, leaving a bare sentence. Same trap + // `hook-wrappers.ts` documents for `HookDiagnosticsLogger`. + error: (msg: string, data?: unknown) => logger.error?.(`${label} ${msg}`, undefined, toMeta(data)), + }; +} + export function hookBodyRunnerFactory( runner: ScriptRunner, opts: FactoryOptions, @@ -69,7 +155,11 @@ export function hookBodyRunnerFactory( const body = parsed.data; return async function boundBodyHandler(engineCtx: any): Promise { - const sandboxCtx = buildSandboxContext(engineCtx, opts.ql); + const sandboxCtx = buildSandboxContext( + engineCtx, + opts.ql, + buildBodyLogSurface(opts, { kind: 'hook', name: hook.name }), + ); try { opts.logger?.debug?.('[BodyRunner] hook fired', { appId: opts.appId, hook: hook.name }); const result = await runner.run(body, sandboxCtx, { @@ -169,7 +259,11 @@ export function actionBodyRunnerFactory( const body = parsed.data; return async function boundActionHandler(actionCtx: any): Promise { - const sandboxCtx = buildActionSandboxContext(actionCtx, opts.ql); + const sandboxCtx = buildActionSandboxContext( + actionCtx, + opts.ql, + buildBodyLogSurface(opts, { kind: 'action', name: action.name }), + ); try { opts.logger?.debug?.('[BodyRunner] action fired', { appId: opts.appId, @@ -304,7 +398,11 @@ function buildSandboxApi(engineCtx: any, ql: any, errLabel: string) { }; } -function buildSandboxContext(engineCtx: any, ql: any): ScriptContext { +function buildSandboxContext( + engineCtx: any, + ql: any, + log: ScriptContext['log'], +): ScriptContext { // `input` and `previous` are the engine's own spellings, and the only ones: // `HookContextSchema` (`packages/spec/src/data/hook.zod.ts`) declares neither a // top-level `doc` nor a `previousDoc`, and objectql's `engine.ts` — the sole @@ -336,12 +434,19 @@ function buildSandboxContext(engineCtx: any, ql: any): ScriptContext { object: typeof engineCtx?.object === 'string' ? engineCtx.object : undefined, result: engineCtx?.result, api: buildSandboxApi(engineCtx, ql, 'hook body'), - log: engineCtx?.logger, + // [#7448] NOT `engineCtx?.logger` — a key no HookContext producer writes and + // `HookContextSchema` never declared, so the `['log']` capability resolved + // `undefined` and every body log line vanished. See {@link buildBodyLogSurface}. + log, crypto: globalThis.crypto, }; } -function buildActionSandboxContext(actionCtx: any, ql: any): ScriptContext { +function buildActionSandboxContext( + actionCtx: any, + ql: any, + log: ScriptContext['log'], +): ScriptContext { // Action ctx convention (mirrors http-dispatcher.ts): // { record, params, recordId, user, session, engine, services, ... } // The script signature is `(input, ctx)` — input gets `params`, ctx gets @@ -374,7 +479,9 @@ function buildActionSandboxContext(actionCtx: any, ql: any): ScriptContext { // a body makes to it rather than letting them vanish. record: unwrapProxyToPlain(actionCtx?.record), api: buildSandboxApi(actionCtx, ql, 'action body'), - log: actionCtx?.logger, + // [#7448] Same removal as the hook face: neither action-context assembly + // site (`../domains/actions.ts`, `../action-execution.ts`) writes `logger`. + log, crypto: globalThis.crypto, }; } diff --git a/packages/runtime/src/sandbox/quickjs-runner.ts b/packages/runtime/src/sandbox/quickjs-runner.ts index c0ba1175c3..8a59690846 100644 --- a/packages/runtime/src/sandbox/quickjs-runner.ts +++ b/packages/runtime/src/sandbox/quickjs-runner.ts @@ -642,7 +642,17 @@ export class QuickJSScriptRunner implements ScriptRunner { throwSandboxFault(vm, `capability 'log' not granted to ${origin.kind} '${origin.name}'`); } const msg = vm.getString(msgH); - const data = dataH ? safeJsonParse(vm.getString(dataH)) : undefined; + // [#7448] `vm.dump`, NOT `vm.getString` — the marshalling every other + // host-call bridge in this file already uses (`ctx.api`'s + // `argHandles.map((h) => vm.dump(h))`, and the return-value paths). + // `getString` on a non-string handle applies JS string coercion INSIDE + // the VM, so the `data` object a body passes arrives as the literal + // `"[object Object]"` — which `safeJsonParse` then fails to parse and + // returns verbatim, so every structured field of every body log call + // was lost. That is the payload half of the same declared-capability + // gap #7448 recorded, surfaced by its reproduction; `dump` + // deserialises the handle into a real value. + const data = dataH ? vm.dump(dataH) : undefined; ctx.log?.[level]?.(msg, data); return vm.undefined; });