diff --git a/src/__tests__/orchestrate.test.ts b/src/__tests__/orchestrate.test.ts index b404b9d..e05a7e5 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,79 @@ 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("logs the review request with its phase 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", + 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/main.ts b/src/main.ts index 410cdb8..72b5b6e 100644 --- a/src/main.ts +++ b/src/main.ts @@ -127,14 +127,13 @@ try { ), generateFindings: createPromptedGenerateFindings( { - openrouterClient: createOpenRouterClient( - { - sdk: new OpenRouter({ apiKey: config.openrouterApiKey }), - requestTimeoutMs: config.requestTimeoutSeconds * 1000, - remainingReviewMs, - }, - logger, - ), + // 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, + 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..fc51ffc 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 @@ -105,15 +106,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 +164,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 +201,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 +284,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 +334,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 +369,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 +413,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 +446,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 +470,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 +508,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 +540,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 +577,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 +599,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 +625,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 +662,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) @@ -682,36 +678,36 @@ 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({ 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 +750,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 +835,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 +870,61 @@ 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) + 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) + + 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 +937,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 +982,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 +1037,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 +1073,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 +1105,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 @@ -1095,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 { @@ -1111,17 +1148,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 @@ -1141,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 { @@ -1154,11 +1192,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 +1209,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 +1244,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 +1255,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 +1292,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 +1339,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 +1357,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 +1375,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 +1393,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 +1414,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 +1433,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 +1451,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 +1465,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 +1481,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 +1494,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 +1508,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 +1542,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 +1571,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 +1583,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 +1602,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,14 +1625,18 @@ 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([ { level: "warn", message: "generation cost lookup failed", - data: { error: "HTTP 500" }, + data: { + operation: "generation cost lookup", + generationId: "gen-no-cost", + error: "HTTP 500", + }, }, ]) }) @@ -1611,14 +1652,18 @@ 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([ { 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", + }, }, ]) }) @@ -1630,14 +1675,14 @@ 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([ { level: "warn", message: "unexpected generation response shape", - data: {}, + data: { operation: "generation cost lookup", generationId: "gen-no-cost" }, }, ]) }) @@ -1652,9 +1697,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 +1719,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..f4c4bed 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`, 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 + userPrompt: string + model: string + fallbackModel: string | null + }, + logger: Logger, + ) => Promise } const chatResultSchema = z.object({ @@ -230,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. + * - Add no identifying props to its log lines; the caller binds them to `logger`. */ const withDeadline = async ( { start, timeoutMs, - logContext, }: { start: (signal: AbortSignal) => Promise timeoutMs: number - logContext: Record }, logger: Logger, ): Promise> => { @@ -266,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), @@ -382,30 +386,34 @@ 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 => { +/** 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, + 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 => { + /** 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, + ): Promise => { const { model } = chatRequest const remainingMs = remainingReviewMs() @@ -419,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 @@ -547,7 +554,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() @@ -557,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) => { @@ -566,19 +579,18 @@ export const createOpenRouterClient = ( ) }, timeoutMs: Math.min(requestTimeoutMs, remainingMs), - logContext: { operation: "generation cost lookup", generationId }, }, - logger, + 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 @@ -587,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 } @@ -595,17 +607,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 - }): Promise => { + const requestReview: OpenRouterClient["requestReview"] = async ( + { systemPrompt, userPrompt, model, fallbackModel }, + logger, + ) => { const modelLadder = fallbackModel === null ? [model] : [model, fallbackModel] const attempts: ModelAttempt[] = [] const ensureReviewTimeRemaining = (): void => { @@ -630,13 +635,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..894ba71 100644 --- a/src/orchestrate.ts +++ b/src/orchestrate.ts @@ -1290,9 +1290,8 @@ 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 with no tool + * calls. The stage dispatcher calls the returned function once per phase. */ export const createPromptedGenerateFindings = ( { openrouterClient, @@ -1305,8 +1304,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 +1312,15 @@ export const createPromptedGenerateFindings = ( delimiterNonce, }) - log.info("requesting review", { - phase: reviewContext.phase.id, - model, - fallbackModel, - }) + // 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 }) - return openrouterClient.requestReview({ - systemPrompt, - userPrompt, - model, - fallbackModel, - }) + phaseLogger.info("requesting review", { model, fallbackModel }) + + return openrouterClient.requestReview( + { systemPrompt, userPrompt, model, fallbackModel }, + phaseLogger, + ) } }