From ab4f290ada96d50492de9cd9397bcadff4f1fca0 Mon Sep 17 00:00:00 2001 From: Tanisha Aberdeen <32620895+aliasunder@users.noreply.github.com> Date: Wed, 30 Sep 2026 12:30:30 -0400 Subject: [PATCH 1/5] feat(openrouter): tag client log lines with the review phase requestReview now takes the caller's logger, and the prompted strategy passes a child bound to the phase id. Every attempt, fallback-advance, ceiling-retry, acceptance, cost-lookup, and late-settlement line the client logs carries `phase`, so concurrent parallel phases on the same model can be told apart. The client factory no longer takes a logger. Co-Authored-By: Claude Opus 5.5 --- src/__tests__/orchestrate.test.ts | 145 +++++++- src/main.ts | 13 +- src/openrouter/__tests__/client.test.ts | 439 +++++++++++++----------- src/openrouter/client.ts | 95 ++--- src/orchestrate.ts | 15 +- 5 files changed, 428 insertions(+), 279 deletions(-) diff --git a/src/__tests__/orchestrate.test.ts b/src/__tests__/orchestrate.test.ts index b404b9d..fefdbb4 100644 --- a/src/__tests__/orchestrate.test.ts +++ b/src/__tests__/orchestrate.test.ts @@ -8,6 +8,7 @@ import type { ContextReader } from "../context/workspace.js" import { ReviewRequestError, createOpenRouterClient, + type ChatRequestSubset, type ModelAttempt, type OpenRouterClient, type StructuredReviewResult, @@ -3939,14 +3940,11 @@ describe("staged phases", () => { choices: [{ message: { content: JSON.stringify(fixtureReviewResponse) } }], usage: { promptTokens: 10, completionTokens: 20 }, })) - const client = createOpenRouterClient( - { - sdk: { chat: { send }, generations: { getGeneration } }, - requestTimeoutMs: 900_000, - remainingReviewMs, - }, - createTestLogger(), - ) + const client = createOpenRouterClient({ + sdk: { chat: { send }, generations: { getGeneration } }, + requestTimeoutMs: 900_000, + remainingReviewMs, + }) const stubs = makeOrchestrateDeps({ remainingReviewMs, generateFindings: createPromptedGenerateFindings( @@ -4033,14 +4031,11 @@ describe("staged phases", () => { .mockResolvedValueOnce(response) .mockResolvedValueOnce(response) .mockImplementation(() => lateResponse.promise) - const client = createOpenRouterClient( - { - sdk: { chat: { send } }, - requestTimeoutMs: 900_000, - remainingReviewMs, - }, - createTestLogger(), - ) + const client = createOpenRouterClient({ + sdk: { chat: { send } }, + requestTimeoutMs: 900_000, + remainingReviewMs, + }) const stubs = makeOrchestrateDeps({ config: { phases: "parallel" }, remainingReviewMs, @@ -4119,6 +4114,90 @@ describe("staged phases", () => { } }) + it("tags each parallel phase's client log lines with that phase", async () => { + const response = { + id: "completed", + model: "test/model", + choices: [{ message: { content: JSON.stringify(fixtureReviewResponse) } }], + usage: { promptTokens: 10, completionTokens: 20, cost: 0.01 }, + } + + // correctness-security is dispatched first, so a logger shared across the + // concurrent calls would already carry a later phase when its failure logs. + // The failure is keyed on that phase's prompt text, not on call order + const correctnessSecurityPassScope = "this pass covers correctness & security" + const failedPrompts = new Set() + const send = vi.fn(async ({ chatRequest }: { chatRequest: ChatRequestSubset }) => { + const systemPrompt = first(chatRequest.messages).content + const isFirstCorrectnessSecurityRequest = + systemPrompt.includes(correctnessSecurityPassScope) && !failedPrompts.has(systemPrompt) + + if (isFirstCorrectnessSecurityRequest) { + failedPrompts.add(systemPrompt) + throw Object.assign(new Error("HTTP 500"), { statusCode: 500 }) + } + return response + }) + const client = createOpenRouterClient({ + sdk: { chat: { send } }, + requestTimeoutMs: 900_000, + remainingReviewMs: () => Infinity, + retryDelayMs: 0, + }) + const generateLogger = createTestLogger() + const stubs = makeOrchestrateDeps({ + config: { phases: "parallel" }, + generateFindings: createPromptedGenerateFindings( + { openrouterClient: client, model: "test/model", fallbackModel: null }, + generateLogger, + ), + }) + + const result = await orchestrate(stubs.deps, createTestLogger()) + + // Completion order depends on scheduling; which phase each line names is + // what this test checks, so the accepted lines are compared by phase + const acceptedByPhase = logsWithMessage(generateLogger, "review response accepted").toSorted( + (left, right) => String(left.data.phase).localeCompare(String(right.data.phase)), + ) + const acceptedEntry = (phase: string, attemptCount: number) => ({ + level: "info", + message: "review response accepted", + data: { + phase, + model: "test/model", + routedModel: "test/model", + generationId: "completed", + attemptCount, + }, + }) + + expect(result.phases).toEqual([ + { phase: "correctness-security", status: "completed" }, + { phase: "conventions-tests", status: "completed" }, + { phase: "subtle-bugs", status: "completed" }, + ]) + expect(send).toHaveBeenCalledTimes(4) + expect(logsWithMessage(generateLogger, "review attempt failed")).toEqual([ + { + level: "warn", + message: "review attempt failed", + data: { + phase: "correctness-security", + model: "test/model", + attemptNumber: 1, + outcome: "api_error", + errorSummary: "HTTP 500: HTTP 500", + }, + }, + ]) + expect(acceptedByPhase).toEqual([ + acceptedEntry("conventions-tests", 1), + acceptedEntry("correctness-security", 2), + acceptedEntry("subtle-bugs", 1), + ]) + }) + it("posts the surviving phases' findings when one phase fails, naming the gap on the status comment and the check run", async () => { const timeoutAttempt: ModelAttempt = { model: "test/model", @@ -4550,6 +4629,40 @@ describe("createPromptedGenerateFindings", () => { ).toEqual([{ model: "test/primary", fallbackModel: "test/fallback" }]) }) + it("passes requestReview a logger tagged with the review phase", async () => { + const stubClient: OpenRouterClient = { + requestReview: async (_params, logger) => { + logger.info("stub client line") + return { review: { analysis: "", findings: [] }, modelUsed: "m", attempts: [] } + }, + } + const logger = createTestLogger() + const generate = createPromptedGenerateFindings( + { openrouterClient: stubClient, model: "m", fallbackModel: null }, + logger, + ) + const reviewContext: Omit = { + prContext: fixturePrContext, + conventions: null, + conventionsFile: "AGENTS.md", + conventionsBudgetTokens: 8_000, + changedFiles: [], + relatedFiles: [], + relatedDocs: [], + annotatedDiff: annotateDiff(parseDiff(sampleDiff)), + priorFindings: [], + priorBotComments: [], + } + + await generate({ ...reviewContext, phase: COMBINED_PHASE }) + await generate({ ...reviewContext, phase: SUBTLE_BUGS_PHASE }) + + expect(logsWithMessage(logger, "stub client line")).toEqual([ + { level: "info", message: "stub client line", data: { phase: "combined" } }, + { level: "info", message: "stub client line", data: { phase: "subtle-bugs" } }, + ]) + }) + it("includes annotated diff in the user prompt", async () => { const requestReviewCalls: RequestReviewParams[] = [] const stubClient: OpenRouterClient = { diff --git a/src/main.ts b/src/main.ts index 410cdb8..6321f1b 100644 --- a/src/main.ts +++ b/src/main.ts @@ -127,14 +127,11 @@ try { ), generateFindings: createPromptedGenerateFindings( { - openrouterClient: createOpenRouterClient( - { - sdk: new OpenRouter({ apiKey: config.openrouterApiKey }), - requestTimeoutMs: config.requestTimeoutSeconds * 1000, - remainingReviewMs, - }, - logger, - ), + openrouterClient: createOpenRouterClient({ + sdk: new OpenRouter({ apiKey: config.openrouterApiKey }), + requestTimeoutMs: config.requestTimeoutSeconds * 1000, + remainingReviewMs, + }), model: config.model, fallbackModel: config.fallbackModel === "" ? null : config.fallbackModel, }, diff --git a/src/openrouter/__tests__/client.test.ts b/src/openrouter/__tests__/client.test.ts index 2825a5e..7a5524c 100644 --- a/src/openrouter/__tests__/client.test.ts +++ b/src/openrouter/__tests__/client.test.ts @@ -105,15 +105,12 @@ const makeSdkStub = ({ const makeClient = (stub: { sdk: OpenRouterLike }) => { const logger = createTestLogger() - const client = createOpenRouterClient( - { - sdk: stub.sdk, - remainingReviewMs: () => Infinity, - requestTimeoutMs: 45_000, - retryDelayMs: 0, - }, - logger, - ) + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs: 0, + }) return { client, logger } } @@ -166,11 +163,13 @@ const requestParams = { describe("requestReview", () => { it("does not start an attempt when the review deadline has expired", async () => { const stub = makeSdkStub({ sendResponses: [] }) - const client = createOpenRouterClient( - { sdk: stub.sdk, requestTimeoutMs: 45_000, remainingReviewMs: () => 0 }, - createTestLogger(), - ) - const error = await captureRejection(client.requestReview(requestParams)) + const logger = createTestLogger() + const client = createOpenRouterClient({ + sdk: stub.sdk, + requestTimeoutMs: 45_000, + remainingReviewMs: () => 0, + }) + const error = await captureRejection(client.requestReview(requestParams, logger)) expect(error).toBeInstanceOf(ReviewRequestError) if (!(error instanceof ReviewRequestError)) throw error expect({ @@ -201,15 +200,13 @@ describe("requestReview", () => { ], }) const deadline = performance.now() + 100 - const client = createOpenRouterClient( - { - sdk: stub.sdk, - requestTimeoutMs: 45_000, - remainingReviewMs: () => deadline - performance.now(), - }, - createTestLogger(), - ) - const rejection = captureRejection(client.requestReview(requestParams)) + const logger = createTestLogger() + const client = createOpenRouterClient({ + sdk: stub.sdk, + requestTimeoutMs: 45_000, + remainingReviewMs: () => deadline - performance.now(), + }) + const rejection = captureRejection(client.requestReview(requestParams, logger)) await vi.advanceTimersByTimeAsync(100) const error = await rejection expect(error).toBeInstanceOf(ReviewRequestError) @@ -286,15 +283,13 @@ describe("requestReview", () => { ], }) const deadline = performance.now() + 100 - const client = createOpenRouterClient( - { - sdk: stub.sdk, - requestTimeoutMs: 45_000, - remainingReviewMs: () => deadline - performance.now(), - }, - createTestLogger(), - ) - const rejection = captureRejection(client.requestReview(requestParams)) + const logger = createTestLogger() + const client = createOpenRouterClient({ + sdk: stub.sdk, + requestTimeoutMs: 45_000, + remainingReviewMs: () => deadline - performance.now(), + }) + const rejection = captureRejection(client.requestReview(requestParams, logger)) await vi.advanceTimersByTimeAsync(100) const error = await rejection expect(error).toBeInstanceOf(ReviewRequestError) @@ -338,11 +333,13 @@ describe("requestReview", () => { }, ], }) - const client = createOpenRouterClient( - { sdk: stub.sdk, requestTimeoutMs: 45_000, remainingReviewMs }, - createTestLogger(), - ) - expect(await client.requestReview(requestParams)).toEqual({ + const logger = createTestLogger() + const client = createOpenRouterClient({ + sdk: stub.sdk, + requestTimeoutMs: 45_000, + remainingReviewMs, + }) + expect(await client.requestReview(requestParams, logger)).toEqual({ review: acceptedReview, modelUsed: requestParams.model, attempts: [ @@ -371,15 +368,13 @@ describe("requestReview", () => { generationResponses: [{ pending: () => late.promise }], }) const deadline = performance.now() + 100 - const client = createOpenRouterClient( - { - sdk: stub.sdk, - requestTimeoutMs: 45_000, - remainingReviewMs: () => deadline - performance.now(), - }, - createTestLogger(), - ) - const request = client.requestReview(requestParams) + const logger = createTestLogger() + const client = createOpenRouterClient({ + sdk: stub.sdk, + requestTimeoutMs: 45_000, + remainingReviewMs: () => deadline - performance.now(), + }) + const request = client.requestReview(requestParams, logger) await vi.advanceTimersByTimeAsync(100) const result = await request const expected = { @@ -417,9 +412,9 @@ describe("requestReview", () => { it("sends the strict json_schema response format with the review schema and per-attempt timeout", async () => { const stub = makeSdkStub({ sendResponses: [{ value: acceptedChatResult }] }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) expect(stub.sendCalls).toEqual([ { @@ -450,9 +445,9 @@ describe("requestReview", () => { it("returns the parsed review and a single accepted attempt on first success", async () => { const stub = makeSdkStub({ sendResponses: [{ value: acceptedChatResult }] }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(result).toEqual({ review: acceptedReview, @@ -474,9 +469,9 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ value: invalidJsonChatResult }, { value: acceptedChatResult }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(stub.sendCalls.map((sendCall) => sendCall.chatRequest.model)).toEqual([ "openai/gpt-5-mini", @@ -512,9 +507,9 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ value: emptyContentResult }, { value: acceptedChatResult }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(result.attempts).toEqual([ { @@ -544,9 +539,9 @@ describe("requestReview", () => { { value: acceptedChatResult }, ], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(stub.sendCalls.map((sendCall) => sendCall.chatRequest.model)).toEqual([ "openai/gpt-5-mini", @@ -581,9 +576,9 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ error: makeStatusError(429) }, { value: acceptedChatResult }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(stub.sendCalls.map((sendCall) => sendCall.chatRequest.model)).toEqual([ "openai/gpt-5-mini", @@ -603,9 +598,9 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ error: new Error("socket hang up") }, { value: acceptedChatResult }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(stub.sendCalls.map((sendCall) => sendCall.chatRequest.model)).toEqual([ "openai/gpt-5-mini", @@ -629,7 +624,7 @@ describe("requestReview", () => { }) const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(stub.sendCalls.map((sendCall) => sendCall.chatRequest.model)).toEqual([ "openai/gpt-5-mini", @@ -666,9 +661,9 @@ describe("requestReview", () => { sendResponses: [{ value: acceptedChatResult }], generationResponses: [{ value: { data: { totalCost: 0.01 } } }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) const signal = stub.sendCalls[0]?.options?.signal expect(signal).toBeInstanceOf(AbortSignal) @@ -696,22 +691,22 @@ describe("requestReview", () => { sendResponses: [{ pending: rejectOnAbort }, { pending: rejectOnAbort }], }) const logger = createTestLogger() - const client = createOpenRouterClient( + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs: 0, + }) + + // Attach the rejection handler BEFORE advancing timers so the + // second attempt's async abort rejection is caught immediately. + const reviewPromise = client.requestReview( { - sdk: stub.sdk, - remainingReviewMs: () => Infinity, - requestTimeoutMs: 45_000, - retryDelayMs: 0, + ...requestParams, + fallbackModel: null, }, logger, ) - - // Attach the rejection handler BEFORE advancing timers so the - // second attempt's async abort rejection is caught immediately. - const reviewPromise = client.requestReview({ - ...requestParams, - fallbackModel: null, - }) void reviewPromise.catch(() => undefined) // Two attempts × 45s each — advance past both deadlines @@ -754,17 +749,14 @@ describe("requestReview", () => { ], }) const logger = createTestLogger() - const client = createOpenRouterClient( - { - sdk: stub.sdk, - remainingReviewMs: () => Infinity, - requestTimeoutMs: 45_000, - retryDelayMs: 0, - }, - logger, - ) + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs: 0, + }) - const reviewPromise = client.requestReview(requestParams) + const reviewPromise = client.requestReview(requestParams, logger) await vi.advanceTimersByTimeAsync(45_000) const result = await reviewPromise @@ -842,17 +834,14 @@ describe("requestReview", () => { sendResponses: [{ pending: resolveLate }, { value: acceptedChatResult }], }) const logger = createTestLogger() - const client = createOpenRouterClient( - { - sdk: stub.sdk, - remainingReviewMs: () => Infinity, - requestTimeoutMs: 45_000, - retryDelayMs: 0, - }, - logger, - ) + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs: 0, + }) - const reviewPromise = client.requestReview(requestParams) + const reviewPromise = client.requestReview(requestParams, logger) await vi.advanceTimersByTimeAsync(45_000) const result = await reviewPromise expect(result.attempts.map((attempt) => [attempt.model, attempt.outcome])).toEqual([ @@ -880,6 +869,56 @@ describe("requestReview", () => { } }) + it("tags a late settlement with the caller's logger context after the request has rejected", async () => { + vi.useFakeTimers() + try { + const resolveLate = (): Promise => { + return new Promise((resolve) => { + setTimeout(() => resolve(acceptedChatResult), 120_000) + }) + } + const stub = makeSdkStub({ + sendResponses: [{ pending: resolveLate }, { error: makeStatusError(400) }], + }) + const logger = createTestLogger() + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs: 0, + }) + + const rejection = captureRejection( + client.requestReview( + { ...requestParams, fallbackModel: null }, + logger.child({ phase: "subtle-bugs" }), + ), + ) + await vi.advanceTimersByTimeAsync(45_000) + expect(await rejection).toBeInstanceOf(ReviewRequestError) + expect(logsWithMessage(logger, "deadline-elapsed request settled")).toEqual([]) + + await vi.advanceTimersByTimeAsync(75_000) + + expect(logsWithMessage(logger, "deadline-elapsed request settled")).toEqual([ + { + level: "warn", + message: "deadline-elapsed request settled", + data: { + phase: "subtle-bugs", + operation: "chat request", + model: "openai/gpt-5-mini", + elapsedMs: 120_000, + timeoutMs: 45_000, + settledWith: "response", + }, + }, + ]) + } finally { + vi.useRealTimers() + } + }) + it("logs a late non-abort rejection without raising an unhandled rejection", async () => { vi.useFakeTimers() try { @@ -892,17 +931,14 @@ describe("requestReview", () => { sendResponses: [{ pending: rejectLate }, { value: acceptedChatResult }], }) const logger = createTestLogger() - const client = createOpenRouterClient( - { - sdk: stub.sdk, - remainingReviewMs: () => Infinity, - requestTimeoutMs: 45_000, - retryDelayMs: 0, - }, - logger, - ) + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs: 0, + }) - const reviewPromise = client.requestReview(requestParams) + const reviewPromise = client.requestReview(requestParams, logger) await vi.advanceTimersByTimeAsync(45_000) const result = await reviewPromise expect(result.attempts.map((attempt) => [attempt.model, attempt.outcome])).toEqual([ @@ -940,20 +976,20 @@ describe("requestReview", () => { ], }) const logger = createTestLogger() - const client = createOpenRouterClient( + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs: 0, + }) + + const reviewPromise = client.requestReview( { - sdk: stub.sdk, - remainingReviewMs: () => Infinity, - requestTimeoutMs: 45_000, - retryDelayMs: 0, + ...requestParams, + fallbackModel: null, }, logger, ) - - const reviewPromise = client.requestReview({ - ...requestParams, - fallbackModel: null, - }) await vi.advanceTimersByTimeAsync(45_000) const result = await reviewPromise @@ -995,17 +1031,14 @@ describe("requestReview", () => { ], }) const logger = createTestLogger() - const client = createOpenRouterClient( - { - sdk: stub.sdk, - remainingReviewMs: () => Infinity, - requestTimeoutMs: 45_000, - retryDelayMs: 0, - }, - logger, - ) + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs: 0, + }) - const reviewPromise = client.requestReview(requestParams) + const reviewPromise = client.requestReview(requestParams, logger) void reviewPromise.catch(() => undefined) // One primary deadline, then two fallback deadlines (last-rung retry) await vi.advanceTimersByTimeAsync(135_000) @@ -1034,19 +1067,16 @@ describe("requestReview", () => { ], }) const logger = createTestLogger() - const client = createOpenRouterClient( - { - sdk: stub.sdk, - remainingReviewMs: () => Infinity, - requestTimeoutMs: 45_000, - retryDelayMs, - }, - logger, - ) + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs, + }) const setTimeoutSpy = vi.spyOn(globalThis, "setTimeout") try { - const reviewPromise = client.requestReview(requestParams) + const reviewPromise = client.requestReview(requestParams, logger) await vi.advanceTimersByTimeAsync(45_000) await reviewPromise @@ -1069,16 +1099,13 @@ describe("requestReview", () => { }) const logger = createTestLogger() const deadline = performance.now() + 100 - const client = createOpenRouterClient( - { - sdk: stub.sdk, - requestTimeoutMs: 45_000, - remainingReviewMs: () => deadline - performance.now(), - }, - logger, - ) + const client = createOpenRouterClient({ + sdk: stub.sdk, + requestTimeoutMs: 45_000, + remainingReviewMs: () => deadline - performance.now(), + }) - const reviewPromise = client.requestReview(requestParams) + const reviewPromise = client.requestReview(requestParams, logger) await vi.advanceTimersByTimeAsync(100) await reviewPromise @@ -1111,17 +1138,14 @@ describe("requestReview", () => { generationResponses: [{ pending: () => new Promise(() => undefined) }], }) const logger = createTestLogger() - const client = createOpenRouterClient( - { - sdk: stub.sdk, - remainingReviewMs: () => Infinity, - requestTimeoutMs: 45_000, - retryDelayMs: 0, - }, - logger, - ) + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs: 0, + }) - const reviewPromise = client.requestReview(requestParams) + const reviewPromise = client.requestReview(requestParams, logger) await vi.advanceTimersByTimeAsync(45_000) const result = await reviewPromise @@ -1154,11 +1178,11 @@ describe("requestReview", () => { sendResponses: [{ value: acceptedChatResult }], }) delete stub.sdk.generations - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) const clearTimeoutSpy = vi.spyOn(globalThis, "clearTimeout") try { - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) expect(clearTimeoutSpy).toHaveBeenCalled() } finally { clearTimeoutSpy.mockRestore() @@ -1171,21 +1195,18 @@ describe("requestReview", () => { sendResponses: [{ error: makeStatusError(429) }, { error: makeStatusError(429) }], }) const logger = createTestLogger() - const client = createOpenRouterClient( - { - sdk: stub.sdk, - remainingReviewMs: () => Infinity, - requestTimeoutMs: 45_000, - retryDelayMs, - }, - logger, - ) + const client = createOpenRouterClient({ + sdk: stub.sdk, + remainingReviewMs: () => Infinity, + requestTimeoutMs: 45_000, + retryDelayMs, + }) const setTimeoutSpy = vi.spyOn(globalThis, "setTimeout") try { - await expect(client.requestReview({ ...requestParams, fallbackModel: null })).rejects.toThrow( - "review request failed", - ) + await expect( + client.requestReview({ ...requestParams, fallbackModel: null }, logger), + ).rejects.toThrow("review request failed") // retryDelayMs sleeps happen between retryable failures; the guard // `attemptNumber <= MAX_ATTEMPTS_PER_MODEL` prevents an extra sleep @@ -1209,9 +1230,9 @@ describe("requestReview", () => { { value: acceptedChatResult }, ], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(result.attempts[0]?.errorSummary).toBe(`HTTP 429: ${"x".repeat(200)}…`) }) @@ -1220,9 +1241,9 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ error: makeStatusError(404) }, { value: acceptedChatResult }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(stub.sendCalls.map((sendCall) => sendCall.chatRequest.model)).toEqual([ "openai/gpt-5-mini", @@ -1257,7 +1278,7 @@ describe("requestReview", () => { }) const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) // 262,144 window − 135,762 input − 8,192 margin expect(sentCeilings(stub)).toEqual([ @@ -1304,9 +1325,9 @@ describe("requestReview", () => { { value: acceptedChatResult }, ], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) expect(sentCeilings(stub)).toEqual([ { model: "openai/gpt-5-mini", maxCompletionTokens: 128_000 }, @@ -1322,9 +1343,9 @@ describe("requestReview", () => { { value: acceptedChatResult }, ], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) expect(sentCeilings(stub)).toEqual([ { model: "openai/gpt-5-mini", maxCompletionTokens: 128_000 }, @@ -1340,9 +1361,9 @@ describe("requestReview", () => { { value: acceptedChatResult }, ], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) expect(sentCeilings(stub)).toEqual([ { model: "openai/gpt-5-mini", maxCompletionTokens: 128_000 }, @@ -1358,9 +1379,9 @@ describe("requestReview", () => { { value: acceptedChatResult }, ], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) expect(sentCeilings(stub)).toEqual([ { model: "openai/gpt-5-mini", maxCompletionTokens: 128_000 }, @@ -1379,7 +1400,7 @@ describe("requestReview", () => { }) const { client, logger } = makeClient(stub) - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) expect(sentCeilings(stub)).toEqual([ { model: "openai/gpt-5-mini", maxCompletionTokens: 128_000 }, @@ -1398,7 +1419,7 @@ describe("requestReview", () => { }) const { client, logger } = makeClient(stub) - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) expect(sentCeilings(stub)).toEqual([ { model: "openai/gpt-5-mini", maxCompletionTokens: 128_000 }, @@ -1416,9 +1437,9 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ error: overflowWordedGatewayError }, { value: acceptedChatResult }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) expect(sentCeilings(stub)).toEqual([ { model: "openai/gpt-5-mini", maxCompletionTokens: 128_000 }, @@ -1430,9 +1451,9 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ error: makeStatusError(400) }, { value: acceptedChatResult }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await client.requestReview(requestParams) + await client.requestReview(requestParams, logger) expect(sentCeilings(stub)).toEqual([ { model: "openai/gpt-5-mini", maxCompletionTokens: 128_000 }, @@ -1446,9 +1467,9 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ error: makeStatusError(statusCode) }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await expect(client.requestReview(requestParams)).rejects.toThrow( + await expect(client.requestReview(requestParams, logger)).rejects.toThrow( `OpenRouter auth/credit error — aborting without fallback: openai/gpt-5-mini: api_error (HTTP ${statusCode}: HTTP ${statusCode})`, ) expect(stub.sendCalls).toHaveLength(1) @@ -1459,9 +1480,11 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ error: makeStatusError(500) }, { error: makeStatusError(503) }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await expect(client.requestReview({ ...requestParams, fallbackModel: null })).rejects.toThrow( + await expect( + client.requestReview({ ...requestParams, fallbackModel: null }, logger), + ).rejects.toThrow( "review request failed after 2 attempt(s): openai/gpt-5-mini: api_error (HTTP 500: HTTP 500); openai/gpt-5-mini: api_error (HTTP 503: HTTP 503)", ) expect(stub.sendCalls).toHaveLength(2) @@ -1471,10 +1494,10 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ error: makeStatusError(500) }, { error: makeStatusError(503) }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) const failure = await captureRejection( - client.requestReview({ ...requestParams, fallbackModel: null }), + client.requestReview({ ...requestParams, fallbackModel: null }, logger), ) if (!(failure instanceof ReviewRequestError)) { @@ -1505,9 +1528,9 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ error: makeStatusError(402) }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const failure = await captureRejection(client.requestReview(requestParams)) + const failure = await captureRejection(client.requestReview(requestParams, logger)) if (!(failure instanceof ReviewRequestError)) { throw new Error("expected a ReviewRequestError") @@ -1534,9 +1557,9 @@ describe("requestReview", () => { { value: invalidJsonChatResult }, ], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - await expect(client.requestReview(requestParams)).rejects.toThrow( + await expect(client.requestReview(requestParams, logger)).rejects.toThrow( "review request failed after 4 attempt(s)", ) expect(stub.sendCalls).toHaveLength(4) @@ -1546,9 +1569,9 @@ describe("requestReview", () => { const stub = makeSdkStub({ sendResponses: [{ value: { unexpected: true } }, { value: acceptedChatResult }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(result.attempts[0]).toEqual({ model: "openai/gpt-5-mini", @@ -1565,9 +1588,9 @@ describe("requestReview", () => { sendResponses: [{ value: makeNoCostChatResult() }], generationResponses: [{ value: { data: { totalCost: 0.0399 } } }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(stub.generationCalls).toEqual([ { @@ -1588,7 +1611,7 @@ describe("requestReview", () => { }) const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(result.attempts[0]?.costUsd).toBeNull() expect(logsWithMessage(logger, "generation cost lookup failed")).toEqual([ @@ -1611,7 +1634,7 @@ describe("requestReview", () => { } const { client, logger } = makeClient({ sdk: sdkWithThrowingLookup }) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(result.attempts[0]?.costUsd).toBeNull() expect(logsWithMessage(logger, "generation cost lookup failed")).toEqual([ @@ -1630,7 +1653,7 @@ describe("requestReview", () => { }) const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(result.attempts[0]?.costUsd).toBeNull() expect(logsWithMessage(logger, "unexpected generation response shape")).toEqual([ @@ -1652,9 +1675,9 @@ describe("requestReview", () => { sendResponses: [{ value: noUsageResult }], generationResponses: [{ value: { data: { totalCost: 0.0399 } } }], }) - const { client } = makeClient(stub) + const { client, logger } = makeClient(stub) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) // costUsd from the lookup proves the missing usage block routed the // accepted attempt through the generation-cost fallback @@ -1674,9 +1697,9 @@ describe("requestReview", () => { const sdkWithoutGenerations: OpenRouterLike = { chat: { send: async () => makeNoCostChatResult() }, } - const { client } = makeClient({ sdk: sdkWithoutGenerations }) + const { client, logger } = makeClient({ sdk: sdkWithoutGenerations }) - const result = await client.requestReview(requestParams) + const result = await client.requestReview(requestParams, logger) expect(result.attempts[0]?.costUsd).toBeNull() }) diff --git a/src/openrouter/client.ts b/src/openrouter/client.ts index aec02ca..fcee01a 100644 --- a/src/openrouter/client.ts +++ b/src/openrouter/client.ts @@ -72,12 +72,18 @@ export type OpenRouterLike = { } export type OpenRouterClient = { - requestReview: (params: { - systemPrompt: string - userPrompt: string - model: string - fallbackModel: string | null - }) => Promise + /** Every line the request logs goes through `logger`, including a late + * settlement logged after the call has returned, so props the caller binds + * to it tag all of them. */ + requestReview: ( + params: { + systemPrompt: string + userPrompt: string + model: string + fallbackModel: string | null + }, + logger: Logger, + ) => Promise } const chatResultSchema = z.object({ @@ -382,30 +388,30 @@ const summarizeAttempts = (attempts: ModelAttempt[]): string => { return attempts.map(describeAttempt).join("; ") } -export const createOpenRouterClient = ( - { - sdk, - requestTimeoutMs, - remainingReviewMs, - retryDelayMs = RETRY_DELAY_MS, - }: { - sdk: OpenRouterLike - /** Per-attempt deadline. When it elapses the attempt records outcome - * `timeout` and the ladder moves on — to the next model when one - * exists, otherwise a same-model retry while attempts remain — whether - * or not the provider connection closes. The HTTP call is aborted - * best-effort. */ - requestTimeoutMs: number - /** Milliseconds left in the whole review's time budget; 0 or less once - * it has run out. Caps every attempt, cost lookup, and retry delay. */ - remainingReviewMs: () => number - retryDelayMs?: number - }, - logger: Logger, -): OpenRouterClient => { +export const createOpenRouterClient = ({ + sdk, + requestTimeoutMs, + remainingReviewMs, + retryDelayMs = RETRY_DELAY_MS, +}: { + sdk: OpenRouterLike + /** Per-attempt deadline. When it elapses the attempt records outcome + * `timeout` and the ladder moves on — to the next model when one + * exists, otherwise a same-model retry while attempts remain — whether + * or not the provider connection closes. The HTTP call is aborted + * best-effort. */ + requestTimeoutMs: number + /** Milliseconds left in the whole review's time budget; 0 or less once + * it has run out. Caps every attempt, cost lookup, and retry delay. */ + remainingReviewMs: () => number + retryDelayMs?: number +}): OpenRouterClient => { const requestTimeoutSummary = `no response within ${Math.round(requestTimeoutMs / 1000)}s` - const attemptOnce = async (chatRequest: ChatRequestSubset): Promise => { + const attemptOnce = async ( + chatRequest: ChatRequestSubset, + logger: Logger, + ): Promise => { const { model } = chatRequest const remainingMs = remainingReviewMs() @@ -547,7 +553,10 @@ export const createOpenRouterClient = ( /** A cost lookup failure must never fail a completed review, so every * failure degrades to a null cost. */ - const lookupGenerationCost = async (generationId: string): Promise => { + const lookupGenerationCost = async ( + generationId: string, + logger: Logger, + ): Promise => { const generations = sdk.generations const remainingMs = remainingReviewMs() @@ -595,17 +604,20 @@ export const createOpenRouterClient = ( return parsed.data.data.totalCost } - const requestReview = async ({ - systemPrompt, - userPrompt, - model, - fallbackModel, - }: { - systemPrompt: string - userPrompt: string - model: string - fallbackModel: string | null - }): Promise => { + const requestReview = async ( + { + systemPrompt, + userPrompt, + model, + fallbackModel, + }: { + systemPrompt: string + userPrompt: string + model: string + fallbackModel: string | null + }, + logger: Logger, + ): Promise => { const modelLadder = fallbackModel === null ? [model] : [model, fallbackModel] const attempts: ModelAttempt[] = [] const ensureReviewTimeRemaining = (): void => { @@ -630,13 +642,14 @@ export const createOpenRouterClient = ( ensureReviewTimeRemaining() const attemptResult = await attemptOnce( buildChatRequest({ systemPrompt, userPrompt, model: ladderModel, maxCompletionTokens }), + logger, ) if (attemptResult.kind === "accepted") { // The generation lookup runs only when the response's usage omits the cost const costUsd = attemptResult.attempt.costUsd ?? - (await lookupGenerationCost(attemptResult.generationId)) + (await lookupGenerationCost(attemptResult.generationId, logger)) attempts.push({ ...attemptResult.attempt, costUsd }) logger.info("review response accepted", { model: ladderModel, diff --git a/src/orchestrate.ts b/src/orchestrate.ts index 832d4f1..07122ae 100644 --- a/src/orchestrate.ts +++ b/src/orchestrate.ts @@ -1321,11 +1321,14 @@ export const createPromptedGenerateFindings = ( fallbackModel, }) - return openrouterClient.requestReview({ - systemPrompt, - userPrompt, - model, - fallbackModel, - }) + // Parallel phases call the same model at once, so the phase is what tells + // their client log lines apart. The child comes from `logger`, not `log`, + // because those lines come from the client module, not this one + const phaseLogger = logger.child({ phase: reviewContext.phase.id }) + + return openrouterClient.requestReview( + { systemPrompt, userPrompt, model, fallbackModel }, + phaseLogger, + ) } } From 9a98c2a0e8d1129608e2dc47c926fe450c635036 Mon Sep 17 00:00:00 2001 From: Tanisha Aberdeen <32620895+aliasunder@users.noreply.github.com> Date: Wed, 30 Sep 2026 12:39:57 -0400 Subject: [PATCH 2/5] style: state the per-call logger contract where each reader meets it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - withDeadline takes its operation context from a child logger instead of a parallel logContext record; the log output is unchanged. - requestReview takes its type from OpenRouterClient instead of repeating the params shape. - createPromptedGenerateFindings builds the phase logger once and derives its own module-tagged line from it; the comment now gives the real reason client lines skip the module tag. - Doc comments explain the late-settlement line, the logger-free factory, attemptOnce's logging, and drop an undefined roadmap reference. Ship-Check: code-quality · claude-opus-5-5 Co-Authored-By: Claude Opus 5.5 --- src/main.ts | 2 ++ src/openrouter/client.ts | 42 +++++++++++++++------------------------- src/orchestrate.ts | 22 ++++++++++----------- 3 files changed, 28 insertions(+), 38 deletions(-) diff --git a/src/main.ts b/src/main.ts index 6321f1b..72b5b6e 100644 --- a/src/main.ts +++ b/src/main.ts @@ -127,6 +127,8 @@ try { ), generateFindings: createPromptedGenerateFindings( { + // createOpenRouterClient takes no logger because each review phase + // passes its own phase-tagged logger to requestReview openrouterClient: createOpenRouterClient({ sdk: new OpenRouter({ apiKey: config.openrouterApiKey }), requestTimeoutMs: config.requestTimeoutSeconds * 1000, diff --git a/src/openrouter/client.ts b/src/openrouter/client.ts index fcee01a..612fe8d 100644 --- a/src/openrouter/client.ts +++ b/src/openrouter/client.ts @@ -72,9 +72,9 @@ export type OpenRouterLike = { } export type OpenRouterClient = { - /** Every line the request logs goes through `logger`, including a late - * settlement logged after the call has returned, so props the caller binds - * to it tag all of them. */ + /** Every line the request logs goes through `logger`, so props the caller + * binds to it tag all of them. A timed-out HTTP call can still settle + * after requestReview returns, and the line that logs it uses `logger` too. */ requestReview: ( params: { systemPrompt: string @@ -236,16 +236,15 @@ const describeLateSettlement = (late: SettledResult): LateSettlement => { /** Bounds an SDK call with an authoritative deadline: * - Resolve the deadline before aborting so it wins deterministically. * - Return at the deadline even when the SDK ignores the abort. - * - Observe the abandoned call and log how it eventually settles. */ + * - Observe the abandoned call and log how it eventually settles. + * - Log only timing; the caller binds the operation's identifying props to `logger`. */ const withDeadline = async ( { start, timeoutMs, - logContext, }: { start: (signal: AbortSignal) => Promise timeoutMs: number - logContext: Record }, logger: Logger, ): Promise> => { @@ -272,11 +271,10 @@ const withDeadline = async ( if (bounded.status !== "timed_out") return bounded - logger.warn("request deadline elapsed", { ...logContext, timeoutMs }) + logger.warn("request deadline elapsed", { timeoutMs }) const logLateSettlement = (late: SettledResult): void => { logger.warn("deadline-elapsed request settled", { - ...logContext, elapsedMs: DateTime.now().diff(startedAt).toMillis(), timeoutMs, settledWith: describeLateSettlement(late), @@ -388,6 +386,8 @@ const summarizeAttempts = (attempts: ModelAttempt[]): string => { return attempts.map(describeAttempt).join("; ") } +/** The client holds no logger. Each requestReview call passes its own, so + * concurrent callers can tag their requests' lines with their own props. */ export const createOpenRouterClient = ({ sdk, requestTimeoutMs, @@ -408,6 +408,8 @@ export const createOpenRouterClient = ({ }): OpenRouterClient => { const requestTimeoutSummary = `no response within ${Math.round(requestTimeoutMs / 1000)}s` + /** Sends one chat request under the per-attempt deadline. Its only log lines + * are withDeadline's; requestReview logs each attempt's outcome. */ const attemptOnce = async ( chatRequest: ChatRequestSubset, logger: Logger, @@ -425,9 +427,8 @@ export const createOpenRouterClient = ({ return sdk.chat.send({ chatRequest }, { retries: { strategy: "none" }, signal }) }, timeoutMs: Math.min(requestTimeoutMs, remainingMs), - logContext: { operation: "chat request", model }, }, - logger, + logger.child({ operation: "chat request", model }), ) // Retryable even when the review deadline caused the timeout, because @@ -575,9 +576,8 @@ export const createOpenRouterClient = ({ ) }, timeoutMs: Math.min(requestTimeoutMs, remainingMs), - logContext: { operation: "generation cost lookup", generationId }, }, - logger, + logger.child({ operation: "generation cost lookup", generationId }), ) if (lookup.status === "timed_out") { @@ -604,20 +604,10 @@ export const createOpenRouterClient = ({ return parsed.data.data.totalCost } - const requestReview = async ( - { - systemPrompt, - userPrompt, - model, - fallbackModel, - }: { - systemPrompt: string - userPrompt: string - model: string - fallbackModel: string | null - }, - logger: Logger, - ): Promise => { + const requestReview: OpenRouterClient["requestReview"] = async ( + { systemPrompt, userPrompt, model, fallbackModel }, + logger, + ) => { const modelLadder = fallbackModel === null ? [model] : [model, fallbackModel] const attempts: ModelAttempt[] = [] const ensureReviewTimeRemaining = (): void => { diff --git a/src/orchestrate.ts b/src/orchestrate.ts index 07122ae..609c987 100644 --- a/src/orchestrate.ts +++ b/src/orchestrate.ts @@ -1290,9 +1290,9 @@ export const orchestrate = async ( } } -/** Prompted strategy — builds the prompt for one review phase and sends it - * to OpenRouter; the stage dispatcher calls it once per phase. V1.5/V2 - * tool-loop strategies swap in behind the same GenerateFindings interface. */ +/** Builds one review phase's prompt and sends it to OpenRouter in a single + * request with no tool calls. The stage dispatcher calls the returned + * function once per phase. */ export const createPromptedGenerateFindings = ( { openrouterClient, @@ -1305,8 +1305,6 @@ export const createPromptedGenerateFindings = ( }, logger: Logger, ): GenerateFindings => { - const log = logger.child({ module: "generateFindings" }) - return async (reviewContext) => { const delimiterNonce = generateDelimiterNonce() const systemPrompt = buildSystemPrompt({ phase: reviewContext.phase }) @@ -1315,17 +1313,17 @@ export const createPromptedGenerateFindings = ( delimiterNonce, }) - log.info("requesting review", { - phase: reviewContext.phase.id, + // Parallel phases call the same model at once, so the phase prop is what + // tells their log lines apart + const phaseLogger = logger.child({ phase: reviewContext.phase.id }) + + // Only this line gets the module tag. The client's lines record their own + // source file, and a generateFindings tag on them would misattribute them + phaseLogger.child({ module: "generateFindings" }).info("requesting review", { model, fallbackModel, }) - // Parallel phases call the same model at once, so the phase is what tells - // their client log lines apart. The child comes from `logger`, not `log`, - // because those lines come from the client module, not this one - const phaseLogger = logger.child({ phase: reviewContext.phase.id }) - return openrouterClient.requestReview( { systemPrompt, userPrompt, model, fallbackModel }, phaseLogger, From e8259f2cf6b4d219f598d4874bc3c8e5db9aba5b Mon Sep 17 00:00:00 2001 From: Tanisha Aberdeen <32620895+aliasunder@users.noreply.github.com> Date: Wed, 30 Sep 2026 12:44:05 -0400 Subject: [PATCH 3/5] test: pin the phase-tagged review request log and the late-settlement rejection MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The "requesting review" line had no assertion, so a change to how its phase and module tags are bound could pass the suite. It is now pinned whole. The late-settlement test asserts the ladder-exhaustion message instead of only the error class. Two multiline client test callbacks get block bodies, and the stub queue guard is a truthy check. Ship-Check: test-audit · claude-opus-5-5 Co-Authored-By: Claude Opus 5.5 --- src/__tests__/orchestrate.test.ts | 40 +++++++++++++++++++++++++ src/openrouter/__tests__/client.test.ts | 20 ++++++++----- 2 files changed, 53 insertions(+), 7 deletions(-) diff --git a/src/__tests__/orchestrate.test.ts b/src/__tests__/orchestrate.test.ts index fefdbb4..0abd13e 100644 --- a/src/__tests__/orchestrate.test.ts +++ b/src/__tests__/orchestrate.test.ts @@ -4663,6 +4663,46 @@ describe("createPromptedGenerateFindings", () => { ]) }) + it("logs the review request with its phase, module tag, and ladder models", async () => { + const stubClient: OpenRouterClient = { + requestReview: async () => { + return { review: { analysis: "", findings: [] }, modelUsed: "test/primary", attempts: [] } + }, + } + const logger = createTestLogger() + const generate = createPromptedGenerateFindings( + { openrouterClient: stubClient, model: "test/primary", fallbackModel: "test/fallback" }, + logger, + ) + + await generate({ + prContext: fixturePrContext, + phase: SUBTLE_BUGS_PHASE, + conventions: null, + conventionsFile: "AGENTS.md", + conventionsBudgetTokens: 8_000, + changedFiles: [], + relatedFiles: [], + relatedDocs: [], + annotatedDiff: annotateDiff(parseDiff(sampleDiff)), + priorFindings: [], + priorBotComments: [], + }) + + expect(logsWithMessage(logger, "requesting review")).toEqual([ + { + level: "info", + message: "requesting review", + data: { + phase: "subtle-bugs", + module: "generateFindings", + model: "test/primary", + fallbackModel: "test/fallback", + }, + }, + ]) + }) + it("includes annotated diff in the user prompt", async () => { const requestReviewCalls: RequestReviewParams[] = [] const stubClient: OpenRouterClient = { diff --git a/src/openrouter/__tests__/client.test.ts b/src/openrouter/__tests__/client.test.ts index 7a5524c..16781e5 100644 --- a/src/openrouter/__tests__/client.test.ts +++ b/src/openrouter/__tests__/client.test.ts @@ -9,8 +9,9 @@ import { type OpenRouterLike, } from "../client.js" -const readJsonFixture = (name: string): unknown => - JSON.parse(readFileSync(new URL(`../../../fixtures/${name}`, import.meta.url), "utf8")) +const readJsonFixture = (name: string): unknown => { + return JSON.parse(readFileSync(new URL(`../../../fixtures/${name}`, import.meta.url), "utf8")) +} const acceptedChatResult = readJsonFixture("openrouter.chat-result.json") const invalidJsonChatResult = readJsonFixture("openrouter.invalid-json.json") @@ -67,7 +68,7 @@ const makeSdkStub = ({ }): unknown => { const next = queue[callCount - 1] - if (next === undefined) { + if (!next) { throw new Error(`stub: unexpected ${operation} call #${callCount}`) } if ("error" in next) throw next.error @@ -677,14 +678,14 @@ describe("requestReview", () => { // DOMException the aborted fetch raised const rejectOnAbort = (options: StubOptions): Promise => { return new Promise((_resolve, reject) => { - options?.signal?.addEventListener("abort", () => + options?.signal?.addEventListener("abort", () => { reject( Object.assign(new Error("Request aborted by client"), { name: "RequestAbortedError", cause: new DOMException("This operation was aborted", "AbortError"), }), - ), - ) + ) + }) }) } const stub = makeSdkStub({ @@ -895,7 +896,12 @@ describe("requestReview", () => { ), ) await vi.advanceTimersByTimeAsync(45_000) - expect(await rejection).toBeInstanceOf(ReviewRequestError) + const error = await rejection + + if (!(error instanceof ReviewRequestError)) throw error + expect(error.message).toBe( + "review request failed after 2 attempt(s): openai/gpt-5-mini: timeout (no response within 45s); openai/gpt-5-mini: api_error (HTTP 400: HTTP 400)", + ) expect(logsWithMessage(logger, "deadline-elapsed request settled")).toEqual([]) await vi.advanceTimersByTimeAsync(75_000) From b6ffb6e81a3b9c0cd6a108f4949fc703adf49c79 Mon Sep 17 00:00:00 2001 From: Tanisha Aberdeen <32620895+aliasunder@users.noreply.github.com> Date: Wed, 30 Sep 2026 12:48:24 -0400 Subject: [PATCH 4/5] fix: tag cost-lookup failure lines with the generation and correct two doc claims MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The cost-lookup failure warnings logged through the request logger, so they carried no generationId while the lookup's deadline lines did. All lookup lines now go through one child logger that binds it. withDeadline's doc said it logs only timing, but it also logs how the abandoned call settled. createPromptedGenerateFindings's doc said one request, but the client's retry and fallback ladder can send several. Ship-Check: bug-check · claude-opus-5-5 Co-Authored-By: Claude Opus 5.5 --- src/openrouter/__tests__/client.test.ts | 26 ++++++++++++++++++++----- src/openrouter/client.ts | 13 ++++++++----- src/orchestrate.ts | 5 ++--- 3 files changed, 31 insertions(+), 13 deletions(-) diff --git a/src/openrouter/__tests__/client.test.ts b/src/openrouter/__tests__/client.test.ts index 16781e5..fc51ffc 100644 --- a/src/openrouter/__tests__/client.test.ts +++ b/src/openrouter/__tests__/client.test.ts @@ -1128,7 +1128,11 @@ describe("requestReview", () => { { level: "warn", message: "generation cost lookup failed", - data: { error: "review deadline exceeded" }, + data: { + operation: "generation cost lookup", + generationId: "gen-no-cost", + error: "review deadline exceeded", + }, }, ]) } finally { @@ -1171,7 +1175,11 @@ describe("requestReview", () => { { level: "warn", message: "generation cost lookup failed", - data: { error: "no response within 45s" }, + data: { + operation: "generation cost lookup", + generationId: "gen-no-cost", + error: "no response within 45s", + }, }, ]) } finally { @@ -1624,7 +1632,11 @@ describe("requestReview", () => { { level: "warn", message: "generation cost lookup failed", - data: { error: "HTTP 500" }, + data: { + operation: "generation cost lookup", + generationId: "gen-no-cost", + error: "HTTP 500", + }, }, ]) }) @@ -1647,7 +1659,11 @@ describe("requestReview", () => { { level: "warn", message: "generation cost lookup failed", - data: { error: "lookup threw before returning a promise" }, + data: { + operation: "generation cost lookup", + generationId: "gen-no-cost", + error: "lookup threw before returning a promise", + }, }, ]) }) @@ -1666,7 +1682,7 @@ describe("requestReview", () => { { level: "warn", message: "unexpected generation response shape", - data: {}, + data: { operation: "generation cost lookup", generationId: "gen-no-cost" }, }, ]) }) diff --git a/src/openrouter/client.ts b/src/openrouter/client.ts index 612fe8d..f4c4bed 100644 --- a/src/openrouter/client.ts +++ b/src/openrouter/client.ts @@ -237,7 +237,7 @@ const describeLateSettlement = (late: SettledResult): LateSettlement => { * - Resolve the deadline before aborting so it wins deterministically. * - Return at the deadline even when the SDK ignores the abort. * - Observe the abandoned call and log how it eventually settles. - * - Log only timing; the caller binds the operation's identifying props to `logger`. */ + * - Add no identifying props to its log lines; the caller binds them to `logger`. */ const withDeadline = async ( { start, @@ -567,6 +567,9 @@ export const createOpenRouterClient = ({ // runs long const reviewDeadlineIsBinding = remainingMs <= requestTimeoutMs + // Every lookup line names the generation, so a failure ties back to it + const lookupLogger = logger.child({ operation: "generation cost lookup", generationId }) + const lookup = await withDeadline( { start: (signal) => { @@ -577,17 +580,17 @@ export const createOpenRouterClient = ({ }, timeoutMs: Math.min(requestTimeoutMs, remainingMs), }, - logger.child({ operation: "generation cost lookup", generationId }), + lookupLogger, ) if (lookup.status === "timed_out") { - logger.warn("generation cost lookup failed", { + lookupLogger.warn("generation cost lookup failed", { error: reviewDeadlineIsBinding ? "review deadline exceeded" : requestTimeoutSummary, }) return null } if (lookup.status === "rejected") { - logger.warn("generation cost lookup failed", { + lookupLogger.warn("generation cost lookup failed", { error: summarizeError(lookup.error), }) return null @@ -596,7 +599,7 @@ export const createOpenRouterClient = ({ const parsed = generationResponseSchema.safeParse(lookup.value) if (!parsed.success) { - logger.warn("unexpected generation response shape") + lookupLogger.warn("unexpected generation response shape") return null } diff --git a/src/orchestrate.ts b/src/orchestrate.ts index 609c987..9e64368 100644 --- a/src/orchestrate.ts +++ b/src/orchestrate.ts @@ -1290,9 +1290,8 @@ export const orchestrate = async ( } } -/** Builds one review phase's prompt and sends it to OpenRouter in a single - * request with no tool calls. The stage dispatcher calls the returned - * function once per phase. */ +/** Builds one review phase's prompt and sends it to OpenRouter with no tool + * calls. The stage dispatcher calls the returned function once per phase. */ export const createPromptedGenerateFindings = ( { openrouterClient, From fec6d294196bef5984d975725e1e916037e56342 Mon Sep 17 00:00:00 2001 From: Tanisha Aberdeen <32620895+aliasunder@users.noreply.github.com> Date: Wed, 30 Sep 2026 13:57:23 -0400 Subject: [PATCH 5/5] refactor(orchestrate): drop the hand-set module tag from the review request log The requesting-review line already carries the phase and an auto-captured source file, so the manual module tag added nothing and needed a comment explaining why client lines lack it. Co-Authored-By: Claude Opus 5.5 --- src/__tests__/orchestrate.test.ts | 3 +-- src/orchestrate.ts | 7 +------ 2 files changed, 2 insertions(+), 8 deletions(-) diff --git a/src/__tests__/orchestrate.test.ts b/src/__tests__/orchestrate.test.ts index 0abd13e..e05a7e5 100644 --- a/src/__tests__/orchestrate.test.ts +++ b/src/__tests__/orchestrate.test.ts @@ -4663,7 +4663,7 @@ describe("createPromptedGenerateFindings", () => { ]) }) - it("logs the review request with its phase, module tag, and ladder models", async () => { + it("logs the review request with its phase and ladder models", async () => { const stubClient: OpenRouterClient = { requestReview: async () => { return { review: { analysis: "", findings: [] }, modelUsed: "test/primary", attempts: [] } @@ -4695,7 +4695,6 @@ describe("createPromptedGenerateFindings", () => { message: "requesting review", data: { phase: "subtle-bugs", - module: "generateFindings", model: "test/primary", fallbackModel: "test/fallback", }, diff --git a/src/orchestrate.ts b/src/orchestrate.ts index 9e64368..894ba71 100644 --- a/src/orchestrate.ts +++ b/src/orchestrate.ts @@ -1316,12 +1316,7 @@ export const createPromptedGenerateFindings = ( // tells their log lines apart const phaseLogger = logger.child({ phase: reviewContext.phase.id }) - // Only this line gets the module tag. The client's lines record their own - // source file, and a generateFindings tag on them would misattribute them - phaseLogger.child({ module: "generateFindings" }).info("requesting review", { - model, - fallbackModel, - }) + phaseLogger.info("requesting review", { model, fallbackModel }) return openrouterClient.requestReview( { systemPrompt, userPrompt, model, fallbackModel },