diff --git a/Cargo.lock b/Cargo.lock index 70aa69f..a8c7939 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1358,7 +1358,7 @@ checksum = "05c8b63e8d9609db387f0324918f81d68fe27748f084ef092fb35954d0539a85" [[package]] name = "postil-cli" -version = "0.9.16" +version = "0.9.17" dependencies = [ "aho-corasick", "anyhow", diff --git a/Cargo.toml b/Cargo.toml index a046969..255e342 100644 --- a/Cargo.toml +++ b/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" diff --git a/bench/src/scorer-eval.test.ts b/bench/src/scorer-eval.test.ts index cd9c4fa..7b59dbf 100644 --- a/bench/src/scorer-eval.test.ts +++ b/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 () => { diff --git a/bench/src/scorer-eval.ts b/bench/src/scorer-eval.ts index c10114f..ce36857 100644 --- a/bench/src/scorer-eval.ts +++ b/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,