Skip to content

Commit 07f93e0

Browse files
os-muskclaude
andauthored
fix(metadata-protocol): the pass-2 deferred-reference summary says which moment it describes (#17588)
`SeedLoaderService` prints its pass-2 diagnostics from inside `AppPlugin.start()`, which the kernel completes for every plugin before it fires `kernel:ready` — where `bootstrapPlatformAdmin` promotes the first admin and `claimSeedOwnership` re-owns every `owner_id IS NULL` row of every user-authored object. That handoff is the designed completion of a NULL owner column (this file's own seed-identity comment, `app-plugin.ts`, `claim-seed-ownership.ts` and `system-names.ts` all name it), so the write is not the surprise — the log line is. Two branches asserted a bare present-tense `x.owner_id stays NULL` about a column the same boot then filled. Both now read `is NULL at the end of pass 2` and carry a shared scope sentence naming the boot step that can supersede them, and stating that a non-NULL value found later is not evidence that the reference resolved. Level, error count and remedy are unchanged. The two DROPPED branches are deliberately left alone: they report a row that never landed, which no later boot step can write to. Claude-Session: https://claude.ai/code/session_01RuoNSXUbBoWHkNS4AknTrM Co-authored-by: Claude <noreply@anthropic.com>
1 parent 86c5052 commit 07f93e0

6 files changed

Lines changed: 434 additions & 11 deletions
Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,24 @@
1+
---
2+
'@objectstack/metadata-protocol': patch
3+
---
4+
5+
Seed loader: the pass-2 deferred-reference diagnostics now say which moment they describe
6+
7+
`SeedLoaderService` runs inside `AppPlugin.start()`, which the kernel completes for every
8+
plugin before it fires `kernel:ready` — where the first-admin handoff
9+
(`claimSeedOwnership`) re-owns every `owner_id IS NULL` row of every user-authored object.
10+
That handoff is the designed completion of a NULL owner column, so two of the loader's
11+
pass-2 lines — `Deferred reference UNRESOLVED after pass 2` and
12+
`Deferred reference back-fill FAILED` — were making a bare present-tense claim
13+
(`x.owner_id stays NULL`) that the same boot then made false, with nothing in either the
14+
log or the table to tell an operator that the other reading existed.
15+
16+
Both lines now read `is NULL at the end of pass 2` and carry a scope sentence naming the
17+
boot step that can supersede them and stating that a non-NULL value found later is not
18+
evidence the reference resolved. Level, error count and remedy are unchanged — this is a
19+
scope declaration, not a silencing. The two `Deferred reference DROPPED` lines are
20+
deliberately untouched: they report a row that never landed, so no later boot step can
21+
write a column of it and their claim survives to the end of boot as written.
22+
23+
Nothing an author writes changes. Anything that greps the loader's output for the literal
24+
`stays NULL` on these two lines should grep for `is NULL at the end of pass 2` instead.

‎packages/metadata-protocol/src/seed-loader-deferred-failure.test.ts‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -226,9 +226,9 @@ describe('seed deferred back-fill failure is reported, not swallowed (framework#
226226
.find((m: string) => m.includes('audit_department.head_id'));
227227
expect(line, 'the failed back-fill was not reported at error level').toBeDefined();
228228

229-
// The consequence, concretely: which reference stays NULL, and that
230-
// everything else looks fine.
231-
expect(line).toContain('stays NULL');
229+
// The consequence, concretely: which reference is NULL, as of when
230+
// (#17177), and that everything else looks fine.
231+
expect(line).toContain('is NULL at the end of pass 2');
232232
expect(line).toContain('HALF-WRITTEN');
233233
expect(line).toContain('audit_worker.name');
234234
// The fix.
Lines changed: 349 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,349 @@
1+
// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license.
2+
3+
import { describe, it, expect, vi } from 'vitest';
4+
import { SeedLoaderService } from './seed-loader.js';
5+
import type { IDataEngine, IMetadataService } from '@objectstack/spec/contracts';
6+
import {
7+
assertEngineDeleteDispatch,
8+
assertEngineUpdateDispatch,
9+
assertEngineFindOnePredicate,
10+
} from '@objectstack/metadata-core';
11+
12+
/**
13+
* [#17177] The pass-2 summary said `owner_id stays NULL` about 120 rows whose
14+
* `owner_id` was NOT NULL by the time the boot finished.
15+
*
16+
* ## Which side is wrong — answered before anything was edited
17+
*
18+
* The WRITE is the designed behaviour, not the surprise. `seed-loader.ts`'s own
19+
* seed-identity comment says a seeded owner column "simply lands NULL —
20+
* semantically 'owned by whoever becomes the first admin', which the
21+
* first-admin handoff (`claimSeedOwnership`) then fills in"; `app-plugin.ts`,
22+
* `claim-seed-ownership.ts` and `system-names.ts` say the same from their own
23+
* side. So the platform intends that write, performs it on every boot that
24+
* mints an admin, and the LOG LINE is the side that is wrong: it made a bare
25+
* present-tense claim about a column whose value the same boot goes on to
26+
* change.
27+
*
28+
* ## Why the fix is a scope declaration and not a re-read
29+
*
30+
* The loader physically cannot describe the end of boot. Its lines are printed
31+
* inside `AppPlugin.start()`; the kernel runs `start()` for every plugin and
32+
* only then fires `kernel:ready`, where `bootstrapPlatformAdmin` promotes the
33+
* first admin and calls `claimSeedOwnership`. Re-reading the table before
34+
* `load()` returns would therefore read the SAME NULL it just reported — the
35+
* contradicting write has not happened yet. (And an inline seed that overruns
36+
* `OS_INLINE_SEED_BUDGET_MS` finishes on the far side of `kernel:ready`, so the
37+
* two writes are not even in a fixed order to read after.) Declaring the moment
38+
* is the only repair available from inside the loader.
39+
*
40+
* ## What this file pins
41+
*
42+
* The contradiction itself is REPRODUCED here, in one process, in the real
43+
* order: pass 2 reports the reference unresolved, the handoff's predicate write
44+
* lands, the row reads back non-NULL. That reproduction holds before AND after
45+
* the fix — it is the control that proves the scenario is the card's. What
46+
* changes is the sentence the operator is left holding.
47+
*/
48+
49+
const ADMIN_ID = 'usr_dev_admin';
50+
51+
function createLogger() {
52+
return { info: vi.fn(), warn: vi.fn(), error: vi.fn(), debug: vi.fn() };
53+
}
54+
55+
/** `where` matching that treats an absent column as NULL, like a real driver. */
56+
function matches(row: Record<string, unknown>, where: Record<string, unknown>): boolean {
57+
return Object.entries(where).every(([k, v]) => {
58+
if (k.startsWith('$')) throw new Error(`fake driver: unsupported operator ${k}`);
59+
if (v === null) return row[k] === null || row[k] === undefined;
60+
return row[k] === v;
61+
});
62+
}
63+
64+
/**
65+
* A store-backed double. `update` honours BOTH dispatch shapes the real engine
66+
* has (`@objectstack/metadata-core`'s `assertEngineUpdateDispatch` is the
67+
* arbiter): `by-id` for the loader's pass-2 back-fill, `multi` for the
68+
* predicate write the first-admin handoff issues.
69+
*/
70+
function createFaithfulEngine(): { engine: IDataEngine; store: Record<string, any[]> } {
71+
const store: Record<string, any[]> = {};
72+
let idCounter = 0;
73+
74+
const engine = {
75+
find: vi.fn(async (objectName: string, query?: any) => {
76+
let records = store[objectName] || [];
77+
if (query?.where) records = records.filter((r) => matches(r, query.where));
78+
if (typeof query?.limit === 'number') records = records.slice(0, query.limit);
79+
return records;
80+
}),
81+
findOne: vi.fn(async (objectName: string, query?: any) => {
82+
assertEngineFindOnePredicate(objectName, query);
83+
const rows = await (engine.find as any)(objectName, { ...query, limit: 1 });
84+
return rows[0] ?? null;
85+
}),
86+
insert: vi.fn(async (objectName: string, data: any) => {
87+
if (!store[objectName]) store[objectName] = [];
88+
if (Array.isArray(data)) {
89+
const records = data.map((d) => ({ id: `gen-${++idCounter}`, ...d }));
90+
store[objectName].push(...records);
91+
return records;
92+
}
93+
const record = { id: `gen-${++idCounter}`, ...data };
94+
store[objectName].push(record);
95+
return record;
96+
}),
97+
update: vi.fn(async (objectName: string, data: any, options?: any) => {
98+
const dispatch = assertEngineUpdateDispatch(data, options);
99+
const records = store[objectName] || [];
100+
if (dispatch.kind === 'multi') {
101+
const hit = records.filter((r) => matches(r, options?.where ?? {}));
102+
for (const r of hit) Object.assign(r, data);
103+
return { updated: hit.length };
104+
}
105+
const idx = records.findIndex((r) => r.id === dispatch.id);
106+
if (idx >= 0) { records[idx] = { ...records[idx], ...data }; return records[idx]; }
107+
return data;
108+
}),
109+
delete: vi.fn(async (_objectName: string, options?: any) => {
110+
assertEngineDeleteDispatch(options);
111+
return { deleted: 1 };
112+
}),
113+
count: vi.fn(async (objectName: string) => (store[objectName] || []).length),
114+
aggregate: vi.fn(async () => []),
115+
} as unknown as IDataEngine;
116+
117+
return { engine, store };
118+
}
119+
120+
/**
121+
* `claim_contract.owner_id` and `claim_user.contract_id` point at each other,
122+
* which is what forces the loader to defer the reference to pass 2 at all.
123+
*/
124+
function createMetadata(): IMetadataService {
125+
const objects: Record<string, any> = {
126+
claim_contract: {
127+
name: 'claim_contract',
128+
fields: {
129+
name: { type: 'text' },
130+
owner_id: { type: 'lookup', reference: 'claim_user' },
131+
},
132+
},
133+
claim_user: {
134+
name: 'claim_user',
135+
fields: {
136+
name: { type: 'text' },
137+
contract_id: { type: 'lookup', reference: 'claim_contract' },
138+
},
139+
},
140+
};
141+
return {
142+
getObject: vi.fn(async (name: string) => objects[name]),
143+
listObjects: vi.fn(async () => Object.values(objects)),
144+
register: vi.fn(async () => {}),
145+
get: vi.fn(async (_t: string, name: string) => objects[name]),
146+
list: vi.fn(async () => []),
147+
unregister: vi.fn(async () => {}),
148+
exists: vi.fn(async () => false),
149+
listNames: vi.fn(async () => []),
150+
} as unknown as IMetadataService;
151+
}
152+
153+
const CONFIG = {
154+
dryRun: false,
155+
haltOnError: false,
156+
multiPass: true,
157+
defaultMode: 'insert',
158+
batchSize: 1000,
159+
transaction: false,
160+
} as any;
161+
162+
/**
163+
* The later writer, spelled exactly as `claimSeedOwnership` spells it —
164+
* `packages/plugins/plugin-security/src/claim-seed-ownership.ts`, whose
165+
* `io.reown` is
166+
* `ql.update(name, { owner_id: adminUserId }, { where: predicate, multi: true, context: SYSTEM_CTX })`
167+
* over the `owner_id IS NULL` predicate. Reproduced here rather than imported:
168+
* `metadata-protocol` does not depend on `plugin-security` (and must not — the
169+
* dependency runs the other way), so the call shape is copied and the engine
170+
* double above is what holds it honest.
171+
*/
172+
async function claimUnownedRowsForFirstAdmin(engine: IDataEngine, objectName: string) {
173+
return (engine as any).update(
174+
objectName,
175+
{ owner_id: ADMIN_ID },
176+
{ where: { owner_id: null }, multi: true, context: { isSystem: true } },
177+
);
178+
}
179+
180+
const unresolvedLines = (logger: ReturnType<typeof createLogger>) =>
181+
logger.error.mock.calls
182+
.map((c: unknown[]) => String(c[0]))
183+
.filter((m) => m.includes('UNRESOLVED after pass 2'));
184+
185+
describe('[#17177] the pass-2 deferred-reference summary says WHEN it is true', () => {
186+
/**
187+
* The card's boot, reproduced: the loader reports `owner_id` unresolved, the
188+
* first-admin handoff then claims the row, and the table disagrees with a
189+
* bare reading of the line. Steps 1-4 are the control and hold on both sides
190+
* of the fix; step 5 is the repair.
191+
*/
192+
it('reproduces the contradiction and leaves the operator a line that survives it', async () => {
193+
const { engine, store } = createFaithfulEngine();
194+
const logger = createLogger();
195+
196+
// 1. Seed a contract owned by a user this load never creates — the card's
197+
// `clm_contract.owner_id` shape.
198+
const result = await new SeedLoaderService(engine, createMetadata(), logger).load({
199+
seeds: [
200+
{
201+
object: 'claim_contract',
202+
externalId: 'name',
203+
mode: 'insert',
204+
env: ['prod', 'dev', 'test'],
205+
records: [{ name: 'ACME-001', owner_id: 'dev-admin' }],
206+
},
207+
] as any,
208+
config: CONFIG,
209+
});
210+
211+
// 2. The row landed; the reference did not. The line fired, and at the
212+
// moment it fired it was TRUE — which is the whole reason the write, not
213+
// the log, had to be ruled on first.
214+
const row = () => store.claim_contract.find((r) => r.name === 'ACME-001')!;
215+
expect(row(), 'the contract row was not seeded — wrong scenario').toBeDefined();
216+
expect(row().owner_id == null, 'owner_id was already set — nothing to contradict').toBe(true);
217+
const lines = unresolvedLines(logger);
218+
expect(lines.length, 'the pass-2 unresolved diagnostic never fired').toBe(1);
219+
const line = lines[0];
220+
expect(line).toContain('claim_contract.owner_id');
221+
expect(result.errors.some((e) => e.message.includes('unresolved after pass 2'))).toBe(true);
222+
223+
// 3. Boot continues. `kernel:ready` promotes the first admin and
224+
// `claimSeedOwnership` claims every NULL-owned row — by design.
225+
await claimUnownedRowsForFirstAdmin(engine, 'claim_contract');
226+
227+
// 4. THE CONTRADICTION, reproduced: the summary above is still the only
228+
// seed diagnostic an operator has, and the column it reported is no
229+
// longer NULL. Nothing re-ran the loader; nothing recomputed the line.
230+
expect(row().owner_id).toBe(ADMIN_ID);
231+
expect(unresolvedLines(logger).length, 'the summary was recomputed — the card assumes it is not').toBe(1);
232+
233+
// 5. THE REPAIR. The line an operator is holding at the end of boot has to
234+
// survive being read against that table. It does not assert a state it
235+
// cannot vouch for; it says which moment it describes, names the boot
236+
// step that can supersede it, and says what the non-NULL value does NOT
237+
// mean.
238+
expect(line, 'the line still makes a bare, unscoped claim about the column').not.toContain('stays NULL');
239+
expect(line).toContain('is NULL at the end of pass 2');
240+
expect(line).toContain('END OF PASS 2');
241+
expect(line).toContain('first-admin handoff');
242+
expect(line).toContain('not evidence that this reference resolved');
243+
244+
// The repair is a scope declaration, not a silencing: level, count and
245+
// remedy are untouched.
246+
expect(logger.warn).not.toHaveBeenCalled();
247+
expect(result.success).toBe(false);
248+
expect(result.summary.totalErrored).toBe(1);
249+
expect(line).toMatch(/re-run the seed/);
250+
});
251+
252+
/**
253+
* The other branch that names a column and a NULL: the target resolved and
254+
* the back-fill WRITE failed. Same exposure — the row exists, so the handoff
255+
* can claim it — so it carries the same scope.
256+
*/
257+
it('the back-fill-FAILED branch carries the same scope, for the same reason', async () => {
258+
const { engine, store } = createFaithfulEngine();
259+
const logger = createLogger();
260+
const realUpdate = (engine.update as any).getMockImplementation();
261+
(engine.update as any).mockImplementation(async (obj: string, data: any, opts: any) => {
262+
if (obj === 'claim_contract' && !opts?.multi) throw new Error('UPDATE rejected by validation rule');
263+
return realUpdate(obj, data, opts);
264+
});
265+
266+
await new SeedLoaderService(engine, createMetadata(), logger).load({
267+
seeds: [
268+
{
269+
object: 'claim_contract',
270+
externalId: 'name',
271+
mode: 'insert',
272+
env: ['prod', 'dev', 'test'],
273+
records: [{ name: 'ACME-002', owner_id: 'Ada' }],
274+
},
275+
{
276+
object: 'claim_user',
277+
externalId: 'name',
278+
mode: 'insert',
279+
env: ['prod', 'dev', 'test'],
280+
records: [{ name: 'Ada', contract_id: 'ACME-002' }],
281+
},
282+
] as any,
283+
config: CONFIG,
284+
});
285+
286+
const failed = logger.error.mock.calls
287+
.map((c: unknown[]) => String(c[0]))
288+
.find((m) => m.includes('back-fill FAILED'));
289+
expect(failed, 'the back-fill-failure diagnostic never fired').toBeDefined();
290+
expect(failed).not.toContain('stays NULL');
291+
expect(failed).toContain('is NULL at the end of pass 2');
292+
expect(failed).toContain('END OF PASS 2');
293+
// Still carries its own cause — the scope note is additive.
294+
expect(failed).toContain('UPDATE rejected by validation rule');
295+
296+
// And the exposure is real: the row is there for the handoff to claim.
297+
await claimUnownedRowsForFirstAdmin(engine, 'claim_contract');
298+
expect(store.claim_contract.find((r) => r.name === 'ACME-002')!.owner_id).toBe(ADMIN_ID);
299+
});
300+
301+
/**
302+
* NEGATIVE CONTROL — the guard against fixing this by rewording every line
303+
* that says NULL. A DROPPED row never landed, so no later boot step can write
304+
* a column of it: that claim is still true at the end of boot and must NOT be
305+
* hedged. A blanket reword would fail here.
306+
*/
307+
it('a DROPPED row — one that never landed — is NOT hedged: no later writer can reach it', async () => {
308+
const { engine, store } = createFaithfulEngine();
309+
const logger = createLogger();
310+
const realInsert = (engine.insert as any).getMockImplementation();
311+
(engine.insert as any).mockImplementation(async (obj: string, data: any, opts: any) => {
312+
if (obj === 'claim_contract') throw new Error('CHECK constraint failed: claim_contract');
313+
return realInsert(obj, data, opts);
314+
});
315+
316+
await new SeedLoaderService(engine, createMetadata(), logger).load({
317+
seeds: [
318+
{
319+
object: 'claim_contract',
320+
externalId: 'name',
321+
mode: 'insert',
322+
env: ['prod', 'dev', 'test'],
323+
records: [{ name: 'ACME-003', owner_id: 'Ada' }],
324+
},
325+
{
326+
object: 'claim_user',
327+
externalId: 'name',
328+
mode: 'insert',
329+
env: ['prod', 'dev', 'test'],
330+
records: [{ name: 'Ada', contract_id: 'ACME-003' }],
331+
},
332+
] as any,
333+
config: CONFIG,
334+
});
335+
336+
const dropped = logger.error.mock.calls
337+
.map((c: unknown[]) => String(c[0]))
338+
.find((m) => m.includes('Deferred reference DROPPED'));
339+
expect(dropped, 'the drop diagnostic never fired — wrong scenario').toBeDefined();
340+
expect(store.claim_contract ?? [], 'the row landed after all — wrong scenario').toHaveLength(0);
341+
expect(dropped).not.toContain('END OF PASS 2');
342+
expect(dropped).toContain('is never written');
343+
344+
// Proof the asymmetry is the right one: the handoff's predicate write
345+
// matches nothing, because there is no row.
346+
await claimUnownedRowsForFirstAdmin(engine, 'claim_contract');
347+
expect(store.claim_contract ?? []).toHaveLength(0);
348+
});
349+
});

‎packages/metadata-protocol/src/seed-loader-unresolved-drop.test.ts‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -343,8 +343,9 @@ describe('a deferred reference still unresolved after pass 2 is logged too (fram
343343
expect(message).toContain("record 'Platform'");
344344
expect(message).toContain('drop_person.name');
345345
expect(message).toContain('Nobody');
346-
// CONSEQUENCE + REMEDY.
347-
expect(message).toContain('stays NULL');
346+
// CONSEQUENCE + REMEDY — the consequence now carries the moment it is
347+
// true of (#17177: a later boot step can write this column).
348+
expect(message).toContain('is NULL at the end of pass 2');
348349
expect(message).toContain('counter looks healthy');
349350
expect(message).toMatch(/re-run the seed/);
350351
expect(meta).toMatchObject({ object: 'drop_team', field: 'lead_id', recordIndex: 0 });

0 commit comments

Comments
 (0)