Files
PaperClipAI/server/src/services/usage-receipts-read.test.ts
T
DottaandPaperclip 199670ba99 fix(accounting): prevent usage receipt stalls during streamed run updates (#20385)
## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work.
> - Native Runner commits usage receipts before it acknowledges retained
events.
> - Usage receipts and streamed run logs update the same run row.
> - A repeatable-read snapshot can become stale before the receipt
writer locks that row.
> - Continuous log writes can exhaust all accounting retries and stall
the retained event.
> - This pull request uses the existing run lock with READ COMMITTED for
standalone receipt writes.
> - Other accounting operations keep their consistent snapshot. Stall
diagnostics retain safe nested error codes.

## Linked Issues or Issue Description

Related: #20235.

**What happened?**

A hosted native run stopped on a retained usage event. Its diagnostic
reported `Error at source seq N`. The saved outbox and accounting
records locate the failing delivery boundary. Traces show repeated
accounting transactions while streamed events still updated the run row.
The historical inner exception is unavailable.

A controlled PostgreSQL reproduction proves a matching defect: a run-log
append after company validation makes the receipt writer's
repeatable-read snapshot stale. Repeated appends exhaust all four
retries with SQLSTATE `40001`. This is a demonstrated failure mechanism;
attribution of the historical incident remains an inference.

**Expected behavior**

Commit the receipt under its existing run-row lock despite concurrent
run-log writes. Observe concurrent finalization and preserve
late-receipt debt. Keep duplicate receipts idempotent and reject
conflicting or cross-company receipts.

**Steps to reproduce**

Run `server/src/services/usage-receipts-read.test.ts`. The concurrency
regression uses real PostgreSQL and the production run-log append
function. It commits a log append after company validation and before
the receipt locks the run. Before the repair, the receipt rejects with a
wrapped `40001` after four attempts. After the repair, it commits once.
The finalization variant verifies that a newly settled run receives
late-receipt debt without replacing settled state.

## What Changed

- Allow aggregate-lock-protected accounting writers to select READ
COMMITTED. Keep repeatable read as the default.
- Use READ COMMITTED only for standalone usage receipt writes. Keep the
existing run lock, immutable receipt journal, replay checks and
transactional budget-work publication.
- Add PostgreSQL regressions for concurrent log appends, concurrent
finalization, duplicate delivery and the unchanged default snapshot.
- Read the outer event-commit error and at most three nested causes for
an existing safe error code. Exclude exception messages and SQL.
- Document receipt isolation and bounded stall diagnostics.

## Verification

- Red: the production receipt writer exhausted four retries with
PostgreSQL `40001` under controlled concurrent run-log appends.
- Red: wrapped database and transport stall diagnostics returned `Error`
instead of `40001` and `ECONNRESET`.
- Green: Runner control-plane tests passed all 207 cases. All 68 server
assertions passed across receipt reads, native usage delivery and cost
accounting. Cost-accounting teardown exceeded its 30-second limit twice
on this loaded host, after all 28 assertions passed. The workspace
project retained its configured 30-second hook limit despite the CLI
override. This is a local suite cleanup failure, not a passing suite;
the same revision passed the complete server suites in CI.
- Server layered TypeScript checking passed, including source and test
layers. Runner TypeScript checking passed. Server checks cover
`ccfe3bdeb1ab88537a03fd6af9044f66863939a5`; the unchanged Runner checks
cover its parent.
- Local environment: macOS arm64, Node 26.4.0, disposable embedded
PostgreSQL. Native usage-delivery tests use the real Rust receiver.
- CI at `ccfe3bdeb1ab88537a03fd6af9044f66863939a5`:
[build](https://github.com/paperclipai/paperclip/actions/runs/42714760702/job/129493568428),
[typecheck](https://github.com/paperclipai/paperclip/actions/runs/42714760702/job/129493568367),
native Runner integration, browser shards and all nine serialized server
groups passed. All 12 general server shards passed in the [full
run](https://github.com/paperclipai/paperclip/actions/runs/42714760702).
Final rollup: 59 successful checks/statuses, three intentionally skipped
checks, no pending or failed checks.
- [Greptile reviewed this revision at 5/5 with no actionable
findings](https://github.com/paperclipai/paperclip/pull/20385#issuecomment-6753163397).
- Hosted evidence came from the task, run, saved sandbox outbox,
accounting receipts and traces. The run started fresh and did not cross
a deployment. No original agent turn was replayed.
- The hosted repair has not been deployed. The original task has not
been resumed. A fixed-revision remote-provider user journey remains
unverified.

## Risks

- READ COMMITTED changes snapshot timing for standalone receipt writes.
The run-row lock protects all mutable receipt/accounting reads and
serializes competing receipts and finalization. Other accounting
operations retain repeatable read.
- Receipt identity, replay conflict checks, company scoping, budget
publication, retry bounds and acknowledgement rules remain intact.
- No persisted format, provider identity or database schema changes.
Existing saved state needs no migration.
- Diagnostics inspect at most four objects and retain only the existing
identifier format, with an 80-character code limit.
- The reproduced race matches the incident boundary and timing, but the
original inner exception was not recorded. Rollout and live acceptance
remain necessary before incident resolution.

## Model Used

- OpenAI Codex, GPT-6 family, with code and shell tools. The exact model
ID and context window are not exposed in this session.

## Checklist

- [x] I have included a thinking path that traces from project context
to this change
- [x] I have specified the model used (with version and capability
details)
- [x] I have checked ROADMAP.md and confirmed this PR does not duplicate
planned core work
- [x] I have searched GitHub for duplicate or related PRs and linked
them above
- [x] I have either (a) linked existing issues with `Fixes: #` / `Closes
#` / `Refs #` OR (b) described the issue in-PR following the relevant
issue template
- [x] I have not referenced internal/instance-local Paperclip issues or
links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip`
URLs)
- [x] My branch name describes the change (e.g. `docs/...`, `fix/...`)
and contains no internal Paperclip ticket id or instance-derived details
- [x] I have run tests locally and they pass
- [x] I have added or updated tests where applicable
- [x] I have updated relevant documentation to reflect my changes
- [x] I have considered and documented any risks above
- [x] All Paperclip CI gates are green
- [x] Greptile is 5/5 with no open P2s, recommendations, or follow-ups
- [x] I will address all Greptile and reviewer comments before
requesting merge

---------

Co-authored-by: Paperclip <noreply@paperclip.ing>
2026-11-09 17:35:13 -06:00

151 lines
9.0 KiB
TypeScript

import { randomBytes, randomUUID } from "node:crypto";
import { eq } from "drizzle-orm";
import { afterAll, beforeAll, describe, expect, it } from "vitest";
import { agents, companies, createDb, heartbeatRuns, runUsageReceipts, type Db } from "@paperclipai/db";
import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "../__tests__/helpers/embedded-postgres.js";
import { withOperationAccountingTransaction } from "./accounting-transaction.js";
import { appendHeartbeatRunEvent } from "./heartbeat-run-events.js";
import { persistUsageReceipt, type UsageReceiptEnvelope } from "./usage-receipts.js";
const support = await getEmbeddedPostgresTestSupport();
describe.skipIf(!support.supported)("usage receipt PostgreSQL reads", () => {
let database: Awaited<ReturnType<typeof startEmbeddedPostgresTestDatabase>>;
let db: Db;
beforeAll(async () => {
database = await startEmbeddedPostgresTestDatabase("usage-receipt-read-");
db = createDb(database.connectionString);
}, 60_000);
afterAll(async () => { await db?.$client.end(); await database?.cleanup(); });
async function fixture() {
const companyId = randomUUID(), agentId = randomUUID(), runId = randomUUID(), sourceId = randomUUID();
await db.insert(companies).values({ id: companyId, name: "Receipt fixture", issuePrefix: companyId.slice(0, 8) });
await db.insert(agents).values({ id: agentId, companyId, name: "Receipt agent", adapterType: "process", status: "active" });
const payload = randomBytes(128 * 1024).toString("base64");
const evidence = { contextSnapshot: { prompt: payload }, runnerProfileJson: { instructions: payload },
resultJson: { stdout: payload }, stdoutExcerpt: payload, stderrExcerpt: payload };
await db.insert(heartbeatRuns).values({ id: runId, companyId, agentId, status: "running", ...evidence,
usageJson: { accountingReceiptSourceId: sourceId, accountingReceiptSequence: 0, preserved: "receipt metadata" } });
const receipt = (sequence: number): UsageReceiptEnvelope => ({ schema: "paperclip/accounting-receipt/v1",
id: randomUUID(), companyId, runId, sourceId, sequence, receivedAt: new Date().toISOString(), adapterType: "process",
receipt: { complete: false, usageBasis: "per_run", costUsd: sequence / 100, billingType: "metered_api" } });
return { companyId, agentId, runId, evidence, receipt };
}
it("updates live usage with a small locked read and preserves all execution evidence", async () => {
const f = await fixture(), reads: unknown[][] = [];
const observed = new Proxy(db, { get(target, key) {
if (key !== "transaction") return Reflect.get(target, key);
return (callback: Parameters<Db["transaction"]>[0], options: Parameters<Db["transaction"]>[1]) => target.transaction(tx => callback(new Proxy(tx, {
get(transaction, property) {
if (property !== "select") return Reflect.get(transaction, property);
return (...fields: Parameters<Db["select"]>) => {
const builder = transaction.select(...fields), from = builder.from.bind(builder);
builder.from = ((...args: Parameters<typeof from>) => {
const query = from(...args);
if (args[0] === heartbeatRuns) {
const execute = query.execute.bind(query);
query.execute = async (...executeArgs: Parameters<typeof execute>) => {
expect(query.toSQL().sql).toContain("for update");
const rows = await execute(...executeArgs); reads.push(rows); return rows;
};
}
return query;
}) as typeof builder.from;
return builder;
};
},
})), options);
} });
await persistUsageReceipt(observed, f.receipt(1));
expect(reads).toHaveLength(1);
expect(reads[0]).toHaveLength(1);
expect(Buffer.byteLength(JSON.stringify(reads))).toBeLessThan(2048);
const [stored] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, f.runId));
expect(stored).toMatchObject(f.evidence);
expect(stored.usageJson).toMatchObject({ preserved: "receipt metadata", accountingReceiptSequence: 1,
budgetExposure: { costCents: "1.0000000" } });
expect(Buffer.byteLength(JSON.stringify(stored))).toBeGreaterThan(512 * 1024);
});
it.each(["run event", "finalization"])("commits a usage receipt after concurrent %s between company validation and the run lock", async mode => {
const f = await fixture();
let interleavings = 0;
const observed = new Proxy(db, { get(target, key) {
if (key !== "transaction") return Reflect.get(target, key);
return (callback: Parameters<Db["transaction"]>[0], options: Parameters<Db["transaction"]>[1]) =>
target.transaction(tx => callback(new Proxy(tx, { get(transaction, property) {
if (property !== "select") return Reflect.get(transaction, property);
return (...fields: Parameters<Db["select"]>) => {
const builder = transaction.select(...fields), from = builder.from.bind(builder);
builder.from = ((...args: Parameters<typeof from>) => {
const query = from(...args);
if (args[0] === companies) {
const execute = query.execute.bind(query);
query.execute = async (...executeArgs: Parameters<typeof execute>) => {
const rows = await execute(...executeArgs);
// Commit the other writer after the snapshot starts, before
// the receipt can acquire the run row next.
if (mode === "run event") {
await appendHeartbeatRunEvent(db, { companyId: f.companyId, runId: f.runId,
agentId: f.agentId, eventType: "lifecycle", message: "stream advanced" });
} else {
await db.update(heartbeatRuns).set({ costAccountedAt: new Date(),
status: "succeeded", finishedAt: new Date() }).where(eq(heartbeatRuns.id, f.runId));
}
interleavings++;
return rows;
};
}
return query;
}) as typeof builder.from;
return builder;
};
} })), options);
} });
const receipt = f.receipt(1);
await expect(persistUsageReceipt(observed, receipt)).resolves.toBeUndefined();
expect(interleavings).toBe(1);
await persistUsageReceipt(db, receipt);
expect(await db.select().from(runUsageReceipts).where(eq(runUsageReceipts.runId, f.runId))).toHaveLength(1);
const [run] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, f.runId));
expect(run.usageJson).toMatchObject({ preserved: "receipt metadata",
accountingReceiptSequence: mode === "run event" ? 1 : 0 });
if (mode === "finalization") {
expect(run.costAccountedAt).not.toBeNull();
expect(run.status).toBe("succeeded");
expect(run.usageJson?.accountingLateReceiptPending).toBe(true);
expect(Object.keys(run.usageJson?.accountingLateReceiptDebts as object)).toEqual([receipt.id]);
}
expect(run.nextEventSeq).toBe(mode === "run event" ? 2 : 1);
expect(run).toMatchObject(f.evidence);
});
it("retains the consistent snapshot for other accounting operations", async () => {
const f = await fixture();
const seen = await withOperationAccountingTransaction(db, f.companyId, async tx => {
const [before] = await tx.select({ seq: heartbeatRuns.nextEventSeq }).from(heartbeatRuns).where(eq(heartbeatRuns.id, f.runId));
await appendHeartbeatRunEvent(db, { companyId: f.companyId, runId: f.runId,
agentId: f.agentId, eventType: "lifecycle", message: "concurrent event" });
const [after] = await tx.select({ seq: heartbeatRuns.nextEventSeq }).from(heartbeatRuns).where(eq(heartbeatRuns.id, f.runId));
return [before.seq, after.seq];
});
expect(seen).toEqual([1, 1]);
const [current] = await db.select({ seq: heartbeatRuns.nextEventSeq }).from(heartbeatRuns).where(eq(heartbeatRuns.id, f.runId));
expect(current.seq).toBe(2);
});
it("serializes competing checkpoints and retains replay conflicts and company isolation", async () => {
const f = await fixture(), first = f.receipt(1), second = f.receipt(2);
await Promise.all([persistUsageReceipt(db, first), persistUsageReceipt(db, second)]);
await persistUsageReceipt(db, first);
const [stored] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, f.runId));
expect(stored.usageJson).toMatchObject({ accountingReceiptSequence: 2, budgetExposure: { costCents: "2.0000000" } });
expect(await db.select().from(runUsageReceipts).where(eq(runUsageReceipts.runId, f.runId))).toHaveLength(2);
await expect(persistUsageReceipt(db, { ...first, receipt: { ...first.receipt, costUsd: 10 } })).rejects.toThrow("Conflicting");
const foreign = await fixture();
await expect(persistUsageReceipt(db, { ...f.receipt(3), companyId: foreign.companyId })).rejects.toThrow("not found");
expect((await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, f.runId)))[0]).toEqual(stored);
});
});