The release gate's own output caught this: every test brain printed "[VFS] old-root sweep complete in 1ms and recorded" — hundreds of lines — and a consumer would get two of them on the first open of every store. They were emitted on the always-visible channel, which a production log level deliberately CANNOT silence. That channel exists so an operator can always learn why a database is slow; a 0ms no-op on a fresh store is not that, and announcing it there trains people to ignore the one channel built to be impossible to ignore. It was also inconsistent with every other narration in this work, all of which is silent under a threshold. The sweep now speaks when it has something to say — duplicate roots removed, or a wall over a second that a person watching a slow first open deserves explained — and otherwise does its work, records its marker, and stays quiet. cleanupOldRoots() reports what it removed so the decision rests on a fact rather than on a guess. Pin: a fresh store's sweep emits nothing on the channel and still records its marker, so the silence can never be mistaken for the work being skipped.
133 lines
5.2 KiB
TypeScript
133 lines
5.2 KiB
TypeScript
/**
|
||
* @module tests/integration/vfs-root-sweep-once
|
||
* @description THE OLD-ROOT SWEEP RUNS ONCE PER STORE, NOT ONCE PER OPEN.
|
||
*
|
||
* The VFS bootstrap ran a filtered `find()` over the whole store on EVERY
|
||
* open, hunting for root directories created before the fixed root id existed
|
||
* — duplicates a store has either always had or never will. MEASURED on a
|
||
* 14,056-noun / 72,679-verb store: the phase it dominates cost 43–53 SECONDS
|
||
* of every open, warm reopens included.
|
||
*
|
||
* The law: a migration sweep is caused by the store's state, not by the clock
|
||
* or the open count. It runs behind the doors, records that it ran, and a
|
||
* store carrying that record never sweeps again.
|
||
*/
|
||
|
||
import { describe, it, expect, afterEach, vi } from 'vitest'
|
||
import { mkdtempSync, rmSync, 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 { VirtualFileSystem } from '../../src/vfs/VirtualFileSystem.js'
|
||
import { prodLog } from '../../src/utils/logger.js'
|
||
|
||
describe('the VFS old-root sweep', () => {
|
||
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 open(dir: string): Promise<Brainy> {
|
||
const brain = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } })
|
||
brains.push(brain)
|
||
await brain.init()
|
||
return brain
|
||
}
|
||
|
||
it('sweeps on the first open, records it, and never sweeps again', async () => {
|
||
const dir = mkdtempSync(join(tmpdir(), 'brainy-root-sweep-'))
|
||
dirs.push(dir)
|
||
|
||
const sweepSpy = vi.spyOn(
|
||
VirtualFileSystem.prototype as unknown as { cleanupOldRoots: () => Promise<void> },
|
||
'cleanupOldRoots'
|
||
)
|
||
|
||
const first = await open(dir)
|
||
await (first.vfs as unknown as { whenRootSweepSettled: () => Promise<void> }).whenRootSweepSettled()
|
||
expect(sweepSpy).toHaveBeenCalledTimes(1)
|
||
// The record is durable engine plumbing under _system/, like every other marker.
|
||
expect(
|
||
existsSync(join(dir, '_system', 'vfs-root-sweep.json')) ||
|
||
existsSync(join(dir, '_system', 'vfs-root-sweep.json.gz'))
|
||
).toBe(true)
|
||
|
||
await first.add({ data: 'a row so the store is not trivially empty', type: NounType.Concept })
|
||
await first.flush()
|
||
await first.close()
|
||
brains.splice(brains.indexOf(first), 1)
|
||
|
||
sweepSpy.mockClear()
|
||
const second = await open(dir)
|
||
await (second.vfs as unknown as { whenRootSweepSettled: () => Promise<void> }).whenRootSweepSettled()
|
||
expect(sweepSpy).not.toHaveBeenCalled()
|
||
|
||
await second.close()
|
||
brains.splice(brains.indexOf(second), 1)
|
||
|
||
// ...and a third open, to prove it is the record and not a one-off.
|
||
sweepSpy.mockClear()
|
||
const third = await open(dir)
|
||
await (third.vfs as unknown as { whenRootSweepSettled: () => Promise<void> }).whenRootSweepSettled()
|
||
expect(sweepSpy).not.toHaveBeenCalled()
|
||
}, 180_000)
|
||
|
||
it('a sweep that removes nothing on a fresh store says nothing', async () => {
|
||
const dir = mkdtempSync(join(tmpdir(), 'brainy-root-sweep-quiet-'))
|
||
dirs.push(dir)
|
||
|
||
// The always-visible channel cannot be silenced by a log level, so a line
|
||
// on it has to earn its place. A fresh store's sweep finds no duplicate
|
||
// roots and costs a millisecond — it must do its work, record its marker,
|
||
// and stay quiet, or it trains operators to ignore the one channel that
|
||
// exists to be impossible to ignore.
|
||
const narrated: string[] = []
|
||
const spy = vi.spyOn(prodLog, 'narrate').mockImplementation(((...args: unknown[]) => {
|
||
narrated.push(args.map((a) => String(a)).join(' '))
|
||
}) as typeof prodLog.narrate)
|
||
|
||
const brain = await open(dir)
|
||
await (brain.vfs as unknown as { whenRootSweepSettled: () => Promise<void> }).whenRootSweepSettled()
|
||
spy.mockRestore()
|
||
|
||
expect(narrated.filter((l) => /old-root sweep/i.test(l))).toEqual([])
|
||
// ...and it still did the work: the marker is recorded, so no future open sweeps.
|
||
expect(
|
||
existsSync(join(dir, '_system', 'vfs-root-sweep.json')) ||
|
||
existsSync(join(dir, '_system', 'vfs-root-sweep.json.gz'))
|
||
).toBe(true)
|
||
}, 180_000)
|
||
|
||
it('the open does not wait for the sweep', async () => {
|
||
const dir = mkdtempSync(join(tmpdir(), 'brainy-root-sweep-async-'))
|
||
dirs.push(dir)
|
||
|
||
const proto = VirtualFileSystem.prototype as unknown as Record<
|
||
string,
|
||
(...args: unknown[]) => Promise<unknown>
|
||
>
|
||
const real = proto.cleanupOldRoots
|
||
proto.cleanupOldRoots = async function slow(this: unknown, ...args: unknown[]) {
|
||
await new Promise((r) => setTimeout(r, 4_000))
|
||
return real.apply(this, args)
|
||
}
|
||
try {
|
||
const startedAt = Date.now()
|
||
const brain = await open(dir)
|
||
const openMs = Date.now() - startedAt
|
||
expect(openMs).toBeLessThan(3_000)
|
||
await (brain.vfs as unknown as { whenRootSweepSettled: () => Promise<void> }).whenRootSweepSettled()
|
||
} finally {
|
||
proto.cleanupOldRoots = real
|
||
}
|
||
}, 180_000)
|
||
})
|