From 5501d5a8fb37b00f347e6346c56d2bb040c1acf4 Mon Sep 17 00:00:00 2001 From: Erhnysr Date: Tue, 6 Oct 2026 10:34:21 +0000 Subject: [PATCH 1/2] fix(reconcile): flag a partial ledger read instead of reporting it as complete loadGatewayRows kept the rows it had read when a page after the first failed, or when the page cap was reached with a cursor still pending, and nothing marked the result as short. A short ledger reconciles cleanly: every charge on the unread pages drops out of chargedNotRecorded, so `clawrouter reconcile` printed no unrecorded charges and exited 0. Keep the rows, but record why the read stopped. formatReconcile prints a "Partial ledger" warning above the totals, and the command exits 1 so a scheduled check does not read a partial ledger as a clean one. Exit 2 for unrecorded charges is unchanged. --- README.md | 5 +- src/cli.ts | 8 +-- src/reconcile.test.ts | 120 +++++++++++++++++++++++++++++++++++++++++- src/reconcile.ts | 52 +++++++++++++++--- 4 files changed, 171 insertions(+), 14 deletions(-) diff --git a/README.md b/README.md index e1afaef5..3ddc7e14 100644 --- a/README.md +++ b/README.md @@ -697,8 +697,9 @@ table has drifted from the gateway's. **Charged but not in this machine's journal** is the one to look at hardest: money left the account for a call this machine did not make — expected if the same key is used on another machine or by another BlockRun product, and worth investigating if not. Exit code `2` in that -case, so a scheduled check can alert on it. Rows still **pending pricing** are -excluded from the totals rather than counted as $0. +case, so a scheduled check can alert on it, and `1` when the ledger could not be +read in full, since the unread pages could hold exactly those charges. Rows still +**pending pricing** are excluded from the totals rather than counted as $0. Your per-call sum will always be less than your card statement by exactly the top-up fees, which are charged at purchase and never appear as ledger rows. That diff --git a/src/cli.ts b/src/cli.ts index de0d9b12..6d700d46 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -308,12 +308,12 @@ async function cmdReconcile(days: number): Promise { process.exit(1); } try { - const { reconcile, formatReconcile } = await import("./reconcile.js"); + const { reconcile, formatReconcile, reconcileExitCode } = await import("./reconcile.js"); const result = await reconcile(resolved.key, days); console.log(formatReconcile(result, days)); - // Money charged that this machine cannot account for is the one outcome - // worth a non-zero exit, so a scheduled check can alert on it. - process.exitCode = result.chargedNotRecorded.length > 0 ? 2 : 0; + // Non-zero so a scheduled check can alert: unaccounted charges, or a + // ledger read too short to rule them out. + process.exitCode = reconcileExitCode(result); } catch (error) { console.error(`✗ ${error instanceof Error ? error.message : String(error)}`); process.exit(1); diff --git a/src/reconcile.test.ts b/src/reconcile.test.ts index d5f1dc05..e9855939 100644 --- a/src/reconcile.test.ts +++ b/src/reconcile.test.ts @@ -18,8 +18,14 @@ * would report a number that changes on the next run. */ -import { describe, it, expect } from "vitest"; -import { joinRows, formatReconcile, type LocalRow } from "./reconcile.js"; +import { afterEach, describe, it, expect, vi } from "vitest"; +import { + joinRows, + formatReconcile, + loadGatewayRows, + reconcileExitCode, + type LocalRow, +} from "./reconcile.js"; import type { UsageRow } from "./api-key.js"; const local = (requestId: string, cost: number, model = "openai/gpt-4o-mini"): LocalRow => ({ @@ -130,3 +136,113 @@ describe("formatReconcile", () => { expect(out).toContain("0.000007"); }); }); + +describe("loadGatewayRows", () => { + // One ledger page as GET /v1/usage returns it. + const page = (ids: string[], nextCursor: string | null) => + new Response( + JSON.stringify({ + data: ids.map((id) => ({ + request_id: id, + timestamp: "2026-09-05T18:00:00Z", + endpoint: "/v1/chat/completions", + cost_usd: 0.01, + cost_state: "priced", + })), + next_cursor: nextCursor, + }), + { status: 200, headers: { "content-type": "application/json" } }, + ); + + afterEach(() => { + vi.unstubAllGlobals(); + }); + + it("follows the cursor to the last page, passing it back verbatim", async () => { + const fetchMock = vi + .fn() + .mockResolvedValueOnce(page(["a"], "opaque/cursor=1")) + .mockResolvedValueOnce(page(["b"], null)); + vi.stubGlobal("fetch", fetchMock); + + const r = await loadGatewayRows("brk_live_test", "2026-09-01T00:00:00.000Z"); + + expect(r?.rows.map((x) => x.requestId)).toEqual(["a", "b"]); + expect(new URL(fetchMock.mock.calls[1][0] as string).searchParams.get("cursor")).toBe( + "opaque/cursor=1", + ); + }); + + it("marks the ledger incomplete when a page after the first fails", async () => { + // Page 2 is lost. Page 1 alone reconciles "cleanly": every charge on the + // missing pages silently drops out of chargedNotRecorded, the finding this + // command exists to surface. + vi.stubGlobal( + "fetch", + vi + .fn() + .mockResolvedValueOnce(page(["a"], "c1")) + .mockResolvedValueOnce(new Response("upstream error", { status: 502 })), + ); + + const r = await loadGatewayRows("brk_live_test", "2026-09-01T00:00:00.000Z"); + + expect(r?.rows.map((x) => x.requestId)).toEqual(["a"]); + expect(r?.incomplete).toMatch(/page 2/); + }); + + it("marks the ledger incomplete when pages are left past the cap", async () => { + // Every page says there is more. Stopping at the cap is fine; passing what + // was read off as the whole ledger is not. + const fetchMock = vi.fn().mockImplementation(async () => page(["x"], "more")); + vi.stubGlobal("fetch", fetchMock); + + const r = await loadGatewayRows("brk_live_test", "2026-09-01T00:00:00.000Z", 3); + + expect(fetchMock).toHaveBeenCalledTimes(3); + expect(r?.rows).toHaveLength(3); + expect(r?.incomplete).toMatch(/more than 3 pages/); + }); + + it("still returns undefined when the first page fails", async () => { + vi.stubGlobal("fetch", vi.fn().mockResolvedValue(new Response("", { status: 401 }))); + await expect(loadGatewayRows("brk_live_test", "2026-09-01T00:00:00.000Z")).resolves.toBe( + undefined, + ); + }); + + it("leaves a complete read unmarked", async () => { + vi.stubGlobal("fetch", vi.fn().mockResolvedValueOnce(page(["a"], null))); + const r = await loadGatewayRows("brk_live_test", "2026-09-01T00:00:00.000Z"); + expect(r?.incomplete).toBeUndefined(); + }); +}); + +describe("partial ledger", () => { + const partial = () => { + const r = joinRows([local("a", 0.01)], [remote("a", 0.01)]); + r.ledgerIncomplete = "page 2 of the ledger could not be read"; + return r; + }; + + it("says so before the totals it qualifies", () => { + const out = formatReconcile(partial(), 7); + expect(out).toContain("Partial ledger: page 2 of the ledger could not be read"); + expect(out.indexOf("Partial ledger")).toBeLessThan(out.indexOf("Gateway charged")); + }); + + it("does not exit 0, since unread pages can hide unrecorded charges", () => { + expect(reconcileExitCode(partial())).toBe(1); + }); + + it("keeps exit 2 for unrecorded charges, partial or not", () => { + const r = joinRows([], [remote("ghost", 2.43)]); + expect(reconcileExitCode(r)).toBe(2); + r.ledgerIncomplete = "page 2 of the ledger could not be read"; + expect(reconcileExitCode(r)).toBe(2); + }); + + it("exits 0 for a complete, clean reconciliation", () => { + expect(reconcileExitCode(joinRows([local("a", 0.01)], [remote("a", 0.01)]))).toBe(0); + }); +}); diff --git a/src/reconcile.ts b/src/reconcile.ts index c72fa982..df392e05 100644 --- a/src/reconcile.ts +++ b/src/reconcile.ts @@ -46,6 +46,8 @@ export type ReconcileResult = { unavailableDays: string[]; /** Journal entries with no request id at all — unreconcilable, not a mismatch. */ unkeyedLocalCount: number; + /** Why the ledger read stopped before its last page, if it did. */ + ledgerIncomplete?: string; }; /** Read journal entries written on or after `since`. */ @@ -91,24 +93,42 @@ export async function loadLocalRows(since: Date): Promise<{ rows: LocalRow[]; un return { rows, unkeyed }; } -/** Pull the whole ledger window, following the opaque cursor. */ +/** + * Pull the whole ledger window, following the opaque cursor. + * + * When the read stops early (a later page fails, or pages are left past + * `maxPages`) the rows read so far are kept, but `incomplete` says why. A short + * ledger looks clean on its own: every charge on the unread pages silently + * drops out of `chargedNotRecorded`. + */ export async function loadGatewayRows( apiKey: string, from: string, maxPages = 40, -): Promise<{ rows: UsageRow[]; unavailableDays: string[] } | undefined> { +): Promise<{ rows: UsageRow[]; unavailableDays: string[]; incomplete?: string } | undefined> { const rows: UsageRow[] = []; const unavailableDays = new Set(); let cursor: string | undefined; for (let page = 0; page < maxPages; page++) { const result = await fetchUsagePage(apiKey, { from, limit: 500, cursor }); - if (!result) return page === 0 ? undefined : { rows, unavailableDays: [...unavailableDays] }; + if (!result) { + if (page === 0) return undefined; + return { + rows, + unavailableDays: [...unavailableDays], + incomplete: `page ${page + 1} of the ledger could not be read`, + }; + } rows.push(...result.rows); result.unavailableDays.forEach((d) => unavailableDays.add(d)); - if (!result.nextCursor) break; + if (!result.nextCursor) return { rows, unavailableDays: [...unavailableDays] }; cursor = result.nextCursor; // opaque by contract — passed back, never parsed } - return { rows, unavailableDays: [...unavailableDays] }; + return { + rows, + unavailableDays: [...unavailableDays], + incomplete: `the ledger has more than ${maxPages} pages for this window; try fewer --days`, + }; } /** Amounts equal to the cent, allowing for float representation. */ @@ -171,7 +191,21 @@ export async function reconcile(apiKey: string, days: number): Promise 0) return 2; + if (r.ledgerIncomplete) return 1; + return 0; } const usd = (n: number): string => (Math.abs(n) < 0.01 ? `$${n.toFixed(6)}` : `$${n.toFixed(2)}`); @@ -182,6 +216,12 @@ export function formatReconcile(r: ReconcileResult, days: number): string { const mismatched = r.matched.filter((m) => Math.abs(m.deltaUsd) > CENT_EPSILON); out.push(`\nBlockRun reconciliation — last ${days} day${days === 1 ? "" : "s"}\n`); + if (r.ledgerIncomplete) { + // First, because it qualifies every number below. + out.push(` ⚠ Partial ledger: ${r.ledgerIncomplete}.`); + out.push(` The totals and lists below cover only the pages that were read;`); + out.push(` charges on the unread pages are not checked.\n`); + } out.push( ` Gateway charged: ${usd(r.gatewayTotalUsd)} (${r.matched.length + r.chargedNotRecorded.length} settled calls)`, ); From 9d46d71f931e3cf0c101b905d9c7fe2c05306770 Mon Sep 17 00:00:00 2001 From: Erhnysr Date: Tue, 6 Oct 2026 11:20:04 +0000 Subject: [PATCH 2/2] fix(reconcile): stop at a repeated ledger cursor; say only the gateway side is partial A ledger that hands back a cursor already requested would be followed until the page cap, appending the same rows on every pass. Remember the cursors requested and stop, marked incomplete, when one comes back. The partial-ledger warning said the totals and lists cover only the pages read, but the journal total and the recorded-locally list come from the whole local window. Say that only the gateway side is short, and that calls billed on unread pages show up as recorded with no ledger row. --- src/reconcile.test.ts | 38 ++++++++++++++++++++++++++++++++++---- src/reconcile.ts | 27 +++++++++++++++++++++------ 2 files changed, 55 insertions(+), 10 deletions(-) diff --git a/src/reconcile.test.ts b/src/reconcile.test.ts index e9855939..f7baa25f 100644 --- a/src/reconcile.test.ts +++ b/src/reconcile.test.ts @@ -192,18 +192,39 @@ describe("loadGatewayRows", () => { }); it("marks the ledger incomplete when pages are left past the cap", async () => { - // Every page says there is more. Stopping at the cap is fine; passing what - // was read off as the whole ledger is not. - const fetchMock = vi.fn().mockImplementation(async () => page(["x"], "more")); + // Every page says there is more, each with a fresh cursor. Stopping at the + // cap is fine; passing what was read off as the whole ledger is not. + let n = 0; + const fetchMock = vi.fn().mockImplementation(async () => { + n++; + return page([`x${n}`], `c${n}`); + }); vi.stubGlobal("fetch", fetchMock); const r = await loadGatewayRows("brk_live_test", "2026-09-01T00:00:00.000Z", 3); expect(fetchMock).toHaveBeenCalledTimes(3); - expect(r?.rows).toHaveLength(3); + expect(r?.rows.map((x) => x.requestId)).toEqual(["x1", "x2", "x3"]); expect(r?.incomplete).toMatch(/more than 3 pages/); }); + it("stops at a cursor it has already requested instead of reading that page again", async () => { + // Page 2 hands back the cursor that produced it. Following it would append + // page 2's rows on every pass until the cap and count those charges twice. + const fetchMock = vi + .fn() + .mockResolvedValueOnce(page(["a"], "c1")) + .mockResolvedValueOnce(page(["b"], "c1")) + .mockImplementation(async () => page(["b"], "c1")); + vi.stubGlobal("fetch", fetchMock); + + const r = await loadGatewayRows("brk_live_test", "2026-09-01T00:00:00.000Z", 5); + + expect(fetchMock).toHaveBeenCalledTimes(2); + expect(r?.rows.map((x) => x.requestId)).toEqual(["a", "b"]); + expect(r?.incomplete).toMatch(/stopped advancing after page 2/); + }); + it("still returns undefined when the first page fails", async () => { vi.stubGlobal("fetch", vi.fn().mockResolvedValue(new Response("", { status: 401 }))); await expect(loadGatewayRows("brk_live_test", "2026-09-01T00:00:00.000Z")).resolves.toBe( @@ -231,6 +252,15 @@ describe("partial ledger", () => { expect(out.indexOf("Partial ledger")).toBeLessThan(out.indexOf("Gateway charged")); }); + it("calls only the gateway side short, since the journal still covers the window", () => { + // The journal total and recordedNotCharged come from the full local window; + // only the ledger side is missing pages. + const out = formatReconcile(partial(), 7); + expect(out).toMatch(/gateway total is\s+short/); + expect(out).toMatch(/recorded locally with no settled ledger row/); + expect(out).not.toMatch(/totals and lists below cover only/i); + }); + it("does not exit 0, since unread pages can hide unrecorded charges", () => { expect(reconcileExitCode(partial())).toBe(1); }); diff --git a/src/reconcile.ts b/src/reconcile.ts index df392e05..8a5aec96 100644 --- a/src/reconcile.ts +++ b/src/reconcile.ts @@ -96,10 +96,10 @@ export async function loadLocalRows(since: Date): Promise<{ rows: LocalRow[]; un /** * Pull the whole ledger window, following the opaque cursor. * - * When the read stops early (a later page fails, or pages are left past - * `maxPages`) the rows read so far are kept, but `incomplete` says why. A short - * ledger looks clean on its own: every charge on the unread pages silently - * drops out of `chargedNotRecorded`. + * When the read stops early (a later page fails, the cursor stops advancing, or + * pages are left past `maxPages`) the rows read so far are kept, but + * `incomplete` says why. A short ledger looks clean on its own: every charge on + * the unread pages silently drops out of `chargedNotRecorded`. */ export async function loadGatewayRows( apiKey: string, @@ -108,6 +108,7 @@ export async function loadGatewayRows( ): Promise<{ rows: UsageRow[]; unavailableDays: string[]; incomplete?: string } | undefined> { const rows: UsageRow[] = []; const unavailableDays = new Set(); + const requested = new Set(); let cursor: string | undefined; for (let page = 0; page < maxPages; page++) { const result = await fetchUsagePage(apiKey, { from, limit: 500, cursor }); @@ -122,7 +123,17 @@ export async function loadGatewayRows( rows.push(...result.rows); result.unavailableDays.forEach((d) => unavailableDays.add(d)); if (!result.nextCursor) return { rows, unavailableDays: [...unavailableDays] }; + // A cursor already requested leads back to a page already read. Following + // it would append the same rows again on every pass until `maxPages`. + if (requested.has(result.nextCursor)) { + return { + rows, + unavailableDays: [...unavailableDays], + incomplete: `the ledger's page cursor stopped advancing after page ${page + 1}`, + }; + } cursor = result.nextCursor; // opaque by contract — passed back, never parsed + requested.add(cursor); } return { rows, @@ -218,9 +229,13 @@ export function formatReconcile(r: ReconcileResult, days: number): string { out.push(`\nBlockRun reconciliation — last ${days} day${days === 1 ? "" : "s"}\n`); if (r.ledgerIncomplete) { // First, because it qualifies every number below. + // Only the gateway side is short. The journal still covers the whole window, + // so its total is complete and calls billed on unread pages land in + // recordedNotCharged rather than matched. out.push(` ⚠ Partial ledger: ${r.ledgerIncomplete}.`); - out.push(` The totals and lists below cover only the pages that were read;`); - out.push(` charges on the unread pages are not checked.\n`); + out.push(` Only the ledger pages that were read are compared: the gateway total is`); + out.push(` short, charges on the unread pages are not checked, and calls billed on`); + out.push(` those pages show up as recorded locally with no settled ledger row.\n`); } out.push( ` Gateway charged: ${usd(r.gatewayTotalUsd)} (${r.matched.length + r.chargedNotRecorded.length} settled calls)`,