From bc11f40cf6af286300061bd0c13cb7e5fc9dfd3d Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 4 Aug 2026 14:06:43 +0000 Subject: [PATCH] fix(metadata): invalidate the list cache AFTER the storage delete lands (#5259) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `MetadataManager.unregister()` dropped the registry entry and called `invalidateListCache(type)` BEFORE awaiting `loader.delete()`. Those two steps are separated by a real await window (one DB round-trip per writable loader), and inside it the manager held a state that exists nowhere else: registry already empty, loader not yet empty. `list()` merges the two, so a read arriving in that window missed the just-cleared cache, assembled the still-stored row into its answer, and memoized it as a COMPLETE read — the full 30s healthy TTL, because no loader threw and #5184's 2s degraded TTL therefore never applied. Nothing invalidated again once the delete landed (`notifyWatchers()` does not touch `listCache`), so an item gone from storage kept being enumerated for up to half a minute while `get()` said it was gone. Fixed by ordering, not by a second invalidation. `register()` never had this defect because it writes the registry first and the registry outranks every loader in the merge, so its save window already shows the post-write state. The invariant is therefore not "invalidate early" but invalidate LAST, once every store already holds the state being announced. `unregister()` now deletes from storage first, then drops the registry entry and invalidates with nothing awaited between them, then publishes and announces (#5219's invalidate-before-notify bar, unchanged). Composes with #5253's single-flight rather than duplicating it: a read still in flight when the delete lands cannot be reached by dropping `listCache` — it has not written its entry yet and would write the pre-delete answer afterwards. `invalidateListCache()` also retracts that read's `inflightListReads` registration, so it resolves for the callers already waiting on it but loses the right to memoize, while a caller arriving later starts a fresh read. A failing `loader.delete()` used to `logger.warn` and continue. Per AGENTS.md "Degradation log levels" that is durability degradation, not functional: `unregister()` resolves normally, the caller is told the delete succeeded, and the surviving row is read straight back out of storage — permanently, since nothing retries it. It now logs at `error`, once per un-deleted item, naming the consequence and the fix, and the seam is named `deleteMetaItemFromLoader` so `check:durability-log-level` covers it (22 -> 23 seams, all loud). The registry entry is still dropped in that case, deliberately: the loader still holds the row so the item is served either way, and keeping the entry would only pin an in-memory copy on top of a stored row nobody maintains. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01Pbu27iNUfQCHeuS551Rqo7 --- .../unregister-invalidate-after-delete.md | 56 ++ ...anager-unregister-invalidate-order.test.ts | 515 ++++++++++++++++++ packages/metadata/src/metadata-manager.ts | 200 ++++++- ...check-durability-degradation-log-level.mjs | 4 + 4 files changed, 762 insertions(+), 13 deletions(-) create mode 100644 .changeset/unregister-invalidate-after-delete.md create mode 100644 packages/metadata/src/metadata-manager-unregister-invalidate-order.test.ts diff --git a/.changeset/unregister-invalidate-after-delete.md b/.changeset/unregister-invalidate-after-delete.md new file mode 100644 index 0000000000..65daef3333 --- /dev/null +++ b/.changeset/unregister-invalidate-after-delete.md @@ -0,0 +1,56 @@ +--- +"@objectstack/metadata": patch +--- + +fix(metadata): `unregister()` invalidates the list cache AFTER the storage delete lands (#5259) + +`MetadataManager.unregister()` dropped the registry entry and called +`invalidateListCache(type)` **before** awaiting `loader.delete()`. Those two steps +are separated by a real await window — one DB round-trip per writable loader — and +inside it the manager held a state that exists nowhere else: **registry already +empty, loader not yet empty**. `list()` merges the two, so a read arriving in that +window missed the just-cleared cache, assembled the still-stored row into its +answer, and memoized it as a *complete* read — the full 30s healthy TTL, because no +loader threw and #5184's 2s degraded TTL therefore never applied. + +Nothing invalidated again once the delete landed (`notifyWatchers()` does not touch +`listCache`), so an item that was gone from storage kept being enumerated for up to +half a minute. `list()` is the enumeration seam behind `GET /api/v1/metadata/:type`, +the Studio left rail, sync/export and every consumer that decides existence from a +declared set — and `get()`, which never reads that cache, said the item was gone the +whole time. For a gating type (`permission`, `api`) the two faces of one manager +answered opposite questions about whether a declaration exists. + +**Fixed by ordering, not by an extra invalidation.** `register()` never had this +defect because it writes the registry *first* and the registry outranks every loader +in the merge, so its own save window already shows the post-write state. The +invariant is therefore not "invalidate early" but *invalidate last, once every store +already holds the announced state*. `unregister()` now deletes from storage first, +then drops the registry entry and invalidates with **nothing awaited between them**, +then publishes and announces — #5219's invalidate-before-notify discipline unchanged. +A `list()` racing the delete now either sees a coherent pre-delete state (the delete +has not landed and has not been announced — that answer is the truth) or the +post-delete state; it can no longer cache the pre-delete answer past the delete. + +This composes with #5253's single-flight rather than duplicating it: a read still +*in flight* when the delete lands cannot be reached by dropping `listCache` — it has +not written its entry yet and would write the pre-delete answer afterwards. +`invalidateListCache()` also retracts that read's `inflightListReads` registration, +so it resolves for the callers already waiting on it but loses the right to memoize, +while a caller arriving later starts a fresh read. + +**A storage delete that fails is now loud.** It used to `logger.warn('Failed to +delete …')` and continue. Per AGENTS.md "Degradation log levels" this is +durability/consistency degradation, not functional: `unregister()` resolves +normally, the caller is told the delete succeeded, and the surviving row is read +straight back out of storage by the very next `list()`/`get()` — permanently, since +nothing retries it. It now logs at `error`, once per un-deleted item, naming the +consequence and the fix. The registry entry is still dropped in that case, +deliberately: the loader still holds the row so the item is served either way, and +keeping the entry would only pin an in-memory copy on top of a stored row nobody +maintains — dropping it makes the next read fall through to storage, which is the +actual truth after a failed delete, and makes it visible immediately instead of at +the next restart. + +No API change. `unregister()` still resolves rather than throwing when a loader +refuses the delete. diff --git a/packages/metadata/src/metadata-manager-unregister-invalidate-order.test.ts b/packages/metadata/src/metadata-manager-unregister-invalidate-order.test.ts new file mode 100644 index 0000000000..a106b4eb13 --- /dev/null +++ b/packages/metadata/src/metadata-manager-unregister-invalidate-order.test.ts @@ -0,0 +1,515 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * #5259 — `unregister()` invalidates the list cache AFTER the storage delete + * lands, not before it. + * + * `unregister()` used to drop the registry entry and call + * `invalidateListCache(type)` and only THEN `await loader.delete(...)`. Between + * those two steps the manager sat in a state that exists nowhere else — + * **registry already empty, loader not yet empty** — and `list()` merges the + * two. So a read arriving in that window missed the just-cleared cache, + * assembled the still-stored row into its answer, and memoized it as a + * COMPLETE read: the full 30s healthy TTL, because no loader threw and #5184's + * 2s degraded TTL therefore never applied. Nothing invalidated again after the + * delete landed (`notifyWatchers()` does not touch `listCache`), so a row that + * was gone from storage kept being enumerated for up to half a minute — while + * `get()`, which never reads that cache, said it was gone. + * + * `register()` never had the defect, and the reason is the fix: it writes the + * registry first, and the registry outranks every loader in the merge, so its + * own save window already shows the post-write state. The invariant is + * therefore not "invalidate early" but **invalidate last, once every store + * already holds the announced state** — which for a delete means storage first, + * then registry + invalidate with nothing awaited between them, then announce + * (#5219's invalidate-before-notify bar, unchanged). + * + * What these tests pin: + * 1. the issue's probe, verbatim — a `list()` racing the delete must not + * leave the deleted item cached once the delete has landed; + * 2. the composition with #5253's single-flight: a read still IN FLIGHT when + * the delete lands is covered by `invalidateListCache()` retracting its + * `inflightListReads` registration — dropping `listCache` alone cannot + * reach it, because it has not written its entry yet; + * 3. the invalidation is after ALL loaders, not per loader; + * 4. a watcher woken by the `deleted` event that re-reads sees the delete; + * 5. the `loader.delete()` failure path is now loud at `error` with its + * consequence and its fix, once per un-deleted item; + * 6. the deliberate decision that the registry entry is STILL dropped when + * the storage delete failed — the runtime converges on storage truth + * instead of pinning a second in-memory copy; + * 7. `register()`'s own ordering is unchanged. + */ + +import { describe, it, expect, vi, beforeEach } from 'vitest'; +import type { + MetadataLoadOptions, + MetadataLoadResult, + MetadataLoaderContract, + MetadataSaveResult, + MetadataStats, +} from '@objectstack/spec/system'; +import { MetadataManager } from './metadata-manager.js'; +import type { MetadataLoader } from './loaders/loader-interface.js'; +import type { MetadataWatchEvent } from '@objectstack/spec/system'; + +// Stable logger mock — the failure-path assertions read what was logged. +const logger = vi.hoisted(() => ({ + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + debug: vi.fn(), +})); + +vi.mock('@objectstack/core', () => ({ + createLogger: () => logger, +})); + +/** Mirror of the manager's private `ListCacheEntry` (deliberately not exported). */ +type ListCacheEntry = { ts: number; items: unknown[]; degraded: boolean }; + +const peekEntry = (mgr: MetadataManager, type: string): ListCacheEntry | undefined => + (mgr as unknown as { listCache: Map }).listCache.get(type); + +/** Peek at #5253's in-flight map — internal by design, load-bearing here. */ +const inflight = (mgr: MetadataManager): Map> => + (mgr as unknown as { inflightListReads: Map> }).inflightListReads; + +/** Peek at the in-memory registry — the half `list()` cannot tell apart from a loader hit. */ +const registryHas = (mgr: MetadataManager, type: string, name: string): boolean => + (mgr as unknown as { registry: Map> }).registry.get(type)?.has(name) ?? + false; + +const names = (items: unknown[]): string[] => + (items as { name: string }[]).map((i) => i.name).sort(); + +/** A gate a test opens by hand, so nothing depends on timer ordering. */ +class Gate { + private parked: Array<() => void> = []; + closed = false; + async pass(): Promise { + if (!this.closed) return; + await new Promise((resolve) => this.parked.push(resolve)); + } + get parkedCount(): number { + return this.parked.length; + } + releaseAll(): void { + const parked = this.parked; + this.parked = []; + for (const resolve of parked) resolve(); + } +} + +/** + * A writable `datasource:` loader backed by a real store — the shape + * `unregister()` actually persists to. + * + * `loadMany` SNAPSHOTS the store before parking, modelling a real read that + * began before a concurrent delete committed: it answers with the rows it saw, + * not with whatever the store holds when it finally returns. That is precisely + * the read whose answer must not outlive the delete. + */ +class StoreLoader implements MetadataLoader { + readonly contract: MetadataLoaderContract; + /** type → name → data. */ + readonly store = new Map>(); + + readonly readGate = new Gate(); + readonly writeGate = new Gate(); + readonly deleteGate = new Gate(); + + /** When true, `delete()` throws instead of removing the row (storage outage). */ + failDeletes = false; + /** When true the loader has no `delete` at all — see `hasDelete`. */ + loadManyCalls = 0; + deleteCalls: Array<{ type: string; name: string }> = []; + + constructor(name = 'db') { + this.contract = { + name, + protocol: 'datasource:', + capabilities: { read: true, write: true, watch: false, list: true }, + }; + } + + seed(type: string, name: string, data: unknown): void { + if (!this.store.has(type)) this.store.set(type, new Map()); + this.store.get(type)!.set(name, data); + } + + has(type: string, name: string): boolean { + return this.store.get(type)?.has(name) ?? false; + } + + async loadMany(type: string, _options?: MetadataLoadOptions): Promise { + this.loadManyCalls += 1; + const snapshot = Array.from(this.store.get(type)?.values() ?? []); + await this.readGate.pass(); + return snapshot as T[]; + } + + async save(type: string, name: string, data: unknown): Promise { + await this.writeGate.pass(); + this.seed(type, name, data); + return { success: true }; + } + + async delete(type: string, name: string): Promise { + this.deleteCalls.push({ type, name }); + await this.deleteGate.pass(); + if (this.failDeletes) { + throw Object.assign(new Error('delete failed: ECONNRESET'), { code: 'ECONNRESET' }); + } + this.store.get(type)?.delete(name); + } + + async load(type: string, name: string): Promise { + const data = this.store.get(type)?.get(name); + return { data: data ?? null }; + } + async exists(type: string, name: string): Promise { + return this.has(type, name); + } + async stat(): Promise { + return null; + } + async list(type: string): Promise { + return Array.from(this.store.get(type)?.keys() ?? []); + } +} + +/** Give queued microtasks a chance to run. */ +const flush = async (): Promise => { + for (let i = 0; i < 8; i++) await Promise.resolve(); +}; + +const newManager = (...loaders: MetadataLoader[]): MetadataManager => { + const manager = new MetadataManager({ formats: ['json'], loaders: [] }); + for (const loader of loaders) manager.registerLoader(loader); + return manager; +}; + +beforeEach(() => { + logger.error.mockClear(); + logger.info.mockClear(); + logger.warn.mockClear(); + logger.debug.mockClear(); +}); + +describe('#5259 — a list() racing unregister() cannot outlive the delete', () => { + it("the issue's probe: after the delete lands, list() is empty — not the deleted item for 30s", async () => { + const loader = new StoreLoader(); + const manager = newManager(loader); + await manager.register('view', 'doomed', { name: 'doomed' }); + expect(loader.has('view', 'doomed')).toBe(true); + + // Park the storage delete so the probe can read inside the window. + loader.deleteGate.closed = true; + const removal = manager.unregister('view', 'doomed'); + await flush(); + expect(loader.deleteGate.parkedCount).toBe(1); + + // The concurrent read. Inside the window the delete has neither landed + // nor been announced, so seeing the item is the TRUTH, not the bug — + // and, unlike before the fix, it is a coherent truth: registry and + // loader agree, rather than the registry being empty already. + const during = await manager.list('view'); + expect(names(during)).toEqual(['doomed']); + expect(peekEntry(manager, 'view')).toBeDefined(); + + // Let the delete land. + loader.deleteGate.releaseAll(); + await removal; + expect(loader.has('view', 'doomed')).toBe(false); + + // The pin. Before the fix this read was served from a 30s-TTL entry + // written inside the window: `AFTER DELETE, list("view") = + // [{"name":"doomed"}]` with the loader store already empty. + expect(peekEntry(manager, 'view')).toBeUndefined(); + expect(await manager.list('view')).toEqual([]); + }); + + it('the deleted item does not come back on any read within the healthy TTL', async () => { + const loader = new StoreLoader(); + const manager = newManager(loader); + await manager.register('view', 'doomed', { name: 'doomed' }); + await manager.register('view', 'keeper', { name: 'keeper' }); + + loader.deleteGate.closed = true; + const removal = manager.unregister('view', 'doomed'); + await flush(); + await manager.list('view'); // caches the pre-delete pair + loader.deleteGate.releaseAll(); + await removal; + + // Nothing advances the clock: if the window's entry had survived, these + // reads would serve it for the next 30s. + for (let i = 0; i < 3; i++) { + expect(names(await manager.list('view'))).toEqual(['keeper']); + } + }); + + it('#5253 composition: a read still IN FLIGHT when the delete lands loses the right to cache', async () => { + const loader = new StoreLoader(); + const manager = newManager(loader); + await manager.register('view', 'doomed', { name: 'doomed' }); + + // A read that parks inside `loadMany`, having already snapshotted the + // pre-delete rows. `listCache` cannot cover this one — it has not + // written an entry yet, and would write the pre-delete answer AFTER any + // invalidation. Only retracting its `inflightListReads` registration + // reaches it, which is the mechanism #5253 added and this ordering fix + // depends on. + loader.readGate.closed = true; + const inFlight = manager.list('view'); + await flush(); + expect(loader.readGate.parkedCount).toBe(1); + expect(inflight(manager).has('view')).toBe(true); + + // The delete lands (and is announced) while that read is still parked. + await manager.unregister('view', 'doomed'); + expect(loader.has('view', 'doomed')).toBe(false); + expect(inflight(manager).has('view')).toBe(false); // registration retracted + + // The caller already waiting keeps its answer — it asked before the + // delete, and restarting the read under it is what #5253 rejected. + loader.readGate.releaseAll(); + expect(names(await inFlight)).toEqual(['doomed']); + + // But that answer was NOT memoized, so nobody else inherits it. + expect(peekEntry(manager, 'view')).toBeUndefined(); + loader.readGate.closed = false; + expect(await manager.list('view')).toEqual([]); + }); + + it('the invalidation happens after ALL writable loaders, not after each one', async () => { + const fast = new StoreLoader('fast'); + const slow = new StoreLoader('slow'); + const manager = newManager(fast, slow); + await manager.register('view', 'doomed', { name: 'doomed' }); + expect(fast.has('view', 'doomed')).toBe(true); + expect(slow.has('view', 'doomed')).toBe(true); + + // `fast` deletes immediately, `slow` parks: the window where one store + // is already empty and the other is not. + slow.deleteGate.closed = true; + const removal = manager.unregister('view', 'doomed'); + await flush(); + expect(fast.has('view', 'doomed')).toBe(false); + expect(slow.deleteGate.parkedCount).toBe(1); + + // A read completing in that partial window still memoizes the item… + expect(names(await manager.list('view'))).toEqual(['doomed']); + expect(peekEntry(manager, 'view')).toBeDefined(); + + // …and the single invalidation after the LAST delete clears it. + slow.deleteGate.releaseAll(); + await removal; + expect(peekEntry(manager, 'view')).toBeUndefined(); + expect(await manager.list('view')).toEqual([]); + }); + + it('#5219 bar: a watcher woken by the `deleted` event re-reads the post-delete state', async () => { + const loader = new StoreLoader(); + const manager = newManager(loader); + await manager.register('view', 'doomed', { name: 'doomed' }); + await manager.list('view'); // warm the cache with the pre-delete answer + + let seen: unknown[] | undefined; + const observed = new Promise((resolve) => { + manager.subscribe('view', async (event: MetadataWatchEvent) => { + if (event.type !== 'deleted') return; + seen = await manager.list('view'); + resolve(); + }); + }); + + await manager.unregister('view', 'doomed'); + await observed; + expect(seen).toEqual([]); + }); + + it('{ notify: false } still suppresses the announcement — and still invalidates', async () => { + const loader = new StoreLoader(); + const manager = newManager(loader); + await manager.register('view', 'doomed', { name: 'doomed' }); + await manager.list('view'); + + const events: MetadataWatchEvent[] = []; + manager.subscribe('view', (event) => { + events.push(event); + }); + + await manager.unregister('view', 'doomed', { notify: false }); + expect(events).toEqual([]); + expect(await manager.list('view')).toEqual([]); + }); +}); + +describe('#5259 — a storage delete that fails is loud', () => { + it('logs at `error` (not `warn`) and names both the consequence and the fix', async () => { + const loader = new StoreLoader(); + const manager = newManager(loader); + await manager.register('view', 'doomed', { name: 'doomed' }); + logger.error.mockClear(); + logger.warn.mockClear(); + + loader.failDeletes = true; + // Still resolves: the seam is best-effort by contract, which is exactly + // why the log has to carry the whole signal. + await expect(manager.unregister('view', 'doomed')).resolves.toBeUndefined(); + + expect(logger.error).toHaveBeenCalledTimes(1); + const [message, cause, context] = logger.error.mock.calls[0] as [string, unknown, unknown]; + // Consequence — the row survived, and the system still looks healthy. + expect(message).toContain('view/doomed'); + expect(message).toContain('db'); + expect(message).toMatch(/STILL in its store/); + expect(message).toMatch(/reappears/); + // Fix — what to do about it. + expect(message).toMatch(/Fix:/); + expect(cause).toBeInstanceOf(Error); + expect(context).toMatchObject({ loader: 'db', type: 'view', name: 'doomed' }); + + // The old `warn` is gone, not merely joined by an error. + const warnedAboutDelete = logger.warn.mock.calls.some((call) => + String(call[0]).toLowerCase().includes('delete'), + ); + expect(warnedAboutDelete).toBe(false); + }); + + it('reports once per un-deleted ITEM — a batch teardown does not lose the casualty list', async () => { + const loader = new StoreLoader(); + const manager = newManager(loader); + await manager.register('view', 'alpha', { name: 'alpha' }); + await manager.register('view', 'beta', { name: 'beta' }); + logger.error.mockClear(); + + loader.failDeletes = true; + await manager.bulkUnregister([ + { type: 'view', name: 'alpha' }, + { type: 'view', name: 'beta' }, + ]); + + expect(logger.error).toHaveBeenCalledTimes(2); + const messages = logger.error.mock.calls.map((call) => String(call[0])); + expect(messages.some((m) => m.includes('view/alpha'))).toBe(true); + expect(messages.some((m) => m.includes('view/beta'))).toBe(true); + }); + + it('reports once per loader that failed, naming each store that kept the row', async () => { + const a = new StoreLoader('db_a'); + const b = new StoreLoader('db_b'); + const manager = newManager(a, b); + await manager.register('view', 'doomed', { name: 'doomed' }); + logger.error.mockClear(); + + a.failDeletes = true; + b.failDeletes = true; + await manager.unregister('view', 'doomed'); + + expect(logger.error).toHaveBeenCalledTimes(2); + const messages = logger.error.mock.calls.map((call) => String(call[0])); + expect(messages.some((m) => m.includes('db_a'))).toBe(true); + expect(messages.some((m) => m.includes('db_b'))).toBe(true); + }); + + it('one loader failing does not stop the delete reaching the others', async () => { + const broken = new StoreLoader('broken'); + const healthy = new StoreLoader('healthy'); + const manager = newManager(broken, healthy); + await manager.register('view', 'doomed', { name: 'doomed' }); + + broken.failDeletes = true; + await manager.unregister('view', 'doomed'); + + expect(broken.has('view', 'doomed')).toBe(true); + expect(healthy.has('view', 'doomed')).toBe(false); + expect(healthy.deleteCalls).toEqual([{ type: 'view', name: 'doomed' }]); + }); + + /** + * The decision the issue asked for, pinned so it cannot be reversed by + * accident: the registry entry is dropped even though the storage delete + * failed. + * + * Keeping it would look safer and is not. The loader still holds the row + * and `list()`/`get()` merge registry ∪ loaders, so the item is served + * either way — the surviving registry entry would only decide WHICH copy + * wins, pinning an in-memory definition on top of a stored row nobody + * maintains anymore. Dropping it makes the next read fall through to + * storage, which after a failed delete is the actual truth (the item still + * exists), and makes that visible immediately instead of at the next + * restart. The divergence is reported by the `error` above, not papered + * over with a second in-memory copy. + */ + it('drops the registry entry anyway, so the next read converges on storage truth', async () => { + const loader = new StoreLoader(); + const manager = newManager(loader); + await manager.register('view', 'doomed', { name: 'doomed' }); + + loader.failDeletes = true; + await manager.unregister('view', 'doomed'); + + expect(registryHas(manager, 'view', 'doomed')).toBe(false); + // Storage kept the row, so the item is visibly back — immediately, and + // in every face at once rather than `list()` and `get()` disagreeing. + expect(loader.has('view', 'doomed')).toBe(true); + expect(names(await manager.list('view'))).toEqual(['doomed']); + expect(await manager.get('view', 'doomed')).toEqual({ name: 'doomed' }); + }); +}); + +describe('#5259 — register() is unchanged', () => { + it('still writes the registry BEFORE its save window, so a read inside it sees the new value', async () => { + const loader = new StoreLoader(); + const manager = newManager(loader); + await manager.register('view', 'existing', { name: 'existing', v: 1 }); + await manager.list('view'); // warm the cache + + // Park the storage write: the mirror image of the delete window. + loader.writeGate.closed = true; + const write = manager.register('view', 'existing', { name: 'existing', v: 2 }); + await flush(); + expect(loader.writeGate.parkedCount).toBe(1); + + // Registry-first + invalidate-first is what makes this the NEW value: + // the registry outranks the loader's still-old row in the merge. This + // is the ordering #5259 deliberately did NOT change. + const during = (await manager.list('view')) as Array<{ name: string; v: number }>; + expect(during).toEqual([{ name: 'existing', v: 2 }]); + + loader.writeGate.releaseAll(); + await write; + expect(await manager.list('view')).toEqual([{ name: 'existing', v: 2 }]); + expect(loader.store.get('view')?.get('existing')).toEqual({ name: 'existing', v: 2 }); + }); + + it('still announces added/changed, and the announcement still follows the invalidation', async () => { + const loader = new StoreLoader(); + const manager = newManager(loader); + + const seen: Array<{ type: string; listedAtEvent: string[] }> = []; + const settled: Array> = []; + manager.subscribe('view', (event: MetadataWatchEvent) => { + settled.push( + (async () => { + seen.push({ + type: event.type, + listedAtEvent: names(await manager.list('view')), + }); + })(), + ); + }); + + await manager.register('view', 'a', { name: 'a' }); + await manager.register('view', 'a', { name: 'a', v: 2 }); + await manager.unregister('view', 'a'); + await Promise.all(settled); + + expect(seen.map((s) => s.type)).toEqual(['added', 'changed', 'deleted']); + // Every watcher that re-read on the event saw the post-write state. + expect(seen.map((s) => s.listedAtEvent)).toEqual([['a'], ['a'], []]); + }); +}); diff --git a/packages/metadata/src/metadata-manager.ts b/packages/metadata/src/metadata-manager.ts index 3a6678a162..83539e9884 100644 --- a/packages/metadata/src/metadata-manager.ts +++ b/packages/metadata/src/metadata-manager.ts @@ -78,6 +78,23 @@ import type { ApiEndpointMatch } from '@objectstack/spec/contracts'; */ export type WatchCallback = (event: MetadataWatchEvent) => void | Promise; +/** + * [#5259] A {@link MetadataLoader} that also implements deletion. + * + * `MetadataLoader` declares `save?` but no `delete?`, so `unregister()` has + * always duck-typed the method at the call site. Naming the shape here replaces + * the two `as any` casts that did it before — the cast is still a cast, but it + * is now one declared shape rather than an untyped hole, and the `typeof + * … === 'function'` guard in front of it is what actually decides. + * + * Whether the loader contract itself should declare `delete?` (and what a + * `capabilities.write` loader *without* one means) is a separate question, + * deliberately not answered here. + */ +type DeletableMetadataLoader = MetadataLoader & { + delete?: (type: string, name: string) => Promise; +}; + /** * [#5189] Appended to the namespace gate's message when `publishPackage` was * called without one, because the gate's own text ("declare an explicit @@ -228,6 +245,17 @@ export class MetadataManager implements IMetadataService { // // Invalidated on every `register()` / `unregister()` to keep CRUD writes // visible to subsequent reads. + // + // [#5259] WHERE in a write the invalidation sits is part of that promise, not + // an implementation detail. `list()` merges registry ∪ loaders, so an + // invalidation issued while only ONE of the two has been updated lets the + // next read memoize the half-applied view for a full TTL. The rule both + // writers follow: **invalidate last, once every store already holds the state + // being announced** — `register()` satisfies it by writing the registry + // first (the registry outranks loaders in the merge, so its save window + // already shows the post-write value); `unregister()` satisfies it by + // deleting from storage first and invalidating after, with nothing awaited + // between the registry drop and the invalidation. See `unregister()`. private listCache = new Map(); private static readonly LIST_CACHE_TTL_MS = 30_000; /** @@ -863,6 +891,14 @@ export class MetadataManager implements IMetadataService { * pre-write answer, and a caller arriving after this point gets a fresh read * instead of joining a pre-write one. The reasoning — including why waiting * callers are NOT restarted — is on the `inflightListReads` field. + * + * [#5259] Both halves are only as good as WHEN the caller invokes this. This + * clears what is stale *as of now*; it cannot pre-empt a store the caller has + * not finished updating yet. Callers must therefore invalidate only once + * every store already holds the state they are about to announce — see the + * `listCache` field comment and {@link unregister}, whose pre-#5259 ordering + * invalidated one await too early and let the next read cache a view in which + * the registry was empty and the loader was not. */ private invalidateListCache(type: string): void { this.listCache.delete(type); @@ -933,9 +969,78 @@ export class MetadataManager implements IMetadataService { * {@link MetadataWatchEvent} — the delete half of the {@link register} * contract. Pass `{ notify: false }` only for teardown that announces by * other means. + * + * ## [#5259] Storage FIRST, in-memory second — the order is the fix + * + * This method used to drop the registry entry and call + * {@link invalidateListCache} *before* awaiting `loader.delete()`. Those two + * steps are separated by a real await window (one DB round-trip per writable + * loader), and inside it the manager was in a state that exists nowhere else: + * **registry already empty, loader not yet empty**. `list()` merges the two, + * so a read arriving in that window + * + * • missed the cache (it had just been invalidated), + * • assembled the still-stored row into its answer, and + * • memoized that answer as a COMPLETE read — the full 30s healthy TTL, + * because no loader threw, so #5184's 2s degraded TTL never applied. + * + * Nothing invalidated again afterwards ({@link notifyWatchers} does not touch + * `listCache`), so a row that was gone from storage kept being enumerated for + * up to 30s — and `get()`, which never consulted that cache, disagreed with + * `list()` the whole time. For a gating type (`permission`, `api`) the two + * faces of the same manager answered opposite questions about whether a + * declaration exists. + * + * {@link register} never had this defect, and the reason is instructive: it + * writes the registry *first*, and the registry outranks every loader in the + * merge, so throughout its own save window the merged view already equals the + * post-write state. The invariant that makes register correct is not "where + * the invalidate sits" but **the invalidate must be the last thing after + * every store already holds the announced state**. Restated for delete, that + * means storage first: + * + * 1. `await loader.delete()` on every writable loader. Throughout this + * window registry AND loaders still hold the item, so a concurrent + * `list()` observes a coherent pre-delete state — which is the truth, + * because the delete has not landed and has not been announced. + * 2. Drop the registry entry and `invalidateListCache(type)` — with **no + * await between them**, so no read can interleave and observe the + * half-applied state that produced the bug. Everything cached or + * in-flight from step 1 is dropped here, at the moment the final state + * becomes true. + * 3. Publish + announce. #5219's invalidate-before-notify bar, unchanged: + * a watcher woken by the `deleted` event and re-reading through `list()` + * gets a fresh read of the post-delete state. + * + * **Composition with #5253's single-flight (this is the load-bearing half).** + * A `list()` that is still walking the loaders when step 2 runs cannot be + * fixed by dropping `listCache` alone — it has not written its entry yet, and + * it would write the pre-delete answer *after* the invalidation. The + * mechanism that covers it is `invalidateListCache()` also retracting the + * read's registration in `inflightListReads`: a retracted read still resolves + * for the callers already waiting on it (they asked before the delete) but + * loses the right to memoize, and any caller arriving after step 2 starts a + * fresh read rather than joining the pre-delete one. So every read is + * covered: one that FINISHED in the window has its entry deleted, one still + * IN FLIGHT loses its permission to cache, and one starting later reads the + * post-delete state. That is why the invalidate must come after the deletes + * rather than being duplicated on both sides of them — a second invalidate + * before the await would buy nothing and would re-open step 1's window. */ async unregister(type: string, name: string, options?: MetadataWriteOptions): Promise { - // Remove from in-memory registry + // ── 1. Storage first ──────────────────────────────────────────────── + // Delete only from database-backed loaders that declare write capability. + for (const loader of this.loaders.values()) { + if (loader.contract.protocol !== 'datasource:' || !loader.contract.capabilities.write) continue; + if (typeof (loader as DeletableMetadataLoader).delete !== 'function') continue; + try { + await this.deleteMetaItemFromLoader(loader, type, name); + } catch (error) { + this.reportMetaItemDeleteFailure(loader.contract.name, type, name, error); + } + } + + // ── 2. In-memory state, then invalidation — nothing awaited between ── const typeStore = this.registry.get(type); if (typeStore) { typeStore.delete(name); @@ -945,18 +1050,7 @@ export class MetadataManager implements IMetadataService { } this.invalidateListCache(type); - // Delete only from database-backed loaders that declare write capability - for (const loader of this.loaders.values()) { - if (loader.contract.protocol !== 'datasource:' || !loader.contract.capabilities.write) continue; - if (typeof (loader as any).delete === 'function') { - try { - await (loader as any).delete(type, name); - } catch (error) { - this.logger.warn(`Failed to delete ${type}/${name} from loader ${loader.contract.name}`, { error }); - } - } - } - + // ── 3. Announce ───────────────────────────────────────────────────── // Publish metadata.{type}.deleted event to realtime service await this.publishRealtimeMetadataEvent('deleted', type, name, { userId: options?.userId, @@ -975,6 +1069,86 @@ export class MetadataManager implements IMetadataService { } } + /** + * Delete one metadata item from one writable loader — the storage half of + * {@link unregister}. + * + * A one-line wrapper on purpose: it gives this durability seam a **name**. + * `check:durability-log-level` matches by callee name against an explicit + * vocabulary, and the raw call is `loader.delete(...)` — putting `delete` in + * that vocabulary would claim every `.delete()` in the monorepo (`Map`, + * `Set`, cache handles, `URLSearchParams`) and the gate would drown in false + * positives, which is exactly the failure mode its own header warns about. + * Named here, `deleteMetaItemFromLoader` is in `DURABILITY_CRITICAL_CALLEES` + * with a blast radius of precisely this call site, mirroring `saveMetaItem` + * on the write side (#4754). + * + * `MetadataLoader` declares `save?` but no `delete?`, which is why the caller + * duck-types before getting here; widening the loader contract is a separate + * question and deliberately not answered by this issue. + */ + private async deleteMetaItemFromLoader( + loader: MetadataLoader, + type: string, + name: string, + ): Promise { + const del = (loader as DeletableMetadataLoader).delete; + if (typeof del !== 'function') return; + await del.call(loader, type, name); + } + + /** + * Report — at `error` — that a loader refused to delete an item the runtime + * has already dropped and announced as deleted. + * + * [#5259] This used to be a `logger.warn('Failed to delete …')` and continue. + * AGENTS.md → "Degradation log levels" decides the level with one question: + * *after the degradation, does the system still look normal from the outside + * while something it claims is persisted has not actually landed?* Here it is + * the deletion that did not land, which is the same class and the same + * silence: `unregister()` resolves normally, the caller is told the delete + * succeeded, and the surviving row is read straight back out of storage — + * permanently, since nothing ever retries this. Durability/consistency + * degradation ⇒ `error`, naming the **consequence** and the **fix**. + * + * **Why the registry entry is still dropped when this fires.** The + * alternative — keep the item registered so runtime state matches storage — + * looks safer and is not. The loader still holds the row, and `list()`/`get()` + * merge registry ∪ loaders, so the item is served either way; the only thing + * the surviving registry entry would change is *which copy wins*, pinning an + * in-memory definition that outranks the stored row nobody is maintaining + * anymore. Dropping it makes the very next read fall through to storage, + * which is the actual truth after a failed delete — the item still exists — + * and it surfaces that immediately (the item visibly reappears) instead of at + * the next restart. One truth, read from where it lives; the divergence is + * reported here rather than papered over with a second in-memory copy. + * + * **Said once per un-deleted item, not once per loader.** The once-per-outage + * discipline of {@link reportLoaderReadFailure} exists because `list()` is hot + * and its repeats are *identical*; these are not. Each line names a different + * item that is still in storage and that nothing will ever retry, so + * collapsing them would hand an operator the first casualty and silently drop + * the rest of the list — the failure this level was raised to prevent. + */ + private reportMetaItemDeleteFailure( + loaderName: string, + type: string, + name: string, + error: unknown, + ): void { + this.logger.error( + `[MetadataManager] Loader \`${loaderName}\` could NOT delete \`${type}/${name}\` — the row is STILL in its store, ` + + `while the runtime has already dropped the item from its registry and announced it as deleted. ` + + `Nothing looks broken: \`unregister()\` resolves normally and the caller (Studio/Setup, REST DELETE, the CLI, a package teardown) ` + + `is told the delete succeeded — but the surviving row is read straight back out of storage by the very next \`list()\`/\`get()\`, ` + + `so the "deleted" item reappears and keeps reappearing across restarts. Nothing retries this delete. ` + + `Fix: check the datasource behind \`${loaderName}\` — connection, credentials, and that its metadata table exists and is writable — ` + + `then re-issue the delete for \`${type}/${name}\`. Until that succeeds the item is NOT deleted, whatever the delete call reported.`, + error instanceof Error ? error : undefined, + { loader: loaderName, type, name, error }, + ); + } + /** * Check if a metadata item exists */ diff --git a/scripts/check-durability-degradation-log-level.mjs b/scripts/check-durability-degradation-log-level.mjs index 436b1407ab..bd32564d10 100644 --- a/scripts/check-durability-degradation-log-level.mjs +++ b/scripts/check-durability-degradation-log-level.mjs @@ -144,6 +144,10 @@ const DURABILITY_CRITICAL_CALLEES = new Map([ 'saveMetaItem', 'The metadata definition was never written to the authoritative store — the runtime looks completely normal because the in-memory registry already has it, and the definition simply vanishes on the next provision/restart (#4754, from #4669).', ], + [ + 'deleteMetaItemFromLoader', + 'The metadata definition was never deleted from the authoritative store — `unregister()` still resolves and still announces `deleted`, the in-memory registry entry is gone, and the surviving row is read straight back out of storage by the very next `list()`/`get()`, so the "deleted" item reappears and survives every restart. Nothing retries it (#5259).', + ], ]); /** Log levels that are ACCEPTABLE inside a durability-guarding catch. */