fix(logging): write log fields without throwing and without credentials

formatLogLine wrote the fields of a log call with JSON.stringify. A
circular reference threw, so Strapi's error middleware lost the error
it was logging: the axios error of a failed PayPal token request holds
its request object, which refers to itself. An Error was written as {},
and the config.headers of an axios error carried "Authorization: Basic"
with the base64 of the PayPal client id and secret into the line.

The fields are now copied before they are written:
- a field named like a credential (authorization, cookie, password,
  secret, token, api key) is written as "[redacted]", at any depth;
- an Error is written as { name, message }, with the first line of the
  message as describeError has it, and its stack only with the stack
  option;
- an object that contains itself is written once, the reference to it
  as "[Circular]";
- an instance of a class is written as its toJSON(), or as its class
  name without one: a request object keeps its headers in _header;
- a bigint is written as its digits, an unreadable field as
  "[unreadable]".

The three todo tests of the formatter pass and are regular tests now.

Refs libretech/mp#71
Refs libretech/mp#67

src/logging/format.ts

@@ -1,3 +1,5 @@
+import { describeError } from "./error";
+
 /** What winston hands a printf template (logform's TransformableInfo); Strapi's default format has added `timestamp`. */
 export type LogInfo = {
 	level: string;
@@ -5,10 +7,76 @@ export type LogInfo = {
 	[key: string | symbol]: unknown;
 };
 
-/** One console line: `<timestamp>Z <level>: <message> <all other fields as indented JSON, if any>`. */
-export const formatLogLine = ({ timestamp, level, message, ...rest }: LogInfo): string => {
-	let restString = JSON.stringify(rest, undefined, 2);
+export type LogFormatOptions = {
+	/** Writes the stack of an error value too. config/logger.ts sets it at the debug level, the local one. */
+	stack?: boolean;
+};
+
+// A field whose name matches holds a credential or a session, at any depth: an axios error carries the request headers in
+// config.headers, among them "Authorization: Basic <base64 of the PayPal client id and secret>".
+const SENSITIVE_KEY = /authorization|cookie|password|secret|token|api[-_]?key/i;
+const REDACTED = "[redacted]";
+
+/**
+ * A copy of the value that JSON.stringify writes without throwing and without credentials:
+ * - a field whose name matches SENSITIVE_KEY becomes "[redacted]";
+ * - an Error becomes { name, message } as describeError has them, the first line of the message only, plus the stack if asked;
+ * - an object that contains itself is written once, the reference to it as "[Circular]";
+ * - an instance of a class other than Object and Array is written as its toJSON() if it has one, else as "[ClassName]": a request
+ *   or socket object keeps the request headers, and with them the credentials, in fields such as _header;
+ * - a bigint, which JSON.stringify throws on, becomes its digits, and a value that cannot be read becomes "[unreadable]".
+ */
+const toLoggable = (value: unknown, options: LogFormatOptions, ancestors: object[]): unknown => {
+	if (typeof value === "bigint") return value.toString();
+	if (typeof value !== "object" || value === null) return value;
+	if (ancestors.includes(value)) return "[Circular]";
+
+	ancestors.push(value);
+	try {
+		if (value instanceof Error) {
+			const { name, message } = describeError(value);
+			return options.stack && typeof value.stack === "string" ? { name, message, stack: value.stack } : { name, message };
+		}
+		if (Array.isArray(value)) return value.map((item) => toLoggable(item, options, ancestors));
+
+		const prototype = Object.getPrototypeOf(value);
+		if (prototype !== Object.prototype && prototype !== null) {
+			const { toJSON } = value as { toJSON?: unknown };
+			if (typeof toJSON === "function") return toLoggable(toJSON.call(value), options, ancestors);
+			const name = (value as { constructor?: { name?: unknown } }).constructor?.name;
+			return `[${typeof name === "string" && name !== "" ? name : "object"}]`;
+		}
+
+		const copy: Record<string, unknown> = {};
+		for (const key of Object.keys(value)) {
+			const field = (value as Record<string, unknown>)[key];
+			// Dropped as JSON.stringify drops them; a function named toJSON would also be called on the copy.
+			if (typeof field === "function") continue;
+			copy[key] = SENSITIVE_KEY.test(key) ? REDACTED : toLoggable(field, options, ancestors);
+		}
+		return copy;
+	} catch {
+		return "[unreadable]";
+	} finally {
+		ancestors.pop();
+	}
+};
+
+const asText = (value: unknown): string => {
+	try {
+		return String(value);
+	} catch {
+		return "[unreadable]";
+	}
+};
+
+/**
+ * One console line: `<timestamp>Z <level>: <message> <all other fields as indented JSON, if any>`. Never throws: a log call that
+ * throws loses the line, and in Strapi's error middleware the error it was logging.
+ */
+export const formatLogLine = ({ timestamp, level, message, ...rest }: LogInfo, options: LogFormatOptions = {}): string => {
+	let restString = JSON.stringify(toLoggable(rest, options, []), undefined, 2);
 	restString = restString === "{}" ? "" : restString;
 
-	return `${timestamp}Z ${level}: ${message} ${restString}`;
+	return `${asText(timestamp)}Z ${asText(level)}: ${asText(message)} ${restString}`;
 };

tests/unit/log-error.test.ts

@@ -50,7 +50,7 @@ test("describes a thrown value that is not an error by its type alone", () => {
 });
 
 test("the log line of the description holds no credentials", () => {
-	// Compare log-format.test.ts: the line of the error object itself holds them, a known defect of the formatter.
+	// The formatter now also keeps them out of the line of the error object itself, see log-format.test.ts.
 	const line = formatLogLine({
 		timestamp: TIMESTAMP,
 		level: "error",

tests/unit/log-format.test.ts

@@ -33,48 +33,141 @@ test("ignores the symbol keys winston adds", () => {
 	assert.equal(formatLogLine(info), "2026-10-08 21:29:40.426Z info: hello ");
 });
 
-// Known defects: these assert the correct behaviour and fail today, which the todo marks as expected.
+// Fixed defects of https://git.librete.ch/libretech/mp/issues/67.
 
-test(
-	"does not throw on a circular reference",
-	{ todo: "JSON.stringify throws on a circular reference — https://git.librete.ch/libretech/mp/issues/67" },
-	() => {
-		const request: Record<string, unknown> = { method: "POST", path: "/v1/oauth2/token" };
-		request.self = request;
+test("does not throw on a circular reference", () => {
+	const request: Record<string, unknown> = { method: "POST", path: "/v1/oauth2/token" };
+	request.self = request;
 
-		assert.doesNotThrow(() => formatLogLine({ timestamp: TIMESTAMP, level: "error", message: "app:e:paypal-api", request }));
+	assert.doesNotThrow(() => formatLogLine({ timestamp: TIMESTAMP, level: "error", message: "app:e:paypal-api", request }));
+});
+
+test("does not write the Authorization header of an axios-like error into the line", () => {
+	const error = Object.assign(new Error("getaddrinfo EAI_AGAIN api-m.paypal.com"), {
+		name: "AxiosError",
+		code: "EAI_AGAIN",
+		config: { method: "post", url: "https://api-m.paypal.com/v1/oauth2/token", headers: { Authorization: `Basic ${CREDENTIALS}` } }
+	});
+	// What strapi.log.error(error) hands this formatter: Strapi's logErrors format spreads the error and appends its stack.
+	const line = formatLogLine({ ...error, message: `${error.message}\n${error.stack}`, level: "error", timestamp: TIMESTAMP });
+
+	assert.ok(!line.includes(CREDENTIALS), line);
+});
+
+test("renders an Error with its message instead of {}", () => {
+	const error = new Error("getaddrinfo EAI_AGAIN api-m.paypal.com");
+	// strapi.log.error("…", { error }), as in the order controller's capturePayment
+	const line = formatLogLine({
+		timestamp: TIMESTAMP,
+		level: "error",
+		message: "app:e:order-controller: Error capturing payment for order x",
+		error
+	});
+
+	assert.ok(line.includes("getaddrinfo EAI_AGAIN api-m.paypal.com"), line);
+});
+
+// Safe serialisation.
+
+const fieldsOf = (line: string) => JSON.parse(line.slice(line.indexOf("{")));
+
+test("redacts the fields named like a credential at any depth, whatever their case", () => {
+	const line = formatLogLine({
+		timestamp: TIMESTAMP,
+		level: "debug",
+		message: "app:d:test",
+		token: "A21AAF…",
+		request: {
+			method: "POST",
+			headers: { Authorization: `Basic ${CREDENTIALS}`, Cookie: "koa.sess=abc", "X-API-Key": "k1", "Content-Type": "application/json" },
+			body: { grant_type: "client_credentials", client_secret: "s3cr3t", user: { password: "hunter2", api_key: "k2", apikey: "k3" } },
+			responses: [{ headers: { "set-cookie": ["koa.sess=def"] }, data: { access_token: "A21AAG…", expires_in: 32400 } }]
+		}
+	});
+
+	assert.deepEqual(fieldsOf(line), {
+		token: "[redacted]",
+		request: {
+			method: "POST",
+			headers: { Authorization: "[redacted]", Cookie: "[redacted]", "X-API-Key": "[redacted]", "Content-Type": "application/json" },
+			body: {
+				grant_type: "client_credentials",
+				client_secret: "[redacted]",
+				user: { password: "[redacted]", api_key: "[redacted]", apikey: "[redacted]" }
+			},
+			responses: [{ headers: { "set-cookie": "[redacted]" }, data: { access_token: "[redacted]", expires_in: 32400 } }]
+		}
+	});
+});
+
+test("writes the other fields of an object that contains itself, and the reference to it as [Circular]", () => {
+	const request: Record<string, unknown> = { method: "POST", path: "/v1/oauth2/token" };
+	request.socket = { request, remoteAddress: "151.101.1.21" };
+	const line = formatLogLine({ timestamp: TIMESTAMP, level: "error", message: "app:e:paypal-api", request, list: [request] });
+
+	assert.deepEqual(fieldsOf(line), {
+		request: { method: "POST", path: "/v1/oauth2/token", socket: { request: "[Circular]", remoteAddress: "151.101.1.21" } },
+		list: [{ method: "POST", path: "/v1/oauth2/token", socket: { request: "[Circular]", remoteAddress: "151.101.1.21" } }]
+	});
+});
+
+test("writes an object that is referenced twice, but not by itself, both times", () => {
+	const delivery = { id: 1, price: 4.95 };
+
+	assert.deepEqual(fieldsOf(formatLogLine({ timestamp: TIMESTAMP, level: "info", message: "m", before: delivery, after: delivery })), {
+		before: { id: 1, price: 4.95 },
+		after: { id: 1, price: 4.95 }
+	});
+});
+
+test("writes an Error as its name and the first line of its message, and its stack only when asked", () => {
+	const error = Object.assign(new Error('The response did not match the response schema.\n\nGiven value: {"email_address":"erika@example.org"}'), {
+		request: { url: "https://api-m.paypal.com/v2/checkout/orders", headers: { Authorization: "Bearer A21AAF…" } },
+		statusCode: 201
+	});
+	const info = { timestamp: TIMESTAMP, level: "error", message: "app:e:paypal-api", error };
+
+	assert.deepEqual(fieldsOf(formatLogLine(info)), { error: { name: "Error", message: "The response did not match the response schema." } });
+	const withStack = fieldsOf(formatLogLine(info, { stack: true }));
+	assert.equal(withStack.error.stack, error.stack);
+	assert.deepEqual(Object.keys(withStack.error), ["name", "message", "stack"]);
+});
+
+test("writes an instance of a class without toJSON as its class name, so the headers a request object keeps stay out", () => {
+	class ClientRequest {
+		_header = `POST /v1/oauth2/token HTTP/1.1\r\nAuthorization: Basic ${CREDENTIALS}\r\n\r\n`;
+		method = "POST";
 	}
-);
+	const line = formatLogLine({ timestamp: TIMESTAMP, level: "error", message: "m", request: new ClientRequest(), seen: new Set([1]) });
 
-test(
-	"does not write the Authorization header of an axios-like error into the line",
-	{ todo: "the PayPal client credentials are logged — https://git.librete.ch/libretech/mp/issues/67" },
-	() => {
-		const error = Object.assign(new Error("getaddrinfo EAI_AGAIN api-m.paypal.com"), {
-			name: "AxiosError",
-			code: "EAI_AGAIN",
-			config: { method: "post", url: "https://api-m.paypal.com/v1/oauth2/token", headers: { Authorization: `Basic ${CREDENTIALS}` } }
-		});
-		// What strapi.log.error(error) hands this formatter: Strapi's logErrors format spreads the error and appends its stack.
-		const line = formatLogLine({ ...error, message: `${error.message}\n${error.stack}`, level: "error", timestamp: TIMESTAMP });
+	assert.deepEqual(fieldsOf(line), { request: "[ClientRequest]", seen: "[Set]" });
+	assert.ok(!line.includes(CREDENTIALS), line);
+});
 
-		assert.ok(!line.includes(CREDENTIALS), line);
+test("writes an instance of a class with toJSON as what toJSON returns, redacted", () => {
+	// Like axios's AxiosHeaders, which an axios error carries in config.headers.
+	class AxiosHeaders {
+		toJSON() {
+			return { Accept: "application/json", Authorization: `Basic ${CREDENTIALS}` };
+		}
 	}
-);
+	const at = new Date("2026-10-08T19:13:05.000Z");
+	const line = formatLogLine({ timestamp: TIMESTAMP, level: "error", message: "m", config: { headers: new AxiosHeaders() }, at });
 
-test(
-	"renders an Error with its message instead of {}",
-	{ todo: "an Error is rendered as {} — https://git.librete.ch/libretech/mp/issues/67" },
-	() => {
-		const error = new Error("getaddrinfo EAI_AGAIN api-m.paypal.com");
-		// strapi.log.error("…", { error }), as in the order controller's capturePayment
-		const line = formatLogLine({
-			timestamp: TIMESTAMP,
-			level: "error",
-			message: "app:e:order-controller: Error capturing payment for order x",
-			error
-		});
+	assert.deepEqual(fieldsOf(line), {
+		config: { headers: { Accept: "application/json", Authorization: "[redacted]" } },
+		at: "2026-10-08T19:13:05.000Z"
+	});
+});
 
-		assert.ok(line.includes("getaddrinfo EAI_AGAIN api-m.paypal.com"), line);
-	}
-);
+test("writes a bigint as its digits and a field that cannot be read as [unreadable]", () => {
+	const unreadable = {
+		get value() {
+			throw new Error("no");
+		}
+	};
+	// The PayPal SDK keeps an OAuth token's expiry as a bigint, which JSON.stringify throws on.
+	const line = formatLogLine({ timestamp: TIMESTAMP, level: "debug", message: "m", expiry: 1791587585n, unreadable });
+
+	assert.deepEqual(fieldsOf(line), { expiry: "1791587585", unreadable: "[unreadable]" });
+});