feat(observability): span the unnamed gaps in run preparation (#20396)

## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work
> - Before a task reaches the agent, the server prepares the run: it
reads the task, the workspace and the configuration, and then hands the
run to the native controller
> - With an OTLP endpoint, each preparation step emits a
`heartbeat.prepare.<phase>` or `native.controller.<phase>` span
> - On a hosted test deployment, 0.3 to 0.5 s of each `task.prepare`
sits between those spans, and about 0.5 s more sits between
`execution.dispatch_admission` and `native.coordinator.claim`
> - Nobody can say which step is slow in that time, so latency work in
this area is guesswork
> - This pull request adds spans around the existing awaited work in
those gaps, with the existing timing helpers and naming conventions
> - The benefit is that a trace of a slow preparation now names the step
that used the time

## Linked Issues or Issue Description

**What existing behavior does this improve?**
The OpenTelemetry trace of task preparation. Today it has unnamed gaps
between the named preparation spans.

**Subsystem affected**
Server: heartbeat run preparation and the native controller
(`server/src/services/heartbeat.ts`,
`server/src/services/native-runtime/native-session-executor.ts`).

**Current behavior**
On a hosted test deployment (8 runs per group), `task.prepare` takes 2.6
to 3.4 s. Between `heartbeat.prepare.runtime_state` and
`heartbeat.prepare.run_identity`, about 0.25 s has no span. Between
`execution.dispatch_admission` and `native.coordinator.claim`, about 0.5
s has no span, and in one pair of runs it was 1.4 s. Nobody can tell
which step used that time.

**Proposed behavior**
Spans name the existing awaited reads and writes in those gaps. The
change adds no reads and records no content. The operator endpoint gate
and the no-operation behaviour stay.

**Reason and benefit**
Latency work in this area needs a measurement. With these spans, a trace
of a slow preparation names the step that used the time, so a fix can be
confirmed or rejected after deployment.

**Breaking changes**
None. The change adds span names to the closed list. It changes no API,
schema or behaviour.

**Additional context**
The server uses postgres.js, which the auto-instrumentation does not
cover, so database spans do not fill these gaps.

## What Changed

- `server/src/services/execution-preparation-timing.ts`: add the new
closed phase names.
- `server/src/services/heartbeat.ts`: add `heartbeat.prepare.*` spans
for `chat_retry_admission`, `workspace_selection`,
`dependency_readiness`, `issue_checkout`, `instance_settings`,
`workspace_context`, `project_context`, `plan_wake_routing`,
`routine_environment`, `responsible_user` and `execution_start`. The
re-reads of the issue after a checkout use the existing `issue_context`
name.
- `server/src/services/native-runtime/native-session-executor.ts`: add
`native.controller.*` spans for `attachment_staging`, `warm_restore`,
`span_persistence` (persistence of the preparation spans to the run log)
and `state_migration` before the coordinator claim.
- `doc/observability.md`: list the new spans.
- `server/src/__tests__/heartbeat-preparation-gap-spans.test.ts`: run a
real heartbeat through native preparation with an in-memory span
exporter. Check that each new span is emitted and that the new
preparation spans are children of `task.execution_attempt`.

## Verification

- `pnpm --filter @paperclipai/server typecheck`
- `npx vitest run src/__tests__/heartbeat-preparation-gap-spans.test.ts`
(fails without the source change, passes with it)
- `npx vitest run
src/services/heartbeat/preparation-timing-context.test.ts
src/services/execution-preparation-timing.test.ts
src/services/native-runtime/native-session-executor.test.ts
src/__tests__/heartbeat-context-compaction-execution.test.ts`

## Risks

- Low risk. The change only wraps existing awaited calls. Values and
errors pass through the timing helper unchanged, and a checkout conflict
still reaches the same `catch`.
- Phases of 50 ms or more inside `heartbeat.prepare.*` are also written
to the run log, as for the existing phases. This adds a few run-log rows
on slow runs.
- Without an OTLP endpoint, the helpers keep their current no-operation
behaviour.

## Model Used

- Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, used through Claude
Code with tool use (shell, file edits, test runs) and extended thinking.

## Checklist

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

🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Nicky LeachandClaude Opus 5.5 authored and GitHub committed 2026-11-09 15:27:58 -08:00
1 parent 09241442ea
commit d95fdd8d79
5 files changed
+234 -73

No files matched your search

@@ -9533,9 +9533,10 @@ export async function executePaperclipNativeSession(input: {
}
return preparedInput;
};
const stageAttachments = () => createRunPreparationTiming(runId, "native.controller")("attachment_staging", prepareAttachments);
return needsWarmRetirement
? await executePaperclipNativeSessionWithinScope(input, prepareAttachments, false, ownDiagnosticLease)
: await executePaperclipNativeSessionWithinScope(await prepareAttachments(), undefined, false, ownDiagnosticLease);
? await executePaperclipNativeSessionWithinScope(input, stageAttachments, false, ownDiagnosticLease)
: await executePaperclipNativeSessionWithinScope(await stageAttachments(), undefined, false, ownDiagnosticLease);
} catch (error) {
executionFailure = error;
if (error instanceof NativeControllerRecoveryWaitingError) {
@@ -9692,7 +9693,8 @@ async function executePaperclipNativeSessionAttempt(
: null;
const stagedRestart = input.restartRecovery?.kind === "reattach_remote_runner"
? await verifyStagedAttachmentRestart(input) : null;
if (input.useRunnerd) await restoreWarmRunnerdController(input);
const timeController = createRunPreparationTiming(input.execution.binding.runId, "native.controller");
if (input.useRunnerd) await timeController("warm_restore", () => restoreWarmRunnerdController(input));
const identityRedactor = createAgentIdentityRedactor(input.runnerEnvironment?.PAPERCLIP_AGENT_PRIVATE_KEY);
const redactIdentityText = (text: string) => redactSensitiveText(
identityRedactor.chunk("diagnostic", text) + identityRedactor.finish("diagnostic"),
@@ -9718,7 +9720,6 @@ async function executePaperclipNativeSessionAttempt(
"paperclip_runner_provider_unsupported: ACPX candidate requires exact host qualification authorization",
);
}
const timeController = createRunPreparationTiming(input.execution.binding.runId, "native.controller");
const preparationSpans = input.preparationSpans ?? [];
const preparationStarts = nativeRunPreparationStarts(
preparationSpans,
@@ -9772,20 +9773,22 @@ async function executePaperclipNativeSessionAttempt(
startedAtMs: environmentStartedAtMs,
})
: null;
for (const span of preparationSpans) {
const rootMilestone = isNativeRunRootHistoricalSpan(span.name);
await trace.record({
...span,
parentName: rootMilestone
? "task.provider_session"
: environmentSpans.includes(span)
? "environment.startup"
: "task.prepare",
});
}
if (environmentScope) {
await trace.end(environmentScope, { endedAtMs: environmentEndedAtMs });
}
await timeController("span_persistence", async () => {
for (const span of preparationSpans) {
const rootMilestone = isNativeRunRootHistoricalSpan(span.name);
await trace.record({
...span,
parentName: rootMilestone
? "task.provider_session"
: environmentSpans.includes(span)
? "environment.startup"
: "task.prepare",
});
}
if (environmentScope) {
await trace.end(environmentScope, { endedAtMs: environmentEndedAtMs });
}
});
let retainedTransition: VerifiedWarmTransitionBinding | undefined;
let remoteWarmRecovery: RemoteWarmSessionRecovery | undefined;
const cachedReleasedOwner = warmNativeSessions.get(nativeSessionScopeKey(input.execution));
@@ -9870,7 +9873,7 @@ async function executePaperclipNativeSessionAttempt(
}
}
if (input.useRunnerd) {
retainedTransition = await migrateRunnerdStateRootForExecution({
retainedTransition = await timeController("state_migration", () => migrateRunnerdStateRootForExecution({
db: input.db,
execution: input.execution,
preparedExecutionAdmission: input.preparedExecutionAdmission,
@@ -9881,7 +9884,7 @@ async function executePaperclipNativeSessionAttempt(
restartRecovery: input.restartRecovery,
runnerExecutionTarget: input.runnerExecutionTarget,
bootstrapRetryLeaseOwner: input.leaseOwner,
});
}));
}
const durableRunnerBinding = input.useRunnerd
? loadRunnerdDurableBinding(input.execution, retainedTransition)