Fix JSON.stringify circular reference error in logging infrastructure (#607)

Resolves circular structure errors when serializing request/response bodies for logging.

Other changes:
* Added test coverage for logging infrastructure
* Fixed flaky stream test
* Calculate body size directly from strings/buffers instead of stringifying
* Use util.inspect instead of JSON.stringify for body serialization

Fixes #606

Author: EhabY

CHANGELOG.md

@@ -5,6 +5,7 @@
 ### Fixed
 
 - Logging in or out in one VS Code window now properly updates the authentication status in all other open windows.
+- Fix an issue with JSON stringification errors occurring when logging circular objects.
 
 ### Added
 

src/api/coderApi.ts

@@ -1,4 +1,9 @@
-import { type AxiosInstance } from "axios";
+import {
+	type AxiosResponseHeaders,
+	type AxiosInstance,
+	type AxiosHeaders,
+	type AxiosResponseTransformer,
+} from "axios";
 import { Api } from "coder/site/src/api/api";
 import {
 	type GetInboxNotificationResponse,
@@ -23,6 +28,7 @@ import {
 	type RequestConfigWithMeta,
 	HttpClientLogLevel,
 } from "../logging/types";
+import { sizeOf } from "../logging/utils";
 import { WsLogger } from "../logging/wsLogger";
 import {
 	OneWayWebSocket,
@@ -207,7 +213,24 @@ function addLoggingInterceptors(client: AxiosInstance, logger: Logger) {
 		(config) => {
 			const configWithMeta = config as RequestConfigWithMeta;
 			configWithMeta.metadata = createRequestMeta();
-			logRequest(logger, configWithMeta, getLogLevel());
+
+			config.transformRequest = [
+				...wrapRequestTransform(
+					config.transformRequest || client.defaults.transformRequest || [],
+					configWithMeta,
+				),
+				(data) => {
+					// Log after setting the raw request size
+					logRequest(logger, configWithMeta, getLogLevel());
+					return data;
+				},
+			];
+
+			config.transformResponse = wrapResponseTransform(
+				config.transformResponse || client.defaults.transformResponse || [],
+				configWithMeta,
+			);
+
 			return config;
 		},
 		(error: unknown) => {
@@ -228,6 +251,59 @@ function addLoggingInterceptors(client: AxiosInstance, logger: Logger) {
 	);
 }
 
+function wrapRequestTransform(
+	transformer: AxiosResponseTransformer | AxiosResponseTransformer[],
+	config: RequestConfigWithMeta,
+): AxiosResponseTransformer[] {
+	return [
+		(data: unknown, headers: AxiosHeaders) => {
+			const transformerArray = Array.isArray(transformer)
+				? transformer
+				: [transformer];
+
+			// Transform the request first then get the size (measure what's sent over the wire)
+			const result = transformerArray.reduce(
+				(d, fn) => fn.call(config, d, headers),
+				data,
+			);
+
+			config.rawRequestSize = getSize(config.headers, result);
+
+			return result;
+		},
+	];
+}
+
+function wrapResponseTransform(
+	transformer: AxiosResponseTransformer | AxiosResponseTransformer[],
+	config: RequestConfigWithMeta,
+): AxiosResponseTransformer[] {
+	return [
+		(data: unknown, headers: AxiosResponseHeaders, status?: number) => {
+			// Get the size before transforming the response (measure what's sent over the wire)
+			config.rawResponseSize = getSize(headers, data);
+
+			const transformerArray = Array.isArray(transformer)
+				? transformer
+				: [transformer];
+
+			return transformerArray.reduce(
+				(d, fn) => fn.call(config, d, headers, status),
+				data,
+			);
+		},
+	];
+}
+
+function getSize(headers: AxiosHeaders, data: unknown): number | undefined {
+	const contentLength = headers["content-length"];
+	if (contentLength !== undefined) {
+		return parseInt(contentLength, 10);
+	}
+
+	return sizeOf(data);
+}
+
 function getLogLevel(): HttpClientLogLevel {
 	const logLevelStr = vscode.workspace
 		.getConfiguration()

src/core/cliManager.ts

@@ -267,7 +267,7 @@ export class CliManager {
 			if (Number.isNaN(contentLength)) {
 				this.output.warn(
 					"Got invalid or missing content length",
-					rawContentLength,
+					rawContentLength ?? "",
 				);
 			} else {
 				this.output.info("Got content length", prettyBytes(contentLength));

src/logging/formatters.ts

@@ -1,6 +1,8 @@
 import prettyBytes from "pretty-bytes";
 
-import type { InternalAxiosRequestConfig } from "axios";
+import { safeStringify } from "./utils";
+
+import type { AxiosRequestConfig } from "axios";
 
 const SENSITIVE_HEADERS = ["Coder-Session-Token", "Proxy-Authorization"];
 
@@ -18,35 +20,14 @@ export function formatTime(ms: number): string {
 }
 
 export function formatMethod(method: string | undefined): string {
-	return (method ?? "GET").toUpperCase();
+	return method?.toUpperCase() || "GET";
 }
 
-/**
- * Formats content-length for display. Returns the header value if available,
- * otherwise estimates size by serializing the data body (prefixed with ~).
- */
-export function formatContentLength(
-	headers: Record<string, unknown>,
-	data: unknown,
-): string {
-	const len = headers["content-length"];
-	if (len && typeof len === "string") {
-		const bytes = parseInt(len, 10);
-		return isNaN(bytes) ? "(?b)" : `(${prettyBytes(bytes)})`;
-	}
-
-	// Estimate from data if no header
-	if (data !== undefined && data !== null) {
-		const estimated = Buffer.byteLength(JSON.stringify(data), "utf8");
-		return `(~${prettyBytes(estimated)})`;
-	}
-
-	return `(${prettyBytes(0)})`;
+export function formatSize(size: number | undefined): string {
+	return size === undefined ? "(? B)" : `(${prettyBytes(size)})`;
 }
 
-export function formatUri(
-	config: InternalAxiosRequestConfig | undefined,
-): string {
+export function formatUri(config: AxiosRequestConfig | undefined): string {
 	return config?.url || "<no url>";
 }
 
@@ -66,7 +47,7 @@ export function formatHeaders(headers: Record<string, unknown>): string {
 
 export function formatBody(body: unknown): string {
 	if (body) {
-		return JSON.stringify(body);
+		return safeStringify(body) ?? "<invalid body>";
 	} else {
 		return "<no body>";
 	}

src/logging/httpLogger.ts

@@ -5,9 +5,9 @@ import { getErrorDetail } from "../error";
 
 import {
 	formatBody,
-	formatContentLength,
 	formatHeaders,
 	formatMethod,
+	formatSize,
 	formatTime,
 	formatUri,
 } from "./formatters";
@@ -42,11 +42,10 @@ export function logRequest(
 		return;
 	}
 
-	const { requestId, method, url } = parseConfig(config);
-	const len = formatContentLength(config.headers, config.data);
+	const { requestId, method, url, requestSize } = parseConfig(config);
 
 	const msg = [
-		`→ ${shortId(requestId)} ${method} ${url} ${len}`,
+		`→ ${shortId(requestId)} ${method} ${url} ${requestSize}`,
 		...buildExtraLogs(config.headers, config.data, logLevel),
 	];
 	logger.trace(msg.join("\n"));
@@ -64,11 +63,12 @@ export function logResponse(
 		return;
 	}
 
-	const { requestId, method, url, time } = parseConfig(response.config);
-	const len = formatContentLength(response.headers, response.data);
+	const { requestId, method, url, time, responseSize } = parseConfig(
+		response.config,
+	);
 
 	const msg = [
-		`← ${shortId(requestId)} ${response.status} ${method} ${url} ${len} ${time}`,
+		`← ${shortId(requestId)} ${response.status} ${method} ${url} ${responseSize} ${time}`,
 		...buildExtraLogs(response.headers, response.data, logLevel),
 	];
 	logger.trace(msg.join("\n"));
@@ -150,12 +150,16 @@ function parseConfig(config: RequestConfigWithMeta | undefined): {
 	method: string;
 	url: string;
 	time: string;
+	requestSize: string;
+	responseSize: string;
 } {
 	const meta = config?.metadata;
 	return {
 		requestId: meta?.requestId || "unknown",
 		method: formatMethod(config?.method),
 		url: formatUri(config),
 		time: meta ? formatTime(Date.now() - meta.startedAt) : "?ms",
+		requestSize: formatSize(config?.rawRequestSize),
+		responseSize: formatSize(config?.rawResponseSize),
 	};
 }

src/logging/types.ts

@@ -14,4 +14,6 @@ export interface RequestMeta {
 
 export type RequestConfigWithMeta = InternalAxiosRequestConfig & {
 	metadata?: RequestMeta;
+	rawRequestSize?: number;
+	rawResponseSize?: number;
 };

src/logging/utils.ts

@@ -1,21 +1,37 @@
 import { Buffer } from "node:buffer";
 import crypto from "node:crypto";
+import util from "node:util";
 
 export function shortId(id: string): string {
 	return id.slice(0, 8);
 }
 
+export function createRequestId(): string {
+	return crypto.randomUUID().replace(/-/g, "");
+}
+
+/**
+ * Returns the byte size of the data if it can be determined from the data's intrinsic properties,
+ * otherwise returns undefined (e.g., for plain objects and arrays that would require serialization).
+ */
 export function sizeOf(data: unknown): number | undefined {
 	if (data === null || data === undefined) {
 		return 0;
 	}
-	if (typeof data === "string") {
-		return Buffer.byteLength(data);
+	if (typeof data === "boolean") {
+		return 4;
+	}
+	if (typeof data === "number") {
+		return 8;
 	}
-	if (Buffer.isBuffer(data)) {
-		return data.length;
+	if (typeof data === "string" || typeof data === "bigint") {
+		return Buffer.byteLength(data.toString());
 	}
-	if (data instanceof ArrayBuffer || ArrayBuffer.isView(data)) {
+	if (
+		Buffer.isBuffer(data) ||
+		data instanceof ArrayBuffer ||
+		ArrayBuffer.isView(data)
+	) {
 		return data.byteLength;
 	}
 	if (
@@ -28,6 +44,19 @@ export function sizeOf(data: unknown): number | undefined {
 	return undefined;
 }
 
-export function createRequestId(): string {
-	return crypto.randomUUID().replace(/-/g, "");
+export function safeStringify(data: unknown): string | null {
+	try {
+		return util.inspect(data, {
+			showHidden: false,
+			depth: Infinity,
+			maxArrayLength: Infinity,
+			maxStringLength: Infinity,
+			breakLength: Infinity,
+			compact: true,
+			getters: false, // avoid side-effects
+		});
+	} catch {
+		// Should rarely happen but just in case
+		return null;
+	}
 }

src/logging/wsLogger.ts

@@ -77,6 +77,6 @@ export class WsLogger {
 
 	private formatBytes(): string {
 		const bytes = prettyBytes(this.byteCount);
-		return this.unknownByteCount ? `>=${bytes}` : bytes;
+		return this.unknownByteCount ? `>= ${bytes}` : bytes;
 	}
 }

test/mocks/testHelpers.ts

@@ -1,6 +1,8 @@
 import { vi } from "vitest";
 import * as vscode from "vscode";
 
+import { type Logger } from "@/logging/logger";
+
 /**
  * Mock configuration provider that integrates with the vscode workspace configuration mock.
  * Use this to set configuration values that will be returned by vscode.workspace.getConfiguration().
@@ -286,3 +288,13 @@ export class InMemorySecretStorage implements vscode.SecretStorage {
 		this.listeners.forEach((listener) => listener(event));
 	}
 }
+
+export function createMockLogger(): Logger {
+	return {
+		trace: vi.fn(),
+		debug: vi.fn(),
+		info: vi.fn(),
+		warn: vi.fn(),
+		error: vi.fn(),
+	};
+}