fix(objectql): an unevaluable advisory validation rule logs one line saying the write proceeded, not two saying it was rejected

.changeset/24782-advisory-unevaluable-log.md

@@ -0,0 +1,13 @@
+---
+'@objectstack/objectql': patch
+---
+
+fix(objectql): an advisory validation rule that cannot be evaluated logs one line saying the write proceeded, not two saying it was rejected (#24782)
+
+Clause-②: no (log text only: no response, status, code, outcome or export moves)
+
+A `severity: 'warning'` or `'info'` validation rule whose predicate cannot be evaluated never blocks the write. Only `error` rules fail closed (#4649). The write answers 2xx and the row persists. The server log said the opposite, twice. The predicate evaluator logged "— write rejected: a rule that cannot be evaluated fails closed, it is never skipped" before the rule's severity was consulted. Then the advisory per-write line repeated the unevaluable violation's own message, which also ends "— write rejected.".
+
+Such a rule now logs ONE line: `Validation rule 'NAME' (warning): the rule could not be evaluated (FAULT) — write proceeded: the rule is advisory, so it was not applied to this write`. This covers a `script` / `cross_field` condition, a `conditional`'s `when`, and the relationship-traversal refusal. On the seed / boot path the same text folds into that load's advisory summary line, which keeps its shape.
+
+Unchanged: an unevaluable `error` rule is refused with the same `400 VALIDATION_FAILED` body, and its log line still says the write was rejected and the rule fails closed. Which rules block is unchanged. An unevaluable rule still stays out of a write answer's `warnings`. `requiredWhen`, `readonlyWhen` and the option `visibleWhen` gate still refuse on every severity.

packages/objectql/src/validation/advisory-write-answer.test.ts

@@ -482,3 +482,33 @@ describe('[#22726] P2 — the preview appends the same hits to the row\'s `warni
     ]);
   });
 });
+
+describe('[#24782] an unevaluable advisory rule: the write succeeds, and the log says so once', () => {
+  beforeEach(async () => {
+    await boot();
+    engine.registry.registerObject({
+      name: 'adv_unevaluable',
+      label: 'Probe',
+      fields: { title: { name: 'title', label: 'Title', type: 'text' } },
+      validations: [{
+        type: 'script' as const,
+        name: 'qa_unevaluable_warn',
+        severity: 'warning' as const,
+        message: 'x',
+        condition: 'int(record.title) > 1',
+      }],
+    } as never, 'com.objectstack.test.24782');
+  });
+
+  it('createData stores the row, answers no `warnings`, and logs one advisory line', async () => {
+    const res: any = await protocol.createData({ object: 'adv_unevaluable', data: { title: 'abc' } });
+
+    expect(storeFor('adv_unevaluable').get(res.id)).toMatchObject({ title: 'abc' });
+    // #22726: an unevaluable rule has no verdict, so it is not a hit.
+    expect(Object.keys(res)).not.toContain('warnings');
+    const ruleLines = warns.filter((l) => l.includes('qa_unevaluable_warn'));
+    expect(ruleLines).toHaveLength(1);
+    expect(ruleLines[0]).toMatch(/^Validation rule 'qa_unevaluable_warn' \(warning\): the rule could not be evaluated \(.+\) — write proceeded/);
+    expect(ruleLines[0]).not.toMatch(/write rejected|fails closed/);
+  });
+});

packages/objectql/src/validation/rule-unevaluable-advisory-log.test.ts

@@ -0,0 +1,194 @@
+// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license.
+
+import { describe, it, expect } from 'vitest';
+import { runWithAdvisoryAggregation, type AdvisoryGroup } from '@objectstack/core';
+
+import { evaluateValidationRules } from './rule-validator.js';
+import { ValidationError } from './record-validator.js';
+
+// [#10126] Pay the first transform of these dist-resolved workspace deps at MODULE
+// LOAD, not inside a clocked `it()` body.
+import '@objectstack/spec';
+import '@objectstack/formula';
+
+/**
+ * [#24782] What the operator log says about a validation rule that could not be
+ * EVALUATED, by severity.
+ *
+ * #4649 fails such a rule closed — but `severity` still governs blocking, so an
+ * unevaluable `warning` / `info` rule never refuses the write. Until #24782 its
+ * log said the opposite, twice: the predicate evaluator's fail-closed sentence
+ * ("— write rejected: a rule that cannot be evaluated fails closed"), logged
+ * before the rule's severity was consulted, and the advisory branch's per-write
+ * line, which embedded the unevaluable violation's own message (ending
+ * "— write rejected."). An operator reading the log for a disputed write was
+ * told it was refused when it was stored.
+ *
+ * The pins:
+ *  - an unevaluable advisory rule logs exactly ONE line, naming the rule, its
+ *    severity and the fault, and saying the write proceeded — never "write
+ *    rejected", never "fails closed" — on each predicate slot: a `script`
+ *    condition, a `conditional`'s `when`, and the relationship-traversal refusal;
+ *  - the seed / boot aggregation (#13889) folds that same advisory text;
+ *  - CONTROL: an unevaluable `error` rule is refused exactly as before, and its
+ *    log still says the write was rejected and the rule fails closed.
+ */
+
+const FAULTED_CONDITION = 'int(record.title) > 1';
+
+const probe = (severity: 'error' | 'warning' | 'info') => ({
+  name: 'qa_vr_probe',
+  fields: { title: { type: 'text', label: 'Title' } },
+  validations: [
+    { type: 'script', name: 'qa_unevaluable', severity, message: 'x', condition: FAULTED_CONDITION },
+  ],
+});
+
+const conditionalProbe = (severity: 'error' | 'warning') => ({
+  name: 'qa_vr_probe',
+  fields: { title: { type: 'text', label: 'Title' } },
+  validations: [
+    {
+      type: 'conditional',
+      name: 'qa_unevaluable_when',
+      severity,
+      message: 'x',
+      when: FAULTED_CONDITION,
+      then: { type: 'script', name: 'qa_then', message: 'then', condition: 'false' },
+    },
+  ],
+});
+
+/** A rule reading one hop through a lookup whose parent row was unreadable. */
+const traversalProbe = (severity: 'error' | 'warning') => ({
+  name: 'crm_opportunity',
+  fields: {
+    amount: { type: 'currency', label: 'Amount' },
+    account: { type: 'lookup', reference: 'crm_account', label: 'Account' },
+  },
+  validations: [
+    {
+      type: 'script',
+      name: 'partner_cap',
+      severity,
+      message: 'Partner accounts are capped at 10000.',
+      fields: ['amount'],
+      condition: "record.account.type == 'partner' && record.amount > 10000",
+    },
+  ],
+});
+const unreadableAccount = { account: { object: 'crm_account', unavailable: 'unreadable' } };
+
+function run(
+  schema: unknown,
+  data: Record<string, unknown>,
+  related?: Record<string, unknown>,
+): { warns: string[]; thrown: unknown; returned: unknown } {
+  const warns: string[] = [];
+  let thrown: unknown;
+  let returned: unknown;
+  try {
+    returned = evaluateValidationRules(schema as never, data, 'insert', {
+      logger: { warn: (m: unknown) => { warns.push(String(m)); } },
+      ...(related ? { related: related as never } : {}),
+    });
+  } catch (err) {
+    thrown = err;
+  }
+  return { warns, thrown, returned };
+}
+
+function expectOneAdvisoryLine(warns: string[], rule: string, severity: string, fault: RegExp): void {
+  expect(warns).toHaveLength(1);
+  const [line] = warns;
+  expect(line).toContain(`Validation rule '${rule}' (${severity}):`);
+  expect(line).toMatch(fault);
+  expect(line).toContain('write proceeded');
+  expect(line).not.toMatch(/write rejected/);
+  expect(line).not.toMatch(/fails closed/);
+}
+
+describe('[#24782] an unevaluable ADVISORY rule logs one line, and it says the write proceeded', () => {
+  it.each(['warning', 'info'] as const)('a `script` condition at severity %s', (severity) => {
+    const { warns, thrown, returned } = run(probe(severity), { title: 'abc' });
+
+    expect(thrown).toBeUndefined();
+    // #22726: an unevaluable rule has no verdict, so it is not an advisory hit.
+    expect(returned).toEqual([]);
+    expectOneAdvisoryLine(warns, 'qa_unevaluable', severity, /could not be evaluated \(.+\)/);
+  });
+
+  it('a `conditional` whose `when` cannot be evaluated', () => {
+    const { warns, thrown, returned } = run(conditionalProbe('warning'), { title: 'abc' });
+
+    expect(thrown).toBeUndefined();
+    expect(returned).toEqual([]);
+    expectOneAdvisoryLine(warns, 'qa_unevaluable_when', 'warning', /could not be evaluated \(.+\)/);
+  });
+
+  it('the relationship-traversal refusal (the related row was unreadable)', () => {
+    const { warns, thrown, returned } = run(
+      traversalProbe('warning'), { amount: 20000, account: 'acc_1' }, unreadableAccount,
+    );
+
+    expect(thrown).toBeUndefined();
+    expect(returned).toEqual([]);
+    expectOneAdvisoryLine(warns, 'partner_cap', 'warning', /could not be evaluated \(.+\)/);
+  });
+
+  it('on the seed / boot path the hit folds into the summary with the same advisory text, and no per-row line', async () => {
+    const warns: string[] = [];
+    let groups: AdvisoryGroup[] = [];
+    await runWithAdvisoryAggregation(async () => {
+      evaluateValidationRules(probe('warning') as never, { title: 'abc' }, 'insert', {
+        logger: { warn: (m: unknown) => { warns.push(String(m)); } },
+      });
+    }, (g) => { groups = g; });
+
+    expect(warns).toEqual([]);
+    expect(groups).toHaveLength(1);
+    expect(groups[0]).toMatchObject({ rule: 'qa_unevaluable', severity: 'warning', rows: 1 });
+    expect(groups[0]!.message).toMatch(/could not be evaluated \(.+\) — write proceeded/);
+    expect(groups[0]!.message).not.toMatch(/write rejected|fails closed/);
+  });
+});
+
+describe('[#24782] CONTROL — an unevaluable `error` rule is refused, and its log says so', () => {
+  const refusalOf = (thrown: unknown) => {
+    expect(thrown).toBeInstanceOf(ValidationError);
+    return (thrown as ValidationError).fields;
+  };
+
+  it('a `script` condition', () => {
+    const { warns, thrown } = run(probe('error'), { title: 'abc' });
+
+    const fields = refusalOf(thrown);
+    expect(fields).toHaveLength(1);
+    expect(fields[0]).toMatchObject({
+      field: '_record',
+      code: 'rule_violation',
+      constraint: { rule: 'qa_unevaluable', reason: 'unevaluable' },
+    });
+    expect(fields[0]!.message).toMatch(/^Validation rule 'qa_unevaluable' could not be evaluated \(.+\) — write rejected\./);
+    expect(warns).toHaveLength(1);
+    expect(warns[0]).toMatch(
+      /^Validation rule 'qa_unevaluable' predicate failed to evaluate \(.+\) — write rejected: a rule that cannot be evaluated fails closed, it is never skipped$/s,
+    );
+  });
+
+  it('a `conditional` whose `when` cannot be evaluated', () => {
+    const { warns, thrown } = run(conditionalProbe('error'), { title: 'abc' });
+
+    expect(refusalOf(thrown)[0]).toMatchObject({ constraint: { rule: 'qa_unevaluable_when', reason: 'unevaluable' } });
+    expect(warns).toHaveLength(1);
+    expect(warns[0]).toMatch(/^Validation rule 'qa_unevaluable_when' when-predicate failed to evaluate \(.+\) — write rejected: a rule that cannot be evaluated fails closed/s);
+  });
+
+  it('the relationship-traversal refusal', () => {
+    const { warns, thrown } = run(traversalProbe('error'), { amount: 20000, account: 'acc_1' }, unreadableAccount);
+
+    expect(refusalOf(thrown)[0]).toMatchObject({ constraint: { rule: 'partner_cap', reason: 'unevaluable' } });
+    expect(warns).toHaveLength(1);
+    expect(warns[0]).toMatch(/^Validation rule 'partner_cap' predicate could not be evaluated \(.+\) — write rejected$/);
+  });
+});

packages/objectql/src/validation/rule-validator.ts

@@ -339,6 +339,24 @@ interface RuleContext {
    *  when it resolved none. Applied per rule — see
    *  {@link resolveTraversalScope}. */
   related: RelatedRecordBinding | undefined;
+  /** [#24782] The TOP-LEVEL rule being evaluated is advisory (`warning` /
+   *  `info`) — set per rule by `evaluateValidationRules`, and inherited by a
+   *  `conditional`'s branch, whose outer rule's severity governs. See
+   *  {@link failClosedLogger}. */
+  advisory: boolean;
+}
+
+/**
+ * [#24782] The logger an unevaluable predicate writes its fail-closed sentence
+ * to ("— write rejected: a rule that cannot be evaluated fails closed"): the
+ * write's logger for an `error` rule, whose write IS rejected, and none for an
+ * advisory rule, whose write proceeds. The predicate evaluators run before the
+ * caller acts on the rule's severity, so they cannot word the outcome
+ * themselves; for an advisory rule `evaluateValidationRules` reports the fault
+ * once, worded as what happened — see {@link unevaluableAdvisoryMessage}.
+ */
+function failClosedLogger(ctx: Pick<RuleContext, 'logger' | 'advisory'>): EvaluateRulesOptions['logger'] {
+  return ctx.advisory ? undefined : ctx.logger;
 }
 
 /**
@@ -3438,9 +3456,10 @@ export function nullPreviousReadDetail(
  * `onValidationAdvisory` listener (see {@link emitValidationAdvisories}) and
  * the validate-only preview appends it to the row's `warnings`. A rule that
  * could not be EVALUATED (`constraint.reason: 'unevaluable'`) is not a hit: it
- * has no verdict, and its text ("could not be evaluated … write rejected") is a
- * fault report for the operator, false for a write an advisory never blocks —
- * so it stays in the log only.
+ * has no verdict, and its text ("could not be evaluated … write rejected") is
+ * the refusal an `error` rule returns, false for a write an advisory never
+ * blocks — so it is not a hit, and the log reports it once in its own words
+ * ({@link unevaluableAdvisoryMessage}, #24782).
  */
 export function evaluateValidationRules(
   objectSchema: { validations?: unknown[]; fields?: Record<string, ConditionalFieldDef> } | undefined | null,
@@ -3478,7 +3497,7 @@ export function evaluateValidationRules(
   // and update: what a predicate can read is the object's DECLARED shape, not
   // whatever subset of columns this driver happened to return.
   if (groundTruth) materializeDeclaredFields(merged, fields);
-  const ctx: RuleContext = { data, merged, previous, mode, logger: opts.logger, fields, messages: opts.messages, related: opts.related };
+  const ctx: RuleContext = { data, merged, previous, mode, logger: opts.logger, fields, messages: opts.messages, related: opts.related, advisory: false };
 
   const errors: FieldValidationError[] = [];
   // [#22726] The advisory hits this evaluation returns — see the doc above.
@@ -3603,9 +3622,10 @@ export function evaluateValidationRules(
     .sort((a, b) => (a.priority ?? 100) - (b.priority ?? 100));
 
   for (const rule of ordered) {
+    const severity = rule.severity ?? 'error';
     let violation: FieldValidationError | null = null;
     try {
-      violation = evaluateRule(rule, ctx);
+      violation = evaluateRule(rule, { ...ctx, advisory: severity !== 'error' });
     } catch (err) {
       // Defensive: a broken rule must never brick a write.
       opts.logger?.warn?.(`Validation rule '${rule.name}' threw — skipped`, err);
@@ -3614,8 +3634,8 @@ export function evaluateValidationRules(
 
     if (!violation) continue;
 
-    const severity = rule.severity ?? 'error';
-    if (severity !== 'error' && violation.constraint?.reason !== 'unevaluable') {
+    const unevaluable = violation.constraint?.reason === 'unevaluable';
+    if (severity !== 'error' && !unevaluable) {
       advisories.push(advisoryEvent(rule, severity, violation));
     }
     if (severity === 'error') {
@@ -3628,16 +3648,22 @@ export function evaluateValidationRules(
       // row count and example rows. Off that path no scope is active,
       // `recordAdvisoryHit` returns false, and the per-write line below is
       // emitted verbatim — an ordinary interactive write is untouched.
+      //
+      // [#24782] An UNEVALUABLE advisory rule is reported through the same two
+      // outlets, once, but not with its violation's message: that text is the
+      // refusal an `error` rule returns ("… — write rejected."), false for a
+      // write this rule does not block. The evaluator logged nothing for it
+      // (see `failClosedLogger`), so this is its only line.
       !recordAdvisoryHit({
         object: advisoryObjectName(objectSchema),
         rule: String(rule.name ?? '(unnamed)'),
         severity,
-        message: violation.message,
+        message: unevaluable ? unevaluableAdvisoryMessage(rule, violation) : violation.message,
         recordRef: advisoryRecordRef(merged, data),
       })
     ) {
       opts.logger?.warn?.(
-        `Validation rule '${rule.name}' (${severity}): ${violation.message}`,
+        `Validation rule '${rule.name}' (${severity}): ${unevaluable ? unevaluableAdvisoryMessage(rule, violation) : violation.message}`,
       );
     }
   }
@@ -3646,6 +3672,20 @@ export function evaluateValidationRules(
   return advisories;
 }
 
+/**
+ * [#24782] What an advisory rule that could not be EVALUATED reports, in place
+ * of its violation's message: the fault, and that the write proceeded — the
+ * rule is advisory, so having no verdict does not block (#4649 fails closed on
+ * `severity: 'error'` only). Names the branch when the fault is a
+ * `conditional`'s branch rather than the rule itself.
+ */
+function unevaluableAdvisoryMessage(rule: BaseRule, violation: FieldValidationError): string {
+  const faulted = violation.constraint?.rule;
+  const subject = typeof faulted === 'string' && faulted !== rule.name ? `its branch '${faulted}'` : 'the rule';
+  return `${subject} could not be evaluated (${String(violation.constraint?.fault)})`
+    + ' — write proceeded: the rule is advisory, so it was not applied to this write';
+}
+
 /**
  * [#22726] One advisory hit as the event the write reports it through. Every
  * member is copied from the evaluation's own verdict — the violation the rule
@@ -3753,7 +3793,7 @@ function evaluateRule(rule: BaseRule, ctx: RuleContext): FieldValidationError |
       return checkStateMachine(rule as StateMachineRule, ctx.mode, ctx.data, ctx.previous, ctx);
     case 'script':
     case 'cross_field':
-      return checkPredicate(rule as PredicateRule, ctx.merged, ctx.previous, ctx.logger, ctx.messages, ctx.related, ctx.fields);
+      return checkPredicate(rule as PredicateRule, ctx.merged, ctx.previous, failClosedLogger(ctx), ctx.messages, ctx.related, ctx.fields);
     case 'format':
       return checkFormat(rule as FormatRule, ctx.data, ctx.logger, ctx.messages);
     case 'json_schema':
@@ -4689,13 +4729,13 @@ function checkConditional(
   let record = ctx.merged;
   if (typeof expr.source === 'string' && expr.dialect === 'cel') {
     const scope = resolveTraversalScope(record, expr.source, ctx.related, ctx.fields);
-    if (!scope.ok) return traversalScopeRefusal(rule.name, '_record', scope, 'when-predicate', ctx.logger);
+    if (!scope.ok) return traversalScopeRefusal(rule.name, '_record', scope, 'when-predicate', failClosedLogger(ctx));
     record = scope.record;
   }
   const result = ExpressionEngine.evaluate<boolean>(expr, ruleScope(record, ctx.previous));
 
   if (!result.ok) {
-    ctx.logger?.warn?.(
+    failClosedLogger(ctx)?.warn?.(
       `Validation rule '${rule.name}' when-predicate failed to evaluate (${result.error.kind}: ${result.error.message}) — write rejected: a rule that cannot be evaluated fails closed, it is never skipped`,
     );
     const nullRead = nullPreviousReadDetail(result.error, rule.when, ctx.previous, ctx.fields, 'when-predicate');