Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
39 changes: 39 additions & 0 deletions .changeset/ctx-log-debug-installed.md
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,39 @@
---
"@objectstack/runtime": patch
---

fix(runtime): `ctx.log.debug` works in hook and action bodies — the sandbox installs the fourth level the CLI and docs already promise (#7661)

A body that called `ctx.log.debug(…)` threw **`TypeError: not a function`**
inside the VM. Under `onError: 'abort'` that aborted the write, so the failure
mode was a refused save, not a missing log line.

Nothing about the body was wrong. `debug` was declared on three surfaces and
implemented on none:

- the CLI's capability extractor matched `ctx.log.debug` and granted the `log`
capability for it, so `os build` blessed the body,
- the docs table taught `ctx.log.info / warn / error / debug` → `log`, and
- the sandbox installed `info` / `warn` / `error`.

An author who followed the documentation got a body whose declared capability
was satisfied and whose call then threw. `debug` is now installed in the QuickJS
`ctx.log` bridge and declared on the sandbox's `ScriptContext['log']`, so all
four surfaces agree on four methods.

**Enforced rather than retired** (ADR-0049 enforce-or-remove). This is the same
shape as `crypto.hash` (#4391) one member over, but that one was removed because
implementing it widened the sandbox's *security* surface. Emitting a debug-level
diagnostic from a hook body carries no such argument — `--log-level debug` is
exactly what such a body is for — and `Logger.debug(message, meta)` already
existed on the contract, so the host logger needed nothing new.

`debug` behaves like the other three levels in every respect: it is gated behind
the `log` capability, its line is attributed to the emitting hook or action, its
structured `data` crosses the VM boundary as a value rather than
`"[object Object]"`, and when the BodyRunner was constructed without a logger it
raises the same once-per-body "ctx.log output is discarded" warning instead of
dropping the call silently.

Unaffected: `info` / `warn` / `error` behaviour, the capability tokens, the
extractor regex, and the docs table — all three were already correct.
106 changes: 106 additions & 0 deletions packages/runtime/src/sandbox/body-log-capability.test.ts
Original file line numberDiff line numberDiff line change
Expand Up@@ -144,6 +144,112 @@ describe('[#7448] hook body ctx.log reaches the host log stream', () => {
});
});

/**
* [#7661] `ctx.log.debug` is the FOURTH member, not a decoration.
*
* The extractor (`packages/cli/src/utils/extract-hook-body.ts`) already matches
* `ctx.log.debug` and grants `['log']` for it, and the docs table already
* teaches it — so an author following the documentation wrote a body whose
* declared capability was satisfied and whose call then threw
* `TypeError: not a function` inside the VM, because the install loop covered
* only `info`/`warn`/`error`. Enforce arm of ADR-0049: the sandbox grows the
* method the other surfaces already promise.
*
* Each assertion below is on what the HOST LOGGER RECEIVED, for the same reason
* the #7448 block above is: a `debug` installed as a no-op passes a
* "nothing threw" test and is still not a real fourth method.
*/
describe('[#7661] hook body ctx.log.debug is installed and delivers', () => {
const runner = new QuickJSScriptRunner();

it('delivers the card\'s own reproduction — ctx.log.debug(\'hi\') — as a debug record', async () => {
const logger = captureLogger();
const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger });
const fn = factory({
name: 'h',
object: 'showcase_task',
events: ['afterUpdate'],
body: { language: 'js', source: "ctx.log.debug('hi');", capabilities: ['log'] },
} as any);

// Before the install this rejected with `TypeError: not a function`, so the
// await itself is half the pin: under `onError: 'abort'` that throw aborts
// the write.
await expect(fn!({ input: {} } as any)).resolves.toBeUndefined();

// …and the other half: the record REACHED the logger, at debug level.
const emitted = logger.lines.filter((l) => l.message.includes('hi'));
expect(emitted.length).toBe(1);
expect(emitted[0].level).toBe('debug');
// Attributed like every other level — an author running ten hooks at
// `--log-level debug` has to be able to tell which one spoke.
expect(emitted[0].message).toContain('h');
});

it('carries structured data across the VM boundary as a value', async () => {
const logger = captureLogger();
const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger });
const fn = factory({
name: 'showcase_debug_trace',
object: 'showcase_task',
events: ['afterUpdate'],
body: {
language: 'js',
source: "ctx.log.debug('trace', { step: 2, tags: ['a'], at: { deep: true } });",
capabilities: ['log'],
},
} as any);

await fn!({ input: {} } as any);

const line = logger.lines.find((l) => l.message.includes('trace'));
expect(line?.level).toBe('debug');
// `Logger.debug` is `(message, meta)` — two args, unlike `error`.
expect(line?.meta).toEqual({ step: 2, tags: ['a'], at: { deep: true } });
});

it('gates debug behind the log capability like the other three levels', async () => {
const logger = captureLogger();
const factory = hookBodyRunnerFactory(runner, { ql: {}, appId: 'showcase', logger });
const fn = factory({
name: 'ungranted_hook',
object: 'showcase_task',
events: ['afterUpdate'],
// `capabilities` omits 'log' — the fourth method must be no cheaper to
// reach than the first three.
body: { language: 'js', source: "ctx.log.debug('hi');", capabilities: [] },
} as any);

await expect(fn!({ input: {} } as any)).rejects.toThrow(/capability 'log' not granted/);
expect(logger.lines.filter((l) => l.message.includes('hi'))).toHaveLength(0);
});

it('names the hook in the unservable-capability warning for debug too', async () => {
// The no-logger surface returns a warn-once stub per method; a `debug`
// missing from it would be `undefined` and throw inside the VM again —
// the same defect one construction shape over.
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_debug_hook',
object: 'showcase_task',
events: ['afterUpdate'],
body: { language: 'js', source: "ctx.log.debug('a');", capabilities: ['log'] },
} as any);
await expect(fn!({ input: {} } as any)).resolves.toBeUndefined();
} finally {
console.warn = original;
}

const capabilityWarnings = warnings.filter((w) => w.includes('ctx.log output is discarded'));
expect(capabilityWarnings.length).toBe(1);
expect(capabilityWarnings[0]).toContain('silent_debug_hook');
});
});

describe('[#7448] action body ctx.log reaches the host log stream', () => {
const runner = new QuickJSScriptRunner();

Expand Down
13 changes: 12 additions & 1 deletion packages/runtime/src/sandbox/body-runner.ts
Original file line numberDiff line numberDiff line change
Expand Up@@ -111,7 +111,10 @@ function buildBodyLogSurface(
`discarded. Pass \`logger\` to ${origin.kind}BodyRunnerFactory({ … }). See #7448.`,
);
};
return { info: warnOnce, warn: warnOnce, error: warnOnce };
// [#7661] `debug` is warned for like the other three. A member missing from
// THIS branch is `undefined` at `ctx.log?.[level]?.(…)`, which is the same
// `TypeError: not a function` one construction shape over.
return { debug: warnOnce, info: warnOnce, warn: warnOnce, error: warnOnce };
}

// `Logger.meta` is a `Record` (`packages/spec/src/contracts/logger.ts`); a
Expand All@@ -124,6 +127,14 @@ function buildBodyLogSurface(
};

return {
// [#7661] The fourth level. `installCtx` forwards through
// `ctx.log?.[level]?.(…)` — an optional call — so a `debug` absent from this
// object is not a throw but a SILENT DROP: the VM-side method exists, the
// body runs to completion, and the line goes nowhere. That is the #7448
// defect verbatim, which is why the pin asserts a delivered record rather
// than the absence of a throw. `Logger.debug` is `(message, meta)` — two
// args, like `info`/`warn` and unlike `error` below.
debug: (msg: string, data?: unknown) => logger.debug?.(`${label} ${msg}`, toMeta(data)),
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
Expand Down
Original file line numberDiff line numberDiff line change
Expand Up@@ -92,7 +92,9 @@ describe('[#4431] an in-VM capability denial reaches the classifier as a FAULT',
});

it('ctx.log without the log capability', async () => {
const log = { info: () => {}, warn: () => {}, error: () => {} };
// Four members since #7661 — `debug` is a real level of this seam, not a
// decoration, so a host double that omits it no longer type-checks.
const log = { debug: () => {}, info: () => {}, warn: () => {}, error: () => {} };
const err = await faultOf(() =>
runner.runScript(
{ language: 'js', source: "ctx.log.info('hi'); return 1;", capabilities: [] },
Expand Down
3 changes: 2 additions & 1 deletion packages/runtime/src/sandbox/quickjs-runner.test.ts
Original file line numberDiff line numberDiff line change
Expand Up@@ -111,7 +111,8 @@ describe('QuickJSScriptRunner — L2 hook script', () => {
});

it('rejects log calls without log capability', async () => {
const log = { info: () => {}, warn: () => {}, error: () => {} };
// Four members since #7661 — see `ScriptContext['log']`.
const log = { debug: () => {}, info: () => {}, warn: () => {}, error: () => {} };
await expect(
runner.runScript(
{
Expand Down
14 changes: 13 additions & 1 deletion packages/runtime/src/sandbox/quickjs-runner.ts
Original file line numberDiff line numberDiff line change
Expand Up@@ -636,7 +636,19 @@ export class QuickJSScriptRunner implements ScriptRunner {
apiObj.dispose();

const logObj = vm.newObject();
for (const level of ['info', 'warn', 'error'] as const) {
// [#7661] FOUR levels, not three. `debug` was granted by the CLI's
// capability extractor (`ctx\.log\.(?:info|warn|error|debug)` → `log`) and
// taught by the docs table while this loop installed only the first three,
// so a body that followed the documentation threw `TypeError: not a
// function` here — and under `onError: 'abort'` that aborted the write.
// Enforced rather than retired from the other two surfaces (ADR-0049): the
// `crypto.hash` precedent this shape echoes (#4391) was removed because
// implementing it widened the sandbox's SECURITY surface, and emitting a
// debug-level diagnostic carries no such argument — `--log-level debug` is
// exactly what such a body is for. `Logger.debug(message, meta)` is on the
// contract (`packages/spec/src/contracts/logger.ts`), so nothing new is
// required of the host logger either.
for (const level of ['debug', 'info', 'warn', 'error'] as const) {
const fn = vm.newFunction(level, (msgH, dataH) => {
if (!caps.has('log')) {
throwSandboxFault(vm, `capability 'log' not granted to ${origin.kind} '${origin.name}'`);
Expand Down
13 changes: 13 additions & 0 deletions packages/runtime/src/sandbox/script-runner.ts
Original file line numberDiff line numberDiff line change
Expand Up@@ -240,7 +240,20 @@ export interface ScriptContext {
/** Engine-side `result` (only set for after* hooks). */
result?: unknown;
api?: unknown;
/**
* Host-provided log seam for the `['log']` capability — four levels, matching
* the four `installCtx` (quickjs-runner.ts) wires onto the VM's `ctx.log` and
* the four the CLI's capability extractor infers `log` from.
*
* `debug` joined the other three in #7661. It was the `crypto.hash` shape one
* member over — inferred by the extractor and taught by the docs table with
* nothing installed behind it, so the one call it typed threw inside the VM.
* Unlike hashing it was ENFORCED rather than removed (ADR-0049): a body
* emitting debug-level diagnostics is exactly what `--log-level debug` is
* for, and `Logger.debug(message, meta)` already existed on the contract.
*/
log?: {
debug: (msg: string, data?: unknown) => void;
info: (msg: string, data?: unknown) => void;
warn: (msg: string, data?: unknown) => void;
error: (msg: string, data?: unknown) => void;
Expand Down
Loading