Skip to content

Commit 7c844d2

Browse files
os-helpclaude
andauthored
fix(runtime): serve the hook/action ['log'] capability from a logger that exists (#7448) (#7660)
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. Co-authored-by: Claude <noreply@anthropic.com>
1 parent 21888ab commit 7c844d2

4 files changed

Lines changed: 340 additions & 7 deletions

File tree

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
---
2+
"@objectstack/runtime": patch
3+
---
4+
5+
fix(runtime): a hook/action body's `ctx.log` output reaches the host log stream (#7448)
6+
7+
A body that declared the `['log']` capability and called `ctx.log.info(…)` ran to
8+
completion, returned normally, and produced **nothing** — an author could not tell
9+
"my hook did not run" apart from "my hook ran and logged into the void". QA run
10+
#7439 measured it on the showcase at `--log-level debug`: `[BodyRunner] hook fired`
11+
appeared, while the `task completed: …` line the body itself emitted did not.
12+
13+
**Cause.** `body-runner.ts` wired the capability to `engineCtx?.logger` (hooks) and
14+
`actionCtx?.logger` (actions) — a key **no producer writes**. `HookContextSchema`
15+
declares no `logger`, ObjectQL's engine builds all four of its HookContexts without
16+
one, and neither action-context assembly site (`domains/actions.ts`,
17+
`action-execution.ts`) writes one either. So `ctx.log` was `undefined` on every
18+
path, and the VM bridge forwards through `ctx.log?.[level]?.(…)` — an optional call
19+
on an absent seam. The BodyRunner's own diagnostics were visible throughout because
20+
they use a different logger (`opts.logger`), which every construction site does
21+
supply.
22+
23+
**Fix.** The capability is now served from `opts.logger` — the engine's own
24+
`Logger`, handed to the factory by all four `app-plugin.ts` sites, and the same one
25+
whose `[BodyRunner] hook fired` was already observable. The dead `engineCtx.logger` /
26+
`actionCtx.logger` limbs are removed rather than kept as a second de-facto contract,
27+
matching the `doc`/`previousDoc` (#5906) and `session.user` (#6316) removals in this
28+
file. Lines are prefixed with their origin (`[hook 'showcase_audit_task_completion']
29+
task completed: …`) so an author running many hooks can tell which one spoke, and
30+
`error` is dispatched through the `Logger` contract's real `(message, error, meta)`
31+
signature so a body's structured data no longer lands in the `Error` slot and lose
32+
every field.
33+
34+
**Second defect, same capability.** The VM bridge read the optional `data` argument
35+
with `vm.getString`, which coerces inside the VM — so `ctx.log.info('msg', { code:
36+
'E1' })` arrived at the host as the literal string `"[object Object]"` and every
37+
structured field was lost. It now uses `vm.dump`, the marshalling every other
38+
host-call bridge in that file already uses.
39+
40+
When a BodyRunner is constructed with no logger at all — no production path, but
41+
reachable for embedders — the capability no longer degrades silently: it warns once
42+
per invocation, naming the body and the remedy. It deliberately does not fall back
43+
to `console`, which would override the level threshold, formatting and sinks the
44+
host chose and start a second, unfiltered log stream it never configured.
Lines changed: 172 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,172 @@
1+
// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license.
2+
3+
/**
4+
* [#7448] The `['log']` capability must reach the host log stream.
5+
*
6+
* These tests assert OBSERVABILITY, not wiring. A null-check ("`ctx.log` is
7+
* not undefined") passes on a surface that swallows every call, which is the
8+
* exact defect #7448 recorded: QA run #7439 saw `[BodyRunner] hook fired` at
9+
* `--log-level debug` while the `ctx.log.info('task completed: …')` the body
10+
* emitted never appeared anywhere. So every assertion here is on what the
11+
* HOST LOGGER RECEIVED after a real QuickJS body ran.
12+
*
13+
* The captured logger is a `Logger`-contract double: `error` takes
14+
* `(message, error, meta)`, so a body's `data` landing in the `error` slot
15+
* would show up here as a lost `meta` rather than passing silently — the
16+
* shape-dispatch trap `hook-wrappers.ts` documents for `HookDiagnosticsLogger`.
17+
*/
18+
19+
import { describe, it, expect } from 'vitest';
20+
import { hookBodyRunnerFactory, actionBodyRunnerFactory } from './body-runner.js';
21+
import { QuickJSScriptRunner } from './quickjs-runner.js';
22+
23+
interface Line {
24+
level: 'debug' | 'info' | 'warn' | 'error';
25+
message: string;
26+
error?: Error;
27+
meta?: Record<string, any>;
28+
}
29+
30+
/** A `Logger`-contract double — note `error`'s three-arg signature. */
31+
function captureLogger() {
32+
const lines: Line[] = [];
33+
return {
34+
lines,
35+
debug: (message: string, meta?: any) => { lines.push({ level: 'debug', message, meta }); },
36+
info: (message: string, meta?: any) => { lines.push({ level: 'info', message, meta }); },
37+
warn: (message: string, meta?: any) => { lines.push({ level: 'warn', message, meta }); },
38+
error: (message: string, error?: Error, meta?: any) => {
39+
lines.push({ level: 'error', message, error, meta });
40+
},
41+
};
42+
}
43+
44+
describe('[#7448] hook body ctx.log reaches the host log stream', () => {
45+
const runner = new QuickJSScriptRunner();
46+
47+
it('emits the body\'s info line on the logger the factory was constructed with', async () => {
48+
const logger = captureLogger();
49+
const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger });
50+
// The showcase's own `showcase_audit_task_completion` body, verbatim.
51+
const fn = factory({
52+
name: 'showcase_audit_task_completion',
53+
object: 'showcase_task',
54+
events: ['afterUpdate'],
55+
body: {
56+
language: 'js',
57+
source:
58+
"var r = ctx.result || ctx.input || {}; ctx.log.info('task completed: ' + (r.title || r.id || 'unknown'));",
59+
capabilities: ['log'],
60+
},
61+
} as any);
62+
expect(typeof fn).toBe('function');
63+
64+
await fn!({ input: {}, result: { title: 'Ship the thing' } } as any);
65+
66+
// The oracle QA run #7439 could not capture: the NAMED line, at info.
67+
const emitted = logger.lines.filter((l) => l.message.includes('task completed: Ship the thing'));
68+
expect(emitted.length).toBe(1);
69+
expect(emitted[0].level).toBe('info');
70+
});
71+
72+
it('emits warn and error levels too, and keeps the body\'s data out of the Error slot', async () => {
73+
const logger = captureLogger();
74+
const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger });
75+
const fn = factory({
76+
name: 'showcase_warn_over_budget',
77+
object: 'showcase_project',
78+
events: ['afterUpdate'],
79+
body: {
80+
language: 'js',
81+
source:
82+
"ctx.log.warn('project over budget: Apollo'); " +
83+
"ctx.log.error('hard fail', { code: 'E1', spent: 120, tags: ['a', 'b'], at: { deep: true } });",
84+
capabilities: ['log'],
85+
},
86+
} as any);
87+
88+
await fn!({ input: {} } as any);
89+
90+
const warned = logger.lines.find((l) => l.message.includes('project over budget: Apollo'));
91+
expect(warned?.level).toBe('warn');
92+
93+
const errored = logger.lines.find((l) => l.message.includes('hard fail'));
94+
expect(errored?.level).toBe('error');
95+
// `Logger.error` is `(message, error, meta)`. The body's data belongs in
96+
// `meta`; landing it in `error` is how a diagnostic loses every field.
97+
expect(errored?.error).toBeUndefined();
98+
// Structured data must cross the VM boundary as a VALUE. Before #7448 the
99+
// bridge read it with `vm.getString`, so this arrived as the string
100+
// `"[object Object]"` and every field below was gone.
101+
expect(errored?.meta).toEqual({ code: 'E1', spent: 120, tags: ['a', 'b'], at: { deep: true } });
102+
});
103+
104+
it('attributes the line to the emitting hook', async () => {
105+
const logger = captureLogger();
106+
const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger });
107+
const fn = factory({
108+
name: 'showcase_audit_task_completion',
109+
object: 'showcase_task',
110+
events: ['afterUpdate'],
111+
body: { language: 'js', source: "ctx.log.info('hello');", capabilities: ['log'] },
112+
} as any);
113+
114+
await fn!({ input: {} } as any);
115+
116+
const line = logger.lines.find((l) => l.message.includes('hello'));
117+
expect(line).toBeDefined();
118+
// An author running ten hooks has to be able to tell which one spoke.
119+
expect(line!.message).toContain('showcase_audit_task_completion');
120+
});
121+
122+
it('warns once, naming the hook, when the capability cannot be served', async () => {
123+
// No logger at all — the one shape where `['log']` genuinely cannot work.
124+
// It must not be silent about that; `console.warn` is the only stream left.
125+
const warnings: string[] = [];
126+
const original = console.warn;
127+
console.warn = (...args: any[]) => { warnings.push(args.map(String).join(' ')); };
128+
try {
129+
const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase' });
130+
const fn = factory({
131+
name: 'silent_hook',
132+
object: 'showcase_task',
133+
events: ['afterUpdate'],
134+
body: { language: 'js', source: "ctx.log.info('a'); ctx.log.info('b');", capabilities: ['log'] },
135+
} as any);
136+
await fn!({ input: {} } as any);
137+
} finally {
138+
console.warn = original;
139+
}
140+
141+
const capabilityWarnings = warnings.filter((w) => w.includes('ctx.log output is discarded'));
142+
expect(capabilityWarnings.length).toBe(1); // once per body, not once per call
143+
expect(capabilityWarnings[0]).toContain('silent_hook');
144+
});
145+
});
146+
147+
describe('[#7448] action body ctx.log reaches the host log stream', () => {
148+
const runner = new QuickJSScriptRunner();
149+
150+
it('emits the body\'s log line on the factory logger', async () => {
151+
const logger = captureLogger();
152+
const factory = actionBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger });
153+
const fn = factory({
154+
name: 'recalculate_totals',
155+
object: 'showcase_project',
156+
type: 'script',
157+
body: {
158+
language: 'js',
159+
source: "ctx.log.info('recalculated: ' + ctx.input.n); return { ok: true };",
160+
capabilities: ['log'],
161+
},
162+
} as any);
163+
expect(typeof fn).toBe('function');
164+
165+
const value = await fn!({ params: { n: 3 } } as any);
166+
expect(value).toEqual({ ok: true });
167+
168+
const line = logger.lines.find((l) => l.message.includes('recalculated: 3'));
169+
expect(line?.level).toBe('info');
170+
expect(line!.message).toContain('recalculate_totals');
171+
});
172+
});

‎packages/runtime/src/sandbox/body-runner.ts‎

Lines changed: 113 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -49,6 +49,92 @@ interface FactoryOptions {
4949
logger?: any;
5050
}
5151

52+
/**
53+
* Build the `['log']` capability surface for one body invocation (#7448).
54+
*
55+
* ## Why this is not `engineCtx?.logger`
56+
*
57+
* It was, at `:339` (hooks) and `:377` (actions), and that key is written by
58+
* nobody. `HookContextSchema` (`packages/spec/src/data/hook.zod.ts`) declares
59+
* no `logger`, and ObjectQL's engine — the sole producer of a HookContext —
60+
* builds all four of them (`engine.ts` `beforeFind` / `find` / `update` /
61+
* `delete` assembly sites) without one. Both action-context assembly sites
62+
* (`../domains/actions.ts` REST `/actions`, `../action-execution.ts` MCP
63+
* `run_action`) likewise write no `logger`. So `ctx.log` resolved `undefined`
64+
* on EVERY path, and `installCtx` (`quickjs-runner.ts`) forwards through
65+
* `ctx.log?.[level]?.(…)` — an optional call on an absent host seam. The
66+
* capability gate passes, the VM-side `ctx.log.info` exists, the body runs to
67+
* completion and returns normally, and the line goes nowhere. QA run #7439 saw
68+
* exactly that: `[BodyRunner] hook fired` at `--log-level debug` with the
69+
* body's own `ctx.log.info('task completed: …')` absent.
70+
*
71+
* That is the third limb of this shape removed from this file, not the first:
72+
* `doc` / `previousDoc` (#5906) and `session.user` (#6316) were also keys no
73+
* producer ever wrote, deleted rather than left as a second de-facto contract
74+
* (Prime Directive #12). The remedy is the same — read the source that exists.
75+
* `opts.logger` is the engine's own `Logger`, handed to the factory by all four
76+
* construction sites in `../app-plugin.ts` (`logger: ctx.logger`), and it is
77+
* the very logger whose `[BodyRunner] hook fired` WAS observable in the same
78+
* QA run. Adding a `logger` to `HookContextSchema` instead would widen the
79+
* metadata contract to re-supply, per invocation, something the runner already
80+
* holds for the lifetime of the bind.
81+
*
82+
* ## Why absence warns rather than falling back to `console`
83+
*
84+
* A declared capability must not silently produce nothing — either it works or
85+
* the author is told it cannot. When the factory was constructed with no logger
86+
* at all, working is not on the table, so this takes the told branch. Routing
87+
* to `console` instead would override a decision that belongs to the host: a
88+
* `Logger` carries the level threshold, formatting and sinks the host chose,
89+
* and a host running at `warn` would start receiving body `info` lines on an
90+
* unfiltered second stream it never configured. No production path reaches the
91+
* warning — all four `../app-plugin.ts` sites pass `ctx.logger` — so it is a
92+
* diagnostic for embedders that construct the factory directly, and it fires
93+
* once per invocation rather than once per call so a chatty body cannot bury
94+
* the rest of the log.
95+
*/
96+
function buildBodyLogSurface(
97+
opts: FactoryOptions,
98+
origin: { kind: 'hook' | 'action'; name: string },
99+
): ScriptContext['log'] {
100+
const logger = opts.logger;
101+
const label = `[${origin.kind} '${origin.name}']`;
102+
103+
if (!logger) {
104+
let warned = false;
105+
const warnOnce = () => {
106+
if (warned) return;
107+
warned = true;
108+
console.warn(
109+
`[BodyRunner] ${origin.kind} '${origin.name}' (app '${opts.appId}') declares the 'log' ` +
110+
`capability, but this BodyRunner was constructed without a logger — ctx.log output is ` +
111+
`discarded. Pass \`logger\` to ${origin.kind}BodyRunnerFactory({ … }). See #7448.`,
112+
);
113+
};
114+
return { info: warnOnce, warn: warnOnce, error: warnOnce };
115+
}
116+
117+
// `Logger.meta` is a `Record` (`packages/spec/src/contracts/logger.ts`); a
118+
// body may pass anything JSON-serialisable, so non-objects are carried under
119+
// a `data` key rather than dropped on the floor.
120+
const toMeta = (data: unknown): Record<string, any> | undefined => {
121+
if (data === undefined || data === null) return undefined;
122+
if (typeof data === 'object' && !Array.isArray(data)) return data as Record<string, any>;
123+
return { data };
124+
};
125+
126+
return {
127+
info: (msg: string, data?: unknown) => logger.info?.(`${label} ${msg}`, toMeta(data)),
128+
warn: (msg: string, data?: unknown) => logger.warn?.(`${label} ${msg}`, toMeta(data)),
129+
// ⚠️ `Logger.error` is `(message, error, meta)` — THREE args, and the body's
130+
// `data` is the third. Passing it second lands a meta object in the `Error`
131+
// slot, where `ConsoleLogger`/`JsonLogger` read `error.message`/`error.stack`
132+
// as `undefined` and drop every field, leaving a bare sentence. Same trap
133+
// `hook-wrappers.ts` documents for `HookDiagnosticsLogger`.
134+
error: (msg: string, data?: unknown) => logger.error?.(`${label} ${msg}`, undefined, toMeta(data)),
135+
};
136+
}
137+
52138
export function hookBodyRunnerFactory(
53139
runner: ScriptRunner,
54140
opts: FactoryOptions,
@@ -69,7 +155,11 @@ export function hookBodyRunnerFactory(
69155
const body = parsed.data;
70156

71157
return async function boundBodyHandler(engineCtx: any): Promise<void> {
72-
const sandboxCtx = buildSandboxContext(engineCtx, opts.ql);
158+
const sandboxCtx = buildSandboxContext(
159+
engineCtx,
160+
opts.ql,
161+
buildBodyLogSurface(opts, { kind: 'hook', name: hook.name }),
162+
);
73163
try {
74164
opts.logger?.debug?.('[BodyRunner] hook fired', { appId: opts.appId, hook: hook.name });
75165
const result = await runner.run(body, sandboxCtx, {
@@ -169,7 +259,11 @@ export function actionBodyRunnerFactory(
169259
const body = parsed.data;
170260

171261
return async function boundActionHandler(actionCtx: any): Promise<unknown> {
172-
const sandboxCtx = buildActionSandboxContext(actionCtx, opts.ql);
262+
const sandboxCtx = buildActionSandboxContext(
263+
actionCtx,
264+
opts.ql,
265+
buildBodyLogSurface(opts, { kind: 'action', name: action.name }),
266+
);
173267
try {
174268
opts.logger?.debug?.('[BodyRunner] action fired', {
175269
appId: opts.appId,
@@ -304,7 +398,11 @@ function buildSandboxApi(engineCtx: any, ql: any, errLabel: string) {
304398
};
305399
}
306400

307-
function buildSandboxContext(engineCtx: any, ql: any): ScriptContext {
401+
function buildSandboxContext(
402+
engineCtx: any,
403+
ql: any,
404+
log: ScriptContext['log'],
405+
): ScriptContext {
308406
// `input` and `previous` are the engine's own spellings, and the only ones:
309407
// `HookContextSchema` (`packages/spec/src/data/hook.zod.ts`) declares neither a
310408
// top-level `doc` nor a `previousDoc`, and objectql's `engine.ts` — the sole
@@ -336,12 +434,19 @@ function buildSandboxContext(engineCtx: any, ql: any): ScriptContext {
336434
object: typeof engineCtx?.object === 'string' ? engineCtx.object : undefined,
337435
result: engineCtx?.result,
338436
api: buildSandboxApi(engineCtx, ql, 'hook body'),
339-
log: engineCtx?.logger,
437+
// [#7448] NOT `engineCtx?.logger` — a key no HookContext producer writes and
438+
// `HookContextSchema` never declared, so the `['log']` capability resolved
439+
// `undefined` and every body log line vanished. See {@link buildBodyLogSurface}.
440+
log,
340441
crypto: globalThis.crypto,
341442
};
342443
}
343444

344-
function buildActionSandboxContext(actionCtx: any, ql: any): ScriptContext {
445+
function buildActionSandboxContext(
446+
actionCtx: any,
447+
ql: any,
448+
log: ScriptContext['log'],
449+
): ScriptContext {
345450
// Action ctx convention (mirrors http-dispatcher.ts):
346451
// { record, params, recordId, user, session, engine, services, ... }
347452
// The script signature is `(input, ctx)` — input gets `params`, ctx gets
@@ -374,7 +479,9 @@ function buildActionSandboxContext(actionCtx: any, ql: any): ScriptContext {
374479
// a body makes to it rather than letting them vanish.
375480
record: unwrapProxyToPlain(actionCtx?.record),
376481
api: buildSandboxApi(actionCtx, ql, 'action body'),
377-
log: actionCtx?.logger,
482+
// [#7448] Same removal as the hook face: neither action-context assembly
483+
// site (`../domains/actions.ts`, `../action-execution.ts`) writes `logger`.
484+
log,
378485
crypto: globalThis.crypto,
379486
};
380487
}

0 commit comments

Comments
 (0)