From e4ede44df8e63e5ab2a262be416d2f3fa551e91d Mon Sep 17 00:00:00 2001 From: oratis Date: Sun, 9 Aug 2026 23:03:26 +0800 Subject: [PATCH] fix(llm): reconcile cache-hit accounting between the two usage meters MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #20 stopped cache hits from billing real money, but closed only half the gap. It zeroed `usdCents` while deliberately keeping the token counts "for visibility" — and those tokens still reach `agent_runs`. Since `getStats()` skips cache hits entirely, money agreed at zero while SUM(agent_runs.input_tokens) ran ahead of the in-memory counters by exactly the cached volume, with nothing anywhere recording why. The ledger that is meant to back tiered billing was unexplainable from the other meter. Cache hits are now counted in their own `stats.cached` bucket, whose `usdCents` is spend avoided rather than incurred. Two identities hold per process: SUM(cost_usd_cents) === totalUsdCents, and SUM(input_tokens) === Σ byProvider[*].inputTokens + cached.inputTokens. Money agrees outright; tokens agree once cached volume is added back. - llm: `stats.cached` + `recordCacheHit()`, cleared by `resetStats()`; the stored cache entry is never mutated, so `cachedUsdCents` no longer risks decaying to zero on a repeat hit - content-video: `res.usage?.usdCents ?? 25`, not `||`. Zero is a real answer — a cache hit, or any model absent from PRICING — and `||` charged the 25¢ estimate anyway, billing for spend that never happened - usage-ledger: document the cost-based semantics, so nobody "repairs" a well-cached month by re-deriving cost from token counts - llm: export `cacheKey` so hit accounting is testable without a network Scope worth recording: the original over-billing was latent, not active. Only `temperature` 0-or-absent calls are cacheable, and the one such call site (community.js classify) discards `res.usage`. No cached cost ever reached the ledger. This is contract hygiene for the 13 of 15 call sites that do forward usage — the trap springs on the next cacheable call added. Tests: 9 new. Each was verified to fail without its fix (reverting `??` fails 1; removing `recordCacheHit` fails 4). npm test 665/665. Co-Authored-By: Claude Opus 5 --- server/__tests__/llm-cache-billing.test.js | 260 +++++++++++++++++++++ server/agents-v2/content-video.js | 7 +- server/llm/index.js | 54 ++++- server/usage-ledger.js | Bin 9679 -> 10779 bytes 4 files changed, 319 insertions(+), 2 deletions(-) create mode 100644 server/__tests__/llm-cache-billing.test.js diff --git a/server/__tests__/llm-cache-billing.test.js b/server/__tests__/llm-cache-billing.test.js new file mode 100644 index 0000000..1aab26c --- /dev/null +++ b/server/__tests__/llm-cache-billing.test.js @@ -0,0 +1,260 @@ +/** + * Cache-hit accounting contract for llm.complete(). + * + * A cache hit makes no API call and incurs no provider charge, but it still + * flows through every caller that persists `res.usage` into `agent_runs` — and + * from there into `GET /api/usage`, which is meant to be the basis for tiered + * billing. Before this was pinned down, a hit returned the ORIGINAL call's + * usage verbatim, so the ledger charged full price for a request that never + * left the process while `llm.getStats()` (which skips recordUsage() on the + * cached path) reported it as free. The two meters disagreed by exactly the + * cached volume. + * + * The semantics these tests fix in place are cost-based: we bill for money that + * left the building, not for value delivered. + * + * - a hit reports `usdCents: 0` — nothing is charged + * - it keeps `inputTokens` / `outputTokens` — the work is still visible + * - it carries `cachedUsdCents` — the saving stays auditable + * - `stats.cached` accumulates the same volume, so the persisted ledger and + * the in-memory counters RECONCILE instead of merely differing + * + * That last point is the one worth guarding: zeroing the cost alone still left + * the ledger's token columns unexplainable from getStats(). + * + * No network: every test primes the cache directly, so complete() returns from + * the cache branch before any provider is reached. + */ + +const { test } = require('node:test'); +const assert = require('node:assert/strict'); + +const LLM_PATH = require.resolve('../llm'); +const VIDEO_PATH = require.resolve('../agents-v2/content-video'); + +const MODEL = 'claude-sonnet-4-5'; + +function freshLlm() { + delete require.cache[LLM_PATH]; + // `../cache` is deliberately NOT reloaded: complete() and this test must + // share the one defaultCache singleton for priming to be visible. + const llm = require('../llm'); + require('../cache').defaultCache.clear(); + llm.resetStats(); + return llm; +} + +/** + * Store a result under the exact key complete() will compute, so the next + * matching call is served from cache. `usage` mirrors a live call's shape: + * real token counts and a real, non-zero cost. + */ +function primeCache(llm, messages, usage) { + const key = llm.cacheKey('anthropic', MODEL, messages, undefined); + require('../cache').defaultCache.set(key, { + provider: 'anthropic', + model: MODEL, + text: 'cached answer', + toolUses: [], + raw: {}, + usage, + stopReason: 'end_turn', + }, 60_000); + return key; +} + +// temperature 0 is what makes a call cacheable at all; provider/model are +// explicit so the assertions do not depend on ambient env vars. +const hit = (messages) => ({ + provider: 'anthropic', model: MODEL, messages, temperature: 0, +}); + +test('cache hit: bills nothing, keeps tokens, and reports the avoided spend', async () => { + const llm = freshLlm(); + const messages = [{ role: 'user', content: 'cache-billing: zero cost' }]; + primeCache(llm, messages, { inputTokens: 1000, outputTokens: 500, usdCents: 111 }); + + const res = await llm.complete(hit(messages)); + + assert.equal(res.fromCache, true, 'served from cache'); + assert.equal(res.usage.usdCents, 0, 'a cache hit must not be billed'); + assert.equal(res.usage.billedUsdCents, 0); + assert.equal(res.usage.cachedUsdCents, 111, 'the saving stays auditable'); + // Tokens survive: they are what the ledger reports as work done. + assert.equal(res.usage.inputTokens, 1000); + assert.equal(res.usage.outputTokens, 500); + assert.equal(res.text, 'cached answer', 'the cached payload itself is intact'); +}); + +test('cache hit: stays out of the billed counters', async () => { + const llm = freshLlm(); + const messages = [{ role: 'user', content: 'cache-billing: not billed' }]; + primeCache(llm, messages, { inputTokens: 1000, outputTokens: 500, usdCents: 111 }); + + await llm.complete(hit(messages)); + const stats = llm.getStats(); + + assert.equal(stats.totalUsdCents, 0, 'no money left the building'); + assert.deepEqual(stats.byProvider, {}, 'no provider was called'); + assert.deepEqual(stats.byModel, {}); +}); + +test('cache hit: counted in stats.cached so the two meters reconcile', async () => { + const llm = freshLlm(); + const messages = [{ role: 'user', content: 'cache-billing: reconcile' }]; + primeCache(llm, messages, { inputTokens: 1000, outputTokens: 500, usdCents: 111 }); + + const res = await llm.complete(hit(messages)); + + // What a caller persists into agent_runs, mirroring agent-runtime/index.js. + const persisted = { + cost_usd_cents: res.usage.usdCents || 0, + input_tokens: res.usage.inputTokens || 0, + output_tokens: res.usage.outputTokens || 0, + }; + + const stats = llm.getStats(); + const billedTokens = Object.values(stats.byProvider) + .reduce((sum, b) => sum + b.inputTokens, 0); + + // Money: the ledger and getStats() agree outright. + assert.equal(persisted.cost_usd_cents, stats.totalUsdCents); + // Tokens: the ledger records volume the billed counters deliberately skip. + // It reconciles only once the cached bucket is added back — which is the + // whole reason that bucket exists. + assert.equal(persisted.input_tokens, billedTokens + stats.cached.inputTokens); + assert.equal(stats.cached.calls, 1); + assert.equal(stats.cached.inputTokens, 1000); + assert.equal(stats.cached.outputTokens, 500); + assert.equal(stats.cached.usdCents, 111, 'cached.usdCents is spend AVOIDED'); +}); + +test('repeat hits on one key keep reporting the full saving', async () => { + const llm = freshLlm(); + const messages = [{ role: 'user', content: 'cache-billing: repeat' }]; + primeCache(llm, messages, { inputTokens: 1000, outputTokens: 500, usdCents: 111 }); + + const first = await llm.complete(hit(messages)); + const second = await llm.complete(hit(messages)); + + // Guards against zeroing the STORED entry instead of a per-hit copy, which + // would silently decay the audit trail to zero after the first read. + assert.equal(first.usage.cachedUsdCents, 111); + assert.equal(second.usage.cachedUsdCents, 111); + assert.equal(second.usage.usdCents, 0); + + const stats = llm.getStats(); + assert.equal(stats.cached.calls, 2); + assert.equal(stats.cached.usdCents, 222, 'avoided spend accumulates per hit'); + assert.equal(stats.totalUsdCents, 0, 'still nothing billed'); +}); + +test('resetStats clears the cached bucket too', async () => { + const llm = freshLlm(); + const messages = [{ role: 'user', content: 'cache-billing: reset' }]; + primeCache(llm, messages, { inputTokens: 1000, outputTokens: 500, usdCents: 111 }); + + await llm.complete(hit(messages)); + assert.equal(llm.getStats().cached.calls, 1); + + llm.resetStats(); + assert.deepEqual(llm.getStats().cached, { + calls: 0, inputTokens: 0, outputTokens: 0, usdCents: 0, + }); +}); + +test('cache hit with no usage on the stored entry does not fabricate one', async () => { + const llm = freshLlm(); + const messages = [{ role: 'user', content: 'cache-billing: no usage' }]; + primeCache(llm, messages, undefined); + + const res = await llm.complete(hit(messages)); + + assert.equal(res.fromCache, true); + assert.equal(res.usage, undefined, 'absent usage stays absent'); + // Nothing to count, but the hit still happened. + const stats = llm.getStats(); + assert.equal(stats.cached.calls, 1); + assert.equal(stats.cached.usdCents, 0); + assert.equal(stats.totalUsdCents, 0); +}); + +test('a non-cacheable call (temperature > 0) never consults the cache', async () => { + const llm = freshLlm(); + const messages = [{ role: 'user', content: 'cache-billing: hot temperature' }]; + primeCache(llm, messages, { inputTokens: 1000, outputTokens: 500, usdCents: 111 }); + + // Same prompt, non-zero temperature: complete() must fall through to the + // provider rather than serving the primed entry. With no API key set that + // surfaces as a throw, which is exactly the proof we want — and it documents + // why the bug stayed latent: every agent but community's classify pass sends + // a non-zero temperature, so almost nothing is cacheable today. + const origKey = process.env.ANTHROPIC_API_KEY; + delete process.env.ANTHROPIC_API_KEY; + try { + await assert.rejects( + () => llm.complete({ provider: 'anthropic', model: MODEL, messages, temperature: 0.7 }), + /ANTHROPIC_API_KEY not set/ + ); + } finally { + if (origKey !== undefined) process.env.ANTHROPIC_API_KEY = origKey; + } + assert.equal(llm.getStats().cached.calls, 0, 'no cache hit was recorded'); +}); + +// --------------------------------------------------------------------------- +// Downstream: agents must not re-inflate a zero cost back into a charge. + +/** Load content-video against a stubbed ../llm, then restore the real one. */ +function withStubbedLlm(completeImpl, fn) { + const original = require.cache[LLM_PATH]; + delete require.cache[VIDEO_PATH]; + require.cache[LLM_PATH] = { + exports: { complete: completeImpl, isConfigured: () => true }, + loaded: true, id: LLM_PATH, filename: LLM_PATH, children: [], parent: null, + }; + try { + return fn(require('../agents-v2/content-video')); + } finally { + delete require.cache[VIDEO_PATH]; + if (original) require.cache[LLM_PATH] = original; + else delete require.cache[LLM_PATH]; + } +} + +const VIDEO_RESULT = (usage) => ({ + text: '', + usage, + toolUses: [{ + name: 'compose_video', + input: { title: 'T', hook: 'H', beats: [{ voiceover: 'v', visual: 'x' }], cta: 'C' }, + }], +}); + +test('content-video: a zero-cost script is not re-billed at the 25c estimate', async () => { + // `|| 25` treated a legitimate zero — a cache hit, or any model missing from + // llm's PRICING table — as "cost unknown" and charged the estimate anyway. + const out = await withStubbedLlm( + async () => VIDEO_RESULT({ inputTokens: 1000, outputTokens: 500, usdCents: 0, cachedUsdCents: 111 }), + (agent) => agent.run( + { brief: 'b', include_voiceover: false }, + { emit: () => {}, logger: console } + ) + ); + + assert.equal(out.cost.usdCents, 0, 'zero cost must survive into the agent output'); + assert.equal(out.cost.inputTokens, 1000, 'tokens still reported'); + assert.equal(out.cost.outputTokens, 500); +}); + +test('content-video: genuinely absent usage still falls back to the estimate', async () => { + const out = await withStubbedLlm( + async () => VIDEO_RESULT(undefined), + (agent) => agent.run( + { brief: 'b', include_voiceover: false }, + { emit: () => {}, logger: console } + ) + ); + + assert.equal(out.cost.usdCents, 25, 'unknown cost is still estimated, not zeroed'); +}); diff --git a/server/agents-v2/content-video.js b/server/agents-v2/content-video.js index 3629dc2..0a8857f 100644 --- a/server/agents-v2/content-video.js +++ b/server/agents-v2/content-video.js @@ -135,7 +135,12 @@ Write the video package. Call compose_video.`; ctx.emit('progress', { step: 'complete', message: 'Video package ready' }); - const scriptCost = res.usage?.usdCents || 25; + // `??`, not `||`: zero is a real answer, not a missing one. A cache hit + // reports usdCents 0 by design, and so does any live call on a model absent + // from llm's PRICING table (or one small enough to round to zero). `||` + // read all three as "unknown" and charged the 25¢ estimate anyway, billing + // for spend that never happened. Only genuinely absent usage falls back. + const scriptCost = res.usage?.usdCents ?? 25; const voiceCharCount = includeVoice && audioDataUrl ? [pkg.hook, ...pkg.beats.map(b => b.voiceover), pkg.cta].filter(Boolean).join(' ').length : 0; diff --git a/server/llm/index.js b/server/llm/index.js index fcdf4c3..cf61a45 100644 --- a/server/llm/index.js +++ b/server/llm/index.js @@ -10,6 +10,13 @@ * - Tool use / function calling (Anthropic + OpenAI both supported) * - Retry with exponential backoff on 429/5xx * + * Metering contract: a cache hit is FREE. It reports `usdCents: 0` and is kept + * out of the billed counters, because no request was made and no provider + * charged us. Its token counts and `cachedUsdCents` (the spend avoided) survive + * for visibility, and `stats.cached` accumulates the same volume so the + * persisted ledger in `agent_runs` stays reconcilable against getStats(). Only + * calls with `temperature` 0 or absent are cacheable at all — see complete(). + * * NOT supported: streaming. Every provider call is a single fetch + json(). * (This header claimed "Streaming via async iterator" for a long time; it was * never implemented, and Conductor's plan-progress SSE had to fall back to @@ -32,10 +39,29 @@ const DEFAULT_PROVIDER = process.env.LLM_DEFAULT_PROVIDER || process.env.GOOGLE_AI_API_KEY ? 'google' : null); // Usage accumulator (reset via resetStats) +// +// `byProvider` / `byModel` / `totalUsdCents` meter money that actually left the +// building: recordUsage() runs on the live-call path only, so a cache hit adds +// nothing to them. But a cache hit still reports its original token counts (see +// complete()), and those reach `agent_runs` — so with cached volume tracked +// nowhere, this meter and the persisted ledger could never be reconciled; the +// ledger would just look inexplicably larger with no way to say why. +// +// `cached` closes that gap. It counts hits separately, and its `usdCents` is +// spend *avoided* rather than spend incurred. Within one process lifetime, over +// the runs that process recorded, both of these hold: +// +// SUM(agent_runs.cost_usd_cents) === totalUsdCents +// SUM(agent_runs.input_tokens) === Σ byProvider[*].inputTokens + cached.inputTokens +// +// Money agrees outright; tokens agree once cached volume is added back. +const emptyCacheBucket = () => ({ calls: 0, inputTokens: 0, outputTokens: 0, usdCents: 0 }); + const stats = { byProvider: {}, // provider → { calls, inputTokens, outputTokens, usdCents } byModel: {}, totalUsdCents: 0, + cached: emptyCacheBucket(), // cache hits: free, but not invisible }; function recordUsage(provider, model, inputTokens, outputTokens, usdCents) { @@ -51,6 +77,19 @@ function recordUsage(provider, model, inputTokens, outputTokens, usdCents) { stats.totalUsdCents += usdCents; } +/** + * Record a cache hit. Deliberately NOT recordUsage(): no request was made, so + * no provider charged us, and folding this into the billed buckets would + * reintroduce exactly the over-billing this separation exists to prevent. + * `avoidedUsdCents` is what the hit would have cost had it gone out live. + */ +function recordCacheHit(inputTokens, outputTokens, avoidedUsdCents) { + stats.cached.calls += 1; + stats.cached.inputTokens += inputTokens; + stats.cached.outputTokens += outputTokens; + stats.cached.usdCents += avoidedUsdCents; +} + function getStats() { return JSON.parse(JSON.stringify(stats)); } @@ -59,6 +98,7 @@ function resetStats() { stats.byProvider = {}; stats.byModel = {}; stats.totalUsdCents = 0; + stats.cached = emptyCacheBucket(); } // Pricing per 1M tokens. Update as prices change. @@ -371,8 +411,17 @@ async function complete({ // cents for a request that never left the process, and disagree with // getStats(). Report zero spend, keep the token counts for visibility, // and let `fromCache` explain the discrepancy to anyone comparing. + // + // The stored entry is never mutated — `usage` below is a fresh object on + // every hit, built from the original — so `cachedUsdCents` stays accurate + // across repeat hits on the same key rather than decaying to zero. + const base = cached.usage || {}; + const avoidedUsdCents = base.usdCents || 0; + // Tracked here, not in the billed buckets, so the persisted ledger's + // token counts remain reconcilable against getStats(). See `stats`. + recordCacheHit(base.inputTokens || 0, base.outputTokens || 0, avoidedUsdCents); const usage = cached.usage - ? { ...cached.usage, usdCents: 0, billedUsdCents: 0, cachedUsdCents: cached.usage.usdCents || 0 } + ? { ...base, usdCents: 0, billedUsdCents: 0, cachedUsdCents: avoidedUsdCents } : cached.usage; return { ...cached, usage, fromCache: true }; } @@ -455,4 +504,7 @@ module.exports = { resetStats, computeCostCents, PRICING, + // exported for tests — lets a test prime defaultCache for the exact key + // complete() will look up, so cache-hit accounting is testable offline. + cacheKey, }; diff --git a/server/usage-ledger.js b/server/usage-ledger.js index ef4367b05fe37bc1683802134bb57662e6895866..abb86002cf96f9b2a86cc701fefcf367325051b3 100644 GIT binary patch delta 1111 zcmZWpL5>qK5R~@FD_YBC7bRKFAPy@|fCNbFJ>%G&88aUD$o6E&X?O%TK7qtT_yaGY z+7oFJNRc9?+tt-o)%o@A`@@fTwY)aAW9od#WD=8=DHe7cI!uM46tbO3ExRZ53?FJj z7v9V+lDfy6K6_1vMDqslz?=^He_-{EYV)-1*pUC<~!Iu|Ce!n3iMNrzz%!W?#BWNuTVe?DiJLOt0uUik%NkJ@W_{ zKxC5STOUoJ#>a6g`yxF9W}&+ZB2)S6SNi?+8QRDHRXB6V zk`C;2vq54(!-dyi;+fVdb+h100jE4N*7R915+4_V=!RwvVOtU13bU!=8|60myd5BS zVn-7BB{`w@A0Fr$q8p#CRiVQfM7NHUKk33M$!bC+u)3OeKvTen4&zq_v}o)0U^2iV zv(wjdq$xw{s=~~4@G$2nNtrQr>fm(XW6>29?=bnG4_D6GcrsyPavc0gY47M0RIzF) z6v4U`zD`{p$AVGacTC=Dr(^50m$<3&>5?2IwxAyW&*2RmhdY<8B!)AM!Pv^L67HkS z7=R`7C=tfaMnkzESnhUZ4qU_zO>LXFH3hRDC1VZqz=NdoAnQe>`$}aq(aCPMC6NUo