|
| 1 | +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. |
| 2 | + |
| 3 | +/** |
| 4 | + * [#26153] A sandboxed body's BUSINESS REFUSAL is logged once, at `info`, |
| 5 | + * without a stack; a FAULT keeps `error` and its stack. |
| 6 | + * |
| 7 | + * ## What was measured broken |
| 8 | + * |
| 9 | + * A `beforeUpdate` hook refusing a script action's `ctx.api` write |
| 10 | + * (`422 INVALID_STATE` on the wire) wrote two `ERROR [BodyRunner]` lines with |
| 11 | + * full stacks for one ordinary refusal: `sandboxed hook threw` at the hook's |
| 12 | + * catch, then `sandboxed action threw` at the action's catch for the same |
| 13 | + * refusal relayed across the VM hop. An operator watching ERROR could not tell |
| 14 | + * a refused click from a crashed hook. |
| 15 | + * |
| 16 | + * ## The line this file pins |
| 17 | + * |
| 18 | + * Refusal vs fault is read off {@link mapDataError} — the ADR-0112 table the |
| 19 | + * HTTP doors answer with — by its status band, never a second list. The last |
| 20 | + * block pins that, for every shape reaching these catches, its band is the |
| 21 | + * band the `/actions` door actually answers, so the log level cannot drift |
| 22 | + * from the status the caller saw. |
| 23 | + */ |
| 24 | + |
| 25 | +import { describe, it, expect, vi } from 'vitest'; |
| 26 | +import { mapDataError } from '@objectstack/types'; |
| 27 | + |
| 28 | +import { HttpDispatcher } from '../http-dispatcher.js'; |
| 29 | +import { actionBodyRunnerFactory, hookBodyRunnerFactory } from './body-runner.js'; |
| 30 | +import { QuickJSScriptRunner } from './quickjs-runner.js'; |
| 31 | + |
| 32 | +const REFUSAL = 'A current clean version is required before signing.'; |
| 33 | + |
| 34 | +const runner = new QuickJSScriptRunner({ hookTimeoutMs: 10_000, actionTimeoutMs: 10_000 }); |
| 35 | + |
| 36 | +interface LogCall { level: 'debug' | 'info' | 'warn' | 'error'; msg: string; err?: unknown; meta?: any } |
| 37 | + |
| 38 | +/** A logger that records every call, so a test reads level, error argument and meta. */ |
| 39 | +function recordingLogger() { |
| 40 | + const calls: LogCall[] = []; |
| 41 | + return { |
| 42 | + calls, |
| 43 | + logger: { |
| 44 | + debug: (msg: string, meta?: any) => calls.push({ level: 'debug', msg, meta }), |
| 45 | + info: (msg: string, meta?: any) => calls.push({ level: 'info', msg, meta }), |
| 46 | + warn: (msg: string, meta?: any) => calls.push({ level: 'warn', msg, meta }), |
| 47 | + error: (msg: string, err?: unknown, meta?: any) => calls.push({ level: 'error', msg, err, meta }), |
| 48 | + }, |
| 49 | + /** The calls an operator sees at the default level: everything above `debug`. */ |
| 50 | + visible: () => calls.filter((c) => c.level !== 'debug'), |
| 51 | + }; |
| 52 | +} |
| 53 | + |
| 54 | +/** Does any argument of this call carry a stack? */ |
| 55 | +function carriesStack(call: LogCall): boolean { |
| 56 | + const hasStack = (v: unknown) => typeof (v as { stack?: unknown } | null)?.stack === 'string'; |
| 57 | + return hasStack(call.err) || hasStack(call.meta) || Object.values(call.meta ?? {}).some(hasStack); |
| 58 | +} |
| 59 | + |
| 60 | +const REFUSING_HOOK = ` |
| 61 | + const e = new Error(${JSON.stringify(REFUSAL)}); |
| 62 | + e.code = 'INVALID_STATE'; |
| 63 | + e.status = 422; |
| 64 | + throw e; |
| 65 | +`; |
| 66 | +const CRASHING_HOOK = 'const v = null; return v.version;'; |
| 67 | + |
| 68 | +/** A sandboxed `beforeUpdate` hook bound through the real factory. */ |
| 69 | +function boundHook(logger: object, source: string) { |
| 70 | + const fn = hookBodyRunnerFactory(runner, { ql: {}, appId: 'clm', logger })({ |
| 71 | + name: 'contract_state_machine', |
| 72 | + object: 'clm_contract', |
| 73 | + events: ['beforeUpdate'], |
| 74 | + body: { language: 'js', source }, |
| 75 | + } as any); |
| 76 | + expect(fn, 'the hook body must bind').toBeTypeOf('function'); |
| 77 | + return fn!; |
| 78 | +} |
| 79 | + |
| 80 | +/** |
| 81 | + * A script action whose `ctx.api` write dispatches the hook, as the engine |
| 82 | + * does: the update the body asks for runs the bound hook first. |
| 83 | + */ |
| 84 | +function boundAction(logger: object, hook: (ctx: any) => Promise<void>, source?: string) { |
| 85 | + const ql = { |
| 86 | + object: (object: string) => ({ |
| 87 | + update: async (data: any) => { |
| 88 | + await hook({ object, event: 'beforeUpdate', input: { ...data } }); |
| 89 | + return data; |
| 90 | + }, |
| 91 | + }), |
| 92 | + }; |
| 93 | + const fn = actionBodyRunnerFactory(runner, { ql, appId: 'clm', logger })({ |
| 94 | + name: 'start_signing', |
| 95 | + object: 'clm_contract', |
| 96 | + type: 'script', |
| 97 | + body: { |
| 98 | + language: 'js', |
| 99 | + source: source ?? "return await ctx.api.object('clm_contract').update({ id: ctx.recordId, status: 'signing' });", |
| 100 | + capabilities: ['api.write'], |
| 101 | + }, |
| 102 | + }); |
| 103 | + expect(fn, 'the action body must bind').toBeTypeOf('function'); |
| 104 | + return fn!; |
| 105 | +} |
| 106 | + |
| 107 | +async function rejectionOf(p: Promise<unknown>): Promise<any> { |
| 108 | + const err = await p.then(() => null, (e) => e); |
| 109 | + expect(err, 'expected the body to reject — a throw is never swallowed').not.toBeNull(); |
| 110 | + return err; |
| 111 | +} |
| 112 | + |
| 113 | +describe('[#26153] a business refusal is logged once, at info, without a stack', () => { |
| 114 | + it('a hook refusal reached through a script action: one info line, no error line', async () => { |
| 115 | + const rec = recordingLogger(); |
| 116 | + const action = boundAction(rec.logger, boundHook(rec.logger, REFUSING_HOOK)); |
| 117 | + |
| 118 | + const err = await rejectionOf(action({ recordId: 'c_1', record: { id: 'c_1' } })); |
| 119 | + |
| 120 | + // Still rethrown, still the refusal the door answers 422 INVALID_STATE. |
| 121 | + expect(err.innerMessage).toBe(REFUSAL); |
| 122 | + expect(err.code).toBe('INVALID_STATE'); |
| 123 | + expect(err.status).toBe(422); |
| 124 | + |
| 125 | + const visible = rec.visible(); |
| 126 | + expect(visible.filter((c) => c.level === 'error'), 'a refusal is not an ERROR').toEqual([]); |
| 127 | + expect(visible, 'one line for one refusal — the action must not repeat its hook').toHaveLength(1); |
| 128 | + const [line] = visible; |
| 129 | + expect(line.level).toBe('info'); |
| 130 | + expect(carriesStack(line), 'a refusal line carries no stack').toBe(false); |
| 131 | + expect(line.meta).toMatchObject({ hook: 'contract_state_machine', code: 'INVALID_STATE', status: 422 }); |
| 132 | + }); |
| 133 | + |
| 134 | + it('a hook refusal fired by a /data write (no action): one info line naming the hook', async () => { |
| 135 | + const rec = recordingLogger(); |
| 136 | + const hook = boundHook(rec.logger, REFUSING_HOOK); |
| 137 | + |
| 138 | + await rejectionOf(hook({ object: 'clm_contract', event: 'beforeUpdate', input: { id: 'c_1' } })); |
| 139 | + |
| 140 | + const visible = rec.visible(); |
| 141 | + expect(visible).toHaveLength(1); |
| 142 | + expect(visible[0].level).toBe('info'); |
| 143 | + expect(carriesStack(visible[0])).toBe(false); |
| 144 | + expect(visible[0].meta).toMatchObject({ hook: 'contract_state_machine', code: 'INVALID_STATE', status: 422 }); |
| 145 | + }); |
| 146 | + |
| 147 | + it("an action body's OWN refusal: one info line naming the action", async () => { |
| 148 | + const rec = recordingLogger(); |
| 149 | + const action = boundAction(rec.logger, async () => {}, REFUSING_HOOK); |
| 150 | + |
| 151 | + const err = await rejectionOf(action({ recordId: 'c_1' })); |
| 152 | + expect(err.status).toBe(422); |
| 153 | + |
| 154 | + const visible = rec.visible(); |
| 155 | + expect(visible).toHaveLength(1); |
| 156 | + expect(visible[0].level).toBe('info'); |
| 157 | + expect(carriesStack(visible[0])).toBe(false); |
| 158 | + expect(visible[0].meta).toMatchObject({ action: 'start_signing', code: 'INVALID_STATE', status: 422 }); |
| 159 | + }); |
| 160 | +}); |
| 161 | + |
| 162 | +describe('[#26153] a fault keeps error and its stack', () => { |
| 163 | + it('a hook that crashes through an action: error with a stack at both catches (kept as before)', async () => { |
| 164 | + const rec = recordingLogger(); |
| 165 | + const action = boundAction(rec.logger, boundHook(rec.logger, CRASHING_HOOK)); |
| 166 | + |
| 167 | + await rejectionOf(action({ recordId: 'c_1' })); |
| 168 | + |
| 169 | + const visible = rec.visible(); |
| 170 | + // A repeated FAULT is left as it was: the hook's line and the action's. |
| 171 | + expect(visible.map((c) => [c.level, c.msg])).toEqual([ |
| 172 | + ['error', '[BodyRunner] sandboxed hook threw'], |
| 173 | + ['error', '[BodyRunner] sandboxed action threw'], |
| 174 | + ]); |
| 175 | + expect(visible.every(carriesStack), 'a fault keeps its stack').toBe(true); |
| 176 | + }); |
| 177 | + |
| 178 | + it("an action body's own crash: one error line with a stack", async () => { |
| 179 | + const rec = recordingLogger(); |
| 180 | + const action = boundAction(rec.logger, async () => {}, CRASHING_HOOK); |
| 181 | + |
| 182 | + await rejectionOf(action({ recordId: 'c_1' })); |
| 183 | + |
| 184 | + const visible = rec.visible(); |
| 185 | + expect(visible).toHaveLength(1); |
| 186 | + expect(visible[0].level).toBe('error'); |
| 187 | + expect(carriesStack(visible[0])).toBe(true); |
| 188 | + }); |
| 189 | +}); |
| 190 | + |
| 191 | +// ── the level follows the wire ─────────────────────────────────────────────── |
| 192 | + |
| 193 | +const scriptAction = { |
| 194 | + name: 'start_signing', |
| 195 | + objectName: 'clm_contract', |
| 196 | + type: 'script', |
| 197 | + body: { language: 'js', source: 'return 1;', capabilities: ['api.write'] }, |
| 198 | +}; |
| 199 | + |
| 200 | +/** The `/actions` door harness `nested-hook-refusal-is-a-rejection.test.ts` uses. */ |
| 201 | +async function actionsDoorStatus(thrown: unknown): Promise<number> { |
| 202 | + const objectDef = { name: 'clm_contract', actions: [scriptAction] }; |
| 203 | + const ql: any = { |
| 204 | + executeAction: vi.fn(async () => { throw thrown; }), |
| 205 | + getSchema: (n: string) => (n === objectDef.name ? objectDef : undefined), |
| 206 | + registry: { getObject: (n: string) => (n === objectDef.name ? objectDef : undefined), getItem: () => undefined }, |
| 207 | + find: vi.fn(async () => [{ id: 'c_1', status: 'draft' }]), |
| 208 | + insert: vi.fn(), update: vi.fn(), delete: vi.fn(), |
| 209 | + }; |
| 210 | + const metadata: any = { |
| 211 | + load: vi.fn(async () => null), |
| 212 | + listObjects: vi.fn(async () => [objectDef]), |
| 213 | + getObject: vi.fn(async () => objectDef), |
| 214 | + }; |
| 215 | + const kernel: any = { |
| 216 | + context: { getService: (n: string) => (n === 'objectql' || n === 'data' ? ql : n === 'metadata' ? metadata : null) }, |
| 217 | + }; |
| 218 | + const res: any = await new HttpDispatcher(kernel).handleActions( |
| 219 | + '/clm_contract/start_signing/c_1', |
| 220 | + 'POST', |
| 221 | + {}, |
| 222 | + { request: {}, environmentId: 'platform', executionContext: { userId: 'u1', systemPermissions: [] } } as any, |
| 223 | + ); |
| 224 | + return res.response.status; |
| 225 | +} |
| 226 | + |
| 227 | +const band = (status: number) => (status < 500 ? '4xx' : '5xx'); |
| 228 | + |
| 229 | +describe('[#26153] the refusal/fault split is the band the /actions door answers', () => { |
| 230 | + const escapes: Array<[string, () => Promise<any>]> = [ |
| 231 | + ['a nested hook refusal (422)', () => |
| 232 | + rejectionOf(boundAction(recordingLogger().logger, boundHook(recordingLogger().logger, REFUSING_HOOK))({ recordId: 'c_1' }))], |
| 233 | + ['an action refusal with no declared status', () => |
| 234 | + rejectionOf(boundAction(recordingLogger().logger, async () => {}, `throw new Error(${JSON.stringify(REFUSAL)});`)({ recordId: 'c_1' }))], |
| 235 | + ['a nested hook crash', () => |
| 236 | + rejectionOf(boundAction(recordingLogger().logger, boundHook(recordingLogger().logger, CRASHING_HOOK))({ recordId: 'c_1' }))], |
| 237 | + ['an action crash', () => |
| 238 | + rejectionOf(boundAction(recordingLogger().logger, async () => {}, CRASHING_HOOK)({ recordId: 'c_1' }))], |
| 239 | + ['a denied capability (the sandbox\'s own fault)', () => |
| 240 | + rejectionOf(actionBodyRunnerFactory(runner, { ql: {}, appId: 'clm' })({ |
| 241 | + name: 'start_signing', object: 'clm_contract', type: 'script', |
| 242 | + body: { language: 'js', source: "return await ctx.api.object('clm_contract').update({ id: 'c_1' });" }, |
| 243 | + })!({ recordId: 'c_1' }))], |
| 244 | + ]; |
| 245 | + |
| 246 | + for (const [label, escape] of escapes) { |
| 247 | + it(label, async () => { |
| 248 | + const err = await escape(); |
| 249 | + // Read first: the door rewrites `err.message` to the client sentence. |
| 250 | + const logged = band(mapDataError(err).status); |
| 251 | + expect(logged).toBe(band(await actionsDoorStatus(err))); |
| 252 | + }); |
| 253 | + } |
| 254 | +}); |
0 commit comments