diff --git a/.changeset/registry-collision-order-symmetric.md b/.changeset/registry-collision-order-symmetric.md new file mode 100644 index 0000000000..ed9a084abd --- /dev/null +++ b/.changeset/registry-collision-order-symmetric.md @@ -0,0 +1,41 @@ +--- +'@objectstack/objectql': patch +--- + +fix(objectql): the `[Registry] Collision` warning fires in the cold-boot order too (#12027) + +The artifact-vs-DB collision warning was order-asymmetric, and silent in the +order a kernel boot actually produces. It was guarded on `packageId &&`, so it +spoke only when the PACKAGE registered second — but the artifact reaches the +registry in kernel Phase 1 (`AppPlugin.init` -> `manifest.register`) and the +`sys_metadata` overlay is rehydrated in Phase 2 (`ObjectQLPlugin.start` -> +`loadMetaFromDb`), under the bare name with no package id. The kernel runs +init-all then start-all, so at boot the overlay is ALWAYS the second arrival — +the exact order the guard excluded. The direction that did warn is the +late-registration one: a marketplace install, a post-`start()` +`manifest.register`, an HMR reload. + +The consequence is worse than a missing line, because the mechanism looked +sound to anyone who had seen it work: ADR-0005 says this warning is what makes +the silent shadowing "discoverable in startup logs", and in the only order +startup produces it was not discoverable at all. Measured on a real +`@objectstack/example-crm` boot before the fix: one stored `view` overlay of a +packaged view produced 0 collision lines and 4 silent shadowings (the container +plus its three expanded ViewItems). + +The cold-boot direction now warns with its own message rather than a widened +version of the existing one. Both orders end in the same state — the runtime +row wins either way — but the event differs, and the event is what an operator +acts on: a package that is dead on arrival behind a row that predates it, +versus a stored row taking over a definition this process just loaded from +code. Which definition wins is unchanged in both orders, and pinned as such. + +Graded `patch`: this adds a diagnostic to a path that printed nothing. No API +changes, no accept/reject behaviour changes, and resolution order is untouched. +The one operator-visible effect worth stating is the log itself — a deployment +that customizes packaged metadata will see one new `[Registry] Collision` line +per shadowed name per process, where it previously saw none. Volume was +measured rather than assumed: 0 lines on a stock boot (a stock `sys_metadata` +holds no overlay of a packaged name), and the line marks the transition into +the bare slot rather than the state, so the read-side hydration and the +write-through do not re-emit it on later reads and writes. diff --git a/packages/objectql/src/registry-collision-order.test.ts b/packages/objectql/src/registry-collision-order.test.ts new file mode 100644 index 0000000000..a97dedc0d8 --- /dev/null +++ b/packages/objectql/src/registry-collision-order.test.ts @@ -0,0 +1,264 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#12027] The artifact-vs-DB collision warning fires in BOTH registration + * orders — including the one a cold boot actually produces. + * + * ## What was wrong, and why "the warning is missing" is the wrong description + * + * The warning existed and worked. It was guarded on `packageId &&`, so it + * spoke only when the PACKAGE registered second. A kernel boot cannot produce + * that order: + * + * ``` + * Phase 1 init AppPlugin.init -> manifest.register -> ObjectQL.registerApp + * -> registerItem(type, item, 'name', packageId) // pkg:name + * Phase 2 start ObjectQLPlugin.start -> restoreMetadataFromDb + * -> protocol.loadMetaFromDb -> hydrateOverlayIntoRegistry + * -> registerItem(type, item, 'name') // bare name + * ``` + * + * The kernel runs init-all THEN start-all, so the artifact is ALWAYS the first + * arrival at boot and the overlay always the second — the exact order the + * `packageId &&` half excluded. Measured on a real `@objectstack/example-crm` + * boot: one stored `view` overlay of a packaged view produced **0** collision + * lines and 4 silent shadowings (the container plus its three expanded + * ViewItems). So a reader who had ever SEEN the warning fire (a marketplace + * install, an HMR reload — the late-registration order) had every reason to + * believe the mechanism was sound, while the case it missed was the one that + * happens on every boot. + * + * That is why the first case below is the load-bearing one: a pin written only + * for the direction that already warned would pass on `origin/main` and prove + * nothing. + * + * ## Two messages, not one widened message + * + * Both orders end in the same state — `getItem` checks the bare key first, so + * the runtime row wins either way (pinned at the bottom of this file, because + * a diagnostic repair must not move precedence). What differs is the EVENT, + * and the event is what an operator acts on: a package that is dead on arrival + * behind a row that predates it, versus a stored row taking over a definition + * this process just loaded from code. `distinguishable messages` pins that a + * later "one message fits both" simplification cannot silently drop it. + * + * ## The narrowing cases are not decoration + * + * A warning that fires on every boot of a normal deployment says nothing (the + * #12015 ruling, one warning over). Three of the cases below are the volume + * bound: no packaged item means no line at all, a re-registration of the same + * overlay is silent (the line marks the transition, not the state — otherwise + * the read-side hydration would warn once per GET), and a composite entry that + * is itself an overlay or a tenant-authored body is not a packaged definition + * being shadowed. + */ + +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; +import { SchemaRegistry } from './registry'; + +const PKG = 'com.acme.crm'; + +/** Every `[Registry] Collision` line emitted while `fn` runs. */ +function collisionsDuring(fn: () => void): string[] { + const spy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + try { + fn(); + return spy.mock.calls + .map((args) => args.map((a) => String(a)).join(' ')) + .filter((line) => line.includes('[Registry] Collision')); + } finally { + spy.mockRestore(); + } +} + +describe('[#12027] SchemaRegistry collision warning is order-symmetric', () => { + let registry: SchemaRegistry; + + beforeEach(() => { + registry = new SchemaRegistry({ multiTenant: false }); + registry.logLevel = 'silent'; + }); + afterEach(() => { + vi.restoreAllMocks(); + }); + + it('COMMON COLD-BOOT ORDER — artifact first, then the sys_metadata row: warns', () => { + // The case that was silent on `origin/main`. Phase 1 registers the packaged + // flow under `pkg:name`; Phase 2 hydrates the stored row under the bare name. + registry.registerItem('flow', { name: 'nightly_sync', label: 'packaged' }, 'name', PKG); + + const lines = collisionsDuring(() => { + registry.registerItem('flow', { name: 'nightly_sync', label: 'runtime' }, 'name'); + }); + + expect(lines).toHaveLength(1); + // The line has to carry the three things an operator needs: which item, + // which package lost, and what now serves. + expect(lines[0]).toContain('flow/nightly_sync'); + expect(lines[0]).toContain(PKG); + expect(lines[0]).toContain('shadows the package value'); + }); + + it('LATE-REGISTRATION ORDER — sys_metadata row first, then the package: still warns', () => { + // Unchanged behaviour, pinned so the repair cannot trade one order for the + // other. This order is a marketplace install / HMR reload, not a boot. + registry.registerItem('flow', { name: 'nightly_sync', label: 'runtime' }, 'name'); + + const lines = collisionsDuring(() => { + registry.registerItem('flow', { name: 'nightly_sync', label: 'packaged' }, 'name', PKG); + }); + + expect(lines).toHaveLength(1); + expect(lines[0]).toContain('flow/nightly_sync'); + expect(lines[0]).toContain('will shadow the package value'); + }); + + it('the two orders produce DISTINGUISHABLE messages', () => { + // Same end state, different event. A reader must be able to tell "your new + // package is dead on arrival" from "a stored row just took over"; a single + // message widened to fit both would have to drop which one arrived second. + const bootOrder = collisionsDuring(() => { + registry.registerItem('page', { name: 'home', label: 'packaged' }, 'name', PKG); + registry.registerItem('page', { name: 'home', label: 'runtime' }, 'name'); + }); + const lateOrder = collisionsDuring(() => { + registry.registerItem('doc', { name: 'home', label: 'runtime' }, 'name'); + registry.registerItem('doc', { name: 'home', label: 'packaged' }, 'name', PKG); + }); + + expect(bootOrder).toHaveLength(1); + expect(lateOrder).toHaveLength(1); + expect(bootOrder[0]).not.toEqual(lateOrder[0]); + // The tense is the discriminator, and it is the accurate part: one has + // already happened, the other is what the arriving package is walking into. + expect(bootOrder[0]).toContain('has just been registered from sys_metadata'); + expect(lateOrder[0]).toContain('already'); + }); + + it('a discriminated bundle member is judged against its OWN member key', () => { + // [#7730] `email_template` is keyed by (name, locale). The overlay slot the + // warning asks about is the member with the SAME discriminator, so the + // packaged `zh-CN` member and the stored `zh-CN` row collide. + registry.registerItem( + 'email_template', + { name: 'welcome', locale: 'zh-CN', subject: 'packaged' }, + 'name', + PKG, + ); + + const lines = collisionsDuring(() => { + registry.registerItem( + 'email_template', + { name: 'welcome', locale: 'zh-CN', subject: 'runtime' }, + 'name', + ); + }); + + expect(lines).toHaveLength(1); + expect(lines[0]).toContain('email_template/welcome'); + }); + + describe('what is NOT a collision — the volume bound', () => { + it('a runtime row with no packaged counterpart is silent', () => { + const lines = collisionsDuring(() => { + registry.registerItem('flow', { name: 'tenant_only', label: 'runtime' }, 'name'); + }); + expect(lines).toEqual([]); + }); + + it('re-registering the SAME overlay warns once, not once per registration', () => { + // The read-side hydration (`getMetaItems`) and the write-through both + // re-register an overlay that is already in the bare slot. Warning on the + // STATE rather than the transition would put a line in the log on every + // GET of a customized item. + registry.registerItem('flow', { name: 'nightly_sync', label: 'packaged' }, 'name', PKG); + + const first = collisionsDuring(() => { + registry.registerItem('flow', { name: 'nightly_sync', label: 'runtime' }, 'name'); + }); + const repeats = collisionsDuring(() => { + registry.registerItem('flow', { name: 'nightly_sync', label: 'runtime v2' }, 'name'); + registry.registerItem('flow', { name: 'nightly_sync', label: 'runtime v3' }, 'name'); + }); + + expect(first).toHaveLength(1); + expect(repeats).toEqual([]); + }); + + it('a composite entry carrying the sys_metadata sentinel is not a packaged definition', () => { + // `_packageId: 'sys_metadata'` marks an overlay bound to no package + // (#4636). Nothing shipped from code here, so nothing is being shadowed. + registry.registerItem( + 'flow', + { name: 'nightly_sync', _packageId: 'sys_metadata' }, + 'name', + 'sys_metadata', + ); + const lines = collisionsDuring(() => { + registry.registerItem('flow', { name: 'nightly_sync', label: 'runtime' }, 'name'); + }); + expect(lines).toEqual([]); + }); + + it('a tenant-authored composite entry is not a packaged definition', () => { + // ADR-0010 `_provenance: 'org'` — a tenant's own item that came back from + // a kernel rebuild keyed by a package id (cloud#970). `isCodeArtifactBody` + // is the single answer to "does a code package ship this?", and this is + // not it. + registry.registerItem( + 'flow', + { name: 'nightly_sync', _packageId: PKG, _provenance: 'org' }, + 'name', + PKG, + ); + const lines = collisionsDuring(() => { + registry.registerItem('flow', { name: 'nightly_sync', label: 'runtime' }, 'name'); + }); + expect(lines).toEqual([]); + }); + + it('a package re-registering its own item is silent in both directions', () => { + const lines = collisionsDuring(() => { + registry.registerItem('flow', { name: 'nightly_sync', label: 'v1' }, 'name', PKG); + registry.registerItem('flow', { name: 'nightly_sync', label: 'v2' }, 'name', PKG); + }); + expect(lines).toEqual([]); + }); + + it('two packages shipping the same bare name is coexistence, not shadowing', () => { + // ADR-0048 §3.4 — distinct composite keys, package-scoped resolution. + // Neither registration takes the bare slot, so this guard never speaks. + const lines = collisionsDuring(() => { + registry.registerItem('page', { name: 'home', label: 'CRM' }, 'name', PKG); + registry.registerItem('page', { name: 'home', label: 'HR' }, 'name', 'com.acme.hr'); + }); + expect(lines).toEqual([]); + }); + }); + + describe('the diagnostic repair moves nothing', () => { + it('the runtime row still wins in BOTH orders (ADR-0005 overlay precedence)', () => { + // Clause ② in test form: this card adds a line to a path that printed + // nothing. Which definition wins is untouched, and untouched IN BOTH + // ORDERS — a warning that changed precedence would be a different card. + const bootOrder = new SchemaRegistry({ multiTenant: false }); + bootOrder.logLevel = 'silent'; + collisionsDuring(() => { + bootOrder.registerItem('flow', { name: 'nightly_sync', label: 'packaged' }, 'name', PKG); + bootOrder.registerItem('flow', { name: 'nightly_sync', label: 'runtime' }, 'name'); + }); + expect(bootOrder.getItem('flow', 'nightly_sync')?.label).toBe('runtime'); + expect(bootOrder.getItem('flow', 'nightly_sync', PKG)?.label).toBe('runtime'); + // …and the packaged definition is still reachable as an artifact. + expect(bootOrder.getArtifactItem('flow', 'nightly_sync', PKG)?.label).toBe('packaged'); + + const lateOrder = new SchemaRegistry({ multiTenant: false }); + lateOrder.logLevel = 'silent'; + collisionsDuring(() => { + lateOrder.registerItem('flow', { name: 'nightly_sync', label: 'runtime' }, 'name'); + lateOrder.registerItem('flow', { name: 'nightly_sync', label: 'packaged' }, 'name', PKG); + }); + expect(lateOrder.getItem('flow', 'nightly_sync')?.label).toBe('runtime'); + }); + }); +}); diff --git a/packages/objectql/src/registry.ts b/packages/objectql/src/registry.ts index 6017454437..2b289e739f 100644 --- a/packages/objectql/src/registry.ts +++ b/packages/objectql/src/registry.ts @@ -2911,7 +2911,12 @@ export class SchemaRegistry { // the DB row silently shadow the new artifact value. That is correct // ADR-0005 behavior, but the silent shadowing can surprise package // authors and operators. Log a single warning so the situation is - // discoverable in startup logs. + // discoverable in the logs. + // + // [#12027] This guard covers ONE of the two orders — the package arriving + // second, which at runtime means a late registration (marketplace install, + // HMR reload), never a cold boot. The cold-boot order is covered by the + // second guard below; read the two together. // [#7730] `bareKey` rather than `baseName`: for a discriminated type the // overlay slot this warning asks about is the bundle member with the SAME // discriminator (`auth.welcome@zh-CN`), not the name on its own — which is @@ -2929,6 +2934,78 @@ export class SchemaRegistry { } } + // [#12027] THE SAME COLLISION, IN THE ORDER A COLD BOOT ACTUALLY PRODUCES. + // + // The guard above carries `packageId &&`, so it only ever speaks when the + // PACKAGE registers second. A kernel boot cannot produce that order: the + // artifact reaches this registry in kernel Phase 1 (AppPlugin.init -> + // `manifest.register` -> `ObjectQL.registerApp`), and `sys_metadata` + // rehydration runs in Phase 2 (`ObjectQLPlugin.start` -> + // `restoreMetadataFromDb` -> `loadMetaFromDb` -> the protocol's + // `hydrateOverlayIntoRegistry`, which registers under the BARE key with no + // packageId). Phase 1 strictly precedes Phase 2, so at boot the overlay is + // always the second arrival and the guard above is structurally unreachable + // — it fires only for a LATE package registration (marketplace install, a + // post-`start()` `manifest.register`, an HMR reload). + // + // Measured on a real `@objectstack/example-crm` boot before this landed: a + // stored `view` overlay of a packaged view produced 0 `[Registry] Collision` + // lines and 4 silent shadowings (the container plus its three expanded + // ViewItems). ADR-0005 §Collision-warning says this warning is what makes + // the silent shadowing "discoverable in startup logs"; in the only order + // startup produces, it was not discoverable at all. + // + // ## Why this is a SECOND message and not one message widened to fit both + // + // The two orders are the same end state (`getItem` checks the bare key + // first, so the runtime row wins either way) reached by two different + // events, and the event is the part an operator has to act on. Above: a + // package just arrived and is DEAD ON ARRIVAL behind a row that predates + // it. Here: a stored row just took over a definition this process already + // loaded from code. A single message would have to drop which one arrived + // second, which is precisely the fact that tells the reader whether they + // are looking at a failed install or at a customization taking effect. + // + // ## Why it says "may be deliberate", and why it still fires by default + // + // Unlike the order above — where `!dbOnly._packageId` narrows to a + // package-LESS row, i.e. an accidental name collision — this direction + // cannot tell a deliberate customization from an accidental collision: the + // protocol merges the artifact's `_packageId`/`_provenance` envelope onto + // the overlay body (ADR-0010 §3.3 `mergeArtifactProtection`) before it + // reaches this method, so both look identical here. The message therefore + // states the consequence and both readings rather than accusing. It stays + // at `warn` because a diagnostic nobody sees is the defect being fixed. + // + // Volume, measured rather than assumed (the #12015 discipline — a warning + // that fires on every boot of a stock deployment is saying nothing): + // 0 lines on a stock CRM boot, because a stock `sys_metadata` holds no + // overlay of a packaged name; thereafter once per shadowed name per + // process. `!collection.has(bareKey)` is what bounds it — the line marks + // the TRANSITION (a bare slot that was empty is now taken), not the state, + // so the read-side hydration and the write-through, which re-register the + // same overlay on later reads and writes, stay silent. + if (!packageId && !collection.has(bareKey)) { + let shadowed: any; + for (const [key, existing] of collection) { + if (key !== bareKey && key.endsWith(`:${bareKey}`) && isCodeArtifactBody(existing)) { + shadowed = existing; + break; + } + } + if (shadowed) { + console.warn( + `[Registry] Collision: ${type}/${baseName} is shipped by package ` + + `"${shadowed._packageId}" and a runtime-authored row with the same name has ` + + `just been registered from sys_metadata. The runtime row now shadows the ` + + `package value (ADR-0005 overlay precedence): every read of ${type}/${baseName} ` + + `serves the stored row, not the packaged definition. That is the sanctioned ` + + `path when the row is a deliberate customization — if it is not one, delete ` + + `the sys_metadata row (or rename one of the two) so the package value serves.`, + ); + } + } + collection.set(storageKey, item); this.log(`[Registry] Registered ${type}: ${storageKey}`); }