coderouter: single usage-read timeouts stay out of Sentry

web/services/coderouter/usage.ts

@@ -12,6 +12,7 @@ import {
 } from "./refresh";
 import { fetchProviderRead } from "./providerFetch";
 import { addCoderouterBreadcrumb, reportCoderouterFailure } from "./observability";
+import { recordCoderouterSpan } from "./requestTelemetry";
 import type { CodeRouterAccountSummary, CodeRouterCredential } from "./types";
 
 const CODEX_USAGE_URL = "https://chatgpt.com/backend-api/wham/usage";
@@ -23,6 +24,8 @@ export type AccountsUsageDependencies = {
   readonly credential: typeof freshCredential;
   readonly fetchUsage: (credential: CodeRouterCredential) => Promise<Response>;
   readonly report: typeof reportCoderouterFailure;
+  /** Records a usage-read timeout that is not reported. Defaults to a log line and a route span. */
+  readonly observeTimeout?: (observation: UsageTimeoutObservation) => void;
   /** Consecutive usage-read timeouts per account; defaults to one tracker per loader. */
   readonly timeoutStreaks?: UsageTimeoutStreaks;
 };
@@ -34,6 +37,11 @@ export type AccountsUsageDependencies = {
 export const USAGE_TIMEOUT_ERROR_STREAK = 3;
 const MAX_TRACKED_TIMEOUT_ACCOUNTS = 1_000;
 
+export type UsageTimeoutObservation = {
+  readonly provider: string;
+  readonly consecutive: number;
+};
+
 export type UsageTimeoutStreaks = {
   readonly record: (accountId: string) => number;
   readonly clear: (accountId: string) => void;
@@ -72,12 +80,14 @@ type AccountWithUsage = CodeRouterAccountSummary & {
 
 type ResolvedUsageDependencies = AccountsUsageDependencies & {
   readonly timeoutStreaks: UsageTimeoutStreaks;
+  readonly observeTimeout: (observation: UsageTimeoutObservation) => void;
 };
 
 export function createAccountsUsageLoader(supplied: AccountsUsageDependencies) {
   const dependencies: ResolvedUsageDependencies = {
     ...supplied,
     timeoutStreaks: supplied.timeoutStreaks ?? createUsageTimeoutStreaks(),
+    observeTimeout: supplied.observeTimeout ?? observeUsageTimeout,
   };
   return async (teamId: string, access?: CoderouterAccountAccess) => {
     const startedAt = performance.now();
@@ -130,13 +140,13 @@ async function accountUsage(
       known,
     });
     if (credential.provider !== "codex") return account;
-    let response = await dependencies.fetchUsage(credential);
+    let response = await usageRead(() => dependencies.fetchUsage(credential));
     if (response.status === 401) {
       // Release the rejected response's connection before the retry.
       await response.body?.cancel().catch(() => undefined);
       const refreshed = await refreshRejectedCredential(dependencies, teamId, account, known);
       if (refreshed.provider !== "codex") return account;
-      response = await dependencies.fetchUsage(refreshed);
+      response = await usageRead(() => dependencies.fetchUsage(refreshed));
     }
     if (!response.ok) {
       await response.body?.cancel().catch(() => undefined);
@@ -150,7 +160,7 @@ async function accountUsage(
       );
       return { ...account, usageError: `HTTP ${response.status}` };
     }
-    const usage: unknown = await response.json();
+    const usage: unknown = await usageRead(() => response.json());
     dependencies.timeoutStreaks.clear(account.id);
     const cooldownMs = usageCooldown(usage);
     if (cooldownMs !== null) {
@@ -167,7 +177,7 @@ async function accountUsage(
     if (error instanceof CodeRouterRefreshBusy) {
       return { ...account, usageError: "credential_refreshing" };
     }
-    if (isTimeout(error)) return reportUsageTimeout(dependencies, account, error);
+    if (error instanceof UsageReadTimeout) return reportUsageTimeout(dependencies, account, error.cause);
     dependencies.report("provider_usage", error, {
       provider: account.provider,
     });
@@ -176,28 +186,56 @@ async function accountUsage(
 }
 
 /**
- * The usage endpoint answers in ~0.35 s at p50 and ~2 s at p99; a read past
- * the 5 s budget is almost always a stalled response body. The account list
- * is polled, so the next poll retries: one timeout is an upstream warning,
- * and only an account that keeps timing out escalates to an error.
+ * The usage endpoint answers in ~0.35 s at p50; its tail stalls a response
+ * body past the 5 s budget on a few percent of reads while the provider is
+ * degraded. The account list is polled, so the next poll retries. A timeout
+ * is always logged and kept on the route trace; only an account that keeps
+ * timing out reports to Sentry, as an error.
  */
 function reportUsageTimeout(
   dependencies: ResolvedUsageDependencies,
   account: CodeRouterAccountSummary,
   error: unknown,
 ): AccountWithUsage {
   const consecutive = dependencies.timeoutStreaks.record(account.id);
-  dependencies.report(
-    "provider_usage",
-    error,
-    { provider: account.provider, timeout: true, consecutive },
-    consecutive >= USAGE_TIMEOUT_ERROR_STREAK ? {} : { fault: "upstream" },
-  );
+  dependencies.observeTimeout({ provider: account.provider, consecutive });
+  if (consecutive >= USAGE_TIMEOUT_ERROR_STREAK) {
+    dependencies.report(
+      "provider_usage",
+      error,
+      { provider: account.provider, timeout: true, consecutive },
+    );
+  }
   return { ...account, usageError: "timeout" };
 }
 
-function isTimeout(error: unknown): boolean {
-  return error instanceof Error && error.name === "TimeoutError";
+function observeUsageTimeout(observation: UsageTimeoutObservation): void {
+  console.warn("coderouter.usage_timeout", observation);
+  recordCoderouterSpan({
+    name: "usage_timeout",
+    startedAt: performance.now(),
+    attributes: { provider: observation.provider, timeout: true, consecutive: observation.consecutive },
+  });
+}
+
+/**
+ * Marks a timeout from the usage read itself. Credential refresh timeouts
+ * keep their normal reporting and never count toward the streak.
+ */
+class UsageReadTimeout extends Error {
+  constructor(readonly cause: unknown) {
+    super("usage read timed out");
+    this.name = "TimeoutError";
+  }
+}
+
+async function usageRead<T>(read: () => Promise<T>): Promise<T> {
+  try {
+    return await read();
+  } catch (error) {
+    if (error instanceof Error && error.name === "TimeoutError") throw new UsageReadTimeout(error);
+    throw error;
+  }
 }
 
 /**

web/tests/coderouter-usage-timeouts.test.ts

@@ -65,6 +65,7 @@ type Reported = {
 /** One loader whose usage reads follow `outcomes` in order, sharing one streak tracker. */
 function poller(outcomes: Array<"timeout" | "ok">) {
   const reported: Reported[] = [];
+  const observed: number[] = [];
   const load = createAccountsUsageLoader({
     listAccounts: async () => [account],
     listEncryptedCredentials: async () => [envelope],
@@ -80,31 +81,33 @@ function poller(outcomes: Array<"timeout" | "ok">) {
     report: (failure, _error, context = {}, options = {}) => {
       reported.push({ failure, context, options });
     },
+    observeTimeout: (observation) => {
+      observed.push(observation.consecutive);
+    },
     timeoutStreaks: createUsageTimeoutStreaks(),
   });
-  return { load, reported };
+  return { load, reported, observed };
 }
 
 describe("coderouter usage read timeouts", () => {
-  test("a single usage-read timeout is an upstream warning, not an operator error", async () => {
+  test("a single usage-read timeout is observed but never reported to Sentry", async () => {
     const run = poller(["timeout"]);
     const result = await run.load("team-1");
     expect(result.accounts[0]).toMatchObject({ usageError: "timeout" });
-    expect(run.reported).toHaveLength(1);
-    expect(run.reported[0]).toMatchObject({
-      failure: "provider_usage",
-      context: { provider: "codex", timeout: true, consecutive: 1 },
-      options: { fault: "upstream" },
-    });
+    expect(run.reported).toEqual([]);
+    expect(run.observed).toEqual([1]);
   });
 
-  test("an account that times out on consecutive polls escalates to an error", async () => {
+  test("only an account that times out on consecutive polls reports, as an error", async () => {
     const run = poller(Array.from({ length: USAGE_TIMEOUT_ERROR_STREAK }, () => "timeout" as const));
     for (let poll = 0; poll < USAGE_TIMEOUT_ERROR_STREAK; poll++) await run.load("team-1");
-    const last = run.reported.at(-1);
-    expect(last?.context.consecutive).toBe(USAGE_TIMEOUT_ERROR_STREAK);
-    expect(last?.options.fault).toBeUndefined();
-    expect(run.reported.slice(0, -1).every((report) => report.options.fault === "upstream")).toBe(true);
+    expect(run.observed).toEqual(Array.from({ length: USAGE_TIMEOUT_ERROR_STREAK }, (_, index) => index + 1));
+    expect(run.reported).toHaveLength(1);
+    expect(run.reported[0]).toMatchObject({
+      failure: "provider_usage",
+      context: { provider: "codex", timeout: true, consecutive: USAGE_TIMEOUT_ERROR_STREAK },
+    });
+    expect(run.reported[0]?.options.fault).toBeUndefined();
   });
 
   test("a successful read resets the streak", async () => {
@@ -114,9 +117,37 @@ describe("coderouter usage read timeouts", () => {
     const polls = outcomes.length;
     const run = poller(outcomes);
     for (let poll = 0; poll < polls; poll++) await run.load("team-1");
-    const last = run.reported.at(-1);
-    expect(last?.context.consecutive).toBe(1);
-    expect(last?.options.fault).toBe("upstream");
+    expect(run.observed.at(-1)).toBe(1);
+    expect(run.reported).toEqual([]);
+  });
+
+  test("a credential refresh timeout keeps its report and does not count toward the streak", async () => {
+    const reported: Reported[] = [];
+    const observed: number[] = [];
+    const load = createAccountsUsageLoader({
+      listAccounts: async () => [account],
+      listEncryptedCredentials: async () => [envelope],
+      markCooldown: async () => {},
+      // The usage read rejects the token, so the forced refresh runs and
+      // times out: a refresh failure, not a usage-read timeout.
+      credential: async (input) => {
+        if (input.force) throw new DOMException("The operation timed out.", "TimeoutError");
+        return codex();
+      },
+      fetchUsage: async () => new Response(null, { status: 401 }),
+      report: (failure, _error, context = {}, options = {}) => {
+        reported.push({ failure, context, options });
+      },
+      observeTimeout: (observation) => {
+        observed.push(observation.consecutive);
+      },
+      timeoutStreaks: createUsageTimeoutStreaks(),
+    });
+    const result = await load("team-1");
+    expect(result.accounts[0]).toMatchObject({ usageError: "unavailable" });
+    expect(observed).toEqual([]);
+    expect(reported).toHaveLength(1);
+    expect(reported[0]?.failure).toBe("provider_usage");
   });
 
   test("upstream faults are warnings in Sentry and PostHog", () => {