diff --git a/doc/live-transcript-delivery.md b/doc/live-transcript-delivery.md new file mode 100644 index 00000000000..5151ab7a59f --- /dev/null +++ b/doc/live-transcript-delivery.md @@ -0,0 +1,180 @@ +# Interested transcript delivery + +The company WebSocket is a presentation channel. Its subscriptions cannot change +runner execution, PRP acknowledgements, recovery checkpoints, accounting, or +canonical run logs. Authorization and redaction still run at delivery, including +after access is revoked. A subscription is never an authorization grant. Full event +rows and log chunks require the current `company_scope:read` permission used by +HTTP transcript reads, as well as access to the run's task. A restricted agent +can still receive authorized lifecycle and lightweight activity notifications. +The check runs for each full delivery on both negotiated and older connections; +changing a trust policy takes effect without reconnecting. + +## Additive negotiation + +Older clients receive the existing full event stream. New clients first send +`live.hello` with `version: 1` and `capabilities: ["run-interests"]`. A compatible +server replies with `live.capabilities` carrying the same version and capability. +An older server can ignore the hello; the client retains HTTP polling. + +The browser then sends `live.interests`, a monotonically increasing `revision`, +and a replacement `runIds` array. The server applies that complete set before +replying with `live.subscribed` and the applied revision. The browser ignores +stale acknowledgements. Every connection starts a new revision sequence. +An unchanged run stays healthy while unrelated interests change. New interests +wait for an acknowledgement that includes them; only connection changes or an +explicit resynchronization advance the shared recovery generation. This avoids +aborting existing readers when another view starts or stops watching a run. +Views exceeding the 1,000-interest protocol limit retain HTTP fallback for +interests that cannot be advertised. + +All mounted consumers share the existing company connection. Interests are +reference counted: removing one of two views of the same run does not unsubscribe +the other. Disabled views and hidden tabs withdraw their interests. Company and +account changes dispose the old connection. Progress, lifecycle, attention, and +activity notifications continue independently of transcript interests. + +For an uninterested run, full `heartbeat.run.event` and `heartbeat.run.log` +payloads become an authorized `heartbeat.run.activity` notification containing +only run ID, agent ID, and last-output time. These notifications are coalesced to +at most one per run per second, driven by output rather than an idle timer. + +## Catch-up and ordering + +Consumers install their event listener before advertising interest. After the +latest subscription is acknowledged they read canonical history, merging it with +events that arrive during the read. Native events deduplicate by run sequence; +legacy logs also track log identity and persisted byte offsets. Streamed rows +never advance the persisted-history cursor. A second sequence gap observed during +an in-flight read remains pending until history covers it. + +Compact conversation history intentionally excludes tool and reasoning rows. +After a complete filtered scan, its coverage includes the committed sequence known +before that read began, even when no matching conversation row has that sequence. +This settles excluded activity without recurring reads or downloading the full +event stream. A later notification cannot be covered by an older in-flight scan; +its catch-up must still recover any intervening conversation rows. + +Native publication signals carry a committed sequence without a PRP body. They +trigger a canonical read through that sequence, including consecutive signals, +and never enter the transcript merge. A delayed signal cannot replace complete +text. Signals that arrive during an older read remain pending until history +covers them. This adds event-driven reads for payload-free notifications, not a +recurring poll or a recovery-checkpoint write. + +Live catch-up refreshes only the affected run. Each run has at most one history +read in flight and one retry timer. Terminal notifications during a read coalesce +into one subsequent read. A busy run cannot cancel a sibling's paginated history. +This applies to both native commit signals and truncated legacy log chunks. +If subscription acknowledgement aborts Agent Detail's first history request, +negotiated recovery still drains the saved live tail without waiting for another +source event. Its first page initializes the manual history cursor; subsequent +catch-up pages use the independent recovery cursor. A completed run that was +never live retains manual pagination. + +Agent Detail also refreshes its event history and shell log independently. A +signal for one cannot abort the other's page or advance its persisted cursor; +terminal notifications queue a follow-up for each active reader. + +Catch-up runs on subscription, reconnect, show, explicit resynchronization, gaps, +and terminal status. Task transcript catch-up drains pending pages. Failed reads retry even +when the socket remains connected. After successful negotiated catch-up there +are no recurring transcript reads. Historical agent-detail logs retain their +existing explicit pagination. Agent Detail event history also reads at most one +1,000-row page automatically; a full page exposes **Load more events** and pauses +automatic history reads until the user requests the next page. Full live events +continue to arrive. Live retention keeps the opening 200 events (including the +invocation card) plus the latest 2,000, including through terminal transition. +Completed runs retain explicitly requested history. Initial and paginated read +failures remain visible, preserve loaded rows, and offer **Retry events**. Older clients and servers +retain fallback polling when no explicit event page is waiting. + +## Backpressure + +Each connection retains at most 1,000 queued items and 1 MiB across queued payloads +and socket buffering. Authorization that is still in flight counts toward the +queue. Interests are checked again after asynchronous authorization. Incoming +interest messages have a 64 KiB transport limit and at most 1,000 run IDs. + +Overflow discards pending delivery work, invalidates in-flight results, and sends +`live.resync` with the affected revision. The browser replaces its interests and +catches up after the new acknowledgement. It also refreshes active application +queries because overflow can drop lifecycle messages. Persistent congestion +closes the socket with code 1013 after five seconds; this timer exists only while +congestion is pending. An older client is closed on overflow so its normal +reconnect path can catch up. + +A new interest acknowledgement does not cancel the congestion deadline while an +old authorization or decoration read remains in flight. If that read settles, +the connection may recover; if it remains stalled, the original deadline closes +the socket even without another source event. + +The server does not persist a browser-specific event backlog. Canonical history +is the recovery source. Execution continues whether there are zero viewers or +many viewers. + +## Verification + +The delivery tests cover legacy compatibility, authorization/redaction, revoked +access, interest changes during authorization, item and byte bounds, and the +congestion deadline. Browser-hook tests cover reference counting, acknowledgement +races, history/live ordering, failed reads, hide/show, company changes, terminal +catch-up, and zero recurring reads after negotiation. + +Run the native browser journey with +`pnpm exec playwright test --config tests/e2e/playwright-transcript-delivery.config.ts`. +It uses the production runner and the existing deterministic Codex app-server +fixture. It creates a task through the current composer, opens two views, verifies +zero recurring transcript reads during settled streaming, changes companies, +disconnects the presentation socket, and checks terminal output after reload. +The fixture pins provider selection through the existing acceptance-only loader; +it does not contact a real model or add a production admission option. + +The legacy journey is +`pnpm exec playwright test --config tests/e2e/playwright.config.ts agent-chat-sessions.spec.ts --grep 'chat first open'`. +Both use a disposable server and can use an explicitly supplied disposable +`DATABASE_URL` when local embedded Postgres is unavailable. Browser fixtures +establish delivery behavior, not native-provider or hosted-upgrade qualification. + +`server/src/realtime/live-event-delivery.cost.test.ts` compares identical output +with zero interests, one viewer, three browser connections, and simulated socket +congestion. Set `PAPERCLIP_LIVE_DELIVERY_COST_REPORT` to retain its JSON report. +This measures the in-process presentation boundary, not production network or +database cost. CPU, heap deltas, and latency are diagnostic measurements, not +performance assertions. Current acceptance evidence lives in +`doc/plans/2026-10-22-hot-upgrade-qualification.md`. + +Agent Detail's event log also treats notifications without a message or payload as +commit signals. It retains saved event details when a delayed signal arrives and +requests canonical history for a signal not yet covered by its persisted cursor, +including consecutive sequences. Complete live rows still merge directly without +recurring history reads. Both development and production page variants use this +behavior; their regressions fail on the preceding merge and pass after the fix. + +## Recovery reads and plugin delivery + +Resynchronization can also discard lifecycle events used by application lists. +Those views refresh after the replacement interest acknowledgement, when the +server has resumed delivery. An older in-flight query cannot satisfy that +boundary. One follow-up waits for it without cancelling the useful older read. +The follow-up checks the current company, connection, visibility and query cache +identity. Ordinary interest acknowledgements add no application refresh. + +The five-second delivery deadline also covers an authorization, redaction or +decoration read that stalls before a queue reaches its bounds. Ping traffic and +interest revisions cannot reset that deadline. Closing disposes queued work and +rejects late results; the one already-started dependency read may still finish. +A legacy browser retains its existing skip-and-poll handling of a rejected read. +Transcript and activity events skip toast decoration and its business lookup. + +Plugin run notifications share the bounded queue and canonical structural, +current-user and registered-secret redaction after their existing scope checks. +This work belongs to the active recipient, never the producer. Plugins do not +poll canonical history. Any failed delivery, backlog closure or subscription +timeout sends one content-free stream error and removes the subscription. +Disposal suppresses late notifications and new lookups. The error ends plugin +delivery without changing the underlying execution or recorded run status. + +Explanatory code comments introduced by this slice are kept in this document, +as required by the contribution guide. Vitest environment and scoped lint +directives remain because they configure test execution and analysis. diff --git a/doc/plans/2026-10-22-hot-upgrade-qualification.md b/doc/plans/2026-10-22-hot-upgrade-qualification.md index 78a1f20ea09..cd9c4996eb3 100644 --- a/doc/plans/2026-10-22-hot-upgrade-qualification.md +++ b/doc/plans/2026-10-22-hot-upgrade-qualification.md @@ -1441,6 +1441,33 @@ are added; reconstruction is limited to warm admission with an external marker or an older local projection. +### Delivery read deadlines below the queue bound + +Four cases reproduce a live-delivery freeze when a permission or decoration +read never settles, for both old and negotiated clients, with only two retained +items. The five-second pending-read deadline now closes the connection before +overflow is necessary. Disposal clears queued items, prevents late results from +being sent, and leaves unrelated connections responsive. Interest revisions +cannot reset the pending read's original deadline. The underlying read is not +cancelled by socket closure; at most the already-started read remains until its +driver settles. That closed connection can launch no subsequent delivery work. + +After correction, all 28 delivery, unchanged workload-cost and WebSocket cases +pass with server typecheck. Six new cases include the four stalled-read variants +and settling/disposal before expiry; they confirm no timer remains when idle. +The workload comparison preserves the existing viewer-interest authorization +call counts. These unit counts do not measure final hosted SQL or CPU savings, +and do not complete the active-agent/viewer performance matrix. + + +The late-error regression also fails before correction: a rejected read after +socket disposal could create a new congestion timer. Closed deliveries now +ignore that rejection before any recovery work starts. The final combined +delivery/cost/WebSocket/toast batch first has four loopback EPERM failures and +31 passes; its permitted repeat passes all 35 cases. The prior 28-case result +excluded the toast file. Both outcomes remain recorded, and no hosted result +is inferred from these local fault tests. + Master `e9e84bb8a1` then adds migration 0390. The fifth reconciliation generates checkpoint migration 0391 with the identical prior idempotent DDL, preserving every master SQL file and journal entry. The five snapshots are 0387–0391. @@ -1449,6 +1476,66 @@ variants pass after integration. Current-head CI and review remain required; prior source checks are not carried forward as a new-head pass. +### Plugin recipient redaction and post-recovery application reads + +The new native live payload reproduced a registered-secret leak through plugin +`agents.sessions.event` notifications. Browser-only redaction did not protect +that separate recipient. Browser and plugin delivery now share the canonical +structural, current-user and per-run registered-secret read pipeline. Plugin +subscriptions use the existing bounded delivery queue, including its stalled +read deadline and disposal rules. No redaction lookup is added to the producer +or an uninterested native stream. Existing plugin company/run/session checks +remain in their owner. Legacy chunks and final text are also redacted. + +The regression registers a synthetic run secret through the production registry +and publishes native events through the real bus and host-service subscription. +Database storage and the secret provider are scripted; the registry, recipient +pipeline and worker notification are real. Native, legacy and final messages +stay redacted; disposal suppresses late notification and later reads. The +initial implementation dropped failed redactions. All 47 registry/plugin/delivery/WebSocket/toast +cases pass, with server typecheck. Recipient redaction can add database reads +for active plugin subscribers; final hosted plugin-viewer costs are unmeasured. + +A subsequent review reproduced a lost terminal notification when either the +settings read or registered-secret resolution failed. Both regressions failed +before the fix. Plugins now receive one content-free delivery error and their +subscription is removed on any delivery failure. The same path handles backlog +closure and the existing subscription timeout. This error ends notification +delivery; it does not stop the agent or change the recorded run status. No +retry, extra read or browser delivery behavior is added. All 50 cases in the +six-file registry/plugin/delivery/WebSocket/toast lane pass, including both +terminal failures, timeout, no subsequent reads, and existing late-disposal +coverage. Server typecheck passes. Database storage and secret provider remain +scripted in the plugin regression; hosted plugin-consumer recovery is unmeasured. + +Two UI regressions reproduce a run missed between the pre-resync refresh and +the server's replacement-interest acknowledgement. Application queries now +refresh after a matching recovery ACK. If a read was already in flight, one +follow-up waits for it to settle; stale scopes and inactive queries cannot +refresh. Initial and ordinary interest acknowledgements add no refresh. All +174 live-provider/recovery/interest cases and UI typecheck pass, including +stale/duplicate acknowledgements and disconnect, hidden, company, session and +unmount races. Token gates pass. This introduces no recurring healthy polling. + +### Current Linux receipts and one expiry-worker diagnostic retry + +At server `8fbe62b41d`, Linux job 122535673837 passes all 938 native-executor +cases. The warm external-checkpoint regression is included. Job 122535673326 +passes the native recovery lane (115 passes, five container-only skips), +including the encrypted-restore session guard, fresh preparation (63.694 s), +claim-lock contention (4.043 s), and 101-owner recovery (4.284 s). + +Server job 122535673841 has 3,876 passes, one skip and one failure in the +unchanged expiry-worker retry/drain timing test; cleanup also reports that +test's retained injected error. The entire server/database tree and this +fixture are identical on qualification source `b64cac6951`, whose job +122536300082 passes all 20 expiry cases and all 3,877 shard cases. The fixture +advances fake time while asynchronous retry work can be in flight. One +diagnostic retry of the failed current-head server job is authorized and +requested; the exact timing race is not proven and no assertion is weakened. +A repeated failure requires investigation, not another retry. This record does +not mark that gate green before the retry finishes. + ### Per-replacement identity and malformed receipt retention The last qualification review reproduces two gaps. An intermediate rollback @@ -1514,6 +1601,18 @@ server typecheck and all 13 warm-owner variants pass. No runtime recovery behavior changes in this integration, and fresh exact-head CI and reviews are required. No hosted fixture, deployment, budget or access changes. +### Transcript contribution-rule review + +The transcript review found explanatory code comments that conflict with the +contribution guide. The 104 comments introduced by that slice are removed, and +the useful ordering, deadline and plugin-delivery explanations are kept in +`doc/live-transcript-delivery.md`. Existing comments and executable test/lint +directives remain. Parsing every edited source before and after removal gives +identical non-comment tokens. The six-file server delivery lane passes all 50 +cases, six affected UI suites pass all 91 cases, and token gates pass. No new +test or runtime behavior is introduced; fresh exact-head CI and review remain +required for the new transcript head. + ### Eighth master integration after reviewer continuation Master `2cd747d1b6` is integrated in server `051769955e`. It includes the @@ -1615,3 +1714,25 @@ the deterministic preservation suite. The corrected batch explicitly includes both preservation suites and passes all 158 cases across 13 files. The earlier 146-case receipt retains its own source and selection; these counts do not imply identical test inventories. E2E typecheck also passes after master integration. + + +After the server squash merge and qualification retarget, the transcript slice +again passes 50 focused server cases, 91 focused UI cases, both typechecks and +token gates. Runner vendor preparation rebuilds the current master inputs before +those tests. No new browser journey or hosted experiment is claimed. The old +browser receipts remain attributed to their source; new-head CI and reviews are +still required before the transcript slice can merge. + + +### Qualification slice merged; transcript slice retargeted to master + +PR #17455 source `8f1d6ec02f5bf6c90e7b27da8156953cabd9a180` merged as +`6987c2f20bf2978c84f9c69b9840586407dfad29` after all 57 current-head checks +completed cleanly, legacy status passed, both completed reviews scored 5/5, and +actionable feedback was resolved. The transcript slice now targets master. +Its evidence-document add/add conflict retains every line of the merged +qualification record and the transcript evidence additions. No production code +changes during this retarget; the 50 server/91 UI cases, typechecks and token +checks retain their prior source attribution. Fresh exact-head CI and reviews +remain required. The hosted active-agent matrix and genuine A/B upgrades remain +open acceptance work; these merges do not qualify them. diff --git a/packages/shared/src/constants.ts b/packages/shared/src/constants.ts index 574d033e665..2d6d93331d5 100644 --- a/packages/shared/src/constants.ts +++ b/packages/shared/src/constants.ts @@ -945,6 +945,7 @@ export const LIVE_EVENT_TYPES = [ "heartbeat.run.progress", "heartbeat.run.event", "heartbeat.run.log", + "heartbeat.run.activity", "agent.session.goal.changed", "agent.status", "activity.logged", diff --git a/packages/shared/src/index.ts b/packages/shared/src/index.ts index c698a2904aa..2cac341fa39 100644 --- a/packages/shared/src/index.ts +++ b/packages/shared/src/index.ts @@ -1270,6 +1270,8 @@ export type { AgentWakeupRequest, InstanceSchedulerHeartbeatAgent, LiveEvent, + LiveDeliveryClientMessage, + LiveDeliveryServerMessage, DashboardRunActivityDay, DashboardSummary, TimelineActorType, diff --git a/packages/shared/src/types/index.ts b/packages/shared/src/types/index.ts index fe0ed6ec356..8f2e9711dea 100644 --- a/packages/shared/src/types/index.ts +++ b/packages/shared/src/types/index.ts @@ -936,7 +936,7 @@ export type { AgentWakeupRequest, InstanceSchedulerHeartbeatAgent, } from "./heartbeat.js"; -export type { LiveEvent } from "./live.js"; +export type { LiveEvent, LiveDeliveryClientMessage, LiveDeliveryServerMessage } from "./live.js"; export type { DashboardRunActivityDay, DashboardSummary } from "./dashboard.js"; export type { TimelineActorType, diff --git a/packages/shared/src/types/live.ts b/packages/shared/src/types/live.ts index b4da9a874b9..0536e4ee79a 100644 --- a/packages/shared/src/types/live.ts +++ b/packages/shared/src/types/live.ts @@ -9,3 +9,11 @@ export interface LiveEvent { toastEligible?: boolean; payload: Record; } + +export type LiveDeliveryClientMessage = { type: "live.hello"; version: 1; capabilities: string[] } | { + type: "live.interests"; version: 1; revision: number; runIds: string[]; +}; +export type LiveDeliveryServerMessage = + | { type: "live.capabilities"; version: 1; capabilities: string[] } + | { type: "live.subscribed"; version: 1; revision: number } + | { type: "live.resync"; version: 1; revision: number; reason: "delivery_overflow" }; diff --git a/server/src/__tests__/live-events-run-read.test.ts b/server/src/__tests__/live-events-run-read.test.ts index b02b0d4cf45..1d0dd974a5d 100644 --- a/server/src/__tests__/live-events-run-read.test.ts +++ b/server/src/__tests__/live-events-run-read.test.ts @@ -1,4 +1,9 @@ -import { randomUUID } from "node:crypto"; +import { createHash, randomBytes, randomUUID } from "node:crypto"; +import { homedir } from "node:os"; +import { redactEventPayload } from "../redaction.js"; +import { redactCurrentUserValue } from "../log-redaction.js"; +import { createRunSecretRedactionRegistry } from "../services/run-secret-redaction.js"; +import { instanceSettingsService } from "../services/instance-settings.js"; import { once } from "node:events"; import { createServer } from "node:http"; import type { AddressInfo } from "node:net"; @@ -7,28 +12,34 @@ import { drizzle } from "drizzle-orm/postgres-js"; import { WebSocket } from "ws"; import { afterAll, beforeAll, describe, expect, it } from "vitest"; import { - agents, authUsers, companies, companyMemberships, createDb, + agentApiKeys, agents, authUsers, companies, companyMemberships, createDb, heartbeatRuns, issueAccessGrants, issues, type Db, } from "@paperclipai/db"; import * as schema from "@paperclipai/db/schema/index"; import { setupLiveEventsWebSocketServer } from "../realtime/live-events-ws.js"; import { publishLiveEvent } from "../services/live-events.js"; -import { startEmbeddedPostgresTestDatabase } from "./helpers/embedded-postgres.js"; +import { authorizationService, type AuthorizationActor } from "../services/authorization.js"; +import { getHeartbeatRunReadDecisions } from "../services/heartbeat-run-privacy.js"; +import { startRecoveryPostgres } from "./helpers/recovery-postgres.js"; describe("live-event run read boundaries", () => { - let temporary: Awaited>; + let temporary: Awaited>; let db: Db; const previousPrivacy = process.env.PAPERCLIP_ISSUE_PRIVACY_MODE; + const previousMasterKey = process.env.PAPERCLIP_SECRETS_MASTER_KEY; beforeAll(async () => { - temporary = await startEmbeddedPostgresTestDatabase("live-event-run-reads-"); + temporary = await startRecoveryPostgres("live-event-run-reads-"); db = createDb(temporary.connectionString); process.env.PAPERCLIP_ISSUE_PRIVACY_MODE = "enforce"; + process.env.PAPERCLIP_SECRETS_MASTER_KEY = randomBytes(32).toString("base64"); }, 120_000); afterAll(async () => { if (previousPrivacy === undefined) delete process.env.PAPERCLIP_ISSUE_PRIVACY_MODE; else process.env.PAPERCLIP_ISSUE_PRIVACY_MODE = previousPrivacy; + if (previousMasterKey === undefined) delete process.env.PAPERCLIP_SECRETS_MASTER_KEY; + else process.env.PAPERCLIP_SECRETS_MASTER_KEY = previousMasterKey; await temporary?.cleanup(); }); @@ -146,4 +157,120 @@ describe("live-event run read boundaries", () => { if (server.listening) await new Promise((resolve, reject) => server.close(error => error ? reject(error) : resolve())); } }); + + it.each([false, true])("keeps transcript permissions current for agent sockets (negotiated=%s)", async negotiated => { + const companyId = randomUUID(), viewer = randomUUID(), issueId = randomUUID(); + await db.insert(companies).values({ id: companyId, name: "Restricted live reads", issuePrefix: `RL${companyId.slice(0, 6)}` }); + await db.insert(authUsers).values({ id: viewer, name: "Fixture operator", email: `${viewer}@example.test`, createdAt: new Date(), updatedAt: new Date() }); + await db.insert(companyMemberships).values({ companyId, principalType: "user", principalId: viewer, membershipRole: "operator", status: "active" }); + const restrictedPermissions = { trustPreset: "low_trust_review", authorizationPolicy: { + trustPreset: "low_trust_review", trustBoundary: { mode: "low_trust_review", companyId, rootIssueId: issueId }, + } }; + const [agent] = await db.insert(agents).values({ companyId, name: "Restricted viewer", adapterType: "process", permissions: restrictedPermissions }).returning(); + await db.insert(issues).values({ id: issueId, companyId, title: "Allowed task", assigneeAgentId: agent.id, responsibleUserId: viewer }); + const [run] = await db.insert(heartbeatRuns).values({ companyId, agentId: agent.id, scopeKind: "issue", issueId, status: "running" }).returning(); + const token = randomBytes(32).toString("hex"); + await db.insert(agentApiKeys).values({ companyId, agentId: agent.id, name: "Unscoped fixture", responsibleUserId: viewer, + keyHash: createHash("sha256").update(token).digest("hex") }); + const actor: AuthorizationActor = { type: "agent", agentId: agent.id, companyId, source: "agent_key", onBehalfOfUserId: viewer }; + const access = authorizationService(db); + const transcriptAllowed = async () => (await access.decide({ actor, action: "company_scope:read", resource: { type: "company", companyId } })).allowed; + expect(await getHeartbeatRunReadDecisions(db, access, actor, [run])).toEqual([true]); + expect(await transcriptAllowed()).toBe(false); + const server = createServer(); + const wss = setupLiveEventsWebSocketServer(server, db, { deploymentMode: "authenticated" }); + server.listen(0, "127.0.0.1"); await once(server, "listening"); + const socket = new WebSocket(`ws://127.0.0.1:${(server.address() as AddressInfo).port}/api/companies/${companyId}/events/ws`, { + headers: { authorization: `Bearer ${token}` }, + }); + const messages: Array<{ type: string; revision?: number; payload?: Record }> = []; + socket.on("message", bytes => messages.push(JSON.parse(bytes.toString()))); + const batch = async () => { + const start = messages.length, barrier = randomUUID(); + publishLiveEvent({ companyId, type: "heartbeat.run.event", payload: { runId: run.id, seq: 1, + payload: { prpEvent: { eventType: "item.delta", payload: { text: "native-text-and-tool-detail" } } } } }); + publishLiveEvent({ companyId, type: "heartbeat.run.log", payload: { runId: run.id, chunk: "legacy-log-content" } }); + publishLiveEvent({ companyId, type: "heartbeat.run.status", payload: { runId: run.id, status: "running" } }); + publishLiveEvent({ companyId, type: "agent.status", payload: { agentId: barrier, status: "idle" } }); + await expect.poll(() => messages.some(message => message.payload?.agentId === barrier)).toBe(true); + return messages.slice(start); + }; + try { + await once(socket, "open"); + if (negotiated) { + socket.send(JSON.stringify({ type: "live.interests", version: 1, revision: 1, runIds: [run.id] })); + await expect.poll(() => messages.some(message => message.type === "live.subscribed")).toBe(true); + } + const denied = await batch(); + expect(denied.some(message => message.type === "heartbeat.run.status")).toBe(true); + expect(denied.filter(message => ["heartbeat.run.event", "heartbeat.run.log"].includes(message.type))).toEqual([]); + await db.update(agents).set({ permissions: {} }).where(eq(agents.id, agent.id)); + expect(await transcriptAllowed()).toBe(true); + expect((await batch()).filter(message => ["heartbeat.run.event", "heartbeat.run.log"].includes(message.type))).toHaveLength(2); + await db.update(agents).set({ permissions: restrictedPermissions }).where(eq(agents.id, agent.id)); + expect(await transcriptAllowed()).toBe(false); + expect((await batch()).filter(message => ["heartbeat.run.event", "heartbeat.run.log"].includes(message.type))).toEqual([]); + } finally { + socket.terminate(); + await Promise.all([...wss.clients].map(client => { const closed = new Promise(resolve => client.on("close", resolve)); client.terminate(); return closed; })); + await new Promise((resolve, reject) => (wss as typeof wss & { close(callback: (error?: Error) => void): void }).close(error => error ? reject(error) : resolve())); + await new Promise((resolve, reject) => server.close(error => error ? reject(error) : resolve())); + } + }); + + it.each(["authenticated", "local_trusted"] as const)("redacts native live rows like history reads for %s viewers", async deploymentMode => { + const companyId = randomUUID(), viewer = randomUUID(); + await db.insert(companies).values({ id: companyId, name: "Live redaction", issuePrefix: `LR${companyId.slice(0, 6)}` }); + await db.insert(authUsers).values({ id: viewer, name: "Fixture viewer", email: `${viewer}@example.test`, createdAt: new Date(), updatedAt: new Date() }); + await db.insert(companyMemberships).values({ companyId, principalType: "user", principalId: viewer, membershipRole: "operator", status: "active" }); + const [agent] = await db.insert(agents).values({ companyId, name: "Redaction fixture", adapterType: "process" }).returning(); + const [run] = await db.insert(heartbeatRuns).values({ companyId, agentId: agent.id, scopeKind: "company", status: "running" }).returning(); + const registered = "registered-live-sentinel-value"; + const registry = createRunSecretRedactionRegistry(db); + await registry.register(companyId, run.id, registered); + await instanceSettingsService(db).updateGeneral({ censorUsernameInLogs: true }); + const body = { prpEvent: { eventType: "item.delta", payload: { kind: "agentMessage", + text: `${homedir()}/synthetic.txt ${registered}`, password: "sensitive-key-sentinel" } } }; + const sourcePayload = { runId: run.id, agentId: agent.id, seq: 1, eventType: "item.delta", payload: body }; + const expected = await registry.redactForRun(companyId, run.id, + redactCurrentUserValue({ ...sourcePayload, payload: redactEventPayload(body) }, { enabled: true })); + const queries: string[] = []; + const observedDb = drizzle(db.$client, { schema, logger: { logQuery(query) { queries.push(query); } } }) as Db; + const server = createServer(); + const wss = setupLiveEventsWebSocketServer(server, observedDb, { deploymentMode, + resolveCloudActor: async () => ({ userId: viewer, companyIds: [companyId] }) }); + server.listen(0, "127.0.0.1"); await once(server, "listening"); + const socket = new WebSocket(`ws://127.0.0.1:${(server.address() as AddressInfo).port}/api/companies/${companyId}/events/ws`); + const messages: Array<{ type: string; revision?: number; payload?: Record }> = []; + socket.on("message", bytes => messages.push(JSON.parse(bytes.toString()))); + const barrier = async () => { + const id = randomUUID(); + publishLiveEvent({ companyId, type: "agent.status", payload: { agentId: id, status: "idle" } }); + await expect.poll(() => messages.some(message => message.payload?.agentId === id)).toBe(true); + }; + try { + await once(socket, "open"); + socket.send(JSON.stringify({ type: "live.interests", version: 1, revision: 1, runIds: [] })); + await expect.poll(() => messages.some(message => message.type === "live.subscribed" && message.revision === 1)).toBe(true); + const baseline = queries.length; + publishLiveEvent({ companyId, type: "heartbeat.run.event", payload: sourcePayload }); await barrier(); + expect(messages.some(message => message.type === "heartbeat.run.event")).toBe(false); + expect(queries.slice(baseline).some(query => query.includes("paperclipSecretRedactions") || query.includes('from "instance_settings"'))).toBe(false); + socket.send(JSON.stringify({ type: "live.interests", version: 1, revision: 2, runIds: [run.id] })); + await expect.poll(() => messages.some(message => message.type === "live.subscribed" && message.revision === 2)).toBe(true); + publishLiveEvent({ companyId, type: "heartbeat.run.event", payload: sourcePayload }); await barrier(); + const delivered = messages.find(message => message.type === "heartbeat.run.event"); + expect(delivered?.payload).toEqual(expected); + expect(JSON.stringify(delivered)).not.toContain(registered); + expect(JSON.stringify(delivered)).not.toContain("sensitive-key-sentinel"); + expect(JSON.stringify(delivered)).not.toContain(homedir()); + expect(JSON.stringify(sourcePayload)).toContain(registered); + } finally { + socket.terminate(); + await Promise.all([...wss.clients].map(client => { const closed = new Promise(resolve => client.on("close", resolve)); client.terminate(); return closed; })); + await new Promise((resolve, reject) => (wss as typeof wss & { close(callback: (error?: Error) => void): void }).close(error => error ? reject(error) : resolve())); + await new Promise((resolve, reject) => server.close(error => error ? reject(error) : resolve())); + } + }); + }); diff --git a/server/src/__tests__/native-observer-replay.test.ts b/server/src/__tests__/native-observer-replay.test.ts index 468722bc2d9..09aaec970d0 100644 --- a/server/src/__tests__/native-observer-replay.test.ts +++ b/server/src/__tests__/native-observer-replay.test.ts @@ -18,7 +18,8 @@ import type { PrpEvent } from "../vendor/paperclip-runner/index.js"; import { setupLiveEventsWebSocketServer } from "../realtime/live-events-ws.js"; import { PaperclipControlPlanePort } from "../services/native-runtime/paperclip-control-plane-port.js"; import { subscribeCompanyLiveEvents } from "../services/live-events.js"; -import { startEmbeddedPostgresTestDatabase } from "./helpers/embedded-postgres.js"; +import { startRecoveryPostgres } from "./helpers/recovery-postgres.js"; +import { redactEventPayload } from "../redaction.js"; import { compareObserverReplays, type ObserverReplayMeasurement } from "./helpers/observer-replay-report.js"; const output = "Synthetic replay output.\n"; @@ -36,17 +37,17 @@ const fixturePayloads = [ { eventType: "item.completed", payload: { kind: "agentMessage", item: { id: "answer", text: output } } }, ]; const fixture = createHash("sha256").update(JSON.stringify(fixturePayloads)).digest("hex"); -const expectedDeliveries = 7; // item.delta is durable but does not emit a live signal. +const expectedDeliveries = fixturePayloads.length; describe("native event replay observation evidence", () => { - let temporary: Awaited>; + let temporary: Awaited>; let db: Db; const companyId = randomUUID(); const agentId = randomUUID(); const userId = `observer-${randomUUID()}`; beforeAll(async () => { - temporary = await startEmbeddedPostgresTestDatabase("observer-replay-"); + temporary = await startRecoveryPostgres("observer-replay-"); db = createDb(temporary.connectionString); await db.insert(companies).values({ id: companyId, name: "Synthetic replay", issuePrefix: "REPLAY" }); await db.insert(agents).values({ id: agentId, companyId, name: "Fixture", adapterType: "codex_local" }); @@ -221,11 +222,12 @@ describe("native event replay observation evidence", () => { expect(rows.map(row => row.seq)).toEqual(events.map(event => event.sourceSeq)); expect(durable.events.at(-1)?.payload).toEqual({ kind: "agentMessage", item: { id: "answer", text: output } }); for (const messages of received) { - expect(messages.map(event => event.payload)).toEqual(events.filter(event => event.eventType !== "item.delta").map(event => ({ + expect(messages.map(event => event.payload)).toEqual(events.map(event => ({ runId, agentId, issueId, seq: event.sourceSeq, eventType: event.eventType, + stream: "system", level: "info", payload: redactEventPayload({ prpEvent: event }), }))); expect(messages.every(event => event.companyId === companyId)).toBe(true); - expect(JSON.stringify(messages)).not.toContain(output.trim()); + expect(JSON.stringify(messages)).toContain(output.trim()); } expect(activeViewers).toBe(viewerCount); if (cadenceMs !== null) expect(pollOffsets.every(offsets => offsets.length >= 2)).toBe(true); diff --git a/server/src/__tests__/plugin-agent-sessions.test.ts b/server/src/__tests__/plugin-agent-sessions.test.ts index 28a06d9a20f..f12f5d06e54 100644 --- a/server/src/__tests__/plugin-agent-sessions.test.ts +++ b/server/src/__tests__/plugin-agent-sessions.test.ts @@ -1,5 +1,23 @@ -import { describe, expect, it, vi } from "vitest"; +import { beforeEach, describe, expect, it, vi } from "vitest"; import { publishLiveEvent } from "../services/live-events.js"; +import { heartbeatRuns } from "@paperclipai/db"; +import { createRunSecretRedactionRegistry } from "../services/run-secret-redaction.js"; +import { REDACTED_EVENT_VALUE } from "../redaction.js"; +import { homedir } from "node:os"; +import { setImmediate } from "node:timers/promises"; + +const { readSettings, resolveSecretVersion } = vi.hoisted(() => ({ + readSettings: vi.fn(async () => ({ censorUsernameInLogs: true })), + resolveSecretVersion: vi.fn(async ({ material }: { material: { synthetic: string } }) => material.synthetic), +})); + +vi.mock("../services/instance-settings.js", () => ({ + instanceSettingsService: () => ({ getGeneral: readSettings }), +})); +vi.mock("../secrets/provider-registry.js", () => ({ getSecretProvider: () => ({ + createSecret: async ({ value }: { value: string }) => ({ material: { synthetic: value } }), + resolveVersion: resolveSecretVersion, +}) })); const mockWakeup = vi.hoisted(() => vi.fn()); const mockHeartbeatService = vi.hoisted(() => vi.fn(() => ({ wakeup: mockWakeup }))); @@ -38,7 +56,133 @@ function createSessionLookupDb(session: { } as never; } +function createRunRedactionDb(session: Parameters[0]) { + let contextSnapshot: unknown = {}; + const db = { + select: () => ({ from: (table: unknown) => { + const rows = () => table === heartbeatRuns ? [{ contextSnapshot }] : [session]; + const query = { where: () => query, for: () => query, + then: (resolve: (value: unknown[]) => unknown) => Promise.resolve(rows()).then(resolve) }; + return query; + } }), + update: () => ({ set: (value: { contextSnapshot: unknown }) => ({ where: async () => { contextSnapshot = value.contextSnapshot; } }) }), + transaction: async (callback: (tx: unknown) => unknown) => callback(db), + }; + return db; +} + describe("plugin agent sessions", () => { + beforeEach(() => { + readSettings.mockReset().mockResolvedValue({ censorUsernameInLogs: true }); + resolveSecretVersion.mockReset().mockImplementation(async ({ material }) => material.synthetic); + }); + it("redacts registered native run secrets before notifying the plugin worker", async () => { + const session = { id: "session-1", companyId: "company-1", agentId: "agent-1", taskKey: "plugin:paperclip.gateway:session:session-1" }; + const db = createRunRedactionDb(session); + const secret = "synthetic-registered-run-secret"; + await createRunSecretRedactionRegistry(db as never).register(session.companyId, "run-1", secret); + const notifyWorker = vi.fn(); + mockWakeup.mockResolvedValue({ id: "run-1" }); + const services = buildHostServices(db as never, "plugin-record-id", "paperclip.gateway", createEventBusStub(), notifyWorker); + try { + await services.agentSessions.sendMessage({ sessionId: session.id, companyId: session.companyId, prompt: "synthetic" }); + const native = { runId: "run-1", seq: 1, message: `output ${secret}`, payload: { + prpEvent: { payload: { text: `output ${secret}`, apiKey: "unregistered-credential", cwd: `${homedir()}/synthetic` } }, + } }; + publishLiveEvent({ companyId: session.companyId, type: "heartbeat.run.event", payload: native }); + await vi.waitFor(() => expect(notifyWorker).toHaveBeenCalledOnce()); + const delivered = notifyWorker.mock.calls[0][1]; + expect(JSON.stringify(delivered)).not.toContain(secret); + expect(JSON.stringify(delivered)).not.toContain("unregistered-credential"); + expect(JSON.stringify(delivered)).not.toContain(`${homedir()}/synthetic`); + expect(delivered.message).toBe(`output ${REDACTED_EVENT_VALUE}`); + expect(native.message).toContain(secret); + publishLiveEvent({ companyId: session.companyId, type: "heartbeat.run.log", + payload: { runId: "run-1", seq: 2, chunk: `legacy ${secret}` } }); + await vi.waitFor(() => expect(notifyWorker).toHaveBeenCalledTimes(2)); + publishLiveEvent({ companyId: session.companyId, type: "heartbeat.run.status", + payload: { runId: "run-1", status: "succeeded", finalText: `done ${secret}` } }); + await vi.waitFor(() => expect(notifyWorker.mock.calls.at(-1)![1].eventType).toBe("done")); + expect(notifyWorker).toHaveBeenCalledTimes(3); + expect(JSON.stringify(notifyWorker.mock.calls)).not.toContain(secret); + expect(notifyWorker.mock.calls.at(-1)![1].message).toBe(`done ${REDACTED_EVENT_VALUE}`); + } finally { services.dispose(); } + }); + + it.each(["settings", "registered secret"])("ends plugin delivery with a safe error when final-status %s redaction fails", async source => { + const session = { id: "session-1", companyId: "company-1", agentId: "agent-1", taskKey: "plugin:paperclip.gateway:session:session-1" }; + const db = createRunRedactionDb(session); + const secret = "synthetic-final-run-secret"; + await createRunSecretRedactionRegistry(db as never).register(session.companyId, "run-1", secret); + mockWakeup.mockResolvedValue({ id: "run-1" }); + const notifyWorker = vi.fn(); + const services = buildHostServices(db as never, "plugin-record-id", "paperclip.gateway", createEventBusStub(), notifyWorker); + try { + await services.agentSessions.sendMessage({ sessionId: session.id, companyId: session.companyId, prompt: "synthetic" }); + if (source === "settings") readSettings.mockRejectedValueOnce(new Error(`unavailable ${secret}`)); + else resolveSecretVersion.mockRejectedValueOnce(new Error(`unavailable ${secret}`)); + publishLiveEvent({ companyId: session.companyId, type: "heartbeat.run.status", + payload: { runId: "run-1", status: "succeeded", finalText: `done ${secret}` } }); + await vi.waitFor(() => expect(notifyWorker).toHaveBeenCalledOnce()); + expect(notifyWorker).toHaveBeenCalledWith("agents.sessions.event", { + sessionId: session.id, runId: "run-1", seq: 0, eventType: "error", stream: "system", + message: "Run event delivery unavailable", payload: { reason: "delivery_unavailable" }, + }); + expect(JSON.stringify(notifyWorker.mock.calls)).not.toContain(secret); + readSettings.mockClear(); + resolveSecretVersion.mockClear(); + publishLiveEvent({ companyId: session.companyId, type: "heartbeat.run.event", + payload: { runId: "run-1", seq: 2, message: `later ${secret}` } }); + publishLiveEvent({ companyId: session.companyId, type: "heartbeat.run.status", + payload: { runId: "run-1", status: "succeeded", finalText: `later ${secret}` } }); + await setImmediate(); + expect(notifyWorker).toHaveBeenCalledOnce(); + expect(readSettings).not.toHaveBeenCalled(); + expect(resolveSecretVersion).not.toHaveBeenCalled(); + } finally { services.dispose(); } + }); + + it("finishes an expired plugin subscription with a delivery error", async () => { + vi.useFakeTimers(); + const session = { id: "session-1", companyId: "company-1", agentId: "agent-1", taskKey: "plugin:paperclip.gateway:session:session-1" }; + mockWakeup.mockResolvedValue({ id: "run-1" }); + const notifyWorker = vi.fn(); + const services = buildHostServices(createSessionLookupDb(session), "plugin-record-id", "paperclip.gateway", createEventBusStub(), notifyWorker); + try { + await services.agentSessions.sendMessage({ sessionId: session.id, companyId: session.companyId, prompt: "synthetic" }); + await vi.advanceTimersByTimeAsync(30 * 60 * 1_000); + expect(notifyWorker).toHaveBeenCalledOnce(); + expect(notifyWorker.mock.calls[0][1]).toMatchObject({ eventType: "error", payload: { reason: "delivery_unavailable" } }); + publishLiveEvent({ companyId: session.companyId, type: "heartbeat.run.status", + payload: { runId: "run-1", status: "succeeded", finalText: "late result" } }); + await vi.advanceTimersByTimeAsync(30 * 60 * 1_000); + expect(notifyWorker).toHaveBeenCalledOnce(); + expect(readSettings).not.toHaveBeenCalled(); + } finally { + services.dispose(); + vi.useRealTimers(); + } + }); + + it("cannot notify a disposed plugin when an earlier redaction read settles", async () => { + let release!: (value: { censorUsernameInLogs: boolean }) => void; + readSettings.mockImplementationOnce(() => new Promise(resolve => { release = resolve; })); + const session = { id: "session-1", companyId: "company-1", agentId: "agent-1", taskKey: "plugin:paperclip.gateway:session:session-1" }; + mockWakeup.mockResolvedValue({ id: "run-1" }); + const notifyWorker = vi.fn(); + const services = buildHostServices(createSessionLookupDb(session), "plugin-record-id", "paperclip.gateway", createEventBusStub(), notifyWorker); + await services.agentSessions.sendMessage({ sessionId: session.id, companyId: session.companyId, prompt: "synthetic" }); + publishLiveEvent({ companyId: session.companyId, type: "heartbeat.run.event", payload: { runId: "run-1", seq: 1 } }); + await vi.waitFor(() => expect(readSettings).toHaveBeenCalledOnce()); + services.dispose(); + readSettings.mockClear(); + release({ censorUsernameInLogs: true }); + await setImmediate(); + publishLiveEvent({ companyId: session.companyId, type: "heartbeat.run.status", payload: { runId: "run-1", status: "succeeded" } }); + await setImmediate(); + expect(notifyWorker).not.toHaveBeenCalled(); + expect(readSettings).not.toHaveBeenCalled(); + }); it("delivers the message body in wake context and returns final assistant text on done", async () => { const companyId = "company-1"; const agentId = "agent-1"; @@ -98,7 +242,7 @@ describe("plugin agent sessions", () => { }, }); - expect(notifyWorker).toHaveBeenCalledWith( + await vi.waitFor(() => expect(notifyWorker).toHaveBeenCalledWith( "agents.sessions.event", expect.objectContaining({ sessionId, @@ -106,7 +250,7 @@ describe("plugin agent sessions", () => { eventType: "done", message: "Hello! How can I help?", }), - ); + )); services.dispose(); }); diff --git a/server/src/realtime/live-event-delivery.cost.test.ts b/server/src/realtime/live-event-delivery.cost.test.ts new file mode 100644 index 00000000000..d72fa3b1fe1 --- /dev/null +++ b/server/src/realtime/live-event-delivery.cost.test.ts @@ -0,0 +1,75 @@ +import { writeFile } from "node:fs/promises"; +import { setImmediate } from "node:timers/promises"; +import { expect, it, vi } from "vitest"; +import type { LiveEvent } from "@paperclipai/shared"; +import { createLiveEventDelivery, LIVE_DELIVERY_MAX_BYTES, LIVE_DELIVERY_MAX_ITEMS } from "./live-event-delivery.js"; + +it("bounds presentation cost for the same output with zero, one, multiple and congested viewers", async () => { + const now = vi.spyOn(Date, "now").mockReturnValue(1_000_000); + const source = Array.from({ length: 1_024 }, (_, index): LiveEvent => Object.freeze({ + id: index + 1, companyId: "company", type: "heartbeat.run.log", createdAt: "2026-10-24T00:00:00Z", + payload: Object.freeze({ runId: "run", agentId: "agent", seq: index + 1, chunk: "x".repeat(2_048) }), + })); + const reports = []; + try { + for (const scenario of [{ name: "zero-interests", viewers: 1, interested: false, slow: false }, + { name: "one-viewer", viewers: 1, interested: true, slow: false }, + { name: "three-browsers", viewers: 3, interested: true, slow: false }, + { name: "slow-viewer", viewers: 1, interested: true, slow: true }]) { + let bytes = 0, transcripts = 0, authorizationReads = 0, peakItems = 0, peakBytes = 0; + const latencies: number[] = []; + const enqueued = new Map(); + const deliveries = Array.from({ length: scenario.viewers }, () => { + const socket = { readyState: 1, bufferedAmount: 0, + send(data: string, callback?: (error?: Error) => void) { + bytes += Buffer.byteLength(data); + const frame = JSON.parse(data) as LiveEvent; + if (frame.type === "heartbeat.run.log") { + transcripts += 1; + latencies.push(performance.now() - enqueued.get(frame.id)!); + } + if (scenario.slow) socket.bufferedAmount += Buffer.byteLength(data); + else callback?.(); + }, close() { socket.readyState = 3; }, + }; + const delivery = createLiveEventDelivery({ socket, + authorize: async event => { authorizationReads += 1; return event; }, decorate: async event => event, + onError: error => { throw error; }, + }); + delivery.receive(JSON.stringify({ type: "live.interests", version: 1, revision: 1, runIds: scenario.interested ? ["run"] : [] })); + return delivery; + }); + const cpu = process.cpuUsage(), memory = process.memoryUsage().heapUsed, started = performance.now(); + try { + for (const event of source) { + enqueued.set(event.id, performance.now()); + for (const delivery of deliveries) { + delivery.enqueue(event); + const metrics = delivery.metrics(); + peakItems = Math.max(peakItems, metrics.retainedItems); + peakBytes = Math.max(peakBytes, metrics.retainedBytes); + } + if (event.id % 16 === 0) await setImmediate(); + } + await setImmediate(); + const used = process.cpuUsage(cpu); + latencies.sort((a, b) => a - b); + reports.push({ scenario: scenario.name, sourceEvents: source.length, connections: scenario.viewers, + transcripts, wireBytes: bytes, authorizationCallbacks: authorizationReads, peakRetainedItems: peakItems, + peakRetainedBytes: peakBytes, resyncRequired: deliveries.some(delivery => delivery.metrics().needsResync), + elapsedMs: performance.now() - started, cpuMs: (used.user + used.system) / 1000, + heapDeltaBytes: process.memoryUsage().heapUsed - memory, + deliveryP95Ms: latencies[Math.floor(latencies.length * 0.95)] ?? null }); + expect(peakItems).toBeLessThanOrEqual(LIVE_DELIVERY_MAX_ITEMS); + expect(peakBytes).toBeLessThanOrEqual(LIVE_DELIVERY_MAX_BYTES); + if (!scenario.interested) { expect(transcripts).toBe(0); expect(authorizationReads).toBe(1); } + else if (!scenario.slow) expect(transcripts).toBe(source.length * scenario.viewers); + else expect(deliveries[0].metrics().needsResync).toBe(true); + } finally { for (const delivery of deliveries) delivery.dispose(); } + } + const report = { schema: "paperclip.live-delivery-cost/v1", scope: "in-process presentation boundary; simulated socket congestion", + sqlMeasured: false, networkMeasured: false, timingAndMemoryAreDiagnostic: true, reports }; + if (process.env.PAPERCLIP_LIVE_DELIVERY_COST_REPORT) await writeFile(process.env.PAPERCLIP_LIVE_DELIVERY_COST_REPORT, `${JSON.stringify(report, null, 2)}\n`); + expect(source.every(event => event.payload.chunk === "x".repeat(2_048))).toBe(true); + } finally { now.mockRestore(); } +}); diff --git a/server/src/realtime/live-event-delivery.test.ts b/server/src/realtime/live-event-delivery.test.ts new file mode 100644 index 00000000000..02e8c536c83 --- /dev/null +++ b/server/src/realtime/live-event-delivery.test.ts @@ -0,0 +1,207 @@ +import { afterEach, expect, it, vi } from "vitest"; +import type { LiveEvent } from "@paperclipai/shared"; +import { createLiveEventDelivery, LIVE_DELIVERY_MAX_BYTES, LIVE_DELIVERY_MAX_ITEMS } from "./live-event-delivery.js"; + +const event = (seq = 1, runId = "run-1"): LiveEvent => ({ id: seq, companyId: "company", type: "heartbeat.run.log", + createdAt: "2026-10-24T00:00:00Z", payload: { runId, agentId: "agent", seq, chunk: "output" } }); +function fixture(authorize = vi.fn(async (value: LiveEvent) => value as LiveEvent | null)) { + const frames: any[] = []; + const socket = { readyState: 1, bufferedAmount: 0, send: vi.fn((text: string, callback?: (error?: Error) => void) => { + frames.push(JSON.parse(text)); callback?.(); + }), close: vi.fn() }; + const decorate = vi.fn(async (value: LiveEvent) => ({ ...value, toastEligible: true })); + const onError = vi.fn(); + const delivery = createLiveEventDelivery({ socket, authorize, decorate, onError }); + const subscribe = (runIds: string[], revision = 1) => delivery.receive(JSON.stringify({ type: "live.interests", version: 1, revision, runIds })); + return { socket, frames, delivery, subscribe, authorize, decorate, onError }; +} +const settle = async () => { for (let n = 0; n < 12; n++) await Promise.resolve(); }; +afterEach(() => vi.useRealTimers()); + +it("leaves older clients on the full stream and negotiates only after a client hello", async () => { + const f = fixture(); + expect(f.frames).toEqual([]); + f.delivery.enqueue(event()); await settle(); + expect(f.frames[0].payload.chunk).toBe("output"); + f.delivery.receive(JSON.stringify({ type: "live.hello", version: 1 })); + expect(f.frames.at(-1)).toMatchObject({ type: "live.capabilities", capabilities: ["run-interests"] }); + f.delivery.dispose(); +}); +it("filters full transcripts before authorization while keeping bounded authorized activity and lifecycle", async () => { + const f = fixture(); f.subscribe([]); + const original = event(); + for (let i = 0; i < 512; i++) f.delivery.enqueue({ ...original, id: i }); + f.delivery.enqueue({ ...event(), type: "heartbeat.run.status", payload: { runId: "run-1", status: "succeeded" } }); + await settle(); + expect(f.authorize).toHaveBeenCalledTimes(2); + expect(f.frames.filter(frame => frame.type === "heartbeat.run.log")).toEqual([]); + expect(f.frames.find(frame => frame.type === "heartbeat.run.activity").payload).toEqual({ runId: "run-1", agentId: "agent", lastOutputAt: original.createdAt }); + expect(f.frames.at(-1)).toMatchObject({ type: "heartbeat.run.status", toastEligible: true }); + expect(original.payload.chunk).toBe("output"); + f.delivery.dispose(); +}); +it("reauthorizes each interested delivery and rechecks interests after an asynchronous permission lookup", async () => { + let release!: (event: LiveEvent) => void; + const f = fixture(vi.fn(() => new Promise(resolve => { release = resolve; }))); + f.subscribe(["run-1"]); f.delivery.enqueue(event()); + f.subscribe([], 2); release(event()); await settle(); + expect(f.frames.filter(frame => frame.type === "heartbeat.run.log")).toEqual([]); + expect(f.frames.at(-1)).toMatchObject({ type: "live.subscribed", revision: 2 }); + f.delivery.dispose(); +}); +it("cannot turn run interest into authorization or bypass delivery redaction", async () => { + const f = fixture(vi.fn(async value => value.payload.seq === 1 ? { ...value, payload: { ...value.payload, chunk: "redacted" } } : null)); + f.subscribe(["run-1"]); f.delivery.enqueue(event()); f.delivery.enqueue(event(2)); await settle(); + expect(f.authorize).toHaveBeenCalledTimes(2); + expect(f.frames.filter(frame => frame.type === "heartbeat.run.log").map(frame => frame.payload.chunk)).toEqual(["redacted"]); + f.delivery.dispose(); +}); +it.each(["items", "bytes"])("bounds queued %s, notifies resynchronization and resumes only after a new revision", async kind => { + let release!: (event: LiveEvent) => void; + const f = fixture(vi.fn(() => new Promise(resolve => { release = resolve; }))); + f.subscribe(["run-1"]); f.delivery.enqueue(event()); + if (kind === "items") for (let i = 0; i < LIVE_DELIVERY_MAX_ITEMS; i++) f.delivery.enqueue(event(i + 2)); + else f.delivery.enqueue({ ...event(2), payload: { ...event(2).payload, chunk: "x".repeat(LIVE_DELIVERY_MAX_BYTES) } }); + expect(f.delivery.metrics()).toMatchObject({ needsResync: true }); + expect(f.delivery.metrics().retainedBytes).toBeLessThanOrEqual(LIVE_DELIVERY_MAX_BYTES); + expect(f.delivery.metrics().retainedItems).toBeLessThanOrEqual(LIVE_DELIVERY_MAX_ITEMS); + expect(f.frames.filter(frame => frame.type === "live.resync")).toHaveLength(1); + release(event()); await settle(); + expect(f.frames.filter(frame => frame.type === "heartbeat.run.log")).toHaveLength(0); + f.subscribe(["run-1"], 2); + expect(f.delivery.metrics().needsResync).toBe(false); + f.delivery.dispose(); +}); +it("closes persistent congestion on its pending-work deadline without another source event", async () => { + vi.useFakeTimers(); + const f = fixture(); f.subscribe(["run-1"]); f.socket.bufferedAmount = LIVE_DELIVERY_MAX_BYTES; + f.delivery.enqueue(event()); await vi.advanceTimersByTimeAsync(5_000); + expect(f.socket.close).toHaveBeenCalledWith(1013, "persistent event backlog"); + f.delivery.dispose(); + expect(vi.getTimerCount()).toBe(0); +}); +it("keeps an unsent gap notice through unrelated interest changes after the socket drains", async () => { + vi.useFakeTimers(); + const f = fixture(); + try { + f.subscribe(["run-1"]); + f.socket.bufferedAmount = LIVE_DELIVERY_MAX_BYTES; + f.delivery.enqueue(event()); + expect(f.frames.some(frame => frame.type === "live.resync")).toBe(false); + await vi.advanceTimersByTimeAsync(4_000); + f.socket.bufferedAmount = 0; + f.subscribe(["run-1", "run-2"], 2); + expect(f.frames.at(-1)).toMatchObject({ type: "live.resync", revision: 2 }); + expect(f.delivery.metrics().needsResync).toBe(true); + f.delivery.enqueue(event(2)); await settle(); + expect(f.frames.some(frame => frame.type === "heartbeat.run.log")).toBe(false); + await vi.advanceTimersByTimeAsync(1_000); + expect(f.socket.close).toHaveBeenCalledWith(1013, "persistent event backlog"); + } finally { f.delivery.dispose(); } + expect(vi.getTimerCount()).toBe(0); +}); +it.each([false, true])("preserves the overflow deadline across resubscription until delivery settles: %s", async settled => { + vi.useFakeTimers(); + let release!: (event: LiveEvent) => void; + const f = fixture(vi.fn(() => new Promise(resolve => { release = resolve; }))); + try { + f.subscribe(["run-1"]); f.delivery.enqueue(event()); + f.delivery.enqueue({ ...event(2), payload: { ...event(2).payload, chunk: "x".repeat(LIVE_DELIVERY_MAX_BYTES) } }); + expect(f.frames.at(-1)).toMatchObject({ type: "live.resync", revision: 1 }); + await vi.advanceTimersByTimeAsync(4_000); + f.subscribe(["run-1"], 2); + expect(f.frames.at(-1)).toMatchObject({ type: "live.subscribed", revision: 2 }); + expect(f.delivery.metrics().needsResync).toBe(false); + if (settled) { release(event()); await settle(); } + await vi.advanceTimersByTimeAsync(1_000); + if (settled) expect(f.socket.close).not.toHaveBeenCalled(); + else expect(f.socket.close).toHaveBeenCalledWith(1013, "persistent event backlog"); + } finally { f.delivery.dispose(); } + expect(vi.getTimerCount()).toBe(0); +}); +it("recovers failed delivery reads through resync rather than silently claiming healthy streaming", async () => { + const f = fixture(vi.fn(async () => { throw new Error("permission database unavailable"); })); + f.subscribe(["run-1"]); f.delivery.enqueue(event()); await settle(); + expect(f.frames.at(-1)).toMatchObject({ type: "live.resync" }); + expect(f.onError).toHaveBeenCalledOnce(); f.delivery.dispose(); +}); +it("keeps older clients connected after a failed permission read and authorizes the next event", async () => { + const authorize = vi.fn(async (value: LiveEvent) => value); + authorize.mockRejectedValueOnce(new Error("permission database unavailable")); + const f = fixture(authorize); + f.delivery.enqueue(event()); f.delivery.enqueue(event(2)); await settle(); + expect(f.frames.map(frame => frame.payload.seq)).toEqual([2]); + expect(f.socket.close).not.toHaveBeenCalled(); + expect(f.onError).toHaveBeenCalledOnce(); + f.delivery.dispose(); +}); +it("rejects unbounded interest sets and stale revision commands", () => { + const f = fixture(); f.subscribe(["run-1"]); f.subscribe([], 1); + expect(f.socket.close).toHaveBeenCalledWith(1008, "invalid run interests"); + const other = fixture(); other.subscribe(Array.from({ length: 1001 }, (_, i) => `run-${i}`)); + expect(other.socket.close).toHaveBeenCalled(); + f.delivery.dispose(); other.delivery.dispose(); +}); + +it.each([false, true].flatMap(negotiated => ["authorize", "decorate"].map(stage => ({ negotiated, stage }))))( + "closes a stalled $stage read below the queue bound (negotiated=$negotiated)", async ({ negotiated, stage }) => { + vi.useFakeTimers(); + let release!: (value: LiveEvent) => void; + const pending = new Promise(resolve => { release = resolve; }); + const f = fixture(stage === "authorize" ? vi.fn(() => pending) : undefined); + const other = fixture(); + try { + if (stage === "decorate") f.decorate.mockImplementationOnce(async () => ({ ...await pending, toastEligible: true })); + if (negotiated) f.subscribe(["run-1"]); + const source = stage === "authorize" ? event() : { ...event(), type: "heartbeat.run.status" as const }; + f.delivery.enqueue(source); + f.delivery.enqueue(event(2)); + other.delivery.enqueue(event()); + await settle(); + expect(other.frames).toHaveLength(1); + expect(f.delivery.metrics()).toMatchObject({ retainedItems: 2, needsResync: false }); + await vi.advanceTimersByTimeAsync(4_000); + if (negotiated) f.subscribe(["run-1"], 2); + await vi.advanceTimersByTimeAsync(999); + expect(f.socket.close).not.toHaveBeenCalled(); + await vi.advanceTimersByTimeAsync(1); + expect(f.socket.close).toHaveBeenCalledWith(1013, "persistent event backlog"); + expect(f.delivery.metrics().retainedItems).toBe(1); + expect(vi.getTimerCount()).toBe(0); + release(source); await settle(); + expect(f.delivery.metrics()).toMatchObject({ retainedItems: 0, retainedBytes: 0 }); + expect(f.frames.filter(frame => frame.type.startsWith("heartbeat."))).toEqual([]); + expect(f.authorize).toHaveBeenCalledOnce(); + } finally { f.delivery.dispose(); other.delivery.dispose(); } + }); + +it.each(["resolve", "dispose"])("clears a pending-read deadline on %s without idle work", async ending => { + vi.useFakeTimers(); + let release!: (value: LiveEvent) => void; + const f = fixture(vi.fn(() => new Promise(resolve => { release = resolve; }))); + try { + f.subscribe(["run-1"]); f.delivery.enqueue(event()); + await vi.advanceTimersByTimeAsync(4_999); + if (ending === "dispose") f.delivery.dispose(); + release(event()); await settle(); + expect(vi.getTimerCount()).toBe(0); + await vi.advanceTimersByTimeAsync(5_001); + expect(f.socket.close).not.toHaveBeenCalled(); + expect(f.frames.filter(frame => frame.type === "heartbeat.run.log")).toHaveLength(ending === "resolve" ? 1 : 0); + } finally { f.delivery.dispose(); } +}); + +it("cannot restart recovery timers when a timed-out read later rejects", async () => { + vi.useFakeTimers(); + let reject!: (error: Error) => void; + const f = fixture(vi.fn(() => new Promise((_resolve, rejectRead) => { reject = rejectRead; }))); + try { + f.subscribe(["run-1"]); f.delivery.enqueue(event()); + await vi.advanceTimersByTimeAsync(5_000); + expect(f.socket.close).toHaveBeenCalledOnce(); + reject(new Error("late permission failure")); await settle(); + expect(vi.getTimerCount()).toBe(0); + expect(f.frames.some(frame => frame.type === "live.resync")).toBe(false); + expect(f.authorize).toHaveBeenCalledOnce(); + } finally { f.delivery.dispose(); } +}); diff --git a/server/src/realtime/live-event-delivery.ts b/server/src/realtime/live-event-delivery.ts new file mode 100644 index 00000000000..2df3a70dfa1 --- /dev/null +++ b/server/src/realtime/live-event-delivery.ts @@ -0,0 +1,168 @@ +import type { LiveEvent } from "@paperclipai/shared"; + +export const LIVE_DELIVERY_MAX_ITEMS = 1_000; +export const LIVE_DELIVERY_MAX_BYTES = 1024 * 1024; +const CONGESTION_DEADLINE_MS = 5_000; +const transcript = (event: LiveEvent) => event.type === "heartbeat.run.event" || event.type === "heartbeat.run.log"; +const runId = (event: LiveEvent) => typeof event.payload.runId === "string" ? event.payload.runId : null; +interface Socket { + readyState: number; + bufferedAmount?: number; + send(data: string, callback?: (error?: Error) => void): void; + close(code?: number, reason?: string): void; +} + +export function createLiveEventDelivery(input: { + socket: Socket; + authorize(event: LiveEvent): Promise; + decorate(event: LiveEvent): Promise; + onError(error: unknown): void; +}) { + const { socket } = input; + let negotiated = false; + let revision = 0; + let interests = new Set(); + let queued: Array<{ event: LiveEvent; bytes: number; epoch: number }> = []; + let retainedBytes = 0; + let retainedItems = 0; + let epoch = 0; + let draining = false; + let disposed = false; + let needsResync = false; + let notifiedRevision = -1; + let congestionTimer: ReturnType | undefined; + let pendingReadTimer: ReturnType | undefined; + const activityAt = new Map(); + const isOpen = () => !disposed && socket.readyState === 1; + const room = (bytes: number, items = 1) => retainedItems + items <= LIVE_DELIVERY_MAX_ITEMS + && retainedBytes + bytes + (socket.bufferedAmount ?? 0) <= LIVE_DELIVERY_MAX_BYTES; + const wants = (event: LiveEvent) => !negotiated || !transcript(event) || interests.has(runId(event) ?? ""); + function dispose() { + disposed = true; epoch += 1; + for (const item of queued) { retainedBytes -= item.bytes; retainedItems -= 1; } + queued = []; activityAt.clear(); + if (congestionTimer) clearTimeout(congestionTimer); + if (pendingReadTimer) clearTimeout(pendingReadTimer); + congestionTimer = pendingReadTimer = undefined; + } + function closeBacklog() { + dispose(); + socket.close(1013, "persistent event backlog"); + } + function control(value: object): boolean { + const encoded = JSON.stringify(value); + if (!isOpen() || !room(Buffer.byteLength(encoded))) return false; + socket.send(encoded, error => { if (error) socket.close(1011, "live delivery failed"); }); + return true; + } + function resync() { + if (!needsResync || !isOpen() || notifiedRevision === revision) return; + if (control({ type: "live.resync", version: 1, revision, reason: "delivery_overflow" })) notifiedRevision = revision; + } + function overflow() { + if (!negotiated) { socket.close(1013, "event backlog"); return; } + epoch += 1; + for (const item of queued) { retainedBytes -= item.bytes; retainedItems -= 1; } + queued = []; + needsResync = true; + if (!congestionTimer) { + congestionTimer = setTimeout(() => { + congestionTimer = undefined; + if (needsResync || draining || (socket.bufferedAmount ?? 0) >= LIVE_DELIVERY_MAX_BYTES / 2) closeBacklog(); + }, CONGESTION_DEADLINE_MS); + congestionTimer.unref?.(); + } + resync(); + } + function project(event: LiveEvent): LiveEvent | null { + if (wants(event)) return event; + const id = runId(event); + if (!id) return null; + const now = Date.now(); + if (now - (activityAt.get(id) ?? -Infinity) < 1_000) return null; + if (activityAt.size >= LIVE_DELIVERY_MAX_ITEMS) activityAt.delete(activityAt.keys().next().value!); + activityAt.set(id, now); + return { ...event, type: "heartbeat.run.activity", payload: { runId: id, agentId: event.payload.agentId, + lastOutputAt: event.createdAt } }; + } + async function drain() { + if (draining) return; + draining = true; + try { + while (queued.length && isOpen()) { + const item = queued.shift()!; + try { + if (item.epoch !== epoch || !wants(item.event)) continue; + pendingReadTimer = setTimeout(closeBacklog, CONGESTION_DEADLINE_MS); + pendingReadTimer.unref?.(); + const visible = await input.authorize(item.event); + if (!visible || item.epoch !== epoch || !wants(item.event) || !isOpen()) continue; + const decorated = transcript(visible) || visible.type === "heartbeat.run.activity" + ? visible : await input.decorate(visible); + if (item.epoch !== epoch || !wants(item.event) || !isOpen()) continue; + const encoded = JSON.stringify(decorated); + const bytes = Buffer.byteLength(encoded); + if (bytes > LIVE_DELIVERY_MAX_BYTES || retainedBytes - item.bytes + bytes + (socket.bufferedAmount ?? 0) > LIVE_DELIVERY_MAX_BYTES) { + overflow(); continue; + } + socket.send(encoded, error => { + if (error) socket.close(1011, "live delivery failed"); + else resync(); + }); + } catch (error) { + if (!isOpen()) continue; + input.onError(error); + if (negotiated) overflow(); + } finally { + if (pendingReadTimer) clearTimeout(pendingReadTimer); + pendingReadTimer = undefined; + retainedBytes -= item.bytes; retainedItems -= 1; + } + } + } finally { draining = false; resync(); } + } + return { + receive(raw: string) { + if (!isOpen()) return; + if (Buffer.byteLength(raw) > 64 * 1024) { socket.close(1009, "interest message too large"); return; } + let value: unknown; + try { value = JSON.parse(raw); } catch { return; } + if (!value || typeof value !== "object") return; + if ((value as { type?: unknown }).type === "live.hello") { + if ((value as { version?: unknown }).version === 1) control({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + return; + } + if ((value as { type?: unknown }).type !== "live.interests") return; + const message = value as { version?: unknown; revision?: unknown; runIds?: unknown }; + if (message.version !== 1 || !Number.isSafeInteger(message.revision) || Number(message.revision) <= revision + || !Array.isArray(message.runIds) || message.runIds.length > LIVE_DELIVERY_MAX_ITEMS + || message.runIds.some(id => typeof id !== "string" || id.length > 128 || !/^[a-zA-Z0-9_-]+$/.test(id))) { + socket.close(1008, "invalid run interests"); return; + } + negotiated = true; + const unnotifiedGap = needsResync && notifiedRevision !== revision; + revision = Number(message.revision); + interests = new Set(message.runIds); + needsResync = unnotifiedGap; + if (control({ type: "live.subscribed", version: 1, revision })) { + resync(); + if (!needsResync && !draining && (socket.bufferedAmount ?? 0) < LIVE_DELIVERY_MAX_BYTES / 2 && congestionTimer) { + clearTimeout(congestionTimer); congestionTimer = undefined; + } + } else overflow(); + }, + enqueue(source: LiveEvent) { + if (!isOpen()) return; + if (source.type === "heartbeat.run.status") activityAt.delete(runId(source) ?? ""); + if (needsResync) return; + const event = project(source); + if (!event) return; + const bytes = Buffer.byteLength(JSON.stringify(event)); + if (!room(bytes)) { overflow(); return; } + queued.push({ event, bytes, epoch }); retainedBytes += bytes; retainedItems += 1; + void drain(); + }, + dispose, + metrics: () => ({ retainedBytes, retainedItems, negotiated, revision, needsResync }), + }; +} diff --git a/server/src/realtime/live-events-ws.ts b/server/src/realtime/live-events-ws.ts index 95159016122..06bffa0ae68 100644 --- a/server/src/realtime/live-events-ws.ts +++ b/server/src/realtime/live-events-ws.ts @@ -1,3 +1,4 @@ +import { createLiveEventDelivery } from "./live-event-delivery.js"; import { skillAccessService } from "../services/skill-access.js"; import { createHash } from "node:crypto"; import type { IncomingMessage, Server as HttpServer } from "node:http"; @@ -13,11 +14,14 @@ import { activityToastIdentity } from "./activity-toast-identity.js"; import { taskToastEligible } from "./task-toast-eligibility.js"; import { subscribeCompanyLiveEvents } from "../services/live-events.js"; import { trackIdleWork } from "../services/task-admission.js"; +import { createLiveRunEventRedactor } from "../services/live-run-event-redaction.js"; interface WsSocket { readyState: number; ping(): void; - send(data: string): void; + bufferedAmount?: number; + send(data: string, callback?: (error?: Error) => void): void; + on(event: "message", listener: (data: Buffer, isBinary: boolean) => void): void; terminate(): void; close(code?: number, reason?: string): void; on(event: "pong", listener: () => void): void; @@ -41,7 +45,7 @@ interface WsServer { const require = createRequire(import.meta.url); const { WebSocket, WebSocketServer } = require("ws") as { WebSocket: { OPEN: number }; - WebSocketServer: new (opts: { noServer: boolean }) => WsServer; + WebSocketServer: new (opts: { noServer: boolean; maxPayload: number }) => WsServer; }; import { authorizationService, type AuthorizationActor } from "../services/authorization.js"; @@ -253,7 +257,8 @@ export function setupLiveEventsWebSocketServer( resolveCloudActor?: (req: IncomingMessage) => Promise; }, ) { - const wss = new WebSocketServer({ noServer: true }); + const wss = new WebSocketServer({ noServer: true, maxPayload: 64 * 1024 }); + const redactRunEvent = createLiveRunEventRedactor(db); const cleanupByClient = new Map void>(); const aliveByClient = new Map(); @@ -303,6 +308,11 @@ export function setupLiveEventsWebSocketServer( : payload.entityType === "issue" && typeof payload.entityId === "string" ? payload.entityId : null; const runId = typeof payload.runId === "string" ? payload.runId : payload.entityType === "heartbeat_run" && typeof payload.entityId === "string" ? payload.entityId : null; + if (event.type === "heartbeat.run.event" || event.type === "heartbeat.run.log") { + const decision = await access.decide({ actor: context!.actor, action: "company_scope:read", + resource: { type: "company", companyId: event.companyId } }); + if (!decision.allowed) return null; + } const readBindings: Parameters[3][number][] = []; if (issueId) { readBindings.push({ companyId: event.companyId, scopeKind: "issue", issueId }); @@ -347,33 +357,29 @@ export function setupLiveEventsWebSocketServer( if (event.type.startsWith("plugin.")) return event; return null; } - let delivery = Promise.resolve(); - let pending = 0; - const unsubscribe = subscribeCompanyLiveEvents(context.companyId, (event) => { - if (socket.readyState !== WebSocket.OPEN) return; - if (++pending > 1000) { socket.close(1013, "event backlog"); return; } - delivery = delivery.then(async () => { - if (socket.readyState !== WebSocket.OPEN) return; - // Check at delivery time, including after a grant is revoked while the - // subscription remains open. Never cache successful privacy decisions. - const visible = await visibleEvent(event); - if (visible) { - // Relevance is independent of authorization and cache delivery. A - // failed relevance lookup must keep the authorized update flowing. - let toastEligible = false; - try { - toastEligible = await taskToastEligible(db, visible, - context.actor.type === "board" ? context.actor.userId ?? null : null); - } catch (err) { - logger.warn({ err, companyId: context.companyId }, "task toast eligibility failed"); - } - if (socket.readyState === WebSocket.OPEN) socket.send(JSON.stringify({ ...visible, toastEligible })); - } - }).catch(err => logger.warn({ err, companyId: context.companyId }, "live event authorization failed")) - .finally(() => { pending -= 1; }); + const delivery = createLiveEventDelivery({ socket, authorize: async event => { + const visible = await visibleEvent(event); + if (!visible || visible.type !== "heartbeat.run.event") return visible; + const payload = visible.payload.payload; + if (!payload || typeof payload !== "object" || Array.isArray(payload) || !("prpEvent" in payload)) return visible; + return redactRunEvent(visible); + }, + decorate: async visible => { + let toastEligible = false; + try { + toastEligible = await taskToastEligible(db, visible, + context.actor.type === "board" ? context.actor.userId ?? null : null); + } catch (err) { logger.warn({ err, companyId: context.companyId }, "task toast eligibility failed"); } + return { ...visible, toastEligible }; + }, + onError: err => logger.warn({ err, companyId: context.companyId }, "live event authorization failed"), }); - - cleanupByClient.set(socket, unsubscribe); + const unsubscribe = subscribeCompanyLiveEvents(context.companyId, event => delivery.enqueue(event)); + socket.on("message", (data, isBinary) => { + if (isBinary) { socket.close(1003, "text messages required"); return; } + delivery.receive(data.toString()); + }); + cleanupByClient.set(socket, () => { unsubscribe(); delivery.dispose(); }); aliveByClient.set(socket, true); socket.on("pong", () => { diff --git a/server/src/services/heartbeat/run-output.ts b/server/src/services/heartbeat/run-output.ts index 2b285ef8297..62d929938ff 100644 --- a/server/src/services/heartbeat/run-output.ts +++ b/server/src/services/heartbeat/run-output.ts @@ -174,6 +174,8 @@ export function createHeartbeatRunOutput(db: Db, input: HeartbeatRunOutputInput) seq: chunkSeq, stream, chunk: payloadChunk, + logRef: handle?.logRef, + logStore: handle?.store, truncated: payloadChunk.length !== sanitizedChunk.length, }, }); diff --git a/server/src/services/live-run-event-redaction.ts b/server/src/services/live-run-event-redaction.ts new file mode 100644 index 00000000000..4818f183fc5 --- /dev/null +++ b/server/src/services/live-run-event-redaction.ts @@ -0,0 +1,19 @@ +import type { Db } from "@paperclipai/db"; +import type { LiveEvent } from "@paperclipai/shared"; +import { redactCurrentUserValue } from "../log-redaction.js"; +import { redactEventPayload } from "../redaction.js"; +import { instanceSettingsService } from "./instance-settings.js"; +import { createRunSecretRedactionRegistry } from "./run-secret-redaction.js"; + +export function createLiveRunEventRedactor(db: Db) { + const settings = instanceSettingsService(db); + const redactions = createRunSecretRedactionRegistry(db); + return async (event: LiveEvent): Promise => { + const runId = event.payload.runId; + if (typeof runId !== "string") return null; + const redacted = redactCurrentUserValue({ ...event, + payload: redactEventPayload(event.payload) ?? {}, + }, { enabled: (await settings.getGeneral()).censorUsernameInLogs }); + return redactions.redactForRun(event.companyId, runId, redacted); + }; +} diff --git a/server/src/services/native-runtime/paperclip-control-plane-port.test.ts b/server/src/services/native-runtime/paperclip-control-plane-port.test.ts index 4676979de87..57d49cff0aa 100644 --- a/server/src/services/native-runtime/paperclip-control-plane-port.test.ts +++ b/server/src/services/native-runtime/paperclip-control-plane-port.test.ts @@ -42,6 +42,7 @@ import { runControlPlanePortConformance, } from "../../vendor/paperclip-runner/testing.js"; import { startEmbeddedPostgresTestDatabase } from "../../__tests__/helpers/embedded-postgres.js"; +import { startRecoveryPostgres } from "../../__tests__/helpers/recovery-postgres.js"; import { PaperclipControlPlanePort } from "./paperclip-control-plane-port.js"; import { NativeRunCoordinatorStore } from "./native-run-coordinator-store.js"; import { finalizeNativeRun, repairCommittedNativeChatResponse } from "./native-run-finalizer.js"; @@ -65,7 +66,7 @@ import { } from "../live-events.js"; describe("PaperclipControlPlanePort conformance", () => { - let temporary: Awaited> | null = null; + let temporary: Awaited> | null = null; let db: ReturnType; const contractId = "00000000-0000-4000-8000-000000000004"; const contractSha = "phase6-conformance-contract"; @@ -86,7 +87,7 @@ describe("PaperclipControlPlanePort conformance", () => { const governanceRunnerId = "00000000-0000-4000-8000-000000000021"; beforeAll(async () => { - temporary = await startEmbeddedPostgresTestDatabase("paperclip-native-port-"); + temporary = await startRecoveryPostgres("paperclip-native-port-"); db = createDb(temporary.connectionString); const identity = CONTROL_PLANE_CONFORMANCE_OPEN.identity; await db.insert(companies).values({ id: identity.companyId, name: "Phase 6", issuePrefix: "P6C" }); @@ -596,7 +597,7 @@ describe("PaperclipControlPlanePort conformance", () => { ); }); - it("signals committed safe progress after row visibility without forwarding its payload", async () => { + it("streams committed native rows and deltas after visibility without repeating receipts", async () => { const identity = CONTROL_PLANE_CONFORMANCE_OPEN.identity; const issueId = "40000000-0000-4000-8000-000000000042"; const runId = "41000000-0000-4000-8000-000000000042"; @@ -725,8 +726,10 @@ describe("PaperclipControlPlanePort conformance", () => { issueId, seq: 1, eventType: "tool.execution.started", + stream: "system", + level: "info", + payload: { prpEvent: progressEvent }, }]); - expect(JSON.stringify(observed)).not.toContain("must-not-cross-live-signal"); await expect(port.appendEvent(progressEvent)).resolves.toMatchObject({ disposition: "duplicate", @@ -758,10 +761,14 @@ describe("PaperclipControlPlanePort conformance", () => { ...progressEvent, sourceEventId: "safe-progress-signal:3", sourceSeq: 3, - eventType: "turn.started", - payload: {}, + eventType: "item.delta", + itemId: "streaming-message", + payload: { kind: "agentMessage", text: "still writing" }, })).resolves.toMatchObject({ disposition: "committed" }); - expect(observed).toHaveLength(1); + expect(observed).toHaveLength(2); + expect(observed[1]).toMatchObject({ seq: 3, eventType: "item.delta", payload: { + prpEvent: { eventType: "item.delta", payload: { text: "still writing" } }, + } }); expect(committedCallbacks).toEqual([ "safe-progress-signal:1", "safe-progress-signal:2", diff --git a/server/src/services/native-runtime/paperclip-control-plane-port.ts b/server/src/services/native-runtime/paperclip-control-plane-port.ts index d6c6413d060..b8e371da2bf 100644 --- a/server/src/services/native-runtime/paperclip-control-plane-port.ts +++ b/server/src/services/native-runtime/paperclip-control-plane-port.ts @@ -25,7 +25,7 @@ import { validatePrpStructuredRunResult, } from "../../vendor/paperclip-runner/index.js"; import { appendHeartbeatRunEvent } from "../heartbeat-run-events.js"; -import { publishChatPublicationCommitSignal } from "../chat-publication-reconciliation.js"; +import { publishLiveEvent } from "../live-events.js"; import { nativeSha256 } from "./canonical.js"; import { redactRunnerApiPayloads } from "./runner-api-log-redaction.js"; @@ -286,14 +286,23 @@ export class PaperclipControlPlanePort implements ControlPlanePort { }); this.#assertActive(options); if (persisted.disposition === "committed") { - publishChatPublicationCommitSignal({ - companyId: this.#binding.companyId, - issueId: this.#binding.issueId, - runId: this.#binding.runId, - agentId: this.#binding.agentId, - seq: persisted.row.seq, - eventType: event.eventType, - }); + try { + publishLiveEvent({ + companyId: this.#binding.companyId, + type: "heartbeat.run.event", + payload: { + runId: this.#binding.runId, + agentId: this.#binding.agentId, + issueId: this.#binding.issueId, + seq: persisted.row.seq, + eventType: persisted.row.eventType, + stream: persisted.row.stream, + level: persisted.row.level, + payload: persisted.row.payload, + }, + }); + } catch { + } await this.#onCommittedEvent?.(event); } else { // A recovered runner may replay the event whose durable side effects diff --git a/server/src/services/plugin-host-services.ts b/server/src/services/plugin-host-services.ts index 7a9b1cbe825..e6b1238e0f9 100644 --- a/server/src/services/plugin-host-services.ts +++ b/server/src/services/plugin-host-services.ts @@ -1,4 +1,6 @@ import { projectGitAuthorizationService } from "./project-git-authorization.js"; +import { createLiveEventDelivery } from "../realtime/live-event-delivery.js"; +import { createLiveRunEventRedactor } from "./live-run-event-redaction.js"; import { projectInstanceSecretService } from "./project-instance-secrets.js"; import { pluginAgentRuntimeState, pluginAgentRuntimeIdentity } from "./plugin-agent-runtime-state.js"; import { createAgentLifecycle } from "./agent-lifecycle.js"; @@ -3564,54 +3566,82 @@ export function buildHostServices( if (notifyWorker) { const TERMINAL_STATUSES = new Set(["succeeded", "interrupted", "failed", "cancelled", "timed_out"]); + let active = true; const cleanup = () => { - unsubscribe(); + stopDelivery(); clearTimeout(timeoutTimer); activeSubscriptions.delete(entry); }; - - const unsubscribe = subscribeCompanyLiveEvents(companyId, (event) => { - const payload = event.payload as Record | undefined; - if (!payload || payload.runId !== run.id) return; - - if (event.type === "heartbeat.run.log" || event.type === "heartbeat.run.event") { - notifyWorker("agents.sessions.event", { - sessionId: params.sessionId, - runId: run.id, - seq: (payload.seq as number) ?? 0, - eventType: "chunk", - stream: (payload.stream as string) ?? null, - message: (payload.chunk as string) ?? (payload.message as string) ?? null, - payload: payload, - }); - } else if (event.type === "heartbeat.run.status") { - const status = payload.status as string; - if (TERMINAL_STATUSES.has(status)) { - notifyWorker("agents.sessions.event", { - sessionId: params.sessionId, - runId: run.id, - seq: 0, - eventType: status === "succeeded" ? "done" : "error", - stream: "system", - message: status === "succeeded" - ? (typeof payload.finalText === "string" ? payload.finalText : null) - : `Run ${status}`, - payload: payload, - }); - cleanup(); - } else { - notifyWorker("agents.sessions.event", { - sessionId: params.sessionId, - runId: run.id, - seq: 0, - eventType: "status", - stream: "system", - message: `Run status: ${status}`, - payload: payload, - }); - } + const failDelivery = () => { + if (!active) return; + cleanup(); + try { + notifyWorker("agents.sessions.event", { sessionId: params.sessionId, runId: run.id, + seq: 0, eventType: "error", stream: "system", message: "Run event delivery unavailable", + payload: { reason: "delivery_unavailable" } }); + } catch (err) { + logger.warn({ err, pluginId, runId: run.id }, "plugin session delivery unavailable"); } + }; + const delivery = createLiveEventDelivery({ + socket: { + get readyState() { return active ? 1 : 3; }, + send(encoded, callback) { + const event = JSON.parse(encoded) as import("@paperclipai/shared").LiveEvent; + const payload = event.payload; + if (event.type === "heartbeat.run.log" || event.type === "heartbeat.run.event") { + notifyWorker("agents.sessions.event", { + sessionId: params.sessionId, + runId: run.id, + seq: (payload.seq as number) ?? 0, + eventType: "chunk", + stream: (payload.stream as string) ?? null, + message: (payload.chunk as string) ?? (payload.message as string) ?? null, + payload: payload, + }); + } else if (event.type === "heartbeat.run.status") { + const status = payload.status as string; + if (TERMINAL_STATUSES.has(status)) { + notifyWorker("agents.sessions.event", { + sessionId: params.sessionId, + runId: run.id, + seq: 0, + eventType: status === "succeeded" ? "done" : "error", + stream: "system", + message: status === "succeeded" + ? (typeof payload.finalText === "string" ? payload.finalText : null) + : `Run ${status}`, + payload: payload, + }); + cleanup(); + } else { + notifyWorker("agents.sessions.event", { + sessionId: params.sessionId, + runId: run.id, + seq: 0, + eventType: "status", + stream: "system", + message: `Run status: ${status}`, + payload: payload, + }); + } + } + callback?.(); + }, + close: failDelivery, + }, + authorize: createLiveRunEventRedactor(db), + decorate: async event => event, + onError: err => { + logger.warn({ err, pluginId, runId: run.id }, "plugin session event redaction failed"); + failDelivery(); + }, }); + const unsubscribe = subscribeCompanyLiveEvents(companyId, event => { + if (event.payload.runId === run.id && + ["heartbeat.run.log", "heartbeat.run.event", "heartbeat.run.status"].includes(event.type)) delivery.enqueue(event); + }); + const stopDelivery = () => { active = false; delivery.dispose(); unsubscribe(); }; // Safety-net timeout: if the run never reaches a terminal status, // force-cleanup the subscription to prevent unbounded leaks. @@ -3620,10 +3650,10 @@ export function buildHostServices( { pluginId, pluginKey, runId: run.id }, "session event subscription timed out — forcing cleanup", ); - cleanup(); + failDelivery(); }, SESSION_EVENT_SUBSCRIPTION_TIMEOUT_MS); - const entry = { unsubscribe, timer: timeoutTimer }; + const entry = { unsubscribe: stopDelivery, timer: timeoutTimer }; activeSubscriptions.add(entry); } diff --git a/tests/e2e/fixtures/in-feed-codex.mjs b/tests/e2e/fixtures/in-feed-codex.mjs index e1bcaec8e4e..43acbb058e7 100644 --- a/tests/e2e/fixtures/in-feed-codex.mjs +++ b/tests/e2e/fixtures/in-feed-codex.mjs @@ -8,6 +8,7 @@ import { createInterface } from 'node:readline'; if (process.argv.includes('--version')) { console.log('codex-cli 0.115.0 (in-feed fixture)'); process.exit(0); } let threadId = `fixture-${randomUUID()}`; let turnId, toolSequence = 0, declined = false; +let helloProbe = false; const recoveryFixture = process.env.PAPERCLIP_RECOVERY_FIXTURE === "1"; let currentObjective = ""; let emitCeoLineage = false; @@ -55,6 +56,11 @@ async function finish(text, evidenceRef) { evidence: [{ ref: evidenceRef }], verification: [{ commandOrCheck: 'Fixture outcome', status: 'passed' }], attentionRequests: [], artifacts: [] }); } async function execute() { + if (helloProbe) { + send({ method: 'item/completed', params: { threadId, turnId, item: { id: `answer-${turnId}`, type: 'agentMessage', phase: 'final_answer', text: 'hello' } } }); + send({ method: 'turn/completed', params: { threadId, turn: { id: turnId, status: 'completed' } } }); + return; + } if (process.argv.includes('--task-retry-fixture')) { const text = 'The saved result is confirmed. No external publication was repeated.'; await call('report_progress', { idempotencyKey: 'saved-result-confirmation', body: text }); @@ -67,6 +73,8 @@ async function execute() { // Report completion before a deliberately slow final answer. The real // runner and control plane must keep listening after the tool succeeds. await finish('The fixture work is complete.', 'fixture:STREAM-42'); + send({ method: 'item/completed', params: { threadId, turnId, + item: { id: `waiting-${turnId}`, type: 'agentMessage', phase: 'commentary', text: 'STREAM-42: waiting for the final answer.' } } }); // Exceed both former completion deadlines: cold (5s) and reusable (30s). await new Promise((resolve) => setTimeout(resolve, 31_000)); const itemId = `answer-${turnId}`; @@ -148,10 +156,13 @@ createInterface({ input: process.stdin }).on('line', (line) => { if (recoveryFixture) send({ method: 'configWarning', params: { message: 'Recovery fixture startup notice before the first turn' } }); if (method === 'thread/resume' && message.params?.threadId) threadId = message.params.threadId; if (message.params?.completionContract) completionContract = message.params.completionContract; - send({ id, result: { model: 'in-feed-fixture', modelProvider: 'fixture', thread: { id: threadId, sessionId: threadId } } }); + const model = process.argv.includes('--completion-stream-fixture') ? message.params?.model ?? 'in-feed-fixture' : 'in-feed-fixture'; + send({ id, result: { model, modelProvider: 'fixture', thread: { id: threadId, sessionId: threadId } } }); } else if (method === 'thread/read') send({ id, result: { thread: { id: threadId, turns: [] } } }); else if (method === 'turn/start') { + helloProbe = process.argv.includes('--completion-stream-fixture') + && JSON.stringify(message.params?.input).includes('Respond only with hello. Do not use tools or inspect files.'); emitCeoLineage = JSON.stringify(message.params).includes('CEO descendant fixture'); declined = /connection_intent/.test(JSON.stringify(message.params)) && /rejected/.test(JSON.stringify(message.params)); for (const part of message.params?.input ?? []) { diff --git a/tests/e2e/playwright-transcript-delivery.config.ts b/tests/e2e/playwright-transcript-delivery.config.ts new file mode 100644 index 00000000000..f2e35aa2d67 --- /dev/null +++ b/tests/e2e/playwright-transcript-delivery.config.ts @@ -0,0 +1,23 @@ +import fs from "node:fs"; +import os from "node:os"; +import path from "node:path"; +import { defineConfig } from "@playwright/test"; +import base from "./playwright.config"; + +const providerHome = fs.mkdtempSync(path.join(os.tmpdir(), "transcript-provider-")); +const server = base.webServer as Exclude; +export default defineConfig({ + ...base, + testMatch: "transcript-delivery.journey.ts", + use: { ...base.use, actionTimeout: 15_000, trace: "retain-on-failure" }, + webServer: { + ...server, + env: { + ...server?.env, + PAPERCLIP_STOP_CODEX_COMMAND: path.resolve(import.meta.dirname, "fixtures/completion-stream-bin/codex"), + CODEX_HOME: providerHome, + OPENAI_API_KEY: "transcript-fixture-key", + NODE_OPTIONS: `${server?.env?.NODE_OPTIONS ?? ""} --import=${path.resolve(import.meta.dirname, "fixtures/composer-stop-codex-loader.mjs")}`, + }, + }, +}); diff --git a/tests/e2e/transcript-delivery.journey.ts b/tests/e2e/transcript-delivery.journey.ts new file mode 100644 index 00000000000..53a99d0d4dd --- /dev/null +++ b/tests/e2e/transcript-delivery.journey.ts @@ -0,0 +1,133 @@ +import { expect, test, type WebSocket } from "@playwright/test"; +import { json } from "./agent-chat.shared"; + +test("native transcript survives two views and reload through negotiated streaming", async ({ page, context, request }, info) => { + test.setTimeout(120_000); + await page.addInitScript(() => { + const sockets = new Set(); + const OriginalWebSocket = window.WebSocket; + window.WebSocket = class extends OriginalWebSocket { + constructor(url: string | URL, protocols?: string | string[]) { + super(url, protocols); + if (String(url).includes("/events/ws")) sockets.add(this); + this.addEventListener("close", () => sockets.delete(this)); + } + }; + Object.assign(window, { closeTranscriptTransport: () => { + for (const socket of sockets) socket.close(); + } }); + }); + const company = await json(await request.post("/api/companies", { data: { name: "Native transcript delivery" } })); + const original = await json(await request.get("/api/instance/settings/experimental")); + const frames: Array<{ type?: string; runIds?: string[]; revision?: number }> = []; + let connections = 0; + const activeConnections = new Set(); + let transcriptReads = 0; + page.on("request", request => { if (/\/heartbeat-runs\/[^/]+\/(events|log)(\?|$)/.test(request.url())) transcriptReads += 1; }); + page.on("websocket", socket => { + if (!socket.url().includes("/events/ws")) return; + connections += 1; + activeConnections.add(socket); + socket.on("close", () => { activeConnections.delete(socket); }); + socket.on("framesent", frame => { try { frames.push(JSON.parse(String(frame.payload))); } catch {} }); + socket.on("framereceived", frame => { try { frames.push(JSON.parse(String(frame.payload))); } catch {} }); + }); + try { + await json(await request.patch("/api/instance/settings/experimental", { data: { enableNativeRunner: true, enableWorktreeRunExecution: true } })); + await json(await request.post(`/api/companies/${company.id}/user-secret-definitions`, { data: { key: "OPENAI_API_KEY", name: "Fixture credential" } })); + await json(await request.post(`/api/companies/${company.id}/me/user-secrets`, { data: { definitionKey: "OPENAI_API_KEY", value: "not-a-real-model-key" } })); + const agent = await json(await request.post(`/api/companies/${company.id}/agents`, { data: { name: "CEO", role: "ceo", adapterType: "paperclip_runner", + adapterConfig: { provider: "codex", model: "gpt-5.1-codex-mini", env: { + OPENAI_API_KEY: { type: "user_secret_ref", key: "OPENAI_API_KEY", version: "latest", required: true }, + } } } })); + await expect.poll(async () => (await json(await request.get(`/api/agents/${agent.id}`))).lifecycleState, + { timeout: 30_000 }).toBe("ready"); + await page.goto(`/${company.issuePrefix}/agents/${agent.id}/overview`); + await page.getByRole("link", { name: "Tasks", exact: true }).click(); + await page.getByRole("button", { name: "New Task", exact: true }).last().click(); + const dialog = page.getByRole("dialog"); + await dialog.getByRole("textbox", { name: "editable markdown" }).fill("Summarize the launch decisions and include the source link"); + await expect(dialog.getByRole("button", { name: "Select assignee" })).toContainText("CEO"); + await dialog.getByRole("button", { name: "Create task", exact: true }).click(); + await expect.poll(async () => (await json(await request.get(`/api/companies/${company.id}/issues`))).length).toBe(1); + const [issue] = await json(await request.get(`/api/companies/${company.id}/issues`)); + const route = `/${company.issuePrefix}/issues/${issue.identifier}`; + activeConnections.clear(); + frames.length = 0; + await page.goto(route); + let runId = ""; + await expect.poll(async () => { + const runs = await json(await request.get(`/api/companies/${company.id}/heartbeat-runs`)); + runId = runs[0]?.id ?? ""; + return runs[0]?.status; + }).toBe("running"); + const subscribed = () => { + const index = frames.findLastIndex(frame => frame.type === "live.interests"); + const interest = frames[index]; + return Boolean(interest?.runIds?.includes(runId) + && frames.slice(index + 1).some(frame => frame.type === "live.subscribed" && frame.revision === interest.revision)); + }; + await expect.poll(subscribed).toBe(true); + await expect(page.getByText("STREAM-42: waiting for the final answer.", { exact: false }).first()).toBeVisible(); + await page.waitForTimeout(2_000); + const healthyReads = transcriptReads; + await page.waitForTimeout(2_500); + const healthyPollingReads = transcriptReads - healthyReads; + expect(healthyPollingReads).toBe(0); + expect(activeConnections.size).toBe(1); + const second = await context.newPage(); + await second.goto(route); + const other = await json(await request.post("/api/companies", { data: { name: "Transcript isolation" } })); + await page.goto(`/${other.issuePrefix}/dashboard`); + await expect.poll(() => frames.findLast(frame => frame.type === "live.interests")?.runIds).toEqual([]); + await page.goto(route); + await expect.poll(subscribed).toBe(true); + const beforeReconnect = connections; + await context.setOffline(true); + await page.evaluate(() => (window as unknown as { closeTranscriptTransport(): void }).closeTranscriptTransport()); + await page.waitForTimeout(1_000); + await context.setOffline(false); + await expect.poll(() => connections, { timeout: 15_000 }).toBeGreaterThan(beforeReconnect); + await expect.poll(subscribed).toBe(true); + await expect.poll(async () => (await json(await request.get(`/api/companies/${company.id}/heartbeat-runs`)))[0]?.status, { timeout: 70_000 }).toBe("succeeded"); + for (const view of [page, second]) { + await expect(view.getByText("STREAM-42: The launch has two stages.", { exact: false }).first()).toBeVisible(); + await view.reload(); + await expect(view.getByText("STREAM-42: The launch has two stages.", { exact: false }).first()).toBeVisible(); + } + const runs = await json(await request.get(`/api/companies/${company.id}/heartbeat-runs`)); + expect(runs).toHaveLength(1); + const comments = await json(await request.get(`/api/issues/${issue.id}/comments`)); + expect(comments.filter((comment: { body: string }) => comment.body.includes("STREAM-42"))).toHaveLength(1); + await page.screenshot({ path: info.outputPath("native-transcript.png"), fullPage: true }); + await page.goto(`/${company.issuePrefix}/agents/${agent.id}/runs/${runId}`); + const eventDetails = page.getByText(/^Events \(\d+\)$/).locator(".."); + await expect(eventDetails.getByText("STREAM-42: The launch has two stages.", { exact: false }).first()).toBeVisible(); + await page.reload(); + await expect(eventDetails.getByText("STREAM-42: The launch has two stages.", { exact: false }).first()).toBeVisible(); + const eventsRoute = `**/api/heartbeat-runs/${runId}/events?*`; + const logRoute = `**/api/heartbeat-runs/${runId}/log?*`; + await page.route(eventsRoute, route => route.fulfill({ status: 503, json: { error: "History temporarily unavailable" } })); + await page.route(logRoute, async route => { + const response = await route.fetch(); + await route.fulfill({ json: { ...await response.json(), content: "", nextOffset: 0 } }); + }); + await page.reload(); + await expect(page.getByText("Could not load events. Try again.", { exact: true })).toBeVisible(); + await expect(page.getByText("No log events.", { exact: true })).toHaveCount(0); + await page.unroute(eventsRoute); await page.unroute(logRoute); + await page.getByRole("button", { name: "Retry events", exact: true }).click(); + await expect(eventDetails.getByText("STREAM-42: The launch has two stages.", { exact: false }).first()).toBeVisible(); + await expect(page.getByText("Could not load events. Try again.", { exact: true })).toHaveCount(0); + await page.screenshot({ path: info.outputPath("native-agent-events.png"), fullPage: true }); + await info.attach("delivery-evidence", { body: JSON.stringify({ dependency: "deterministic Codex app-server", runId: runs[0].id, + connections, healthyPollingReads, negotiated: frames.some(frame => frame.type === "live.subscribed"), + interestRevisions: frames.filter(frame => frame.type === "live.interests") }), contentType: "application/json" }); + await second.close(); + } finally { + const live = await json(await request.get(`/api/companies/${company.id}/live-runs`)); + for (const run of live) await json(await request.post(`/api/heartbeat-runs/${run.id}/cancel`)); + await json(await request.patch("/api/instance/settings/experimental", { data: { enableNativeRunner: original.enableNativeRunner, + enableWorktreeRunExecution: original.enableWorktreeRunExecution } })); + } +}); diff --git a/ui/src/components/ActiveAgentsPanel.tsx b/ui/src/components/ActiveAgentsPanel.tsx index b3aaf50a2d7..8f09811cf69 100644 --- a/ui/src/components/ActiveAgentsPanel.tsx +++ b/ui/src/components/ActiveAgentsPanel.tsx @@ -126,7 +126,7 @@ export function ActiveAgentsPanel({ maxChunksPerRun: DASHBOARD_MAX_CHUNKS_PER_RUN, logPollIntervalMs: DASHBOARD_LOG_POLL_INTERVAL_MS, logReadLimitBytes: DASHBOARD_LOG_READ_LIMIT_BYTES, - enableRealtimeUpdates: false, + enabled: showTranscripts, }); return ( diff --git a/ui/src/components/TaskChatThread.tsx b/ui/src/components/TaskChatThread.tsx index 48333ea7345..ec184eb080e 100644 --- a/ui/src/components/TaskChatThread.tsx +++ b/ui/src/components/TaskChatThread.tsx @@ -951,7 +951,7 @@ export function TaskChatThread(props: TaskChatThreadProps) { hydratedRunIds: hydratedNativeRunIds, terminalHydratedRunIds, retry: retryNativeEvents, - } = useNativeRunTranscripts(nativeRuns); + } = useNativeRunTranscripts(nativeRuns, { companyId }); const logRuns = useMemo(() => runs.filter((run) => (!nativeRuns.some((nativeRun) => nativeRun.id === run.id && nativeRun.conversationOnly) || nativeTranscriptErrorsByRun.has(run.id) || diff --git a/ui/src/components/transcript/useLiveRunTranscripts.streaming.test.tsx b/ui/src/components/transcript/useLiveRunTranscripts.streaming.test.tsx new file mode 100644 index 00000000000..f250e2f9254 --- /dev/null +++ b/ui/src/components/transcript/useLiveRunTranscripts.streaming.test.tsx @@ -0,0 +1,321 @@ +// @vitest-environment jsdom + +import { act, type ReactNode } from "react"; +import { createRoot as createReactRoot } from "react-dom/client"; +import type { LiveEvent } from "@paperclipai/shared"; +import { __liveUpdatesTestUtils, type CompanyLiveEventHandler } from "../../context/LiveUpdatesProvider"; +import { LiveTranscriptInterests } from "../../lib/live-transcript-interests"; +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { useLiveRunTranscripts } from "./useLiveRunTranscripts"; + +const { useQueryMock, logMock, buildTranscriptMock } = vi.hoisted(() => ({ + useQueryMock: vi.fn(() => ({ data: { censorUsernameInLogs: false } })), + logMock: vi.fn(async (_runId: string, _offset: number, _limit: number, _options: { signal: AbortSignal }) => + ({ runId: "run-1", store: "memory", logRef: "log-1", content: "", nextOffset: 0 })), + buildTranscriptMock: vi.fn((chunks: unknown[]) => chunks), +})); + +vi.mock("@tanstack/react-query", () => ({ + useQuery: useQueryMock, +})); + +vi.mock("../../api/instanceSettings", () => ({ + instanceSettingsApi: { + getGeneral: vi.fn(), + }, +})); + +vi.mock("../../api/heartbeats", () => ({ + heartbeatsApi: { + log: logMock, + }, +})); + +vi.mock("../../adapters", () => ({ + buildTranscript: buildTranscriptMock, + getUIAdapter: () => null, + onAdapterChange: () => () => {}, +})); + +const { LiveEventSubscriptionContext } = __liveUpdatesTestUtils; +let listeners: Set; +let interests: LiveTranscriptInterests; +let sent: Array<{ type: string; revision?: number; runIds?: string[] }>; +let socketConstructed: ReturnType void>>; +function createRoot(container: HTMLDivElement) { + const root = createReactRoot(container); + const subscription = { + companyId: "company-1", transcripts: interests, + subscribe(handler: CompanyLiveEventHandler) { + listeners.add(handler); + return () => { listeners.delete(handler); }; + }, + }; + return { + unmount: () => root.unmount(), + render: (children: ReactNode) => root.render( + {children}, + ), + }; +} +function sendEvent(event: Omit) { + for (const listener of listeners) listener({ ...event, id: 1 }); +} +function negotiate() { + interests.open({ send: data => sent.push(JSON.parse(data)) }); + interests.receive({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + acknowledge(); +} +function acknowledge() { + interests.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1)?.revision }); +} + +// eslint-disable-next-line @typescript-eslint/no-explicit-any +(globalThis as any).IS_REACT_ACT_ENVIRONMENT = true; + +describe("useLiveRunTranscripts shared-stream recovery", () => { + const OriginalWebSocket = globalThis.WebSocket; + + beforeEach(() => { + vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + listeners = new Set(); interests = new LiveTranscriptInterests(); sent = []; + socketConstructed = vi.fn(); + useQueryMock.mockClear(); + logMock.mockReset(); + logMock.mockImplementation(async (_id, offset) => ({ runId: "run-1", store: "memory", logRef: "log-1", content: "", nextOffset: offset })); + buildTranscriptMock.mockClear(); + globalThis.WebSocket = class { constructor() { socketConstructed(); } } as unknown as typeof WebSocket; + }); + + afterEach(() => { + globalThis.WebSocket = OriginalWebSocket; + vi.restoreAllMocks(); + vi.useRealTimers(); + }); + + it("fetches a consecutive truncated row excluded from an in-flight history response", async () => { + vi.useFakeTimers(); + let value: ReturnType; + function Harness() { + value = useLiveRunTranscripts({ companyId: "company-1", runs: [{ id: "run-1", status: "running", adapterType: "codex_local" }] }); + return null; + } + const root = createRoot(document.createElement("div")); + const row = (seq: number, chunk: string) => JSON.stringify({ seq, ts: "2026-10-24T00:00:00Z", stream: "stdout", chunk }) + "\n"; + const first = row(1, "first"); + const second = row(2, "complete second output"); + try { + await act(async () => root.render()); + let finish!: (value: Awaited>) => void; + logMock.mockImplementationOnce(() => new Promise(resolve => { finish = resolve; })); + await act(async () => negotiate()); + await act(async () => { + sendEvent({ companyId: "company-1", type: "heartbeat.run.log", createdAt: "2026-10-24T00:00:00Z", + payload: { runId: "run-1", seq: 1, chunk: "first", stream: "stdout" } }); + sendEvent({ companyId: "company-1", type: "heartbeat.run.log", createdAt: "2026-10-24T00:00:00Z", + payload: { runId: "run-1", seq: 2, chunk: "short", truncated: true, stream: "stdout" } }); + }); + await act(async () => finish({ runId: "run-1", store: "memory", logRef: "log-1", content: first, nextOffset: first.length })); + const beforeRetry = logMock.mock.calls.length; + logMock.mockResolvedValueOnce({ runId: "run-1", store: "memory", logRef: "log-1", content: second, nextOffset: first.length + second.length }); + await act(async () => vi.advanceTimersByTimeAsync(2000)); + expect(logMock.mock.calls.length).toBeGreaterThan(beforeRetry); + expect(value!.transcriptByRun.get("run-1")).toEqual(expect.arrayContaining([expect.objectContaining({ chunk: "complete second output", seq: 2 })])); + const settledReads = logMock.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(logMock).toHaveBeenCalledTimes(settledReads); + } finally { await act(async () => root.unmount()); } + }); + + it("finishes slow legacy pages while a sibling catches up repeated truncated output", async () => { + vi.useFakeTimers(); + let value: ReturnType; + function Harness() { + value = useLiveRunTranscripts({ companyId: "company-1", runs: [ + { id: "run-1", status: "running", adapterType: "codex_local" }, + { id: "slow", status: "succeeded", adapterType: "codex_local" }, + ] }); + return null; + } + const root = createRoot(document.createElement("div")); + type Result = Awaited>; + const slow: Array<{ resolve: (value: Result) => void; signal: AbortSignal }> = []; + const row = (seq: number, chunk: string) => JSON.stringify({ seq, ts: "2026-10-24T00:00:00Z", stream: "stdout", chunk }) + "\n"; + let seq = 0; + try { + await act(async () => root.render()); + logMock.mockImplementation(async (id, offset, _limit, { signal }) => { + if (id === "slow") return new Promise(resolve => slow.push({ resolve, signal })); + return { runId: id, store: "memory", logRef: "log-1", content: offset < seq ? row(seq, `complete ${seq}`) : "", nextOffset: seq }; + }); + await act(async () => negotiate()); + for (seq = 1; seq <= 3; seq++) { + await act(async () => sendEvent({ companyId: "company-1", type: "heartbeat.run.log", createdAt: "2026-10-24T00:00:00Z", + payload: { runId: "run-1", seq, truncated: true } })); + } + expect(slow).toHaveLength(1); + expect(slow[0].signal.aborted).toBe(false); + expect(value!.transcriptByRun.get("run-1")).toEqual(expect.arrayContaining([expect.objectContaining({ seq: 3, chunk: "complete 3" })])); + await act(async () => slow[0].resolve({ runId: "slow", store: "memory", logRef: "log-1", content: row(1, "older output"), nextOffset: 1 })); + expect(slow).toHaveLength(2); + expect(slow[1].signal.aborted).toBe(false); + await act(async () => slow[1].resolve({ runId: "slow", store: "memory", logRef: "log-1", content: "", nextOffset: 1 })); + expect(value!.transcriptByRun.get("slow")).toEqual(expect.arrayContaining([expect.objectContaining({ chunk: "older output" })])); + const reads = logMock.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(logMock).toHaveBeenCalledTimes(reads); + } finally { await act(async () => root.unmount()); } + }); + + it("coalesces legacy terminal catch-up behind an in-flight read without aborting it", async () => { + let value: ReturnType; + function Harness() { + value = useLiveRunTranscripts({ companyId: "company-1", runs: [{ id: "run-1", status: "running", adapterType: "codex_local" }] }); + return null; + } + const root = createRoot(document.createElement("div")); + let finish!: (result: Awaited>) => void; + try { + await act(async () => root.render()); + logMock.mockImplementationOnce(() => new Promise(resolve => { finish = resolve; })); + await act(async () => negotiate()); + const reads = logMock.mock.calls.length; + const signal = logMock.mock.calls.at(-1)![3].signal; + await act(async () => { + for (let i = 0; i < 3; i++) sendEvent({ companyId: "company-1", type: "heartbeat.run.status", createdAt: "2026-10-24T00:00:00Z", + payload: { runId: "run-1", status: "succeeded" } }); + }); + expect(signal.aborted).toBe(false); + expect(logMock).toHaveBeenCalledTimes(reads); + logMock.mockResolvedValueOnce({ runId: "run-1", store: "memory", logRef: "log-1", content: + JSON.stringify({ seq: 1, ts: "2026-10-24T00:00:00Z", stream: "stdout", chunk: "terminal output" }) + "\n", nextOffset: 1 }); + await act(async () => finish({ runId: "run-1", store: "memory", logRef: "log-1", content: "", nextOffset: 0 })); + expect(logMock).toHaveBeenCalledTimes(reads + 2); + expect(value!.transcriptByRun.get("run-1")).toEqual(expect.arrayContaining([expect.objectContaining({ chunk: "terminal output" })])); + } finally { await act(async () => root.unmount()); } + }); + + it("keeps a legacy catch-up in flight through unrelated interest replacements", async () => { + vi.useFakeTimers(); + let value: ReturnType; + function Harness() { + value = useLiveRunTranscripts({ companyId: "company-1", runs: [{ id: "run-1", status: "running", adapterType: "codex_local" }] }); + return null; + } + const root = createRoot(document.createElement("div")); + let finish!: (result: Awaited>) => void; + try { + await act(async () => root.render()); + logMock.mockImplementationOnce(() => new Promise(resolve => { finish = resolve; })); + await act(async () => negotiate()); + const reads = logMock.mock.calls.length; + const signal = logMock.mock.calls.at(-1)![3].signal; + for (let index = 0; index < 4; index++) { + let release!: () => void; + await act(async () => { release = interests.acquire([`native-sibling-${index}`]); }); + expect(signal.aborted).toBe(false); + await act(async () => acknowledge()); + await act(async () => release()); + await act(async () => acknowledge()); + expect(signal.aborted).toBe(false); + expect(logMock).toHaveBeenCalledTimes(reads); + } + await act(async () => finish({ runId: "run-1", store: "memory", logRef: "log-1", content: + JSON.stringify({ seq: 1, ts: "2026-10-24T00:00:00Z", stream: "stdout", chunk: "uninterrupted legacy output" }) + "\n", nextOffset: 1 })); + expect(value!.transcriptByRun.get("run-1")).toEqual(expect.arrayContaining([expect.objectContaining({ chunk: "uninterrupted legacy output" })])); + const settled = logMock.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(logMock).toHaveBeenCalledTimes(settled); + } finally { await act(async () => root.unmount()); } + }); + + it("keeps HTTP polling until interest acknowledgement, then stops recurring reads", async () => { + vi.useFakeTimers(); + function Harness({ bytes = 0 }: { bytes?: number }) { + useLiveRunTranscripts({ companyId: "company-1", runs: [{ id: "run-1", status: "running", adapterType: "codex_local", lastOutputBytes: bytes }] }); + return null; + } + const root = createRoot(document.createElement("div")); + try { + await act(async () => root.render()); + await act(async () => vi.advanceTimersByTimeAsync(30_000)); + expect(logMock.mock.calls.length).toBeGreaterThan(1); + await act(async () => negotiate()); + const afterCatchup = logMock.mock.calls.length; + await act(async () => root.render()); + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(logMock).toHaveBeenCalledTimes(afterCatchup); + await act(async () => interests.close()); + const afterDisconnect = logMock.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(30_000)); + expect(logMock.mock.calls.length).toBeGreaterThan(afterDisconnect); + expect(socketConstructed).not.toHaveBeenCalled(); + } finally { await act(async () => root.unmount()); } + }); + + it("reads past a running run's stale byte count after hide/show without another live event", async () => { + vi.useFakeTimers(); + const visibility = vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + const line = (seq: number, chunk: string) => JSON.stringify({ seq, chunk, ts: "2026-10-26T00:00:00Z", stream: "stdout" }) + "\n"; + const segments = [line(1, "initial output")]; + const originalBytes = segments[0]!.length; + logMock.mockImplementation(async (_id, offset) => { + let cursor = 0; + for (const segment of segments) { + if (cursor === offset) return { runId: "run-1", store: "memory", logRef: "log-1", content: segment, nextOffset: offset + segment.length }; + cursor += segment.length; + } + return { runId: "run-1", store: "memory", logRef: "log-1", content: "", nextOffset: offset }; + }); + function Harness() { + useLiveRunTranscripts({ companyId: "company-1", runs: [{ id: "run-1", status: "running", adapterType: "codex_local", logBytes: originalBytes }] }); + return null; + } + const root = createRoot(document.createElement("div")); + try { + await act(async () => root.render()); + await act(async () => negotiate()); + await act(async () => { visibility.mockReturnValue("hidden"); document.dispatchEvent(new Event("visibilitychange")); }); + segments.push(line(2, "saved during disconnect"), line(3, "last saved page")); + await act(async () => { visibility.mockReturnValue("visible"); document.dispatchEvent(new Event("visibilitychange")); }); + await act(async () => acknowledge()); + const chunks = buildTranscriptMock.mock.calls.at(-1)?.[0]; + expect(chunks).toEqual([ + expect.objectContaining({ chunk: "initial output" }), + expect.objectContaining({ chunk: "saved during disconnect" }), + expect.objectContaining({ chunk: "last saved page" }), + ]); + const caughtUp = logMock.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(logMock).toHaveBeenCalledTimes(caughtUp); + } finally { await act(async () => root.unmount()); } + }); + + it("catches up after resynchronization, hide/show, and terminal status", async () => { + const visibility = vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + function Harness() { + useLiveRunTranscripts({ companyId: "company-1", runs: [{ id: "run-1", status: "running", adapterType: "codex_local" }] }); + return null; + } + const root = createRoot(document.createElement("div")); + try { + await act(async () => root.render()); + await act(async () => negotiate()); + const prior = logMock.mock.calls.length; + await act(async () => { interests.receive({ type: "live.resync", version: 1, revision: sent.at(-1)?.revision }); acknowledge(); }); + expect(logMock.mock.calls.length).toBeGreaterThan(prior); + await act(async () => { visibility.mockReturnValue("hidden"); document.dispatchEvent(new Event("visibilitychange")); }); + expect(sent.at(-1)?.runIds).toEqual([]); + const hiddenReads = logMock.mock.calls.length; + await act(async () => acknowledge()); + expect(logMock).toHaveBeenCalledTimes(hiddenReads); + await act(async () => { visibility.mockReturnValue("visible"); document.dispatchEvent(new Event("visibilitychange")); }); + await act(async () => acknowledge()); + expect(sent.at(-1)?.runIds).toEqual(["run-1"]); + expect(logMock.mock.calls.length).toBeGreaterThan(hiddenReads); + const beforeTerminal = logMock.mock.calls.length; + await act(async () => sendEvent({ companyId: "company-1", type: "heartbeat.run.status", createdAt: new Date().toISOString(), payload: { runId: "run-1", status: "succeeded" } })); + expect(logMock.mock.calls.length).toBeGreaterThan(beforeTerminal); + } finally { await act(async () => root.unmount()); } + }); +}); diff --git a/ui/src/components/transcript/useLiveRunTranscripts.test.tsx b/ui/src/components/transcript/useLiveRunTranscripts.test.tsx index 0636b1f6267..f69777b9cc3 100644 --- a/ui/src/components/transcript/useLiveRunTranscripts.test.tsx +++ b/ui/src/components/transcript/useLiveRunTranscripts.test.tsx @@ -1,7 +1,10 @@ // @vitest-environment jsdom -import { act } from "react"; -import { createRoot } from "react-dom/client"; +import { act, type ReactNode } from "react"; +import { createRoot as createReactRoot } from "react-dom/client"; +import type { LiveEvent } from "@paperclipai/shared"; +import { __liveUpdatesTestUtils, type CompanyLiveEventHandler } from "../../context/LiveUpdatesProvider"; +import { LiveTranscriptInterests } from "../../lib/live-transcript-interests"; import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; import { ApiError } from "../../api/client"; import { useLiveRunTranscripts } from "./useLiveRunTranscripts"; @@ -9,7 +12,8 @@ import { TRANSCRIPT_REQUEST_TIMEOUT_MS } from "./read-transcript-request"; const { useQueryMock, logMock, buildTranscriptMock } = vi.hoisted(() => ({ useQueryMock: vi.fn(() => ({ data: { censorUsernameInLogs: false } })), - logMock: vi.fn(async () => ({ runId: "run-1", store: "memory", logRef: "log-1", content: "", nextOffset: 0 })), + logMock: vi.fn(async (_runId: string, _offset: number, _limit: number, _options: { signal: AbortSignal }) => + ({ runId: "run-1", store: "memory", logRef: "log-1", content: "", nextOffset: 0 })), buildTranscriptMock: vi.fn((chunks: unknown[]) => chunks), })); @@ -35,40 +39,37 @@ vi.mock("../../adapters", () => ({ onAdapterChange: () => () => {}, })); -class FakeWebSocket { - static readonly CONNECTING = 0; - static readonly OPEN = 1; - static readonly CLOSING = 2; - static readonly CLOSED = 3; - static instances: FakeWebSocket[] = []; - - readonly url: string; - readyState = FakeWebSocket.CONNECTING; - onopen: ((event: Event) => void) | null = null; - onmessage: ((event: MessageEvent) => void) | null = null; - onerror: ((event: Event) => void) | null = null; - onclose: ((event: CloseEvent) => void) | null = null; - closeCalls: Array<{ code?: number; reason?: string }> = []; - - constructor(url: string) { - this.url = url; - FakeWebSocket.instances.push(this); - } - - close(code?: number, reason?: string) { - this.closeCalls.push({ code, reason }); - this.readyState = FakeWebSocket.CLOSING; - } - - triggerOpen() { - this.readyState = FakeWebSocket.OPEN; - this.onopen?.(new Event("open")); - } - - triggerClose() { - this.readyState = FakeWebSocket.CLOSED; - this.onclose?.(new CloseEvent("close")); - } +const { LiveEventSubscriptionContext } = __liveUpdatesTestUtils; +let listeners: Set; +let interests: LiveTranscriptInterests; +let sent: Array<{ type: string; revision?: number; runIds?: string[] }>; +let socketConstructed: ReturnType void>>; +function createRoot(container: HTMLDivElement) { + const root = createReactRoot(container); + const subscription = { + companyId: "company-1", transcripts: interests, + subscribe(handler: CompanyLiveEventHandler) { + listeners.add(handler); + return () => { listeners.delete(handler); }; + }, + }; + return { + unmount: () => root.unmount(), + render: (children: ReactNode) => root.render( + {children}, + ), + }; +} +function sendEvent(event: Omit) { + for (const listener of listeners) listener({ ...event, id: 1 }); +} +function negotiate() { + interests.open({ send: data => sent.push(JSON.parse(data)) }); + interests.receive({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + acknowledge(); +} +function acknowledge() { + interests.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1)?.revision }); } // eslint-disable-next-line @typescript-eslint/no-explicit-any @@ -79,12 +80,13 @@ describe("useLiveRunTranscripts", () => { beforeEach(() => { vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); - FakeWebSocket.instances = []; + listeners = new Set(); interests = new LiveTranscriptInterests(); sent = []; + socketConstructed = vi.fn(); useQueryMock.mockClear(); logMock.mockReset(); - logMock.mockImplementation(async () => ({ runId: "run-1", store: "memory", logRef: "log-1", content: "", nextOffset: 0 })); + logMock.mockImplementation(async (_id, offset) => ({ runId: "run-1", store: "memory", logRef: "log-1", content: "", nextOffset: offset })); buildTranscriptMock.mockClear(); - globalThis.WebSocket = FakeWebSocket as unknown as typeof WebSocket; + globalThis.WebSocket = class { constructor() { socketConstructed(); } } as unknown as typeof WebSocket; }); afterEach(() => { @@ -108,7 +110,7 @@ describe("useLiveRunTranscripts", () => { await act(async () => root.render()); await act(async () => vi.advanceTimersByTimeAsync(10_000)); expect(logMock).not.toHaveBeenCalled(); - expect(FakeWebSocket.instances).toHaveLength(0); + expect(socketConstructed).not.toHaveBeenCalled(); await act(async () => { visibility.mockReturnValue("visible"); document.dispatchEvent(new Event("visibilitychange")); @@ -136,6 +138,7 @@ describe("useLiveRunTranscripts", () => { const result = (content: string) => ({ runId: "run-1", store: "memory", logRef: "log-1", content, nextOffset: 100_000 }); let resolveExpanded!: (value: ReturnType) => void; logMock.mockResolvedValueOnce(result(`${row(2, "Latest answer")}\n`)); + logMock.mockResolvedValueOnce(result("")); logMock.mockImplementationOnce(() => new Promise(resolve => { resolveExpanded = resolve; })); function Harness({ limit, bytes = 100_000 }: { limit: number; bytes?: number }) { ({ truncatedRunIds } = useLiveRunTranscripts({ @@ -149,7 +152,7 @@ describe("useLiveRunTranscripts", () => { const chunks = () => buildTranscriptMock.mock.calls.at(-1)?.[0]; try { await act(async () => root.render()); - expect(logMock).toHaveBeenLastCalledWith("run-1", 68_000, 32_000, expect.objectContaining({ alignStartToRecord: true })); + expect(logMock).toHaveBeenNthCalledWith(1, "run-1", 68_000, 32_000, expect.objectContaining({ alignStartToRecord: true })); expect(truncatedRunIds.has("run-1")).toBe(true); expect(chunks()).toEqual([expect.objectContaining({ chunk: "Latest answer" })]); await act(async () => root.render()); @@ -173,7 +176,9 @@ describe("useLiveRunTranscripts", () => { const row = (seq: number) => `${JSON.stringify({ seq, chunk: `Output ${seq}`, stream: "stdout", ts: "2026-10-24T00:00:00Z" })}\n`; const response = { runId: "run-1", store: "memory", logRef: "log-1" }; logMock.mockResolvedValueOnce({ ...response, content: row(1), nextOffset: 100 }); + logMock.mockResolvedValueOnce({ ...response, content: "", nextOffset: 100 }); logMock.mockResolvedValueOnce({ ...response, content: row(2), nextOffset: 100_000 }); + logMock.mockResolvedValueOnce({ ...response, content: "", nextOffset: 100_000 }); function Harness({ bytes }: { bytes: number }) { ({ truncatedRunIds } = useLiveRunTranscripts({ runs: [{ id: "run-1", status: "succeeded", adapterType: "codex_local", logBytes: bytes }], @@ -184,10 +189,10 @@ describe("useLiveRunTranscripts", () => { const root = createRoot(document.createElement("div")); try { await act(async () => root.render()); - expect(logMock).toHaveBeenLastCalledWith("run-1", 0, 32_000, expect.anything()); + expect(logMock).toHaveBeenNthCalledWith(1, "run-1", 0, 32_000, expect.anything()); expect(truncatedRunIds.has("run-1")).toBe(false); await act(async () => root.render()); - expect(logMock).toHaveBeenLastCalledWith("run-1", 100, 32_000, expect.anything()); + expect(logMock).toHaveBeenNthCalledWith(3, "run-1", 100, 32_000, expect.anything()); expect(truncatedRunIds.has("run-1")).toBe(false); } finally { await act(async () => root.unmount()); } }); @@ -198,6 +203,7 @@ describe("useLiveRunTranscripts", () => { const earlier = row(1, "Earlier activity"); const recent = row(2, "Latest answer"); logMock.mockResolvedValueOnce(result(`${recent}\n`)); + logMock.mockResolvedValueOnce(result("")); logMock.mockRejectedValueOnce(new Error("Temporary storage failure")); logMock.mockImplementationOnce(async (...args: unknown[]) => { const options = args[3] as { alignStartToRecord?: boolean }; @@ -224,7 +230,7 @@ describe("useLiveRunTranscripts", () => { expect.objectContaining({ chunk: "Earlier activity" }), expect.objectContaining({ chunk: "Latest answer" }), ]); - expect(logMock).toHaveBeenLastCalledWith("run-1", 244_000, 256_000, expect.objectContaining({ alignStartToRecord: true })); + expect(logMock).toHaveBeenCalledWith("run-1", 244_000, 256_000, expect.objectContaining({ alignStartToRecord: true })); expect(latest.errorsByRun.size).toBe(0); await act(async () => root.render()); expect(logMock).toHaveBeenLastCalledWith("run-1", 500_000, 256_000, expect.not.objectContaining({ alignStartToRecord: true })); @@ -233,40 +239,19 @@ describe("useLiveRunTranscripts", () => { } }); - it("waits for a connecting socket to open before closing it during cleanup", async () => { + it("registers interests on the shared connection without creating a socket", async () => { function Harness() { - useLiveRunTranscripts({ - companyId: "company-1", - runs: [{ id: "run-1", status: "running", adapterType: "codex_local" }], - }); + useLiveRunTranscripts({ companyId: "company-1", runs: [{ id: "run-1", status: "running", adapterType: "codex_local" }] }); return null; } - - const container = document.createElement("div"); - document.body.appendChild(container); - const root = createRoot(container); - - await act(async () => { - root.render(); - await Promise.resolve(); - }); - - expect(FakeWebSocket.instances).toHaveLength(1); - const socket = FakeWebSocket.instances[0]; - expect(socket.closeCalls).toHaveLength(0); - - act(() => { - root.unmount(); - }); - - expect(socket.closeCalls).toHaveLength(0); - - act(() => { - socket.triggerOpen(); - }); - - expect(socket.closeCalls).toEqual([{ code: 1000, reason: "live_run_transcripts_unmount" }]); - container.remove(); + const root = createRoot(document.createElement("div")); + await act(async () => root.render()); + await act(async () => negotiate()); + expect(sent.at(-1)?.runIds).toEqual(["run-1"]); + expect(socketConstructed).not.toHaveBeenCalled(); + await act(async () => root.unmount()); + expect(sent.at(-1)?.runIds).toEqual([]); + expect(listeners.size).toBe(0); }); it("treats stored run output as available before transcript chunks finish loading", async () => { @@ -427,7 +412,7 @@ describe("useLiveRunTranscripts", () => { }); expect(logMock).not.toHaveBeenCalled(); - expect(FakeWebSocket.instances).toHaveLength(0); + expect(socketConstructed).not.toHaveBeenCalled(); await act(async () => { root.render(); @@ -436,7 +421,7 @@ describe("useLiveRunTranscripts", () => { expect(logMock).toHaveBeenCalledTimes(1); expect(logMock).toHaveBeenCalledWith("run-queued", 0, 256_000, expect.objectContaining({ signal: expect.any(AbortSignal) })); - expect(FakeWebSocket.instances).toHaveLength(1); + expect(socketConstructed).not.toHaveBeenCalled(); act(() => { root.unmount(); @@ -464,7 +449,7 @@ describe("useLiveRunTranscripts", () => { await Promise.resolve(); }); - expect(FakeWebSocket.instances).toHaveLength(0); + expect(socketConstructed).not.toHaveBeenCalled(); expect(logMock).toHaveBeenCalledWith("run-1", 0, 64_000, expect.objectContaining({ signal: expect.any(AbortSignal) })); act(() => { @@ -617,26 +602,13 @@ describe("useLiveRunTranscripts", () => { await Promise.resolve(); }); - expect(FakeWebSocket.instances).toHaveLength(1); - const socket = FakeWebSocket.instances[0]!; + expect(socketConstructed).not.toHaveBeenCalled(); const sendLogEvent = (seq: number, chunk: string) => { - socket.onmessage?.( - new MessageEvent("message", { - data: JSON.stringify({ - companyId: "company-1", - type: "heartbeat.run.log", - createdAt: "2026-04-20T00:00:01.000Z", - payload: { - runId: "run-1", - ts: "2026-04-20T00:00:01.000Z", - stream: "stdout", - chunk, - seq, - }, - }), - }), - ); + sendEvent({ + companyId: "company-1", type: "heartbeat.run.log", createdAt: "2026-04-20T00:00:01.000Z", + payload: { runId: "run-1", ts: "2026-04-20T00:00:01.000Z", stream: "stdout", chunk, seq }, + }); }; // The websocket races ahead of the poller and its seq-2 chunk arrives @@ -695,26 +667,15 @@ describe("useLiveRunTranscripts", () => { await Promise.resolve(); }); - expect(FakeWebSocket.instances).toHaveLength(1); + expect(socketConstructed).not.toHaveBeenCalled(); expect(buildTranscriptMock).toHaveBeenCalledTimes(2); buildTranscriptMock.mockClear(); await act(async () => { - FakeWebSocket.instances[0]!.onmessage?.( - new MessageEvent("message", { - data: JSON.stringify({ - companyId: "company-1", - type: "heartbeat.run.log", - createdAt: "2026-04-20T00:00:00.000Z", - payload: { - runId: "run-1", - ts: "2026-04-20T00:00:00.000Z", - stream: "stdout", - chunk: "hello from run 1\n", - }, - }), - }), - ); + sendEvent({ + companyId: "company-1", type: "heartbeat.run.log", createdAt: "2026-04-20T00:00:00.000Z", + payload: { runId: "run-1", ts: "2026-04-20T00:00:00.000Z", stream: "stdout", chunk: "hello from run 1\n" }, + }); await Promise.resolve(); }); @@ -839,121 +800,4 @@ describe("useLiveRunTranscripts", () => { } }); - it("keeps HTTP log polling when the socket constructor fails and retries later", async () => { - vi.useFakeTimers(); - globalThis.WebSocket = class { - constructor() { throw new TypeError("WebSocket is not a constructor"); } - } as unknown as typeof WebSocket; - const runs = [{ id: "run-1", status: "running", adapterType: "codex_local" }]; - function Harness() { - useLiveRunTranscripts({ companyId: "company-1", runs }); - return null; - } - const root = createRoot(document.createElement("div")); - try { - await act(async () => root.render()); - expect(logMock).toHaveBeenCalledTimes(1); - await act(async () => vi.advanceTimersByTimeAsync(30_000)); - expect(logMock.mock.calls.length).toBeGreaterThan(1); - globalThis.WebSocket = FakeWebSocket as unknown as typeof WebSocket; - await act(async () => vi.advanceTimersByTimeAsync(15_000)); - expect(FakeWebSocket.instances).toHaveLength(1); - await act(async () => FakeWebSocket.instances[0].triggerOpen()); - // Cleanup must not depend on the global constructor remaining available. - globalThis.WebSocket = undefined as unknown as typeof WebSocket; - } finally { - await act(async () => root.unmount()); - } - const calls = logMock.mock.calls.length; - await act(async () => vi.advanceTimersByTimeAsync(30_000)); - expect(logMock).toHaveBeenCalledTimes(calls); - expect(FakeWebSocket.instances[0].closeCalls).toHaveLength(1); - }); - - it("backs off exponentially when the live event socket keeps failing", async () => { - vi.useFakeTimers(); - try { - function Harness({ lastOutputBytes }: { lastOutputBytes?: number }) { - useLiveRunTranscripts({ - companyId: "company-1", - runs: [{ id: "run-1", status: "running", adapterType: "codex_local", lastOutputBytes }], - }); - return null; - } - - const container = document.createElement("div"); - document.body.appendChild(container); - const root = createRoot(container); - - await act(async () => { - root.render(); - await Promise.resolve(); - }); - expect(FakeWebSocket.instances).toHaveLength(1); - - // Cold backend: every handshake fails. Delays must grow 1.5s → 3s → 6s - // instead of hammering a flat interval. - await act(async () => { - FakeWebSocket.instances[0].triggerClose(); - await vi.advanceTimersByTimeAsync(1_499); - }); - expect(FakeWebSocket.instances).toHaveLength(1); - await act(async () => { - await vi.advanceTimersByTimeAsync(1); - }); - expect(FakeWebSocket.instances).toHaveLength(2); - - await act(async () => { - FakeWebSocket.instances[1].triggerClose(); - await vi.advanceTimersByTimeAsync(2_999); - }); - expect(FakeWebSocket.instances).toHaveLength(2); - await act(async () => { - await vi.advanceTimersByTimeAsync(1); - }); - expect(FakeWebSocket.instances).toHaveLength(3); - - await act(async () => { - FakeWebSocket.instances[2].triggerClose(); - await vi.advanceTimersByTimeAsync(5_999); - }); - expect(FakeWebSocket.instances).toHaveLength(3); - await act(async () => { - await vi.advanceTimersByTimeAsync(1); - }); - expect(FakeWebSocket.instances).toHaveLength(4); - - // Run-metadata changes restart the socket effect; the progressed delay - // must survive the restart instead of resetting to the base delay. - await act(async () => { - root.render(); - await Promise.resolve(); - }); - expect(FakeWebSocket.instances).toHaveLength(5); - await act(async () => { - FakeWebSocket.instances[4].triggerClose(); - await vi.advanceTimersByTimeAsync(11_999); - }); - expect(FakeWebSocket.instances).toHaveLength(5); - await act(async () => { - await vi.advanceTimersByTimeAsync(1); - }); - expect(FakeWebSocket.instances).toHaveLength(6); - - // A successful connection resets the backoff to the base delay. - await act(async () => { - FakeWebSocket.instances[5].triggerOpen(); - FakeWebSocket.instances[5].triggerClose(); - await vi.advanceTimersByTimeAsync(1_500); - }); - expect(FakeWebSocket.instances).toHaveLength(7); - - act(() => { - root.unmount(); - }); - container.remove(); - } finally { - vi.useRealTimers(); - } - }); }); diff --git a/ui/src/components/transcript/useLiveRunTranscripts.ts b/ui/src/components/transcript/useLiveRunTranscripts.ts index 134e88e766d..b5a46263c12 100644 --- a/ui/src/components/transcript/useLiveRunTranscripts.ts +++ b/ui/src/components/transcript/useLiveRunTranscripts.ts @@ -1,3 +1,5 @@ +import { TranscriptSequence } from "../../lib/transcript-sequence"; +import { useTranscriptLiveStream } from "../../context/LiveUpdatesProvider"; import { usePageVisibility } from "../../lib/page-visibility"; import { useCallback, useEffect, useMemo, useRef, useState } from "react"; import { readTranscriptRequest } from "./read-transcript-request"; @@ -8,8 +10,6 @@ import { instanceSettingsApi } from "../../api/instanceSettings"; import { heartbeatsApi } from "../../api/heartbeats"; import { buildTranscript, getUIAdapter, onAdapterChange, type RunLogChunk, type TranscriptEntry } from "../../adapters"; import { queryKeys } from "../../lib/queryKeys"; -import { buildSameOriginWebSocketUrl } from "../../lib/websocket-url"; -import { tryCreateWebSocket } from "../../lib/websocket"; import { mergeRunLogChunks, parsePersistedLogContent, @@ -17,17 +17,8 @@ import { type ChunkRetentionBudget, } from "../../lib/run-log-chunks"; -// TODO(perf): this whole hook polls the log/runs endpoints on an interval. The -// durable fix is server push (SSE/websocket) for transcript deltas so idle tabs -// do no periodic work at all; the constants below only reduce the churn of the -// current polling approach. -const SOCKET_CONNECTING = 0; -const SOCKET_OPEN = 1; const LOG_POLL_INTERVAL_MS = 2000; const LOG_READ_LIMIT_BYTES = 256_000; -// When realtime websocket updates are enabled, the frequent log poll is -// redundant with the live stream; keep only a slow safety-net poll to cover -// gaps and reconnects instead of polling every couple of seconds. const REALTIME_FALLBACK_POLL_INTERVAL_MS = 30_000; const EMPTY_RUN_LOG_CHUNKS: RunLogChunk[] = []; // Retained transcript payload budget for full task views. A byte budget (rather @@ -54,6 +45,7 @@ export interface RunTranscriptSource { hasStoredOutput?: boolean; logBytes?: number | null; lastOutputBytes?: number | null; + logRef?: string | null; } interface UseLiveRunTranscriptsOptions { @@ -69,6 +61,7 @@ interface UseLiveRunTranscriptsOptions { logPollIntervalMs?: number; logReadLimitBytes?: number; enableRealtimeUpdates?: boolean; + enabled?: boolean; } function readString(value: unknown): string | null { @@ -104,6 +97,7 @@ export function useLiveRunTranscripts({ logPollIntervalMs = LOG_POLL_INTERVAL_MS, logReadLimitBytes = LOG_READ_LIMIT_BYTES, enableRealtimeUpdates = true, + enabled = true, }: UseLiveRunTranscriptsOptions) { // Ticker consumers opt into the silent chunk-count cap; full task views use a // byte budget that collapses (not discards) the oldest output when exceeded. @@ -119,9 +113,9 @@ export function useLiveRunTranscripts({ () => runs .map((run) => { - const logBytes = typeof run.logBytes === "number" ? run.logBytes : ""; - const lastOutputBytes = typeof run.lastOutputBytes === "number" ? run.lastOutputBytes : ""; - return `${run.id}:${run.status}:${run.adapterType}:${run.hasStoredOutput === true ? "1" : "0"}:${logBytes}:${lastOutputBytes}`; + const logBytes = isTerminalStatus(run.status) && typeof run.logBytes === "number" ? run.logBytes : ""; + const lastOutputBytes = isTerminalStatus(run.status) && typeof run.lastOutputBytes === "number" ? run.lastOutputBytes : ""; + return `${run.id}:${run.status}:${run.adapterType}:${run.hasStoredOutput === true ? "1" : "0"}:${logBytes}:${lastOutputBytes}:${run.logRef ?? ""}`; }) .sort((a, b) => a.localeCompare(b)) .join(","), @@ -144,6 +138,45 @@ export function useLiveRunTranscripts({ const pendingLogRowsByRunRef = useRef(new Map()); const logOffsetByRunRef = useRef(new Map()); const logReadLimitByRunRef = useRef(new Map()); + const logIdentityRef = useRef(new Map()); + const retiredLogIdentitiesRef = useRef(new Map>()); + const sequencesRef = useRef(new Map()); + const sequence = (id: string) => { + let value = sequencesRef.current.get(id); + if (!value) { value = new TranscriptSequence(); sequencesRef.current.set(id, value); } + return value; + }; + const gapPendingRef = useRef(new Set()); + const refreshByRunRef = useRef(new Map void>()); + const requestCatchUp = (runId: string) => { + if (gapPendingRef.current.has(runId)) return; + gapPendingRef.current.add(runId); + refreshByRunRef.current.get(runId)?.(); + }; + const bindLog = (runId: string, store: unknown, ref: unknown): "same" | "changed" | "stale" => { + if (typeof ref !== "string" || !ref) return "same"; + const identity = `${typeof store === "string" ? store : ""}:${ref}`; + const prior = logIdentityRef.current.get(runId); + if (prior === identity) return "same"; + if (retiredLogIdentitiesRef.current.get(runId)?.has(identity)) return "stale"; + logIdentityRef.current.set(runId, identity); + if (!prior) return "same"; + const retired = retiredLogIdentitiesRef.current.get(runId) ?? new Set(); + retired.add(prior); + if (retired.size > 8) retired.delete(retired.values().next().value!); + retiredLogIdentitiesRef.current.set(runId, retired); + logOffsetByRunRef.current.set(runId, 0); logReadLimitByRunRef.current.delete(runId); + pendingLogRowsByRunRef.current.delete(runId); pendingLogRowsByRunRef.current.delete(`${runId}:records`); + trimmedSeqFloorByRunRef.current.delete(runId); sequencesRef.current.delete(runId); + for (const key of seenChunkKeysRef.current) if (key.includes(`:${runId}:`)) seenChunkKeysRef.current.delete(key); + setChunksByRun(previous => new Map(previous).set(runId, [])); + setTruncatedRunIds(previous => { + if (!previous.has(runId)) return previous; + const next = new Set(previous); next.delete(runId); return next; + }); + return "changed"; + }; + const [truncatedRunIds, setTruncatedRunIds] = useState>(new Set()); const missingTerminalLogRunIdsRef = useRef(new Set()); // PAP-462 B3: buffered runs that dropped out of the `runs` list, mapped to the @@ -152,10 +185,6 @@ export function useLiveRunTranscripts({ // the effect again once the nearest deadline elapses so a run that stays gone // is eventually cleaned up even if the `runs` list never changes again. const absenceDeadlineByRunRef = useRef(new Map()); - // Backoff state for the live event socket. Held outside the socket effect - // because that effect restarts on run-metadata changes; per-effect state - // would reset a progressed delay back to its base mid-outage. - const reconnectStateRef = useRef<{ companyId: string; attempt: number } | null>(null); const prevKnownRunIdsRef = useRef(new Set()); const [pruneTick, setPruneTick] = useState(0); const transcriptCacheRef = useRef(new Map()); + const previousCompanyRef = useRef(companyId); + useEffect(() => { + if (previousCompanyRef.current === companyId) return; + previousCompanyRef.current = companyId; + setChunksByRun(new Map()); setHydratedRunIds(new Set()); setErrorsByRun(new Map()); + seenChunkKeysRef.current.clear(); trimmedSeqFloorByRunRef.current.clear(); + pendingLogRowsByRunRef.current.clear(); logOffsetByRunRef.current.clear(); logReadLimitByRunRef.current.clear(); + logIdentityRef.current.clear(); retiredLogIdentitiesRef.current.clear(); sequencesRef.current.clear(); + gapPendingRef.current.clear(); missingTerminalLogRunIdsRef.current.clear(); + absenceDeadlineByRunRef.current.clear(); prevKnownRunIdsRef.current.clear(); transcriptCacheRef.current.clear(); + }, [companyId]); + // Tick counter to force transcript recomputation when dynamic parser loads const [parserTick, setParserTick] = useState(0); useEffect(() => { @@ -294,6 +335,11 @@ export function useLiveRunTranscripts({ } } + for (const map of [logIdentityRef.current, retiredLogIdentitiesRef.current, sequencesRef.current]) { + for (const id of map.keys()) if (!retainedRunIds.has(id)) map.delete(id); + } + for (const id of gapPendingRef.current) if (!retainedRunIds.has(id)) gapPendingRef.current.delete(id); + // Re-run once the nearest grace window elapses so a run that stays gone is // pruned even if `normalizedRuns` never changes again. if (soonestExpiryMs !== Number.POSITIVE_INFINITY) { @@ -305,193 +351,21 @@ export function useLiveRunTranscripts({ } }, [normalizedRuns, pruneTick]); - useEffect(() => { - if (!visible) return; - const readableRuns = normalizedRuns.filter(canReadPersistedLog); - if (readableRuns.length === 0) return; - - let cancelled = false; - const controller = new AbortController(); - const inFlightRunIds = new Set(); - - const readRunLog = async (run: RunTranscriptSource) => { - if (missingTerminalLogRunIdsRef.current.has(run.id) || inFlightRunIds.has(run.id)) { - return; - } - inFlightRunIds.add(run.id); - let alignStartToRecord = !logOffsetByRunRef.current.has(run.id); - let offset = logOffsetByRunRef.current.get(run.id) ?? resolveInitialLogOffset(run, logReadLimitBytes); - let rewinding = false; - const previousReadLimit = logReadLimitByRunRef.current.get(run.id); - if (previousReadLimit !== undefined && logReadLimitBytes > previousReadLimit) { - // Expanding a compact tail must reread the earlier range. Retain the - // visible chunks; merging by sequence deduplicates the overlapping tail. - const expandedOffset = resolveInitialLogOffset(run, logReadLimitBytes); - if (expandedOffset < offset) { - alignStartToRecord = true; - offset = expandedOffset; - rewinding = true; - } - } - try { - const result = await readTranscriptRequest( - (signal) => heartbeatsApi.log(run.id, offset, logReadLimitBytes, { - signal, - ...(alignStartToRecord && offset > 0 ? { alignStartToRecord: true } : {}), - }), - controller.signal, - ); - if (cancelled) return; - - // Commit the expanded window only after success so retries still align - // its first record and failed reads leave the previous parser intact. - if (previousReadLimit === undefined || rewinding) { - setTruncatedRunIds((previous) => { - if (previous.has(run.id) === (offset > 0)) return previous; - const next = new Set(previous); - if (offset > 0) next.add(run.id); - else next.delete(run.id); - return next; - }); - } - logReadLimitByRunRef.current.set(run.id, logReadLimitBytes); - if (rewinding) { - pendingLogRowsByRunRef.current.delete(run.id); - pendingLogRowsByRunRef.current.delete(`${run.id}:records`); - } - setErrorsByRun((previous) => { - if (!previous.has(run.id)) return previous; - const next = new Map(previous); - next.delete(run.id); - return next; - }); - appendChunks(run.id, parsePersistedLogContent(run.id, result.content, pendingLogRowsByRunRef.current)); - - if (result.nextOffset !== undefined) { - logOffsetByRunRef.current.set(run.id, result.nextOffset); - return; - } - if (result.content.length > 0) { - logOffsetByRunRef.current.set(run.id, offset + result.content.length); - } - } catch (error) { - if (cancelled) return; - if (error instanceof ApiError && error.status === 404) { - setErrorsByRun((previous) => { - if (!previous.has(run.id)) return previous; - const next = new Map(previous); - next.delete(run.id); - return next; - }); - // A newly started run may not have created its log yet. - if (isTerminalStatus(run.status)) missingTerminalLogRunIdsRef.current.add(run.id); - } else { - setErrorsByRun((previous) => { - if (previous.has(run.id)) return previous; - const next = new Map(previous); - next.set(run.id, error instanceof Error ? error : new Error("Run history could not be loaded")); - return next; - }); - } - } finally { - inFlightRunIds.delete(run.id); - if (!cancelled) { - setHydratedRunIds((prev) => { - if (prev.has(run.id)) return prev; - const next = new Set(prev); - next.add(run.id); - return next; - }); - } - } - }; - - const readAll = async () => { - await Promise.all(readableRuns.map((run) => readRunLog(run))); - }; - - void readAll(); - const activeRuns = readableRuns.filter((run) => run.status === "running"); - // The realtime websocket is the primary live source when enabled, so the - // recurring poll only needs to run as a slow fallback rather than doubling - // the live update work every couple of seconds. - const effectivePollMs = enableRealtimeUpdates - ? Math.max(logPollIntervalMs, REALTIME_FALLBACK_POLL_INTERVAL_MS) - : logPollIntervalMs; - const interval = activeRuns.length > 0 && effectivePollMs > 0 - ? window.setInterval(() => { - void Promise.all(activeRuns.map((run) => readRunLog(run))); - }, effectivePollMs) - : null; - - return () => { - cancelled = true; - controller.abort(); - if (interval !== null) window.clearInterval(interval); - }; - }, [visible, enableRealtimeUpdates, logPollIntervalMs, logReadLimitBytes, normalizedRuns, runIdsKey, retryGeneration]); - - useEffect(() => { - if (!visible || !enableRealtimeUpdates) return; - if (!companyId || activeRunIds.size === 0) return; - - let closed = false; - let reconnectTimer: number | null = null; - let socket: WebSocket | null = null; - - // The attempt counter lives in a ref keyed to the company: this effect - // restarts whenever run metadata changes, and a per-effect counter would - // reset the backoff to its base delay mid-outage on every such restart. - if (reconnectStateRef.current?.companyId !== companyId) { - reconnectStateRef.current = { companyId, attempt: 0 }; - } - const reconnectState = reconnectStateRef.current; - - // Exponential backoff (1.5s → 15s cap), mirroring LiveUpdatesProvider. - // A flat retry hammers a backend that is still cold-starting — every - // failed handshake immediately queues the next one, so a stack that - // takes a minute to come up sees a steady stream of doomed connections. - const scheduleReconnect = () => { - if (closed) return; - reconnectState.attempt += 1; - const delayMs = Math.min(15_000, 1_500 * 2 ** Math.min(reconnectState.attempt - 1, 4)); - reconnectTimer = window.setTimeout(connect, delayMs); - }; - - const connect = () => { - if (closed) return; - const url = buildSameOriginWebSocketUrl( - `/api/companies/${encodeURIComponent(companyId)}/events/ws`, - ); - socket = tryCreateWebSocket(url); - if (!socket) { - scheduleReconnect(); - return; - } - - socket.onopen = () => { - if (closed) return; - reconnectState.attempt = 0; - }; - - socket.onmessage = (message) => { - const raw = typeof message.data === "string" ? message.data : ""; - if (!raw) return; - - let event: LiveEvent; - try { - event = JSON.parse(raw) as LiveEvent; - } catch { - return; - } - + const stream = useTranscriptLiveStream([...activeRunIds], { companyId, enabled: enabled && enableRealtimeUpdates }, event => { if (event.companyId !== companyId) return; const payload = event.payload ?? {}; const runId = readString(payload["runId"]); - if (!runId || !activeRunIds.has(runId)) return; + if (!runId) return; if (!runById.has(runId)) return; if (event.type === "heartbeat.run.log") { + const binding = bindLog(runId, payload.logStore, payload.logRef); + if (binding === "stale") return; + const seq = readChunkSeq(payload.seq); + if (payload.truncated === true) sequence(runId).requireHistory(seq); + const gap = sequence(runId).observe(seq); + if (binding === "changed" || payload.truncated === true || gap) requestCatchUp(runId); + if (payload.truncated === true) return; const chunk = readString(payload["chunk"]); if (!chunk) return; const ts = readString(payload["ts"]) ?? event.createdAt; @@ -526,6 +400,7 @@ export function useLiveRunTranscripts({ if (event.type === "heartbeat.run.status") { const status = readString(payload["status"]) ?? "updated"; + if (isTerminalStatus(status)) refreshByRunRef.current.get(runId)?.(true); appendChunks(runId, [{ ts: event.createdAt, stream: isTerminalStatus(status) && status !== "succeeded" ? "stderr" : "system", @@ -533,39 +408,154 @@ export function useLiveRunTranscripts({ dedupeKey: `socket:status:${runId}:${status}:${readString(payload["finishedAt"]) ?? ""}`, }]); } - }; + }); - socket.onerror = () => { - socket?.close(); - }; + useEffect(() => { + if (!visible || !enabled) return; + const readableRuns = normalizedRuns.filter(canReadPersistedLog); + if (readableRuns.length === 0) return; - socket.onclose = () => { - scheduleReconnect(); - }; - }; + let cancelled = false; + const controller = new AbortController(); + const inFlightRunIds = new Set(); + const retryTimers = new Map(); + const pendingRefresh = new Set(); - connect(); - - return () => { - closed = true; - if (reconnectTimer !== null) window.clearTimeout(reconnectTimer); - if (socket) { - socket.onmessage = null; - socket.onerror = null; - socket.onclose = null; - if (socket.readyState === SOCKET_CONNECTING) { - // Defer the close until the handshake completes so the browser - // does not emit a noisy "closed before the connection is established" - // warning during rapid run teardown. - socket.onopen = () => { - socket?.close(1000, "live_run_transcripts_unmount"); - }; - } else if (socket.readyState === SOCKET_OPEN) { - socket.close(1000, "live_run_transcripts_unmount"); + const readRunLog = async (run: RunTranscriptSource) => { + if (cancelled || missingTerminalLogRunIdsRef.current.has(run.id) || inFlightRunIds.has(run.id)) { + return; + } + pendingRefresh.delete(run.id); + window.clearTimeout(retryTimers.get(run.id)); + retryTimers.delete(run.id); + inFlightRunIds.add(run.id); + let failed = false; + let alignStartToRecord = !logOffsetByRunRef.current.has(run.id); + let offset = logOffsetByRunRef.current.get(run.id) ?? resolveInitialLogOffset(run, logReadLimitBytes); + let rewinding = false; + const previousReadLimit = logReadLimitByRunRef.current.get(run.id); + if (previousReadLimit !== undefined && logReadLimitBytes > previousReadLimit) { + const expandedOffset = resolveInitialLogOffset(run, logReadLimitBytes); + if (expandedOffset < offset) { + alignStartToRecord = true; + offset = expandedOffset; + rewinding = true; + } + } + let recordInitialWindow = previousReadLimit === undefined || rewinding; + try { + for (;;) { + const result = await readTranscriptRequest( + (signal) => heartbeatsApi.log(run.id, offset, logReadLimitBytes, { + signal, + ...(alignStartToRecord && offset > 0 ? { alignStartToRecord: true } : {}), + }), controller.signal, + ); + if (cancelled) return; + const binding = bindLog(run.id, result.store, result.logRef); + if (binding === "stale") { failed = true; return; } + if (binding === "changed" && offset !== 0) { offset = 0; continue; } + if (recordInitialWindow || binding === "changed") { + const windowIsTruncated = offset > 0; + setTruncatedRunIds(previous => { + if (previous.has(run.id) === windowIsTruncated) return previous; + const next = new Set(previous); + if (windowIsTruncated) next.add(run.id); + else next.delete(run.id); + return next; + }); + recordInitialWindow = false; + } + logReadLimitByRunRef.current.set(run.id, logReadLimitBytes); + if (rewinding) { + pendingLogRowsByRunRef.current.delete(run.id); + pendingLogRowsByRunRef.current.delete(`${run.id}:records`); + rewinding = false; + } + alignStartToRecord = false; + setErrorsByRun(previous => { + if (!previous.has(run.id)) return previous; + const next = new Map(previous); next.delete(run.id); return next; + }); + const rows = parsePersistedLogContent(run.id, result.content, pendingLogRowsByRunRef.current); + appendChunks(run.id, rows); + for (const row of rows) sequence(run.id).confirm(row.seq); + const next = result.nextOffset ?? offset + new TextEncoder().encode(result.content).byteLength; + logOffsetByRunRef.current.set(run.id, next); + if (result.nextOffset === undefined || result.content.length === 0 || next <= offset) break; + offset = next; + } + failed = sequence(run.id).needsCatchup; + if (!failed) gapPendingRef.current.delete(run.id); + } catch (error) { + if (cancelled) return; + failed = true; + if (error instanceof ApiError && error.status === 404) { + setErrorsByRun((previous) => { + if (!previous.has(run.id)) return previous; + const next = new Map(previous); + next.delete(run.id); + return next; + }); + // A newly started run may not have created its log yet. + if (isTerminalStatus(run.status)) { missingTerminalLogRunIdsRef.current.add(run.id); failed = false; } + } else { + setErrorsByRun((previous) => { + if (previous.has(run.id)) return previous; + const next = new Map(previous); + next.set(run.id, error instanceof Error ? error : new Error("Run history could not be loaded")); + return next; + }); + } + } finally { + inFlightRunIds.delete(run.id); + if (!cancelled) { + if (pendingRefresh.has(run.id)) { + missingTerminalLogRunIdsRef.current.delete(run.id); + void readRunLog(run); + } else if (failed && stream.healthy) { + const timer = window.setTimeout(() => { retryTimers.delete(run.id); void readRunLog(run); }, LOG_POLL_INTERVAL_MS); + retryTimers.set(run.id, timer); + } + setHydratedRunIds((prev) => { + if (prev.has(run.id)) return prev; + const next = new Set(prev); + next.add(run.id); + return next; + }); } } }; - }, [visible, activeRunIds, companyId, enableRealtimeUpdates, runById]); + + for (const run of readableRuns) { + refreshByRunRef.current.set(run.id, (force = false) => { + if (force) { pendingRefresh.add(run.id); missingTerminalLogRunIdsRef.current.delete(run.id); } + void readRunLog(run); + }); + void readRunLog(run); + } + const activeRuns = readableRuns.filter((run) => run.status === "running"); + // The realtime websocket is the primary live source when enabled, so the + // recurring poll only needs to run as a slow fallback rather than doubling + // the live update work every couple of seconds. + const effectivePollMs = enableRealtimeUpdates + ? Math.max(logPollIntervalMs, REALTIME_FALLBACK_POLL_INTERVAL_MS) + : logPollIntervalMs; + const interval = !stream.healthy && activeRuns.length > 0 && effectivePollMs > 0 + ? window.setInterval(() => { + void Promise.all(activeRuns.map((run) => readRunLog(run))); + }, effectivePollMs) + : null; + + return () => { + cancelled = true; + refreshByRunRef.current.clear(); + controller.abort(); + for (const timer of retryTimers.values()) window.clearTimeout(timer); + if (interval !== null) window.clearInterval(interval); + }; + }, [visible, enableRealtimeUpdates, logPollIntervalMs, logReadLimitBytes, normalizedRuns, runIdsKey, retryGeneration, enabled, companyId, stream.healthy, stream.epoch]); + const transcriptByRun = useMemo(() => { const next = new Map(); diff --git a/ui/src/components/transcript/useNativeRunTranscripts.streaming.test.tsx b/ui/src/components/transcript/useNativeRunTranscripts.streaming.test.tsx new file mode 100644 index 00000000000..23324b27bb5 --- /dev/null +++ b/ui/src/components/transcript/useNativeRunTranscripts.streaming.test.tsx @@ -0,0 +1,290 @@ +// @vitest-environment jsdom +import { act } from "react"; +import { createRoot, type Root } from "react-dom/client"; +import { afterEach, beforeEach, expect, it, vi } from "vitest"; +import type { HeartbeatRunEvent, LiveEvent } from "@paperclipai/shared"; +import { __liveUpdatesTestUtils, type CompanyLiveEventHandler } from "../../context/LiveUpdatesProvider"; +import { LiveTranscriptInterests } from "../../lib/live-transcript-interests"; +import { useNativeRunTranscripts } from "./useNativeRunTranscripts"; +import { nativeRunEventsToTranscript } from "./native-run-events"; + +const events = vi.hoisted(() => vi.fn()); +const conversationEvents = vi.hoisted(() => vi.fn()); +vi.mock("../../api/heartbeats", () => ({ heartbeatsApi: { events, conversationEvents } })); +(globalThis as typeof globalThis & { IS_REACT_ACT_ENVIRONMENT?: boolean }).IS_REACT_ACT_ENVIRONMENT = true; +const { LiveEventSubscriptionContext } = __liveUpdatesTestUtils; +let root: Root; +let store: LiveTranscriptInterests; +let listeners: Set; +let sent: Array<{ revision?: number; runIds?: string[] }>; +let latest: ReturnType; +let subscription: { companyId: string; transcripts: LiveTranscriptInterests; subscribe: (fn: CompanyLiveEventHandler) => () => void }; +const row = (seq: number, message = `row ${seq}`, runId = "run-1"): HeartbeatRunEvent => ({ + id: seq, seq, runId, companyId: "company-1", agentId: "agent-1", eventType: "item.completed", + stream: null, level: null, color: null, message, payload: { prpEvent: { + schema: "paperclip.prp.event.v1", schemaVersion: 1, sourceEventId: `event-${seq}`, + sourceSeq: seq, sourceInstanceId: "runner-1", sourceKind: "runner", runId, + normalizedSessionId: "session-1", eventType: "item.completed", itemId: `message-${seq}`, + emittedAt: "2026-10-24T00:00:00Z", payload: { kind: "agentMessage", channel: "progress", text: message }, + } }, createdAt: new Date("2026-10-24T00:00:00Z"), +}); +function emit(seq: number, signalOnly = false, kind = "agentMessage") { + const value = row(seq); + const envelope = value.payload!.prpEvent as { payload: Record }; + envelope.payload = { ...envelope.payload, kind }; + const event: LiveEvent = { id: seq, companyId: value.companyId, type: "heartbeat.run.event", createdAt: value.createdAt.toISOString(), payload: signalOnly + ? { runId: value.runId, agentId: value.agentId, eventType: value.eventType, seq } + : { ...value } }; + for (const listener of listeners) listener(event); +} +function Probe({ companyId = "company-1", enabled = true, older = false, compact = false }: { companyId?: string; enabled?: boolean; older?: boolean; compact?: boolean }) { + latest = useNativeRunTranscripts([ + { id: "run-1", status: "running", runtimeMode: "native", conversationOnly: compact }, + ...(older ? [{ id: "older", status: "succeeded", runtimeMode: "native" as const }] : []), + ], { companyId, enabled }); + return null; +} +async function render(companyId = "company-1", enabled = true, older = false, compact = false) { + await act(async () => root.render()); +} +async function negotiate() { + await act(async () => { + store.open({ send: text => sent.push(JSON.parse(text)) }); + store.receive({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + store.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1)?.revision }); + }); +} +beforeEach(() => { + vi.useFakeTimers(); + vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + events.mockReset().mockResolvedValue([]); + conversationEvents.mockReset().mockResolvedValue([]); + root = createRoot(document.createElement("div")); + store = new LiveTranscriptInterests(); listeners = new Set(); sent = []; + subscription = { companyId: "company-1", transcripts: store, subscribe(fn) { listeners.add(fn); return () => { listeners.delete(fn); }; } }; +}); +afterEach(async () => { await act(async () => root.unmount()); vi.restoreAllMocks(); vi.useRealTimers(); }); + +it("merges history arriving after live output without losing rows or duplicating a sequence", async () => { + let complete!: (rows: HeartbeatRunEvent[]) => void; + events.mockImplementationOnce(() => new Promise(resolve => { complete = resolve; })); + await render(); + await act(async () => emit(3)); + expect(events).toHaveBeenCalledTimes(1); + await act(async () => complete([row(1), row(2), row(3, "canonical row 3")])); + expect(latest.transcriptByRun.get("run-1")).toEqual(nativeRunEventsToTranscript([row(1), row(2), row(3, "canonical row 3")])); +}); + +it.each(["agentMessage", "reasoning"])("streams %s deltas after hydration without recurring history reads", async kind => { + events.mockResolvedValueOnce([row(1)]); + await render(); await negotiate(); + const reads = events.mock.calls.length; + const delta = row(2, "still writing"); + delta.eventType = "item.delta"; + const envelope = delta.payload!.prpEvent as Record; + envelope.eventType = "item.delta"; + envelope.payload = { kind, text: "still writing" }; + await act(async () => { + for (const listener of listeners) listener({ id: 2, companyId: delta.companyId, + type: "heartbeat.run.event", createdAt: delta.createdAt.toISOString(), payload: { ...delta } }); + await vi.advanceTimersByTimeAsync(90_000); + }); + expect(JSON.stringify(latest.transcriptByRun.get("run-1"))).toContain("still writing"); + expect(events).toHaveBeenCalledTimes(reads); +}); + +it("fetches a consecutive native commit signal and never replaces its complete row with a delayed signal", async () => { + events.mockResolvedValueOnce([row(1)]); + await render(); await negotiate(); + const reads = events.mock.calls.length; + events.mockResolvedValueOnce([row(2, "completed output")]); + await act(async () => emit(2, true)); + expect(events).toHaveBeenCalledTimes(reads + 1); + expect(events.mock.calls.at(-1)?.slice(0, 3)).toEqual(["run-1", 1, 1_000]); + expect(latest.transcriptByRun.get("run-1")).toEqual(nativeRunEventsToTranscript([row(1), row(2, "completed output")])); + await act(async () => { emit(2, true); emit(1, true); await vi.advanceTimersByTimeAsync(90_000); }); + expect(events).toHaveBeenCalledTimes(reads + 1); + expect(latest.transcriptByRun.get("run-1")).toEqual(nativeRunEventsToTranscript([row(1), row(2, "completed output")])); +}); + +it("retains a signal arriving during an older catch-up until its canonical row is visible", async () => { + await render(); await negotiate(); + let complete!: (rows: HeartbeatRunEvent[]) => void; + events.mockImplementationOnce(() => new Promise(resolve => { complete = resolve; })); + await act(async () => emit(1, true)); + const reads = events.mock.calls.length; + await act(async () => emit(2, true)); + expect(events).toHaveBeenCalledTimes(reads); + await act(async () => complete([row(1)])); + expect(latest.transcriptByRun.get("run-1")).toEqual(nativeRunEventsToTranscript([row(1)])); + events.mockRejectedValueOnce(new Error("history temporarily unavailable")); + await act(async () => vi.advanceTimersByTimeAsync(2_000)); + expect(latest.errorsByRun.has("run-1")).toBe(true); + events.mockResolvedValueOnce([row(2)]); + await act(async () => vi.advanceTimersByTimeAsync(2_000)); + expect(latest.errorsByRun.size).toBe(0); + expect(latest.transcriptByRun.get("run-1")).toEqual(nativeRunEventsToTranscript([row(1), row(2)])); + const recoveredReads = events.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(events).toHaveBeenCalledTimes(recoveredReads); +}); + +it("renders complete live PRP rows without initiating or scheduling history reads", async () => { + await render(); await negotiate(); + const reads = events.mock.calls.length; + await act(async () => { emit(1); emit(2); await vi.advanceTimersByTimeAsync(90_000); }); + expect(events).toHaveBeenCalledTimes(reads); + expect(latest.transcriptByRun.get("run-1")).toEqual(nativeRunEventsToTranscript([row(1), row(2)])); +}); + +function emitTerminal() { + const event: LiveEvent = { id: 100, companyId: "company-1", type: "heartbeat.run.status", + createdAt: new Date().toISOString(), payload: { runId: "run-1", status: "succeeded" } }; + for (const listener of listeners) listener(event); +} + +it("finishes slow historical pages while a sibling receives repeated commit and terminal notifications", async () => { + await render(); await negotiate(); + const olderReads: Array<{ cursor: number; signal: AbortSignal; resolve: (rows: HeartbeatRunEvent[]) => void }> = []; + events.mockImplementation((runId: string, cursor: number, _limit: number, { signal }: { signal: AbortSignal }) => { + if (runId === "older") return new Promise(resolve => olderReads.push({ cursor, signal, resolve })); + return Promise.resolve([row(cursor + 1)]); + }); + await render("company-1", true, true); + expect(olderReads).toHaveLength(1); + await act(async () => emit(2, true)); + expect(olderReads[0].signal.aborted).toBe(false); + expect(olderReads).toHaveLength(1); + const firstPage = Array.from({ length: 1_000 }, (_, i) => row(i + 1, `historical ${i + 1}`, "older")); + await act(async () => olderReads[0].resolve(firstPage)); + expect(olderReads).toHaveLength(2); + expect(olderReads[1].cursor).toBe(1_000); + expect(latest.hydratedRunIds.has("older")).toBe(false); + await act(async () => emit(3, true)); + await act(async () => emit(4, true)); + await act(async () => emitTerminal()); + expect(olderReads[1].signal.aborted).toBe(false); + expect(olderReads).toHaveLength(2); + const lastRow = row(1_001, "last historical output", "older"); + await act(async () => olderReads[1].resolve([lastRow])); + expect(latest.hydratedRunIds.has("older")).toBe(true); + expect(latest.transcriptByRun.get("older")).toEqual(nativeRunEventsToTranscript([...firstPage, lastRow])); + const reads = events.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(events).toHaveBeenCalledTimes(reads); +}); + +it("queues one terminal catch-up behind an in-flight read without aborting or overlapping it", async () => { + await render(); await negotiate(); + let complete!: (rows: HeartbeatRunEvent[]) => void; + let activeSignal!: AbortSignal; + events.mockImplementationOnce((_runId, _cursor, _limit, { signal }) => { + activeSignal = signal; + return new Promise(resolve => { complete = resolve; }); + }); + await act(async () => emit(1, true)); + const reads = events.mock.calls.length; + await act(async () => { emitTerminal(); emitTerminal(); }); + expect(activeSignal.aborted).toBe(false); + expect(events).toHaveBeenCalledTimes(reads); + events.mockResolvedValueOnce([row(2, "terminal output")]); + await act(async () => complete([row(1)])); + expect(events).toHaveBeenCalledTimes(reads + 1); + expect(latest.transcriptByRun.get("run-1")).toEqual(nativeRunEventsToTranscript([row(1), row(2, "terminal output")])); + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(events).toHaveBeenCalledTimes(reads + 1); +}); + +it("performs no recurring history reads after an acknowledged catch-up, and retries a failed catch-up", async () => { + await render(); await negotiate(); + const reads = events.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(events).toHaveBeenCalledTimes(reads); + events.mockRejectedValueOnce(new Error("temporary history outage")); + await act(async () => { + store.receive({ type: "live.resync", version: 1, revision: sent.at(-1)?.revision }); + store.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1)?.revision }); + }); + expect(latest.errorsByRun.has("run-1")).toBe(true); + await act(async () => vi.advanceTimersByTimeAsync(2_000)); + expect(latest.errorsByRun.size).toBe(0); + const recoveredReads = events.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(events).toHaveBeenCalledTimes(recoveredReads); +}); + +it("withdraws disabled views and rejects events from the previous company", async () => { + await render(); await negotiate(); + await act(async () => emit(1)); + expect(latest.transcriptByRun.get("run-1")).toHaveLength(1); + await render("company-1", false); + expect(sent.at(-1)?.runIds).toEqual([]); + const reads = events.mock.calls.length; + await act(async () => { emit(2); await vi.advanceTimersByTimeAsync(30_000); }); + expect(events).toHaveBeenCalledTimes(reads); + expect(latest.transcriptByRun.get("run-1")).toHaveLength(1); + await render("company-2"); + await act(async () => emit(3)); + expect(latest.transcriptByRun.get("run-1") ?? []).toEqual([]); +}); + + +it("finishes catch-up while unrelated consumers repeatedly replace shared interests", async () => { + await render(); await negotiate(); + let complete!: (rows: HeartbeatRunEvent[]) => void; + events.mockImplementationOnce(() => new Promise(resolve => { complete = resolve; })); + await act(async () => emit(1, true)); + const reads = events.mock.calls.length; + const signal = events.mock.calls.at(-1)![3].signal as AbortSignal; + for (let index = 0; index < 4; index++) { + let release!: () => void; + await act(async () => { release = store.acquire([`unrelated-${index}`]); }); + expect(signal.aborted).toBe(false); + await act(async () => store.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1)?.revision })); + await act(async () => { release(); }); + await act(async () => store.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1)?.revision })); + expect(signal.aborted).toBe(false); + expect(events).toHaveBeenCalledTimes(reads); + } + await act(async () => complete([row(1, "uninterrupted catch-up")])); + expect(latest.transcriptByRun.get("run-1")).toEqual(nativeRunEventsToTranscript([row(1, "uninterrupted catch-up")])); + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(events).toHaveBeenCalledTimes(reads); +}); + +it.each([false, true])("settles compact recovery through filtered-out activity without recurring reads (signal only: %s)", async signalOnly => { + conversationEvents.mockResolvedValueOnce([row(2, "Saved answer")]); + await render("company-1", true, false, true); + await negotiate(); + await act(async () => store.close()); + conversationEvents.mockImplementation((_runId, after: number) => Promise.resolve(after < 6 ? [row(6, "Recovered answer")] : [])); + await negotiate(); + await act(async () => emit(10, signalOnly, "reasoning")); + const settledReads = conversationEvents.mock.calls.length; + expect(latest.transcriptByRun.get("run-1")?.filter(entry => entry.kind === "assistant").map(entry => entry.text)) + .toEqual(["Saved answer", "Recovered answer"]); + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(conversationEvents).toHaveBeenCalledTimes(settledReads); + expect(events).not.toHaveBeenCalled(); +}); + +it("does not skip compact conversation rows committed during an older catch-up", async () => { + conversationEvents.mockResolvedValueOnce([row(2, "Saved answer")]); + await render("company-1", true, false, true); + await negotiate(); + let complete!: (rows: HeartbeatRunEvent[]) => void; + conversationEvents.mockImplementationOnce(() => new Promise(resolve => { complete = resolve; })); + await act(async () => emit(4, true, "reasoning")); + const reads = conversationEvents.mock.calls.length; + await act(async () => emit(6, true, "reasoning")); + expect(conversationEvents).toHaveBeenCalledTimes(reads); + conversationEvents.mockImplementation((_runId, after: number) => Promise.resolve(after < 5 ? [row(5, "Answer committed during catch-up")] : [])); + await act(async () => complete([])); + await act(async () => vi.advanceTimersByTimeAsync(2_000)); + expect(conversationEvents.mock.calls.at(-1)?.slice(0, 3)).toEqual(["run-1", 4, 1_000]); + expect(latest.transcriptByRun.get("run-1")?.filter(entry => entry.kind === "assistant").map(entry => entry.text)) + .toEqual(["Saved answer", "Answer committed during catch-up"]); + const settledReads = conversationEvents.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(conversationEvents).toHaveBeenCalledTimes(settledReads); +}); diff --git a/ui/src/components/transcript/useNativeRunTranscripts.ts b/ui/src/components/transcript/useNativeRunTranscripts.ts index a9c7f85f19e..ba2d627b86f 100644 --- a/ui/src/components/transcript/useNativeRunTranscripts.ts +++ b/ui/src/components/transcript/useNativeRunTranscripts.ts @@ -1,3 +1,7 @@ +import { TranscriptSequence } from "../../lib/transcript-sequence"; +import { useTranscriptLiveStream } from "../../context/LiveUpdatesProvider"; +import { usePageVisibility } from "../../lib/page-visibility"; +import { liveRunEvent, mergeRunEvents } from "../../lib/live-run-event"; import { useCallback, useEffect, useMemo, useRef, useState } from "react"; import type { HeartbeatRunEvent } from "@paperclipai/shared"; import type { TranscriptEntry } from "@/adapters"; @@ -24,7 +28,8 @@ function isLive(status: string): boolean { return status === "queued" || status === "running"; } -export function useNativeRunTranscripts(runs: readonly NativeRunTranscriptSource[]) { +export function useNativeRunTranscripts(runs: readonly NativeRunTranscriptSource[], options: { companyId?: string | null; enabled?: boolean } = {}) { + const { visible } = usePageVisibility(); const nativeRunsKey = runs .filter((run) => run.runtimeMode === "native") .map((run) => `${run.id}:${run.status}:${Boolean(run.conversationOnly)}`) @@ -46,15 +51,54 @@ export function useNativeRunTranscripts(runs: readonly NativeRunTranscriptSource const cursorByRunRef = useRef(new Map()); const conversationOnlyByRunRef = useRef(new Map()); + const sequencesRef = useRef(new Map()); + const sequence = (id: string) => { + let value = sequencesRef.current.get(id); + if (!value) { value = new TranscriptSequence(); sequencesRef.current.set(id, value); } + return value; + }; + const gapPendingRef = useRef(new Set()); + const historyReadsRef = useRef(new Map()); + const refreshByRunRef = useRef(new Map void>()); + const previousCompanyRef = useRef(options.companyId); useEffect(() => { + if (previousCompanyRef.current === options.companyId) return; + previousCompanyRef.current = options.companyId; + setEventsByRun(new Map()); setErrorsByRun(new Map()); setHydratedRunIds(new Set()); setHydratedStatusByRun(new Map()); + projectionCacheRef.current.clear(); cursorByRunRef.current.clear(); conversationOnlyByRunRef.current.clear(); + sequencesRef.current.clear(); gapPendingRef.current.clear(); + }, [options.companyId]); + const stream = useTranscriptLiveStream(nativeRuns.filter(run => isLive(run.status)).map(run => run.id), options, event => { + const runId = typeof event.payload.runId === "string" ? event.payload.runId : null; + if (!runId || !nativeRuns.some(run => run.id === runId)) return; + if (event.type === "heartbeat.run.status" && typeof event.payload.status === "string" && !isLive(event.payload.status)) { + refreshByRunRef.current.get(runId)?.(true); return; + } + const row = liveRunEvent(event); + if (!row) return; + const cursor = sequence(runId); + const envelope = row.payload?.prpEvent; + const hasTranscriptBody = envelope !== null && typeof envelope === "object" && !Array.isArray(envelope); + if (!hasTranscriptBody) cursor.requireHistory(row.seq); + if (cursor.observe(row.seq) && !gapPendingRef.current.has(runId)) { + gapPendingRef.current.add(runId); + refreshByRunRef.current.get(runId)?.(); + } + if (hasTranscriptBody) setEventsByRun(previous => new Map(previous).set(runId, mergeRunEvents(previous.get(runId) ?? [], [row]))); + }); + + + useEffect(() => { + if (!visible || options.enabled === false) return; for (const run of nativeRuns) { const mode = Boolean(run.conversationOnly); - if (conversationOnlyByRunRef.current.get(run.id) !== mode) cursorByRunRef.current.delete(run.id); + if (conversationOnlyByRunRef.current.get(run.id) !== mode) { cursorByRunRef.current.delete(run.id); sequencesRef.current.delete(run.id); } conversationOnlyByRunRef.current.set(run.id, mode); } let cancelled = false; const controller = new AbortController(); - const timers = new Set(); + const timers = new Map(); + const pendingRefresh = new Set(); const retainedIds = new Set(nativeRuns.map((run) => run.id)); const retainMap = (previous: Map) => { const next = new Map([...previous].filter(([id]) => retainedIds.has(id))); @@ -68,13 +112,21 @@ export function useNativeRunTranscripts(runs: readonly NativeRunTranscriptSource return next.size === previous.size ? previous : next; }); for (const id of cursorByRunRef.current.keys()) { - if (!retainedIds.has(id)) cursorByRunRef.current.delete(id); + if (!retainedIds.has(id)) { + cursorByRunRef.current.delete(id); sequencesRef.current.delete(id); gapPendingRef.current.delete(id); + } } const refreshRun = async (run: NativeRunTranscriptSource) => { + if (cancelled || historyReadsRef.current.has(run.id)) return; + pendingRefresh.delete(run.id); + window.clearTimeout(timers.get(run.id)); + timers.delete(run.id); + historyReadsRef.current.set(run.id, controller.signal); let failed = false; try { let cursor = cursorByRunRef.current.get(run.id) ?? 0; + const observedBeforeRead = sequence(run.id).observed; const incoming: HeartbeatRunEvent[] = []; for (;;) { const page = await readTranscriptRequest( @@ -93,10 +145,14 @@ export function useNativeRunTranscripts(runs: readonly NativeRunTranscriptSource } // Commit this run's cursor with its rows. A slow sibling must neither // hold its readiness hostage nor stall live polling for this run. - cursorByRunRef.current.set(run.id, cursor); + const coveredCursor = run.conversationOnly ? Math.max(cursor, observedBeforeRead) : cursor; + cursorByRunRef.current.set(run.id, coveredCursor); + sequence(run.id).confirm(coveredCursor); + failed = sequence(run.id).needsCatchup; + if (!failed) gapPendingRef.current.delete(run.id); if (incoming.length > 0) setEventsByRun((previous) => { const next = new Map(previous); - next.set(run.id, [...new Map([...(previous.get(run.id) ?? []), ...incoming].map((event) => [event.seq, event])).values()].sort((a, b) => a.seq - b.seq)); + next.set(run.id, mergeRunEvents(previous.get(run.id) ?? [], incoming)); return next; }); setErrorsByRun((previous) => { @@ -122,23 +178,34 @@ export function useNativeRunTranscripts(runs: readonly NativeRunTranscriptSource return next; }); } + if (historyReadsRef.current.get(run.id) === controller.signal) historyReadsRef.current.delete(run.id); if (cancelled) return; setHydratedRunIds((previous) => previous.has(run.id) ? previous : new Set([...previous, run.id])); - if (isLive(run.status) || failed) { + if (pendingRefresh.has(run.id)) { + void refreshRun(run); + } else if ((isLive(run.status) && !stream.healthy) || failed) { const timer = window.setTimeout(() => { - timers.delete(timer); + timers.delete(run.id); void refreshRun(run); }, EVENT_POLL_INTERVAL_MS); - timers.add(timer); + timers.set(run.id, timer); } }; - for (const run of nativeRuns) void refreshRun(run); + for (const run of nativeRuns) { + refreshByRunRef.current.set(run.id, (force = false) => { + if (force) pendingRefresh.add(run.id); + void refreshRun(run); + }); + void refreshRun(run); + } return () => { cancelled = true; + refreshByRunRef.current.clear(); controller.abort(); - for (const timer of timers) window.clearTimeout(timer); + for (const [id, signal] of historyReadsRef.current) if (signal === controller.signal) historyReadsRef.current.delete(id); + for (const timer of timers.values()) window.clearTimeout(timer); }; - }, [nativeRuns, retryGeneration]); + }, [nativeRuns, retryGeneration, visible, options.enabled, options.companyId, stream.healthy, stream.epoch]); const transcriptByRun = useMemo(() => { const transcripts = new Map(); diff --git a/ui/src/components/useSummaryDraftStream.ts b/ui/src/components/useSummaryDraftStream.ts index 4cd052dd63c..942565412cf 100644 --- a/ui/src/components/useSummaryDraftStream.ts +++ b/ui/src/components/useSummaryDraftStream.ts @@ -1,11 +1,13 @@ +import { TranscriptSequence } from "@/lib/transcript-sequence"; import { usePageVisibility } from "@/lib/page-visibility"; import { useCallback, useEffect, useMemo, useRef, useState } from "react"; import { useQuery } from "@tanstack/react-query"; import type { LiveEvent, SummarySlotIssueRef } from "@paperclipai/shared"; +import { readTranscriptRequest } from "./transcript/read-transcript-request"; import type { RunLogChunk } from "@/adapters"; import { heartbeatsApi } from "@/api/heartbeats"; -import { useCompanyLiveEvent } from "@/context/LiveUpdatesProvider"; +import { useCompanyLiveEvent, useTranscriptLiveStream } from "@/context/LiveUpdatesProvider"; import { queryKeys } from "@/lib/queryKeys"; import { mergeRunLogChunks, @@ -71,6 +73,30 @@ export function useSummaryDraftStream( const mergeRefs = useRef(freshMergeRefs()); const pendingLogRowsRef = useRef(new Map()); const logOffsetRef = useRef(0); + const logIdentityRef = useRef(null); + const retiredLogIdentitiesRef = useRef(new Set()); + const sequenceRef = useRef(new TranscriptSequence()); + const gapPendingRef = useRef(false); + const [catchupGeneration, setCatchupGeneration] = useState(0); + const requestCatchup = () => { + if (gapPendingRef.current) return; + gapPendingRef.current = true; + setCatchupGeneration(value => value + 1); + }; + const bindLog = (store: unknown, ref: unknown) => { + if (typeof ref !== "string" || !ref) return "same"; + const identity = `${typeof store === "string" ? store : ""}:${ref}`; + if (identity === logIdentityRef.current) return "same"; + if (retiredLogIdentitiesRef.current.has(identity)) return "stale"; + const prior = logIdentityRef.current; + logIdentityRef.current = identity; + if (!prior) return "same"; + retiredLogIdentitiesRef.current.add(prior); + if (retiredLogIdentitiesRef.current.size > 8) retiredLogIdentitiesRef.current.delete(retiredLogIdentitiesRef.current.values().next().value!); + logOffsetRef.current = 0; pendingLogRowsRef.current.clear(); sequenceRef.current = new TranscriptSequence(); + mergeRefs.current = freshMergeRefs(); setChunks([]); + return "changed"; + }; // Reset all stream state whenever the tracked generation changes — including // a superseded generation (new issue id) or generation ending (null). @@ -80,7 +106,7 @@ export function useSummaryDraftStream( mergeRefs.current = freshMergeRefs(); pendingLogRowsRef.current = new Map(); logOffsetRef.current = 0; - }, [issueId]); + }, [companyId, issueId]); const appendChunks = useCallback((incoming: IncomingRunLogChunk[]) => { if (incoming.length === 0) return; @@ -98,7 +124,7 @@ export function useSummaryDraftStream( // Learn the generation run id from live progress/queued events for the issue. useCompanyLiveEvent((event: LiveEvent) => { - if (!issueId) return; + if (!issueId || event.companyId !== companyId) return; if (event.type !== "heartbeat.run.progress" && event.type !== "heartbeat.run.queued") return; const payload = event.payload ?? {}; if (payload.issueId !== issueId) return; @@ -111,7 +137,7 @@ export function useSummaryDraftStream( const activeRunQuery = useQuery({ queryKey: queryKeys.issues.activeRun(issueId ?? "__none__"), queryFn: () => heartbeatsApi.activeRunForIssue(issueId!), - enabled: Boolean(companyId) && Boolean(issueId) && !runId, + enabled: visible && Boolean(companyId) && Boolean(issueId) && !runId, retry: false, refetchInterval: runId ? false : 4000, }); @@ -123,14 +149,23 @@ export function useSummaryDraftStream( useEffect(() => { logOffsetRef.current = 0; pendingLogRowsRef.current = new Map(); - }, [runId]); - + logIdentityRef.current = null; retiredLogIdentitiesRef.current.clear(); sequenceRef.current = new TranscriptSequence(); + gapPendingRef.current = false; mergeRefs.current = freshMergeRefs(); setChunks([]); + }, [runId, companyId, issueId]); // Live token deltas over the shared company-events socket. - useCompanyLiveEvent((event: LiveEvent) => { + const stream = useTranscriptLiveStream(runId ? [runId] : [], { companyId, enabled: visible && Boolean(issueId) }, (event: LiveEvent) => { if (!visible || !runId) return; + if (event.type === "heartbeat.run.status" && event.payload.runId === runId) { setCatchupGeneration(value => value + 1); return; } if (event.type !== "heartbeat.run.log") return; const payload = event.payload ?? {}; if (payload.runId !== runId) return; + const binding = bindLog(payload.logStore, payload.logRef); + if (binding === "stale") return; + const seq = readChunkSeq(payload.seq); + if (payload.truncated === true) sequenceRef.current.requireHistory(seq); + const gap = sequenceRef.current.observe(seq); + if (binding === "changed" || payload.truncated === true || gap) requestCatchup(); + if (payload.truncated === true) return; const chunk = readPayloadString(payload.chunk); if (!chunk) return; const ts = readPayloadString(payload.ts) ?? event.createdAt; @@ -145,33 +180,38 @@ export function useSummaryDraftStream( useEffect(() => { if (!visible || !runId) return; let cancelled = false; - let reading = false; + const controller = new AbortController(); + let timer: number | undefined; const read = async () => { - if (reading || cancelled) return; - reading = true; + let failed = false; try { - const result = await heartbeatsApi.log(runId, logOffsetRef.current, LOG_READ_LIMIT_BYTES); - if (cancelled) return; - appendChunks(parsePersistedLogContent(runId, result.content, pendingLogRowsRef.current)); - if (result.nextOffset !== undefined) { - logOffsetRef.current = result.nextOffset; - } else if (result.content.length > 0) { - logOffsetRef.current += result.content.length; + for (;;) { + const offset = logOffsetRef.current; + const result = await readTranscriptRequest(signal => heartbeatsApi.log(runId, offset, LOG_READ_LIMIT_BYTES, { signal }), controller.signal); + if (cancelled) return; + const binding = bindLog(result.store, result.logRef); + if (binding === "stale") { failed = true; break; } + if (binding === "changed" && offset !== 0) continue; + const rows = parsePersistedLogContent(runId, result.content, pendingLogRowsRef.current); + appendChunks(rows); + for (const row of rows) sequenceRef.current.confirm(row.seq); + const next = result.nextOffset ?? offset + new TextEncoder().encode(result.content).byteLength; + logOffsetRef.current = next; + if (result.nextOffset === undefined || !result.content || next <= offset) break; } + failed ||= sequenceRef.current.needsCatchup; + if (!failed) gapPendingRef.current = false; } catch { - // Ignore transient/404 reads (log not yet flushed, run just started). - } finally { - reading = false; + failed = true; } + if (!cancelled && (!stream.healthy || failed)) timer = window.setTimeout(() => void read(), LOG_POLL_INTERVAL_MS); }; - void read(); - const interval = window.setInterval(() => void read(), LOG_POLL_INTERVAL_MS); return () => { - cancelled = true; - window.clearInterval(interval); + cancelled = true; controller.abort(); + if (timer !== undefined) window.clearTimeout(timer); }; - }, [visible, runId, appendChunks]); + }, [visible, companyId, runId, appendChunks, stream.healthy, stream.epoch, catchupGeneration]); const parse = useMemo(() => parseSummaryDraftStream(extractAssistantOutputText(chunks)), [chunks]); diff --git a/ui/src/context/LiveUpdatesProvider.recovery.test.tsx b/ui/src/context/LiveUpdatesProvider.recovery.test.tsx index 591e735fa49..db874fed347 100644 --- a/ui/src/context/LiveUpdatesProvider.recovery.test.tsx +++ b/ui/src/context/LiveUpdatesProvider.recovery.test.tsx @@ -28,7 +28,9 @@ class Socket { onclose: (() => void) | null = null; onmessage: ((message: { data: string }) => void) | null = null; onerror: (() => void) | null = null; + sent: Array<{ type: string; revision?: number }> = []; constructor() { Socket.instances.push(this); } + send(encoded: string) { this.sent.push(JSON.parse(encoded)); } close() { this.readyState = 3; } } @@ -102,6 +104,70 @@ describe("LiveUpdatesProvider connection recovery", () => { } } + it.each([false, true])("discovers a run started in the resync gap after acknowledgement (older read pending=%s)", async pending => { + vi.stubGlobal("WebSocket", Socket); + await renderPolling(); + const socket = Socket.instances[0]; + const deliver = async (type: string, extras: Record = {}) => { + await act(async () => socket.onmessage?.({ data: JSON.stringify({ type, version: 1, ...extras }) })); + await act(async () => vi.advanceTimersByTimeAsync(1)); + }; + await act(async () => socket.onopen?.()); + await deliver("live.capabilities", { capabilities: ["run-interests"] }); + await deliver("live.subscribed", { revision: socket.sent.at(-1)!.revision }); + pollRead.mockClear(); + let release!: (value: unknown) => void; + if (pending) pollRead.mockImplementationOnce(() => new Promise(resolve => { release = resolve; })); + await deliver("live.resync", { revision: socket.sent.at(-1)!.revision }); + expect(pollRead).toHaveBeenCalledOnce(); + const next = [{ id: "new-run", status: "running" }]; + pollRead.mockResolvedValue(next); + await deliver("live.subscribed", { revision: socket.sent.at(-1)!.revision }); + if (pending) { + expect(pollRead).toHaveBeenCalledOnce(); + await act(async () => release([])); + await act(async () => vi.advanceTimersByTimeAsync(1)); + } + expect(pollRead).toHaveBeenCalledTimes(2); + expect(client.getQueryData(["company-1", "idle-run-fixture"])).toEqual(next); + }); + + it.each(["unmount", "disconnect", "company", "session", "hidden"])("discards a queued resync-ack refresh after %s", async change => { + vi.stubGlobal("WebSocket", Socket); + await renderPolling(); + const socket = Socket.instances[0]; + const deliver = async (type: string, extras: Record = {}) => { + await act(async () => socket.onmessage?.({ data: JSON.stringify({ type, version: 1, ...extras }) })); + await act(async () => vi.advanceTimersByTimeAsync(1)); + }; + await act(async () => socket.onopen?.()); + await deliver("live.capabilities", { capabilities: ["run-interests"] }); + await deliver("live.subscribed", { revision: socket.sent.at(-1)!.revision }); + let release!: (value: unknown) => void; + pollRead.mockImplementationOnce(() => new Promise(resolve => { release = resolve; })); + await deliver("live.resync", { revision: socket.sent.at(-1)!.revision }); + await deliver("live.subscribed", { revision: socket.sent.at(-1)!.revision }); + if (change === "unmount") await act(async () => root.unmount()); + if (change === "disconnect") await act(async () => socket.onerror?.()); + if (change === "company") { companySelection.id = "company-2"; await renderPolling(); } + if (change === "session") { + const next = { user: { id: "viewer" }, session: { id: "replacement", userId: "viewer" } }; + sessionRead.mockResolvedValue(next); + await act(async () => client.setQueryData(queryKeys.auth.session, next)); + await act(async () => vi.advanceTimersByTimeAsync(1)); + } + if (change === "hidden") await act(async () => { + vi.spyOn(document, "visibilityState", "get").mockReturnValue("hidden"); + document.dispatchEvent(new Event("visibilitychange")); + }); + const reads = pollRead.mock.calls.length; + const invalidate = vi.spyOn(client, "invalidateQueries"); + await act(async () => release([])); + await act(async () => vi.advanceTimersByTimeAsync(1)); + expect(pollRead).toHaveBeenCalledTimes(reads); + expect(invalidate).not.toHaveBeenCalled(); + }); + it.each([null, []])("keeps setup polling, then stops known-empty polling after connection for %j", async (data) => { vi.stubGlobal("WebSocket", Socket); pollRead.mockResolvedValue(data); diff --git a/ui/src/context/LiveUpdatesProvider.tsx b/ui/src/context/LiveUpdatesProvider.tsx index d24879ba378..b2d0f8021e4 100644 --- a/ui/src/context/LiveUpdatesProvider.tsx +++ b/ui/src/context/LiveUpdatesProvider.tsx @@ -1,5 +1,7 @@ +import { LiveTranscriptInterests, DISCONNECTED_TRANSCRIPT_STREAM } from "../lib/live-transcript-interests"; import { resolveAgentAppearance } from "@paperclipai/shared"; import { getPageVisibility, usePageVisibility } from "../lib/page-visibility"; +import { createLiveQueryRecovery } from "../lib/live-query-recovery"; import { createContext, useCallback, @@ -8,6 +10,7 @@ import { useMemo, useRef, useState, + useSyncExternalStore, type ReactNode, } from "react"; import { @@ -82,6 +85,8 @@ type LiveUpdatesSocketLike = { export type CompanyLiveEventHandler = (event: LiveEvent) => void; interface LiveEventSubscription { + companyId?: string | null; + transcripts?: LiveTranscriptInterests; subscribe: (handler: CompanyLiveEventHandler) => () => void; } @@ -179,6 +184,30 @@ export function useTaskRunLiveUpdates(scope: { return connected && Boolean(scope.issueId && scope.assigneeAgentId); } +const subscribeNoop = () => () => {}; +const disconnectedSnapshot = () => DISCONNECTED_TRANSCRIPT_STREAM; + +export function useTranscriptLiveStream(runIds: readonly string[], options: { companyId?: string | null; enabled?: boolean }, handler: CompanyLiveEventHandler) { + const subscription = useContext(LiveEventSubscriptionContext); + const { visible } = usePageVisibility(); + useCompanyLiveEvent(event => { + if (visible && options.enabled !== false && (options.companyId === undefined || event.companyId === options.companyId)) handler(event); + }); + const key = [...new Set(runIds)].sort().join(","); + const active = visible && options.enabled !== false && subscription?.transcripts !== undefined + && (options.companyId === undefined || subscription.companyId === options.companyId); + const state = useSyncExternalStore(subscription?.transcripts?.subscribe ?? subscribeNoop, + subscription?.transcripts?.snapshot ?? disconnectedSnapshot, disconnectedSnapshot); + useEffect(() => { + if (!active || !subscription?.transcripts) return; + return subscription.transcripts.acquire(key ? key.split(",") : []); + }, [active, subscription, key]); + return active ? { + healthy: state.healthy && (key === "" || key.split(",").every(id => state.subscribedRunIds.has(id))), + epoch: state.epoch, + } : DISCONNECTED_TRANSCRIPT_STREAM; +} + function readString(value: unknown): string | null { return typeof value === "string" && value.length > 0 ? value : null; } @@ -677,7 +706,7 @@ function readRunLiveStatusPatchFromPayload( return patch; } - if (eventType === "heartbeat.run.log") { + if (eventType === "heartbeat.run.log" || eventType === "heartbeat.run.activity") { patch.lastEventAt = readString(payload.ts) ?? eventCreatedAt; return patch; } @@ -1853,7 +1882,7 @@ function handleLiveEvent( liveStatusPatch, ) : false; - if (event.type === "heartbeat.run.log") { + if (event.type === "heartbeat.run.log" || event.type === "heartbeat.run.activity") { return; } @@ -2057,9 +2086,10 @@ export function LiveUpdatesProvider({ children }: { children: ReactNode }) { subscribersRef.current.delete(handler); }; }, []); + const transcripts = useMemo(() => new LiveTranscriptInterests(), [liveCompanyId, socketAuthKey]); const subscriptionValue = useMemo( - () => ({ subscribe }), - [subscribe], + () => ({ subscribe, transcripts, companyId: liveCompanyId }), + [subscribe, transcripts, liveCompanyId], ); // Coalesce the per-event invalidation storm. Optimistic setQueryData writes @@ -2154,6 +2184,9 @@ export function LiveUpdatesProvider({ children }: { children: ReactNode }) { return; } socket = nextSocket; + let recoveryActive = true; + const recoverQueries = createLiveQueryRecovery(queryClient, + () => !closed && recoveryActive && socket === nextSocket && getPageVisibility().visible); nextSocket.onopen = () => { if (closed || socket !== nextSocket) { @@ -2162,6 +2195,7 @@ export function LiveUpdatesProvider({ children }: { children: ReactNode }) { } setConnectedScopeKey(socketScopeKey); stopPolling(); + transcripts.open(nextSocket); if (reconnectAttempt > 0) { gateRef.current.suppressUntil = Date.now() + RECONNECT_SUPPRESS_MS; } @@ -2181,12 +2215,18 @@ export function LiveUpdatesProvider({ children }: { children: ReactNode }) { nextSocket.onmessage = (message) => { if (closed || socket !== nextSocket) return; - if (!getPageVisibility().visible) return; const raw = typeof message.data === "string" ? message.data : ""; if (!raw) return; try { const parsed = JSON.parse(raw) as LiveEvent; + if (transcripts.receive(parsed, recoverQueries)) { + if ((parsed as { type: string }).type === "live.resync") { + void queryClient.invalidateQueries({ type: "active" }, { cancelRefetch: false }); + } + return; + } + if (!getPageVisibility().visible) return; handleLiveEvent( coalescingClient, liveCompanyId, @@ -2213,6 +2253,7 @@ export function LiveUpdatesProvider({ children }: { children: ReactNode }) { nextSocket.onerror = () => { if (closed || socket !== nextSocket) return; + recoveryActive = false; setConnectedScopeKey((current) => current === socketScopeKey ? null : current); // Wait for onclose to drive the reconnect. Self-closing here is what // produces the "closed before connection established" browser noise. @@ -2220,7 +2261,9 @@ export function LiveUpdatesProvider({ children }: { children: ReactNode }) { nextSocket.onclose = () => { if (socket !== nextSocket) return; + recoveryActive = false; socket = null; + transcripts.close(); if (closed) return; setConnectedScopeKey((current) => current === socketScopeKey ? null : current); startPolling(); @@ -2241,6 +2284,7 @@ export function LiveUpdatesProvider({ children }: { children: ReactNode }) { stopPolling(); const activeSocket = socket; socket = null; + transcripts.close(); closeSocketQuietly(activeSocket, "provider_unmount"); }; }, [ @@ -2253,6 +2297,7 @@ export function LiveUpdatesProvider({ children }: { children: ReactNode }) { canConnectSocket, socketAuthKey, socketScopeKey, + transcripts, ]); return ( diff --git a/ui/src/lib/live-query-recovery.ts b/ui/src/lib/live-query-recovery.ts new file mode 100644 index 00000000000..1b04bdf3bb9 --- /dev/null +++ b/ui/src/lib/live-query-recovery.ts @@ -0,0 +1,21 @@ +import type { Query, QueryClient } from "@tanstack/react-query"; + +export function createLiveQueryRecovery(client: QueryClient, isCurrent: () => boolean) { + const waiting = new WeakSet(); + return () => { + if (!isCurrent()) return; + for (const query of client.getQueryCache().findAll({ type: "active" })) { + if (waiting.has(query)) continue; + const refresh = () => client.invalidateQueries({ queryKey: query.queryKey, exact: true }, { cancelRefetch: false }); + if (query.state.fetchStatus !== "fetching") { + void refresh(); + continue; + } + waiting.add(query); + void (query.promise ?? refresh()).catch(() => undefined).then(() => { + waiting.delete(query); + if (isCurrent() && query.isActive() && client.getQueryCache().get(query.queryHash) === query) return refresh(); + }).catch(() => undefined); + } + }; +} diff --git a/ui/src/lib/live-run-event.ts b/ui/src/lib/live-run-event.ts new file mode 100644 index 00000000000..a5f908c6c9b --- /dev/null +++ b/ui/src/lib/live-run-event.ts @@ -0,0 +1,19 @@ +import type { HeartbeatRunEvent, LiveEvent } from "@paperclipai/shared"; + +export function liveRunEvent(event: LiveEvent): HeartbeatRunEvent | null { + if (event.type !== "heartbeat.run.event") return null; + const p = event.payload; + if (typeof p.runId !== "string" || typeof p.agentId !== "string" || !Number.isSafeInteger(p.seq) + || Number(p.seq) < 1 || typeof p.eventType !== "string") return null; + return { id: Number(p.seq), runId: p.runId, companyId: event.companyId, agentId: p.agentId, seq: Number(p.seq), + eventType: p.eventType, stream: p.stream === "stdout" || p.stream === "stderr" || p.stream === "system" ? p.stream : null, + level: p.level === "info" || p.level === "warn" || p.level === "error" ? p.level : null, color: typeof p.color === "string" ? p.color : null, + message: typeof p.message === "string" ? p.message : null, + payload: p.payload && typeof p.payload === "object" && !Array.isArray(p.payload) ? p.payload as Record : null, + createdAt: new Date(event.createdAt) }; +} +export function mergeRunEvents(previous: readonly HeartbeatRunEvent[], incoming: readonly HeartbeatRunEvent[]): HeartbeatRunEvent[] { + const rows = new Map(previous.map(row => [row.seq, row])); + for (const row of incoming) rows.set(row.seq, row); + return [...rows.values()].sort((a, b) => a.seq - b.seq); +} diff --git a/ui/src/lib/live-transcript-interests.test.ts b/ui/src/lib/live-transcript-interests.test.ts new file mode 100644 index 00000000000..c61e480da9e --- /dev/null +++ b/ui/src/lib/live-transcript-interests.test.ts @@ -0,0 +1,93 @@ +import { expect, it, vi } from "vitest"; +import { LiveTranscriptInterests } from "./live-transcript-interests"; +function fixture() { + const store = new LiveTranscriptInterests(); const sent: any[] = []; + const socket = { send: (text: string) => sent.push(JSON.parse(text)) }; + const capable = () => store.receive({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + const acknowledge = () => store.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1).revision }); + return { store, sent, socket, capable, acknowledge }; +} +it("acknowledges a recovery boundary once, ignoring stale and ordinary interest acknowledgements", () => { + const f = fixture(), recovered = vi.fn(); + f.store.open(f.socket); f.capable(); f.acknowledge(); + f.store.receive({ type: "live.resync", version: 1, revision: 1 }, recovered); + f.store.receive({ type: "live.subscribed", version: 1, revision: 1 }, recovered); + expect(recovered).not.toHaveBeenCalled(); + f.store.receive({ type: "live.subscribed", version: 1, revision: 2 }, recovered); + f.store.receive({ type: "live.subscribed", version: 1, revision: 2 }, recovered); + f.store.acquire(["new-run"]); + f.store.receive({ type: "live.subscribed", version: 1, revision: 3 }, recovered); + expect(recovered).toHaveBeenCalledOnce(); +}); +it("unions ref-counted consumers and acknowledges the applied revision before becoming healthy", () => { + const f = fixture(); const releaseA = f.store.acquire(["run-1"]); f.store.open(f.socket); + expect(f.sent).toEqual([{ type: "live.hello", version: 1, capabilities: ["run-interests"] }]); + f.capable(); expect(f.sent.at(-1).runIds).toEqual(["run-1"]); expect(f.store.snapshot().healthy).toBe(false); + f.acknowledge(); expect(f.store.snapshot().healthy).toBe(true); + const releaseB = f.store.acquire(["run-1"]); + expect(f.sent).toHaveLength(2); + releaseA(); expect(f.sent).toHaveLength(2); + releaseB(); expect(f.sent.at(-1)).toMatchObject({ revision: 2, runIds: [] }); + releaseB(); expect(f.sent).toHaveLength(3); +}); +it("handles subscription races, resync and reconnect without accepting an old ACK", () => { + const f = fixture(); f.store.open(f.socket); f.capable(); + f.store.acquire(["run-1"]); f.store.acquire(["run-2"]); + f.store.receive({ type: "live.subscribed", version: 1, revision: 1 }); + expect(f.store.snapshot().healthy).toBe(false); + f.acknowledge(); const epoch = f.store.snapshot().epoch; + f.store.receive({ type: "live.resync", version: 1, revision: f.sent.at(-1).revision }); + expect(f.store.snapshot()).toMatchObject({ healthy: false }); + f.acknowledge(); expect(f.store.snapshot().epoch).toBeGreaterThan(epoch); + f.store.close(); expect(f.store.snapshot().healthy).toBe(false); + f.store.open(f.socket); f.capable(); expect(f.sent.at(-1)).toMatchObject({ revision: 1, runIds: ["run-1", "run-2"] }); +}); +it("keeps older servers on HTTP fallback without inventing support", () => { + const f = fixture(); f.store.acquire(["run-1"]); f.store.open(f.socket); + expect(f.store.receive({ type: "heartbeat.run.log", payload: {} })).toBe(false); + expect(f.store.snapshot().healthy).toBe(false); +}); +it("keeps fallback available across socket-close races and excessive interests", () => { + const f = fixture(); + expect(() => f.store.open({ send() { throw new Error("socket closed"); } })).not.toThrow(); + expect(f.store.snapshot().healthy).toBe(false); + const release = f.store.acquire(Array.from({ length: 1_001 }, (_, index) => `run-${index}`)); + f.store.open(f.socket); f.capable(); + expect(f.sent.at(-1).runIds).toHaveLength(1_000); + f.acknowledge(); expect(f.store.snapshot().healthy).toBe(false); + release(); f.acknowledge(); expect(f.store.snapshot().healthy).toBe(true); + expect(f.store.receive({ type: 42 })).toBe(false); +}); + +it("keeps acknowledged interests healthy while new interests wait for their own revision", () => { + const f = fixture(); f.store.acquire(["existing"]); f.store.open(f.socket); f.capable(); f.acknowledge(); + const epoch = f.store.snapshot().epoch; + const priorRevision = f.sent.at(-1).revision; + const release = f.store.acquire(["new"]); + expect(f.store.snapshot()).toMatchObject({ healthy: true, epoch }); + expect([...f.store.snapshot().subscribedRunIds]).toEqual(["existing"]); + f.store.receive({ type: "live.subscribed", version: 1, revision: priorRevision }); + expect(f.store.snapshot().subscribedRunIds.has("new")).toBe(false); + f.acknowledge(); + expect([...f.store.snapshot().subscribedRunIds]).toEqual(["existing", "new"]); + expect(f.store.snapshot().epoch).toBe(epoch); + release(); f.acknowledge(); + expect(f.store.snapshot()).toMatchObject({ healthy: true, epoch }); + expect([...f.store.snapshot().subscribedRunIds]).toEqual(["existing"]); +}); + +it("recovers an overflow reported before a newer interest revision was acknowledged", () => { + const f = fixture(); f.store.acquire(["existing"]); f.store.open(f.socket); f.capable(); f.acknowledge(); + const overflowRevision = f.sent.at(-1).revision; + const epoch = f.store.snapshot().epoch; + f.store.acquire(["new"]); + f.store.receive({ type: "live.resync", version: 1, revision: overflowRevision }); + expect(f.store.snapshot().healthy).toBe(false); + expect(f.store.snapshot().epoch).toBeGreaterThan(epoch); + const recoveringRevision = f.sent.at(-1).revision; + f.store.receive({ type: "live.resync", version: 1, revision: overflowRevision }); + expect(f.sent.at(-1).revision).toBe(recoveringRevision); + f.acknowledge(); + expect(f.store.snapshot().healthy).toBe(true); + expect([...f.store.snapshot().subscribedRunIds]).toEqual(["existing", "new"]); +}); diff --git a/ui/src/lib/live-transcript-interests.ts b/ui/src/lib/live-transcript-interests.ts new file mode 100644 index 00000000000..3f7e13130f3 --- /dev/null +++ b/ui/src/lib/live-transcript-interests.ts @@ -0,0 +1,84 @@ +import type { LiveDeliveryClientMessage } from "@paperclipai/shared"; + +export interface TranscriptStreamState { healthy: boolean; epoch: number; subscribedRunIds: ReadonlySet } +export const DISCONNECTED_TRANSCRIPT_STREAM: TranscriptStreamState = { healthy: false, epoch: 0, subscribedRunIds: new Set() }; +interface Sender { send(data: string): void } + +export class LiveTranscriptInterests { + readonly #counts = new Map(); + readonly #listeners = new Set<() => void>(); + #socket: Sender | null = null; + #capable = false; + #revision = 0; + #acknowledged = 0; + #lastResyncRevision = 0; + #recovering = false; + #subscribedRunIds = new Set(); + #sentRunIds: string[] = []; + #snapshot: TranscriptStreamState = DISCONNECTED_TRANSCRIPT_STREAM; + readonly snapshot = () => this.#snapshot; + readonly subscribe = (listener: () => void) => { this.#listeners.add(listener); return () => { this.#listeners.delete(listener); }; }; + #publish(healthy: boolean, resync = false) { + this.#snapshot = { healthy, epoch: this.#snapshot.epoch + (resync ? 1 : 0), subscribedRunIds: this.#subscribedRunIds }; + for (const listener of this.#listeners) listener(); + } + #send(message: LiveDeliveryClientMessage) { + try { this.#socket?.send(JSON.stringify(message)); } + catch { this.close(); } + } + #replace() { + if (!this.#socket || !this.#capable) return; + const message: LiveDeliveryClientMessage = { type: "live.interests", version: 1, revision: ++this.#revision, + runIds: [...this.#counts.keys()].sort().slice(0, 1_000) }; + this.#sentRunIds = message.runIds; + this.#subscribedRunIds = new Set(this.#sentRunIds.filter(id => this.#subscribedRunIds.has(id))); + this.#publish(this.#snapshot.healthy); + this.#send(message); + } + acquire(runIds: readonly string[]): () => void { + const unique = [...new Set(runIds)]; + let changed = false; + for (const id of unique) { const count = this.#counts.get(id) ?? 0; this.#counts.set(id, count + 1); changed ||= count === 0; } + if (changed) this.#replace(); + let released = false; + return () => { + if (released) return; + released = true; changed = false; + for (const id of unique) { + const count = this.#counts.get(id) ?? 0; + if (count <= 1) { this.#counts.delete(id); changed = true; } + else this.#counts.set(id, count - 1); + } + if (changed) this.#replace(); + }; + } + open(socket: Sender) { + this.#socket = socket; this.#capable = false; this.#revision = 0; this.#acknowledged = 0; this.#lastResyncRevision = 0; + this.#subscribedRunIds = new Set(); this.#recovering = false; + this.#publish(false, true); + this.#send({ type: "live.hello", version: 1, capabilities: ["run-interests"] }); + } + close() { this.#socket = null; this.#capable = false; this.#recovering = false; this.#subscribedRunIds = new Set(); this.#publish(false, true); } + receive(value: unknown, onRecoveryAcknowledged?: () => void): boolean { + if (!value || typeof value !== "object") return false; + const frame = value as { type?: string; version?: number; capabilities?: unknown; revision?: number }; + if (typeof frame.type !== "string" || !frame.type.startsWith("live.")) return false; + if (frame.version !== 1 || !this.#socket) return true; + if (frame.type === "live.capabilities" && Array.isArray(frame.capabilities) && frame.capabilities.includes("run-interests")) { + if (!this.#capable) { this.#capable = true; this.#replace(); } + } else if (frame.type === "live.subscribed" && frame.revision === this.#revision && this.#acknowledged !== frame.revision) { + this.#acknowledged = frame.revision; + this.#subscribedRunIds = new Set(this.#sentRunIds); + this.#publish(this.#counts.size <= 1_000); + if (this.#recovering) { this.#recovering = false; onRecoveryAcknowledged?.(); } + } else if (frame.type === "live.resync" && Number.isSafeInteger(frame.revision) + && Number(frame.revision) > this.#lastResyncRevision && Number(frame.revision) <= this.#revision) { + this.#lastResyncRevision = Number(frame.revision); + this.#recovering = true; + this.#subscribedRunIds = new Set(); + this.#publish(false, true); + this.#replace(); + } + return true; + } +} diff --git a/ui/src/lib/transcript-sequence.test.ts b/ui/src/lib/transcript-sequence.test.ts new file mode 100644 index 00000000000..4c2fa60a08b --- /dev/null +++ b/ui/src/lib/transcript-sequence.test.ts @@ -0,0 +1,35 @@ +import { expect, it } from "vitest"; +import { TranscriptSequence } from "./transcript-sequence"; + +it("keeps a second gap pending when it arrives during the first history read", () => { + const cursor = new TranscriptSequence(); + cursor.confirm(1); + expect(cursor.observe(3)).toBe(true); + expect(cursor.observe(5)).toBe(true); + cursor.confirm(3); + expect(cursor.needsCatchup).toBe(true); + cursor.confirm(5); + expect(cursor.needsCatchup).toBe(false); + expect(cursor.observe(6)).toBe(false); + expect(cursor.persisted).toBe(5); +}); + +it("accepts out-of-order and duplicate stream rows without advancing the history cursor", () => { + const cursor = new TranscriptSequence(); + cursor.confirm(20); + expect(cursor.observe(19)).toBe(false); + expect(cursor.observe(21)).toBe(false); + expect(cursor.observe(21)).toBe(false); + expect(cursor.persisted).toBe(20); +}); + +it("keeps a consecutive truncated row pending beyond an older history response", () => { + const cursor = new TranscriptSequence(); + cursor.confirm(10); + cursor.requireHistory(11); + expect(cursor.observe(11)).toBe(true); + cursor.confirm(10); + expect(cursor.needsCatchup).toBe(true); + cursor.confirm(11); + expect(cursor.needsCatchup).toBe(false); +}); diff --git a/ui/src/lib/transcript-sequence.ts b/ui/src/lib/transcript-sequence.ts new file mode 100644 index 00000000000..50e34e567df --- /dev/null +++ b/ui/src/lib/transcript-sequence.ts @@ -0,0 +1,26 @@ +export class TranscriptSequence { + observed = 0; + persisted = 0; + missingThrough = 0; + + observe(seq: number | undefined): boolean { + if (seq === undefined) return false; + if (seq > this.observed + 1) this.missingThrough = Math.max(this.missingThrough, seq - 1); + this.observed = Math.max(this.observed, seq); + return this.needsCatchup; + } + + confirm(seq: number | undefined): void { + if (seq === undefined) return; + this.persisted = Math.max(this.persisted, seq); + this.observed = Math.max(this.observed, seq); + } + + requireHistory(seq: number | undefined): void { + if (seq !== undefined) this.missingThrough = Math.max(this.missingThrough, seq); + } + + get needsCatchup(): boolean { + return this.missingThrough > this.persisted; + } +} diff --git a/ui/src/pages/AgentDetail.log-visibility.test.tsx b/ui/src/pages/AgentDetail.log-visibility.test.tsx index d0a96b68a60..d8e486fd84d 100644 --- a/ui/src/pages/AgentDetail.log-visibility.test.tsx +++ b/ui/src/pages/AgentDetail.log-visibility.test.tsx @@ -1,12 +1,14 @@ // @vitest-environment jsdom import { act } from "react"; import { createRoot } from "react-dom/client"; -import type { HeartbeatRun } from "@paperclipai/shared"; +import type { HeartbeatRun, HeartbeatRunEvent, LiveEvent } from "@paperclipai/shared"; import { afterEach, expect, it, vi } from "vitest"; +import { __liveUpdatesTestUtils, type CompanyLiveEventHandler } from "../context/LiveUpdatesProvider"; +import { LiveTranscriptInterests } from "../lib/live-transcript-interests"; import { LogViewer } from "./AgentDetail"; import { LogViewer as ProductionLogViewer } from "./AgentDetail.production"; -const { log, events, empty } = vi.hoisted(() => ({ log: vi.fn(), events: vi.fn(async () => []), empty: [] })); +const { log, events, empty } = vi.hoisted(() => ({ log: vi.fn(), events: vi.fn(async (_runId?: string, _cursor?: number, _limit?: number, _options?: { signal?: AbortSignal }): Promise => []), empty: [] })); vi.mock("../api/heartbeats", () => ({ heartbeatsApi: { log, events } })); vi.mock("@tanstack/react-query", async (original) => ({ ...await original(), @@ -21,7 +23,7 @@ vi.mock("../components/transcript/RunTranscriptView", () => ({ RunTranscriptView: ({ entries }: { entries: Array<{ chunk: string }> }) =>
{entries.map(line => line.chunk).join(" ")}
, })); (globalThis as typeof globalThis & { IS_REACT_ACT_ENVIRONMENT?: boolean }).IS_REACT_ACT_ENVIRONMENT = true; -afterEach(() => { vi.restoreAllMocks(); vi.unstubAllGlobals(); vi.useRealTimers(); log.mockReset(); events.mockClear(); }); +afterEach(() => { vi.restoreAllMocks(); vi.unstubAllGlobals(); vi.useRealTimers(); log.mockReset(); events.mockReset(); events.mockResolvedValue([]); }); it.each([LogViewer, ProductionLogViewer])("retains legacy history and reads only the next offset on visibility recovery (%#)", async (Viewer) => { const visibility = vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); @@ -49,12 +51,12 @@ it.each([LogViewer, ProductionLogViewer])("retains legacy history and reads only document.dispatchEvent(new Event("visibilitychange")); }); expect(container.textContent).toContain("retained history"); - expect(log).toHaveBeenLastCalledWith("run-1", first.length, expect.any(Number)); + expect(log).toHaveBeenLastCalledWith("run-1", first.length, expect.any(Number), expect.objectContaining({ signal: expect.any(AbortSignal) })); await act(async () => complete({ content: second, nextOffset: first.length + second.length })); expect(container.textContent).toContain("retained history new output"); log.mockResolvedValueOnce({ content: first, nextOffset: first.length }); await act(async () => root.render()); - expect(log).toHaveBeenLastCalledWith("run-2", 0, expect.any(Number)); + expect(log).toHaveBeenLastCalledWith("run-2", 0, expect.any(Number), expect.objectContaining({ signal: expect.any(AbortSignal) })); expect(container.textContent).not.toContain("new output"); } finally { await act(async () => root.unmount()); @@ -62,33 +64,415 @@ it.each([LogViewer, ProductionLogViewer])("retains legacy history and reads only } }); -it.each([LogViewer, ProductionLogViewer])("polls logs when WebSocket construction fails and recovers on retry (%#)", async (Viewer) => { +it.each([LogViewer, ProductionLogViewer])("uses shared streaming and retains fallback reads until negotiation (%#)", async (Viewer) => { vi.useFakeTimers(); vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); - vi.stubGlobal("WebSocket", undefined); + const socket = vi.fn(); + vi.stubGlobal("WebSocket", class { constructor() { socket(); } }); log.mockResolvedValue({ content: "", nextOffset: 0 }); const run = { id: "run-1", companyId: "company-1", agentId: "agent-1", status: "running", logRef: "log" } as HeartbeatRun; const root = createRoot(document.createElement("div")); - const sockets: Array<{ onopen: (() => void) | null; close: () => void }> = []; + const transcripts = new LiveTranscriptInterests(); + const messages: Array<{ revision?: number; runIds?: string[] }> = []; + const subscription = { companyId: "company-1", transcripts, subscribe: () => () => {} }; + const { LiveEventSubscriptionContext } = __liveUpdatesTestUtils; try { - await act(async () => root.render()); + await act(async () => root.render()); const initialReads = log.mock.calls.length; await act(async () => vi.advanceTimersByTimeAsync(2000)); expect(log.mock.calls.length).toBeGreaterThan(initialReads); expect(events).toHaveBeenCalled(); - vi.stubGlobal("WebSocket", class { - onopen = null; - close = vi.fn(); - constructor() { sockets.push(this); } + await act(async () => { + transcripts.open({ send: text => messages.push(JSON.parse(text)) }); + transcripts.receive({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + transcripts.receive({ type: "live.subscribed", version: 1, revision: messages.at(-1)?.revision }); }); - await act(async () => vi.advanceTimersByTimeAsync(1000)); - expect(sockets).toHaveLength(1); - await act(async () => sockets[0].onopen?.()); + expect(messages.at(-1)?.runIds).toEqual([run.id]); const readsWhenConnected = log.mock.calls.length; - await act(async () => vi.advanceTimersByTimeAsync(4000)); + const eventReadsWhenConnected = events.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); expect(log).toHaveBeenCalledTimes(readsWhenConnected); + expect(events).toHaveBeenCalledTimes(eventReadsWhenConnected); + expect(socket).not.toHaveBeenCalled(); + } finally { await act(async () => root.unmount()); } + expect(messages.at(-1)?.runIds).toEqual([]); +}); + +it.each([LogViewer, ProductionLogViewer])("re-enables cancelled history paging after hiding and showing a completed run (%#)", async Viewer => { + const visibility = vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + log.mockResolvedValue({ content: "", nextOffset: 0 }); + const rows = Array.from({ length: 1001 }, (_, index) => ({ id: index + 1, seq: index + 1, + runId: "run-1", companyId: "company-1", agentId: "agent-1", createdAt: new Date(), + eventType: "output", stream: "system" as const, level: "info" as const, color: null, message: null, payload: null })); + let finishCancelled!: (rows: HeartbeatRunEvent[]) => void; + events.mockResolvedValueOnce(rows.slice(0, 1000)); + events.mockImplementationOnce(() => new Promise(resolve => { finishCancelled = resolve; })); + events.mockResolvedValueOnce(rows.slice(1000)); + const run = { id: "run-1", companyId: "company-1", agentId: "agent-1", status: "succeeded" } as HeartbeatRun; + const container = document.createElement("div"); + const root = createRoot(container); + const more = () => [...container.querySelectorAll("button")].find(button => /Load more events|Loading\.\.\./.test(button.textContent ?? "")); + try { + await act(async () => root.render()); + await act(async () => more()!.click()); + expect(more()!.disabled).toBe(true); + const cancelledSignal = events.mock.calls[1]![3]!.signal; + await act(async () => { visibility.mockReturnValue("hidden"); document.dispatchEvent(new Event("visibilitychange")); }); + expect(cancelledSignal?.aborted).toBe(true); + await act(async () => { visibility.mockReturnValue("visible"); document.dispatchEvent(new Event("visibilitychange")); }); + expect(events).toHaveBeenCalledTimes(2); + expect(more()!.disabled).toBe(false); + await act(async () => more()!.click()); + expect(events).toHaveBeenCalledTimes(3); + expect(events).toHaveBeenLastCalledWith(run.id, 1000, 1000, expect.objectContaining({ signal: expect.any(AbortSignal) })); + expect(more()).toBeUndefined(); + await act(async () => finishCancelled(rows.slice(1000))); + expect(events).toHaveBeenCalledTimes(3); + expect(more()).toBeUndefined(); + } finally { await act(async () => root.unmount()); } +}, 30_000); + +it.each([LogViewer, ProductionLogViewer])("bounds automatic event history and pages further only on request (%#)", async Viewer => { + vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + log.mockResolvedValue({ content: "", nextOffset: 0 }); + const rows = Array.from({ length: 2_001 }, (_, index) => ({ id: index + 1, seq: index + 1, + runId: "run-1", companyId: "company-1", agentId: "agent-1", createdAt: new Date(), + eventType: index === 0 ? "adapter.invoke" : "output", stream: "system" as const, level: "info" as const, + color: null, message: null, payload: index === 0 ? { command: "invocation-retained-proof", args: [], cwd: "/workspace" } : null })); + events.mockImplementation(async (_runId?: string, cursor = 0) => rows.filter(row => row.seq > cursor).slice(0, 1000)); + const run = { id: "run-1", companyId: "company-1", agentId: "agent-1", status: "succeeded" } as HeartbeatRun; + const container = document.createElement("div"); + const root = createRoot(container); + try { + await act(async () => root.render()); + expect(events).toHaveBeenCalledTimes(1); + expect(container.textContent).toContain("invocation-retained-proof"); + const more = [...container.querySelectorAll("button")].find(button => button.textContent === "Load more events"); + expect(more).toBeDefined(); + events.mockRejectedValueOnce(new Error("history unavailable")); + await act(async () => more!.click()); + expect(container.textContent).toContain("Could not load events. Try again."); + expect(container.textContent).toContain("invocation-retained-proof"); + await act(async () => more!.click()); + expect(events).toHaveBeenCalledTimes(3); + expect(container.textContent).not.toContain("Could not load events. Try again."); + expect(events).toHaveBeenLastCalledWith(run.id, 1000, 1000, expect.objectContaining({ signal: expect.any(AbortSignal) })); + expect(container.textContent).toContain("invocation-retained-proof"); + } finally { await act(async () => root.unmount()); } +}, 30_000); + +it.each([LogViewer, ProductionLogViewer])("preserves saved event details and catches up payload-free commit signals (%#)", async Viewer => { + vi.useFakeTimers(); + vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + log.mockResolvedValue({ content: "", nextOffset: 0 }); + const run = { id: "run-1", companyId: "company-1", agentId: "agent-1", status: "running" } as HeartbeatRun; + const row = (seq: number, message: string): HeartbeatRunEvent => ({ id: seq, seq, runId: run.id, + companyId: run.companyId, agentId: run.agentId, eventType: "item.completed", message, + stream: null, level: null, color: null, payload: { detail: message }, createdAt: new Date() }); + events.mockResolvedValue([row(1, "saved event details")]); + const transcripts = new LiveTranscriptInterests(); + const listeners = new Set(); + const messages: Array<{ revision?: number }> = []; + const subscription = { companyId: run.companyId, transcripts, + subscribe(fn: CompanyLiveEventHandler) { listeners.add(fn); return () => { listeners.delete(fn); }; } }; + const emit = (seq: number, details?: HeartbeatRunEvent) => { + const event: LiveEvent = { id: seq, companyId: run.companyId, type: "heartbeat.run.event", + createdAt: new Date().toISOString(), payload: details ? { ...details } : { + runId: run.id, agentId: run.agentId, eventType: "item.completed", seq, + } }; + for (const listener of listeners) listener(event); + }; + const container = document.createElement("div"); + const root = createRoot(container); + const { LiveEventSubscriptionContext } = __liveUpdatesTestUtils; + try { + await act(async () => root.render()); + await act(async () => { + transcripts.open({ send: text => messages.push(JSON.parse(text)) }); + transcripts.receive({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + transcripts.receive({ type: "live.subscribed", version: 1, revision: messages.at(-1)?.revision }); + }); + const initialReads = events.mock.calls.length; + expect(container.textContent).toContain("saved event details"); + await act(async () => emit(1)); + expect(container.textContent).toContain("saved event details"); + expect(events).toHaveBeenCalledTimes(initialReads); + events.mockResolvedValueOnce([row(2, "new canonical event details")]); + await act(async () => emit(2)); + expect(container.textContent).toContain("new canonical event details"); + expect(events).toHaveBeenLastCalledWith(run.id, 1, 1000, expect.objectContaining({ signal: expect.any(AbortSignal) })); + const caughtUpReads = events.mock.calls.length; + await act(async () => { emit(2); emit(3, row(3, "complete live event details")); }); + expect(container.textContent).toContain("complete live event details"); + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(events).toHaveBeenCalledTimes(caughtUpReads); + expect(container.textContent).toContain("saved event details"); + expect(container.textContent).toContain("new canonical event details"); + await act(async () => { + for (let seq = 4; seq <= 2_205; seq++) emit(seq, row(seq, `live row ${seq}`)); + }); + expect(container.textContent).toContain("saved event details"); + expect(container.textContent).toContain("live row 2205"); + expect(container.textContent).toContain("Events (2200)"); + await act(async () => root.render()); + expect(container.textContent).toContain("saved event details"); + expect(container.textContent).toContain("live row 2205"); + } finally { await act(async () => root.unmount()); } +}, 30_000); + +it.each([LogViewer, ProductionLogViewer])("merges saved and live rows with colliding database and run-sequence IDs (%#)", async Viewer => { + vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + const consoleError = vi.spyOn(console, "error").mockImplementation(() => {}); + log.mockResolvedValue({ content: "", nextOffset: 0 }); + const run = { id: "run-1", companyId: "company-1", agentId: "agent-1", status: "running" } as HeartbeatRun; + const row = (id: number, seq: number, message: string): HeartbeatRunEvent => ({ id, seq, runId: run.id, + companyId: run.companyId, agentId: run.agentId, eventType: "item.completed", message, + stream: null, level: null, color: null, payload: {}, createdAt: new Date() }); + events.mockResolvedValueOnce([row(2, 1, "saved first row")]); + const listeners = new Set(); + const subscription = { companyId: run.companyId, transcripts: new LiveTranscriptInterests(), + subscribe(fn: CompanyLiveEventHandler) { listeners.add(fn); return () => { listeners.delete(fn); }; } }; + const container = document.createElement("div"), root = createRoot(container); + const { LiveEventSubscriptionContext } = __liveUpdatesTestUtils; + const emit = (seq: number, message: string) => { + const event: LiveEvent = { id: seq, companyId: run.companyId, type: "heartbeat.run.event", + createdAt: new Date().toISOString(), payload: { ...row(seq, seq, message) } }; + for (const listener of listeners) listener(event); + }; + try { + await act(async () => root.render()); + await act(async () => { emit(2, "live second row"); emit(3, "live third row"); }); + expect(container.textContent).toContain("saved first row"); + expect(container.textContent).toContain("live second row"); + expect(container.textContent).toContain("live third row"); + expect(consoleError.mock.calls.filter(args => args.some(value => String(value).includes("same key")))).toEqual([]); + } finally { await act(async () => root.unmount()); } +}); + +it.each([ + { Viewer: LogViewer, stalled: "log" }, { Viewer: ProductionLogViewer, stalled: "log" }, + { Viewer: LogViewer, stalled: "events" }, { Viewer: ProductionLogViewer, stalled: "events" }, +])("finishes a slow $stalled page while the other reader catches up (%#)", async ({ Viewer, stalled }) => { + vi.useFakeTimers(); + vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + log.mockResolvedValue({ content: "" }); + const run = { id: "run-1", companyId: "company-1", agentId: "agent-1", status: "running", logRef: "log" } as HeartbeatRun; + const row = (seq: number): HeartbeatRunEvent => ({ id: seq, seq, runId: run.id, + companyId: run.companyId, agentId: run.agentId, eventType: "item.completed", message: `event ${seq}`, + stream: null, level: null, color: null, payload: {}, createdAt: new Date() }); + const logRow = (seq: number) => JSON.stringify({ seq, ts: "2026-10-24T00:00:00Z", stream: "stdout", chunk: `shell ${seq}` }) + "\n"; + const transcripts = new LiveTranscriptInterests(); + const listeners = new Set(); + const messages: Array<{ revision?: number }> = []; + const subscription = { companyId: run.companyId, transcripts, + subscribe(fn: CompanyLiveEventHandler) { listeners.add(fn); return () => { listeners.delete(fn); }; } }; + const emit = (type: LiveEvent["type"], seq: number) => { + for (const listener of listeners) listener({ id: seq, companyId: run.companyId, type, + createdAt: new Date().toISOString(), payload: { runId: run.id, agentId: run.agentId, seq, eventType: "item.completed", truncated: true, status: "succeeded" } }); + }; + const container = document.createElement("div"); + const root = createRoot(container); + const { LiveEventSubscriptionContext } = __liveUpdatesTestUtils; + let finishLog!: (value: { content: string }) => void; + let finishEvents!: (value: HeartbeatRunEvent[]) => void; + const held = stalled === "log" ? log : events; + try { + await act(async () => root.render()); + await act(async () => { + transcripts.open({ send: text => messages.push(JSON.parse(text)) }); + transcripts.receive({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + transcripts.receive({ type: "live.subscribed", version: 1, revision: messages.at(-1)?.revision }); + }); + if (stalled === "log") log.mockImplementationOnce(() => new Promise(resolve => { finishLog = resolve; })); + else events.mockImplementationOnce(() => new Promise(resolve => { finishEvents = resolve; })); + await act(async () => emit(stalled === "log" ? "heartbeat.run.log" : "heartbeat.run.event", 1)); + const calls = held.mock.calls as unknown as Array<[string, number, number, { signal: AbortSignal }]>; + const heldCount = calls.length; + const signal = calls.at(-1)![3].signal; + for (let seq = 1; seq <= 3; seq++) { + if (stalled === "log") events.mockResolvedValueOnce([row(seq)]); + else log.mockResolvedValueOnce({ content: logRow(seq) }); + await act(async () => emit(stalled === "log" ? "heartbeat.run.event" : "heartbeat.run.log", seq)); + } + expect(held).toHaveBeenCalledTimes(heldCount); + expect(signal.aborted).toBe(false); + expect(container.textContent).toContain(stalled === "log" ? "event 3" : "shell 3"); + await act(async () => { emit("heartbeat.run.status", 4); emit("heartbeat.run.status", 5); }); + expect(held).toHaveBeenCalledTimes(heldCount); + expect(signal.aborted).toBe(false); + await act(async () => { + if (stalled === "log") finishLog({ content: logRow(1) }); + else finishEvents([row(1)]); + }); + expect(held).toHaveBeenCalledTimes(heldCount + 1); + expect(container.textContent).toContain(stalled === "log" ? "shell 1" : "event 1"); + const settled = [events.mock.calls.length, log.mock.calls.length]; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect([events.mock.calls.length, log.mock.calls.length]).toEqual(settled); + } finally { await act(async () => root.unmount()); } +}); + +it.each([LogViewer, ProductionLogViewer])("shows and retries an initial event-history failure instead of claiming empty history (%#)", async Viewer => { + vi.useFakeTimers(); + vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + log.mockResolvedValue({ content: "", nextOffset: 0 }); + events.mockRejectedValue(new Error("history unavailable")); + const run = { id: "run-1", companyId: "company-1", agentId: "agent-1", status: "succeeded" } as HeartbeatRun; + const container = document.createElement("div"); + const root = createRoot(container); + try { + await act(async () => root.render()); + expect(container.textContent).toContain("Could not load events. Try again."); + expect(container.textContent).not.toContain("No log events."); + await act(async () => vi.advanceTimersByTimeAsync(2000)); + expect(events).toHaveBeenCalledTimes(2); + expect(container.textContent).toContain("Could not load events. Try again."); + events.mockResolvedValueOnce([{ id: 1, seq: 1, runId: run.id, companyId: run.companyId, agentId: run.agentId, + eventType: "item.completed", message: "Recovered history", payload: {}, stream: null, level: null, + color: null, createdAt: new Date() }]); + const retry = [...container.querySelectorAll("button")].find(button => button.textContent === "Retry events"); + expect(retry).toBeDefined(); + await act(async () => retry!.click()); + expect(container.textContent).toContain("Recovered history"); + expect(container.textContent).not.toContain("Could not load events. Try again."); + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(events).toHaveBeenCalledTimes(3); + } finally { await act(async () => root.unmount()); } +}); + + +it.each([LogViewer, ProductionLogViewer])("recovers a paginated live tail and preserves pages explicitly loaded afterward (%#)", async Viewer => { + vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + log.mockResolvedValue({ content: "", nextOffset: 0 }); + const run = { id: "run-1", companyId: "company-1", agentId: "agent-1", status: "running" } as HeartbeatRun; + const rows: HeartbeatRunEvent[] = Array.from({ length: 5_000 }, (_, index) => ({ id: index + 1, seq: index + 1, + runId: run.id, companyId: run.companyId, agentId: run.agentId, createdAt: new Date(), eventType: "output", + stream: "system", level: "info", color: null, message: `activity-proof-${index + 1}-end`, payload: null })); + events.mockImplementation(async (_runId?: string, cursor = 0) => rows.filter(row => row.seq > cursor).slice(0, 1_000)); + const transcripts = new LiveTranscriptInterests(); + const listeners = new Set(); + const sent: Array<{ revision?: number }> = []; + const subscription = { companyId: run.companyId, transcripts, + subscribe(fn: CompanyLiveEventHandler) { listeners.add(fn); return () => { listeners.delete(fn); }; } }; + const container = document.createElement("div"), root = createRoot(container); + const { LiveEventSubscriptionContext } = __liveUpdatesTestUtils; + const render = async (status = "running") => act(async () => root.render()); + const emit = (row: HeartbeatRunEvent) => { for (const listener of listeners) listener({ id: row.seq, + companyId: run.companyId, type: "heartbeat.run.event", createdAt: row.createdAt.toISOString(), payload: { ...row } }); }; + try { + await render(); + expect(events).toHaveBeenCalledTimes(1); + await act(async () => { + transcripts.open({ send: text => sent.push(JSON.parse(text)) }); + transcripts.receive({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + transcripts.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1)?.revision }); + emit(rows[4_999]!); + }); + expect(container.textContent).toContain("activity-proof-5000-end"); + expect(events.mock.calls.some(call => call[1] === 4_000)).toBe(true); + const more = () => [...container.querySelectorAll("button")].find(button => button.textContent === "Load more events")!; + await act(async () => more().click()); + expect(container.textContent).toContain("activity-proof-1500-end"); + expect(events.mock.calls.at(-1)?.slice(0, 3)).toEqual([run.id, 1_000, 1_000]); + rows.push({ ...rows[0]!, id: 5_001, seq: 5_001, message: "resync-tail-proof" }); + await act(async () => { + transcripts.receive({ type: "live.resync", version: 1, revision: sent.at(-1)?.revision, reason: "delivery_overflow" }); + transcripts.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1)?.revision }); + }); + expect(container.textContent).toContain("resync-tail-proof"); + expect(container.textContent).toContain("activity-proof-1500-end"); + rows.push({ ...rows[0]!, id: 5_002, seq: 5_002, message: "terminal-tail-proof" }); + await render("succeeded"); + expect(container.textContent).toContain("terminal-tail-proof"); + expect(container.textContent).toContain("activity-proof-1500-end"); + } finally { await act(async () => root.unmount()); } +}, 60_000); + + +it.each([LogViewer, ProductionLogViewer].flatMap(Viewer => ["completed-return", "catchup-retry"].map(mode => ({ Viewer, mode }))))("preserves event read mode for $mode (%#)", async ({ Viewer, mode }) => { + vi.useFakeTimers(); + const visibility = vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + log.mockResolvedValue({ content: "", nextOffset: 0 }); + const run = { id: "run-1", companyId: "company-1", agentId: "agent-1", status: mode === "completed-return" ? "succeeded" : "running" } as HeartbeatRun; + const rows: HeartbeatRunEvent[] = Array.from({ length: mode === "completed-return" ? 2_001 : 5_000 }, (_, index) => ({ + id: index + 1, seq: index + 1, runId: run.id, companyId: run.companyId, agentId: run.agentId, + createdAt: new Date(), eventType: "output", stream: "system", level: "info", color: null, + message: `mode-proof-${index + 1}-end`, payload: null, + })); + let failRecovery = mode === "catchup-retry"; + events.mockImplementation(async (_id, cursor = 0) => { + if (cursor === 4_000 && failRecovery) { failRecovery = false; throw new Error("saved tail temporarily unavailable"); } + return rows.filter(row => row.seq > cursor).slice(0, 1_000); + }); + const transcripts = new LiveTranscriptInterests(), sent: Array<{ revision?: number }> = []; + const subscription = { companyId: run.companyId, transcripts, subscribe: () => () => {} }; + const container = document.createElement("div"), root = createRoot(container); + const { LiveEventSubscriptionContext } = __liveUpdatesTestUtils; + try { + await act(async () => root.render()); + expect(events).toHaveBeenCalledTimes(1); + if (mode === "completed-return") { + await act(async () => { visibility.mockReturnValue("hidden"); document.dispatchEvent(new Event("visibilitychange")); }); + await act(async () => { visibility.mockReturnValue("visible"); document.dispatchEvent(new Event("visibilitychange")); }); + expect(events).toHaveBeenCalledTimes(1); + expect(container.textContent).not.toContain("mode-proof-2001-end"); + } else { + await act(async () => { + transcripts.open({ send: text => sent.push(JSON.parse(text)) }); + transcripts.receive({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + transcripts.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1)?.revision }); + }); + expect(container.textContent).toContain("Could not load events. Try again."); + const retry = [...container.querySelectorAll("button")].find(button => button.textContent === "Retry events"); + expect(retry).toBeDefined(); + await act(async () => retry!.click()); + expect(container.textContent).toContain("mode-proof-5000-end"); + expect(events.mock.calls.filter(call => call[1] === 4_000)).toHaveLength(2); + const caughtUp = events.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(events).toHaveBeenCalledTimes(caughtUp); + } + } finally { await act(async () => root.unmount()); } +}, 60_000); + +it.each([LogViewer, ProductionLogViewer])("recovers the latest saved tail when acknowledgement aborts the initial history read (%#)", async Viewer => { + vi.useFakeTimers(); + vi.spyOn(document, "visibilityState", "get").mockReturnValue("visible"); + log.mockResolvedValue({ content: "", nextOffset: 0 }); + const run = { id: "run-1", companyId: "company-1", agentId: "agent-1", status: "running" } as HeartbeatRun; + const rows: HeartbeatRunEvent[] = Array.from({ length: 5_000 }, (_, index) => ({ + id: index + 1, seq: index + 1, runId: run.id, companyId: run.companyId, agentId: run.agentId, + createdAt: new Date(), eventType: "output", stream: "system", level: "info", color: null, + message: `initial-ack-proof-${index + 1}-end`, payload: null, + })); + let finishInitial!: (value: HeartbeatRunEvent[]) => void; + events.mockImplementation((_id, cursor = 0) => Promise.resolve(rows.filter(row => row.seq > cursor).slice(0, 1_000))); + events.mockImplementationOnce(() => new Promise(resolve => { finishInitial = resolve; })); + const transcripts = new LiveTranscriptInterests(), sent: Array<{ revision?: number }> = []; + const subscription = { companyId: run.companyId, transcripts, subscribe: () => () => {} }; + const container = document.createElement("div"), root = createRoot(container); + const { LiveEventSubscriptionContext } = __liveUpdatesTestUtils; + try { + await act(async () => root.render()); + const initialSignal = events.mock.calls[0]![3]!.signal!; + await act(async () => { + transcripts.open({ send: text => sent.push(JSON.parse(text)) }); + transcripts.receive({ type: "live.capabilities", version: 1, capabilities: ["run-interests"] }); + transcripts.receive({ type: "live.subscribed", version: 1, revision: sent.at(-1)?.revision }); + }); + expect(initialSignal.aborted).toBe(true); + expect(container.textContent).toContain("initial-ack-proof-5000-end"); + const more = [...container.querySelectorAll("button")].find(button => button.textContent === "Load more events"); + expect(more).toBeDefined(); + await act(async () => more!.click()); + expect(events.mock.calls.at(-1)?.slice(0, 3)).toEqual([run.id, 1_000, 1_000]); + expect(container.textContent).toContain("initial-ack-proof-1500-end"); + expect(container.textContent).toContain("initial-ack-proof-5000-end"); + const settledReads = events.mock.calls.length; + await act(async () => vi.advanceTimersByTimeAsync(90_000)); + expect(events).toHaveBeenCalledTimes(settledReads); } finally { + finishInitial([]); await act(async () => root.unmount()); } - expect(sockets[0].close).toHaveBeenCalled(); -}); +}, 60_000); diff --git a/ui/src/pages/AgentDetail.production.tsx b/ui/src/pages/AgentDetail.production.tsx index b89c8f42501..b2998335d84 100644 --- a/ui/src/pages/AgentDetail.production.tsx +++ b/ui/src/pages/AgentDetail.production.tsx @@ -1,8 +1,12 @@ +import { TranscriptSequence } from "../lib/transcript-sequence"; +import { readTranscriptRequest } from "../components/transcript/read-transcript-request"; +import { useTranscriptLiveStream } from "../context/LiveUpdatesProvider"; +import { liveRunEvent, mergeRunEvents } from "../lib/live-run-event"; import { useSelectedHeartbeatRun } from "../hooks/useSelectedHeartbeatRun"; import { AgentCharacter } from "../components/AgentCharacter"; import { characterStateForAgent } from "@paperclipai/shared"; import { mergeRunLogChunks, readChunkSeq } from "../lib/run-log-chunks"; -import { getPageVisibility, usePageVisibility } from "../lib/page-visibility"; +import { usePageVisibility } from "../lib/page-visibility"; import { useCallback, useEffect, useMemo, useState, useRef } from "react"; import { useParams, useNavigate, useLocation, Link, Navigate, useBeforeUnload, type NavigateFunction } from "@/lib/router"; import { useQuery, useMutation, useQueryClient, type QueryClient } from "@tanstack/react-query"; @@ -64,8 +68,6 @@ import { ScrollToBottom } from "../components/ScrollToBottom"; import { SourceResolvedFoldCallout } from "../components/SourceResolvedFoldCallout"; import { SourceResolvedFoldBadge } from "../components/SourceResolvedFoldBadge"; import { readSourceResolvedWatchdogFold } from "../lib/source-resolved-watchdog-fold"; -import { buildSameOriginWebSocketUrl } from "../lib/websocket-url"; -import { tryCreateWebSocket } from "../lib/websocket"; import { formatCents, formatDate, relativeTime, formatTokens, visibleRunCostUsd, visibleRunTokenTotal } from "../lib/utils"; import { cn } from "../lib/utils"; import { describeRunRetryState } from "../lib/runRetryState"; @@ -101,7 +103,6 @@ import { AgentToolsTab } from "./AgentToolsTab"; import { AgentChannelsPanel } from "../components/chat/AgentChannelsPanel"; import { useChatConnectorsEnabled } from "@/hooks/useChatConnectorsEnabled"; import { - appendCapped, LIVE_TRANSCRIPT_RENDER_LIMIT, MAX_LIVE_EVENTS, MAX_LIVE_LOG_LINES, @@ -3733,6 +3734,11 @@ function RunDetail({ run: initialRun, agentRouteId, adapterType, adapterConfig } export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType: string }) { const { visible } = usePageVisibility(); const [events, setEvents] = useState([]); + const [hasMoreEvents, setHasMoreEvents] = useState(false); + const [eventsError, setEventsError] = useState(null); + const hasMoreEventsRef = useRef(false); + const [loadingMoreEvents, setLoadingMoreEvents] = useState(false); + const loadMoreEventsRef = useRef<(() => void) | null>(null); const [logLines, setLogLines] = useState([]); const [loading, setLoading] = useState(true); const [logLoading, setLogLoading] = useState(!!run.logRef); @@ -3747,7 +3753,6 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType const [hasMoreLog, setHasMoreLog] = useState(false); const [loadingMoreLog, setLoadingMoreLog] = useState(false); const [isFollowing, setIsFollowing] = useState(false); - const [isStreamingConnected, setIsStreamingConnected] = useState(false); const [transcriptMode, setTranscriptMode] = useState("nice"); const logEndRef = useRef(null); const pendingLogLineRef = useRef(""); @@ -3797,7 +3802,9 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType const chunk = typeof raw.chunk === "string" ? raw.chunk : ""; const ts = typeof raw.ts === "string" ? raw.ts : new Date().toISOString(); if (!chunk) continue; - parsed.push({ ts, stream, chunk, seq: readChunkSeq(raw.seq) }); + const seq = readChunkSeq(raw.seq); + logSequenceRef.current.confirm(seq); + parsed.push({ ts, stream, chunk, seq }); } catch { // ignore malformed lines } @@ -3810,18 +3817,145 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType } } - // Fetch events - const { data: initialEvents } = useQuery({ - queryKey: ["run-events", run.id], - queryFn: () => heartbeatsApi.events(run.id, 0, 200), + const refreshEventsRef = useRef<((force?: boolean) => void) | null>(null); + const refreshLogRef = useRef<((force?: boolean) => void) | null>(null); + const eventSequenceRef = useRef(new TranscriptSequence()); + const logSequenceRef = useRef(new TranscriptSequence()); + const eventsReadCursorRef = useRef(0); + const eventsCatchupCursorRef = useRef(0); + const retainedEventHistoryThroughRef = useRef(0); + const logIdentityRef = useRef(run.logRef ?? null); + const retiredLogRefs = useRef(new Set()); + const wasLiveRef = useRef(isLive); + const bindLog = (ref: unknown): "same" | "changed" | "stale" => { + if (typeof ref !== "string" || !ref || ref === logIdentityRef.current) return "same"; + if (retiredLogRefs.current.has(ref)) return "stale"; + const prior = logIdentityRef.current; + logIdentityRef.current = ref; + if (!prior) return "same"; + retiredLogRefs.current.add(prior); + if (retiredLogRefs.current.size > 8) retiredLogRefs.current.delete(retiredLogRefs.current.values().next().value!); + pendingLogLineRef.current = ""; + logMergeRefs.current = { seenChunkKeys: new Set(), trimmedSeqFloorByRun: new Map() }; + logSequenceRef.current = new TranscriptSequence(); + setLogLines([]); setLogOffset(0); + return "changed"; + }; + useEffect(() => { + eventsReadCursorRef.current = 0; eventsCatchupCursorRef.current = 0; retainedEventHistoryThroughRef.current = 0; eventSequenceRef.current = new TranscriptSequence(); logSequenceRef.current = new TranscriptSequence(); + wasLiveRef.current = isLive; + logIdentityRef.current = run.logRef ?? null; retiredLogRefs.current.clear(); + hasMoreEventsRef.current = false; setHasMoreEvents(false); setLoadingMoreEvents(false); setEventsError(null); + setEvents([]); setLoading(true); + }, [run.id, run.companyId]); + useEffect(() => { if (isLive) wasLiveRef.current = true; }, [isLive]); + + function appendEvents(rows: HeartbeatRunEvent[], retainHistory = false) { + if (retainHistory) retainedEventHistoryThroughRef.current = Math.max( + retainedEventHistoryThroughRef.current, rows.at(-1)?.seq ?? 0, + ); + setEvents(previous => { + const merged = mergeRunEvents(previous, rows); + if (!isLive && !wasLiveRef.current) return merged; + const retainedThrough = Math.max(200, retainedEventHistoryThroughRef.current); + const prefix = merged.filter(row => row.seq <= retainedThrough); + const tail = merged.filter(row => row.seq > retainedThrough); + return [...prefix, ...tail.slice(-MAX_LIVE_EVENTS)]; + }); + } + + const stream = useTranscriptLiveStream(isLive ? [run.id] : [], { companyId: run.companyId, enabled: visible }, event => { + if (event.companyId !== run.companyId) return; + const payload = asRecord(event.payload); + if (!payload || payload.runId !== run.id) return; + if (event.type === "heartbeat.run.log") { + const binding = bindLog(payload.logRef); + if (binding === "stale") return; + const seq = readChunkSeq(payload.seq); + if (payload.truncated === true) logSequenceRef.current.requireHistory(seq); + const gap = logSequenceRef.current.observe(seq); + if (binding === "changed" || payload.truncated === true || gap) refreshLogRef.current?.(); + if (payload.truncated === true) return; + const chunk = typeof payload.chunk === "string" ? payload.chunk : ""; + if (!chunk) return; + const channel = payload.stream === "stderr" || payload.stream === "system" ? payload.stream : "stdout"; + appendLogLines([{ ts: asNonEmptyString(payload.ts) ?? event.createdAt, stream: channel, chunk, seq }]); + return; + } + if (event.type === "heartbeat.run.progress") { + const line = buildHeartbeatProgressLogLine(payload, event.createdAt); + if (!line) return; + const key = heartbeatProgressLogLineKey(line); + if (seenProgressLogLineKeysRef.current.has(key)) return; + seenProgressLogLineKeysRef.current.add(key); appendLogLines([line]); + return; + } + if (event.type === "heartbeat.run.status") { + refreshEventsRef.current?.(true); refreshLogRef.current?.(true); return; + } + const row = liveRunEvent(event); + if (!row) return; + const commitSignal = row.message === null && row.payload === null; + if (commitSignal) eventSequenceRef.current.requireHistory(row.seq); + if (eventSequenceRef.current.observe(row.seq)) refreshEventsRef.current?.(); + if (commitSignal) return; + appendEvents([row]); }); useEffect(() => { - if (initialEvents) { - setEvents(initialEvents); - setLoading(false); - } - }, [initialEvents]); + setLoadingMoreEvents(false); + if (!visible) return; + let cancelled = false; + let timer: number | undefined; + const abort = new AbortController(); + let reading = false; + let pendingRefresh = false; + let failedRead: { requested: boolean; catchup: boolean } | null = null; + const read = async (requested = false, catchup = false) => { + if (cancelled) return; + if (reading) { if (catchup) pendingRefresh = true; return; } + if (hasMoreEventsRef.current && !requested && !catchup) return; + reading = true; pendingRefresh = false; setLoadingMoreEvents(true); setEventsError(null); + window.clearTimeout(timer); timer = undefined; + let failed = false; + try { + const cursor = catchup ? Math.max(eventsCatchupCursorRef.current, eventsReadCursorRef.current) : eventsReadCursorRef.current; + const initializesHistory = eventsReadCursorRef.current === 0; + const rows = await readTranscriptRequest(signal => heartbeatsApi.events(run.id, cursor, 1000, { signal }), abort.signal); + if (cancelled) return; + appendEvents(rows, !catchup || initializesHistory); + const next = Math.max(cursor, rows.at(-1)?.seq ?? cursor); + eventsCatchupCursorRef.current = Math.max(eventsCatchupCursorRef.current, next); + eventSequenceRef.current.confirm(next); + if (catchup) { + if (rows.length === 1000 && next > cursor) pendingRefresh = true; + } + if (!catchup || initializesHistory) { + eventsReadCursorRef.current = next; + hasMoreEventsRef.current = rows.length === 1000 && next > cursor; + setHasMoreEvents(hasMoreEventsRef.current); + } + failed = eventSequenceRef.current.needsCatchup; + failedRead = null; + } catch { + failed = true; failedRead = { requested, catchup }; + if (!cancelled) setEventsError("Could not load events. Try again."); + } + if (cancelled) return; + reading = false; setLoadingMoreEvents(false); setLoading(false); + if (pendingRefresh) void read(false, true); + else if (failed || (isLive && !stream.healthy && !hasMoreEventsRef.current)) { + timer = window.setTimeout(() => void read(requested, catchup || eventSequenceRef.current.needsCatchup), 2000); + } + }; + refreshEventsRef.current = () => { void read(false, wasLiveRef.current); }; + loadMoreEventsRef.current = () => { void read(failedRead?.requested ?? true, failedRead?.catchup ?? false); }; + void read(false, wasLiveRef.current && (stream.healthy || eventsReadCursorRef.current > 0)); + return () => { + cancelled = true; refreshEventsRef.current = null; loadMoreEventsRef.current = null; + abort.abort(); if (timer !== undefined) window.clearTimeout(timer); + }; + }, [visible, run.id, run.companyId, run.status, stream.healthy, stream.epoch]); const getScrollContainer = useCallback((): ScrollContainer => { if (scrollContainerRef.current) return scrollContainerRef.current; @@ -3916,45 +4050,50 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType setLogError(null); }, [run.id, run.logRef, setLogOffset]); - // Fetch persisted shell log, retaining partial rows and offsets across hides. useEffect(() => { if (!visible) return; + if (!run.logRef && !shouldPollShellLog) { setLogLoading(false); return; } let cancelled = false; - const offset = logOffsetRef.current; - if (!run.logRef && !shouldPollShellLog) { - setLogLoading(false); - return () => { - cancelled = true; - }; - } - + let timer: number | undefined; + const abort = new AbortController(); setLogLoading(true); + let reading = false; + let pendingRefresh = false; const load = async () => { + if (cancelled || reading) return; + reading = true; pendingRefresh = false; + window.clearTimeout(timer); timer = undefined; + let failed = false; try { - const result = await heartbeatsApi.log(run.id, offset, RUN_LOG_PAGE_BYTES); - if (cancelled) return; - appendLogContent(result.content, result.nextOffset === undefined); - const next = result.nextOffset ?? offset + result.content.length; - setLogOffset(next); - setHasMoreLog(!shouldPollShellLog && result.nextOffset !== undefined); - } catch (err) { - if (!cancelled) { - if (shouldPollShellLog && isRunLogUnavailable(err)) { - setLogLoading(false); - return; - } - setLogError(err instanceof Error ? err.message : "Failed to load run log"); + for (;;) { + const offset = logOffsetRef.current; + const result = await readTranscriptRequest(signal => heartbeatsApi.log(run.id, offset, RUN_LOG_PAGE_BYTES, { signal }), abort.signal); + if (cancelled) return; + const binding = bindLog(result.logRef); + if (binding === "stale") { failed = true; break; } + if (binding === "changed" && offset !== 0) continue; + appendLogContent(result.content, result.nextOffset === undefined); + const next = result.nextOffset ?? offset + new TextEncoder().encode(result.content).byteLength; + setLogOffset(next); setLogError(null); + setHasMoreLog(!wasLiveRef.current && result.nextOffset !== undefined && !!result.content); + if (!wasLiveRef.current || result.nextOffset === undefined || !result.content || next <= offset) break; } - } finally { - if (!cancelled) setLogLoading(false); + failed ||= logSequenceRef.current.needsCatchup; + } catch (err) { + if (cancelled) return; + failed = shouldPollShellLog || !isRunLogUnavailable(err); + if (!isRunLogUnavailable(err)) setLogError(err instanceof Error ? err.message : "Failed to load run log"); } + if (cancelled) return; + reading = false; + setLogLoading(false); + if (pendingRefresh) void load(); + else if (failed || (shouldPollShellLog && !stream.healthy)) timer = window.setTimeout(() => void load(), 2000); }; - + refreshLogRef.current = (force = false) => { if (force) pendingRefresh = true; void load(); }; void load(); - return () => { - cancelled = true; - }; - }, [visible, run.id, run.logRef, run.logBytes, shouldPollShellLog]); + return () => { cancelled = true; refreshLogRef.current = null; abort.abort(); if (timer !== undefined) window.clearTimeout(timer); }; + }, [visible, run.id, run.companyId, run.logRef, isLive ? null : run.logBytes, shouldPollShellLog, stream.healthy, stream.epoch]); async function loadMorePersistedLog() { if (loadingMoreLog || !hasMoreLog) return; @@ -3963,7 +4102,7 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType try { const result = await heartbeatsApi.log(run.id, logOffset, RUN_LOG_PAGE_BYTES); appendLogContent(result.content, result.nextOffset === undefined); - const next = result.nextOffset ?? logOffset + result.content.length; + const next = result.nextOffset ?? logOffset + new TextEncoder().encode(result.content).byteLength; setLogOffset(next); setHasMoreLog(result.nextOffset !== undefined); } catch (err) { @@ -3973,192 +4112,6 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType } } - // Poll for live updates - useEffect(() => { - if (!visible || !isLive || isStreamingConnected) return; - let pending = false; - let cancelled = false; - const interval = setInterval(async () => { - if (pending || cancelled || !getPageVisibility().visible) return; - pending = true; - const maxSeq = events.length > 0 ? Math.max(...events.map((e) => e.seq)) : 0; - try { - const newEvents = await heartbeatsApi.events(run.id, maxSeq, 100); - if (cancelled) return; - if (newEvents.length > 0) { - setEvents((prev) => appendCapped(prev, newEvents, MAX_LIVE_EVENTS)); - } - } catch { - // ignore polling errors - } finally { - pending = false; - } - }, 2000); - return () => { - cancelled = true; - clearInterval(interval); - }; - }, [visible, run.id, isLive, isStreamingConnected, events]); - - // Poll shell log for running runs - useEffect(() => { - if (!visible || !shouldPollShellLog || isStreamingConnected) return; - let pending = false; - let cancelled = false; - const interval = setInterval(async () => { - if (pending || cancelled || !getPageVisibility().visible) return; - pending = true; - try { - const result = await heartbeatsApi.log(run.id, logOffset, 256_000); - if (cancelled) return; - if (result.content) { - appendLogContent(result.content, result.nextOffset === undefined); - } - if (result.nextOffset !== undefined) { - setLogOffset(result.nextOffset); - } else if (result.content.length > 0) { - setLogOffset((prev) => prev + result.content.length); - } - } catch (err) { - if (isRunLogUnavailable(err)) return; - // ignore polling errors - } finally { - pending = false; - } - }, 2000); - return () => { - cancelled = true; - clearInterval(interval); - }; - }, [visible, run.id, shouldPollShellLog, isStreamingConnected, logOffset]); - - // Stream live updates from websocket (primary path for running runs). - useEffect(() => { - if (!visible || !isLive) return; - - let closed = false; - let reconnectTimer: number | null = null; - let socket: WebSocket | null = null; - - const scheduleReconnect = () => { - if (closed) return; - reconnectTimer = window.setTimeout(connect, 1500); - }; - - const connect = () => { - if (closed) return; - const url = buildSameOriginWebSocketUrl( - `/api/companies/${encodeURIComponent(run.companyId)}/events/ws`, - ); - socket = tryCreateWebSocket(url); - if (!socket) { - scheduleReconnect(); - return; - } - - socket.onopen = () => { - setIsStreamingConnected(true); - }; - - socket.onmessage = (message) => { - const rawMessage = typeof message.data === "string" ? message.data : ""; - if (!rawMessage) return; - - let event: LiveEvent; - try { - event = JSON.parse(rawMessage) as LiveEvent; - } catch { - return; - } - - if (event.companyId !== run.companyId) return; - const payload = asRecord(event.payload); - const eventRunId = asNonEmptyString(payload?.runId); - if (!payload || eventRunId !== run.id) return; - - if (event.type === "heartbeat.run.log") { - const chunk = typeof payload.chunk === "string" ? payload.chunk : ""; - if (!chunk) return; - const streamRaw = asNonEmptyString(payload.stream); - const stream = streamRaw === "stderr" || streamRaw === "system" ? streamRaw : "stdout"; - const ts = asNonEmptyString((payload as Record).ts) ?? event.createdAt; - appendLogLines([{ ts, stream, chunk, seq: readChunkSeq(payload.seq) }]); - return; - } - - if (event.type === "heartbeat.run.progress") { - const line = buildHeartbeatProgressLogLine(payload, event.createdAt); - if (!line) return; - const key = heartbeatProgressLogLineKey(line); - if (seenProgressLogLineKeysRef.current.has(key)) return; - seenProgressLogLineKeysRef.current.add(key); - appendLogLines([line]); - return; - } - - if (event.type !== "heartbeat.run.event") return; - - const seq = typeof payload.seq === "number" ? payload.seq : null; - if (seq === null || !Number.isFinite(seq)) return; - - const streamRaw = asNonEmptyString(payload.stream); - const stream = - streamRaw === "stdout" || streamRaw === "stderr" || streamRaw === "system" - ? streamRaw - : null; - const levelRaw = asNonEmptyString(payload.level); - const level = - levelRaw === "info" || levelRaw === "warn" || levelRaw === "error" - ? levelRaw - : null; - - const liveEvent: HeartbeatRunEvent = { - id: seq, - companyId: run.companyId, - runId: run.id, - agentId: run.agentId, - seq, - eventType: asNonEmptyString(payload.eventType) ?? "event", - stream, - level, - color: asNonEmptyString(payload.color), - message: asNonEmptyString(payload.message), - payload: asRecord(payload.payload), - createdAt: new Date(event.createdAt), - }; - - setEvents((prev) => { - if (prev.some((existing) => existing.seq === seq)) return prev; - return appendCapped(prev, [liveEvent], MAX_LIVE_EVENTS); - }); - }; - - socket.onerror = () => { - socket?.close(); - }; - - socket.onclose = () => { - setIsStreamingConnected(false); - scheduleReconnect(); - }; - }; - - connect(); - - return () => { - closed = true; - setIsStreamingConnected(false); - if (reconnectTimer !== null) window.clearTimeout(reconnectTimer); - if (socket) { - socket.onopen = null; - socket.onmessage = null; - socket.onerror = null; - socket.onclose = null; - socket.close(1000, "run_detail_unmount"); - } - }; - }, [visible, isLive, run.companyId, run.id, run.agentId]); - const censorUsernameInLogs = useQuery({ queryKey: queryKeys.instance.generalSettings, queryFn: () => instanceSettingsApi.getGeneral(), @@ -4200,7 +4153,7 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType return

Loading run logs...

; } - if (events.length === 0 && logLines.length === 0 && !logError) { + if (events.length === 0 && logLines.length === 0 && !logError && !eventsError) { return

No log events.

; } @@ -4346,9 +4299,15 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType )} - {events.length > 0 && ( + {(events.length > 0 || eventsError) && (
Events ({events.length})
+ {eventsError &&

{eventsError}

} + {(hasMoreEvents || eventsError) && ( + + )}
{events.map((evt) => { const color = evt.color @@ -4357,7 +4316,7 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType ?? "text-foreground"; return ( -
+
{new Date(evt.createdAt).toLocaleTimeString("en-US", { hour12: false })} diff --git a/ui/src/pages/AgentDetail.tsx b/ui/src/pages/AgentDetail.tsx index 5a2693c0e2d..47492b31a53 100644 --- a/ui/src/pages/AgentDetail.tsx +++ b/ui/src/pages/AgentDetail.tsx @@ -1,3 +1,7 @@ +import { TranscriptSequence } from "../lib/transcript-sequence"; +import { readTranscriptRequest } from "../components/transcript/read-transcript-request"; +import { useTranscriptLiveStream } from "../context/LiveUpdatesProvider"; +import { liveRunEvent, mergeRunEvents } from "../lib/live-run-event"; import { useSelectedHeartbeatRun } from "../hooks/useSelectedHeartbeatRun"; import { grokBotApi } from "@/api/grokBot"; import { GrokBotWorkSummary } from "@/components/GrokBotWorkSummary"; @@ -9,7 +13,7 @@ import { InstructionHistory } from "../components/InstructionHistory"; import { AgentCharacter } from "../components/AgentCharacter"; import { characterStateForAgent } from "@paperclipai/shared"; import { mergeRunLogChunks, readChunkSeq } from "../lib/run-log-chunks"; -import { getPageVisibility, usePageVisibility } from "../lib/page-visibility"; +import { usePageVisibility } from "../lib/page-visibility"; import { useCallback, useEffect, useMemo, useState, useRef } from "react"; import { useParams, useNavigate, useLocation, Link, Navigate, useBeforeUnload, type NavigateFunction } from "@/lib/router"; import { useQuery, useMutation, useQueryClient, type QueryClient } from "@tanstack/react-query"; @@ -69,8 +73,6 @@ import { ScrollToBottom } from "../components/ScrollToBottom"; import { SourceResolvedFoldCallout } from "../components/SourceResolvedFoldCallout"; import { SourceResolvedFoldBadge } from "../components/SourceResolvedFoldBadge"; import { readSourceResolvedWatchdogFold } from "../lib/source-resolved-watchdog-fold"; -import { buildSameOriginWebSocketUrl } from "../lib/websocket-url"; -import { tryCreateWebSocket } from "../lib/websocket"; import { formatDate, relativeTime, formatTokens, visibleRunCostUsd, visibleRunTokenTotal, hasUnavailableProviderAccounting, supportsRawProviderTrace } from "../lib/utils"; import { cn } from "../lib/utils"; import { RunRetryDetails } from "../components/RunRetryDetails"; @@ -107,7 +109,6 @@ import { RunTranscriptView, type TranscriptMode } from "../components/transcript import { AgentToolsTab } from "./AgentToolsTab"; import { AgentChannelsPanel } from "../components/chat/AgentChannelsPanel"; import { - appendCapped, LIVE_TRANSCRIPT_RENDER_LIMIT, MAX_LIVE_EVENTS, MAX_LIVE_LOG_LINES, @@ -4022,6 +4023,11 @@ function RunDetail({ run: initialRun, agentRouteId, adapterType, adapterConfig } export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType: string }) { const { visible } = usePageVisibility(); const [events, setEvents] = useState([]); + const [hasMoreEvents, setHasMoreEvents] = useState(false); + const [eventsError, setEventsError] = useState(null); + const hasMoreEventsRef = useRef(false); + const [loadingMoreEvents, setLoadingMoreEvents] = useState(false); + const loadMoreEventsRef = useRef<(() => void) | null>(null); const [logLines, setLogLines] = useState([]); const [loading, setLoading] = useState(true); const [logLoading, setLogLoading] = useState(!!run.logRef); @@ -4036,7 +4042,6 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType const [hasMoreLog, setHasMoreLog] = useState(false); const [loadingMoreLog, setLoadingMoreLog] = useState(false); const [isFollowing, setIsFollowing] = useState(false); - const [isStreamingConnected, setIsStreamingConnected] = useState(false); const [transcriptMode, setTranscriptMode] = useState("nice"); const logEndRef = useRef(null); const pendingLogLineRef = useRef(""); @@ -4086,7 +4091,9 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType const chunk = typeof raw.chunk === "string" ? raw.chunk : ""; const ts = typeof raw.ts === "string" ? raw.ts : new Date().toISOString(); if (!chunk) continue; - parsed.push({ ts, stream, chunk, seq: readChunkSeq(raw.seq) }); + const seq = readChunkSeq(raw.seq); + logSequenceRef.current.confirm(seq); + parsed.push({ ts, stream, chunk, seq }); } catch { // ignore malformed lines } @@ -4099,18 +4106,145 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType } } - // Fetch events - const { data: initialEvents } = useQuery({ - queryKey: ["run-events", run.id], - queryFn: () => heartbeatsApi.events(run.id, 0, 200), + const refreshEventsRef = useRef<((force?: boolean) => void) | null>(null); + const refreshLogRef = useRef<((force?: boolean) => void) | null>(null); + const eventSequenceRef = useRef(new TranscriptSequence()); + const logSequenceRef = useRef(new TranscriptSequence()); + const eventsReadCursorRef = useRef(0); + const eventsCatchupCursorRef = useRef(0); + const retainedEventHistoryThroughRef = useRef(0); + const logIdentityRef = useRef(run.logRef ?? null); + const retiredLogRefs = useRef(new Set()); + const wasLiveRef = useRef(isLive); + const bindLog = (ref: unknown): "same" | "changed" | "stale" => { + if (typeof ref !== "string" || !ref || ref === logIdentityRef.current) return "same"; + if (retiredLogRefs.current.has(ref)) return "stale"; + const prior = logIdentityRef.current; + logIdentityRef.current = ref; + if (!prior) return "same"; + retiredLogRefs.current.add(prior); + if (retiredLogRefs.current.size > 8) retiredLogRefs.current.delete(retiredLogRefs.current.values().next().value!); + pendingLogLineRef.current = ""; + logMergeRefs.current = { seenChunkKeys: new Set(), trimmedSeqFloorByRun: new Map() }; + logSequenceRef.current = new TranscriptSequence(); + setLogLines([]); setLogOffset(0); + return "changed"; + }; + useEffect(() => { + eventsReadCursorRef.current = 0; eventsCatchupCursorRef.current = 0; retainedEventHistoryThroughRef.current = 0; eventSequenceRef.current = new TranscriptSequence(); logSequenceRef.current = new TranscriptSequence(); + wasLiveRef.current = isLive; + logIdentityRef.current = run.logRef ?? null; retiredLogRefs.current.clear(); + hasMoreEventsRef.current = false; setHasMoreEvents(false); setLoadingMoreEvents(false); setEventsError(null); + setEvents([]); setLoading(true); + }, [run.id, run.companyId]); + useEffect(() => { if (isLive) wasLiveRef.current = true; }, [isLive]); + + function appendEvents(rows: HeartbeatRunEvent[], retainHistory = false) { + if (retainHistory) retainedEventHistoryThroughRef.current = Math.max( + retainedEventHistoryThroughRef.current, rows.at(-1)?.seq ?? 0, + ); + setEvents(previous => { + const merged = mergeRunEvents(previous, rows); + if (!isLive && !wasLiveRef.current) return merged; + const retainedThrough = Math.max(200, retainedEventHistoryThroughRef.current); + const prefix = merged.filter(row => row.seq <= retainedThrough); + const tail = merged.filter(row => row.seq > retainedThrough); + return [...prefix, ...tail.slice(-MAX_LIVE_EVENTS)]; + }); + } + + const stream = useTranscriptLiveStream(isLive ? [run.id] : [], { companyId: run.companyId, enabled: visible }, event => { + if (event.companyId !== run.companyId) return; + const payload = asRecord(event.payload); + if (!payload || payload.runId !== run.id) return; + if (event.type === "heartbeat.run.log") { + const binding = bindLog(payload.logRef); + if (binding === "stale") return; + const seq = readChunkSeq(payload.seq); + if (payload.truncated === true) logSequenceRef.current.requireHistory(seq); + const gap = logSequenceRef.current.observe(seq); + if (binding === "changed" || payload.truncated === true || gap) refreshLogRef.current?.(); + if (payload.truncated === true) return; + const chunk = typeof payload.chunk === "string" ? payload.chunk : ""; + if (!chunk) return; + const channel = payload.stream === "stderr" || payload.stream === "system" ? payload.stream : "stdout"; + appendLogLines([{ ts: asNonEmptyString(payload.ts) ?? event.createdAt, stream: channel, chunk, seq }]); + return; + } + if (event.type === "heartbeat.run.progress") { + const line = buildHeartbeatProgressLogLine(payload, event.createdAt); + if (!line) return; + const key = heartbeatProgressLogLineKey(line); + if (seenProgressLogLineKeysRef.current.has(key)) return; + seenProgressLogLineKeysRef.current.add(key); appendLogLines([line]); + return; + } + if (event.type === "heartbeat.run.status") { + refreshEventsRef.current?.(true); refreshLogRef.current?.(true); return; + } + const row = liveRunEvent(event); + if (!row) return; + const commitSignal = row.message === null && row.payload === null; + if (commitSignal) eventSequenceRef.current.requireHistory(row.seq); + if (eventSequenceRef.current.observe(row.seq)) refreshEventsRef.current?.(); + if (commitSignal) return; + appendEvents([row]); }); useEffect(() => { - if (initialEvents) { - setEvents(initialEvents); - setLoading(false); - } - }, [initialEvents]); + setLoadingMoreEvents(false); + if (!visible) return; + let cancelled = false; + let timer: number | undefined; + const abort = new AbortController(); + let reading = false; + let pendingRefresh = false; + let failedRead: { requested: boolean; catchup: boolean } | null = null; + const read = async (requested = false, catchup = false) => { + if (cancelled) return; + if (reading) { if (catchup) pendingRefresh = true; return; } + if (hasMoreEventsRef.current && !requested && !catchup) return; + reading = true; pendingRefresh = false; setLoadingMoreEvents(true); setEventsError(null); + window.clearTimeout(timer); timer = undefined; + let failed = false; + try { + const cursor = catchup ? Math.max(eventsCatchupCursorRef.current, eventsReadCursorRef.current) : eventsReadCursorRef.current; + const initializesHistory = eventsReadCursorRef.current === 0; + const rows = await readTranscriptRequest(signal => heartbeatsApi.events(run.id, cursor, 1000, { signal }), abort.signal); + if (cancelled) return; + appendEvents(rows, !catchup || initializesHistory); + const next = Math.max(cursor, rows.at(-1)?.seq ?? cursor); + eventsCatchupCursorRef.current = Math.max(eventsCatchupCursorRef.current, next); + eventSequenceRef.current.confirm(next); + if (catchup) { + if (rows.length === 1000 && next > cursor) pendingRefresh = true; + } + if (!catchup || initializesHistory) { + eventsReadCursorRef.current = next; + hasMoreEventsRef.current = rows.length === 1000 && next > cursor; + setHasMoreEvents(hasMoreEventsRef.current); + } + failed = eventSequenceRef.current.needsCatchup; + failedRead = null; + } catch { + failed = true; failedRead = { requested, catchup }; + if (!cancelled) setEventsError("Could not load events. Try again."); + } + if (cancelled) return; + reading = false; setLoadingMoreEvents(false); setLoading(false); + if (pendingRefresh) void read(false, true); + else if (failed || (isLive && !stream.healthy && !hasMoreEventsRef.current)) { + timer = window.setTimeout(() => void read(requested, catchup || eventSequenceRef.current.needsCatchup), 2000); + } + }; + refreshEventsRef.current = () => { void read(false, wasLiveRef.current); }; + loadMoreEventsRef.current = () => { void read(failedRead?.requested ?? true, failedRead?.catchup ?? false); }; + void read(false, wasLiveRef.current && (stream.healthy || eventsReadCursorRef.current > 0)); + return () => { + cancelled = true; refreshEventsRef.current = null; loadMoreEventsRef.current = null; + abort.abort(); if (timer !== undefined) window.clearTimeout(timer); + }; + }, [visible, run.id, run.companyId, run.status, stream.healthy, stream.epoch]); const getScrollContainer = useCallback((): ScrollContainer => { if (scrollContainerRef.current) return scrollContainerRef.current; @@ -4205,45 +4339,50 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType setLogError(null); }, [run.id, run.logRef, setLogOffset]); - // Fetch persisted shell log, retaining partial rows and offsets across hides. useEffect(() => { if (!visible) return; + if (!run.logRef && !shouldPollShellLog) { setLogLoading(false); return; } let cancelled = false; - const offset = logOffsetRef.current; - if (!run.logRef && !shouldPollShellLog) { - setLogLoading(false); - return () => { - cancelled = true; - }; - } - + let timer: number | undefined; + const abort = new AbortController(); setLogLoading(true); + let reading = false; + let pendingRefresh = false; const load = async () => { + if (cancelled || reading) return; + reading = true; pendingRefresh = false; + window.clearTimeout(timer); timer = undefined; + let failed = false; try { - const result = await heartbeatsApi.log(run.id, offset, RUN_LOG_PAGE_BYTES); - if (cancelled) return; - appendLogContent(result.content, result.nextOffset === undefined); - const next = result.nextOffset ?? offset + result.content.length; - setLogOffset(next); - setHasMoreLog(!shouldPollShellLog && result.nextOffset !== undefined); - } catch (err) { - if (!cancelled) { - if (shouldPollShellLog && isRunLogUnavailable(err)) { - setLogLoading(false); - return; - } - setLogError(err instanceof Error ? err.message : "Failed to load run log"); + for (;;) { + const offset = logOffsetRef.current; + const result = await readTranscriptRequest(signal => heartbeatsApi.log(run.id, offset, RUN_LOG_PAGE_BYTES, { signal }), abort.signal); + if (cancelled) return; + const binding = bindLog(result.logRef); + if (binding === "stale") { failed = true; break; } + if (binding === "changed" && offset !== 0) continue; + appendLogContent(result.content, result.nextOffset === undefined); + const next = result.nextOffset ?? offset + new TextEncoder().encode(result.content).byteLength; + setLogOffset(next); setLogError(null); + setHasMoreLog(!wasLiveRef.current && result.nextOffset !== undefined && !!result.content); + if (!wasLiveRef.current || result.nextOffset === undefined || !result.content || next <= offset) break; } - } finally { - if (!cancelled) setLogLoading(false); + failed ||= logSequenceRef.current.needsCatchup; + } catch (err) { + if (cancelled) return; + failed = shouldPollShellLog || !isRunLogUnavailable(err); + if (!isRunLogUnavailable(err)) setLogError(err instanceof Error ? err.message : "Failed to load run log"); } + if (cancelled) return; + reading = false; + setLogLoading(false); + if (pendingRefresh) void load(); + else if (failed || (shouldPollShellLog && !stream.healthy)) timer = window.setTimeout(() => void load(), 2000); }; - + refreshLogRef.current = (force = false) => { if (force) pendingRefresh = true; void load(); }; void load(); - return () => { - cancelled = true; - }; - }, [visible, run.id, run.logRef, run.logBytes, shouldPollShellLog]); + return () => { cancelled = true; refreshLogRef.current = null; abort.abort(); if (timer !== undefined) window.clearTimeout(timer); }; + }, [visible, run.id, run.companyId, run.logRef, isLive ? null : run.logBytes, shouldPollShellLog, stream.healthy, stream.epoch]); async function loadMorePersistedLog() { if (loadingMoreLog || !hasMoreLog) return; @@ -4252,7 +4391,7 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType try { const result = await heartbeatsApi.log(run.id, logOffset, RUN_LOG_PAGE_BYTES); appendLogContent(result.content, result.nextOffset === undefined); - const next = result.nextOffset ?? logOffset + result.content.length; + const next = result.nextOffset ?? logOffset + new TextEncoder().encode(result.content).byteLength; setLogOffset(next); setHasMoreLog(result.nextOffset !== undefined); } catch (err) { @@ -4262,192 +4401,6 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType } } - // Poll for live updates - useEffect(() => { - if (!visible || !isLive || isStreamingConnected) return; - let pending = false; - let cancelled = false; - const interval = setInterval(async () => { - if (pending || cancelled || !getPageVisibility().visible) return; - pending = true; - const maxSeq = events.length > 0 ? Math.max(...events.map((e) => e.seq)) : 0; - try { - const newEvents = await heartbeatsApi.events(run.id, maxSeq, 100); - if (cancelled) return; - if (newEvents.length > 0) { - setEvents((prev) => appendCapped(prev, newEvents, MAX_LIVE_EVENTS)); - } - } catch { - // ignore polling errors - } finally { - pending = false; - } - }, 2000); - return () => { - cancelled = true; - clearInterval(interval); - }; - }, [visible, run.id, isLive, isStreamingConnected, events]); - - // Poll shell log for running runs - useEffect(() => { - if (!visible || !shouldPollShellLog || isStreamingConnected) return; - let pending = false; - let cancelled = false; - const interval = setInterval(async () => { - if (pending || cancelled || !getPageVisibility().visible) return; - pending = true; - try { - const result = await heartbeatsApi.log(run.id, logOffset, 256_000); - if (cancelled) return; - if (result.content) { - appendLogContent(result.content, result.nextOffset === undefined); - } - if (result.nextOffset !== undefined) { - setLogOffset(result.nextOffset); - } else if (result.content.length > 0) { - setLogOffset((prev) => prev + result.content.length); - } - } catch (err) { - if (isRunLogUnavailable(err)) return; - // ignore polling errors - } finally { - pending = false; - } - }, 2000); - return () => { - cancelled = true; - clearInterval(interval); - }; - }, [visible, run.id, shouldPollShellLog, isStreamingConnected, logOffset]); - - // Stream live updates from websocket (primary path for running runs). - useEffect(() => { - if (!visible || !isLive) return; - - let closed = false; - let reconnectTimer: number | null = null; - let socket: WebSocket | null = null; - - const scheduleReconnect = () => { - if (closed) return; - reconnectTimer = window.setTimeout(connect, 1500); - }; - - const connect = () => { - if (closed) return; - const url = buildSameOriginWebSocketUrl( - `/api/companies/${encodeURIComponent(run.companyId)}/events/ws`, - ); - socket = tryCreateWebSocket(url); - if (!socket) { - scheduleReconnect(); - return; - } - - socket.onopen = () => { - setIsStreamingConnected(true); - }; - - socket.onmessage = (message) => { - const rawMessage = typeof message.data === "string" ? message.data : ""; - if (!rawMessage) return; - - let event: LiveEvent; - try { - event = JSON.parse(rawMessage) as LiveEvent; - } catch { - return; - } - - if (event.companyId !== run.companyId) return; - const payload = asRecord(event.payload); - const eventRunId = asNonEmptyString(payload?.runId); - if (!payload || eventRunId !== run.id) return; - - if (event.type === "heartbeat.run.log") { - const chunk = typeof payload.chunk === "string" ? payload.chunk : ""; - if (!chunk) return; - const streamRaw = asNonEmptyString(payload.stream); - const stream = streamRaw === "stderr" || streamRaw === "system" ? streamRaw : "stdout"; - const ts = asNonEmptyString((payload as Record).ts) ?? event.createdAt; - appendLogLines([{ ts, stream, chunk, seq: readChunkSeq(payload.seq) }]); - return; - } - - if (event.type === "heartbeat.run.progress") { - const line = buildHeartbeatProgressLogLine(payload, event.createdAt); - if (!line) return; - const key = heartbeatProgressLogLineKey(line); - if (seenProgressLogLineKeysRef.current.has(key)) return; - seenProgressLogLineKeysRef.current.add(key); - appendLogLines([line]); - return; - } - - if (event.type !== "heartbeat.run.event") return; - - const seq = typeof payload.seq === "number" ? payload.seq : null; - if (seq === null || !Number.isFinite(seq)) return; - - const streamRaw = asNonEmptyString(payload.stream); - const stream = - streamRaw === "stdout" || streamRaw === "stderr" || streamRaw === "system" - ? streamRaw - : null; - const levelRaw = asNonEmptyString(payload.level); - const level = - levelRaw === "info" || levelRaw === "warn" || levelRaw === "error" - ? levelRaw - : null; - - const liveEvent: HeartbeatRunEvent = { - id: seq, - companyId: run.companyId, - runId: run.id, - agentId: run.agentId, - seq, - eventType: asNonEmptyString(payload.eventType) ?? "event", - stream, - level, - color: asNonEmptyString(payload.color), - message: asNonEmptyString(payload.message), - payload: asRecord(payload.payload), - createdAt: new Date(event.createdAt), - }; - - setEvents((prev) => { - if (prev.some((existing) => existing.seq === seq)) return prev; - return appendCapped(prev, [liveEvent], MAX_LIVE_EVENTS); - }); - }; - - socket.onerror = () => { - socket?.close(); - }; - - socket.onclose = () => { - setIsStreamingConnected(false); - scheduleReconnect(); - }; - }; - - connect(); - - return () => { - closed = true; - setIsStreamingConnected(false); - if (reconnectTimer !== null) window.clearTimeout(reconnectTimer); - if (socket) { - socket.onopen = null; - socket.onmessage = null; - socket.onerror = null; - socket.onclose = null; - socket.close(1000, "run_detail_unmount"); - } - }; - }, [visible, isLive, run.companyId, run.id, run.agentId]); - const censorUsernameInLogs = useQuery({ queryKey: queryKeys.instance.generalSettings, queryFn: () => instanceSettingsApi.getGeneral(), @@ -4489,7 +4442,7 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType return

Loading run logs...

; } - if (events.length === 0 && logLines.length === 0 && !logError) { + if (events.length === 0 && logLines.length === 0 && !logError && !eventsError) { return

No log events.

; } @@ -4635,9 +4588,15 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType
)} - {events.length > 0 && ( + {(events.length > 0 || eventsError) && (
Events ({events.length})
+ {eventsError &&

{eventsError}

} + {(hasMoreEvents || eventsError) && ( + + )}
{events.map((evt) => { const color = evt.color @@ -4646,7 +4605,7 @@ export function LogViewer({ run, adapterType }: { run: HeartbeatRun; adapterType ?? "text-foreground"; return ( -
+
{new Date(evt.createdAt).toLocaleTimeString("en-US", { hour12: false })}