Skip to content

Commit e3f4068

Browse files
committed
fix(usage): persist the absolute context checkpoint in usage rows
Kiro rows in Logs showed only small per-request estimates because the cumulative context figure never reached usage.jsonl. Two individually-correct changes composed into the regression: - fc51700 threaded a Kiro absolute context checkpoint (OcxUsage.contextTotalTokens) through the adapter and the bridge, and proved persistence with a test that re-parses the bridged SSE wire, where responsesUsage() folds the checkpoint into input_tokens / total_tokens. The separate field was not needed on that path. - 0422ce1 (landed later on dev) made the bridge report RAW adapter usage via onUsage and made applyResponseLogMetadata skip wire re-parsing when usageFromBridge is set, so synthetic zero detail objects could no longer be misread as measured cache numbers. After the second change the logged usage is the raw per-attempt object, where the cumulative figure exists only as contextTotalTokens — and normalizeUsageValue() omitted that key from its field whitelist, so it was dropped at write time. Zero rows in a 5202-row live Kiro sample carried it. normalizeUsageValue() now carries contextTotalTokens, and the read-side validator accepts it. The checkpoint is deliberately NOT folded into totalTokens: it is an absolute snapshot, not a per-request total, and must never be summed across requests. Cache read/write detail is untouched: cost estimation and the cache_detail_missing reason read only the three cache fields, so the provenance behavior 0422ce1 protected still holds. Tests: the new request-log case covers the production composition (onUsage + usageFromBridge) end to end through usage.jsonl, which the existing wire-reparse test could not catch.
1 parent aa22207 commit e3f4068

3 files changed

Lines changed: 151 additions & 2 deletions

File tree

src/usage/log.ts

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -128,6 +128,13 @@ function normalizeUsageValue(usage: OcxUsage | undefined): OcxUsage | undefined
128128
return {
129129
inputTokens: usage.inputTokens,
130130
outputTokens: usage.outputTokens,
131+
// Absolute active-context checkpoint (types.ts). Stateful providers such as Kiro report
132+
// per-attempt usage only, so this field is the ONLY carrier of the cumulative context
133+
// figure once the log records raw adapter usage instead of re-parsing the bridged wire
134+
// (usageFromBridge, request-log.ts). Omitting it here silently dropped Kiro's context
135+
// growth from every persisted row. It is deliberately NOT folded into totalTokens:
136+
// a checkpoint is not a per-request total and must never be summed across requests.
137+
...(typeof usage.contextTotalTokens === "number" ? { contextTotalTokens: usage.contextTotalTokens } : {}),
131138
...(typeof usage.totalTokens === "number" ? { totalTokens: usage.totalTokens } : {}),
132139
...(typeof usage.cachedInputTokens === "number" ? { cachedInputTokens: usage.cachedInputTokens } : {}),
133140
...(typeof usage.cacheReadInputTokens === "number" ? { cacheReadInputTokens: usage.cacheReadInputTokens } : {}),
@@ -162,6 +169,7 @@ function normalizeAttemptUsage(raw: unknown): OcxUsage | null {
162169
if (!isNonNegativeFiniteNumber(usage.inputTokens)
163170
|| !isNonNegativeFiniteNumber(usage.outputTokens)) return null;
164171
for (const key of [
172+
"contextTotalTokens",
165173
"totalTokens",
166174
"cachedInputTokens",
167175
"cacheReadInputTokens",

tests/request-log.test.ts

Lines changed: 98 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -24,8 +24,16 @@ import {
2424
type RequestLogContext,
2525
} from "../src/server/request-log";
2626
import { bridgeToResponsesSSE } from "../src/bridge";
27-
import type { AdapterEvent } from "../src/types";
28-
import type { PersistedUsageEntry } from "../src/usage/log";
27+
import type { AdapterEvent, OcxUsage } from "../src/types";
28+
import {
29+
appendUsageEntry,
30+
readUsageEntries,
31+
resetUsageReadCacheForTests,
32+
type PersistedUsageEntry,
33+
} from "../src/usage/log";
34+
import { mkdtempSync, rmSync } from "node:fs";
35+
import { tmpdir } from "node:os";
36+
import { join } from "node:path";
2937

3038
async function* replayAdapterEvents(events: AdapterEvent[]): AsyncGenerator<AdapterEvent> {
3139
for (const event of events) yield event;
@@ -933,6 +941,94 @@ describe("request log metadata", () => {
933941
});
934942
});
935943

944+
test("deferred logging keeps the checkpoint when the bridge reports raw usage (production path)", async () => {
945+
// Regression guard for the composition that shipped the bug. The test above exercises the
946+
// OLD source of logged usage: re-parsing the bridged wire, where responsesUsage() folds
947+
// contextTotalTokens into input_tokens/total_tokens. Production no longer does that —
948+
// responses/core.ts wires bridgeToResponsesSSE's onUsage callback, stores the RAW adapter
949+
// usage and sets usageFromBridge, which suppresses wire re-parsing. In that shape the
950+
// cumulative figure exists ONLY as contextTotalTokens, so usage-log normalization has to
951+
// carry the field or Kiro context growth vanishes from every persisted row.
952+
const entries: RequestLogEntry[] = [];
953+
let reportedRaw: OcxUsage | undefined;
954+
const logCtx: Partial<RequestLogContext> = {
955+
model: "kiro/claude-opus-5",
956+
provider: "kiro-p9d8524",
957+
usageLogInputTokens: 200,
958+
};
959+
const body = bridgeToResponsesSSE(
960+
replayAdapterEvents([{
961+
type: "done",
962+
usage: {
963+
inputTokens: 58,
964+
outputTokens: 100,
965+
contextTotalTokens: 50_000,
966+
estimated: true,
967+
},
968+
}]),
969+
"kiro/claude-opus-5",
970+
undefined,
971+
undefined,
972+
undefined,
973+
undefined,
974+
undefined,
975+
{
976+
onUsage: usage => {
977+
// Mirror responses/core.ts: store RAW adapter usage and mark provenance so the
978+
// deferred logger does not re-parse the wire.
979+
reportedRaw = usage;
980+
logCtx.usageFromBridge = true;
981+
if (usage) logCtx.usage = usage;
982+
},
983+
},
984+
);
985+
const response = responseWithDeferredRequestLog(
986+
new Response(body, { status: 200, headers: { "content-type": "text/event-stream" } }),
987+
"ocx-test-kiro-raw-usage-checkpoint",
988+
Date.now(),
989+
logCtx,
990+
entry => entries.push(entry),
991+
);
992+
await response.text();
993+
994+
// The bridge hands the logger the RAW adapter usage, not the projected wire shape.
995+
expect(reportedRaw).toMatchObject({ inputTokens: 58, contextTotalTokens: 50_000 });
996+
expect(entries).toHaveLength(1);
997+
const logged = entries[0]?.usage;
998+
expect(logged?.contextTotalTokens).toBe(50_000);
999+
// Cache detail stays absent so cost estimation still reports cache_detail_missing —
1000+
// the provenance behavior that the raw-usage change was introduced to protect.
1001+
expect(logged && "cacheReadInputTokens" in logged).toBe(false);
1002+
expect(logged && "cacheCreationInputTokens" in logged).toBe(false);
1003+
1004+
// End-to-end: the checkpoint must also survive serialization to usage.jsonl. Asserting
1005+
// only the in-memory entry would pass even while persistence silently drops the field,
1006+
// which is exactly how the original regression escaped review.
1007+
const home = mkdtempSync(join(tmpdir(), "ocx-req-log-usage-"));
1008+
const previousHome = process.env.OPENCODEX_HOME;
1009+
process.env.OPENCODEX_HOME = home;
1010+
try {
1011+
resetUsageReadCacheForTests();
1012+
appendUsageEntry({
1013+
requestId: entries[0]!.requestId,
1014+
timestamp: entries[0]!.timestamp,
1015+
provider: entries[0]!.provider,
1016+
model: entries[0]!.model,
1017+
status: entries[0]!.status,
1018+
durationMs: entries[0]!.durationMs,
1019+
usageStatus: entries[0]!.usageStatus,
1020+
...(logged ? { usage: logged } : {}),
1021+
});
1022+
const [persisted] = readUsageEntries();
1023+
expect(persisted?.usage?.contextTotalTokens).toBe(50_000);
1024+
} finally {
1025+
if (previousHome === undefined) delete process.env.OPENCODEX_HOME;
1026+
else process.env.OPENCODEX_HOME = previousHome;
1027+
resetUsageReadCacheForTests();
1028+
rmSync(home, { recursive: true, force: true });
1029+
}
1030+
});
1031+
9361032
test("final logging shows numeric Kiro estimates even when SSE usage is absent", async () => {
9371033
const entries: RequestLogEntry[] = [];
9381034
const response = responseWithDeferredRequestLog(

tests/usage-log.test.ts

Lines changed: 45 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -102,6 +102,51 @@ describe("usage log", () => {
102102
})]);
103103
});
104104

105+
test("persists an absolute context checkpoint for stateful providers", () => {
106+
// Kiro reports per-attempt usage only, so contextTotalTokens is the sole carrier of the
107+
// cumulative context figure once the log stores raw adapter usage (usageFromBridge).
108+
// Dropping it here erased Kiro context growth from every persisted row.
109+
appendUsageEntry({
110+
requestId: "ocx-context-checkpoint",
111+
timestamp: 1,
112+
provider: "kiro",
113+
model: "claude-opus-5",
114+
status: 200,
115+
durationMs: 10,
116+
usageStatus: "estimated",
117+
usage: { inputTokens: 220, outputTokens: 252, contextTotalTokens: 127_000, estimated: true },
118+
totalTokens: 472,
119+
});
120+
expect(readUsageEntries()).toEqual([expect.objectContaining({
121+
requestId: "ocx-context-checkpoint",
122+
usage: expect.objectContaining({
123+
inputTokens: 220,
124+
outputTokens: 252,
125+
contextTotalTokens: 127_000,
126+
estimated: true,
127+
}),
128+
// The checkpoint must NOT be folded into the per-request total.
129+
totalTokens: 472,
130+
})]);
131+
});
132+
133+
test("never invents a context checkpoint when the adapter reported none", () => {
134+
appendUsageEntry({
135+
requestId: "ocx-no-checkpoint",
136+
timestamp: 1,
137+
provider: "kiro",
138+
model: "claude-opus-5",
139+
status: 200,
140+
durationMs: 10,
141+
usageStatus: "estimated",
142+
usage: { inputTokens: 61, outputTokens: 48, estimated: true },
143+
totalTokens: 109,
144+
});
145+
const [entry] = readUsageEntries();
146+
expect(entry?.usage).toBeDefined();
147+
expect(entry?.usage && "contextTotalTokens" in entry.usage).toBe(false);
148+
});
149+
105150
test("persists only canonical ordered attempt fields", () => {
106151
appendUsageEntry({
107152
requestId: "ocx-attempts",

0 commit comments

Comments
 (0)