Skip to content

Commit 4c45be1

Browse files
os-zhuangclaude
andauthored
fix(convention): 持久性降级记 error 而非 warn —— 把 #4460 定成规则,并给规则装上机械检查 (#4632) (#4730)
* 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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Br2xsJsczFsTR9bvbh2Ny * 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<string, any>): void error(message: string, error?: Error, meta?: Record<string, any>): 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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Br2xsJsczFsTR9bvbh2Ny --------- Co-authored-by: Claude <noreply@anthropic.com>
1 parent 51c5227 commit 4c45be1

12 files changed

Lines changed: 1263 additions & 23 deletions

File tree

Lines changed: 54 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,54 @@
1+
---
2+
"@objectstack/objectql": patch
3+
"@objectstack/service-automation": patch
4+
---
5+
6+
fix(convention): a best-effort degradation that costs DURABILITY logs `error`, not `warn` — and a gate that enforces it (#4632)
7+
8+
#4420: the durable suspended-run store attached to a table that was never
9+
created. Every write failed into a `warn` nobody read, every restart dropped all
10+
in-flight approvals, and the process reported perfect health the entire time —
11+
the symptom surfaced a release after the cause. #4460 raised that **one** site to
12+
`error`. This makes it the rule, because the *class* is what recurs.
13+
14+
**The rule** (AGENTS.md → "Degradation log levels") is a question, not an
15+
adjective, so an agent can apply it while writing the `catch`:
16+
17+
> After the degradation, does the system still look "normal" from the outside,
18+
> while something it claims is persisted has not actually landed?
19+
> Yes → `error`. No → `warn`/`info` is right.
20+
21+
An `error` here owes two things in its first line: the **consequence** (what is
22+
not durable, and that the system will keep looking healthy anyway) and the
23+
**fix** (the composition change that restores durability, or the explicit opt-out
24+
that makes the degradation deliberate). Say it once, not once per failed write.
25+
26+
**Sites raised to `error`** — each was reviewed individually; escalating a
27+
functional degradation is the mirror-image failure and was deliberately avoided:
28+
29+
| Where | What was silently lost |
30+
|:---|:---|
31+
| `objectql` schema sync, per object | DDL never ran — the object stays registered, routed and rendered while its table/columns do not exist |
32+
| `objectql` schema sync, summary | `info: Schema sync complete` printed over a pass with failures; now an `error` naming the count |
33+
| `objectql` reload-time schema sync | a Studio edit adds a field, the UI shows it, the API accepts it, the column was never created |
34+
| `ObjectQL.syncSchemas()` | an **empty** `catch` — marketplace install and template seeding wrote into tables this failure means do not exist, then reported success |
35+
| `service-automation` wait-timer re-arm (4 paths) | runs stay persisted but nothing re-arms them: every approval paused before the restart hangs forever |
36+
37+
**Deliberately left at `warn`** — the rule cuts both ways, and over-applying it
38+
trains everyone to skim `error`: the batch→sequential schema-sync fallback (it
39+
*recovers*), and "no job service is registered" on the re-arm path (a declared
40+
absence in a host that never composed auto-resume — nothing was promised and
41+
then broken).
42+
43+
**It has teeth.** A convention that lives only in AGENTS.md is the same
44+
"declared ≠ enforced" shape this repo keeps paying to fix, so
45+
`pnpm check:durability-log-level` walks the AST for `catch` blocks guarding a
46+
declared vocabulary of durability-critical operations and fails when one
47+
degrades below `error` without rethrowing. It follows same-file helpers (so
48+
extracting a reporter cannot quietly defeat it) and ships its own `--self-test`.
49+
Deliberately narrow: it cannot *discover* a new durability seam, only stop known
50+
ones from regressing — extend `DURABILITY_CRITICAL_CALLEES` in the same PR that
51+
fixes a new one.
52+
53+
No API, schema or behaviour changes — only the level, and the text, of what
54+
already-failing paths report.

.github/workflows/lint.yml

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -188,6 +188,22 @@ jobs:
188188
- name: Init-service declaration guard
189189
run: pnpm check:init-service-contract
190190

191+
# Durability-degradation log-level guard (#4632). #4460 raised ONE
192+
# best-effort degradation from warn to error — the durable suspended-run
193+
# store writing to a table that never existed (#4420), which looked healthy
194+
# while every restart dropped all in-flight approvals. The rule that fix
195+
# implied now lives in AGENTS.md ("Degradation log levels"): a degradation
196+
# that costs only FUNCTIONALITY may warn; one that costs DURABILITY must
197+
# error, naming the consequence and the fix. This gate is what keeps that
198+
# from being one more declared-but-unenforced convention — it walks the AST
199+
# for catch blocks guarding a declared vocabulary of durability-critical
200+
# operations (schema DDL, suspended-run re-arm) and fails when one degrades
201+
# below `error` without rethrowing. Deliberately narrow: it cannot discover
202+
# a new durability seam, only stop known ones from regressing. Runs its own
203+
# --self-test first.
204+
- name: Durability-degradation log-level guard
205+
run: pnpm check:durability-log-level
206+
191207
# Release-notes drift guard: the platform is one version-locked train, so
192208
# every released @objectstack/spec major must have a curated, navigable
193209
# release page at content/docs/releases/v<major>.mdx. Catches the gap that

AGENTS.md

Lines changed: 63 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -538,6 +538,69 @@ composition with its real services, or do not claim an answer.
538538

539539
---
540540

541+
## Degradation log levels — `warn` vs `error`
542+
543+
Nearly every `catch` in this repo is a best-effort degradation, and nearly every
544+
one of them logs `warn`. That default is wrong for a specific, recurring class,
545+
and the cost of getting it wrong is not noise — it is silent data loss. Decide
546+
the level with **one question**, not with an adjective:
547+
548+
> **After the degradation, does the system still look "normal" from the outside,
549+
> while something it claims is persisted has not actually landed?**
550+
> **Yes → `error`. No → `warn`/`info` is right.**
551+
552+
- **Functional degradation → `warn` / `info`.** A screen is missing, a trigger is
553+
not armed, a capability is not enabled, an optional service never showed up.
554+
The system is *visibly* smaller than it should be, and the next person to use
555+
the missing thing finds out. `ScheduleTriggerPlugin: job service not available
556+
— scheduled flows will not run until one is registered` is exactly right at
557+
`warn`.
558+
- **Durability / data-consistency degradation → `error`.** A write that claims
559+
to persist does not, DDL that was supposed to run did not, persisted state and
560+
runtime state disagree. Nothing looks broken; the loss surfaces a release
561+
later, to someone who cannot connect it to this line.
562+
563+
**Why this is a rule and not a preference.** #4420: the durable suspended-run
564+
store attached to a table that was never created, every write failed into a
565+
`warn` nobody read, and every restart dropped all in-flight approvals — the
566+
symptom surfaced a release after the cause. #4460 raised that one site to
567+
`error`; #4632 made it the rule, because the *class* is what recurs. It is the
568+
same failure Prime Directive #10 names — advertising a capability (here:
569+
durability) the runtime does not deliver — and the same instinct as "Absence must
570+
be loud" above: **prefer failing to falling back**, and when you must fall back,
571+
say what was lost.
572+
573+
**An `error` here owes two things**, both, in the first line it prints
574+
(`packages/services/service-automation/src/plugin.ts` `start()` is the reference
575+
text):
576+
577+
1. the **consequence**, concretely — *what* is not durable, and that the system
578+
will keep looking healthy anyway;
579+
2. the **fix** — the composition/config change that restores durability, or the
580+
explicit opt-out that makes the degradation deliberate (`suspendedRunStore:
581+
'memory'`, `OS_SKIP_SCHEMA_SYNC`).
582+
583+
Say it **once**, at the first degradation, not once per failed write.
584+
585+
**Do not over-apply it.** Escalating a functional degradation to `error` is the
586+
mirror-image failure: it trains everyone to skim `error`, which is what made the
587+
#4420 `warn` unreadable in the first place. In particular, an `if (!service)`
588+
composition branch is usually functional and usually belongs at `warn`; a `catch`
589+
around a write, a DDL call, or a store initialization is where this rule bites.
590+
591+
**It has teeth** (a rule this repo only writes down is the very "declared ≠
592+
enforced" shape it keeps paying to fix): `pnpm check:durability-log-level` walks
593+
the AST for `catch` blocks guarding a declared vocabulary of durability-critical
594+
operations and fails when one logs below `error` without rethrowing. It is
595+
deliberately narrow — it cannot *discover* a new durability seam, only stop the
596+
known ones from regressing. Found a new one? Add it to
597+
`DURABILITY_CRITICAL_CALLEES` in `scripts/check-durability-degradation-log-level.mjs`
598+
in the same PR that fixes it. Accepted exceptions live in
599+
`scripts/durability-degradation.baseline.json`, hand-edited with a reason and
600+
shrink-only.
601+
602+
---
603+
541604
## Post-Task Checklist
542605

543606
1. `pnpm test` — verify nothing broke. Touched a type-check-covered package? `pnpm typecheck` too.

package.json

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -44,6 +44,7 @@
4444
"check:error-code-casing": "node scripts/check-error-code-casing.mjs --self-test && node scripts/check-error-code-casing.mjs",
4545
"check:wildcard-fallthrough": "node scripts/check-wildcard-fallthrough.mjs --self-test && node scripts/check-wildcard-fallthrough.mjs",
4646
"check:init-service-contract": "node scripts/check-init-service-contract.mjs --self-test && node scripts/check-init-service-contract.mjs",
47+
"check:durability-log-level": "node scripts/check-durability-degradation-log-level.mjs --self-test && node scripts/check-durability-degradation-log-level.mjs",
4748
"check:console-sha": "node scripts/check-console-sha.mjs",
4849
"check:release-notes": "node scripts/check-release-notes.mjs",
4950
"check:node-version": "node scripts/check-node-version.mjs",

packages/objectql/src/engine.ts

Lines changed: 18 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -5337,8 +5337,24 @@ export class ObjectQL implements IObjectQLEngine {
53375337
if (typeof (driver as any).syncSchema === 'function') {
53385338
try {
53395339
await (driver as any).syncSchema(tableName, obj);
5340-
} catch {
5341-
// best effort — log suppressed to avoid noise on already-synced tables
5340+
} catch (e: unknown) {
5341+
// #4632 — this catch used to be empty, with the comment "log
5342+
// suppressed to avoid noise on already-synced tables". Suppressing an
5343+
// already-synced no-op is not what it did: `syncSchema` is required to
5344+
// be idempotent (see this method's doc comment), so a driver that
5345+
// reaches this catch did NOT sync. The only callers are runtime
5346+
// installs — marketplace plugin install, template seeding — which go
5347+
// on to INSERT into a table this failure means does not exist, and
5348+
// then report the install as successful. Nothing that claims to be
5349+
// persisted afterwards is.
5350+
this.logger.error(
5351+
`Schema sync FAILED for object '${obj.name}' — its table/collection was NOT created or altered, yet the object is ` +
5352+
`registered and will be written to: those writes will fail, or drop the columns that were never created. ` +
5353+
`Any seeding or install step that continues past this point is not durable. ` +
5354+
`Fix the driver error below, then re-run the install/sync.`,
5355+
e as Error,
5356+
{ object: obj.name, tableName, driver: (driver as any)?.name },
5357+
);
53425358
}
53435359
}
53445360
}

packages/objectql/src/plugin.ts

Lines changed: 66 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -402,9 +402,19 @@ export class ObjectQLPlugin implements Plugin {
402402
try {
403403
await this.syncRegisteredSchemas(ctx);
404404
} catch (e: any) {
405-
ctx.logger.warn('[ObjectQLPlugin] reload-time schema sync failed', {
406-
error: e?.message ?? String(e),
407-
});
405+
// #4632 — durability degradation, not a functional one. A
406+
// Studio edit that adds a field lands in metadata (the UI
407+
// shows it, the API accepts it, the author sees a saved
408+
// record) while the column it needs was never created. The
409+
// author is told the value was saved and it was not.
410+
// `Logger.error` is `(message, error?, meta?)` — the second
411+
// slot is the Error, NOT the context bag `warn` takes there.
412+
ctx.logger.error(
413+
'[ObjectQLPlugin] reload-time schema sync FAILED — objects changed by this metadata reload are live in the ' +
414+
'registry, UI and API, but their new/altered columns were NOT created: writes against them are accepted and ' +
415+
'then silently lost or rejected. Fix the driver error below and reload again (or restart) to re-run DDL.',
416+
e instanceof Error ? e : new Error(String(e?.message ?? e)),
417+
);
408418
}
409419
});
410420
await this.reloadSchemaSync;
@@ -910,6 +920,42 @@ export class ObjectQLPlugin implements Plugin {
910920

911921
let synced = 0;
912922
let skipped = 0;
923+
let failed = 0;
924+
925+
/**
926+
* #4632 — a failed schema sync is a DURABILITY degradation, not a
927+
* functional one, so it is reported at `error`.
928+
*
929+
* The object stays in the registry, keeps its REST routes, keeps rendering
930+
* in the UI — the system looks completely healthy — while its table or its
931+
* newly-declared columns were never created. Writes then fail, or (on
932+
* drivers that accept unknown attributes) succeed while silently dropping
933+
* the un-created column: the thing the system claims it persisted is not
934+
* on disk. That is exactly the #4420 shape one layer up from the durable
935+
* suspended-run store #4460 fixed, so it carries the same obligation —
936+
* name the CONSEQUENCE and the FIX at the first failure.
937+
*/
938+
const reportSyncFailure = (
939+
obj: any,
940+
tableName: string,
941+
driverName: string,
942+
err: unknown,
943+
): void => {
944+
failed++;
945+
// NB `Logger.error` is `(message, error?, meta?)` — the Error goes in the
946+
// SECOND slot, unlike `warn`'s `(message, meta?)`. This call was written
947+
// as a mechanical warn→error swap and the mismatch only surfaced in the
948+
// DTS build, never in a test run.
949+
ctx.logger.error(
950+
`Schema sync FAILED for object '${obj?.name}' — its table/columns were NOT created or altered, but the object stays ` +
951+
`registered and served: writes to it will fail, or silently drop the columns that were never created. ` +
952+
`Nothing that claims to be persisted for this object is guaranteed to be on disk. ` +
953+
`Fix the driver/datasource error below and restart (or trigger a metadata reload) to re-run DDL; ` +
954+
`if this deployment manages DDL out-of-band, set \`skipSchemaSync\` / OS_SKIP_SCHEMA_SYNC so the omission is deliberate.`,
955+
err instanceof Error ? err : new Error(String(err)),
956+
{ object: obj?.name, tableName, driver: driverName },
957+
);
958+
};
913959

914960
// Group objects by driver for potential batch optimization
915961
const driverGroups = new Map<any, Array<{ obj: any; tableName: string }>>();
@@ -993,18 +1039,15 @@ export class ObjectQLPlugin implements Plugin {
9931039
driver: driver.name,
9941040
error: e instanceof Error ? e.message : String(e),
9951041
});
996-
// Fallback: sequential sync for this driver's objects
1042+
// Fallback: sequential sync for this driver's objects. The batch
1043+
// warn above is correct at `warn` — it RECOVERS here; only a
1044+
// sequential failure actually loses the DDL.
9971045
for (const { obj, tableName } of entries) {
9981046
try {
9991047
await driver.syncSchema(tableName, obj);
10001048
synced++;
10011049
} catch (seqErr: unknown) {
1002-
ctx.logger.warn('Failed to sync schema for object', {
1003-
object: obj.name,
1004-
tableName,
1005-
driver: driver.name,
1006-
error: seqErr instanceof Error ? seqErr.message : String(seqErr),
1007-
});
1050+
reportSyncFailure(obj, tableName, driver.name, seqErr);
10081051
}
10091052
}
10101053
}
@@ -1015,18 +1058,24 @@ export class ObjectQLPlugin implements Plugin {
10151058
await driver.syncSchema(tableName, obj);
10161059
synced++;
10171060
} catch (e: unknown) {
1018-
ctx.logger.warn('Failed to sync schema for object', {
1019-
object: obj.name,
1020-
tableName,
1021-
driver: driver.name,
1022-
error: e instanceof Error ? e.message : String(e),
1023-
});
1061+
reportSyncFailure(obj, tableName, driver.name, e);
10241062
}
10251063
}
10261064
}
10271065
}
10281066

1029-
if (synced > 0 || skipped > 0) {
1067+
// #4632 — never claim "complete" over a pass that lost DDL. The old line
1068+
// logged `info: Schema sync complete` after any number of failures, which
1069+
// is the "looks normal" half of the accident: the only honest summary of a
1070+
// pass with failures is an error.
1071+
if (failed > 0) {
1072+
ctx.logger.error(
1073+
`Schema sync finished with ${failed} FAILED object(s) — those objects are registered and served but their storage was ` +
1074+
`never created or altered; writes to them are not durable. See the per-object errors above for the driver failure and the fix.`,
1075+
undefined,
1076+
{ synced, skipped, failed, total: allObjects.length },
1077+
);
1078+
} else if (synced > 0 || skipped > 0) {
10301079
ctx.logger.info('Schema sync complete', { synced, skipped, total: allObjects.length });
10311080
}
10321081
}

0 commit comments

Comments
 (0)