From 5d588c427a932f2f635e4520ff95ea65bc4fb806 Mon Sep 17 00:00:00 2001 From: Hannes Rudolph Date: Wed, 17 Dec 2025 21:02:47 -0700 Subject: [PATCH] fix(logging): address PR review feedback - withLogging: count tool_call_partial chunks using index-based tracking to avoid undercounting (resolves fix-id: 085ec7dcd8) - createLoggingFetch: handle non-string request bodies (Blob, ArrayBuffer, FormData, ReadableStream) by returning descriptive placeholders instead of misleading toString() output (resolves fix-id: 78ceafcb0f) - Added comprehensive tests for both fixes --- .../__tests__/http-interceptor.spec.ts | 274 ++++++++++++++++++ .../logging/__tests__/with-logging.spec.ts | 48 +++ src/api/core/logging/http-interceptor.ts | 47 ++- src/api/core/logging/with-logging.ts | 9 + src/api/providers/__tests__/vertex.spec.ts | 6 +- 5 files changed, 376 insertions(+), 8 deletions(-) create mode 100644 src/api/core/logging/__tests__/http-interceptor.spec.ts diff --git a/src/api/core/logging/__tests__/http-interceptor.spec.ts b/src/api/core/logging/__tests__/http-interceptor.spec.ts new file mode 100644 index 0000000000..02d8819048 --- /dev/null +++ b/src/api/core/logging/__tests__/http-interceptor.spec.ts @@ -0,0 +1,274 @@ +/** + * @fileoverview Tests for the HTTP interceptor logging module + */ + +import { createLoggingFetch } from "../http-interceptor" +import * as envConfig from "../env-config" + +// Mock the env-config module +vi.mock("../env-config", () => ({ + isLoggingEnabled: vi.fn(), +})) + +describe("createLoggingFetch", () => { + let consoleSpy: ReturnType + let mockFetch: ReturnType + + beforeEach(() => { + vi.clearAllMocks() + consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}) + + // Mock global fetch + mockFetch = vi.fn().mockResolvedValue( + new Response(JSON.stringify({ result: "success" }), { + status: 200, + statusText: "OK", + headers: { "content-type": "application/json" }, + }), + ) + vi.stubGlobal("fetch", mockFetch) + }) + + afterEach(() => { + vi.unstubAllGlobals() + }) + + describe("body parsing", () => { + beforeEach(() => { + vi.mocked(envConfig.isLoggingEnabled).mockReturnValue(true) + }) + + it("should parse JSON string body correctly", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + const body = JSON.stringify({ message: "hello" }) + + await loggingFetch("https://api.example.com/test", { + method: "POST", + body, + }) + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP REQUEST", + expect.objectContaining({ + body: { message: "hello" }, + }), + ) + }) + + it("should handle plain string body", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + + await loggingFetch("https://api.example.com/test", { + method: "POST", + body: "plain text content", + }) + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP REQUEST", + expect.objectContaining({ + body: "plain text content", + }), + ) + }) + + it("should handle URLSearchParams body", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + const params = new URLSearchParams({ key: "value", foo: "bar" }) + + await loggingFetch("https://api.example.com/test", { + method: "POST", + body: params, + }) + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP REQUEST", + expect.objectContaining({ + body: "key=value&foo=bar", + }), + ) + }) + + it("should handle Blob body with placeholder", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + const blob = new Blob(["binary content"], { type: "application/octet-stream" }) + + await loggingFetch("https://api.example.com/test", { + method: "POST", + body: blob, + }) + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP REQUEST", + expect.objectContaining({ + body: expect.stringMatching(/^\[Blob: \d+ bytes, type: application\/octet-stream\]$/), + }), + ) + }) + + it("should handle ArrayBuffer body with placeholder", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + const buffer = new ArrayBuffer(16) + + await loggingFetch("https://api.example.com/test", { + method: "POST", + body: buffer, + }) + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP REQUEST", + expect.objectContaining({ + body: "[ArrayBuffer: 16 bytes]", + }), + ) + }) + + it("should handle FormData body with placeholder", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + const formData = new FormData() + formData.append("field", "value") + + await loggingFetch("https://api.example.com/test", { + method: "POST", + body: formData, + }) + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP REQUEST", + expect.objectContaining({ + body: "[FormData]", + }), + ) + }) + + it("should handle undefined body", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + + await loggingFetch("https://api.example.com/test", { + method: "GET", + }) + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP REQUEST", + expect.objectContaining({ + body: undefined, + }), + ) + }) + + it("should handle null body", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + + await loggingFetch("https://api.example.com/test", { + method: "POST", + body: null, + }) + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP REQUEST", + expect.objectContaining({ + body: undefined, + }), + ) + }) + }) + + describe("when logging is disabled", () => { + it("should not log requests or responses", async () => { + vi.mocked(envConfig.isLoggingEnabled).mockReturnValue(false) + const loggingFetch = createLoggingFetch("TestProvider") + + await loggingFetch("https://api.example.com/test", { + method: "POST", + body: JSON.stringify({ test: true }), + }) + + expect(consoleSpy).not.toHaveBeenCalled() + }) + }) + + describe("header sanitization", () => { + beforeEach(() => { + vi.mocked(envConfig.isLoggingEnabled).mockReturnValue(true) + }) + + it("should mask authorization header values", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + + await loggingFetch("https://api.example.com/test", { + method: "GET", + headers: { + Authorization: "Bearer sk-1234567890abcdef", + }, + }) + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP REQUEST", + expect.objectContaining({ + headers: expect.objectContaining({ + Authorization: "Bear...cdef", + }), + }), + ) + }) + + it("should mask x-api-key header values", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + + await loggingFetch("https://api.example.com/test", { + method: "GET", + headers: { + "x-api-key": "api-key-12345678", + }, + }) + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP REQUEST", + expect.objectContaining({ + headers: expect.objectContaining({ + "x-api-key": "api-...5678", + }), + }), + ) + }) + }) + + describe("response handling", () => { + beforeEach(() => { + vi.mocked(envConfig.isLoggingEnabled).mockReturnValue(true) + }) + + it("should log streaming responses without body", async () => { + mockFetch.mockResolvedValueOnce( + new Response("data: test\n\n", { + status: 200, + statusText: "OK", + headers: { "content-type": "text/event-stream" }, + }), + ) + + const loggingFetch = createLoggingFetch("TestProvider") + await loggingFetch("https://api.example.com/stream") + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP RESPONSE", + expect.objectContaining({ + status: 200, + streaming: true, + }), + ) + }) + + it("should log non-streaming responses with body", async () => { + const loggingFetch = createLoggingFetch("TestProvider") + await loggingFetch("https://api.example.com/test") + + expect(consoleSpy).toHaveBeenCalledWith( + "[TestProvider] RAW HTTP RESPONSE", + expect.objectContaining({ + status: 200, + body: { result: "success" }, + }), + ) + }) + }) +}) diff --git a/src/api/core/logging/__tests__/with-logging.spec.ts b/src/api/core/logging/__tests__/with-logging.spec.ts index 77a70a6b42..f80500fd30 100644 --- a/src/api/core/logging/__tests__/with-logging.spec.ts +++ b/src/api/core/logging/__tests__/with-logging.spec.ts @@ -179,6 +179,54 @@ describe("withLogging", () => { ) }) + it("should count tool_call_partial chunks without overcounting", async () => { + // Simulates streaming tool calls with multiple partial chunks per tool + const chunks: ApiStreamChunk[] = [ + // First tool call (index 0) - multiple partials + { type: "tool_call_partial", index: 0, id: "call1", name: "read_file" }, + { type: "tool_call_partial", index: 0, arguments: '{"path":' }, + { type: "tool_call_partial", index: 0, arguments: '"/src/file.ts"}' }, + // Second tool call (index 1) - multiple partials + { type: "tool_call_partial", index: 1, id: "call2", name: "write_file" }, + { type: "tool_call_partial", index: 1, arguments: '{"path":' }, + { type: "tool_call_partial", index: 1, arguments: '"/src/new.ts",' }, + { type: "tool_call_partial", index: 1, arguments: '"content":"hello"}' }, + ] + + const stream = withLogging({ context: baseContext, request: baseRequest }, () => createMockStream(chunks)) + + await collectStream(stream) + + // Should count only 2 unique tool calls (by index), not 7 partial chunks + expect(ApiLogger.logResponse).toHaveBeenCalledWith( + "mock-request-id", + baseContext, + expect.objectContaining({ toolCallCount: 2 }), + ) + }) + + it("should count single tool_call_partial chunk correctly", async () => { + const chunks: ApiStreamChunk[] = [ + { + type: "tool_call_partial", + index: 0, + id: "call1", + name: "read_file", + arguments: '{"path":"/file.ts"}', + }, + ] + + const stream = withLogging({ context: baseContext, request: baseRequest }, () => createMockStream(chunks)) + + await collectStream(stream) + + expect(ApiLogger.logResponse).toHaveBeenCalledWith( + "mock-request-id", + baseContext, + expect.objectContaining({ toolCallCount: 1 }), + ) + }) + it("should capture usage metrics from usage chunk", async () => { const chunks: ApiStreamChunk[] = [ { type: "text", text: "Response" }, diff --git a/src/api/core/logging/http-interceptor.ts b/src/api/core/logging/http-interceptor.ts index 10df9e90af..813eeecd40 100644 --- a/src/api/core/logging/http-interceptor.ts +++ b/src/api/core/logging/http-interceptor.ts @@ -31,15 +31,48 @@ function sanitizeHeaders(headers: Record): Record let reasoningLength = 0 let toolCallCount = 0 let usage: ApiStreamUsageChunk | undefined + // Track seen tool_call_partial indices to avoid overcounting + const seenToolCallPartialIndices = new Set() try { for await (const chunk of generator()) { @@ -62,6 +64,13 @@ export async function* withLogging(options: WithLoggingOptions, generator: () => case "tool_call_start": toolCallCount++ break + case "tool_call_partial": + // Count each unique tool call only once using index + if (!seenToolCallPartialIndices.has(chunk.index)) { + seenToolCallPartialIndices.add(chunk.index) + toolCallCount++ + } + break case "usage": usage = chunk break diff --git a/src/api/providers/__tests__/vertex.spec.ts b/src/api/providers/__tests__/vertex.spec.ts index 1420b05c7a..c7032bd520 100644 --- a/src/api/providers/__tests__/vertex.spec.ts +++ b/src/api/providers/__tests__/vertex.spec.ts @@ -1,7 +1,11 @@ // npx vitest run src/api/providers/__tests__/vertex.spec.ts // Mock vscode first to avoid import errors -vitest.mock("vscode", () => ({})) +vitest.mock("vscode", () => ({ + workspace: { + workspaceFolders: undefined, + }, +})) import { Anthropic } from "@anthropic-ai/sdk"