Skip to content

Commit beefe89

Browse files
os-zhuangclaude
andauthored
fix(metadata): never invent an event_seq from a read that failed (#4825) (#4872)
`DatabaseLoader.nextEventSeq()` folded every failure of its `sys_metadata_history` read into one answer: } catch { // Table not provisioned yet or driver error — start at 1. return 1; } The comment named BOTH reasons and then answered both the same way. Only one is benign. With N rows already in the table, a flaky read (connection drop, timeout, privileges) handed the next history row `event_seq = 1`, colliding with an existing row — while the insert SUCCEEDED and nothing was logged. `event_seq` is the ordering key that history listing and rollback targeting both stand on, so the timeline is silently wrong from then on, and neither a retry nor a restart repairs it. This is the #4728 shape one layer down, but the costlier half: not bytes that never landed, but bytes that landed wrong. Discriminate by error TYPE, reusing #4728's machinery rather than starting a second classifier in the same package. `schema-sync-errors.ts` now holds ONE matcher (code -> errno -> message -> `cause` chain) with two vocabularies; `isSchemaAlreadyExistsError` keeps its exact signature and behaviour, and `isMissingTableError` joins it. They are not each other's negation: both ask "is this the one benign reason?" and default to not-benign, so an unrecognised error is loud under both. - benign "table not provisioned" (SQLite `no such table`, PG `42P01` / `relation "x" does not exist`, MySQL `ER_NO_SUCH_TABLE` / errno 1146) -> return 1; there are no rows, so nothing can collide. - everything else -> rethrow. `createHistoryRecord()` reports at `error` (consequence, why a hole beats a wrong number, the fix) and SKIPS the history row. Classification stays narrow on purpose: a bare `does not exist` also covers role/database/column, all real failures against a table that may be full of rows, so the message test requires table/relation alongside. Two boundaries deliberately unchanged: the metadata write itself does not fail (the record already landed; reporting it failed would be a worse lie than the bug), and this path's known non-transactional concurrency race stays a documented limitation — a read failure is a different thing. Reported once, with an `info` on recovery. Tests pin the VALUE that lands, not just whether a write happened: with rows 1 and 2 present, a failed read leaves [1, 2] rather than [1, 2, 1]. Both directions plus a same-call-site/opposite-verdict case, so neither a `() => true` classifier nor the old `return 1` could pass. Claude-Session: https://claude.ai/code/session_015Br2xsJsczFsTR9bvbh2Ny Co-authored-by: Claude <noreply@anthropic.com>
1 parent 5046afe commit beefe89

5 files changed

Lines changed: 612 additions & 45 deletions

File tree

Lines changed: 43 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,43 @@
1+
---
2+
"@objectstack/metadata": patch
3+
---
4+
5+
fix(metadata): 历史序号 `event_seq` 不再从一次失败的读里凭空发号 —— 只有「表还没建」可以从 1 开始 (#4825)
6+
7+
`DatabaseLoader.nextEventSeq()` 过去把读 `sys_metadata_history`**全部**失败折成同一个答案:
8+
9+
```ts
10+
} catch {
11+
// Table not provisioned yet or driver error — start at 1.
12+
return 1;
13+
}
14+
```
15+
16+
注释同时点名了两种原因,然后用同一个 `return 1` 对待。这是 #4728 刚修掉的同一种形状,但危害是
17+
**更贵的那一半**:#4728 是「字节没落盘」,本条是「**落盘的字节是错的**」。历史表里已经有 N 行时,
18+
一次瞬时读失败(连接抖动、超时、权限)会让下一条历史拿到 `event_seq = 1`,与既有行**直接撞号**,
19+
而 insert **成功**、日志**一行没有**`event_seq` 正是历史列表排序与 rollback 定位的依据,撞号之后
20+
版本顺序就永久不可信 —— 重试不修、重启也不修。
21+
22+
现在按**错误类型**判别,复用 #4728 落地的那套判别机制(`packages/metadata/src/utils/schema-sync-errors.ts`
23+
里新增的 `isMissingTableError()` 与既有 `isSchemaAlreadyExistsError()` 共用同一个 code / errno /
24+
message + `cause` 链匹配器,而不是在同一个包里另起一套错误判别):
25+
26+
- **良性的「表还没建」**(SQLite `no such table: …`、Postgres SQLSTATE `42P01` /
27+
`relation "…" does not exist`、MySQL `ER_NO_SUCH_TABLE` / errno `1146`,并跟随 `cause` 链)——
28+
没有行,就没有可撞的号,`1` 确实是下一个号,静默返回。
29+
- **其余一切读失败** —— `nextEventSeq()` 原样抛出。调用方 `createHistoryRecord()`
30+
`console.error` 上报**后果**(该条历史记录未写入;元数据写入本身已成功,所以服务器仍报告健康,
31+
而变更历史正在悄悄出现空洞,版本时间线与 rollback 目标将不完整)、**为什么是空洞而不是错号**
32+
(从 1 发号会与既有行撞号,把「不完整」变成「顺序错误」,后者无人能发现)与**修复动作**,
33+
然后**跳过这条历史记录**
34+
- 判别的方向刻意保守:凡是没有被正面识别为「表不存在」的,一律当作真实失败。`does not exist`
35+
本身不够 —— `role "…" does not exist``database "…" does not exist``column "…" does not exist`
36+
都是真实失败,对着一张可能满是行的表返回 1 正是要避免的事,所以消息匹配要求 table/relation 与
37+
该短语同现。
38+
39+
两条边界保持不变:元数据写入本身****因此失败(记录已经落盘,把它报成失败是比原缺陷更糟的谎),
40+
以及本路径已知的并发撞号限制(非事务,canonical producer 仍是 `SysMetadataRepository`)——那是被
41+
记录过的限制,与「读失败静默重置到 1」是两回事。报告只说**一次**,恢复时补一条 `info`
42+
43+
无 API / schema 变更;新增内部工具 `isMissingTableError()`(未从包入口导出)。

packages/metadata/src/loaders/database-loader.test.ts

Lines changed: 195 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -641,6 +641,201 @@ describe('DatabaseLoader schema-sync failure reporting (#4728)', () => {
641641
});
642642
});
643643

644+
// ---------- event_seq is never invented from a read that failed ----------
645+
646+
/**
647+
* #4825 (same family as #4728, rule: #4632).
648+
*
649+
* `nextEventSeq()` used to `catch { return 1 }`, with a comment naming BOTH
650+
* "table not provisioned yet" (benign) and "driver error" (not benign). With N
651+
* rows already in `sys_metadata_history`, one flaky read therefore handed the
652+
* next row `event_seq = 1` — colliding with an existing row while the insert
653+
* SUCCEEDED and nothing was logged.
654+
*
655+
* That is why these tests assert on the VALUE that lands, not merely on whether
656+
* a write happened: the damage here is not a missing row, it is a written row
657+
* carrying a wrong number, which no retry and no restart repairs.
658+
*
659+
* Both directions are pinned, plus a same-call-site/opposite-verdict case — a
660+
* suite proving only the loud half would pass on a `() => true` classifier,
661+
* which is the bug, and one proving only the benign half would pass on the
662+
* `catch { return 1 }` being replaced.
663+
*/
664+
describe('DatabaseLoader event_seq on a failed history read (#4825)', () => {
665+
let errorSpy: ReturnType<typeof vi.spyOn>;
666+
let infoSpy: ReturnType<typeof vi.spyOn>;
667+
668+
/** Benign: nothing has been provisioned, so there is no row to collide with. */
669+
const noSuchTable = () =>
670+
Object.assign(new Error('no such table: sys_metadata_history'), { code: 'SQLITE_ERROR' });
671+
672+
/** NOT benign: the rows are still there, this read just did not see them. */
673+
const connectionReset = () =>
674+
Object.assign(new Error('read ECONNRESET'), { code: 'ECONNRESET' });
675+
676+
/** Every `event_seq` this driver was asked to persist, in order. */
677+
function historySeqsWritten(driver: IDataDriver): unknown[] {
678+
const calls = (driver.create as ReturnType<typeof vi.fn>).mock.calls as unknown[][];
679+
return calls
680+
.filter((call: unknown[]) => call[0] === 'sys_metadata_history')
681+
.map((call: unknown[]) => (call[1] as Record<string, unknown>).event_seq);
682+
}
683+
684+
/** The mock driver's own `find`, still callable after we wrap it. */
685+
type DriverFind = (table: string, query: unknown) => Promise<Record<string, unknown>[]>;
686+
687+
/**
688+
* A driver whose reads of the HISTORY table fail while `broken` — writes and
689+
* the `sys_metadata` table keep working throughout, which is exactly what
690+
* makes the defect invisible in production.
691+
*/
692+
function driverWithBreakableHistoryReads(makeError: () => unknown, startBroken = false) {
693+
const driver = createMockDriver();
694+
const realFind = driver.find as DriverFind;
695+
let broken = startBroken;
696+
driver.find = vi.fn().mockImplementation((table: string, query: unknown) => {
697+
if (broken && table === 'sys_metadata_history') return Promise.reject(makeError());
698+
return realFind(table, query);
699+
});
700+
return {
701+
driver,
702+
breakReads: () => {
703+
broken = true;
704+
},
705+
healReads: () => {
706+
broken = false;
707+
},
708+
};
709+
}
710+
711+
beforeEach(() => {
712+
errorSpy = vi.spyOn(console, 'error').mockImplementation(() => {});
713+
infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {});
714+
});
715+
716+
afterEach(() => {
717+
errorSpy.mockRestore();
718+
infoSpy.mockRestore();
719+
});
720+
721+
describe('the benign case — the history table is not provisioned yet', () => {
722+
it('numbers from 1 and stays silent', async () => {
723+
const { driver } = driverWithBreakableHistoryReads(noSuchTable, true);
724+
const loader = new DatabaseLoader({ driver });
725+
726+
await loader.save('object', 'account', { name: 'account' });
727+
728+
expect(historySeqsWritten(driver)).toEqual([1]);
729+
expect(errorSpy).not.toHaveBeenCalled();
730+
expect(infoSpy).not.toHaveBeenCalled();
731+
});
732+
});
733+
734+
describe('a REAL read failure against a table that already has rows', () => {
735+
it('does NOT restart at 1 — no colliding row is written at all', async () => {
736+
const { driver, breakReads } = driverWithBreakableHistoryReads(connectionReset);
737+
const loader = new DatabaseLoader({ driver });
738+
739+
// Build real history first: two rows, event_seq 1 and 2.
740+
await loader.save('object', 'account', { name: 'account' });
741+
await loader.save('object', 'contact', { name: 'contact' });
742+
expect(historySeqsWritten(driver)).toEqual([1, 2]);
743+
744+
breakReads();
745+
await loader.save('object', 'lead', { name: 'lead' });
746+
747+
// Before #4825 this was [1, 2, 1] — a duplicate `event_seq` written
748+
// successfully, silently, over the top of an existing row's number.
749+
expect(historySeqsWritten(driver)).toEqual([1, 2]);
750+
});
751+
752+
it('reports at error, naming the consequence, the deliberate skip, and the fix', async () => {
753+
const { driver, breakReads } = driverWithBreakableHistoryReads(connectionReset);
754+
const loader = new DatabaseLoader({ driver });
755+
756+
await loader.save('object', 'account', { name: 'account' });
757+
breakReads();
758+
await loader.save('object', 'lead', { name: 'lead' });
759+
760+
expect(errorSpy).toHaveBeenCalledTimes(1);
761+
const [message, cause] = errorSpy.mock.calls[0] as [string, unknown];
762+
expect(message).toContain('sys_metadata_history');
763+
expect(message).toContain('event_seq');
764+
// consequence: the row is gone AND the system keeps looking fine
765+
expect(message).toMatch(/NOT written/);
766+
expect(message).toMatch(/SUCCEEDED/);
767+
expect(message).toMatch(/looking healthy/i);
768+
// why a hole is preferable to a wrong number
769+
expect(message).toMatch(/collide/i);
770+
// fix
771+
expect(message).toMatch(/fix the datasource\/driver error/i);
772+
// and the driver error is carried, not discarded
773+
expect((cause as Error).message).toBe('read ECONNRESET');
774+
});
775+
776+
it('does not fail the metadata write it accompanies', async () => {
777+
const { driver, breakReads } = driverWithBreakableHistoryReads(connectionReset);
778+
const loader = new DatabaseLoader({ driver });
779+
780+
breakReads();
781+
const result = await loader.save('object', 'account', { name: 'account' });
782+
783+
// The record write already happened; reporting it as failed would be a
784+
// worse lie than the one being fixed. The history hole is what is loud.
785+
expect(result.success).toBe(true);
786+
expect((await loader.load('object', 'account')).data).toEqual({ name: 'account' });
787+
});
788+
789+
it('says it once, not once per skipped entry, and reports recovery', async () => {
790+
const { driver, breakReads, healReads } = driverWithBreakableHistoryReads(connectionReset);
791+
const loader = new DatabaseLoader({ driver });
792+
793+
await loader.save('object', 'account', { name: 'account' });
794+
breakReads();
795+
await loader.save('object', 'contact', { name: 'contact' });
796+
await loader.save('object', 'lead', { name: 'lead' });
797+
expect(errorSpy).toHaveBeenCalledTimes(1);
798+
799+
healReads();
800+
await loader.save('object', 'deal', { name: 'deal' });
801+
802+
expect(errorSpy).toHaveBeenCalledTimes(1);
803+
expect(infoSpy).toHaveBeenCalledTimes(1);
804+
expect((infoSpy.mock.calls[0] as [string])[0]).toMatch(/readable again/i);
805+
// Numbering resumes after the surviving max (1), never from 1 again.
806+
expect(historySeqsWritten(driver)).toEqual([1, 2]);
807+
});
808+
});
809+
810+
it('DISTINGUISHES the two: same call site, opposite verdicts', async () => {
811+
const { driver: benignDriver } = driverWithBreakableHistoryReads(noSuchTable, true);
812+
const { driver: realDriver } = driverWithBreakableHistoryReads(connectionReset, true);
813+
814+
await new DatabaseLoader({ driver: benignDriver }).save('object', 'account', { name: 'a' });
815+
await new DatabaseLoader({ driver: realDriver }).save('object', 'account', { name: 'a' });
816+
817+
// Benign: numbered, written, silent. Real: not numbered, not written, loud.
818+
expect(historySeqsWritten(benignDriver)).toEqual([1]);
819+
expect(historySeqsWritten(realDriver)).toEqual([]);
820+
expect(errorSpy).toHaveBeenCalledTimes(1);
821+
});
822+
823+
it('applies to the rollback history path too, not just save()', async () => {
824+
const { driver, breakReads } = driverWithBreakableHistoryReads(connectionReset);
825+
const loader = new DatabaseLoader({ driver });
826+
827+
await loader.save('object', 'account', { name: 'account' });
828+
await loader.save('object', 'account', { name: 'account', label: 'Account' });
829+
expect(historySeqsWritten(driver)).toEqual([1, 2]);
830+
831+
breakReads();
832+
await loader.registerRollback('object', 'account', { name: 'account' }, 1);
833+
834+
expect(historySeqsWritten(driver)).toEqual([1, 2]);
835+
expect(errorSpy).toHaveBeenCalledTimes(1);
836+
});
837+
});
838+
644839
// ---------- DatabaseLoader read-through cache ----------
645840

646841
describe('DatabaseLoader read-through cache', () => {

packages/metadata/src/loaders/database-loader.ts

Lines changed: 65 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -26,7 +26,7 @@ import type { IDataDriver, IDataEngine } from '@objectstack/spec/contracts';
2626
import type { MetadataLoader } from './loader-interface.js';
2727
import { calculateChecksum } from '../utils/metadata-history-utils.js';
2828
import { LRUCache } from '../utils/lru-cache.js';
29-
import { isSchemaAlreadyExistsError } from '../utils/schema-sync-errors.js';
29+
import { isMissingTableError, isSchemaAlreadyExistsError } from '../utils/schema-sync-errors.js';
3030
import { addSysMetadataOverlayIndex } from '../migrations/add-sys-metadata-overlay-index.js';
3131
import { migrateProjectIdToEnvironmentId } from '../migrations/migrate-project-id-to-environment-id.js';
3232

@@ -131,6 +131,12 @@ export class DatabaseLoader implements MetadataLoader {
131131
*/
132132
private schemaFailureReported = false;
133133
private historySchemaFailureReported = false;
134+
/**
135+
* Same once-only discipline for the #4825 seam: the history table is readable
136+
* or it is not, and repeating the report per skipped write turns a real
137+
* degradation into noise people learn to skim.
138+
*/
139+
private historySeqFailureReported = false;
134140

135141
/** (type, name) → metadata payload — primes `load()` */
136142
private readonly loadCache?: LRUCache<string, Record<string, unknown> | null>;
@@ -267,6 +273,24 @@ export class DatabaseLoader implements MetadataLoader {
267273
* Reads `MAX(event_seq) + 1` for the configured `organization_id`.
268274
* Legacy path — not transactional, so concurrent writes can collide.
269275
* The canonical (transactional) producer is `SysMetadataRepository`.
276+
*
277+
* #4825 (same shape as #4728, rule from #4632) — discriminate by error TYPE.
278+
* This used to `catch { return 1 }`, with a comment that named BOTH reasons a
279+
* read can fail and then answered both the same way. Exactly one of them is
280+
* benign: the history table has not been provisioned, so there is no row to
281+
* be inconsistent with and 1 genuinely IS the next number. Every other reason
282+
* — connection drop, timeout, insufficient privileges — means the rows are
283+
* still there and simply were not seen, and answering 1 against a table with
284+
* N rows **collides with existing rows**: the insert succeeds, the log stays
285+
* empty, and `event_seq` (the ordering key that history listing and rollback
286+
* targeting both stand on) is silently wrong from then on. Note this is the
287+
* costlier half of the #4728 family — not bytes that never landed, but bytes
288+
* that landed *wrong*, which no retry and no restart repairs.
289+
*
290+
* @throws The underlying driver error, unchanged, for every non-benign read
291+
* failure. Deliberate: a sequence number this method cannot derive
292+
* from data it actually read is not a number it may invent. The
293+
* caller ({@link createHistoryRecord}) owns the consequence.
270294
*/
271295
private async nextEventSeq(): Promise<number> {
272296
const where: Record<string, unknown> = this.organizationId
@@ -280,9 +304,11 @@ export class DatabaseLoader implements MetadataLoader {
280304
if (v > max) max = v;
281305
}
282306
return max + 1;
283-
} catch {
284-
// Table not provisioned yet or driver error — start at 1.
285-
return 1;
307+
} catch (error) {
308+
// Benign — and ONLY benign: there is no table, therefore no row, so
309+
// numbering from 1 cannot collide with anything.
310+
if (isMissingTableError(error)) return 1;
311+
throw error;
286312
}
287313
}
288314

@@ -493,7 +519,41 @@ export class DatabaseLoader implements MetadataLoader {
493519
// transaction, so concurrent writers can collide. The SysMetadataRepository
494520
// path serializes this under engine.transaction(); DatabaseLoader is
495521
// deprecated for new writes and tolerates the race.
496-
const eventSeq = await this.nextEventSeq();
522+
//
523+
// #4825: the concurrency race above is a KNOWN, recorded limitation of this
524+
// path. A read failure is not the same thing and is not tolerated — if the
525+
// sequence cannot be derived from rows we actually read, we write NO history
526+
// row rather than one carrying a number we made up. A missing row is loud
527+
// here and visibly absent later; a colliding row is silent now and corrupts
528+
// the ordering that `queryHistory` and `rollback` both depend on, forever.
529+
let eventSeq: number;
530+
try {
531+
eventSeq = await this.nextEventSeq();
532+
} catch (error) {
533+
if (!this.historySeqFailureReported) {
534+
this.historySeqFailureReported = true;
535+
console.error(
536+
`[Metadata] Could not read \`${this.historyTableName}\` to determine the next \`event_seq\` — the history ` +
537+
`entry for ${type}/${name} was NOT written, and further entries are being skipped while this persists. ` +
538+
`The metadata write itself SUCCEEDED, so the server keeps looking healthy while its change history ` +
539+
`silently develops holes: version timelines and rollback targets will be incomplete. The entry is skipped ` +
540+
`deliberately — numbering it from 1 (what this code did before #4825) would collide with existing rows and ` +
541+
`make \`event_seq\` ordering wrong rather than merely incomplete, which nothing detects and no restart ` +
542+
`repairs. Fix the datasource/driver error below (connection, timeout, privileges); the next metadata write ` +
543+
`retries and reports recovery.`,
544+
error,
545+
);
546+
}
547+
return;
548+
}
549+
550+
if (this.historySeqFailureReported) {
551+
this.historySeqFailureReported = false;
552+
console.info(
553+
`[Metadata] \`${this.historyTableName}\` is readable again — \`event_seq\` numbering recovered and change ` +
554+
`history is being recorded again. Entries skipped during the outage are not backfilled.`,
555+
);
556+
}
497557

498558
const historyRecord: Partial<MetadataHistoryRecord> = {
499559
id: historyId,

0 commit comments

Comments
 (0)