From 3d43ce5a0af8ad3db5120a8d0a137900157d1484 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 4 Aug 2026 05:30:13 +0000 Subject: [PATCH] fix(metadata-protocol): log the seed record dropped for an unresolvable reference at `error` (#4997) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The pass-1 branch that drops a WHOLE record — reference unresolvable and no pass 2 to fix it — counted the loss (`errored`), reported it (`result.errors` → `success: false`) and its own comment claimed "LOUD", but it made no logger call at all. A seed that dropped N records printed exactly what a clean one printed, and the `packages/runtime` seed call sites that only `await` the load never read `result.success`. It now logs at `error` per AGENTS.md → "Degradation log levels" (#4632), naming the consequence (record #i of was not seeded AT ALL, not just its association) and all three remedies (seed the target first, enable `multiPass` so pass 2 back-fills, or fix the natural key in the seed data). Applying the same objective criterion — does the outcome enter `errors`/`allErrors`? — to the rest of the file found one more branch with a count and no log: "deferred reference unresolved after pass 2", whose sibling (back-fill write failed) has logged at `error` since #4729. Aligned. The dry-run branch stays QUIET by decision, with the reason in a comment and a test pinning it: a dry run writes nothing, its caller is reading the result object by definition, and an `error` about a simulated outcome trains readers to skim `error`. No counters, result shapes or `result.errors` messages changed. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01NrmBxj8rK2uGCnh9aipjwX --- ...seed-loader-unresolved-record-drop-loud.md | 37 ++ .../src/seed-loader-unresolved-drop.test.ts | 352 ++++++++++++++++++ packages/metadata-protocol/src/seed-loader.ts | 76 +++- 3 files changed, 454 insertions(+), 11 deletions(-) create mode 100644 .changeset/seed-loader-unresolved-record-drop-loud.md create mode 100644 packages/metadata-protocol/src/seed-loader-unresolved-drop.test.ts diff --git a/.changeset/seed-loader-unresolved-record-drop-loud.md b/.changeset/seed-loader-unresolved-record-drop-loud.md new file mode 100644 index 0000000000..2d829492b5 --- /dev/null +++ b/.changeset/seed-loader-unresolved-record-drop-loud.md @@ -0,0 +1,37 @@ +--- +"@objectstack/metadata-protocol": patch +--- + +fix(metadata-protocol): a seed record dropped for an unresolvable reference now says so at `error` (#4997) + +When a seed's `lookup` / `master_detail` / `user` reference could not be +resolved and no pass 2 would run (`multiPass: false`), the loader dropped the +**whole record** — the right call, since writing it would put the raw +natural-key string into the FK column or, on an upsert UPDATE, corrupt the row +already there. The drop was counted (`errored`) and reported +(`result.errors` → `success: false`), and the code comment above it claimed +"LOUD", but the branch made **no logger call at all**. On the console a seed +that silently dropped N records was indistinguishable from a clean one, and the +`packages/runtime` seed call sites that only `await` the load never look at +`result.success` — so the loss surfaced later as "the app installed but the data +isn't there". + +That branch now logs at `error`, per AGENTS.md → "Degradation log levels" +(#4632): the line names the record (`` record #i), the field, the target +`.` it could not find, and the **consequence** (the whole record +was not seeded — not merely the association), followed by all three **remedies** +— seed the target object first, enable `multiPass` so pass 2 back-fills the +reference, or fix the natural key in the seed data. + +The same objective criterion (does the outcome enter `errors`/`allErrors`?) +found one more never-logged branch in the same file and aligned it: a **deferred +reference still unresolved after pass 2** was counted exactly like its sibling +whose back-fill *write* fails — which has logged at `error` since #4729 — and +logged nowhere. It now reports that the row was seeded while the relationship is +permanently missing, and how to complete it. + +The **dry-run** branch stays deliberately quiet and is pinned that way by test: +a dry run writes nothing, its caller is by definition reading the result object, +and an `error` line about a simulated outcome only trains readers to skim +`error`. No counters, result shapes or messages in `result.errors` changed — +this is console output that was missing, not a contract change. diff --git a/packages/metadata-protocol/src/seed-loader-unresolved-drop.test.ts b/packages/metadata-protocol/src/seed-loader-unresolved-drop.test.ts new file mode 100644 index 0000000000..363a02531b --- /dev/null +++ b/packages/metadata-protocol/src/seed-loader-unresolved-drop.test.ts @@ -0,0 +1,352 @@ +// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. + +import { describe, it, expect, vi } from 'vitest'; +// `.js` extension deliberately: under `moduleResolution: nodenext` an +// extensionless relative import does not resolve, every symbol it names +// degrades to `any`, and the callbacks below then report TS7006 — the trap +// AGENTS.md → "Build & Test" describes. Both spellings exist in this package's +// tests; this one is the one tsc can actually read. +import { SeedLoaderService } from './seed-loader.js'; +import type { IDataEngine, IMetadataService } from '@objectstack/spec/contracts'; + +/** + * framework#4997: a record DROPPED because its reference cannot be resolved — + * and no pass 2 will run — must be LOUD in the console too, not only in the + * result object. + * + * The branch's own comment claimed "LOUD: counted + reported" while it made no + * logger call at all, so a seed that silently dropped N records looked exactly + * like a clean one on the console. The only difference was whether the caller + * inspected `result.success` — and several `packages/runtime` seed call sites + * just `await` the load and carry on. This is the deeper notch of #4729's + * finding (count says "error", log level says *nothing*), which that PR could + * not see because its audit criterion was the file's `logger.warn` calls, and + * `pnpm check:durability-log-level` cannot see it either: this is not a + * `try`/`catch`. + * + * Pinned here, per AGENTS.md → "Degradation log levels" (#4632): + * - the DROPPED-record branch logs at `error`, naming the consequence (the + * WHOLE record was not seeded) and every remedy; + * - the same objective criterion — does this outcome enter + * `errors`/`allErrors`? — applied to the file's other never-logged branch, + * "deferred reference unresolved after pass 2"; + * - the DRY-RUN branch stays deliberately QUIET (its caller reads the result + * by definition; a loud line about a simulated outcome trains readers to + * skim `error`), which is a decision and therefore pinned as one. + */ + +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 }; +} + +/** `drop_order.customer_id` → `drop_customer`; no cycle, so nothing defers. */ +function createMetadata(): IMetadataService { + const objects: Record = { + drop_customer: { + name: 'drop_customer', + fields: { name: { type: 'text' } }, + }, + drop_order: { + name: 'drop_order', + fields: { + name: { type: 'text' }, + customer_id: { type: 'lookup', reference: 'drop_customer' }, + }, + }, + }; + 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 SINGLE_PASS = { + dryRun: false, + haltOnError: false, + multiPass: false, + defaultMode: 'insert', + batchSize: 1000, + transaction: false, +} as any; + +/** Record #0 seeds cleanly; record #1 points at a customer that does not exist. */ +const ORDERS = [ + { + object: 'drop_order', + externalId: 'name', + mode: 'insert', + env: ['prod', 'dev', 'test'], + records: [ + { name: 'ORD-1' }, + { name: 'ORD-2', customer_id: 'Ghost Inc' }, + ], + }, +] as any[]; + +describe('a record dropped for an unresolvable reference is logged, not only counted (framework#4997)', () => { + it('logs at ERROR naming the object, the record, the field, the target and every remedy', async () => { + const { engine, store } = createFaithfulEngine(); + const logger = createLogger(); + + await new SeedLoaderService(engine, createMetadata(), logger).load({ + seeds: ORDERS, + config: SINGLE_PASS, + }); + + // The loss is real: ORD-2 was not written at all (not "written without the + // link" — that is the referencesDropped shape, a different branch). + expect(store.drop_order.map((r) => r.name)).toEqual(['ORD-1']); + + // Mutation pin: before #4997 this path made NO logger call whatsoever. + expect(logger.error).toHaveBeenCalledTimes(1); + const [message, cause, meta] = (logger.error as any).mock.calls[0]; + + // WHAT was lost — object, record ordinal, field, target, attempted value. + expect(message).toContain('drop_order'); + expect(message).toContain('record #1'); + expect(message).toContain('customer_id'); + expect(message).toContain('drop_customer.name'); + expect(message).toContain('Ghost Inc'); + + // CONSEQUENCE (#4632): the WHOLE record is gone, not just the association. + expect(message).toContain('NOT seeded AT ALL'); + expect(message).toContain('WHOLE'); + + // REMEDY (#4632) — all three routes the issue names. + expect(message).toContain('seed drop_customer BEFORE drop_order'); + expect(message).toContain('multiPass'); + expect(message).toContain('fix the natural key'); + expect(message).toMatch(/re-run the seed/); + + // Structured payload per the `Logger` contract's `(message, error, meta)`. + // There is no thrown Error behind this one — nothing failed, the target + // simply is not there — so the error slot is deliberately undefined. + expect(cause).toBeUndefined(); + expect(meta).toMatchObject({ + object: 'drop_order', + field: 'customer_id', + target: 'drop_customer.name', + recordIndex: 1, + }); + + // Mutation pin: not `warn` — the level #4729 aligned everywhere else here. + expect(logger.warn).not.toHaveBeenCalled(); + }); + + it('is still COUNTED and reported, which is what the log level now agrees with', async () => { + const { engine } = createFaithfulEngine(); + + const result = await new SeedLoaderService(engine, createMetadata(), createLogger()).load({ + seeds: ORDERS, + config: SINGLE_PASS, + }); + + expect(result.success).toBe(false); + expect(result.summary.totalErrored).toBe(1); + expect(result.summary.totalInserted).toBe(1); + // A dropped RECORD, never a dropped FIELD — the two counters mean different + // losses and must not blur (framework#3932). + expect(result.summary.totalReferencesDropped).toBe(0); + expect(result.results[0].errored).toBe(1); + // Row counters still reconcile against the dataset total. + const r = result.results[0]; + expect(r.inserted + r.updated + r.skipped + r.errored).toBe(r.total); + + const error = result.errors.find((e) => e.field === 'customer_id')!; + expect(error.message).toContain('Cannot resolve reference: drop_order.customer_id'); + expect(error.recordIndex).toBe(1); + expect(error.attemptedValue).toBe('Ghost Inc'); + }); + + it('a load where every reference resolves logs nothing loud (do not train readers to skim `error`)', async () => { + const { engine } = createFaithfulEngine(); + const logger = createLogger(); + + const result = await new SeedLoaderService(engine, createMetadata(), logger).load({ + seeds: [ + { + object: 'drop_customer', + externalId: 'name', + mode: 'insert', + env: ['prod', 'dev', 'test'], + records: [{ name: 'Ghost Inc' }], + }, + ORDERS[0], + ] as any, + config: SINGLE_PASS, + }); + + expect(result.success).toBe(true); + expect(logger.error).not.toHaveBeenCalled(); + expect(logger.warn).not.toHaveBeenCalled(); + }); +}); + +describe('a DRY RUN reports the same miss in the result and stays quiet (framework#4997)', () => { + it('carries the note in result.errors while the console says nothing', async () => { + const { engine, store } = createFaithfulEngine(); + const logger = createLogger(); + + const result = await new SeedLoaderService(engine, createMetadata(), logger).load({ + seeds: ORDERS, + config: { ...SINGLE_PASS, dryRun: true }, + }); + + // A dry run writes nothing, so nothing was lost. + expect(store.drop_order).toBeUndefined(); + expect(engine.insert).not.toHaveBeenCalled(); + + // The caller of a dry run is by definition reading the result — the note is + // there, in full. + expect(result.dryRun).toBe(true); + expect(result.success).toBe(false); + const note = result.errors.find((e) => e.field === 'customer_id')!; + expect(note.message).toContain('[dry-run] Reference may not resolve'); + expect(note.message).toContain('drop_order.customer_id'); + expect(note.message).toContain('Ghost Inc'); + expect(note.recordIndex).toBe(1); + + // …and the console stays QUIET. This is a DECISION, not an oversight: an + // `error` line about a SIMULATED outcome is the over-application AGENTS.md + // warns about. Deleting the `if (config.dryRun)` guard's quietness — i.e. + // logging here like the real-run branch does — must turn this red. + expect(logger.error).not.toHaveBeenCalled(); + expect(logger.warn).not.toHaveBeenCalled(); + }); +}); + +/** + * The same objective criterion (#5001 style: does this outcome enter + * `errors`/`allErrors`?) applied to the file's OTHER never-logged branch. Its + * sibling — the pass-2 back-fill whose WRITE fails — has logged at `error` + * since #4729; "the target never materialized" was counted identically and + * logged nowhere. + */ +describe('a deferred reference still unresolved after pass 2 is logged too (framework#4997)', () => { + const CIRCULAR = { + ...SINGLE_PASS, + multiPass: true, + } as any; + + function createCircularMetadata(): IMetadataService { + const objects: Record = { + drop_team: { + name: 'drop_team', + fields: { + name: { type: 'text' }, + lead_id: { type: 'lookup', reference: 'drop_person' }, + }, + }, + drop_person: { + name: 'drop_person', + fields: { + name: { type: 'text' }, + team_id: { type: 'lookup', reference: 'drop_team' }, + }, + }, + }; + 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; + } + + it('logs at ERROR naming the row, the NULL reference, the missing target and the remedy', async () => { + const { engine, store } = createFaithfulEngine(); + const logger = createLogger(); + + const result = await new SeedLoaderService(engine, createCircularMetadata(), logger).load({ + seeds: [ + { + object: 'drop_team', + externalId: 'name', + mode: 'insert', + env: ['prod', 'dev', 'test'], + // 'Nobody' is never seeded and is not in the database — pass 2 cannot + // rescue it, so the deferred reference is permanently NULL. + records: [{ name: 'Platform', lead_id: 'Nobody' }], + }, + ] as any, + config: CIRCULAR, + }); + + // The ROW landed (unlike the pass-1 drop above) — only the link is missing. + expect(store.drop_team.map((r) => r.name)).toEqual(['Platform']); + expect(store.drop_team[0].lead_id == null).toBe(true); + + // Mutation pin: this branch made no logger call before #4997. + expect(logger.error).toHaveBeenCalledTimes(1); + const [message, , meta] = (logger.error as any).mock.calls[0]; + expect(message).toContain('drop_team.lead_id'); + expect(message).toContain("record 'Platform'"); + expect(message).toContain('drop_person.name'); + expect(message).toContain('Nobody'); + // CONSEQUENCE + REMEDY. + expect(message).toContain('stays NULL'); + expect(message).toContain('counter looks healthy'); + expect(message).toMatch(/re-run the seed/); + expect(meta).toMatchObject({ object: 'drop_team', field: 'lead_id', recordIndex: 0 }); + expect(logger.warn).not.toHaveBeenCalled(); + + // …and it was already counted — the half the log level now agrees with. + expect(result.success).toBe(false); + expect(result.summary.totalErrored).toBe(1); + expect(result.errors.some((e) => e.message.includes('unresolved after pass 2'))).toBe(true); + }); +}); diff --git a/packages/metadata-protocol/src/seed-loader.ts b/packages/metadata-protocol/src/seed-loader.ts index e744ef3941..eeefc755d9 100644 --- a/packages/metadata-protocol/src/seed-loader.ts +++ b/packages/metadata-protocol/src/seed-loader.ts @@ -752,6 +752,15 @@ export class SeedLoaderService implements ISeedLoaderService { if (sawUnresolved) { if (config.dryRun) { // Dry-run: report the miss but leave the authored value untouched. + // + // Deliberately QUIET — no logger call, unlike the real-run branch + // below (#4997). A dry run writes nothing, so nothing was lost: its + // caller is by definition reading the result object (that is the + // whole point of `validate()`), and an `error` line about a + // SIMULATED outcome is the over-application AGENTS.md → "Degradation + // log levels" warns about — it trains readers to skim `error`, which + // is what made the #4420 log unreadable in the first place. Pinned by + // test so this stays a decision rather than an oversight. pushError( `[dry-run] Reference may not resolve: ${objectName}.${ref.field} = ` + `'${String(unresolvedItem)}' → ${ref.targetObject}.${ref.targetField}`, @@ -782,21 +791,41 @@ export class SeedLoaderService implements ISeedLoaderService { }); referencesDeferred++; } else { - // Cannot resolve and no pass 2 will run — skip the whole record - // (LOUD: counted + reported). Writing it anyway would either - // carry the raw natural-key string into the FK column or, on - // update, corrupt the existing row. + // Cannot resolve and no pass 2 will run — skip the whole record. + // Writing it anyway would either carry the raw natural-key string + // into the FK column or, on update, corrupt the existing row. // - // "LOUD" here means counted + in `result.errors` ONLY — this path - // logs nothing at all, so a load that drops N records looks - // identical to a clean one in the console. Filed as #4997 rather - // than fixed under #4729, whose audit criterion was the file's - // `logger.warn` calls. - pushError( + // LOUD, and now in all three registers: COUNTED (`errored`, below), + // REPORTED (`result.errors` / `allErrors` → `success: false`) and + // LOGGED at `error`. Until #4997 the comment here claimed "LOUD: + // counted + reported" while this path logged nothing at all, so a + // load that dropped N records was indistinguishable from a clean one + // in the console — and `packages/runtime`'s seed call sites only + // `await` the result. `error` is the level AGENTS.md → "Degradation + // log levels" reserves for exactly this: the boot looks healthy while + // rows the seed declares are simply not there. + const error = pushError( `Cannot resolve reference: ${objectName}.${ref.field} = '${String(unresolvedItem)}' → ` + `${ref.targetObject}.${ref.targetField} not found`, unresolvedItem, ); + this.logger.error( + `[SeedLoader] ${error.message}. ${objectName} record #${i} was NOT seeded AT ALL — the WHOLE ` + + `record is dropped, not just its \`${ref.field}\` link, because writing it would put the raw ` + + `natural key '${String(unresolvedItem)}' into the FK column (or, on an upsert UPDATE, corrupt ` + + `the row already there). Nothing retries this: pass 2 is off. Restore the record in one of ` + + `three ways, then re-run the seed — seed ${ref.targetObject} BEFORE ${objectName} so the ` + + `target row exists; or enable \`multiPass\` so pass 2 back-fills the reference once every ` + + `object is loaded; or fix the natural key in the ${objectName} seed data so it names a real ` + + `${ref.targetObject}.${ref.targetField}.`, + undefined, + { + object: objectName, + field: ref.field, + target: `${ref.targetObject}.${ref.targetField}`, + recordIndex: i, + }, + ); unresolvedRefError = true; } continue; @@ -1146,8 +1175,33 @@ export class SeedLoaderService implements ISeedLoaderService { // Still unresolved after pass 2 — the target never materialized. Name // the element that missed: on a multi-value field only one of several // natural keys is usually at fault. + // + // Logged at `error` for the same reason the back-fill-write failure + // above is, and aligned with it under the same objective criterion + // (#4997, extending #4729/#5001): this outcome enters `allErrors` and + // bumps `errored`, and until now it was the file's other + // counted-but-never-logged branch. The row itself WAS seeded, so every + // row counter reads healthy while the association it declared is + // permanently absent. + const missedValue = this.formatAttempted(stillUnresolved ? missingItem : deferred.attemptedValue); + this.logger.error( + `[SeedLoader] Deferred reference UNRESOLVED after pass 2 — ${deferred.objectName}.${deferred.field} ` + + `stays NULL on record '${deferred.recordExternalId}'. The row itself was seeded, so every row ` + + `counter looks healthy while the relationship is MISSING: nothing links it to ` + + `${deferred.targetObject}.${deferred.targetField} = '${missedValue}', because no such ` + + `${deferred.targetObject} row exists — neither seeded in this load nor already in the database. ` + + `Nothing retries this: pass 2 is the last one. Add the missing ${deferred.targetObject} record to ` + + `the seed (or fix the natural key that names it) and re-run the seed to complete the link.`, + undefined, + { + object: deferred.objectName, + field: deferred.field, + target: `${deferred.targetObject}.${deferred.targetField}`, + recordIndex: deferred.recordIndex, + }, + ); this.recordDeferredError(deferred, allResults, allErrors, - `Deferred reference unresolved after pass 2: ${deferred.objectName}.${deferred.field} = '${this.formatAttempted(stillUnresolved ? missingItem : deferred.attemptedValue)}' → ${deferred.targetObject}.${deferred.targetField} not found`); + `Deferred reference unresolved after pass 2: ${deferred.objectName}.${deferred.field} = '${missedValue}' → ${deferred.targetObject}.${deferred.targetField} not found`); } } }