From 336fb1b257eb4a324ed2ec01a519fdbbf2da86f7 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 3 Aug 2026 00:51:58 +0000 Subject: [PATCH 1/2] fix(convention): durability-costing degradations log error, not warn (#4632) #4420: the durable suspended-run store attached to a table that was never created. Every write failed into a warn nobody read, every restart dropped all in-flight approvals, and the process reported perfect health throughout. #4460 raised that ONE site to error. This makes it the rule, because the class is what recurs. The rule (AGENTS.md, new "Degradation log levels" section) is a judgment QUESTION rather than an adjective, so it can be applied while writing the catch: after the degradation, does the system still look "normal" from the outside while something it claims is persisted has not actually landed? Yes -> error. An error here owes the CONSEQUENCE and the FIX in its first line, once, per the #4460 reference text in service-automation's start(). Anchored in AGENTS.md rather than an ADR addendum: this is an authoring judgment every agent applies at every catch, not an architectural decision scoped to one subsystem, and it is broader than the plugin-ordering context ADR-0116 covers. It cross-references its two existing cousins -- Prime Directive #10 (declared != enforced) and "Absence must be loud". Sites raised to error, each judged individually: - objectql schema sync, per object and summary (the info line said "Schema sync complete" over a pass that lost DDL) - objectql reload-time schema sync (a Studio edit shows a field the column for which was never created) - ObjectQL.syncSchemas() -- an EMPTY catch; marketplace install and template seeding write into tables this failure means do not exist - service-automation suspended wait-timer re-arm, 4 paths Left at warn deliberately: the batch->sequential schema-sync fallback (it recovers) and "no job service registered" on the re-arm path (a declared absence, not a broken promise). Over-applying this rule trains everyone to skim error, which is what made the original #4420 warn unreadable. Teeth: pnpm check:durability-log-level walks the AST for catch blocks guarding a declared vocabulary of durability-critical operations and fails when one degrades below error without rethrowing. Follows same-file helpers so extracting a reporter cannot quietly defeat it; ships a 10-case --self-test; exceptions are hand-written and shrink-only with no --fix flag. Deliberately narrow -- a ratchet, not a proof; both limitations are stated in the script header. Findings in the two packages frozen this round are filed, not fixed: #4728 (metadata database-loader silent DDL swallow, baselined) and #4729 (metadata-protocol seed-loader: its own comment demands error). Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_015Br2xsJsczFsTR9bvbh2Ny --- .../durability-degradation-log-level.md | 54 ++ .github/workflows/lint.yml | 16 + AGENTS.md | 63 ++ package.json | 1 + packages/objectql/src/engine.ts | 24 +- packages/objectql/src/plugin.ts | 80 ++- .../schema-sync-durability-log-level.test.ts | 202 +++++++ .../builtin/wait-node-rearm-log-level.test.ts | 189 ++++++ .../src/builtin/wait-node.ts | 44 +- .../services/service-automation/src/plugin.ts | 14 +- ...check-durability-degradation-log-level.mjs | 546 ++++++++++++++++++ scripts/durability-degradation.baseline.json | 19 + 12 files changed, 1229 insertions(+), 23 deletions(-) create mode 100644 .changeset/durability-degradation-log-level.md create mode 100644 packages/objectql/src/schema-sync-durability-log-level.test.ts create mode 100644 packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts create mode 100644 scripts/check-durability-degradation-log-level.mjs create mode 100644 scripts/durability-degradation.baseline.json diff --git a/.changeset/durability-degradation-log-level.md b/.changeset/durability-degradation-log-level.md new file mode 100644 index 0000000000..3de8ffc20a --- /dev/null +++ b/.changeset/durability-degradation-log-level.md @@ -0,0 +1,54 @@ +--- +"@objectstack/objectql": patch +"@objectstack/service-automation": patch +--- + +fix(convention): a best-effort degradation that costs DURABILITY logs `error`, not `warn` — and a gate that enforces it (#4632) + +#4420: the durable suspended-run store attached to a table that was never +created. Every write failed into a `warn` nobody read, every restart dropped all +in-flight approvals, and the process reported perfect health the entire time — +the symptom surfaced a release after the cause. #4460 raised that **one** site to +`error`. This makes it the rule, because the *class* is what recurs. + +**The rule** (AGENTS.md → "Degradation log levels") is a question, not an +adjective, so an agent can apply it while writing the `catch`: + +> After the degradation, does the system still look "normal" from the outside, +> while something it claims is persisted has not actually landed? +> Yes → `error`. No → `warn`/`info` is right. + +An `error` here owes two things in its first line: the **consequence** (what is +not durable, and that the system will keep looking healthy anyway) and the +**fix** (the composition change that restores durability, or the explicit opt-out +that makes the degradation deliberate). Say it once, not once per failed write. + +**Sites raised to `error`** — each was reviewed individually; escalating a +functional degradation is the mirror-image failure and was deliberately avoided: + +| Where | What was silently lost | +|:---|:---| +| `objectql` schema sync, per object | DDL never ran — the object stays registered, routed and rendered while its table/columns do not exist | +| `objectql` schema sync, summary | `info: Schema sync complete` printed over a pass with failures; now an `error` naming the count | +| `objectql` reload-time schema sync | a Studio edit adds a field, the UI shows it, the API accepts it, the column was never created | +| `ObjectQL.syncSchemas()` | an **empty** `catch` — marketplace install and template seeding wrote into tables this failure means do not exist, then reported success | +| `service-automation` wait-timer re-arm (4 paths) | runs stay persisted but nothing re-arms them: every approval paused before the restart hangs forever | + +**Deliberately left at `warn`** — the rule cuts both ways, and over-applying it +trains everyone to skim `error`: the batch→sequential schema-sync fallback (it +*recovers*), and "no job service is registered" on the re-arm path (a declared +absence in a host that never composed auto-resume — nothing was promised and +then broken). + +**It has teeth.** A convention that lives only in AGENTS.md is the same +"declared ≠ enforced" shape this repo keeps paying to fix, so +`pnpm check:durability-log-level` walks the AST for `catch` blocks guarding a +declared vocabulary of durability-critical operations and fails when one +degrades below `error` without rethrowing. It follows same-file helpers (so +extracting a reporter cannot quietly defeat it) and ships its own `--self-test`. +Deliberately narrow: it cannot *discover* a new durability seam, only stop known +ones from regressing — extend `DURABILITY_CRITICAL_CALLEES` in the same PR that +fixes a new one. + +No API, schema or behaviour changes — only the level, and the text, of what +already-failing paths report. diff --git a/.github/workflows/lint.yml b/.github/workflows/lint.yml index 7b52501eac..ef8ffa811c 100644 --- a/.github/workflows/lint.yml +++ b/.github/workflows/lint.yml @@ -188,6 +188,22 @@ jobs: - name: Init-service declaration guard run: pnpm check:init-service-contract + # Durability-degradation log-level guard (#4632). #4460 raised ONE + # best-effort degradation from warn to error — the durable suspended-run + # store writing to a table that never existed (#4420), which looked healthy + # while every restart dropped all in-flight approvals. The rule that fix + # implied now lives in AGENTS.md ("Degradation log levels"): a degradation + # that costs only FUNCTIONALITY may warn; one that costs DURABILITY must + # error, naming the consequence and the fix. This gate is what keeps that + # from being one more declared-but-unenforced convention — it walks the AST + # for catch blocks guarding a declared vocabulary of durability-critical + # operations (schema DDL, suspended-run re-arm) and fails when one degrades + # below `error` without rethrowing. Deliberately narrow: it cannot discover + # a new durability seam, only stop known ones from regressing. Runs its own + # --self-test first. + - name: Durability-degradation log-level guard + run: pnpm check:durability-log-level + # Release-notes drift guard: the platform is one version-locked train, so # every released @objectstack/spec major must have a curated, navigable # release page at content/docs/releases/v.mdx. Catches the gap that diff --git a/AGENTS.md b/AGENTS.md index 73d47f3627..633c82c198 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -538,6 +538,69 @@ composition with its real services, or do not claim an answer. --- +## Degradation log levels — `warn` vs `error` + +Nearly every `catch` in this repo is a best-effort degradation, and nearly every +one of them logs `warn`. That default is wrong for a specific, recurring class, +and the cost of getting it wrong is not noise — it is silent data loss. Decide +the level with **one question**, not with an adjective: + +> **After the degradation, does the system still look "normal" from the outside, +> while something it claims is persisted has not actually landed?** +> **Yes → `error`. No → `warn`/`info` is right.** + +- **Functional degradation → `warn` / `info`.** A screen is missing, a trigger is + not armed, a capability is not enabled, an optional service never showed up. + The system is *visibly* smaller than it should be, and the next person to use + the missing thing finds out. `ScheduleTriggerPlugin: job service not available + — scheduled flows will not run until one is registered` is exactly right at + `warn`. +- **Durability / data-consistency degradation → `error`.** A write that claims + to persist does not, DDL that was supposed to run did not, persisted state and + runtime state disagree. Nothing looks broken; the loss surfaces a release + later, to someone who cannot connect it to this line. + +**Why this is a rule and not a preference.** #4420: the durable suspended-run +store attached to a table that was never created, every write failed into a +`warn` nobody read, and every restart dropped all in-flight approvals — the +symptom surfaced a release after the cause. #4460 raised that one site to +`error`; #4632 made it the rule, because the *class* is what recurs. It is the +same failure Prime Directive #10 names — advertising a capability (here: +durability) the runtime does not deliver — and the same instinct as "Absence must +be loud" above: **prefer failing to falling back**, and when you must fall back, +say what was lost. + +**An `error` here owes two things**, both, in the first line it prints +(`packages/services/service-automation/src/plugin.ts` `start()` is the reference +text): + +1. the **consequence**, concretely — *what* is not durable, and that the system + will keep looking healthy anyway; +2. the **fix** — the composition/config change that restores durability, or the + explicit opt-out that makes the degradation deliberate (`suspendedRunStore: + 'memory'`, `OS_SKIP_SCHEMA_SYNC`). + +Say it **once**, at the first degradation, not once per failed write. + +**Do not over-apply it.** Escalating a functional degradation to `error` is the +mirror-image failure: it trains everyone to skim `error`, which is what made the +#4420 `warn` unreadable in the first place. In particular, an `if (!service)` +composition branch is usually functional and usually belongs at `warn`; a `catch` +around a write, a DDL call, or a store initialization is where this rule bites. + +**It has teeth** (a rule this repo only writes down is the very "declared ≠ +enforced" shape it keeps paying to fix): `pnpm check:durability-log-level` walks +the AST for `catch` blocks guarding a declared vocabulary of durability-critical +operations and fails when one logs below `error` without rethrowing. It is +deliberately narrow — it cannot *discover* a new durability seam, only stop the +known ones from regressing. Found a new one? Add it to +`DURABILITY_CRITICAL_CALLEES` in `scripts/check-durability-degradation-log-level.mjs` +in the same PR that fixes it. Accepted exceptions live in +`scripts/durability-degradation.baseline.json`, hand-edited with a reason and +shrink-only. + +--- + ## Post-Task Checklist 1. `pnpm test` — verify nothing broke. Touched a type-check-covered package? `pnpm typecheck` too. diff --git a/package.json b/package.json index 89d84d49ab..7ab4e9d72c 100644 --- a/package.json +++ b/package.json @@ -44,6 +44,7 @@ "check:error-code-casing": "node scripts/check-error-code-casing.mjs --self-test && node scripts/check-error-code-casing.mjs", "check:wildcard-fallthrough": "node scripts/check-wildcard-fallthrough.mjs --self-test && node scripts/check-wildcard-fallthrough.mjs", "check:init-service-contract": "node scripts/check-init-service-contract.mjs --self-test && node scripts/check-init-service-contract.mjs", + "check:durability-log-level": "node scripts/check-durability-degradation-log-level.mjs --self-test && node scripts/check-durability-degradation-log-level.mjs", "check:console-sha": "node scripts/check-console-sha.mjs", "check:release-notes": "node scripts/check-release-notes.mjs", "check:node-version": "node scripts/check-node-version.mjs", diff --git a/packages/objectql/src/engine.ts b/packages/objectql/src/engine.ts index 4f93b7d517..792f414be8 100644 --- a/packages/objectql/src/engine.ts +++ b/packages/objectql/src/engine.ts @@ -5337,8 +5337,28 @@ export class ObjectQL implements IObjectQLEngine { if (typeof (driver as any).syncSchema === 'function') { try { await (driver as any).syncSchema(tableName, obj); - } catch { - // best effort — log suppressed to avoid noise on already-synced tables + } catch (e: unknown) { + // #4632 — this catch used to be empty, with the comment "log + // suppressed to avoid noise on already-synced tables". Suppressing an + // already-synced no-op is not what it did: `syncSchema` is required to + // be idempotent (see this method's doc comment), so a driver that + // reaches this catch did NOT sync. The only callers are runtime + // installs — marketplace plugin install, template seeding — which go + // on to INSERT into a table this failure means does not exist, and + // then report the install as successful. Nothing that claims to be + // persisted afterwards is. + this.logger.error( + `Schema sync FAILED for object '${obj.name}' — its table/collection was NOT created or altered, yet the object is ` + + `registered and will be written to: those writes will fail, or drop the columns that were never created. ` + + `Any seeding or install step that continues past this point is not durable. ` + + `Fix the driver error below, then re-run the install/sync.`, + { + object: obj.name, + tableName, + driver: (driver as any)?.name, + error: e instanceof Error ? e.message : String(e), + }, + ); } } } diff --git a/packages/objectql/src/plugin.ts b/packages/objectql/src/plugin.ts index d61d362d80..134188e24a 100644 --- a/packages/objectql/src/plugin.ts +++ b/packages/objectql/src/plugin.ts @@ -402,9 +402,17 @@ export class ObjectQLPlugin implements Plugin { try { await this.syncRegisteredSchemas(ctx); } catch (e: any) { - ctx.logger.warn('[ObjectQLPlugin] reload-time schema sync failed', { - error: e?.message ?? String(e), - }); + // #4632 — durability degradation, not a functional one. A + // Studio edit that adds a field lands in metadata (the UI + // shows it, the API accepts it, the author sees a saved + // record) while the column it needs was never created. The + // author is told the value was saved and it was not. + ctx.logger.error( + '[ObjectQLPlugin] reload-time schema sync FAILED — objects changed by this metadata reload are live in the ' + + 'registry, UI and API, but their new/altered columns were NOT created: writes against them are accepted and ' + + 'then silently lost or rejected. Fix the driver error below and reload again (or restart) to re-run DDL.', + { error: e?.message ?? String(e) }, + ); } }); await this.reloadSchemaSync; @@ -910,6 +918,42 @@ export class ObjectQLPlugin implements Plugin { let synced = 0; let skipped = 0; + let failed = 0; + + /** + * #4632 — a failed schema sync is a DURABILITY degradation, not a + * functional one, so it is reported at `error`. + * + * The object stays in the registry, keeps its REST routes, keeps rendering + * in the UI — the system looks completely healthy — while its table or its + * newly-declared columns were never created. Writes then fail, or (on + * drivers that accept unknown attributes) succeed while silently dropping + * the un-created column: the thing the system claims it persisted is not + * on disk. That is exactly the #4420 shape one layer up from the durable + * suspended-run store #4460 fixed, so it carries the same obligation — + * name the CONSEQUENCE and the FIX at the first failure. + */ + const reportSyncFailure = ( + obj: any, + tableName: string, + driverName: string, + err: unknown, + ): void => { + failed++; + ctx.logger.error( + `Schema sync FAILED for object '${obj?.name}' — its table/columns were NOT created or altered, but the object stays ` + + `registered and served: writes to it will fail, or silently drop the columns that were never created. ` + + `Nothing that claims to be persisted for this object is guaranteed to be on disk. ` + + `Fix the driver/datasource error below and restart (or trigger a metadata reload) to re-run DDL; ` + + `if this deployment manages DDL out-of-band, set \`skipSchemaSync\` / OS_SKIP_SCHEMA_SYNC so the omission is deliberate.`, + { + object: obj?.name, + tableName, + driver: driverName, + error: err instanceof Error ? err.message : String(err), + }, + ); + }; // Group objects by driver for potential batch optimization const driverGroups = new Map>(); @@ -993,18 +1037,15 @@ export class ObjectQLPlugin implements Plugin { driver: driver.name, error: e instanceof Error ? e.message : String(e), }); - // Fallback: sequential sync for this driver's objects + // Fallback: sequential sync for this driver's objects. The batch + // warn above is correct at `warn` — it RECOVERS here; only a + // sequential failure actually loses the DDL. for (const { obj, tableName } of entries) { try { await driver.syncSchema(tableName, obj); synced++; } catch (seqErr: unknown) { - ctx.logger.warn('Failed to sync schema for object', { - object: obj.name, - tableName, - driver: driver.name, - error: seqErr instanceof Error ? seqErr.message : String(seqErr), - }); + reportSyncFailure(obj, tableName, driver.name, seqErr); } } } @@ -1015,18 +1056,23 @@ export class ObjectQLPlugin implements Plugin { await driver.syncSchema(tableName, obj); synced++; } catch (e: unknown) { - ctx.logger.warn('Failed to sync schema for object', { - object: obj.name, - tableName, - driver: driver.name, - error: e instanceof Error ? e.message : String(e), - }); + reportSyncFailure(obj, tableName, driver.name, e); } } } } - if (synced > 0 || skipped > 0) { + // #4632 — never claim "complete" over a pass that lost DDL. The old line + // logged `info: Schema sync complete` after any number of failures, which + // is the "looks normal" half of the accident: the only honest summary of a + // pass with failures is an error. + if (failed > 0) { + ctx.logger.error( + `Schema sync finished with ${failed} FAILED object(s) — those objects are registered and served but their storage was ` + + `never created or altered; writes to them are not durable. See the per-object errors above for the driver failure and the fix.`, + { synced, skipped, failed, total: allObjects.length }, + ); + } else if (synced > 0 || skipped > 0) { ctx.logger.info('Schema sync complete', { synced, skipped, total: allObjects.length }); } } diff --git a/packages/objectql/src/schema-sync-durability-log-level.test.ts b/packages/objectql/src/schema-sync-durability-log-level.test.ts new file mode 100644 index 0000000000..a8cf8be01f --- /dev/null +++ b/packages/objectql/src/schema-sync-durability-log-level.test.ts @@ -0,0 +1,202 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. +// +// #4632 — a failed schema sync is a DURABILITY degradation, so it is reported +// at `error`, not `warn`. +// +// #4420 is the accident that made this a rule: a store attached to a table that +// was never created, every write failing into a `warn` nobody read, every +// restart dropping all in-flight approvals — while the system reported itself +// healthy the entire time. #4460 fixed that one site; the schema-sync path +// below is the same shape one layer up, and it is the path that DECIDES whether +// a table exists at all. These tests pin the level and the two things the +// message owes the reader: the CONSEQUENCE and the FIX. + +import { describe, it, expect } from 'vitest'; +import { ObjectQL } from './engine.js'; +import { ObjectQLPlugin } from './plugin.js'; + +interface Recorded { + level: 'debug' | 'info' | 'warn' | 'error'; + message: string; + meta?: unknown; +} + +function recordingLogger() { + const records: Recorded[] = []; + const push = (level: Recorded['level']) => (message: string, meta?: unknown) => + void records.push({ level, message: String(message), meta }); + return { + records, + logger: { debug: push('debug'), info: push('info'), warn: push('warn'), error: push('error') }, + at(level: Recorded['level']) { + return records.filter((r) => r.level === level); + }, + }; +} + +/** A driver whose DDL always fails — the whole point of these tests. */ +function failingDriver(name: string, message: string) { + return { + name, + supports: {}, + async syncSchema() { + throw new Error(message); + }, + async find() { + return []; + }, + }; +} + +describe('ObjectQL.syncSchemas() — DDL failure is an error, not a silent swallow (#4632)', () => { + it('reports a failed syncSchema at error, naming the consequence and the fix', async () => { + const rec = recordingLogger(); + const engine = new ObjectQL({ logger: rec.logger } as any); + engine.registerDriver(failingDriver('default', 'no such column: status') as any); + engine.registerObject({ + name: 'invoice', + label: 'Invoice', + fields: { id: { type: 'text' }, status: { type: 'text' } }, + } as any); + + await engine.syncSchemas(); + + const errors = rec.at('error'); + expect(errors).toHaveLength(1); + // CONSEQUENCE: the reader must learn the table is not there and that writes + // are not durable — not merely that "something failed". + expect(errors[0].message).toContain("'invoice'"); + expect(errors[0].message).toMatch(/NOT created or altered/); + expect(errors[0].message).toMatch(/not durable/); + // FIX: what to actually do about it. + expect(errors[0].message).toMatch(/re-run the install\/sync/); + // The driver's own error is preserved for diagnosis. + expect(JSON.stringify(errors[0].meta)).toContain('no such column: status'); + }); + + it('does not hide the failure at warn/debug — the level is the whole point', async () => { + const rec = recordingLogger(); + const engine = new ObjectQL({ logger: rec.logger } as any); + engine.registerDriver(failingDriver('default', 'boom') as any); + engine.registerObject({ name: 'invoice', label: 'Invoice', fields: { id: { type: 'text' } } } as any); + + await engine.syncSchemas(); + + // Before #4632 this catch was empty with the comment "log suppressed to + // avoid noise on already-synced tables" — zero output on a lost DDL. + expect(rec.at('error').length).toBeGreaterThan(0); + expect(rec.at('warn').filter((r) => /sync/i.test(r.message))).toHaveLength(0); + }); + + it('stays silent when DDL succeeds — the rule must not create noise', async () => { + const rec = recordingLogger(); + const engine = new ObjectQL({ logger: rec.logger } as any); + engine.registerDriver({ + name: 'default', + supports: {}, + async syncSchema() { + /* succeeds */ + }, + async find() { + return []; + }, + } as any); + engine.registerObject({ name: 'invoice', label: 'Invoice', fields: { id: { type: 'text' } } } as any); + + await engine.syncSchemas(); + + expect(rec.at('error')).toHaveLength(0); + }); +}); + +describe('ObjectQLPlugin.syncRegisteredSchemas() — per-object and summary levels (#4632)', () => { + /** Drive the private sync pass directly: the level is the unit under test. */ + async function runSync(driver: unknown, objects: Array>) { + const rec = recordingLogger(); + const plugin = new ObjectQLPlugin(); + const engine = new ObjectQL({ logger: rec.logger } as any); + engine.registerDriver(driver as any); + for (const obj of objects) engine.registerObject(obj as any); + (plugin as any).ql = engine; + await (plugin as any).syncRegisteredSchemas({ logger: rec.logger }); + return rec; + } + + it('reports each failed object at error with the consequence and the opt-out', async () => { + const rec = await runSync(failingDriver('default', 'permission denied for schema public'), [ + { name: 'invoice', label: 'Invoice', fields: { id: { type: 'text' } } }, + ]); + + const perObject = rec.at('error').find((r) => r.message.includes("'invoice'")); + expect(perObject).toBeDefined(); + expect(perObject!.message).toMatch(/NOT created or altered/); + expect(perObject!.message).toMatch(/stays\s+registered and served/); + // The FIX includes the DELIBERATE opt-out, so a host that manages DDL + // out-of-band can make the omission explicit instead of living with an error. + expect(perObject!.message).toMatch(/OS_SKIP_SCHEMA_SYNC/); + expect(JSON.stringify(perObject!.meta)).toContain('permission denied for schema public'); + }); + + it('never logs "Schema sync complete" at info over a pass that lost DDL', async () => { + const rec = await runSync(failingDriver('default', 'boom'), [ + { name: 'invoice', label: 'Invoice', fields: { id: { type: 'text' } } }, + { name: 'payment', label: 'Payment', fields: { id: { type: 'text' } } }, + ]); + + // The "looks normal" half of #4420: the old code printed `info: Schema sync + // complete` after any number of failures. + expect(rec.at('info').filter((r) => /complete/i.test(r.message))).toHaveLength(0); + + const summary = rec.at('error').find((r) => /finished with/.test(r.message)); + expect(summary).toBeDefined(); + expect(summary!.message).toContain('2 FAILED'); + expect(summary!.meta).toMatchObject({ failed: 2, synced: 0 }); + }); + + it('still says "complete" at info when every object synced', async () => { + const rec = await runSync( + { + name: 'default', + supports: {}, + async syncSchema() { + /* succeeds */ + }, + async find() { + return []; + }, + }, + [{ name: 'invoice', label: 'Invoice', fields: { id: { type: 'text' } } }], + ); + + expect(rec.at('error')).toHaveLength(0); + expect(rec.at('info').some((r) => /Schema sync complete/.test(r.message))).toBe(true); + }); + + it('keeps the batch→sequential fallback at warn — it RECOVERS, so it is not a loss', async () => { + // The rule cuts both ways: escalating a degradation that costs nothing is + // the mirror-image failure, and it is what makes `error` unreadable. + let batchCalls = 0; + const rec = await runSync( + { + name: 'default', + supports: { batchSchemaSync: true }, + async syncSchemasBatch() { + batchCalls++; + throw new Error('batch endpoint unavailable'); + }, + async syncSchema() { + /* the sequential retry succeeds */ + }, + async find() { + return []; + }, + }, + [{ name: 'invoice', label: 'Invoice', fields: { id: { type: 'text' } } }], + ); + + expect(batchCalls).toBe(1); + expect(rec.at('warn').some((r) => /Batch schema sync failed/.test(r.message))).toBe(true); + expect(rec.at('error')).toHaveLength(0); + expect(rec.at('info').some((r) => /Schema sync complete/.test(r.message))).toBe(true); + }); +}); diff --git a/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts b/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts new file mode 100644 index 0000000000..0014d9071e --- /dev/null +++ b/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts @@ -0,0 +1,189 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. +// +// #4632 — degradation log levels on the cold-boot re-arm path. +// +// This path is the second half of the #4420 story. #4460 made sure a durable +// store is never attached over a table that cannot exist; that guarantees the +// suspended runs REACH the disk. Getting them back off it is this function's +// job, and every way it can fail leaves a run persisted-but-unreachable: the +// rows are there, the process boots clean, and the approval nobody can find +// waits forever. The persisted state and the runtime disagree, and the runtime +// is the one that looks healthy — so those failures are `error`. +// +// The mirror-image failure is just as real, and this file pins it too: the +// `no job service` branch is a declared absence, not a broken promise, and +// escalating it would fire once per suspended run on every boot of every +// job-less host — teaching everyone to skim `error`, which is exactly what made +// the original #4420 `warn` unreadable. + +import { describe, it, expect } from 'vitest'; +import { AutomationEngine } from '../engine.js'; +import { InMemorySuspendedRunStore } from '../suspended-run-store.js'; +import { registerWaitNode, rearmSuspendedWaitTimers } from './wait-node.js'; +import type { IJobService } from '@objectstack/spec/contracts'; + +type Line = { level: 'info' | 'warn' | 'error'; msg: string }; + +function capturingLogger() { + const lines: Line[] = []; + const at = (level: Line['level']) => (msg: string) => void lines.push({ level, msg: String(msg) }); + const logger: any = { info: at('info'), warn: at('warn'), error: at('error'), debug() {} }; + logger.child = () => logger; + return { + logger, + lines, + text(level: Line['level']) { + return lines.filter((l) => l.level === level).map((l) => l.msg).join('\n'); + }, + }; +} + +const waitFlow = (config: Record) => + ({ + name: 'wait_flow', + label: 'wait_flow', + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'pause', type: 'wait', label: 'Wait', config }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [ + { id: 'e1', source: 'start', target: 'pause' }, + { id: 'e2', source: 'pause', target: 'end' }, + ], + }) as never; + +function silent() { + const l: any = { info() {}, warn() {}, error() {}, debug() {} }; + l.child = () => l; + return l; +} + +/** Boot one "process" against `store`, parked at a wait node. */ +function bootEngine(store: InMemorySuspendedRunStore, config: Record) { + const engine = new AutomationEngine(silent()); + registerWaitNode(engine, { logger: silent(), getService() { throw new Error('no service'); } } as any); + engine.setSuspendedRunStore(store); + engine.registerFlow('wait_flow', waitFlow(config)); + return engine; +} + +/** A store that persisted fine and then cannot be read back. */ +function unreadableStore(message: string): any { + return { + async list() { + throw new Error(message); + }, + async save() {}, + async load() { + return null; + }, + async remove() {}, + }; +} + +describe('rearmSuspendedWaitTimers — durability degradations are errors (#4632)', () => { + it('reports an unlistable store at error, naming the consequence and the fix', async () => { + const cap = capturingLogger(); + const engine = new AutomationEngine(silent()); + + const rearmed = await rearmSuspendedWaitTimers( + engine, + unreadableStore('SQLITE_ERROR: no such table: sys_automation_run'), + undefined, + cap.logger, + ); + + expect(rearmed).toBe(0); + // CONSEQUENCE — nothing re-armed, everything hangs, but the runs survive. + expect(cap.text('error')).toMatch(/NO timer was re-armed/); + expect(cap.text('error')).toMatch(/hang indefinitely/); + expect(cap.text('error')).toMatch(/still persisted/); + // FIX — both the repair and the manual escape hatch. + expect(cap.text('error')).toMatch(/restart to re-attempt/); + expect(cap.text('error')).toMatch(/resume\(runId\)/); + expect(cap.text('error')).toContain('no such table: sys_automation_run'); + // The level is the point: this must not be discoverable only at warn. + expect(cap.text('warn')).toBe(''); + }); + + it('reports a failed re-schedule at error — the run waits with nothing to wake it', async () => { + const store = new InMemorySuspendedRunStore(); + const config = { eventType: 'timer', timerDuration: 'PT2H' }; + const first = bootEngine(store, config); + const paused = await first.execute('wait_flow'); + expect(paused.status).toBe('paused'); + + const brokenJob: IJobService = { + async schedule() { + throw new Error('scheduler backend unreachable'); + }, + } as never; + + const cap = capturingLogger(); + const rearmed = await rearmSuspendedWaitTimers(bootEngine(store, config), store, brokenJob, cap.logger); + + expect(rearmed).toBe(0); + expect(cap.text('error')).toMatch(/could NOT be re-scheduled/); + expect(cap.text('error')).toMatch(/hang past that deadline/); + expect(cap.text('error')).toMatch(/resume\('/); + expect(cap.text('error')).toContain('scheduler backend unreachable'); + // The run itself is untouched — persisted, and still resumable by hand. + expect(await store.list()).toHaveLength(1); + }); + + it('reports an overdue run that could not be resumed at error', async () => { + const store = new InMemorySuspendedRunStore(); + const config = { eventType: 'timer', timerDuration: '1' }; + const first = bootEngine(store, config); + await first.execute('wait_flow'); + await new Promise((r) => setTimeout(r, 10)); // let the 1ms deadline lapse + + // A fresh "process" that never registered the flow: resume() cannot run it. + const amnesiac = new AutomationEngine(silent()); + amnesiac.setSuspendedRunStore(store); + + const cap = capturingLogger(); + await rearmSuspendedWaitTimers(amnesiac, store, undefined, cap.logger); + + expect(cap.text('error')).toMatch(/is OVERDUE and could not be resumed/); + expect(cap.text('error')).toMatch(/nothing will\s+wake it again/); + expect(cap.text('error')).toMatch(/resume\('/); + }); +}); + +describe('rearmSuspendedWaitTimers — functional degradations stay at warn (#4632)', () => { + it('keeps "no job service registered" at warn: a declared absence, not a broken promise', async () => { + const store = new InMemorySuspendedRunStore(); + const config = { eventType: 'timer', timerDuration: 'PT2H' }; + const first = bootEngine(store, config); + await first.execute('wait_flow'); + + const cap = capturingLogger(); + const rearmed = await rearmSuspendedWaitTimers(bootEngine(store, config), store, undefined, cap.logger); + + expect(rearmed).toBe(0); + // A host that never composed a job service never had auto-resume; nothing + // was promised and then lost. It says so, at warn, with the remedy. + expect(cap.text('warn')).toMatch(/no job service is registered/); + expect(cap.text('warn')).toMatch(/resume it externally/); + expect(cap.text('error')).toBe(''); + expect(await store.list()).toHaveLength(1); + }); + + it('says nothing at all when every timer re-arms cleanly', async () => { + const store = new InMemorySuspendedRunStore(); + const config = { eventType: 'timer', timerDuration: 'PT2H' }; + const first = bootEngine(store, config); + await first.execute('wait_flow'); + + const okJob: IJobService = { async schedule() {}, async cancel() {} } as never; + const cap = capturingLogger(); + const rearmed = await rearmSuspendedWaitTimers(bootEngine(store, config), store, okJob, cap.logger); + + expect(rearmed).toBe(1); + expect(cap.text('error')).toBe(''); + expect(cap.text('warn')).toBe(''); + }); +}); diff --git a/packages/services/service-automation/src/builtin/wait-node.ts b/packages/services/service-automation/src/builtin/wait-node.ts index ff6aae71a3..70b69a4263 100644 --- a/packages/services/service-automation/src/builtin/wait-node.ts +++ b/packages/services/service-automation/src/builtin/wait-node.ts @@ -125,6 +125,13 @@ export function registerWaitNode(engine: AutomationEngine, ctx: PluginContext): interface RearmLogger { info(msg: string, ...args: unknown[]): void; warn(msg: string, ...args: unknown[]): void; + /** + * #4632 — required, not optional. Every degradation on the re-arm path leaves + * a run persisted-but-unreachable, which is a durability degradation and must + * be reported at `error`; a logger that cannot carry that level could not + * satisfy the contract this function owes its caller. + */ + error(msg: string, ...args: unknown[]): void; } /** @@ -157,7 +164,16 @@ export async function rearmSuspendedWaitTimers( try { runs = await store.list(); } catch (err) { - logger.warn(`[wait] timer re-arm: failed to list suspended runs: ${(err as Error)?.message ?? err}`); + // #4632 — durability degradation, not a functional one: returning 0 here + // re-arms NOTHING, so every run persisted before this restart stays paused + // forever while the process reports a clean boot. The rows survived; the + // promise that they would resume did not. + logger.error( + `[wait] suspended wait-timer re-arm ABORTED — the suspended-run store could not be listed, so NO timer was re-armed: ` + + `every wait/approval paused before this restart will hang indefinitely instead of resuming. The runs themselves are ` + + `still persisted. Fix the store/datasource error and restart to re-attempt the re-arm, or resume them via ` + + `resume(runId). Cause: ${(err as Error)?.message ?? err}`, + ); return 0; } @@ -174,12 +190,26 @@ export async function rearmSuspendedWaitTimers( await engine.resume(run.runId); rearmed++; } catch (err) { - logger.warn(`[wait] timer re-arm: resume of overdue run '${run.runId}' failed: ${(err as Error)?.message ?? err}`); + // #4632 — this run's deadline already passed, so nothing else will ever + // wake it: it is persisted, overdue, and now unreachable. + logger.error( + `[wait] suspended run '${run.runId}' is OVERDUE and could not be resumed — it stays persisted but nothing will ` + + `wake it again (its deadline has already passed, so no timer will be re-armed for it). Fix the cause below and ` + + `restart, or resume it directly via resume('${run.runId}'). Cause: ${(err as Error)?.message ?? err}`, + ); } continue; } if (!job) { + // #4632 — deliberately stays `warn`. This is the FUNCTIONAL half of the + // rule: a host with no job service never had auto-resume to begin with, + // so nothing was promised and then broken — the capability is simply not + // composed, and the line already names the remedy. Escalating a declared + // absence like this to `error` is the mirror-image failure: it would fire + // once per suspended run on every boot of every job-less host, and teach + // everyone to skim `error` — which is what made the #4420 `warn` + // unreadable in the first place. logger.warn( `[wait] timer re-arm: run '${run.runId}' waits until ${wakeAt} but no job service is registered — ` + `resume it externally via resume(runId)`, @@ -202,7 +232,15 @@ export async function rearmSuspendedWaitTimers( }); rearmed++; } catch (err) { - logger.warn(`[wait] timer re-arm: failed to re-schedule run '${run.runId}': ${(err as Error)?.message ?? err}`); + // #4632 — the run is persisted and waiting, but its wake-up job was never + // scheduled: it will sit at its wait node past its deadline with nothing + // to resume it. + logger.error( + `[wait] suspended run '${run.runId}' could NOT be re-scheduled — it stays persisted with a deadline of ${wakeAt}, ` + + `but no job was armed to wake it, so it will hang past that deadline instead of resuming. Fix the job-service ` + + `error below and restart to re-attempt the re-arm, or resume it via resume('${run.runId}'). ` + + `Cause: ${(err as Error)?.message ?? err}`, + ); } } return rearmed; diff --git a/packages/services/service-automation/src/plugin.ts b/packages/services/service-automation/src/plugin.ts index 2888086b0d..603ef42b11 100644 --- a/packages/services/service-automation/src/plugin.ts +++ b/packages/services/service-automation/src/plugin.ts @@ -879,7 +879,19 @@ export class AutomationServicePlugin implements Plugin { ctx.logger.info(`[Automation] Re-armed ${rearmed} suspended wait timer(s) after restart`); } } catch (err) { - ctx.logger.warn(`[Automation] wait-timer re-arm failed: ${(err as Error).message}`); + // #4632 — the persisted state and the runtime now disagree, and + // the runtime is the one that looks fine. The suspended runs ARE + // on disk (durability held), but nothing re-armed their timers, + // so no wait/approval that was in flight before this restart will + // ever resume on its own. To everyone waiting on one, that is + // indistinguishable from the #4420 loss this store exists to + // prevent — so it is reported at `error`, not `warn`. + ctx.logger.error( + `[Automation] suspended wait-timer re-arm FAILED after restart — suspended runs are still persisted in ` + + `sys_automation_run, but their timers were NOT re-armed: every wait/approval paused before this restart ` + + `will hang indefinitely instead of resuming. Fix the job-service error below and restart to re-attempt the ` + + `re-arm; runs can also be resumed manually via the automation resume API. Cause: ${(err as Error).message}`, + ); } } } diff --git a/scripts/check-durability-degradation-log-level.mjs b/scripts/check-durability-degradation-log-level.mjs new file mode 100644 index 0000000000..be00f436c8 --- /dev/null +++ b/scripts/check-durability-degradation-log-level.mjs @@ -0,0 +1,546 @@ +#!/usr/bin/env node +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * Durability-degradation log-level guard (#4632, from #4471 / #4420 / #4460). + * + * ## The rule it enforces + * + * AGENTS.md → "Degradation log levels": a best-effort degradation whose + * consequence is only reduced FUNCTIONALITY (a screen missing, a capability + * not armed) may log `warn`/`info`. A degradation whose consequence is that + * something the system CLAIMS to persist is not actually persisted — while the + * system keeps looking healthy — MUST log `error`, naming the consequence and + * the fix. + * + * The judgment question, from AGENTS.md: + * + * > After the degradation, does the system still look "normal" from the + * > outside while something it claims is persisted has not actually landed? + * > Yes → `error`. + * + * #4420 is the accident this exists for: the durable suspended-run store was + * attached to a table that was never created, every write failed into a `warn` + * nobody read, and each restart silently dropped every in-flight approval. The + * system reported itself healthy the whole time. #4460 fixed that ONE site; + * this gate is what keeps the class fixed. + * + * ## What it checks (deliberately narrow — see "Why a vocabulary") + * + * For every `try`/`catch` whose `try` block calls a **durability-critical** + * operation from the declared vocabulary below, the `catch` must either + * + * - rethrow (the failure propagates — the loudest option), or + * - log at `error` (or `fatal`). + * + * A `catch` that logs `warn`/`info`/`debug`, or swallows silently, is a + * violation: the write did not happen, and nothing above will ever hear so. + * + * ## Why a vocabulary, and not "detect persistence" + * + * "Is this catch guarding a durability seam?" is a semantic question, and a + * heuristic that guesses it (callee names matching /save|write|persist/, say) + * produces false positives at a rate that would get the gate disabled — and a + * gate people disable is worth less than no gate, because it also *reports + * success*. So the vocabulary is EXPLICIT and small: the operations whose + * failure is known to mean "the bytes did not land". Adding an entry is a + * deliberate, reviewable act. + * + * Two honest limitations, stated up front rather than discovered later: + * + * 1. It cannot FIND a durability seam whose operation is not in the + * vocabulary. It guarantees the seams already paid for cannot regress to + * `warn`, and gives one place to extend. A ratchet, not a proof. + * 2. The `catch` is scanned for a loud log across its whole subtree, so a + * catch that RECOVERS through a nested try (the batch→sequential schema + * sync fallback in `objectql/plugin.ts`) passes on the nested path's + * `error`. That is the right verdict for that shape — the durability-losing + * path does end loudly — but it does mean an unrelated nested + * `logger.error` would satisfy the gate. Narrowing this would fail the + * legitimate recovering catch, which is the worse trade. + * + * ## Why AST, not regex + * + * The guarded call is rarely adjacent to the log line — in `objectql/plugin.ts` + * the `await driver.syncSchema(...)` and its `logger.warn` sit in different + * blocks of a nested loop, and in #4420 the call was in a private method the + * try block invoked. Line proximity does not decide this; block structure does. + * + * Nested function bodies inside the `try` are NOT descended into: a callback + * registered inside a try (`ctx.hook('kernel:ready', async () => …)`) runs + * later and is not guarded by that catch. Same choice, same reason, as + * `check-init-service-contract.mjs`. + * + * The `catch` side, by contrast, DOES follow same-file helpers transitively: a + * catch that calls `reportSyncFailure(...)` is loud if that helper is. Without + * this, extracting a shared reporter — normal, good refactoring — would defeat + * the gate, which would make "hide the failure behind one indirection" the + * cheapest way to go quiet. That is the #4420 shape itself, and it is why + * `check-init-service-contract.mjs` walks a call graph too. + * + * ## Usage + * + * node scripts/check-durability-degradation-log-level.mjs # audit + * node scripts/check-durability-degradation-log-level.mjs --list # every guarded seam found + * node scripts/check-durability-degradation-log-level.mjs --self-test # verify the checker + */ + +import { readFileSync, readdirSync, statSync, existsSync } from 'node:fs'; +import { join, relative, sep } from 'node:path'; +import { fileURLToPath } from 'node:url'; +import ts from 'typescript'; + +const ROOT = fileURLToPath(new URL('..', import.meta.url)); +const BASELINE_PATH = join(ROOT, 'scripts', 'durability-degradation.baseline.json'); + +/** + * Operations whose failure means "the bytes did not land". + * + * Each entry names WHY it is durability-critical — the note is printed in the + * violation message, so the author reads the consequence rather than a rule id. + */ +const DURABILITY_CRITICAL_CALLEES = new Map([ + [ + 'syncSchema', + 'DDL for the object never ran — the table/columns do not exist, yet the object stays registered and served.', + ], + [ + 'syncSchemasBatch', + 'DDL for a whole batch of objects never ran — their tables/columns do not exist, yet the objects stay registered and served.', + ], + [ + 'syncRegisteredSchemas', + 'The schema-sync pass never completed — objects are registered and served against tables that were never created or altered.', + ], + [ + 'initObjects', + 'Object storage was never initialized — writes go to a table that does not exist.', + ], + [ + 'rearmSuspendedWaitTimers', + 'Suspended runs survive on disk but nothing will ever resume them — the persisted state and the runtime disagree (ADR-0019, #4420).', + ], +]); + +/** Log levels that are ACCEPTABLE inside a durability-guarding catch. */ +const LOUD_LEVELS = new Set(['error', 'fatal']); +/** Log levels that are NOT — the whole point of the gate. */ +const QUIET_LEVELS = new Set(['warn', 'info', 'debug', 'trace', 'log']); + +const SKIP_DIRS = new Set(['node_modules', 'dist', 'build', '.git', '.turbo', 'coverage', '.cache']); + +function collectSourceFiles(dir, out = []) { + let entries; + try { + entries = readdirSync(dir); + } catch { + return out; + } + for (const entry of entries) { + if (SKIP_DIRS.has(entry)) continue; + const full = join(dir, entry); + let st; + try { + st = statSync(full); + } catch { + continue; + } + if (st.isDirectory()) { + collectSourceFiles(full, out); + } else if ( + entry.endsWith('.ts') && + !entry.endsWith('.d.ts') && + !entry.endsWith('.test.ts') && + !entry.endsWith('.spec.ts') + ) { + out.push(full); + } + } + return out; +} + +/** Walk `node`'s subtree without descending into bodies that run LATER. */ +function walkSameTick(node, visit) { + node.forEachChild((child) => { + if ( + ts.isFunctionDeclaration(child) || + ts.isFunctionExpression(child) || + ts.isArrowFunction(child) || + ts.isMethodDeclaration(child) || + ts.isClassDeclaration(child) || + ts.isClassExpression(child) + ) { + return; + } + visit(child); + walkSameTick(child, visit); + }); +} + +/** Walk everything, including nested function bodies. */ +function walkAll(node, visit) { + node.forEachChild((child) => { + visit(child); + walkAll(child, visit); + }); +} + +function calleeName(node) { + if (!ts.isCallExpression(node)) return undefined; + const expr = node.expression; + if (ts.isIdentifier(expr)) return expr.text; + if (ts.isPropertyAccessExpression(expr) && ts.isIdentifier(expr.name)) return expr.name.text; + return undefined; +} + +/** + * `x.logger.warn(...)` / `logger.warn(...)` / `this.log.error(...)` / + * `console.error(...)` → 'warn' | 'error' | … + * + * Matched on the SHAPE `.(…)`, so a renamed local + * (`const log = ctx.logger`) is still seen. `console` counts because + * `console.error` is every bit as loud as `logger.error` — measuring the gate + * against the repo turned up a real site (`metadata/src/loaders/ + * database-loader.ts` history-schema sync) that reports honestly via `console`, + * and flagging it would have been a false positive. + */ +function loggerLevel(node) { + if (!ts.isCallExpression(node)) return undefined; + const expr = node.expression; + if (!ts.isPropertyAccessExpression(expr) || !ts.isIdentifier(expr.name)) return undefined; + const level = expr.name.text; + if (!LOUD_LEVELS.has(level) && !QUIET_LEVELS.has(level)) return undefined; + const receiver = expr.expression; + let receiverName; + if (ts.isIdentifier(receiver)) receiverName = receiver.text; + else if (ts.isPropertyAccessExpression(receiver) && ts.isIdentifier(receiver.name)) { + receiverName = receiver.name.text; + } + if (!receiverName) return undefined; + return /^(logger|log|console)$/i.test(receiverName) ? level : undefined; +} + +/** + * Index every named function-like body in the file, so a `catch` that delegates + * to a helper can be judged by what the helper does. + * + * Covers `function foo() {}`, `const foo = () => {}` / `= function () {}`, and + * class methods `foo() {}` — the three shapes the repo actually uses. Keyed by + * bare name: same-file collisions are rare and the effect of one would only be + * to consider a catch louder, never quieter than it is. + */ +function indexFunctionBodies(sf) { + const byName = new Map(); + walkAll(sf, (node) => { + if (ts.isFunctionDeclaration(node) && node.name && node.body) { + byName.set(node.name.text, node.body); + } else if (ts.isMethodDeclaration(node) && ts.isIdentifier(node.name) && node.body) { + byName.set(node.name.text, node.body); + } else if ( + ts.isVariableDeclaration(node) && + ts.isIdentifier(node.name) && + node.initializer && + (ts.isArrowFunction(node.initializer) || ts.isFunctionExpression(node.initializer)) && + node.initializer.body + ) { + byName.set(node.name.text, node.initializer.body); + } + }); + return byName; +} + +function analyzeSourceFile(sf, relPath, findings, seams) { + const lineOf = (node) => sf.getLineAndCharacterOfPosition(node.getStart(sf)).line + 1; + const functionBodies = indexFunctionBodies(sf); + + /** + * Collect the log levels a catch reaches, following same-file helper calls + * transitively (depth-capped, cycle-safe). + */ + const collectResponse = (block, seen = new Set(), depth = 0) => { + const levels = []; + let rethrows = false; + walkSameTick(block, (child) => { + if (ts.isThrowStatement(child)) rethrows = true; + const level = loggerLevel(child); + if (level) { + levels.push({ level, line: lineOf(child) }); + return; + } + if (depth >= 3) return; + const name = calleeName(child); + if (!name || seen.has(name)) return; + const body = functionBodies.get(name); + if (!body) return; + seen.add(name); + const nested = collectResponse(body, seen, depth + 1); + for (const l of nested.levels) levels.push({ ...l, viaHelper: name }); + // A helper that rethrows does NOT make the CATCH rethrow — it only + // does if the catch itself propagates. Deliberately not inherited. + }); + return { levels, rethrows }; + }; + + walkAll(sf, (node) => { + if (!ts.isTryStatement(node) || !node.catchClause) return; + + // 1. Does the guarded block call a durability-critical operation? + const guarded = []; + const inspectForCritical = (child) => { + const name = calleeName(child); + if (name && DURABILITY_CRITICAL_CALLEES.has(name)) { + guarded.push({ callee: name, line: lineOf(child) }); + } + }; + // The try block itself may BE a call at top level, so check it too. + inspectForCritical(node.tryBlock); + walkSameTick(node.tryBlock, inspectForCritical); + if (guarded.length === 0) return; + + // 2. How does the catch respond? + const { levels, rethrows } = collectResponse(node.catchClause.block); + + const loud = levels.filter((l) => LOUD_LEVELS.has(l.level)); + const quiet = levels.filter((l) => QUIET_LEVELS.has(l.level)); + + const seam = { + file: relPath, + callee: guarded[0].callee, + calleeLine: guarded[0].line, + catchLine: lineOf(node.catchClause), + rethrows, + loud: loud.map((l) => `${l.level}@${l.line}${l.viaHelper ? ` via ${l.viaHelper}()` : ''}`), + quiet: quiet.map((l) => `${l.level}@${l.line}${l.viaHelper ? ` via ${l.viaHelper}()` : ''}`), + }; + seams.push(seam); + + if (rethrows || loud.length > 0) return; + + findings.push({ + ...seam, + why: DURABILITY_CRITICAL_CALLEES.get(guarded[0].callee), + kind: quiet.length > 0 ? 'quiet-log' : 'silent-swallow', + }); + }); +} + +function loadBaseline() { + if (!existsSync(BASELINE_PATH)) return { entries: [] }; + return JSON.parse(readFileSync(BASELINE_PATH, 'utf8')); +} + +function baselineKey(f) { + return `${f.file}::${f.callee}`; +} + +function run({ list = false } = {}) { + const packagesDir = join(ROOT, 'packages'); + const files = collectSourceFiles(packagesDir); + const findings = []; + const seams = []; + + for (const file of files) { + const text = readFileSync(file, 'utf8'); + if (!text.includes('catch')) continue; + const sf = ts.createSourceFile(file, text, ts.ScriptTarget.Latest, true, ts.ScriptKind.TS); + analyzeSourceFile(sf, relative(ROOT, file).split(sep).join('/'), findings, seams); + } + + if (list) { + console.log(`\nDurability-critical catch seams found: ${seams.length}\n`); + for (const s of seams) { + const verdict = s.rethrows + ? 'rethrows' + : s.loud.length > 0 + ? `loud (${s.loud.join(', ')})` + : s.quiet.length > 0 + ? `QUIET (${s.quiet.join(', ')})` + : 'SILENT'; + console.log(` ${s.file}:${s.catchLine} guards ${s.callee}()@${s.calleeLine} → ${verdict}`); + } + console.log(''); + } + + const baseline = loadBaseline(); + const allowed = new Map((baseline.entries ?? []).map((e) => [`${e.file}::${e.callee}`, e])); + const violations = []; + const usedBaselineKeys = new Set(); + + for (const f of findings) { + const key = baselineKey(f); + if (allowed.has(key)) { + usedBaselineKeys.add(key); + continue; + } + violations.push(f); + } + + // Shrink-only: a baseline entry whose violation is gone must be deleted, so + // the file can never quietly re-license a site that was already fixed. + const stale = [...allowed.keys()].filter((k) => !usedBaselineKeys.has(k)); + + let failed = false; + + if (violations.length > 0) { + failed = true; + console.error( + `\n✗ ${violations.length} durability-critical catch(es) degrade quietly (AGENTS.md → "Degradation log levels", #4632):\n`, + ); + for (const v of violations) { + console.error(` ${v.file}:${v.catchLine}`); + console.error(` guards : ${v.callee}() at line ${v.calleeLine}`); + console.error(` consequence: ${v.why}`); + console.error( + ` found : ${v.kind === 'quiet-log' ? `catch logs ${v.quiet.join(', ')} and does not rethrow` : 'catch swallows the failure with no log at all'}`, + ); + console.error( + ` fix : log at \`error\` naming the CONSEQUENCE and the FIX (see packages/services/service-automation/src/plugin.ts start(), #4460), or rethrow.\n`, + ); + } + } + + if (stale.length > 0) { + failed = true; + console.error( + `\n✗ ${stale.length} stale baseline entr(ies) in scripts/durability-degradation.baseline.json — the site no longer violates, so delete the entry (the baseline is shrink-only):\n`, + ); + for (const k of stale) console.error(` ${k}`); + console.error(''); + } + + if (!failed) { + console.log( + `✓ durability-degradation log levels: ${seams.length} durability-critical catch seam(s), all loud or rethrowing` + + (allowed.size > 0 ? ` (${allowed.size} baselined)` : '') + + '.', + ); + } + + return failed ? 1 : 0; +} + +// ── Self-test ──────────────────────────────────────────────────────────────── +// A checker nobody checks is the shape this gate exists to prevent. These +// fixtures pin both directions: it must FLAG the #4420 shape and must NOT flag +// the shapes that are legitimately `warn`. +function selfTest() { + const cases = [ + { + name: 'flags: catch around syncSchema logging warn', + code: ` + class P { async f(ctx: any, driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { ctx.logger.warn('failed', { e }); } + } }`, + expectViolation: true, + }, + { + name: 'flags: catch around syncSchema swallowing silently', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } catch { /* ignore */ } + } }`, + expectViolation: true, + }, + { + name: 'passes: catch around syncSchema logging error', + code: ` + class P { async f(ctx: any, driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { ctx.logger.error('DDL never ran — writes will not persist; fix X', { e }); } + } }`, + expectViolation: false, + }, + { + name: 'passes: catch around syncSchema that rethrows', + code: ` + class P { async f(ctx: any, driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { ctx.logger.warn('context'); throw e; } + } }`, + expectViolation: false, + }, + { + name: 'passes: functional degradation (no critical callee) may warn', + code: ` + class P { async f(ctx: any, automation: any) { + try { automation.registerTrigger(this.t); } + catch (e) { ctx.logger.warn('trigger NOT installed'); } + } }`, + expectViolation: false, + }, + { + name: 'passes: critical call inside a LATER callback is not guarded by this catch', + code: ` + class P { async f(ctx: any, driver: any, obj: any) { + try { ctx.hook('kernel:ready', async () => { await driver.syncSchema('t', obj); }); } + catch (e) { ctx.logger.warn('hook registration failed'); } + } }`, + expectViolation: false, + }, + { + name: 'passes: console.error is as loud as logger.error', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { console.error('DDL never ran — writes will not persist; fix X', e); } + } }`, + expectViolation: false, + }, + { + name: 'passes: catch delegating to a LOUD same-file helper', + code: ` + class P { async f(ctx: any, driver: any, obj: any) { + const report = (e: unknown) => { ctx.logger.error('DDL never ran — not durable; fix X', e); }; + try { await driver.syncSchema('t', obj); } catch (e) { report(e); } + } }`, + expectViolation: false, + }, + { + name: 'flags: catch delegating to a QUIET same-file helper', + code: ` + class P { async f(ctx: any, driver: any, obj: any) { + const report = (e: unknown) => { ctx.logger.warn('failed', e); }; + try { await driver.syncSchema('t', obj); } catch (e) { report(e); } + } }`, + expectViolation: true, + }, + { + name: 'flags: renamed logger local is still seen', + code: ` + class P { async f(log: any, driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { log.warn('failed'); } + } }`, + expectViolation: true, + }, + ]; + + let failures = 0; + for (const c of cases) { + const sf = ts.createSourceFile('t.ts', c.code, ts.ScriptTarget.Latest, true, ts.ScriptKind.TS); + const findings = []; + const seams = []; + analyzeSourceFile(sf, 't.ts', findings, seams); + const got = findings.length > 0; + if (got !== c.expectViolation) { + failures++; + console.error(` ✗ ${c.name}: expected violation=${c.expectViolation}, got ${got}`); + } else { + console.log(` ✓ ${c.name}`); + } + } + if (failures > 0) { + console.error(`\n✗ self-test: ${failures} case(s) failed\n`); + return 1; + } + console.log(`\n✓ self-test: ${cases.length} case(s) passed\n`); + return 0; +} + +const args = process.argv.slice(2); +if (args.includes('--self-test')) { + process.exit(selfTest()); +} else { + process.exit(run({ list: args.includes('--list') })); +} diff --git a/scripts/durability-degradation.baseline.json b/scripts/durability-degradation.baseline.json new file mode 100644 index 0000000000..939a64336a --- /dev/null +++ b/scripts/durability-degradation.baseline.json @@ -0,0 +1,19 @@ +{ + "$comment": [ + "Accepted exceptions for scripts/check-durability-degradation-log-level.mjs (#4632).", + "SHRINK-ONLY and hand-edited under review: the checker fails on a stale entry, so a", + "site that gets fixed must have its entry deleted in the same PR. There is deliberately", + "no `--fix`/`--update` flag — a generator would let a new violation be admitted by", + "'just run the update command', which is precisely how a gate stops meaning anything.", + "Every entry names WHY it is still here and WHAT closes it." + ], + "entries": [ + { + "file": "packages/metadata/src/loaders/database-loader.ts", + "callee": "syncSchema", + "reason": "ensureSchema() catches a failed sys_metadata DDL, sets `schemaReady = true` and continues — every subsequent metadata write targets a table that may not exist. Real durability finding, NOT an accepted design. Left baselined only because packages/metadata/** was frozen for this round (#4556 was rewriting its write path concurrently); fixing it here would have collided.", + "tracked_by": "#4728", + "closes_when": "#4728 raises the swallow to `error` (or rethrows) and deletes this entry." + } + ] +} From e4fa4af86e6ca1fdb0551d4891b30ac11165e593 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 3 Aug 2026 01:02:02 +0000 Subject: [PATCH 2/2] fix(objectql): pass the Error in Logger.error's SECOND slot, not the context bag CI caught what a filter-scoped typecheck could not: src/engine.ts(5356,15): error TS2353: Object literal may only specify known properties, and 'object' does not exist in type 'Error'. `Logger` (packages/spec/src/contracts/logger.ts) is asymmetric on purpose: warn (message: string, meta?: Record): void error(message: string, error?: Error, meta?: Record): void Every escalation in the previous commit was written as a mechanical warn -> error swap, which silently slides the context bag from the `meta` slot into the `Error` slot. Excess-property checking makes that a hard error -- but ONLY where a declaration is emitted, so it surfaced in the tsup DTS build and in the repo-wide TypeScript Type Check, while every runtime test stayed green (a plain object in the Error slot logs fine). Four call sites corrected to (message, Error, meta): - engine.ts syncSchemas() -> e as Error, { object, tableName, driver } - plugin.ts reload-time schema sync -> the caught error - plugin.ts reportSyncFailure() -> the caught error, { object, tableName, driver } - plugin.ts pass summary -> undefined (no single error owns a whole pass) The tests now assert the ARGUMENT POSITIONS rather than a flattened `meta`, so this exact slide fails a test run too instead of only a build: expect(args[0]).toBeInstanceOf(Error) expect(args[1]).toMatchObject({ object: 'invoice' }) Also fixed the overdue-resume test: AutomationEngine.resume() REPORTS machine-state problems in its result rather than throwing, so an unregistered flow never reached the catch under test. It now injects a throwing resume stub, which is what that catch actually guards. Verified: turbo dependency-closure build, objectql + service-automation builds WITH DTS, objectql typecheck, 7 + 25 tests, gate self-test 10/10. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_015Br2xsJsczFsTR9bvbh2Ny --- packages/objectql/src/engine.ts | 8 +--- packages/objectql/src/plugin.ts | 17 ++++---- .../schema-sync-durability-log-level.test.ts | 42 +++++++++++++++---- .../builtin/wait-node-rearm-log-level.test.ts | 15 +++++-- 4 files changed, 58 insertions(+), 24 deletions(-) diff --git a/packages/objectql/src/engine.ts b/packages/objectql/src/engine.ts index 792f414be8..3250ba6d0f 100644 --- a/packages/objectql/src/engine.ts +++ b/packages/objectql/src/engine.ts @@ -5352,12 +5352,8 @@ export class ObjectQL implements IObjectQLEngine { `registered and will be written to: those writes will fail, or drop the columns that were never created. ` + `Any seeding or install step that continues past this point is not durable. ` + `Fix the driver error below, then re-run the install/sync.`, - { - object: obj.name, - tableName, - driver: (driver as any)?.name, - error: e instanceof Error ? e.message : String(e), - }, + e as Error, + { object: obj.name, tableName, driver: (driver as any)?.name }, ); } } diff --git a/packages/objectql/src/plugin.ts b/packages/objectql/src/plugin.ts index 134188e24a..d3e542a038 100644 --- a/packages/objectql/src/plugin.ts +++ b/packages/objectql/src/plugin.ts @@ -407,11 +407,13 @@ export class ObjectQLPlugin implements Plugin { // shows it, the API accepts it, the author sees a saved // record) while the column it needs was never created. The // author is told the value was saved and it was not. + // `Logger.error` is `(message, error?, meta?)` — the second + // slot is the Error, NOT the context bag `warn` takes there. ctx.logger.error( '[ObjectQLPlugin] reload-time schema sync FAILED — objects changed by this metadata reload are live in the ' + 'registry, UI and API, but their new/altered columns were NOT created: writes against them are accepted and ' + 'then silently lost or rejected. Fix the driver error below and reload again (or restart) to re-run DDL.', - { error: e?.message ?? String(e) }, + e instanceof Error ? e : new Error(String(e?.message ?? e)), ); } }); @@ -940,18 +942,18 @@ export class ObjectQLPlugin implements Plugin { err: unknown, ): void => { failed++; + // NB `Logger.error` is `(message, error?, meta?)` — the Error goes in the + // SECOND slot, unlike `warn`'s `(message, meta?)`. This call was written + // as a mechanical warn→error swap and the mismatch only surfaced in the + // DTS build, never in a test run. ctx.logger.error( `Schema sync FAILED for object '${obj?.name}' — its table/columns were NOT created or altered, but the object stays ` + `registered and served: writes to it will fail, or silently drop the columns that were never created. ` + `Nothing that claims to be persisted for this object is guaranteed to be on disk. ` + `Fix the driver/datasource error below and restart (or trigger a metadata reload) to re-run DDL; ` + `if this deployment manages DDL out-of-band, set \`skipSchemaSync\` / OS_SKIP_SCHEMA_SYNC so the omission is deliberate.`, - { - object: obj?.name, - tableName, - driver: driverName, - error: err instanceof Error ? err.message : String(err), - }, + err instanceof Error ? err : new Error(String(err)), + { object: obj?.name, tableName, driver: driverName }, ); }; @@ -1070,6 +1072,7 @@ export class ObjectQLPlugin implements Plugin { ctx.logger.error( `Schema sync finished with ${failed} FAILED object(s) — those objects are registered and served but their storage was ` + `never created or altered; writes to them are not durable. See the per-object errors above for the driver failure and the fix.`, + undefined, { synced, skipped, failed, total: allObjects.length }, ); } else if (synced > 0 || skipped > 0) { diff --git a/packages/objectql/src/schema-sync-durability-log-level.test.ts b/packages/objectql/src/schema-sync-durability-log-level.test.ts index a8cf8be01f..0497f760ed 100644 --- a/packages/objectql/src/schema-sync-durability-log-level.test.ts +++ b/packages/objectql/src/schema-sync-durability-log-level.test.ts @@ -18,13 +18,21 @@ import { ObjectQLPlugin } from './plugin.js'; interface Recorded { level: 'debug' | 'info' | 'warn' | 'error'; message: string; - meta?: unknown; + /** + * Everything after the message. The two loggers in play take DIFFERENT + * shapes — the engine's is `(msg, Error, context)` while `PluginContext`'s is + * `(msg, context)` — so the recorder keeps the raw tail and each assertion + * says which one it means. (Collapsing them into a single `meta` is what let + * a `{ object: … }` land in the engine's `Error` slot and turn the DTS build + * red while every runtime test stayed green.) + */ + args: unknown[]; } function recordingLogger() { const records: Recorded[] = []; - const push = (level: Recorded['level']) => (message: string, meta?: unknown) => - void records.push({ level, message: String(message), meta }); + const push = (level: Recorded['level']) => (message: string, ...args: unknown[]) => + void records.push({ level, message: String(message), args }); return { records, logger: { debug: push('debug'), info: push('info'), warn: push('warn'), error: push('error') }, @@ -34,6 +42,13 @@ function recordingLogger() { }; } +/** Flatten a record's tail args to text, Error messages included. */ +function tailText(r: Recorded): string { + return r.args + .map((a) => (a instanceof Error ? a.message : JSON.stringify(a))) + .join(' '); +} + /** A driver whose DDL always fails — the whole point of these tests. */ function failingDriver(name: string, message: string) { return { @@ -70,8 +85,12 @@ describe('ObjectQL.syncSchemas() — DDL failure is an error, not a silent swall expect(errors[0].message).toMatch(/not durable/); // FIX: what to actually do about it. expect(errors[0].message).toMatch(/re-run the install\/sync/); - // The driver's own error is preserved for diagnosis. - expect(JSON.stringify(errors[0].meta)).toContain('no such column: status'); + // The driver's own error is preserved for diagnosis, and — the part CI + // caught — it goes in the engine logger's `Error` slot, with the structured + // context in the third argument where it type-checks. + expect(errors[0].args[0]).toBeInstanceOf(Error); + expect((errors[0].args[0] as Error).message).toContain('no such column: status'); + expect(errors[0].args[1]).toMatchObject({ object: 'invoice' }); }); it('does not hide the failure at warn/debug — the level is the whole point', async () => { @@ -134,7 +153,13 @@ describe('ObjectQLPlugin.syncRegisteredSchemas() — per-object and summary leve // The FIX includes the DELIBERATE opt-out, so a host that manages DDL // out-of-band can make the omission explicit instead of living with an error. expect(perObject!.message).toMatch(/OS_SKIP_SCHEMA_SYNC/); - expect(JSON.stringify(perObject!.meta)).toContain('permission denied for schema public'); + // `Logger.error` is `(message, error?, meta?)` on BOTH loggers — the Error + // in slot 2, the context bag in slot 3. (`warn` puts context in slot 2, + // which is exactly the asymmetry that made a mechanical warn→error swap + // compile-fail in the DTS build while every runtime assertion stayed green.) + expect(perObject!.args[0]).toBeInstanceOf(Error); + expect(tailText(perObject!)).toContain('permission denied for schema public'); + expect(perObject!.args[1]).toMatchObject({ object: 'invoice' }); }); it('never logs "Schema sync complete" at info over a pass that lost DDL', async () => { @@ -150,7 +175,10 @@ describe('ObjectQLPlugin.syncRegisteredSchemas() — per-object and summary leve const summary = rec.at('error').find((r) => /finished with/.test(r.message)); expect(summary).toBeDefined(); expect(summary!.message).toContain('2 FAILED'); - expect(summary!.meta).toMatchObject({ failed: 2, synced: 0 }); + // No single Error owns a whole-pass summary, so slot 2 is `undefined` and + // the counts ride in slot 3. + expect(summary!.args[0]).toBeUndefined(); + expect(summary!.args[1]).toMatchObject({ failed: 2, synced: 0 }); }); it('still says "complete" at info when every object synced', async () => { diff --git a/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts b/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts index 0014d9071e..00f794ba11 100644 --- a/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts +++ b/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts @@ -140,16 +140,23 @@ describe('rearmSuspendedWaitTimers — durability degradations are errors (#4632 await first.execute('wait_flow'); await new Promise((r) => setTimeout(r, 10)); // let the 1ms deadline lapse - // A fresh "process" that never registered the flow: resume() cannot run it. - const amnesiac = new AutomationEngine(silent()); - amnesiac.setSuspendedRunStore(store); + // `resume()` normally REPORTS machine-state problems in its result rather + // than throwing, so the only thing that reaches this catch is a genuine + // fault on the resume path (a driver blowing up, the store vanishing + // mid-resume). Stand one in. + const brokenEngine = { + async resume() { + throw new Error('datasource connection lost mid-resume'); + }, + } as never; const cap = capturingLogger(); - await rearmSuspendedWaitTimers(amnesiac, store, undefined, cap.logger); + await rearmSuspendedWaitTimers(brokenEngine, store, undefined, cap.logger); expect(cap.text('error')).toMatch(/is OVERDUE and could not be resumed/); expect(cap.text('error')).toMatch(/nothing will\s+wake it again/); expect(cap.text('error')).toMatch(/resume\('/); + expect(cap.text('error')).toContain('datasource connection lost mid-resume'); }); });