soulcraftlabs/open-brainy
2
0
Fork 0
Code Issues 1 Pull requests Projects Releases 342 Packages Wiki Activity Actions 6

fix(storage): a suspect count ledger heals itself, and counts.json is written atomically
Some checks are pending
CI / Node 22 (push) Waiting to run
Details
CI / Node 24 (push) Waiting to run
Details
CI / Integration + conformance (Node 22) (push) Waiting to run
Details
CI / Bun (latest) (push) Waiting to run
Details

Browse source 
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. Two copies of the same archive derived
different numbers (14,231 and 14,081), because each had been persisted at a
different moment under the old rule that counted one entity per id DIRECTORY.
A downstream index heal subtracted against that denominator and reported
remaining work that did not exist.

The scan already applies the right predicate — one entity per IDENTITY RECORD
(the metadata content leg), shared with pruneOrphanedEntities so the two agree
by construction. What was missing is that a ledger persisted under the old rule
was only FLAGGED suspect and then went on serving its wrong numbers for the
life of the store, waiting for an operator to run repairIndex.

- The ledger now derives itself honestly in the BACKGROUND after the open,
  narrating start and finish with the correction it made. Background because
  these scalars are denominators — no read is served from them — and because
  walks exactly like these are how a 24,898-id store spent minutes of a
  restart in silence. Observable via whenCountLedgerSettled(); nothing in the
  read path waits on it.
- A derivation that raced a write refuses to stamp its number "exact": one
  retry on a quiet store, then the ledger stays SUSPECT and says so, naming
  repairIndex as the door that recounts under a barrier.
- The one derivation that CANNOT leave the foreground says why it cannot:
  getNounCount()/getVerbCount() are served from it, and a background walk
  would make a populated store answer "0 entities" — a wrong answer, not a
  slow one. It narrates its start and its wall instead.
- counts.json is written temp+rename. A truncating write left a window —
  measured at roughly 750ms after a flush or close — in which a concurrent
  reader saw the file EMPTY; an unparseable ledger sends the next open down
  the full-rescan path, so the cheapest file in the store was buying the most
  expensive recovery.
- The writer lock's clean-close record is now consulted before the
  same-process branch too: a restart reported "Re-acquiring writer lock ...
  this is a bug" immediately after a clean close, sending an operator after a
  leak that did not exist.

Pins: tests/integration/count-ledger-identity-record.test.ts (background
correction with scar and ghost fixtures, two copies of one archive agreeing,
counts.json never observed unparseable across 40 persists);
tests/integration/ledger-derivation-identity.test.ts updated to the new law —
the OPEN still never walks (proved by slowing the walk 1.2s and timing the
open), and the ledger heals behind it.
This commit is contained in:
David Snelling 2026-08-28 10:28:25 -07:00
parent afe08a1ff9
commit f4e2d34b4e
3 changed files with 519 additions and 72 deletions
Download patch file Download diff file Expand all files Collapse all files

253
src/storage/adapters/fileSystemStorage.ts
View file

@ -120,6 +120,13 @@ export class FileSystemStorage extends BaseStorage {
*/
private writerHeartbeatInFlight?: Promise<void>
/**
* 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<void>
// 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<void> {
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/<kind>/<shard>/<id>/…`) —
// 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<void> {
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)
}