fix(storage): a suspect count ledger heals itself, and counts.json is written atomically
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:
parent
afe08a1ff9
commit
f4e2d34b4e
3 changed files with 519 additions and 72 deletions
|
|
@ -120,6 +120,13 @@ export class FileSystemStorage extends BaseStorage {
|
||||||
*/
|
*/
|
||||||
private writerHeartbeatInFlight?: Promise<void>
|
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
|
// Flush-request RPC state. The writer polls `locks/_flush_requests/` for
|
||||||
// new `.req` files and emits `.ack` files in `locks/_flush_responses/` after
|
// new `.req` files and emits `.ack` files in `locks/_flush_responses/` after
|
||||||
// flushing. Inspectors call `requestFlushOverFilesystem` to drop a request
|
// 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) {
|
if (existing) {
|
||||||
// Same-process re-open: a second Brainy instance in this Node process
|
// Same-process re-open: a second Brainy instance in this Node process
|
||||||
// (e.g. test "simulate server restart" patterns, or a consumer that
|
// (e.g. test "simulate server restart" patterns, or a consumer that
|
||||||
// explicitly re-instantiates without closing first). This isn't the
|
// explicitly re-instantiates without closing first). This isn't the
|
||||||
// dangerous cross-process case the lock exists to prevent — the two
|
// dangerous cross-process case the lock exists to prevent — the two
|
||||||
// instances share a memory space and can't silently diverge from each
|
// 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) {
|
if (existing.pid === myPid && existing.hostname === hostname && !options?.force) {
|
||||||
|
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(
|
console.warn(
|
||||||
`[brainy] Re-acquiring writer lock for ${this.rootDir} held by the same process (PID ${existing.pid}). ` +
|
`[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 you intended to keep the previous Brainy instance alive, this is a bug — close it first.`
|
||||||
)
|
)
|
||||||
|
}
|
||||||
const info: WriterLockInfo = {
|
const info: WriterLockInfo = {
|
||||||
pid: myPid,
|
pid: myPid,
|
||||||
hostname,
|
hostname,
|
||||||
|
|
@ -1915,17 +1945,11 @@ export class FileSystemStorage extends BaseStorage {
|
||||||
return info
|
return info
|
||||||
}
|
}
|
||||||
|
|
||||||
// THE CLEAN-CLOSE RECORD IS CONSULTED FIRST (see WriterCloseRecord).
|
// A cleanly-released lock is stale by RECORD, not by inference. Only
|
||||||
// A lock file whose release was RECORDED is bookkeeping left behind by
|
// when no record vouches for this lock do we fall back to pid
|
||||||
// an orderly shutdown, not evidence of a crash — take it over calmly
|
// liveness, and then we say THAT honestly too: an unrecorded lock
|
||||||
// and say so. Only when no record vouches for this lock do we fall
|
// means the writer did not complete its close, so the store was not
|
||||||
// back to inferring liveness from the pid, and then we say THAT
|
// closed cleanly and this open pays recovery.
|
||||||
// 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)
|
|
||||||
const stale =
|
const stale =
|
||||||
releasedCleanly || (!options?.force && (await this.isWriterLockStale(existing)))
|
releasedCleanly || (!options?.force && (await this.isWriterLockStale(existing)))
|
||||||
if (!options?.force && !stale) {
|
if (!options?.force && !stale) {
|
||||||
|
|
@ -2224,6 +2248,9 @@ export class FileSystemStorage extends BaseStorage {
|
||||||
try {
|
try {
|
||||||
await this.writeFileAtomic(recordFile, JSON.stringify(record, null, 2))
|
await this.writeFileAtomic(recordFile, JSON.stringify(record, null, 2))
|
||||||
} catch (err) {
|
} 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(
|
console.warn(
|
||||||
`[brainy] Failed to write the writer clean-close record for ${this.rootDir} — ` +
|
`[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 ` +
|
`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.allCountsDerivedBy = undefined
|
||||||
this.allCountsSuspect = true
|
this.allCountsSuspect = true
|
||||||
needsPersist = true
|
needsPersist = true
|
||||||
prodLog.warn(
|
prodLog.narrate(
|
||||||
'[FileSystemStorage] canonical count ledger was derived under the legacy ' +
|
'[FileSystemStorage] canonical count ledger was derived under the legacy ' +
|
||||||
'container rule — marked suspect; a sanctioned recount (repairIndex) restores ' +
|
'container rule — it counts one entity per id DIRECTORY, so every ghost/scar ' +
|
||||||
'exact denominators'
|
'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 {
|
} else {
|
||||||
const nouns = await this.scanCanonicalEntities('nouns')
|
// No ALL scalars at all. There is nothing to serve in the meantime —
|
||||||
const verbs = await this.scanCanonicalEntities('verbs')
|
// a zero would read as an empty store — so the scalars stay unknown
|
||||||
this.totalNounCountAll = nouns.count
|
// and SUSPECT until the background derivation lands. The open does
|
||||||
this.totalVerbCountAll = verbs.count
|
// not wait for it: an id-tree walk is O(ids) and this file has been
|
||||||
this.allCountsSuspect = false
|
// the whole reason a 24k-id store opened in silence.
|
||||||
this.allCountsDerivedBy = 'identity-record'
|
this.allCountsSuspect = true
|
||||||
console.warn(
|
this.scheduleCountLedgerDerivation('counts.json predates the ALL-visibility ledger')
|
||||||
`[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
|
|
||||||
}
|
}
|
||||||
|
|
||||||
// The vectored-noun scalar (shipped after the ALL scalars above — a
|
// 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') {
|
if (typeof counts.totalVectoredNounCount === 'number') {
|
||||||
this.totalVectoredNounCount = counts.totalVectoredNounCount
|
this.totalVectoredNounCount = counts.totalVectoredNounCount
|
||||||
} else {
|
} else {
|
||||||
const vectored = await this.scanVectoredNounCount()
|
// O(nouns) CONTENT reads — the most expensive derivation of the
|
||||||
this.totalVectoredNounCount = vectored
|
// three, and the one most likely to have been the silent minutes at
|
||||||
console.warn(
|
// the front of a large store's open. Background, suspect until it
|
||||||
`[FileSystemStorage] counts.json predates the vectored-noun count ledger — ` +
|
// lands, same as the ALL scalars.
|
||||||
`derived once by reading every noun's vectors.json (${vectored} vectored) and ` +
|
this.allCountsSuspect = true
|
||||||
`persisted; no further scan.`
|
this.scheduleCountLedgerDerivation('counts.json predates the vectored-noun ledger')
|
||||||
)
|
|
||||||
needsPersist = true
|
|
||||||
}
|
}
|
||||||
if (needsPersist) {
|
if (needsPersist) {
|
||||||
await this.persistCounts()
|
await this.persistCounts()
|
||||||
|
|
@ -2827,6 +2856,22 @@ export class FileSystemStorage extends BaseStorage {
|
||||||
* Initialize counts by scanning disk (only done once)
|
* Initialize counts by scanning disk (only done once)
|
||||||
*/
|
*/
|
||||||
private async initializeCountsFromDisk(): Promise<void> {
|
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 {
|
try {
|
||||||
// Count the CANONICAL 8.0 layout (`entities/<kind>/<shard>/<id>/…`) —
|
// Count the CANONICAL 8.0 layout (`entities/<kind>/<shard>/<id>/…`) —
|
||||||
// the tree saveNoun/getNouns actually read and write. The previous scan
|
// the tree saveNoun/getNouns actually read and write. The previous scan
|
||||||
|
|
@ -2874,6 +2919,11 @@ export class FileSystemStorage extends BaseStorage {
|
||||||
}
|
}
|
||||||
|
|
||||||
await this.persistCounts()
|
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) {
|
} catch (error) {
|
||||||
console.error('Error initializing counts from disk:', 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
|
* directories (absolute paths) — nouns feed the type-distribution estimate
|
||||||
* above. An absent tree (fresh store) counts zero.
|
* 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(
|
private async scanCanonicalEntities(
|
||||||
kind: 'nouns' | 'verbs'
|
kind: 'nouns' | 'verbs'
|
||||||
): Promise<{ count: number; sampleDirs: string[] }> {
|
): Promise<{ count: number; sampleDirs: string[] }> {
|
||||||
|
|
@ -3053,10 +3215,15 @@ export class FileSystemStorage extends BaseStorage {
|
||||||
lastUpdated: new Date().toISOString()
|
lastUpdated: new Date().toISOString()
|
||||||
}
|
}
|
||||||
|
|
||||||
await fs.promises.writeFile(
|
// ATOMIC (temp + rename), never a plain writeFile. A direct write
|
||||||
this.countsFilePath,
|
// truncates the file first, so every persist opened a window — measured
|
||||||
JSON.stringify(counts, null, 2)
|
// 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) {
|
} catch (error) {
|
||||||
console.error('Error persisting counts:', error)
|
console.error('Error persisting counts:', error)
|
||||||
}
|
}
|
||||||
|
|
|
||||||
251
tests/integration/count-ledger-identity-record.test.ts
Normal file
251
tests/integration/count-ledger-identity-record.test.ts
Normal file
|
|
@ -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 `<id>/` 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 `<id>/` container directories under
|
||||||
|
* `entities/<kind>/<shard>/` — 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<string, (...args: unknown[]) => Promise<unknown>>
|
||||||
|
}
|
||||||
|
).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<void> }).persistCounts()
|
||||||
|
}
|
||||||
|
clearInterval(watcher)
|
||||||
|
await brain.close()
|
||||||
|
expect(sawUnparseable).toBe(0)
|
||||||
|
}, 180_000)
|
||||||
|
})
|
||||||
|
|
@ -11,14 +11,22 @@
|
||||||
* (1) IDENTITY, NOT CONTAINER — the derivation counts one entity per
|
* (1) IDENTITY, NOT CONTAINER — the derivation counts one entity per
|
||||||
* metadata content leg (`metadata.json` or `.json.gz`), the same test
|
* metadata content leg (`metadata.json` or `.json.gz`), the same test
|
||||||
* `pruneOrphanedEntities()` uses, so the two agree by construction.
|
* `pruneOrphanedEntities()` uses, so the two agree by construction.
|
||||||
* (2) THE STAMP NAMES SUSPECT COUNTS LOUDLY, AT O(1) — a counts.json that
|
* (2) THE STAMP NAMES SUSPECT COUNTS LOUDLY, AND THE OPEN NEVER WALKS — a
|
||||||
* carries the ALL scalars but no `allCountsDerivedBy: 'identity-record'`
|
* counts.json that carries the ALL scalars but no
|
||||||
* stamp predates this fix; loading it marks `suspect = true` from a
|
* `allCountsDerivedBy: 'identity-record'` stamp predates this fix;
|
||||||
* single field read alone, never a directory walk, and warns exactly
|
* loading it marks `suspect = true` from a single field read alone and
|
||||||
* once naming the cause.
|
* warns exactly once naming the cause. The open itself never pays a
|
||||||
* (3) THE SANCTIONED RECOUNT CLEARS IT — `repairIndex()` prunes the orphaned
|
* directory walk.
|
||||||
* containers, recounts from the canonical metadata.json walk, and
|
* (2b) AND IT HEALS ITSELF. The ledger used to stay wrong for the life of the
|
||||||
* re-stamps — suspect clears and the ALL scalar is exact again.
|
* 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
|
* (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
|
* with no counts.json stamps as it writes, so a brand-new store never
|
||||||
* carries the legacy signature.
|
* carries the legacy signature.
|
||||||
|
|
@ -115,29 +123,43 @@ describe('ledger derivation identity — the ALL scalar is the identity-record p
|
||||||
delete raw.allCountsDerivedBy
|
delete raw.allCountsDerivedBy
|
||||||
fs.writeFileSync(countsPath(dir), JSON.stringify(raw, null, 2))
|
fs.writeFileSync(countsPath(dir), JSON.stringify(raw, null, 2))
|
||||||
|
|
||||||
const warnSpy = vi.spyOn(prodLog, 'warn')
|
const narrateSpy = vi.spyOn(prodLog, 'narrate')
|
||||||
// The two derivation walks live on FileSystemStorage's prototype —
|
// The derivation walks live on FileSystemStorage's prototype. Slow them
|
||||||
// spying here (rather than on fs.promises.readdir globally) isolates
|
// deliberately: the OPEN must not wait for them, and on a two-row store a
|
||||||
// THIS code path's behavior from unrelated walks elsewhere in the open
|
// real walk finishes too fast to tell "not awaited" from "instant".
|
||||||
// sequence (a separate, pre-existing engine's own O(store) cost — not
|
const proto = FileSystemStorage.prototype as any
|
||||||
// this fix's concern, and not something this pin should be sensitive
|
const realScanEntities = proto.scanCanonicalEntities
|
||||||
// to). Neither derivation method may run: the stamp check is a field
|
let scanEntitiesCalls = 0
|
||||||
// read on the already-parsed counts.json, nothing more.
|
proto.scanCanonicalEntities = async function slow(this: any, ...args: any[]) {
|
||||||
const scanEntitiesSpy = vi.spyOn(FileSystemStorage.prototype as any, 'scanCanonicalEntities')
|
scanEntitiesCalls++
|
||||||
const scanVectoredSpy = vi.spyOn(FileSystemStorage.prototype as any, 'scanVectoredNounCount')
|
await new Promise((r) => setTimeout(r, 1_200))
|
||||||
|
return realScanEntities.apply(this, args)
|
||||||
|
}
|
||||||
|
try {
|
||||||
|
const openStarted = Date.now()
|
||||||
brain = await open()
|
brain = await open()
|
||||||
|
const openMs = Date.now() - openStarted
|
||||||
|
|
||||||
const ledger = await brain.storage.getCanonicalCounts()
|
// THE OPEN DID NOT WALK: two slowed walks would have added 2.4s to it.
|
||||||
expect(ledger.suspect).toBe(true)
|
expect(openMs).toBeLessThan(2_000)
|
||||||
|
|
||||||
const stampWarnings = warnSpy.mock.calls.filter(
|
// The stamp check itself is an O(1) field read, and it names the cause.
|
||||||
([msg]) => String(msg).includes('legacy') && String(msg).includes('container rule')
|
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
|
expect(stampWarnings.length).toBe(1) // exactly one, loud
|
||||||
|
|
||||||
expect(scanEntitiesSpy).not.toHaveBeenCalled() // O(1) field read only, no re-derivation walk
|
// ...and the honest derivation is already running behind the open.
|
||||||
expect(scanVectoredSpy).not.toHaveBeenCalled()
|
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()
|
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))
|
fs.writeFileSync(countsPath(dir), JSON.stringify(raw, null, 2))
|
||||||
|
|
||||||
brain = await open()
|
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()
|
await brain.repairIndex()
|
||||||
|
|
||||||
|
|
|
||||||
Loading…
Add table
Add a link
Reference in a new issue