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; });