diff --git a/.changeset/6444-evaluator-fault-warn-dedupe.md b/.changeset/6444-evaluator-fault-warn-dedupe.md new file mode 100644 index 0000000000..afdf051590 --- /dev/null +++ b/.changeset/6444-evaluator-fault-warn-dedupe.md @@ -0,0 +1,24 @@ +--- +'@object-ui/core': patch +--- + +`ExpressionEvaluator.evaluate` now reports a faulting `${…}` at most **once per authored +source** instead of once per evaluation (objectui#6444). It is the hottest of the three +predicate paths in this area — `SchemaRenderer` calls it for every `properties.*` value, +every `props.*` value and `content`, for every node, on every render — so a single broken +`${…}` prop in a 200-row list wrote 200 console lines per render, and 200 more on the next +one. Measured on the built evaluator before the fix: three identical faulting +`evaluateCondition` calls produced 3 lines where the `{ dialect: 'cel' }` envelope produced +1; the 200-row list produced 200. After: 1 in every case. + +This is the one-per-source rate limit both sibling reporters already carry +(`warnPredicateFailure` in `fieldRules.ts`, `visibilityDiagnostic.ts` in `@object-ui/react`), +not a third mechanism. The dedupe key is the predicate's **authoring** identity — the fault +site plus the source text, never the scope it ran against — which is both the siblings' +precedent and the defect itself: the 200-row flood is one authored source evaluated against +200 distinct scopes, so a scope-sensitive key would emit all 200 lines again. + +Nothing else moves. The two message texts are unchanged, a distinct broken source still gets +its own line, `EvaluationOptions.onFault` still fires on every fault (objectui#6038's passback +contract, so a caller doing its own warn-once bookkeeping keeps control of it), `throwOnError` +still throws on every evaluation, and no symbol is added to the published surface. diff --git a/packages/core/src/evaluator/ExpressionEvaluator.ts b/packages/core/src/evaluator/ExpressionEvaluator.ts index 298b84bc05..678d9b85de 100644 --- a/packages/core/src/evaluator/ExpressionEvaluator.ts +++ b/packages/core/src/evaluator/ExpressionEvaluator.ts @@ -85,18 +85,74 @@ export interface EvaluationOptions { onFault?: (reason: string) => void; } +/** + * The two built-in fault sites of {@link ExpressionEvaluator.evaluate}, tagged + * so they cannot silence each other through the dedupe below. They describe + * different faults — one PART of a multi-part template failed to evaluate, + * versus the WHOLE expression did — and each owns its message text. + */ +type EvaluationFaultSite = 'template-part' | 'whole-expression'; + +/** + * Authored sources already reported by {@link reportEvaluationFault}, keyed on + * `[site, source]`. + * + * ## Why a rate limit at all (objectui#6444) + * + * `evaluate` is the hottest of the three predicate paths in this area: + * `SchemaRenderer` calls it for every `properties.*` value, every `props.*` + * value and `content`, for every node, on every render — and both sites below + * used to log on EVERY evaluation. Measured on the built evaluator at + * `830ed5803`: three identical faulting `evaluateCondition` calls produced + * **3** console lines where the `{ dialect: 'cel' }` envelope produced **1**, + * and one broken `${…}` prop rendered across a 200-row list produced **200** + * lines — then 200 more on the next render. + * + * This is the one-per-source ceiling both sibling reporters already carry, not + * a third mechanism: `warnPredicateFailure` in `./fieldRules.js` (keyed on + * dialect + source) and `visibilityDiagnostic.ts` in `@object-ui/react` (keyed + * on type + key + source). + * + * ## Why the key is the source TEXT, and never the scope + * + * Both siblings key on the AUTHORING identity of the predicate, and neither + * keys on the data it was evaluated against: "a broken predicate is + * re-evaluated on every render/keystroke, and the point is one loud line, not + * a scrolling wall". Here that precedent is also the defect itself — the + * 200-row flood is ONE authored source evaluated against 200 DIFFERENT scopes, + * so a scope-sensitive key reproduces all 200 lines and fixes nothing. + * + * The key is JSON-encoded, never joined with a control character — that is + * what made a sibling of this file binary to grep (objectstack#5450). + * + * Unbounded, exactly like both siblings: entries are distinct AUTHORED + * expressions, a count an app's metadata bounds; a row count does not. + */ +const warnedEvaluationFaults = new Set(); + /** * One fault, one report: hand the reason to the caller's {@link * EvaluationOptions.onFault} when it supplied one, otherwise fall back to this - * class's historical `console.warn`. + * class's historical `console.warn` — now at most once per authored source. * * Kept as a module-local function rather than repeating the ternary at each * catch, so the "supplying `onFault` suppresses the built-in line" rule is - * stated once and cannot drift between the three sites that implement it. + * stated once and cannot drift between the three sites that implement it. The + * two message texts moved in here for the same reason: the dedupe key and the + * line a reader sees are now built from the same `source`, so the stated + * ceiling cannot drift from what the console actually prints. + * + * The rate limit governs the built-in line ONLY. `onFault` still fires on + * every fault, matching the passback contract `./fieldRules.js` already + * documents for the canonical engine — "independent of … the one-time-warning + * dedupe: it fires on every fault, so a caller doing its own warn-once + * bookkeeping keeps control of it". A caller that reports per node must not + * have its faults swallowed by this module's bookkeeping. */ function reportEvaluationFault( onFault: ((reason: string) => void) | undefined, - builtinMessage: string, + site: EvaluationFaultSite, + source: string, error: unknown, ): void { const reason = error instanceof Error ? error.message : String(error); @@ -104,7 +160,15 @@ function reportEvaluationFault( onFault(reason); return; } - console.warn(builtinMessage, error); + const key = JSON.stringify([site, source]); + if (warnedEvaluationFaults.has(key)) return; + warnedEvaluationFaults.add(key); + console.warn( + site === 'template-part' + ? `Expression evaluation failed for: ${source}` + : `Failed to evaluate expression: ${source}`, + error, + ); } /** @@ -181,7 +245,7 @@ export class ExpressionEvaluator { if (throwOnError) { throw error; } - reportEvaluationFault(onFault, `Expression evaluation failed for: ${expr}`, error); + reportEvaluationFault(onFault, 'template-part', expr, error); return match; // Return original if evaluation fails } }); @@ -189,7 +253,7 @@ export class ExpressionEvaluator { if (throwOnError) { throw error; } - reportEvaluationFault(onFault, `Failed to evaluate expression: ${expression}`, error); + reportEvaluationFault(onFault, 'whole-expression', expression, error); return defaultValue ?? expression; } } diff --git a/packages/core/src/evaluator/__tests__/ExpressionEvaluator.faultWarnDedupe.test.ts b/packages/core/src/evaluator/__tests__/ExpressionEvaluator.faultWarnDedupe.test.ts new file mode 100644 index 0000000000..304e3283fa --- /dev/null +++ b/packages/core/src/evaluator/__tests__/ExpressionEvaluator.faultWarnDedupe.test.ts @@ -0,0 +1,197 @@ +/** + * ObjectUI + * Copyright (c) 2024-present ObjectStack Inc. + * + * This source code is licensed under the MIT license found in the + * LICENSE file in the root directory of this source tree. + */ + +/** + * objectui#6444 — the built-in fault warnings of `evaluate` are rate limited to + * ONE line per authored source, like both sibling reporters already are. + * + * ## The defect, measured on the built evaluator at `830ed5803` + * + * `evaluateCondition('${nosuchroot.x > 1}')` three times in a row produced + * **3** console lines, where the `{ dialect: 'cel' }` envelope produced **1** + * for the same three calls. `evaluate` is the hottest of the three paths — + * `SchemaRenderer` calls it for every `properties.*` value, every `props.*` + * value and `content`, for every node, on every render — so ONE broken `${…}` + * prop in a 200-row list was 200 console lines per render, and 200 more on the + * next one. + * + * ## What these cells have to measure, and why one direction is not enough + * + * "Two faults from the same source log once" passes just as well if the dedupe + * silenced everything; "two faults from different sources log twice" passes + * just as well if it deduped nothing. Only the pair measures the GRANULARITY, + * so both are pinned below — plus the cell that discriminates the granularity + * actually chosen: the same source across MANY DIFFERENT SCOPES is still one + * line. That third cell is the card's open point (source text alone vs source + + * scope) settled as a measurement: the 200-row flood is one authored source + * against 200 distinct scopes, so a scope-sensitive key emits all 200 lines + * again and fixes nothing. + * + * Every cell also asserts that the evaluation REALLY happened and returned its + * documented fail-soft value — a "only one warn" pin passes vacuously if the + * evaluator stopped being called or stopped faulting. + */ + +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; + +type EvaluatorModule = typeof import('../ExpressionEvaluator.js'); + +/** + * The dedupe under test is MODULE state, and module state outlives a test case: + * without this reset the second cell to fault on a given source reads the first + * cell's entry, sees silence, and passes having checked nothing. `vi.resetModules()` + * + a fresh dynamic import gives every cell its own `Set` — and the last cell in + * this file proves that this reset genuinely resets, rather than assuming it. + * (Cells also use distinct source texts, so the discipline does not rest on the + * hook alone.) + */ +let mod: EvaluatorModule; +let warn: ReturnType; + +beforeEach(async () => { + vi.resetModules(); + mod = await import('../ExpressionEvaluator.js'); + warn = vi.spyOn(console, 'warn').mockImplementation(() => {}); +}); + +afterEach(() => { + vi.restoreAllMocks(); +}); + +const SCOPE = { record: { id: 1, status: 'open' }, data: { total: 99 } }; +const make = (scope: Record = SCOPE) => new mod.ExpressionEvaluator(scope); +const lines = () => warn.mock.calls.map((c: unknown[]) => String(c[0])); + +describe('#6444 — one authoring mistake, one loud line', () => { + it('SAME source, three evaluations: ONE line — and all three evaluations really ran and really faulted', () => { + const src = '${nosuchroot.dedupe_same > 1}'; + const e = make(); + + const verdicts = [e.evaluateCondition(src), e.evaluateCondition(src), e.evaluateCondition(src)]; + + // The fault happened every time: the documented fail-OPEN verdict, three times. + expect(verdicts).toEqual([true, true, true]); + // And the evaluator is still doing its job in the same run — so the single + // line is a rate limit, not a stopped evaluator. + expect(e.evaluate('Total: ${data.total}')).toBe('Total: 99'); + expect(warn).toHaveBeenCalledTimes(1); + expect(lines()[0]).toBe('Failed to evaluate expression: ${nosuchroot.dedupe_same > 1}'); + }); + + it('DIFFERENT sources: each still gets its own line — the dedupe is not blanket silence', () => { + const e = make(); + + expect(e.evaluateCondition('${nosuchroot.distinct_a > 1}')).toBe(true); + expect(e.evaluateCondition('${nosuchroot.distinct_b > 1}')).toBe(true); + + expect(warn).toHaveBeenCalledTimes(2); + expect(lines()).toEqual([ + 'Failed to evaluate expression: ${nosuchroot.distinct_a > 1}', + 'Failed to evaluate expression: ${nosuchroot.distinct_b > 1}', + ]); + }); + + it('THE OPEN POINT: one source across 200 DIFFERENT scopes is ONE line — the 200-row list from the card', () => { + // This is the cell that separates the two candidate keyings. Keyed on the + // source TEXT (what shipped) this is 1; keyed on source + scope it is 200, + // which is the defect verbatim. + const src = 'Row ${record.id}: ${nosuchroot.row_total}'; + const rendered: string[] = []; + for (let row = 0; row < 200; row++) { + rendered.push(make({ record: { id: row }, data: { total: 99 } }).evaluate(src) as string); + } + + expect(warn).toHaveBeenCalledTimes(1); + expect(lines()[0]).toBe('Expression evaluation failed for: nosuchroot.row_total'); + + // 200 real evaluations against 200 real scopes: the healthy half of the + // template interpolates each row's OWN id, and the faulting half returns + // its source verbatim (the documented fail-soft value for a template part). + expect(rendered).toHaveLength(200); + expect(rendered[0]).toBe('Row 0: ${nosuchroot.row_total}'); + expect(rendered[199]).toBe('Row 199: ${nosuchroot.row_total}'); + expect(new Set(rendered).size).toBe(200); + }); + + it('the two fault SITES report independently and keep their own message text', () => { + // `evaluate` has two built-in fault paths: one PART of a multi-part + // template failing, and the WHOLE expression failing. They are different + // faults, so the dedupe key is tagged with the site and neither can + // silence the other. Message texts are unchanged from before #6444. + const e = make(); + + expect(e.evaluate('a ${nosuchroot.site_part} b')).toBe('a ${nosuchroot.site_part} b'); + expect(e.evaluate('${nosuchroot.site_whole}')).toBe('${nosuchroot.site_whole}'); + + expect(lines()).toEqual([ + 'Expression evaluation failed for: nosuchroot.site_part', + 'Failed to evaluate expression: ${nosuchroot.site_whole}', + ]); + }); + + it('a HEALTHY expression never warns — the silence that makes one line mean something', () => { + const e = make(); + expect(e.evaluate('Total: ${data.total}')).toBe('Total: 99'); + expect(e.evaluate('${record.status}')).toBe('open'); + expect(e.evaluateCondition("${record.status == 'open'}")).toBe(true); + expect(e.evaluateCondition("${record.status == 'closed'}")).toBe(false); + expect(warn).not.toHaveBeenCalled(); + }); +}); + +describe('#6444 — the rate limit governs the built-in line ONLY', () => { + it('`onFault` still fires on EVERY fault for the same source — the passback contract is unmoved', () => { + // `fieldRules.ts` documents this for the canonical engine ("independent of + // … the one-time-warning dedupe: it fires on every fault, so a caller doing + // its own warn-once bookkeeping keeps control of it"). A caller that reports + // per node must not have its faults swallowed by THIS module's bookkeeping. + const src = '${nosuchroot.passback > 1}'; + const reasons: string[] = []; + const e = make(); + + for (let i = 0; i < 3; i++) { + expect(e.evaluateCondition(src, { onFault: (r) => reasons.push(r) })).toBe(true); + } + + expect(reasons).toHaveLength(3); + expect(reasons.every((r) => r.includes('nosuchroot'))).toBe(true); + // Supplying `onFault` still suppresses the built-in line entirely (#6038). + expect(warn).not.toHaveBeenCalled(); + }); + + it('`throwOnError` still throws on EVERY evaluation — the fail-closed signal is not rate limited', () => { + const src = '${nosuchroot.failclosed > 1}'; + const e = make(); + + expect(() => e.evaluateCondition(src, { throwOnError: true })).toThrow(); + expect(() => e.evaluateCondition(src, { throwOnError: true })).toThrow(); + expect(warn).not.toHaveBeenCalled(); + }); +}); + +describe('#6444 — the module reset this file depends on', () => { + it('the dedupe survives new evaluator INSTANCES, and `vi.resetModules()` genuinely clears it', async () => { + // Both halves matter. The first is why the fix works at all: a 200-row list + // builds a fresh evaluator per row, so a per-instance Set would dedupe + // nothing. The second is why every other cell in this file is a real + // measurement rather than a reading of the previous cell's leftover entry. + const src = '${nosuchroot.reset_probe > 1}'; + const first = await import('../ExpressionEvaluator.js'); + + expect(new first.ExpressionEvaluator(SCOPE).evaluateCondition(src)).toBe(true); + expect(new first.ExpressionEvaluator(SCOPE).evaluateCondition(src)).toBe(true); + expect(warn).toHaveBeenCalledTimes(1); // distinct instances, one line + + vi.resetModules(); + const second = await import('../ExpressionEvaluator.js'); + expect(second.ExpressionEvaluator).not.toBe(first.ExpressionEvaluator); // really a new module + + expect(new second.ExpressionEvaluator(SCOPE).evaluateCondition(src)).toBe(true); + expect(warn).toHaveBeenCalledTimes(2); // fresh Set → the SAME source warns again + }); +}); diff --git a/packages/core/src/evaluator/__tests__/ExpressionEvaluator.onFault.test.ts b/packages/core/src/evaluator/__tests__/ExpressionEvaluator.onFault.test.ts index a7704a5509..cb0c3adda3 100644 --- a/packages/core/src/evaluator/__tests__/ExpressionEvaluator.onFault.test.ts +++ b/packages/core/src/evaluator/__tests__/ExpressionEvaluator.onFault.test.ts @@ -160,16 +160,24 @@ describe('#6038 — the seam moves no verdict and adds no evaluation', () => { expect(withProbe).toBeGreaterThan(plain); }); - it('without onFault, nothing about the existing console output moves', () => { - // The compatibility half: every caller that does not opt in must see the - // exact lines it saw before. A bare-string fault stays silent (it always - // was), and the two loud dialects keep their own generic lines. + it('without onFault, the loud dialect still prints its own generic line', () => { + // The compatibility half: every caller that does not opt in must still see + // its line. A bare-string fault stays silent (it always was), and the + // `${…}` dialect keeps its own generic text. + // + // objectui#6444 rate limited that built-in line to ONE per authored source, + // module-wide, so this cell faults on a source no other cell in this file + // uses. Reusing `FAULT_TEMPLATE` here would read the dedupe entry the + // verdict-parity cell above already made and see silence — a green run + // that measured nothing. The rate limit itself is pinned in + // `ExpressionEvaluator.faultWarnDedupe.test.ts`. + const OWN_TEMPLATE = '${nosuchroot.compat_6038 > 1}'; const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}); try { expect(evaluator().evaluateCondition(FAULT_BARE)).toBe(true); expect(warn).not.toHaveBeenCalled(); - expect(evaluator().evaluateCondition(FAULT_TEMPLATE)).toBe(true); + expect(evaluator().evaluateCondition(OWN_TEMPLATE)).toBe(true); expect(warn).toHaveBeenCalledTimes(1); expect(String(warn.mock.calls[0][0])).toContain('Failed to evaluate expression'); } finally {