diff --git a/doc/run-log-events.md b/doc/run-log-events.md index ff1d7150c4e..eb7d5afb676 100644 --- a/doc/run-log-events.md +++ b/doc/run-log-events.md @@ -99,6 +99,30 @@ and `harness_state.launch_material` for remote state inspection and fresh launch material. These events retain the existing schema and carry no paths or exception strings. They also become native Observability spans only with an operator OTLP endpoint. +## Local runner startup sub-steps + +`run.performance.span` splits a local Runner startup (`runner.session.bootstrap` or +`runner.session.resume`) into three sequential children of `runner.session.startup`: + +- `runner.runtime.stage`: controller-side launch preparation before the Runner + process exists (runtime context, provider home, launch profiles; on resume, the + durable-state checks and authority rotation as well). +- `runner.process.launch`: from spawning `paperclip-runnerd` until its first + authenticated connection to the PRP control plane. An exact adoption of a live + Runner records no launch, so this span keeps meaning a fresh Runner process + (see startup reuse above). +- `provider.session.load`: from that authentication until the provider session + identity is confirmed. It covers `run.prepare` and `session.open`, or on resume + the `run.attach` that restores the provider and the recovery probe. + +Each carries `mode` (`bootstrap` or `resume`), `target: "local"`, and `outcome` +(`failed` when startup fails inside the step). The Runner transport reports each +milestone synchronously; the controller writes the row as deferred diagnostic +work, so the run-log write never delays `turn.start`. Remote launchers keep their +own `runner.runtime.stage` and `runner.process.launch` spans. These rows stay in +the instance run log; with an operator OTLP endpoint they are also Observability +spans. They are not Telemetry. + ## Native PRP Run-Log Events Provider startup command failures and failed provider turns can carry a diff --git a/packages/paperclip-runner/runner/crates/runner-core/src/bin/fake-codex-app-server.rs b/packages/paperclip-runner/runner/crates/runner-core/src/bin/fake-codex-app-server.rs index 929ae1f74e7..3318ffe0b3b 100644 --- a/packages/paperclip-runner/runner/crates/runner-core/src/bin/fake-codex-app-server.rs +++ b/packages/paperclip-runner/runner/crates/runner-core/src/bin/fake-codex-app-server.rs @@ -1344,6 +1344,9 @@ fn run() -> Result<(), Box> { } } "thread/resume" => { + if let Some(delay) = argument(&args, "--thread-resume-delay-ms") { + thread::sleep(Duration::from_millis(delay.parse()?)); + } if reject_missing_resume_state { send(json!({"id": id, "error": { "code": -32600, diff --git a/packages/paperclip-runner/src/control-plane/durable-prp-control-plane.ts b/packages/paperclip-runner/src/control-plane/durable-prp-control-plane.ts index e591d742379..2b435c75464 100644 --- a/packages/paperclip-runner/src/control-plane/durable-prp-control-plane.ts +++ b/packages/paperclip-runner/src/control-plane/durable-prp-control-plane.ts @@ -305,6 +305,8 @@ export interface DurablePrpControlPlaneOptions { onProtocolIntegrityError?: ( error: NativeSessionProtocolIntegrityError, ) => void; + /** Diagnostic only: called synchronously after each runner connection is authenticated. */ + onAuthenticatedConnection?: () => void; connectionLeaseTtlMs?: number; } @@ -2035,6 +2037,7 @@ export class DurablePrpControlPlane { #recoverSemanticToolInput?: DurablePrpControlPlaneOptions["recoverSemanticToolInput"]; #beforeAuthenticatedConnection?: DurablePrpControlPlaneOptions["beforeAuthenticatedConnection"]; #onProtocolIntegrityError?: DurablePrpControlPlaneOptions["onProtocolIntegrityError"]; + #onAuthenticatedConnection?: DurablePrpControlPlaneOptions["onAuthenticatedConnection"]; #protocolIntegrityError: NativeSessionProtocolIntegrityError | null = null; #connectionLeaseTtlMs: number; #persistCheckpoint: ((checkpoint: DurablePrpCheckpoint) => Promise) | null = null; @@ -2093,6 +2096,7 @@ export class DurablePrpControlPlane { this.#recoverSemanticToolInput = options.recoverSemanticToolInput; this.#beforeAuthenticatedConnection = options.beforeAuthenticatedConnection; this.#onProtocolIntegrityError = options.onProtocolIntegrityError; + this.#onAuthenticatedConnection = options.onAuthenticatedConnection; this.#connectionLeaseTtlMs = options.connectionLeaseTtlMs ?? 60_000; } @@ -3773,6 +3777,7 @@ export class DurablePrpControlPlane { } this.#store.state.connectionCount += 1; + try { this.#onAuthenticatedConnection?.(); } catch { /* Diagnostics never change admission. */ } this.#connectionLeaseFailure = null; this.#store.state.lastLeaseId = lease.leaseId; this.#store.state.lastLeaseExpiresAt = lease.expiresAt; diff --git a/packages/paperclip-runner/src/index.ts b/packages/paperclip-runner/src/index.ts index 5a68103f668..3d28bfcf616 100644 --- a/packages/paperclip-runner/src/index.ts +++ b/packages/paperclip-runner/src/index.ts @@ -97,6 +97,7 @@ export { type RetainedRunnerdMaintenanceEpochReceipt, type RunnerdCodexTransport, type RunnerdCodexTransportOptions, + type RunnerdStartupStep, } from "./live/runnerd-codex-transport.js"; export * from "./live/workspace-file-reference.js"; export { readLinuxProcessStartedAt, type LinuxProcessStartOptions } from "./live/linux-process-start.js"; diff --git a/packages/paperclip-runner/src/live/runnerd-codex-transport-startup-steps.test.ts b/packages/paperclip-runner/src/live/runnerd-codex-transport-startup-steps.test.ts new file mode 100644 index 00000000000..3f9db93417b --- /dev/null +++ b/packages/paperclip-runner/src/live/runnerd-codex-transport-startup-steps.test.ts @@ -0,0 +1,106 @@ +import { mkdtemp, rm } from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { expect, it } from "vitest"; +import { createCapabilityRunnerdCodexTransport, type RunnerdStartupStep } from "./runnerd-codex-transport.js"; +import { defaultCapabilityRunnerdBinary, fakeCodex, fakeCodexArgs } from "../../test/support/runnerd-transport.js"; + +const STEP_ORDER = ["runner.runtime.stage", "runner.process.launch", "provider.session.load"]; +const PROVIDER_DELAY_MS = 1_500; + +/** A slow provider must show up as session load, never as runner process launch. */ +function expectProviderTimeInSessionLoad(steps: RunnerdStartupStep[]): void { + const duration = (name: string) => { + const step = steps.find((candidate) => candidate.name === name)!; + return step.endedAtMs - step.startedAtMs; + }; + expect(duration("provider.session.load")).toBeGreaterThanOrEqual(PROVIDER_DELAY_MS); + expect(duration("runner.process.launch")).toBeLessThan(PROVIDER_DELAY_MS); +} + +function expectOrderedSteps(steps: RunnerdStartupStep[], mode: RunnerdStartupStep["mode"]): void { + expect(steps.map((step) => step.name)).toEqual(STEP_ORDER); + for (const [index, step] of steps.entries()) { + expect(step).toMatchObject({ mode, outcome: "ok" }); + expect(step.endedAtMs).toBeGreaterThanOrEqual(step.startedAtMs); + // Sub-steps are sequential: each starts at or after the previous one ended. + if (index > 0) expect(step.startedAtMs).toBeGreaterThanOrEqual(steps[index - 1]!.endedAtMs); + } +} + +it("reports local stage, launch and provider session load for bootstrap and cold resume", async () => { + const root = await mkdtemp(join(tmpdir(), "runnerd-startup-steps-")); + const identity = { + runnerInstanceId: "startup-steps-runner", + environmentLeaseId: "startup-steps-lease", + runId: "first-run", + normalizedSessionId: "startup-steps-session", + turnId: "first-turn", + itemId: "first-item", + }; + const options = { + runnerBinary: defaultCapabilityRunnerdBinary(), + codexCommand: fakeCodex, + // Delay the provider's own session start and resume. The runner process + // authenticates first, so the delay belongs to provider.session.load. + codexArgs: fakeCodexArgs(root, "--thread-start-delay-ms", String(PROVIDER_DELAY_MS), + "--thread-resume-delay-ms", String(PROVIDER_DELAY_MS)), + stateDirectory: root, + lifecyclePolicy: { mode: "warm" as const, idleTimeoutMs: 60_000 }, + runnerReconnectGraceMs: 2_000, + }; + const bootstrapSteps: RunnerdStartupStep[] = []; + const first = createCapabilityRunnerdCodexTransport({ + ...options, prpIdentity: identity, onStartupStep: (step) => { bootstrapSteps.push(step); }, + }); + let resumed: ReturnType | undefined; + try { + const opened = await first.transport.request("thread/start", { cwd: tmpdir(), dynamicTools: [] }); + expectOrderedSteps(bootstrapSteps, "bootstrap"); + expectProviderTimeInSessionLoad(bootstrapSteps); + const thread = opened.thread as { id: string; sessionId: string }; + await first.transport.close(); + // Closing a live transport is not a startup: no further steps. + expect(bootstrapSteps).toHaveLength(3); + + const resumeSteps: RunnerdStartupStep[] = []; + // A new run on the saved session rotates authority through run.attach, + // which restores the provider before the command completes. + resumed = createCapabilityRunnerdCodexTransport({ + ...options, + prpIdentity: { ...identity, runId: "second-run", turnId: "second-turn", itemId: "second-item" }, + resumeProviderSession: { driverSessionId: thread.id, providerSessionId: thread.sessionId }, + onStartupStep: (step) => { resumeSteps.push(step); }, + }); + await resumed.transport.request("thread/read", {}); + expectOrderedSteps(resumeSteps, "resume"); + expectProviderTimeInSessionLoad(resumeSteps); + } finally { + await resumed?.transport.close().catch(() => undefined); + await first.transport.close().catch(() => undefined); + await rm(root, { recursive: true, force: true }); + } +}, 60_000); + +it("never lets a failing startup-step sink change startup", async () => { + const root = await mkdtemp(join(tmpdir(), "runnerd-startup-steps-sink-")); + const names: string[] = []; + const bundle = createCapabilityRunnerdCodexTransport({ + runnerBinary: defaultCapabilityRunnerdBinary(), + codexCommand: fakeCodex, + codexArgs: fakeCodexArgs(root), + stateDirectory: root, + onStartupStep: (step) => { + names.push(step.name); + throw new Error("diagnostic sink unavailable"); + }, + }); + try { + const opened = await bundle.transport.request("thread/start", { cwd: tmpdir(), dynamicTools: [] }); + expect((opened.thread as { id?: string }).id).toEqual(expect.any(String)); + expect(names).toEqual(STEP_ORDER); + } finally { + await bundle.transport.close().catch(() => undefined); + await rm(root, { recursive: true, force: true }); + } +}, 60_000); diff --git a/packages/paperclip-runner/src/live/runnerd-codex-transport.ts b/packages/paperclip-runner/src/live/runnerd-codex-transport.ts index c5cdae6cb56..42bf22e7bd8 100644 --- a/packages/paperclip-runner/src/live/runnerd-codex-transport.ts +++ b/packages/paperclip-runner/src/live/runnerd-codex-transport.ts @@ -1569,6 +1569,11 @@ export interface CapabilityRunnerdCodexTransportOptions extends RunnerExecutionD /** Controller-owned opt-in operation timing. No exporter lives in Runner. */ measureOperation?(phase: string, work: () => Promise, attributes?: Record): Promise; recordTimingReceipt?(receipt: unknown): void; + /** + * Controller-owned startup sub-steps for the run log. Called synchronously + * at each milestone; the controller must not wait on it before turn.start. + */ + onStartupStep?(step: RunnerdStartupStep): void; onDiagnostic?: (message: string) => void; onEvidence?: (evidence: Readonly) => void; /** Persist process ownership immediately after spawn, before waiting for @@ -1636,6 +1641,15 @@ export interface CapabilityRunnerdCodexTransportOptions extends RunnerExecutionD }) => void | Promise; } +/** One measured local startup sub-step, named for the run-log span it becomes. */ +export interface RunnerdStartupStep { + name: "runner.runtime.stage" | "runner.process.launch" | "provider.session.load"; + mode: "bootstrap" | "resume"; + startedAtMs: number; + endedAtMs: number; + outcome: "ok" | "failed"; +} + export type RunnerdCodexTransportOptions = CapabilityRunnerdCodexTransportOptions; @@ -3950,6 +3964,12 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { #nextTraceDebugSequence = 1; #traceRehydrationSpoolOverflow = false; readonly #traceFrameIndex = new RunnerdTraceFrameIndex(); + #startupSteps: { + begin(name: RunnerdStartupStep["name"]): void; + /** Move on only from the named open step (later reconnects are not startup milestones). */ + advance(from: RunnerdStartupStep["name"], to: RunnerdStartupStep["name"]): void; + end(): void; + } | null = null; #pendingTraceRehydrations: PendingTraceRehydration[] = []; #pendingDriverTraceInterpretations: PendingDriverTraceInterpretation[] = []; #restoredRuntimeRequests: CodexRpcServerRequest[] = []; @@ -5781,7 +5801,43 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { async #start( params: Record, ): Promise> { - return this.options.measureOperation ? this.options.measureOperation("runner.transport.cold_start", () => this.#startWork(params)) : this.#startWork(params); + const work = () => this.#withStartupSteps("bootstrap", () => this.#startWork(params)); + return this.options.measureOperation ? this.options.measureOperation("runner.transport.cold_start", work) : work(); + } + + /** + * Time this startup's sub-steps for the controller's run log. A nested + * startup (exact adoption from thread/start) keeps the outer clock. + */ + async #withStartupSteps(mode: RunnerdStartupStep["mode"], work: () => Promise): Promise { + const onStep = this.options.onStartupStep; + if (!onStep || this.#startupSteps !== null) return work(); + let open: { name: RunnerdStartupStep["name"]; startedAtMs: number } | null = null; + const close = (outcome: RunnerdStartupStep["outcome"]) => { + if (!open) return; + const step = { ...open, mode, endedAtMs: Date.now(), outcome }; + open = null; + try { onStep(step); } catch { /* Diagnostics never change startup. */ } + }; + this.#startupSteps = { + begin: name => { close("ok"); open = { name, startedAtMs: Date.now() }; }, + advance: (from, to) => { + if (open?.name !== from) return; + close("ok"); + open = { name: to, startedAtMs: Date.now() }; + }, + end: () => close("ok"), + }; + try { + const value = await work(); + close("ok"); + return value; + } catch (error) { + close("failed"); + throw error; + } finally { + this.#startupSteps = null; + } } /** Runner state held by an external Runner host (a plugin task or a sandbox). */ @@ -5838,6 +5894,8 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { expectedRunnerVersion: runnerArtifact.version, expectedRunnerDigest: runnerArtifact.digest, onProtocolIntegrityError: (error) => this.#failTransport(error), + // The runner process is up once it authenticates; provider work follows. + onAuthenticatedConnection: () => this.#startupSteps?.advance("runner.process.launch", "provider.session.load"), get authorityRunId() { return authorityRunId(); }, semanticInputMode: this.#retainsSourceInputs() || this.options.recoveryPurpose === "stop_cleanup" ? "retain_only" : "dispatch", onSemanticToolInput: this.options.recoveryPurpose === "stop_cleanup" ? undefined : (call) => this.#handleSemanticToolInput(call), @@ -5866,7 +5924,9 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { }); } const unclaimedBootstrap = core.unclaimedBootstrapCheckpoint(); + this.#startupSteps?.begin("runner.runtime.stage"); const prepared = await this.#prepareLaunch(params, identity, dynamicTools); + this.#startupSteps?.end(); const { runAttachTemplate } = prepared; // Preserve the first generation's provider attachment seed independently // of bounded command history. The in-memory copy serves a live warm @@ -5897,6 +5957,7 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { const bootstrapTicket = core.issueBootstrapTicket(RUNNER_BOOTSTRAP_TICKET_TTL_MS); await core.flushCheckpoint(); this.#assertStartupOpen(); + this.#startupSteps?.begin("runner.process.launch"); const handle = spawnRunner({ connection: registration?.connection ?? { mode: "connect", @@ -5942,8 +6003,10 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { this.#publish(); this.#pump = setInterval(() => this.#pumpEventsSafely(), 5); await this.#waitCommand("run.prepare", undefined, undefined, true); + this.#startupSteps?.advance("runner.process.launch", "provider.session.load"); await this.#waitCommand("session.open", undefined, admissionDeadline, true); await this.#waitForProviderIdentity(undefined, admissionDeadline); + this.#startupSteps?.end(); this.#startupComplete = true; this.#diagnostic("runnerd authenticated to the durable PRP control plane"); return this.#openedThreadResponse(params); @@ -5988,11 +6051,13 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { } async #resume(): Promise { - return this.options.measureOperation ? this.options.measureOperation("runner.transport.resume", () => this.#resumeWork()) : this.#resumeWork(); + const work = () => this.#withStartupSteps("resume", () => this.#resumeWork()); + return this.options.measureOperation ? this.options.measureOperation("runner.transport.resume", work) : work(); } async #resumeWork(): Promise { if (this.options.acpxCandidateAdmission?.agent === "antigravity") throw new Error("ACPX candidate durable runner recovery is not admitted"); + this.#startupSteps?.begin("runner.runtime.stage"); let desiredIdentity = this.options.prpIdentity; if (desiredIdentity === undefined) { throw new Error("PRP provider resume state is unavailable"); @@ -6350,6 +6415,8 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { expectedRunnerVersion: runnerArtifact.version, expectedRunnerDigest: runnerArtifact.digest, onProtocolIntegrityError: (error) => this.#failTransport(error), + // The runner process is up once it authenticates; provider work follows. + onAuthenticatedConnection: () => this.#startupSteps?.advance("runner.process.launch", "provider.session.load"), get authorityRunId() { return authorityRunId(); }, semanticInputMode: this.#retainsSourceInputs() || this.options.recoveryPurpose === "stop_cleanup" ? "retain_only" : "dispatch", onSemanticToolInput: this.options.recoveryPurpose === "stop_cleanup" ? undefined : (call) => this.#handleSemanticToolInput(call), @@ -6709,6 +6776,9 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { const admissionDeadline = this.#sourceAttachmentDeadline === null ? this.#coldAdmissionDeadline(adoptedRunner === undefined) : Math.min(Date.now() + 30_000, this.#sourceAttachmentDeadline); + // An adopted runner is already live: no launch step (a launch span means a fresh process). + if (adoptedRunner) this.#startupSteps?.end(); + else this.#startupSteps?.begin("runner.process.launch"); const handle = adoptedRunner ? null : spawnRunner({ @@ -6860,6 +6930,10 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { if (runAttachment) { await this.#waitCommand("run.attach", runAttachment.commandId, admissionDeadline, true); } + // A launched runner normally advanced at authentication, before run.attach + // restores the provider. An adopted runner had no launch step. + if (adoptedRunner) this.#startupSteps?.begin("provider.session.load"); + else this.#startupSteps?.advance("runner.process.launch", "provider.session.load"); if (recoveryProbeCommandId !== null) { await this.#waitCommand(sourceAttachmentTarget ? "session.open" : "runner.drain", recoveryProbeCommandId, admissionDeadline, true); if (this.#checkpointProviderIdentityExpectation !== null) { @@ -6889,6 +6963,7 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { : undefined, admissionDeadline, ); + this.#startupSteps?.end(); this.#startupComplete = true; if (recoveringAttachment && staged) { this.#sourceRecoveryIdentity = null; diff --git a/server/src/__tests__/redaction.test.ts b/server/src/__tests__/redaction.test.ts index 5d060d67d1a..98682dc89b9 100644 --- a/server/src/__tests__/redaction.test.ts +++ b/server/src/__tests__/redaction.test.ts @@ -399,6 +399,9 @@ describe("redaction", () => { "runner.prp.route.register", "runner.transport.connect", "runner.session.bootstrap", + "runner.runtime.stage", + "runner.process.launch", + "provider.session.load", "runner.turn.submit", "runner.session.startup", "provider_pack.select", diff --git a/server/src/redaction.ts b/server/src/redaction.ts index bf10373836a..a48caa03448 100644 --- a/server/src/redaction.ts +++ b/server/src/redaction.ts @@ -334,6 +334,7 @@ const NATIVE_RUN_SPAN_NAMES = new Set([ "native.result.finalize", "native.session.execute", "provider.session.continuity_break", + "provider.session.load", "provider.session.resume", "provider.time_to_first_agent_event", "provider.turn.queue", @@ -352,6 +353,7 @@ const NATIVE_RUN_SPAN_NAMES = new Set([ "runner.artifact.discover", "runner.artifact.prepare", "runner.prp.authenticate", + "runner.process.launch", "runner.prp.route.register", "runner.runtime.stage", "runner.session.bootstrap", diff --git a/server/src/services/native-runtime/native-run-trace.test.ts b/server/src/services/native-runtime/native-run-trace.test.ts index 0320f0f4656..1cfb22cddcd 100644 --- a/server/src/services/native-runtime/native-run-trace.test.ts +++ b/server/src/services/native-runtime/native-run-trace.test.ts @@ -10,6 +10,7 @@ import { nativeRunPreparationStarts, recordFailedSkillPreparation, recordNativeProviderPerformanceSpans, + recordNativeRunnerStartupStep, resolveNativeTimeToFirstTokenStart, NATIVE_RUN_SPAN_EVENT_TYPE, NATIVE_RUN_TRACE_SCHEMA_VERSION, @@ -604,3 +605,41 @@ describe("deferred diagnostics", () => { expect(late).not.toHaveBeenCalled(); }); }); + +describe("local runner startup sub-steps", () => { + it("records each step beneath runner.session.startup without blocking the caller", async () => { + const events: AdapterRuntimeEvent[] = []; + let releaseSink!: () => void; + const sinkGate = new Promise((resolve) => { releaseSink = resolve; }); + const { traceContext, spans } = createRecordingTraceContext(); + const trace = createNativeRunTrace({ + runId: "startup-steps", startedAtMs: 1_000, traceContext, + onEvent: async (event) => { await sinkGate; events.push(event); }, + }); + const startup = trace.start("runner.session.startup", { parentName: "task.provider_session", startedAtMs: 1_000 }); + // Synchronous and detached: a stalled run-log sink cannot delay turn.start. + recordNativeRunnerStartupStep(trace, { name: "runner.runtime.stage", mode: "bootstrap", startedAtMs: 1_000, endedAtMs: 1_200, outcome: "ok" }); + recordNativeRunnerStartupStep(trace, { name: "runner.process.launch", mode: "bootstrap", startedAtMs: 1_200, endedAtMs: 1_900, outcome: "ok" }); + recordNativeRunnerStartupStep(trace, { name: "provider.session.load", mode: "resume", startedAtMs: 1_900, endedAtMs: 4_000, outcome: "failed" }); + expect(events).toHaveLength(0); + const ended = trace.end(startup, { endedAtMs: 4_000 }); + const finished = trace.finish("ok"); + releaseSink(); + await ended; + await finished; + const payloads = events.map((event) => event.payload as Record); + const step = (name: string) => payloads.find((payload) => payload.span === name); + expect(step("runner.runtime.stage")).toMatchObject({ parentSpan: "runner.session.startup", startOffsetMs: 0, durationMs: 200, outcome: "ok", mode: "bootstrap", target: "local" }); + expect(step("runner.process.launch")).toMatchObject({ parentSpan: "runner.session.startup", startOffsetMs: 200, durationMs: 700, outcome: "ok" }); + expect(step("provider.session.load")).toMatchObject({ parentSpan: "runner.session.startup", durationMs: 2_100, outcome: "failed", mode: "resume" }); + expect(events.find((event) => (event.payload as Record).span === "provider.session.load")?.level).toBe("warn"); + expect(spans.find((span) => span.name === "runner.process.launch")?.parentName).toBe("runner.session.startup"); + // Settled before the root measurement closes. + const names = payloads.map((payload) => payload.span); + expect(names.indexOf("provider.session.load")).toBeLessThan(names.indexOf("task.provider_session.measured")); + }); + + it("is a no-op without a trace", () => { + expect(() => recordNativeRunnerStartupStep(undefined, { name: "runner.process.launch", mode: "bootstrap", startedAtMs: 1, endedAtMs: 2, outcome: "ok" })).not.toThrow(); + }); +}); diff --git a/server/src/services/native-runtime/native-run-trace.ts b/server/src/services/native-runtime/native-run-trace.ts index 3fccc1c9b55..a2967612164 100644 --- a/server/src/services/native-runtime/native-run-trace.ts +++ b/server/src/services/native-runtime/native-run-trace.ts @@ -625,6 +625,32 @@ export async function recordNativeProviderPerformanceSpans(trace: NativeRunTrace } catch { /* Diagnostics cannot replace the work's result. */ } } +/** One local runner startup sub-step measured by the runner transport. */ +export interface NativeRunnerStartupStep { + name: "runner.runtime.stage" | "runner.process.launch" | "provider.session.load"; + mode: "bootstrap" | "resume"; + startedAtMs: number; + endedAtMs: number; + outcome: NativeRunSpanOutcome; +} + +/** + * Record a local runner startup sub-step under `runner.session.startup`. + * Run log (and Observability when an operator endpoint is set) only, never + * Telemetry. Detached: the run-log write never delays `turn.start`; the + * trace settles it at finish. + */ +export function recordNativeRunnerStartupStep(trace: NativeRunTrace | undefined, step: NativeRunnerStartupStep): void { + trace?.defer(() => trace.record({ + name: step.name, + parentName: "runner.session.startup", + startedAtMs: step.startedAtMs, + endedAtMs: step.endedAtMs, + outcome: step.outcome, + attributes: { mode: step.mode, target: "local" }, + })); +} + /** Emit preparation failure even when execution aborts before a native session exists. */ export async function recordFailedSkillPreparation(input: { runId: string; diff --git a/server/src/services/native-runtime/native-session-executor.ts b/server/src/services/native-runtime/native-session-executor.ts index 2531fe72169..4ee6b2a0305 100644 --- a/server/src/services/native-runtime/native-session-executor.ts +++ b/server/src/services/native-runtime/native-session-executor.ts @@ -284,6 +284,7 @@ import { isNativeRunRootHistoricalSpan, nativeRunPreparationStarts, recordNativeProviderPerformanceSpans, + recordNativeRunnerStartupStep, resolveNativeTimeToFirstTokenStart, type NativeRunHistoricalSpan, type NativeRunSpanScope, @@ -16003,6 +16004,8 @@ async function createRunnerdBackendWithinSessionClaim( ...(input.recoveryPurpose === "stop_cleanup" ? { recoveryPurpose: "stop_cleanup" as const } : {}), measureOperation: process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim() ? measureRunnerOperation : undefined, recordTimingReceipt: process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim() ? recordRunnerTimingReceipt : undefined, + // Remote launchers record their own stage and launch spans. + ...(remoteTarget ? {} : { onStartupStep: (step: Parameters[1]) => recordNativeRunnerStartupStep(input.trace, step) }), onSpawn: input.onSpawn, ...(input.execution.provider.kind === "codex" ? { disableCodexWebSearch: "webSearch" in input.execution.provider && input.execution.provider.webSearch === "disabled" } : {}), homeMode: preconfiguredHome ? "preconfigured" : "isolated",