From 75bf61e8e2a3feb5308aa0d24323cd11fd2f724d Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 12 Aug 2026 03:47:00 +0000 Subject: [PATCH] fix(runtime): install ctx.log.debug in the sandbox (#7661) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `ctx.log.debug` was declared on three surfaces and implemented on none: the CLI capability extractor matched it and granted `log`, the docs table taught it, and the QuickJS install loop covered only `info`/`warn`/`error`. A body that followed the documentation therefore threw `TypeError: not a function` inside the VM — and under `onError: 'abort'` that aborted the write. Enforced rather than retired (ADR-0049). The `crypto.hash` precedent this shape echoes (#4391) was removed because implementing it widened the sandbox's security surface; emitting a debug-level diagnostic carries no such argument, and `Logger.debug(message, meta)` already existed on the contract. - `quickjs-runner.ts`: the install loop now covers four levels. - `script-runner.ts`: `ScriptContext['log']` declares `debug`. - `body-runner.ts`: the host-side log surface forwards `debug` to the factory's logger, and warns for it in the no-logger branch. Without this the new VM method would be a SILENT DROP rather than a throw, since `installCtx` forwards through the optional call `ctx.log?.[level]?.(…)`. Two existing test doubles built a three-member `ctx.log`; they now build four. Reverse-verified in both directions: with the install reverted the new pin fails with the card's own `TypeError: not a function`, and with only the host-side forward removed it fails on the delivery assertions while nothing throws — so the pin cannot be satisfied by a no-op `debug`. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01CUymLqPDq3d7PgiwpZsbA2 --- .changeset/ctx-log-debug-installed.md | 39 +++++++ .../src/sandbox/body-log-capability.test.ts | 106 ++++++++++++++++++ packages/runtime/src/sandbox/body-runner.ts | 13 ++- .../capability-denial-is-a-fault.test.ts | 4 +- .../src/sandbox/quickjs-runner.test.ts | 3 +- .../runtime/src/sandbox/quickjs-runner.ts | 14 ++- packages/runtime/src/sandbox/script-runner.ts | 13 +++ 7 files changed, 188 insertions(+), 4 deletions(-) create mode 100644 .changeset/ctx-log-debug-installed.md diff --git a/.changeset/ctx-log-debug-installed.md b/.changeset/ctx-log-debug-installed.md new file mode 100644 index 0000000000..5884ac144a --- /dev/null +++ b/.changeset/ctx-log-debug-installed.md @@ -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. diff --git a/packages/runtime/src/sandbox/body-log-capability.test.ts b/packages/runtime/src/sandbox/body-log-capability.test.ts index d687e59a29..1cb49eb12c 100644 --- a/packages/runtime/src/sandbox/body-log-capability.test.ts +++ b/packages/runtime/src/sandbox/body-log-capability.test.ts @@ -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(); diff --git a/packages/runtime/src/sandbox/body-runner.ts b/packages/runtime/src/sandbox/body-runner.ts index ee20a29432..1d478edb97 100644 --- a/packages/runtime/src/sandbox/body-runner.ts +++ b/packages/runtime/src/sandbox/body-runner.ts @@ -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 @@ -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 diff --git a/packages/runtime/src/sandbox/capability-denial-is-a-fault.test.ts b/packages/runtime/src/sandbox/capability-denial-is-a-fault.test.ts index f581787878..49ed25be18 100644 --- a/packages/runtime/src/sandbox/capability-denial-is-a-fault.test.ts +++ b/packages/runtime/src/sandbox/capability-denial-is-a-fault.test.ts @@ -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: [] }, diff --git a/packages/runtime/src/sandbox/quickjs-runner.test.ts b/packages/runtime/src/sandbox/quickjs-runner.test.ts index c1815279a5..42e99dc10d 100644 --- a/packages/runtime/src/sandbox/quickjs-runner.test.ts +++ b/packages/runtime/src/sandbox/quickjs-runner.test.ts @@ -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( { diff --git a/packages/runtime/src/sandbox/quickjs-runner.ts b/packages/runtime/src/sandbox/quickjs-runner.ts index 8a59690846..6302862040 100644 --- a/packages/runtime/src/sandbox/quickjs-runner.ts +++ b/packages/runtime/src/sandbox/quickjs-runner.ts @@ -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}'`); diff --git a/packages/runtime/src/sandbox/script-runner.ts b/packages/runtime/src/sandbox/script-runner.ts index f0cd3bf0dd..cbb7dce8b0 100644 --- a/packages/runtime/src/sandbox/script-runner.ts +++ b/packages/runtime/src/sandbox/script-runner.ts @@ -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;