diff --git a/apps/sim/lib/workflows/persistence/utils.ts b/apps/sim/lib/workflows/persistence/utils.ts index b3d9fc0d979..3d9c6a14ee5 100644 --- a/apps/sim/lib/workflows/persistence/utils.ts +++ b/apps/sim/lib/workflows/persistence/utils.ts @@ -295,7 +295,10 @@ export async function loadDeployedWorkflowState( await resolveWorkspaceId(workflowId, providedWorkspaceId) ) } catch (error) { - logger.error(`Error loading deployed workflow state ${workflowId}:`, error) + // An undeployed workflow is an outcome each caller handles, not a load failure. + if (!(error instanceof NoActiveDeploymentError)) { + logger.error(`Error loading deployed workflow state ${workflowId}:`, error) + } throw error } } diff --git a/packages/logger/src/index.test.ts b/packages/logger/src/index.test.ts index 0c47e916ca7..a48f79b97cd 100644 --- a/packages/logger/src/index.test.ts +++ b/packages/logger/src/index.test.ts @@ -188,4 +188,141 @@ describe('Logger', () => { expect(parsed.metadataError).toBe(true) }) }) + + describe('wrapped driver errors', () => { + const createEnabledLogger = () => + new Logger('Test', { enabled: true, colorize: false, logLevel: LogLevel.DEBUG }) + + /** + * Mirrors Drizzle's `DrizzleQueryError`: SQL plus bound values in the message, and `query`, + * `params` and `cause` as own enumerable properties, wrapping the driver error. + */ + const queryError = (params: string) => { + const cause = Object.assign(new Error('canceling statement due to statement timeout'), { + name: 'PostgresError', + code: '57014', + detail: `Key (email)=(${params}) already exists.`, + }) + const query = 'select "id" from "user_table_rows" where "table_id" = $1 limit $2' + const error = Object.assign(new Error(`Failed query: ${query}\nparams: ${params}`), { + query, + params: params.split(','), + cause, + }) + error.name = 'DrizzleQueryError' + return error + } + + const consoleOutput = () => + [...consoleLogSpy.mock.calls, ...consoleErrorSpy.mock.calls].flat().join(' ') + + test('names the deepest cause and its code on the line', () => { + createEnabledLogger().error('Failed to query rows:', { error: queryError('tbl_1,52') }) + + const parsed = JSON.parse(consoleErrorSpy.mock.calls[0][0] as string) + expect(parsed.errorCause).toBe('PostgresError: canceling statement due to statement timeout') + expect(parsed.errorCode).toBe('57014') + }) + + test('reports the cause of the same error the line reports when given two', () => { + const conflict = Object.assign(new Error('duplicate key value'), { + name: 'PostgresError', + code: '23505', + }) + const second = new Error('Failed query: insert into "t" values ($1)', { cause: conflict }) + + createEnabledLogger().error('Retry failed', queryError('tbl_1'), second) + + const parsed = JSON.parse(consoleErrorSpy.mock.calls[0][0] as string) + expect(parsed.error).toBe(second.message) + expect(parsed.errorCause).toBe('PostgresError: duplicate key value') + expect(parsed.errorCode).toBe('23505') + }) + + test.each([ + ['an object field', (error: Error) => [{ error }]], + ['a bare argument', (error: Error) => [error]], + ])('keeps bound values out of the message and stack when passed as %s', (_, args) => { + createEnabledLogger().error( + 'Failed to query rows:', + ...args(queryError('alice@example.com,52')) + ) + + const line = consoleErrorSpy.mock.calls[0][0] as string + expect(line).not.toContain('alice@example.com') + const parsed = JSON.parse(line) + expect(parsed.error).toContain('Failed query: select "id"') + expect(parsed.error).toContain('params: [redacted]') + expect(parsed.stack).toContain('params: [redacted]') + expect(parsed.stack).toMatch(/\n\s+at /) + }) + + test.each([ + ['under another key', (error: Error) => ({ dbError: error })], + ['nested inside metadata', (error: Error) => ({ details: { attempt: 2, error } })], + ])('keeps bound values out of an error logged %s', (_, arg) => { + createEnabledLogger().error('Insert failed', arg(queryError('alice@example.com'))) + + expect(consoleOutput()).not.toContain('alice@example.com') + }) + + test.each([ + ['an object field', (error: Error) => [{ error }]], + ['a bare argument', (error: Error) => [error]], + ['nested inside metadata', (error: Error) => [{ details: { error } }]], + ])('keeps bound values out of colorized output when passed as %s', (_, args) => { + new Logger('Test', { enabled: true, colorize: true, logLevel: LogLevel.DEBUG }).error( + 'Failed to query rows:', + ...args(queryError('alice@example.com')) + ) + + const output = consoleOutput() + expect(output).toContain('params: [redacted]') + expect(output).not.toContain('alice@example.com') + }) + + test.each([ + ['a bare argument', (error: Error) => [error]], + ['an object field', (error: Error) => [{ error }]], + ])('keeps bound values out of the exported log record when passed as %s', (_, args) => { + const emit = vi.fn() + const getLoggerSpy = vi + .spyOn(logs, 'getLogger') + .mockReturnValue({ emit, enabled: () => true }) + try { + createEnabledLogger().error( + 'Failed to query rows:', + ...args(queryError('alice@example.com')) + ) + + const { attributes } = emit.mock.calls[0][0] + expect(JSON.stringify(attributes)).not.toContain('alice@example.com') + expect(attributes['error.cause']).toBe( + 'PostgresError: canceling statement due to statement timeout' + ) + } finally { + getLoggerSpy.mockRestore() + } + }) + + test('emits a line for a nested error that references itself', () => { + const error = Object.assign(new Error('self-referencing failure'), { + context: {} as Record, + }) + error.context.error = error + + expect(() => createEnabledLogger().error('Failed', { details: { error } })).not.toThrow() + const parsed = JSON.parse(consoleErrorSpy.mock.calls[0][0] as string) + expect(parsed.details.error.message).toBe('self-referencing failure') + expect(parsed.details.error.context.error).toBe('[Circular]') + }) + + test('leaves an unwrapped error without cause fields', () => { + createEnabledLogger().error('Request failed', { error: new Error('plain failure') }) + + const parsed = JSON.parse(consoleErrorSpy.mock.calls[0][0] as string) + expect(parsed.error).toBe('plain failure') + expect(parsed).not.toHaveProperty('errorCause') + }) + }) }) diff --git a/packages/logger/src/index.ts b/packages/logger/src/index.ts index d13b7f47af0..304e070c5e3 100644 --- a/packages/logger/src/index.ts +++ b/packages/logger/src/index.ts @@ -5,6 +5,7 @@ * Provides standardized console logging with environment-aware configuration. */ import { logs, SeverityNumber } from '@opentelemetry/api-logs' +import { describeError, redactBoundParameters } from '@sim/utils/errors' import { filterUndefined, isRecordLike } from '@sim/utils/object' import chalk from 'chalk' import { getRequestContext, type RequestContext } from './request-context' @@ -131,55 +132,105 @@ const getLogConfig = () => { } } +interface LoggedError { + message: string + stack?: string + /** `"Name: message"` of the deepest `.cause` link, present only when the error wraps another. */ + cause?: string + code?: string + /** Whether the message carried a bound-parameter tail, marking the error as a query wrapper. */ + redacted: boolean +} + +/** + * The fields a log line keeps for an error. + * + * Drizzle's `DrizzleQueryError` appends `\nparams: ` — user data — to + * its message, and the stack repeats the message, so both are redacted. The + * wrapper's message is only the failing SQL; the reason (a statement timeout, a + * constraint violation) lives on the driver error in `.cause`, which no field + * would otherwise carry. + */ +const toLoggedError = (error: Error): LoggedError => { + const message = redactBoundParameters(error.message) + const stack = + error.stack === undefined || message === error.message + ? error.stack + : error.stack.includes(error.message) + ? error.stack.replace(error.message, () => message) + : redactBoundParameters(error.stack) + const described = describeError(error) + return { + message, + stack, + ...(described.causeChain ? { cause: `${described.name}: ${described.message}` } : {}), + ...(described.code ? { code: described.code } : {}), + redacted: message !== error.message, + } +} + /** * Renders an error as the plain object `JSON.stringify` cannot produce for it. * * `message`, `stack` and `name` are non-enumerable on `Error.prototype`, so a - * plain stringify emits `{}`. Own enumerable properties are copied too — driver - * and HTTP errors carry the useful part (`code`, `status`) there. + * plain stringify emits `{}` — or, for an error with own enumerable properties, + * only those. Own properties are copied because driver and HTTP errors carry the + * useful part (`code`, `status`) there, except what `toLoggedError` replaces: a + * query wrapper's `params` holds the redacted values, and a summarized `cause` + * would carry the driver's `detail`. */ -const errorToPlainObject = (error: Error, isDev: boolean): Record => { - const errorObj: Record = { - message: error.message, - stack: isDev ? error.stack : undefined, +const toPlainError = (error: Error, includeStack: boolean): Record => { + const logged = toLoggedError(error) + const plain: Record = { + message: logged.message, + stack: includeStack ? logged.stack : undefined, name: error.name, + ...(logged.cause ? { cause: logged.cause } : {}), + ...(logged.code ? { code: logged.code } : {}), } for (const key of Object.keys(error)) { - if (!(key in errorObj)) { - errorObj[key] = (error as unknown as Record)[key] - } + if (key in plain || (logged.redacted && key === 'params')) continue + plain[key] = (error as unknown as Record)[key] } - return errorObj + return plain } -/** - * Format objects for logging - * - * Errors held under a key are unwrapped as well as bare ones — `{ error }` is - * the common call shape, and it would otherwise print as `{"error":{}}`. - */ +/** JSON replacer that serializes every `Error`, however deeply nested, as its plain form. */ +const errorReplacer = + (includeStack: boolean) => + (_key: string, value: unknown): unknown => + value instanceof Error ? toPlainError(value, includeStack) : value + +/** Format objects for logging. */ const formatObject = (obj: unknown, isDev: boolean): string => { try { - if (obj instanceof Error) { - return JSON.stringify(errorToPlainObject(obj, isDev), null, isDev ? 2 : 0) - } - if (isRecordLike(obj)) { - let unwrapped: Record | undefined - for (const [key, value] of Object.entries(obj as Record)) { - if (!(value instanceof Error)) continue - unwrapped ??= { ...(obj as Record) } - unwrapped[key] = errorToPlainObject(value, isDev) - } - if (unwrapped) { - return JSON.stringify(unwrapped, null, isDev ? 2 : 0) - } - } - return JSON.stringify(obj, null, isDev ? 2 : 0) + return JSON.stringify(obj, errorReplacer(isDev), isDev ? 2 : 0) } catch { return '[Circular or Non-Serializable Object]' } } +/** + * The error a line is about, chosen as `mergeArgs` chooses it: the last bare + * `Error` argument, else the first `{ error }` field. + */ +const primaryError = (args: unknown[]): Error | undefined => { + for (let i = args.length - 1; i >= 0; i--) { + const arg = args[i] + if (arg instanceof Error) return arg + } + for (const arg of args) { + if (isRecordLike(arg) && arg.error instanceof Error) return arg.error + } + return undefined +} + +/** Adds an error's cause fields to the entry without displacing caller-supplied values. */ +const assignErrorCause = (entry: Record, logged: LoggedError) => { + if (logged.cause !== undefined && entry.errorCause === undefined) entry.errorCause = logged.cause + if (logged.code !== undefined && entry.errorCode === undefined) entry.errorCode = logged.code +} + /** * Merges caller-supplied log arguments into the structured entry. * @@ -188,23 +239,28 @@ const formatObject = (obj: unknown, isDev: boolean): string => { * is by far the most common call shape, which would otherwise reduce the one * field worth reading to an empty object. Errors nested in an object argument * are therefore unwrapped like a bare `Error` argument. `error` stays a plain - * message string so log queries can group on it; richer diagnostics are opt-in - * via `describeError` from `@sim/utils/errors`. + * message string so log queries can group on it; the primary error's deepest + * cause and its code go in `errorCause` and `errorCode`. */ const mergeArgs = (entry: Record, args: unknown[]): Record => { + /** The error whose stack the line carries; its cause is assigned last so a later error cannot inherit an earlier one's. */ + let reported: LoggedError | undefined for (const arg of args) { if (arg === null || arg === undefined) continue if (arg instanceof Error) { - entry.error = arg.message - entry.stack = arg.stack + reported = toLoggedError(arg) + entry.error = reported.message + entry.stack = reported.stack } else if (typeof arg === 'object') { const source = arg as Record for (const key of Object.keys(source)) { const value = source[key] if (value instanceof Error) { - entry[key] = value.message + const logged = toLoggedError(value) + entry[key] = logged.message if (key === 'error' && entry.stack === undefined) { - entry.stack = value.stack + entry.stack = logged.stack + reported = logged } } else { entry[key] = value @@ -214,12 +270,18 @@ const mergeArgs = (entry: Record, args: unknown[]): Record { const ancestors: object[] = [] + /** What `JSON.stringify` descends into for each ancestor — an error's plain form, not the error. */ + const holders: object[] = [] return function (this: unknown, _key: string, value: unknown): unknown { if (typeof value === 'bigint') return value.toString() if (value === null || typeof value !== 'object') return value @@ -230,10 +292,15 @@ const tolerantReplacer = () => { * appearance of a merely repeated reference `[Circular]` and discard real * data, since a payload that references one object twice has no cycle. */ - while (ancestors.length > 0 && ancestors[ancestors.length - 1] !== this) ancestors.pop() + while (holders.length > 0 && holders[holders.length - 1] !== this) { + holders.pop() + ancestors.pop() + } if (ancestors.includes(value)) return '[Circular]' + const serialized = value instanceof Error ? toPlainError(value, false) : value ancestors.push(value) - return value + holders.push(serialized) + return serialized } } @@ -247,7 +314,7 @@ const tolerantReplacer = () => { */ const serializeEntry = (base: Record, args: unknown[]): string => { try { - return JSON.stringify(mergeArgs({ ...base }, args)) + return JSON.stringify(mergeArgs({ ...base }, args), errorReplacer(false)) } catch {} try { @@ -583,15 +650,20 @@ function emitOtelLogRecord( for (const [key, value] of Object.entries(filterUndefined(metadata))) { attributes[key] = String(value) } - const firstError = args.find((arg) => arg instanceof Error) as Error | undefined - if (firstError) { - attributes['error.message'] = firstError.message - if (firstError.stack) attributes['error.stack'] = firstError.stack + const error = primaryError(args) + if (error) { + const logged = toLoggedError(error) + attributes['error.message'] = logged.message + if (logged.stack) attributes['error.stack'] = logged.stack + if (logged.cause) attributes['error.cause'] = logged.cause } const plainArgs = args.filter((arg) => !(arg instanceof Error)) if (plainArgs.length > 0) { try { - attributes['log.args'] = JSON.stringify(plainArgs).slice(0, OTEL_LOG_ARG_MAX_CHARS) + attributes['log.args'] = JSON.stringify(plainArgs, errorReplacer(false)).slice( + 0, + OTEL_LOG_ARG_MAX_CHARS + ) } catch { attributes['log.args'] = String(plainArgs).slice(0, OTEL_LOG_ARG_MAX_CHARS) }