P1 registered two healthy modes in `ORDINARY_DEGRADATIONS` — `hybrid` (the wired
success path) and `no_vector_space` (a space with nothing comparable to score) —
and the commit message claimed that meant "a healthy wired recall does not log a
warning every turn". Nothing tested it. Measured on 1309afe:
M-a delete 'hybrid' → # tests 268 # pass 268 # fail 0
M-b delete 'no_vector_space' → # tests 268 # pass 268 # fail 0
M-ab delete both → # tests 268 # pass 268 # fail 0
while the behaviour really broke (real apply(), debugLog=false):
mutated hybrid recall → lines=[['warn', '... degraded=hybrid ... inject=138ch']]
released hybrid recall → lines=[]
A false fault alarm on the happiest path, every single turn, and the suite green.
Why the existing tests could not see it: A3d/D3b assert the LABEL
(`hits.degraded === 'hybrid'`). Removing a member from the Set does not change any
label — it changes only whether `logRecallTurn` treats that label as a fault. The
defect lived exactly in the gap between "the label is right" and "the level is
right", and `grep ORDINARY_DEGRADATIONS test/` was empty. A claim in a commit
message with nothing behind it is the same failure mode as a guard that cannot
fail.
What this commit adds (test/memory-log.test.js only — lib/ untouched)
L10 one group, three outcomes at the SAME verbosity (debugLog: false):
`hybrid` → zero lines
`no_vector_space` → zero lines
`embed_error` → exactly one line, type 'warn' ← the control
Each case asserts its own PRECONDITION first (the run really was
`hybrid` / `no_vector_space`, and something was really injected), so a
silent log cannot be confused with a build that never reached the route.
Without the third case, "silent" would also be satisfied by a build that
logs nothing at all — which is the original bug the log channel exists
for (L4).
L10† real mutation: 'hybrid' removed from the Set → L10.1 red
L11† real mutation: 'no_vector_space' removed → L10.2 red
Both via `withMutatedIndex` (copy the package, rewrite ONE anchor,
`count === 1` self-check, import fresh). The mutant runs the SAME
`assertLevelContract` body the released build passes — a criterion copied
for the mutant can drift, a shared one cannot. The mutation then asserts
the throw is `ERR_ASSERTION` AND that the message starts with the specific
sub-assertion name, so an import failure cannot make it green for the
wrong reason.
L11 measured behaviour, pinned so nobody "fixes" it later: a fused recall
whose candidates were ALL refused by `minScore` still reports `hybrid`
with zero hits, and is still silent. `no_vector_space` is returned at
exactly one place (`recall.js`, `vectorScores.size === 0`) and means
"there was nothing to score" — never "everything was filtered". Collapsing
the two would hide a threshold set too high behind a "fresh space" story.
Two fixture pitfalls found while writing this, both recorded in the test because
each one silently disarmed its own case:
· `commit` embeds when an embedder is mounted, so the `no_vector_space` case has
to write its block BEFORE the embedder appears. The first attempt mounted the
embedder first, the space filled up, and the label came back `hybrid` — the
assertion then failed for its own precondition rather than for the subject.
· `StableMem.recall()` forwards only `topK`/`signal`, so a `minScore` passed
there never reaches the scorer and L11's precondition would have passed on an
unchanged result. It drives `recallBlocksHybrid` directly instead.
Not asserted, deliberately: `'no_embedder'`, `'aborted'` and `'vector_ready_unused'`
are also in the Set, but their silence is already carried by L1/L5 (no embedder)
and W11e/W12 elsewhere. Adding them here would inflate the group without covering a
new decision.
旁证 (not acceptance): npm test 272/272, npm run check 12/12, npm pack --dry-run
10 files / 75.3 kB. docs/ and README.md untouched.
786 lines
34 KiB
JavaScript
786 lines
34 KiB
JavaScript
/**
|
||
* Observability contract for the recall log.
|
||
*
|
||
* The plugin shipped with zero `console.*` and zero `ctx.logger` calls, so a
|
||
* production recall failure left no trace anywhere: `degraded` is a return value
|
||
* the caller sees once, and the injected text only shows up if the model quotes
|
||
* it. These tests pin the replacement channel.
|
||
*
|
||
* What is pinned here, and why each assertion exists:
|
||
*
|
||
* L1 `debugLog: false` (the default) is quiet on an ordinary turn, and still
|
||
* carries every fact the operator needs when it does speak.
|
||
* L2 `debugLog: true` emits exactly ONE line covering recall / budget /
|
||
* degradation / injection.
|
||
* L3 the query TEXT is never logged — only its length.
|
||
* L4 a real fault (`embed_error`) speaks even with `debugLog` off, at `warn`.
|
||
* L5 a zero-injection turn is `debug`, not `info` — the commonest case must
|
||
* cost nothing at normal verbosity.
|
||
* L6 logging changes no behaviour: the returned text and `lastRecall` are
|
||
* identical with the summary on and off.
|
||
* L7 nothing is ever written to stdout (headless prints the ANSWER there) and
|
||
* the console fallback goes to `console.warn`, not `console.log`.
|
||
* L10 `ORDINARY_DEGRADATIONS` actually gates the level: the two healthy modes
|
||
* (`hybrid`, `no_vector_space`) are SILENT with `debugLog` off, while a
|
||
* real fault (`embed_error`) is a single `warn`. L10†/L11† mutate the set to
|
||
* prove those two assertions bite.
|
||
* L11 a fused recall whose candidates are ALL refused by `minScore` still
|
||
* reports `hybrid` with zero hits, and is still silent. `no_vector_space`
|
||
* means "there was nothing to score", never "everything was filtered" —
|
||
* collapsing the two would hide a threshold set too high.
|
||
*
|
||
* @module dsh-memory/test/memory-log
|
||
*/
|
||
|
||
import assert from 'node:assert/strict'
|
||
import { mkdtempSync, rmSync } from 'node:fs'
|
||
import { tmpdir } from 'node:os'
|
||
import { join } from 'node:path'
|
||
import test from 'node:test'
|
||
import { Context } from '@deepseek-ai/cordis'
|
||
import { Logger } from '@deepseek-ai/cordis'
|
||
import { createUserMessage } from '@deepseek-ai/dsh-llm'
|
||
import { SystemPrompt } from '@deepseek-ai/dsh-system-prompt'
|
||
import { ToolRuntime } from '@deepseek-ai/dsh-tools'
|
||
import { apply as applyMemory, StableMem } from '../lib/index.js'
|
||
import { recallBlocksHybrid, segmentRecallBudget } from '../lib/recall.js'
|
||
import { BlockStore } from '../lib/store.js'
|
||
|
||
/**
|
||
* Build a real cordis app + plugin instance, capturing every log record.
|
||
*
|
||
* `levels: { default: 3 }` is DEBUG: cordis skips a record when
|
||
* `(exporter.levels[name] ?? default ?? logger.level ?? INFO) < level`
|
||
* (cordis/lib/index.js:470-472), so the default would silently drop `debug` and
|
||
* L5 could never observe its own subject.
|
||
*
|
||
* @param {object} config plugin config
|
||
*/
|
||
async function makeMemWith(apply, config = {}) {
|
||
const dir = mkdtempSync(join(tmpdir(), 'mlog-'))
|
||
const ctx = new Context()
|
||
new SystemPrompt(ctx, {})
|
||
new ToolRuntime(ctx, {})
|
||
const records = []
|
||
ctx.logger.exporter({
|
||
levels: { default: 3 },
|
||
export: (message) => records.push(message),
|
||
})
|
||
const mem = apply(ctx, { path: join(dir, 'm.db'), ...config })
|
||
return {
|
||
ctx,
|
||
mem,
|
||
records,
|
||
/**
|
||
* Only this plugin's lines, rendered the way the logger actually prints them.
|
||
*
|
||
* `Logger.format` rather than a plain `args.join(' ')`: every call site emits
|
||
* `log(level)('%s', line)` so the payload cannot be reformatted (see `emit`)
|
||
* — a naive join would keep the literal `%s` prefix and hide a regression
|
||
* where the payload stopped being a single argument.
|
||
*/
|
||
lines: () =>
|
||
records
|
||
.filter((record) => record.name === 'dsh-memory')
|
||
.map((record) => ({ type: record.type, text: Logger.format({}, record) })),
|
||
async done() {
|
||
await ctx.fiber.dispose()
|
||
rmSync(dir, { recursive: true, force: true })
|
||
},
|
||
}
|
||
}
|
||
|
||
/**
|
||
* The same app, built by the module under test.
|
||
*
|
||
* Parameterised by `apply` so the ORDINARY_DEGRADATIONS mutants below can run the
|
||
* IDENTICAL criterion body against a mutated `lib/index.js`. A criterion that is
|
||
* copied for the mutant can drift from the real one; a criterion that is shared
|
||
* cannot.
|
||
*
|
||
* @param {object} [config] plugin config
|
||
*/
|
||
async function makeMem(config = {}) {
|
||
return makeMemWith(applyMemory, config)
|
||
}
|
||
|
||
/** A one-message human batch. */
|
||
function ask(text) {
|
||
return [createUserMessage({ content: [{ type: 'text', text }], source: { kind: 'user' } })]
|
||
}
|
||
|
||
/** An embedder that fails the way a dead provider does. */
|
||
const failingEmbedder = {
|
||
async embedText() {
|
||
throw new Error('read ECONNREFUSED 127.0.0.1:8081')
|
||
},
|
||
info: () => ({ fingerprint: 'fp-log', dimension: 3 }),
|
||
}
|
||
|
||
// ── L1: default config is quiet, and stays quiet for the commonest case ───
|
||
test('L1: debugLog defaults to false and an ordinary hitless turn logs nothing', async () => {
|
||
const { mem, lines, done } = await makeMem()
|
||
try {
|
||
assert.equal(mem.debugLog, false, 'the default must be false — the log is opt-in')
|
||
// No embedder is the shipping default; recall degrades to `no_embedder`,
|
||
// which is a standing configuration fact, not an event (same judgement W11e
|
||
// made for the model-facing notice).
|
||
await mem.commit({ text: '某条无关记忆' })
|
||
for (const turn of ['今天天气怎么样', '你好', '好的']) {
|
||
await mem.contextForStep(ask(turn))
|
||
}
|
||
assert.deepEqual(lines(), [], `the default must be silent; got ${JSON.stringify(lines())}`)
|
||
} finally {
|
||
await done()
|
||
}
|
||
})
|
||
|
||
// ── L2/L3: opt in, then all four fact groups appear in ONE line ───────────
|
||
test('L2: debugLog=true emits one line covering recall, budget, degradation and injection', async () => {
|
||
const { mem, lines, done } = await makeMem({ debugLog: true, topK: 3, budgetTokens: 500 })
|
||
try {
|
||
assert.equal(mem.debugLog, true, 'config.debugLog must reach the service')
|
||
await mem.commit({ text: '值班室分机号 4324,值班人 老周' })
|
||
|
||
const question = '值班室分机号是多少'
|
||
const text = await mem.contextForStep(ask(question))
|
||
assert.notEqual(text, '', 'precondition: the block must be recalled')
|
||
|
||
const emitted = lines()
|
||
assert.equal(emitted.length, 1, `exactly one line per recall turn; got ${JSON.stringify(emitted)}`)
|
||
const [record] = emitted
|
||
assert.equal(record.type, 'info', 'a turn that injected something is an info line')
|
||
|
||
// recall: length only, never the text.
|
||
assert.match(record.text, /recall query=9ch/, `query length in code points; got: ${record.text}`)
|
||
assert.ok(
|
||
!record.text.includes(question),
|
||
`the query TEXT must never be logged; got: ${record.text}`,
|
||
)
|
||
assert.match(record.text, /hits=[1-9]\d*/, 'hit count')
|
||
assert.match(record.text, /topK=3/, 'topK actually used')
|
||
assert.match(record.text, /zeroHit=no/, 'the 0-hit flag must be stated, not inferred')
|
||
|
||
// budget: which cap applied and what it retained.
|
||
assert.match(record.text, /budget=500 /, 'the explicit budget wins')
|
||
assert.match(record.text, /source=explicit/, 'source must name the rule that produced the budget')
|
||
assert.match(record.text, /kept=1\b/, 'retained count after segmenting')
|
||
assert.match(record.text, /singleHitOverBudget=(yes|no)/, 'the over-budget single-hit case is reported')
|
||
|
||
// degradation: the empty case is reported as healthy, explicitly.
|
||
assert.match(record.text, /degraded=no_embedder/, 'the mode is named, not omitted')
|
||
assert.match(record.text, /skipped=0 skippedDim=0/, 'skip counters')
|
||
assert.match(record.text, /err=-/, 'no error digest when there is no error')
|
||
|
||
// injection: the exact string length that reached the model.
|
||
assert.match(record.text, new RegExp(`inject=${[...text].length}ch`), 'injected length')
|
||
} finally {
|
||
await done()
|
||
}
|
||
})
|
||
|
||
test('L3: the budget source is named for each precedence rule', async () => {
|
||
// explicit > host window > fallback, read straight off the summary line.
|
||
const explicit = await makeMem({ debugLog: true, budgetTokens: 1234 })
|
||
try {
|
||
await explicit.mem.commit({ text: '值班室分机号 4324' })
|
||
await explicit.mem.contextForStep(ask('值班室分机号是多少'))
|
||
assert.match(explicit.lines()[0].text, /budget=1234 source=explicit/)
|
||
} finally {
|
||
await explicit.done()
|
||
}
|
||
|
||
const host = await makeMem({ debugLog: true })
|
||
try {
|
||
await host.mem.commit({ text: '值班室分机号 4324' })
|
||
// A host window of 100 tokens → 80% = 80 token budget.
|
||
await host.mem.contextForStep(ask('值班室分机号是多少'), undefined, { contextWindow: 100 })
|
||
assert.match(host.lines()[0].text, /budget=80 source=host/)
|
||
} finally {
|
||
await host.done()
|
||
}
|
||
|
||
const fallback = await makeMem({ debugLog: true })
|
||
try {
|
||
await fallback.mem.commit({ text: '值班室分机号 4324' })
|
||
await fallback.mem.contextForStep(ask('值班室分机号是多少'))
|
||
assert.match(fallback.lines()[0].text, /budget=4096 source=fallback/)
|
||
} finally {
|
||
await fallback.done()
|
||
}
|
||
})
|
||
|
||
// ── L4: a real fault speaks with the log switched off ─────────────────────
|
||
test('L4: an embed_error is warned about even when debugLog is false', async () => {
|
||
const { mem, lines, done } = await makeMem({ embedder: failingEmbedder })
|
||
try {
|
||
assert.equal(mem.debugLog, false)
|
||
await mem.commit({ text: '值班室分机号 4324' })
|
||
// `commit` also embeds, so clear the records that produced to keep the
|
||
// assertion about the RECALL line unambiguous.
|
||
lines().length = 0
|
||
await mem.contextForStep(ask('值班室分机号是多少'))
|
||
|
||
const recalled = lines().filter((line) => line.text.startsWith('recall '))
|
||
assert.equal(recalled.length, 1, `a fault must produce exactly one recall line; got ${JSON.stringify(recalled)}`)
|
||
assert.equal(recalled[0].type, 'warn', 'a failed search is a warn, not an info/debug')
|
||
assert.match(recalled[0].text, /degraded=embed_error/)
|
||
assert.match(
|
||
recalled[0].text,
|
||
/err=read ECONNREFUSED 127\.0\.0\.1:8081/,
|
||
`the error digest must name the cause; got: ${recalled[0].text}`,
|
||
)
|
||
} finally {
|
||
await done()
|
||
}
|
||
})
|
||
|
||
test('L4b: a long provider error is flattened and truncated, never a multi-line log', async () => {
|
||
const verbose = {
|
||
async embedText() {
|
||
throw new Error(`connection refused\n at socket.js:1\n${'x'.repeat(400)}`)
|
||
},
|
||
info: () => ({ fingerprint: 'fp-log2', dimension: 3 }),
|
||
}
|
||
const { mem, lines, done } = await makeMem({ embedder: verbose })
|
||
try {
|
||
await mem.contextForStep(ask('值班室分机号是多少'))
|
||
const recalled = lines().filter((line) => line.text.startsWith('recall '))
|
||
assert.equal(recalled.length, 1)
|
||
assert.ok(!recalled[0].text.includes('\n'), 'a log line must be one line')
|
||
assert.ok(recalled[0].text.includes('...'), 'the digest must be truncated')
|
||
assert.ok(
|
||
recalled[0].text.length < 400,
|
||
`the digest must be bounded; got ${recalled[0].text.length} chars`,
|
||
)
|
||
} finally {
|
||
await done()
|
||
}
|
||
})
|
||
|
||
// ── L5: the commonest case is `debug`, not `info` ────────────────────────
|
||
test('L5: a zero-injection turn logs exactly one DEBUG line, not info', async () => {
|
||
const { mem, lines, done } = await makeMem({ debugLog: true })
|
||
try {
|
||
await mem.commit({ text: '某条无关记忆' })
|
||
const text = await mem.contextForStep(ask('今天天气怎么样'))
|
||
assert.equal(text, '', 'precondition: nothing is injected')
|
||
|
||
const emitted = lines()
|
||
assert.equal(emitted.length, 1, `still exactly one line; got ${JSON.stringify(emitted)}`)
|
||
assert.equal(emitted[0].type, 'debug', 'zero injection must not be an info line')
|
||
assert.match(emitted[0].text, /zeroHit=yes/, 'the 0-hit case must say so')
|
||
assert.match(emitted[0].text, /inject=0ch/)
|
||
} finally {
|
||
await done()
|
||
}
|
||
})
|
||
|
||
test('L5b: a batch with no human prompt logs one debug line and recalls nothing', async () => {
|
||
const { mem, lines, done } = await makeMem({ debugLog: true })
|
||
try {
|
||
// This is the shape that once made every real turn recall the skill catalog,
|
||
// so "there was no human prompt" is worth a line of its own.
|
||
const injected = await mem.contextForStep([
|
||
createUserMessage({
|
||
content: [{ type: 'text', text: '[Skills]\n- alpha\n- beta' }],
|
||
source: { kind: 'skill-catalog', form: 'snapshot' },
|
||
}),
|
||
])
|
||
assert.equal(injected, '', 'an injected snapshot is not a recall query')
|
||
const emitted = lines()
|
||
assert.equal(emitted.length, 1)
|
||
assert.equal(emitted[0].type, 'debug')
|
||
assert.match(emitted[0].text, /query=0ch/)
|
||
assert.match(emitted[0].text, /skipped=no-human-prompt/)
|
||
} finally {
|
||
await done()
|
||
}
|
||
})
|
||
|
||
// ── L6: observability must be inert ──────────────────────────────────────
|
||
test('L6: turning the log on changes neither the injected text nor lastRecall', async () => {
|
||
const run = async (debugLog) => {
|
||
const app = await makeMem({ debugLog })
|
||
try {
|
||
await app.mem.commit({ text: '值班室分机号 4324,值班人 老周' })
|
||
const text = await app.mem.contextForStep(ask('值班室分机号是多少'), undefined, {
|
||
contextWindow: 2000,
|
||
})
|
||
const { at, ...lastRecall } = app.mem.stats().last_recall ?? {}
|
||
void at
|
||
return { text, lastRecall }
|
||
} finally {
|
||
await app.done()
|
||
}
|
||
}
|
||
|
||
const quiet = await run(false)
|
||
const loud = await run(true)
|
||
assert.equal(loud.text, quiet.text, 'the injected text must be byte-identical')
|
||
assert.notEqual(quiet.text, '', 'precondition: something was injected')
|
||
assert.deepEqual(loud.lastRecall, quiet.lastRecall, 'the stats surface must be unchanged')
|
||
})
|
||
|
||
// ── L7: stdout stays clean; the fallback shim goes to warn ───────────────
|
||
test('L7: logging never touches stdout, and the console fallback uses console.warn', async () => {
|
||
const stdout = []
|
||
const warned = []
|
||
const errored = []
|
||
const originals = {
|
||
log: console.log,
|
||
warn: console.warn,
|
||
error: console.error,
|
||
}
|
||
console.log = (...args) => stdout.push(args)
|
||
console.warn = (...args) => warned.push(args)
|
||
console.error = (...args) => errored.push(args)
|
||
|
||
const { mem, done } = await makeMem({ debugLog: true })
|
||
let fallbackCtx = null
|
||
let fallbackStore = null
|
||
try {
|
||
await mem.commit({ text: '值班室分机号 4324' })
|
||
await mem.contextForStep(ask('值班室分机号是多少'))
|
||
assert.deepEqual(
|
||
stdout,
|
||
[],
|
||
`the real logger path must never write stdout (headless prints the ANSWER there); got ${JSON.stringify(stdout)}`,
|
||
)
|
||
|
||
// Now the fallback: a context whose logger service cannot produce a facade.
|
||
// `resolveLogger` must degrade to console.warn rather than throw.
|
||
fallbackCtx = new Context()
|
||
fallbackCtx.logger = () => {
|
||
throw new Error('no logger service')
|
||
}
|
||
fallbackStore = new BlockStore({ path: ':memory:' }).open()
|
||
const fallback = new StableMem(fallbackCtx, { store: fallbackStore, debugLog: true })
|
||
fallback.log.warn('%s', 'shim warn')
|
||
fallback.log.debug('%s', 'shim debug')
|
||
fallback.log.error('%s', 'shim error')
|
||
|
||
assert.deepEqual(stdout, [], `stdout must stay clean; got ${JSON.stringify(stdout)}`)
|
||
assert.deepEqual(
|
||
warned.map((args) => args.join(' ')),
|
||
['shim warn', 'shim debug'],
|
||
'the fallback routes both debug and info to console.warn',
|
||
)
|
||
assert.deepEqual(errored.map((args) => args.join(' ')), ['shim error'])
|
||
} finally {
|
||
console.log = originals.log
|
||
console.warn = originals.warn
|
||
console.error = originals.error
|
||
fallbackStore?.close()
|
||
await fallbackCtx?.fiber.dispose()
|
||
await done()
|
||
}
|
||
})
|
||
|
||
// ── L4†: a mutation, not a self-test ─────────────────────────────────────
|
||
//
|
||
// "A guard that cannot fail is not a guard" — the same rule W11d†/W11e† follow in
|
||
// phase-B-H. This one patches `lib/index.js` on a COPY, imports it fresh, and
|
||
// asserts the behaviour flips. If the anchor moves, the split-count assertion
|
||
// fails loudly instead of the test silently passing against unmutated source.
|
||
test('L4†: silencing the fault branch turns L4 red', async () => {
|
||
const { readFileSync, writeFileSync, mkdtempSync, rmSync, cpSync } = await import('node:fs')
|
||
const { tmpdir } = await import('node:os')
|
||
const { join } = await import('node:path')
|
||
const { fileURLToPath, pathToFileURL } = await import('node:url')
|
||
|
||
const libDir = fileURLToPath(new URL('../lib/', import.meta.url))
|
||
const pkgRoot = fileURLToPath(new URL('..', import.meta.url))
|
||
const dir = mkdtempSync(join(tmpdir(), 'mlog-mut-'))
|
||
try {
|
||
cpSync(libDir, join(dir, 'lib'), { recursive: true })
|
||
cpSync(join(pkgRoot, 'package.json'), join(dir, 'package.json'))
|
||
try {
|
||
cpSync(join(pkgRoot, 'node_modules'), join(dir, 'node_modules'), {
|
||
recursive: true,
|
||
dereference: false,
|
||
})
|
||
} catch {
|
||
// Poetry-free install: the body below will fail loudly, which is correct.
|
||
}
|
||
|
||
const target = join(dir, 'lib', 'index.js')
|
||
const source = readFileSync(target, 'utf8')
|
||
const anchor = ' if (this.debugLog !== true && !fault) return'
|
||
assert.equal(
|
||
source.split(anchor).length - 1,
|
||
1,
|
||
'L4† anchor must occur exactly once — did the gating line move?',
|
||
)
|
||
writeFileSync(target, source.replace(anchor, ' if (this.debugLog !== true) return // MUTATED'))
|
||
|
||
const mod = await import(pathToFileURL(target).href)
|
||
const ctx = new Context()
|
||
new SystemPrompt(ctx, {})
|
||
new ToolRuntime(ctx, {})
|
||
const records = []
|
||
ctx.logger.exporter({ levels: { default: 3 }, export: (message) => records.push(message) })
|
||
try {
|
||
const mem = mod.apply(ctx, {
|
||
path: join(dir, 'm.db'),
|
||
embedder: failingEmbedder,
|
||
})
|
||
await mem.contextForStep(ask('值班室分机号是多少'))
|
||
const recalled = records.filter(
|
||
(record) => record.name === 'dsh-memory' && String(record.args[1] ?? '').startsWith('recall '),
|
||
)
|
||
assert.deepEqual(
|
||
recalled,
|
||
[],
|
||
'under the mutation a fault is silent with debugLog off, so L4 must fail',
|
||
)
|
||
} finally {
|
||
await ctx.fiber.dispose()
|
||
}
|
||
} finally {
|
||
rmSync(dir, { recursive: true, force: true })
|
||
}
|
||
})
|
||
|
||
// ── L8: the line must actually be READABLE in a real process ──────────────
|
||
//
|
||
// Measured: cordis ships one default exporter (an in-memory ring buffer) and no
|
||
// dsh bundle installs a terminal one, so `ctx.logger.info(...)` in a real profile
|
||
// lands in a buffer nobody drains. A "we added logging" change that only reaches
|
||
// that buffer would be green here and still print nothing in `dsh headless`.
|
||
// So this asserts on process.stderr, which is where an operator can see it.
|
||
test('L8: the summary reaches stderr, gated by debugLog, and never stdout', async () => {
|
||
const originalWrite = process.stderr.write
|
||
const stderr = []
|
||
const stdout = []
|
||
const originalOutWrite = process.stdout.write
|
||
process.stderr.write = (chunk, ...rest) => {
|
||
stderr.push(String(chunk))
|
||
return originalWrite.call(process.stderr, chunk, ...rest)
|
||
}
|
||
process.stdout.write = (chunk, ...rest) => {
|
||
stdout.push(String(chunk))
|
||
return originalOutWrite.call(process.stdout, chunk, ...rest)
|
||
}
|
||
|
||
const runTurn = async (config) => {
|
||
stderr.length = 0
|
||
const app = await makeMem(config)
|
||
try {
|
||
await app.mem.commit({ text: '值班室分机号 4324,值班人 老周' })
|
||
stderr.length = 0 // drop anything the commit produced
|
||
await app.mem.contextForStep(ask('值班室分机号是多少'))
|
||
return stderr.join('')
|
||
} finally {
|
||
await app.done()
|
||
}
|
||
}
|
||
|
||
try {
|
||
const loud = await runTurn({ debugLog: true })
|
||
assert.match(loud, /^dsh-memory: info: recall query=9ch/m, `want one info line on stderr; got: ${JSON.stringify(loud)}`)
|
||
|
||
const quiet = await runTurn({})
|
||
assert.equal(quiet, '', `debugLog=false must print nothing for a healthy turn; got: ${JSON.stringify(quiet)}`)
|
||
|
||
assert.deepEqual(stdout, [], `stdout must never be written; got ${JSON.stringify(stdout)}`)
|
||
} finally {
|
||
process.stderr.write = originalWrite
|
||
process.stdout.write = originalOutWrite
|
||
}
|
||
})
|
||
|
||
test('L8b: foreign loggers are not reprinted under this plugin’s prefix', async () => {
|
||
// The exporters map is process-wide, so a sink without a name check would
|
||
// duplicate every other plugin's warnings — turning an observability change
|
||
// into an amplification bug.
|
||
const originalWrite = process.stderr.write
|
||
const stderr = []
|
||
process.stderr.write = (chunk, ...rest) => {
|
||
stderr.push(String(chunk))
|
||
return originalWrite.call(process.stderr, chunk, ...rest)
|
||
}
|
||
const { ctx, mem, done } = await makeMem({ debugLog: true })
|
||
try {
|
||
stderr.length = 0
|
||
ctx.logger('some-other-plugin').warn('%s', 'not mine')
|
||
ctx.logger('some-other-plugin').info('%s', 'also not mine')
|
||
void mem
|
||
assert.equal(stderr.join(''), '', `another plugin's records must not be reprinted; got: ${JSON.stringify(stderr)}`)
|
||
} finally {
|
||
process.stderr.write = originalWrite
|
||
await done()
|
||
}
|
||
})
|
||
|
||
// ══════════════════════════════════════════════════════════════════════════════
|
||
// L10 · ORDINARY_DEGRADATIONS must actually DECIDE the level
|
||
// ══════════════════════════════════════════════════════════════════════════════
|
||
//
|
||
// P1 added two healthy modes to `lib/recall.js` (`hybrid`, `no_vector_space`) and
|
||
// registered both in `ORDINARY_DEGRADATIONS`. Nothing tested that registration:
|
||
// `grep ORDINARY_DEGRADATIONS test/` was empty, and every P1-era assertion checked
|
||
// the LABEL (`hits.degraded === 'hybrid'`), never the LOG LEVEL. Deleting `'hybrid'`
|
||
// from the set therefore kept all 268 tests green while a healthy wired recall
|
||
// started emitting `warn` on every turn — a false fault alarm on the happiest path.
|
||
//
|
||
// The three cases below are deliberately in ONE group so the contrast is visible:
|
||
// two healthy modes must be silent, one real fault must speak, all at the same
|
||
// verbosity (`debugLog: false`, the shipping default).
|
||
|
||
/**
|
||
* An embedder whose vectors put every block and the query on the same axis.
|
||
*
|
||
* Deterministic and transport-free: "a vector exists in this space" is the only
|
||
* fact these cases need, and a real provider would add neither coverage nor
|
||
* determinism.
|
||
*
|
||
* @param {string} fingerprint
|
||
*/
|
||
function fixedEmbedder(fingerprint) {
|
||
return {
|
||
async embedText() { return [1, 0, 0] },
|
||
info: () => ({ fingerprint, dimension: 3 }),
|
||
}
|
||
}
|
||
|
||
const L10_SPACE = 'fp-l10'
|
||
|
||
/**
|
||
* Seed one block that carries a vector in the active space.
|
||
*
|
||
* The explicit vector+fingerprint pair goes through the documented
|
||
* `commit({ vector, fingerprint })` path, so the write is a normal store write
|
||
* rather than a fixture shortcut: `recallBlocksHybrid` sees a real row.
|
||
*
|
||
* @param {{mem: object}} app
|
||
* @param {string} text
|
||
*/
|
||
async function commitVectored(app, text) {
|
||
await app.mem.commit({ text, vector: [1, 0, 0], fingerprint: L10_SPACE })
|
||
}
|
||
|
||
/** The criterion, shared by the real module and every mutant. */
|
||
async function assertLevelContract(build) {
|
||
// ── (1) `hybrid` is silent at the default verbosity ─────────────────────
|
||
//
|
||
// Preconditions asserted, not assumed: the space really holds a comparable
|
||
// vector, the hit really carries a vector contribution, and the label really is
|
||
// `hybrid`. Without them a silent log would be indistinguishable from a build
|
||
// that never reached the vector route at all.
|
||
const hybridApp = await build({ embedder: fixedEmbedder(L10_SPACE) })
|
||
let hybridText
|
||
let hybridHits
|
||
try {
|
||
await commitVectored(hybridApp, '值班室分机号 4324')
|
||
hybridText = await hybridApp.mem.contextForStep(ask('值班室分机号是多少'))
|
||
hybridHits = hybridApp.mem.lastRecall
|
||
const emitted = hybridApp.lines()
|
||
assert.equal(hybridHits?.mode, 'hybrid', `precondition: the wired route must be labelled hybrid; got ${JSON.stringify(hybridHits)}`)
|
||
assert.notEqual(hybridText, '', 'precondition: the block must actually be recalled')
|
||
assert.deepEqual(
|
||
emitted,
|
||
[],
|
||
'L10.1: a HEALTHY wired recall must log nothing with debugLog off. ' +
|
||
'A `warn` here is a false fault alarm on the happiest path, every turn. ' +
|
||
`got ${JSON.stringify(emitted)}`,
|
||
)
|
||
} finally {
|
||
await hybridApp.done()
|
||
}
|
||
|
||
// ── (2) `no_vector_space` is silent too ─────────────────────────────────
|
||
//
|
||
// A configured embedder whose space holds no usable vector. This is a DATA
|
||
// state (fresh space), not a provider fault, so it must not warn either.
|
||
//
|
||
// ★ The block must be written while NO embedder is mounted, otherwise `commit`
|
||
// embeds it and the space is no longer empty — a fixture that quietly fills the
|
||
// space it is supposed to leave bare would make this case assert nothing (it did,
|
||
// on the first attempt: the label came back `hybrid`).
|
||
const emptyApp = await build({})
|
||
try {
|
||
await emptyApp.mem.commit({ text: '值班室分机号 4324' })
|
||
emptyApp.mem.embedder = fixedEmbedder('fp-l10-empty')
|
||
await emptyApp.mem.contextForStep(ask('值班室分机号是多少'))
|
||
const mode = emptyApp.mem.lastRecall?.mode
|
||
assert.equal(mode, 'no_vector_space', `precondition: an empty space must report no_vector_space; got ${mode}`)
|
||
assert.deepEqual(
|
||
emptyApp.lines(),
|
||
[],
|
||
'L10.2: `no_vector_space` is a standing data state, not a fault — it must not warn. ' +
|
||
`got ${JSON.stringify(emptyApp.lines())}`,
|
||
)
|
||
} finally {
|
||
await emptyApp.done()
|
||
}
|
||
|
||
// ── (3) `embed_error` DOES speak, at `warn`, exactly once ───────────────
|
||
//
|
||
// The control. Without it, "silent" could be satisfied by a build that never
|
||
// logs at all — which is the bug the whole log channel exists to fix (L4).
|
||
const faultApp = await build({ embedder: failingEmbedder })
|
||
try {
|
||
await faultApp.mem.commit({ text: '值班室分机号 4324' })
|
||
await faultApp.mem.contextForStep(ask('值班室分机号是多少'))
|
||
const recalled = faultApp.lines().filter((line) => line.text.startsWith('recall '))
|
||
assert.equal(recalled.length, 1, `L10.3: a fault must produce exactly one recall line; got ${JSON.stringify(recalled)}`)
|
||
assert.equal(recalled[0].type, 'warn', `L10.3: a fault is a warn; got ${recalled[0].type}`)
|
||
assert.match(recalled[0].text, /degraded=embed_error/, 'and names the fault')
|
||
} finally {
|
||
await faultApp.done()
|
||
}
|
||
}
|
||
|
||
test('L10: healthy modes are silent and faults warn — the same verbosity, three outcomes', async () => {
|
||
await assertLevelContract(makeMem)
|
||
})
|
||
|
||
// ══════════════════════════════════════════════════════════════════════════════
|
||
// L11 · `minScore` filtering everything is NOT `no_vector_space`
|
||
// ══════════════════════════════════════════════════════════════════════════════
|
||
//
|
||
// Measured behaviour (pinned because "everything was filtered out" looks like a
|
||
// bug to a future reader, and the tempting fix — call it `no_vector_space` — would
|
||
// erase the distinction between "there was nothing to score" and "the threshold is
|
||
// too high"). `no_vector_space` is returned at exactly one place,
|
||
// `recall.js`'s `vectorScores.size === 0`; a fused run that produced candidates
|
||
// and then gated them all keeps the `hybrid` label with `hits: []`.
|
||
|
||
test('L11: a fused recall gated to zero hits by minScore still reports hybrid, and stays silent', async () => {
|
||
const { mem, lines, done } = await makeMem({ embedder: fixedEmbedder(L10_SPACE) })
|
||
try {
|
||
await commitVectored({ mem }, '值班室分机号 4324')
|
||
const question = '值班室分机号是多少'
|
||
|
||
// ★ `minScore` is applied PER PATH against the RAW VECTOR score (V5), not
|
||
// against the fused 0.7. The block's vector score is 1.0, so the threshold
|
||
// that removes it has to exceed 1.0.
|
||
//
|
||
// ★ Driven through `recallBlocksHybrid` rather than `mem.recall`: the
|
||
// service method forwards only `topK`/`signal`, so a threshold passed there
|
||
// would never reach the scorer and this precondition would silently pass on an
|
||
// unchanged result.
|
||
const raw = await recallBlocksHybrid(mem.store, fixedEmbedder(L10_SPACE), question, {
|
||
topK: 3,
|
||
minScore: 1.5,
|
||
})
|
||
assert.deepEqual(
|
||
[...raw].map((hit) => hit.text),
|
||
[],
|
||
`precondition: the threshold must remove every candidate; got ${JSON.stringify(
|
||
[...raw].map((hit) => hit.text),
|
||
)}`,
|
||
)
|
||
assert.equal(
|
||
raw.degraded,
|
||
'hybrid',
|
||
`a gated recall is NOT an empty space: the vector route did score candidates. Got ${raw.degraded}`,
|
||
)
|
||
assert.equal(raw.degradedError, undefined, 'and it carries no error')
|
||
|
||
// The log decision is the subject of L10, so drive the real method with the
|
||
// real gated result. Nothing here is a stub: `logRecallTurn` is what the
|
||
// plugin calls on every turn.
|
||
mem.logRecallTurn({
|
||
query: question,
|
||
messages: ask(question),
|
||
raw,
|
||
segmented: segmentRecallBudget(raw, { topK: 3 }),
|
||
injected: '',
|
||
})
|
||
assert.deepEqual(
|
||
lines(),
|
||
[],
|
||
`L11: a hybrid recall with zero surviving hits must still be silent with debugLog off; got ${JSON.stringify(lines())}`,
|
||
)
|
||
} finally {
|
||
await done()
|
||
}
|
||
})
|
||
|
||
// ══════════════════════════════════════════════════════════════════════════════
|
||
// L10† / L11† · the mutations that make the two silent assertions bite
|
||
// ══════════════════════════════════════════════════════════════════════════════
|
||
|
||
/**
|
||
* Copy the package, rewrite ONE anchor in `lib/index.js`, import it fresh.
|
||
*
|
||
* Same shape as L4† (and the mutation discipline note in docs/phase-b-criteria.md):
|
||
* the anchor must occur exactly once, or the test fails loudly rather than
|
||
* silently asserting against unmutated source.
|
||
*
|
||
* @param {string} anchor exact source text, expected once
|
||
* @param {string} replacement
|
||
* @param {(apply: Function) => Promise<void>} body receives the mutated `apply`
|
||
*/
|
||
async function withMutatedIndex(anchor, replacement, body) {
|
||
const { readFileSync, writeFileSync, mkdtempSync, rmSync, cpSync } = await import('node:fs')
|
||
const { tmpdir } = await import('node:os')
|
||
const { join } = await import('node:path')
|
||
const { fileURLToPath, pathToFileURL } = await import('node:url')
|
||
|
||
const libDir = fileURLToPath(new URL('../lib/', import.meta.url))
|
||
const pkgRoot = fileURLToPath(new URL('..', import.meta.url))
|
||
const dir = mkdtempSync(join(tmpdir(), 'mlog-l8-'))
|
||
try {
|
||
cpSync(libDir, join(dir, 'lib'), { recursive: true })
|
||
cpSync(join(pkgRoot, 'package.json'), join(dir, 'package.json'))
|
||
try {
|
||
cpSync(join(pkgRoot, 'node_modules'), join(dir, 'node_modules'), {
|
||
recursive: true,
|
||
dereference: false,
|
||
})
|
||
} catch {
|
||
// A poetry-free install fails loudly in the body below, which is correct.
|
||
}
|
||
|
||
const target = join(dir, 'lib', 'index.js')
|
||
const source = readFileSync(target, 'utf8')
|
||
assert.equal(
|
||
source.split(anchor).length - 1,
|
||
1,
|
||
`mutation anchor must occur exactly once — did the set move?\n${anchor}`,
|
||
)
|
||
writeFileSync(target, source.replace(anchor, replacement))
|
||
|
||
const mod = await import(pathToFileURL(target).href)
|
||
await body((ctx, config) => mod.apply(ctx, config))
|
||
} finally {
|
||
rmSync(dir, { recursive: true, force: true })
|
||
}
|
||
}
|
||
|
||
for (const [name, removed, bites] of [
|
||
['L10\u2020', "'hybrid'", 'L10.1'],
|
||
['L11\u2020', "'no_vector_space'", 'L10.2'],
|
||
]) {
|
||
test(`${name}: removing ${removed} from ORDINARY_DEGRADATIONS turns ${bites} red`, async (t) => {
|
||
const anchor = " 'ok', 'hybrid', 'no_embedder', 'aborted', 'no_vector_space', 'vector_ready_unused',"
|
||
const replacement = [
|
||
' // MUTATED: one healthy mode de-registered',
|
||
" 'ok', 'no_embedder', 'aborted',",
|
||
removed === "'hybrid'" ? " 'no_vector_space', 'vector_ready_unused'," : " 'hybrid', 'vector_ready_unused',",
|
||
].join('\n')
|
||
|
||
await withMutatedIndex(anchor, replacement, async (apply) => {
|
||
// The SAME criterion body the unmutated build passes. It must throw, and the
|
||
// throw must be the assertion's own — a different error (a bad import, a
|
||
// missing node_modules) would make this test green for the wrong reason.
|
||
await assert.rejects(
|
||
() => assertLevelContract((config) => makeMemWith(apply, config)),
|
||
(error) => {
|
||
assert.equal(error.code, 'ERR_ASSERTION', `only the criterion may bite; got ${error.code}: ${error.message}`)
|
||
assert.ok(
|
||
String(error.message).startsWith(bites),
|
||
`the biting assertion must be ${bites}; got: ${String(error.message).split('\n')[0]}`,
|
||
)
|
||
t.diagnostic(`${name} RAW RED >>> ${String(error.message).split('\n')[0]}`)
|
||
return true
|
||
},
|
||
`${name}: with ${removed} de-registered, ${bites} must go red`,
|
||
)
|
||
})
|
||
})
|
||
}
|