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

.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.

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<string, any>;
+}
+
+/** 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');
+ });
+});

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<string, any> | undefined => {
+ if (data === undefined || data === null) return undefined;
+ if (typeof data === 'object' && !Array.isArray(data)) return data as Record<string, any>;
+ 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<void> {
- 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<unknown> {
- 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,
  };
 }