diff --git a/gemini-extension.json b/gemini-extension.json index e37f67902..e578b68af 100644 --- a/gemini-extension.json +++ b/gemini-extension.json @@ -5,7 +5,7 @@ "mcpServers": { "token-optimizer": { "command": "npx", - "args": ["-y", "@ooples/token-optimizer-mcp@5.3.6"] + "args": ["-y", "@ooples/token-optimizer-mcp@5.4.0"] } }, "settings": [ diff --git a/hooks-core/fleet.mjs b/hooks-core/fleet.mjs index 2ea85123e..ceca20fd9 100644 --- a/hooks-core/fleet.mjs +++ b/hooks-core/fleet.mjs @@ -36,7 +36,7 @@ import { createHash } from 'node:crypto'; import { readFileSync, readdirSync, statSync, existsSync, openSync, readSync, closeSync } from 'node:fs'; import { join, basename } from 'node:path'; import { homedir } from 'node:os'; -import { readMetrics } from './metrics.mjs'; +import { readMetrics, balanceSheet } from './metrics.mjs'; import { cacheHealth, readCacheUsage } from './cache.mjs'; import { activeRules } from './remedy.mjs'; import { monthly, money, priceNote } from './pricing.mjs'; @@ -164,6 +164,15 @@ const sha256 = (path) => { * exists where a refusal actually replaced a read, so its presence is evidence * that the veto is live in that project rather than that a config file says so. */ +/** Never let a malformed log take down a fleet scan. */ +function safeBalance(dir) { + try { + return balanceSheet(dir); + } catch { + return null; + } +} + export function scanProject(project) { const dir = project.cwd ? wikiDir(project.cwd) : null; const events = dir && existsSync(dir) ? readMetrics(dir) : []; @@ -186,6 +195,14 @@ export function scanProject(project) { perRead: reads.length ? Math.round(tokens / reads.length) : null, enforcing: substitutions > 0, substitutions, + // THE BALANCE, PER PROJECT, LABELLED BY HOW EACH LINE IS KNOWN. + // + // The fleet view is where 'is this paying for itself' is actually asked, + // and it had only raw counts to answer with. The two benefit lines stay + // separate here as everywhere else: one is arithmetic on known file sizes, + // the other is a causal estimate from the holdout, and summing them would + // launder an assumption into a measurement. + balance: dir && existsSync(dir) ? safeBalance(dir) : null, anchors: [...new Set(reads.map((r) => r.anchor).filter(Boolean))], rules: dir ? activeRules(dir) : [], cache: project.transcript ? cacheHealth(readCacheUsage(project.transcript)) : null, diff --git a/hooks-core/inject.mjs b/hooks-core/inject.mjs index 5abb9c428..c8991aa2e 100644 --- a/hooks-core/inject.mjs +++ b/hooks-core/inject.mjs @@ -43,6 +43,21 @@ const touchBudget = () => Number(process.env.TOKEN_OPTIMIZER_TOUCH_BUDGET) || 50 const standingBudget = () => Number(process.env.TOKEN_OPTIMIZER_STANDING_BUDGET) || 400; +/** + * The stratification key for a command. + * + * Normalised so that the same intent lands in the same arm: trailing + * whitespace and a differing set of paths should not flip a command between + * treated and withheld, because that is what makes the two arms comparable. + */ +function commandKey(command) { + return String(command || '') + .trim() + .replace(/\s+/g, ' ') + .slice(0, 120) + .toLowerCase(); +} + /** Most findings considered for one command before the budget decides. */ const MAX_COMMAND_CANDIDATES = 20; @@ -131,12 +146,18 @@ export function forTouch( .filter((f) => !alreadyInjected.has(f.key)); if (!candidates.length) return null; + // STRATIFIED BY FILE AND EPOCH, which is the documented design here: the + // same file lands in the holdout during some epochs and the treated arm in + // others, so the comparison becomes within-file and the dominant source of + // variance drops out. A session-pinned arm would destroy that. const holdout = inHoldout(filePath); const served = serve(graph, candidates); const { kept, spent } = fit(served, budget); record(dir, { kind: 'inject', + // The surface whose saving CAN be measured: reads of this anchor afterwards. + surface: 'file', anchor: filePath, holdout, tokens: holdout ? 0 : spent, @@ -145,10 +166,17 @@ export function forTouch( sessionId, }); - if (holdout || !kept.length) return null; - + // MARKED SEEN IN BOTH ARMS, for the same reason as the command path: a file + // touched repeatedly -- the normal shape of working on it -- would otherwise + // write a fresh holdout row every time while a treated file was suppressed + // after its first delivery. The report counts rows, so the control arm would + // grow faster purely from repetition. + // + // This is the identical defect that was fixed in `forCommand` and not here. for (const f of kept) alreadyInjected.add(f.key); + if (holdout || !kept.length) return null; + return `Known about ${filePath} (from previous sessions):\n${kept.map(render).join('\n')}`; } @@ -293,19 +321,46 @@ export function forCommand( const { kept, spent } = fit(served, budget); if (!kept.length) return null; + // THE COMMAND PATH TAKES PART IN THE HOLDOUT TOO. + // + // `holdout: false` was hardcoded here, so 95 of 136 injections measured on a + // real machine were structurally excluded from the only mechanism that can + // establish causation. Seventy per cent of what the feature does could never + // be shown to help or hurt. + // + // Stratified on the COMMAND rather than a file, by the same (key, epoch) + // hash: the same command lands in the same arm all session, so a command run + // repeatedly cannot straddle both arms and contaminate each. + const key = commandKey(command); + const holdout = inHoldout(key); + record(dir, { kind: 'inject', trigger: 'command', + // The surface the report needs to keep these OUT of the file-read balance: + // a command has no anchor that read events can be joined to. + surface: 'command', anchor: String(command).slice(0, 120), - holdout: false, - tokens: spent, - count: kept.length, + holdout, + tokens: holdout ? 0 : spent, + count: holdout ? 0 : kept.length, stale: kept.some((f) => f.stale), sessionId, }); + // MARKED SEEN IN BOTH ARMS. + // + // The held branch used to return before updating the gate, so a command run + // repeatedly wrote a fresh holdout row every time while a treated command was + // filtered after its first delivery. The report counts rows, so the holdout + // arm was systematically overweighted -- a bias in the very comparison this + // exists to make. for (const f of kept) alreadyInjected.add(f.key); + // Withheld means withheld. Returning the text anyway would record an arm the + // subject never actually experienced. + if (holdout) return null; + return `Before running this — known from previous sessions:\n${kept .map(render) .join('\n')}`; @@ -475,7 +530,7 @@ export function standingRules(dir, graph, { budget = standingBudget() } = {}) { * informative response available -- more useful than the file, not a lossier * version of it. */ -export function substitutionFor(dir, graph, rawPath, source) { +export function substitutionFor(dir, graph, rawPath, source, { sessionId } = {}) { const filePath = canonicalPath(rawPath); const budget = substitutionBudget(dir, filePath); const built = annotatedSkeleton(graph, rawPath, source, { budget }); @@ -484,15 +539,50 @@ export function substitutionFor(dir, graph, rawPath, source) { // costs the model a round trip; send it back to the ordinary redirect. if (built.tokens * 4 > source.length * 0.5) return null; + // THE HOLDOUT BELONGS ON THIS PATH, not only on findings injection. + // + // Substitution is the lever that actually moves tokens -- it replaces a whole + // file with a skeleton -- and it had no control arm at all, while the 10% + // holdout sat on findings injection, which is two orders of magnitude + // smaller. Withholding here serves the file the model asked for and records + // what that cost, which is the only way the saving stops being an assumption. + // PINNED FOR THE SESSION, with a fixed epoch. + // + // Unlike the file-touch arm above, this one must not rotate: a session + // running across midnight would substitute for a file in one half and serve + // the whole file in the other, so `measuredCounterfactual` would mix treated + // and control observations for the same file. + // + // Keying on the session alone was not enough -- with the epoch still in play + // the arm flipped 104 times in 400 simulated midnight crossings. The session + // id already provides the rotation the epoch was there for. + const holdout = inHoldout(`${sessionId || ''}|${filePath}`, 0); + record(dir, { kind: 'substitute', anchor: filePath, - tokens: built.tokens, + // Recorded so provenance is checkable. Without it, 366 of 370 substitutions + // on this machine turned out to be the enforcement suite's own fixture and + // nothing distinguished them from real work. + sessionId, + holdout, + tokens: holdout ? 0 : built.tokens, findings: built.findings, symbols: built.symbols, - bytesAvoided: source.length, + // GROSS, kept for continuity with existing records. + bytesAvoided: holdout ? 0 : source.length, + // NET, which is the honest figure: the skeleton was still sent. Reporting + // the whole file as avoided while spending `tokens` on a replacement + // overstates the saving by exactly the size of the replacement. + tokensNetAvoided: holdout ? 0 : Math.max(0, Math.ceil(source.length / 4) - built.tokens), + // What the control arm actually paid, so the two arms are comparable. + tokensFullFile: Math.ceil(source.length / 4), }); + // Withheld means the model gets what it asked for: the whole file. That is + // the control arm, and it must really be paid or the comparison is fiction. + if (holdout) return null; + return built.text; } diff --git a/hooks-core/metrics.mjs b/hooks-core/metrics.mjs index 50beb9e9a..52f0d4b23 100644 --- a/hooks-core/metrics.mjs +++ b/hooks-core/metrics.mjs @@ -21,7 +21,7 @@ import { statSync, openSync, readSync, closeSync, } from 'node:fs'; import { join } from 'node:path'; -import { createHash } from 'node:crypto'; +import { createHash, randomBytes } from 'node:crypto'; /** * Read per call, not once at module load. @@ -41,6 +41,28 @@ const EPOCH_MS = 86_400_000; const metricsPath = (dir) => join(dir, 'metrics.jsonl'); +/** + * The balance log: `inject` and `harvest` only. + * + * WHY A SECOND FILE. The event window is measured in EVENTS, and injections are + * a tiny minority of them -- 136 injections against 6,725 captures across every + * graph on one machine. So the last 5,000 events are almost entirely captures + * and reads, and the injections that carry the measurement age out first. + * + * Measured on this repository before the fix: 44 inject records in the file, 9 + * of them holdout, all at lines 60-76 of 9,058 -- every single one outside the + * window. `report()` therefore said "0 holdout" while the file plainly + * contained nine, and the net balance was uncomputable on all 122 graphs. + * + * A separate log fixes it structurally rather than by enlarging a number. + * These records are rare, so the file stays small for years, and a tail window + * on it drops BOTH arms proportionally instead of starving the rare one. + */ +const balancePath = (dir) => join(dir, 'balance.jsonl'); + +/** Kinds the net balance is computed from, and which therefore must survive. */ +const BALANCE_KINDS = new Set(['inject', 'harvest', 'substitute']); + /** * Is this touch in the holdout arm? * @@ -52,7 +74,19 @@ export function inHoldout(anchorKey, now = Date.now()) { const fraction = holdoutFraction(); if (fraction <= 0) return false; const epoch = Math.floor(now / EPOCH_MS); - const digest = createHash('sha1').update(`${anchorKey}:${epoch}`).digest(); + // SHA-256, NOT SHA-1. + // + // This is a bucketing hash, not a security primitive -- nothing is kept + // secret and nothing is authenticated, only spread evenly across two arms. + // But CodeQL flags sha1 as a weak algorithm, seven high-severity alerts + // across the core and its six vendored copies, and arguing that a finding is + // benign is a worse habit than paying a cost that rounds to nothing here. + // Both are deterministic, which is the only property this depends on. + // + // The change DOES reassign arms: a given (anchor, epoch) may land on the + // other side than before. With nine holdout records in existence that costs + // nothing, and stratification is a fresh draw either way. + const digest = createHash('sha256').update(`${anchorKey}:${epoch}`).digest(); return (digest[0] / 256) < fraction; } @@ -63,9 +97,62 @@ export function inHoldout(anchorKey, now = Date.now()) { * moment the cost is knowable. This is the producer that makes the holdout * comparison a measurement rather than a subtraction of two zeroes. */ -export function recordRead(dir, { anchor, sessionId, bytes }) { +export function recordRead(dir, { anchor, sessionId, bytes, fp = null }) { if (!anchor || !bytes) return; - record(dir, { kind: 'read', anchor, sessionId, tokens: Math.ceil(bytes / 4) }); + record(dir, { + kind: 'read', + anchor, + sessionId, + tokens: Math.ceil(bytes / 4), + // THE CHANGE DETECTOR, recorded AT READ TIME. + // + // Without it, 'was this re-read wasteful' is undecidable. Measured before + // this field existed: 575 repeat reads of a file within one session, and + // only 99 could be classified -- 4,735 capture events carried anchors on + // just 122 of them, because most captures are bookkeeping calls that touch + // no file at all. The waste figure was 98% unknowable, and the 14.6M I + // first reported was really 213,651 confirmed plus a very large shrug. + // + // It belongs on the READ, not on a capture: the read already knows the + // anchor, the session and the cost, so the fingerprint completes the record + // rather than needing to be joined to another one. + fp, + }); +} + +/** + * A cheap fingerprint of a file's current content: size and mtime. + * + * NOT a content hash, deliberately. This runs on the PreToolUse path before + * every tool call, and hashing a file there would add a full read to the + * critical path for a measurement. `statSync` is already being done to resolve + * the operand, so this is free. + * + * WHAT IT CAN MISS: a write that leaves both size and mtime identical. That + * requires deliberately restoring the timestamp, so for the question being + * asked -- did this file change between two reads in one session -- it is + * sound. Stated here because a change-detector that silently misses changes + * would understate legitimate re-reads and overstate waste, which is the + * direction this project must never err in. + */ +export function fingerprint(path) { + try { + const st = statSync(path); + return `${st.size}:${Math.round(st.mtimeMs)}`; + } catch { + return null; + } +} + +/** + * A unique id per record. Counter plus randomness: the counter separates + * records written in the same millisecond by one process, the random suffix + * separates concurrent processes, which detached workers routinely are. + */ +let idCounter = 0; +function nextId() { + idCounter += 1; + return `${idCounter.toString(36)}-${randomBytes(4).toString('hex')}`; } export function record(dir, event) { @@ -78,7 +165,24 @@ export function record(dir, event) { } catch { // Not POSIX, or not ours to chmod; the write still proceeds. } - appendFileSync(metricsPath(dir), JSON.stringify({ ...event, at: Date.now() }) + '\n'); + // The CALLER'S timestamp wins when it supplied one. Overwriting it made + // `rereadWaste`'s ordering depend on write order rather than on `at`, so a + // test that set explicit times was passing by luck. + // + // `id` EXISTS SO DEDUPE IS EXACT. A record is written to both logs, so the + // reader has to drop one copy -- and it was matching on a composite of the + // fields, which cannot tell a duplicate from two genuinely distinct events + // that happen to look alike. Twenty-five identical injections written in a + // single millisecond collapsed to ONE, so a graph with ample data reported + // 'insufficient data (2 treated, 1 holdout)'. Real events were being + // discarded by the deduplicator, silently. + const line = + JSON.stringify({ id: nextId(), ...event, at: event.at ?? Date.now() }) + '\n'; + appendFileSync(metricsPath(dir), line); + // Balance-critical records go to their own log as well, so the windows on + // the firehose can never starve the measurement. Written SECOND: a torn + // write here costs a duplicate the reader dedupes, not a lost event. + if (BALANCE_KINDS.has(event.kind)) appendFileSync(balancePath(dir), line); } catch { // Metrics must never break a tool call. } @@ -108,7 +212,22 @@ export function readMetrics(dir) { return readAll(dir); } +/** + * How the last readAll truncated, if it did. + * + * Returned out of band rather than on the array, because callers pass the + * events around freely and a property hung on an array would be lost the first + * time anything filtered it -- which is exactly how `eventsTruncated` came to + * report only half the truth. + */ +let lastReadTruncation = { byBytes: false, byEvents: false }; + +export function readTruncation() { + return { ...lastReadTruncation }; +} + function readAll(dir) { + lastReadTruncation = { byBytes: false, byEvents: false }; const path = metricsPath(dir); if (!existsSync(path)) return []; @@ -130,13 +249,16 @@ function readAll(dir) { // The first line is almost certainly cut mid-record; drop it rather than // letting it fail to parse and look like corruption. text = text.slice(text.indexOf('\n') + 1); + lastReadTruncation.byBytes = true; } } catch { return []; } const out = []; - for (const line of text.split('\n').slice(-MAX_EVENTS)) { + const lines = text.split('\n'); + if (lines.length > MAX_EVENTS) lastReadTruncation.byEvents = true; + for (const line of lines.slice(-MAX_EVENTS)) { if (!line) continue; try { out.push(JSON.parse(line)); @@ -147,6 +269,323 @@ function readAll(dir) { return out; } +/** + * Balance records, read WITHOUT the event window that was starving them. + * + * Reads the dedicated log in full, and merges in whatever the firehose still + * holds so graphs that predate the split are not left unmeasurable. Duplicates + * are inevitable once both logs carry the same record, so they are removed on + * an identity built from the fields that make an event unique. + * + * The byte cap still applies to the dedicated log, but it means something very + * different here: these records are rare, so the cap is years of history rather + * than hours, and it drops BOTH arms proportionally when it finally bites. + */ +/** + * Every balance record in a file, with NO event window. + * + * The byte cap still bounds the read, because the firehose can be enormous. The + * event cap does not apply: it is what buried these records in the first place, + * and they are rare enough that keeping all of them inside the byte window costs + * nothing. + */ +function scanForBalance(path) { + if (!existsSync(path)) return []; + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + return []; + } + const out = []; + for (const line of text.split('\n')) { + if (!line) continue; + try { + const e = JSON.parse(line); + if (BALANCE_KINDS.has(e.kind)) out.push(e); + } catch { + /* a torn line costs a record, not the report */ + } + } + return out; +} + +export function readBalance(dir) { + const merged = []; + const path = balancePath(dir); + if (existsSync(path)) { + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + text = ''; + } + for (const line of text.split('\n')) { + if (!line) continue; + try { + merged.push(JSON.parse(line)); + } catch { + /* a torn line costs a record, not the report */ + } + } + } + + // MIGRATION, not a fallback. Every graph written before the split has its + // only copy of these records in the firehose; ignoring them would reset the + // measurement to zero on 122 existing graphs. + // + // IT MUST NOT GO THROUGH readAll. The first version of this fix did, and + // readAll applies the very event window that was starving the measurement -- + // so the migration inherited the bug it existed to repair and the real graphs + // still reported zero holdouts. Verified against them: unchanged at 0 until + // this scan stopped windowing. + for (const e of scanForBalance(metricsPath(dir))) merged.push(e); + + const seen = new Set(); + const out = []; + for (const e of merged) { + // The record's OWN id when it has one. The composite below is the legacy + // path for records written before ids existed; it is lossy by nature, which + // is precisely why new records carry an id instead. + const id = + e.id ?? [e.kind, e.at, e.anchor ?? '', e.sessionId ?? '', e.tokens ?? ''].join('|'); + if (seen.has(id)) continue; + seen.add(id); + out.push(e); + } + return out; +} + +/** + * Is this anchor a test fixture rather than real work? + * + * Not fussiness. Measured on this machine: 366 of 370 substitutions pointed at + * the enforcement suite's own big.ts fixture under a temp dir, and counting them made + * the product look like it had avoided 40 MB of reads. It had avoided 154 KB. + * A balance sheet that counts its own test suite as revenue is worse than none. + */ +export function isFixtureAnchor(anchor) { + const p = String(anchor || ''); + + // TWO CONDITIONS, BOTH REQUIRED. The previous version was a ternary chain in + // which every branch evaluated to `underTemp`, so the scratch test was dead + // code: it excluded ALL temp paths -- including a real project checked out + // under /tmp -- and on macOS excluded nothing at all, because tmpdir() there + // is /var/folders///T/ and did not match. + const underTemp = + new RegExp( + '[\\\\/](AppData[\\\\/]Local[\\\\/])?(Temp|tmp)[\\\\/]' + + '|[\\\\/]var[\\\\/]folders[\\\\/][^\\\\/]+[\\\\/][^\\\\/]+[\\\\/]T[\\\\/]', + 'i' + ).test(p); + if (!underTemp) return false; + + // Only names this suite actually creates. A user's own scratch checkout under + // a temp directory is real work and must still be counted. + return /(to-hooks-|ab-[a-z]+-|cooccur-|holdout-|reread-|feedback-e2e|standing-e2e|lesson-origin|archive-|gen-eol-|tear-|edge-src|fixture)/i.test( + p + ); +} + +/** + * The balance sheet, with every line labelled by HOW it is known. + * + * The shipped report counted every cost and one benefit that has never been + * computable, so it was negative by construction. These are the two things + * actually known, kept apart because they are known differently and must never + * be summed into a single hero number: + * + * MEASURED-COUNTERFACTUAL substitution. The file size is known exactly and + * the replacement's size is known exactly, so the + * saving is arithmetic -- resting on the one + * assumption that the model would have read what it + * explicitly asked for. + * ESTIMATED-CAUSAL findings injection, from the holdout. Genuinely + * causal when it has samples, and worth far less + * token-wise. + * + * Fixture anchors are excluded from both. + */ +/** + * Re-read waste, split into what is KNOWN and what is not. + * + * The question is narrow on purpose: how often does one session read the same + * file twice with the file UNCHANGED in between? That is waste the graph can + * remove, and it needs no holdout, no estimate and no join -- the reads carry + * their own fingerprints. + * + * A repeat read of a file that CHANGED is not waste and is reported as such. + * Conflating the two is how the first version of this measurement turned + * 213,651 confirmed tokens into a 14.6M headline. + * + * `undecidable` is reported rather than hidden. Reads written before the + * fingerprint existed cannot be classified, and a measurement that quietly + * counted them either way would be inventing its own answer. + */ +export function rereadWaste( + dir, + // `includeFixtures` exists so the suite can exercise this against files it + // creates under the temp directory -- which the fixture filter otherwise + // excludes by design, making the real path untestable. + { events = readMetrics(dir), includeFixtures = false } = {} +) { + const groups = new Map(); + for (const e of events) { + if (e.kind !== 'read' || !e.anchor) continue; + if (!includeFixtures && isFixtureAnchor(e.anchor)) continue; + const key = `${e.sessionId || ''}|${canonicalKeyish(e.anchor)}`; + if (!groups.has(key)) groups.set(key, []); + groups.get(key).push(e); + } + + const out = { + repeats: 0, + wasteful: 0, + wastefulTokens: 0, + legitimate: 0, + legitimateTokens: 0, + undecidable: 0, + undecidableTokens: 0, + }; + + for (const list of groups.values()) { + if (list.length < 2) continue; + list.sort((a, b) => (a.at || 0) - (b.at || 0)); + for (let i = 1; i < list.length; i++) { + const prev = list[i - 1]; + const cur = list[i]; + const tokens = cur.tokens || 0; + out.repeats += 1; + if (!prev.fp || !cur.fp) { + out.undecidable += 1; + out.undecidableTokens += tokens; + } else if (prev.fp === cur.fp) { + out.wasteful += 1; + out.wastefulTokens += tokens; + } else { + out.legitimate += 1; + out.legitimateTokens += tokens; + } + } + } + + const decided = out.wasteful + out.legitimate; + out.coverage = out.repeats ? decided / out.repeats : null; + return out; +} + +export function balanceSheet(dir) { + const balance = readBalance(dir).filter((e) => !isFixtureAnchor(e.anchor)); + const events = readMetrics(dir); + const truncation = readTruncation(); + + const subs = balance.filter((e) => e.kind === 'substitute'); + const served = subs.filter((e) => !e.holdout); + const withheldSubs = subs.filter((e) => e.holdout); + + // NET, not gross: the skeleton was still sent. + const netAvoided = served.reduce( + (sum, e) => + sum + + (e.tokensNetAvoided ?? + Math.max(0, Math.ceil((e.bytesAvoided || 0) / 4) - (e.tokens || 0))), + 0 + ); + const substitutionCost = served.reduce((sum, e) => sum + (e.tokens || 0), 0); + + const injectCost = balance + .filter((e) => e.kind === 'inject' && !e.holdout) + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const harvestCost = balance + .filter((e) => e.kind === 'harvest') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const standingCost = events + .filter((e) => e.kind === 'standing') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + + // RE-READS, decided by fingerprint rather than assumed. + const waste = rereadWaste(dir, { events }); + + return { + measuredCounterfactual: { + what: 'substitution: a skeleton sent instead of the file the model asked for', + substitutions: served.length, + withheld: withheldSubs.length, + tokensAvoidedNet: netAvoided, + tokensSpent: substitutionCost, + // THE CONTROL ARM'S ACTUAL COST. `tokensFullFile` was recorded and read + // by nothing, so the comparison the holdout exists for was not + // computable from the report. + controlArmTokens: withheldSubs.reduce((sum, e) => sum + (e.tokensFullFile || 0), 0), + assumption: 'that the model would have read the file it explicitly requested', + }, + estimatedCausal: { + what: 'findings injection, from the stratified holdout', + ...(() => { + const r = report(dir); + return { + treated: r.injections, + holdouts: r.holdouts, + tokensAvoided: r.estimatedTokensAvoided, + sufficientData: r.sufficientData, + verdict: r.verdict, + }; + })(), + }, + costs: { injection: injectCost, harvest: harvestCost, standing: standingCost, substitution: substitutionCost }, + waste, + // Deliberately NOT a single number. The two benefit lines are known + // differently; adding them would launder an assumption into a measurement. + // TWO WINDOWS, STATED RATHER THAN BLENDED. Balance records are read in + // full; everything derived from `events` sees only the tail of + // metrics.jsonl. Once that log rolls past its cap these cover different + // periods, and a reader has to be able to see that rather than assume one + // consistent balance. + windows: { + balance: 'all balance.jsonl records within the byte cap', + events: `tail of metrics.jsonl (<= ${MAX_BYTES} bytes, <= ${MAX_EVENTS} events)`, + // BOTH CAPS, from the reader itself. The previous flag tested the event + // count only, so a log truncated by the BYTE cap with fewer than + // MAX_EVENTS surviving records reported `false` -- the one case where the + // window silently covers a shorter period than the balance side. + eventsTruncated: truncation.byBytes || truncation.byEvents, + truncatedBy: truncation, + }, + note: 'benefit lines are reported separately by evidence strength and are never summed', + }; +} + +/** Cheap path normalisation for grouping reads; not the identity canonicaliser. */ +function canonicalKeyish(p) { + return String(p || '').replace(/\\/g, '/').toLowerCase(); +} + /** * The report. * @@ -157,8 +596,29 @@ function readAll(dir) { */ export function report(dir) { const events = readAll(dir); + // Injections and harvests come from the log that cannot be starved. + const balance = readBalance(dir); - const injections = events.filter((e) => e.kind === 'inject'); + // COMMAND INJECTIONS ARE COUNTED SEPARATELY, not mixed into the balance. + // + // The saving is measured by joining an injection to the READS of its anchor + // afterwards. A command injection's anchor is the command text, which no read + // event will ever match, so both arms would contribute zero downstream and + // every command record would pull both means toward zero -- diluting a real + // file-touch saving in proportion to how many commands ran. + // + // They still take part in the holdout, and are reported, because a structural + // exclusion is how 95 of 136 injections came to be unmeasurable. What is + // missing is a downstream join for them, and that is stated rather than + // papered over with a number. + const allInjections = balance.filter((e) => e.kind === 'inject'); + // `trigger` is the pre-`surface` spelling. Records written before the split + // carry it and no surface at all, so keying only on surface would silently + // file 95 historical command injections into the file-read balance -- exactly + // the dilution the split exists to prevent. + const isCommand = (e) => e.surface === 'command' || e.trigger === 'command'; + const commandInjections = allInjections.filter(isCommand); + const injections = allInjections.filter((e) => !isCommand(e)); const treated = injections.filter((e) => !e.holdout); const withheld = injections.filter((e) => e.holdout); @@ -166,7 +626,7 @@ export function report(dir) { rows.length ? rows.reduce((sum, r) => sum + (r[field] || 0), 0) / rows.length : 0; const injectedTokens = treated.reduce((sum, e) => sum + (e.tokens || 0), 0); - const harvestTokens = events + const harvestTokens = balance .filter((e) => e.kind === 'harvest') .reduce((sum, e) => sum + (e.tokens || 0), 0); @@ -236,6 +696,8 @@ export function report(dir) { return { injections: treated.length, + commandInjections: commandInjections.length, + commandHoldouts: commandInjections.filter((e) => e.holdout).length, holdouts: withheld.length, staleServed: injections.filter((e) => e.stale).length, staleRate: injections.length ? injections.filter((e) => e.stale).length / injections.length : 0, diff --git a/integrations/amp/settings.json b/integrations/amp/settings.json index 7dba98097..32abfed1f 100644 --- a/integrations/amp/settings.json +++ b/integrations/amp/settings.json @@ -4,7 +4,7 @@ "command": "npx", "args": [ "-y", - "@ooples/token-optimizer-mcp@5.3.6" + "@ooples/token-optimizer-mcp@5.4.0" ], "env": {} } diff --git a/integrations/cline/mcp.json b/integrations/cline/mcp.json index d254a4f5d..9f0fa99ec 100644 --- a/integrations/cline/mcp.json +++ b/integrations/cline/mcp.json @@ -4,7 +4,7 @@ "command": "npx", "args": [ "-y", - "@ooples/token-optimizer-mcp@5.3.6" + "@ooples/token-optimizer-mcp@5.4.0" ], "env": {} } diff --git a/integrations/codex/config.toml b/integrations/codex/config.toml index 238aad6bc..a1b74d79c 100644 --- a/integrations/codex/config.toml +++ b/integrations/codex/config.toml @@ -5,6 +5,6 @@ [mcp_servers.token-optimizer] command = "npx" -args = ["-y", "@ooples/token-optimizer-mcp@5.3.6"] +args = ["-y", "@ooples/token-optimizer-mcp@5.4.0"] # Optional: point the cache somewhere stable. # env = { TOKEN_OPTIMIZER_CACHE_DIR = "~/.token-optimizer-cache" } diff --git a/integrations/codex/hooks/lib/fleet.mjs b/integrations/codex/hooks/lib/fleet.mjs index 68da2228b..5bb953b51 100644 --- a/integrations/codex/hooks/lib/fleet.mjs +++ b/integrations/codex/hooks/lib/fleet.mjs @@ -38,7 +38,7 @@ import { createHash } from 'node:crypto'; import { readFileSync, readdirSync, statSync, existsSync, openSync, readSync, closeSync } from 'node:fs'; import { join, basename } from 'node:path'; import { homedir } from 'node:os'; -import { readMetrics } from './metrics.mjs'; +import { readMetrics, balanceSheet } from './metrics.mjs'; import { cacheHealth, readCacheUsage } from './cache.mjs'; import { activeRules } from './remedy.mjs'; import { monthly, money, priceNote } from './pricing.mjs'; @@ -166,6 +166,15 @@ const sha256 = (path) => { * exists where a refusal actually replaced a read, so its presence is evidence * that the veto is live in that project rather than that a config file says so. */ +/** Never let a malformed log take down a fleet scan. */ +function safeBalance(dir) { + try { + return balanceSheet(dir); + } catch { + return null; + } +} + export function scanProject(project) { const dir = project.cwd ? wikiDir(project.cwd) : null; const events = dir && existsSync(dir) ? readMetrics(dir) : []; @@ -188,6 +197,14 @@ export function scanProject(project) { perRead: reads.length ? Math.round(tokens / reads.length) : null, enforcing: substitutions > 0, substitutions, + // THE BALANCE, PER PROJECT, LABELLED BY HOW EACH LINE IS KNOWN. + // + // The fleet view is where 'is this paying for itself' is actually asked, + // and it had only raw counts to answer with. The two benefit lines stay + // separate here as everywhere else: one is arithmetic on known file sizes, + // the other is a causal estimate from the holdout, and summing them would + // launder an assumption into a measurement. + balance: dir && existsSync(dir) ? safeBalance(dir) : null, anchors: [...new Set(reads.map((r) => r.anchor).filter(Boolean))], rules: dir ? activeRules(dir) : [], cache: project.transcript ? cacheHealth(readCacheUsage(project.transcript)) : null, diff --git a/integrations/codex/hooks/lib/inject.mjs b/integrations/codex/hooks/lib/inject.mjs index 21606f1c0..022b7de0d 100644 --- a/integrations/codex/hooks/lib/inject.mjs +++ b/integrations/codex/hooks/lib/inject.mjs @@ -45,6 +45,21 @@ const touchBudget = () => Number(process.env.TOKEN_OPTIMIZER_TOUCH_BUDGET) || 50 const standingBudget = () => Number(process.env.TOKEN_OPTIMIZER_STANDING_BUDGET) || 400; +/** + * The stratification key for a command. + * + * Normalised so that the same intent lands in the same arm: trailing + * whitespace and a differing set of paths should not flip a command between + * treated and withheld, because that is what makes the two arms comparable. + */ +function commandKey(command) { + return String(command || '') + .trim() + .replace(/\s+/g, ' ') + .slice(0, 120) + .toLowerCase(); +} + /** Most findings considered for one command before the budget decides. */ const MAX_COMMAND_CANDIDATES = 20; @@ -133,12 +148,18 @@ export function forTouch( .filter((f) => !alreadyInjected.has(f.key)); if (!candidates.length) return null; + // STRATIFIED BY FILE AND EPOCH, which is the documented design here: the + // same file lands in the holdout during some epochs and the treated arm in + // others, so the comparison becomes within-file and the dominant source of + // variance drops out. A session-pinned arm would destroy that. const holdout = inHoldout(filePath); const served = serve(graph, candidates); const { kept, spent } = fit(served, budget); record(dir, { kind: 'inject', + // The surface whose saving CAN be measured: reads of this anchor afterwards. + surface: 'file', anchor: filePath, holdout, tokens: holdout ? 0 : spent, @@ -147,10 +168,17 @@ export function forTouch( sessionId, }); - if (holdout || !kept.length) return null; - + // MARKED SEEN IN BOTH ARMS, for the same reason as the command path: a file + // touched repeatedly -- the normal shape of working on it -- would otherwise + // write a fresh holdout row every time while a treated file was suppressed + // after its first delivery. The report counts rows, so the control arm would + // grow faster purely from repetition. + // + // This is the identical defect that was fixed in `forCommand` and not here. for (const f of kept) alreadyInjected.add(f.key); + if (holdout || !kept.length) return null; + return `Known about ${filePath} (from previous sessions):\n${kept.map(render).join('\n')}`; } @@ -295,19 +323,46 @@ export function forCommand( const { kept, spent } = fit(served, budget); if (!kept.length) return null; + // THE COMMAND PATH TAKES PART IN THE HOLDOUT TOO. + // + // `holdout: false` was hardcoded here, so 95 of 136 injections measured on a + // real machine were structurally excluded from the only mechanism that can + // establish causation. Seventy per cent of what the feature does could never + // be shown to help or hurt. + // + // Stratified on the COMMAND rather than a file, by the same (key, epoch) + // hash: the same command lands in the same arm all session, so a command run + // repeatedly cannot straddle both arms and contaminate each. + const key = commandKey(command); + const holdout = inHoldout(key); + record(dir, { kind: 'inject', trigger: 'command', + // The surface the report needs to keep these OUT of the file-read balance: + // a command has no anchor that read events can be joined to. + surface: 'command', anchor: String(command).slice(0, 120), - holdout: false, - tokens: spent, - count: kept.length, + holdout, + tokens: holdout ? 0 : spent, + count: holdout ? 0 : kept.length, stale: kept.some((f) => f.stale), sessionId, }); + // MARKED SEEN IN BOTH ARMS. + // + // The held branch used to return before updating the gate, so a command run + // repeatedly wrote a fresh holdout row every time while a treated command was + // filtered after its first delivery. The report counts rows, so the holdout + // arm was systematically overweighted -- a bias in the very comparison this + // exists to make. for (const f of kept) alreadyInjected.add(f.key); + // Withheld means withheld. Returning the text anyway would record an arm the + // subject never actually experienced. + if (holdout) return null; + return `Before running this — known from previous sessions:\n${kept .map(render) .join('\n')}`; @@ -477,7 +532,7 @@ export function standingRules(dir, graph, { budget = standingBudget() } = {}) { * informative response available -- more useful than the file, not a lossier * version of it. */ -export function substitutionFor(dir, graph, rawPath, source) { +export function substitutionFor(dir, graph, rawPath, source, { sessionId } = {}) { const filePath = canonicalPath(rawPath); const budget = substitutionBudget(dir, filePath); const built = annotatedSkeleton(graph, rawPath, source, { budget }); @@ -486,15 +541,50 @@ export function substitutionFor(dir, graph, rawPath, source) { // costs the model a round trip; send it back to the ordinary redirect. if (built.tokens * 4 > source.length * 0.5) return null; + // THE HOLDOUT BELONGS ON THIS PATH, not only on findings injection. + // + // Substitution is the lever that actually moves tokens -- it replaces a whole + // file with a skeleton -- and it had no control arm at all, while the 10% + // holdout sat on findings injection, which is two orders of magnitude + // smaller. Withholding here serves the file the model asked for and records + // what that cost, which is the only way the saving stops being an assumption. + // PINNED FOR THE SESSION, with a fixed epoch. + // + // Unlike the file-touch arm above, this one must not rotate: a session + // running across midnight would substitute for a file in one half and serve + // the whole file in the other, so `measuredCounterfactual` would mix treated + // and control observations for the same file. + // + // Keying on the session alone was not enough -- with the epoch still in play + // the arm flipped 104 times in 400 simulated midnight crossings. The session + // id already provides the rotation the epoch was there for. + const holdout = inHoldout(`${sessionId || ''}|${filePath}`, 0); + record(dir, { kind: 'substitute', anchor: filePath, - tokens: built.tokens, + // Recorded so provenance is checkable. Without it, 366 of 370 substitutions + // on this machine turned out to be the enforcement suite's own fixture and + // nothing distinguished them from real work. + sessionId, + holdout, + tokens: holdout ? 0 : built.tokens, findings: built.findings, symbols: built.symbols, - bytesAvoided: source.length, + // GROSS, kept for continuity with existing records. + bytesAvoided: holdout ? 0 : source.length, + // NET, which is the honest figure: the skeleton was still sent. Reporting + // the whole file as avoided while spending `tokens` on a replacement + // overstates the saving by exactly the size of the replacement. + tokensNetAvoided: holdout ? 0 : Math.max(0, Math.ceil(source.length / 4) - built.tokens), + // What the control arm actually paid, so the two arms are comparable. + tokensFullFile: Math.ceil(source.length / 4), }); + // Withheld means the model gets what it asked for: the whole file. That is + // the control arm, and it must really be paid or the comparison is fiction. + if (holdout) return null; + return built.text; } diff --git a/integrations/codex/hooks/lib/metrics.mjs b/integrations/codex/hooks/lib/metrics.mjs index 0df6ee24a..3fc52e22b 100644 --- a/integrations/codex/hooks/lib/metrics.mjs +++ b/integrations/codex/hooks/lib/metrics.mjs @@ -23,7 +23,7 @@ import { statSync, openSync, readSync, closeSync, } from 'node:fs'; import { join } from 'node:path'; -import { createHash } from 'node:crypto'; +import { createHash, randomBytes } from 'node:crypto'; /** * Read per call, not once at module load. @@ -43,6 +43,28 @@ const EPOCH_MS = 86_400_000; const metricsPath = (dir) => join(dir, 'metrics.jsonl'); +/** + * The balance log: `inject` and `harvest` only. + * + * WHY A SECOND FILE. The event window is measured in EVENTS, and injections are + * a tiny minority of them -- 136 injections against 6,725 captures across every + * graph on one machine. So the last 5,000 events are almost entirely captures + * and reads, and the injections that carry the measurement age out first. + * + * Measured on this repository before the fix: 44 inject records in the file, 9 + * of them holdout, all at lines 60-76 of 9,058 -- every single one outside the + * window. `report()` therefore said "0 holdout" while the file plainly + * contained nine, and the net balance was uncomputable on all 122 graphs. + * + * A separate log fixes it structurally rather than by enlarging a number. + * These records are rare, so the file stays small for years, and a tail window + * on it drops BOTH arms proportionally instead of starving the rare one. + */ +const balancePath = (dir) => join(dir, 'balance.jsonl'); + +/** Kinds the net balance is computed from, and which therefore must survive. */ +const BALANCE_KINDS = new Set(['inject', 'harvest', 'substitute']); + /** * Is this touch in the holdout arm? * @@ -54,7 +76,19 @@ export function inHoldout(anchorKey, now = Date.now()) { const fraction = holdoutFraction(); if (fraction <= 0) return false; const epoch = Math.floor(now / EPOCH_MS); - const digest = createHash('sha1').update(`${anchorKey}:${epoch}`).digest(); + // SHA-256, NOT SHA-1. + // + // This is a bucketing hash, not a security primitive -- nothing is kept + // secret and nothing is authenticated, only spread evenly across two arms. + // But CodeQL flags sha1 as a weak algorithm, seven high-severity alerts + // across the core and its six vendored copies, and arguing that a finding is + // benign is a worse habit than paying a cost that rounds to nothing here. + // Both are deterministic, which is the only property this depends on. + // + // The change DOES reassign arms: a given (anchor, epoch) may land on the + // other side than before. With nine holdout records in existence that costs + // nothing, and stratification is a fresh draw either way. + const digest = createHash('sha256').update(`${anchorKey}:${epoch}`).digest(); return (digest[0] / 256) < fraction; } @@ -65,9 +99,62 @@ export function inHoldout(anchorKey, now = Date.now()) { * moment the cost is knowable. This is the producer that makes the holdout * comparison a measurement rather than a subtraction of two zeroes. */ -export function recordRead(dir, { anchor, sessionId, bytes }) { +export function recordRead(dir, { anchor, sessionId, bytes, fp = null }) { if (!anchor || !bytes) return; - record(dir, { kind: 'read', anchor, sessionId, tokens: Math.ceil(bytes / 4) }); + record(dir, { + kind: 'read', + anchor, + sessionId, + tokens: Math.ceil(bytes / 4), + // THE CHANGE DETECTOR, recorded AT READ TIME. + // + // Without it, 'was this re-read wasteful' is undecidable. Measured before + // this field existed: 575 repeat reads of a file within one session, and + // only 99 could be classified -- 4,735 capture events carried anchors on + // just 122 of them, because most captures are bookkeeping calls that touch + // no file at all. The waste figure was 98% unknowable, and the 14.6M I + // first reported was really 213,651 confirmed plus a very large shrug. + // + // It belongs on the READ, not on a capture: the read already knows the + // anchor, the session and the cost, so the fingerprint completes the record + // rather than needing to be joined to another one. + fp, + }); +} + +/** + * A cheap fingerprint of a file's current content: size and mtime. + * + * NOT a content hash, deliberately. This runs on the PreToolUse path before + * every tool call, and hashing a file there would add a full read to the + * critical path for a measurement. `statSync` is already being done to resolve + * the operand, so this is free. + * + * WHAT IT CAN MISS: a write that leaves both size and mtime identical. That + * requires deliberately restoring the timestamp, so for the question being + * asked -- did this file change between two reads in one session -- it is + * sound. Stated here because a change-detector that silently misses changes + * would understate legitimate re-reads and overstate waste, which is the + * direction this project must never err in. + */ +export function fingerprint(path) { + try { + const st = statSync(path); + return `${st.size}:${Math.round(st.mtimeMs)}`; + } catch { + return null; + } +} + +/** + * A unique id per record. Counter plus randomness: the counter separates + * records written in the same millisecond by one process, the random suffix + * separates concurrent processes, which detached workers routinely are. + */ +let idCounter = 0; +function nextId() { + idCounter += 1; + return `${idCounter.toString(36)}-${randomBytes(4).toString('hex')}`; } export function record(dir, event) { @@ -80,7 +167,24 @@ export function record(dir, event) { } catch { // Not POSIX, or not ours to chmod; the write still proceeds. } - appendFileSync(metricsPath(dir), JSON.stringify({ ...event, at: Date.now() }) + '\n'); + // The CALLER'S timestamp wins when it supplied one. Overwriting it made + // `rereadWaste`'s ordering depend on write order rather than on `at`, so a + // test that set explicit times was passing by luck. + // + // `id` EXISTS SO DEDUPE IS EXACT. A record is written to both logs, so the + // reader has to drop one copy -- and it was matching on a composite of the + // fields, which cannot tell a duplicate from two genuinely distinct events + // that happen to look alike. Twenty-five identical injections written in a + // single millisecond collapsed to ONE, so a graph with ample data reported + // 'insufficient data (2 treated, 1 holdout)'. Real events were being + // discarded by the deduplicator, silently. + const line = + JSON.stringify({ id: nextId(), ...event, at: event.at ?? Date.now() }) + '\n'; + appendFileSync(metricsPath(dir), line); + // Balance-critical records go to their own log as well, so the windows on + // the firehose can never starve the measurement. Written SECOND: a torn + // write here costs a duplicate the reader dedupes, not a lost event. + if (BALANCE_KINDS.has(event.kind)) appendFileSync(balancePath(dir), line); } catch { // Metrics must never break a tool call. } @@ -110,7 +214,22 @@ export function readMetrics(dir) { return readAll(dir); } +/** + * How the last readAll truncated, if it did. + * + * Returned out of band rather than on the array, because callers pass the + * events around freely and a property hung on an array would be lost the first + * time anything filtered it -- which is exactly how `eventsTruncated` came to + * report only half the truth. + */ +let lastReadTruncation = { byBytes: false, byEvents: false }; + +export function readTruncation() { + return { ...lastReadTruncation }; +} + function readAll(dir) { + lastReadTruncation = { byBytes: false, byEvents: false }; const path = metricsPath(dir); if (!existsSync(path)) return []; @@ -132,13 +251,16 @@ function readAll(dir) { // The first line is almost certainly cut mid-record; drop it rather than // letting it fail to parse and look like corruption. text = text.slice(text.indexOf('\n') + 1); + lastReadTruncation.byBytes = true; } } catch { return []; } const out = []; - for (const line of text.split('\n').slice(-MAX_EVENTS)) { + const lines = text.split('\n'); + if (lines.length > MAX_EVENTS) lastReadTruncation.byEvents = true; + for (const line of lines.slice(-MAX_EVENTS)) { if (!line) continue; try { out.push(JSON.parse(line)); @@ -149,6 +271,323 @@ function readAll(dir) { return out; } +/** + * Balance records, read WITHOUT the event window that was starving them. + * + * Reads the dedicated log in full, and merges in whatever the firehose still + * holds so graphs that predate the split are not left unmeasurable. Duplicates + * are inevitable once both logs carry the same record, so they are removed on + * an identity built from the fields that make an event unique. + * + * The byte cap still applies to the dedicated log, but it means something very + * different here: these records are rare, so the cap is years of history rather + * than hours, and it drops BOTH arms proportionally when it finally bites. + */ +/** + * Every balance record in a file, with NO event window. + * + * The byte cap still bounds the read, because the firehose can be enormous. The + * event cap does not apply: it is what buried these records in the first place, + * and they are rare enough that keeping all of them inside the byte window costs + * nothing. + */ +function scanForBalance(path) { + if (!existsSync(path)) return []; + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + return []; + } + const out = []; + for (const line of text.split('\n')) { + if (!line) continue; + try { + const e = JSON.parse(line); + if (BALANCE_KINDS.has(e.kind)) out.push(e); + } catch { + /* a torn line costs a record, not the report */ + } + } + return out; +} + +export function readBalance(dir) { + const merged = []; + const path = balancePath(dir); + if (existsSync(path)) { + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + text = ''; + } + for (const line of text.split('\n')) { + if (!line) continue; + try { + merged.push(JSON.parse(line)); + } catch { + /* a torn line costs a record, not the report */ + } + } + } + + // MIGRATION, not a fallback. Every graph written before the split has its + // only copy of these records in the firehose; ignoring them would reset the + // measurement to zero on 122 existing graphs. + // + // IT MUST NOT GO THROUGH readAll. The first version of this fix did, and + // readAll applies the very event window that was starving the measurement -- + // so the migration inherited the bug it existed to repair and the real graphs + // still reported zero holdouts. Verified against them: unchanged at 0 until + // this scan stopped windowing. + for (const e of scanForBalance(metricsPath(dir))) merged.push(e); + + const seen = new Set(); + const out = []; + for (const e of merged) { + // The record's OWN id when it has one. The composite below is the legacy + // path for records written before ids existed; it is lossy by nature, which + // is precisely why new records carry an id instead. + const id = + e.id ?? [e.kind, e.at, e.anchor ?? '', e.sessionId ?? '', e.tokens ?? ''].join('|'); + if (seen.has(id)) continue; + seen.add(id); + out.push(e); + } + return out; +} + +/** + * Is this anchor a test fixture rather than real work? + * + * Not fussiness. Measured on this machine: 366 of 370 substitutions pointed at + * the enforcement suite's own big.ts fixture under a temp dir, and counting them made + * the product look like it had avoided 40 MB of reads. It had avoided 154 KB. + * A balance sheet that counts its own test suite as revenue is worse than none. + */ +export function isFixtureAnchor(anchor) { + const p = String(anchor || ''); + + // TWO CONDITIONS, BOTH REQUIRED. The previous version was a ternary chain in + // which every branch evaluated to `underTemp`, so the scratch test was dead + // code: it excluded ALL temp paths -- including a real project checked out + // under /tmp -- and on macOS excluded nothing at all, because tmpdir() there + // is /var/folders///T/ and did not match. + const underTemp = + new RegExp( + '[\\\\/](AppData[\\\\/]Local[\\\\/])?(Temp|tmp)[\\\\/]' + + '|[\\\\/]var[\\\\/]folders[\\\\/][^\\\\/]+[\\\\/][^\\\\/]+[\\\\/]T[\\\\/]', + 'i' + ).test(p); + if (!underTemp) return false; + + // Only names this suite actually creates. A user's own scratch checkout under + // a temp directory is real work and must still be counted. + return /(to-hooks-|ab-[a-z]+-|cooccur-|holdout-|reread-|feedback-e2e|standing-e2e|lesson-origin|archive-|gen-eol-|tear-|edge-src|fixture)/i.test( + p + ); +} + +/** + * The balance sheet, with every line labelled by HOW it is known. + * + * The shipped report counted every cost and one benefit that has never been + * computable, so it was negative by construction. These are the two things + * actually known, kept apart because they are known differently and must never + * be summed into a single hero number: + * + * MEASURED-COUNTERFACTUAL substitution. The file size is known exactly and + * the replacement's size is known exactly, so the + * saving is arithmetic -- resting on the one + * assumption that the model would have read what it + * explicitly asked for. + * ESTIMATED-CAUSAL findings injection, from the holdout. Genuinely + * causal when it has samples, and worth far less + * token-wise. + * + * Fixture anchors are excluded from both. + */ +/** + * Re-read waste, split into what is KNOWN and what is not. + * + * The question is narrow on purpose: how often does one session read the same + * file twice with the file UNCHANGED in between? That is waste the graph can + * remove, and it needs no holdout, no estimate and no join -- the reads carry + * their own fingerprints. + * + * A repeat read of a file that CHANGED is not waste and is reported as such. + * Conflating the two is how the first version of this measurement turned + * 213,651 confirmed tokens into a 14.6M headline. + * + * `undecidable` is reported rather than hidden. Reads written before the + * fingerprint existed cannot be classified, and a measurement that quietly + * counted them either way would be inventing its own answer. + */ +export function rereadWaste( + dir, + // `includeFixtures` exists so the suite can exercise this against files it + // creates under the temp directory -- which the fixture filter otherwise + // excludes by design, making the real path untestable. + { events = readMetrics(dir), includeFixtures = false } = {} +) { + const groups = new Map(); + for (const e of events) { + if (e.kind !== 'read' || !e.anchor) continue; + if (!includeFixtures && isFixtureAnchor(e.anchor)) continue; + const key = `${e.sessionId || ''}|${canonicalKeyish(e.anchor)}`; + if (!groups.has(key)) groups.set(key, []); + groups.get(key).push(e); + } + + const out = { + repeats: 0, + wasteful: 0, + wastefulTokens: 0, + legitimate: 0, + legitimateTokens: 0, + undecidable: 0, + undecidableTokens: 0, + }; + + for (const list of groups.values()) { + if (list.length < 2) continue; + list.sort((a, b) => (a.at || 0) - (b.at || 0)); + for (let i = 1; i < list.length; i++) { + const prev = list[i - 1]; + const cur = list[i]; + const tokens = cur.tokens || 0; + out.repeats += 1; + if (!prev.fp || !cur.fp) { + out.undecidable += 1; + out.undecidableTokens += tokens; + } else if (prev.fp === cur.fp) { + out.wasteful += 1; + out.wastefulTokens += tokens; + } else { + out.legitimate += 1; + out.legitimateTokens += tokens; + } + } + } + + const decided = out.wasteful + out.legitimate; + out.coverage = out.repeats ? decided / out.repeats : null; + return out; +} + +export function balanceSheet(dir) { + const balance = readBalance(dir).filter((e) => !isFixtureAnchor(e.anchor)); + const events = readMetrics(dir); + const truncation = readTruncation(); + + const subs = balance.filter((e) => e.kind === 'substitute'); + const served = subs.filter((e) => !e.holdout); + const withheldSubs = subs.filter((e) => e.holdout); + + // NET, not gross: the skeleton was still sent. + const netAvoided = served.reduce( + (sum, e) => + sum + + (e.tokensNetAvoided ?? + Math.max(0, Math.ceil((e.bytesAvoided || 0) / 4) - (e.tokens || 0))), + 0 + ); + const substitutionCost = served.reduce((sum, e) => sum + (e.tokens || 0), 0); + + const injectCost = balance + .filter((e) => e.kind === 'inject' && !e.holdout) + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const harvestCost = balance + .filter((e) => e.kind === 'harvest') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const standingCost = events + .filter((e) => e.kind === 'standing') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + + // RE-READS, decided by fingerprint rather than assumed. + const waste = rereadWaste(dir, { events }); + + return { + measuredCounterfactual: { + what: 'substitution: a skeleton sent instead of the file the model asked for', + substitutions: served.length, + withheld: withheldSubs.length, + tokensAvoidedNet: netAvoided, + tokensSpent: substitutionCost, + // THE CONTROL ARM'S ACTUAL COST. `tokensFullFile` was recorded and read + // by nothing, so the comparison the holdout exists for was not + // computable from the report. + controlArmTokens: withheldSubs.reduce((sum, e) => sum + (e.tokensFullFile || 0), 0), + assumption: 'that the model would have read the file it explicitly requested', + }, + estimatedCausal: { + what: 'findings injection, from the stratified holdout', + ...(() => { + const r = report(dir); + return { + treated: r.injections, + holdouts: r.holdouts, + tokensAvoided: r.estimatedTokensAvoided, + sufficientData: r.sufficientData, + verdict: r.verdict, + }; + })(), + }, + costs: { injection: injectCost, harvest: harvestCost, standing: standingCost, substitution: substitutionCost }, + waste, + // Deliberately NOT a single number. The two benefit lines are known + // differently; adding them would launder an assumption into a measurement. + // TWO WINDOWS, STATED RATHER THAN BLENDED. Balance records are read in + // full; everything derived from `events` sees only the tail of + // metrics.jsonl. Once that log rolls past its cap these cover different + // periods, and a reader has to be able to see that rather than assume one + // consistent balance. + windows: { + balance: 'all balance.jsonl records within the byte cap', + events: `tail of metrics.jsonl (<= ${MAX_BYTES} bytes, <= ${MAX_EVENTS} events)`, + // BOTH CAPS, from the reader itself. The previous flag tested the event + // count only, so a log truncated by the BYTE cap with fewer than + // MAX_EVENTS surviving records reported `false` -- the one case where the + // window silently covers a shorter period than the balance side. + eventsTruncated: truncation.byBytes || truncation.byEvents, + truncatedBy: truncation, + }, + note: 'benefit lines are reported separately by evidence strength and are never summed', + }; +} + +/** Cheap path normalisation for grouping reads; not the identity canonicaliser. */ +function canonicalKeyish(p) { + return String(p || '').replace(/\\/g, '/').toLowerCase(); +} + /** * The report. * @@ -159,8 +598,29 @@ function readAll(dir) { */ export function report(dir) { const events = readAll(dir); + // Injections and harvests come from the log that cannot be starved. + const balance = readBalance(dir); - const injections = events.filter((e) => e.kind === 'inject'); + // COMMAND INJECTIONS ARE COUNTED SEPARATELY, not mixed into the balance. + // + // The saving is measured by joining an injection to the READS of its anchor + // afterwards. A command injection's anchor is the command text, which no read + // event will ever match, so both arms would contribute zero downstream and + // every command record would pull both means toward zero -- diluting a real + // file-touch saving in proportion to how many commands ran. + // + // They still take part in the holdout, and are reported, because a structural + // exclusion is how 95 of 136 injections came to be unmeasurable. What is + // missing is a downstream join for them, and that is stated rather than + // papered over with a number. + const allInjections = balance.filter((e) => e.kind === 'inject'); + // `trigger` is the pre-`surface` spelling. Records written before the split + // carry it and no surface at all, so keying only on surface would silently + // file 95 historical command injections into the file-read balance -- exactly + // the dilution the split exists to prevent. + const isCommand = (e) => e.surface === 'command' || e.trigger === 'command'; + const commandInjections = allInjections.filter(isCommand); + const injections = allInjections.filter((e) => !isCommand(e)); const treated = injections.filter((e) => !e.holdout); const withheld = injections.filter((e) => e.holdout); @@ -168,7 +628,7 @@ export function report(dir) { rows.length ? rows.reduce((sum, r) => sum + (r[field] || 0), 0) / rows.length : 0; const injectedTokens = treated.reduce((sum, e) => sum + (e.tokens || 0), 0); - const harvestTokens = events + const harvestTokens = balance .filter((e) => e.kind === 'harvest') .reduce((sum, e) => sum + (e.tokens || 0), 0); @@ -238,6 +698,8 @@ export function report(dir) { return { injections: treated.length, + commandInjections: commandInjections.length, + commandHoldouts: commandInjections.filter((e) => e.holdout).length, holdouts: withheld.length, staleServed: injections.filter((e) => e.stale).length, staleRate: injections.length ? injections.filter((e) => e.stale).length / injections.length : 0, diff --git a/integrations/codex/plugin/.mcp.json b/integrations/codex/plugin/.mcp.json index f8529d07e..9ae381329 100644 --- a/integrations/codex/plugin/.mcp.json +++ b/integrations/codex/plugin/.mcp.json @@ -2,7 +2,7 @@ "mcp_servers": { "token-optimizer": { "command": "npx", - "args": ["-y", "@ooples/token-optimizer-mcp@5.3.6"] + "args": ["-y", "@ooples/token-optimizer-mcp@5.4.0"] } } } diff --git a/integrations/codex/plugin/hooks/lib/fleet.mjs b/integrations/codex/plugin/hooks/lib/fleet.mjs index 68da2228b..5bb953b51 100644 --- a/integrations/codex/plugin/hooks/lib/fleet.mjs +++ b/integrations/codex/plugin/hooks/lib/fleet.mjs @@ -38,7 +38,7 @@ import { createHash } from 'node:crypto'; import { readFileSync, readdirSync, statSync, existsSync, openSync, readSync, closeSync } from 'node:fs'; import { join, basename } from 'node:path'; import { homedir } from 'node:os'; -import { readMetrics } from './metrics.mjs'; +import { readMetrics, balanceSheet } from './metrics.mjs'; import { cacheHealth, readCacheUsage } from './cache.mjs'; import { activeRules } from './remedy.mjs'; import { monthly, money, priceNote } from './pricing.mjs'; @@ -166,6 +166,15 @@ const sha256 = (path) => { * exists where a refusal actually replaced a read, so its presence is evidence * that the veto is live in that project rather than that a config file says so. */ +/** Never let a malformed log take down a fleet scan. */ +function safeBalance(dir) { + try { + return balanceSheet(dir); + } catch { + return null; + } +} + export function scanProject(project) { const dir = project.cwd ? wikiDir(project.cwd) : null; const events = dir && existsSync(dir) ? readMetrics(dir) : []; @@ -188,6 +197,14 @@ export function scanProject(project) { perRead: reads.length ? Math.round(tokens / reads.length) : null, enforcing: substitutions > 0, substitutions, + // THE BALANCE, PER PROJECT, LABELLED BY HOW EACH LINE IS KNOWN. + // + // The fleet view is where 'is this paying for itself' is actually asked, + // and it had only raw counts to answer with. The two benefit lines stay + // separate here as everywhere else: one is arithmetic on known file sizes, + // the other is a causal estimate from the holdout, and summing them would + // launder an assumption into a measurement. + balance: dir && existsSync(dir) ? safeBalance(dir) : null, anchors: [...new Set(reads.map((r) => r.anchor).filter(Boolean))], rules: dir ? activeRules(dir) : [], cache: project.transcript ? cacheHealth(readCacheUsage(project.transcript)) : null, diff --git a/integrations/codex/plugin/hooks/lib/inject.mjs b/integrations/codex/plugin/hooks/lib/inject.mjs index 21606f1c0..022b7de0d 100644 --- a/integrations/codex/plugin/hooks/lib/inject.mjs +++ b/integrations/codex/plugin/hooks/lib/inject.mjs @@ -45,6 +45,21 @@ const touchBudget = () => Number(process.env.TOKEN_OPTIMIZER_TOUCH_BUDGET) || 50 const standingBudget = () => Number(process.env.TOKEN_OPTIMIZER_STANDING_BUDGET) || 400; +/** + * The stratification key for a command. + * + * Normalised so that the same intent lands in the same arm: trailing + * whitespace and a differing set of paths should not flip a command between + * treated and withheld, because that is what makes the two arms comparable. + */ +function commandKey(command) { + return String(command || '') + .trim() + .replace(/\s+/g, ' ') + .slice(0, 120) + .toLowerCase(); +} + /** Most findings considered for one command before the budget decides. */ const MAX_COMMAND_CANDIDATES = 20; @@ -133,12 +148,18 @@ export function forTouch( .filter((f) => !alreadyInjected.has(f.key)); if (!candidates.length) return null; + // STRATIFIED BY FILE AND EPOCH, which is the documented design here: the + // same file lands in the holdout during some epochs and the treated arm in + // others, so the comparison becomes within-file and the dominant source of + // variance drops out. A session-pinned arm would destroy that. const holdout = inHoldout(filePath); const served = serve(graph, candidates); const { kept, spent } = fit(served, budget); record(dir, { kind: 'inject', + // The surface whose saving CAN be measured: reads of this anchor afterwards. + surface: 'file', anchor: filePath, holdout, tokens: holdout ? 0 : spent, @@ -147,10 +168,17 @@ export function forTouch( sessionId, }); - if (holdout || !kept.length) return null; - + // MARKED SEEN IN BOTH ARMS, for the same reason as the command path: a file + // touched repeatedly -- the normal shape of working on it -- would otherwise + // write a fresh holdout row every time while a treated file was suppressed + // after its first delivery. The report counts rows, so the control arm would + // grow faster purely from repetition. + // + // This is the identical defect that was fixed in `forCommand` and not here. for (const f of kept) alreadyInjected.add(f.key); + if (holdout || !kept.length) return null; + return `Known about ${filePath} (from previous sessions):\n${kept.map(render).join('\n')}`; } @@ -295,19 +323,46 @@ export function forCommand( const { kept, spent } = fit(served, budget); if (!kept.length) return null; + // THE COMMAND PATH TAKES PART IN THE HOLDOUT TOO. + // + // `holdout: false` was hardcoded here, so 95 of 136 injections measured on a + // real machine were structurally excluded from the only mechanism that can + // establish causation. Seventy per cent of what the feature does could never + // be shown to help or hurt. + // + // Stratified on the COMMAND rather than a file, by the same (key, epoch) + // hash: the same command lands in the same arm all session, so a command run + // repeatedly cannot straddle both arms and contaminate each. + const key = commandKey(command); + const holdout = inHoldout(key); + record(dir, { kind: 'inject', trigger: 'command', + // The surface the report needs to keep these OUT of the file-read balance: + // a command has no anchor that read events can be joined to. + surface: 'command', anchor: String(command).slice(0, 120), - holdout: false, - tokens: spent, - count: kept.length, + holdout, + tokens: holdout ? 0 : spent, + count: holdout ? 0 : kept.length, stale: kept.some((f) => f.stale), sessionId, }); + // MARKED SEEN IN BOTH ARMS. + // + // The held branch used to return before updating the gate, so a command run + // repeatedly wrote a fresh holdout row every time while a treated command was + // filtered after its first delivery. The report counts rows, so the holdout + // arm was systematically overweighted -- a bias in the very comparison this + // exists to make. for (const f of kept) alreadyInjected.add(f.key); + // Withheld means withheld. Returning the text anyway would record an arm the + // subject never actually experienced. + if (holdout) return null; + return `Before running this — known from previous sessions:\n${kept .map(render) .join('\n')}`; @@ -477,7 +532,7 @@ export function standingRules(dir, graph, { budget = standingBudget() } = {}) { * informative response available -- more useful than the file, not a lossier * version of it. */ -export function substitutionFor(dir, graph, rawPath, source) { +export function substitutionFor(dir, graph, rawPath, source, { sessionId } = {}) { const filePath = canonicalPath(rawPath); const budget = substitutionBudget(dir, filePath); const built = annotatedSkeleton(graph, rawPath, source, { budget }); @@ -486,15 +541,50 @@ export function substitutionFor(dir, graph, rawPath, source) { // costs the model a round trip; send it back to the ordinary redirect. if (built.tokens * 4 > source.length * 0.5) return null; + // THE HOLDOUT BELONGS ON THIS PATH, not only on findings injection. + // + // Substitution is the lever that actually moves tokens -- it replaces a whole + // file with a skeleton -- and it had no control arm at all, while the 10% + // holdout sat on findings injection, which is two orders of magnitude + // smaller. Withholding here serves the file the model asked for and records + // what that cost, which is the only way the saving stops being an assumption. + // PINNED FOR THE SESSION, with a fixed epoch. + // + // Unlike the file-touch arm above, this one must not rotate: a session + // running across midnight would substitute for a file in one half and serve + // the whole file in the other, so `measuredCounterfactual` would mix treated + // and control observations for the same file. + // + // Keying on the session alone was not enough -- with the epoch still in play + // the arm flipped 104 times in 400 simulated midnight crossings. The session + // id already provides the rotation the epoch was there for. + const holdout = inHoldout(`${sessionId || ''}|${filePath}`, 0); + record(dir, { kind: 'substitute', anchor: filePath, - tokens: built.tokens, + // Recorded so provenance is checkable. Without it, 366 of 370 substitutions + // on this machine turned out to be the enforcement suite's own fixture and + // nothing distinguished them from real work. + sessionId, + holdout, + tokens: holdout ? 0 : built.tokens, findings: built.findings, symbols: built.symbols, - bytesAvoided: source.length, + // GROSS, kept for continuity with existing records. + bytesAvoided: holdout ? 0 : source.length, + // NET, which is the honest figure: the skeleton was still sent. Reporting + // the whole file as avoided while spending `tokens` on a replacement + // overstates the saving by exactly the size of the replacement. + tokensNetAvoided: holdout ? 0 : Math.max(0, Math.ceil(source.length / 4) - built.tokens), + // What the control arm actually paid, so the two arms are comparable. + tokensFullFile: Math.ceil(source.length / 4), }); + // Withheld means the model gets what it asked for: the whole file. That is + // the control arm, and it must really be paid or the comparison is fiction. + if (holdout) return null; + return built.text; } diff --git a/integrations/codex/plugin/hooks/lib/metrics.mjs b/integrations/codex/plugin/hooks/lib/metrics.mjs index 0df6ee24a..3fc52e22b 100644 --- a/integrations/codex/plugin/hooks/lib/metrics.mjs +++ b/integrations/codex/plugin/hooks/lib/metrics.mjs @@ -23,7 +23,7 @@ import { statSync, openSync, readSync, closeSync, } from 'node:fs'; import { join } from 'node:path'; -import { createHash } from 'node:crypto'; +import { createHash, randomBytes } from 'node:crypto'; /** * Read per call, not once at module load. @@ -43,6 +43,28 @@ const EPOCH_MS = 86_400_000; const metricsPath = (dir) => join(dir, 'metrics.jsonl'); +/** + * The balance log: `inject` and `harvest` only. + * + * WHY A SECOND FILE. The event window is measured in EVENTS, and injections are + * a tiny minority of them -- 136 injections against 6,725 captures across every + * graph on one machine. So the last 5,000 events are almost entirely captures + * and reads, and the injections that carry the measurement age out first. + * + * Measured on this repository before the fix: 44 inject records in the file, 9 + * of them holdout, all at lines 60-76 of 9,058 -- every single one outside the + * window. `report()` therefore said "0 holdout" while the file plainly + * contained nine, and the net balance was uncomputable on all 122 graphs. + * + * A separate log fixes it structurally rather than by enlarging a number. + * These records are rare, so the file stays small for years, and a tail window + * on it drops BOTH arms proportionally instead of starving the rare one. + */ +const balancePath = (dir) => join(dir, 'balance.jsonl'); + +/** Kinds the net balance is computed from, and which therefore must survive. */ +const BALANCE_KINDS = new Set(['inject', 'harvest', 'substitute']); + /** * Is this touch in the holdout arm? * @@ -54,7 +76,19 @@ export function inHoldout(anchorKey, now = Date.now()) { const fraction = holdoutFraction(); if (fraction <= 0) return false; const epoch = Math.floor(now / EPOCH_MS); - const digest = createHash('sha1').update(`${anchorKey}:${epoch}`).digest(); + // SHA-256, NOT SHA-1. + // + // This is a bucketing hash, not a security primitive -- nothing is kept + // secret and nothing is authenticated, only spread evenly across two arms. + // But CodeQL flags sha1 as a weak algorithm, seven high-severity alerts + // across the core and its six vendored copies, and arguing that a finding is + // benign is a worse habit than paying a cost that rounds to nothing here. + // Both are deterministic, which is the only property this depends on. + // + // The change DOES reassign arms: a given (anchor, epoch) may land on the + // other side than before. With nine holdout records in existence that costs + // nothing, and stratification is a fresh draw either way. + const digest = createHash('sha256').update(`${anchorKey}:${epoch}`).digest(); return (digest[0] / 256) < fraction; } @@ -65,9 +99,62 @@ export function inHoldout(anchorKey, now = Date.now()) { * moment the cost is knowable. This is the producer that makes the holdout * comparison a measurement rather than a subtraction of two zeroes. */ -export function recordRead(dir, { anchor, sessionId, bytes }) { +export function recordRead(dir, { anchor, sessionId, bytes, fp = null }) { if (!anchor || !bytes) return; - record(dir, { kind: 'read', anchor, sessionId, tokens: Math.ceil(bytes / 4) }); + record(dir, { + kind: 'read', + anchor, + sessionId, + tokens: Math.ceil(bytes / 4), + // THE CHANGE DETECTOR, recorded AT READ TIME. + // + // Without it, 'was this re-read wasteful' is undecidable. Measured before + // this field existed: 575 repeat reads of a file within one session, and + // only 99 could be classified -- 4,735 capture events carried anchors on + // just 122 of them, because most captures are bookkeeping calls that touch + // no file at all. The waste figure was 98% unknowable, and the 14.6M I + // first reported was really 213,651 confirmed plus a very large shrug. + // + // It belongs on the READ, not on a capture: the read already knows the + // anchor, the session and the cost, so the fingerprint completes the record + // rather than needing to be joined to another one. + fp, + }); +} + +/** + * A cheap fingerprint of a file's current content: size and mtime. + * + * NOT a content hash, deliberately. This runs on the PreToolUse path before + * every tool call, and hashing a file there would add a full read to the + * critical path for a measurement. `statSync` is already being done to resolve + * the operand, so this is free. + * + * WHAT IT CAN MISS: a write that leaves both size and mtime identical. That + * requires deliberately restoring the timestamp, so for the question being + * asked -- did this file change between two reads in one session -- it is + * sound. Stated here because a change-detector that silently misses changes + * would understate legitimate re-reads and overstate waste, which is the + * direction this project must never err in. + */ +export function fingerprint(path) { + try { + const st = statSync(path); + return `${st.size}:${Math.round(st.mtimeMs)}`; + } catch { + return null; + } +} + +/** + * A unique id per record. Counter plus randomness: the counter separates + * records written in the same millisecond by one process, the random suffix + * separates concurrent processes, which detached workers routinely are. + */ +let idCounter = 0; +function nextId() { + idCounter += 1; + return `${idCounter.toString(36)}-${randomBytes(4).toString('hex')}`; } export function record(dir, event) { @@ -80,7 +167,24 @@ export function record(dir, event) { } catch { // Not POSIX, or not ours to chmod; the write still proceeds. } - appendFileSync(metricsPath(dir), JSON.stringify({ ...event, at: Date.now() }) + '\n'); + // The CALLER'S timestamp wins when it supplied one. Overwriting it made + // `rereadWaste`'s ordering depend on write order rather than on `at`, so a + // test that set explicit times was passing by luck. + // + // `id` EXISTS SO DEDUPE IS EXACT. A record is written to both logs, so the + // reader has to drop one copy -- and it was matching on a composite of the + // fields, which cannot tell a duplicate from two genuinely distinct events + // that happen to look alike. Twenty-five identical injections written in a + // single millisecond collapsed to ONE, so a graph with ample data reported + // 'insufficient data (2 treated, 1 holdout)'. Real events were being + // discarded by the deduplicator, silently. + const line = + JSON.stringify({ id: nextId(), ...event, at: event.at ?? Date.now() }) + '\n'; + appendFileSync(metricsPath(dir), line); + // Balance-critical records go to their own log as well, so the windows on + // the firehose can never starve the measurement. Written SECOND: a torn + // write here costs a duplicate the reader dedupes, not a lost event. + if (BALANCE_KINDS.has(event.kind)) appendFileSync(balancePath(dir), line); } catch { // Metrics must never break a tool call. } @@ -110,7 +214,22 @@ export function readMetrics(dir) { return readAll(dir); } +/** + * How the last readAll truncated, if it did. + * + * Returned out of band rather than on the array, because callers pass the + * events around freely and a property hung on an array would be lost the first + * time anything filtered it -- which is exactly how `eventsTruncated` came to + * report only half the truth. + */ +let lastReadTruncation = { byBytes: false, byEvents: false }; + +export function readTruncation() { + return { ...lastReadTruncation }; +} + function readAll(dir) { + lastReadTruncation = { byBytes: false, byEvents: false }; const path = metricsPath(dir); if (!existsSync(path)) return []; @@ -132,13 +251,16 @@ function readAll(dir) { // The first line is almost certainly cut mid-record; drop it rather than // letting it fail to parse and look like corruption. text = text.slice(text.indexOf('\n') + 1); + lastReadTruncation.byBytes = true; } } catch { return []; } const out = []; - for (const line of text.split('\n').slice(-MAX_EVENTS)) { + const lines = text.split('\n'); + if (lines.length > MAX_EVENTS) lastReadTruncation.byEvents = true; + for (const line of lines.slice(-MAX_EVENTS)) { if (!line) continue; try { out.push(JSON.parse(line)); @@ -149,6 +271,323 @@ function readAll(dir) { return out; } +/** + * Balance records, read WITHOUT the event window that was starving them. + * + * Reads the dedicated log in full, and merges in whatever the firehose still + * holds so graphs that predate the split are not left unmeasurable. Duplicates + * are inevitable once both logs carry the same record, so they are removed on + * an identity built from the fields that make an event unique. + * + * The byte cap still applies to the dedicated log, but it means something very + * different here: these records are rare, so the cap is years of history rather + * than hours, and it drops BOTH arms proportionally when it finally bites. + */ +/** + * Every balance record in a file, with NO event window. + * + * The byte cap still bounds the read, because the firehose can be enormous. The + * event cap does not apply: it is what buried these records in the first place, + * and they are rare enough that keeping all of them inside the byte window costs + * nothing. + */ +function scanForBalance(path) { + if (!existsSync(path)) return []; + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + return []; + } + const out = []; + for (const line of text.split('\n')) { + if (!line) continue; + try { + const e = JSON.parse(line); + if (BALANCE_KINDS.has(e.kind)) out.push(e); + } catch { + /* a torn line costs a record, not the report */ + } + } + return out; +} + +export function readBalance(dir) { + const merged = []; + const path = balancePath(dir); + if (existsSync(path)) { + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + text = ''; + } + for (const line of text.split('\n')) { + if (!line) continue; + try { + merged.push(JSON.parse(line)); + } catch { + /* a torn line costs a record, not the report */ + } + } + } + + // MIGRATION, not a fallback. Every graph written before the split has its + // only copy of these records in the firehose; ignoring them would reset the + // measurement to zero on 122 existing graphs. + // + // IT MUST NOT GO THROUGH readAll. The first version of this fix did, and + // readAll applies the very event window that was starving the measurement -- + // so the migration inherited the bug it existed to repair and the real graphs + // still reported zero holdouts. Verified against them: unchanged at 0 until + // this scan stopped windowing. + for (const e of scanForBalance(metricsPath(dir))) merged.push(e); + + const seen = new Set(); + const out = []; + for (const e of merged) { + // The record's OWN id when it has one. The composite below is the legacy + // path for records written before ids existed; it is lossy by nature, which + // is precisely why new records carry an id instead. + const id = + e.id ?? [e.kind, e.at, e.anchor ?? '', e.sessionId ?? '', e.tokens ?? ''].join('|'); + if (seen.has(id)) continue; + seen.add(id); + out.push(e); + } + return out; +} + +/** + * Is this anchor a test fixture rather than real work? + * + * Not fussiness. Measured on this machine: 366 of 370 substitutions pointed at + * the enforcement suite's own big.ts fixture under a temp dir, and counting them made + * the product look like it had avoided 40 MB of reads. It had avoided 154 KB. + * A balance sheet that counts its own test suite as revenue is worse than none. + */ +export function isFixtureAnchor(anchor) { + const p = String(anchor || ''); + + // TWO CONDITIONS, BOTH REQUIRED. The previous version was a ternary chain in + // which every branch evaluated to `underTemp`, so the scratch test was dead + // code: it excluded ALL temp paths -- including a real project checked out + // under /tmp -- and on macOS excluded nothing at all, because tmpdir() there + // is /var/folders///T/ and did not match. + const underTemp = + new RegExp( + '[\\\\/](AppData[\\\\/]Local[\\\\/])?(Temp|tmp)[\\\\/]' + + '|[\\\\/]var[\\\\/]folders[\\\\/][^\\\\/]+[\\\\/][^\\\\/]+[\\\\/]T[\\\\/]', + 'i' + ).test(p); + if (!underTemp) return false; + + // Only names this suite actually creates. A user's own scratch checkout under + // a temp directory is real work and must still be counted. + return /(to-hooks-|ab-[a-z]+-|cooccur-|holdout-|reread-|feedback-e2e|standing-e2e|lesson-origin|archive-|gen-eol-|tear-|edge-src|fixture)/i.test( + p + ); +} + +/** + * The balance sheet, with every line labelled by HOW it is known. + * + * The shipped report counted every cost and one benefit that has never been + * computable, so it was negative by construction. These are the two things + * actually known, kept apart because they are known differently and must never + * be summed into a single hero number: + * + * MEASURED-COUNTERFACTUAL substitution. The file size is known exactly and + * the replacement's size is known exactly, so the + * saving is arithmetic -- resting on the one + * assumption that the model would have read what it + * explicitly asked for. + * ESTIMATED-CAUSAL findings injection, from the holdout. Genuinely + * causal when it has samples, and worth far less + * token-wise. + * + * Fixture anchors are excluded from both. + */ +/** + * Re-read waste, split into what is KNOWN and what is not. + * + * The question is narrow on purpose: how often does one session read the same + * file twice with the file UNCHANGED in between? That is waste the graph can + * remove, and it needs no holdout, no estimate and no join -- the reads carry + * their own fingerprints. + * + * A repeat read of a file that CHANGED is not waste and is reported as such. + * Conflating the two is how the first version of this measurement turned + * 213,651 confirmed tokens into a 14.6M headline. + * + * `undecidable` is reported rather than hidden. Reads written before the + * fingerprint existed cannot be classified, and a measurement that quietly + * counted them either way would be inventing its own answer. + */ +export function rereadWaste( + dir, + // `includeFixtures` exists so the suite can exercise this against files it + // creates under the temp directory -- which the fixture filter otherwise + // excludes by design, making the real path untestable. + { events = readMetrics(dir), includeFixtures = false } = {} +) { + const groups = new Map(); + for (const e of events) { + if (e.kind !== 'read' || !e.anchor) continue; + if (!includeFixtures && isFixtureAnchor(e.anchor)) continue; + const key = `${e.sessionId || ''}|${canonicalKeyish(e.anchor)}`; + if (!groups.has(key)) groups.set(key, []); + groups.get(key).push(e); + } + + const out = { + repeats: 0, + wasteful: 0, + wastefulTokens: 0, + legitimate: 0, + legitimateTokens: 0, + undecidable: 0, + undecidableTokens: 0, + }; + + for (const list of groups.values()) { + if (list.length < 2) continue; + list.sort((a, b) => (a.at || 0) - (b.at || 0)); + for (let i = 1; i < list.length; i++) { + const prev = list[i - 1]; + const cur = list[i]; + const tokens = cur.tokens || 0; + out.repeats += 1; + if (!prev.fp || !cur.fp) { + out.undecidable += 1; + out.undecidableTokens += tokens; + } else if (prev.fp === cur.fp) { + out.wasteful += 1; + out.wastefulTokens += tokens; + } else { + out.legitimate += 1; + out.legitimateTokens += tokens; + } + } + } + + const decided = out.wasteful + out.legitimate; + out.coverage = out.repeats ? decided / out.repeats : null; + return out; +} + +export function balanceSheet(dir) { + const balance = readBalance(dir).filter((e) => !isFixtureAnchor(e.anchor)); + const events = readMetrics(dir); + const truncation = readTruncation(); + + const subs = balance.filter((e) => e.kind === 'substitute'); + const served = subs.filter((e) => !e.holdout); + const withheldSubs = subs.filter((e) => e.holdout); + + // NET, not gross: the skeleton was still sent. + const netAvoided = served.reduce( + (sum, e) => + sum + + (e.tokensNetAvoided ?? + Math.max(0, Math.ceil((e.bytesAvoided || 0) / 4) - (e.tokens || 0))), + 0 + ); + const substitutionCost = served.reduce((sum, e) => sum + (e.tokens || 0), 0); + + const injectCost = balance + .filter((e) => e.kind === 'inject' && !e.holdout) + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const harvestCost = balance + .filter((e) => e.kind === 'harvest') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const standingCost = events + .filter((e) => e.kind === 'standing') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + + // RE-READS, decided by fingerprint rather than assumed. + const waste = rereadWaste(dir, { events }); + + return { + measuredCounterfactual: { + what: 'substitution: a skeleton sent instead of the file the model asked for', + substitutions: served.length, + withheld: withheldSubs.length, + tokensAvoidedNet: netAvoided, + tokensSpent: substitutionCost, + // THE CONTROL ARM'S ACTUAL COST. `tokensFullFile` was recorded and read + // by nothing, so the comparison the holdout exists for was not + // computable from the report. + controlArmTokens: withheldSubs.reduce((sum, e) => sum + (e.tokensFullFile || 0), 0), + assumption: 'that the model would have read the file it explicitly requested', + }, + estimatedCausal: { + what: 'findings injection, from the stratified holdout', + ...(() => { + const r = report(dir); + return { + treated: r.injections, + holdouts: r.holdouts, + tokensAvoided: r.estimatedTokensAvoided, + sufficientData: r.sufficientData, + verdict: r.verdict, + }; + })(), + }, + costs: { injection: injectCost, harvest: harvestCost, standing: standingCost, substitution: substitutionCost }, + waste, + // Deliberately NOT a single number. The two benefit lines are known + // differently; adding them would launder an assumption into a measurement. + // TWO WINDOWS, STATED RATHER THAN BLENDED. Balance records are read in + // full; everything derived from `events` sees only the tail of + // metrics.jsonl. Once that log rolls past its cap these cover different + // periods, and a reader has to be able to see that rather than assume one + // consistent balance. + windows: { + balance: 'all balance.jsonl records within the byte cap', + events: `tail of metrics.jsonl (<= ${MAX_BYTES} bytes, <= ${MAX_EVENTS} events)`, + // BOTH CAPS, from the reader itself. The previous flag tested the event + // count only, so a log truncated by the BYTE cap with fewer than + // MAX_EVENTS surviving records reported `false` -- the one case where the + // window silently covers a shorter period than the balance side. + eventsTruncated: truncation.byBytes || truncation.byEvents, + truncatedBy: truncation, + }, + note: 'benefit lines are reported separately by evidence strength and are never summed', + }; +} + +/** Cheap path normalisation for grouping reads; not the identity canonicaliser. */ +function canonicalKeyish(p) { + return String(p || '').replace(/\\/g, '/').toLowerCase(); +} + /** * The report. * @@ -159,8 +598,29 @@ function readAll(dir) { */ export function report(dir) { const events = readAll(dir); + // Injections and harvests come from the log that cannot be starved. + const balance = readBalance(dir); - const injections = events.filter((e) => e.kind === 'inject'); + // COMMAND INJECTIONS ARE COUNTED SEPARATELY, not mixed into the balance. + // + // The saving is measured by joining an injection to the READS of its anchor + // afterwards. A command injection's anchor is the command text, which no read + // event will ever match, so both arms would contribute zero downstream and + // every command record would pull both means toward zero -- diluting a real + // file-touch saving in proportion to how many commands ran. + // + // They still take part in the holdout, and are reported, because a structural + // exclusion is how 95 of 136 injections came to be unmeasurable. What is + // missing is a downstream join for them, and that is stated rather than + // papered over with a number. + const allInjections = balance.filter((e) => e.kind === 'inject'); + // `trigger` is the pre-`surface` spelling. Records written before the split + // carry it and no surface at all, so keying only on surface would silently + // file 95 historical command injections into the file-read balance -- exactly + // the dilution the split exists to prevent. + const isCommand = (e) => e.surface === 'command' || e.trigger === 'command'; + const commandInjections = allInjections.filter(isCommand); + const injections = allInjections.filter((e) => !isCommand(e)); const treated = injections.filter((e) => !e.holdout); const withheld = injections.filter((e) => e.holdout); @@ -168,7 +628,7 @@ export function report(dir) { rows.length ? rows.reduce((sum, r) => sum + (r[field] || 0), 0) / rows.length : 0; const injectedTokens = treated.reduce((sum, e) => sum + (e.tokens || 0), 0); - const harvestTokens = events + const harvestTokens = balance .filter((e) => e.kind === 'harvest') .reduce((sum, e) => sum + (e.tokens || 0), 0); @@ -238,6 +698,8 @@ export function report(dir) { return { injections: treated.length, + commandInjections: commandInjections.length, + commandHoldouts: commandInjections.filter((e) => e.holdout).length, holdouts: withheld.length, staleServed: injections.filter((e) => e.stale).length, staleRate: injections.length ? injections.filter((e) => e.stale).length / injections.length : 0, diff --git a/integrations/continue/config.yaml b/integrations/continue/config.yaml index c02a6daf3..7711d44a2 100644 --- a/integrations/continue/config.yaml +++ b/integrations/continue/config.yaml @@ -1,4 +1,4 @@ mcpServers: - name: token-optimizer command: npx - args: ["-y", "@ooples/token-optimizer-mcp@5.3.6"] + args: ["-y", "@ooples/token-optimizer-mcp@5.4.0"] diff --git a/integrations/copilot/mcp-config.json b/integrations/copilot/mcp-config.json index 65ea5c89b..8d139fc1a 100644 --- a/integrations/copilot/mcp-config.json +++ b/integrations/copilot/mcp-config.json @@ -3,7 +3,7 @@ "token-optimizer": { "type": "local", "command": "npx", - "args": ["-y", "@ooples/token-optimizer-mcp@5.3.6"], + "args": ["-y", "@ooples/token-optimizer-mcp@5.4.0"], "tools": ["*"] } } diff --git a/integrations/crush/crush.json b/integrations/crush/crush.json index f694c4030..856f5c4d3 100644 --- a/integrations/crush/crush.json +++ b/integrations/crush/crush.json @@ -5,7 +5,7 @@ "command": "npx", "args": [ "-y", - "@ooples/token-optimizer-mcp@5.3.6" + "@ooples/token-optimizer-mcp@5.4.0" ], "env": {} } diff --git a/integrations/cursor/mcp.json b/integrations/cursor/mcp.json index d254a4f5d..9f0fa99ec 100644 --- a/integrations/cursor/mcp.json +++ b/integrations/cursor/mcp.json @@ -4,7 +4,7 @@ "command": "npx", "args": [ "-y", - "@ooples/token-optimizer-mcp@5.3.6" + "@ooples/token-optimizer-mcp@5.4.0" ], "env": {} } diff --git a/integrations/droid/mcp.json b/integrations/droid/mcp.json index d254a4f5d..9f0fa99ec 100644 --- a/integrations/droid/mcp.json +++ b/integrations/droid/mcp.json @@ -4,7 +4,7 @@ "command": "npx", "args": [ "-y", - "@ooples/token-optimizer-mcp@5.3.6" + "@ooples/token-optimizer-mcp@5.4.0" ], "env": {} } diff --git a/integrations/gemini/gemini-extension.json b/integrations/gemini/gemini-extension.json index e37f67902..e578b68af 100644 --- a/integrations/gemini/gemini-extension.json +++ b/integrations/gemini/gemini-extension.json @@ -5,7 +5,7 @@ "mcpServers": { "token-optimizer": { "command": "npx", - "args": ["-y", "@ooples/token-optimizer-mcp@5.3.6"] + "args": ["-y", "@ooples/token-optimizer-mcp@5.4.0"] } }, "settings": [ diff --git a/integrations/gemini/hooks/lib/fleet.mjs b/integrations/gemini/hooks/lib/fleet.mjs index 68da2228b..5bb953b51 100644 --- a/integrations/gemini/hooks/lib/fleet.mjs +++ b/integrations/gemini/hooks/lib/fleet.mjs @@ -38,7 +38,7 @@ import { createHash } from 'node:crypto'; import { readFileSync, readdirSync, statSync, existsSync, openSync, readSync, closeSync } from 'node:fs'; import { join, basename } from 'node:path'; import { homedir } from 'node:os'; -import { readMetrics } from './metrics.mjs'; +import { readMetrics, balanceSheet } from './metrics.mjs'; import { cacheHealth, readCacheUsage } from './cache.mjs'; import { activeRules } from './remedy.mjs'; import { monthly, money, priceNote } from './pricing.mjs'; @@ -166,6 +166,15 @@ const sha256 = (path) => { * exists where a refusal actually replaced a read, so its presence is evidence * that the veto is live in that project rather than that a config file says so. */ +/** Never let a malformed log take down a fleet scan. */ +function safeBalance(dir) { + try { + return balanceSheet(dir); + } catch { + return null; + } +} + export function scanProject(project) { const dir = project.cwd ? wikiDir(project.cwd) : null; const events = dir && existsSync(dir) ? readMetrics(dir) : []; @@ -188,6 +197,14 @@ export function scanProject(project) { perRead: reads.length ? Math.round(tokens / reads.length) : null, enforcing: substitutions > 0, substitutions, + // THE BALANCE, PER PROJECT, LABELLED BY HOW EACH LINE IS KNOWN. + // + // The fleet view is where 'is this paying for itself' is actually asked, + // and it had only raw counts to answer with. The two benefit lines stay + // separate here as everywhere else: one is arithmetic on known file sizes, + // the other is a causal estimate from the holdout, and summing them would + // launder an assumption into a measurement. + balance: dir && existsSync(dir) ? safeBalance(dir) : null, anchors: [...new Set(reads.map((r) => r.anchor).filter(Boolean))], rules: dir ? activeRules(dir) : [], cache: project.transcript ? cacheHealth(readCacheUsage(project.transcript)) : null, diff --git a/integrations/gemini/hooks/lib/inject.mjs b/integrations/gemini/hooks/lib/inject.mjs index 21606f1c0..022b7de0d 100644 --- a/integrations/gemini/hooks/lib/inject.mjs +++ b/integrations/gemini/hooks/lib/inject.mjs @@ -45,6 +45,21 @@ const touchBudget = () => Number(process.env.TOKEN_OPTIMIZER_TOUCH_BUDGET) || 50 const standingBudget = () => Number(process.env.TOKEN_OPTIMIZER_STANDING_BUDGET) || 400; +/** + * The stratification key for a command. + * + * Normalised so that the same intent lands in the same arm: trailing + * whitespace and a differing set of paths should not flip a command between + * treated and withheld, because that is what makes the two arms comparable. + */ +function commandKey(command) { + return String(command || '') + .trim() + .replace(/\s+/g, ' ') + .slice(0, 120) + .toLowerCase(); +} + /** Most findings considered for one command before the budget decides. */ const MAX_COMMAND_CANDIDATES = 20; @@ -133,12 +148,18 @@ export function forTouch( .filter((f) => !alreadyInjected.has(f.key)); if (!candidates.length) return null; + // STRATIFIED BY FILE AND EPOCH, which is the documented design here: the + // same file lands in the holdout during some epochs and the treated arm in + // others, so the comparison becomes within-file and the dominant source of + // variance drops out. A session-pinned arm would destroy that. const holdout = inHoldout(filePath); const served = serve(graph, candidates); const { kept, spent } = fit(served, budget); record(dir, { kind: 'inject', + // The surface whose saving CAN be measured: reads of this anchor afterwards. + surface: 'file', anchor: filePath, holdout, tokens: holdout ? 0 : spent, @@ -147,10 +168,17 @@ export function forTouch( sessionId, }); - if (holdout || !kept.length) return null; - + // MARKED SEEN IN BOTH ARMS, for the same reason as the command path: a file + // touched repeatedly -- the normal shape of working on it -- would otherwise + // write a fresh holdout row every time while a treated file was suppressed + // after its first delivery. The report counts rows, so the control arm would + // grow faster purely from repetition. + // + // This is the identical defect that was fixed in `forCommand` and not here. for (const f of kept) alreadyInjected.add(f.key); + if (holdout || !kept.length) return null; + return `Known about ${filePath} (from previous sessions):\n${kept.map(render).join('\n')}`; } @@ -295,19 +323,46 @@ export function forCommand( const { kept, spent } = fit(served, budget); if (!kept.length) return null; + // THE COMMAND PATH TAKES PART IN THE HOLDOUT TOO. + // + // `holdout: false` was hardcoded here, so 95 of 136 injections measured on a + // real machine were structurally excluded from the only mechanism that can + // establish causation. Seventy per cent of what the feature does could never + // be shown to help or hurt. + // + // Stratified on the COMMAND rather than a file, by the same (key, epoch) + // hash: the same command lands in the same arm all session, so a command run + // repeatedly cannot straddle both arms and contaminate each. + const key = commandKey(command); + const holdout = inHoldout(key); + record(dir, { kind: 'inject', trigger: 'command', + // The surface the report needs to keep these OUT of the file-read balance: + // a command has no anchor that read events can be joined to. + surface: 'command', anchor: String(command).slice(0, 120), - holdout: false, - tokens: spent, - count: kept.length, + holdout, + tokens: holdout ? 0 : spent, + count: holdout ? 0 : kept.length, stale: kept.some((f) => f.stale), sessionId, }); + // MARKED SEEN IN BOTH ARMS. + // + // The held branch used to return before updating the gate, so a command run + // repeatedly wrote a fresh holdout row every time while a treated command was + // filtered after its first delivery. The report counts rows, so the holdout + // arm was systematically overweighted -- a bias in the very comparison this + // exists to make. for (const f of kept) alreadyInjected.add(f.key); + // Withheld means withheld. Returning the text anyway would record an arm the + // subject never actually experienced. + if (holdout) return null; + return `Before running this — known from previous sessions:\n${kept .map(render) .join('\n')}`; @@ -477,7 +532,7 @@ export function standingRules(dir, graph, { budget = standingBudget() } = {}) { * informative response available -- more useful than the file, not a lossier * version of it. */ -export function substitutionFor(dir, graph, rawPath, source) { +export function substitutionFor(dir, graph, rawPath, source, { sessionId } = {}) { const filePath = canonicalPath(rawPath); const budget = substitutionBudget(dir, filePath); const built = annotatedSkeleton(graph, rawPath, source, { budget }); @@ -486,15 +541,50 @@ export function substitutionFor(dir, graph, rawPath, source) { // costs the model a round trip; send it back to the ordinary redirect. if (built.tokens * 4 > source.length * 0.5) return null; + // THE HOLDOUT BELONGS ON THIS PATH, not only on findings injection. + // + // Substitution is the lever that actually moves tokens -- it replaces a whole + // file with a skeleton -- and it had no control arm at all, while the 10% + // holdout sat on findings injection, which is two orders of magnitude + // smaller. Withholding here serves the file the model asked for and records + // what that cost, which is the only way the saving stops being an assumption. + // PINNED FOR THE SESSION, with a fixed epoch. + // + // Unlike the file-touch arm above, this one must not rotate: a session + // running across midnight would substitute for a file in one half and serve + // the whole file in the other, so `measuredCounterfactual` would mix treated + // and control observations for the same file. + // + // Keying on the session alone was not enough -- with the epoch still in play + // the arm flipped 104 times in 400 simulated midnight crossings. The session + // id already provides the rotation the epoch was there for. + const holdout = inHoldout(`${sessionId || ''}|${filePath}`, 0); + record(dir, { kind: 'substitute', anchor: filePath, - tokens: built.tokens, + // Recorded so provenance is checkable. Without it, 366 of 370 substitutions + // on this machine turned out to be the enforcement suite's own fixture and + // nothing distinguished them from real work. + sessionId, + holdout, + tokens: holdout ? 0 : built.tokens, findings: built.findings, symbols: built.symbols, - bytesAvoided: source.length, + // GROSS, kept for continuity with existing records. + bytesAvoided: holdout ? 0 : source.length, + // NET, which is the honest figure: the skeleton was still sent. Reporting + // the whole file as avoided while spending `tokens` on a replacement + // overstates the saving by exactly the size of the replacement. + tokensNetAvoided: holdout ? 0 : Math.max(0, Math.ceil(source.length / 4) - built.tokens), + // What the control arm actually paid, so the two arms are comparable. + tokensFullFile: Math.ceil(source.length / 4), }); + // Withheld means the model gets what it asked for: the whole file. That is + // the control arm, and it must really be paid or the comparison is fiction. + if (holdout) return null; + return built.text; } diff --git a/integrations/gemini/hooks/lib/metrics.mjs b/integrations/gemini/hooks/lib/metrics.mjs index 0df6ee24a..3fc52e22b 100644 --- a/integrations/gemini/hooks/lib/metrics.mjs +++ b/integrations/gemini/hooks/lib/metrics.mjs @@ -23,7 +23,7 @@ import { statSync, openSync, readSync, closeSync, } from 'node:fs'; import { join } from 'node:path'; -import { createHash } from 'node:crypto'; +import { createHash, randomBytes } from 'node:crypto'; /** * Read per call, not once at module load. @@ -43,6 +43,28 @@ const EPOCH_MS = 86_400_000; const metricsPath = (dir) => join(dir, 'metrics.jsonl'); +/** + * The balance log: `inject` and `harvest` only. + * + * WHY A SECOND FILE. The event window is measured in EVENTS, and injections are + * a tiny minority of them -- 136 injections against 6,725 captures across every + * graph on one machine. So the last 5,000 events are almost entirely captures + * and reads, and the injections that carry the measurement age out first. + * + * Measured on this repository before the fix: 44 inject records in the file, 9 + * of them holdout, all at lines 60-76 of 9,058 -- every single one outside the + * window. `report()` therefore said "0 holdout" while the file plainly + * contained nine, and the net balance was uncomputable on all 122 graphs. + * + * A separate log fixes it structurally rather than by enlarging a number. + * These records are rare, so the file stays small for years, and a tail window + * on it drops BOTH arms proportionally instead of starving the rare one. + */ +const balancePath = (dir) => join(dir, 'balance.jsonl'); + +/** Kinds the net balance is computed from, and which therefore must survive. */ +const BALANCE_KINDS = new Set(['inject', 'harvest', 'substitute']); + /** * Is this touch in the holdout arm? * @@ -54,7 +76,19 @@ export function inHoldout(anchorKey, now = Date.now()) { const fraction = holdoutFraction(); if (fraction <= 0) return false; const epoch = Math.floor(now / EPOCH_MS); - const digest = createHash('sha1').update(`${anchorKey}:${epoch}`).digest(); + // SHA-256, NOT SHA-1. + // + // This is a bucketing hash, not a security primitive -- nothing is kept + // secret and nothing is authenticated, only spread evenly across two arms. + // But CodeQL flags sha1 as a weak algorithm, seven high-severity alerts + // across the core and its six vendored copies, and arguing that a finding is + // benign is a worse habit than paying a cost that rounds to nothing here. + // Both are deterministic, which is the only property this depends on. + // + // The change DOES reassign arms: a given (anchor, epoch) may land on the + // other side than before. With nine holdout records in existence that costs + // nothing, and stratification is a fresh draw either way. + const digest = createHash('sha256').update(`${anchorKey}:${epoch}`).digest(); return (digest[0] / 256) < fraction; } @@ -65,9 +99,62 @@ export function inHoldout(anchorKey, now = Date.now()) { * moment the cost is knowable. This is the producer that makes the holdout * comparison a measurement rather than a subtraction of two zeroes. */ -export function recordRead(dir, { anchor, sessionId, bytes }) { +export function recordRead(dir, { anchor, sessionId, bytes, fp = null }) { if (!anchor || !bytes) return; - record(dir, { kind: 'read', anchor, sessionId, tokens: Math.ceil(bytes / 4) }); + record(dir, { + kind: 'read', + anchor, + sessionId, + tokens: Math.ceil(bytes / 4), + // THE CHANGE DETECTOR, recorded AT READ TIME. + // + // Without it, 'was this re-read wasteful' is undecidable. Measured before + // this field existed: 575 repeat reads of a file within one session, and + // only 99 could be classified -- 4,735 capture events carried anchors on + // just 122 of them, because most captures are bookkeeping calls that touch + // no file at all. The waste figure was 98% unknowable, and the 14.6M I + // first reported was really 213,651 confirmed plus a very large shrug. + // + // It belongs on the READ, not on a capture: the read already knows the + // anchor, the session and the cost, so the fingerprint completes the record + // rather than needing to be joined to another one. + fp, + }); +} + +/** + * A cheap fingerprint of a file's current content: size and mtime. + * + * NOT a content hash, deliberately. This runs on the PreToolUse path before + * every tool call, and hashing a file there would add a full read to the + * critical path for a measurement. `statSync` is already being done to resolve + * the operand, so this is free. + * + * WHAT IT CAN MISS: a write that leaves both size and mtime identical. That + * requires deliberately restoring the timestamp, so for the question being + * asked -- did this file change between two reads in one session -- it is + * sound. Stated here because a change-detector that silently misses changes + * would understate legitimate re-reads and overstate waste, which is the + * direction this project must never err in. + */ +export function fingerprint(path) { + try { + const st = statSync(path); + return `${st.size}:${Math.round(st.mtimeMs)}`; + } catch { + return null; + } +} + +/** + * A unique id per record. Counter plus randomness: the counter separates + * records written in the same millisecond by one process, the random suffix + * separates concurrent processes, which detached workers routinely are. + */ +let idCounter = 0; +function nextId() { + idCounter += 1; + return `${idCounter.toString(36)}-${randomBytes(4).toString('hex')}`; } export function record(dir, event) { @@ -80,7 +167,24 @@ export function record(dir, event) { } catch { // Not POSIX, or not ours to chmod; the write still proceeds. } - appendFileSync(metricsPath(dir), JSON.stringify({ ...event, at: Date.now() }) + '\n'); + // The CALLER'S timestamp wins when it supplied one. Overwriting it made + // `rereadWaste`'s ordering depend on write order rather than on `at`, so a + // test that set explicit times was passing by luck. + // + // `id` EXISTS SO DEDUPE IS EXACT. A record is written to both logs, so the + // reader has to drop one copy -- and it was matching on a composite of the + // fields, which cannot tell a duplicate from two genuinely distinct events + // that happen to look alike. Twenty-five identical injections written in a + // single millisecond collapsed to ONE, so a graph with ample data reported + // 'insufficient data (2 treated, 1 holdout)'. Real events were being + // discarded by the deduplicator, silently. + const line = + JSON.stringify({ id: nextId(), ...event, at: event.at ?? Date.now() }) + '\n'; + appendFileSync(metricsPath(dir), line); + // Balance-critical records go to their own log as well, so the windows on + // the firehose can never starve the measurement. Written SECOND: a torn + // write here costs a duplicate the reader dedupes, not a lost event. + if (BALANCE_KINDS.has(event.kind)) appendFileSync(balancePath(dir), line); } catch { // Metrics must never break a tool call. } @@ -110,7 +214,22 @@ export function readMetrics(dir) { return readAll(dir); } +/** + * How the last readAll truncated, if it did. + * + * Returned out of band rather than on the array, because callers pass the + * events around freely and a property hung on an array would be lost the first + * time anything filtered it -- which is exactly how `eventsTruncated` came to + * report only half the truth. + */ +let lastReadTruncation = { byBytes: false, byEvents: false }; + +export function readTruncation() { + return { ...lastReadTruncation }; +} + function readAll(dir) { + lastReadTruncation = { byBytes: false, byEvents: false }; const path = metricsPath(dir); if (!existsSync(path)) return []; @@ -132,13 +251,16 @@ function readAll(dir) { // The first line is almost certainly cut mid-record; drop it rather than // letting it fail to parse and look like corruption. text = text.slice(text.indexOf('\n') + 1); + lastReadTruncation.byBytes = true; } } catch { return []; } const out = []; - for (const line of text.split('\n').slice(-MAX_EVENTS)) { + const lines = text.split('\n'); + if (lines.length > MAX_EVENTS) lastReadTruncation.byEvents = true; + for (const line of lines.slice(-MAX_EVENTS)) { if (!line) continue; try { out.push(JSON.parse(line)); @@ -149,6 +271,323 @@ function readAll(dir) { return out; } +/** + * Balance records, read WITHOUT the event window that was starving them. + * + * Reads the dedicated log in full, and merges in whatever the firehose still + * holds so graphs that predate the split are not left unmeasurable. Duplicates + * are inevitable once both logs carry the same record, so they are removed on + * an identity built from the fields that make an event unique. + * + * The byte cap still applies to the dedicated log, but it means something very + * different here: these records are rare, so the cap is years of history rather + * than hours, and it drops BOTH arms proportionally when it finally bites. + */ +/** + * Every balance record in a file, with NO event window. + * + * The byte cap still bounds the read, because the firehose can be enormous. The + * event cap does not apply: it is what buried these records in the first place, + * and they are rare enough that keeping all of them inside the byte window costs + * nothing. + */ +function scanForBalance(path) { + if (!existsSync(path)) return []; + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + return []; + } + const out = []; + for (const line of text.split('\n')) { + if (!line) continue; + try { + const e = JSON.parse(line); + if (BALANCE_KINDS.has(e.kind)) out.push(e); + } catch { + /* a torn line costs a record, not the report */ + } + } + return out; +} + +export function readBalance(dir) { + const merged = []; + const path = balancePath(dir); + if (existsSync(path)) { + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + text = ''; + } + for (const line of text.split('\n')) { + if (!line) continue; + try { + merged.push(JSON.parse(line)); + } catch { + /* a torn line costs a record, not the report */ + } + } + } + + // MIGRATION, not a fallback. Every graph written before the split has its + // only copy of these records in the firehose; ignoring them would reset the + // measurement to zero on 122 existing graphs. + // + // IT MUST NOT GO THROUGH readAll. The first version of this fix did, and + // readAll applies the very event window that was starving the measurement -- + // so the migration inherited the bug it existed to repair and the real graphs + // still reported zero holdouts. Verified against them: unchanged at 0 until + // this scan stopped windowing. + for (const e of scanForBalance(metricsPath(dir))) merged.push(e); + + const seen = new Set(); + const out = []; + for (const e of merged) { + // The record's OWN id when it has one. The composite below is the legacy + // path for records written before ids existed; it is lossy by nature, which + // is precisely why new records carry an id instead. + const id = + e.id ?? [e.kind, e.at, e.anchor ?? '', e.sessionId ?? '', e.tokens ?? ''].join('|'); + if (seen.has(id)) continue; + seen.add(id); + out.push(e); + } + return out; +} + +/** + * Is this anchor a test fixture rather than real work? + * + * Not fussiness. Measured on this machine: 366 of 370 substitutions pointed at + * the enforcement suite's own big.ts fixture under a temp dir, and counting them made + * the product look like it had avoided 40 MB of reads. It had avoided 154 KB. + * A balance sheet that counts its own test suite as revenue is worse than none. + */ +export function isFixtureAnchor(anchor) { + const p = String(anchor || ''); + + // TWO CONDITIONS, BOTH REQUIRED. The previous version was a ternary chain in + // which every branch evaluated to `underTemp`, so the scratch test was dead + // code: it excluded ALL temp paths -- including a real project checked out + // under /tmp -- and on macOS excluded nothing at all, because tmpdir() there + // is /var/folders///T/ and did not match. + const underTemp = + new RegExp( + '[\\\\/](AppData[\\\\/]Local[\\\\/])?(Temp|tmp)[\\\\/]' + + '|[\\\\/]var[\\\\/]folders[\\\\/][^\\\\/]+[\\\\/][^\\\\/]+[\\\\/]T[\\\\/]', + 'i' + ).test(p); + if (!underTemp) return false; + + // Only names this suite actually creates. A user's own scratch checkout under + // a temp directory is real work and must still be counted. + return /(to-hooks-|ab-[a-z]+-|cooccur-|holdout-|reread-|feedback-e2e|standing-e2e|lesson-origin|archive-|gen-eol-|tear-|edge-src|fixture)/i.test( + p + ); +} + +/** + * The balance sheet, with every line labelled by HOW it is known. + * + * The shipped report counted every cost and one benefit that has never been + * computable, so it was negative by construction. These are the two things + * actually known, kept apart because they are known differently and must never + * be summed into a single hero number: + * + * MEASURED-COUNTERFACTUAL substitution. The file size is known exactly and + * the replacement's size is known exactly, so the + * saving is arithmetic -- resting on the one + * assumption that the model would have read what it + * explicitly asked for. + * ESTIMATED-CAUSAL findings injection, from the holdout. Genuinely + * causal when it has samples, and worth far less + * token-wise. + * + * Fixture anchors are excluded from both. + */ +/** + * Re-read waste, split into what is KNOWN and what is not. + * + * The question is narrow on purpose: how often does one session read the same + * file twice with the file UNCHANGED in between? That is waste the graph can + * remove, and it needs no holdout, no estimate and no join -- the reads carry + * their own fingerprints. + * + * A repeat read of a file that CHANGED is not waste and is reported as such. + * Conflating the two is how the first version of this measurement turned + * 213,651 confirmed tokens into a 14.6M headline. + * + * `undecidable` is reported rather than hidden. Reads written before the + * fingerprint existed cannot be classified, and a measurement that quietly + * counted them either way would be inventing its own answer. + */ +export function rereadWaste( + dir, + // `includeFixtures` exists so the suite can exercise this against files it + // creates under the temp directory -- which the fixture filter otherwise + // excludes by design, making the real path untestable. + { events = readMetrics(dir), includeFixtures = false } = {} +) { + const groups = new Map(); + for (const e of events) { + if (e.kind !== 'read' || !e.anchor) continue; + if (!includeFixtures && isFixtureAnchor(e.anchor)) continue; + const key = `${e.sessionId || ''}|${canonicalKeyish(e.anchor)}`; + if (!groups.has(key)) groups.set(key, []); + groups.get(key).push(e); + } + + const out = { + repeats: 0, + wasteful: 0, + wastefulTokens: 0, + legitimate: 0, + legitimateTokens: 0, + undecidable: 0, + undecidableTokens: 0, + }; + + for (const list of groups.values()) { + if (list.length < 2) continue; + list.sort((a, b) => (a.at || 0) - (b.at || 0)); + for (let i = 1; i < list.length; i++) { + const prev = list[i - 1]; + const cur = list[i]; + const tokens = cur.tokens || 0; + out.repeats += 1; + if (!prev.fp || !cur.fp) { + out.undecidable += 1; + out.undecidableTokens += tokens; + } else if (prev.fp === cur.fp) { + out.wasteful += 1; + out.wastefulTokens += tokens; + } else { + out.legitimate += 1; + out.legitimateTokens += tokens; + } + } + } + + const decided = out.wasteful + out.legitimate; + out.coverage = out.repeats ? decided / out.repeats : null; + return out; +} + +export function balanceSheet(dir) { + const balance = readBalance(dir).filter((e) => !isFixtureAnchor(e.anchor)); + const events = readMetrics(dir); + const truncation = readTruncation(); + + const subs = balance.filter((e) => e.kind === 'substitute'); + const served = subs.filter((e) => !e.holdout); + const withheldSubs = subs.filter((e) => e.holdout); + + // NET, not gross: the skeleton was still sent. + const netAvoided = served.reduce( + (sum, e) => + sum + + (e.tokensNetAvoided ?? + Math.max(0, Math.ceil((e.bytesAvoided || 0) / 4) - (e.tokens || 0))), + 0 + ); + const substitutionCost = served.reduce((sum, e) => sum + (e.tokens || 0), 0); + + const injectCost = balance + .filter((e) => e.kind === 'inject' && !e.holdout) + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const harvestCost = balance + .filter((e) => e.kind === 'harvest') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const standingCost = events + .filter((e) => e.kind === 'standing') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + + // RE-READS, decided by fingerprint rather than assumed. + const waste = rereadWaste(dir, { events }); + + return { + measuredCounterfactual: { + what: 'substitution: a skeleton sent instead of the file the model asked for', + substitutions: served.length, + withheld: withheldSubs.length, + tokensAvoidedNet: netAvoided, + tokensSpent: substitutionCost, + // THE CONTROL ARM'S ACTUAL COST. `tokensFullFile` was recorded and read + // by nothing, so the comparison the holdout exists for was not + // computable from the report. + controlArmTokens: withheldSubs.reduce((sum, e) => sum + (e.tokensFullFile || 0), 0), + assumption: 'that the model would have read the file it explicitly requested', + }, + estimatedCausal: { + what: 'findings injection, from the stratified holdout', + ...(() => { + const r = report(dir); + return { + treated: r.injections, + holdouts: r.holdouts, + tokensAvoided: r.estimatedTokensAvoided, + sufficientData: r.sufficientData, + verdict: r.verdict, + }; + })(), + }, + costs: { injection: injectCost, harvest: harvestCost, standing: standingCost, substitution: substitutionCost }, + waste, + // Deliberately NOT a single number. The two benefit lines are known + // differently; adding them would launder an assumption into a measurement. + // TWO WINDOWS, STATED RATHER THAN BLENDED. Balance records are read in + // full; everything derived from `events` sees only the tail of + // metrics.jsonl. Once that log rolls past its cap these cover different + // periods, and a reader has to be able to see that rather than assume one + // consistent balance. + windows: { + balance: 'all balance.jsonl records within the byte cap', + events: `tail of metrics.jsonl (<= ${MAX_BYTES} bytes, <= ${MAX_EVENTS} events)`, + // BOTH CAPS, from the reader itself. The previous flag tested the event + // count only, so a log truncated by the BYTE cap with fewer than + // MAX_EVENTS surviving records reported `false` -- the one case where the + // window silently covers a shorter period than the balance side. + eventsTruncated: truncation.byBytes || truncation.byEvents, + truncatedBy: truncation, + }, + note: 'benefit lines are reported separately by evidence strength and are never summed', + }; +} + +/** Cheap path normalisation for grouping reads; not the identity canonicaliser. */ +function canonicalKeyish(p) { + return String(p || '').replace(/\\/g, '/').toLowerCase(); +} + /** * The report. * @@ -159,8 +598,29 @@ function readAll(dir) { */ export function report(dir) { const events = readAll(dir); + // Injections and harvests come from the log that cannot be starved. + const balance = readBalance(dir); - const injections = events.filter((e) => e.kind === 'inject'); + // COMMAND INJECTIONS ARE COUNTED SEPARATELY, not mixed into the balance. + // + // The saving is measured by joining an injection to the READS of its anchor + // afterwards. A command injection's anchor is the command text, which no read + // event will ever match, so both arms would contribute zero downstream and + // every command record would pull both means toward zero -- diluting a real + // file-touch saving in proportion to how many commands ran. + // + // They still take part in the holdout, and are reported, because a structural + // exclusion is how 95 of 136 injections came to be unmeasurable. What is + // missing is a downstream join for them, and that is stated rather than + // papered over with a number. + const allInjections = balance.filter((e) => e.kind === 'inject'); + // `trigger` is the pre-`surface` spelling. Records written before the split + // carry it and no surface at all, so keying only on surface would silently + // file 95 historical command injections into the file-read balance -- exactly + // the dilution the split exists to prevent. + const isCommand = (e) => e.surface === 'command' || e.trigger === 'command'; + const commandInjections = allInjections.filter(isCommand); + const injections = allInjections.filter((e) => !isCommand(e)); const treated = injections.filter((e) => !e.holdout); const withheld = injections.filter((e) => e.holdout); @@ -168,7 +628,7 @@ export function report(dir) { rows.length ? rows.reduce((sum, r) => sum + (r[field] || 0), 0) / rows.length : 0; const injectedTokens = treated.reduce((sum, e) => sum + (e.tokens || 0), 0); - const harvestTokens = events + const harvestTokens = balance .filter((e) => e.kind === 'harvest') .reduce((sum, e) => sum + (e.tokens || 0), 0); @@ -238,6 +698,8 @@ export function report(dir) { return { injections: treated.length, + commandInjections: commandInjections.length, + commandHoldouts: commandInjections.filter((e) => e.holdout).length, holdouts: withheld.length, staleServed: injections.filter((e) => e.stale).length, staleRate: injections.length ? injections.filter((e) => e.stale).length / injections.length : 0, diff --git a/integrations/kilo/kilo.jsonc b/integrations/kilo/kilo.jsonc index d188bb369..24f356141 100644 --- a/integrations/kilo/kilo.jsonc +++ b/integrations/kilo/kilo.jsonc @@ -5,7 +5,7 @@ "command": [ "npx", "-y", - "@ooples/token-optimizer-mcp@5.3.6" + "@ooples/token-optimizer-mcp@5.4.0" ], "environment": {}, "enabled": true diff --git a/integrations/opencode/hooks/lib/fleet.mjs b/integrations/opencode/hooks/lib/fleet.mjs index 68da2228b..5bb953b51 100644 --- a/integrations/opencode/hooks/lib/fleet.mjs +++ b/integrations/opencode/hooks/lib/fleet.mjs @@ -38,7 +38,7 @@ import { createHash } from 'node:crypto'; import { readFileSync, readdirSync, statSync, existsSync, openSync, readSync, closeSync } from 'node:fs'; import { join, basename } from 'node:path'; import { homedir } from 'node:os'; -import { readMetrics } from './metrics.mjs'; +import { readMetrics, balanceSheet } from './metrics.mjs'; import { cacheHealth, readCacheUsage } from './cache.mjs'; import { activeRules } from './remedy.mjs'; import { monthly, money, priceNote } from './pricing.mjs'; @@ -166,6 +166,15 @@ const sha256 = (path) => { * exists where a refusal actually replaced a read, so its presence is evidence * that the veto is live in that project rather than that a config file says so. */ +/** Never let a malformed log take down a fleet scan. */ +function safeBalance(dir) { + try { + return balanceSheet(dir); + } catch { + return null; + } +} + export function scanProject(project) { const dir = project.cwd ? wikiDir(project.cwd) : null; const events = dir && existsSync(dir) ? readMetrics(dir) : []; @@ -188,6 +197,14 @@ export function scanProject(project) { perRead: reads.length ? Math.round(tokens / reads.length) : null, enforcing: substitutions > 0, substitutions, + // THE BALANCE, PER PROJECT, LABELLED BY HOW EACH LINE IS KNOWN. + // + // The fleet view is where 'is this paying for itself' is actually asked, + // and it had only raw counts to answer with. The two benefit lines stay + // separate here as everywhere else: one is arithmetic on known file sizes, + // the other is a causal estimate from the holdout, and summing them would + // launder an assumption into a measurement. + balance: dir && existsSync(dir) ? safeBalance(dir) : null, anchors: [...new Set(reads.map((r) => r.anchor).filter(Boolean))], rules: dir ? activeRules(dir) : [], cache: project.transcript ? cacheHealth(readCacheUsage(project.transcript)) : null, diff --git a/integrations/opencode/hooks/lib/inject.mjs b/integrations/opencode/hooks/lib/inject.mjs index 21606f1c0..022b7de0d 100644 --- a/integrations/opencode/hooks/lib/inject.mjs +++ b/integrations/opencode/hooks/lib/inject.mjs @@ -45,6 +45,21 @@ const touchBudget = () => Number(process.env.TOKEN_OPTIMIZER_TOUCH_BUDGET) || 50 const standingBudget = () => Number(process.env.TOKEN_OPTIMIZER_STANDING_BUDGET) || 400; +/** + * The stratification key for a command. + * + * Normalised so that the same intent lands in the same arm: trailing + * whitespace and a differing set of paths should not flip a command between + * treated and withheld, because that is what makes the two arms comparable. + */ +function commandKey(command) { + return String(command || '') + .trim() + .replace(/\s+/g, ' ') + .slice(0, 120) + .toLowerCase(); +} + /** Most findings considered for one command before the budget decides. */ const MAX_COMMAND_CANDIDATES = 20; @@ -133,12 +148,18 @@ export function forTouch( .filter((f) => !alreadyInjected.has(f.key)); if (!candidates.length) return null; + // STRATIFIED BY FILE AND EPOCH, which is the documented design here: the + // same file lands in the holdout during some epochs and the treated arm in + // others, so the comparison becomes within-file and the dominant source of + // variance drops out. A session-pinned arm would destroy that. const holdout = inHoldout(filePath); const served = serve(graph, candidates); const { kept, spent } = fit(served, budget); record(dir, { kind: 'inject', + // The surface whose saving CAN be measured: reads of this anchor afterwards. + surface: 'file', anchor: filePath, holdout, tokens: holdout ? 0 : spent, @@ -147,10 +168,17 @@ export function forTouch( sessionId, }); - if (holdout || !kept.length) return null; - + // MARKED SEEN IN BOTH ARMS, for the same reason as the command path: a file + // touched repeatedly -- the normal shape of working on it -- would otherwise + // write a fresh holdout row every time while a treated file was suppressed + // after its first delivery. The report counts rows, so the control arm would + // grow faster purely from repetition. + // + // This is the identical defect that was fixed in `forCommand` and not here. for (const f of kept) alreadyInjected.add(f.key); + if (holdout || !kept.length) return null; + return `Known about ${filePath} (from previous sessions):\n${kept.map(render).join('\n')}`; } @@ -295,19 +323,46 @@ export function forCommand( const { kept, spent } = fit(served, budget); if (!kept.length) return null; + // THE COMMAND PATH TAKES PART IN THE HOLDOUT TOO. + // + // `holdout: false` was hardcoded here, so 95 of 136 injections measured on a + // real machine were structurally excluded from the only mechanism that can + // establish causation. Seventy per cent of what the feature does could never + // be shown to help or hurt. + // + // Stratified on the COMMAND rather than a file, by the same (key, epoch) + // hash: the same command lands in the same arm all session, so a command run + // repeatedly cannot straddle both arms and contaminate each. + const key = commandKey(command); + const holdout = inHoldout(key); + record(dir, { kind: 'inject', trigger: 'command', + // The surface the report needs to keep these OUT of the file-read balance: + // a command has no anchor that read events can be joined to. + surface: 'command', anchor: String(command).slice(0, 120), - holdout: false, - tokens: spent, - count: kept.length, + holdout, + tokens: holdout ? 0 : spent, + count: holdout ? 0 : kept.length, stale: kept.some((f) => f.stale), sessionId, }); + // MARKED SEEN IN BOTH ARMS. + // + // The held branch used to return before updating the gate, so a command run + // repeatedly wrote a fresh holdout row every time while a treated command was + // filtered after its first delivery. The report counts rows, so the holdout + // arm was systematically overweighted -- a bias in the very comparison this + // exists to make. for (const f of kept) alreadyInjected.add(f.key); + // Withheld means withheld. Returning the text anyway would record an arm the + // subject never actually experienced. + if (holdout) return null; + return `Before running this — known from previous sessions:\n${kept .map(render) .join('\n')}`; @@ -477,7 +532,7 @@ export function standingRules(dir, graph, { budget = standingBudget() } = {}) { * informative response available -- more useful than the file, not a lossier * version of it. */ -export function substitutionFor(dir, graph, rawPath, source) { +export function substitutionFor(dir, graph, rawPath, source, { sessionId } = {}) { const filePath = canonicalPath(rawPath); const budget = substitutionBudget(dir, filePath); const built = annotatedSkeleton(graph, rawPath, source, { budget }); @@ -486,15 +541,50 @@ export function substitutionFor(dir, graph, rawPath, source) { // costs the model a round trip; send it back to the ordinary redirect. if (built.tokens * 4 > source.length * 0.5) return null; + // THE HOLDOUT BELONGS ON THIS PATH, not only on findings injection. + // + // Substitution is the lever that actually moves tokens -- it replaces a whole + // file with a skeleton -- and it had no control arm at all, while the 10% + // holdout sat on findings injection, which is two orders of magnitude + // smaller. Withholding here serves the file the model asked for and records + // what that cost, which is the only way the saving stops being an assumption. + // PINNED FOR THE SESSION, with a fixed epoch. + // + // Unlike the file-touch arm above, this one must not rotate: a session + // running across midnight would substitute for a file in one half and serve + // the whole file in the other, so `measuredCounterfactual` would mix treated + // and control observations for the same file. + // + // Keying on the session alone was not enough -- with the epoch still in play + // the arm flipped 104 times in 400 simulated midnight crossings. The session + // id already provides the rotation the epoch was there for. + const holdout = inHoldout(`${sessionId || ''}|${filePath}`, 0); + record(dir, { kind: 'substitute', anchor: filePath, - tokens: built.tokens, + // Recorded so provenance is checkable. Without it, 366 of 370 substitutions + // on this machine turned out to be the enforcement suite's own fixture and + // nothing distinguished them from real work. + sessionId, + holdout, + tokens: holdout ? 0 : built.tokens, findings: built.findings, symbols: built.symbols, - bytesAvoided: source.length, + // GROSS, kept for continuity with existing records. + bytesAvoided: holdout ? 0 : source.length, + // NET, which is the honest figure: the skeleton was still sent. Reporting + // the whole file as avoided while spending `tokens` on a replacement + // overstates the saving by exactly the size of the replacement. + tokensNetAvoided: holdout ? 0 : Math.max(0, Math.ceil(source.length / 4) - built.tokens), + // What the control arm actually paid, so the two arms are comparable. + tokensFullFile: Math.ceil(source.length / 4), }); + // Withheld means the model gets what it asked for: the whole file. That is + // the control arm, and it must really be paid or the comparison is fiction. + if (holdout) return null; + return built.text; } diff --git a/integrations/opencode/hooks/lib/metrics.mjs b/integrations/opencode/hooks/lib/metrics.mjs index 0df6ee24a..3fc52e22b 100644 --- a/integrations/opencode/hooks/lib/metrics.mjs +++ b/integrations/opencode/hooks/lib/metrics.mjs @@ -23,7 +23,7 @@ import { statSync, openSync, readSync, closeSync, } from 'node:fs'; import { join } from 'node:path'; -import { createHash } from 'node:crypto'; +import { createHash, randomBytes } from 'node:crypto'; /** * Read per call, not once at module load. @@ -43,6 +43,28 @@ const EPOCH_MS = 86_400_000; const metricsPath = (dir) => join(dir, 'metrics.jsonl'); +/** + * The balance log: `inject` and `harvest` only. + * + * WHY A SECOND FILE. The event window is measured in EVENTS, and injections are + * a tiny minority of them -- 136 injections against 6,725 captures across every + * graph on one machine. So the last 5,000 events are almost entirely captures + * and reads, and the injections that carry the measurement age out first. + * + * Measured on this repository before the fix: 44 inject records in the file, 9 + * of them holdout, all at lines 60-76 of 9,058 -- every single one outside the + * window. `report()` therefore said "0 holdout" while the file plainly + * contained nine, and the net balance was uncomputable on all 122 graphs. + * + * A separate log fixes it structurally rather than by enlarging a number. + * These records are rare, so the file stays small for years, and a tail window + * on it drops BOTH arms proportionally instead of starving the rare one. + */ +const balancePath = (dir) => join(dir, 'balance.jsonl'); + +/** Kinds the net balance is computed from, and which therefore must survive. */ +const BALANCE_KINDS = new Set(['inject', 'harvest', 'substitute']); + /** * Is this touch in the holdout arm? * @@ -54,7 +76,19 @@ export function inHoldout(anchorKey, now = Date.now()) { const fraction = holdoutFraction(); if (fraction <= 0) return false; const epoch = Math.floor(now / EPOCH_MS); - const digest = createHash('sha1').update(`${anchorKey}:${epoch}`).digest(); + // SHA-256, NOT SHA-1. + // + // This is a bucketing hash, not a security primitive -- nothing is kept + // secret and nothing is authenticated, only spread evenly across two arms. + // But CodeQL flags sha1 as a weak algorithm, seven high-severity alerts + // across the core and its six vendored copies, and arguing that a finding is + // benign is a worse habit than paying a cost that rounds to nothing here. + // Both are deterministic, which is the only property this depends on. + // + // The change DOES reassign arms: a given (anchor, epoch) may land on the + // other side than before. With nine holdout records in existence that costs + // nothing, and stratification is a fresh draw either way. + const digest = createHash('sha256').update(`${anchorKey}:${epoch}`).digest(); return (digest[0] / 256) < fraction; } @@ -65,9 +99,62 @@ export function inHoldout(anchorKey, now = Date.now()) { * moment the cost is knowable. This is the producer that makes the holdout * comparison a measurement rather than a subtraction of two zeroes. */ -export function recordRead(dir, { anchor, sessionId, bytes }) { +export function recordRead(dir, { anchor, sessionId, bytes, fp = null }) { if (!anchor || !bytes) return; - record(dir, { kind: 'read', anchor, sessionId, tokens: Math.ceil(bytes / 4) }); + record(dir, { + kind: 'read', + anchor, + sessionId, + tokens: Math.ceil(bytes / 4), + // THE CHANGE DETECTOR, recorded AT READ TIME. + // + // Without it, 'was this re-read wasteful' is undecidable. Measured before + // this field existed: 575 repeat reads of a file within one session, and + // only 99 could be classified -- 4,735 capture events carried anchors on + // just 122 of them, because most captures are bookkeeping calls that touch + // no file at all. The waste figure was 98% unknowable, and the 14.6M I + // first reported was really 213,651 confirmed plus a very large shrug. + // + // It belongs on the READ, not on a capture: the read already knows the + // anchor, the session and the cost, so the fingerprint completes the record + // rather than needing to be joined to another one. + fp, + }); +} + +/** + * A cheap fingerprint of a file's current content: size and mtime. + * + * NOT a content hash, deliberately. This runs on the PreToolUse path before + * every tool call, and hashing a file there would add a full read to the + * critical path for a measurement. `statSync` is already being done to resolve + * the operand, so this is free. + * + * WHAT IT CAN MISS: a write that leaves both size and mtime identical. That + * requires deliberately restoring the timestamp, so for the question being + * asked -- did this file change between two reads in one session -- it is + * sound. Stated here because a change-detector that silently misses changes + * would understate legitimate re-reads and overstate waste, which is the + * direction this project must never err in. + */ +export function fingerprint(path) { + try { + const st = statSync(path); + return `${st.size}:${Math.round(st.mtimeMs)}`; + } catch { + return null; + } +} + +/** + * A unique id per record. Counter plus randomness: the counter separates + * records written in the same millisecond by one process, the random suffix + * separates concurrent processes, which detached workers routinely are. + */ +let idCounter = 0; +function nextId() { + idCounter += 1; + return `${idCounter.toString(36)}-${randomBytes(4).toString('hex')}`; } export function record(dir, event) { @@ -80,7 +167,24 @@ export function record(dir, event) { } catch { // Not POSIX, or not ours to chmod; the write still proceeds. } - appendFileSync(metricsPath(dir), JSON.stringify({ ...event, at: Date.now() }) + '\n'); + // The CALLER'S timestamp wins when it supplied one. Overwriting it made + // `rereadWaste`'s ordering depend on write order rather than on `at`, so a + // test that set explicit times was passing by luck. + // + // `id` EXISTS SO DEDUPE IS EXACT. A record is written to both logs, so the + // reader has to drop one copy -- and it was matching on a composite of the + // fields, which cannot tell a duplicate from two genuinely distinct events + // that happen to look alike. Twenty-five identical injections written in a + // single millisecond collapsed to ONE, so a graph with ample data reported + // 'insufficient data (2 treated, 1 holdout)'. Real events were being + // discarded by the deduplicator, silently. + const line = + JSON.stringify({ id: nextId(), ...event, at: event.at ?? Date.now() }) + '\n'; + appendFileSync(metricsPath(dir), line); + // Balance-critical records go to their own log as well, so the windows on + // the firehose can never starve the measurement. Written SECOND: a torn + // write here costs a duplicate the reader dedupes, not a lost event. + if (BALANCE_KINDS.has(event.kind)) appendFileSync(balancePath(dir), line); } catch { // Metrics must never break a tool call. } @@ -110,7 +214,22 @@ export function readMetrics(dir) { return readAll(dir); } +/** + * How the last readAll truncated, if it did. + * + * Returned out of band rather than on the array, because callers pass the + * events around freely and a property hung on an array would be lost the first + * time anything filtered it -- which is exactly how `eventsTruncated` came to + * report only half the truth. + */ +let lastReadTruncation = { byBytes: false, byEvents: false }; + +export function readTruncation() { + return { ...lastReadTruncation }; +} + function readAll(dir) { + lastReadTruncation = { byBytes: false, byEvents: false }; const path = metricsPath(dir); if (!existsSync(path)) return []; @@ -132,13 +251,16 @@ function readAll(dir) { // The first line is almost certainly cut mid-record; drop it rather than // letting it fail to parse and look like corruption. text = text.slice(text.indexOf('\n') + 1); + lastReadTruncation.byBytes = true; } } catch { return []; } const out = []; - for (const line of text.split('\n').slice(-MAX_EVENTS)) { + const lines = text.split('\n'); + if (lines.length > MAX_EVENTS) lastReadTruncation.byEvents = true; + for (const line of lines.slice(-MAX_EVENTS)) { if (!line) continue; try { out.push(JSON.parse(line)); @@ -149,6 +271,323 @@ function readAll(dir) { return out; } +/** + * Balance records, read WITHOUT the event window that was starving them. + * + * Reads the dedicated log in full, and merges in whatever the firehose still + * holds so graphs that predate the split are not left unmeasurable. Duplicates + * are inevitable once both logs carry the same record, so they are removed on + * an identity built from the fields that make an event unique. + * + * The byte cap still applies to the dedicated log, but it means something very + * different here: these records are rare, so the cap is years of history rather + * than hours, and it drops BOTH arms proportionally when it finally bites. + */ +/** + * Every balance record in a file, with NO event window. + * + * The byte cap still bounds the read, because the firehose can be enormous. The + * event cap does not apply: it is what buried these records in the first place, + * and they are rare enough that keeping all of them inside the byte window costs + * nothing. + */ +function scanForBalance(path) { + if (!existsSync(path)) return []; + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + return []; + } + const out = []; + for (const line of text.split('\n')) { + if (!line) continue; + try { + const e = JSON.parse(line); + if (BALANCE_KINDS.has(e.kind)) out.push(e); + } catch { + /* a torn line costs a record, not the report */ + } + } + return out; +} + +export function readBalance(dir) { + const merged = []; + const path = balancePath(dir); + if (existsSync(path)) { + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + text = ''; + } + for (const line of text.split('\n')) { + if (!line) continue; + try { + merged.push(JSON.parse(line)); + } catch { + /* a torn line costs a record, not the report */ + } + } + } + + // MIGRATION, not a fallback. Every graph written before the split has its + // only copy of these records in the firehose; ignoring them would reset the + // measurement to zero on 122 existing graphs. + // + // IT MUST NOT GO THROUGH readAll. The first version of this fix did, and + // readAll applies the very event window that was starving the measurement -- + // so the migration inherited the bug it existed to repair and the real graphs + // still reported zero holdouts. Verified against them: unchanged at 0 until + // this scan stopped windowing. + for (const e of scanForBalance(metricsPath(dir))) merged.push(e); + + const seen = new Set(); + const out = []; + for (const e of merged) { + // The record's OWN id when it has one. The composite below is the legacy + // path for records written before ids existed; it is lossy by nature, which + // is precisely why new records carry an id instead. + const id = + e.id ?? [e.kind, e.at, e.anchor ?? '', e.sessionId ?? '', e.tokens ?? ''].join('|'); + if (seen.has(id)) continue; + seen.add(id); + out.push(e); + } + return out; +} + +/** + * Is this anchor a test fixture rather than real work? + * + * Not fussiness. Measured on this machine: 366 of 370 substitutions pointed at + * the enforcement suite's own big.ts fixture under a temp dir, and counting them made + * the product look like it had avoided 40 MB of reads. It had avoided 154 KB. + * A balance sheet that counts its own test suite as revenue is worse than none. + */ +export function isFixtureAnchor(anchor) { + const p = String(anchor || ''); + + // TWO CONDITIONS, BOTH REQUIRED. The previous version was a ternary chain in + // which every branch evaluated to `underTemp`, so the scratch test was dead + // code: it excluded ALL temp paths -- including a real project checked out + // under /tmp -- and on macOS excluded nothing at all, because tmpdir() there + // is /var/folders///T/ and did not match. + const underTemp = + new RegExp( + '[\\\\/](AppData[\\\\/]Local[\\\\/])?(Temp|tmp)[\\\\/]' + + '|[\\\\/]var[\\\\/]folders[\\\\/][^\\\\/]+[\\\\/][^\\\\/]+[\\\\/]T[\\\\/]', + 'i' + ).test(p); + if (!underTemp) return false; + + // Only names this suite actually creates. A user's own scratch checkout under + // a temp directory is real work and must still be counted. + return /(to-hooks-|ab-[a-z]+-|cooccur-|holdout-|reread-|feedback-e2e|standing-e2e|lesson-origin|archive-|gen-eol-|tear-|edge-src|fixture)/i.test( + p + ); +} + +/** + * The balance sheet, with every line labelled by HOW it is known. + * + * The shipped report counted every cost and one benefit that has never been + * computable, so it was negative by construction. These are the two things + * actually known, kept apart because they are known differently and must never + * be summed into a single hero number: + * + * MEASURED-COUNTERFACTUAL substitution. The file size is known exactly and + * the replacement's size is known exactly, so the + * saving is arithmetic -- resting on the one + * assumption that the model would have read what it + * explicitly asked for. + * ESTIMATED-CAUSAL findings injection, from the holdout. Genuinely + * causal when it has samples, and worth far less + * token-wise. + * + * Fixture anchors are excluded from both. + */ +/** + * Re-read waste, split into what is KNOWN and what is not. + * + * The question is narrow on purpose: how often does one session read the same + * file twice with the file UNCHANGED in between? That is waste the graph can + * remove, and it needs no holdout, no estimate and no join -- the reads carry + * their own fingerprints. + * + * A repeat read of a file that CHANGED is not waste and is reported as such. + * Conflating the two is how the first version of this measurement turned + * 213,651 confirmed tokens into a 14.6M headline. + * + * `undecidable` is reported rather than hidden. Reads written before the + * fingerprint existed cannot be classified, and a measurement that quietly + * counted them either way would be inventing its own answer. + */ +export function rereadWaste( + dir, + // `includeFixtures` exists so the suite can exercise this against files it + // creates under the temp directory -- which the fixture filter otherwise + // excludes by design, making the real path untestable. + { events = readMetrics(dir), includeFixtures = false } = {} +) { + const groups = new Map(); + for (const e of events) { + if (e.kind !== 'read' || !e.anchor) continue; + if (!includeFixtures && isFixtureAnchor(e.anchor)) continue; + const key = `${e.sessionId || ''}|${canonicalKeyish(e.anchor)}`; + if (!groups.has(key)) groups.set(key, []); + groups.get(key).push(e); + } + + const out = { + repeats: 0, + wasteful: 0, + wastefulTokens: 0, + legitimate: 0, + legitimateTokens: 0, + undecidable: 0, + undecidableTokens: 0, + }; + + for (const list of groups.values()) { + if (list.length < 2) continue; + list.sort((a, b) => (a.at || 0) - (b.at || 0)); + for (let i = 1; i < list.length; i++) { + const prev = list[i - 1]; + const cur = list[i]; + const tokens = cur.tokens || 0; + out.repeats += 1; + if (!prev.fp || !cur.fp) { + out.undecidable += 1; + out.undecidableTokens += tokens; + } else if (prev.fp === cur.fp) { + out.wasteful += 1; + out.wastefulTokens += tokens; + } else { + out.legitimate += 1; + out.legitimateTokens += tokens; + } + } + } + + const decided = out.wasteful + out.legitimate; + out.coverage = out.repeats ? decided / out.repeats : null; + return out; +} + +export function balanceSheet(dir) { + const balance = readBalance(dir).filter((e) => !isFixtureAnchor(e.anchor)); + const events = readMetrics(dir); + const truncation = readTruncation(); + + const subs = balance.filter((e) => e.kind === 'substitute'); + const served = subs.filter((e) => !e.holdout); + const withheldSubs = subs.filter((e) => e.holdout); + + // NET, not gross: the skeleton was still sent. + const netAvoided = served.reduce( + (sum, e) => + sum + + (e.tokensNetAvoided ?? + Math.max(0, Math.ceil((e.bytesAvoided || 0) / 4) - (e.tokens || 0))), + 0 + ); + const substitutionCost = served.reduce((sum, e) => sum + (e.tokens || 0), 0); + + const injectCost = balance + .filter((e) => e.kind === 'inject' && !e.holdout) + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const harvestCost = balance + .filter((e) => e.kind === 'harvest') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const standingCost = events + .filter((e) => e.kind === 'standing') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + + // RE-READS, decided by fingerprint rather than assumed. + const waste = rereadWaste(dir, { events }); + + return { + measuredCounterfactual: { + what: 'substitution: a skeleton sent instead of the file the model asked for', + substitutions: served.length, + withheld: withheldSubs.length, + tokensAvoidedNet: netAvoided, + tokensSpent: substitutionCost, + // THE CONTROL ARM'S ACTUAL COST. `tokensFullFile` was recorded and read + // by nothing, so the comparison the holdout exists for was not + // computable from the report. + controlArmTokens: withheldSubs.reduce((sum, e) => sum + (e.tokensFullFile || 0), 0), + assumption: 'that the model would have read the file it explicitly requested', + }, + estimatedCausal: { + what: 'findings injection, from the stratified holdout', + ...(() => { + const r = report(dir); + return { + treated: r.injections, + holdouts: r.holdouts, + tokensAvoided: r.estimatedTokensAvoided, + sufficientData: r.sufficientData, + verdict: r.verdict, + }; + })(), + }, + costs: { injection: injectCost, harvest: harvestCost, standing: standingCost, substitution: substitutionCost }, + waste, + // Deliberately NOT a single number. The two benefit lines are known + // differently; adding them would launder an assumption into a measurement. + // TWO WINDOWS, STATED RATHER THAN BLENDED. Balance records are read in + // full; everything derived from `events` sees only the tail of + // metrics.jsonl. Once that log rolls past its cap these cover different + // periods, and a reader has to be able to see that rather than assume one + // consistent balance. + windows: { + balance: 'all balance.jsonl records within the byte cap', + events: `tail of metrics.jsonl (<= ${MAX_BYTES} bytes, <= ${MAX_EVENTS} events)`, + // BOTH CAPS, from the reader itself. The previous flag tested the event + // count only, so a log truncated by the BYTE cap with fewer than + // MAX_EVENTS surviving records reported `false` -- the one case where the + // window silently covers a shorter period than the balance side. + eventsTruncated: truncation.byBytes || truncation.byEvents, + truncatedBy: truncation, + }, + note: 'benefit lines are reported separately by evidence strength and are never summed', + }; +} + +/** Cheap path normalisation for grouping reads; not the identity canonicaliser. */ +function canonicalKeyish(p) { + return String(p || '').replace(/\\/g, '/').toLowerCase(); +} + /** * The report. * @@ -159,8 +598,29 @@ function readAll(dir) { */ export function report(dir) { const events = readAll(dir); + // Injections and harvests come from the log that cannot be starved. + const balance = readBalance(dir); - const injections = events.filter((e) => e.kind === 'inject'); + // COMMAND INJECTIONS ARE COUNTED SEPARATELY, not mixed into the balance. + // + // The saving is measured by joining an injection to the READS of its anchor + // afterwards. A command injection's anchor is the command text, which no read + // event will ever match, so both arms would contribute zero downstream and + // every command record would pull both means toward zero -- diluting a real + // file-touch saving in proportion to how many commands ran. + // + // They still take part in the holdout, and are reported, because a structural + // exclusion is how 95 of 136 injections came to be unmeasurable. What is + // missing is a downstream join for them, and that is stated rather than + // papered over with a number. + const allInjections = balance.filter((e) => e.kind === 'inject'); + // `trigger` is the pre-`surface` spelling. Records written before the split + // carry it and no surface at all, so keying only on surface would silently + // file 95 historical command injections into the file-read balance -- exactly + // the dilution the split exists to prevent. + const isCommand = (e) => e.surface === 'command' || e.trigger === 'command'; + const commandInjections = allInjections.filter(isCommand); + const injections = allInjections.filter((e) => !isCommand(e)); const treated = injections.filter((e) => !e.holdout); const withheld = injections.filter((e) => e.holdout); @@ -168,7 +628,7 @@ export function report(dir) { rows.length ? rows.reduce((sum, r) => sum + (r[field] || 0), 0) / rows.length : 0; const injectedTokens = treated.reduce((sum, e) => sum + (e.tokens || 0), 0); - const harvestTokens = events + const harvestTokens = balance .filter((e) => e.kind === 'harvest') .reduce((sum, e) => sum + (e.tokens || 0), 0); @@ -238,6 +698,8 @@ export function report(dir) { return { injections: treated.length, + commandInjections: commandInjections.length, + commandHoldouts: commandInjections.filter((e) => e.holdout).length, holdouts: withheld.length, staleServed: injections.filter((e) => e.stale).length, staleRate: injections.length ? injections.filter((e) => e.stale).length / injections.length : 0, diff --git a/integrations/opencode/opencode.json b/integrations/opencode/opencode.json index dd99ecaca..ff6316d0c 100644 --- a/integrations/opencode/opencode.json +++ b/integrations/opencode/opencode.json @@ -3,7 +3,7 @@ "mcp": { "token-optimizer": { "type": "local", - "command": ["npx", "-y", "@ooples/token-optimizer-mcp@5.3.6"], + "command": ["npx", "-y", "@ooples/token-optimizer-mcp@5.4.0"], "enabled": true } }, diff --git a/integrations/qwen/hooks/lib/fleet.mjs b/integrations/qwen/hooks/lib/fleet.mjs index 68da2228b..5bb953b51 100644 --- a/integrations/qwen/hooks/lib/fleet.mjs +++ b/integrations/qwen/hooks/lib/fleet.mjs @@ -38,7 +38,7 @@ import { createHash } from 'node:crypto'; import { readFileSync, readdirSync, statSync, existsSync, openSync, readSync, closeSync } from 'node:fs'; import { join, basename } from 'node:path'; import { homedir } from 'node:os'; -import { readMetrics } from './metrics.mjs'; +import { readMetrics, balanceSheet } from './metrics.mjs'; import { cacheHealth, readCacheUsage } from './cache.mjs'; import { activeRules } from './remedy.mjs'; import { monthly, money, priceNote } from './pricing.mjs'; @@ -166,6 +166,15 @@ const sha256 = (path) => { * exists where a refusal actually replaced a read, so its presence is evidence * that the veto is live in that project rather than that a config file says so. */ +/** Never let a malformed log take down a fleet scan. */ +function safeBalance(dir) { + try { + return balanceSheet(dir); + } catch { + return null; + } +} + export function scanProject(project) { const dir = project.cwd ? wikiDir(project.cwd) : null; const events = dir && existsSync(dir) ? readMetrics(dir) : []; @@ -188,6 +197,14 @@ export function scanProject(project) { perRead: reads.length ? Math.round(tokens / reads.length) : null, enforcing: substitutions > 0, substitutions, + // THE BALANCE, PER PROJECT, LABELLED BY HOW EACH LINE IS KNOWN. + // + // The fleet view is where 'is this paying for itself' is actually asked, + // and it had only raw counts to answer with. The two benefit lines stay + // separate here as everywhere else: one is arithmetic on known file sizes, + // the other is a causal estimate from the holdout, and summing them would + // launder an assumption into a measurement. + balance: dir && existsSync(dir) ? safeBalance(dir) : null, anchors: [...new Set(reads.map((r) => r.anchor).filter(Boolean))], rules: dir ? activeRules(dir) : [], cache: project.transcript ? cacheHealth(readCacheUsage(project.transcript)) : null, diff --git a/integrations/qwen/hooks/lib/inject.mjs b/integrations/qwen/hooks/lib/inject.mjs index 21606f1c0..022b7de0d 100644 --- a/integrations/qwen/hooks/lib/inject.mjs +++ b/integrations/qwen/hooks/lib/inject.mjs @@ -45,6 +45,21 @@ const touchBudget = () => Number(process.env.TOKEN_OPTIMIZER_TOUCH_BUDGET) || 50 const standingBudget = () => Number(process.env.TOKEN_OPTIMIZER_STANDING_BUDGET) || 400; +/** + * The stratification key for a command. + * + * Normalised so that the same intent lands in the same arm: trailing + * whitespace and a differing set of paths should not flip a command between + * treated and withheld, because that is what makes the two arms comparable. + */ +function commandKey(command) { + return String(command || '') + .trim() + .replace(/\s+/g, ' ') + .slice(0, 120) + .toLowerCase(); +} + /** Most findings considered for one command before the budget decides. */ const MAX_COMMAND_CANDIDATES = 20; @@ -133,12 +148,18 @@ export function forTouch( .filter((f) => !alreadyInjected.has(f.key)); if (!candidates.length) return null; + // STRATIFIED BY FILE AND EPOCH, which is the documented design here: the + // same file lands in the holdout during some epochs and the treated arm in + // others, so the comparison becomes within-file and the dominant source of + // variance drops out. A session-pinned arm would destroy that. const holdout = inHoldout(filePath); const served = serve(graph, candidates); const { kept, spent } = fit(served, budget); record(dir, { kind: 'inject', + // The surface whose saving CAN be measured: reads of this anchor afterwards. + surface: 'file', anchor: filePath, holdout, tokens: holdout ? 0 : spent, @@ -147,10 +168,17 @@ export function forTouch( sessionId, }); - if (holdout || !kept.length) return null; - + // MARKED SEEN IN BOTH ARMS, for the same reason as the command path: a file + // touched repeatedly -- the normal shape of working on it -- would otherwise + // write a fresh holdout row every time while a treated file was suppressed + // after its first delivery. The report counts rows, so the control arm would + // grow faster purely from repetition. + // + // This is the identical defect that was fixed in `forCommand` and not here. for (const f of kept) alreadyInjected.add(f.key); + if (holdout || !kept.length) return null; + return `Known about ${filePath} (from previous sessions):\n${kept.map(render).join('\n')}`; } @@ -295,19 +323,46 @@ export function forCommand( const { kept, spent } = fit(served, budget); if (!kept.length) return null; + // THE COMMAND PATH TAKES PART IN THE HOLDOUT TOO. + // + // `holdout: false` was hardcoded here, so 95 of 136 injections measured on a + // real machine were structurally excluded from the only mechanism that can + // establish causation. Seventy per cent of what the feature does could never + // be shown to help or hurt. + // + // Stratified on the COMMAND rather than a file, by the same (key, epoch) + // hash: the same command lands in the same arm all session, so a command run + // repeatedly cannot straddle both arms and contaminate each. + const key = commandKey(command); + const holdout = inHoldout(key); + record(dir, { kind: 'inject', trigger: 'command', + // The surface the report needs to keep these OUT of the file-read balance: + // a command has no anchor that read events can be joined to. + surface: 'command', anchor: String(command).slice(0, 120), - holdout: false, - tokens: spent, - count: kept.length, + holdout, + tokens: holdout ? 0 : spent, + count: holdout ? 0 : kept.length, stale: kept.some((f) => f.stale), sessionId, }); + // MARKED SEEN IN BOTH ARMS. + // + // The held branch used to return before updating the gate, so a command run + // repeatedly wrote a fresh holdout row every time while a treated command was + // filtered after its first delivery. The report counts rows, so the holdout + // arm was systematically overweighted -- a bias in the very comparison this + // exists to make. for (const f of kept) alreadyInjected.add(f.key); + // Withheld means withheld. Returning the text anyway would record an arm the + // subject never actually experienced. + if (holdout) return null; + return `Before running this — known from previous sessions:\n${kept .map(render) .join('\n')}`; @@ -477,7 +532,7 @@ export function standingRules(dir, graph, { budget = standingBudget() } = {}) { * informative response available -- more useful than the file, not a lossier * version of it. */ -export function substitutionFor(dir, graph, rawPath, source) { +export function substitutionFor(dir, graph, rawPath, source, { sessionId } = {}) { const filePath = canonicalPath(rawPath); const budget = substitutionBudget(dir, filePath); const built = annotatedSkeleton(graph, rawPath, source, { budget }); @@ -486,15 +541,50 @@ export function substitutionFor(dir, graph, rawPath, source) { // costs the model a round trip; send it back to the ordinary redirect. if (built.tokens * 4 > source.length * 0.5) return null; + // THE HOLDOUT BELONGS ON THIS PATH, not only on findings injection. + // + // Substitution is the lever that actually moves tokens -- it replaces a whole + // file with a skeleton -- and it had no control arm at all, while the 10% + // holdout sat on findings injection, which is two orders of magnitude + // smaller. Withholding here serves the file the model asked for and records + // what that cost, which is the only way the saving stops being an assumption. + // PINNED FOR THE SESSION, with a fixed epoch. + // + // Unlike the file-touch arm above, this one must not rotate: a session + // running across midnight would substitute for a file in one half and serve + // the whole file in the other, so `measuredCounterfactual` would mix treated + // and control observations for the same file. + // + // Keying on the session alone was not enough -- with the epoch still in play + // the arm flipped 104 times in 400 simulated midnight crossings. The session + // id already provides the rotation the epoch was there for. + const holdout = inHoldout(`${sessionId || ''}|${filePath}`, 0); + record(dir, { kind: 'substitute', anchor: filePath, - tokens: built.tokens, + // Recorded so provenance is checkable. Without it, 366 of 370 substitutions + // on this machine turned out to be the enforcement suite's own fixture and + // nothing distinguished them from real work. + sessionId, + holdout, + tokens: holdout ? 0 : built.tokens, findings: built.findings, symbols: built.symbols, - bytesAvoided: source.length, + // GROSS, kept for continuity with existing records. + bytesAvoided: holdout ? 0 : source.length, + // NET, which is the honest figure: the skeleton was still sent. Reporting + // the whole file as avoided while spending `tokens` on a replacement + // overstates the saving by exactly the size of the replacement. + tokensNetAvoided: holdout ? 0 : Math.max(0, Math.ceil(source.length / 4) - built.tokens), + // What the control arm actually paid, so the two arms are comparable. + tokensFullFile: Math.ceil(source.length / 4), }); + // Withheld means the model gets what it asked for: the whole file. That is + // the control arm, and it must really be paid or the comparison is fiction. + if (holdout) return null; + return built.text; } diff --git a/integrations/qwen/hooks/lib/metrics.mjs b/integrations/qwen/hooks/lib/metrics.mjs index 0df6ee24a..3fc52e22b 100644 --- a/integrations/qwen/hooks/lib/metrics.mjs +++ b/integrations/qwen/hooks/lib/metrics.mjs @@ -23,7 +23,7 @@ import { statSync, openSync, readSync, closeSync, } from 'node:fs'; import { join } from 'node:path'; -import { createHash } from 'node:crypto'; +import { createHash, randomBytes } from 'node:crypto'; /** * Read per call, not once at module load. @@ -43,6 +43,28 @@ const EPOCH_MS = 86_400_000; const metricsPath = (dir) => join(dir, 'metrics.jsonl'); +/** + * The balance log: `inject` and `harvest` only. + * + * WHY A SECOND FILE. The event window is measured in EVENTS, and injections are + * a tiny minority of them -- 136 injections against 6,725 captures across every + * graph on one machine. So the last 5,000 events are almost entirely captures + * and reads, and the injections that carry the measurement age out first. + * + * Measured on this repository before the fix: 44 inject records in the file, 9 + * of them holdout, all at lines 60-76 of 9,058 -- every single one outside the + * window. `report()` therefore said "0 holdout" while the file plainly + * contained nine, and the net balance was uncomputable on all 122 graphs. + * + * A separate log fixes it structurally rather than by enlarging a number. + * These records are rare, so the file stays small for years, and a tail window + * on it drops BOTH arms proportionally instead of starving the rare one. + */ +const balancePath = (dir) => join(dir, 'balance.jsonl'); + +/** Kinds the net balance is computed from, and which therefore must survive. */ +const BALANCE_KINDS = new Set(['inject', 'harvest', 'substitute']); + /** * Is this touch in the holdout arm? * @@ -54,7 +76,19 @@ export function inHoldout(anchorKey, now = Date.now()) { const fraction = holdoutFraction(); if (fraction <= 0) return false; const epoch = Math.floor(now / EPOCH_MS); - const digest = createHash('sha1').update(`${anchorKey}:${epoch}`).digest(); + // SHA-256, NOT SHA-1. + // + // This is a bucketing hash, not a security primitive -- nothing is kept + // secret and nothing is authenticated, only spread evenly across two arms. + // But CodeQL flags sha1 as a weak algorithm, seven high-severity alerts + // across the core and its six vendored copies, and arguing that a finding is + // benign is a worse habit than paying a cost that rounds to nothing here. + // Both are deterministic, which is the only property this depends on. + // + // The change DOES reassign arms: a given (anchor, epoch) may land on the + // other side than before. With nine holdout records in existence that costs + // nothing, and stratification is a fresh draw either way. + const digest = createHash('sha256').update(`${anchorKey}:${epoch}`).digest(); return (digest[0] / 256) < fraction; } @@ -65,9 +99,62 @@ export function inHoldout(anchorKey, now = Date.now()) { * moment the cost is knowable. This is the producer that makes the holdout * comparison a measurement rather than a subtraction of two zeroes. */ -export function recordRead(dir, { anchor, sessionId, bytes }) { +export function recordRead(dir, { anchor, sessionId, bytes, fp = null }) { if (!anchor || !bytes) return; - record(dir, { kind: 'read', anchor, sessionId, tokens: Math.ceil(bytes / 4) }); + record(dir, { + kind: 'read', + anchor, + sessionId, + tokens: Math.ceil(bytes / 4), + // THE CHANGE DETECTOR, recorded AT READ TIME. + // + // Without it, 'was this re-read wasteful' is undecidable. Measured before + // this field existed: 575 repeat reads of a file within one session, and + // only 99 could be classified -- 4,735 capture events carried anchors on + // just 122 of them, because most captures are bookkeeping calls that touch + // no file at all. The waste figure was 98% unknowable, and the 14.6M I + // first reported was really 213,651 confirmed plus a very large shrug. + // + // It belongs on the READ, not on a capture: the read already knows the + // anchor, the session and the cost, so the fingerprint completes the record + // rather than needing to be joined to another one. + fp, + }); +} + +/** + * A cheap fingerprint of a file's current content: size and mtime. + * + * NOT a content hash, deliberately. This runs on the PreToolUse path before + * every tool call, and hashing a file there would add a full read to the + * critical path for a measurement. `statSync` is already being done to resolve + * the operand, so this is free. + * + * WHAT IT CAN MISS: a write that leaves both size and mtime identical. That + * requires deliberately restoring the timestamp, so for the question being + * asked -- did this file change between two reads in one session -- it is + * sound. Stated here because a change-detector that silently misses changes + * would understate legitimate re-reads and overstate waste, which is the + * direction this project must never err in. + */ +export function fingerprint(path) { + try { + const st = statSync(path); + return `${st.size}:${Math.round(st.mtimeMs)}`; + } catch { + return null; + } +} + +/** + * A unique id per record. Counter plus randomness: the counter separates + * records written in the same millisecond by one process, the random suffix + * separates concurrent processes, which detached workers routinely are. + */ +let idCounter = 0; +function nextId() { + idCounter += 1; + return `${idCounter.toString(36)}-${randomBytes(4).toString('hex')}`; } export function record(dir, event) { @@ -80,7 +167,24 @@ export function record(dir, event) { } catch { // Not POSIX, or not ours to chmod; the write still proceeds. } - appendFileSync(metricsPath(dir), JSON.stringify({ ...event, at: Date.now() }) + '\n'); + // The CALLER'S timestamp wins when it supplied one. Overwriting it made + // `rereadWaste`'s ordering depend on write order rather than on `at`, so a + // test that set explicit times was passing by luck. + // + // `id` EXISTS SO DEDUPE IS EXACT. A record is written to both logs, so the + // reader has to drop one copy -- and it was matching on a composite of the + // fields, which cannot tell a duplicate from two genuinely distinct events + // that happen to look alike. Twenty-five identical injections written in a + // single millisecond collapsed to ONE, so a graph with ample data reported + // 'insufficient data (2 treated, 1 holdout)'. Real events were being + // discarded by the deduplicator, silently. + const line = + JSON.stringify({ id: nextId(), ...event, at: event.at ?? Date.now() }) + '\n'; + appendFileSync(metricsPath(dir), line); + // Balance-critical records go to their own log as well, so the windows on + // the firehose can never starve the measurement. Written SECOND: a torn + // write here costs a duplicate the reader dedupes, not a lost event. + if (BALANCE_KINDS.has(event.kind)) appendFileSync(balancePath(dir), line); } catch { // Metrics must never break a tool call. } @@ -110,7 +214,22 @@ export function readMetrics(dir) { return readAll(dir); } +/** + * How the last readAll truncated, if it did. + * + * Returned out of band rather than on the array, because callers pass the + * events around freely and a property hung on an array would be lost the first + * time anything filtered it -- which is exactly how `eventsTruncated` came to + * report only half the truth. + */ +let lastReadTruncation = { byBytes: false, byEvents: false }; + +export function readTruncation() { + return { ...lastReadTruncation }; +} + function readAll(dir) { + lastReadTruncation = { byBytes: false, byEvents: false }; const path = metricsPath(dir); if (!existsSync(path)) return []; @@ -132,13 +251,16 @@ function readAll(dir) { // The first line is almost certainly cut mid-record; drop it rather than // letting it fail to parse and look like corruption. text = text.slice(text.indexOf('\n') + 1); + lastReadTruncation.byBytes = true; } } catch { return []; } const out = []; - for (const line of text.split('\n').slice(-MAX_EVENTS)) { + const lines = text.split('\n'); + if (lines.length > MAX_EVENTS) lastReadTruncation.byEvents = true; + for (const line of lines.slice(-MAX_EVENTS)) { if (!line) continue; try { out.push(JSON.parse(line)); @@ -149,6 +271,323 @@ function readAll(dir) { return out; } +/** + * Balance records, read WITHOUT the event window that was starving them. + * + * Reads the dedicated log in full, and merges in whatever the firehose still + * holds so graphs that predate the split are not left unmeasurable. Duplicates + * are inevitable once both logs carry the same record, so they are removed on + * an identity built from the fields that make an event unique. + * + * The byte cap still applies to the dedicated log, but it means something very + * different here: these records are rare, so the cap is years of history rather + * than hours, and it drops BOTH arms proportionally when it finally bites. + */ +/** + * Every balance record in a file, with NO event window. + * + * The byte cap still bounds the read, because the firehose can be enormous. The + * event cap does not apply: it is what buried these records in the first place, + * and they are rare enough that keeping all of them inside the byte window costs + * nothing. + */ +function scanForBalance(path) { + if (!existsSync(path)) return []; + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + return []; + } + const out = []; + for (const line of text.split('\n')) { + if (!line) continue; + try { + const e = JSON.parse(line); + if (BALANCE_KINDS.has(e.kind)) out.push(e); + } catch { + /* a torn line costs a record, not the report */ + } + } + return out; +} + +export function readBalance(dir) { + const merged = []; + const path = balancePath(dir); + if (existsSync(path)) { + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + text = ''; + } + for (const line of text.split('\n')) { + if (!line) continue; + try { + merged.push(JSON.parse(line)); + } catch { + /* a torn line costs a record, not the report */ + } + } + } + + // MIGRATION, not a fallback. Every graph written before the split has its + // only copy of these records in the firehose; ignoring them would reset the + // measurement to zero on 122 existing graphs. + // + // IT MUST NOT GO THROUGH readAll. The first version of this fix did, and + // readAll applies the very event window that was starving the measurement -- + // so the migration inherited the bug it existed to repair and the real graphs + // still reported zero holdouts. Verified against them: unchanged at 0 until + // this scan stopped windowing. + for (const e of scanForBalance(metricsPath(dir))) merged.push(e); + + const seen = new Set(); + const out = []; + for (const e of merged) { + // The record's OWN id when it has one. The composite below is the legacy + // path for records written before ids existed; it is lossy by nature, which + // is precisely why new records carry an id instead. + const id = + e.id ?? [e.kind, e.at, e.anchor ?? '', e.sessionId ?? '', e.tokens ?? ''].join('|'); + if (seen.has(id)) continue; + seen.add(id); + out.push(e); + } + return out; +} + +/** + * Is this anchor a test fixture rather than real work? + * + * Not fussiness. Measured on this machine: 366 of 370 substitutions pointed at + * the enforcement suite's own big.ts fixture under a temp dir, and counting them made + * the product look like it had avoided 40 MB of reads. It had avoided 154 KB. + * A balance sheet that counts its own test suite as revenue is worse than none. + */ +export function isFixtureAnchor(anchor) { + const p = String(anchor || ''); + + // TWO CONDITIONS, BOTH REQUIRED. The previous version was a ternary chain in + // which every branch evaluated to `underTemp`, so the scratch test was dead + // code: it excluded ALL temp paths -- including a real project checked out + // under /tmp -- and on macOS excluded nothing at all, because tmpdir() there + // is /var/folders///T/ and did not match. + const underTemp = + new RegExp( + '[\\\\/](AppData[\\\\/]Local[\\\\/])?(Temp|tmp)[\\\\/]' + + '|[\\\\/]var[\\\\/]folders[\\\\/][^\\\\/]+[\\\\/][^\\\\/]+[\\\\/]T[\\\\/]', + 'i' + ).test(p); + if (!underTemp) return false; + + // Only names this suite actually creates. A user's own scratch checkout under + // a temp directory is real work and must still be counted. + return /(to-hooks-|ab-[a-z]+-|cooccur-|holdout-|reread-|feedback-e2e|standing-e2e|lesson-origin|archive-|gen-eol-|tear-|edge-src|fixture)/i.test( + p + ); +} + +/** + * The balance sheet, with every line labelled by HOW it is known. + * + * The shipped report counted every cost and one benefit that has never been + * computable, so it was negative by construction. These are the two things + * actually known, kept apart because they are known differently and must never + * be summed into a single hero number: + * + * MEASURED-COUNTERFACTUAL substitution. The file size is known exactly and + * the replacement's size is known exactly, so the + * saving is arithmetic -- resting on the one + * assumption that the model would have read what it + * explicitly asked for. + * ESTIMATED-CAUSAL findings injection, from the holdout. Genuinely + * causal when it has samples, and worth far less + * token-wise. + * + * Fixture anchors are excluded from both. + */ +/** + * Re-read waste, split into what is KNOWN and what is not. + * + * The question is narrow on purpose: how often does one session read the same + * file twice with the file UNCHANGED in between? That is waste the graph can + * remove, and it needs no holdout, no estimate and no join -- the reads carry + * their own fingerprints. + * + * A repeat read of a file that CHANGED is not waste and is reported as such. + * Conflating the two is how the first version of this measurement turned + * 213,651 confirmed tokens into a 14.6M headline. + * + * `undecidable` is reported rather than hidden. Reads written before the + * fingerprint existed cannot be classified, and a measurement that quietly + * counted them either way would be inventing its own answer. + */ +export function rereadWaste( + dir, + // `includeFixtures` exists so the suite can exercise this against files it + // creates under the temp directory -- which the fixture filter otherwise + // excludes by design, making the real path untestable. + { events = readMetrics(dir), includeFixtures = false } = {} +) { + const groups = new Map(); + for (const e of events) { + if (e.kind !== 'read' || !e.anchor) continue; + if (!includeFixtures && isFixtureAnchor(e.anchor)) continue; + const key = `${e.sessionId || ''}|${canonicalKeyish(e.anchor)}`; + if (!groups.has(key)) groups.set(key, []); + groups.get(key).push(e); + } + + const out = { + repeats: 0, + wasteful: 0, + wastefulTokens: 0, + legitimate: 0, + legitimateTokens: 0, + undecidable: 0, + undecidableTokens: 0, + }; + + for (const list of groups.values()) { + if (list.length < 2) continue; + list.sort((a, b) => (a.at || 0) - (b.at || 0)); + for (let i = 1; i < list.length; i++) { + const prev = list[i - 1]; + const cur = list[i]; + const tokens = cur.tokens || 0; + out.repeats += 1; + if (!prev.fp || !cur.fp) { + out.undecidable += 1; + out.undecidableTokens += tokens; + } else if (prev.fp === cur.fp) { + out.wasteful += 1; + out.wastefulTokens += tokens; + } else { + out.legitimate += 1; + out.legitimateTokens += tokens; + } + } + } + + const decided = out.wasteful + out.legitimate; + out.coverage = out.repeats ? decided / out.repeats : null; + return out; +} + +export function balanceSheet(dir) { + const balance = readBalance(dir).filter((e) => !isFixtureAnchor(e.anchor)); + const events = readMetrics(dir); + const truncation = readTruncation(); + + const subs = balance.filter((e) => e.kind === 'substitute'); + const served = subs.filter((e) => !e.holdout); + const withheldSubs = subs.filter((e) => e.holdout); + + // NET, not gross: the skeleton was still sent. + const netAvoided = served.reduce( + (sum, e) => + sum + + (e.tokensNetAvoided ?? + Math.max(0, Math.ceil((e.bytesAvoided || 0) / 4) - (e.tokens || 0))), + 0 + ); + const substitutionCost = served.reduce((sum, e) => sum + (e.tokens || 0), 0); + + const injectCost = balance + .filter((e) => e.kind === 'inject' && !e.holdout) + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const harvestCost = balance + .filter((e) => e.kind === 'harvest') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const standingCost = events + .filter((e) => e.kind === 'standing') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + + // RE-READS, decided by fingerprint rather than assumed. + const waste = rereadWaste(dir, { events }); + + return { + measuredCounterfactual: { + what: 'substitution: a skeleton sent instead of the file the model asked for', + substitutions: served.length, + withheld: withheldSubs.length, + tokensAvoidedNet: netAvoided, + tokensSpent: substitutionCost, + // THE CONTROL ARM'S ACTUAL COST. `tokensFullFile` was recorded and read + // by nothing, so the comparison the holdout exists for was not + // computable from the report. + controlArmTokens: withheldSubs.reduce((sum, e) => sum + (e.tokensFullFile || 0), 0), + assumption: 'that the model would have read the file it explicitly requested', + }, + estimatedCausal: { + what: 'findings injection, from the stratified holdout', + ...(() => { + const r = report(dir); + return { + treated: r.injections, + holdouts: r.holdouts, + tokensAvoided: r.estimatedTokensAvoided, + sufficientData: r.sufficientData, + verdict: r.verdict, + }; + })(), + }, + costs: { injection: injectCost, harvest: harvestCost, standing: standingCost, substitution: substitutionCost }, + waste, + // Deliberately NOT a single number. The two benefit lines are known + // differently; adding them would launder an assumption into a measurement. + // TWO WINDOWS, STATED RATHER THAN BLENDED. Balance records are read in + // full; everything derived from `events` sees only the tail of + // metrics.jsonl. Once that log rolls past its cap these cover different + // periods, and a reader has to be able to see that rather than assume one + // consistent balance. + windows: { + balance: 'all balance.jsonl records within the byte cap', + events: `tail of metrics.jsonl (<= ${MAX_BYTES} bytes, <= ${MAX_EVENTS} events)`, + // BOTH CAPS, from the reader itself. The previous flag tested the event + // count only, so a log truncated by the BYTE cap with fewer than + // MAX_EVENTS surviving records reported `false` -- the one case where the + // window silently covers a shorter period than the balance side. + eventsTruncated: truncation.byBytes || truncation.byEvents, + truncatedBy: truncation, + }, + note: 'benefit lines are reported separately by evidence strength and are never summed', + }; +} + +/** Cheap path normalisation for grouping reads; not the identity canonicaliser. */ +function canonicalKeyish(p) { + return String(p || '').replace(/\\/g, '/').toLowerCase(); +} + /** * The report. * @@ -159,8 +598,29 @@ function readAll(dir) { */ export function report(dir) { const events = readAll(dir); + // Injections and harvests come from the log that cannot be starved. + const balance = readBalance(dir); - const injections = events.filter((e) => e.kind === 'inject'); + // COMMAND INJECTIONS ARE COUNTED SEPARATELY, not mixed into the balance. + // + // The saving is measured by joining an injection to the READS of its anchor + // afterwards. A command injection's anchor is the command text, which no read + // event will ever match, so both arms would contribute zero downstream and + // every command record would pull both means toward zero -- diluting a real + // file-touch saving in proportion to how many commands ran. + // + // They still take part in the holdout, and are reported, because a structural + // exclusion is how 95 of 136 injections came to be unmeasurable. What is + // missing is a downstream join for them, and that is stated rather than + // papered over with a number. + const allInjections = balance.filter((e) => e.kind === 'inject'); + // `trigger` is the pre-`surface` spelling. Records written before the split + // carry it and no surface at all, so keying only on surface would silently + // file 95 historical command injections into the file-read balance -- exactly + // the dilution the split exists to prevent. + const isCommand = (e) => e.surface === 'command' || e.trigger === 'command'; + const commandInjections = allInjections.filter(isCommand); + const injections = allInjections.filter((e) => !isCommand(e)); const treated = injections.filter((e) => !e.holdout); const withheld = injections.filter((e) => e.holdout); @@ -168,7 +628,7 @@ export function report(dir) { rows.length ? rows.reduce((sum, r) => sum + (r[field] || 0), 0) / rows.length : 0; const injectedTokens = treated.reduce((sum, e) => sum + (e.tokens || 0), 0); - const harvestTokens = events + const harvestTokens = balance .filter((e) => e.kind === 'harvest') .reduce((sum, e) => sum + (e.tokens || 0), 0); @@ -238,6 +698,8 @@ export function report(dir) { return { injections: treated.length, + commandInjections: commandInjections.length, + commandHoldouts: commandInjections.filter((e) => e.holdout).length, holdouts: withheld.length, staleServed: injections.filter((e) => e.stale).length, staleRate: injections.length ? injections.filter((e) => e.stale).length / injections.length : 0, diff --git a/integrations/roo/mcp.json b/integrations/roo/mcp.json index d254a4f5d..9f0fa99ec 100644 --- a/integrations/roo/mcp.json +++ b/integrations/roo/mcp.json @@ -4,7 +4,7 @@ "command": "npx", "args": [ "-y", - "@ooples/token-optimizer-mcp@5.3.6" + "@ooples/token-optimizer-mcp@5.4.0" ], "env": {} } diff --git a/integrations/windsurf/mcp_config.json b/integrations/windsurf/mcp_config.json index d254a4f5d..9f0fa99ec 100644 --- a/integrations/windsurf/mcp_config.json +++ b/integrations/windsurf/mcp_config.json @@ -4,7 +4,7 @@ "command": "npx", "args": [ "-y", - "@ooples/token-optimizer-mcp@5.3.6" + "@ooples/token-optimizer-mcp@5.4.0" ], "env": {} } diff --git a/integrations/zed/settings.json b/integrations/zed/settings.json index 8365d27e4..82e71de97 100644 --- a/integrations/zed/settings.json +++ b/integrations/zed/settings.json @@ -4,7 +4,7 @@ "command": "npx", "args": [ "-y", - "@ooples/token-optimizer-mcp@5.3.6" + "@ooples/token-optimizer-mcp@5.4.0" ], "env": {} } diff --git a/plugin/.mcp.json b/plugin/.mcp.json index 5aab11c8b..f55ca5dfb 100644 --- a/plugin/.mcp.json +++ b/plugin/.mcp.json @@ -2,7 +2,7 @@ "mcpServers": { "token-optimizer": { "command": "npx", - "args": ["-y", "@ooples/token-optimizer-mcp@5.3.6"], + "args": ["-y", "@ooples/token-optimizer-mcp@5.4.0"], "env": {} } } diff --git a/plugin/hooks/lib/fleet.mjs b/plugin/hooks/lib/fleet.mjs index 68da2228b..5bb953b51 100644 --- a/plugin/hooks/lib/fleet.mjs +++ b/plugin/hooks/lib/fleet.mjs @@ -38,7 +38,7 @@ import { createHash } from 'node:crypto'; import { readFileSync, readdirSync, statSync, existsSync, openSync, readSync, closeSync } from 'node:fs'; import { join, basename } from 'node:path'; import { homedir } from 'node:os'; -import { readMetrics } from './metrics.mjs'; +import { readMetrics, balanceSheet } from './metrics.mjs'; import { cacheHealth, readCacheUsage } from './cache.mjs'; import { activeRules } from './remedy.mjs'; import { monthly, money, priceNote } from './pricing.mjs'; @@ -166,6 +166,15 @@ const sha256 = (path) => { * exists where a refusal actually replaced a read, so its presence is evidence * that the veto is live in that project rather than that a config file says so. */ +/** Never let a malformed log take down a fleet scan. */ +function safeBalance(dir) { + try { + return balanceSheet(dir); + } catch { + return null; + } +} + export function scanProject(project) { const dir = project.cwd ? wikiDir(project.cwd) : null; const events = dir && existsSync(dir) ? readMetrics(dir) : []; @@ -188,6 +197,14 @@ export function scanProject(project) { perRead: reads.length ? Math.round(tokens / reads.length) : null, enforcing: substitutions > 0, substitutions, + // THE BALANCE, PER PROJECT, LABELLED BY HOW EACH LINE IS KNOWN. + // + // The fleet view is where 'is this paying for itself' is actually asked, + // and it had only raw counts to answer with. The two benefit lines stay + // separate here as everywhere else: one is arithmetic on known file sizes, + // the other is a causal estimate from the holdout, and summing them would + // launder an assumption into a measurement. + balance: dir && existsSync(dir) ? safeBalance(dir) : null, anchors: [...new Set(reads.map((r) => r.anchor).filter(Boolean))], rules: dir ? activeRules(dir) : [], cache: project.transcript ? cacheHealth(readCacheUsage(project.transcript)) : null, diff --git a/plugin/hooks/lib/inject.mjs b/plugin/hooks/lib/inject.mjs index 21606f1c0..022b7de0d 100644 --- a/plugin/hooks/lib/inject.mjs +++ b/plugin/hooks/lib/inject.mjs @@ -45,6 +45,21 @@ const touchBudget = () => Number(process.env.TOKEN_OPTIMIZER_TOUCH_BUDGET) || 50 const standingBudget = () => Number(process.env.TOKEN_OPTIMIZER_STANDING_BUDGET) || 400; +/** + * The stratification key for a command. + * + * Normalised so that the same intent lands in the same arm: trailing + * whitespace and a differing set of paths should not flip a command between + * treated and withheld, because that is what makes the two arms comparable. + */ +function commandKey(command) { + return String(command || '') + .trim() + .replace(/\s+/g, ' ') + .slice(0, 120) + .toLowerCase(); +} + /** Most findings considered for one command before the budget decides. */ const MAX_COMMAND_CANDIDATES = 20; @@ -133,12 +148,18 @@ export function forTouch( .filter((f) => !alreadyInjected.has(f.key)); if (!candidates.length) return null; + // STRATIFIED BY FILE AND EPOCH, which is the documented design here: the + // same file lands in the holdout during some epochs and the treated arm in + // others, so the comparison becomes within-file and the dominant source of + // variance drops out. A session-pinned arm would destroy that. const holdout = inHoldout(filePath); const served = serve(graph, candidates); const { kept, spent } = fit(served, budget); record(dir, { kind: 'inject', + // The surface whose saving CAN be measured: reads of this anchor afterwards. + surface: 'file', anchor: filePath, holdout, tokens: holdout ? 0 : spent, @@ -147,10 +168,17 @@ export function forTouch( sessionId, }); - if (holdout || !kept.length) return null; - + // MARKED SEEN IN BOTH ARMS, for the same reason as the command path: a file + // touched repeatedly -- the normal shape of working on it -- would otherwise + // write a fresh holdout row every time while a treated file was suppressed + // after its first delivery. The report counts rows, so the control arm would + // grow faster purely from repetition. + // + // This is the identical defect that was fixed in `forCommand` and not here. for (const f of kept) alreadyInjected.add(f.key); + if (holdout || !kept.length) return null; + return `Known about ${filePath} (from previous sessions):\n${kept.map(render).join('\n')}`; } @@ -295,19 +323,46 @@ export function forCommand( const { kept, spent } = fit(served, budget); if (!kept.length) return null; + // THE COMMAND PATH TAKES PART IN THE HOLDOUT TOO. + // + // `holdout: false` was hardcoded here, so 95 of 136 injections measured on a + // real machine were structurally excluded from the only mechanism that can + // establish causation. Seventy per cent of what the feature does could never + // be shown to help or hurt. + // + // Stratified on the COMMAND rather than a file, by the same (key, epoch) + // hash: the same command lands in the same arm all session, so a command run + // repeatedly cannot straddle both arms and contaminate each. + const key = commandKey(command); + const holdout = inHoldout(key); + record(dir, { kind: 'inject', trigger: 'command', + // The surface the report needs to keep these OUT of the file-read balance: + // a command has no anchor that read events can be joined to. + surface: 'command', anchor: String(command).slice(0, 120), - holdout: false, - tokens: spent, - count: kept.length, + holdout, + tokens: holdout ? 0 : spent, + count: holdout ? 0 : kept.length, stale: kept.some((f) => f.stale), sessionId, }); + // MARKED SEEN IN BOTH ARMS. + // + // The held branch used to return before updating the gate, so a command run + // repeatedly wrote a fresh holdout row every time while a treated command was + // filtered after its first delivery. The report counts rows, so the holdout + // arm was systematically overweighted -- a bias in the very comparison this + // exists to make. for (const f of kept) alreadyInjected.add(f.key); + // Withheld means withheld. Returning the text anyway would record an arm the + // subject never actually experienced. + if (holdout) return null; + return `Before running this — known from previous sessions:\n${kept .map(render) .join('\n')}`; @@ -477,7 +532,7 @@ export function standingRules(dir, graph, { budget = standingBudget() } = {}) { * informative response available -- more useful than the file, not a lossier * version of it. */ -export function substitutionFor(dir, graph, rawPath, source) { +export function substitutionFor(dir, graph, rawPath, source, { sessionId } = {}) { const filePath = canonicalPath(rawPath); const budget = substitutionBudget(dir, filePath); const built = annotatedSkeleton(graph, rawPath, source, { budget }); @@ -486,15 +541,50 @@ export function substitutionFor(dir, graph, rawPath, source) { // costs the model a round trip; send it back to the ordinary redirect. if (built.tokens * 4 > source.length * 0.5) return null; + // THE HOLDOUT BELONGS ON THIS PATH, not only on findings injection. + // + // Substitution is the lever that actually moves tokens -- it replaces a whole + // file with a skeleton -- and it had no control arm at all, while the 10% + // holdout sat on findings injection, which is two orders of magnitude + // smaller. Withholding here serves the file the model asked for and records + // what that cost, which is the only way the saving stops being an assumption. + // PINNED FOR THE SESSION, with a fixed epoch. + // + // Unlike the file-touch arm above, this one must not rotate: a session + // running across midnight would substitute for a file in one half and serve + // the whole file in the other, so `measuredCounterfactual` would mix treated + // and control observations for the same file. + // + // Keying on the session alone was not enough -- with the epoch still in play + // the arm flipped 104 times in 400 simulated midnight crossings. The session + // id already provides the rotation the epoch was there for. + const holdout = inHoldout(`${sessionId || ''}|${filePath}`, 0); + record(dir, { kind: 'substitute', anchor: filePath, - tokens: built.tokens, + // Recorded so provenance is checkable. Without it, 366 of 370 substitutions + // on this machine turned out to be the enforcement suite's own fixture and + // nothing distinguished them from real work. + sessionId, + holdout, + tokens: holdout ? 0 : built.tokens, findings: built.findings, symbols: built.symbols, - bytesAvoided: source.length, + // GROSS, kept for continuity with existing records. + bytesAvoided: holdout ? 0 : source.length, + // NET, which is the honest figure: the skeleton was still sent. Reporting + // the whole file as avoided while spending `tokens` on a replacement + // overstates the saving by exactly the size of the replacement. + tokensNetAvoided: holdout ? 0 : Math.max(0, Math.ceil(source.length / 4) - built.tokens), + // What the control arm actually paid, so the two arms are comparable. + tokensFullFile: Math.ceil(source.length / 4), }); + // Withheld means the model gets what it asked for: the whole file. That is + // the control arm, and it must really be paid or the comparison is fiction. + if (holdout) return null; + return built.text; } diff --git a/plugin/hooks/lib/metrics.mjs b/plugin/hooks/lib/metrics.mjs index 0df6ee24a..3fc52e22b 100644 --- a/plugin/hooks/lib/metrics.mjs +++ b/plugin/hooks/lib/metrics.mjs @@ -23,7 +23,7 @@ import { statSync, openSync, readSync, closeSync, } from 'node:fs'; import { join } from 'node:path'; -import { createHash } from 'node:crypto'; +import { createHash, randomBytes } from 'node:crypto'; /** * Read per call, not once at module load. @@ -43,6 +43,28 @@ const EPOCH_MS = 86_400_000; const metricsPath = (dir) => join(dir, 'metrics.jsonl'); +/** + * The balance log: `inject` and `harvest` only. + * + * WHY A SECOND FILE. The event window is measured in EVENTS, and injections are + * a tiny minority of them -- 136 injections against 6,725 captures across every + * graph on one machine. So the last 5,000 events are almost entirely captures + * and reads, and the injections that carry the measurement age out first. + * + * Measured on this repository before the fix: 44 inject records in the file, 9 + * of them holdout, all at lines 60-76 of 9,058 -- every single one outside the + * window. `report()` therefore said "0 holdout" while the file plainly + * contained nine, and the net balance was uncomputable on all 122 graphs. + * + * A separate log fixes it structurally rather than by enlarging a number. + * These records are rare, so the file stays small for years, and a tail window + * on it drops BOTH arms proportionally instead of starving the rare one. + */ +const balancePath = (dir) => join(dir, 'balance.jsonl'); + +/** Kinds the net balance is computed from, and which therefore must survive. */ +const BALANCE_KINDS = new Set(['inject', 'harvest', 'substitute']); + /** * Is this touch in the holdout arm? * @@ -54,7 +76,19 @@ export function inHoldout(anchorKey, now = Date.now()) { const fraction = holdoutFraction(); if (fraction <= 0) return false; const epoch = Math.floor(now / EPOCH_MS); - const digest = createHash('sha1').update(`${anchorKey}:${epoch}`).digest(); + // SHA-256, NOT SHA-1. + // + // This is a bucketing hash, not a security primitive -- nothing is kept + // secret and nothing is authenticated, only spread evenly across two arms. + // But CodeQL flags sha1 as a weak algorithm, seven high-severity alerts + // across the core and its six vendored copies, and arguing that a finding is + // benign is a worse habit than paying a cost that rounds to nothing here. + // Both are deterministic, which is the only property this depends on. + // + // The change DOES reassign arms: a given (anchor, epoch) may land on the + // other side than before. With nine holdout records in existence that costs + // nothing, and stratification is a fresh draw either way. + const digest = createHash('sha256').update(`${anchorKey}:${epoch}`).digest(); return (digest[0] / 256) < fraction; } @@ -65,9 +99,62 @@ export function inHoldout(anchorKey, now = Date.now()) { * moment the cost is knowable. This is the producer that makes the holdout * comparison a measurement rather than a subtraction of two zeroes. */ -export function recordRead(dir, { anchor, sessionId, bytes }) { +export function recordRead(dir, { anchor, sessionId, bytes, fp = null }) { if (!anchor || !bytes) return; - record(dir, { kind: 'read', anchor, sessionId, tokens: Math.ceil(bytes / 4) }); + record(dir, { + kind: 'read', + anchor, + sessionId, + tokens: Math.ceil(bytes / 4), + // THE CHANGE DETECTOR, recorded AT READ TIME. + // + // Without it, 'was this re-read wasteful' is undecidable. Measured before + // this field existed: 575 repeat reads of a file within one session, and + // only 99 could be classified -- 4,735 capture events carried anchors on + // just 122 of them, because most captures are bookkeeping calls that touch + // no file at all. The waste figure was 98% unknowable, and the 14.6M I + // first reported was really 213,651 confirmed plus a very large shrug. + // + // It belongs on the READ, not on a capture: the read already knows the + // anchor, the session and the cost, so the fingerprint completes the record + // rather than needing to be joined to another one. + fp, + }); +} + +/** + * A cheap fingerprint of a file's current content: size and mtime. + * + * NOT a content hash, deliberately. This runs on the PreToolUse path before + * every tool call, and hashing a file there would add a full read to the + * critical path for a measurement. `statSync` is already being done to resolve + * the operand, so this is free. + * + * WHAT IT CAN MISS: a write that leaves both size and mtime identical. That + * requires deliberately restoring the timestamp, so for the question being + * asked -- did this file change between two reads in one session -- it is + * sound. Stated here because a change-detector that silently misses changes + * would understate legitimate re-reads and overstate waste, which is the + * direction this project must never err in. + */ +export function fingerprint(path) { + try { + const st = statSync(path); + return `${st.size}:${Math.round(st.mtimeMs)}`; + } catch { + return null; + } +} + +/** + * A unique id per record. Counter plus randomness: the counter separates + * records written in the same millisecond by one process, the random suffix + * separates concurrent processes, which detached workers routinely are. + */ +let idCounter = 0; +function nextId() { + idCounter += 1; + return `${idCounter.toString(36)}-${randomBytes(4).toString('hex')}`; } export function record(dir, event) { @@ -80,7 +167,24 @@ export function record(dir, event) { } catch { // Not POSIX, or not ours to chmod; the write still proceeds. } - appendFileSync(metricsPath(dir), JSON.stringify({ ...event, at: Date.now() }) + '\n'); + // The CALLER'S timestamp wins when it supplied one. Overwriting it made + // `rereadWaste`'s ordering depend on write order rather than on `at`, so a + // test that set explicit times was passing by luck. + // + // `id` EXISTS SO DEDUPE IS EXACT. A record is written to both logs, so the + // reader has to drop one copy -- and it was matching on a composite of the + // fields, which cannot tell a duplicate from two genuinely distinct events + // that happen to look alike. Twenty-five identical injections written in a + // single millisecond collapsed to ONE, so a graph with ample data reported + // 'insufficient data (2 treated, 1 holdout)'. Real events were being + // discarded by the deduplicator, silently. + const line = + JSON.stringify({ id: nextId(), ...event, at: event.at ?? Date.now() }) + '\n'; + appendFileSync(metricsPath(dir), line); + // Balance-critical records go to their own log as well, so the windows on + // the firehose can never starve the measurement. Written SECOND: a torn + // write here costs a duplicate the reader dedupes, not a lost event. + if (BALANCE_KINDS.has(event.kind)) appendFileSync(balancePath(dir), line); } catch { // Metrics must never break a tool call. } @@ -110,7 +214,22 @@ export function readMetrics(dir) { return readAll(dir); } +/** + * How the last readAll truncated, if it did. + * + * Returned out of band rather than on the array, because callers pass the + * events around freely and a property hung on an array would be lost the first + * time anything filtered it -- which is exactly how `eventsTruncated` came to + * report only half the truth. + */ +let lastReadTruncation = { byBytes: false, byEvents: false }; + +export function readTruncation() { + return { ...lastReadTruncation }; +} + function readAll(dir) { + lastReadTruncation = { byBytes: false, byEvents: false }; const path = metricsPath(dir); if (!existsSync(path)) return []; @@ -132,13 +251,16 @@ function readAll(dir) { // The first line is almost certainly cut mid-record; drop it rather than // letting it fail to parse and look like corruption. text = text.slice(text.indexOf('\n') + 1); + lastReadTruncation.byBytes = true; } } catch { return []; } const out = []; - for (const line of text.split('\n').slice(-MAX_EVENTS)) { + const lines = text.split('\n'); + if (lines.length > MAX_EVENTS) lastReadTruncation.byEvents = true; + for (const line of lines.slice(-MAX_EVENTS)) { if (!line) continue; try { out.push(JSON.parse(line)); @@ -149,6 +271,323 @@ function readAll(dir) { return out; } +/** + * Balance records, read WITHOUT the event window that was starving them. + * + * Reads the dedicated log in full, and merges in whatever the firehose still + * holds so graphs that predate the split are not left unmeasurable. Duplicates + * are inevitable once both logs carry the same record, so they are removed on + * an identity built from the fields that make an event unique. + * + * The byte cap still applies to the dedicated log, but it means something very + * different here: these records are rare, so the cap is years of history rather + * than hours, and it drops BOTH arms proportionally when it finally bites. + */ +/** + * Every balance record in a file, with NO event window. + * + * The byte cap still bounds the read, because the firehose can be enormous. The + * event cap does not apply: it is what buried these records in the first place, + * and they are rare enough that keeping all of them inside the byte window costs + * nothing. + */ +function scanForBalance(path) { + if (!existsSync(path)) return []; + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + return []; + } + const out = []; + for (const line of text.split('\n')) { + if (!line) continue; + try { + const e = JSON.parse(line); + if (BALANCE_KINDS.has(e.kind)) out.push(e); + } catch { + /* a torn line costs a record, not the report */ + } + } + return out; +} + +export function readBalance(dir) { + const merged = []; + const path = balancePath(dir); + if (existsSync(path)) { + let text = ''; + try { + const { size } = statSync(path); + if (size <= MAX_BYTES) { + text = readFileSync(path, 'utf8'); + } else { + const fd = openSync(path, 'r'); + try { + const buffer = Buffer.allocUnsafe(MAX_BYTES); + const read = readSync(fd, buffer, 0, MAX_BYTES, size - MAX_BYTES); + text = buffer.subarray(0, read).toString('utf8'); + } finally { + closeSync(fd); + } + text = text.slice(text.indexOf('\n') + 1); + } + } catch { + text = ''; + } + for (const line of text.split('\n')) { + if (!line) continue; + try { + merged.push(JSON.parse(line)); + } catch { + /* a torn line costs a record, not the report */ + } + } + } + + // MIGRATION, not a fallback. Every graph written before the split has its + // only copy of these records in the firehose; ignoring them would reset the + // measurement to zero on 122 existing graphs. + // + // IT MUST NOT GO THROUGH readAll. The first version of this fix did, and + // readAll applies the very event window that was starving the measurement -- + // so the migration inherited the bug it existed to repair and the real graphs + // still reported zero holdouts. Verified against them: unchanged at 0 until + // this scan stopped windowing. + for (const e of scanForBalance(metricsPath(dir))) merged.push(e); + + const seen = new Set(); + const out = []; + for (const e of merged) { + // The record's OWN id when it has one. The composite below is the legacy + // path for records written before ids existed; it is lossy by nature, which + // is precisely why new records carry an id instead. + const id = + e.id ?? [e.kind, e.at, e.anchor ?? '', e.sessionId ?? '', e.tokens ?? ''].join('|'); + if (seen.has(id)) continue; + seen.add(id); + out.push(e); + } + return out; +} + +/** + * Is this anchor a test fixture rather than real work? + * + * Not fussiness. Measured on this machine: 366 of 370 substitutions pointed at + * the enforcement suite's own big.ts fixture under a temp dir, and counting them made + * the product look like it had avoided 40 MB of reads. It had avoided 154 KB. + * A balance sheet that counts its own test suite as revenue is worse than none. + */ +export function isFixtureAnchor(anchor) { + const p = String(anchor || ''); + + // TWO CONDITIONS, BOTH REQUIRED. The previous version was a ternary chain in + // which every branch evaluated to `underTemp`, so the scratch test was dead + // code: it excluded ALL temp paths -- including a real project checked out + // under /tmp -- and on macOS excluded nothing at all, because tmpdir() there + // is /var/folders///T/ and did not match. + const underTemp = + new RegExp( + '[\\\\/](AppData[\\\\/]Local[\\\\/])?(Temp|tmp)[\\\\/]' + + '|[\\\\/]var[\\\\/]folders[\\\\/][^\\\\/]+[\\\\/][^\\\\/]+[\\\\/]T[\\\\/]', + 'i' + ).test(p); + if (!underTemp) return false; + + // Only names this suite actually creates. A user's own scratch checkout under + // a temp directory is real work and must still be counted. + return /(to-hooks-|ab-[a-z]+-|cooccur-|holdout-|reread-|feedback-e2e|standing-e2e|lesson-origin|archive-|gen-eol-|tear-|edge-src|fixture)/i.test( + p + ); +} + +/** + * The balance sheet, with every line labelled by HOW it is known. + * + * The shipped report counted every cost and one benefit that has never been + * computable, so it was negative by construction. These are the two things + * actually known, kept apart because they are known differently and must never + * be summed into a single hero number: + * + * MEASURED-COUNTERFACTUAL substitution. The file size is known exactly and + * the replacement's size is known exactly, so the + * saving is arithmetic -- resting on the one + * assumption that the model would have read what it + * explicitly asked for. + * ESTIMATED-CAUSAL findings injection, from the holdout. Genuinely + * causal when it has samples, and worth far less + * token-wise. + * + * Fixture anchors are excluded from both. + */ +/** + * Re-read waste, split into what is KNOWN and what is not. + * + * The question is narrow on purpose: how often does one session read the same + * file twice with the file UNCHANGED in between? That is waste the graph can + * remove, and it needs no holdout, no estimate and no join -- the reads carry + * their own fingerprints. + * + * A repeat read of a file that CHANGED is not waste and is reported as such. + * Conflating the two is how the first version of this measurement turned + * 213,651 confirmed tokens into a 14.6M headline. + * + * `undecidable` is reported rather than hidden. Reads written before the + * fingerprint existed cannot be classified, and a measurement that quietly + * counted them either way would be inventing its own answer. + */ +export function rereadWaste( + dir, + // `includeFixtures` exists so the suite can exercise this against files it + // creates under the temp directory -- which the fixture filter otherwise + // excludes by design, making the real path untestable. + { events = readMetrics(dir), includeFixtures = false } = {} +) { + const groups = new Map(); + for (const e of events) { + if (e.kind !== 'read' || !e.anchor) continue; + if (!includeFixtures && isFixtureAnchor(e.anchor)) continue; + const key = `${e.sessionId || ''}|${canonicalKeyish(e.anchor)}`; + if (!groups.has(key)) groups.set(key, []); + groups.get(key).push(e); + } + + const out = { + repeats: 0, + wasteful: 0, + wastefulTokens: 0, + legitimate: 0, + legitimateTokens: 0, + undecidable: 0, + undecidableTokens: 0, + }; + + for (const list of groups.values()) { + if (list.length < 2) continue; + list.sort((a, b) => (a.at || 0) - (b.at || 0)); + for (let i = 1; i < list.length; i++) { + const prev = list[i - 1]; + const cur = list[i]; + const tokens = cur.tokens || 0; + out.repeats += 1; + if (!prev.fp || !cur.fp) { + out.undecidable += 1; + out.undecidableTokens += tokens; + } else if (prev.fp === cur.fp) { + out.wasteful += 1; + out.wastefulTokens += tokens; + } else { + out.legitimate += 1; + out.legitimateTokens += tokens; + } + } + } + + const decided = out.wasteful + out.legitimate; + out.coverage = out.repeats ? decided / out.repeats : null; + return out; +} + +export function balanceSheet(dir) { + const balance = readBalance(dir).filter((e) => !isFixtureAnchor(e.anchor)); + const events = readMetrics(dir); + const truncation = readTruncation(); + + const subs = balance.filter((e) => e.kind === 'substitute'); + const served = subs.filter((e) => !e.holdout); + const withheldSubs = subs.filter((e) => e.holdout); + + // NET, not gross: the skeleton was still sent. + const netAvoided = served.reduce( + (sum, e) => + sum + + (e.tokensNetAvoided ?? + Math.max(0, Math.ceil((e.bytesAvoided || 0) / 4) - (e.tokens || 0))), + 0 + ); + const substitutionCost = served.reduce((sum, e) => sum + (e.tokens || 0), 0); + + const injectCost = balance + .filter((e) => e.kind === 'inject' && !e.holdout) + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const harvestCost = balance + .filter((e) => e.kind === 'harvest') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + const standingCost = events + .filter((e) => e.kind === 'standing') + .reduce((sum, e) => sum + (e.tokens || 0), 0); + + // RE-READS, decided by fingerprint rather than assumed. + const waste = rereadWaste(dir, { events }); + + return { + measuredCounterfactual: { + what: 'substitution: a skeleton sent instead of the file the model asked for', + substitutions: served.length, + withheld: withheldSubs.length, + tokensAvoidedNet: netAvoided, + tokensSpent: substitutionCost, + // THE CONTROL ARM'S ACTUAL COST. `tokensFullFile` was recorded and read + // by nothing, so the comparison the holdout exists for was not + // computable from the report. + controlArmTokens: withheldSubs.reduce((sum, e) => sum + (e.tokensFullFile || 0), 0), + assumption: 'that the model would have read the file it explicitly requested', + }, + estimatedCausal: { + what: 'findings injection, from the stratified holdout', + ...(() => { + const r = report(dir); + return { + treated: r.injections, + holdouts: r.holdouts, + tokensAvoided: r.estimatedTokensAvoided, + sufficientData: r.sufficientData, + verdict: r.verdict, + }; + })(), + }, + costs: { injection: injectCost, harvest: harvestCost, standing: standingCost, substitution: substitutionCost }, + waste, + // Deliberately NOT a single number. The two benefit lines are known + // differently; adding them would launder an assumption into a measurement. + // TWO WINDOWS, STATED RATHER THAN BLENDED. Balance records are read in + // full; everything derived from `events` sees only the tail of + // metrics.jsonl. Once that log rolls past its cap these cover different + // periods, and a reader has to be able to see that rather than assume one + // consistent balance. + windows: { + balance: 'all balance.jsonl records within the byte cap', + events: `tail of metrics.jsonl (<= ${MAX_BYTES} bytes, <= ${MAX_EVENTS} events)`, + // BOTH CAPS, from the reader itself. The previous flag tested the event + // count only, so a log truncated by the BYTE cap with fewer than + // MAX_EVENTS surviving records reported `false` -- the one case where the + // window silently covers a shorter period than the balance side. + eventsTruncated: truncation.byBytes || truncation.byEvents, + truncatedBy: truncation, + }, + note: 'benefit lines are reported separately by evidence strength and are never summed', + }; +} + +/** Cheap path normalisation for grouping reads; not the identity canonicaliser. */ +function canonicalKeyish(p) { + return String(p || '').replace(/\\/g, '/').toLowerCase(); +} + /** * The report. * @@ -159,8 +598,29 @@ function readAll(dir) { */ export function report(dir) { const events = readAll(dir); + // Injections and harvests come from the log that cannot be starved. + const balance = readBalance(dir); - const injections = events.filter((e) => e.kind === 'inject'); + // COMMAND INJECTIONS ARE COUNTED SEPARATELY, not mixed into the balance. + // + // The saving is measured by joining an injection to the READS of its anchor + // afterwards. A command injection's anchor is the command text, which no read + // event will ever match, so both arms would contribute zero downstream and + // every command record would pull both means toward zero -- diluting a real + // file-touch saving in proportion to how many commands ran. + // + // They still take part in the holdout, and are reported, because a structural + // exclusion is how 95 of 136 injections came to be unmeasurable. What is + // missing is a downstream join for them, and that is stated rather than + // papered over with a number. + const allInjections = balance.filter((e) => e.kind === 'inject'); + // `trigger` is the pre-`surface` spelling. Records written before the split + // carry it and no surface at all, so keying only on surface would silently + // file 95 historical command injections into the file-read balance -- exactly + // the dilution the split exists to prevent. + const isCommand = (e) => e.surface === 'command' || e.trigger === 'command'; + const commandInjections = allInjections.filter(isCommand); + const injections = allInjections.filter((e) => !isCommand(e)); const treated = injections.filter((e) => !e.holdout); const withheld = injections.filter((e) => e.holdout); @@ -168,7 +628,7 @@ export function report(dir) { rows.length ? rows.reduce((sum, r) => sum + (r[field] || 0), 0) / rows.length : 0; const injectedTokens = treated.reduce((sum, e) => sum + (e.tokens || 0), 0); - const harvestTokens = events + const harvestTokens = balance .filter((e) => e.kind === 'harvest') .reduce((sum, e) => sum + (e.tokens || 0), 0); @@ -238,6 +698,8 @@ export function report(dir) { return { injections: treated.length, + commandInjections: commandInjections.length, + commandHoldouts: commandInjections.filter((e) => e.holdout).length, holdouts: withheld.length, staleServed: injections.filter((e) => e.stale).length, staleRate: injections.length ? injections.filter((e) => e.stale).length / injections.length : 0, diff --git a/plugin/hooks/pretooluse-router.mjs b/plugin/hooks/pretooluse-router.mjs index 51f984fa6..9e08291cb 100644 --- a/plugin/hooks/pretooluse-router.mjs +++ b/plugin/hooks/pretooluse-router.mjs @@ -14,7 +14,7 @@ import { readPayload, loadState, saveState, alreadyDenied, allow, allowWithContext, enforce, mode, MODE_OFF } from './lib/policy.mjs'; import { decide, remember, normalizePayload, readCostBytes, touchedFiles, isContentDump } from './lib/decide.mjs'; -import { recordRead } from './lib/metrics.mjs'; +import { recordRead, fingerprint } from './lib/metrics.mjs'; import { wikiDir, load, harvest, projectRootFor, contentHash } from './lib/wiki.mjs'; import { refusalPayload, substitutionFor, forTouch, forCommand } from './lib/inject.mjs'; import { indexFile } from './lib/staleness.mjs'; @@ -75,6 +75,11 @@ try { anchor: payload.tool_input.file_path, sessionId: payload.session_id, bytes, + // So a later re-read of the same file can be told from a re-read of a + // file that CHANGED in between. Re-reading what you just edited is + // correct behaviour, not waste, and without this the two are + // indistinguishable. + fp: fingerprint(payload.tool_input.file_path), }); } else if (isContentDump(payload.tool_input.command)) { // ONLY commands that actually print the file pay for its bytes. `Write`, @@ -83,7 +88,14 @@ try { // comparison is built on -- and an overstated saving is the one number // this project must never produce. for (const { path, size } of touched) { - if (size > 0) recordRead(dirFor(path), { anchor: path, sessionId: payload.session_id, bytes: size }); + if (size > 0) { + recordRead(dirFor(path), { + anchor: path, + sessionId: payload.session_id, + bytes: size, + fp: fingerprint(path), + }); + } } } @@ -218,8 +230,16 @@ try { // Index on this read, so the NEXT touch of the file is annotated even if // no semantic harvest has run against it yet. indexFile(dir, payload.tool_input.file_path, source); - const substitution = substitutionFor(dir, load(dir), payload.tool_input.raw_file_path - ?? payload.tool_input.file_path, source); + const substitution = substitutionFor( + dir, + load(dir), + payload.tool_input.raw_file_path ?? payload.tool_input.file_path, + source, + // Carried through so a substitution can be told apart from a test + // fixture later. Without it the balance sheet counted the suite's own + // 366 fixture writes as product value. + { sessionId: payload.session_id } + ); if (substitution) reason = substitution; } } catch { diff --git a/tests/fixtures/ab-injection-harness.mjs b/tests/fixtures/ab-injection-harness.mjs index dda91261b..5bb5f17b5 100644 --- a/tests/fixtures/ab-injection-harness.mjs +++ b/tests/fixtures/ab-injection-harness.mjs @@ -133,7 +133,20 @@ export function buildArms() { tool_input: { command: c.probeCommand }, }), encoding: 'utf8', - env: { ...process.env, TOKEN_OPTIMIZER_WIKI_DIR: caseDir }, + env: { + ...process.env, + TOKEN_OPTIMIZER_WIKI_DIR: caseDir, + // THE HOLDOUT IS OFF FOR THE HARNESS. + // + // The harness builds the TREATMENT arm: its whole job is to capture + // what the hook emits when it serves. With the holdout live, a case + // whose command hashes into the withheld arm produces no context, and + // the treatment arm silently becomes a second control -- the exact + // failure the repeatability guard was added to catch, arriving by a + // different route. It showed up as 4 of 5 arms on Linux CI and 5 of 5 + // locally, because the arm depends on the temp path. + TOKEN_OPTIMIZER_HOLDOUT: '0', + }, }); // FAIL FAST. A hook that crashed and a hook that had nothing to say both diff --git a/tests/hooks/command-injection.test.mjs b/tests/hooks/command-injection.test.mjs index 6a72b983c..934f84e83 100644 --- a/tests/hooks/command-injection.test.mjs +++ b/tests/hooks/command-injection.test.mjs @@ -10,7 +10,7 @@ * * These tests pin the trigger path that closes that gap. */ -import { describe, it, expect, beforeEach, afterEach } from '@jest/globals'; +import { describe, it, expect, beforeEach, afterEach, afterAll } from '@jest/globals'; import { forCommand } from '../../hooks-core/inject.mjs'; import { load, putNodeWithEdges, putNode, nodeId } from '../../hooks-core/wiki.mjs'; import { mkdtempSync, rmSync, writeFileSync, readFileSync } from 'fs'; @@ -30,6 +30,25 @@ function seed({ key, claim, type = 'command', trigger, confidence = 0.9 }) { ); } +// THE HOLDOUT IS OFF IN THIS SUITE, DELIBERATELY. +// +// `forCommand` now takes part in the holdout, so a command whose stratification +// hash lands in the withheld arm correctly returns null. These tests are about +// DELIVERY, not measurement, and leaving the holdout on would make them depend +// on which epoch they run in -- passing today and failing tomorrow for a reason +// nobody would connect to a date. The measurement itself is tested in +// tests/hooks/holdout-measurement.test.mjs, where the arm is chosen explicitly. +const PRIOR_HOLDOUT = process.env.TOKEN_OPTIMIZER_HOLDOUT; +process.env.TOKEN_OPTIMIZER_HOLDOUT = '0'; +afterAll(() => { + // RESTORED, because this variable is process-wide and jest shares a process + // between suites in a worker. Leaving it at 0 silently disabled the holdout + // for any suite that ran afterwards -- including the one whose entire subject + // is the holdout. + if (PRIOR_HOLDOUT === undefined) delete process.env.TOKEN_OPTIMIZER_HOLDOUT; + else process.env.TOKEN_OPTIMIZER_HOLDOUT = PRIOR_HOLDOUT; +}); + beforeEach(() => { dir = mkdtempSync(join(tmpdir(), 'cmd-inject-')); anchorFile = join(dir, 'harvest.mjs'); diff --git a/tests/hooks/holdout-measurement.test.mjs b/tests/hooks/holdout-measurement.test.mjs new file mode 100644 index 000000000..a683f345e --- /dev/null +++ b/tests/hooks/holdout-measurement.test.mjs @@ -0,0 +1,186 @@ +/** + * The causal measurement, which had never once produced a reading. + * + * Measured across 122 real project graphs on one machine before this fix: + * 6,725 captures, 136 injections, 97 treated, and **zero** holdout samples + * counted. The net token balance was therefore uncomputable everywhere, which + * means the question the whole product exists to answer -- does this save more + * than it costs -- had no evidence of any kind behind it. + * + * Two independent causes, both reproduced here: + * + * 1. The event window is measured in EVENTS, and injections are a tiny minority + * of them. On this repository the log held 44 inject records, 9 of them + * holdout, ALL at lines 60-76 of 9,058 -- every one outside the last 5,000. + * `report()` said "0 holdout" while the file plainly contained nine. + * + * 2. `forCommand` hardcoded `holdout: false`, so 95 of those 136 injections + * could never contribute to the comparison at all. + */ +import { describe, it, expect, beforeEach, afterEach } from '@jest/globals'; +import { mkdtempSync, rmSync, writeFileSync, appendFileSync, existsSync, readFileSync } from 'fs'; +import { join } from 'path'; +import { tmpdir } from 'os'; +import { record, report, readBalance, inHoldout } from '../../hooks-core/metrics.mjs'; +import { forCommand } from '../../hooks-core/inject.mjs'; +import { putNode, putNodeWithEdges, load } from '../../hooks-core/wiki.mjs'; + +const NL = String.fromCharCode(10); + +// A KNOWN POSITIVE FRACTION, set before anything calls inHoldout(). +// +// Another suite sets this to '0' for its own reasons, and jest shares a process +// between suites in a worker -- so without pinning it here, the suite whose +// subject IS the holdout could run with the holdout disabled and still pass by +// finding no withheld command. +process.env.TOKEN_OPTIMIZER_HOLDOUT = '0.1'; +let dir; + +beforeEach(() => { + dir = mkdtempSync(join(tmpdir(), 'holdout-')); +}); + +afterEach(() => { + try { + rmSync(dir, { recursive: true, force: true }); + } catch { + /* windows */ + } +}); + +describe('the balance log survives the event window', () => { + it('keeps holdout records that the firehose window has long since dropped', () => { + // Exactly the shape of the real file: a handful of injections at the very + // beginning, then thousands of ordinary events burying them. + record(dir, { kind: 'inject', surface: 'file', anchor: '/a.ts', holdout: true, tokens: 0 }); + record(dir, { kind: 'inject', surface: 'file', anchor: '/b.ts', holdout: true, tokens: 0 }); + for (let i = 0; i < 20; i++) { + record(dir, { kind: 'inject', surface: 'file', anchor: `/t${i}.ts`, holdout: false, tokens: 50 }); + } + + // Bury them under more events than the window admits, writing straight to + // the firehose so the balance log is not touched. + const noise = + Array.from({ length: 6000 }, (_, i) => + JSON.stringify({ kind: 'capture', anchor: `/noise${i}.ts`, at: Date.now() }) + ).join(NL) + NL; + appendFileSync(join(dir, 'metrics.jsonl'), noise); + + const balance = readBalance(dir); + const holdouts = balance.filter((e) => e.kind === 'inject' && e.holdout); + expect(holdouts).toHaveLength(2); + + const r = report(dir); + expect(r.holdouts).toBe(2); + expect(r.injections).toBe(20); + }, 60_000); + + it('does not double-count a record present in both logs', () => { + record(dir, { kind: 'inject', surface: 'file', anchor: '/a.ts', holdout: true, tokens: 0 }); + // Both files legitimately hold this record; the reader must dedupe it. + expect(existsSync(join(dir, 'balance.jsonl'))).toBe(true); + const inFirehose = readFileSync(join(dir, 'metrics.jsonl'), 'utf8').split(NL).filter(Boolean); + const inBalance = readFileSync(join(dir, 'balance.jsonl'), 'utf8').split(NL).filter(Boolean); + expect(inFirehose).toHaveLength(1); + expect(inBalance).toHaveLength(1); + + expect(readBalance(dir).filter((e) => e.kind === 'inject')).toHaveLength(1); + }); + + it('still reads a graph written before the split, rather than resetting it to zero', () => { + // MIGRATION. 122 graphs already exist with their only copy in the firehose. + // Ignoring those would zero the measurement on every one of them. + const legacy = + [ + JSON.stringify({ kind: 'inject', surface: 'file', anchor: '/old.ts', holdout: true, tokens: 0, at: 1 }), + JSON.stringify({ kind: 'inject', surface: 'file', anchor: '/old2.ts', holdout: false, tokens: 40, at: 2 }), + ].join(NL) + NL; + writeFileSync(join(dir, 'metrics.jsonl'), legacy); + expect(existsSync(join(dir, 'balance.jsonl'))).toBe(false); + + const r = report(dir); + expect(r.holdouts).toBe(1); + expect(r.injections).toBe(1); + }); +}); + +describe('the command path takes part in the holdout', () => { + const seed = (graphDir, trigger) => { + const anchor = join(graphDir, 'subject.ts'); + writeFileSync(anchor, 'export const subject = 1;' + NL); + const fid = putNode(graphDir, { kind: 'file', key: anchor, hash: 'h' }); + putNodeWithEdges( + graphDir, + { + kind: 'finding', + key: 'f-' + trigger, + claim: 'Use npm test, not npx jest, for this project.', + type: 'command', + trigger, + confidence: 0.95, + }, + [{ edge: 'derived_from', to: fid }] + ); + }; + + it('records a surface, so the report can keep commands out of the file balance', () => { + seed(dir, 'jest'); + forCommand(dir, load(dir), 'npx jest tests/', { sessionId: 's1' }); + const rec = readBalance(dir).find((e) => e.kind === 'inject'); + expect(rec).toBeDefined(); + expect(rec.surface).toBe('command'); + }); + + it('withholds the text on a command that lands in the holdout arm', () => { + // Find a command the stratifier actually withholds, rather than asserting a + // rate: the arm is deterministic in (key, epoch), so one exists. + let held = null; + for (let i = 0; i < 400 && !held; i++) { + const cmd = `npx jest suite-${i}`; + if (inHoldout(cmd.trim().replace(/\s+/g, ' ').slice(0, 120).toLowerCase())) held = cmd; + } + expect(held).not.toBeNull(); + + seed(dir, 'jest'); + const out = forCommand(dir, load(dir), held, { sessionId: 's1' }); + + // Withheld means withheld: the subject must not receive the text, or the + // arm records an experience that never happened. + expect(out).toBeNull(); + + const rec = readBalance(dir).find((e) => e.kind === 'inject'); + expect(rec.holdout).toBe(true); + expect(rec.tokens).toBe(0); + }); + + it('serves and charges tokens on a command in the treated arm', () => { + let treated = null; + for (let i = 0; i < 400 && !treated; i++) { + const cmd = `npx jest case-${i}`; + if (!inHoldout(cmd.trim().replace(/\s+/g, ' ').slice(0, 120).toLowerCase())) treated = cmd; + } + expect(treated).not.toBeNull(); + + seed(dir, 'jest'); + const out = forCommand(dir, load(dir), treated, { sessionId: 's1' }); + expect(out).toContain('npm test'); + + const rec = readBalance(dir).find((e) => e.kind === 'inject'); + expect(rec.holdout).toBe(false); + expect(rec.tokens).toBeGreaterThan(0); + }); + + it('is counted separately, because no read event can be joined to a command', () => { + // A command's anchor is the command text. Mixing these into the file-read + // balance would pull BOTH arm means toward zero in proportion to how many + // commands ran, diluting a real saving with records that cannot show one. + record(dir, { kind: 'inject', surface: 'command', anchor: 'npx jest', holdout: false, tokens: 30 }); + record(dir, { kind: 'inject', surface: 'command', anchor: 'git fetch', holdout: true, tokens: 0 }); + record(dir, { kind: 'inject', surface: 'file', anchor: '/a.ts', holdout: false, tokens: 20 }); + + const r = report(dir); + expect(r.injections).toBe(1); // file surface only + expect(r.commandInjections).toBe(2); + expect(r.commandHoldouts).toBe(1); + }); +}); diff --git a/tests/hooks/reread-waste.test.mjs b/tests/hooks/reread-waste.test.mjs new file mode 100644 index 000000000..cbd060706 --- /dev/null +++ b/tests/hooks/reread-waste.test.mjs @@ -0,0 +1,144 @@ +/** + * Re-read waste, and why the first version of this number was 68x too big. + * + * The claim "the graph prevents re-reading files you have already read" was + * measured by counting every repeat read of a file within one session. That + * produced 575 repeats and 14,569,375 tokens, which I reported as the + * addressable target. + * + * It was wrong. Re-reading a file you have just EDITED is correct behaviour, + * not waste, and the count could not tell the two apart. When the reads were + * classified against what content hashes existed, only 99 of 575 could be + * decided at all: 73 genuinely wasteful (213,651 tokens) and 26 legitimate. + * The other 476 -- 97.8% of the tokens -- were unknowable, because capture + * events carried an anchor on 122 of 4,735 records. + * + * So the fix is not a better sum over the same data. It is recording a + * fingerprint ON THE READ, where the anchor, session and cost already are, so + * the question becomes decidable at the point it is asked. + */ +import { describe, it, expect, beforeEach, afterEach } from '@jest/globals'; +import { mkdtempSync, rmSync, writeFileSync } from 'fs'; +import { join } from 'path'; +import { tmpdir } from 'os'; +import { record, rereadWaste, fingerprint, recordRead } from '../../hooks-core/metrics.mjs'; + +let dir; +let project; + +beforeEach(() => { + dir = mkdtempSync(join(tmpdir(), 'reread-')); + project = mkdtempSync(join(tmpdir(), 'reread-src-')); +}); + +afterEach(() => { + for (const d of [dir, project]) { + try { + rmSync(d, { recursive: true, force: true }); + } catch { + /* windows */ + } + } +}); + +/** A read of `anchor` at `at`, with the fingerprint the router would capture. */ +const read = (anchor, at, fp, tokens = 100) => + record(dir, { kind: 'read', anchor, sessionId: 's1', tokens, fp, at }); + +describe('a repeat read is only waste when the file did not change', () => { + it('counts an unchanged re-read as wasteful', () => { + read('/src/a.ts', 1, '100:5000'); + read('/src/a.ts', 2, '100:5000'); + + const w = rereadWaste(dir); + expect(w.repeats).toBe(1); + expect(w.wasteful).toBe(1); + expect(w.legitimate).toBe(0); + expect(w.wastefulTokens).toBe(100); + }); + + it('counts a re-read AFTER AN EDIT as legitimate, not waste', () => { + // THE CASE THAT BROKE THE FIRST MEASUREMENT. The largest single contributor + // to the 14.6M was one file read 22 times in a session -- while it was + // being edited. Every one of those reads was necessary. + read('/src/a.ts', 1, '100:5000'); + read('/src/a.ts', 2, '140:6000'); + read('/src/a.ts', 3, '180:7000'); + + const w = rereadWaste(dir); + expect(w.repeats).toBe(2); + expect(w.wasteful).toBe(0); + expect(w.legitimate).toBe(2); + expect(w.wastefulTokens).toBe(0); + }); + + it('reports what it cannot decide instead of guessing', () => { + // Reads written before the fingerprint existed. Counting them either way + // would be the measurement inventing its own answer. + read('/src/a.ts', 1, null); + read('/src/a.ts', 2, null); + + const w = rereadWaste(dir); + expect(w.repeats).toBe(1); + expect(w.undecidable).toBe(1); + expect(w.wasteful).toBe(0); + expect(w.legitimate).toBe(0); + expect(w.coverage).toBe(0); + }); + + it('reports coverage, so a confident number from thin data is visible', () => { + read('/src/a.ts', 1, '1:1'); + read('/src/a.ts', 2, '1:1'); + read('/src/b.ts', 1, null); + read('/src/b.ts', 2, null); + + const w = rereadWaste(dir); + expect(w.repeats).toBe(2); + expect(w.coverage).toBe(0.5); + }); + + it('does not treat two different sessions as a re-read', () => { + record(dir, { kind: 'read', anchor: '/src/a.ts', sessionId: 's1', tokens: 100, fp: '1:1', at: 1 }); + record(dir, { kind: 'read', anchor: '/src/a.ts', sessionId: 's2', tokens: 100, fp: '1:1', at: 2 }); + + expect(rereadWaste(dir).repeats).toBe(0); + }); + + it('ignores fixture anchors, which are 366 of 370 substitutions on this machine', () => { + read(join(tmpdir(), 'to-hooks-x', 'big.ts'), 1, '1:1'); + read(join(tmpdir(), 'to-hooks-x', 'big.ts'), 2, '1:1'); + + expect(rereadWaste(dir).repeats).toBe(0); + }); +}); + +describe('the fingerprint itself', () => { + it('changes when the file changes, and is stable when it does not', () => { + const f = join(project, 'a.ts'); + writeFileSync(f, 'export const a = 1;'); + const first = fingerprint(f); + expect(first).toBeTruthy(); + expect(fingerprint(f)).toBe(first); + + writeFileSync(f, 'export const a = 1; export const b = 2;'); + expect(fingerprint(f)).not.toBe(first); + }); + + it('returns null for a file that is not there, rather than throwing', () => { + expect(fingerprint(join(project, 'nope.ts'))).toBeNull(); + }); + + it('is attached by recordRead, so a read is self-describing', () => { + const f = join(project, 'b.ts'); + writeFileSync(f, 'x'.repeat(400)); + recordRead(dir, { anchor: f, sessionId: 's1', bytes: 400, fp: fingerprint(f) }); + recordRead(dir, { anchor: f, sessionId: 's1', bytes: 400, fp: fingerprint(f) }); + + // The scratch file lives under the temp directory, which the fixture + // filter excludes by design; opt in so the real path is exercised. + const w = rereadWaste(dir, { includeFixtures: true }); + expect(w.repeats).toBe(1); + expect(w.wasteful).toBe(1); + expect(w.coverage).toBe(1); + }); +}); diff --git a/tests/hooks/review-round2.test.mjs b/tests/hooks/review-round2.test.mjs index 0f4e0c608..b3616ef20 100644 --- a/tests/hooks/review-round2.test.mjs +++ b/tests/hooks/review-round2.test.mjs @@ -18,6 +18,21 @@ import { load, putNode, GRAPH_VERSION } from '../../hooks-core/wiki.mjs'; import { indexFile } from '../../hooks-core/staleness.mjs'; import { record, recordRead, report } from '../../hooks-core/metrics.mjs'; +// THE HOLDOUT IS OFF IN THIS SUITE, DELIBERATELY. +// +// These assert what injection DELIVERS and how downstream cost is joined, not whether the holdout works. +// +// The arm is a hash of the anchor, and the anchor is a fresh mkdtemp path, so +// whether it is withheld changes with the path the OS hands out. That passed +// on Windows and failed on Linux CI -- a test that depends on which machine +// runs it is not testing what it claims to. +const PRIOR_HOLDOUT = process.env.TOKEN_OPTIMIZER_HOLDOUT; +process.env.TOKEN_OPTIMIZER_HOLDOUT = '0'; +afterAll(() => { + if (PRIOR_HOLDOUT === undefined) delete process.env.TOKEN_OPTIMIZER_HOLDOUT; + else process.env.TOKEN_OPTIMIZER_HOLDOUT = PRIOR_HOLDOUT; +}); + const ROOT = join(dirname(fileURLToPath(import.meta.url)), '..', '..'); let workspace; diff --git a/tests/hooks/skeleton.test.mjs b/tests/hooks/skeleton.test.mjs index dc6ac0a0d..77bb0709d 100644 --- a/tests/hooks/skeleton.test.mjs +++ b/tests/hooks/skeleton.test.mjs @@ -18,6 +18,20 @@ import { annotatedSkeleton, contestedHistory, gitSignals } from '../../hooks-cor import { load, putNode, putEdge, nodeId } from '../../hooks-core/wiki.mjs'; import { indexFile } from '../../hooks-core/staleness.mjs'; import { substitutionBudget, record, recordRead } from '../../hooks-core/metrics.mjs'; + +// THE HOLDOUT IS OFF IN THIS SUITE, DELIBERATELY. +// +// `substitutionFor` now takes part in the holdout, so a file whose +// stratification hash lands in the withheld arm correctly returns null -- the +// model is given the real file instead. These tests are about what a +// substitution CONTAINS, not about measurement. +// +// Without this the suite is a coin flip: the anchor is a fresh mkdtemp path on +// every run, so whether it lands in the holdout changes run to run. It failed +// once and then passed on the retry, which is the worst way for a test to +// behave -- it looks fixed. +const PRIOR_HOLDOUT = process.env.TOKEN_OPTIMIZER_HOLDOUT; +process.env.TOKEN_OPTIMIZER_HOLDOUT = '0'; import { substitutionFor } from '../../hooks-core/inject.mjs'; import { canonicalPath } from '../../hooks-core/paths.mjs'; @@ -201,3 +215,10 @@ describe('the budget is earned per file, from the control arm', () => { expect(substitutionBudget(dir, anchor)).toBeLessThan(1200); }); }); + +// Restored at the end: the variable is process-wide and jest shares a process +// between suites, so leaving it at 0 disables the holdout for whatever runs next. +afterAll(() => { + if (PRIOR_HOLDOUT === undefined) delete process.env.TOKEN_OPTIMIZER_HOLDOUT; + else process.env.TOKEN_OPTIMIZER_HOLDOUT = PRIOR_HOLDOUT; +});