diff --git a/.changeset/26153-body-refusal-log-once.md b/.changeset/26153-body-refusal-log-once.md new file mode 100644 index 00000000000..f1455ec5415 --- /dev/null +++ b/.changeset/26153-body-refusal-log-once.md @@ -0,0 +1,14 @@ +--- +'@objectstack/runtime': patch +--- + +fix: a sandboxed hook's or action's business refusal is logged once, at info, without a stack + +Clause-②: no +Metadata-protocol: none + +When a sandboxed hook or action body refuses on purpose, for example a state-machine hook answered as `422 INVALID_STATE`, the server log used to get two `ERROR [BodyRunner]` lines with full stacks: one at the hook and one again at the action that triggered it. An operator watching for errors could not tell a refused click from a crashed hook. + +Now a throw that the HTTP doors answer in the 4xx band writes one `info` line, `[BodyRunner] sandboxed hook refused` (or `action refused`), naming the hook or action, its declared `code` and the status, with no stack. The action does not repeat a refusal its hook already logged. A throw that becomes a 5xx (a crash, a denied capability, a declared 5xx) still logs `error` with its stack, at both the hook and the action as before. + +The refusal-or-fault split is read from the same error table the HTTP doors answer with (`mapDataError`), so the log level follows the status the caller saw. The HTTP status, body and message of every refusal are unchanged, and every throw is still rethrown. diff --git a/packages/runtime/src/sandbox/body-runner.ts b/packages/runtime/src/sandbox/body-runner.ts index 58df4905a51..bfd61dd8ec7 100644 --- a/packages/runtime/src/sandbox/body-runner.ts +++ b/packages/runtime/src/sandbox/body-runner.ts @@ -72,6 +72,8 @@ import { storedMetadataBodySubjectRecordRefusal, storedMetadataFamilyTableList, } from '../stored-metadata-body-boundary.js'; +import { mapDataError } from '@objectstack/types'; +import { isRelayedSandboxRefusal } from './quickjs-runner.js'; interface FactoryOptions { ql: any; @@ -378,6 +380,39 @@ function executionContextFromHook(engineCtx: any): any { }; } +/** + * [#26153] The one log line for a sandboxed hook's or action's throw, written + * by both catches below before they rethrow. + * + * A BUSINESS REFUSAL — a throw the HTTP doors answer in the 4xx band — is an + * ordinary outcome: one `info` line naming the body, its declared `code` and + * the status, and no stack. A FAULT (5xx) keeps `error` with the error and its + * stack. The band is read off {@link mapDataError}, ADR-0112's table the doors + * answer with, ⛔ never a second list of codes or names that could drift from + * the status the caller saw; `body-throw-log-level.test.ts` pins that band + * against the `/actions` door's answer for each shape reaching these catches. + * + * A nested body's refusal re-thrown unchanged ({@link isRelayedSandboxRefusal}) + * was already logged by the nested body's own catch, so the outer one writes + * nothing for it: one refused action is one line. A relayed FAULT is still + * logged at both catches, as before. + */ +function logBodyThrow(opts: FactoryOptions, origin: { kind: 'hook' | 'action'; name: string }, err: any): void { + const subject = { appId: opts.appId, [origin.kind]: origin.name }; + const { status } = mapDataError(err); + if (status >= 500) { + opts.logger?.error?.(`[BodyRunner] sandboxed ${origin.kind} threw`, err, subject); + return; + } + if (isRelayedSandboxRefusal(err)) return; + opts.logger?.info?.(`[BodyRunner] sandboxed ${origin.kind} refused`, { + ...subject, + code: typeof err?.code === 'string' ? err.code : undefined, + status, + message: typeof err?.message === 'string' ? err.message : String(err), + }); +} + export function hookBodyRunnerFactory( runner: ScriptRunner, opts: FactoryOptions, @@ -451,10 +486,7 @@ export function hookBodyRunnerFactory( }); applyMutationsToInput(engineCtx, result, sandboxCtx.input); } catch (err: any) { - opts.logger?.error?.('[BodyRunner] sandboxed hook threw', err, { - appId: opts.appId, - hook: hook.name, - }); + logBodyThrow(opts, { kind: 'hook', name: hook.name }, err); throw err; } }; @@ -559,10 +591,7 @@ export function actionBodyRunnerFactory( warnDiscardedRecordWrites(result, action.name, action.object, opts); return result.value; } catch (err: any) { - opts.logger?.error?.('[BodyRunner] sandboxed action threw', err, { - appId: opts.appId, - action: action.name, - }); + logBodyThrow(opts, { kind: 'action', name: action.name }, err); throw err; } }; diff --git a/packages/runtime/src/sandbox/body-throw-log-level.test.ts b/packages/runtime/src/sandbox/body-throw-log-level.test.ts new file mode 100644 index 00000000000..e4af9462a45 --- /dev/null +++ b/packages/runtime/src/sandbox/body-throw-log-level.test.ts @@ -0,0 +1,254 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#26153] A sandboxed body's BUSINESS REFUSAL is logged once, at `info`, + * without a stack; a FAULT keeps `error` and its stack. + * + * ## What was measured broken + * + * A `beforeUpdate` hook refusing a script action's `ctx.api` write + * (`422 INVALID_STATE` on the wire) wrote two `ERROR [BodyRunner]` lines with + * full stacks for one ordinary refusal: `sandboxed hook threw` at the hook's + * catch, then `sandboxed action threw` at the action's catch for the same + * refusal relayed across the VM hop. An operator watching ERROR could not tell + * a refused click from a crashed hook. + * + * ## The line this file pins + * + * Refusal vs fault is read off {@link mapDataError} — the ADR-0112 table the + * HTTP doors answer with — by its status band, never a second list. The last + * block pins that, for every shape reaching these catches, its band is the + * band the `/actions` door actually answers, so the log level cannot drift + * from the status the caller saw. + */ + +import { describe, it, expect, vi } from 'vitest'; +import { mapDataError } from '@objectstack/types'; + +import { HttpDispatcher } from '../http-dispatcher.js'; +import { actionBodyRunnerFactory, hookBodyRunnerFactory } from './body-runner.js'; +import { QuickJSScriptRunner } from './quickjs-runner.js'; + +const REFUSAL = 'A current clean version is required before signing.'; + +const runner = new QuickJSScriptRunner({ hookTimeoutMs: 10_000, actionTimeoutMs: 10_000 }); + +interface LogCall { level: 'debug' | 'info' | 'warn' | 'error'; msg: string; err?: unknown; meta?: any } + +/** A logger that records every call, so a test reads level, error argument and meta. */ +function recordingLogger() { + const calls: LogCall[] = []; + return { + calls, + logger: { + debug: (msg: string, meta?: any) => calls.push({ level: 'debug', msg, meta }), + info: (msg: string, meta?: any) => calls.push({ level: 'info', msg, meta }), + warn: (msg: string, meta?: any) => calls.push({ level: 'warn', msg, meta }), + error: (msg: string, err?: unknown, meta?: any) => calls.push({ level: 'error', msg, err, meta }), + }, + /** The calls an operator sees at the default level: everything above `debug`. */ + visible: () => calls.filter((c) => c.level !== 'debug'), + }; +} + +/** Does any argument of this call carry a stack? */ +function carriesStack(call: LogCall): boolean { + const hasStack = (v: unknown) => typeof (v as { stack?: unknown } | null)?.stack === 'string'; + return hasStack(call.err) || hasStack(call.meta) || Object.values(call.meta ?? {}).some(hasStack); +} + +const REFUSING_HOOK = ` + const e = new Error(${JSON.stringify(REFUSAL)}); + e.code = 'INVALID_STATE'; + e.status = 422; + throw e; +`; +const CRASHING_HOOK = 'const v = null; return v.version;'; + +/** A sandboxed `beforeUpdate` hook bound through the real factory. */ +function boundHook(logger: object, source: string) { + const fn = hookBodyRunnerFactory(runner, { ql: {}, appId: 'clm', logger })({ + name: 'contract_state_machine', + object: 'clm_contract', + events: ['beforeUpdate'], + body: { language: 'js', source }, + } as any); + expect(fn, 'the hook body must bind').toBeTypeOf('function'); + return fn!; +} + +/** + * A script action whose `ctx.api` write dispatches the hook, as the engine + * does: the update the body asks for runs the bound hook first. + */ +function boundAction(logger: object, hook: (ctx: any) => Promise, source?: string) { + const ql = { + object: (object: string) => ({ + update: async (data: any) => { + await hook({ object, event: 'beforeUpdate', input: { ...data } }); + return data; + }, + }), + }; + const fn = actionBodyRunnerFactory(runner, { ql, appId: 'clm', logger })({ + name: 'start_signing', + object: 'clm_contract', + type: 'script', + body: { + language: 'js', + source: source ?? "return await ctx.api.object('clm_contract').update({ id: ctx.recordId, status: 'signing' });", + capabilities: ['api.write'], + }, + }); + expect(fn, 'the action body must bind').toBeTypeOf('function'); + return fn!; +} + +async function rejectionOf(p: Promise): Promise { + const err = await p.then(() => null, (e) => e); + expect(err, 'expected the body to reject — a throw is never swallowed').not.toBeNull(); + return err; +} + +describe('[#26153] a business refusal is logged once, at info, without a stack', () => { + it('a hook refusal reached through a script action: one info line, no error line', async () => { + const rec = recordingLogger(); + const action = boundAction(rec.logger, boundHook(rec.logger, REFUSING_HOOK)); + + const err = await rejectionOf(action({ recordId: 'c_1', record: { id: 'c_1' } })); + + // Still rethrown, still the refusal the door answers 422 INVALID_STATE. + expect(err.innerMessage).toBe(REFUSAL); + expect(err.code).toBe('INVALID_STATE'); + expect(err.status).toBe(422); + + const visible = rec.visible(); + expect(visible.filter((c) => c.level === 'error'), 'a refusal is not an ERROR').toEqual([]); + expect(visible, 'one line for one refusal — the action must not repeat its hook').toHaveLength(1); + const [line] = visible; + expect(line.level).toBe('info'); + expect(carriesStack(line), 'a refusal line carries no stack').toBe(false); + expect(line.meta).toMatchObject({ hook: 'contract_state_machine', code: 'INVALID_STATE', status: 422 }); + }); + + it('a hook refusal fired by a /data write (no action): one info line naming the hook', async () => { + const rec = recordingLogger(); + const hook = boundHook(rec.logger, REFUSING_HOOK); + + await rejectionOf(hook({ object: 'clm_contract', event: 'beforeUpdate', input: { id: 'c_1' } })); + + const visible = rec.visible(); + expect(visible).toHaveLength(1); + expect(visible[0].level).toBe('info'); + expect(carriesStack(visible[0])).toBe(false); + expect(visible[0].meta).toMatchObject({ hook: 'contract_state_machine', code: 'INVALID_STATE', status: 422 }); + }); + + it("an action body's OWN refusal: one info line naming the action", async () => { + const rec = recordingLogger(); + const action = boundAction(rec.logger, async () => {}, REFUSING_HOOK); + + const err = await rejectionOf(action({ recordId: 'c_1' })); + expect(err.status).toBe(422); + + const visible = rec.visible(); + expect(visible).toHaveLength(1); + expect(visible[0].level).toBe('info'); + expect(carriesStack(visible[0])).toBe(false); + expect(visible[0].meta).toMatchObject({ action: 'start_signing', code: 'INVALID_STATE', status: 422 }); + }); +}); + +describe('[#26153] a fault keeps error and its stack', () => { + it('a hook that crashes through an action: error with a stack at both catches (kept as before)', async () => { + const rec = recordingLogger(); + const action = boundAction(rec.logger, boundHook(rec.logger, CRASHING_HOOK)); + + await rejectionOf(action({ recordId: 'c_1' })); + + const visible = rec.visible(); + // A repeated FAULT is left as it was: the hook's line and the action's. + expect(visible.map((c) => [c.level, c.msg])).toEqual([ + ['error', '[BodyRunner] sandboxed hook threw'], + ['error', '[BodyRunner] sandboxed action threw'], + ]); + expect(visible.every(carriesStack), 'a fault keeps its stack').toBe(true); + }); + + it("an action body's own crash: one error line with a stack", async () => { + const rec = recordingLogger(); + const action = boundAction(rec.logger, async () => {}, CRASHING_HOOK); + + await rejectionOf(action({ recordId: 'c_1' })); + + const visible = rec.visible(); + expect(visible).toHaveLength(1); + expect(visible[0].level).toBe('error'); + expect(carriesStack(visible[0])).toBe(true); + }); +}); + +// ── the level follows the wire ─────────────────────────────────────────────── + +const scriptAction = { + name: 'start_signing', + objectName: 'clm_contract', + type: 'script', + body: { language: 'js', source: 'return 1;', capabilities: ['api.write'] }, +}; + +/** The `/actions` door harness `nested-hook-refusal-is-a-rejection.test.ts` uses. */ +async function actionsDoorStatus(thrown: unknown): Promise { + const objectDef = { name: 'clm_contract', actions: [scriptAction] }; + const ql: any = { + executeAction: vi.fn(async () => { throw thrown; }), + getSchema: (n: string) => (n === objectDef.name ? objectDef : undefined), + registry: { getObject: (n: string) => (n === objectDef.name ? objectDef : undefined), getItem: () => undefined }, + find: vi.fn(async () => [{ id: 'c_1', status: 'draft' }]), + insert: vi.fn(), update: vi.fn(), delete: vi.fn(), + }; + const metadata: any = { + load: vi.fn(async () => null), + listObjects: vi.fn(async () => [objectDef]), + getObject: vi.fn(async () => objectDef), + }; + const kernel: any = { + context: { getService: (n: string) => (n === 'objectql' || n === 'data' ? ql : n === 'metadata' ? metadata : null) }, + }; + const res: any = await new HttpDispatcher(kernel).handleActions( + '/clm_contract/start_signing/c_1', + 'POST', + {}, + { request: {}, environmentId: 'platform', executionContext: { userId: 'u1', systemPermissions: [] } } as any, + ); + return res.response.status; +} + +const band = (status: number) => (status < 500 ? '4xx' : '5xx'); + +describe('[#26153] the refusal/fault split is the band the /actions door answers', () => { + const escapes: Array<[string, () => Promise]> = [ + ['a nested hook refusal (422)', () => + rejectionOf(boundAction(recordingLogger().logger, boundHook(recordingLogger().logger, REFUSING_HOOK))({ recordId: 'c_1' }))], + ['an action refusal with no declared status', () => + rejectionOf(boundAction(recordingLogger().logger, async () => {}, `throw new Error(${JSON.stringify(REFUSAL)});`)({ recordId: 'c_1' }))], + ['a nested hook crash', () => + rejectionOf(boundAction(recordingLogger().logger, boundHook(recordingLogger().logger, CRASHING_HOOK))({ recordId: 'c_1' }))], + ['an action crash', () => + rejectionOf(boundAction(recordingLogger().logger, async () => {}, CRASHING_HOOK)({ recordId: 'c_1' }))], + ['a denied capability (the sandbox\'s own fault)', () => + rejectionOf(actionBodyRunnerFactory(runner, { ql: {}, appId: 'clm' })({ + name: 'start_signing', object: 'clm_contract', type: 'script', + body: { language: 'js', source: "return await ctx.api.object('clm_contract').update({ id: 'c_1' });" }, + })!({ recordId: 'c_1' }))], + ]; + + for (const [label, escape] of escapes) { + it(label, async () => { + const err = await escape(); + // Read first: the door rewrites `err.message` to the client sentence. + const logged = band(mapDataError(err).status); + expect(logged).toBe(band(await actionsDoorStatus(err))); + }); + } +}); diff --git a/packages/runtime/src/sandbox/quickjs-runner.ts b/packages/runtime/src/sandbox/quickjs-runner.ts index 04f49a96f07..1758a636cff 100644 --- a/packages/runtime/src/sandbox/quickjs-runner.ts +++ b/packages/runtime/src/sandbox/quickjs-runner.ts @@ -512,11 +512,14 @@ export class QuickJSScriptRunner implements ScriptRunner { // wrapper the VM error carried, which #17265 left in place on // purpose ("moves the STATUS, not the sentence") and which every // door then served verbatim as the author's words. - throw new SandboxError( + const relayed = readRelayedRefusal(vm); + const thrown = new SandboxError( `${args.origin.kind} '${args.origin.name}' threw: ${errStr}`, - readRelayedRefusal(vm) ?? userFacingMessage(withoutSandboxErrorPrefix(String(errStr))), + relayed ?? userFacingMessage(withoutSandboxErrorPrefix(String(errStr))), info, ); + if (relayed !== undefined) relayedRefusals.add(thrown); + throw thrown; } const resH = vm.getProp(vm.global, '__result'); @@ -2041,6 +2044,23 @@ function readRelayedRefusal(vm: QuickJSContext): string | undefined { return typeof raw === 'string' && raw.length > 0 ? raw : undefined; } +/** + * [#26153] The errors this runner built from a {@link readRelayedRefusal} + * sentence: a NESTED body's refusal the outer body re-threw unchanged. + * + * The nested body ran through a BodyRunner catch of its own, which already + * logged it, so the outer catch asks {@link isRelayedSandboxRefusal} rather + * than writing the same refusal a second time. Identity, not a field, for the + * reason {@link readRelayedRefusal} stays off {@link SandboxErrorInfo}: this + * is a fact about the hop, not something a caller may hand the error. + */ +const relayedRefusals = new WeakSet(); + +/** [#26153] Was this error a nested body's refusal relayed across the VM hop? */ +export function isRelayedSandboxRefusal(err: unknown): boolean { + return typeof err === 'object' && err !== null && relayedRefusals.has(err); +} + /** * Read the `__errorInfo` side-channel the wrapper's reject handler writes. * Returns `undefined` when the body's error carried nothing structured — which