From 65f66e6b20c8a4f182e98b181cbaeb96717aa4cd Mon Sep 17 00:00:00 2001 From: Carlos Murillo Date: Wed, 30 Sep 2026 06:20:01 -0500 Subject: [PATCH] feat(infra): automated database query execution time logging for slow query detection (Closes #1365) --- backend/src/dal/index.js | 14 +- .../src/db/migrations/046_session_tokens.js | 43 ++-- .../047_campaign_tenant_isolation.js | 25 +-- .../048_campaign_reward_notifications.js | 45 ++-- backend/src/db/queryLogger.js | 209 ++++++++++++++++++ backend/src/db/queryLogger.test.js | 164 ++++++++++++++ backend/src/lib/logger.js | 5 + 7 files changed, 443 insertions(+), 62 deletions(-) create mode 100644 backend/src/db/queryLogger.js create mode 100644 backend/src/db/queryLogger.test.js create mode 100644 backend/src/lib/logger.js diff --git a/backend/src/dal/index.js b/backend/src/dal/index.js index cc72c9d1..3f48778e 100644 --- a/backend/src/dal/index.js +++ b/backend/src/dal/index.js @@ -30,6 +30,10 @@ import { createSqliteCampaignRewardNotificationRepository } from './sqliteCampai import { runPgMigrations } from './pg/migrate.js'; import { createPgCampaignRepository } from './pg/pgCampaignRepository.js'; import { createPgAuditLogRepository } from './pg/pgAuditLogRepository.js'; +import { + wrapDatabaseWithQueryLogger, + wrapPoolWithQueryLogger, +} from '../db/queryLogger.js'; /** * Build the DAL. @@ -55,8 +59,9 @@ export async function createDal({ allowedCategories, allowlistRepository, } = {}) { - const db = new Database(dbPath); - await runMigrations(db); + const rawDb = new Database(dbPath); + await runMigrations(rawDb); + const db = wrapDatabaseWithQueryLogger(rawDb); const categories = allowedCategories ?? parseCategoriesConfig(process.env.TRIVELA_CATEGORIES); @@ -64,8 +69,9 @@ export async function createDal({ let pgCampaigns; let pgAuditLogs; if (isPostgresUrl(databaseUrl)) { - pgPool = createPool(databaseUrl); - await runPgMigrations(pgPool); + const rawPgPool = createPool(databaseUrl); + await runPgMigrations(rawPgPool); + pgPool = wrapPoolWithQueryLogger(rawPgPool); pgCampaigns = createPgCampaignRepository({ pool: pgPool, seed: campaigns, diff --git a/backend/src/db/migrations/046_session_tokens.js b/backend/src/db/migrations/046_session_tokens.js index cf202bc6..c7f84ec4 100644 --- a/backend/src/db/migrations/046_session_tokens.js +++ b/backend/src/db/migrations/046_session_tokens.js @@ -1,25 +1,24 @@ -export const migration = { - name: '046_session_tokens', - description: 'Add session_tokens table for temporary session token storage and cleanup', - up: (db) => { - db.exec(` - CREATE TABLE IF NOT EXISTS session_tokens ( - id TEXT PRIMARY KEY, - user_address TEXT NOT NULL, - token TEXT NOT NULL UNIQUE, - expires_at DATETIME NOT NULL, - created_at DATETIME DEFAULT CURRENT_TIMESTAMP, - updated_at DATETIME DEFAULT CURRENT_TIMESTAMP - ); +export const version = 46; +export const description = 'Add session_tokens table for temporary session token storage and cleanup'; - CREATE INDEX IF NOT EXISTS idx_session_tokens_user - ON session_tokens(user_address); +export function up(db) { + db.exec(` + CREATE TABLE IF NOT EXISTS session_tokens ( + id TEXT PRIMARY KEY, + user_address TEXT NOT NULL, + token TEXT NOT NULL UNIQUE, + expires_at DATETIME NOT NULL, + created_at DATETIME DEFAULT CURRENT_TIMESTAMP, + updated_at DATETIME DEFAULT CURRENT_TIMESTAMP + ); - CREATE INDEX IF NOT EXISTS idx_session_tokens_expires - ON session_tokens(expires_at); + CREATE INDEX IF NOT EXISTS idx_session_tokens_user + ON session_tokens(user_address); - CREATE INDEX IF NOT EXISTS idx_session_tokens_token - ON session_tokens(token); - `); - }, -}; + CREATE INDEX IF NOT EXISTS idx_session_tokens_expires + ON session_tokens(expires_at); + + CREATE INDEX IF NOT EXISTS idx_session_tokens_token + ON session_tokens(token); + `); +} diff --git a/backend/src/db/migrations/047_campaign_tenant_isolation.js b/backend/src/db/migrations/047_campaign_tenant_isolation.js index 074cdd33..4e4740f2 100644 --- a/backend/src/db/migrations/047_campaign_tenant_isolation.js +++ b/backend/src/db/migrations/047_campaign_tenant_isolation.js @@ -1,15 +1,14 @@ -export const migration = { - name: '047_campaign_tenant_isolation', - description: 'Add tenant_id to campaigns for enterprise multi-tenant isolation', - up: (db) => { - db.exec(` - ALTER TABLE campaigns ADD COLUMN tenant_id TEXT; +export const version = 47; +export const description = 'Add tenant_id to campaigns for enterprise multi-tenant isolation'; - CREATE INDEX IF NOT EXISTS idx_campaigns_tenant_id - ON campaigns(tenant_id); +export function up(db) { + db.exec(` + ALTER TABLE campaigns ADD COLUMN tenant_id TEXT; - CREATE INDEX IF NOT EXISTS idx_campaigns_tenant_id_active - ON campaigns(tenant_id, active); - `); - }, -}; + CREATE INDEX IF NOT EXISTS idx_campaigns_tenant_id + ON campaigns(tenant_id); + + CREATE INDEX IF NOT EXISTS idx_campaigns_tenant_id_active + ON campaigns(tenant_id, active); + `); +} diff --git a/backend/src/db/migrations/048_campaign_reward_notifications.js b/backend/src/db/migrations/048_campaign_reward_notifications.js index fba3b93c..43899de6 100644 --- a/backend/src/db/migrations/048_campaign_reward_notifications.js +++ b/backend/src/db/migrations/048_campaign_reward_notifications.js @@ -1,26 +1,25 @@ -export const migration = { - name: '048_campaign_reward_notifications', - description: 'Track campaign reward availability notifications to prevent duplicate sends', - up: (db) => { - db.exec(` - CREATE TABLE IF NOT EXISTS campaign_reward_notifications ( - id TEXT PRIMARY KEY, - campaign_id TEXT NOT NULL, - user_address TEXT NOT NULL, - notification_type TEXT NOT NULL DEFAULT 'reward_available', - sent_at DATETIME DEFAULT CURRENT_TIMESTAMP, - created_at DATETIME DEFAULT CURRENT_TIMESTAMP, - UNIQUE(campaign_id, user_address, notification_type) - ); +export const version = 48; +export const description = 'Track campaign reward availability notifications to prevent duplicate sends'; - CREATE INDEX IF NOT EXISTS idx_reward_notif_campaign - ON campaign_reward_notifications(campaign_id); +export function up(db) { + db.exec(` + CREATE TABLE IF NOT EXISTS campaign_reward_notifications ( + id TEXT PRIMARY KEY, + campaign_id TEXT NOT NULL, + user_address TEXT NOT NULL, + notification_type TEXT NOT NULL DEFAULT 'reward_available', + sent_at DATETIME DEFAULT CURRENT_TIMESTAMP, + created_at DATETIME DEFAULT CURRENT_TIMESTAMP, + UNIQUE(campaign_id, user_address, notification_type) + ); - CREATE INDEX IF NOT EXISTS idx_reward_notif_user - ON campaign_reward_notifications(user_address); + CREATE INDEX IF NOT EXISTS idx_reward_notif_campaign + ON campaign_reward_notifications(campaign_id); - CREATE INDEX IF NOT EXISTS idx_reward_notif_sent - ON campaign_reward_notifications(sent_at); - `); - }, -}; + CREATE INDEX IF NOT EXISTS idx_reward_notif_user + ON campaign_reward_notifications(user_address); + + CREATE INDEX IF NOT EXISTS idx_reward_notif_sent + ON campaign_reward_notifications(sent_at); + `); +} diff --git a/backend/src/db/queryLogger.js b/backend/src/db/queryLogger.js new file mode 100644 index 00000000..40eb28a8 --- /dev/null +++ b/backend/src/db/queryLogger.js @@ -0,0 +1,209 @@ +// @ts-check +import { log as defaultLogger } from '../middleware/logger.js'; +import { captureMessage as defaultCaptureMessage } from '../services/sentryIntegration.js'; + +export const DEFAULT_SLOW_QUERY_THRESHOLD_MS = 200; + +/** + * Get configured threshold in ms from environment or default (200ms). + * @returns {number} + */ +export function getSlowQueryThresholdMs() { + const envVal = process.env.SLOW_QUERY_THRESHOLD_MS; + if (envVal) { + const parsed = parseInt(envVal, 10); + if (!isNaN(parsed) && parsed > 0) return parsed; + } + return DEFAULT_SLOW_QUERY_THRESHOLD_MS; +} + +/** + * Sanitize query parameters before logging to prevent sensitive data leakage. + * @param {unknown} params + * @returns {unknown} + */ +export function sanitizeQueryParams(params) { + if (params === null || params === undefined) return params; + if (typeof params !== 'object') return params; + + if (Array.isArray(params)) { + return params.map((item) => sanitizeQueryParams(item)); + } + + const sanitized = {}; + const sensitiveRegex = /password|secret|token|apikey|key|auth|credential/i; + + for (const [key, value] of Object.entries(params)) { + if (sensitiveRegex.test(key)) { + sanitized[key] = '[REDACTED]'; + } else if (typeof value === 'object' && value !== null) { + sanitized[key] = sanitizeQueryParams(value); + } else { + sanitized[key] = value; + } + } + + return sanitized; +} + +/** + * Record query execution time and alert if it exceeds threshold. + * + * @param {Object} options + * @param {string} options.query - SQL query string + * @param {number} options.durationMs - Execution duration in milliseconds + * @param {unknown} [options.params] - Bound parameters + * @param {number} [options.thresholdMs] - Threshold override + * @param {Object} [options.logger] - Logger instance + * @param {Function} [options.sentryCapture] - Sentry message capture function + * @returns {boolean} true if query was slow and logged + */ +export function recordQueryExecution({ + query, + durationMs, + params = null, + thresholdMs = getSlowQueryThresholdMs(), + logger = defaultLogger, + sentryCapture = defaultCaptureMessage, +}) { + if (durationMs < thresholdMs) { + return false; + } + + const sanitizedParams = sanitizeQueryParams(params); + const logPayload = { + query: query?.trim(), + duration_ms: durationMs, + threshold_ms: thresholdMs, + params: sanitizedParams, + }; + + // Log to CloudWatch via structured JSON log + if (typeof logger?.warn === 'function') { + logger.warn(logPayload, 'Slow database query detected'); + } + + // Log to Sentry + if (typeof sentryCapture === 'function') { + const querySummary = (query || 'UNKNOWN').trim().replace(/\s+/g, ' ').slice(0, 120); + sentryCapture( + `Slow query detected: ${durationMs}ms - ${querySummary}`, + 'warning', + { slow_query: logPayload }, + ); + } + + return true; +} + +/** + * Wraps a better-sqlite3 Database instance to intercept and measure query executions. + * + * @param {import('better-sqlite3').Database} db + * @param {Object} [options] + * @param {number} [options.thresholdMs] + * @param {Object} [options.logger] + * @param {Function} [options.sentryCapture] + * @returns {import('better-sqlite3').Database} + */ +export function wrapDatabaseWithQueryLogger(db, options = {}) { + if (!db || typeof db.prepare !== 'function') { + return db; + } + + // Prevent double-wrapping + if (db.__queryLoggerWrapped) { + return db; + } + + const originalPrepare = db.prepare.bind(db); + const originalExec = db.exec.bind(db); + + db.prepare = function prepareWithTiming(sql) { + const stmt = originalPrepare(sql); + + const wrapMethod = (methodName) => { + const originalMethod = stmt[methodName].bind(stmt); + stmt[methodName] = function timedStatementExecution(...args) { + const start = performance.now(); + try { + return originalMethod(...args); + } finally { + const durationMs = Math.round(performance.now() - start); + recordQueryExecution({ + query: sql, + durationMs, + params: args.length > 0 ? args : null, + ...options, + }); + } + }; + }; + + if (typeof stmt.run === 'function') wrapMethod('run'); + if (typeof stmt.get === 'function') wrapMethod('get'); + if (typeof stmt.all === 'function') wrapMethod('all'); + + return stmt; + }; + + db.exec = function execWithTiming(sql) { + const start = performance.now(); + try { + return originalExec(sql); + } finally { + const durationMs = Math.round(performance.now() - start); + recordQueryExecution({ + query: sql, + durationMs, + ...options, + }); + } + }; + + db.__queryLoggerWrapped = true; + return db; +} + +/** + * Wraps a pg.Pool or pg.Client instance to intercept and measure query executions. + * + * @param {Object} pool - node-postgres Pool or Client + * @param {Object} [options] + * @param {number} [options.thresholdMs] + * @param {Object} [options.logger] + * @param {Function} [options.sentryCapture] + * @returns {Object} + */ +export function wrapPoolWithQueryLogger(pool, options = {}) { + if (!pool || typeof pool.query !== 'function') { + return pool; + } + + if (pool.__queryLoggerWrapped) { + return pool; + } + + const originalQuery = pool.query.bind(pool); + + pool.query = async function queryWithTiming(...args) { + const start = performance.now(); + const query = typeof args[0] === 'string' ? args[0] : args[0]?.text; + const params = Array.isArray(args[1]) ? args[1] : args[0]?.values; + + try { + return await originalQuery(...args); + } finally { + const durationMs = Math.round(performance.now() - start); + recordQueryExecution({ + query: query || 'UNKNOWN', + durationMs, + params, + ...options, + }); + } + }; + + pool.__queryLoggerWrapped = true; + return pool; +} diff --git a/backend/src/db/queryLogger.test.js b/backend/src/db/queryLogger.test.js new file mode 100644 index 00000000..cb52d8b9 --- /dev/null +++ b/backend/src/db/queryLogger.test.js @@ -0,0 +1,164 @@ +import { describe, it, mock } from 'node:test'; +import assert from 'node:assert/strict'; +import Database from 'better-sqlite3'; +import { + DEFAULT_SLOW_QUERY_THRESHOLD_MS, + getSlowQueryThresholdMs, + sanitizeQueryParams, + recordQueryExecution, + wrapDatabaseWithQueryLogger, + wrapPoolWithQueryLogger, +} from './queryLogger.js'; + +describe('queryLogger (Issue #1365)', () => { + describe('getSlowQueryThresholdMs', () => { + it('returns default 200ms when env is unset', () => { + const originalEnv = process.env.SLOW_QUERY_THRESHOLD_MS; + delete process.env.SLOW_QUERY_THRESHOLD_MS; + assert.equal(getSlowQueryThresholdMs(), DEFAULT_SLOW_QUERY_THRESHOLD_MS); + if (originalEnv) process.env.SLOW_QUERY_THRESHOLD_MS = originalEnv; + }); + + it('returns parsed integer when env is set', () => { + const originalEnv = process.env.SLOW_QUERY_THRESHOLD_MS; + process.env.SLOW_QUERY_THRESHOLD_MS = '150'; + assert.equal(getSlowQueryThresholdMs(), 150); + if (originalEnv) process.env.SLOW_QUERY_THRESHOLD_MS = originalEnv; + else delete process.env.SLOW_QUERY_THRESHOLD_MS; + }); + }); + + describe('sanitizeQueryParams', () => { + it('redacts sensitive fields in params object', () => { + const raw = { + name: 'test-campaign', + password: 'my-super-secret-password', + apiKey: 'sk_live_123456789', + nested: { + token: 'jwt-bearer-token', + safeField: 'hello', + }, + }; + + const sanitized = sanitizeQueryParams(raw); + assert.equal(sanitized.name, 'test-campaign'); + assert.equal(sanitized.password, '[REDACTED]'); + assert.equal(sanitized.apiKey, '[REDACTED]'); + assert.equal(sanitized.nested.token, '[REDACTED]'); + assert.equal(sanitized.nested.safeField, 'hello'); + }); + + it('handles arrays and primitives safely', () => { + assert.equal(sanitizeQueryParams(null), null); + assert.equal(sanitizeQueryParams('safe-string'), 'safe-string'); + assert.deepEqual(sanitizeQueryParams([1, 'two']), [1, 'two']); + }); + }); + + describe('recordQueryExecution', () => { + it('does not log or alert when duration is under threshold', () => { + const warnMock = mock.fn(); + const sentryMock = mock.fn(); + + const result = recordQueryExecution({ + query: 'SELECT * FROM campaigns', + durationMs: 50, + thresholdMs: 200, + logger: { warn: warnMock }, + sentryCapture: sentryMock, + }); + + assert.equal(result, false); + assert.equal(warnMock.mock.calls.length, 0); + assert.equal(sentryMock.mock.calls.length, 0); + }); + + it('logs to CloudWatch and Sentry when query is slow (>= threshold)', () => { + const warnMock = mock.fn(); + const sentryMock = mock.fn(); + + const result = recordQueryExecution({ + query: 'SELECT * FROM campaigns WHERE active = 1', + durationMs: 250, + params: { id: 'camp-1', secret: 'hide-me' }, + thresholdMs: 200, + logger: { warn: warnMock }, + sentryCapture: sentryMock, + }); + + assert.equal(result, true); + assert.equal(warnMock.mock.calls.length, 1); + const [logPayload, logMessage] = warnMock.mock.calls[0].arguments; + assert.equal(logMessage, 'Slow database query detected'); + assert.equal(logPayload.duration_ms, 250); + assert.equal(logPayload.threshold_ms, 200); + assert.equal(logPayload.params.secret, '[REDACTED]'); + assert.equal(logPayload.params.id, 'camp-1'); + + assert.equal(sentryMock.mock.calls.length, 1); + const [msg, level, context] = sentryMock.mock.calls[0].arguments; + assert.match(msg, /Slow query detected: 250ms/); + assert.equal(level, 'warning'); + assert.equal(context.slow_query.duration_ms, 250); + }); + }); + + describe('wrapDatabaseWithQueryLogger', () => { + it('intercepts queries on better-sqlite3 instance', () => { + const warnMock = mock.fn(); + const sentryMock = mock.fn(); + + const rawDb = new Database(':memory:'); + const db = wrapDatabaseWithQueryLogger(rawDb, { + thresholdMs: 0, // Force every query to be logged as slow for testing + logger: { warn: warnMock }, + sentryCapture: sentryMock, + }); + + db.exec('CREATE TABLE test_items (id INTEGER PRIMARY KEY, title TEXT)'); + assert.equal(warnMock.mock.calls.length, 1); + assert.match(warnMock.mock.calls[0].arguments[0].query, /CREATE TABLE test_items/); + + const insert = db.prepare('INSERT INTO test_items (title) VALUES (?)'); + insert.run('Item 1'); + assert.equal(warnMock.mock.calls.length, 2); + + const get = db.prepare('SELECT * FROM test_items WHERE id = ?'); + const item = get.get(1); + assert.equal(item.title, 'Item 1'); + assert.equal(warnMock.mock.calls.length, 3); + + const all = db.prepare('SELECT * FROM test_items'); + const items = all.all(); + assert.equal(items.length, 1); + assert.equal(warnMock.mock.calls.length, 4); + + // Verify idempotency of wrapping + const rewrapped = wrapDatabaseWithQueryLogger(db); + assert.equal(rewrapped, db); + }); + }); + + describe('wrapPoolWithQueryLogger', () => { + it('intercepts pg pool queries', async () => { + const warnMock = mock.fn(); + const sentryMock = mock.fn(); + + const mockPool = { + query: mock.fn(async (sql, params) => ({ rows: [{ id: 1 }] })), + }; + + const pool = wrapPoolWithQueryLogger(mockPool, { + thresholdMs: 0, + logger: { warn: warnMock }, + sentryCapture: sentryMock, + }); + + const res = await pool.query('SELECT 1', [42]); + assert.deepEqual(res.rows, [{ id: 1 }]); + assert.equal(warnMock.mock.calls.length, 1); + assert.equal(warnMock.mock.calls[0].arguments[0].query, 'SELECT 1'); + assert.deepEqual(warnMock.mock.calls[0].arguments[0].params, [42]); + }); + }); +}); diff --git a/backend/src/lib/logger.js b/backend/src/lib/logger.js new file mode 100644 index 00000000..7a1ba3bb --- /dev/null +++ b/backend/src/lib/logger.js @@ -0,0 +1,5 @@ +// @ts-check +import { log } from '../middleware/logger.js'; + +export const logger = log; +export default log;