diff --git a/supabase/functions/_backend/plugin_runtime/utils/pg.ts b/supabase/functions/_backend/plugin_runtime/utils/pg.ts index f1711c4e57..e56d002432 100644 --- a/supabase/functions/_backend/plugin_runtime/utils/pg.ts +++ b/supabase/functions/_backend/plugin_runtime/utils/pg.ts @@ -449,53 +449,322 @@ export function getDrizzleClient(db: PluginPgClient, options?: { logger?: boolea return drizzle({ client: db, logger: options?.logger ?? true }) } -// Helper to extract detailed error information from pg errors -export function logPgError(c: Context, functionName: string, error: unknown) { - const e = error as Error & { - code?: string - errno?: number - syscall?: string - address?: string - port?: number - severity?: string - detail?: string - hint?: string - position?: string - routine?: string - file?: string - line?: string - column?: string +const POSTGRES_ERROR_FIELDS = [ + // PostgreSQL server errors (node-postgres DatabaseError) + 'severity', + 'code', + 'detail', + 'hint', + 'position', + 'internalPosition', + 'internalQuery', + 'where', + 'schema', + 'table', + 'column', + 'dataType', + 'constraint', + 'file', + 'line', + 'routine', + + // Network, socket, and TLS errors + 'errno', + 'syscall', + 'address', + 'port', + 'host', + 'hostname', + 'library', + 'function', + 'reason', + 'opensslErrorStack', + + // Driver/runtime errors + 'status', + 'statusCode', + 'command', + 'query', +] as const + +const MAX_POSTGRES_ERROR_CAUSE_DEPTH = 8 +const MAX_POSTGRES_LOG_VALUE_DEPTH = 4 +const MAX_POSTGRES_LOG_ARRAY_ITEMS = 50 +const MAX_POSTGRES_LOG_OBJECT_KEYS = 50 +const POSTGRES_LOG_REDACTED_KEYS = new Set(['bindings', 'parameters', 'params', 'values']) +const POSTGRES_LOG_UNSAFE_KEYS = new Set(['__proto__', 'constructor', 'prototype']) + +function redactPostgresLogText(value: string): string { + return value.replace(/(^|[\r\n])params:[^\r\n]*/gi, '$1params: [redacted]') +} + +function describeThrownValue(value: unknown): string { + if (typeof value === 'string') + return redactPostgresLogText(value) + if (value === null || value === undefined || typeof value === 'number' || typeof value === 'boolean' || typeof value === 'bigint' || typeof value === 'symbol') + return String(value) + return 'object thrown' +} + +function readErrorProperty(error: object, key: PropertyKey): unknown { + try { + const descriptor = Object.getOwnPropertyDescriptor(error, key) + if (!descriptor) + return undefined + if ('value' in descriptor) + return descriptor.value + return '[accessor property omitted]' + } + catch (propertyError) { + return `[unreadable property: ${describeThrownValue(propertyError)}]` + } +} + +function getObjectType(value: object): string { + if (Array.isArray(value)) + return 'Array' + if (value instanceof AggregateError) + return 'AggregateError' + if (value instanceof Error) + return 'Error' + if (typeof value === 'function') + return 'Function' + return 'Object' +} + +function getLogArrayLength(value: unknown[]): number { + const length = readErrorProperty(value, 'length') + return typeof length === 'number' && Number.isSafeInteger(length) && length > 0 + ? length + : 0 +} + +function serializePostgresLogArray( + value: unknown[], + seen: WeakSet, + depth: number, +): unknown[] { + const totalLength = getLogArrayLength(value) + const boundedLength = Math.min(totalLength, MAX_POSTGRES_LOG_ARRAY_ITEMS) + const serialized: unknown[] = [] + for (let index = 0; index < boundedLength; index++) + serialized.push(serializePostgresLogValue(readErrorProperty(value, index), seen, depth + 1)) + + if (totalLength > boundedLength) + serialized.push(`[truncated ${totalLength - boundedLength} items]`) + return serialized +} + +function serializePostgresLogObject( + value: object, + seen: WeakSet, + depth: number, +): unknown { + let keys: string[] + try { + keys = Object.keys(value) + } + catch (keyError) { + return `[unreadable object: ${describeThrownValue(keyError)}]` + } + + // A null-prototype record plus explicit unsafe-key filtering prevents + // attacker-controlled diagnostic keys from invoking `__proto__` setters + // here or in less defensive downstream log processors. + const serialized: Record = Object.create(null) + const blockedKeys: string[] = [] + for (const key of keys.slice(0, MAX_POSTGRES_LOG_OBJECT_KEYS)) { + if (POSTGRES_LOG_UNSAFE_KEYS.has(key.toLowerCase())) { + blockedKeys.push(key) + continue + } + // Structured query objects can carry bound values under these keys. + // Keep the query text and shape, but never copy parameter values to logs. + serialized[key] = POSTGRES_LOG_REDACTED_KEYS.has(key.toLowerCase()) + ? '[redacted]' + : serializePostgresLogValue(readErrorProperty(value, key), seen, depth + 1) + } + + if (keys.length > MAX_POSTGRES_LOG_OBJECT_KEYS) + serialized.__truncatedKeys = keys.length - MAX_POSTGRES_LOG_OBJECT_KEYS + if (blockedKeys.length) + serialized.__blockedKeys = blockedKeys + + return serialized +} + +function serializePostgresLogValue( + value: unknown, + seen = new WeakSet(), + depth = 0, +): unknown { + if (typeof value === 'string') + return redactPostgresLogText(value) + if (typeof value === 'bigint') + return value.toString() + if (typeof value === 'symbol') + return value.toString() + if (typeof value === 'function') { + const functionName = readErrorProperty(value, 'name') + return `[function ${typeof functionName === 'string' && functionName ? functionName : 'anonymous'}]` + } + if (value === null || typeof value !== 'object') + return value + + if (seen.has(value)) + return '[circular]' + if (depth >= MAX_POSTGRES_LOG_VALUE_DEPTH) + return `[truncated ${getObjectType(value)}]` + + seen.add(value) + try { + return Array.isArray(value) + ? serializePostgresLogArray(value, seen, depth) + : serializePostgresLogObject(value, seen, depth) + } + catch (serializationError) { + return `[unserializable ${getObjectType(value)}: ${describeThrownValue(serializationError)}]` + } + finally { + seen.delete(value) + } +} + +function serializePostgresAggregateErrors( + aggregateErrors: unknown[], + seen: WeakSet, + depth: number, +): Record[] { + const totalLength = getLogArrayLength(aggregateErrors) + const boundedLength = Math.min(totalLength, MAX_POSTGRES_LOG_ARRAY_ITEMS) + const errors: Record[] = [] + for (let index = 0; index < boundedLength; index++) { + errors.push(serializePostgresError( + readErrorProperty(aggregateErrors, index), + seen, + depth + 1, + )) + } + if (totalLength > boundedLength) { + errors.push({ + type: 'truncated', + omitted: totalLength - boundedLength, + }) + } + return errors +} + +/** + * Serialize the complete Drizzle/node-postgres cause chain for Cloudflare logs. + * + * Error fields such as `code`, `severity`, and `routine` are not reliably + * enumerable, while Drizzle wraps the original driver error in `cause`. Read + * both explicitly so transient replica/Hyperdrive failures retain their + * PostgreSQL SQLSTATE and network diagnostics. + */ +export function serializePostgresError( + error: unknown, + seen = new WeakSet(), + depth = 0, +): Record { + if (error === null || (typeof error !== 'object' && typeof error !== 'function')) { + return { + type: error === null ? 'null' : typeof error, + value: serializePostgresLogValue(error), + } } + if (seen.has(error)) + return { type: getObjectType(error), circular: true } + + if (depth >= MAX_POSTGRES_ERROR_CAUSE_DEPTH) + return { type: getObjectType(error), truncated: true } + + seen.add(error) + const serialized: Record = { + type: getObjectType(error), + } + try { + const name = readErrorProperty(error, 'name') + const message = readErrorProperty(error, 'message') + const stack = readErrorProperty(error, 'stack') + + serialized.name = name === undefined + ? getObjectType(error) + : serializePostgresLogValue(name) + if (message !== undefined) + serialized.message = serializePostgresLogValue(message) + if (stack !== undefined) + serialized.stack = serializePostgresLogValue(stack) + + for (const field of POSTGRES_ERROR_FIELDS) { + const value = readErrorProperty(error, field) + if (value !== undefined) + serialized[field] = serializePostgresLogValue(value) + } + + const params = readErrorProperty(error, 'params') + if (Array.isArray(params)) { + // Query parameters can contain credentials or other user-provided secrets. + // The affected app is logged explicitly by the caller instead. + serialized.parameterCount = params.length + } + + const aggregateErrors = readErrorProperty(error, 'errors') + if (Array.isArray(aggregateErrors)) + serialized.errors = serializePostgresAggregateErrors(aggregateErrors, seen, depth) + + const cause = readErrorProperty(error, 'cause') + if (cause !== undefined) + serialized.cause = serializePostgresError(cause, seen, depth + 1) + + return serialized + } + catch (serializationError) { + serialized.serializationFailure = describeThrownValue(serializationError) + return serialized + } + finally { + seen.delete(error) + } +} + +export function logPgError( + c: Context, + functionName: string, + error: unknown, + diagnostics: Record = {}, +) { + const cf = c.req.raw.cf + const serializedDiagnostics = serializePostgresLogValue(diagnostics) + const callerDiagnostics = serializedDiagnostics !== null + && typeof serializedDiagnostics === 'object' + && !Array.isArray(serializedDiagnostics) + ? serializedDiagnostics as Record + : { context: serializedDiagnostics } + + // This deliberately verbose payload is temporary while investigating the + // intermittent getAppOwnerPostgres replica/Hyperdrive failure. cloudlogErr({ requestId: c.get('requestId'), message: `${functionName} - PostgreSQL Error`, - error: { - // Basic error info - message: e.message, - name: e.name, - stack: e.stack, - - // PostgreSQL-specific error codes - code: e.code, // e.g., '57P01' for connection termination, 'ECONNREFUSED', 'ETIMEDOUT' - severity: e.severity, - detail: e.detail, - hint: e.hint, - - // Network-level errors - errno: e.errno, // System error number - syscall: e.syscall, // System call that failed (e.g., 'connect', 'read', 'write') - address: e.address, // IP address - port: e.port, // Port number - - // Query position info - position: e.position, - routine: e.routine, - - // File info for debugging - file: e.file, - line: e.line, - column: e.column, + error: serializePostgresError(error), + diagnostics: { + ...callerDiagnostics, + version: 1, + functionName, + databaseSource: c.get('databaseSource') ?? c.res.headers.get('X-Database-Source') ?? 'unknown', + workerSource: c.res.headers.get('X-Worker-Source') ?? 'unknown', + runtime: getRuntimeKey(), + request: { + method: c.req.method, + path: c.req.path, + rayId: c.req.header('cf-ray') ?? c.get('requestId'), + userAgent: c.req.header('user-agent'), + colo: cf?.colo, + continent: cf?.continent, + country: cf?.country, + }, }, }) } @@ -1196,7 +1465,10 @@ export async function getAppOwnerPostgres( return appOwner as AppOwnerPostgresResult } catch (e: unknown) { - logPgError(c, 'getAppOwnerPostgres', e) + logPgError(c, 'getAppOwnerPostgres', e, { + appId, + planActions: actions, + }) return null } } diff --git a/tests/plugin-pg-error-logging.unit.test.ts b/tests/plugin-pg-error-logging.unit.test.ts new file mode 100644 index 0000000000..486a90a828 --- /dev/null +++ b/tests/plugin-pg-error-logging.unit.test.ts @@ -0,0 +1,388 @@ +import { beforeEach, describe, expect, it, vi } from 'vitest' +import { logPgError, serializePostgresError } from '../supabase/functions/_backend/plugin_runtime/utils/pg.ts' + +const { cloudlogErrMock } = vi.hoisted(() => ({ + cloudlogErrMock: vi.fn(), +})) + +vi.mock('../supabase/functions/_backend/plugin_runtime/utils/logging.ts', () => ({ + cloudlog: vi.fn(), + cloudlogErr: cloudlogErrMock, +})) + +function createContext() { + return { + get: (key: string) => { + if (key === 'requestId') + return 'a2331304eca21a55' + if (key === 'databaseSource') + return 'HYPERDRIVE_CAPGO_READ_EU' + return undefined + }, + req: { + method: 'POST', + path: '/stats', + header: (name: string) => { + if (name === 'cf-ray') + return 'a2331304eca21a55-FRA' + if (name === 'user-agent') + return 'CapacitorUpdater/8.43.2' + return undefined + }, + raw: { + cf: { + colo: 'FRA', + continent: 'EU', + country: 'BE', + }, + }, + }, + res: { + headers: new Headers([ + ['X-Database-Source', 'HYPERDRIVE_CAPGO_READ_EU'], + ['X-Worker-Source', 'capgo_plugin-eu-prod'], + ]), + }, + } as any +} + +describe('plugin PostgreSQL error logging', () => { + beforeEach(() => { + cloudlogErrMock.mockReset() + }) + + it('serializes nested Drizzle and PostgreSQL diagnostics', () => { + const postgresError = Object.assign(new Error('terminating connection due to administrator command'), { + code: '57P01', + severity: 'FATAL', + detail: 'The database system is shutting down.', + hint: 'Retry the connection.', + position: '42', + internalPosition: '7', + internalQuery: 'SELECT 1', + where: 'parallel worker', + schema: 'public', + table: 'apps', + column: 'owner_org', + dataType: 'uuid', + constraint: 'apps_owner_org_fkey', + file: 'postgres.c', + line: '3211', + routine: 'ProcessInterrupts', + }) + const drizzleError = Object.assign(new Error('Failed query: select ...'), { + name: 'DrizzleQueryError', + query: 'select "apps"."owner_org" from "apps" where "apps"."app_id" = $1', + params: ['co.spencer.app'], + cause: postgresError, + }) + + expect(serializePostgresError(drizzleError)).toMatchObject({ + type: 'Error', + name: 'DrizzleQueryError', + message: 'Failed query: select ...', + query: expect.stringContaining('owner_org'), + parameterCount: 1, + cause: { + type: 'Error', + name: 'Error', + message: 'terminating connection due to administrator command', + code: '57P01', + severity: 'FATAL', + detail: 'The database system is shutting down.', + hint: 'Retry the connection.', + position: '42', + internalPosition: '7', + internalQuery: 'SELECT 1', + where: 'parallel worker', + schema: 'public', + table: 'apps', + column: 'owner_org', + dataType: 'uuid', + constraint: 'apps_owner_org_fkey', + file: 'postgres.c', + line: '3211', + routine: 'ProcessInterrupts', + }, + }) + }) + + it('serializes network failures and aggregate connection errors', () => { + const firstAddress = Object.assign(new Error('connect ECONNREFUSED 10.0.0.1:5432'), { + code: 'ECONNREFUSED', + errno: -61, + syscall: 'connect', + address: '10.0.0.1', + port: 5432, + }) + const secondAddress = Object.assign(new Error('connect ETIMEDOUT 10.0.0.2:5432'), { + code: 'ETIMEDOUT', + errno: -60, + syscall: 'connect', + address: '10.0.0.2', + port: 5432, + }) + const aggregateError = new AggregateError([firstAddress, secondAddress], 'All connection attempts failed') + + expect(serializePostgresError(aggregateError)).toMatchObject({ + type: 'AggregateError', + message: 'All connection attempts failed', + errors: [ + { + code: 'ECONNREFUSED', + errno: -61, + syscall: 'connect', + address: '10.0.0.1', + port: 5432, + }, + { + code: 'ETIMEDOUT', + errno: -60, + syscall: 'connect', + address: '10.0.0.2', + port: 5432, + }, + ], + }) + }) + + it('serializes a shared aggregate error independently in each branch', () => { + const sharedError = Object.assign(new Error('connection reset'), { + code: 'ECONNRESET', + }) + const aggregateError = new AggregateError([sharedError, sharedError], 'All connection attempts failed') + + expect(serializePostgresError(aggregateError)).toMatchObject({ + errors: [ + { message: 'connection reset', code: 'ECONNRESET' }, + { message: 'connection reset', code: 'ECONNRESET' }, + ], + }) + }) + + it('bounds large aggregate connection errors and records omitted entries', () => { + const aggregateError = new AggregateError( + Array.from({ length: 55 }, (_, index) => new Error(`connection-${index}`)), + 'All connection attempts failed', + ) + const serialized = serializePostgresError(aggregateError) + const errors = serialized.errors as Record[] + + expect(errors).toHaveLength(51) + expect(errors[0]).toMatchObject({ message: 'connection-0' }) + expect(errors[49]).toMatchObject({ message: 'connection-49' }) + expect(errors[50]).toEqual({ type: 'truncated', omitted: 5 }) + }) + + it('represents sparse aggregate slots as undefined', () => { + const errors = new Array(2) + errors[1] = new Error('connection failed') + + expect(serializePostgresError(new AggregateError(errors))).toMatchObject({ + errors: [ + { type: 'undefined', value: undefined }, + { message: 'connection failed' }, + ], + }) + }) + + it('keeps primitive throws and hostile properties safe to log', () => { + expect(serializePostgresError(null)).toEqual({ type: 'null', value: null }) + expect(serializePostgresError('connection reset')).toEqual({ type: 'string', value: 'connection reset' }) + expect(serializePostgresError(42n)).toEqual({ type: 'bigint', value: '42' }) + + let getterCalled = false + const hostileError = new Error('hostile property') + Object.defineProperty(hostileError, 'code', { + get() { + getterCalled = true + throw new Error('getter exploded') + }, + }) + + expect(serializePostgresError(hostileError)).toMatchObject({ + message: 'hostile property', + code: '[accessor property omitted]', + }) + expect(getterCalled).toBe(false) + + const undefinedThrowingProxy = new Proxy(new Error('proxy'), { + getOwnPropertyDescriptor() { + throw undefined + }, + }) + expect(serializePostgresError(undefinedThrowingProxy)).toMatchObject({ + name: '[unreadable property: undefined]', + }) + }) + + it('bounds cyclic structured PostgreSQL fields and remains JSON serializable', () => { + const query: Record = { + text: 'SELECT $1', + values: ['must-not-appear-in-logs'], + } + query.self = query + const postgresError = Object.assign(new Error('query failed'), { query }) + const serialized = serializePostgresError(postgresError) + + expect(serialized).toMatchObject({ + query: { + text: 'SELECT $1', + self: '[circular]', + values: '[redacted]', + }, + }) + expect(() => JSON.stringify(serialized)).not.toThrow() + expect(JSON.stringify(serialized)).not.toContain('must-not-appear-in-logs') + }) + + it('blocks prototype-pollution keys without changing object prototypes', () => { + const maliciousQuery = JSON.parse(`{ + "__proto__": { "polluted": true }, + "constructor": { "prototype": { "polluted": true } }, + "prototype": { "polluted": true }, + "text": "SELECT 1" + }`) + const serialized = serializePostgresError(Object.assign(new Error('query failed'), { + query: maliciousQuery, + })) + const query = serialized.query as Record + + expect(({} as { polluted?: boolean }).polluted).toBeUndefined() + expect(Object.getPrototypeOf(query)).toBeNull() + expect(query).toMatchObject({ + text: 'SELECT 1', + __blockedKeys: ['__proto__', 'constructor', 'prototype'], + }) + expect(Object.prototype.hasOwnProperty.call(query, '__proto__')).toBe(false) + expect(Object.prototype.hasOwnProperty.call(query, 'constructor')).toBe(false) + expect(Object.prototype.hasOwnProperty.call(query, 'prototype')).toBe(false) + + const inheritedError = Object.create({ code: 'POLLUTED' }) + inheritedError.message = 'failed' + expect(serializePostgresError(inheritedError)).not.toHaveProperty('code') + }) + + it('does not invoke accessors while serializing structured fields', () => { + let getterCalled = false + const query = { text: 'SELECT 1' } as Record + Object.defineProperty(query, 'hostile', { + enumerable: true, + get() { + getterCalled = true + return 'must-not-be-read' + }, + }) + + const serialized = serializePostgresError(Object.assign(new Error('query failed'), { query })) + expect(getterCalled).toBe(false) + expect(serialized).toMatchObject({ + query: { hostile: '[accessor property omitted]' }, + }) + }) + + it('redacts Drizzle parameter lines from messages and stacks', () => { + const error = new Error('Failed query: SELECT $1\nparams: super-secret-token') + Object.defineProperty(error, 'stack', { + configurable: true, + value: 'Error: Failed query\nparams: super-secret-token\n at query.ts:1:1', + }) + + const serialized = serializePostgresError(error) + expect(serialized.message).toBe('Failed query: SELECT $1\nparams: [redacted]') + expect(serialized.stack).toBe('Error: Failed query\nparams: [redacted]\n at query.ts:1:1') + expect(JSON.stringify(serialized)).not.toContain('super-secret-token') + }) + + it('logs filterable Worker, replica, request, and app diagnostics', () => { + const postgresError = Object.assign(new Error('server closed the connection unexpectedly'), { + code: '57P01', + severity: 'FATAL', + }) + const drizzleError = Object.assign(new Error('Failed query'), { + name: 'DrizzleQueryError', + cause: postgresError, + }) + + logPgError(createContext(), 'getAppOwnerPostgres', drizzleError, { + appId: 'co.spencer.app', + functionName: 'caller-cannot-override', + planActions: ['mau'], + request: { method: 'DELETE' }, + version: 999, + }) + + expect(cloudlogErrMock).toHaveBeenCalledWith(expect.objectContaining({ + requestId: 'a2331304eca21a55', + message: 'getAppOwnerPostgres - PostgreSQL Error', + error: expect.objectContaining({ + name: 'DrizzleQueryError', + cause: expect.objectContaining({ + code: '57P01', + severity: 'FATAL', + }), + }), + diagnostics: { + appId: 'co.spencer.app', + planActions: ['mau'], + version: 1, + functionName: 'getAppOwnerPostgres', + databaseSource: 'HYPERDRIVE_CAPGO_READ_EU', + workerSource: 'capgo_plugin-eu-prod', + runtime: expect.any(String), + request: { + method: 'POST', + path: '/stats', + rayId: 'a2331304eca21a55-FRA', + userAgent: 'CapacitorUpdater/8.43.2', + colo: 'FRA', + continent: 'EU', + country: 'BE', + }, + }, + })) + }) + + it('blocks prototype-pollution keys in caller diagnostics', () => { + const maliciousDiagnostics = JSON.parse(`{ + "__proto__": { "polluted": true }, + "constructor": { "prototype": { "polluted": true } }, + "prototype": { "polluted": true }, + "appId": "co.safe.app" + }`) + + logPgError(createContext(), 'getAppOwnerPostgres', new Error('failed'), maliciousDiagnostics) + + const payload = cloudlogErrMock.mock.calls[0][0] + expect(({} as { polluted?: boolean }).polluted).toBeUndefined() + expect(Object.getPrototypeOf(payload.diagnostics)).toBe(Object.prototype) + expect(payload.diagnostics).toMatchObject({ + appId: 'co.safe.app', + __blockedKeys: ['__proto__', 'constructor', 'prototype'], + version: 1, + functionName: 'getAppOwnerPostgres', + }) + expect(Object.prototype.hasOwnProperty.call(payload.diagnostics, '__proto__')).toBe(false) + expect(Object.prototype.hasOwnProperty.call(payload.diagnostics, 'constructor')).toBe(false) + expect(Object.prototype.hasOwnProperty.call(payload.diagnostics, 'prototype')).toBe(false) + }) + + it('bounds circular and excessively deep cause chains', () => { + const circularError = new Error('circular') + circularError.cause = circularError + + expect(serializePostgresError(circularError)).toMatchObject({ + message: 'circular', + cause: { circular: true }, + }) + + let deepError: Error = new Error('root') + for (let index = 0; index < 10; index++) + deepError = new Error(`level-${index}`, { cause: deepError }) + + let current: Record = serializePostgresError(deepError) + for (let index = 0; index < 8; index++) + current = current.cause as Record + expect(current).toMatchObject({ truncated: true }) + }) +})