diff --git a/src/storage/adapters/fileSystemStorage.ts b/src/storage/adapters/fileSystemStorage.ts index a01c2015..784ea5d8 100644 --- a/src/storage/adapters/fileSystemStorage.ts +++ b/src/storage/adapters/fileSystemStorage.ts @@ -120,6 +120,13 @@ export class FileSystemStorage extends BaseStorage { */ private writerHeartbeatInFlight?: Promise + /** + * The in-flight background count-ledger derivation, if one was needed at + * open. See {@link scheduleCountLedgerDerivation} — awaited only by + * {@link whenCountLedgerSettled}, never by a read. + */ + private countLedgerDerivation?: Promise + // Flush-request RPC state. The writer polls `locks/_flush_requests/` for // new `.req` files and emits `.ack` files in `locks/_flush_responses/` after // flushing. Inspectors call `requestFlushOverFilesystem` to drop a request @@ -1889,18 +1896,41 @@ export class FileSystemStorage extends BaseStorage { } } + // THE CLEAN-CLOSE RECORD IS READ BEFORE ANY VERDICT (see + // WriterCloseRecord). A lock file whose release was RECORDED is + // bookkeeping left by an orderly shutdown, not evidence of anything — + // and that is true whether the previous holder was another process or + // an earlier instance in THIS one. A production restart reported + // "Re-acquiring writer lock ... this is a bug" immediately after a clean + // close, sending an operator hunting for a leak that did not exist. + const closeRecord = existing ? await this.readWriterCloseRecord() : null + const releasedCleanly = + existing !== null && + closeRecord !== null && + this.closeRecordVouchesFor(closeRecord, existing) + if (existing) { // Same-process re-open: a second Brainy instance in this Node process // (e.g. test "simulate server restart" patterns, or a consumer that // explicitly re-instantiates without closing first). This isn't the // dangerous cross-process case the lock exists to prevent — the two // instances share a memory space and can't silently diverge from each - // other beyond what their callers already see. Warn and take over. + // other beyond what their callers already see. Warn and take over — + // unless the record proves the previous instance already let go, in + // which case there is nothing to warn about. if (existing.pid === myPid && existing.hostname === hostname && !options?.force) { - console.warn( - `[brainy] Re-acquiring writer lock for ${this.rootDir} held by the same process (PID ${existing.pid}). ` + - `If you intended to keep the previous Brainy instance alive, this is a bug — close it first.` - ) + if (releasedCleanly) { + console.warn( + `[brainy] Clearing the leftover writer lock for ${this.rootDir} — an earlier ` + + `instance in this process (PID ${existing.pid}) RELEASED it cleanly at ` + + `${closeRecord!.closedAt} but could not remove the file. Nothing to recover.` + ) + } else { + console.warn( + `[brainy] Re-acquiring writer lock for ${this.rootDir} held by the same process (PID ${existing.pid}). ` + + `If you intended to keep the previous Brainy instance alive, this is a bug — close it first.` + ) + } const info: WriterLockInfo = { pid: myPid, hostname, @@ -1915,17 +1945,11 @@ export class FileSystemStorage extends BaseStorage { return info } - // THE CLEAN-CLOSE RECORD IS CONSULTED FIRST (see WriterCloseRecord). - // A lock file whose release was RECORDED is bookkeeping left behind by - // an orderly shutdown, not evidence of a crash — take it over calmly - // and say so. Only when no record vouches for this lock do we fall - // back to inferring liveness from the pid, and then we say THAT - // honestly too: an unrecorded lock means the writer did not complete - // its close, so the store was not closed cleanly and this open pays - // recovery. - const closeRecord = await this.readWriterCloseRecord() - const releasedCleanly = - closeRecord !== null && this.closeRecordVouchesFor(closeRecord, existing) + // A cleanly-released lock is stale by RECORD, not by inference. Only + // when no record vouches for this lock do we fall back to pid + // liveness, and then we say THAT honestly too: an unrecorded lock + // means the writer did not complete its close, so the store was not + // closed cleanly and this open pays recovery. const stale = releasedCleanly || (!options?.force && (await this.isWriterLockStale(existing))) if (!options?.force && !stale) { @@ -2224,6 +2248,9 @@ export class FileSystemStorage extends BaseStorage { try { await this.writeFileAtomic(recordFile, JSON.stringify(record, null, 2)) } catch (err) { + // ENOENT = the lock directory is gone, i.e. the whole store was removed + // under us. There is no next open to inform. + if ((err as NodeJS.ErrnoException)?.code === 'ENOENT') return console.warn( `[brainy] Failed to write the writer clean-close record for ${this.rootDir} — ` + `the next open will fall back to pid liveness and may report this orderly ` + @@ -2760,25 +2787,29 @@ export class FileSystemStorage extends BaseStorage { this.allCountsDerivedBy = undefined this.allCountsSuspect = true needsPersist = true - prodLog.warn( + prodLog.narrate( '[FileSystemStorage] canonical count ledger was derived under the legacy ' + - 'container rule — marked suspect; a sanctioned recount (repairIndex) restores ' + - 'exact denominators' + 'container rule — it counts one entity per id DIRECTORY, so every ghost/scar ' + + 'container inflates it. Marked suspect, and an honest recount is scheduled to ' + + 'run in the background after this open; until it lands, do not subtract ' + + 'against these ALL scalars.' ) + // A suspect ledger used to stay wrong for the life of the store, + // waiting for an operator to run repairIndex. A downstream index + // heal took its "remaining" figure from these inflated + // denominators and reported work that did not exist. The ledger + // now HEALS ITSELF — in the background, because a denominator is + // a derived scalar and no read is ever served from it. + this.scheduleCountLedgerDerivation('legacy container-rule ledger') } } else { - const nouns = await this.scanCanonicalEntities('nouns') - const verbs = await this.scanCanonicalEntities('verbs') - this.totalNounCountAll = nouns.count - this.totalVerbCountAll = verbs.count - this.allCountsSuspect = false - this.allCountsDerivedBy = 'identity-record' - console.warn( - `[FileSystemStorage] counts.json predates the ALL-visibility count ledger — ` + - `derived once from the canonical id tree (${nouns.count} nouns, ${verbs.count} verbs, ` + - `every tier) and persisted; no further scan.` - ) - needsPersist = true + // No ALL scalars at all. There is nothing to serve in the meantime — + // a zero would read as an empty store — so the scalars stay unknown + // and SUSPECT until the background derivation lands. The open does + // not wait for it: an id-tree walk is O(ids) and this file has been + // the whole reason a 24k-id store opened in silence. + this.allCountsSuspect = true + this.scheduleCountLedgerDerivation('counts.json predates the ALL-visibility ledger') } // The vectored-noun scalar (shipped after the ALL scalars above — a @@ -2791,14 +2822,12 @@ export class FileSystemStorage extends BaseStorage { if (typeof counts.totalVectoredNounCount === 'number') { this.totalVectoredNounCount = counts.totalVectoredNounCount } else { - const vectored = await this.scanVectoredNounCount() - this.totalVectoredNounCount = vectored - console.warn( - `[FileSystemStorage] counts.json predates the vectored-noun count ledger — ` + - `derived once by reading every noun's vectors.json (${vectored} vectored) and ` + - `persisted; no further scan.` - ) - needsPersist = true + // O(nouns) CONTENT reads — the most expensive derivation of the + // three, and the one most likely to have been the silent minutes at + // the front of a large store's open. Background, suspect until it + // lands, same as the ALL scalars. + this.allCountsSuspect = true + this.scheduleCountLedgerDerivation('counts.json predates the vectored-noun ledger') } if (needsPersist) { await this.persistCounts() @@ -2827,6 +2856,22 @@ export class FileSystemStorage extends BaseStorage { * Initialize counts by scanning disk (only done once) */ private async initializeCountsFromDisk(): Promise { + const startedAt = Date.now() + // THIS ONE CANNOT LEAVE THE FOREGROUND, and the reason is worth stating: + // it derives `totalNounCount` / `totalVerbCount`, the scalars + // `getNounCount()` and `getVerbCount()` RETURN. Backgrounding it would + // make a populated store answer "0 entities" until the walk landed — a + // wrong answer, not a slow one, and the serving law grades a failure by + // whether an answer could be wrong. The ALL-visibility denominators, which + // no read is served from, DO run in the background (see + // scheduleCountLedgerDerivation). What this walk owes the operator instead + // is narration: it announces itself, and reports its wall. + prodLog.narrate( + `[FileSystemStorage] no usable counts.json — deriving the entity counters from ` + + `the canonical id tree now. This is O(ids) listings plus one vectors.json read ` + + `per noun, and it BLOCKS the open because getNounCount()/getVerbCount() are ` + + `served from it. It runs once; the result is persisted.` + ) try { // Count the CANONICAL 8.0 layout (`entities////…`) — // the tree saveNoun/getNouns actually read and write. The previous scan @@ -2874,6 +2919,11 @@ export class FileSystemStorage extends BaseStorage { } await this.persistCounts() + prodLog.narrate( + `[FileSystemStorage] counter derivation from the canonical id tree finished in ` + + `${Date.now() - startedAt}ms: ${this.totalNounCount} nouns, ${this.totalVerbCount} verbs, ` + + `${this.totalVectoredNounCount} vectored nouns — persisted, stamped identity-record.` + ) } catch (error) { console.error('Error initializing counts from disk:', error) } @@ -2895,6 +2945,118 @@ export class FileSystemStorage extends BaseStorage { * directories (absolute paths) — nouns feed the type-distribution estimate * above. An absent tree (fresh store) counts zero. */ + /** + * @description Derive the ALL-visibility count ledger honestly — one entity + * per IDENTITY RECORD, never per id directory — IN THE BACKGROUND, once, + * and persist the result stamped `identity-record`. + * + * Why background: these scalars are DENOMINATORS. No read is served from + * them, so deriving them cannot be allowed to hold an open hostage — a + * store with 24,898 ids spent minutes of a production restart inside walks + * exactly like these, in silence, before serving anything. Why at all: a + * ledger derived under the old container rule stayed wrong for the life of + * the store, and a downstream index heal subtracted against it and reported + * remaining work that did not exist (measured on a real store: 14,231 + * derived against 14,056 identity records — precisely the store's 25 noun + * scar directories; verbs 72,729 against 72,679, its 50 verb scars). + * + * Idempotent: a second call while one is in flight joins the first. + * @param reason - What made the ledger untrustworthy, quoted in narration. + * @returns Nothing; observe completion with {@link whenCountLedgerSettled}. + */ + private scheduleCountLedgerDerivation(reason: string): void { + if (this.countLedgerDerivation) return + this.countLedgerDerivation = (async () => { + const startedAt = Date.now() + prodLog.narrate( + `[FileSystemStorage] count-ledger derivation started in the background ` + + `(${reason}) — counting identity records, not id directories; the open does ` + + `not wait for it and no read is served from these scalars.` + ) + try { + const beforeNouns = this.totalNounCountAll + const beforeVerbs = this.totalVerbCountAll + const beforeVectored = this.totalVectoredNounCount + // A walk that RACED A WRITE cannot prove its number: a row that landed + // mid-walk may or may not have been in the shard the walk had already + // passed. Rather than persist a figure that might be off by one and + // stamp it "exact", the walk is repeated once on a quiet store, and if + // the store is never quiet the ledger stays SUSPECT and says so. One + // retry, never a spin. + let attempt = 0 + let derived: { nouns: number; verbs: number; vectored: number } | null = null + while (attempt < 2 && derived === null) { + attempt++ + const activityBefore = this.ledgerActivityStamp() + const nouns = await this.scanCanonicalEntities('nouns') + const verbs = await this.scanCanonicalEntities('verbs') + const vectored = await this.scanVectoredNounCount() + if (this.ledgerActivityStamp() === activityBefore) { + derived = { nouns: nouns.count, verbs: verbs.count, vectored } + } + } + if (derived === null) { + this.allCountsSuspect = true + prodLog.narrate( + `[FileSystemStorage] count-ledger derivation could not finish on a quiet store ` + + `after ${attempt} attempts (${Date.now() - startedAt}ms) — writes landed during ` + + `every walk. The ALL-visibility scalars stay SUSPECT and must not be subtracted ` + + `against; brain.repairIndex() derives them under a recount barrier.` + ) + return + } + this.totalNounCountAll = derived.nouns + this.totalVerbCountAll = derived.verbs + this.totalVectoredNounCount = derived.vectored + this.allCountsDerivedBy = 'identity-record' + this.allCountsSuspect = false + await this.persistCounts() + prodLog.narrate( + `[FileSystemStorage] count-ledger derivation finished in ${Date.now() - startedAt}ms: ` + + `${derived.nouns} nouns / ${derived.verbs} verbs / ${derived.vectored} vectored nouns` + + (beforeNouns !== derived.nouns || + beforeVerbs !== derived.verbs || + beforeVectored !== derived.vectored + ? ` (corrected from ${beforeNouns} / ${beforeVerbs} / ${beforeVectored} — the ` + + `difference is ghost and scar containers the old rule counted as entities)` + : ' (unchanged)') + + ` — persisted, stamped identity-record, no longer suspect.` + ) + } catch (error) { + // The ledger stays suspect and the next open retries. Loud: a + // denominator nobody can derive is a fact an operator must have. + this.allCountsSuspect = true + prodLog.error( + `[FileSystemStorage] count-ledger derivation FAILED after ` + + `${Date.now() - startedAt}ms — the ALL-visibility scalars remain SUSPECT ` + + `and must not be subtracted against; the next open retries:`, + error + ) + } + })() + } + + /** + * @description A cheap witness that the ledger changed while a walk was + * running. Every landed write moves one of these live counters, so an + * unchanged stamp across a walk means no write landed during it. + * @returns A value that differs whenever the live ALL scalars have moved. + */ + private ledgerActivityStamp(): string { + return `${this.totalNounCountAll}:${this.totalVerbCountAll}:${this.totalVectoredNounCount}` + } + + /** + * @description Resolve once any background count-ledger derivation has + * settled (succeeded or failed). Resolves immediately when none was needed. + * Exists so tests and operators can observe the ledger's honest value rather + * than race it; nothing in the read path waits on this. + * @returns A promise that settles with the derivation. + */ + public async whenCountLedgerSettled(): Promise { + await this.countLedgerDerivation + } + private async scanCanonicalEntities( kind: 'nouns' | 'verbs' ): Promise<{ count: number; sampleDirs: string[] }> { @@ -3053,10 +3215,15 @@ export class FileSystemStorage extends BaseStorage { lastUpdated: new Date().toISOString() } - await fs.promises.writeFile( - this.countsFilePath, - JSON.stringify(counts, null, 2) - ) + // ATOMIC (temp + rename), never a plain writeFile. A direct write + // truncates the file first, so every persist opened a window — measured + // at roughly 750ms after a flush or close on a real store — in which a + // concurrent reader saw counts.json EMPTY. An empty file is unparseable, + // and an unparseable ledger sends the next open down the full-rescan + // path: the cheapest file in the store was costing the most expensive + // recovery. The rename is atomic, so a reader sees the old ledger or the + // new one, never neither. + await this.writeFileAtomic(this.countsFilePath, JSON.stringify(counts, null, 2)) } catch (error) { console.error('Error persisting counts:', error) } diff --git a/tests/integration/count-ledger-identity-record.test.ts b/tests/integration/count-ledger-identity-record.test.ts new file mode 100644 index 00000000..1066213a --- /dev/null +++ b/tests/integration/count-ledger-identity-record.test.ts @@ -0,0 +1,251 @@ +/** + * @module tests/integration/count-ledger-identity-record + * @description THE COUNT LEDGER COUNTS RECORDS, NOT DIRECTORIES — and heals + * itself when it was derived the other way. + * + * Measured on a real store: the ALL-visibility ledger read 14,231 nouns + * against 14,056 identity records, and 72,729 verbs against 72,679 — exactly + * that store's 25 noun and 50 verb SCAR directories (empty `/` containers + * left by a pre-8.3.1 partial delete). Two copies of the SAME archive derived + * different numbers, because each had been persisted at a different moment + * under the old container rule. A downstream index heal subtracted against + * those denominators and reported remaining work that did not exist. + * + * The membership predicate is the IDENTITY RECORD (the metadata content leg). + * The scan already applies it; what is pinned here is that a ledger persisted + * under the OLD rule does not go on lying — it is corrected in the background, + * without blocking the open, and two copies of one archive agree. + */ + +import { describe, it, expect, afterEach } from 'vitest' +import { + mkdtempSync, + mkdirSync, + rmSync, + writeFileSync, + readFileSync, + cpSync, + existsSync +} from 'node:fs' +import { tmpdir } from 'node:os' +import { join } from 'node:path' +import { Brainy } from '../../src/brainy.js' +import { NounType } from '../../src/types/graphTypes.js' +import { FileSystemStorage as FileSystemStorageClass } from '../../src/storage/adapters/fileSystemStorage.js' +import type { FileSystemStorage } from '../../src/storage/adapters/fileSystemStorage.js' + +const NOUN_COUNT = 6 +const NOUN_SCARS = 3 +const VERB_SCARS = 2 +/** A REAL two-hex shard — the scan skips any directory that is not one. */ +const SCAR_SHARD = 'ab' + +function makeTempDir(): string { + return mkdtempSync(join(tmpdir(), 'brainy-count-ledger-')) +} + +/** The FileSystemStorage behind a brain. */ +function storageOf(brain: Brainy): FileSystemStorage { + return (brain as unknown as { storage: FileSystemStorage }).storage +} + +/** + * Add `count` empty `/` container directories under + * `entities///` — scars, exactly as a partial delete leaves them. + */ +function addScarContainers(dir: string, kind: 'nouns' | 'verbs', count: number): void { + for (let i = 0; i < count; i++) { + const id = `${SCAR_SHARD}5ca4000-0000-0000-0000-00000000000${i}` + mkdirSync(join(dir, 'entities', kind, SCAR_SHARD, id), { recursive: true }) + } +} + +/** Add one GHOST container: a `vectors.json` leg with no identity record. */ +function addGhostContainer(dir: string): void { + const id = `${SCAR_SHARD}9405700-0000-0000-0000-000000000000` + const idDir = join(dir, 'entities', 'nouns', SCAR_SHARD, id) + mkdirSync(idDir, { recursive: true }) + writeFileSync(join(idDir, 'vectors.json'), JSON.stringify({ id, vector: [0.1, 0.2] })) +} + +/** + * Rewrite counts.json into the LEGACY shape: ALL scalars inflated by the + * containers, and no `allCountsDerivedBy` stamp — exactly what a store carried + * when it was last written by a build that counted directories. + */ +function writeLegacyCountsLedger(dir: string, inflateNouns: number, inflateVerbs: number): void { + const file = join(dir, '_system', 'counts.json') + const counts = JSON.parse(readFileSync(file, 'utf-8')) + counts.totalNounCountAll = (counts.totalNounCountAll ?? 0) + inflateNouns + counts.totalVerbCountAll = (counts.totalVerbCountAll ?? 0) + inflateVerbs + delete counts.allCountsDerivedBy + delete counts.allCountsSuspect + writeFileSync(file, JSON.stringify(counts, null, 2)) +} + +/** + * Seed a store and return the HONEST ledger it holds when freshly written — + * the baseline the correction must return to. Read from the engine rather than + * hardcoded: an open creates its own rows (the VFS root), and a pin that + * asserts a literal would be pinning that incidental fact instead of the rule. + */ +async function seedStore(dir: string): Promise<{ nouns: number; verbs: number }> { + const brain = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } }) + await brain.init() + const ids: string[] = [] + for (let i = 0; i < NOUN_COUNT; i++) { + ids.push(await brain.add({ data: `entity number ${i}`, type: NounType.Concept })) + } + await brain.relate({ from: ids[0], to: ids[1], type: 'relatedTo' } as never) + await brain.relate({ from: ids[1], to: ids[2], type: 'relatedTo' } as never) + await brain.flush() + const ledger = await storageOf(brain).getCanonicalCounts() + const baseline = { nouns: ledger.nouns.all, verbs: ledger.verbs.all } + await brain.close() + return baseline +} + +/** + * Make the ledger walk take `ms` so a test can observe the open completing + * WITHOUT it. Patches the prototype before any brain is constructed; returns + * the restore function. + */ +function slowTheLedgerWalk(ms: number): () => void { + const proto = ( + FileSystemStorageClass as unknown as { + prototype: Record Promise> + } + ).prototype + const real = proto.scanCanonicalEntities + proto.scanCanonicalEntities = async function slow(this: unknown, ...args: unknown[]) { + await new Promise((r) => setTimeout(r, ms)) + return real.apply(this, args) + } + return () => { proto.scanCanonicalEntities = real } +} + +describe('the canonical count ledger', () => { + const dirs: string[] = [] + + afterEach(() => { + for (const d of dirs.splice(0)) { + try { rmSync(d, { recursive: true, force: true }) } catch { /* ignore */ } + } + }) + + function trackDir(): string { + const dir = makeTempDir() + dirs.push(dir) + return dir + } + + it('corrects a legacy container-rule ledger in the background, counting identity records', async () => { + const dir = trackDir() + const baseline = await seedStore(dir) + + // Scars and a ghost: containers with no identity record. + addScarContainers(dir, 'nouns', NOUN_SCARS) + addScarContainers(dir, 'verbs', VERB_SCARS) + addGhostContainer(dir) + // The ledger as the old rule left it: every container counted. + writeLegacyCountsLedger(dir, NOUN_SCARS + 1, VERB_SCARS) + + const restore = slowTheLedgerWalk(1_500) + let brain: Brainy + try { + const openStarted = Date.now() + brain = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } }) + await brain.init() + const openMs = Date.now() - openStarted + const storage = storageOf(brain) + + // THE OPEN DID NOT WAIT. Two walks of 1.5s each would have added 3s. + expect(openMs).toBeLessThan(2_500) + // And while it runs, the scalars say so instead of being subtracted against. + const atOpen = await storage.getCanonicalCounts() + expect(atOpen.suspect).toBe(true) + expect(atOpen.nouns.all).toBe(baseline.nouns + NOUN_SCARS + 1) + + await storage.whenCountLedgerSettled() + } finally { + restore() + } + const storage = storageOf(brain!) + + const healed = await storage.getCanonicalCounts() + expect(healed.nouns.all).toBe(baseline.nouns) + expect(healed.verbs.all).toBe(baseline.verbs) + expect(healed.suspect).toBe(false) + + // And it is PERSISTED with the honest stamp — the correction survives a + // reopen instead of being re-derived (or re-lost) every time. + await brain!.close() + const persisted = JSON.parse(readFileSync(join(dir, '_system', 'counts.json'), 'utf-8')) + expect(persisted.totalNounCountAll).toBe(baseline.nouns) + expect(persisted.totalVerbCountAll).toBe(baseline.verbs) + expect(persisted.allCountsDerivedBy).toBe('identity-record') + + const reopened = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } }) + await reopened.init() + const afterReopen = await storageOf(reopened).getCanonicalCounts() + expect(afterReopen.nouns.all).toBe(baseline.nouns) + expect(afterReopen.suspect).toBe(false) + await reopened.close() + }, 180_000) + + it('derives the same number from two copies of one archive', async () => { + const source = trackDir() + const baseline = await seedStore(source) + addScarContainers(source, 'nouns', NOUN_SCARS) + addGhostContainer(source) + + // Two copies of the SAME bytes, each carrying a DIFFERENT legacy ledger — + // the situation that made one archive report 14,231 and its twin 14,081. + const copyA = trackDir() + const copyB = trackDir() + cpSync(source, copyA, { recursive: true }) + cpSync(source, copyB, { recursive: true }) + writeLegacyCountsLedger(copyA, NOUN_SCARS + 1, 0) + writeLegacyCountsLedger(copyB, 1, 0) + + const derived: number[] = [] + for (const dir of [copyA, copyB]) { + const brain = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } }) + await brain.init() + const storage = storageOf(brain) + await storage.whenCountLedgerSettled() + derived.push((await storage.getCanonicalCounts()).nouns.all) + await brain.close() + } + expect(derived[0]).toBe(derived[1]) + expect(derived[0]).toBe(baseline.nouns) + }, 180_000) + + it('writes counts.json atomically — no reader ever sees it empty', async () => { + const dir = trackDir() + await seedStore(dir) + const file = join(dir, '_system', 'counts.json') + expect(existsSync(file)).toBe(true) + + const brain = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } }) + await brain.init() + const storage = storageOf(brain) + + // Watch the ledger across many persists. A truncating write leaves a + // window in which the file parses as nothing; a temp+rename never does. + let sawUnparseable = 0 + const watcher = setInterval(() => { + try { + JSON.parse(readFileSync(file, 'utf-8')) + } catch { + sawUnparseable++ + } + }, 1) + for (let i = 0; i < 40; i++) { + await (storage as unknown as { persistCounts: () => Promise }).persistCounts() + } + clearInterval(watcher) + await brain.close() + expect(sawUnparseable).toBe(0) + }, 180_000) +}) diff --git a/tests/integration/ledger-derivation-identity.test.ts b/tests/integration/ledger-derivation-identity.test.ts index cb19af4a..7d09e893 100644 --- a/tests/integration/ledger-derivation-identity.test.ts +++ b/tests/integration/ledger-derivation-identity.test.ts @@ -11,14 +11,22 @@ * (1) IDENTITY, NOT CONTAINER — the derivation counts one entity per * metadata content leg (`metadata.json` or `.json.gz`), the same test * `pruneOrphanedEntities()` uses, so the two agree by construction. - * (2) THE STAMP NAMES SUSPECT COUNTS LOUDLY, AT O(1) — a counts.json that - * carries the ALL scalars but no `allCountsDerivedBy: 'identity-record'` - * stamp predates this fix; loading it marks `suspect = true` from a - * single field read alone, never a directory walk, and warns exactly - * once naming the cause. - * (3) THE SANCTIONED RECOUNT CLEARS IT — `repairIndex()` prunes the orphaned - * containers, recounts from the canonical metadata.json walk, and - * re-stamps — suspect clears and the ALL scalar is exact again. + * (2) THE STAMP NAMES SUSPECT COUNTS LOUDLY, AND THE OPEN NEVER WALKS — a + * counts.json that carries the ALL scalars but no + * `allCountsDerivedBy: 'identity-record'` stamp predates this fix; + * loading it marks `suspect = true` from a single field read alone and + * warns exactly once naming the cause. The open itself never pays a + * directory walk. + * (2b) AND IT HEALS ITSELF. The ledger used to stay wrong for the life of the + * store, waiting for an operator to run `repairIndex()` — and a + * downstream index heal subtracted against the inflated denominator and + * reported work that did not exist. An honest derivation now runs in the + * BACKGROUND after the open (never blocking it, observable via + * `whenCountLedgerSettled()`), and refuses to stamp a number it derived + * while writes were landing. + * (3) THE SANCTIONED RECOUNT ALSO CLEARS IT — `repairIndex()` prunes the + * orphaned containers, recounts from the canonical metadata.json walk, + * and re-stamps — the ALL scalar is exact and the containers are gone. * (4) A FRESH STORE IS NEVER SUSPECT — the one-time derivation for a store * with no counts.json stamps as it writes, so a brand-new store never * carries the legacy signature. @@ -115,29 +123,43 @@ describe('ledger derivation identity — the ALL scalar is the identity-record p delete raw.allCountsDerivedBy fs.writeFileSync(countsPath(dir), JSON.stringify(raw, null, 2)) - const warnSpy = vi.spyOn(prodLog, 'warn') - // The two derivation walks live on FileSystemStorage's prototype — - // spying here (rather than on fs.promises.readdir globally) isolates - // THIS code path's behavior from unrelated walks elsewhere in the open - // sequence (a separate, pre-existing engine's own O(store) cost — not - // this fix's concern, and not something this pin should be sensitive - // to). Neither derivation method may run: the stamp check is a field - // read on the already-parsed counts.json, nothing more. - const scanEntitiesSpy = vi.spyOn(FileSystemStorage.prototype as any, 'scanCanonicalEntities') - const scanVectoredSpy = vi.spyOn(FileSystemStorage.prototype as any, 'scanVectoredNounCount') + const narrateSpy = vi.spyOn(prodLog, 'narrate') + // The derivation walks live on FileSystemStorage's prototype. Slow them + // deliberately: the OPEN must not wait for them, and on a two-row store a + // real walk finishes too fast to tell "not awaited" from "instant". + const proto = FileSystemStorage.prototype as any + const realScanEntities = proto.scanCanonicalEntities + let scanEntitiesCalls = 0 + proto.scanCanonicalEntities = async function slow(this: any, ...args: any[]) { + scanEntitiesCalls++ + await new Promise((r) => setTimeout(r, 1_200)) + return realScanEntities.apply(this, args) + } + try { + const openStarted = Date.now() + brain = await open() + const openMs = Date.now() - openStarted - brain = await open() + // THE OPEN DID NOT WALK: two slowed walks would have added 2.4s to it. + expect(openMs).toBeLessThan(2_000) - const ledger = await brain.storage.getCanonicalCounts() - expect(ledger.suspect).toBe(true) + // The stamp check itself is an O(1) field read, and it names the cause. + const atOpen = await brain.storage.getCanonicalCounts() + expect(atOpen.suspect).toBe(true) + const stampWarnings = narrateSpy.mock.calls.filter( + ([msg]: any[]) => String(msg).includes('legacy') && String(msg).includes('container rule') + ) + expect(stampWarnings.length).toBe(1) // exactly one, loud - const stampWarnings = warnSpy.mock.calls.filter( - ([msg]) => String(msg).includes('legacy') && String(msg).includes('container rule') - ) - expect(stampWarnings.length).toBe(1) // exactly one, loud - - expect(scanEntitiesSpy).not.toHaveBeenCalled() // O(1) field read only, no re-derivation walk - expect(scanVectoredSpy).not.toHaveBeenCalled() + // ...and the honest derivation is already running behind the open. + await brain.storage.whenCountLedgerSettled() + expect(scanEntitiesCalls).toBeGreaterThan(0) + const healed = await brain.storage.getCanonicalCounts() + expect(healed.suspect).toBe(false) + expect(healed.nouns.all).toBe(raw.totalNounCountAll) + } finally { + proto.scanCanonicalEntities = realScanEntities + } await brain.close() }) @@ -163,7 +185,14 @@ describe('ledger derivation identity — the ALL scalar is the identity-record p fs.writeFileSync(countsPath(dir), JSON.stringify(raw, null, 2)) brain = await open() - expect((await brain.storage.getCanonicalCounts()).suspect).toBe(true) // named suspect at load + // Named suspect at load, then healed in the background WITHOUT the + // operator asking — the inflated container count is corrected to the + // identity-record population, though the orphaned containers themselves + // are still on disk (only repairIndex() removes those). + await brain.storage.whenCountLedgerSettled() + let healed = await brain.storage.getCanonicalCounts() + expect(healed.suspect).toBe(false) + expect(healed.nouns.all).toBe(realTotal) await brain.repairIndex()