/** * @module tests/integration/idle-costs-nothing * @description AN IDLE BRAIN DOES NO WORK. * * A flush used to re-persist state identical to what was already on disk — * the provider flushes, the watermark stamps, the generation counter, the * entity-tree stamp, roughly 28 writes — because `flush()` never asked whether * anything had changed. * * The field observation that started this: a production process holding 21 * brains printed "All indexes flushed to disk in 216–601ms" per brain every * ~35 seconds and idled at 1.26 cores, with no writes for ten minutes. This * engine's cadence is WRITE-DRIVEN, so that observation is NOT explained by * the cadence and is not claimed to be fixed here — what is fixed is that such * a call now costs nothing. Who was calling flush() remains open. * * The laws pinned here: * (a) the persistence cadence arms only on a write — a brain nobody writes * to flushes zero times, however long it is left open; * (b) a flush on a clean brain is O(1): no provider is called, nothing is * written, and nothing is printed; * (c) one write earns exactly one flush's worth of work, and no more. */ import { describe, it, expect, afterEach, vi } from 'vitest' import { mkdtempSync, rmSync } 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' /** Wait for any in-flight background flush, then let the idle timer settle. */ async function drainCadence(brain: Brainy): Promise { const inner = brain as unknown as { _persistBackgroundFlight: Promise | null } await new Promise((r) => setTimeout(r, 3_000)) await (inner._persistBackgroundFlight ?? Promise.resolve()) await new Promise((r) => setTimeout(r, 500)) } /** How long an idle brain is watched. Longer than the 30s flush interval. */ const IDLE_WATCH_MS = 90_000 describe('an idle brain costs nothing', () => { const dirs: string[] = [] const brains: Brainy[] = [] afterEach(async () => { for (const b of brains.splice(0)) { try { await b.close() } catch { /* already closed */ } } for (const d of dirs.splice(0)) { try { rmSync(d, { recursive: true, force: true }) } catch { /* ignore */ } } vi.restoreAllMocks() }) async function openBrain(): Promise { const dir = mkdtempSync(join(tmpdir(), 'brainy-idle-')) dirs.push(dir) const brain = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } }) brains.push(brain) await brain.init() return brain } it('flushes zero times over 90 idle seconds, and prints nothing', async () => { const brain = await openBrain() // One write and one flush to reach a clean, settled state — then nothing. await brain.add({ data: 'the only write this test performs', type: NounType.Concept }) await brain.flush() const logged: string[] = [] // The STACK behind each narration, kept beside the line it belongs to. // vitest tags a stdout block with the test that is RUNNING, not the brain // that wrote it, so teeing these lines through would only ever name this // test. The call stack does name the driver: `kickBackgroundFlush('idle')` // under `armIdleFlushTimer` is a cadence flush on some brain, the deferred- // embed worker's commit path is a brain still landing vectors, and a bare // `flush()` is an explicit caller. That distinction is the whole question. const stacks: string[] = [] const origLog = console.log console.log = ((...a: unknown[]) => { const line = a.map(String).join(' ') logged.push(line) if (/All indexes flushed to disk|Flushing Brainy indexes/.test(line)) { stacks.push(new Error('flush narration').stack ?? '(no stack)') } }) as typeof console.log // Watch the providers directly: a flush that runs calls all of them. const storage = (brain as unknown as { storage: { flushCounts: () => Promise } }).storage const metadataIndex = (brain as unknown as { metadataIndex: { flush: () => Promise } }).metadataIndex const graphIndex = (brain as unknown as { graphIndex: { flush: () => Promise } }).graphIndex const countsSpy = vi.spyOn(storage, 'flushCounts') const metadataSpy = vi.spyOn(metadataIndex, 'flush') const graphSpy = vi.spyOn(graphIndex, 'flush') try { await new Promise((r) => setTimeout(r, IDLE_WATCH_MS)) } finally { console.log = origLog } // (a) + (b): nothing ran, nothing was said. // // THE SPIES COME FIRST, AND THEY ARE THE ATTRIBUTABLE HALF. They are bound // to THIS brain's providers, so they answer "did this brain flush?" and // nothing else. The console filters below cannot: the gate config runs the // whole suite in ONE process (`pool: 'forks'`, `singleFork: true`), so // `console.log` carries the narration of every brain alive in that // process — including one a previous file opened and never closed, whose // unref'd cadence timer is still doing honest work. A neighbour narrating // is a REAL finding about suite hygiene, but it is not this brain failing // its own law, and the two must not be reported as the same thing. // // So: spies first (whose failure means the engine broke the law), console // second (whose failure means SOMETHING in the process narrated), and the // console assertion carries the captured lines in its message. vitest's // stdout blocks are prefixed `stdout | > `, so those lines // plus the surrounding gate log name the brain that printed them. expect(countsSpy).not.toHaveBeenCalled() expect(metadataSpy).not.toHaveBeenCalled() expect(graphSpy).not.toHaveBeenCalled() const flushChatter = logged.filter( (l) => /All indexes flushed to disk/.test(l) || /Flushing Brainy indexes/.test(l) ) expect( flushChatter, `${flushChatter.length} flush line(s) narrated during the ${IDLE_WATCH_MS}ms idle ` + `window. This brain's own providers were NOT called (asserted above), so another ` + `brain alive in this process printed them — the suite runs every file in ONE ` + `process and 67 test files create more brains than they close.\n` + `${flushChatter.join('\n')}\n\n` + `The stack behind the first one names the driver:\n${stacks[0] ?? '(none captured)'}` ).toEqual([]) }, 180_000) it('an explicit flush over a clean brain calls no provider and prints nothing', async () => { const brain = await openBrain() await brain.add({ data: 'one write', type: NounType.Concept }) await brain.flush() // this one does the work const storage = (brain as unknown as { storage: { flushCounts: () => Promise } }).storage const metadataIndex = (brain as unknown as { metadataIndex: { flush: () => Promise } }).metadataIndex const countsSpy = vi.spyOn(storage, 'flushCounts') const metadataSpy = vi.spyOn(metadataIndex, 'flush') const logged: string[] = [] const origLog = console.log console.log = ((...a: unknown[]) => { logged.push(a.map(String).join(' ')) }) as typeof console.log try { await brain.flush() // ...and this one has nothing to do await brain.flush() await brain.flush() } finally { console.log = origLog } expect(countsSpy).not.toHaveBeenCalled() expect(metadataSpy).not.toHaveBeenCalled() expect(logged.filter((l) => /All indexes flushed to disk/.test(l))).toEqual([]) }, 120_000) it('one write earns exactly one flush', async () => { const brain = await openBrain() await brain.add({ data: 'first', type: NounType.Concept }) await brain.flush() // Settle: the first write also kicked a BACKGROUND flush, which is not // awaited by design. Drain it before counting, or its provider calls land // inside this test's window and are attributed to the write below. await drainCadence(brain) // Count the flushes that actually RAN. (Provider spies cannot answer this: // the storage adapter's own count ledger is write-through, so a write calls // flushCounts() on its own account, with no flush involved.) const logged: string[] = [] const origLog = console.log console.log = ((...a: unknown[]) => { logged.push(a.map(String).join(' ')) }) as typeof console.log const ran = () => logged.filter((l) => /All indexes flushed to disk/.test(l)).length try { await brain.add({ data: 'second — this is the cause', type: NounType.Concept }) await brain.flush() expect(ran()).toBe(1) // No further cause, no further work. await brain.flush() await brain.flush() expect(ran()).toBe(1) } finally { console.log = origLog } }, 120_000) })