mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-13 15:55:46 +01:00
## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - When someone messages an agent, the reply must start fast. The durable ownership plan (#19831) makes time to first token (TTFT) a hard invariant. > - Phase 0 of that plan records a TTFT baseline per adapter and environment, measured from the moment the message or wake is accepted. > - Today `task.time_to_first_token` starts at the wake comment, the answered question, or the run row's creation. A wake request that was accepted earlier (deferred, coalesced or retried) is not part of the measurement, and the span does not say which start it used. > - This pull request moves the start back to the earliest accepted input and names it on the span. > - The benefit is that the baseline and later budgets measure what the user waits for, with no new work before `turn.start`. ## Linked Issues or Issue Description Refs #19831 **What is the problem?** `task.time_to_first_token` does not include the time between an accepted wake request and the creation of its run row. It also does not record which input it started from. **What is the expected outcome?** The span starts at the earliest accepted input and carries an `anchor` attribute: `comment`, `question_response`, `wake_request` or `run_created`. **Why does it matter?** Phase 0 of the durable ownership plan sets TTFT budgets from this baseline. A start that skips queue time hides the latency that deferred wakes add. ## What Changed - `resolveNativeTimeToFirstTokenStart` (pure) in `native-run-trace.ts` picks the start and the anchor. `anchor` joins the closed span-attribute allowlist. - `readNativeRunWakeRequestedAtMs` reads `agent_wakeup_requests.requested_at` for the run. It never throws. - `native-session-executor.ts` calls it only after the first deliverable text, so it adds no wait before `turn.start`. The span now ends at the text commit time, not after the trace write. - Updated `doc/run-log-events.md` and `doc/observability.md`. ## Verification - `cd server && npx vitest run src/services/native-runtime/native-run-trace.test.ts src/services/native-runtime/native-run-wake-anchor.test.ts` (26 pass). - `cd server && npx vitest run src/services/native-runtime/native-session-executor.test.ts -t first` (41 pass). The existing TTFT test now asserts the anchor for each ingress. ## Risks - Low risk. This changes only the run-log and OTLP span. It is not Telemetry (AGENTS.md §5.7), and it does not change runtime behavior. - One indexed primary-key read per native dispatch, after the first text. A read failure drops the anchor and keeps the old start. - TTFT values can grow for deferred wakes. That is the intended correction. `startOffsetMs` can be negative when the wake request comes before the trace start. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), via Claude Code with tool use and code execution. ## 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 - [ ] All Paperclip CI gates are green - [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [ ] I will address all Greptile and reviewer comments before requesting merge 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
75 lines
3.6 KiB
TypeScript
75 lines
3.6 KiB
TypeScript
import { randomUUID } from "node:crypto";
|
|
import { sql } from "drizzle-orm";
|
|
import { afterAll, beforeAll, describe, expect, it } from "vitest";
|
|
import { agentWakeupRequests, agents, companies, createDb, heartbeatRuns } from "@paperclipai/db";
|
|
import {
|
|
getEmbeddedPostgresTestSupport,
|
|
startEmbeddedPostgresTestDatabase,
|
|
} from "../../__tests__/helpers/embedded-postgres.js";
|
|
import { readNativeRunWakeRequestedAtMs } from "./native-run-wake-anchor.js";
|
|
|
|
const support = await getEmbeddedPostgresTestSupport();
|
|
const describeEmbeddedPostgres = support.supported ? describe : describe.skip;
|
|
|
|
describeEmbeddedPostgres("native run wake anchor against PostgreSQL", () => {
|
|
let database: Awaited<ReturnType<typeof startEmbeddedPostgresTestDatabase>> | null = null;
|
|
let db!: ReturnType<typeof createDb>;
|
|
let locker!: ReturnType<typeof createDb>;
|
|
const companyId = randomUUID();
|
|
const agentId = randomUUID();
|
|
const wakeupRequestId = randomUUID();
|
|
const runId = randomUUID();
|
|
const requestedAt = new Date("2026-11-07T10:00:00.000Z");
|
|
|
|
beforeAll(async () => {
|
|
database = await startEmbeddedPostgresTestDatabase("paperclip-wake-anchor-");
|
|
// One connection: a read left running after the timeout would starve the next query.
|
|
db = createDb(database.connectionString, { maxConnections: 1 });
|
|
locker = createDb(database.connectionString, { maxConnections: 2 });
|
|
await db.insert(companies).values({ id: companyId, name: "Anchor", issuePrefix: `A${companyId.slice(0, 6)}` });
|
|
await db.insert(agents).values({ id: agentId, companyId, name: "Anchor agent", role: "engineer", status: "idle", adapterType: "codex_local" });
|
|
await db.insert(agentWakeupRequests).values({ id: wakeupRequestId, companyId, agentId, source: "assignment", status: "claimed", requestedAt });
|
|
await db.insert(heartbeatRuns).values({ id: runId, companyId, agentId, wakeupRequestId, status: "running" });
|
|
}, 60_000);
|
|
|
|
afterAll(async () => {
|
|
await database?.cleanup();
|
|
});
|
|
|
|
it("reads requested_at through the run's wake request", async () => {
|
|
await expect(readNativeRunWakeRequestedAtMs(db, runId)).resolves.toBe(requestedAt.getTime());
|
|
await expect(readNativeRunWakeRequestedAtMs(db, randomUUID())).resolves.toBeNull();
|
|
});
|
|
|
|
it("cancels a blocked read on the server and returns its connection to the pool", async () => {
|
|
let release!: () => void;
|
|
const gate = new Promise<void>((resolve) => { release = resolve; });
|
|
let locked!: () => void;
|
|
const lockHeld = new Promise<void>((resolve) => { locked = resolve; });
|
|
const holder = locker.transaction(async (tx) => {
|
|
await tx.execute(sql`lock table agent_wakeup_requests in access exclusive mode`);
|
|
locked();
|
|
await gate;
|
|
});
|
|
try {
|
|
await lockHeld;
|
|
const startedAt = Date.now();
|
|
await expect(readNativeRunWakeRequestedAtMs(db, runId, 300)).resolves.toBeNull();
|
|
expect(Date.now() - startedAt).toBeLessThan(2_000);
|
|
// The lock is still held. The single pooled connection must already be free,
|
|
// and PostgreSQL must not still be waiting on the anchor read.
|
|
const probeStartedAt = Date.now();
|
|
const [probe] = await db.execute<{ ok: number }>(sql`select 1 as ok`);
|
|
expect(Number(probe?.ok)).toBe(1);
|
|
expect(Date.now() - probeStartedAt).toBeLessThan(1_000);
|
|
const waiting = await locker.execute<{ count: string }>(sql`
|
|
select count(*)::text as count from pg_stat_activity
|
|
where state = 'active' and wait_event_type = 'Lock' and query ilike '%agent_wakeup_requests%'`);
|
|
expect(Number(waiting[0]?.count ?? 0)).toBe(0);
|
|
} finally {
|
|
release();
|
|
await holder;
|
|
}
|
|
}, 20_000);
|
|
});
|