Record where scorer qualification times out

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "postil-cli"
-version = "0.9.16"
+version = "0.9.17"
 edition = "2024"
 description = "Postil: a low-noise AI review gate. Silent on clean PRs, hard gate on real risk."
 license = "Apache-2.0"

bench/src/scorer-eval.test.ts

@@ -1119,51 +1119,70 @@ describe("scorer proxy and isolated runtime", () => {
   });
 
   for (const phase of ["scorer", "adjudication"] as const) {
-    test(`latches ${phase} admission timeout before a retry can dispatch upstream`, async () => {
-      let dispatches = 0;
-      const upstream = createServer(async (req: IncomingMessage, res: ServerResponse) => {
-        await requestBody(req);
-        dispatches++;
-        if (dispatches === 1) return;
-        res.writeHead(200, { "content-type": "application/json" });
-        res.end(JSON.stringify({ usage: { prompt_tokens: 3, completion_tokens: 2, cost: 0.001 } }));
-      });
-      const upstreamBase = await listen(upstream);
-      const proxy = await startScorerProxy(
-        fixture("clean-docs-only"), "falseFinding", upstreamBase, crypto.randomUUID(), 100,
-      );
-      const request = (body: object) => fetch(`${proxy.baseUrl}/chat/completions`, {
-        method: "POST", headers: { "content-type": "application/json" },
-        body: JSON.stringify(body),
-      });
-      try {
-        const first = await request(phase === "scorer" ? scorerRequest() : adjudicationRequest());
-        expect(first.status).toBe(504);
-        await first.text();
-        for (const body of [scorerRequest(), adjudicationRequest()]) {
-          const retry = await request(body);
-          expect(retry.status).toBe(400);
-          expect(await retry.json()).toEqual({ error: "qualification admission already failed after an upstream timeout" });
-        }
-        expect(dispatches).toBe(1);
-        expect(proxy.attempts).toHaveLength(1);
-        expect(proxy.attempts[0]).toMatchObject({
-          phase, outcome: "timedOut", costUsd: null, costProviderDecimal: null,
-          usageValid: false, usagePresent: false, httpStatus: null,
+    for (const headersReceived of [false, true]) {
+      test(`latches ${phase} timeout ${headersReceived ? "during body" : "before headers"} without another dispatch`, async () => {
+        const sensitive = crypto.randomUUID();
+        let dispatches = 0;
+        const upstream = createServer(async (req: IncomingMessage, res: ServerResponse) => {
+          await requestBody(req);
+          dispatches++;
+          if (dispatches === 1) {
+            if (headersReceived) {
+              res.writeHead(202, { "content-type": "application/json", "x-request-id": sensitive });
+              res.flushHeaders();
+              res.write(JSON.stringify({ private: sensitive }).slice(0, -1));
+            }
+            return;
+          }
+          res.writeHead(200, { "content-type": "application/json" });
+          res.end(JSON.stringify({ usage: { prompt_tokens: 3, completion_tokens: 2, cost: 0.001 } }));
         });
-        const diagnostics = scorerCaseDiagnostics({
-          child: { exitCode: 1, stderr: "", timedOut: false }, attempts: proxy.attempts,
+        const upstreamBase = await listen(upstream);
+        const proxy = await startScorerProxy(
+          fixture("clean-docs-only"), "falseFinding", upstreamBase, sensitive, 100,
+        );
+        const request = (body: object) => fetch(`${proxy.baseUrl}/chat/completions`, {
+          method: "POST", headers: { "content-type": "application/json" },
+          body: JSON.stringify(body),
         });
-        expect(diagnostics.failureSignals).toContain("upstreamTimeout");
-        expect(diagnostics.responses[0]).toMatchObject({
-          exactCost: "unavailable", accountingIssues: ["responseUnavailable"],
-        });
-      } finally {
-        await proxy.close();
-        upstream.closeAllConnections();
-        if (upstream.listening) await close(upstream);
-      }
-    });
+        try {
+          const first = await request(phase === "scorer" ? scorerRequest() : adjudicationRequest());
+          expect(first.status).toBe(504);
+          await first.text();
+          for (const body of [scorerRequest(), adjudicationRequest()]) {
+            const retry = await request(body);
+            expect(retry.status).toBe(400);
+            expect(await retry.json()).toEqual({ error: "qualification admission already failed after an upstream timeout" });
+          }
+          expect(dispatches).toBe(1);
+          expect(proxy.attempts).toHaveLength(1);
+          expect(proxy.attempts[0]).toMatchObject({
+            phase, outcome: "timedOut", costUsd: null, costProviderDecimal: null,
+            usageValid: false, usagePresent: false, httpStatus: headersReceived ? 202 : null,
+          });
+          const diagnostics = scorerCaseDiagnostics({
+            child: { exitCode: 1, stderr: "", timedOut: false }, attempts: proxy.attempts,
+          });
+          expect(diagnostics.failureSignals).toContain("upstreamTimeout");
+          expect(diagnostics.responses[0]).toMatchObject({
+            exactCost: "unavailable", accountingIssues: ["responseUnavailable"],
+          });
+          expect(diagnostics.responses[0]?.transport).toEqual({
+            transportPhase: headersReceived ? "readingBody" : "beforeHeaders",
+            headersReceivedMs: headersReceived ? expect.any(Number) : null,
+          });
+          if (headersReceived) {
+            expect(diagnostics.responses[0]!.transport!.headersReceivedMs!).toBeGreaterThanOrEqual(0);
+            expect(diagnostics.responses[0]!.transport!.headersReceivedMs!).toBeLessThanOrEqual(proxy.attempts[0]!.durationMs);
+          }
+          expect(JSON.stringify({ attempts: proxy.attempts, diagnostics })).not.toContain(sensitive);
+        } finally {
+          await proxy.close();
+          upstream.closeAllConnections();
+          if (upstream.listening) await close(upstream);
+        }
+      });
+    }
   }
 
   test("aborts an in-flight upstream request before proxy teardown waits", async () => {

bench/src/scorer-eval.ts

@@ -218,7 +218,13 @@ interface ScorerResponseMetadata {
   conflictingErrorCodes: boolean;
 }
 
+interface ScorerTransportObservation {
+  transportPhase: "beforeHeaders" | "readingBody" | "bodyComplete";
+  headersReceivedMs: number | null;
+}
+
 interface ScorerResponseDiagnostics extends ScorerResponseMetadata {
+  transport?: ScorerTransportObservation;
   ordinal: number;
   phase: ScorerAttempt["phase"];
   outcome: ScorerAttempt["outcome"];
@@ -285,6 +291,7 @@ function scorerResponseDiagnostics(attempt: ScorerAttempt, ordinal: number): Sco
   }
   return {
     ordinal, phase: attempt.phase, outcome: attempt.outcome, httpStatus: attempt.httpStatus,
+    ...(attempt.transport === undefined ? {} : { transport: attempt.transport }),
     modelIdentityPresent: attempt.modelIdentityPresent, providerIdentityPresent: attempt.providerIdentityPresent,
     exactCost: cost === null ? "unavailable" : cost === "0" ? "zero" : "positive",
     accountingIssues,
@@ -413,6 +420,7 @@ export interface ScorerEvalReport {
 }
 
 interface ScorerAttempt {
+  transport?: ScorerTransportObservation;
   ordinal?: number;
   responseMetadata?: ScorerResponseMetadata;
   phase: "adjudication" | "scorer";
@@ -2030,6 +2038,10 @@ export async function startScorerProxy(
       controller.abort();
     }, upstreamTimeoutMs);
     const startedAt = performance.now();
+    const transport: ScorerTransportObservation = {
+      transportPhase: "beforeHeaders", headersReceivedMs: null,
+    };
+    let observedHttpStatus: number | null = null;
     try {
       const upstream = await fetch(`${apiBase.replace(/\/$/, "")}/chat/completions`, {
         method: "POST",
@@ -2042,7 +2054,11 @@ export async function startScorerProxy(
         body: bodyText,
         signal: controller.signal,
       });
+      observedHttpStatus = upstream.status;
+      transport.headersReceivedMs = Math.max(0, Math.round(performance.now() - startedAt));
+      transport.transportPhase = "readingBody";
       const text = await upstream.text();
+      transport.transportPhase = "bodyComplete";
       const response = safeJson(text) as {
         model?: unknown;
         provider?: unknown;
@@ -2052,6 +2068,7 @@ export async function startScorerProxy(
       const usageValid = isValidUsage(response?.usage);
       attempts.push({
         ordinal,
+        transport,
         phase: isAdjudication ? "adjudication" : "scorer",
         outcome: "completed",
         durationMs: performance.now() - startedAt,
@@ -2075,6 +2092,7 @@ export async function startScorerProxy(
     } catch {
       attempts.push({
         ordinal,
+        transport,
         phase: isAdjudication ? "adjudication" : "scorer",
         outcome: closing ? "teardownAborted" : deadlineExceeded ? "timedOut" : "failed",
         durationMs: performance.now() - startedAt,
@@ -2083,7 +2101,7 @@ export async function startScorerProxy(
         costUsd: null,
         costProviderDecimal: null,
         usageValid: false,
-        httpStatus: null,
+        httpStatus: observedHttpStatus,
         modelIdentityPresent: false,
         providerIdentityPresent: false,
         usagePresent: false,