diff --git a/doc/observability.md b/doc/observability.md index 804236b48f3..03495423735 100644 --- a/doc/observability.md +++ b/doc/observability.md @@ -170,6 +170,15 @@ and launcher preparation, run output initialization, workspace validation, runtime services, instruction files, and runtime selection. Database and HTTP instrumentation can attach child spans during each awaited operation. +Execution configuration also records separate phases for mentioned skills, +GitHub identity selection, secret resolution, managed AI runtime preparation, +skill inventory, connector assignments, connector skill preparation and delivery, +connection instructions, and agent identity. Their names are +`heartbeat.prepare.configuration_`, using the closed names in +`server/src/services/heartbeat/preparation-timing.ts`. These intervals are inside +`execution_configuration`; do not add them to its duration. They remain available +when a later setup step fails before the provider lifecycle trace starts. + Each phase starts a new root trace and links to the active trigger span when one exists. An unsampled HTTP request must not suppress diagnostics for the background run it starts. Root traces still follow the operator's configured diff --git a/server/src/__tests__/heartbeat-execution-configuration.test.ts b/server/src/__tests__/heartbeat-execution-configuration.test.ts index 7f1a96e01ea..5a61f7361aa 100644 --- a/server/src/__tests__/heartbeat-execution-configuration.test.ts +++ b/server/src/__tests__/heartbeat-execution-configuration.test.ts @@ -1,4 +1,6 @@ -import { randomUUID } from "node:crypto"; +import { createHash, randomUUID } from "node:crypto"; +import { trace } from "@opentelemetry/api"; +import { InMemorySpanExporter, SimpleSpanProcessor, TracerProvider } from "@opentelemetry/sdk-trace"; import { access, readFile, mkdtemp, rm } from "node:fs/promises"; import { tmpdir } from "node:os"; import path from "node:path"; @@ -120,14 +122,36 @@ describePostgres("heartbeat execution configuration through adapter dispatch", ( expect(JSON.parse(await readFile(path.join(providerHome, "auth.json"), "utf8"))).toEqual({ OPENAI_API_KEY: f.credential }); await input.onMeta?.({ adapterType, command: "fixture", env, prompt: "fixture" }); }); - const { finished, input } = await execute(f); - expect(finished.status, finished.error ?? undefined).toBe("succeeded"); - expect(input?.context.aiConnection).toMatchObject({ accountName: "Fixture account", provider: "openai" }); - expect(providerHome).toEqual(expect.any(String)); - await expect(access(providerHome!)).rejects.toMatchObject({ code: "ENOENT" }); - const events = await db.select().from(heartbeatRunEvents).where(eq(heartbeatRunEvents.runId, finished.id)); - expect(events.some(event => event.eventType === "adapter.invoke")).toBe(true); - expect(JSON.stringify(events)).not.toContain(f.credential); + const exporter = new InMemorySpanExporter(); + const provider = new TracerProvider({ spanProcessors: [new SimpleSpanProcessor({ exporter })] }); + expect(trace.setGlobalTracerProvider(provider)).toBe(true); + try { + const { finished, input } = await execute(f); + expect(finished.status, finished.error ?? undefined).toBe("succeeded"); + expect(input?.context.aiConnection).toMatchObject({ accountName: "Fixture account", provider: "openai" }); + expect(providerHome).toEqual(expect.any(String)); + await expect(access(providerHome!)).rejects.toMatchObject({ code: "ENOENT" }); + const events = await db.select().from(heartbeatRunEvents).where(eq(heartbeatRunEvents.runId, finished.id)); + expect(events.some(event => event.eventType === "adapter.invoke")).toBe(true); + expect(JSON.stringify(events)).not.toContain(f.credential); + await provider.forceFlush(); + const runIdHash = createHash("sha256").update(finished.id).digest("hex").slice(0, 12); + const steps = exporter.getFinishedSpans().filter(span => span.name.startsWith("heartbeat.prepare.configuration_") + && span.attributes["paperclip.task.run.run_id"] === runIdHash); + expect(steps.map(span => span.name)).toEqual([ + "configuration_mentions", "configuration_github_identity", "configuration_secrets", "configuration_ai_runtime", + "configuration_skills", "configuration_connector_assignments", "configuration_connector_skills", + "configuration_connector_delivery", "configuration_connection_instructions", "configuration_agent_identity", + ].map(step => `heartbeat.prepare.${step}`)); + for (const span of steps) { + expect(span.status).toEqual({ code: 0 }); + expect(span.attributes).toEqual({ "paperclip.task.run.run_id": runIdHash }); + expect(span.events).toEqual([]); + } + } finally { + trace.disable(); + await provider.shutdown(); + } }); it("cleans acquired credentials and redacts diagnostics when later skill preparation fails", async () => { @@ -142,18 +166,36 @@ describePostgres("heartbeat execution configuration through adapter dispatch", ( await access(acquiredHome!); return runtime; }); - const { finished, input } = await execute(f); - expect(finished.status).toBe("failed"); - expect(input).toBeUndefined(); - expect(acquiredHome).toEqual(expect.any(String)); - await expect(access(acquiredHome!)).rejects.toMatchObject({ code: "ENOENT" }); - expect(finished.error).toContain("Invalid fixture skill configuration"); - // The diagnostic reporter redacts runtime values before the external sink. - // The legacy local run.error field does not apply this value-based redaction. - await waitForPendingRunFailureReports(); - expect(capturedFailure).toHaveBeenCalled(); - expect(JSON.stringify(capturedFailure.mock.calls)).toContain("Invalid fixture skill configuration"); - expect(JSON.stringify(capturedFailure.mock.calls)).not.toContain(f.credential); + const exporter = new InMemorySpanExporter(); + const provider = new TracerProvider({ spanProcessors: [new SimpleSpanProcessor({ exporter })] }); + expect(trace.setGlobalTracerProvider(provider)).toBe(true); + try { + const { finished, input } = await execute(f); + expect(finished.status).toBe("failed"); + expect(input).toBeUndefined(); + expect(acquiredHome).toEqual(expect.any(String)); + await expect(access(acquiredHome!)).rejects.toMatchObject({ code: "ENOENT" }); + expect(finished.error).toContain("Invalid fixture skill configuration"); + await waitForPendingRunFailureReports(); + expect(capturedFailure).toHaveBeenCalled(); + expect(JSON.stringify(capturedFailure.mock.calls)).toContain("Invalid fixture skill configuration"); + expect(JSON.stringify(capturedFailure.mock.calls)).not.toContain(f.credential); + await provider.forceFlush(); + const runIdHash = createHash("sha256").update(finished.id).digest("hex").slice(0, 12); + const steps = exporter.getFinishedSpans().filter(span => span.name.startsWith("heartbeat.prepare.configuration_") + && span.attributes["paperclip.task.run.run_id"] === runIdHash); + expect(steps.find(span => span.name === "heartbeat.prepare.configuration_ai_runtime")?.status.code).toBe(0); + expect(steps.find(span => span.name === "heartbeat.prepare.configuration_skills")?.status).toEqual({ code: 2 }); + expect(steps.some(span => span.name === "heartbeat.prepare.configuration_connector_assignments")).toBe(false); + for (const span of steps) { + expect(span.attributes).toEqual({ "paperclip.task.run.run_id": runIdHash }); + expect(span.events).toEqual([]); + } + expect(JSON.stringify(steps.map(span => ({ name: span.name, status: span.status, attributes: span.attributes, events: span.events })))).not.toContain(f.credential); + } finally { + trace.disable(); + await provider.shutdown(); + } }); it("defers a busy account without dispatch and preserves its scheduled retry", async () => { diff --git a/server/src/services/heartbeat/execution-configuration.ts b/server/src/services/heartbeat/execution-configuration.ts index 66408dc1032..e36ee3d5f31 100644 --- a/server/src/services/heartbeat/execution-configuration.ts +++ b/server/src/services/heartbeat/execution-configuration.ts @@ -25,6 +25,7 @@ import { skillVersionSelectionMap } from "../runtime-skill-selections.js"; import type { selectHeartbeatEnvironment } from "./environment-selection.js"; import type { createHeartbeatRetries } from "./retries.js"; import type { createHeartbeatLifecycle } from "./run-lifecycle.js"; +import { createHeartbeatPreparationTiming } from "./preparation-timing.js"; import { ConfigurationIncompleteFailure, applyRunScopedMentionedSkillKeys, resolveExecutionRunAdapterConfig, resolveRunScopedMentionedSkillKeys, type createHeartbeatRunPreparation, type resolveAcceptedPlanWakeRoutingDecision, @@ -73,6 +74,7 @@ export interface HeartbeatExecutionConfigurationInput { /** Assembles effective run configuration; the executor retains cleanup ownership. */ export async function prepareHeartbeatExecutionConfiguration(db: Db, input: HeartbeatExecutionConfigurationInput) { const { run, agent, onFailureSecretsResolved, onManagedAiRuntimeAcquired, onIdentityRedactorPrepared } = input; + const time = createHeartbeatPreparationTiming(run.id); const { issueId, context, responsibleUserId, acceptedPlanContinuationWake, acceptedPlanWakeRoutingDecision, taskProjectContext, routineEnvContext } = input.task; const { sourceWorkspaceConfig, aiBinding } = input.config; const { trustPreset, useIsolatedTaskDirectory, explicitTaskDirectory } = input.policy; @@ -94,19 +96,19 @@ export async function prepareHeartbeatExecutionConfiguration(db: Db, input: Hear const skillActor: AuthorizationActor = { type: "agent", agentId: agent.id, companyId: agent.companyId, runId: run.id, source: "agent_jwt", onBehalfOfUserId: responsibleUserId === "local-board" ? null : responsibleUserId }; const runScopedMentionedSkillKeys = - await resolveRunScopedMentionedSkillKeys({ + await time("configuration_mentions", () => resolveRunScopedMentionedSkillKeys({ db, companyId: agent.companyId, issueId, commentIds: extractWakeCommentIds(context), actor: skillActor, - }); + })); const runScopedSkillKeys = acceptedPlanContinuationWake && !acceptedPlanWakeRoutingDecision?.suppressAcceptedContinuation ? [...runScopedMentionedSkillKeys, ACCEPTED_PLAN_CONVERSION_SKILL_KEY] : runScopedMentionedSkillKeys; - const githubSelection = await resolveManagedGitHubIdentitySelection( + const githubSelection = await time("configuration_github_identity", () => resolveManagedGitHubIdentitySelection( db, agent.companyId, { @@ -114,7 +116,7 @@ export async function prepareHeartbeatExecutionConfiguration(db: Db, input: Hear responsibleUserId, allowStandingDelegation: false, }, - ); + )); const useHostGitHub = !githubSelection.configured && trustPreset.kind === "standard" && @@ -123,7 +125,7 @@ export async function prepareHeartbeatExecutionConfiguration(db: Db, input: Hear ); const { resolvedConfig, configuredTaskEnvironment, secretKeys, secretManifest } = - await resolveExecutionRunAdapterConfig({ + await time("configuration_secrets", () => resolveExecutionRunAdapterConfig({ managedAiCredentials: Boolean(aiBinding), managedGitHubCredentials: !useHostGitHub, companyId: agent.companyId, @@ -142,11 +144,11 @@ export async function prepareHeartbeatExecutionConfiguration(db: Db, input: Hear routineEnv: aiBinding ? stripAiAuthBindings(routineEnvContext.env) : routineEnvContext.env, secretsSvc, trustPreset, - }); + })); onFailureSecretsResolved(() => collectRunFailureSecretValues(resolvedConfig.env, secretKeys)); if (aiBinding) { try { - managedAiRuntime = await prepareManagedAiRuntime(db, { companyId: agent.companyId, agentId: agent.id, responsibleUserId, adapterType: agent.adapterType, binding: aiBinding, config: resolvedConfig }); + managedAiRuntime = await time("configuration_ai_runtime", () => prepareManagedAiRuntime(db, { companyId: agent.companyId, agentId: agent.id, responsibleUserId, adapterType: agent.adapterType, binding: aiBinding, config: resolvedConfig })); onManagedAiRuntimeAcquired(managedAiRuntime); } catch (error) { // Only fresh executions can receive a pre-provider wait receipt. A @@ -206,7 +208,7 @@ export async function prepareHeartbeatExecutionConfiguration(db: Db, input: Hear const nativeRunnerPreparationSpans: NativeRunHistoricalSpan[] = []; const skillsPrepareStartedAtMs = Date.now(); let skillDeliveryConfig = effectiveResolvedConfig; - const runtimeSkillEntries = await (async () => { + const runtimeSkillEntries = await time("configuration_skills", async () => { try { const storedVersions = parseObject(run.contextSnapshot?.skillVersions); const hasStoredVersions = Object.prototype.hasOwnProperty.call(run.contextSnapshot ?? {}, "skillVersions"); @@ -261,26 +263,26 @@ export async function prepareHeartbeatExecutionConfiguration(db: Db, input: Hear } throw error; } - })(); + }); nativeRunnerPreparationSpans.push({ name: "skills.prepare", parentName: "task.prepare", startedAtMs: skillsPrepareStartedAtMs, endedAtMs: Date.now(), }); - const connectorAssignments = await resolveConnectorAssignments(db, { companyId: agent.companyId, agentId: agent.id, runId: run.id, issueId: typeof context.issueId === "string" ? context.issueId : undefined }); - const connectorSkillConfig = await applyConnectorSkills(skillDeliveryConfig, runtimeSkillEntries, connectorAssignments); + const connectorAssignments = await time("configuration_connector_assignments", () => resolveConnectorAssignments(db, { companyId: agent.companyId, agentId: agent.id, runId: run.id, issueId: typeof context.issueId === "string" ? context.issueId : undefined })); + const connectorSkillConfig = await time("configuration_connector_skills", () => applyConnectorSkills(skillDeliveryConfig, runtimeSkillEntries, connectorAssignments)); // Both CLI adapters and native context materialization use the same resolved set. runtimeSkillEntries.splice(0, runtimeSkillEntries.length, ...connectorSkillConfig.paperclipRuntimeSkills); - const connectorDelivery = await prepareConnectorSkillDelivery(connectorSkillConfig, agent.adapterType); + const connectorDelivery = await time("configuration_connector_delivery", () => prepareConnectorSkillDelivery(connectorSkillConfig, agent.adapterType)); // Always replace this runtime-only field; caller wake data cannot supply skills. context.paperclipWake = { ...parseObject(context.paperclipWake), connectorSkillInstructions: connectorDelivery.instructions }; - let runtimeConfig = await prepareConnectionInstructionDelivery({ + let runtimeConfig = await time("configuration_connection_instructions", () => prepareConnectionInstructionDelivery({ resolve: () => resolveAssignedConnectionInstructionsForRun(db, { companyId: agent.companyId, agentId: agent.id, runId: run.id }), context, config: connectorDelivery.config, native: agent.adapterType === "paperclip_runner", - }); + })); const agentIdentity = supportsManagedAgentIdentity(agent.adapterType, agent.adapterConfig, run.runtimeMode === "native" ? run.driverKind : undefined) - ? await agentIdentityService(db).ensureAgentIdentity(agent.companyId, agent.id) + ? await time("configuration_agent_identity", () => agentIdentityService(db).ensureAgentIdentity(agent.companyId, agent.id)) : undefined; const identityRedactor = createAgentIdentityRedactor(agentIdentity?.privateKeyPem); onIdentityRedactorPrepared(identityRedactor); diff --git a/server/src/services/heartbeat/preparation-timing-context.test.ts b/server/src/services/heartbeat/preparation-timing-context.test.ts index cac3d5f12ef..824bf85bbf5 100644 --- a/server/src/services/heartbeat/preparation-timing-context.test.ts +++ b/server/src/services/heartbeat/preparation-timing-context.test.ts @@ -77,7 +77,7 @@ it("honors an operator sampler that disables root traces even when the trigger i } }); -it("stays silent and preserves values and errors without a tracer provider", async () => { +it.each(["workspace", "configuration_ai_runtime", "configuration_skills", "configuration_agent_identity"] as const)("stays silent and preserves values and errors without a tracer provider for %s", async phase => { trace.disable(); context.disable(); const messages = ["log", "info", "warn", "error", "debug"] as const; @@ -85,12 +85,12 @@ it("stays silent and preserves values and errors without a tracer provider", asy try { const time = createHeartbeatPreparationTiming("unconfigured-run"); const result = {}; - await expect(time("workspace", async () => { + await expect(time(phase, async () => { expect(trace.getActiveSpan()?.isRecording()).not.toBe(true); return result; })).resolves.toBe(result); const error = new Error("original failure"); - await expect(time("instructions", async () => { throw error; })).rejects.toBe(error); + await expect(time(phase, async () => { throw error; })).rejects.toBe(error); for (const spy of spies) expect(spy).not.toHaveBeenCalled(); } finally { for (const spy of spies) spy.mockRestore(); diff --git a/server/src/services/heartbeat/preparation-timing.ts b/server/src/services/heartbeat/preparation-timing.ts index 2372c0bbf41..7cdad97b685 100644 --- a/server/src/services/heartbeat/preparation-timing.ts +++ b/server/src/services/heartbeat/preparation-timing.ts @@ -3,7 +3,11 @@ import { isSpanContextValid, ROOT_CONTEXT, SpanStatusCode, trace } from "@opente type PreparationPhase = "environment_selection" | "execution_configuration" | "session" | "workspace" | "github_environment" | "github_launchers" | "run_output" - | "workspace_validation" | "runtime_services" | "instructions" | "runtime_selection"; + | "workspace_validation" | "runtime_services" | "instructions" | "runtime_selection" + | "configuration_mentions" | "configuration_github_identity" | "configuration_secrets" + | "configuration_ai_runtime" | "configuration_skills" | "configuration_connector_assignments" + | "configuration_connector_skills" | "configuration_connector_delivery" + | "configuration_connection_instructions" | "configuration_agent_identity"; export function createHeartbeatPreparationTiming(runId: string) { const runIdHash = createHash("sha256").update(runId).digest("hex").slice(0, 12);