diff --git a/.changeset/durability-gate-partial-recovery.md b/.changeset/durability-gate-partial-recovery.md new file mode 100644 index 0000000000..b17471e178 --- /dev/null +++ b/.changeset/durability-gate-partial-recovery.md @@ -0,0 +1,20 @@ +--- +--- + +chore(scripts): the durability log-level gate no longer excuses a catch that only PARTIALLY rethrows + +`check:durability-log-level` skipped any guarded `catch` containing a `throw`. +That is right when the catch propagates on every path — the failure reaches the +caller and nothing is being degraded. It is wrong for a catch that **recovers on +one branch and rethrows on the other**: the rethrow says nothing about the +branch that returns a substitute value, and that branch is a degradation like +any other. + +Found while closing +[#4998](https://github.com/objectstack-ai/objectstack/issues/4998), whose seam +(`writeRecoveringSummary`: recover `ERR_SUMMARY_RECOMPUTE`, rethrow everything +else) has exactly that shape. Registering its callee in +`DURABILITY_CRITICAL_CALLEES` produced a ledger entry that could never fire — +protection that reads as real and enforces nothing, which is worse than none. +Measured against the repo, the tightened rule changes the verdict on no existing +seam (11 seams, all still loud or rethrowing) and needs no baseline entry. diff --git a/.changeset/seed-loader-stale-summary-counter.md b/.changeset/seed-loader-stale-summary-counter.md new file mode 100644 index 0000000000..029979fcf3 --- /dev/null +++ b/.changeset/seed-loader-stale-summary-counter.md @@ -0,0 +1,46 @@ +--- +"@objectstack/spec": minor +"@objectstack/metadata-protocol": patch +--- + +fix(seed-loader): a roll-up summary left stale by a seed is now loud and counted + +The loader recovers a post-write roll-up summary recompute that exhausts its +retries (`ERR_SUMMARY_RECOMPUTE`), and that recovery is correct: the rows WERE +written, so re-writing them would duplicate them (framework#3147). What was +wrong was the rank of the consequence. A roll-up summary is a **persisted +derived column** on the parent record, so after this the database is internally +inconsistent — the detail rows say one thing and the column that summarizes them +says another — and nothing recomputes it until some later write happens to touch +the same parent, which after a seed may never happen. + +The entire event used to be one `warn` line reading *"records were written +(summary values may be stale)"*. It named no object, counted nothing, and left +`success: true` with every row counter clean, so no operator could see which +aggregate was wrong and no caller could detect it at all +([#4998](https://github.com/objectstack-ai/objectstack/issues/4998)). + +**It now logs at `error`**, naming the seeded object and the exact stale column +(`account.total_billed`), stating the consequence (the summary and its detail +rows disagree, nothing self-heals, and the seed still reports success) and the +remedy (fix the recompute error and re-run the seed, or trigger any write on the +affected parent to force a recompute), with the original cause attached. This is +the AGENTS.md "Degradation log levels" rule (#4632): persisted state and runtime +state disagreeing while everything looks normal is `error`, not `warn`. + +**And it is counted** — `SeedLoadResult.summariesStale` and +`SeedLoaderResult.summary.totalSummariesStale`, mirroring `referencesDropped` / +`totalReferencesDropped`, which exists for the same shape one layer down ("the +row was written, something derived from it was lost"). A log line is not +something a caller can branch on; these counters are. + +`success` deliberately stays `true`. It answers *"did the rows land"*, and they +did — every consumer treats `success: false` as "the write failed", so flipping +it would hand the protocol seed-apply surface a `false` with an **empty** errors +array and fail package/marketplace installs that in fact wrote every row. The +counter carries the signal instead; a caller that wants to treat a stale +aggregate as fatal reads `summary.totalSummariesStale > 0`. + +Both counters are additive with a `0` default, so an existing producer or +consumer of `SeedLoaderResult` is unaffected — a payload written before this +release still parses, with `0`. diff --git a/content/docs/references/data/seed-loader.mdx b/content/docs/references/data/seed-loader.mdx index e2d5f1b355..02e535d36a 100644 --- a/content/docs/references/data/seed-loader.mdx +++ b/content/docs/references/data/seed-loader.mdx @@ -151,6 +151,7 @@ Result of loading a single dataset | **referencesResolved** | `integer` | ✅ | References resolved via externalId | | **referencesDeferred** | `integer` | ✅ | References deferred to second pass | | **referencesDropped** | `integer` | ✅ | Reference fields dropped from records that were still written | +| **summariesStale** | `integer` | ✅ | Roll-up summary values left stale by writes for this dataset | | **errors** | `{ sourceObject: string; field: string; targetObject: string; targetField: string; … }[]` | ✅ | Reference resolution errors | diff --git a/packages/metadata-protocol/src/seed-loader-retry.test.ts b/packages/metadata-protocol/src/seed-loader-retry.test.ts index 6dac9f4bf7..d57670755a 100644 --- a/packages/metadata-protocol/src/seed-loader-retry.test.ts +++ b/packages/metadata-protocol/src/seed-loader-retry.test.ts @@ -229,7 +229,13 @@ describe('seed batched path — partial-success engine (framework#3172)', () => }); }); -describe('seed batched path — summary recompute failure is a warning, not an error (framework#3147)', () => { +// The RECOVERY pinned here is framework#3147's and is unchanged: the rows were +// written, so re-writing them would duplicate. Its loudness is not — a stale +// roll-up column is persisted data disagreeing with its detail rows, so the +// seam logs at `error` and counts into `summariesStale` (framework#4998, pinned +// in seed-loader-summary-stale.test.ts). It is still not a WRITE error, which +// is what `totalErrored: 0` below says. +describe('seed batched path — a recompute failure is recovered, not re-written (framework#3147)', () => { it('records the rows as inserted (not errored) and does not re-insert on ERR_SUMMARY_RECOMPUTE', async () => { const { engine, store } = createFaithfulEngine(); const metadata = createMetadata(); diff --git a/packages/metadata-protocol/src/seed-loader-summary-stale.test.ts b/packages/metadata-protocol/src/seed-loader-summary-stale.test.ts new file mode 100644 index 0000000000..3f714dabc5 --- /dev/null +++ b/packages/metadata-protocol/src/seed-loader-summary-stale.test.ts @@ -0,0 +1,304 @@ +// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. + +import { describe, it, expect, vi } from 'vitest'; +import { SeedLoadResultSchema, SeedLoaderResultSchema } from '@objectstack/spec/data'; +import { SeedLoaderService } from './seed-loader'; +import type { IDataEngine, IMetadataService } from '@objectstack/spec/contracts'; + +/** + * framework#4998: a roll-up summary recompute that exhausts its retries must be + * LOUD and COUNTED. + * + * The recovery itself is correct and unchanged (framework#3147): the rows WERE + * written, so re-writing them would duplicate. What was wrong was the + * consequence's rank. A roll-up summary is a persisted DERIVED column on the + * parent record, so after this the database is internally inconsistent — the + * detail rows say one thing and the column summarizing them says another — and + * nothing recomputes it until some later write touches the same parent, which + * after a seed may never happen. The whole event used to be one `warn`: the + * load counted no error, `success` stayed `true`, and no caller could detect it + * programmatically. + * + * So both halves are pinned here, because shipping either alone was the defect: + * the `error` line (with its consequence and its remedy) AND + * `summariesStale` / `summary.totalSummariesStale`. + */ + +function createLogger() { + return { info: vi.fn(), warn: vi.fn(), error: vi.fn(), debug: vi.fn() }; +} + +function createFaithfulEngine(): { engine: IDataEngine; store: Record } { + const store: Record = {}; + let idCounter = 0; + + const engine = { + find: vi.fn(async (objectName: string, query?: any) => { + let records = store[objectName] || []; + if (query?.where) { + records = records.filter((r) => + Object.entries(query.where).every(([k, v]) => r[k] === v), + ); + } + if (typeof query?.limit === 'number') records = records.slice(0, query.limit); + return records; + }), + findOne: vi.fn(async (objectName: string, query?: any) => { + const rows = await (engine.find as any)(objectName, { ...query, limit: 1 }); + return rows[0] ?? null; + }), + insert: vi.fn(async (objectName: string, data: any) => { + if (!store[objectName]) store[objectName] = []; + if (Array.isArray(data)) { + const records = data.map((d) => ({ id: `gen-${++idCounter}`, ...d })); + store[objectName].push(...records); + return records; + } + const record = { id: `gen-${++idCounter}`, ...data }; + store[objectName].push(record); + return record; + }), + update: vi.fn(async (objectName: string, data: any) => { + const records = store[objectName] || []; + const idx = records.findIndex((r) => r.id === data.id); + if (idx >= 0) { records[idx] = { ...records[idx], ...data }; return records[idx]; } + return data; + }), + delete: vi.fn(async () => ({ deleted: 1 })), + count: vi.fn(async (objectName: string) => (store[objectName] || []).length), + aggregate: vi.fn(async () => []), + } as unknown as IDataEngine; + + return { engine, store }; +} + +/** + * Two independent objects — no references between them, so nothing is deferred + * and each dataset's counters stand on their own. + */ +function createMetadata(): IMetadataService { + const objects: Record = { + roll_invoice: { name: 'roll_invoice', fields: { name: { type: 'text' }, total: { type: 'number' } } }, + roll_payment: { name: 'roll_payment', fields: { name: { type: 'text' }, amount: { type: 'number' } } }, + }; + return { + getObject: vi.fn(async (name: string) => objects[name]), + listObjects: vi.fn(async () => Object.values(objects)), + register: vi.fn(async () => {}), + get: vi.fn(async (_t: string, name: string) => objects[name]), + list: vi.fn(async () => []), + unregister: vi.fn(async () => {}), + exists: vi.fn(async () => false), + listNames: vi.fn(async () => []), + } as unknown as IMetadataService; +} + +const CONFIG = { + dryRun: false, + haltOnError: false, + multiPass: true, + defaultMode: 'insert', + batchSize: 1000, + transaction: false, +} as any; + +const seedFor = (object: string, records: any[]) => ({ + object, + externalId: 'name', + mode: 'insert', + env: ['prod', 'dev', 'test'], + records, +}); + +/** + * Make `object`'s ARRAY insert write its rows and then report a post-write + * roll-up recompute failure — objectql's `SummaryRecomputeError` shape + * (framework#3147), matched across the package boundary by `code`. + */ +function failSummaryRecompute( + engine: IDataEngine, + object: string, + failures: Array<{ childObject: string; parentObject: string; parentId: string; field: string; error: unknown }>, +) { + const realInsert = (engine.insert as any).getMockImplementation(); + (engine.insert as any).mockImplementation(async (obj: string, data: any, opts: any) => { + if (obj === object && Array.isArray(data)) { + const written = await realInsert(obj, data, opts); + throw Object.assign( + new Error( + `Roll-up summary recompute failed after retries for ${failures.length} parent record(s); ` + + `the triggering records WERE written (summary values may be stale).`, + ), + { code: 'ERR_SUMMARY_RECOMPUTE', written, failures }, + ); + } + return realInsert(obj, data, opts); + }); +} + +const FAILURES = [ + { childObject: 'roll_invoice', parentObject: 'roll_account', parentId: 'acc-1', field: 'total_billed', error: new Error('deadlock detected') }, + { childObject: 'roll_invoice', parentObject: 'roll_account', parentId: 'acc-2', field: 'total_billed', error: new Error('deadlock detected') }, +]; + +describe('a roll-up summary left stale by a seed is loud and counted (framework#4998)', () => { + it('logs at ERROR naming the object, the stale column, the consequence and the remedy', async () => { + const { engine } = createFaithfulEngine(); + const logger = createLogger(); + failSummaryRecompute(engine, 'roll_invoice', FAILURES); + + await new SeedLoaderService(engine, createMetadata(), logger).load({ + seeds: [seedFor('roll_invoice', [{ name: 'INV-1', total: 10 }, { name: 'INV-2', total: 20 }])] as any, + config: CONFIG, + }); + + expect(logger.error).toHaveBeenCalledTimes(1); + const [message, cause, meta] = (logger.error as any).mock.calls[0]; + + // NAMES the object being seeded and the persisted column that is now wrong. + expect(message).toContain('roll_invoice'); + expect(message).toContain('roll_account.total_billed'); + + // CONSEQUENCE — #4632 requires it in the line that prints, and the specific + // trap here is that everything else still reads healthy. + expect(message).toContain('STALE'); + expect(message).toContain('disagree with the detail rows'); + expect(message).toContain('success: true'); + + // REMEDY — both routes back to a correct summary. + expect(message).toContain('re-run the seed'); + expect(message).toContain('trigger any write on the affected parent record(s)'); + + // The original cause travels with it, structurally (not just pasted in). + expect(message).toContain('Cause: Roll-up summary recompute failed after retries'); + expect(cause).toBeInstanceOf(Error); + expect((cause as Error).message).toContain('the triggering records WERE written'); + expect(meta).toMatchObject({ object: 'roll_invoice', summariesStale: 2 }); + expect(meta.summaryColumns).toEqual(['roll_account.total_billed']); + expect(meta.failures.map((f: any) => f.parentId)).toEqual(['acc-1', 'acc-2']); + expect(meta.failures[0].error).toBe('deadlock detected'); + + // Mutation pin: reverting to the pre-#4998 `warn` must turn this red. The + // AST gate (`pnpm check:durability-log-level`, `performSeedWrite` in its + // DURABILITY_CRITICAL_CALLEES) fails on the same revert in CI. + const warned = (logger.warn as any).mock.calls.map(([m]: [string]) => m).join('\n'); + expect(warned).not.toContain('summary'); + }); + + it('counts it in the result — per object and in the summary — so a caller can branch on it', async () => { + const { engine, store } = createFaithfulEngine(); + failSummaryRecompute(engine, 'roll_invoice', FAILURES); + + const result = await new SeedLoaderService(engine, createMetadata(), createLogger()).load({ + seeds: [seedFor('roll_invoice', [{ name: 'INV-1', total: 10 }, { name: 'INV-2', total: 20 }])] as any, + config: CONFIG, + }); + + // Mutation pin: the pre-#4998 behaviour counted NOTHING anywhere. + expect(result.results[0].summariesStale).toBe(2); + expect(result.summary.totalSummariesStale).toBe(2); + + // …while every other counter stays truthful: the rows DID land, exactly + // once, so `errored` must not move and the reconciliation still holds. + expect(result.summary.totalErrored).toBe(0); + expect(result.summary.totalInserted).toBe(2); + expect(store.roll_invoice).toHaveLength(2); + + // `success` deliberately stays true — it answers "did the rows land", and + // they did. Flipping it would report `success: false` with an EMPTY errors + // array to the protocol seed-apply surface and fail package/marketplace + // installs that wrote every row; the counter above carries the signal. + expect(result.success).toBe(true); + expect(result.errors).toEqual([]); + }); + + it('attributes the count to the dataset that caused it, leaving clean datasets at 0', async () => { + const { engine } = createFaithfulEngine(); + failSummaryRecompute(engine, 'roll_invoice', FAILURES); + + const result = await new SeedLoaderService(engine, createMetadata(), createLogger()).load({ + seeds: [ + seedFor('roll_invoice', [{ name: 'INV-1', total: 10 }, { name: 'INV-2', total: 20 }]), + seedFor('roll_payment', [{ name: 'PAY-1', amount: 5 }]), + ] as any, + config: CONFIG, + }); + + const byObject = Object.fromEntries(result.results.map((r) => [r.object, r.summariesStale])); + expect(byObject).toEqual({ roll_invoice: 2, roll_payment: 0 }); + expect(result.summary.totalSummariesStale).toBe(2); + }); + + it('stays quiet and counts 0 when every recompute succeeds', async () => { + const { engine } = createFaithfulEngine(); + const logger = createLogger(); + + const result = await new SeedLoaderService(engine, createMetadata(), logger).load({ + seeds: [seedFor('roll_invoice', [{ name: 'INV-1', total: 10 }])] as any, + config: CONFIG, + }); + + expect(logger.error).not.toHaveBeenCalled(); + expect(result.results[0].summariesStale).toBe(0); + expect(result.summary.totalSummariesStale).toBe(0); + expect(result.success).toBe(true); + }); + + it('a load with no datasets reports 0 rather than omitting the counter', async () => { + const { engine } = createFaithfulEngine(); + + const result = await new SeedLoaderService(engine, createMetadata(), createLogger()).load({ + seeds: [] as any, + config: CONFIG, + }); + + expect(result.summary.totalSummariesStale).toBe(0); + }); +}); + +describe('the counter survives the contract, and the contract survives older payloads', () => { + it('is carried THROUGH SeedLoaderResultSchema.parse — not stripped as an unknown key', async () => { + const { engine } = createFaithfulEngine(); + failSummaryRecompute(engine, 'roll_invoice', FAILURES); + + const result = await new SeedLoaderService(engine, createMetadata(), createLogger()).load({ + seeds: [seedFor('roll_invoice', [{ name: 'INV-1', total: 10 }, { name: 'INV-2', total: 20 }])] as any, + config: CONFIG, + }); + + // The declared shape is what consumers actually receive over a parse + // boundary. A field the runtime sets but the schema does not declare would + // vanish HERE, silently — which is why #4998 could not be closed inside + // metadata-protocol alone. + const parsed = SeedLoaderResultSchema.parse(result); + expect(parsed.summary.totalSummariesStale).toBe(2); + expect(parsed.results[0].summariesStale).toBe(2); + }); + + it('defaults to 0 for a payload written before the field existed', () => { + // Proving the `.default(0)` claim rather than asserting it: this is exactly + // a pre-#4998 producer's output, and it must still parse. + const legacyPerObject = { + object: 'roll_invoice', + mode: 'insert', + inserted: 2, updated: 0, skipped: 0, errored: 0, total: 2, + referencesResolved: 0, referencesDeferred: 0, + errors: [], + }; + expect(SeedLoadResultSchema.parse(legacyPerObject).summariesStale).toBe(0); + + const legacyResult = { + success: true, + dryRun: false, + dependencyGraph: { nodes: [], insertOrder: [], circularDependencies: [] }, + results: [legacyPerObject], + errors: [], + summary: { + objectsProcessed: 1, totalRecords: 2, totalInserted: 2, totalUpdated: 0, + totalSkipped: 0, totalErrored: 0, totalReferencesResolved: 0, + totalReferencesDeferred: 0, circularDependencyCount: 0, durationMs: 1, + }, + }; + expect(SeedLoaderResultSchema.parse(legacyResult).summary.totalSummariesStale).toBe(0); + }); +}); diff --git a/packages/metadata-protocol/src/seed-loader.ts b/packages/metadata-protocol/src/seed-loader.ts index b88e248975..c57ac68dc3 100644 --- a/packages/metadata-protocol/src/seed-loader.ts +++ b/packages/metadata-protocol/src/seed-loader.ts @@ -133,6 +133,21 @@ export class SeedLoaderService implements ISeedLoaderService { * seeds (those stay intentionally global/cross-tenant). */ private fallbackOrgId?: string; + /** + * Roll-up summary values left stale so far in the CURRENT {@link load} — + * bumped by {@link reportStaleSummaries}, sampled by {@link loadDataset} + * around each dataset so every result entry reports only its own share + * (two datasets may target the same object, so keying by object name would + * double-count). + * + * An instance field for the same reason {@link fallbackOrgId} is one: the + * write path that discovers this is several private methods below the point + * the per-dataset counters live, and threading a callback through + * `writeRecord` would put plumbing in five call sites to carry one number. + * Reset per `load`; datasets are loaded strictly sequentially (`for … await`), + * so the sampling is exact. + */ + private summariesStale = 0; constructor(engine: IDataEngine, metadata: IMetadataService, logger: Logger) { this.engine = engine; @@ -158,6 +173,8 @@ export class SeedLoaderService implements ISeedLoaderService { const config = this.resolveEnvConfig(request.config, request.seeds); const allErrors: ReferenceResolutionError[] = []; const allResults: SeedLoadResult[] = []; + // Per-load counter — a service instance can be reused across loads. + this.summariesStale = 0; // When the caller pinned no target org (an in-process publish has no active // user session — the AI build agent's publish path), BUSINESS seed rows @@ -347,6 +364,14 @@ export class SeedLoaderService implements ISeedLoaderService { * still reconciles against `total`. See framework#3932. */ let referencesDropped = 0; + /** + * Roll-up summaries this dataset leaves stale — sampled as a delta on the + * per-load counter (see {@link SeedLoaderService.summariesStale}) rather + * than tracked locally, because the write that discovers it is several + * methods down. Datasets load sequentially, so the delta is exactly this + * dataset's share even when two datasets target the same object. + */ + const summariesStaleAtStart = this.summariesStale; const errors: ReferenceResolutionError[] = []; // Ensure the object's record map exists @@ -432,14 +457,14 @@ export class SeedLoaderService implements ISeedLoaderService { // Partial-success batch: per-row verdicts, hooks fire once. // On ERR_SUMMARY_RECOMPUTE, writeRecoveringSummary hands back // e.written — which for insertMany IS the outcome array. - freshOutcomes = await this.writeRecoveringSummary(() => engineInsertMany(objectName, toInsert, opts)); + freshOutcomes = await this.writeRecoveringSummary(objectName, () => engineInsertMany(objectName, toInsert, opts)); } else { // Legacy whole-array insert: any bad row throws the batch, and // bulkWrite's per-row degradation (writeOne) sorts it out. A // lone row keeps the historical bare-record insert() shape. const recs = toInsert.length === 1 - ? [await this.writeRecoveringSummary(() => this.engine.insert(objectName, toInsert[0], opts))] - : await this.writeRecoveringSummary(() => this.engine.insert(objectName, toInsert, opts)); + ? [await this.writeRecoveringSummary(objectName, () => this.engine.insert(objectName, toInsert[0], opts))] + : await this.writeRecoveringSummary(objectName, () => this.engine.insert(objectName, toInsert, opts)); freshOutcomes = (recs as any[]).map((r) => ({ ok: true, record: r })); } lastBatchUncertain = false; @@ -470,7 +495,7 @@ export class SeedLoaderService implements ISeedLoaderService { if (hit) return hit; // already committed by a prior attempt } } - return this.writeRecoveringSummary(() => this.engine.insert(objectName, row, opts)); + return this.writeRecoveringSummary(objectName, () => this.engine.insert(objectName, row, opts)); }, }, ); @@ -853,7 +878,7 @@ export class SeedLoaderService implements ISeedLoaderService { insertedRecords.get(objectName)!.set(externalIdValue, decision.id); } try { - await this.writeRecoveringSummary(() => withTransientRetry(() => this.engine.update(objectName, { ...record, id: decision.id }, opts))); + await this.writeRecoveringSummary(objectName, () => withTransientRetry(() => this.engine.update(objectName, { ...record, id: decision.id }, opts))); updated++; } catch (err: any) { errored++; @@ -903,6 +928,7 @@ export class SeedLoaderService implements ISeedLoaderService { referencesResolved, referencesDeferred, referencesDropped, + summariesStale: this.summariesStale - summariesStaleAtStart, errors, }; } @@ -1219,38 +1245,107 @@ export class SeedLoaderService implements ISeedLoaderService { */ private static readonly SEED_OPTIONS = { context: { isSystem: true, skipTriggers: true, seedReplay: true } } as const; + /** + * The engine write {@link writeRecoveringSummary} guards, as a NAMED callee. + * + * Extracted for the same reason {@link writeDeferredReference} is: + * `scripts/check-durability-degradation-log-level.mjs` recognises a guarded + * `try` by the callee names it finds in the block and deliberately does not + * descend into nested function bodies, so the `fn()` parameter this used to + * call directly was invisible to it — no ledger entry could ever have + * matched. `performSeedWrite` is listed in that script's + * `DURABILITY_CRITICAL_CALLEES`, which is what makes the `logger.error` + * below enforced rather than merely written down (#4998; the rule is #4632). + */ + private async performSeedWrite(fn: () => Promise): Promise { + return await fn(); + } + /** * Run an engine write; if it fails ONLY because a post-write roll-up summary * recompute exhausted its retries (framework#3147, `code` - * 'ERR_SUMMARY_RECOMPUTE'), the record WAS written — treat it as a warning - * and return the written value rather than re-writing (which would - * duplicate). Matched by `code` so we needn't import objectql (which depends - * on this package — importing back would cycle). Any other error propagates. + * 'ERR_SUMMARY_RECOMPUTE'), the record WAS written — return the written + * value rather than re-writing (which would duplicate). Matched by `code` so + * we needn't import objectql (which depends on this package — importing back + * would cycle). Any other error propagates. + * + * The RECOVERY is unchanged; what it costs is now reported honestly (#4998). + * A roll-up summary is a persisted DERIVED column on the parent record, so + * exhausting its recompute retries leaves the database internally + * inconsistent — detail rows say one thing, the column that summarizes them + * says another — and nothing recomputes it until some later write touches + * the same parent, which after a seed may never happen. That is the #4632 + * durability class exactly ("persisted state and runtime state disagree + * while everything looks normal"), so it logs at `error` naming the + * consequence and the remedy. * - * Left at `warn` by #4729 deliberately, and the reasoning is filed rather - * than settled here: this is the one degradation in the file that is NOT - * counted as an error (the load still reports `success: true`), so it falls - * outside that issue's "count and level must agree" criterion — but a stale - * roll-up column IS persisted data disagreeing with the rows it summarizes, - * which is arguably the #4632 class. Whether it should become `error`, - * counted, or stay as-is is #4998 (needs a maintainer's call, since it - * changes what a SUCCESSFUL seed prints). + * It is also COUNTED, into `SeedLoadResult.summariesStale` / + * `summary.totalSummariesStale`, because a log line is not something a + * caller can branch on. `success` deliberately stays `true`: the rows landed, + * and every consumer of this result treats `success: false` as "the write + * failed" — the protocol seed-apply surface returns it with an EMPTY errors + * array, the runtime boot banner prints a "0 dropped record(s)" line, and the + * package/marketplace installers fail an install that in fact wrote every + * row. The new counter carries the signal instead. */ - private async writeRecoveringSummary(fn: () => Promise): Promise { + private async writeRecoveringSummary(objectName: string, fn: () => Promise): Promise { try { - return await fn(); + return await this.performSeedWrite(fn); } catch (e: any) { if (e?.code === 'ERR_SUMMARY_RECOMPUTE') { - this.logger.warn( - '[SeedLoader] roll-up summary recompute failed after retries; records were written (summary values may be stale)', - { failures: Array.isArray(e.failures) ? e.failures.length : undefined }, - ); + this.reportStaleSummaries(objectName, e); return e.written as T; } throw e; } } + /** + * Count and announce the roll-up summaries a recovered write left stale. + * + * Split out of {@link writeRecoveringSummary}'s catch so the counting and the + * `error` line are one unit: raising the level without counting was half the + * #4998 defect, and counting without raising the level was the other half. + */ + private reportStaleSummaries(objectName: string, e: SummaryRecomputeLike): void { + const failures = Array.isArray(e.failures) ? e.failures : []; + // One entry per parent record whose summary field could not be recomputed. + // If the producer sent no usable list we still KNOW at least one summary is + // stale — the error code says so — and counting 0 would restore exactly the + // invisibility this counter exists to remove. + const staleCount = failures.length || 1; + const columns = [...new Set( + failures + .filter(f => f?.parentObject && f?.field) + .map(f => `${f.parentObject}.${f.field}`), + )]; + this.summariesStale += staleCount; + this.logger.error( + `[SeedLoader] roll-up summary recompute FAILED after retries while seeding ${objectName} — ` + + `${staleCount} persisted summary value(s) on ` + + `${columns.length > 0 ? columns.join(', ') : 'the parent record(s)'} now hold STALE values: ` + + `they disagree with the detail rows they summarize, and nothing recomputes them on its own. ` + + `The seeded rows themselves WERE written and are deliberately NOT re-written (that would ` + + `duplicate them), so this load still reports success: true with every row counter clean — ` + + `the machine-readable trace is summariesStale on this object's result ` + + `(summary.totalSummariesStale for the load). Fix the recompute error below and re-run the ` + + `seed, or trigger any write on the affected parent record(s) to force a recompute. ` + + `Cause: ${e?.message ?? 'unknown'}`, + e instanceof Error ? e : undefined, + { + object: objectName, + summariesStale: staleCount, + summaryColumns: columns, + failures: failures.map(f => ({ + parentObject: f?.parentObject, + parentId: f?.parentId, + field: f?.field, + error: f?.error instanceof Error ? f.error.message : f?.error, + })), + }, + ); + } + private async writeRecord( objectName: string, record: Record, @@ -1263,7 +1358,7 @@ export class SeedLoaderService implements ISeedLoaderService { switch (mode) { case 'insert': { - const result = await this.writeRecoveringSummary(() => withTransientRetry(() => this.engine.insert(objectName, record, opts))); + const result = await this.writeRecoveringSummary(objectName, () => withTransientRetry(() => this.engine.insert(objectName, record, opts))); return { action: 'inserted', id: this.extractId(result) }; } @@ -1275,7 +1370,7 @@ export class SeedLoaderService implements ISeedLoaderService { if (this.isNoOpReplay(record, existing)) { return { action: 'skipped', id }; } - await this.writeRecoveringSummary(() => withTransientRetry(() => this.engine.update(objectName, { ...record, id }, opts))); + await this.writeRecoveringSummary(objectName, () => withTransientRetry(() => this.engine.update(objectName, { ...record, id }, opts))); return { action: 'updated', id }; } @@ -1285,10 +1380,10 @@ export class SeedLoaderService implements ISeedLoaderService { if (this.isNoOpReplay(record, existing)) { return { action: 'skipped', id }; } - await this.writeRecoveringSummary(() => withTransientRetry(() => this.engine.update(objectName, { ...record, id }, opts))); + await this.writeRecoveringSummary(objectName, () => withTransientRetry(() => this.engine.update(objectName, { ...record, id }, opts))); return { action: 'updated', id }; } else { - const result = await this.writeRecoveringSummary(() => withTransientRetry(() => this.engine.insert(objectName, record, opts))); + const result = await this.writeRecoveringSummary(objectName, () => withTransientRetry(() => this.engine.insert(objectName, record, opts))); return { action: 'inserted', id: this.extractId(result) }; } } @@ -1297,18 +1392,18 @@ export class SeedLoaderService implements ISeedLoaderService { if (existing) { return { action: 'skipped', id: this.extractId(existing) }; } - const result = await this.writeRecoveringSummary(() => withTransientRetry(() => this.engine.insert(objectName, record, opts))); + const result = await this.writeRecoveringSummary(objectName, () => withTransientRetry(() => this.engine.insert(objectName, record, opts))); return { action: 'inserted', id: this.extractId(result) }; } case 'replace': { // Replace mode: just insert (caller should have cleared the table) - const result = await this.writeRecoveringSummary(() => withTransientRetry(() => this.engine.insert(objectName, record, opts))); + const result = await this.writeRecoveringSummary(objectName, () => withTransientRetry(() => this.engine.insert(objectName, record, opts))); return { action: 'inserted', id: this.extractId(result) }; } default: { - const result = await this.writeRecoveringSummary(() => withTransientRetry(() => this.engine.insert(objectName, record, opts))); + const result = await this.writeRecoveringSummary(objectName, () => withTransientRetry(() => this.engine.insert(objectName, record, opts))); return { action: 'inserted', id: this.extractId(result) }; } } @@ -1751,6 +1846,7 @@ export class SeedLoaderService implements ISeedLoaderService { totalReferencesResolved: 0, totalReferencesDeferred: 0, totalReferencesDropped: 0, + totalSummariesStale: 0, circularDependencyCount: 0, durationMs, }, @@ -1774,6 +1870,11 @@ export class SeedLoaderService implements ISeedLoaderService { totalReferencesResolved: results.reduce((sum, r) => sum + r.referencesResolved, 0), totalReferencesDeferred: results.reduce((sum, r) => sum + r.referencesDeferred, 0), totalReferencesDropped: results.reduce((sum, r) => sum + (r.referencesDropped ?? 0), 0), + // No `?? 0`: every result entry is built by `loadDataset`, which always + // populates `summariesStale`. A consumer never needs the fallback either + // — the field is declared with `.default(0)`, so it survives a parse of a + // payload written before it existed (#4998). + totalSummariesStale: results.reduce((sum, r) => sum + r.summariesStale, 0), circularDependencyCount: graph.circularDependencies.length, durationMs, }; @@ -1795,6 +1896,27 @@ export class SeedLoaderService implements ISeedLoaderService { // Internal Types // ========================================================================== +/** + * Structural view of objectql's `SummaryRecomputeError` (framework#3147). + * + * Declared here rather than imported because objectql depends on THIS package, + * so importing it back would cycle — the same reason the error is matched by + * `code` instead of `instanceof`. Every field is optional: this describes an + * object that crossed a package boundary as `unknown`, and the reader + * ({@link SeedLoaderService.reportStaleSummaries}) is what decides what to do + * when a field is missing. + */ +interface SummaryRecomputeLike { + message?: string; + failures?: Array<{ + childObject?: string; + parentObject?: string; + parentId?: string; + field?: string; + error?: unknown; + }>; +} + interface DeferredUpdate { objectName: string; recordExternalId: string; diff --git a/packages/spec/authorable-surface.json b/packages/spec/authorable-surface.json index d88c4db1dd..01cab1f404 100644 --- a/packages/spec/authorable-surface.json +++ b/packages/spec/authorable-surface.json @@ -3810,6 +3810,7 @@ "data/SeedLoadResult:referencesDropped", "data/SeedLoadResult:referencesResolved", "data/SeedLoadResult:skipped", + "data/SeedLoadResult:summariesStale", "data/SeedLoadResult:total", "data/SeedLoadResult:updated", "data/SeedLoaderConfig:batchSize", diff --git a/packages/spec/src/data/seed-loader.zod.ts b/packages/spec/src/data/seed-loader.zod.ts index a58862bbf4..fb0c3b9260 100644 --- a/packages/spec/src/data/seed-loader.zod.ts +++ b/packages/spec/src/data/seed-loader.zod.ts @@ -355,6 +355,30 @@ export const SeedLoadResultSchema = lazySchema(() => z.object({ referencesDropped: z.number().int().min(0).default(0) .describe('Reference fields dropped from records that were still written'), + /** + * Number of persisted roll-up summary values left STALE by this dataset's + * writes — "wrote the rows, broke the aggregate". + * + * A roll-up summary is a DERIVED value that lives as a persisted column on + * the PARENT record. When a seed write lands but its post-write recompute + * exhausts its retries (`ERR_SUMMARY_RECOMPUTE`, framework#3147) the detail + * rows are correct and the column that summarizes them is not, so the two + * disagree in the database. Nothing self-heals: the value stays wrong until + * some later write happens to touch the same parent, and after a seed there + * may never be one. + * + * The rows themselves DID land and are deliberately not re-written (that + * would duplicate them), so `errored` must not move and + * `inserted + updated + skipped + errored` still reconciles against `total` + * — the same reasoning that gave `referencesDropped` its own counter one + * layer down. Without this counter the condition was observable only as a + * single log line: no caller could detect it programmatically, and the load + * reported a clean `success: true` over a summary column that was wrong + * (framework#4998). + */ + summariesStale: z.number().int().min(0).default(0) + .describe('Roll-up summary values left stale by writes for this dataset'), + /** Reference resolution errors for this object */ errors: z.array(ReferenceResolutionErrorSchema).default([]) .describe('Reference resolution errors'), @@ -419,6 +443,18 @@ export const SeedLoaderResultSchema = lazySchema(() => z.object({ totalReferencesDropped: z.number().int().min(0).default(0) .describe('Total reference fields dropped from written records'), + /** + * Total persisted roll-up summary values left stale by the load — "wrote + * the rows, broke the aggregate". See `SeedLoadResult.summariesStale`. + * + * Non-zero means at least one summary column in the database now + * disagrees with the detail rows it summarizes, even though `success` is + * `true` and every row counter reads clean — `success` answers "did the + * rows land", and they did. + */ + totalSummariesStale: z.number().int().min(0).default(0) + .describe('Total roll-up summary values left stale across the load'), + /** Number of circular dependency chains detected */ circularDependencyCount: z.number().int().min(0).describe('Circular dependency chains detected'), diff --git a/scripts/check-durability-degradation-log-level.mjs b/scripts/check-durability-degradation-log-level.mjs index 4e653e17ca..043a60fb40 100644 --- a/scripts/check-durability-degradation-log-level.mjs +++ b/scripts/check-durability-degradation-log-level.mjs @@ -128,6 +128,10 @@ const DURABILITY_CRITICAL_CALLEES = new Map([ 'writeRecord', 'A seed record was not written — the row is simply absent (or, on the upsert/update path, still holds its pre-seed contents) while the load moves on to the next record (#4729).', ], + [ + 'performSeedWrite', + "A seed write's post-write roll-up summary recompute was swallowed — the rows landed, but a persisted summary column now disagrees with the detail rows it summarizes and nothing recomputes it, while every row counter and `success` still read clean (#4998, framework#3147).", + ], [ 'dropPromotedDraftRow', "A published draft was never drained — the active row is correct, but the `state='draft'` row is still in `sys_metadata`, so Studio/Setup keeps showing unpublished changes that do not exist and the next publish promotes the same stale body again (#4981).", @@ -293,6 +297,54 @@ function analyzeSourceFile(sf, relPath, findings, seams) { return { levels, rethrows }; }; + /** + * Does this statement ALWAYS leave by throwing? + * + * Deliberately conservative — only the shapes whose control flow is + * unambiguous. Anything it cannot prove counts as "may complete normally", + * which errs toward judging the seam rather than excusing it. + */ + const alwaysThrows = (stmt) => { + if (ts.isThrowStatement(stmt)) return true; + if (ts.isBlock(stmt)) return stmt.statements.some(alwaysThrows); + if (ts.isIfStatement(stmt)) { + return ( + !!stmt.elseStatement && + alwaysThrows(stmt.thenStatement) && + alwaysThrows(stmt.elseStatement) + ); + } + return false; + }; + + /** + * Does this catch have a path that RECOVERS instead of propagating? + * + * A rethrow is only an excuse when the catch propagates on EVERY path: then + * the failure reaches the caller and nothing is being degraded here. A + * catch that rethrows on one branch and RETURNS a substitute on another is + * two different seams sharing one block, and the recovery branch is a + * degradation like any other — it must be loud or it is exactly the silent + * data loss #4632 is about. + * + * Missing this cost a whole round: seed-loader's `writeRecoveringSummary` + * recovers an `ERR_SUMMARY_RECOMPUTE` (the rows landed; re-writing would + * duplicate) and rethrows everything else. Because the block contained a + * `throw`, the old rule excused it wholesale — registering its callee in + * `DURABILITY_CRITICAL_CALLEES` produced a ledger entry that could never + * fire, i.e. protection that reads as real and enforces nothing (#4998). + */ + const catchRecovers = (block) => { + let sawReturn = false; + walkSameTick(block, (child) => { + if (ts.isReturnStatement(child)) sawReturn = true; + }); + // A `return` is an explicit recovery: the caller gets a value, not the + // failure. With no return, the catch still recovers by falling off the + // end — unless one of its top-level statements always throws. + return sawReturn || !block.statements.some(alwaysThrows); + }; + walkAll(sf, (node) => { if (!ts.isTryStatement(node) || !node.catchClause) return; @@ -311,6 +363,8 @@ function analyzeSourceFile(sf, relPath, findings, seams) { // 2. How does the catch respond? const { levels, rethrows } = collectResponse(node.catchClause.block); + // Only an UNCONDITIONAL rethrow excuses the seam — see catchRecovers(). + const propagatesAlways = rethrows && !catchRecovers(node.catchClause.block); const loud = levels.filter((l) => LOUD_LEVELS.has(l.level)); const quiet = levels.filter((l) => QUIET_LEVELS.has(l.level)); @@ -320,13 +374,14 @@ function analyzeSourceFile(sf, relPath, findings, seams) { callee: guarded[0].callee, calleeLine: guarded[0].line, catchLine: lineOf(node.catchClause), - rethrows, + rethrows: propagatesAlways, + partialRethrow: rethrows && !propagatesAlways, loud: loud.map((l) => `${l.level}@${l.line}${l.viaHelper ? ` via ${l.viaHelper}()` : ''}`), quiet: quiet.map((l) => `${l.level}@${l.line}${l.viaHelper ? ` via ${l.viaHelper}()` : ''}`), }; seams.push(seam); - if (rethrows || loud.length > 0) return; + if (propagatesAlways || loud.length > 0) return; findings.push({ ...seam, @@ -363,7 +418,9 @@ function run({ list = false } = {}) { for (const s of seams) { const verdict = s.rethrows ? 'rethrows' - : s.loud.length > 0 + : s.partialRethrow && s.loud.length > 0 + ? `recovers on one branch, loud (${s.loud.join(', ')})` + : s.loud.length > 0 ? `loud (${s.loud.join(', ')})` : s.quiet.length > 0 ? `QUIET (${s.quiet.join(', ')})` @@ -472,6 +529,55 @@ function selfTest() { } }`, expectViolation: false, }, + { + // #4998: a catch that RECOVERS on one branch and rethrows on the + // other is two seams in one block. The rethrow covers the branch + // that propagates; it says nothing about the branch that returns a + // substitute value, and that branch is a degradation like any + // other. Excusing the whole block on the presence of a `throw` + // made a DURABILITY_CRITICAL_CALLEES entry for such a seam + // unfireable — a ledger line that looks like protection and + // enforces nothing. + name: 'flags: catch that recovers on one branch (rethrowing on the other) and logs warn', + code: ` + class P { async f(ctx: any, driver: any, obj: any) { + try { return await driver.syncSchema('t', obj); } + catch (e: any) { + if (e.code === 'RECOVERABLE') { + ctx.logger.warn('recovered; state may be stale'); + return e.written; + } + throw e; + } + } }`, + expectViolation: true, + }, + { + name: 'passes: the same partial-recovery shape logging error', + code: ` + class P { async f(ctx: any, driver: any, obj: any) { + try { return await driver.syncSchema('t', obj); } + catch (e: any) { + if (e.code === 'RECOVERABLE') { + ctx.logger.error('CONSEQUENCE: stale; FIX: re-run', e); + return e.written; + } + throw e; + } + } }`, + expectViolation: false, + }, + { + name: 'passes: catch that rethrows from inside a conditional and never recovers', + code: ` + class P { async f(ctx: any, driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e: any) { + if (e.code === 'A') { throw e; } else { throw new Error('B'); } + } + } }`, + expectViolation: false, + }, { name: 'passes: functional degradation (no critical callee) may warn', code: `