Skip to content

Commit 1d29e6d

Browse files
fix(metadata-protocol): seed-loader 中「计为错误」的失败一律记 error,不再自相矛盾地记 warn (#4729) (#5001)
`SeedLoaderService` pass-2 延迟引用回填的 catch 上方写着「this must be a reported, counted error, never a silent warning」,紧跟着的调用却是 `this.logger.warn`。计数是对的(`recordDeferredError` 进 `allErrors` ⇒ `success: false`),但日志级别与它矛盾 —— 而这一行是一次 seed 在宿主控制台上 留下的唯一痕迹,`warn` 正是 #4420 证明没人读的那一级。 - 该行提到 `error`,并按 AGENTS.md「Degradation log levels」补齐一条 error 该有的两件东西:**后果**(`<object>.<field>` 停在 NULL、行本身已种下所以 行计数一切正常、循环关系半写入)与**修复动作**(没有任何东西会重试,修掉 写入错误 —— 超出重试预算的瞬时故障,或某条 validation 规则否决了这次 update —— 之后重跑 seed)。 - 按同一判据(这次失败是否计入 `errors` / 是否让 `success` 变 false)盘完本 文件其余 `logger.warn`:另有五处「计为错误、日志 warn」一并提到 `error` —— 批量插入失败行、`cel` 表达式解析失败被丢弃的记录、两处 DROP 引用字段的非法 引用路径(行落了、关联没落,而行计数干净 —— framework#3932),以及顺序写 与 update 两处 catch。两处 DROP 路径的日志行另补后果与修复动作。 - 三处**维持 warn**并把审计结论写进注释:`Halting on first error`(控制流通知, 它所halt 的错误各自已在 error 级别报过)、`NODE_ENV` 无法判定(功能性、 fail-open 降级)、roll-up summary 重算失败(记录确实写入了;陈旧汇总列是否 属于 #4632 第二类另开 #4998 由维护者定夺)。 - 让门禁而不只是测试钉住这个接缝:回填写入抽成 `writeDeferredReference` (原写入在 `withTransientRetry` 闭包里,AST 扫描进不去),与 `writeRecord` 一同登记进 `scripts/check-durability-degradation-log-level.mjs` 的 `DURABILITY_CRITICAL_CALLEES`,这两处 catch 再被降级即 CI 红。 结果对象、API、schema 均无变化,变的只是级别与措辞。 另记录两处不在本单判据内的同文件发现:#4997(无 pass-2 时整条记录被丢弃却 一行日志都不打)、#4998(roll-up summary 陈旧值不计数、只记 warn)。 Claude-Session: https://claude.ai/code/session_01NrmBxj8rK2uGCnh9aipjwX Co-authored-by: Claude <noreply@anthropic.com>
1 parent 02dc076 commit 1d29e6d

6 files changed

Lines changed: 279 additions & 30 deletions

File tree

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
---
2+
"@objectstack/metadata-protocol": patch
3+
---
4+
5+
fix(metadata-protocol): a seed failure that is COUNTED as an error now logs at `error` (#4729)
6+
7+
`SeedLoaderService`'s pass-2 deferred back-fill carried a comment stating that a
8+
failed back-fill "must be a reported, counted error, **never** a silent warning"
9+
— and the line under it called `logger.warn`. The count was right (the failure
10+
lands in `result.errors`, flips `success: false`) but the level contradicted it,
11+
and that log line is the only trace a seed leaves in a host's console. `warn` is
12+
the level #4420 proved nobody reads.
13+
14+
**What changed**
15+
16+
- The failed back-fill logs at **`error`**, and the line now owes what
17+
AGENTS.md → "Degradation log levels" requires of one: the **consequence**
18+
(`<object>.<field>` stays NULL on a named record, the row itself was seeded so
19+
every row counter reads clean, the circular relationship is half-written) and
20+
the **fix** (nothing retries it — repair the write error, which is either a
21+
transient failure that outlasted the retry budget or a validation rule vetoing
22+
the update, then re-run the seed).
23+
- The rest of the file was audited against the same criterion — *is this failure
24+
counted in the load's `errors` (i.e. does it make `success: false`)?* Five more
25+
sites answered yes while logging `warn`, and were raised to `error`: a failed
26+
batch insert row, a record dropped because its `cel` expression could not
27+
resolve, the two invalid-reference paths that DROP a reference field (the row
28+
lands without its association and the row counters stay clean — framework#3932),
29+
and the two write-failure catches on the sequential/update paths. The two
30+
dropped-reference lines also gained the consequence and fix in the message.
31+
- Deliberately left at `warn`, and now documented as audited: "Halting on first
32+
error" (a control-flow notice about failures already reported at `error`), the
33+
`NODE_ENV` scope warning (a functional, fail-open degradation), and the
34+
roll-up-summary recompute (records *were* written; whether a stale summary
35+
column is the same class is #4998).
36+
- The seam is now pinned by CI, not only by tests: the back-fill write was
37+
extracted as `writeDeferredReference` and added — with `writeRecord` — to
38+
`DURABILITY_CRITICAL_CALLEES` in `scripts/check-durability-degradation-log-level.mjs`,
39+
so `pnpm check:durability-log-level` fails if either catch is ever quietened
40+
again.
41+
42+
No API, schema or result-object change: the same errors are reported in
43+
`SeedLoaderResult` exactly as before. What changed is the level and the wording
44+
of what a seeding host sees in its log.

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

Lines changed: 80 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -186,6 +186,86 @@ describe('seed deferred back-fill failure is reported, not swallowed (framework#
186186
expect(result.errors.some((e: { field: string }) => e.field === 'head_id')).toBe(true);
187187
});
188188

189+
/**
190+
* #4729 — the LOG LEVEL has to agree with the count.
191+
*
192+
* The comment above this catch has always said the failure "must be a
193+
* reported, counted error, never a silent warning", and `recordDeferredError`
194+
* duly counts it — but the call underneath it was `logger.warn`, i.e. the
195+
* level #4420 proved nobody reads, on the ONE line this failure leaves in a
196+
* seed's console output. AGENTS.md → "Degradation log levels" also requires
197+
* that line to carry the consequence and the fix, not just a label.
198+
*/
199+
it('logs the failed back-fill at ERROR, naming object.field, the NULL consequence and the remedy (#4729)', async () => {
200+
const { engine, store } = createFaithfulEngine();
201+
const metadata = createMetadata();
202+
const logger = createLogger();
203+
204+
const realUpdate = (engine.update as any).getMockImplementation();
205+
(engine.update as any).mockImplementation(async (obj: string, data: any, opts: any) => {
206+
if (obj === 'audit_department') throw new Error('UPDATE rejected by validation rule');
207+
return realUpdate(obj, data, opts);
208+
});
209+
210+
const result = await new SeedLoaderService(engine, metadata, logger).load({
211+
seeds: SEEDS,
212+
config: CONFIG,
213+
});
214+
215+
// The reference genuinely did not land.
216+
expect(store.audit_department.find((r) => r.name === 'Engineering')!.head_id == null).toBe(true);
217+
218+
const line = logger.error.mock.calls
219+
.map((c: unknown[]) => String(c[0]))
220+
.find((m: string) => m.includes('audit_department.head_id'));
221+
expect(line, 'the failed back-fill was not reported at error level').toBeDefined();
222+
223+
// The consequence, concretely: which reference stays NULL, and that
224+
// everything else looks fine.
225+
expect(line).toContain('stays NULL');
226+
expect(line).toContain('HALF-WRITTEN');
227+
expect(line).toContain('audit_worker.name');
228+
// The fix.
229+
expect(line).toMatch(/re-run the seed/);
230+
// The cause travels on the same line (a `warn` reader is not owed a second look).
231+
expect(line).toContain('UPDATE rejected by validation rule');
232+
// The structured error object is passed through for the logger's own
233+
// error rendering, per the `Logger` contract's `(message, error, meta)`.
234+
const [, err, meta] = logger.error.mock.calls.find((c: unknown[]) =>
235+
String(c[0]).includes('audit_department.head_id'),
236+
)!;
237+
expect(err).toBeInstanceOf(Error);
238+
expect(meta).toMatchObject({ object: 'audit_department', field: 'head_id' });
239+
240+
// NOT at warn — the level this issue exists to correct.
241+
expect(
242+
logger.warn.mock.calls.some((c: unknown[]) => String(c[0]).includes('deferred reference')),
243+
'the back-fill failure is still being reported at warn',
244+
).toBe(false);
245+
246+
// …and it is still COUNTED, which is what the level now agrees with.
247+
expect(result.success).toBe(false);
248+
expect(result.summary.totalErrored).toBeGreaterThan(0);
249+
expect(result.errors.some((e: { field: string }) => e.field === 'head_id')).toBe(true);
250+
});
251+
252+
it('a back-fill that SUCCEEDS logs nothing loud (#4729 — do not train readers to skim `error`)', async () => {
253+
const { engine, store } = createFaithfulEngine();
254+
const metadata = createMetadata();
255+
const logger = createLogger();
256+
257+
const result = await new SeedLoaderService(engine, metadata, logger).load({
258+
seeds: SEEDS,
259+
config: CONFIG,
260+
});
261+
262+
const aliceId = store.audit_worker.find((r) => r.name === 'Alice')!.id;
263+
expect(store.audit_department.find((r) => r.name === 'Engineering')!.head_id).toBe(aliceId);
264+
expect(result.success).toBe(true);
265+
expect(logger.error).not.toHaveBeenCalled();
266+
expect(logger.warn).not.toHaveBeenCalled();
267+
});
268+
189269
it('a transient blip that recovers on retry still reports clean success', async () => {
190270
const { engine, store } = createFaithfulEngine();
191271
const metadata = createMetadata();

packages/metadata-protocol/src/seed-loader-multi-value-reference.test.ts

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -276,7 +276,14 @@ describe('seed reference resolution — multi-value lookup (multiple: true)', ()
276276
// The unwritable value never reaches the driver; the record still lands.
277277
expect(store.book[0].reviewer).toBeUndefined();
278278
expect(store.book[0].name).toBe('Refactoring');
279-
expect(logger.warn).toHaveBeenCalled();
279+
// #4729: the row landed WITHOUT its association and the row counters stay
280+
// clean, so this is reported at `error` — the one level a reader of the
281+
// console is not trained to skim — and the line says what was lost.
282+
const dropped = logger.error.mock.calls.map((c: any[]) => String(c[0])).find((m: string) => m.includes('reviewer'));
283+
expect(dropped, 'the dropped reference was not reported at error level').toBeDefined();
284+
expect(dropped).toContain('DROPPED');
285+
expect(dropped).toContain('re-run the seed');
286+
expect(logger.warn).not.toHaveBeenCalled();
280287

281288
// framework#3932: the row WAS written, so `errored` stays 0 and the row
282289
// counters all look healthy — the loss only shows up here.

0 commit comments

Comments
 (0)