From 57fa6b358de62922cfa9a67766b2a227c434fcdf Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Thu, 15 Oct 2026 08:35:02 -0500 Subject: [PATCH] fix(observability): separate workspace finalization and copyback spans (#16428) Give native workspace finalization its own span name. Keep copyback and commit as separate child measurements, with an exported-span regression that preserves the workspace operation result. Validation: 40 runtime/tracing tests and server typecheck passed locally. Final-head CI, E2E and security checks passed. Apex review: 5/5, zero findings and no unresolved threads. Co-Authored-By: Paperclip --- doc/observability.md | 1 + .../services/execution-preparation-timing.ts | 2 +- .../heartbeat/runtime-execution.test.ts | 35 ++++++++++++++++--- .../services/heartbeat/runtime-execution.ts | 2 +- 4 files changed, 33 insertions(+), 7 deletions(-) diff --git a/doc/observability.md b/doc/observability.md index 8d15d11be67..2fcf0ade1b8 100644 --- a/doc/observability.md +++ b/doc/observability.md @@ -259,6 +259,7 @@ attempt or owning phase: | `runtime_context.asset_*` | Source reads, manifest hashing, cache lookup, cold materialization, and exact file verification on cold and warm paths. | | `workspace_sync.*` | Existing Git and baseline snapshot, pack, seed verification, transfer, and restore operations. Pack and verification can be inside transfer; do not add nested durations. | | `execution.runtime` | Runtime dispatch, usage, workspace finalization and runtime cleanup; this includes work after provider execution. | +| `execution.workspace_finalize` | Best-effort native workspace finalization, including restore recovery, copyback and commit. Its nested restore and commit spans measure distinct steps. | | `execution.workspace_ownership`, `.workspace_ownership_wait`, `.workspace_restore`, `.workspace_commit`, `.native_finalize` | Ownership coordination including its action, acquisition before the action, copyback, final snapshot/stamp/descriptor persistence, and native settlement. | | `completion.*` | Completion handler, run-log finalization, terminal persistence, accounting, liveness, and continuation summaries. | | `response.resolve`, `.authorize`, `.add_comment`, `.transaction*`, `.row_lock`, `.write`, `.publish` | Response selection, existing authorization, comment transaction including commit or rollback, row wait, insert, and external publication enqueue. | diff --git a/server/src/services/execution-preparation-timing.ts b/server/src/services/execution-preparation-timing.ts index c20c5ca3737..58fc7a33cc5 100644 --- a/server/src/services/execution-preparation-timing.ts +++ b/server/src/services/execution-preparation-timing.ts @@ -44,7 +44,7 @@ export type ExecutionPhase = | "runtime_context.instructions" | "runtime_context.skills" | "runtime_context.mcp" | "runtime_context.asset_read" | "runtime_context.asset_manifest" | "runtime_context.asset_cache" | "runtime_context.asset_materialize" | "runtime_context.asset_verify" | "workspace_sync.snapshot_git" | "workspace_sync.snapshot_baseline" | "workspace_sync.pack" | "workspace_sync.seed_verify" | "workspace_sync.stage_workspace" | "workspace_sync.restore" - | "execution.runtime" | "execution.workspace_ownership" | "execution.workspace_restore" | "execution.workspace_commit" + | "execution.runtime" | "execution.workspace_ownership" | "execution.workspace_finalize" | "execution.workspace_restore" | "execution.workspace_commit" | "execution.workspace_ownership_wait" | "execution.realtime" | "execution.usage" | "execution.native_finalize" | "completion.run" | "completion.output" | "completion.terminal_write" | "completion.cost" | "completion.liveness" | "completion.summary" diff --git a/server/src/services/heartbeat/runtime-execution.test.ts b/server/src/services/heartbeat/runtime-execution.test.ts index 20f2ff1ec4d..692ab07b2ec 100644 --- a/server/src/services/heartbeat/runtime-execution.test.ts +++ b/server/src/services/heartbeat/runtime-execution.test.ts @@ -5,6 +5,9 @@ import { join } from "node:path"; import { agents, companies, createDb, EMBEDDED_POSTGRES_TEST_TIMEOUT_MS, heartbeatRuns, issues, nativeRunFinalizations, runUsageReceipts, workspaceOperations, type Db } from "@paperclipai/db"; import { eq, sql } from "drizzle-orm"; import { afterAll, beforeAll, beforeEach, describe, expect, it, vi } from "vitest"; +import { trace } from "@opentelemetry/api"; +import { InMemorySpanExporter, SimpleSpanProcessor, TracerProvider } from "@opentelemetry/sdk-trace"; +import { measureRunPhase, measureWorkspaceSyncPhase, withRunExecutionTiming } from "../execution-preparation-timing.js"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "../../__tests__/helpers/embedded-postgres.js"; import * as legacyRecovery from "../legacy-execution-recovery.js"; import { createAgentIdentityRedactor } from "../agent-identity-redaction.js"; @@ -214,10 +217,17 @@ describe.skipIf(!support.supported)("heartbeat runtime execution boundary", () = it("records native restoration inside the workspace finalization operation", async () => { const { input, run } = await fixture(true); + const endpoint = process.env.OTEL_EXPORTER_OTLP_ENDPOINT; + vi.stubEnv("OTEL_EXPORTER_OTLP_ENDPOINT", "http://collector.test"); + const exporter = new InMemorySpanExporter(); + const provider = new TracerProvider({ spanProcessors: [new SimpleSpanProcessor({ exporter })] }); + expect(trace.setGlobalTracerProvider(provider)).toBe(true); const restore = vi.fn(async () => { expect(await finalizations()).toMatchObject([{ status: "running", metadata: { owningService: "native_workspace_finalizer" }, }]); + await measureWorkspaceSyncPhase("workspace.restore", async () => {}); + await measureRunPhase("execution.workspace_commit", async () => {}); }); input.workspace.nativeWorkspaceSync = { mode: "host_current", @@ -227,11 +237,26 @@ describe.skipIf(!support.supported)("heartbeat runtime execution boundary", () = restoreWorkspace: restore, cleanup: vi.fn(async () => {}), }; - expect(await executeHeartbeatRuntime(db, input)).toMatchObject({ dispatched: true }); - expect(restore).toHaveBeenCalledOnce(); - expect(await finalizations()).toMatchObject([{ - status: "succeeded", metadata: { owningService: "native_workspace_finalizer" }, - }]); + try { + expect(await withRunExecutionTiming(run.id, () => executeHeartbeatRuntime(db, input))).toMatchObject({ dispatched: true }); + expect(restore).toHaveBeenCalledOnce(); + expect(await finalizations()).toMatchObject([{ + status: "succeeded", metadata: { owningService: "native_workspace_finalizer" }, + }]); + await provider.forceFlush(); + const spans = exporter.getFinishedSpans(); + const copyback = spans.filter(span => span.name === "execution.workspace_restore"); + const commit = spans.filter(span => span.name === "execution.workspace_commit"); + expect(copyback).toHaveLength(1); + expect(commit).toHaveLength(1); + const finalization = spans.find(span => span.name === "execution.workspace_finalize")!; + expect(finalization).toBeDefined(); + for (const child of [...copyback, ...commit]) expect(child.parentSpanContext?.spanId).toBe(finalization.spanContext().spanId); + } finally { + vi.stubEnv("OTEL_EXPORTER_OTLP_ENDPOINT", endpoint); + trace.disable(); + await provider.shutdown(); + } }); it("retains an unexported native source before provider-error teardown", async () => { diff --git a/server/src/services/heartbeat/runtime-execution.ts b/server/src/services/heartbeat/runtime-execution.ts index cd8e9fddb87..bbd31e4ee8a 100644 --- a/server/src/services/heartbeat/runtime-execution.ts +++ b/server/src/services/heartbeat/runtime-execution.ts @@ -917,7 +917,7 @@ export async function executeHeartbeatRuntime(db: Db, input: HeartbeatRuntimeExe )).limit(1); if (exported.length) adapterFinalizeOutcome = "succeeded"; else await recordWorkspaceFinalize(hasWorkspaceRestoreFailure(adapterResult.resultJson) ? "failed" : "succeeded", undefined, - async () => { await measureRunPhase("execution.workspace_restore", () => restoreNativeWorkspaceBestEffort({ + async () => { await measureRunPhase("execution.workspace_finalize", () => restoreNativeWorkspaceBestEffort({ db, runId: run.id, assertOwnership: ownership?.assertHeld, restore: () => nativeWorkspaceSync!.restoreWorkspace(ownership?.assertHeld), })); });