From a92f616cd0a457c8ba85d994b24e1f92c2e4d1de Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Mon, 2 Nov 2026 12:12:21 -0600 Subject: [PATCH] fix(db): attribute bounded captures to execution owners (#18634) ## Thinking Path > - Paperclip manages agent work through shared server and database services. > - High query volume can spend main-thread time on SQL construction and result decoding. > - The existing bounded response capture counts rows and bytes, but it cannot name the operation that executed a query. > - Bundled callers can be missing, and measuring every parsed JSON value adds work to the diagnostic. > - This pull request carries a semantic execution owner into each measured query and bounds response sizing. > - Operators can rank query volume by owner before choosing a performance fix. ## Linked Issues or Issue Description Refs #17504, #17522, #17537, #17564. **What existing behavior does this improve?** The opt-in `PAPERCLIP_DB_RESPONSE_CAPTURE_WINDOW` diagnostic. **Subsystem affected** Database diagnostics and existing server execution boundaries. **Current behavior** The capture groups by table, operation, and builder caller. It cannot distinguish execution owners that reuse a prepared query. Bundled deployments need source maps for caller locations. The capture visits every returned value and serializes parsed JSON again to estimate its size. **Proposed behavior** Version 2 captures use fixed semantic owners for HTTP requests, delivery queues, execution phases, and budget work. They count completed calls, returned rows, errors, and completion wall time. They sample successful results 1, 17, 33, and so on, with fixed cell and string/byte limits. Complex values remain explicitly unmeasured. Semantic ownership works without source maps. **Reason and benefit** A short census can identify which operations issue the most queries or return the most rows. It preserves each query's execution owner through pooled connections, concurrent operations, and prepared-query reuse. It reduces diagnostic work without claiming per-query CPU attribution. **Breaking changes** Opt-in capture output moves from `entry.v1`/`summary.v1` to `entry.v2`/`summary.v2`. Sampled primitive byte lower bounds replace all-result byte estimates. Consumers must use the new fields and must not extrapolate them into a total. There is no database migration or application API change. ## What Changed - Added `withDatabaseOperation(owner, action)` to the DB package. The server owns semantic labels. Queries retain execution ownership in their completion closure. - Added fixed owners at existing HTTP, delivery, budget, and execution timing boundaries. Delivery work replaces the context of the producer that woke it. - Added complete call/row/error counters and completion wall durations within the existing bounded window. Durations include waits and are not CPU measurements. - Sampled and bounded primitive-value sizing. Complex and oversized values remain unmeasured. Known owners skip repeated stack extraction. - Preserved the deadline, group limit, paced output, query outcomes, and existing coverage exclusions. Updated the operator documentation. - Added real PostgreSQL owner-isolation and prepared-query tests, server scope tests, and plain bundled-runtime proof. - Moved projection-test and benchmark full-response sizing into an explicit test helper. Existing payload-size thresholds remain unchanged; these synthetic checks do not use the production sampler. ## Verification - Final-commit DB capture suites: 43 tests passed in 13.86 seconds against the actual PostgreSQL driver, including concurrent owners, prepared reuse, transaction failure, a dedicated client, sampling, and a query crossing the deadline. DB typecheck passed. - Server attribution and existing delivery/execution/budget suites: 53 tests passed. Final concurrent HTTP GET/JSON POST scope refinement: 5 tests passed. - Runtime bundle suite: 8 existing tests passed. The new no-source-map owner test passed after its fixture was corrected to use a driver thenable. An ordinary native Promise can bypass an overridden `.then`; the real PostgreSQL tests separately cover driver integration. - Observer-only experiment: three alternating pairs per case on Node 24.22.2, macOS arm64, 3,000 calls per run after warm-up. For an already-materialized synthetic JSON result, median capture CPU fell from 82.37 to 1.87 microseconds/call. For a 100-row primitive result, it fell from 8.10 to 4.40 microseconds/call. Every result retained identity and all calls were counted. The new diagnostic intentionally measures less byte data; these are observer costs, not database latency or a hosted application speedup. Disabled-case timings were below one microsecond/call and too small for a performance conclusion. - Final lifecycle regression: 28 unit tests and DB typecheck passed. Closing the last capture disables and replaces owner storage; overlapping captures retain it. - Final-commit full recursive typecheck passed in 38.38 seconds and full build passed in 40.81 seconds. The build stamp matches `83ed4ba9cebd68d48929c46f15ab32d5c0b9687b`. Focused server attribution tests also passed 5/5 before the test-helper-only migration. Full test acceptance will use the repository's parallel CI gates; the unsharded local command takes hours. - Verification failures retained: initial sandbox runs could not open local IPC/PostgreSQL listeners; permitted reruns exercised the real services. One old test expected JSON serialization and was updated to assert explicit unmeasured complex values. The first bundle fixture used the wrong promise boundary, as described above. A retained-callback regression also demonstrated that disabling and reusing the same AsyncLocalStorage instance could resurrect an old owner; replacing the instance after the last capture closes fixes that case. - The first CI run found older projection tests consuming the previous full-response fields. Those consumers now use the full-response test helper, preserving their byte thresholds. The two complete affected route suites plus helper tests passed 115/115 in 73.08 seconds. A temporary full-row query negative control then failed the unchanged 2,048-byte limit at 5,000,812 bytes and was restored; five other service suites passed 34/34 and the affected chat cases passed 3/3. All three previously failing CI shards passed on the corrected head. A local skill-list benchmark smoke check completed 255 captured queries with no in-flight queries or overflow; this was integration verification under concurrent test load, not a timing benchmark. - Two final-head runner jobs lost communication with GitHub before reporting a test result. One targeted retry of those jobs and their dependent aggregate passed. All 53 final-head checks passed, with 3 intentional skips; previously passing suites were preserved. - Hosted capture remains pending until the reviewed revision is deployed and a bounded window is explicitly configured. Reproduce the focused checks with Node 24 and the repository pnpm version: ```sh pnpm exec vitest run packages/db/src/response-capture.test.ts packages/db/src/response-capture-postgres.test.ts pnpm --dir server exec vitest run --config vitest.config.ts src/__tests__/database-operation-attribution.test.ts scripts/bundle-runtime.test.mjs pnpm -r typecheck pnpm build ``` ## Risks - Owner context is active while a valid future capture window is armed, up to 30 minutes before accounting starts. No-window and expired calls take the direct path. Diagnostics still add bounded work while enabled. - A nearest nested owner is reported. Broad `http.request` and unattributed groups remain visible; this does not identify every service callsite or SQL shape. - The existing census excludes tagged/raw explicit-execute/streaming paths and internal protocol commands. Its counts are not PostgreSQL transaction totals. - Completion wall time includes queue/database/network/scheduling waits. Concurrent durations overlap. Sampled bytes exclude complex values, large strings, and values beyond the sizing limits. - Activation is startup-only. Operators must choose the window after artifact preparation, allow rollout/warm-up time, and remove the expired setting afterward. ## Model Used OpenAI Codex, GPT-6 family, with code execution, repository inspection, and parallel agents. The exact deployment model ID and context-window size 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 --- doc/DATABASE.md | 78 +++++++--- packages/db/src/index.ts | 1 + .../db/src/response-capture-postgres.test.ts | 89 ++++++++++-- packages/db/src/response-capture.test.ts | 125 +++++++++++++--- packages/db/src/response-capture.ts | 125 +++++++++++----- scripts/benchmark-github-webhook-ingress.ts | 6 +- server/scripts/benchmark-skill-list.ts | 6 +- server/scripts/bundle-runtime.test.mjs | 36 +++++ .../agent-auth-identity-transfer.test.ts | 6 +- .../agent-record-read-projections.test.ts | 4 +- .../src/__tests__/attention-service.test.ts | 14 +- .../chat-channels.integration.test.ts | 18 +-- .../__tests__/company-skills-service.test.ts | 20 +-- .../conversation-settlement-transfer.test.ts | 6 +- .../database-operation-attribution.test.ts | 137 ++++++++++++++++++ .../github-operation-credentials.test.ts | 6 +- .../heartbeat-run-event-sequencing.test.ts | 6 +- .../heartbeat-run-privacy-routes.test.ts | 4 +- .../full-database-response-capture.test.ts | 62 ++++++++ .../helpers/full-database-response-capture.ts | 115 +++++++++++++++ .../issue-creation-source-read.test.ts | 4 +- .../issue-queued-comments-routes.test.ts | 8 +- .../legacy-workspace-restore-recovery.test.ts | 10 +- ...native-environment-settlement-work.test.ts | 4 +- .../native-settled-process-release.test.ts | 6 +- .../sandbox-provider-schema-reads.test.ts | 6 +- .../tool-effective-assignments.test.ts | 12 +- server/src/app.ts | 2 + server/src/middleware/database-operation.ts | 5 + .../adapters/release-run-read.test.ts | 10 +- server/src/services/budget-tracing.ts | 33 +++-- .../authorization-run-read.test.ts | 6 +- .../github/webhook-ingress.test.ts | 8 +- .../src/services/delivery-work-coordinator.ts | 5 +- .../services/execution-preparation-timing.ts | 29 ++-- .../native-stop-evidence-read.test.ts | 6 +- .../src/services/heartbeat/run-state.test.ts | 18 +-- .../__tests__/helpers/committed-replay.ts | 6 +- .../chat-attachment-reuse.test.ts | 6 +- .../external-chat-wait.integration.test.ts | 6 +- .../paperclip-runner-tool-authority.test.ts | 6 +- .../recovery/issue-state-read.test.ts | 6 +- .../recovery/legacy-disposition-read.test.ts | 6 +- 43 files changed, 844 insertions(+), 228 deletions(-) create mode 100644 server/src/__tests__/database-operation-attribution.test.ts create mode 100644 server/src/__tests__/helpers/full-database-response-capture.test.ts create mode 100644 server/src/__tests__/helpers/full-database-response-capture.ts create mode 100644 server/src/middleware/database-operation.ts diff --git a/doc/DATABASE.md b/doc/DATABASE.md index e617f321dcc..04698b00f19 100644 --- a/doc/DATABASE.md +++ b/doc/DATABASE.md @@ -522,23 +522,59 @@ leave database construction unchanged. An expired window stays inactive after a restart; remove the setting after the investigation. The diagnostic measures awaited Postgres.js `unsafe` responses before Drizzle -column decoding. It retains the Drizzle builder caller for normal, prepared, -transaction, and dedicated-pool execution. It issues no queries. -It logs the public server caller locations, static schema table, operation, -query/row counts, and response value sizes. It emits at most 2,048 aggregate -groups and a summary. Measurement stops at the deadline. Environment-enabled +column decoding. It issues no queries. Configuration is read when each database +client is created; setting the environment on an already-running process does +not install the capture on existing clients. Prepare the deployment artifact +before choosing the UTC window, then start the window after rollout and warm-up. + +Server entry points use `withDatabaseOperation(owner, action)` to name the work +that executes queries. Owners are fixed semantic labels, never request paths, +company or run IDs, user input, or SQL. The execution owner is captured for each +query and retained through completion, including transactions and dedicated +pools. A prepared query reused by different operations keeps the owner of each +execution. The builder caller is separate from that execution owner. +Owner context is active while a valid future window is armed, up to 30 minutes +before its start, so work that crosses the start boundary keeps its owner. Query +accounting starts only at the window start. With no armed window, or after +expiry, the owner helper calls the action directly without a context scope. + +The capture aggregates owner, static schema table, operation, calls, returned +rows, query errors, and total/maximum completion wall time. `totalWallMs` and +`maxWallMs` include pool, database, network, and event-loop waits; they are not +CPU measurements, and concurrent query durations overlap. Timing excludes the +capture's response sizing. Rank calls and returned rows both per second and per +completed service operation; a busy owner is not necessarily wasteful. + +Response sizing samples successful results 1, 17, 33, and so on per aggregate +group (`sampleEvery: 16`). It examines at most +256 cells, 65,536 string code units, and 65,536 value bytes per sampled result; +an individual string over 16,384 code units is not measured. Parsed objects and +other complex values are not serialized. Oversized, complex, or unexamined +values leave an incomplete sample. `sampledValueBytes` is a lower bound over +sampled primitive values, not a total response-size estimate or network bytes. +Do not extrapolate it as the total bytes returned by the database. Inspect +`sampledResults`, `sampledRows`, `measuredValues`, `unmeasuredValues`, and +`incompleteSamples` alongside it. `sizingWallMs` records the diagnostic's sizing +work separately. Use a separate capture-disabled CPU profile to measure normal +processing cost. + +The diagnostic emits at most 2,048 aggregate groups and a summary. Measurement +stops at the deadline. Environment-enabled captures emit at most 64 records per second and can take another 33 seconds to finish writing the bounded output. Wait for the summary before collecting it. It never logs SQL, parameters, result values, connection strings, or query errors. In-flight queries continue normally. -For a bundled server, keep the linked source maps and enable Node's -`--enable-source-maps` option so the diagnostic can resolve public caller -locations. Restore the prior Node options after capture. Sizes still count when -caller locations are unavailable. +Semantic owners work in a bundled server without source maps. For queries +without an explicit owner, keep the linked source maps and enable Node's +`--enable-source-maps` option to resolve public caller locations. Restore prior +Node options after capture. Known semantic owners avoid repeated stack capture. +Queries without an available owner/caller still contribute to the totals. -Look for `paperclip.db_response_capture.entry.v1` and -`paperclip.db_response_capture.summary.v1` in the process logs. A log provider +Look for `paperclip.db_response_capture.entry.v2` and +`paperclip.db_response_capture.summary.v2` in the process logs. Version 2 uses +sampled, bounded primitive-value sizing; do not interpret it as the version 1 +all-result byte estimate. A log provider can store `event` as a structured field instead of message text. Filter by that field or read the bounded window from the exact deployment. Check the summary and group totals, including the unattributed overflow group. @@ -552,22 +588,26 @@ Fetch a complete capture as follows: from zero through `groupPages - 1`, filtering on the entry event, `captureId`, and `groupPage`. Request at least `groupPageSize` matching records per page. A structured query can use - `@event:paperclip.db_response_capture.entry.v1 AND @captureId: AND @groupPage:0`. + `@event:paperclip.db_response_capture.entry.v2 AND @captureId: AND @groupPage:0`. 3. If the provider's record limit is smaller than a page, fetch each `groupIndex` separately with the same capture ID. Each index matches one entry. Do not split by timestamp: entries can share a timestamp. 4. Deduplicate by `(captureId, groupIndex)`. Require every index from zero through `groups - 1`, with no gaps. Entry count must equal `groups`, summed - `calls` must equal `completedQueries`, and summed `responseValueBytes` must - equal the summary total. A missing page is an incomplete measurement. + `calls` must equal `completedQueries`, and summed `rows`, `sampledResults`, + and `sampledValueBytes` must equal their summary totals. A missing page is an + incomplete measurement. Keep overflow and unattributed groups visible. Tagged raw-driver calls, streams, unawaited raw-driver dispatch, and protocol overhead are not measured. Relational queries use a driver-level caller fallback. -Queries still in flight at the deadline are reported separately. Sizes describe -driver values before column decoding, not billed network bytes. Complex parsed -values use JSON size estimates, counted in `estimatedValues`. Reconcile them with -provider metering and socket measurements. Serialization adds temporary CPU and memory work; -measure the final transfer rate after the window expires. +Queries still in flight at the deadline are reported separately. The census does +not include every PostgreSQL statement or internal transaction command, so its +calls are not interchangeable with database-wide commit counters. It does not +measure SQL compilation, driver parsing CPU, or Drizzle row-mapping CPU. Use the +ranked owners to choose a narrow follow-up profile or synchronous-stage +measurement; do not attribute CPU by subtracting process CPU usage across an +asynchronous query. Remove the capture setting after collecting its final +summary; the absolute deadline already prevents further measurement. ### Push the schema diff --git a/packages/db/src/index.ts b/packages/db/src/index.ts index 53abe16e078..6cab39406a0 100644 --- a/packages/db/src/index.ts +++ b/packages/db/src/index.ts @@ -50,3 +50,4 @@ export { issueReferenceMentions } from "./schema/issue_reference_mentions.js"; export * from "./schema/index.js"; export { databaseWorkScopeKey, signalDatabaseWork, subscribeDatabaseWork, databaseWorkPending, reconcileDatabaseWork } from "./work-signals.js"; +export { withDatabaseOperation } from "./response-capture.js"; diff --git a/packages/db/src/response-capture-postgres.test.ts b/packages/db/src/response-capture-postgres.test.ts index 42d5d805a0c..c737e455c9b 100644 --- a/packages/db/src/response-capture-postgres.test.ts +++ b/packages/db/src/response-capture-postgres.test.ts @@ -4,9 +4,9 @@ import { eq, sql } from "drizzle-orm"; import { pgTable, text } from "drizzle-orm/pg-core"; import { afterAll, afterEach, beforeAll, describe, expect, it, vi } from "vitest"; import { createDb, withDedicatedDbConnection } from "./client.js"; -import { createDatabaseResponseCapture, databaseResponseCaptureFromEnv, installDatabaseResponseCapture } from "./response-capture.js"; +import { createDatabaseResponseCapture, databaseResponseCaptureFromEnv, installDatabaseResponseCapture, withDatabaseOperation } from "./response-capture.js"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "./test-embedded-postgres.js"; -import { encodeRunEventPayload, runEventPayload } from "./run-event-payload.js"; +import { runEventPayload } from "./run-event-payload.js"; import { databaseWorkPending, reconcileDatabaseWork, signalDatabaseWork, subscribeDatabaseWork } from "./work-signals.js"; const table = pgTable("response_capture_fixture", { id: text("id").primaryKey(), payload: text("payload").notNull() }); @@ -31,17 +31,17 @@ describe.skipIf(!support.supported)("database response capture PostgreSQL behavi vi.restoreAllMocks(); vi.unstubAllEnvs(); }); afterAll(async () => { await temporary?.cleanup(); }); - function fixture(prepare?: boolean) { + function fixture(prepare?: boolean, maxConnections?: number, clock?: () => number) { const events: Array> = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); - const db = createDb(temporary.connectionString, { prepare }); + const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event), clock); + const db = createDb(temporary.connectionString, { prepare, maxConnections }); clients.push(db); captures.push(capture); expect(installDatabaseResponseCapture(db, { table, encodedTable }, capture)).toBe(db); expect(installDatabaseResponseCapture(db, { table, encodedTable }, capture)).toBe(db); return { db, capture, events }; } - function summary(events: Array>) { return events.find(event => event.event === "paperclip.db_response_capture.summary.v1")!; } + function summary(events: Array>) { return events.find(event => event.event === "paperclip.db_response_capture.summary.v2")!; } it("retains capture counts when ORM preparation is enabled", async () => { const f = fixture(true), id = randomUUID(), payload = "prepared-capture-value"; @@ -68,12 +68,12 @@ describe.skipIf(!support.supported)("database response capture PostgreSQL behavi expect(await f.db.delete(table).where(eq(table.id, id)).returning()).toEqual([{ id, payload: "changed" }]); f.capture.flush(); expect(summary(f.events)).toMatchObject({ startedQueries: 4, completedQueries: 4 }); - expect(f.events.filter(event => event.event === "paperclip.db_response_capture.entry.v1").map(event => event.operation).sort()) + expect(f.events.filter(event => event.event === "paperclip.db_response_capture.entry.v2").map(event => event.operation).sort()) .toEqual(["delete", "insert", "select", "update"]); expect(JSON.stringify(f.events)).not.toContain(payload); expect(JSON.stringify(f.events)).not.toContain(id); }); - it("counts the stored encoding before a custom column decoder changes the value", async () => { + it("skips complex stored values before a custom column decoder changes them", async () => { const setup = createDb(temporary.connectionString); clients.push(setup); const id = randomUUID(), payload = { text: "codec-payload-sentinel\u0000value".repeat(512) }; await setup.insert(encodedTable).values({ id, payload }); @@ -81,8 +81,7 @@ describe.skipIf(!support.supported)("database response capture PostgreSQL behavi expect(await f.db.select().from(encodedTable).where(eq(encodedTable.id, id))).toEqual([{ id, payload }]); f.capture.flush(); const entry = f.events.find(event => event.table === "response_capture_encoded_fixture")!; - expect(entry.responseValueBytes).toBe(Buffer.byteLength(id) + Buffer.byteLength(encodeRunEventPayload(payload))); - expect(entry.responseValueBytes).toBeGreaterThan(Buffer.byteLength(JSON.stringify({ id, payload }))); + expect(entry).toMatchObject({ sampledValueBytes: Buffer.byteLength(id), measuredValues: 1, unmeasuredValues: 1, incompleteSamples: 1 }); expect(JSON.stringify(f.events)).not.toContain("codec-payload-sentinel"); }); it("keeps a raw driver query lazy and counts repeated awaits without replay", async () => { @@ -109,6 +108,69 @@ describe.skipIf(!support.supported)("database response capture PostgreSQL behavi expect(summary(f.events)).toMatchObject({ startedQueries: 3, completedQueries: 3 }); expect(JSON.stringify(f.events)).not.toContain("prepared-value"); }); + it("attributes concurrent prepared reuse, pooled queries, and transaction errors to their execution owners", async () => { + const setup = createDb(temporary.connectionString); clients.push(setup); + const id = randomUUID(); + await setup.insert(table).values({ id, payload: "owner-private-value" }); + const f = fixture(true, 1); + const prepared = withDatabaseOperation("builder.only", () => + f.db.select().from(table).where(eq(table.id, sql.placeholder("id"))).prepare("owner_reused")); + await Promise.all([ + withDatabaseOperation("response.presentation", async () => { + expect(await prepared.execute({ id })).toEqual([{ id, payload: "owner-private-value" }]); + await f.db.transaction(async tx => { + expect(await tx.select().from(table).where(eq(table.id, id))).toEqual([{ id, payload: "owner-private-value" }]); + }); + }), + withDatabaseOperation("budget.admission", async () => { + expect(await prepared.execute({ id })).toEqual([{ id, payload: "owner-private-value" }]); + await expect(f.db.execute(sql`select 1/0`)).rejects.toThrow(); + }), + ]); + f.capture.flush(); + const entries = f.events.filter(event => event.event === "paperclip.db_response_capture.entry.v2"); + const counts = (owner: string) => entries.filter(event => event.owner === owner).reduce((n, event) => n + Number(event.calls), 0); + expect(counts("response.presentation")).toBe(2); + expect(counts("budget.admission")).toBe(2); + expect(counts("builder.only")).toBe(0); + expect(entries.every(event => (event.callers as string[]).length === 0)).toBe(true); + expect(entries.find(event => event.queryErrors === 1)).toMatchObject({ owner: "budget.admission", rows: 0, sampledResults: 0 }); + expect(summary(f.events)).toMatchObject({ startedQueries: 4, completedQueries: 4, rows: 3 }); + expect(JSON.stringify(f.events)).not.toContain("owner-private-value"); + }); + it("attributes a lazy raw query to its first consumer rather than its builder or repeated await", async () => { + const f = fixture(); + const query = withDatabaseOperation("builder.only", () => f.db.$client.unsafe("select 42 as answer")); + const result = await withDatabaseOperation("consumer.first", async () => await query); + expect(result).toEqual([{ answer: 42 }]); + expect(await withDatabaseOperation("consumer.again", async () => await query)).toBe(result); + f.capture.flush(); + expect(f.events[0]).toMatchObject({ owner: "consumer.first", calls: 1, rows: 1 }); + expect(summary(f.events)).toMatchObject({ startedQueries: 1, completedQueries: 1 }); + }); + it("samples bounded driver values while retaining every query and row", async () => { + const f = fixture(); + await withDatabaseOperation("sampling.owner", async () => { + for (let index = 0; index < 33; index += 1) { + expect(await f.db.execute(sql`select 42 as answer`)).toEqual([{ answer: 42 }]); + } + }); + f.capture.flush(); + expect(f.events[0]).toMatchObject({ owner: "sampling.owner", calls: 33, rows: 33, sampledResults: 3, + sampledRows: 3, sampledValueBytes: 6, measuredValues: 3, unmeasuredValues: 0 }); + expect(summary(f.events)).toMatchObject({ completedQueries: 33, rows: 33, sampledResults: 3, sampledValueBytes: 6 }); + }); + it("leaves a real in-flight query running when the capture deadline passes", async () => { + let clock = Date.now(); + const f = fixture(undefined, 1, () => clock); + const pending = withDatabaseOperation("ending.owner", async () => await f.db.execute(sql`select pg_sleep(0.05), 42 as answer`)); + await new Promise(resolve => setImmediate(resolve)); + clock += 60_000; + f.capture.flush(); + expect(summary(f.events)).toMatchObject({ startedQueries: 1, completedQueries: 0, inFlightAtEnd: 1 }); + expect((await pending)[0].answer).toBe(42); + expect(f.events).toHaveLength(1); + }); it("retains distinct builder callers through normal, prepared, and transaction execution", async () => { const f = fixture(), id = randomUUID(); const setup = createDb(temporary.connectionString); clients.push(setup); @@ -128,7 +190,7 @@ describe.skipIf(!support.supported)("database response capture PostgreSQL behavi expect(await fromB(tx, id)).toEqual([{ id, payload: "caller-sentinel" }]); }); f.capture.flush(); - const entries = f.events.filter(event => event.event === "paperclip.db_response_capture.entry.v1"); + const entries = f.events.filter(event => event.event === "paperclip.db_response_capture.entry.v2"); expect(entries).toHaveLength(2); for (const name of ["a", "b"]) { expect(entries.find(event => (event.callers as string[]).some(location => location.startsWith(`services/capture-caller-${name}.ts:`)))) @@ -191,13 +253,14 @@ describe.skipIf(!support.supported)("database response capture PostgreSQL behavi vi.stubEnv("PAPERCLIP_DB_RESPONSE_CAPTURE_WINDOW", `${new Date(now - 100).toISOString()}/${new Date(now + 59_000).toISOString()}`); const db = createDb(temporary.connectionString, { prepare }); clients.push(db); const capture = databaseResponseCaptureFromEnv()!; captures.push(capture); - expect(await withDedicatedDbConnection(db, async dedicated => dedicated.execute(sql`select ${"dedicated-value"}::text as value`))) + expect(await withDatabaseOperation("dedicated.owner", () => withDedicatedDbConnection(db, async dedicated => dedicated.execute(sql`select ${"dedicated-value"}::text as value`)))) .toEqual([{ value: "dedicated-value" }]); capture.flush(); - await vi.waitFor(() => expect(logs.some(line => JSON.parse(line).event === "paperclip.db_response_capture.summary.v1")).toBe(true), + await vi.waitFor(() => expect(logs.some(line => JSON.parse(line).event === "paperclip.db_response_capture.summary.v2")).toBe(true), { timeout: 1_000, interval: 5 }); const events = logs.map(line => JSON.parse(line) as Record); expect(summary(events)).toMatchObject({ startedQueries: 1, completedQueries: 1 }); + expect(events.find(event => event.event === "paperclip.db_response_capture.entry.v2")).toMatchObject({ owner: "dedicated.owner" }); expect(logs.join("\n")).not.toContain("dedicated-value"); expect(logs.join("\n")).not.toContain(temporary.connectionString); }); diff --git a/packages/db/src/response-capture.test.ts b/packages/db/src/response-capture.test.ts index 73d25d8fc3c..f22a5021c17 100644 --- a/packages/db/src/response-capture.test.ts +++ b/packages/db/src/response-capture.test.ts @@ -1,6 +1,7 @@ +import { AsyncLocalStorage } from "node:async_hooks"; import { integer, pgTable } from "drizzle-orm/pg-core"; import { afterEach, describe, expect, it, vi } from "vitest"; -import { createDatabaseResponseCapture, databaseResponseCaptureFromEnv, installDatabaseResponseCapture, publicDatabaseCallers, responseCaptureWindow } from "./response-capture.js"; +import { createDatabaseResponseCapture, databaseResponseCaptureFromEnv, installDatabaseResponseCapture, publicDatabaseCallers, responseCaptureWindow, withDatabaseOperation } from "./response-capture.js"; const epoch = Date.parse("2020-01-01T00:00:00Z"); const metadata = { operation: "select", table: "capture_fixture", callers: ["services/fixture.ts:4:2"] }; @@ -14,6 +15,9 @@ function fixture(emitOverride?: (event: Record) => void) { captures.push(capture); return { capture, events, now: (value: number) => { clock = value; } }; } +function driverRows(rows: unknown[][]) { + return Object.assign(rows, { columns: Array.from({ length: rows[0]?.length ?? 0 }, (_, index) => ({ name: `column_${index}` })) }); +} describe("bounded database response capture", () => { it("paces a complete environment capture without extending the measurement window or leaving timers", () => { @@ -36,13 +40,13 @@ describe("bounded database response capture", () => { capture.flush(); vi.advanceTimersByTime(32_000); expect(emitted).toHaveLength(2049); - const groups = emitted.filter(item => item.event.event === "paperclip.db_response_capture.entry.v1"); + const groups = emitted.filter(item => item.event.event === "paperclip.db_response_capture.entry.v2"); const summary = emitted.at(-1)!.event; expect(groups).toHaveLength(2048); - expect(summary).toMatchObject({ event: "paperclip.db_response_capture.summary.v1", completedQueries: 2200, + expect(summary).toMatchObject({ event: "paperclip.db_response_capture.summary.v2", completedQueries: 2200, groups: 2048, closedAt: "2020-01-01T00:01:00.000Z" }); expect(groups.reduce((calls, item) => calls + Number(item.event.calls), 0)).toBe(summary.completedQueries); - expect(groups.reduce((bytes, item) => bytes + Number(item.event.responseValueBytes), 0)).toBe(summary.responseValueBytes); + expect(groups.reduce((bytes, item) => bytes + Number(item.event.sampledValueBytes), 0)).toBe(summary.sampledValueBytes); expect(groups.map(item => item.event.groupIndex)).toEqual(Array.from({ length: 2048 }, (_, index) => index)); for (const { at } of emitted) expect(emitted.filter(item => item.at >= at && item.at < at + 1000).length).toBeLessThanOrEqual(64); expect(JSON.stringify(emitted)).not.toContain("capture-response-sentinel"); @@ -89,13 +93,13 @@ describe("bounded database response capture", () => { expect(installDatabaseResponseCapture(db, { table })).toBe(db); expect(db.select).toBe(select); expect(db.transaction).toBe(transaction); }); - it("preserves exact values and only emits counts, sizes, and caller metadata", async () => { - const f = fixture(), rows = [{ text: "sentinel-result-value🙂\n\"", n: 4n }]; + it("preserves exact values and only emits counts, sampled sizes, and caller metadata", async () => { + const f = fixture(), text = "sentinel-result-value🙂\n\"", rows = driverRows([[text, 4n]]); expect(await f.capture.execute(() => Promise.resolve(rows), metadata)).toBe(rows); f.capture.flush(); - const entry = f.events.find(event => event.event === "paperclip.db_response_capture.entry.v1")!; - expect(entry).toMatchObject({ calls: 1, rows: 1, queryErrors: 0, serializationErrors: 0, - responseValueBytes: Buffer.byteLength(JSON.stringify(rows, (_, value) => typeof value === "bigint" ? value.toString() : value)) }); + const entry = f.events.find(event => event.event === "paperclip.db_response_capture.entry.v2")!; + expect(entry).toMatchObject({ calls: 1, rows: 1, queryErrors: 0, owner: "unattributed", sampledResults: 1, + sampledValueBytes: Buffer.byteLength(text) + 1, measuredValues: 2, unmeasuredValues: 0, incompleteSamples: 0 }); expect(JSON.stringify(f.events)).not.toContain("sentinel-result-value"); expect(f.events.at(-1)).toMatchObject({ startedQueries: 1, completedQueries: 1, inFlightAtEnd: 0, rowValuesLogged: false, sqlOrParametersLogged: false, wireBytesMeasured: false }); @@ -106,10 +110,91 @@ describe("bounded database response capture", () => { { name: "sentinel-column-name" }, { name: "b" }, { name: "n" }, { name: "empty" } ] }); expect(await f.capture.execute(() => Promise.resolve(rows), metadata)).toBe(rows); f.capture.flush(); - expect(f.events[0]).toMatchObject({ responseValueBytes: Buffer.byteLength(text) + 1 + 2, estimatedValues: 0 }); + expect(f.events[0]).toMatchObject({ sampledValueBytes: Buffer.byteLength(text) + 1 + 2, measuredValues: 4, unmeasuredValues: 0 }); expect(JSON.stringify(f.events)).not.toContain("sentinel-driver-text"); expect(JSON.stringify(f.events)).not.toContain("sentinel-column-name"); }); + it("counts every result but sizes only the first and every sixteenth successful result per group", () => { + const f = fixture(); + for (let index = 0; index < 33; index += 1) { + const rows = driverRows([["abc", 12]]); + if (index % 16 !== 0) Object.defineProperty(rows[0], 0, { get() { throw new Error("unsampled cell read"); } }); + expect(withDatabaseOperation("fixture.owner", () => f.capture.execute(() => rows, metadata))).toBe(rows); + } + f.capture.flush(); + expect(f.events[0]).toMatchObject({ owner: "fixture.owner", calls: 33, rows: 33, sampledResults: 3, + sampledRows: 3, sampledValueBytes: 15, measuredValues: 6, unmeasuredValues: 0, incompleteSamples: 0 }); + expect(f.events[0].totalWallMs).toBeGreaterThanOrEqual(0); + expect(f.events[0].maxWallMs).toBeLessThanOrEqual(Number(f.events[0].totalWallMs)); + }); + it("bounds sampled cells, string scanning, and bytes without traversing large or complex values", () => { + const f = fixture(); + const rows = driverRows([["x".repeat(1_000_000), { large: "private-json" }, ...Array.from({ length: 300 }, () => "y".repeat(16_384))]]); + Object.defineProperty(rows[0], 256, { get() { throw new Error("cell budget exceeded"); } }); + expect(f.capture.execute(() => rows, metadata)).toBe(rows); + f.capture.flush(); + expect(f.events[0]).toMatchObject({ sampledResults: 1, sampledValueBytes: 65_536, measuredValues: 4, + unmeasuredValues: 298, incompleteSamples: 1 }); + expect(JSON.stringify(f.events)).not.toContain("private-json"); + const cellBound = fixture(), cells = driverRows([Array.from({ length: 257 }, () => null)]); + Object.defineProperty(cells[0], 256, { get() { throw new Error("cell budget exceeded"); } }); + cellBound.capture.execute(() => cells, metadata); + cellBound.capture.flush(); + expect(cellBound.events[0]).toMatchObject({ sampledValueBytes: 0, measuredValues: 256, unmeasuredValues: 1, incompleteSamples: 1 }); + }); + it("restores nested owners and uses the direct path without an active capture", () => { + const returned = Promise.resolve("unchanged"); + expect(withDatabaseOperation("disabled", () => returned)).toBe(returned); + const f = fixture(); + withDatabaseOperation("outer", () => { + withDatabaseOperation("inner", () => f.capture.execute(() => driverRows([[1]]), metadata)); + f.capture.execute(() => driverRows([[2]]), metadata); + }); + f.now(epoch + 60_001); + withDatabaseOperation("expired", () => { + const next = fixture(); + next.capture.execute(() => driverRows([[3]]), metadata); + next.capture.flush(); + expect(next.events[0]).toMatchObject({ owner: "unattributed" }); + }); + f.capture.flush(); + expect(f.events.slice(0, -1).map(event => event.owner).sort()).toEqual(["inner", "outer"]); + }); + it("retains an armed operation across the capture start without counting earlier queries", async () => { + let clock = epoch; + const events: Array> = []; + const capture = createDatabaseResponseCapture({ start: epoch + 1_000, end: epoch + 60_000 }, event => events.push(event), () => clock); + captures.push(capture); + let release!: () => void; + const gate = new Promise(resolve => { release = resolve; }); + const pending = withDatabaseOperation("started.before.window", async () => { + capture.execute(() => driverRows([[1]]), metadata); + await gate; + return capture.execute(() => driverRows([[2]]), metadata); + }); + clock = epoch + 2_000; + release(); + await pending; + capture.flush(); + expect(events[0]).toMatchObject({ owner: "started.before.window", calls: 1, rows: 1 }); + expect(events.at(-1)).toMatchObject({ startedQueries: 1, completedQueries: 1 }); + }); + it("keeps overlapping capture scopes but clears retained owners when the last capture closes", () => { + const first = fixture(), second = fixture(); + let destination = second.capture; + const retained = withDatabaseOperation("previous.capture", () => AsyncLocalStorage.bind(() => + destination.execute(() => driverRows([[1]]), metadata))); + first.capture.flush(); + retained(); + second.capture.flush(); + expect(second.events[0]).toMatchObject({ owner: "previous.capture", calls: 1 }); + const later = fixture(); + destination = later.capture; + withDatabaseOperation("new.capture", () => destination.execute(() => driverRows([[2]]), metadata)); + retained(); + later.capture.flush(); + expect(later.events.slice(0, -1).map(event => event.owner).sort()).toEqual(["new.capture", "unattributed"]); + }); it("does not alter synchronous or asynchronous errors or retry them", async () => { const f = fixture(), error = new Error("sentinel-private-error"); const sync = vi.fn(() => { throw error; }), asyncFailure = vi.fn(() => Promise.reject(error)); @@ -117,14 +202,17 @@ describe("bounded database response capture", () => { await expect(f.capture.execute(asyncFailure, metadata)).rejects.toBe(error); expect(sync).toHaveBeenCalledTimes(1); expect(asyncFailure).toHaveBeenCalledTimes(1); f.capture.flush(); - expect(f.events[0]).toMatchObject({ calls: 2, queryErrors: 2, responseValueBytes: 0 }); + expect(f.events[0]).toMatchObject({ calls: 2, queryErrors: 2, sampledValueBytes: 0 }); expect(JSON.stringify(f.events)).not.toContain("sentinel-private-error"); }); - it("keeps unserializable results and logging failures out of the query outcome", () => { + it("does not serialize complex values or let logging failures change query outcomes", () => { const f = fixture(), circular: Record = {}; circular.self = circular; - expect(f.capture.execute(() => circular, metadata)).toBe(circular); + const toJSON = vi.fn(() => { throw new Error("must not serialize"); }); + const rows = driverRows([[circular, { toJSON }]]); + expect(f.capture.execute(() => rows, metadata)).toBe(rows); f.capture.flush(); - expect(f.events[0]).toMatchObject({ calls: 1, serializationErrors: 1 }); + expect(f.events[0]).toMatchObject({ calls: 1, sampledValueBytes: 0, unmeasuredValues: 2, incompleteSamples: 1 }); + expect(toJSON).not.toHaveBeenCalled(); const brokenLogger = fixture(() => { throw new Error("logger fixture"); }); expect(brokenLogger.capture.execute(() => circular, metadata)).toBe(circular); expect(() => brokenLogger.capture.flush()).not.toThrow(); @@ -152,12 +240,12 @@ describe("bounded database response capture", () => { expect(await result).toBe(rows); f.capture.flush(); expect(f.events).toHaveLength(1); - expect(f.events[0]).toMatchObject({ startedQueries: 1, completedQueries: 0, inFlightAtEnd: 1, responseValueBytes: 0 }); + expect(f.events[0]).toMatchObject({ startedQueries: 1, completedQueries: 0, inFlightAtEnd: 1, sampledValueBytes: 0 }); expect(JSON.stringify(f.events)).not.toContain("late-before-flush-sentinel"); }); - it("bounds cardinality without dropping response-byte totals", () => { + it("bounds cardinality while distinguishing sampled bytes from complete call and row counts", () => { const f = fixture(); - for (let i = 0; i < 2200; i += 1) f.capture.execute(() => [i], { ...metadata, callers: [`services/f${i}.ts:1:1`] }); + for (let i = 0; i < 2200; i += 1) f.capture.execute(() => driverRows([[i]]), { ...metadata, callers: [`services/f${i}.ts:1:1`] }); f.capture.flush(); const summary = f.events.at(-1)!; expect(summary).toMatchObject({ startedQueries: 2200, completedQueries: 2200, groups: 2048, overflowCalls: 153, @@ -169,7 +257,8 @@ describe("bounded database response capture", () => { expect(entries.filter(entry => entry.groupPage === page)).toHaveLength(128); } expect(entries.reduce((sum, entry) => sum + Number(entry.calls), 0)).toBe(2200); - expect(summary.responseValueBytes).toBe(Array.from({ length: 2200 }, (_, i) => Buffer.byteLength(JSON.stringify([i]))).reduce((a, b) => a + b, 0)); + expect(summary).toMatchObject({ rows: 2200, sampledResults: 2057, sampleEvery: 16 }); + expect(summary.sampledValueBytes).toBe(entries.reduce((sum, entry) => sum + Number(entry.sampledValueBytes), 0)); }); it.each([0, 129])("numbers every page including an empty or partial final page (%s)", count => { const f = fixture(); diff --git a/packages/db/src/response-capture.ts b/packages/db/src/response-capture.ts index d53b5fe0c07..64e1bcf2448 100644 --- a/packages/db/src/response-capture.ts +++ b/packages/db/src/response-capture.ts @@ -3,11 +3,27 @@ import { randomUUID } from "node:crypto"; import { getTableName, is, Table } from "drizzle-orm"; type Metadata = { operation: string; table: string; callers: string[] }; -type Entry = Metadata & { calls: number; rows: number; bytes: number; maxBytes: number; queryErrors: number; serializationErrors: number; estimatedValues: number }; +type Entry = Metadata & { owner: string; calls: number; rows: number; queryErrors: number; totalWallMs: number; maxWallMs: number; + sampledResults: number; sampledRows: number; sampledValueBytes: number; maxSampledValueBytes: number; + measuredValues: number; unmeasuredValues: number; incompleteSamples: number; sizingWallMs: number }; type Event = Record; type Method = (this: unknown, ...args: unknown[]) => unknown; export type ResponseCaptureWindow = { start: number; end: number }; const GROUP_PAGE_SIZE = 128; +const SAMPLE_EVERY = 16; +const MAX_SAMPLE_CELLS = 256; +const MAX_SAMPLE_STRING_LENGTH = 16_384; +const MAX_SAMPLE_STRING_UNITS = 65_536; +const MAX_SAMPLE_BYTES = 65_536; +let operationScope = new AsyncLocalStorage(); +const captureWindows = new Set<() => boolean>(); + +export function withDatabaseOperation(owner: string, action: () => T): T { + for (const armed of captureWindows) { + if (armed()) return operationScope.run(owner, action); + } + return action(); +} export function responseCaptureWindow(value: string | undefined, now = Date.now()): ResponseCaptureWindow | undefined { if (!value) return; @@ -32,28 +48,37 @@ export function publicDatabaseCallers(stack: string | undefined): string[] { return callers; } -function responseValueSize(value: unknown): { bytes: number; estimatedValues: number } { +function responseValueSize(value: unknown): { bytes: number; measuredValues: number; unmeasuredValues: number } { const columns = value && typeof value === "object" ? (value as { columns?: unknown }).columns : undefined; if (!Array.isArray(value) || !Array.isArray(columns)) { - const serialized = JSON.stringify(value, (_, item: unknown) => typeof item === "bigint" ? item.toString() : item); - return { bytes: serialized === undefined ? 0 : Buffer.byteLength(serialized), estimatedValues: 1 }; + return { bytes: 0, measuredValues: 0, unmeasuredValues: 1 }; } - let bytes = 0, estimatedValues = 0; + let bytes = 0, measuredValues = 0, visitedValues = 0, stringUnits = 0; + const totalValues = value.length * columns.length; + if (columns.length === 0) return { bytes: 0, measuredValues: 0, unmeasuredValues: 0 }; for (const row of value) { - const cells = Array.isArray(row) ? row : columns.map(column => row[column.name]); - for (const cell of cells) { - if (cell === null || cell === undefined) continue; - if (typeof cell === "string") bytes += Buffer.byteLength(cell); - else if (typeof cell === "boolean") bytes += 1; - else if (typeof cell === "number" || typeof cell === "bigint") bytes += Buffer.byteLength(String(cell)); - else { - estimatedValues += 1; - const serialized = JSON.stringify(cell, (_, item: unknown) => typeof item === "bigint" ? item.toString() : item); - if (serialized !== undefined) bytes += Buffer.byteLength(serialized); + for (let index = 0; index < columns.length; index += 1) { + if (visitedValues >= MAX_SAMPLE_CELLS || bytes >= MAX_SAMPLE_BYTES) { + return { bytes, measuredValues, unmeasuredValues: totalValues - measuredValues }; } + visitedValues += 1; + const cell = Array.isArray(row) ? row[index] : row[columns[index].name]; + let size: number; + if (cell === null || cell === undefined) size = 0; + else if (typeof cell === "string") { + if (cell.length > MAX_SAMPLE_STRING_LENGTH || stringUnits + cell.length > MAX_SAMPLE_STRING_UNITS) continue; + stringUnits += cell.length; + size = Buffer.byteLength(cell); + } else if (typeof cell === "boolean") size = 1; + else if (typeof cell === "number") size = Buffer.byteLength(String(cell)); + else if (typeof cell === "bigint" && cell >= -9_223_372_036_854_775_808n && cell <= 9_223_372_036_854_775_807n) size = Buffer.byteLength(String(cell)); + else continue; + if (bytes + size > MAX_SAMPLE_BYTES) continue; + measuredValues += 1; + bytes += size; } } - return { bytes, estimatedValues }; + return { bytes, measuredValues, unmeasuredValues: totalValues - measuredValues }; } export function createDatabaseResponseCapture( @@ -71,32 +96,45 @@ export function createDatabaseResponseCapture( const send = (event: Event) => { try { emit(event); } catch {} }; const expired = () => closed || now() >= window.end; const active = () => !expired() && now() >= window.start; + const armed = () => !expired(); + captureWindows.add(armed); const flush = () => { if (closed) return; closed = true; clearTimeout(timer); + captureWindows.delete(armed); + if (captureWindows.size === 0) { + operationScope.disable(); + operationScope = new AsyncLocalStorage(); + } scope.disable(); - const ordered = [...entries.values()].sort((a, b) => b.bytes - a.bytes); - for (const [groupIndex, entry] of ordered.entries()) send({ event: "paperclip.db_response_capture.entry.v1", captureId: id, + const ordered = [...entries.values()].sort((a, b) => b.calls - a.calls); + for (const [groupIndex, entry] of ordered.entries()) send({ event: "paperclip.db_response_capture.entry.v2", captureId: id, groupIndex, groupPage: Math.floor(groupIndex / GROUP_PAGE_SIZE), - operation: entry.operation, table: entry.table, callers: entry.callers, calls: entry.calls, rows: entry.rows, - responseValueBytes: entry.bytes, maxResponseValueBytes: entry.maxBytes, estimatedValues: entry.estimatedValues, - queryErrors: entry.queryErrors, serializationErrors: entry.serializationErrors }); - send({ event: "paperclip.db_response_capture.summary.v1", captureId: id, + ...entry }); + send({ event: "paperclip.db_response_capture.summary.v2", captureId: id, windowStart: new Date(window.start).toISOString(), windowEnd: new Date(window.end).toISOString(), closedAt: new Date(now()).toISOString(), startedQueries: started, completedQueries: completed, inFlightAtEnd: inFlight, groups: entries.size, groupPageSize: GROUP_PAGE_SIZE, groupPages: Math.ceil(ordered.length / GROUP_PAGE_SIZE), - overflowCalls, responseValueBytes: ordered.reduce((sum, entry) => sum + entry.bytes, 0), + overflowCalls, rows: ordered.reduce((sum, entry) => sum + entry.rows, 0), + sampledResults: ordered.reduce((sum, entry) => sum + entry.sampledResults, 0), + sampledValueBytes: ordered.reduce((sum, entry) => sum + entry.sampledValueBytes, 0), + sizingWallMs: ordered.reduce((sum, entry) => sum + entry.sizingWallMs, 0), + sampleEvery: SAMPLE_EVERY, sampling: "first-and-every-16th-successful-result-per-group", + maxSampleCells: MAX_SAMPLE_CELLS, maxSampleStringLength: MAX_SAMPLE_STRING_LENGTH, + maxSampleStringUnits: MAX_SAMPLE_STRING_UNITS, maxSampleBytes: MAX_SAMPLE_BYTES, rowValuesLogged: false, sqlOrParametersLogged: false, wireBytesMeasured: false, measurementBoundary: "postgres-js results before Drizzle column decoding", + wallTimeBoundary: "first query consumption to driver result; includes queue, database, network and event-loop waits; not CPU", + byteMeasurement: "sampled primitive values only; complex/oversized/budget-exceeding values unmeasured; no extrapolation", relationalQueriesMeasured: true, unsafeDriverQueriesMeasured: true, taggedDriverQueriesMeasured: false, streamingQueriesMeasured: false }); entries.clear(); }; const timer = setTimeout(flush, Math.max(0, window.end - now())); timer.unref(); - function finish(metadata: Metadata, value: unknown, failed: boolean) { + function finish(metadata: Metadata & { owner: string }, value: unknown, failed: boolean, startedAt: number) { if (!active()) return; inFlight -= 1; completed += 1; @@ -104,38 +142,52 @@ export function createDatabaseResponseCapture( let key = JSON.stringify(metadata); if (!entries.has(key) && entries.size >= 2047) { overflowCalls += 1; - metadata = { operation: "other", table: "other", callers: [] }; + metadata = { owner: "other", operation: "other", table: "other", callers: [] }; key = "overflow"; } let entry = entries.get(key); if (!entry) { - entry = { ...metadata, calls: 0, rows: 0, bytes: 0, maxBytes: 0, queryErrors: 0, serializationErrors: 0, estimatedValues: 0 }; + entry = { ...metadata, calls: 0, rows: 0, queryErrors: 0, totalWallMs: 0, maxWallMs: 0, + sampledResults: 0, sampledRows: 0, sampledValueBytes: 0, maxSampledValueBytes: 0, + measuredValues: 0, unmeasuredValues: 0, incompleteSamples: 0, sizingWallMs: 0 }; entries.set(key, entry); } entry.calls += 1; + const wallMs = performance.now() - startedAt; + entry.totalWallMs += wallMs; + entry.maxWallMs = Math.max(entry.maxWallMs, wallMs); if (failed) { entry.queryErrors += 1; return; } entry.rows += Array.isArray(value) ? value.length : 0; + if ((entry.calls - entry.queryErrors - 1) % SAMPLE_EVERY !== 0) return; + entry.sampledResults += 1; + entry.sampledRows += Array.isArray(value) ? value.length : 0; + const sizingStartedAt = performance.now(); try { const size = responseValueSize(value); - entry.bytes += size.bytes; - entry.maxBytes = Math.max(entry.maxBytes, size.bytes); - entry.estimatedValues += size.estimatedValues; - } catch { entry.serializationErrors += 1; } + entry.sampledValueBytes += size.bytes; + entry.maxSampledValueBytes = Math.max(entry.maxSampledValueBytes, size.bytes); + entry.measuredValues += size.measuredValues; + entry.unmeasuredValues += size.unmeasuredValues; + if (size.unmeasuredValues) entry.incompleteSamples += 1; + } catch { entry.incompleteSamples += 1; } + finally { entry.sizingWallMs += performance.now() - sizingStartedAt; } } catch {} } function execute(action: () => unknown, metadata: Metadata) { if (!active()) return action(); inFlight += 1; started += 1; + const owned = { ...metadata, owner: operationScope.getStore() ?? "unattributed" }; + const startedAt = performance.now(); let result: unknown; try { result = action(); } - catch (error) { finish(metadata, undefined, true); throw error; } + catch (error) { finish(owned, undefined, true, startedAt); throw error; } let asynchronous = false; try { asynchronous = Boolean(result && typeof (result as { then?: unknown }).then === "function"); } catch {} if (asynchronous) { - return Promise.resolve(result).then(value => { finish(metadata, value, false); return value; }, - error => { finish(metadata, undefined, true); throw error; }); + return Promise.resolve(result).then(value => { finish(owned, value, false, startedAt); return value; }, + error => { finish(owned, undefined, true, startedAt); throw error; }); } - finish(metadata, result, false); + finish(owned, result, false, startedAt); return result; } return { window, roots, queries, factories, clients, driverQueries, scope, active, expired, execute, flush }; @@ -240,7 +292,7 @@ export function installDatabaseResponseCapture(db: T, schema: } return scoped ? { ...scoped, table: scoped.table === "other" ? table : scoped.table } : { operation: text.match(/^\s*(select|insert|update|delete)\b/i)?.[1]?.toLowerCase() ?? "execute", - table, callers: publicDatabaseCallers(new Error().stack) }; + table, callers: capture!.active() && !operationScope.getStore() ? publicDatabaseCallers(new Error().stack) : [] }; } function client(value: unknown) { if ((!object(value) && typeof value !== "function") || capture!.clients.has(value)) return; @@ -277,7 +329,8 @@ export function installDatabaseResponseCapture(db: T, schema: try { if (method === "with") { root(result); return result; } const operation = method.startsWith("select") ? "select" : method; - const metadata = { operation, table: operation === "select" || method === "execute" ? "other" : tableName(args[0]), callers: publicDatabaseCallers(new Error().stack) }; + const metadata = { operation, table: operation === "select" || method === "execute" ? "other" : tableName(args[0]), + callers: capture!.active() && !operationScope.getStore() ? publicDatabaseCallers(new Error().stack) : [] }; if (operation === "select") factory(result, "from", metadata, true); else if (method === "insert") factory(result, "values", metadata); else if (method === "update") factory(result, "set", metadata); diff --git a/scripts/benchmark-github-webhook-ingress.ts b/scripts/benchmark-github-webhook-ingress.ts index 3b24116a650..25cbf5891e0 100644 --- a/scripts/benchmark-github-webhook-ingress.ts +++ b/scripts/benchmark-github-webhook-ingress.ts @@ -5,7 +5,7 @@ import { promises as fs, readFileSync } from "node:fs"; import path from "node:path"; import { fileURLToPath, pathToFileURL } from "node:url"; import { applyPendingMigrations, chatActions, createDb, startEmbeddedPostgresTestDatabase, type Db } from "../packages/db/src/index.js"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "../packages/db/src/response-capture.js"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../server/src/__tests__/helpers/full-database-response-capture.js"; import { createGitHubWebhookIngress } from "../server/src/services/chat-channels/github/webhook-ingress.js"; import { captureIngressQueries, cleanupIngressFixture, githubIngressFixture, type CapturedQuery } from "../server/src/__tests__/helpers/github-webhook-ingress.js"; import { resolveExternalTestDatabaseUrl } from "../server/src/__tests__/helpers/external-test-database.js"; @@ -60,7 +60,7 @@ try { queries.length = 0; f.calls.length = 0; const events: Array> = [], timestamp = Date.now(); - const capture = iteration === 11 ? createDatabaseResponseCapture({ start: timestamp - 1, end: timestamp + 59_000 }, event => events.push(event)) : undefined; + const capture = iteration === 11 ? createFullDatabaseResponseCapture({ start: timestamp - 1, end: timestamp + 59_000 }, event => events.push(event)) : undefined; if (capture) installDatabaseResponseCapture(db, { chatActions }, capture); const start = performance.now(); const response = await service.processGitHubWebhookIngress(action.id); @@ -80,7 +80,7 @@ try { const [plan] = await db.$client.unsafe(`EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) ${candidate.sql}`, candidate.params as never[]); const positionalRows = await db.$client.unsafe(candidate.sql, candidate.params as never[]).values(); measurements[name] = { queries: executed, initialQueryPlan: plan["QUERY PLAN"], initialReadJsonBytes: Buffer.byteLength(JSON.stringify(positionalRows)), - responseValueBytes: events.find(event => event.event === "paperclip.db_response_capture.summary.v1")?.responseValueBytes, + responseValueBytes: events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")?.responseValueBytes, captureEvents: events }; } } diff --git a/server/scripts/benchmark-skill-list.ts b/server/scripts/benchmark-skill-list.ts index b535fb2bed1..be1be55b982 100644 --- a/server/scripts/benchmark-skill-list.ts +++ b/server/scripts/benchmark-skill-list.ts @@ -16,7 +16,7 @@ import { authUsers, companies, companyMemberships, companySkills, companySkillSo projectSkillSources, projects, applyPendingMigrations, closeRegisteredClients, createDb, startEmbeddedPostgresTestDatabase } from "../../packages/db/src/index.js"; import * as schema from "../../packages/db/src/schema/index.js"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "../../packages/db/src/response-capture.js"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../src/__tests__/helpers/full-database-response-capture.js"; import { withRunExecutionTiming } from "../src/services/execution-preparation-timing.js"; const argument = (name: string) => process.argv.find(value => value.startsWith(`${name}=`))?.slice(name.length + 1); @@ -195,7 +195,7 @@ try { }; const first = await request(); assert.ok(first.etag); const events: Array> = [], now = Date.now(); - const capture = captureValues ? createDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)) : undefined; + const capture = captureValues ? createFullDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)) : undefined; if (capture) installDatabaseResponseCapture(db, schema, capture); const samples = []; try { @@ -213,7 +213,7 @@ try { } finally { capture?.flush(); } assert.equal(await sourceHash(), measuredSourceHash, "Source changed during measurement"); const timings = samples.map(sample => sample.elapsedMs).sort((a, b) => a - b); - const summary = events.find(event => event.event === "paperclip.db_response_capture.summary.v1"); + const summary = events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1"); if (capture) assert.ok(summary && summary.inFlightAtEnd === 0 && summary.overflowCalls === 0); const rowCount = (await db.select().from(companySkills).where(eq(companySkills.companyId, companyId))).length; console.log(JSON.stringify({ schema: "paperclip.skill-list-benchmark.v1", sourceRevision, measuredSourceHash, diff --git a/server/scripts/bundle-runtime.test.mjs b/server/scripts/bundle-runtime.test.mjs index a634d11b2ac..adacbca2871 100644 --- a/server/scripts/bundle-runtime.test.mjs +++ b/server/scripts/bundle-runtime.test.mjs @@ -130,6 +130,42 @@ describe("bundleRuntime", () => { } }); + it("attributes asynchronous database operations in a plain runtime bundle", async () => { + const captureModule = fileURLToPath(new URL("../../packages/db/src/response-capture.ts", import.meta.url)); + write(path.join(root, "server", "dist", "services", "database-owner.js"), [ + `import { withDatabaseOperation } from ${JSON.stringify(captureModule)};`, + 'export const run = (owner, db) => withDatabaseOperation(owner, async () => {', + ' await Promise.resolve();', + ' return await db.$client.unsafe("select $1", ["private-parameter"]);', + '});', + ].join("\n")); + write(path.join(root, "server", "dist", "index.js"), [ + `import { createDatabaseResponseCapture, installDatabaseResponseCapture } from ${JSON.stringify(captureModule)};`, + 'import { run } from "./services/database-owner.js";', + 'const events = [];', + 'const now = Date.now();', + 'const capture = createDatabaseResponseCapture({ start: now, end: now + 60000 }, event => events.push(event));', + 'const db = { $client: { unsafe: () => ({ then(resolve, reject) { return Promise.resolve(Object.assign([["private-result"]], { columns: [{ name: "value" }] })).then(resolve, reject); } }) } };', + 'installDatabaseResponseCapture(db, {}, capture);', + 'await Promise.all([run("fixture.first", db), run("fixture.second", db)]);', + 'capture.flush();', + 'console.log(JSON.stringify(events));', + ].join("\n")); + const summary = await bundleRuntime({ entry: path.join(root, "server", "dist", "index.js"), outdir: path.join(root, "server", "dist-runtime") }); + const env = { ...process.env }; + delete env.NODE_OPTIONS; + delete env.PAPERCLIP_DB_RESPONSE_CAPTURE_WINDOW; + const { stdout } = await execFileAsync(process.execPath, [summary.outfile], { cwd: path.join(root, "server"), env, timeout: 30_000 }); + const events = JSON.parse(stdout); + const entries = events.filter(event => event.event === "paperclip.db_response_capture.entry.v2"); + expect(entries.map(entry => entry.owner).sort()).toEqual(["fixture.first", "fixture.second"]); + for (const entry of entries) expect(entry).toMatchObject({ calls: 1, rows: 1, callers: [] }); + expect(events.at(-1)).toMatchObject({ event: "paperclip.db_response_capture.summary.v2", completedQueries: 2 }); + expect(stdout).not.toContain("private-parameter"); + expect(stdout).not.toContain("private-result"); + expect(stdout).not.toContain(root); + }); + it("emits a server module that loads without starting the server", async () => { const outdir = path.join(root, "server", "dist-runtime"); const summary = await bundleRuntime({ entry: path.join(root, "server", "dist", "index.js"), outdir }); diff --git a/server/src/__tests__/agent-auth-identity-transfer.test.ts b/server/src/__tests__/agent-auth-identity-transfer.test.ts index 819b23dc64a..995464f7933 100644 --- a/server/src/__tests__/agent-auth-identity-transfer.test.ts +++ b/server/src/__tests__/agent-auth-identity-transfer.test.ts @@ -4,7 +4,7 @@ import request from "supertest"; import { eq } from "drizzle-orm"; import { afterAll, beforeAll, describe, expect, it, vi } from "vitest"; import { agents, companies, createDb, heartbeatRunEvents, heartbeatRuns, issueComments, issues } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "./helpers/embedded-postgres.js"; import { createLocalAgentJwt } from "../agent-auth-jwt.js"; import { actorMiddleware } from "../middleware/auth.js"; @@ -53,7 +53,7 @@ const support = await getEmbeddedPostgresTestSupport(); it("bounds actual middleware responses and preserves the complete stored run", async () => { const fixture = await seed(); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); try { const response = await request(fixture.app).get("/actor").set("Authorization", `Bearer ${fixture.token}`); @@ -61,7 +61,7 @@ const support = await getEmbeddedPostgresTestSupport(); expect(response.body).toMatchObject({ type: "agent", runId: fixture.runId, identityContextId: fixture.identity.id, onBehalfOfUserId: "owner" }); } finally { capture.flush(); } - const reads = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" + const reads = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "heartbeat_runs" && (event.operation === "select" || event.operation === "execute")); expect(reads.reduce((sum, event) => sum + Number(event.calls), 0)).toBeGreaterThanOrEqual(3); expect(reads.reduce((sum, event) => sum + Number(event.responseValueBytes), 0)).toBeLessThan(16_384); diff --git a/server/src/__tests__/agent-record-read-projections.test.ts b/server/src/__tests__/agent-record-read-projections.test.ts index bf0a5183202..7786b017d3e 100644 --- a/server/src/__tests__/agent-record-read-projections.test.ts +++ b/server/src/__tests__/agent-record-read-projections.test.ts @@ -1,6 +1,6 @@ import { randomUUID } from "node:crypto"; import { agents, companies, costEvents, createDb } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { eq } from "drizzle-orm"; import { afterAll, afterEach, beforeAll, beforeEach, describe, expect, it, vi } from "vitest"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "./helpers/embedded-postgres.js"; @@ -61,7 +61,7 @@ describe.skipIf(!support.supported)("agent roster read projections", () => { async function observe(run: (observed: ReturnType) => Promise) { const observed = createDb(database.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { agents, costEvents }, capture); try { const result = await run(observed); diff --git a/server/src/__tests__/attention-service.test.ts b/server/src/__tests__/attention-service.test.ts index 5af78c2cb8b..ca18a4a2d3c 100644 --- a/server/src/__tests__/attention-service.test.ts +++ b/server/src/__tests__/attention-service.test.ts @@ -4,7 +4,7 @@ import { randomUUID } from "node:crypto"; import express from "express"; import request from "supertest"; import { eq, sql } from "drizzle-orm"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { afterAll, afterEach, beforeAll, describe, expect, it } from "vitest"; import { agents, @@ -1164,13 +1164,13 @@ describeEmbeddedPostgres("attention service", () => { }))); } const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); try { const feed = await attentionService(db).list(companyId, { userId: "board-user" }); expect(feed.items.filter(item => item.sourceKind === "failed_run").map(item => item.subject.id)).toEqual([failedId]); } finally { capture.flush(); } - const reads = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" + const reads = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "heartbeat_runs" && (event.operation === "select" || event.operation === "execute")); expect(reads.reduce((sum, event) => sum + Number(event.calls), 0)).toBeGreaterThan(0); expect(reads.reduce((sum, event) => sum + Number(event.rows), 0)).toBeLessThan(64); @@ -1209,7 +1209,7 @@ describeEmbeddedPostgres("attention service", () => { }); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); try { const feed = await attentionService(db).list(companyId, { @@ -1218,7 +1218,7 @@ describeEmbeddedPostgres("attention service", () => { expect(feed.items.filter((item) => item.sourceKind === "failed_run").map((item) => item.subject.id).sort()) .toEqual([...keptIds].sort()); } finally { capture.flush(); } - const reads = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" + const reads = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "heartbeat_runs" && (event.operation === "select" || event.operation === "execute")); expect(reads.reduce((sum, event) => sum + Number(event.calls), 0)).toBeGreaterThan(0); expect(reads.reduce((sum, event) => sum + Number(event.calls), 0)).toBeLessThan(4); @@ -1407,7 +1407,7 @@ describeEmbeddedPostgres("attention service", () => { const interactionItems = feed.items.filter((item) => item.sourceKind === "issue_thread_interaction"); const detailsByKind = new Map(interactionItems.map((item) => [item.detail?.kind, item])); const summaryEvents: Array> = [], captureNow = Date.now(); - const summaryCapture = createDatabaseResponseCapture({ start: captureNow - 100, end: captureNow + 59_000 }, event => summaryEvents.push(event)); + const summaryCapture = createFullDatabaseResponseCapture({ start: captureNow - 100, end: captureNow + 59_000 }, event => summaryEvents.push(event)); installDatabaseResponseCapture(db, { documents, assets, issueAttachments }, summaryCapture); try { const summary = await attentionService(db).summary(companyId, { userId: "board-user" }); @@ -1418,7 +1418,7 @@ describeEmbeddedPostgres("attention service", () => { expect(index.totalCount).toBe(feed.totalCount); } finally { summaryCapture.flush(); } - const cardReads = summaryEvents.filter(event => event.event === "paperclip.db_response_capture.entry.v1" + const cardReads = summaryEvents.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && ["documents", "assets", "issue_attachments"].includes(String(event.table))); expect(cardReads).toEqual([]); diff --git a/server/src/__tests__/chat-channels.integration.test.ts b/server/src/__tests__/chat-channels.integration.test.ts index b12a858543c..cabb3d84093 100644 --- a/server/src/__tests__/chat-channels.integration.test.ts +++ b/server/src/__tests__/chat-channels.integration.test.ts @@ -39,7 +39,7 @@ import { createSystemRecovery } from "../services/system-recovery-state.js"; import { remoteTerminationReceipt } from "../services/remote-execution-termination.js"; import { stageReceiptReactionRemovals } from "../services/chat-receipt-reactions.js"; import type { Db } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { githubResponseAuthorityFields } from "../services/chat-channels/github/response-authority-read.js"; import * as activityLogModule from "../services/activity-log.js"; import * as connectionCredentialBindings from "../services/connection-credential-bindings.js"; @@ -2890,7 +2890,7 @@ describeEmbeddedPostgres("chat channel control-plane integration", () => { const normalizedEvent = { ...delivery.normalizedEvent, unusedContent: bulk }; await db.update(chatDeliveries).set({ normalizedEvent }).where(eq(chatDeliveries.id, delivery.id)); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { chatMessageLinks, chatDeliveries, chatEndpoints, chatConversations, chatEndpointResources, chatGitHubConfigurations, chatExternalPrincipals, chatIdentityLinks, companyMemberships, chatActions, heartbeatRuns }, capture); @@ -2919,7 +2919,7 @@ describeEmbeddedPostgres("chat channel control-plane integration", () => { } }; await db.update(chatDeliveries).set({ normalizedEvent }).where(eq(chatDeliveries.id, delivery.id)); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { chatDeliveries }, capture); let projected: { event: Record }; try { @@ -64493,7 +64493,7 @@ describeEmbeddedPostgres("chat channel control-plane integration", () => { status: "active", membershipRole: "operator" }); } const queryEvents: Record[] = []; - const capture = mode === "backlog_51" ? createDatabaseResponseCapture({ start: Date.now() - 1, + const capture = mode === "backlog_51" ? createFullDatabaseResponseCapture({ start: Date.now() - 1, end: Date.now() + 59_000 }, event => queryEvents.push(event)) : undefined; if (capture) installDatabaseResponseCapture(db, { chatActions, chatDeliveries, chatMessageLinks, issueComments, agentWakeupRequests, chatEndpoints, chatConversations }, capture); @@ -64513,7 +64513,7 @@ describeEmbeddedPostgres("chat channel control-plane integration", () => { idempotencyKey: mode === "concurrent_clicks" ? randomUUID() : input.idempotencyKey })]); if (capture) { capture.flush(); - expect(Number(queryEvents.find(event => event.event === "paperclip.db_response_capture.summary.v1")?.startedQueries)) + expect(Number(queryEvents.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")?.startedQueries)) .toBeLessThan(180); } expect(two.requestId).toBe(one.requestId); @@ -67713,7 +67713,7 @@ describeEmbeddedPostgres("chat channel control-plane integration", () => { }))); const scope = { companyId: context.fixture.companyId, issueId: context.issue.id }; const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { chatActions, agentWakeupRequests }, capture); let scopes: Array<{ companyId: string; issueId: string }>; try { @@ -67730,7 +67730,7 @@ describeEmbeddedPostgres("chat channel control-plane integration", () => { } expect(events.at(-1)).toMatchObject({ startedQueries: mode === "task" ? 0 : 1, completedQueries: mode === "task" ? 0 : 1, inFlightAtEnd: 0 }); - expect(events.filter(event => event.event === "paperclip.db_response_capture.entry.v1") + expect(events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1") .reduce((count, event) => count + Number(event.rows), 0)).toBe(mode === "task" ? 0 : scopes.length); } finally { await context.service.shutdown(); await other.service.shutdown(); @@ -77438,7 +77438,7 @@ describeEmbeddedPostgres("chat channel control-plane integration", () => { }))); const scope = { companyId: context.fixture.companyId, issueId: context.conversation.issueId }; const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { chatActions, agentWakeupRequests }, capture); let scopes: Array<{ companyId: string; issueId: string }>; try { @@ -77455,7 +77455,7 @@ describeEmbeddedPostgres("chat channel control-plane integration", () => { } expect(events.at(-1)).toMatchObject({ startedQueries: mode === "task" ? 0 : 1, completedQueries: mode === "task" ? 0 : 1, inFlightAtEnd: 0 }); - expect(events.filter(event => event.event === "paperclip.db_response_capture.entry.v1") + expect(events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1") .reduce((count, event) => count + Number(event.rows), 0)).toBe(mode === "task" ? 0 : scopes.length); } finally { await context.service.shutdown(); await other.service.shutdown(); diff --git a/server/src/__tests__/company-skills-service.test.ts b/server/src/__tests__/company-skills-service.test.ts index 8da12bed840..6ee86511ad7 100644 --- a/server/src/__tests__/company-skills-service.test.ts +++ b/server/src/__tests__/company-skills-service.test.ts @@ -17,7 +17,7 @@ import { projectWorkspaces, } from "@paperclipai/db"; import { parseFrontmatterMarkdown } from "@paperclipai/shared"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase, @@ -651,17 +651,17 @@ describeEmbeddedPostgres("companySkillService.list", () => { ]); await svc.list(companyId); const events: Record[] = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { agents, costEvents }, capture); let listed: Awaited>; try { listed = await svc.list(companyId); } finally { capture.flush(); } expect(listed.find(item => item.id === first.id)?.attachedAgentCount).toBe(2); expect(listed.find(item => item.id === second.id)?.attachedAgentCount).toBe(1); expect(listed.find(item => item.id === ambiguous.id)?.attachedAgentCount).toBe(0); - const agentReads = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" && event.table === "agents"); + const agentReads = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "agents"); expect(agentReads).toHaveLength(1); expect(Number(agentReads[0]?.responseValueBytes)).toBeLessThan(2_000); - expect(events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" && event.table === "cost_events")).toHaveLength(0); + expect(events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "cost_events")).toHaveLength(0); await db.update(agents).set({ adapterConfig: { paperclipSkillSync: { desiredSkills: [second.key] } } }).where(eq(agents.id, readerId)); const refreshed = await svc.list(companyId, { q: "First" }); expect(refreshed.find(item => item.id === first.id)?.attachedAgentCount).toBe(1); @@ -680,12 +680,12 @@ describeEmbeddedPostgres("companySkillService.list", () => { const before = await svc.list(companyId); expect(before.find(item => item.id === inserted[0]!.id)?.folderPath).toBe("bundled/paperclip-core"); const events: Record[] = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { companySkills }, capture); let after: Awaited>; try { after = await svc.list(companyId); } finally { capture.flush(); } expect(after).toEqual(before); - const reads = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" && event.table === "company_skills"); + const reads = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "company_skills"); expect(reads.reduce((sum, event) => sum + Number(event.responseValueBytes), 0)).toBeLessThan(950_000); const stored = await svc.getById(companyId, inserted[0]!.id); expect(stored?.markdown).toBe(savedMarkdown); @@ -762,11 +762,11 @@ describeEmbeddedPostgres("companySkillService.list", () => { .orderBy(companySkillVersions.id); expect(before.length).toBeGreaterThan(0); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { companySkillVersions }, capture); try { expect(await companySkillService(db).list(companyId)).toEqual(expected); } finally { capture.flush(); } - const reads = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" + const reads = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "company_skill_versions" && event.operation === "select"); expect(reads.reduce((sum, event) => sum + Number(event.calls), 0)).toBeGreaterThan(0); expect(reads.reduce((sum, event) => sum + Number(event.responseValueBytes), 0)).toBeLessThan(4096); @@ -783,11 +783,11 @@ describeEmbeddedPostgres("companySkillService.list", () => { ? { type, companyId: otherCompanyId, agentId: randomUUID() } : { type, companyIds: [otherCompanyId] }; const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { companySkillVersions }, capture); try { expect(await companySkillService(db, { actor }).list(companyId)).toEqual([]); } finally { capture.flush(); } - expect(events.find(event => event.event === "paperclip.db_response_capture.summary.v1")?.completedQueries).toBe(0); + expect(events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")?.completedQueries).toBe(0); }); it("restores a deleted release after warm validation", async () => { diff --git a/server/src/__tests__/conversation-settlement-transfer.test.ts b/server/src/__tests__/conversation-settlement-transfer.test.ts index 6a128b00e95..82b84ed75f3 100644 --- a/server/src/__tests__/conversation-settlement-transfer.test.ts +++ b/server/src/__tests__/conversation-settlement-transfer.test.ts @@ -2,7 +2,7 @@ import { randomUUID } from "node:crypto"; import { and, eq, sql } from "drizzle-orm"; import { afterAll, beforeAll, describe, expect, it } from "vitest"; import { agents, companies, createDb, heartbeatRuns, issueComments, issueThreadInteractions, issues } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "./helpers/embedded-postgres.js"; import { settleConversationTurnForRun } from "../services/agent-conversations.js"; @@ -52,11 +52,11 @@ const support = await getEmbeddedPostgresTestSupport(); it.each(["response", "interaction", "reset"] as const)("bounds %s settlement reads and retains all saved text and run payloads", async reply => { const input = await seed(reply), before = await sourceDigests(input); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns, issues, issueComments }, capture); try { expect(await settleConversationTurnForRun(db, input.companyId, input.runId)).toBe(true); } finally { capture.flush(); } - const reads = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" + const reads = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && ["heartbeat_runs", "issues", "issue_comments"].includes(String(event.table)) && (event.operation === "select" || event.operation === "execute")); expect(reads.reduce((sum, event) => sum + Number(event.calls), 0)).toBeGreaterThanOrEqual(4); diff --git a/server/src/__tests__/database-operation-attribution.test.ts b/server/src/__tests__/database-operation-attribution.test.ts new file mode 100644 index 00000000000..41144ae6b27 --- /dev/null +++ b/server/src/__tests__/database-operation-attribution.test.ts @@ -0,0 +1,137 @@ +import express from "express"; +import request from "supertest"; +import { QueryPromise } from "drizzle-orm/query-promise"; +import { afterEach, expect, it, vi } from "vitest"; +import { withDatabaseOperation } from "@paperclipai/db"; +import { installDatabaseWorkSignals } from "@paperclipai/db/work-signals"; +import { databaseOperationMiddleware } from "../middleware/database-operation.js"; +import { withBudgetSpan } from "../services/budget-tracing.js"; +import { createDeliveryWorkCoordinator } from "../services/delivery-work-coordinator.js"; +import { DELIVERY_QUEUES, notifyDeliveryWork } from "../services/delivery-work-notifications.js"; +import { + createRunPreparationTiming, + measureRunPhase, + withRunExecutionTiming, + withRunResponsePresentationTiming, + withRunWorkspaceFinalizationTiming, +} from "../services/execution-preparation-timing.js"; + +const { owners } = await vi.hoisted(async () => { + const { AsyncLocalStorage } = await import("node:async_hooks"); + return { owners: new AsyncLocalStorage() }; +}); +vi.mock("@paperclipai/db", async importOriginal => ({ + ...await importOriginal(), + withDatabaseOperation: (owner: string, action: () => T): T => owners.run(owner, action), +})); + +class OwnerQuery extends QueryPromise { + async execute() { return owners.getStore(); } +} + +afterEach(() => { + vi.unstubAllEnvs(); + vi.useRealTimers(); +}); + +it.each(["", "http://collector.test"])("attributes lazy queries to execution, preparation, and budget owners with endpoint %s", async endpoint => { + vi.stubEnv("OTEL_EXPORTER_OTLP_ENDPOINT", endpoint); + await withDatabaseOperation("http.request", async () => { + const query = new OwnerQuery(); + await expect(withRunExecutionTiming("private-run", () => query)).resolves.toBe("task.execution_attempt"); + await expect(withRunWorkspaceFinalizationTiming("private-run", () => query)).resolves.toBe("task.workspace_finalization"); + await expect(withRunResponsePresentationTiming("private-run", () => query)).resolves.toBe("task.response_presentation"); + await expect(createRunPreparationTiming("private-run")("agent_read", () => query)).resolves.toBe("heartbeat.prepare.agent_read"); + await expect(createRunPreparationTiming("private-run", "native.controller")("backend_setup", () => query)).resolves.toBe("native.controller.backend_setup"); + await expect(measureRunPhase("skills.inventory", () => query)).resolves.toBe("skills.inventory"); + await expect(withBudgetSpan("budget.accounting.transaction", () => query)).resolves.toBe("budget.accounting.transaction"); + await expect(query).resolves.toBe("http.request"); + }); + expect(owners.getStore()).toBeUndefined(); +}); + +it("keeps owner attribution after the span detail limit and restores nested scopes after failure", async () => { + vi.stubEnv("OTEL_EXPORTER_OTLP_ENDPOINT", "http://collector.test"); + const failure = new Error("private accounting failure"); + await withRunExecutionTiming("private-run", async () => { + for (let i = 0; i < 18; i++) { + await expect(measureRunPhase("skills.inventory", () => new OwnerQuery())).resolves.toBe("skills.inventory"); + } + await expect(measureRunPhase("execution.budget_reservation", async () => { + await expect(withBudgetSpan("budget.admission.reserve", async () => { + await Promise.resolve(); + expect(owners.getStore()).toBe("budget.admission.reserve"); + throw failure; + })).rejects.toBe(failure); + return new OwnerQuery(); + })).resolves.toBe("execution.budget_reservation"); + await expect(new OwnerQuery()).resolves.toBe("task.execution_attempt"); + }); + expect(owners.getStore()).toBeUndefined(); +}); + +it("keeps concurrent HTTP requests and nested work in fixed scopes without using private URLs", async () => { + vi.stubEnv("OTEL_EXPORTER_OTLP_ENDPOINT", ""); + const app = express(); + app.use(databaseOperationMiddleware); + app.use(express.json()); + let arrived = 0; + let release!: () => void; + const both = new Promise(resolve => { release = resolve; }); + app.all("/:privateId", async (req, res) => { + const before = await new OwnerQuery(); + const work = async () => { + if (++arrived === 2) release(); + await both; + return new OwnerQuery(); + }; + const during = req.params.privateId === "first" + ? await withBudgetSpan("budget.admission.reserve", work) + : await measureRunPhase("skills.inventory", work); + res.json({ before, during, after: await new OwnerQuery() }); + }); + const [first, second] = await Promise.all([ + request(app).get("/first?secret=private-first").expect(200), + request(app).post("/second?secret=private-second").send({ private: "request-body" }).expect(200), + ]); + expect(first.body).toEqual({ before: "http.request", during: "budget.admission.reserve", after: "http.request" }); + expect(second.body).toEqual({ before: "http.request", during: "skills.inventory", after: "http.request" }); + expect(owners.getStore()).toBeUndefined(); +}); + +it("replaces producer ownership on each delivery dispatch, including retry and pending checks", async () => { + vi.useFakeTimers(); + const execute = vi.fn(async () => [{ xid: "42" }]); + const database = installDatabaseWorkSignals({ execute, async transaction(action: (tx: object) => Promise): Promise { + return action({ execute }); + } }); + const seen: Array<{ queue: string; phase: string; owner: string | undefined }> = []; + const coordinator = createDeliveryWorkCoordinator({ owner: database, canRun: () => true, + onError: (_error, queue) => { seen.push({ queue, phase: "failure", owner: owners.getStore() }); }, + }); + let fail = true; + try { + const workers = withDatabaseOperation("http.request", () => [DELIVERY_QUEUES.feedback, DELIVERY_QUEUES.email].map(queue => + coordinator.register(queue, { retryMs: 5000, + run: async () => { + await Promise.resolve(); + seen.push({ queue, phase: "run", owner: await new OwnerQuery() }); + if (queue === DELIVERY_QUEUES.feedback && fail) { fail = false; throw new Error("retry"); } + }, + hasPending: async () => { + seen.push({ queue, phase: "pending", owner: await new OwnerQuery() }); + return false; + }, + }))); + await Promise.all(workers.map(worker => worker.ready)); + await withDatabaseOperation("budget.accounting.transaction", () => database.transaction(tx => + notifyDeliveryWork(tx, DELIVERY_QUEUES.feedback))); + await vi.advanceTimersByTimeAsync(1); + expect(seen.map(({ phase }) => phase).sort()).toEqual(["failure", "pending", "pending", "run", "run", "run"]); + for (const entry of seen) expect(entry.owner).toBe(`delivery.${entry.queue}`); + expect(owners.getStore()).toBeUndefined(); + expect(coordinator.nextWakeAt()).toBeNull(); + } finally { + await coordinator.stop(); + } +}); diff --git a/server/src/__tests__/github-operation-credentials.test.ts b/server/src/__tests__/github-operation-credentials.test.ts index 499134e2b55..75eeeacfcb5 100644 --- a/server/src/__tests__/github-operation-credentials.test.ts +++ b/server/src/__tests__/github-operation-credentials.test.ts @@ -8,7 +8,7 @@ import { createRuntimeToolsToken } from "../runtime-tools-token.js"; import { errorHandler } from "../middleware/index.js"; import { randomUUID } from "node:crypto"; import { eq } from "drizzle-orm"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { afterAll, beforeAll, describe, expect, it, vi } from "vitest"; import { agents, @@ -87,7 +87,7 @@ const support = external ? { supported: true } : await getEmbeddedPostgresTestSu }); await db.insert(toolConnections).values(irrelevant); const observed = createDb(external ?? database!.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { toolConnections }, capture); try { expect(await resolveManagedGitHubIdentitySelection(observed, input.companyId, { agentId: input.agentId, responsibleUserId: "A" })) @@ -119,7 +119,7 @@ const support = external ? { supported: true } : await getEmbeddedPostgresTestSu }).where(eq(heartbeatRuns.id, input.runId)); const [before] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, input.runId)); const observed = createDb(external ?? database!.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { heartbeatRuns }, capture); try { expect(await resolveGitHubOperationCredentials(observed, input)).toMatchObject({ diff --git a/server/src/__tests__/heartbeat-run-event-sequencing.test.ts b/server/src/__tests__/heartbeat-run-event-sequencing.test.ts index 98a002f8557..71328d1b64b 100644 --- a/server/src/__tests__/heartbeat-run-event-sequencing.test.ts +++ b/server/src/__tests__/heartbeat-run-event-sequencing.test.ts @@ -1,7 +1,7 @@ import { resolveExternalTestDatabaseUrl } from "./helpers/external-test-database.js"; import { describe, expect, it } from "vitest"; import { eq, sql } from "drizzle-orm"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { agents, companies, @@ -63,11 +63,11 @@ describe("P6-11..13 / P6-17 canonical event allocator", () => { protocolSchemaVersion: 1, canonicalPayload: { sourceSeq } }, }); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRunEvents }, capture); try { expect((await append(5002)).highestContiguousSourceSeq).toBe(5000); } finally { capture.flush(); } - const reads = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" + const reads = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "heartbeat_run_events" && (event.operation === "select" || event.operation === "execute")); expect(reads.reduce((sum, event) => sum + Number(event.calls), 0)).toBeGreaterThan(0); expect(reads.reduce((sum, event) => sum + Number(event.rows), 0)).toBeLessThan(16); diff --git a/server/src/__tests__/heartbeat-run-privacy-routes.test.ts b/server/src/__tests__/heartbeat-run-privacy-routes.test.ts index c610d17ded9..a610b5b25bd 100644 --- a/server/src/__tests__/heartbeat-run-privacy-routes.test.ts +++ b/server/src/__tests__/heartbeat-run-privacy-routes.test.ts @@ -1,7 +1,7 @@ import { randomUUID } from "node:crypto"; import { eq } from "drizzle-orm"; import { drizzle } from "drizzle-orm/postgres-js"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import express from "express"; import request from "supertest"; import { afterAll, afterEach, beforeAll, describe, expect, it, vi } from "vitest"; @@ -268,7 +268,7 @@ describeEmbeddedPostgres("heartbeat run privacy routes", { concurrent: false }, }).where(eq(heartbeatRuns.id, f.privateRunId)); const [before] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, f.privateRunId)); const observed = createDb(externalDatabaseUrl ?? tempDb!.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { heartbeatRuns }, capture); try { const app = createApp(f.companyId, f.grantedAgentId, observed); diff --git a/server/src/__tests__/helpers/full-database-response-capture.test.ts b/server/src/__tests__/helpers/full-database-response-capture.test.ts new file mode 100644 index 00000000000..14a46c2ee8e --- /dev/null +++ b/server/src/__tests__/helpers/full-database-response-capture.test.ts @@ -0,0 +1,62 @@ +import { expect, it } from "vitest"; +import { createFullDatabaseResponseCapture } from "./full-database-response-capture.js"; + +const metadata = { operation: "select", table: "heartbeat_runs", callers: [] }; + +it("measures every oversized string and complex value without sampling or truncation", () => { + const events: Array> = []; + const capture = createFullDatabaseResponseCapture({ start: 0, end: 1000 }, event => events.push(event), () => 0); + const text = "private-payload🙂".repeat(30_000); + const nested = { instructions: text, additional: [{ prompt: text }] }; + const rows = Object.assign([[text, nested]], { columns: [{ name: "stdout_excerpt" }, { name: "context_snapshot" }] }); + const bytes = Buffer.byteLength(text) + Buffer.byteLength(JSON.stringify(nested)); + try { + for (let index = 0; index < 17; index++) expect(capture.execute(() => rows, metadata)).toBe(rows); + capture.flush(); + expect(events[0]).toMatchObject({ event: "paperclip.test_db_response_capture.entry.v1", + calls: 17, rows: 17, responseValueBytes: 17 * bytes, maxResponseValueBytes: bytes, + estimatedValues: 17, serializationErrors: 0, + }); + expect(events[1]).toMatchObject({ event: "paperclip.test_db_response_capture.summary.v1", + startedQueries: 17, completedQueries: 17, inFlightAtEnd: 0, overflowCalls: 0, responseValueBytes: 17 * bytes, + }); + expect(JSON.stringify(events)).not.toContain("private-payload"); + expect(nested.instructions).toBe(text); + } finally { capture.flush(); } +}); + +it("preserves asynchronous results and original query errors", async () => { + const events: Array> = []; + const capture = createFullDatabaseResponseCapture({ start: 0, end: 1000 }, event => events.push(event), () => 0); + const rows = Object.assign([{ value: { nested: "result" } }], { columns: [{ name: "value" }] }); + const failure = new Error("private query failure"); + try { + await expect(capture.execute(async () => rows, metadata)).resolves.toBe(rows); + await expect(capture.execute(async () => { throw failure; }, metadata)).rejects.toBe(failure); + expect(() => capture.execute(() => { throw failure; }, metadata)).toThrow(failure); + capture.flush(); + expect(events[0]).toMatchObject({ calls: 3, rows: 1, queryErrors: 2, + responseValueBytes: Buffer.byteLength(JSON.stringify(rows[0].value)), serializationErrors: 0, + }); + expect(events[1]).toMatchObject({ startedQueries: 3, completedQueries: 3, inFlightAtEnd: 0 }); + expect(JSON.stringify(events)).not.toContain(failure.message); + } finally { capture.flush(); } +}); + +it("reports unfinished work at the deadline without cancelling it or counting a late result", async () => { + const events: Array> = []; + let now = 0; + const capture = createFullDatabaseResponseCapture({ start: 0, end: 1000 }, event => events.push(event), () => now); + let release!: (value: string[]) => void; + const original = new Promise(resolve => { release = resolve; }); + const pending = capture.execute(() => original, metadata); + now = 1000; + capture.flush(); + release(["result"]); + await expect(pending).resolves.toEqual(["result"]); + capture.flush(); + expect(events).toHaveLength(1); + expect(events[0]).toMatchObject({ event: "paperclip.test_db_response_capture.summary.v1", + startedQueries: 1, completedQueries: 0, inFlightAtEnd: 1, responseValueBytes: 0, + }); +}); diff --git a/server/src/__tests__/helpers/full-database-response-capture.ts b/server/src/__tests__/helpers/full-database-response-capture.ts new file mode 100644 index 00000000000..a52831c2adc --- /dev/null +++ b/server/src/__tests__/helpers/full-database-response-capture.ts @@ -0,0 +1,115 @@ +import { randomUUID } from "node:crypto"; +import { createDatabaseResponseCapture, type ResponseCaptureWindow } from "@paperclipai/db/response-capture"; + +export { installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; + +type Capture = ReturnType; +type Metadata = Parameters[1]; +type Entry = Metadata & { calls: number; rows: number; bytes: number; maxBytes: number; + queryErrors: number; serializationErrors: number; estimatedValues: number }; + +function fullResponseValueSize(value: unknown): { bytes: number; estimatedValues: number } { + const columns = value && typeof value === "object" ? (value as { columns?: unknown }).columns : undefined; + if (!Array.isArray(value) || !Array.isArray(columns)) { + const serialized = JSON.stringify(value, (_, item: unknown) => typeof item === "bigint" ? item.toString() : item); + return { bytes: serialized === undefined ? 0 : Buffer.byteLength(serialized), estimatedValues: 1 }; + } + let bytes = 0, estimatedValues = 0; + for (const row of value) { + const cells = Array.isArray(row) ? row : columns.map(column => row[column.name]); + for (const cell of cells) { + if (cell === null || cell === undefined) continue; + if (typeof cell === "string") bytes += Buffer.byteLength(cell); + else if (typeof cell === "boolean") bytes += 1; + else if (typeof cell === "number" || typeof cell === "bigint") bytes += Buffer.byteLength(String(cell)); + else { + estimatedValues += 1; + const serialized = JSON.stringify(cell, (_, item: unknown) => typeof item === "bigint" ? item.toString() : item); + if (serialized !== undefined) bytes += Buffer.byteLength(serialized); + } + } + } + return { bytes, estimatedValues }; +} + +export function createFullDatabaseResponseCapture( + window: ResponseCaptureWindow, + emit: (event: Record) => void, + now: () => number = Date.now, +): Capture { + const capture = createDatabaseResponseCapture(window, () => {}, now); + const id = randomUUID(), entries = new Map(); + let closed = false, inFlight = 0, started = 0, completed = 0, overflowCalls = 0; + const send = (event: Record) => { try { emit(event); } catch {} }; + function flush() { + if (closed) return; + closed = true; + clearTimeout(timer); + capture.flush(); + const ordered = [...entries.values()].sort((a, b) => b.bytes - a.bytes); + for (const [groupIndex, entry] of ordered.entries()) send({ + event: "paperclip.test_db_response_capture.entry.v1", captureId: id, + groupIndex, groupPage: Math.floor(groupIndex / 128), + operation: entry.operation, table: entry.table, callers: entry.callers, + calls: entry.calls, rows: entry.rows, responseValueBytes: entry.bytes, + maxResponseValueBytes: entry.maxBytes, estimatedValues: entry.estimatedValues, + queryErrors: entry.queryErrors, serializationErrors: entry.serializationErrors, + }); + send({ event: "paperclip.test_db_response_capture.summary.v1", captureId: id, + windowStart: new Date(window.start).toISOString(), windowEnd: new Date(window.end).toISOString(), + closedAt: new Date(now()).toISOString(), startedQueries: started, completedQueries: completed, + inFlightAtEnd: inFlight, groups: entries.size, groupPageSize: 128, groupPages: Math.ceil(ordered.length / 128), + overflowCalls, responseValueBytes: ordered.reduce((sum, entry) => sum + entry.bytes, 0), + rowValuesLogged: false, sqlOrParametersLogged: false, wireBytesMeasured: false, + measurementBoundary: "postgres-js results before Drizzle column decoding", + relationalQueriesMeasured: true, unsafeDriverQueriesMeasured: true, + taggedDriverQueriesMeasured: false, streamingQueriesMeasured: false, + }); + entries.clear(); + } + const timer = setTimeout(flush, Math.max(0, window.end - now())); + timer.unref(); + function finish(metadata: Metadata, value: unknown, failed: boolean) { + if (!capture.active()) return; + inFlight -= 1; + completed += 1; + let key = JSON.stringify(metadata); + if (!entries.has(key) && entries.size >= 2047) { + overflowCalls += 1; + metadata = { operation: "other", table: "other", callers: [] }; + key = "overflow"; + } + let entry = entries.get(key); + if (!entry) { + entry = { ...metadata, calls: 0, rows: 0, bytes: 0, maxBytes: 0, + queryErrors: 0, serializationErrors: 0, estimatedValues: 0 }; + entries.set(key, entry); + } + entry.calls += 1; + if (failed) { entry.queryErrors += 1; return; } + entry.rows += Array.isArray(value) ? value.length : 0; + try { + const size = fullResponseValueSize(value); + entry.bytes += size.bytes; + entry.maxBytes = Math.max(entry.maxBytes, size.bytes); + entry.estimatedValues += size.estimatedValues; + } catch { entry.serializationErrors += 1; } + } + function execute(action: () => unknown, metadata: Metadata) { + if (!capture.active()) return action(); + inFlight += 1; + started += 1; + let result: unknown; + try { result = action(); } + catch (error) { finish(metadata, undefined, true); throw error; } + let asynchronous = false; + try { asynchronous = Boolean(result && typeof (result as { then?: unknown }).then === "function"); } catch {} + if (asynchronous) return Promise.resolve(result).then( + value => { finish(metadata, value, false); return value; }, + error => { finish(metadata, undefined, true); throw error; }, + ); + finish(metadata, result, false); + return result; + } + return { ...capture, execute, flush }; +} diff --git a/server/src/__tests__/issue-creation-source-read.test.ts b/server/src/__tests__/issue-creation-source-read.test.ts index 2b47f3af580..ba3a74fc2cf 100644 --- a/server/src/__tests__/issue-creation-source-read.test.ts +++ b/server/src/__tests__/issue-creation-source-read.test.ts @@ -1,6 +1,6 @@ import { randomUUID } from "node:crypto"; import { activityLog, agents, companies, createDb, heartbeatRuns, issues } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { eq } from "drizzle-orm"; import { afterAll, beforeAll, describe, expect, it } from "vitest"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "./helpers/embedded-postgres.js"; @@ -55,7 +55,7 @@ describe.skipIf(!support.supported)("creation source run projections", () => { expect(run.issueId).toBe(binding === "scoped" ? sourceId : null); expect(run.nativeIssueId).toBeNull(); const observed = createDb(database.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { heartbeatRuns, issues }, capture); try { const result = await resolveIssueCreationSource(observed, child); diff --git a/server/src/__tests__/issue-queued-comments-routes.test.ts b/server/src/__tests__/issue-queued-comments-routes.test.ts index 1d0467105af..fed13ba5780 100644 --- a/server/src/__tests__/issue-queued-comments-routes.test.ts +++ b/server/src/__tests__/issue-queued-comments-routes.test.ts @@ -4,7 +4,7 @@ import { randomUUID } from "node:crypto"; import express from "express"; import request from "supertest"; import { eq, sql } from "drizzle-orm"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { afterAll, afterEach, beforeAll, describe, expect, it, vi } from "vitest"; import { agentRuntimeState, @@ -202,7 +202,7 @@ describeEmbeddedPostgres("issue queued-comment routes", () => { if (fallback) await db.update(issues).set({ executionRunId: null }).where(eq(issues.id, f.issueId)); const [before] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, f.runId)); const observed = createDb(tempDb!.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { heartbeatRuns }, capture); try { const response = await request(app(f.companyId, "queue-owner", undefined, observed)) @@ -238,7 +238,7 @@ describeEmbeddedPostgres("issue queued-comment routes", () => { }).where(eq(heartbeatRuns.companyId, f.companyId)); const [before] = await db.select().from(agentWakeupRequests).where(eq(agentWakeupRequests.id, f.wakeId)); const observed = createDb(tempDb!.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { agentWakeupRequests, heartbeatRuns }, capture); try { const response = await request(app(f.companyId, "queue-owner", undefined, observed)).get(path).expect(200); @@ -275,7 +275,7 @@ describeEmbeddedPostgres("issue queued-comment routes", () => { })), ]); const observed = createDb(tempDb!.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { agentWakeupRequests }, capture); try { const response = await request(app(f.companyId, "queue-owner", undefined, observed)).get(path).expect(200); diff --git a/server/src/__tests__/legacy-workspace-restore-recovery.test.ts b/server/src/__tests__/legacy-workspace-restore-recovery.test.ts index 65e0e0cc147..38d748d1a36 100644 --- a/server/src/__tests__/legacy-workspace-restore-recovery.test.ts +++ b/server/src/__tests__/legacy-workspace-restore-recovery.test.ts @@ -1,5 +1,5 @@ import { randomBytes, randomUUID } from "node:crypto"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { and, eq, sql } from "drizzle-orm"; import { afterAll, beforeAll, describe, expect, it, vi } from "vitest"; import { agents, companies, createDb, environmentLeases, environments, executionWorkspaces, heartbeatRuns, issueRecoveryActions, issues, projects } from "@paperclipai/db"; @@ -54,12 +54,12 @@ const support = externalTestDatabaseUrl ? { supported: true } : await getEmbedde runnerProfileJson: { savedProfile: bulk }, stdoutExcerpt: bulk, stderrExcerpt: bulk, }).where(eq(heartbeatRuns.id, f.runId)).returning(); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); let returned: Awaited>; try { returned = await terminalizeLegacyExecution({ db, run: saved!, status: "failed", patch }); } finally { capture.flush(); } - const groups = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1"); + const groups = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1"); const reads = groups.filter(group => group.table === "heartbeat_runs" && group.operation === "select"); expect(reads.reduce((sum, group) => sum + Number(group.calls), 0)).toBe(1); expect(reads.reduce((sum, group) => sum + Number(group.responseValueBytes), 0)).toBeLessThan(4096); @@ -86,7 +86,7 @@ const support = externalTestDatabaseUrl ? { supported: true } : await getEmbedde patch: { resultJson: { workspaceRestoreFailure: "restore_failed", futureResult: bulk } }, }))!; const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); let returned: Awaited>; try { returned = await terminalizeLegacyExecution({ db, run: failed, status: "failed", recordRestoreFailureOnly, @@ -94,7 +94,7 @@ const support = externalTestDatabaseUrl ? { supported: true } : await getEmbedde ...(recordRestoreFailureOnly ? { patch: { resultJson: failed.resultJson } } : {}), }); } finally { capture.flush(); } - const writes = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" + const writes = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "heartbeat_runs" && event.operation === "update"); expect(writes.reduce((sum, group) => sum + Number(group.rows), 0)).toBe(1); expect(returned).toMatchObject({ id: f.runId, status: "failed", finishedAt: failed.finishedAt, diff --git a/server/src/__tests__/native-environment-settlement-work.test.ts b/server/src/__tests__/native-environment-settlement-work.test.ts index 7a52bc5304d..4fd2448b9a4 100644 --- a/server/src/__tests__/native-environment-settlement-work.test.ts +++ b/server/src/__tests__/native-environment-settlement-work.test.ts @@ -11,7 +11,7 @@ import { setTimeout as delay } from "node:timers/promises"; import { eq } from "drizzle-orm"; import { afterAll, afterEach, beforeAll, beforeEach, describe, expect, it, vi } from "vitest"; import { agents, companies, completionContracts, createDb, environmentLeases, environments, heartbeatRuns, issues, nativeRunFinalizations, type Db } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { createDeliveryWorkCoordinator } from "../services/delivery-work-coordinator.js"; import { heartbeatService } from "../services/heartbeat.js"; import { environmentRuntimeService, type EnvironmentDriver } from "../services/environment-runtime.js"; @@ -180,7 +180,7 @@ describe("native environment release scheduling", () => { } const events: Record[] = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { nativeRunFinalizations, heartbeatRuns, environmentLeases }, capture); const settle = vi.fn(async () => {}); const work = nativeEnvironmentSettlementWork(db, settle); diff --git a/server/src/__tests__/native-settled-process-release.test.ts b/server/src/__tests__/native-settled-process-release.test.ts index 1028d9abc07..a6805c61582 100644 --- a/server/src/__tests__/native-settled-process-release.test.ts +++ b/server/src/__tests__/native-settled-process-release.test.ts @@ -1,7 +1,7 @@ import { resolveExternalTestDatabaseUrl } from "./helpers/external-test-database.js"; import { EMBEDDED_POSTGRES_TEST_TIMEOUT_MS } from "@paperclipai/db"; import { randomBytes, randomUUID } from "node:crypto"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { spawn } from "node:child_process"; import os from "node:os"; import { and, eq, sql } from "drizzle-orm"; @@ -222,11 +222,11 @@ suite("settled native run process identity", () => { const saved = await readRun(runId); const events: Array> = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); try { expect(await releaseSettledNativeRunProcess(db, runId)).toBe("released"); } finally { capture.flush(); } - const summary = events.find(event => event.event === "paperclip.db_response_capture.summary.v1")!; + const summary = events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")!; expect(summary.responseValueBytes).toBeLessThan(8192); const after = await readRun(runId); expect(after).toEqual({ ...saved, processPid: null, processGroupId: null, processStartedAt: null, diff --git a/server/src/__tests__/sandbox-provider-schema-reads.test.ts b/server/src/__tests__/sandbox-provider-schema-reads.test.ts index 55f81f8bfbe..fd82c852bbc 100644 --- a/server/src/__tests__/sandbox-provider-schema-reads.test.ts +++ b/server/src/__tests__/sandbox-provider-schema-reads.test.ts @@ -2,7 +2,7 @@ import { randomBytes, randomUUID } from "node:crypto"; import { eq, sql, type SQL } from "drizzle-orm"; import { afterAll, afterEach, beforeAll, beforeEach, describe, expect, it } from "vitest"; import { createDb, plugins, type Db } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import type { PaperclipPluginManifestV1, PluginEnvironmentDriverDeclaration } from "@paperclipai/shared"; import { resolvePluginSandboxProviderConfigSchema, resolvePluginSandboxProviderDriverByKey } from "../services/plugin-environment-driver.js"; import { resolveEnvironmentDriverConfigForRuntime, resolveSandboxProviderSecretRefPaths } from "../services/environment-config.js"; @@ -39,12 +39,12 @@ describe.skipIf(!support.supported)("sandbox provider schema reads", () => { const lookup = (client: Db, driverKey = key) => resolvePluginSandboxProviderConfigSchema({ db: client, driverKey }); async function measure(client: Db, operation: () => Promise) { const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event), () => now); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event), () => now); installDatabaseResponseCapture(client, { plugins }, capture); try { const value = await operation(); capture.flush(); - const entries = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1"); + const entries = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1"); return { value, bytes: entries.reduce((sum, entry) => sum + Number(entry.responseValueBytes), 0), calls: entries.reduce((sum, entry) => sum + Number(entry.calls), 0) }; } finally { capture.flush(); } diff --git a/server/src/__tests__/tool-effective-assignments.test.ts b/server/src/__tests__/tool-effective-assignments.test.ts index 4b99a23eec2..88534789025 100644 --- a/server/src/__tests__/tool-effective-assignments.test.ts +++ b/server/src/__tests__/tool-effective-assignments.test.ts @@ -5,7 +5,7 @@ import { agents, companies, createDb, toolApplications, toolCatalogEntries, toolConnections, toolProfileBindings, toolProfileEntries, toolProfiles, type Db, } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "./helpers/full-database-response-capture.js"; import { toolAccessService } from "../services/tool-access.js"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "./helpers/embedded-postgres.js"; @@ -149,14 +149,14 @@ describeDatabase("effective tool assignments", () => { const before = await service.getEffectiveToolAssignmentsForAgent(f.company.id, f.agent.id); expect(before.allowedTools).toHaveLength(102); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { toolCatalogEntries, toolProfileEntries }, capture); let scoped: Awaited>; try { scoped = await service.getConnectionAssignmentsForAgent(f.company.id, f.agent.id, [f.connection.id]); } finally { capture.flush(); } expect(Number(events.at(-1)?.completedQueries)).toBeGreaterThan(0); expect(Number(events.at(-1)?.responseValueBytes)).toBeLessThan(16 * 1024); - const catalogQueries = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" + const catalogQueries = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "tool_catalog_entries" && event.operation === "select"); expect(catalogQueries).toHaveLength(1); expect(catalogQueries[0]).toMatchObject({ calls: 1, rows: 2 }); @@ -192,13 +192,13 @@ describeDatabase("effective tool assignments", () => { const service = toolAccessService(db), before = await compare(f); const savedRules = await db.select().from(toolProfileEntries); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { toolProfileEntries, toolProfileBindings }, capture); try { const scoped = await service.getConnectionAssignmentsForAgent(f.company.id, f.agent.id, [f.connection.id]); capture.flush(); - const rules = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" && event.table === "tool_profile_entries"); - const bindings = events.filter(event => event.event === "paperclip.db_response_capture.entry.v1" && event.table === "tool_profile_bindings"); + const rules = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "tool_profile_entries"); + const bindings = events.filter(event => event.event === "paperclip.test_db_response_capture.entry.v1" && event.table === "tool_profile_bindings"); expect(rules).toHaveLength(1); expect(Number(rules[0].responseValueBytes)).toBeLessThan(4096); expect(rules[0]).toMatchObject({ calls: 1, rows: 2 }); diff --git a/server/src/app.ts b/server/src/app.ts index 06adc15edb8..17b4e63e127 100644 --- a/server/src/app.ts +++ b/server/src/app.ts @@ -12,6 +12,7 @@ import { DELIVERY_QUEUES } from "./services/delivery-work-notifications.js"; import { createLifecycleDriver } from "./services/agent-lifecycle-driver.js"; import { startAgentLifecycle } from "./services/agent-lifecycle.js"; import { idleAdmissionMiddleware, trackIdleRequestHandlers } from "./middleware/idle-admission.js"; +import { databaseOperationMiddleware } from "./middleware/database-operation.js"; import { staticUiFiles } from "./middleware/static-ui.js"; import { retainedUiAssets } from "./retained-ui-assets.js"; import { createStorageProviderFromConfig } from "./storage/provider-registry.js"; @@ -470,6 +471,7 @@ export async function createApp( }, ) { const app = express(); + app.use(databaseOperationMiddleware); app.use(idleAdmissionMiddleware); const staticUi = express.Router(); app.locals.paperclipDb = db; diff --git a/server/src/middleware/database-operation.ts b/server/src/middleware/database-operation.ts new file mode 100644 index 00000000000..b7cbc7abe01 --- /dev/null +++ b/server/src/middleware/database-operation.ts @@ -0,0 +1,5 @@ +import { withDatabaseOperation } from "@paperclipai/db"; +import type { RequestHandler } from "express"; + +export const databaseOperationMiddleware: RequestHandler = (_req, _res, next) => + withDatabaseOperation("http.request", next); diff --git a/server/src/modules/wake-queue/adapters/release-run-read.test.ts b/server/src/modules/wake-queue/adapters/release-run-read.test.ts index 6a669edf617..4ad78f2b1e0 100644 --- a/server/src/modules/wake-queue/adapters/release-run-read.test.ts +++ b/server/src/modules/wake-queue/adapters/release-run-read.test.ts @@ -1,6 +1,6 @@ import { randomBytes, randomUUID } from "node:crypto"; import { agents, companies, createDb, heartbeatRuns } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../../__tests__/helpers/full-database-response-capture.js"; import { eq } from "drizzle-orm"; import { afterAll, beforeAll, describe, expect, it } from "vitest"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "../../../__tests__/helpers/embedded-postgres.js"; @@ -40,7 +40,7 @@ describe.skipIf(!support.supported)("wake release run reads", () => { const scope = { companyId, runId: before.id }; const events: Array> = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); try { const native = await db.transaction(tx => readReleaseRun(tx as unknown as typeof db, scope)); @@ -51,7 +51,7 @@ describe.skipIf(!support.supported)("wake release run reads", () => { expect(native.run).not.toHaveProperty("stdoutExcerpt"); expect(native.run).not.toHaveProperty("stderrExcerpt"); } finally { capture.flush(); } - const summary = events.find(event => event.event === "paperclip.db_response_capture.summary.v1")!; + const summary = events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")!; expect(summary.completedQueries).toBe(1); expect(summary.responseValueBytes).toBeLessThan(8192); expect((await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, before.id)))[0]).toEqual(before); @@ -97,12 +97,12 @@ describe.skipIf(!support.supported)("wake release run reads", () => { contextSnapshot: { ...context, ...launch }, resultJson: evidence }).returning(); const events: Array> = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); let selected: Awaited>; try { selected = await db.transaction(tx => readReleaseRun(tx as unknown as typeof db, { companyId, runId: before.id })); } finally { capture.flush(); } - const summary = events.find(event => event.event === "paperclip.db_response_capture.summary.v1")!; + const summary = events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")!; expect(summary.completedQueries).toBe(1); expect(summary.responseValueBytes).toBeLessThan(8192); expect(selected!.run?.contextSnapshot).toEqual(context); diff --git a/server/src/services/budget-tracing.ts b/server/src/services/budget-tracing.ts index c0f525a61b1..f4b9212ca8f 100644 --- a/server/src/services/budget-tracing.ts +++ b/server/src/services/budget-tracing.ts @@ -1,18 +1,27 @@ import { trace, type Span } from "@opentelemetry/api"; +import { withDatabaseOperation } from "@paperclipai/db"; + +type BudgetOperation = "budget.accounting.lock_wait" | "budget.accounting.recover" + | "budget.accounting.settlement" | "budget.accounting.transaction" + | "budget.admission.evaluate" | "budget.admission.reserve" + | "budget.cancellation.deliver" | "budget.enforcement.deliver" + | "budget.enforcement.scope" | "budget.exposure.evaluate"; /** Operator-gated OpenTelemetry only; these spans contain no prompt, receipt, * credential, or provider error text. Diagnostics never change accounting. */ -export async function withBudgetSpan(name: string, work: () => Promise, attributes?: Record) { - if (!process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim()) return work(); - let operation: Promise | undefined; - const run = (span?: Span) => operation ??= Promise.resolve().then(work).finally(() => { - try { span?.end(); } catch { /* Diagnostics cannot change accounting. */ } +export function withBudgetSpan(name: BudgetOperation, work: () => Promise, attributes?: Record) { + return withDatabaseOperation(name, async () => { + if (!process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim()) return work(); + let operation: Promise | undefined; + const run = (span?: Span) => operation ??= Promise.resolve().then(work).finally(() => { + try { span?.end(); } catch { /* Diagnostics cannot change accounting. */ } + }); + try { + const traced = trace.getTracer("paperclip.budgets").startActiveSpan(name, { attributes }, span => run(span)); + // Some external SDK implementations can fail before or after the callback. + // Own the accounting promise so either failure still executes work once. + void Promise.resolve(traced).catch(() => undefined); + } catch { /* Preserve the accounting operation if span creation fails. */ } + return operation ?? run(); }); - try { - const traced = trace.getTracer("paperclip.budgets").startActiveSpan(name, { attributes }, span => run(span)); - // Some external SDK implementations can fail before or after the callback. - // Own the accounting promise so either failure still executes work once. - void Promise.resolve(traced).catch(() => undefined); - } catch { /* Preserve the accounting operation if span creation fails. */ } - return operation ?? run(); } diff --git a/server/src/services/chat-channels/authorization-run-read.test.ts b/server/src/services/chat-channels/authorization-run-read.test.ts index 3d56b695222..5e573a5974e 100644 --- a/server/src/services/chat-channels/authorization-run-read.test.ts +++ b/server/src/services/chat-channels/authorization-run-read.test.ts @@ -1,6 +1,6 @@ import { randomBytes, randomUUID } from "node:crypto"; import { agents, companies, createDb, heartbeatRuns } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../__tests__/helpers/full-database-response-capture.js"; import { eq } from "drizzle-orm"; import { afterAll, beforeAll, describe, expect, it } from "vitest"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "../../__tests__/helpers/embedded-postgres.js"; @@ -49,7 +49,7 @@ describe.skipIf(!support.supported)("chat authorization run reads", () => { const [before] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, scope.failedRunId)); const events: Array> = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); try { const selected = await db.transaction(tx => readChatAuthorizationRun(tx, scope, true)); @@ -58,7 +58,7 @@ describe.skipIf(!support.supported)("chat authorization run reads", () => { expect(selected.run).not.toHaveProperty("runnerProfileJson"); expect(selected.run).not.toHaveProperty("stdoutExcerpt"); } finally { capture.flush(); } - const summary = events.find(event => event.event === "paperclip.db_response_capture.summary.v1")!; + const summary = events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")!; expect(summary.completedQueries).toBeGreaterThan(0); expect(summary.responseValueBytes).toBeLessThan(4096); const retry = await db.transaction(tx => readChatAuthorizationRun(tx, scope, false)); diff --git a/server/src/services/chat-channels/github/webhook-ingress.test.ts b/server/src/services/chat-channels/github/webhook-ingress.test.ts index ab868d63c5c..975f0b810de 100644 --- a/server/src/services/chat-channels/github/webhook-ingress.test.ts +++ b/server/src/services/chat-channels/github/webhook-ingress.test.ts @@ -2,7 +2,7 @@ import { createHmac } from "node:crypto"; import { eq } from "drizzle-orm"; import { afterAll, afterEach, beforeAll, describe, expect, it, vi } from "vitest"; import { applyPendingMigrations, chatActions, createDb } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../../__tests__/helpers/full-database-response-capture.js"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "../../../__tests__/helpers/embedded-postgres.js"; import { resolveExternalTestDatabaseUrl } from "../../../__tests__/helpers/external-test-database.js"; import { cleanupIngressFixture, githubIngressFixture as createFixture } from "../../../__tests__/helpers/github-webhook-ingress.js"; @@ -36,7 +36,7 @@ describe.skipIf(!support.supported)("GitHub webhook ingress claim PostgreSQL beh const f = await githubIngressFixture(db, createGitHubWebhookIngress, 768 * 1024); const action = await f.insertAction(); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { chatActions }, capture); try { expect((await f.service.processGitHubWebhookIngress(action.id))?.status).toBe(202); } finally { capture.flush(); } @@ -59,7 +59,7 @@ describe.skipIf(!support.supported)("GitHub webhook ingress claim PostgreSQL beh // A corrupt body must not let a nonclaimant overwrite a live or delayed claim. const action = await f.insertAction({ status, result, payload: { ...f.payload, bodySha256: "0".repeat(64) } }); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 1, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { chatActions }, capture); let response: Response | null; try { response = await f.service.processGitHubWebhookIngress(action.id); } @@ -67,7 +67,7 @@ describe.skipIf(!support.supported)("GitHub webhook ingress claim PostgreSQL beh expect(response?.status ?? null).toBe(accepted ? 202 : null); expect(await f.readAction(action.id)).toEqual(action); expect(f.calls).toEqual([]); - expect(events.find(event => event.event === "paperclip.db_response_capture.summary.v1")?.responseValueBytes).toBeLessThan(1024); + expect(events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")?.responseValueBytes).toBeLessThan(1024); }); it.each(["received", "failed", "processing"])("settles eligible malformed %s payloads without replay", async status => { diff --git a/server/src/services/delivery-work-coordinator.ts b/server/src/services/delivery-work-coordinator.ts index 3e1f1b95b2b..42638c33e34 100644 --- a/server/src/services/delivery-work-coordinator.ts +++ b/server/src/services/delivery-work-coordinator.ts @@ -1,4 +1,5 @@ import { subscribeDatabaseWork, databaseWorkPending, reconcileDatabaseWork } from "@paperclipai/db/work-signals"; +import { withDatabaseOperation } from "@paperclipai/db"; import { createWorkScheduler } from "./work-scheduler.js"; import { type DeliveryQueue } from "./delivery-work-notifications.js"; import { beginIdleTrackedWork } from "./task-admission.js"; @@ -70,7 +71,7 @@ export function createDeliveryWorkCoordinator(input: { const attempt = new AbortController(); let runFailed = false; controller = attempt; - running = Promise.resolve().then(() => reconcileDatabaseWork(input.owner, queue)) + running = withDatabaseOperation(`delivery.${queue}`, () => Promise.resolve().then(() => reconcileDatabaseWork(input.owner, queue)) .then(() => workerStopped || !(input.canRun() || (task.runDuringDrain && input.canReconcile?.())) ? undefined : task.run(attempt.signal).catch(error => { runFailed = true; throw error; })).then(() => workerStopped ? false : task.hasPending()).then(pending => { pendingWork = pending || databaseWorkPending(input.owner, queue); if (pendingWork) schedule(task.retryMs); @@ -98,7 +99,7 @@ export function createDeliveryWorkCoordinator(input: { controller = null; finish(); if (dirty) schedule(0); - }); + })); } function wake() { if (workerStopped) return; diff --git a/server/src/services/execution-preparation-timing.ts b/server/src/services/execution-preparation-timing.ts index 9ee7f8a189e..4ba7aa69457 100644 --- a/server/src/services/execution-preparation-timing.ts +++ b/server/src/services/execution-preparation-timing.ts @@ -1,4 +1,5 @@ import { AsyncLocalStorage } from "node:async_hooks"; +import { withDatabaseOperation } from "@paperclipai/db"; import { EXECUTION_PREPARATION_SPAN_ATTRS, getActiveStepContext, runWithRuntimeParent } from "@paperclipai/adapter-utils/acpx-engine/startup-timing"; import { createHash } from "node:crypto"; import { isSpanContextValid, ROOT_CONTEXT, SpanStatusCode, trace, type Context } from "@opentelemetry/api"; @@ -156,7 +157,7 @@ function measure(runId: string, name: string, work: () => T | Promise, ind ended: false, details: !independent && previous?.runId === runId ? previous.details : new Map(), }; - operation = Promise.resolve().then(() => + operation = withDatabaseOperation(name, () => Promise.resolve().then(() => ownership.run(owned, () => runWithRuntimeParent(owned.parent, work))).then(value => { try { span?.end(); } catch {} owned.ended = true; @@ -166,10 +167,10 @@ function measure(runId: string, name: string, work: () => T | Promise, ind try { span?.end(); } catch {} owned.ended = true; throw error; - }); + })); return operation; }; - if (!endpointEnabled()) return (async () => work())(); + if (!endpointEnabled()) return withDatabaseOperation(name, async () => work()); try { const parent = independent ? undefined : activeParent ?? getRunExecutionTraceContext(runId); const trigger = parent ? undefined : trace.getActiveSpan()?.spanContext(); @@ -202,20 +203,22 @@ export function withRunWorkspaceFinalizationTiming(runId: string, work: () => export function withRunResponsePresentationTiming(runId: string, work: () => T | Promise): Promise { const owned = ownership.getStore(); if (owned?.runId === runId && owned.phase === "task.response_presentation" && !owned.ended) { - return (async () => work())(); + return withDatabaseOperation("task.response_presentation", async () => work()); } return measure(runId, "task.response_presentation", work, true); } -export async function measureRunPhase(phase: ExecutionPhase, work: () => T | Promise, counts?: { fileCount?: number; bytes?: number }): Promise { - const owned = ownership.getStore(); - if (!endpointEnabled() || !owned || owned.ended) return work(); - const count = owned.details.get(phase) ?? 0; - if (count >= 16) return work(); - owned.details.set(phase, count + 1); - // A startup step can be more specific than the owning run phase. Keep that - // causal parent while the child publishes its own context to plugin workers. - return measure(owned.runId, phase, work, false, counts, getActiveStepContext()?.parentContext as Context | undefined); +export function measureRunPhase(phase: ExecutionPhase, work: () => T | Promise, counts?: { fileCount?: number; bytes?: number }): Promise { + return withDatabaseOperation(phase, async () => { + const owned = ownership.getStore(); + if (!endpointEnabled() || !owned || owned.ended) return work(); + const count = owned.details.get(phase) ?? 0; + if (count >= 16) return work(); + owned.details.set(phase, count + 1); + // A startup step can be more specific than the owning run phase. Keep that + // causal parent while the child publishes its own context to plugin workers. + return measure(owned.runId, phase, work, false, counts, getActiveStepContext()?.parentContext as Context | undefined); + }); } export function beginRunPhase(phase: ExecutionPhase): (failed?: boolean) => void { diff --git a/server/src/services/heartbeat/native-stop-evidence-read.test.ts b/server/src/services/heartbeat/native-stop-evidence-read.test.ts index d53a5d4c417..9a139a5cc85 100644 --- a/server/src/services/heartbeat/native-stop-evidence-read.test.ts +++ b/server/src/services/heartbeat/native-stop-evidence-read.test.ts @@ -1,6 +1,6 @@ import { randomBytes, randomUUID } from "node:crypto"; import { heartbeatRuns, issues, type Db } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../__tests__/helpers/full-database-response-capture.js"; import { eq, sql } from "drizzle-orm"; import { describe, expect, it, vi } from "vitest"; import { isAcknowledgedNativeStop } from "../acknowledged-native-stop.js"; @@ -31,7 +31,7 @@ describe.skipIf(!runControlPostgresSupport.supported)("native Stop evidence read contextSnapshot: { savedInput: bulk }, runnerProfileJson: { savedInput: bulk }, stdoutExcerpt: bulk, stderrExcerpt: bulk, resultJson: result }).returning(); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); let evidence: Awaited>; try { evidence = await readNativeStopExecutionEvidence(db, company.id, id); } @@ -68,7 +68,7 @@ describe.skipIf(!runControlPostgresSupport.supported)("native Stop evidence read runtimeMode: "native", status: "cancelled" }).returning(); await db.execute(sql`update ${heartbeatRuns} set result_json = ${JSON.stringify(saved)}::jsonb where id = ${run.id}`); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); try { const evidence = await readNativeStopExecutionEvidence(db, company.id, run.id); diff --git a/server/src/services/heartbeat/run-state.test.ts b/server/src/services/heartbeat/run-state.test.ts index 28faa0efa6d..7769b779da8 100644 --- a/server/src/services/heartbeat/run-state.test.ts +++ b/server/src/services/heartbeat/run-state.test.ts @@ -1,5 +1,5 @@ import { randomBytes, randomUUID } from "node:crypto"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../__tests__/helpers/full-database-response-capture.js"; import type { Db } from "@paperclipai/db"; import { agents, @@ -186,13 +186,13 @@ describePostgres("heartbeat run state database wiring", () => { stdoutExcerpt: payload, stderrExcerpt: payload, }).returning(); const observed = createDb(database.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { heartbeatRuns }, capture); try { const state = extracted.createHeartbeatRunState(observed); const read = await state.getRunExecutionWait(companyId, run.id); capture.flush(); - const summary = events.find(event => event.event === "paperclip.db_response_capture.summary.v1")!; + const summary = events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")!; expect(summary.completedQueries).toBe(2); expect(summary.responseValueBytes).toBeLessThan(4096); expect(read).toMatchObject({ id: run.id, companyId, agentId: agent.id, status: "cancelled", contextSnapshot: context, @@ -228,7 +228,7 @@ describePostgres("heartbeat run state database wiring", () => { resultJson: { stdout: payload }, stdoutExcerpt: payload, stderrExcerpt: payload, }).returning(); const observed = createDb(database.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { heartbeatRuns }, capture); try { const state = extracted.createHeartbeatRunState(observed); @@ -236,7 +236,7 @@ describePostgres("heartbeat run state database wiring", () => { id: run.id, companyId, scopeKind: "issue", issueId: issue.id, executionWorkspaceId: workspaceId, }); capture.flush(); - const summary = events.find(event => event.event === "paperclip.db_response_capture.summary.v1")!; + const summary = events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")!; expect(summary.completedQueries).toBe(1); expect(summary.responseValueBytes).toBeLessThan(1024); expect((await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, run.id)))[0]).toEqual(run); @@ -260,7 +260,7 @@ describePostgres("heartbeat run state database wiring", () => { }).returning(); const observed = createDb(database.connectionString); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { heartbeatRuns }, capture); try { const state = extracted.createHeartbeatRunState(observed); @@ -270,7 +270,7 @@ describePostgres("heartbeat run state database wiring", () => { runtimeModeResolvedAt: null, startedAt: run.startedAt, createdAt: run.createdAt, contextSnapshot: { issueId: issue.id }, runnerProfileJson: { adapterDispatch: { adapterType: "paperclip_runner" } } }); capture.flush(); - const summary = events.find(event => event.event === "paperclip.db_response_capture.summary.v1")!; + const summary = events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")!; expect(summary.completedQueries).toBe(2); expect(summary.responseValueBytes).toBeLessThan(2048); expect((await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, run.id)))[0]).toEqual(run); @@ -321,7 +321,7 @@ describePostgres("heartbeat run state database wiring", () => { await state.getRunWorkspaceSettlement(run.id); const events: Array> = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); expect(await state.getRunCleanupState(run.id)).toEqual({ id: run.id, companyId, agentId: agent.id, runtimeMode: run.runtimeMode, @@ -334,7 +334,7 @@ describePostgres("heartbeat run state database wiring", () => { contextSnapshot: { timerClaimWasFirstHeartbeat: true }, }); capture.flush(); - const summary = events.find(event => event.event === "paperclip.db_response_capture.summary.v1")!; + const summary = events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")!; expect(summary.completedQueries).toBe(2); expect(summary.responseValueBytes).toBeLessThan(2000); expect((await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, run.id)))[0]).toEqual(run); diff --git a/server/src/services/native-runtime/__tests__/helpers/committed-replay.ts b/server/src/services/native-runtime/__tests__/helpers/committed-replay.ts index 7caef7cf216..6f9a222e39e 100644 --- a/server/src/services/native-runtime/__tests__/helpers/committed-replay.ts +++ b/server/src/services/native-runtime/__tests__/helpers/committed-replay.ts @@ -1,5 +1,5 @@ import { heartbeatRuns, type Db } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../../../__tests__/helpers/full-database-response-capture.js"; import { eq } from "drizzle-orm"; import { expect } from "vitest"; @@ -21,11 +21,11 @@ export async function verifyCommittedReplayPayloadReads( const [before] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, runId)); const events: Array> = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); try { await replay(); } finally { capture.flush(); } - const summary = events.find(event => event.event === "paperclip.db_response_capture.summary.v1")!; + const summary = events.find(event => event.event === "paperclip.test_db_response_capture.summary.v1")!; expect(summary.completedQueries).toBeGreaterThan(0); expect(summary.responseValueBytes).toBeLessThan(100_000); const [after] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, runId)); diff --git a/server/src/services/native-runtime/chat-attachment-reuse.test.ts b/server/src/services/native-runtime/chat-attachment-reuse.test.ts index d0de5ab04c9..7870a8033d9 100644 --- a/server/src/services/native-runtime/chat-attachment-reuse.test.ts +++ b/server/src/services/native-runtime/chat-attachment-reuse.test.ts @@ -29,7 +29,7 @@ import { toolApplications, toolConnections, } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../__tests__/helpers/full-database-response-capture.js"; import { startEmbeddedPostgresTestDatabase } from "../../__tests__/helpers/embedded-postgres.js"; import { createLocalDiskStorageProvider } from "../../storage/local-disk-provider.js"; @@ -322,7 +322,7 @@ describe("native same-conversation chat attachment reuse", () => { const deliveries = await db.select().from(chatDeliveries).where(eq(chatDeliveries.endpointId, endpointId)); const bulk = randomBytes(64 * 1024).toString("base64"); const events: Array> = []; - let capture: ReturnType | undefined; + let capture: ReturnType | undefined; try { await db.update(chatEndpoints).set({ communicationInstructions: bulk, setup: { ...endpoint.setup, unusedContent: bulk } as typeof endpoint.setup, @@ -335,7 +335,7 @@ describe("native same-conversation chat attachment reuse", () => { .where(eq(chatDeliveries.id, delivery.id)); } const now = Date.now(); - capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { chatMessageLinks, chatDeliveries, chatConversations, chatEndpoints, chatEndpointResources, chatExternalPrincipals, chatIdentityLinks, companyMemberships }, capture); for (const lockMode of ["read", "blocking", "nonblocking"] as const) { diff --git a/server/src/services/native-runtime/external-chat-wait.integration.test.ts b/server/src/services/native-runtime/external-chat-wait.integration.test.ts index f2951d3b8c0..3bb91b68a38 100644 --- a/server/src/services/native-runtime/external-chat-wait.integration.test.ts +++ b/server/src/services/native-runtime/external-chat-wait.integration.test.ts @@ -8,7 +8,7 @@ import { tmpdir } from "node:os"; import path from "node:path"; import { and, eq, ne, sql } from "drizzle-orm"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../__tests__/helpers/full-database-response-capture.js"; import { afterAll, beforeAll, describe, expect, it, vi } from "vitest"; import { agentWakeupRequests, @@ -922,7 +922,7 @@ describe("native external-chat response wait", () => { await authorizeChatConversationForBoundRun(db, fixture, contextSnapshot, "read"); const observed = createDb(temporary?.connectionString ?? externalTestDatabaseUrl!); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { issues, heartbeatRuns }, capture); try { expect(await listExternalReviewWaits(observed, fixture.companyId, [fixture.issueId])).toEqual(governed ? [] : [ @@ -5462,7 +5462,7 @@ describe("native external-chat response wait", () => { if (reply) await db.update(chatActions).set({ result: { ...reply.result, savedProviderOutput: payload } }).where(eq(chatActions.id, reply.id)); const observed = createDb(temporary?.connectionString ?? externalTestDatabaseUrl!); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { heartbeatRuns, chatActions }, capture); try { const context = await new PaperclipRunnerToolAuthority(observed, fixture) diff --git a/server/src/services/native-runtime/paperclip-runner-tool-authority.test.ts b/server/src/services/native-runtime/paperclip-runner-tool-authority.test.ts index bf4f53dd371..5fab72c4c2c 100644 --- a/server/src/services/native-runtime/paperclip-runner-tool-authority.test.ts +++ b/server/src/services/native-runtime/paperclip-runner-tool-authority.test.ts @@ -19,7 +19,7 @@ import { issueThreadInteractions, issues, } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../__tests__/helpers/full-database-response-capture.js"; import { startRecoveryPostgres } from "../../__tests__/helpers/recovery-postgres.js"; import { initializeRunIdentity, reserveSteeredIdentity, reconcileSteeredIdentity } from "../run-identity.js"; import { documentService } from "../documents.js"; @@ -248,7 +248,7 @@ describe("PaperclipRunnerToolAuthority", () => { }).where(eq(heartbeatRuns.id, runId)); const [expanded] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, runId)); const observed = createDb(temporary!.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { heartbeatRuns, issues, agents, companies }, capture); try { const reader = new PaperclipRunnerToolAuthority(observed, binding); @@ -291,7 +291,7 @@ describe("PaperclipRunnerToolAuthority", () => { await db.update(heartbeatRuns).set({ contextSnapshot: context }).where(eq(heartbeatRuns.id, runId)); const [expanded] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, runId)); const observed = createDb(temporary!.connectionString), events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(observed, { heartbeatRuns, issues, agents, companies }, capture); try { const reader = new PaperclipRunnerToolAuthority(observed, binding); diff --git a/server/src/services/recovery/issue-state-read.test.ts b/server/src/services/recovery/issue-state-read.test.ts index 5a8ad5acf28..b1b4a39a0b5 100644 --- a/server/src/services/recovery/issue-state-read.test.ts +++ b/server/src/services/recovery/issue-state-read.test.ts @@ -1,6 +1,6 @@ import { randomBytes, randomUUID } from "node:crypto"; import { agents, companies, createDb, issueRecoveryActions, issues } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../__tests__/helpers/full-database-response-capture.js"; import { eq } from "drizzle-orm"; import { afterAll, beforeAll, describe, expect, it, vi } from "vitest"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "../../__tests__/helpers/embedded-postgres.js"; @@ -60,7 +60,7 @@ describe.skipIf(!support.supported)("recovery issue state reads", () => { const service = recoveryService(db, { enqueueWakeup }); const events: Array> = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { issues, issueRecoveryActions }, capture); try { await service.reconcileStrandedAssignedIssues(); @@ -100,7 +100,7 @@ describe.skipIf(!support.supported)("recovery issue state reads", () => { const service = recoveryService(db, { enqueueWakeup }); const events: Array> = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { agents, issues, issueRecoveryActions }, capture); try { expect(await service.reconcileStrandedAssignedIssues()).toMatchObject({ skipped: 1 }); diff --git a/server/src/services/recovery/legacy-disposition-read.test.ts b/server/src/services/recovery/legacy-disposition-read.test.ts index 749a7991879..21ae049d472 100644 --- a/server/src/services/recovery/legacy-disposition-read.test.ts +++ b/server/src/services/recovery/legacy-disposition-read.test.ts @@ -1,6 +1,6 @@ import { randomBytes, randomUUID } from "node:crypto"; import { agents, companies, createDb, heartbeatRuns } from "@paperclipai/db"; -import { createDatabaseResponseCapture, installDatabaseResponseCapture } from "@paperclipai/db/response-capture"; +import { createFullDatabaseResponseCapture, installDatabaseResponseCapture } from "../../__tests__/helpers/full-database-response-capture.js"; import { eq } from "drizzle-orm"; import { afterAll, beforeAll, describe, expect, it, vi } from "vitest"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "../../__tests__/helpers/embedded-postgres.js"; @@ -37,7 +37,7 @@ describe.skipIf(!support.supported)("legacy disposition source reads", () => { errorCode: "adapter_failed", resultJson: { executionRecovery: { providerWorkStarted: true }, stdout: bulk } }).returning(); const events: Array> = []; const now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); try { expect(await readLegacyDispositionSource(db, { companyId, issueId, runId: before.id })) @@ -77,7 +77,7 @@ describe.skipIf(!support.supported)("legacy disposition source reads", () => { const enqueueWakeup = vi.fn(async () => { throw new Error("native work must not enter legacy recovery"); }); const service = recoveryService(db, { enqueueWakeup }); const events: Array> = [], now = Date.now(); - const capture = createDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); + const capture = createFullDatabaseResponseCapture({ start: now - 100, end: now + 59_000 }, event => events.push(event)); installDatabaseResponseCapture(db, { heartbeatRuns }, capture); try { expect(await service.reconcileLegacyContinuation(before.id)).toBe("skipped"); } finally { capture.flush(); }