diff --git a/apps/webapp/app/services/logger.server.ts b/apps/webapp/app/services/logger.server.ts index 15b248f0d9..517a03b7e4 100644 --- a/apps/webapp/app/services/logger.server.ts +++ b/apps/webapp/app/services/logger.server.ts @@ -1,5 +1,5 @@ import type { LogLevel } from "@trigger.dev/core/logger"; -import { Logger } from "@trigger.dev/core/logger"; +import { Logger, redact } from "@trigger.dev/core/logger"; import { patchConsoleToTelnet, startTelnetLogServer } from "@trigger.dev/core/v3/telnetLogServer"; import { sensitiveDataReplacer } from "./sensitiveDataReplacer"; import { AsyncLocalStorage } from "async_hooks"; @@ -12,24 +12,40 @@ export function trace(fields: Record, fn: () => T): T { return currentFieldsStore.run(fields, fn); } +// The keys below aren't already in the Logger's default deny-list. Passing them here means the +// extra data sent to Sentry gets the same redaction as the stdout line, instead of bypassing it. +const SENTRY_EXTRA_FILTERED_KEYS = ["examples", "connectionString"]; + Logger.onError = (message, ...args) => { const error = extractErrorFromArgs(args); + const extra = redact(flattenArgs(args), SENTRY_EXTRA_FILTERED_KEYS) as Record; if (error) { - captureException(error, { + captureException(redactError(error), { extra: { message, - ...flattenArgs(args), + ...extra, }, }); } else { captureMessage(message, { level: "error", - extra: flattenArgs(args), + extra, }); } }; +function redactError(error: Error): Error { + const redactedError = new Error(redact(error.message) as string); + redactedError.name = error.name; + + if (error.stack) { + redactedError.stack = redact(error.stack) as string; + } + + return redactedError; +} + function extractErrorFromArgs(args: Array | undefined>) { for (const arg of args) { if (arg && "error" in arg && arg.error instanceof Error) { diff --git a/apps/webapp/test/logger.server.onError.test.ts b/apps/webapp/test/logger.server.onError.test.ts new file mode 100644 index 0000000000..4aebabe6ac --- /dev/null +++ b/apps/webapp/test/logger.server.onError.test.ts @@ -0,0 +1,69 @@ +import { beforeEach, describe, expect, it, vi } from "vitest"; + +const captureExceptionMock = vi.fn(); +const captureMessageMock = vi.fn(); + +vi.mock("@sentry/remix", () => ({ + captureException: captureExceptionMock, + captureMessage: captureMessageMock, +})); + +describe("logger.server Logger.onError", () => { + beforeEach(() => { + captureExceptionMock.mockClear(); + captureMessageMock.mockClear(); + vi.spyOn(console, "error").mockImplementation(() => {}); + }); + + it("redacts the extra payload sent to Sentry on the captureMessage path", async () => { + const { logger } = await import("~/services/logger.server"); + + logger.error("something failed", { + payload: { secret: "do-not-leak" }, + apiKey: "tr_prod_should_not_leak", + }); + + expect(captureMessageMock).toHaveBeenCalledTimes(1); + const [, options] = captureMessageMock.mock.calls[0] as [string, { extra: unknown }]; + + expect(JSON.stringify(options.extra)).not.toContain("do-not-leak"); + expect(JSON.stringify(options.extra)).not.toContain("tr_prod_should_not_leak"); + }); + + it("redacts the exception and extra payload sent to Sentry", async () => { + const { logger } = await import("~/services/logger.server"); + const error = new Error("tr_prod_should_not_leak"); + error.stack = "Bearer secret-token"; + + logger.error("boom", { + error, + payload: { secret: "do-not-leak" }, + }); + + expect(captureExceptionMock).toHaveBeenCalledTimes(1); + const [capturedError, options] = captureExceptionMock.mock.calls[0] as [ + Error, + { extra: unknown }, + ]; + + expect(capturedError).not.toBe(error); + expect(capturedError.message).not.toContain("tr_prod_should_not_leak"); + expect(capturedError.stack).not.toContain("secret-token"); + expect(JSON.stringify(options.extra)).not.toContain("do-not-leak"); + }); + + it("still forwards non-sensitive extra fields", async () => { + const { logger } = await import("~/services/logger.server"); + + logger.error("something failed", { runId: "run_123", keep: "this stays" }); + + expect(captureMessageMock).toHaveBeenCalledTimes(1); + const [, options] = captureMessageMock.mock.calls[0] as [ + string, + { extra: Record }, + ]; + + expect(options.extra.runId).toBe("run_123"); + expect(options.extra.keep).toBe("this stays"); + }); +}); diff --git a/packages/core/src/logger.ts b/packages/core/src/logger.ts index 18ef4634a9..f3e51aef0e 100644 --- a/packages/core/src/logger.ts +++ b/packages/core/src/logger.ts @@ -16,10 +16,53 @@ export type LogLevel = "log" | "error" | "warn" | "info" | "debug" | "verbose"; const logLevels: Array = ["log", "error", "warn", "info", "debug", "verbose"]; +// Applied to every Logger instance, on top of whatever a caller passes in as `filteredKeys`. +// Keeps the previous "opt-in, per-instance" list from being the only thing standing between a +// logged object and a credential or piece of customer content that happens to share its name. +const DEFAULT_FILTERED_KEYS = [ + "authorization", + "token", + "apikey", + "secretkey", + "accesstoken", + "refreshtoken", + "password", + "jwt", + "payload", + "output", + "metadata", + "seedmetadata", + "input", + "email", + "headers", + "completedwaitpoints", +]; + +// Belt-and-braces value-shape check: catches secrets anywhere in values that land under a field +// name we didn't think to deny-list (a trigger.dev API key, bearer token, or OpenAI-style key). +const SECRET_VALUE_PATTERN = /(tr_[a-zA-Z0-9_-]{4,}|sk-[a-zA-Z0-9_-]{4,}|Bearer\s+\S+)/; + +// Per-field and per-structure caps so a single unbounded object (a run payload, a batch of +// items, a DB row) can't blow up log line size or CPU. Truncation keeps the field present and +// queryable rather than dropping it. +const MAX_STRING_LENGTH = 8192; +const MAX_ARRAY_LENGTH = 100; +const MAX_DEPTH = 10; + +function buildFilteredKeySet(filteredKeys: string[]): Set { + const set = new Set(DEFAULT_FILTERED_KEYS); + + for (const key of filteredKeys) { + set.add(key.toLowerCase()); + } + + return set; +} + export class Logger { #name: string; readonly #level: number; - #filteredKeys: string[] = []; + #filteredKeys: Set = new Set(DEFAULT_FILTERED_KEYS); #jsonReplacer?: (key: string, value: unknown) => unknown; #additionalFields: () => Record; @@ -39,7 +82,7 @@ export class Logger { ) { this.#name = name; this.#level = logLevels.indexOf((env.TRIGGER_LOG_LEVEL ?? level) as LogLevel); - this.#filteredKeys = filteredKeys; + this.#filteredKeys = buildFilteredKeySet(filteredKeys); this.#jsonReplacer = createReplacer(jsonReplacer); this.#additionalFields = additionalFields ?? (() => ({})); } @@ -48,7 +91,7 @@ export class Logger { return new Logger( this.#name, logLevels[this.#level], - this.#filteredKeys, + Array.from(this.#filteredKeys), this.#jsonReplacer, () => ({ ...this.#additionalFields(), ...fields }) ); @@ -115,8 +158,8 @@ export class Logger { // Get the current context from trace if it exists const currentSpan = trace.getSpan(context.active()); - const structuredError = extractStructuredErrorFromArgs(...args); - const structuredMessage = extractStructuredMessageFromArgs(...args); + const structuredError = extractStructuredErrorFromArgs(this.#filteredKeys, ...args); + const structuredMessage = extractStructuredMessageFromArgs(this.#filteredKeys, ...args); const structuredLog = { ...structureArgs(safeJsonClone(args) as Record[], this.#filteredKeys), @@ -153,38 +196,52 @@ export class Logger { // Detect if args is an error object // Or if args contains an error object at the "error" key // In both cases, return the error object as a structured error -function extractStructuredErrorFromArgs(...args: Array | undefined>) { - const error = args.find((arg) => arg instanceof Error) as Error | undefined; +// Run every field through the same filter/truncation used for the rest of the log line, so an +// error's message/stack/metadata (which can embed request or row data verbatim) gets the same +// treatment as everything else, instead of bypassing it. +function extractStructuredErrorFromArgs( + filteredKeys: Set, + ...args: Array | undefined> +) { + const error = args.find((arg) => arg instanceof Error) as + | (Error & { metadata?: unknown }) + | undefined; if (error) { return { - message: error.message, - stack: error.stack, + message: filterKeys(error.message, filteredKeys), + stack: filterKeys(error.stack, filteredKeys), name: error.name, - metadata: "metadata" in error ? error.metadata : undefined, + metadata: "metadata" in error ? filterKeys(error.metadata, filteredKeys) : undefined, }; } const structuredError = args.find((arg) => arg?.error); if (structuredError && structuredError.error instanceof Error) { + const nestedError = structuredError.error as Error & { metadata?: unknown }; + return { - message: structuredError.error.message, - stack: structuredError.error.stack, - name: structuredError.error.name, - metadata: "metadata" in structuredError.error ? structuredError.error.metadata : undefined, + message: filterKeys(nestedError.message, filteredKeys), + stack: filterKeys(nestedError.stack, filteredKeys), + name: nestedError.name, + metadata: + "metadata" in nestedError ? filterKeys(nestedError.metadata, filteredKeys) : undefined, }; } return; } -function extractStructuredMessageFromArgs(...args: Array | undefined>) { +function extractStructuredMessageFromArgs( + filteredKeys: Set, + ...args: Array | undefined> +) { // Check to see if there is a `message` key in the args, and if so, return it const structuredMessage = args.find((arg) => arg?.message); if (structuredMessage) { - return structuredMessage.message; + return filterKeys(structuredMessage.message, filteredKeys); } return; @@ -221,37 +278,65 @@ function safeJsonClone(obj: unknown) { } } -// If args is has a single item that is an object, return that object -function structureArgs(args: Array>, filteredKeys: string[] = []) { - if (!args) { +// `args` has already been through safeJsonClone, so this only has to filter/truncate it, not +// clone it again. If there's exactly one arg, return it directly (unwrapped) so it can be spread +// onto the structured log; otherwise filter every arg and return the array. Filtering runs +// regardless of arg count, so a multi-arg call gets the same redaction as the common single-arg +// case. +function structureArgs( + args: Array> | undefined, + filteredKeys: Set = new Set() +) { + if (!args || args.length === 0) { return; } - if (args.length === 0) { - return; - } + const filteredArgs = args.map((arg) => filterKeys(arg, filteredKeys)); - if (args.length === 1 && typeof args[0] === "object") { - return filterKeys(JSON.parse(JSON.stringify(args[0], bigIntReplacer)), filteredKeys); + if (filteredArgs.length === 1) { + return filteredArgs[0]; } - return args; + return filteredArgs; } -// Recursively filter out keys from an object, including nested objects, and arrays -function filterKeys(obj: unknown, keys: string[]): any { +// Recursively filter out keys from an object, including nested objects and arrays. Also caps +// string length, array length and recursion depth, and redacts string values that look like a +// secret regardless of which key they were found under. +function filterKeys(obj: unknown, keys: Set, depth = 0): any { + if (typeof obj === "string") { + if (SECRET_VALUE_PATTERN.test(obj)) { + return `[filtered ${prettyPrintBytes(obj)}]`; + } + + return truncateString(obj); + } + if (typeof obj !== "object" || obj === null) { return obj; } + if (depth >= MAX_DEPTH) { + return "[max depth exceeded]"; + } + if (Array.isArray(obj)) { - return obj.map((item) => filterKeys(item, keys)); + const isTruncated = obj.length > MAX_ARRAY_LENGTH; + const items = (isTruncated ? obj.slice(0, MAX_ARRAY_LENGTH) : obj).map((item) => + filterKeys(item, keys, depth + 1) + ); + + if (isTruncated) { + items.push(`[truncated ${obj.length - MAX_ARRAY_LENGTH} more items]`); + } + + return items; } const filteredObj: any = {}; for (const [key, value] of Object.entries(obj)) { - if (keys.includes(key)) { + if (keys.has(key.toLowerCase())) { if (value) { filteredObj[key] = `[filtered ${prettyPrintBytes(value)}]`; } else { @@ -260,12 +345,29 @@ function filterKeys(obj: unknown, keys: string[]): any { continue; } - filteredObj[key] = filterKeys(value, keys); + filteredObj[key] = filterKeys(value, keys, depth + 1); } return filteredObj; } +function truncateString(value: string): string { + if (value.length <= MAX_STRING_LENGTH) { + return value; + } + + return `${value.slice(0, MAX_STRING_LENGTH)}...[truncated ${ + value.length - MAX_STRING_LENGTH + } chars]`; +} + +// Runs a value through the same default-deny-list + truncation pipeline every Logger applies to +// its own log lines. For destinations that receive log arguments through a side channel (e.g. an +// error reporting `onError` hook) rather than through `Logger#structuredLog` itself. +export function redact(value: unknown, filteredKeys: string[] = []): unknown { + return filterKeys(value, buildFilteredKeySet(filteredKeys)); +} + function prettyPrintBytes(value: unknown): string { if (env.NODE_ENV === "production") { return "skipped size"; diff --git a/packages/core/src/v3/utils/structuredLogger.ts b/packages/core/src/v3/utils/structuredLogger.ts index c85d92a860..e72cbfef47 100644 --- a/packages/core/src/v3/utils/structuredLogger.ts +++ b/packages/core/src/v3/utils/structuredLogger.ts @@ -1,3 +1,5 @@ +import { redact } from "../../logger.js"; + type StructuredArgs = (Record | undefined)[]; export interface StructuredLogger { @@ -88,14 +90,14 @@ export class SimpleStructuredLogger implements StructuredLogger { level: string, ...args: StructuredArgs ) { - const structuredLog = { + const structuredLog = redact({ timestamp: new Date(), message, $name: this.name, $level: level, ...this.fields, ...(args.length === 1 ? args[0] : args), - }; + }) as Record; if (SimpleStructuredLogger.onLog) { try { diff --git a/packages/core/test/logger.test.ts b/packages/core/test/logger.test.ts new file mode 100644 index 0000000000..94930acea2 --- /dev/null +++ b/packages/core/test/logger.test.ts @@ -0,0 +1,211 @@ +import { Logger, redact } from "../src/logger.js"; +import { SimpleStructuredLogger } from "../src/v3/utils/structuredLogger.js"; + +function captureLogLine(fn: () => void): Record { + const spy = vi.spyOn(console, "info").mockImplementation(() => {}); + + try { + fn(); + expect(spy).toHaveBeenCalledTimes(1); + const [line] = spy.mock.calls[0] as [string]; + return JSON.parse(line); + } finally { + spy.mockRestore(); + } +} + +function captureErrorLogLine(fn: () => void): Record { + const spy = vi.spyOn(console, "error").mockImplementation(() => {}); + + try { + fn(); + expect(spy).toHaveBeenCalledTimes(1); + const [line] = spy.mock.calls[0] as [string]; + return JSON.parse(line); + } finally { + spy.mockRestore(); + } +} + +describe("Logger redaction", () => { + it("redacts default deny-listed keys without any caller-supplied filteredKeys", () => { + const logger = new Logger("test", "info"); + + const line = captureLogLine(() => + logger.info("run started", { + payload: { secret: "value" }, + apiKey: "tr_prod_should_not_appear", + harmless: "keep me", + }) + ); + + expect(line.payload).toMatch(/^\[filtered/); + expect(line.apiKey).toMatch(/^\[filtered/); + expect(line.harmless).toBe("keep me"); + expect(JSON.stringify(line)).not.toContain("tr_prod_should_not_appear"); + }); + + it("matches deny-listed keys case-insensitively", () => { + const logger = new Logger("test", "info"); + + const line = captureLogLine(() => + logger.info("case check", { + ApiKey: "tr_prod_secret", + AUTHORIZATION: "Bearer abc123", + }) + ); + + expect(line.ApiKey).toMatch(/^\[filtered/); + expect(line.AUTHORIZATION).toMatch(/^\[filtered/); + }); + + it("recurses into nested objects and arrays", () => { + const logger = new Logger("test", "info"); + + const line = captureLogLine(() => + logger.info("nested check", { + run: { + items: [{ metadata: { token: "abc" } }, { metadata: { token: "def" } }], + }, + }) + ); + + for (const item of line.run.items) { + expect(item.metadata).toMatch(/^\[filtered/); + } + }); + + it("still honors caller-supplied filteredKeys in addition to the defaults", () => { + const logger = new Logger("test", "info", ["connectionString"]); + + const line = captureLogLine(() => + logger.info("db check", { connectionString: "postgres://user:pass@host/db" }) + ); + + expect(line.connectionString).toMatch(/^\[filtered/); + }); + + it("filters every argument, not only a single object argument", () => { + const logger = new Logger("test", "info"); + + const line = captureLogLine(() => + logger.info("two args", { first: "ok" }, { apiKey: "tr_prod_secret_value" }) + ); + + expect(JSON.stringify(line)).not.toContain("tr_prod_secret_value"); + }); + + it("redacts values that contain a secret even under a non-denied key", () => { + const logger = new Logger("test", "info"); + + const line = captureLogLine(() => + logger.info("value pattern check", { + someRandomField: "request failed with tr_live_abcdef123456", + anotherField: "authorization used Bearer some.jwt.value", + normalField: "just some text", + }) + ); + + expect(line.someRandomField).toMatch(/^\[filtered/); + expect(line.anotherField).toMatch(/^\[filtered/); + expect(line.normalField).toBe("just some text"); + }); + + it("redacts a structured message before assigning it to $message", () => { + const logger = new Logger("test", "info"); + + const line = captureLogLine(() => + logger.info("structured message check", { + message: "request failed with Bearer secret.jwt.value", + }) + ); + + expect(line.$message).toMatch(/^\[filtered/); + expect(JSON.stringify(line)).not.toContain("secret.jwt.value"); + }); + + it("truncates strings longer than the per-field cap", () => { + const logger = new Logger("test", "info"); + const longValue = "a".repeat(20_000); + + const line = captureLogLine(() => logger.info("truncation check", { longValue })); + + expect(line.longValue.length).toBeLessThan(longValue.length); + expect(line.longValue).toContain("[truncated"); + }); + + it("truncates arrays longer than the max array length", () => { + const logger = new Logger("test", "info"); + const bigArray = Array.from({ length: 500 }, (_, i) => i); + + const line = captureLogLine(() => logger.info("array truncation check", { bigArray })); + + expect(line.bigArray.length).toBeLessThan(bigArray.length); + expect(line.bigArray[line.bigArray.length - 1]).toContain("truncated"); + }); + + it("runs error metadata through the same key-based redaction as everything else", () => { + const logger = new Logger("test", "info"); + + const error = new Error("a plain failure message") as Error & { metadata?: unknown }; + error.metadata = { apiKey: "tr_prod_should_not_leak" }; + + const line = captureErrorLogLine(() => logger.error("boom", { error })); + + expect(line.error.message).toBe("a plain failure message"); + expect(line.error.metadata.apiKey).toMatch(/^\[filtered/); + expect(JSON.stringify(line)).not.toContain("tr_prod_should_not_leak"); + }); + + it("redacts an error message whose entire value is a bare secret", () => { + const logger = new Logger("test", "info"); + + const error = new Error("tr_prod_secret_value_leaked"); + + const line = captureErrorLogLine(() => logger.error("boom", { error })); + + expect(line.error.message).toMatch(/^\[filtered/); + }); +}); + +describe("SimpleStructuredLogger redaction", () => { + it("redacts fields and arguments with the default deny-list", () => { + const logger = new SimpleStructuredLogger("test"); + + const line = captureLogLine(() => + logger.child({ headers: { authorization: "Bearer should-not-appear" } }).info("run started", { + payload: { secret: "value" }, + apiKey: "tr_prod_should_not_appear", + harmless: "keep me", + }) + ); + + expect(line.headers).toMatch(/^\[filtered/); + expect(line.payload).toMatch(/^\[filtered/); + expect(line.apiKey).toMatch(/^\[filtered/); + expect(line.harmless).toBe("keep me"); + expect(JSON.stringify(line)).not.toContain("should-not-appear"); + }); +}); + +describe("redact()", () => { + it("applies the same default deny-list and truncation as the Logger", () => { + const result = redact({ + apiKey: "tr_prod_secret_value", + email: "user@example.com", + keep: "this stays", + }) as Record; + + expect(result.apiKey).toMatch(/^\[filtered/); + expect(result.email).toMatch(/^\[filtered/); + expect(result.keep).toBe("this stays"); + }); + + it("merges in caller-supplied filteredKeys", () => { + const result = redact({ connectionString: "postgres://user:pass@host/db" }, [ + "connectionString", + ]) as Record; + + expect(result.connectionString).toMatch(/^\[filtered/); + }); +});