From ab071cd222be9f25fd5eaf511a4a89ea4e4f50c5 Mon Sep 17 00:00:00 2001 From: Michael Czechowski Date: Fri, 9 Oct 2026 01:41:34 +0200 Subject: [PATCH] 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 https://git.librete.ch/libretech/mp/issues/71 Refs https://git.librete.ch/libretech/mp/issues/67 --- src/logging/format.ts | 76 +++++++++++++++- tests/unit/log-error.test.ts | 2 +- tests/unit/log-format.test.ts | 167 ++++++++++++++++++++++++++-------- 3 files changed, 203 insertions(+), 42 deletions(-) diff --git a/src/logging/format.ts b/src/logging/format.ts index 693645a..254b264 100644 --- a/src/logging/format.ts +++ b/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: `Z : `. */ -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 ". +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 = {}; + for (const key of Object.keys(value)) { + const field = (value as Record)[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: `Z : `. 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}`; }; diff --git a/tests/unit/log-error.test.ts b/tests/unit/log-error.test.ts index 2407e96..fa9df96 100644 --- a/tests/unit/log-error.test.ts +++ b/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", diff --git a/tests/unit/log-format.test.ts b/tests/unit/log-format.test.ts index 5265264..2a567ea 100644 --- a/tests/unit/log-format.test.ts +++ b/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 = { method: "POST", path: "/v1/oauth2/token" }; - request.self = request; +test("does not throw on a circular reference", () => { + const request: Record = { 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 = { 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]" }); +});