fix(metadata): sys_metadata 的 DDL 失败必须响亮,只静默「表已存在」一种 (#4728)

.changeset/database-loader-ddl-failure-loud.md

@@ -0,0 +1,40 @@
+---
+"@objectstack/metadata": patch
+---
+
+fix(metadata): `sys_metadata` 的 DDL 失败不再被静默吞掉 —— 只有「表已存在」这一种原因可以静音 (#4728)
+
+`DatabaseLoader.ensureSchema()` 过去用一个空 `catch` 吞掉 **全部** DDL 失败,并且照样把
+`schemaReady` 置为 `true`:
+
+```ts
+} catch {
+  // If syncSchema fails (e.g. table already exists), mark ready and continue
+  this.schemaReady = true;
+}
+```
+
+注释里的免责理由只覆盖了失败原因中最良性的一种,却用它为**所有**原因开脱。真实的失败
+(权限不足、数据源根本没连上、列类型冲突)之后,表或新列压根不存在,而进程的状态与成功
+路径**逐字节相同**,启动日志里一行痕迹都没有 —— 这正是 #4420 的形态:声称已持久化、实
+际没落盘、系统看起来完全健康。#4632 把它定成规则(AGENTS.md → "Degradation log levels"),
+机械检查 `pnpm check:durability-log-level` 已经能发现这一处。
+
+现在按**错误类型**判别,而不是按注释里的乐观假设:
+
+- **良性的「已存在」**(SQLite 的 `table … already exists` / `duplicate column name`、
+  Postgres 的 SQLSTATE `42P07`/`42701`/`42710`、MySQL 的 `ER_TABLE_EXISTS_ERROR` 等及其
+  `errno`,并跟随 `cause` 链)—— 表确实已就绪,当作 no-op 静默通过,并照常执行后续的
+  `project_id → environment_id` 迁移与 ADR-0005 索引。
+- **其余一切失败** —— 以 `console.error` 上报,文案同时说清**后果**(`sys_metadata` 的表/
+  列未创建,后续每一次元数据写入都会报错、或在宽松驱动上悄悄丢列,而服务器仍报告健康)
+  与**修复动作**(修掉下面那条驱动/数据源错误后重启)。只说**一次**,不是每次写入都刷屏。
+- `schemaReady` **不再**在真实失败后置 `true`。启动依旧不被阻断(该方法不抛),但 loader
+  不再声称一个它并不具备的就绪状态,下一次元数据操作会重试 —— 数据源只是还在连接这类瞬
+  时故障因此可以自愈,恢复时补一条 `info`。
+
+`ensureHistorySchema()` 按同一规则对齐:良性「已存在」不再每次写入都打一条 `error`(过度
+使用 `error` 是镜像失败),真实失败则同样只响亮一次并保持重试。
+
+无 API / schema 变更;新增内部工具 `isSchemaAlreadyExistsError()`(未从包入口导出)。
+`scripts/durability-degradation.baseline.json` 中指向本单的条目随之删除(该文件 shrink-only)。

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

@@ -1,6 +1,6 @@
 // Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license.
 
-import { describe, it, expect, vi, beforeEach } from 'vitest';
+import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest';
 import { DatabaseLoader, type DatabaseLoaderOptions } from './database-loader';
 import type { IDataDriver } from '@objectstack/spec/contracts';
 import { MetadataManager } from '../metadata-manager';
@@ -433,6 +433,214 @@ describe('DatabaseLoader', () => {
   });
 });
 
+// ---------- DDL failure is loud, and only "already exists" is silent ----------
+
+/**
+ * #4728 (rule: #4632, accident: #4420).
+ *
+ * `ensureSchema()` used to `catch {}` every DDL failure and set
+ * `schemaReady = true` regardless — a total durability failure was byte-for-byte
+ * indistinguishable from success, with no log line at all. The comment excused
+ * *all* failure reasons with the most benign one ("e.g. table already exists").
+ *
+ * Both directions are pinned here on purpose: proving the real failure is loud
+ * is not enough, because "always log error" would pass that alone while making
+ * the benign case unreadable noise. The point is that the two are DISTINGUISHED.
+ */
+describe('DatabaseLoader schema-sync failure reporting (#4728)', () => {
+  let errorSpy: ReturnType<typeof vi.spyOn>;
+  let infoSpy: ReturnType<typeof vi.spyOn>;
+
+  /** A real DDL failure: the table does NOT exist afterwards. */
+  const permissionDenied = () =>
+    Object.assign(new Error('permission denied for schema public'), { code: '42501' });
+
+  /** The one benign reason: the table IS already provisioned. */
+  const alreadyExists = () =>
+    Object.assign(new Error('table sys_metadata already exists'), { code: 'SQLITE_ERROR' });
+
+  beforeEach(() => {
+    errorSpy = vi.spyOn(console, 'error').mockImplementation(() => {});
+    infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {});
+  });
+
+  afterEach(() => {
+    errorSpy.mockRestore();
+    infoSpy.mockRestore();
+  });
+
+  describe('a REAL DDL failure', () => {
+    it('reports at error, naming the consequence and the fix', async () => {
+      const driver = createMockDriver();
+      driver.syncSchema = vi.fn().mockRejectedValue(permissionDenied());
+      const loader = new DatabaseLoader({ driver });
+
+      await loader.list('object');
+
+      expect(errorSpy).toHaveBeenCalledTimes(1);
+      const [message, cause] = errorSpy.mock.calls[0] as [string, unknown];
+      // consequence
+      expect(message).toContain('sys_metadata');
+      expect(message).toContain('FAILED');
+      expect(message).toContain('NOT created');
+      // the system keeps looking healthy — that is the whole point of the level
+      expect(message).toMatch(/reporting healthy/i);
+      // fix
+      expect(message).toMatch(/fix it and restart/i);
+      // and the underlying driver error is carried, not discarded
+      expect((cause as Error).message).toBe('permission denied for schema public');
+    });
+
+    it('does NOT mark the schema ready — the next operation retries the DDL', async () => {
+      const driver = createMockDriver();
+      driver.syncSchema = vi.fn().mockRejectedValue(permissionDenied());
+      const loader = new DatabaseLoader({ driver });
+
+      await loader.list('object');
+      await loader.list('view');
+      await loader.exists('object', 'account');
+
+      // Before #4728 this was 1: the failure set `schemaReady = true` and every
+      // later write proceeded against a table that was never created.
+      expect(driver.syncSchema).toHaveBeenCalledTimes(3);
+    });
+
+    it('says it once, not once per operation', async () => {
+      const driver = createMockDriver();
+      driver.syncSchema = vi.fn().mockRejectedValue(permissionDenied());
+      const loader = new DatabaseLoader({ driver });
+
+      await loader.list('object');
+      await loader.list('view');
+      await loader.list('flow');
+
+      expect(errorSpy).toHaveBeenCalledTimes(1);
+    });
+
+    it('recovers silently-loudly: a transient failure that heals reports the recovery', async () => {
+      const driver = createMockDriver();
+      driver.syncSchema = vi
+        .fn()
+        .mockRejectedValueOnce(
+          Object.assign(new Error('connect ECONNREFUSED 127.0.0.1:5432'), {
+            code: 'ECONNREFUSED',
+          }),
+        )
+        .mockResolvedValue(undefined);
+      const loader = new DatabaseLoader({ driver });
+
+      await loader.list('object'); // datasource still connecting → loud
+      await loader.list('view'); // retried → succeeds
+
+      expect(errorSpy).toHaveBeenCalledTimes(1);
+      expect(infoSpy).toHaveBeenCalledTimes(1);
+      expect((infoSpy.mock.calls[0] as [string])[0]).toMatch(/succeeded on retry/i);
+
+      // Ready now, so a third operation does not re-run the DDL.
+      await loader.list('flow');
+      expect(driver.syncSchema).toHaveBeenCalledTimes(2);
+    });
+  });
+
+  describe('the benign "already exists" failure', () => {
+    it('is silent — no error, no info', async () => {
+      const driver = createMockDriver();
+      driver.syncSchema = vi.fn().mockRejectedValue(alreadyExists());
+      const loader = new DatabaseLoader({ driver });
+
+      await loader.list('object');
+
+      expect(errorSpy).not.toHaveBeenCalled();
+      expect(infoSpy).not.toHaveBeenCalled();
+    });
+
+    it('marks the schema ready — the table is provisioned, so no retry', async () => {
+      const driver = createMockDriver();
+      driver.syncSchema = vi.fn().mockRejectedValue(alreadyExists());
+      const loader = new DatabaseLoader({ driver });
+
+      await loader.list('object');
+      await loader.list('view');
+
+      expect(driver.syncSchema).toHaveBeenCalledTimes(1);
+    });
+
+    it('still runs the post-sync migrations (the table exists, so they apply)', async () => {
+      const driver = createMockDriver();
+      driver.syncSchema = vi.fn().mockRejectedValue(alreadyExists());
+      const raw = vi.fn().mockResolvedValue(undefined);
+      (driver as unknown as { raw: unknown }).raw = raw;
+      const loader = new DatabaseLoader({ driver });
+
+      await loader.list('object');
+
+      expect(raw).toHaveBeenCalled();
+      expect(raw.mock.calls.some(([sql]) => String(sql).includes('idx_sys_metadata_overlay_active'))).toBe(
+        true,
+      );
+    });
+  });
+
+  it('DISTINGUISHES the two: same call site, opposite verdicts', async () => {
+    const benignDriver = createMockDriver();
+    benignDriver.syncSchema = vi.fn().mockRejectedValue(alreadyExists());
+    const realDriver = createMockDriver();
+    realDriver.syncSchema = vi.fn().mockRejectedValue(permissionDenied());
+
+    await new DatabaseLoader({ driver: benignDriver }).list('object');
+    const afterBenign = errorSpy.mock.calls.length;
+
+    await new DatabaseLoader({ driver: realDriver }).list('object');
+    const afterReal = errorSpy.mock.calls.length;
+
+    expect(afterBenign).toBe(0);
+    expect(afterReal).toBe(1);
+  });
+
+  describe('the history table follows the same rule', () => {
+    /** sys_metadata syncs fine; only the history table's DDL fails. */
+    function driverWithFailingHistoryDdl(error: unknown): IDataDriver {
+      const driver = createMockDriver();
+      driver.syncSchema = vi.fn().mockImplementation((table: string) => {
+        if (table === 'sys_metadata_history') return Promise.reject(error);
+        return Promise.resolve(undefined);
+      });
+      return driver;
+    }
+
+    it('reports a real failure at error, naming the lost audit trail and the fix', async () => {
+      const driver = driverWithFailingHistoryDdl(permissionDenied());
+      const loader = new DatabaseLoader({ driver });
+
+      await loader.save('object', 'account', { name: 'account' });
+
+      expect(errorSpy).toHaveBeenCalledTimes(1);
+      const message = (errorSpy.mock.calls[0] as [string])[0];
+      expect(message).toContain('sys_metadata_history');
+      expect(message).toMatch(/will NOT be persisted/);
+      expect(message).toMatch(/restart/i);
+    });
+
+    it('is silent on "already exists" and stops retrying', async () => {
+      const driver = driverWithFailingHistoryDdl(
+        Object.assign(new Error("Table 'sys_metadata_history' already exists"), {
+          code: 'ER_TABLE_EXISTS_ERROR',
+        }),
+      );
+      const loader = new DatabaseLoader({ driver });
+
+      await loader.save('object', 'account', { name: 'account' });
+      await loader.save('object', 'contact', { name: 'contact' });
+
+      expect(errorSpy).not.toHaveBeenCalled();
+      const historySyncs = (driver.syncSchema as ReturnType<typeof vi.fn>).mock.calls.filter(
+        ([table]) => table === 'sys_metadata_history',
+      );
+      expect(historySyncs).toHaveLength(1);
+    });
+  });
+});
+
 // ---------- DatabaseLoader read-through cache ----------
 
 describe('DatabaseLoader read-through cache', () => {

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

@@ -26,6 +26,7 @@ import type { IDataDriver, IDataEngine } from '@objectstack/spec/contracts';
 import type { MetadataLoader } from './loader-interface.js';
 import { calculateChecksum } from '../utils/metadata-history-utils.js';
 import { LRUCache } from '../utils/lru-cache.js';
+import { isSchemaAlreadyExistsError } from '../utils/schema-sync-errors.js';
 import { addSysMetadataOverlayIndex } from '../migrations/add-sys-metadata-overlay-index.js';
 import { migrateProjectIdToEnvironmentId } from '../migrations/migrate-project-id-to-environment-id.js';
 
@@ -123,6 +124,13 @@ export class DatabaseLoader implements MetadataLoader {
   private trackHistory: boolean;
   private schemaReady = false;
   private historySchemaReady = false;
+  /**
+   * Whether the loud "DDL failed" report has already been printed for the
+   * metadata table / history table respectively. AGENTS.md → "Degradation log
+   * levels": say it **once**, at the first degradation, not once per retry.
+   */
+  private schemaFailureReported = false;
+  private historySchemaFailureReported = false;
 
   /** (type, name) → metadata payload — primes `load()` */
   private readonly loadCache?: LRUCache<string, Record<string, unknown> | null>;
@@ -321,22 +329,59 @@ export class DatabaseLoader implements MetadataLoader {
         ...SysMetadataObject,
         name: this.tableName,
       });
-      this.schemaReady = true;
-      // v5.0 forward migration: project_id → environment_id (idempotent).
-      try {
-        await migrateProjectIdToEnvironmentId(this.driver!);
-      } catch {
-        // ignore — migration is best-effort on bootstrap
-      }
-      // Apply ADR-0005 partial UNIQUE INDEX (best-effort, idempotent)
-      try {
-        await addSysMetadataOverlayIndex(this.driver!);
-      } catch {
-        // ignore — index is optimization
+    } catch (error) {
+      // #4728 (rule: #4632, accident: #4420) — discriminate by error TYPE.
+      // Exactly ONE failure reason is benign here: the table/columns are
+      // already provisioned and a non-fully-idempotent driver reports that as
+      // an error. Every other reason (insufficient privileges, datasource never
+      // connected, incompatible column type) means the table or column does NOT
+      // exist — and the previous code marked `schemaReady = true` for all of
+      // them, making a total durability failure indistinguishable from success
+      // with not one line in the log.
+      if (!isSchemaAlreadyExistsError(error)) {
+        if (!this.schemaFailureReported) {
+          this.schemaFailureReported = true;
+          console.error(
+            `[Metadata] DDL for the metadata table \`${this.tableName}\` FAILED — its table/columns were NOT created or altered. ` +
+              `Every metadata write from here on (Studio saves, app installs, org overlays) targets storage that may not exist: ` +
+              `writes will error out, or silently drop columns on a lenient driver, while the server keeps reporting healthy. ` +
+              `This is NOT the benign "already exists" case — check the datasource/driver error below (insufficient privileges, ` +
+              `datasource not connected, incompatible column type), fix it and restart. Schema sync is retried on the next ` +
+              `metadata operation, so a transient cause recovers on its own.`,
+            error,
+          );
+        }
+        // Deliberate, and the opposite of what this code did before: on a REAL
+        // DDL failure `schemaReady` stays FALSE. Startup is still not blocked
+        // (this method does not throw — callers proceed and fail loudly at the
+        // driver if the table is truly missing), but the loader never claims a
+        // readiness it does not have, and the next operation retries the sync
+        // so a datasource that was merely still connecting heals itself. Same
+        // shape as `ensureHistorySchema()` below.
+        return;
       }
+      // Benign — and ONLY benign: the table is already provisioned, so the DDL
+      // was a no-op rather than a failure. Fall through to the ready path.
+    }
+
+    if (this.schemaFailureReported) {
+      this.schemaFailureReported = false;
+      console.info(
+        `[Metadata] DDL for the metadata table \`${this.tableName}\` succeeded on retry — metadata writes are durable again.`,
+      );
+    }
+    this.schemaReady = true;
+    // v5.0 forward migration: project_id → environment_id (idempotent).
+    try {
+      await migrateProjectIdToEnvironmentId(this.driver!);
     } catch {
-      // If syncSchema fails (e.g. table already exists), mark ready and continue
-      this.schemaReady = true;
+      // ignore — migration is best-effort on bootstrap
+    }
+    // Apply ADR-0005 partial UNIQUE INDEX (best-effort, idempotent)
+    try {
+      await addSysMetadataOverlayIndex(this.driver!);
+    } catch {
+      // ignore — index is optimization
     }
   }
 
@@ -358,11 +403,35 @@ export class DatabaseLoader implements MetadataLoader {
         ...SysMetadataHistoryObject,
         name: this.historyTableName,
       });
+      if (this.historySchemaFailureReported) {
+        this.historySchemaFailureReported = false;
+        console.info(
+          `[Metadata] DDL for the metadata history table \`${this.historyTableName}\` succeeded on retry — change history is being recorded again.`,
+        );
+      }
       this.historySchemaReady = true;
     } catch (error) {
-      // Log the error; historySchemaReady remains false so the next operation retries.
-      // If the error is a benign "already exists" the next attempt will also succeed.
-      console.error('Failed to ensure history schema, will retry on next operation:', error);
+      // Same discrimination as `ensureSchema()` above (#4728). A benign
+      // "already exists" means the history table IS provisioned — treat it as
+      // the no-op it is instead of re-reporting it (and re-running the DDL) on
+      // every single write, which is the mirror-image failure: an `error` line
+      // for a non-degradation trains everyone to skim `error`.
+      if (isSchemaAlreadyExistsError(error)) {
+        this.historySchemaReady = true;
+        return;
+      }
+      // Real failure: loud once, `historySchemaReady` stays false so the next
+      // operation retries.
+      if (!this.historySchemaFailureReported) {
+        this.historySchemaFailureReported = true;
+        console.error(
+          `[Metadata] DDL for the metadata history table \`${this.historyTableName}\` FAILED — its table/columns were NOT created. ` +
+            `Metadata change history (versions, diffs, rollback) will NOT be persisted while every metadata write keeps succeeding, ` +
+            `so the audit trail silently ends here. Fix the datasource/driver error below and restart; the sync is retried on the ` +
+            `next metadata operation.`,
+          error,
+        );
+      }
     }
   }