diff --git a/src/cli/agent-runner.ts b/src/cli/agent-runner.ts index 5ef8af7..18ef136 100644 --- a/src/cli/agent-runner.ts +++ b/src/cli/agent-runner.ts @@ -31,6 +31,7 @@ import { currentAgentEnvPathForHome, managedAgentEnvPathForHome, primaryRepoFromConfig, + providerEnvPathForHome, readSetupConfigFromHome, resolveAgentRailHome, type ConnectedRepo, @@ -41,8 +42,10 @@ import type { SetupConfig } from "./setup-config.ts"; import type { TaskBlocker, TaskPriority, TaskStatus } from "../task-store.ts"; import type { TelemetryClient, + TelemetryDurationBucket, TelemetryEventName, TelemetryFailureCategory, + TelemetryOutcome, TelemetryProperties, TelemetryTaskStatus, } from "../telemetry.ts"; @@ -709,6 +712,7 @@ async function executeAgentRun({ fetchImpl, runnerTimeoutMs, runnerPolicy: setupConfig?.runnerPolicy ?? null, + setupConfig, telemetry, }); } catch (error) { @@ -844,6 +848,7 @@ async function executeSingleTaskRun({ fetchImpl, runnerTimeoutMs, runnerPolicy, + setupConfig, telemetry, }: { agentId: string; @@ -865,6 +870,7 @@ async function executeSingleTaskRun({ fetchImpl: typeof globalThis.fetch; runnerTimeoutMs: number; runnerPolicy?: RunnerExecutionPolicyLike | null; + setupConfig?: SetupConfigLike | null; telemetry?: TelemetryClient; }): Promise { const timestamp = now().toISOString(); @@ -980,8 +986,48 @@ async function executeSingleTaskRun({ let filesystemSnapshot: RunnerPolicyFilesystemSnapshot | null = null; let runnerFailureCaptured = false; + let runnerStartedAt: number | null = null; + let runnerCompletionCaptured = false; + + const captureRunnerCompletionOnce = (outcome: TelemetryOutcome): void => { + if (runnerStartedAt === null || runnerCompletionCaptured) { + return; + } + runnerCompletionCaptured = true; + captureRunnerTelemetry(telemetry, "runner_completed", { + runner: safeTelemetryRunner(runner), + outcome, + durationBucket: bucketDuration(Date.now() - runnerStartedAt), + }); + }; try { + const submitProviderReady = await detectSubmitProviderReady(setupConfig, homePath); + if (!submitProviderReady.ok) { + captureRunnerTelemetry(telemetry, "runner_failed", { + runner: safeTelemetryRunner(runner), + failureCategory: "provider_not_configured", + }); + runnerFailureCaptured = true; + return await blockManagedRunAwaitingUser({ + baseUrl, + apiKey, + fetchImpl, + task, + runId, + agentId, + runStore, + homePath, + markdownEnabled, + now, + summary: submitProviderReady.message, + blocker: { + reason: "provider_not_configured", + actionRequired: submitProviderReady.message, + resumeInstructions: "Run `agentrail provider connect github`, then `agentrail task resume ` to retry.", + }, + }); + } await prepareWorktree({ repoPath: repo.path, worktreePath, @@ -1014,6 +1060,11 @@ async function executeSingleTaskRun({ actionRequired: `Choose a runner/policy AgentRail can enforce, or configure an external sandbox/advisory mode. ${summary}`, resumeInstructions: "Update the agent runner policy or selected runner, then run `agentrail task resume ` so AgentRail can start a fresh managed run.", }; + captureRunnerTelemetry(telemetry, "runner_failed", { + runner: safeTelemetryRunner(runner), + failureCategory: "runner_policy_denied", + }); + runnerFailureCaptured = true; return await blockManagedRunAwaitingUser({ baseUrl, apiKey, @@ -1034,6 +1085,11 @@ async function executeSingleTaskRun({ filesystemSnapshot = filesystemPreflight.snapshot; if (!filesystemPreflight.ok) { const summary = filesystemPreflight.summary; + captureRunnerTelemetry(telemetry, "runner_failed", { + runner: safeTelemetryRunner(runner), + failureCategory: "runner_policy_denied", + }); + runnerFailureCaptured = true; return await blockManagedRunAwaitingUser({ baseUrl, apiKey, @@ -1057,6 +1113,7 @@ async function executeSingleTaskRun({ await writeRunnerPolicyGeneratedFiles(runnerPlan); captureRunnerTelemetry(telemetry, "runner_started", buildRunnerStartedTelemetryProperties(runner, task.status)); + runnerStartedAt = Date.now(); const result = await launchRunner({ runner, executable: runnerPlan.executable, @@ -1090,6 +1147,14 @@ async function executeSingleTaskRun({ const filesystemPostRun = await validateRunnerPolicyFilesystemPostRun(runnerPlan, filesystemSnapshot); if (!filesystemPostRun.ok) { const summary = filesystemPostRun.summary; + if (!runnerFailureCaptured) { + captureRunnerTelemetry(telemetry, "runner_failed", { + runner: safeTelemetryRunner(runner), + failureCategory: "runner_policy_violation", + }); + runnerFailureCaptured = true; + } + captureRunnerCompletionOnce("blocked"); return await blockManagedRunAwaitingUser({ baseUrl, apiKey, @@ -1147,6 +1212,7 @@ async function executeSingleTaskRun({ if (markdownEnabled) { await writeRunMarkdown({ homePath, run: completed }); } + captureRunnerCompletionOnce(runnerStatusToOutcome(finalResult.status)); return completed; } catch (error) { if (!runnerFailureCaptured) { @@ -1154,7 +1220,9 @@ async function executeSingleTaskRun({ runner: safeTelemetryRunner(runner), failureCategory: classifyRunnerFailure(error), }); + runnerFailureCaptured = true; } + captureRunnerCompletionOnce("failed"); if (runnerPlan && filesystemSnapshot) { try { await restoreProtectedInstructionFileModes(runnerPlan, filesystemSnapshot); @@ -1252,20 +1320,109 @@ function safeTelemetryTaskStatus(value: unknown): TelemetryTaskStatus | undefine } } -function classifyRunnerFailure(error: unknown): TelemetryFailureCategory { +async function detectSubmitProviderReady( + setupConfig: SetupConfigLike | null | undefined, + homePath: string, +): Promise<{ ok: boolean; message: string }> { + const github = setupConfig?.providers?.github; + const mode = github?.mode === "real" || github?.mode === "disabled" ? github.mode : "real"; + if (mode === "disabled") { + return { ok: true, message: "" }; + } + const tokenEnvName = github?.tokenEnv?.trim() || "GITHUB_TOKEN"; + if (process.env[tokenEnvName]?.trim()) { + return { ok: true, message: "" }; + } + try { + const content = await readFile(providerEnvPathForHome(homePath), "utf8"); + if (parseSimpleEnv(content)[tokenEnvName]?.trim()) { + return { ok: true, message: "" }; + } + } catch { + // Missing provider.env is treated as "not configured". + } + return { + ok: false, + message: + "AgentRail cannot publish a branch or open a pull request without a GitHub provider. " + + "Run `agentrail provider connect github` to enable submissions, then retry. " + + `(Looking for ${tokenEnvName} in shell env or ~/.agentrail/provider.env.)`, + }; +} + +export function classifyRunnerFailure(error: unknown): TelemetryFailureCategory { const text = runnerFailureText(error); if (/\b(etimedout|timeout|timed out)\b/u.test(text)) { return "runner_timeout"; } + if (/\b(econnrefused|enetunreach|enotfound|getaddrinfo)\b/u.test(text) + || /\bfetch failed\b/u.test(text) + || /network unreachable/u.test(text)) { + return "network_error"; + } if (/\b(eacces|eperm)\b/u.test(text) || /sandbox|permission|denied/u.test(text)) { return "sandbox_blocked"; } + if (/\bprompt\b[^.]{0,80}(too (large|long)|exceeded|max tokens|token limit)/u.test(text) + || /context (window|length).{0,40}exceed/u.test(text)) { + return "prompt_too_large"; + } + if (/(refused|declined|cannot comply|will not).{0,40}(request|task|instruction|prompt)/u.test(text)) { + return "model_refused"; + } + if (/template (not modified|unedited|unchanged)/u.test(text) + || /result template.{0,40}(unedited|not modified)/u.test(text)) { + return "result_template_unedited"; + } + if (/\bhandoff\b/u.test(text) + || /result\.json.{0,40}(malformed|invalid|missing|not (found|written))/u.test(text)) { + return "handoff_invalid"; + } if (/\b(enoent)\b/u.test(text) || /not found|command not found|executable|missing/u.test(text)) { return "runner_missing"; } + if (/exit code|exited with|non-?zero exit/u.test(text)) { + return "nonzero_exit"; + } return "unknown"; } +export function bucketDuration(elapsedMs: number): TelemetryDurationBucket { + if (!Number.isFinite(elapsedMs) || elapsedMs < 0) { + return "sub_1s"; + } + if (elapsedMs < 1000) { + return "sub_1s"; + } + if (elapsedMs < 5000) { + return "1_5s"; + } + if (elapsedMs < 30000) { + return "5_30s"; + } + if (elapsedMs < 120000) { + return "30_120s"; + } + return "over_120s"; +} + +function runnerStatusToOutcome(status: unknown): TelemetryOutcome { + switch (status) { + case "succeeded": + return "succeeded"; + case "failed": + return "failed"; + case "cancelled": + return "cancelled"; + case "awaiting_user": + return "awaiting_user"; + case "blocked": + return "blocked"; + default: + return "unknown"; + } +} + function runnerFailureText(error: unknown): string { const parts: string[] = []; if (isRecord(error) && typeof error.code === "string") { diff --git a/src/telemetry.ts b/src/telemetry.ts index dd4993c..84d93ba 100644 --- a/src/telemetry.ts +++ b/src/telemetry.ts @@ -17,6 +17,7 @@ export const TELEMETRY_EVENT_NAMES = [ "runner_wake_attempted", "runner_started", "runner_failed", + "runner_completed", "pr_opened", "ci_status_observed", "review_status_observed", @@ -47,6 +48,15 @@ const TELEMETRY_FAILURE_CATEGORY_VALUES = [ "runner_timeout", "sandbox_blocked", "routing_no_agent", + "nonzero_exit", + "handoff_invalid", + "result_template_unedited", + "network_error", + "runner_policy_denied", + "runner_policy_violation", + "prompt_too_large", + "model_refused", + "provider_not_configured", "unknown", ] as const; const TELEMETRY_CI_STATUS_VALUES = [ @@ -84,6 +94,8 @@ const TELEMETRY_OUTCOME_VALUES = [ "no_route", "conflict", "awaiting_user", + "succeeded", + "cancelled", "unknown", ] as const; const TELEMETRY_DURATION_BUCKET_VALUES = ["sub_1s", "1_5s", "5_30s", "30_120s", "over_120s"] as const; diff --git a/test/agent-runner.test.ts b/test/agent-runner.test.ts index 4b471f3..2a8ecdc 100644 --- a/test/agent-runner.test.ts +++ b/test/agent-runner.test.ts @@ -11,7 +11,12 @@ import { createServer } from "../src/app.ts"; import { AgentAuthStore } from "../src/agent-auth-store.ts"; import { AgentRunStore, type AgentRunRecord, type AgentRunStatus } from "../src/agent-run-store.ts"; import { AgentTaskQueue } from "../src/agent-task-queue.ts"; -import { defaultPrepareWorktree, runAgentReport } from "../src/cli/agent-runner.ts"; +import { + bucketDuration, + classifyRunnerFailure, + defaultPrepareWorktree, + runAgentReport, +} from "../src/cli/agent-runner.ts"; import { runCli } from "../src/cli/index.ts"; import { createSetupConfig } from "../src/cli/setup-config.ts"; import { writeSetupFiles } from "../src/cli/setup-files.ts"; @@ -431,7 +436,7 @@ test("agent run --once starts assigned work, records the run, and writes markdow assert.deepEqual( telemetryEvents.map((event) => event.eventName), - ["runner_wake_attempted", "runner_started"], + ["runner_wake_attempted", "runner_started", "runner_completed"], ); assert.deepEqual(telemetryEvents[0].properties, { runner: "codex", @@ -441,6 +446,12 @@ test("agent run --once starts assigned work, records the run, and writes markdow runner: "codex", taskStatus: "in_progress", }); + assert.equal(telemetryEvents[2].properties.runner, "codex"); + assert.equal(telemetryEvents[2].properties.outcome, "succeeded"); + assert.ok( + typeof telemetryEvents[2].properties.durationBucket === "string", + "runner_completed should include a durationBucket", + ); const telemetryJson = JSON.stringify(telemetryEvents); assert.equal(telemetryJson.includes(task.id), false); assert.equal(telemetryJson.includes(task.title), false); @@ -3804,12 +3815,16 @@ test("agent run blocks before launching Codex when denied read files are present assert.deepEqual( telemetryEvents.map((event) => event.eventName), - ["runner_wake_attempted"], + ["runner_wake_attempted", "runner_failed"], ); assert.deepEqual(telemetryEvents[0].properties, { runner: "codex", count: 1, }); + assert.deepEqual(telemetryEvents[1].properties, { + runner: "codex", + failureCategory: "runner_policy_denied", + }); }); test("agent run emits runner_failed when a consumed handoff leaves task state unchanged", async (t) => { @@ -3899,12 +3914,18 @@ test("agent run emits runner_failed when a consumed handoff leaves task state un assert.deepEqual( telemetryEvents.map((event) => event.eventName), - ["runner_wake_attempted", "runner_started", "runner_failed"], + ["runner_wake_attempted", "runner_started", "runner_failed", "runner_completed"], ); assert.deepEqual(telemetryEvents[2].properties, { runner: "codex", - failureCategory: "unknown", + failureCategory: "handoff_invalid", }); + assert.equal(telemetryEvents[3].properties.runner, "codex"); + assert.equal(telemetryEvents[3].properties.outcome, "failed"); + assert.ok( + typeof telemetryEvents[3].properties.durationBucket === "string", + "runner_completed should include a durationBucket", + ); const telemetryJson = JSON.stringify(telemetryEvents); assert.equal(telemetryJson.includes(run.summary ?? ""), false); assert.equal(telemetryJson.includes(task.id), false); @@ -3913,6 +3934,101 @@ test("agent run emits runner_failed when a consumed handoff leaves task state un assert.equal(telemetryJson.includes(homePath), false); }); +test("agent run blocks before launching the runner when GitHub provider is not connected", async (t) => { + const repoRoot = await mkdtemp(path.join(os.tmpdir(), "agentrail-agent-run-no-gh-")); + const homePath = await mkdtemp(path.join(os.tmpdir(), "agentrail-home-")); + const agentRunStorePath = path.join(homePath, "stores", "agent-runs.json"); + const harness = await createHarness({ agentRunStorePath }); + const stdout = createMemoryWriter(); + const stderr = createMemoryWriter(); + const previousHome = process.env.AGENTRAIL_HOME; + const previousToken = process.env.GITHUB_TOKEN; + const telemetryEvents: Array<{ eventName: string; properties: unknown }> = []; + process.env.AGENTRAIL_HOME = homePath; + delete process.env.GITHUB_TOKEN; + + t.after(async () => { + await rm(repoRoot, { recursive: true, force: true }); + await rm(homePath, { recursive: true, force: true }); + if (previousHome === undefined) delete process.env.AGENTRAIL_HOME; + else process.env.AGENTRAIL_HOME = previousHome; + if (previousToken !== undefined) process.env.GITHUB_TOKEN = previousToken; + await harness.close(); + }); + + // Provider mode "real" without a GITHUB_TOKEN — the failure mode behind + // the silently-501 codex runs observed in production. + await writeSetupRepo(repoRoot, homePath, harness.baseUrl, false, { providerMode: "real" }); + const task = harness.taskQueue.createTask({ + identifier: "AGEA-RUN-NO-GH", + title: "Block when GitHub is not connected", + assignee: { id: "agt_runner", name: "Runner" }, + assigneeAgentId: "agt_runner", + status: "todo", + availableActions: ["start"], + }); + await writeAgentEnv(homePath, { + AGENTRAIL_BASE_URL: harness.baseUrl, + AGENTRAIL_API_KEY: harness.apiKey, + AGENTRAIL_AGENT_ID: "agt_runner", + AGENTRAIL_AGENT_RUNNER: "codex", + AGENTRAIL_MAX_CONCURRENT_TASKS: "1", + AGENTRAIL_REPO_ALLOWLIST: "oxnw/agentrail", + }); + + let launchRunnerCalled = false; + let prepareWorktreeCalled = false; + const exitCode = await runCli(["agent", "run", "--agent-id", "agt_runner", "--once"], { + cwd: repoRoot, + stdout, + stderr, + telemetry: { + capture(eventName, properties) { + telemetryEvents.push({ eventName, properties }); + }, + }, + agentRunner: { + prepareWorktree: async () => { + prepareWorktreeCalled = true; + }, + launchRunner: async () => { + launchRunnerCalled = true; + throw new Error("runner should not launch when GitHub provider is missing"); + }, + publishBranch: async () => { + throw new Error("publishBranch should not run when GitHub provider is missing"); + }, + }, + }); + + assert.equal(exitCode, 0, stderr.toString()); + assert.equal(launchRunnerCalled, false, "launchRunner must not be called"); + assert.equal(prepareWorktreeCalled, false, "prepareWorktree must not be called"); + + const storedTask = harness.taskQueue.getRawTask(task.id); + assert.equal(storedTask?.status, "blocked"); + assert.equal(storedTask?.blocker?.reason, "provider_not_configured"); + assert.match(storedTask?.blocker?.actionRequired ?? "", /agentrail provider connect github/); + + const runStore = new AgentRunStore({ storagePath: agentRunStorePath }); + const [run] = runStore.listRuns(); + assert.equal(run.status, "awaiting_user"); + assert.equal(run.userAction?.reason, "provider_not_configured"); + + const runnerFailedEvents = telemetryEvents.filter((event) => event.eventName === "runner_failed"); + assert.equal(runnerFailedEvents.length, 1); + assert.deepEqual(runnerFailedEvents[0].properties, { + runner: "codex", + failureCategory: "provider_not_configured", + }); + // runner_completed must NOT fire because runner_started never fired. + assert.equal( + telemetryEvents.some((event) => event.eventName === "runner_completed"), + false, + "runner_completed should not fire for a pre-launch block", + ); +}); + test("agent run blocks after Codex creates denied write files", async (t) => { const repoRoot = await mkdtemp(path.join(os.tmpdir(), "agentrail-agent-run-denied-postrun-")); const homePath = await mkdtemp(path.join(os.tmpdir(), "agentrail-home-")); @@ -4446,6 +4562,46 @@ test("agent status reads the persisted run store", async (t) => { assert.equal(body.data[0].status, "awaiting_user"); }); +test("classifyRunnerFailure maps known failure signatures to specific categories", () => { + const cases: Array<[unknown, string]> = [ + [new Error("operation timed out after 60s"), "runner_timeout"], + [Object.assign(new Error("connect"), { code: "ETIMEDOUT" }), "runner_timeout"], + [Object.assign(new Error("fetch failed"), { code: "ECONNREFUSED" }), "network_error"], + [new Error("getaddrinfo ENOTFOUND api.example.com"), "network_error"], + [Object.assign(new Error("permission denied"), { code: "EACCES" }), "sandbox_blocked"], + [new Error("Prompt was too large; max tokens exceeded"), "prompt_too_large"], + [new Error("Model refused the request due to policy"), "model_refused"], + [new Error("Result template not modified — runner did not edit result.json"), "result_template_unedited"], + [new Error("AgentRail consumed the handoff but task state did not progress"), "handoff_invalid"], + [new Error("result.json was malformed and could not be parsed"), "handoff_invalid"], + [Object.assign(new Error("spawn codex"), { code: "ENOENT" }), "runner_missing"], + [new Error("runner exited with non-zero exit code 1"), "nonzero_exit"], + [new Error("Some opaque failure with no signal"), "unknown"], + ]; + for (const [input, expected] of cases) { + assert.equal( + classifyRunnerFailure(input), + expected, + `expected ${expected} for ${input instanceof Error ? input.message : String(input)}`, + ); + } +}); + +test("bucketDuration maps elapsed milliseconds to the duration bucket enum", () => { + assert.equal(bucketDuration(0), "sub_1s"); + assert.equal(bucketDuration(500), "sub_1s"); + assert.equal(bucketDuration(999), "sub_1s"); + assert.equal(bucketDuration(1000), "1_5s"); + assert.equal(bucketDuration(4999), "1_5s"); + assert.equal(bucketDuration(5000), "5_30s"); + assert.equal(bucketDuration(29999), "5_30s"); + assert.equal(bucketDuration(30000), "30_120s"); + assert.equal(bucketDuration(119999), "30_120s"); + assert.equal(bucketDuration(120000), "over_120s"); + assert.equal(bucketDuration(-1), "sub_1s"); + assert.equal(bucketDuration(Number.NaN), "sub_1s"); +}); + function captureRunContextEnv(): () => void { const keys = [ "AGENTRAIL_RUN_ID", @@ -4517,6 +4673,7 @@ async function writeSetupRepo( options?: { runnerPolicy?: Parameters[0]["runnerPolicy"]; managedRuns?: ReturnType["managedRuns"]; + providerMode?: "real" | "disabled"; }, ) { const config = createSetupConfig({ @@ -4530,7 +4687,7 @@ async function writeSetupRepo( interactionMode: "non_interactive", acceptedDefaults: true, baseUrl, - providerMode: "disabled", + providerMode: options?.providerMode ?? "disabled", markdownExport, runnerPolicy: options?.runnerPolicy, }); diff --git a/test/telemetry.test.ts b/test/telemetry.test.ts index 2f4ce07..07dece4 100644 --- a/test/telemetry.test.ts +++ b/test/telemetry.test.ts @@ -30,6 +30,7 @@ test("TELEMETRY_EVENT_NAMES exports the supported telemetry event allowlist", () "runner_wake_attempted", "runner_started", "runner_failed", + "runner_completed", "pr_opened", "ci_status_observed", "review_status_observed", @@ -152,6 +153,36 @@ test("sanitizeTelemetryProperties preserves runtime telemetry enum values", () = ); }); +test("sanitizeTelemetryProperties preserves expanded runner failure categories", () => { + const expanded = [ + "nonzero_exit", + "handoff_invalid", + "result_template_unedited", + "network_error", + "runner_policy_denied", + "runner_policy_violation", + "prompt_too_large", + "model_refused", + ]; + for (const category of expanded) { + assert.deepEqual( + sanitizeTelemetryProperties({ failureCategory: category }), + { failureCategory: category }, + `expected failureCategory=${category} to be preserved`, + ); + } +}); + +test("sanitizeTelemetryProperties preserves runner_completed outcome values", () => { + for (const outcome of ["succeeded", "cancelled"]) { + assert.deepEqual( + sanitizeTelemetryProperties({ outcome }), + { outcome }, + `expected outcome=${outcome} to be preserved`, + ); + } +}); + test("disabled-by-config telemetry sends nothing", async () => { const delivered: TelemetrySinkEvent[] = []; const telemetry = createTelemetry({