From 7723686751902e06f57f8d99f8b1b8ed43d5a404 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 6 Aug 2026 04:33:32 +0000 Subject: [PATCH] fix(objectql): hook layer logs through the Logger contract, not a local dialect (#5637) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The `Logger` contract declares `error(message, error?: Error, meta?)` — the `Error` slot is second, meta third. `hook-binder.ts` and `hook-wrappers.ts` each declared their own four-method logger shape spelling `error` as `(msg, meta?)`, and their call sites put the diagnostic in the `Error` slot accordingly. tsc could not see it (the contract type satisfies the local shape structurally) and `ObjectLogger` hid it at runtime (it dispatches the second argument by shape). The contract's other implementations — `ConsoleLogger`/`JsonLogger` in `@objectstack/observability` — follow the contract literally, so the meta bag landed in the `error` slot and the whole diagnostic disappeared. - Both option interfaces now take `HookDiagnosticsLogger = Pick` from `@objectstack/spec/contracts` (PD #12: no consumer-side dialect). - All four `error(...)` call sites pass meta in the third parameter. The values in hand are a `CelFault` or a `catch` binding of type `unknown`, none of them statically an `Error`, so the `Error` slot stays `undefined`. - `debug`/`info`/`warn` already matched the contract — unchanged. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01V7WetGmnfoXNn8cLieKKmx --- .changeset/hook-logger-contract-shape.md | 49 ++++ packages/objectql/src/hook-binder.ts | 27 ++- .../src/hook-logger-contract-shape.test.ts | 229 ++++++++++++++++++ packages/objectql/src/hook-wrappers.ts | 55 ++++- 4 files changed, 340 insertions(+), 20 deletions(-) create mode 100644 .changeset/hook-logger-contract-shape.md create mode 100644 packages/objectql/src/hook-logger-contract-shape.test.ts diff --git a/.changeset/hook-logger-contract-shape.md b/.changeset/hook-logger-contract-shape.md new file mode 100644 index 0000000000..e18918ec2d --- /dev/null +++ b/.changeset/hook-logger-contract-shape.md @@ -0,0 +1,49 @@ +--- +"@objectstack/objectql": patch +--- + +fix(objectql): the hook layer logs through the `Logger` contract instead of a local dialect (#5637) + +`packages/spec/src/contracts/logger.ts` declares `error(message, error?: Error, +meta?)` — the `Error` slot is **second**, the meta bag **third**. Both hook +modules declared their own four-method logger shape instead, and that shape +spelled `error` as `(msg, meta?)`, so every call site put its diagnostic in the +`Error` slot. + +Nothing caught it. The contract's type satisfies the local shape structurally +(a function of fewer parameters is assignable, and `any` is compatible both +ways), so `tsc` never spoke; and the implementation the platform injects today, +`ObjectLogger`, dispatches its second argument **by shape** +(`errorOrMeta instanceof Error`), so the meta landed anyway. That tolerance is +not something the contract declares. Its two sibling implementations — +`ConsoleLogger` / `JsonLogger` in `@objectstack/observability` — follow the +contract literally: the meta object lands in the `error` slot, `error.message` +and `error.stack` read `undefined`, `meta` **is** `undefined`, and the whole +diagnostic evaporates, leaving a bare sentence. The first host to plug a +faithful structured logger into `ctx.logger` would have lost the fields of every +hook diagnostic, with a symptom ("the log has fewer fields than it used to") +that is close to unattributable. + +So the dialect is gone rather than being met halfway (Prime Directive #12 — one +contract, no consumer-side dialects): + +- `WrapDeclarativeOptions.logger` and `BindHooksOptions.logger` are now + `HookDiagnosticsLogger` = `Pick`, + taken from `@objectstack/spec/contracts` — the four levels this layer calls, + and nothing more. +- All four `error(...)` call sites pass the meta in the contract's third + parameter (`error(msg, undefined, { … })`). The values in hand at each site + are a `CelFault` (`{ kind, message }`) or a `catch` binding of type `unknown`, + none of them statically an `Error`, so the `Error` slot stays empty and each + message is carried in meta exactly as before. + +`debug`/`info`/`warn` already matched the contract and are unchanged. + +No behaviour change for hosts on `ObjectLogger` (the default, and what +`ctx.logger` / `engine.logger` supply): it accepts all three shapes since #5575, +so an empty `Error` slot renders the same record it rendered before. Callers +passing a full `Logger` are unaffected — a `Logger` satisfies the narrowed type +unchanged. A caller that hand-rolled a four-method object still satisfies it too, +as long as its `error` does not *require* a meta object in the second position; +if yours does, move that parameter to third — the contract's order is now the +one the hook layer calls with. diff --git a/packages/objectql/src/hook-binder.ts b/packages/objectql/src/hook-binder.ts index 535cead1d4..f39c4bdbff 100644 --- a/packages/objectql/src/hook-binder.ts +++ b/packages/objectql/src/hook-binder.ts @@ -24,7 +24,7 @@ import type { Hook } from '@objectstack/spec/data'; import { normalizeFlowFunctionEntry, type FlowFunctionEntry } from '@objectstack/spec/automation'; import type { ObjectQL, HookHandler } from './engine.js'; -import { wrapDeclarativeHook } from './hook-wrappers.js'; +import { wrapDeclarativeHook, type HookDiagnosticsLogger } from './hook-wrappers.js'; import type { HookMetricsRecorder } from './hook-metrics.js'; export interface BindHooksOptions { @@ -73,16 +73,19 @@ export interface BindHooksOptions { /** Per-hook execution metrics sink. Defaults to no-op. */ metrics?: HookMetricsRecorder; - /** Logger; defaults to a silent no-op. */ - logger?: { - debug: (msg: string, meta?: any) => void; - info: (msg: string, meta?: any) => void; - warn: (msg: string, meta?: any) => void; - error: (msg: string, meta?: any) => void; - }; + /** + * Logger; defaults to a silent no-op. + * + * The `Logger` contract, narrowed to the levels this layer uses — the SAME + * type the wrapper takes, since every logger handed to the binder is passed + * straight through to `wrapDeclarativeHook`. See + * {@link HookDiagnosticsLogger} for why this is not a locally-declared shape + * (#5637). + */ + logger?: HookDiagnosticsLogger; } -const noopLogger = { +const noopLogger: HookDiagnosticsLogger = { debug: () => {}, info: () => {}, warn: () => {}, @@ -240,7 +243,11 @@ export function bindHooksToEngine( // Under strict, every bind failure is fatal, as advertised. if (opts.strict) throw err; result.errors.push({ hook: hook.name, reason: err?.message ?? String(err) }); - logger.error('[hook-binder] failed to bind hook', { + // Contract arg order (#5637): `error(message, error?: Error, meta?)`. + // `err` is the `any` of a catch clause — a bind failure may be thrown by + // user code and need not be an `Error` — so the Error slot stays empty + // and the diagnostic travels as meta, in the third parameter. + logger.error('[hook-binder] failed to bind hook', undefined, { hook: hook.name, error: err?.message, }); diff --git a/packages/objectql/src/hook-logger-contract-shape.test.ts b/packages/objectql/src/hook-logger-contract-shape.test.ts new file mode 100644 index 0000000000..b447b98a2c --- /dev/null +++ b/packages/objectql/src/hook-logger-contract-shape.test.ts @@ -0,0 +1,229 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#5637] The hook layer writes its diagnostics through the `Logger` CONTRACT. + * + * `packages/spec/src/contracts/logger.ts` declares + * `error(message, error?: Error, meta?)` — the `Error` slot is SECOND and the + * meta bag is THIRD. Both hook modules used to declare their own logger shape + * with `error(msg, meta?)`, and their call sites passed the diagnostic in the + * second slot accordingly. + * + * Nothing caught it: the contract type satisfies that local shape structurally, + * so `tsc` stayed silent, and the implementation the platform happens to inject + * (`ObjectLogger`) dispatches its second argument BY SHAPE, so the meta landed + * anyway. The contract's other implementations (`ConsoleLogger` / `JsonLogger` + * in `@objectstack/observability`) follow the contract literally — the meta bag + * lands in the `error` slot, `error.message`/`error.stack` read `undefined`, + * `meta` IS `undefined`, and the whole diagnostic evaporates. + * + * So these tests judge the call sites with a logger that is FAITHFUL to the + * contract — one that keeps its three parameters apart and records them + * separately. Under the old dialect every one of them fails with + * `meta === undefined` and the diagnostic sitting in `error`. + * + * The last block guards the other direction: `ObjectLogger`'s shape dispatch + * must keep working with `undefined` in the `Error` slot (it is the + * implementation every host gets today, and #5575 is what made its third + * parameter honest). + */ + +import { describe, it, expect } from 'vitest'; +import { ObjectLogger } from '@objectstack/core'; +import type { Hook, HookContext } from '@objectstack/spec/data'; +import { ObjectQL } from './engine.js'; +import { bindHooksToEngine } from './hook-binder.js'; +import { wrapDeclarativeHook, type HookDiagnosticsLogger } from './hook-wrappers.js'; + +/** One `error(...)` call, with its three contract parameters kept apart. */ +interface ErrorCall { + message: string; + error: Error | undefined; + meta: Record | undefined; +} + +/** + * A logger that implements the contract EXACTLY as declared — the behaviour + * `ConsoleLogger`/`JsonLogger` have and `ObjectLogger` generalises. It performs + * no shape dispatch on purpose: that tolerance is what hid the defect, so a + * test that reproduced it could not see anything. + */ +function makeContractLogger() { + const errors: ErrorCall[] = []; + const logger: HookDiagnosticsLogger = { + debug: () => {}, + info: () => {}, + warn: () => {}, + error: (message: string, error?: Error, meta?: Record) => { + errors.push({ message, error, meta }); + }, + }; + return { logger, errors }; +} + +const silentLogger: HookDiagnosticsLogger = { + debug: () => {}, + info: () => {}, + warn: () => {}, + error: () => {}, +}; + +function makeCtx(overrides: Partial = {}): HookContext { + return { + object: 'account', + event: 'beforeInsert', + input: { data: { name: 'acme' } }, + ql: undefined, + ...overrides, + } as HookContext; +} + +/** Every recorded call kept its meta in the meta slot and left `error` empty. */ +function expectContractShape(call: ErrorCall) { + expect(call.error).toBeUndefined(); + expect(call.meta).toBeTypeOf('object'); + expect(call.meta).not.toBeNull(); +} + +describe('[#5637] wrapDeclarativeHook writes diagnostics in the Logger contract shape', () => { + it("onError: 'log' — the suppressed failure keeps its hook/object/event/error meta", async () => { + const { logger, errors } = makeContractLogger(); + const meta: Hook = { + name: 'audit_task', + object: 'account', + events: ['beforeInsert'], + onError: 'log', + handler: async () => { throw new Error('handler exploded'); }, + } as Hook; + + const wrapped = wrapDeclarativeHook(meta, (async () => { throw new Error('handler exploded'); }) as any, { logger }); + // `onError: 'log'` suppresses — the call must not reject. + await wrapped(makeCtx()); + + expect(errors).toHaveLength(1); + const call = errors[0]!; + expect(call.message).toContain('onError=log'); + expectContractShape(call); + expect(call.meta).toMatchObject({ + hook: 'audit_task', + object: 'account', + event: 'beforeInsert', + error: 'handler exploded', + }); + }); + + it('fire-and-forget — the async after-hook failure keeps its meta', async () => { + const { logger, errors } = makeContractLogger(); + const meta: Hook = { + name: 'async_audit', + object: 'account', + events: ['afterInsert'], + async: true, + onError: 'abort', + handler: async () => { throw new Error('async exploded'); }, + } as Hook; + + const wrapped = wrapDeclarativeHook(meta, (async () => { throw new Error('async exploded'); }) as any, { logger }); + await wrapped(makeCtx({ event: 'afterInsert' })); + // Fire-and-forget: the rejection is reported on a later turn. + await new Promise((r) => setTimeout(r, 10)); + + expect(errors).toHaveLength(1); + const call = errors[0]!; + expect(call.message).toContain('fire-and-forget'); + expectContractShape(call); + expect(call.meta).toMatchObject({ hook: 'async_audit', error: 'async exploded' }); + }); + + it('an uncompilable condition keeps the condition source in its meta', () => { + const { logger, errors } = makeContractLogger(); + const meta: Hook = { + name: 'broken_condition', + object: 'account', + events: ['beforeInsert'], + condition: 'record.done == = true', + handler: async () => {}, + } as Hook; + + // The diagnostic is emitted at WRAP time (the compile failure is known + // then); the rejection itself happens per invocation. + wrapDeclarativeHook(meta, (async () => {}) as any, { logger }); + + expect(errors).toHaveLength(1); + const call = errors[0]!; + expect(call.message).toContain('failed to compile'); + expectContractShape(call); + expect(call.meta).toMatchObject({ + hook: 'broken_condition', + condition: 'record.done == = true', + }); + expect(String(call.meta?.error)).not.toBe('undefined'); + }); +}); + +describe('[#5637] bindHooksToEngine writes its bind failure in the Logger contract shape', () => { + it('a throwing registerHook is reported with the hook name and cause in meta', () => { + const engine = new ObjectQL({ logger: silentLogger } as any); + (engine as any).registerHook = () => { throw new Error('registry refused'); }; + + const { logger, errors } = makeContractLogger(); + const hook: Hook = { + name: 'h_bind_fail', + object: 'account', + events: ['beforeInsert'], + handler: async () => {}, + } as Hook; + + const result = bindHooksToEngine(engine, [hook], { packageId: 'app:test', logger }); + + expect(result.registered).toBe(0); + expect(result.errors).toEqual([{ hook: 'h_bind_fail', reason: 'registry refused' }]); + expect(errors).toHaveLength(1); + const call = errors[0]!; + expect(call.message).toContain('failed to bind hook'); + expectContractShape(call); + expect(call.meta).toMatchObject({ hook: 'h_bind_fail', error: 'registry refused' }); + }); +}); + +describe('[#5637] ObjectLogger keeps rendering the meta with an empty Error slot', () => { + /** + * The compatibility half. `ObjectLogger` is what every host injects today + * (`ctx.logger` / `engine.logger`), and since #5575 its `error` honours all + * three shapes — `(msg, Error)`, `(msg, meta)` and `(msg, undefined, meta)`. + * This pins the third one, which is what the hook layer now emits: a bare + * message with the fields gone would be the regression. + */ + it('emits the hook diagnostic fields on a contract-shaped call', async () => { + const written: string[] = []; + const realErrWrite = process.stderr.write.bind(process.stderr); + (process.stderr as { write: unknown }).write = (chunk: string) => { + written.push(String(chunk)); + return true; + }; + + try { + const logger = new ObjectLogger({ level: 'error', format: 'json' }); + const meta: Hook = { + name: 'audit_task', + object: 'account', + events: ['beforeInsert'], + onError: 'log', + handler: async () => { throw new Error('handler exploded'); }, + } as Hook; + const wrapped = wrapDeclarativeHook(meta, (async () => { throw new Error('handler exploded'); }) as any, { logger }); + await wrapped(makeCtx()); + } finally { + (process.stderr as { write: unknown }).write = realErrWrite; + } + + const line = written.find((l) => l.includes('onError=log')); + expect(line, 'the suppressed-failure diagnostic reached stderr').toBeTruthy(); + const record = JSON.parse(line!.trim()); + expect(record.level).toBe('error'); + expect(record.hook).toBe('audit_task'); + expect(record.object).toBe('account'); + expect(record.event).toBe('beforeInsert'); + expect(record.error).toBe('handler exploded'); + }); +}); diff --git a/packages/objectql/src/hook-wrappers.ts b/packages/objectql/src/hook-wrappers.ts index 017c724809..80aa96ee4d 100644 --- a/packages/objectql/src/hook-wrappers.ts +++ b/packages/objectql/src/hook-wrappers.ts @@ -15,25 +15,52 @@ */ import type { Hook, HookContext } from '@objectstack/spec/data'; import type { Expression } from '@objectstack/spec'; +import type { Logger } from '@objectstack/spec/contracts'; import type { HookHandler } from './engine.js'; import { ExpressionEngine, collectCelRootIdentifiers } from '@objectstack/formula'; import { noopHookMetricsRecorder, type HookMetricsRecorder, type HookMetricOutcome } from './hook-metrics.js'; import { materializeDeclaredFields } from './declared-fields.js'; import { describeCelFault, type CelFault } from './cel-fault.js'; +/** + * The logger the hook layer writes its diagnostics to — the `Logger` CONTRACT + * (`@objectstack/spec/contracts`), narrowed to the four levels this layer uses. + * + * ## Why this is a `Pick` of the contract and not a local shape (#5637) + * + * Both hook modules used to declare their own four-method logger shape, and + * that local shape spelled `error` as `(msg, meta?)` — the OPPOSITE of the + * contract, whose second parameter is an `Error` and whose `meta` is THIRD. + * The contract's type satisfies the local shape structurally (a function of + * fewer parameters is assignable, and `any` is compatible in both directions), + * so `tsc` never said a word: the conflict lived only at runtime. + * + * It stayed invisible because the injected implementation happened to be + * `ObjectLogger`, which dispatches its second argument BY SHAPE + * (`errorOrMeta instanceof Error`) and so recorded a meta object in the `Error` + * slot anyway. The contract's other two implementations — + * `ConsoleLogger` / `JsonLogger` in `@objectstack/observability` — follow the + * contract literally: the meta object lands in the `error` slot, `error.message` + * and `error.stack` read `undefined`, `meta` IS `undefined`, and every field of + * the diagnostic disappears, leaving a bare sentence. The symptom ("the log + * lost its fields") is close to unattributable at the host that first hits it. + * + * So the shape is taken from the contract rather than re-typed here (Prime + * Directive #12: one contract, no consumer-side dialects) — a `Pick` of exactly + * what this layer calls, so a caller owes these four methods and nothing more. + * A full `Logger` satisfies it unchanged, which is what every production caller + * passes (`ctx.logger` / `engine.logger`). + */ +export type HookDiagnosticsLogger = Pick; + export interface WrapDeclarativeOptions { /** Logger for declarative-layer diagnostics (timeouts, retries, swallowed errors). */ - logger?: { - debug: (msg: string, meta?: any) => void; - info: (msg: string, meta?: any) => void; - warn: (msg: string, meta?: any) => void; - error: (msg: string, meta?: any) => void; - }; + logger?: HookDiagnosticsLogger; /** Optional per-execution metrics sink. Defaults to no-op. */ metrics?: HookMetricsRecorder; } -const noopLogger = { +const noopLogger: HookDiagnosticsLogger = { debug: () => {}, info: () => {}, warn: () => {}, @@ -269,7 +296,11 @@ export function wrapDeclarativeHook( conditionFn = (ctx: HookContext) => { throw uncompilableConditionError(meta, ctx, source, fault); }; - logger.error('[hook] condition formula failed to compile; every operation on this hook\'s object will be rejected until it is fixed', { + // Contract arg order (#5637): `error(message, error?: Error, meta?)`. + // The fault in hand is a `CelFault` (`{ kind, message }`), not an + // `Error`, so the Error slot is genuinely empty and the diagnostic + // travels as meta — where every implementation of the contract reads it. + logger.error('[hook] condition formula failed to compile; every operation on this hook\'s object will be rejected until it is fixed', undefined, { hook: meta.name, condition: source, error: check.error.message, @@ -338,7 +369,10 @@ export function wrapDeclarativeHook( await runWithRetry(ctx); } catch (err) { if (onError === 'log') { - logger.error('[hook] handler failed (onError=log; suppressing)', { + // Contract arg order (#5637). `err` is `unknown` — a hook handler may + // throw anything — so it is not put in the `Error` slot; its message + // is already carried in the meta bag, which is the third parameter. + logger.error('[hook] handler failed (onError=log; suppressing)', undefined, { hook: meta.name, object: ctx.object, event: ctx.event, @@ -391,7 +425,8 @@ export function wrapDeclarativeHook( .then(() => recordOutcome()) .catch((err) => { recordOutcome(err); - logger.error('[hook] async handler error (fire-and-forget)', { + // Contract arg order (#5637) — see the `onError=log` site above. + logger.error('[hook] async handler error (fire-and-forget)', undefined, { hook: meta.name, error: (err as any)?.message, });