diff --git a/backend/services/logging.ts b/backend/services/logging.ts index 4d14d7c6..d9a5b860 100644 --- a/backend/services/logging.ts +++ b/backend/services/logging.ts @@ -1,254 +1,23 @@ -import { AsyncLocalStorage } from 'async_hooks'; - -export type LogLevel = 'debug' | 'info' | 'warn' | 'error'; - -const LOG_LEVEL_PRIORITY: Record = { - debug: 0, - info: 1, - warn: 2, - error: 3, -}; - -const DEFAULT_LOG_LEVEL: LogLevel = 'info'; -const DEFAULT_BUFFER_SIZE = 200; -const SERVICE_NAME = process.env.LOG_SERVICE_NAME || 'subtrackr-backend'; -const REMOTE_LOG_ENDPOINT = process.env.LOG_REMOTE_ENDPOINT || ''; -const GLOBAL_LOG_LEVEL = (process.env.BACKEND_LOG_LEVEL as LogLevel) || DEFAULT_LOG_LEVEL; -const BUFFER_SIZE = Number(process.env.LOG_BUFFER_SIZE || DEFAULT_BUFFER_SIZE); - -const SENSITIVE_FIELD_PATTERNS = [ - /password/i, - /secret/i, - /token/i, - /ssn/i, - /creditcard/i, - /cardNumber/i, - /email/i, - /phone/i, - /accountNumber/i, - /routingNumber/i, -]; - -const asyncLocalStorage = new AsyncLocalStorage(); -const inMemoryLogBuffer: LogEntry[] = []; - -export interface LogContext { - correlationId?: string; - [key: string]: unknown; -} - -export interface LogMeta { - [key: string]: unknown; -} - -export interface LogEntry { - timestamp: string; - service: string; - module: string; - level: LogLevel; - message: string; - correlationId?: string; - meta?: LogMeta; -} - -function generateId(): string { - return `${Date.now().toString(36)}-${Math.random().toString(36).substring(2, 8)}`; -} - -function parseModuleLevels(envValue: string): Record { - return envValue.split(',').reduce((acc, pair) => { - const [module, level] = pair.split(':').map((part) => part.trim()); - if (module && level && ['debug', 'info', 'warn', 'error'].includes(level)) { - acc[module] = level as LogLevel; - } - return acc; - }, {} as Record); -} - -const MODULE_LOG_LEVELS = parseModuleLevels(process.env.BACKEND_LOG_LEVELS || ''); - -function getModuleLevel(moduleName: string): LogLevel { - const exactMatch = MODULE_LOG_LEVELS[moduleName]; - if (exactMatch) return exactMatch; - - const partialMatch = Object.keys(MODULE_LOG_LEVELS).find((key) => moduleName.startsWith(`${key}:`)); - if (partialMatch) return MODULE_LOG_LEVELS[partialMatch]; - - return GLOBAL_LOG_LEVEL; -} - -function isSensitiveField(key: string): boolean { - return SENSITIVE_FIELD_PATTERNS.some((pattern) => pattern.test(key)); -} - -function redactValue(key: string, value: unknown): unknown { - if (typeof value === 'string') { - return isSensitiveField(key) ? '[REDACTED]' : value; - } - - if (Array.isArray(value)) { - return value.map((item) => redactValue(key, item)); - } - - if (value && typeof value === 'object') { - return redactSensitiveFields(value as Record); - } - - return value; -} - -function redactSensitiveFields(obj: Record): Record { - return Object.entries(obj).reduce((acc, [key, value]) => { - if (isSensitiveField(key)) { - acc[key] = '[REDACTED]'; - } else if (Array.isArray(value)) { - acc[key] = value.map((item) => (typeof item === 'object' ? redactSensitiveFields(item as Record) : item)); - } else if (value && typeof value === 'object') { - acc[key] = redactSensitiveFields(value as Record); - } else { - acc[key] = value; - } - return acc; - }, {} as Record); -} - -function sanitizeMeta(meta?: LogMeta): LogMeta | undefined { - if (!meta) return undefined; - return redactSensitiveFields(meta as Record); -} - -function shouldLog(level: LogLevel, moduleName: string) { - const moduleLevel = getModuleLevel(moduleName); - return LOG_LEVEL_PRIORITY[level] >= LOG_LEVEL_PRIORITY[moduleLevel]; -} - -function formatLog(level: LogLevel, message: string, meta: LogMeta | undefined, moduleName: string, context: LogContext): LogEntry { - return { - timestamp: new Date().toISOString(), - service: SERVICE_NAME, - module: moduleName, - level, - message, - correlationId: context.correlationId, - meta: meta && Object.keys(meta).length ? sanitizeMeta(meta) : undefined, - }; -} - -function enqueueLog(entry: LogEntry) { - inMemoryLogBuffer.push(entry); - while (inMemoryLogBuffer.length > BUFFER_SIZE) { - inMemoryLogBuffer.shift(); - } -} - -function sendToConsole(entry: LogEntry) { - console.log(JSON.stringify(entry)); -} - -async function sendToRemote(entry: LogEntry) { - if (!REMOTE_LOG_ENDPOINT) return; - - try { - await fetch(REMOTE_LOG_ENDPOINT, { - method: 'POST', - headers: { 'Content-Type': 'application/json' }, - body: JSON.stringify(entry), - }); - } catch (error) { - console.warn(JSON.stringify({ - level: 'warn', - message: 'Failed to send log to remote endpoint', - endpoint: REMOTE_LOG_ENDPOINT, - error: String(error), - correlationId: entry.correlationId, - })); - } -} - -function getCurrentContext(): LogContext { - return asyncLocalStorage.getStore() ?? {}; -} - -function buildLogEntry(level: LogLevel, message: string, meta: LogMeta | undefined, moduleName: string): LogEntry { - const context = getCurrentContext(); - const correlationId = context.correlationId || generateId(); - - return formatLog(level, message, meta, moduleName, { - ...context, - correlationId, - }); -} - -function recordLog(entry: LogEntry) { - enqueueLog(entry); - sendToConsole(entry); - if (entry.level === 'error') { - void sendToRemote(entry); - } -} - -function log(level: LogLevel, message: string, meta: LogMeta | undefined, moduleName: string) { - if (!shouldLog(level, moduleName)) return; - - const entry = buildLogEntry(level, message, meta, moduleName); - recordLog(entry); -} - -export interface Logger { - debug(message: string, meta?: LogMeta): void; - info(message: string, meta?: LogMeta): void; - warn(message: string, meta?: LogMeta): void; - error(message: string, meta?: LogMeta): void; - child(moduleName: string): Logger; - withContext(context: LogContext | string, fn: () => T): T; - getCorrelationId(): string; - createCorrelationId(): string; -} - -function createLogger(moduleName: string): Logger { - const logger = { - debug: (message: string, meta?: LogMeta) => log('debug', message, meta, moduleName), - info: (message: string, meta?: LogMeta) => log('info', message, meta, moduleName), - warn: (message: string, meta?: LogMeta) => log('warn', message, meta, moduleName), - error: (message: string, meta?: LogMeta) => log('error', message, meta, moduleName), - child: (childModule: string) => createLogger(`${moduleName}:${childModule}`), - withContext: (context: LogContext | string, fn: () => T): T => { - const store: LogContext = typeof context === 'string' ? { correlationId: context } : context; - return asyncLocalStorage.run(store, fn); - }, - getCorrelationId: (): string => getCurrentContext().correlationId || '', - createCorrelationId: generateId, - }; - - return logger; -} - -export function queryLogs(filter: { - level?: LogLevel; - module?: string; - correlationId?: string; - text?: string; - from?: string; - to?: string; -} = {}): LogEntry[] { - return inMemoryLogBuffer.filter((entry) => { - if (filter.level && entry.level !== filter.level) return false; - if (filter.module && !entry.module.includes(filter.module)) return false; - if (filter.correlationId && entry.correlationId !== filter.correlationId) return false; - if (filter.text && !entry.message.includes(filter.text) && !(entry.meta && JSON.stringify(entry.meta).includes(filter.text))) return false; - if (filter.from && entry.timestamp < filter.from) return false; - if (filter.to && entry.timestamp > filter.to) return false; - return true; - }); -} - -export function clearLogBuffer(): void { - inMemoryLogBuffer.length = 0; -} - -export const logger = createLogger('backend'); -export const createLoggerFor = createLogger; -export const runWithLogContext = (context: LogContext | string, fn: () => T): T => { - const store: LogContext = typeof context === 'string' ? { correlationId: context } : context; - return asyncLocalStorage.run(store, fn); -}; +/** + * backend/services/logging.ts + * + * Issue #910 — Structured logging with correlation IDs + * + * Top-level re-export so service files can import from the shorter path + * `../services/logging` instead of the full shared path. + * + * All heavy logic lives in backend/services/shared/logging.ts. + */ + +export { + logger, + createLoggerFor, + runWithLogContext, + withCorrelationId, + correlationIdStorage, + queryLogs, + clearLogBuffer, + setLogRedactionLevel, +} from './shared/logging'; + +export type { LogLevel, LogContext, LogMeta, LogEntry, Logger } from './shared/logging'; diff --git a/backend/services/shared/logging.ts b/backend/services/shared/logging.ts index 1f482e32..70daf938 100644 --- a/backend/services/shared/logging.ts +++ b/backend/services/shared/logging.ts @@ -1,15 +1,82 @@ +/** + * backend/services/shared/logging.ts + * + * Issue #910 — Implement structured logging with correlation IDs + * + * Production-grade structured logger for SubTrackr backend. + * + * Features: + * - JSON-structured log output (compatible with log aggregators) + * - Correlation ID propagation via AsyncLocalStorage (survives async boundaries) + * - Module-scoped child loggers (logger.child('payments')) + * - Per-module log-level overrides via BACKEND_LOG_LEVELS env var + * - Sensitive field redaction via PiiClassifier + * - In-memory ring-buffer for test assertion and dashboard queries + * - Remote log forwarding (Elasticsearch via logStorage) for errors + * - runWithLogContext() for request-scoped correlation ID injection + */ + import { piiClassifier, type ClassificationLevel } from './piiClassifier'; import { AsyncLocalStorage } from 'node:async_hooks'; import { logStorage } from '../../elasticsearch/logStorage'; +// ───────────────────────────────────────────────────────────────────────────── +// Types +// ───────────────────────────────────────────────────────────────────────────── + export type LogLevel = 'debug' | 'info' | 'warn' | 'error'; -export const correlationIdStorage = new AsyncLocalStorage(); +export interface LogContext { + [key: string]: unknown; + correlationId?: string; +} -export function withCorrelationId(correlationId: string, fn: () => T): T { - return correlationIdStorage.run(correlationId, fn); +export interface LogMeta { + [key: string]: unknown; +} + +export interface LogEntry { + timestamp: string; + service: string; + module: string; + level: LogLevel; + message: string; + correlationId?: string; + meta?: LogMeta; } +export interface Logger { + debug(message: string, meta?: LogMeta): void; + info(message: string, meta?: LogMeta): void; + warn(message: string, meta?: LogMeta): void; + error(message: string, meta?: LogMeta): void; + /** Create a child logger with an extended module name. */ + child(moduleName: string): Logger; + /** Run fn inside an async context that carries the given correlationId. */ + withContext(context: LogContext | string, fn: () => T): T; + /** Return the correlationId active in the current async context (or ''). */ + getCorrelationId(): string; + /** Generate a new random correlation ID. */ + createCorrelationId(): string; + /** Set the PII redaction level for this logger. */ + setRedactionLevel(level: ClassificationLevel): void; +} + +// ───────────────────────────────────────────────────────────────────────────── +// Configuration (environment-driven) +// ───────────────────────────────────────────────────────────────────────────── + +const SERVICE_NAME = process.env.LOG_SERVICE_NAME ?? 'subtrackr-backend'; +const REMOTE_LOG_ENDPOINT = process.env.LOG_REMOTE_ENDPOINT ?? ''; +const DEFAULT_LOG_LEVEL: LogLevel = + (process.env.BACKEND_LOG_LEVEL as LogLevel | undefined) ?? + (typeof (globalThis as { __DEV__?: boolean }).__DEV__ !== 'undefined' && + (globalThis as { __DEV__?: boolean }).__DEV__ + ? 'debug' + : 'info'); + +const BUFFER_SIZE = Number(process.env.LOG_BUFFER_SIZE ?? 200); + const LOG_LEVEL_PRIORITY: Record = { debug: 0, info: 1, @@ -17,83 +84,233 @@ const LOG_LEVEL_PRIORITY: Record = { error: 3, }; -// Change this via env later (__DEV__ is an Expo/RN global; absent in plain Node) -const CURRENT_LEVEL: LogLevel = - typeof (globalThis as { __DEV__?: boolean }).__DEV__ !== 'undefined' && - (globalThis as { __DEV__?: boolean }).__DEV__ - ? 'debug' - : 'info'; +// ───────────────────────────────────────────────────────────────────────────── +// Per-module level overrides +// Format: BACKEND_LOG_LEVELS=payments:debug,auth:warn +// ───────────────────────────────────────────────────────────────────────────── -// Correlation ID generator (simple version) -const generateId = () => { - return Math.random().toString(36).substring(2) + Date.now().toString(36); -}; +function parseModuleLevels(envValue: string): Record { + return envValue.split(',').reduce( + (acc, pair) => { + const [mod, level] = pair.split(':').map((p) => p.trim()); + if (mod && level && ['debug', 'info', 'warn', 'error'].includes(level)) { + acc[mod] = level as LogLevel; + } + return acc; + }, + {} as Record, + ); +} -export interface LogContext { - [key: string]: any; - correlationId?: string; +const MODULE_LOG_LEVELS = parseModuleLevels(process.env.BACKEND_LOG_LEVELS ?? ''); + +function getModuleLevel(moduleName: string): LogLevel { + const exact = MODULE_LOG_LEVELS[moduleName]; + if (exact) return exact; + const prefix = Object.keys(MODULE_LOG_LEVELS).find((k) => moduleName.startsWith(`${k}:`)); + return prefix ? MODULE_LOG_LEVELS[prefix] : DEFAULT_LOG_LEVEL; +} + +function shouldLog(level: LogLevel, moduleName: string): boolean { + return LOG_LEVEL_PRIORITY[level] >= LOG_LEVEL_PRIORITY[getModuleLevel(moduleName)]; } -// ─── PII redaction for structured log context ───────────────────────────────── +// ───────────────────────────────────────────────────────────────────────────── +// Correlation ID — stored in AsyncLocalStorage so it flows across awaits +// ───────────────────────────────────────────────────────────────────────────── + +export const correlationIdStorage = new AsyncLocalStorage(); + +export function withCorrelationId(correlationId: string, fn: () => T): T { + return correlationIdStorage.run(correlationId, fn); +} + +const generateId = (): string => + `${Date.now().toString(36)}-${Math.random().toString(36).substring(2, 8)}`; + +// ───────────────────────────────────────────────────────────────────────────── +// PII redaction +// ───────────────────────────────────────────────────────────────────────────── -let _logRedactionLevel: ClassificationLevel = 'standard'; +let _globalRedactionLevel: ClassificationLevel = 'standard'; -/** Set the classification level used for log PII redaction (default: standard). */ export function setLogRedactionLevel(level: ClassificationLevel): void { - _logRedactionLevel = level; + _globalRedactionLevel = level; } -function sanitizeContext(ctx: LogContext | undefined): LogContext | undefined { - if (!ctx) return ctx; - return piiClassifier.redact(ctx, { level: _logRedactionLevel }) as LogContext; +function sanitizeMeta(meta: LogMeta | undefined, level: ClassificationLevel): LogMeta | undefined { + if (!meta) return undefined; + return piiClassifier.redact(meta as Record, { level }) as LogMeta; } -function shouldLog(level: LogLevel) { - return LOG_LEVEL_PRIORITY[level] >= LOG_LEVEL_PRIORITY[CURRENT_LEVEL]; +// ───────────────────────────────────────────────────────────────────────────── +// In-memory ring buffer (for tests + dashboard queries) +// ───────────────────────────────────────────────────────────────────────────── + +const inMemoryLogBuffer: LogEntry[] = []; + +function enqueue(entry: LogEntry): void { + inMemoryLogBuffer.push(entry); + while (inMemoryLogBuffer.length > BUFFER_SIZE) { + inMemoryLogBuffer.shift(); + } } -function formatLog(level: LogLevel, message: string, context?: LogContext) { - return { - level, - message, - timestamp: new Date().toISOString(), - ...context, - }; +/** Query the in-memory log buffer. Useful in tests and the log dashboard. */ +export function queryLogs( + filter: { + level?: LogLevel; + module?: string; + correlationId?: string; + text?: string; + from?: string; + to?: string; + } = {}, +): LogEntry[] { + return inMemoryLogBuffer.filter((entry) => { + if (filter.level && entry.level !== filter.level) return false; + if (filter.module && !entry.module.includes(filter.module)) return false; + if (filter.correlationId && entry.correlationId !== filter.correlationId) return false; + if ( + filter.text && + !entry.message.includes(filter.text) && + !(entry.meta && JSON.stringify(entry.meta).includes(filter.text)) + ) + return false; + if (filter.from && entry.timestamp < filter.from) return false; + if (filter.to && entry.timestamp > filter.to) return false; + return true; + }); } -function sendToConsole(logEntry: any) { - console.log(JSON.stringify(logEntry)); +/** Clear the in-memory buffer — useful in beforeEach test hooks. */ +export function clearLogBuffer(): void { + inMemoryLogBuffer.length = 0; } -async function sendToRemote(logEntry: any) { +// ───────────────────────────────────────────────────────────────────────────── +// Output sinks +// ───────────────────────────────────────────────────────────────────────────── + +function sendToConsole(entry: LogEntry): void { + console.log(JSON.stringify(entry)); +} + +async function sendToRemote(entry: LogEntry): Promise { + // Forward errors to Elasticsearch logStorage if configured try { - await logStorage.insertLog(logEntry); + await logStorage.insertLog(entry); } catch (e) { + // Don't throw — logging must never crash the application console.error('Failed to forward log to logStorage', e); } + + // Optional HTTP sink for critical alerts + if (!REMOTE_LOG_ENDPOINT) return; + try { + await fetch(REMOTE_LOG_ENDPOINT, { + method: 'POST', + headers: { 'Content-Type': 'application/json' }, + body: JSON.stringify(entry), + }); + } catch { + // Silently swallow — remote logging is best-effort + } } -function log(level: LogLevel, message: string, context?: LogContext) { - if (!shouldLog(level)) return; +// ───────────────────────────────────────────────────────────────────────────── +// Core log function +// ───────────────────────────────────────────────────────────────────────────── - const currentCorrelationId = correlationIdStorage.getStore(); - const mergedContext = { - correlationId: currentCorrelationId, - ...context +function logRecord( + level: LogLevel, + message: string, + meta: LogMeta | undefined, + moduleName: string, + redactionLevel: ClassificationLevel, +): void { + if (!shouldLog(level, moduleName)) return; + + const correlationId = correlationIdStorage.getStore() ?? undefined; + + const entry: LogEntry = { + timestamp: new Date().toISOString(), + service: SERVICE_NAME, + module: moduleName, + level, + message, + correlationId, + meta: sanitizeMeta(meta, redactionLevel), }; - const logEntry = formatLog(level, message, sanitizeContext(mergedContext)); + // Strip undefined keys for clean JSON + if (entry.correlationId === undefined) delete entry.correlationId; + if (entry.meta === undefined) delete entry.meta; + + enqueue(entry); + sendToConsole(entry); - sendToConsole(logEntry); - void sendToRemote(logEntry); + // Forward errors (and remote-endpoint-configured logs) asynchronously + if (level === 'error' || REMOTE_LOG_ENDPOINT) { + void sendToRemote(entry); + } } -export const logger = { - debug: (msg: string, ctx?: LogContext) => log('debug', msg, ctx), - info: (msg: string, ctx?: LogContext) => log('info', msg, ctx), - warn: (msg: string, ctx?: LogContext) => log('warn', msg, ctx), - error: (msg: string, ctx?: LogContext) => log('error', msg, ctx), +// ───────────────────────────────────────────────────────────────────────────── +// Logger factory +// ───────────────────────────────────────────────────────────────────────────── + +function createLogger(moduleName: string, redactionLevel: ClassificationLevel = _globalRedactionLevel): Logger { + let _redactionLevel = redactionLevel; + + const instance: Logger = { + debug: (message, meta) => logRecord('debug', message, meta, moduleName, _redactionLevel), + info: (message, meta) => logRecord('info', message, meta, moduleName, _redactionLevel), + warn: (message, meta) => logRecord('warn', message, meta, moduleName, _redactionLevel), + error: (message, meta) => logRecord('error', message, meta, moduleName, _redactionLevel), + + child: (childModule) => createLogger(`${moduleName}:${childModule}`, _redactionLevel), + + withContext: (context: LogContext | string, fn: () => T): T => { + const correlationId = + typeof context === 'string' ? context : (context.correlationId ?? generateId()); + return correlationIdStorage.run(correlationId, fn); + }, + + getCorrelationId: () => correlationIdStorage.getStore() ?? '', + + createCorrelationId: generateId, - createCorrelationId: generateId, - setRedactionLevel: setLogRedactionLevel, + setRedactionLevel: (level) => { + _redactionLevel = level; + }, + }; + + return instance; +} + +// ───────────────────────────────────────────────────────────────────────────── +// Public API +// ───────────────────────────────────────────────────────────────────────────── + +/** Root logger — use `.child('module')` to get module-scoped loggers. */ +export const logger = createLogger('backend'); + +/** Create a named logger for a specific module. */ +export const createLoggerFor = (moduleName: string): Logger => createLogger(moduleName); + +/** + * Run `fn` in an async context that carries the given correlation ID (or full + * LogContext). All logger calls inside fn (and any awaited code) will + * automatically attach this correlation ID. + * + * @example + * app.use((req, res, next) => { + * runWithLogContext(req.headers['x-correlation-id'] || generateId(), next); + * }); + */ +export const runWithLogContext = (context: LogContext | string, fn: () => T): T => { + const correlationId = + typeof context === 'string' ? context : (context.correlationId ?? generateId()); + return correlationIdStorage.run(correlationId, fn); }; diff --git a/backend/services/shared/rateLimitMiddleware.ts b/backend/services/shared/rateLimitMiddleware.ts index 98820219..592649eb 100644 --- a/backend/services/shared/rateLimitMiddleware.ts +++ b/backend/services/shared/rateLimitMiddleware.ts @@ -1,7 +1,7 @@ /** * Rate Limit Middleware — SubTrackr * - * Issue #998: Implement rate limiting with token bucket algorithm + * Issue #913: Implement rate limiting per user and per API key * * Express / Fastify-compatible middleware that integrates RateLimitingService * (token bucket + sliding-window counters) with standard HTTP headers. @@ -281,3 +281,67 @@ export function createIpRateLimitMiddleware(opts: Omit, +) { + const { + service, + getApiKey = (req) => { + const auth = req.headers['authorization']; + if (typeof auth === 'string' && auth.startsWith('Bearer ')) return auth.slice(7).trim(); + const xKey = req.headers['x-api-key']; + return typeof xKey === 'string' ? xKey.trim() : undefined; + }, + getTier = () => SubscriptionTier.FREE, + } = opts; + + return async function rateLimitStatusMiddleware( + req: MinimalRequest, + res: MinimalResponse, + next: NextFn, + ): Promise { + const apiKey = getApiKey(req); + if (apiKey) { + const tier = await getTier(apiKey, req); + const status = service.getRateLimitStatus(apiKey, tier); + setHeader(res, RATE_LIMIT_HEADERS.LIMIT, String(status.limits.hourlyLimit)); + setHeader(res, RATE_LIMIT_HEADERS.REMAINING, String(status.remaining.hourly)); + setHeader(res, RATE_LIMIT_HEADERS.RESET, String(Math.ceil(status.resetAt.hourly / 1_000))); + setHeader(res, RATE_LIMIT_HEADERS.BURST_REMAINING, String(status.remaining.burstTokens)); + } + next(); + }; +} diff --git a/backend/services/shared/rpcResilienceMiddleware.ts b/backend/services/shared/rpcResilienceMiddleware.ts index 1b9e8cd5..3e365eed 100644 --- a/backend/services/shared/rpcResilienceMiddleware.ts +++ b/backend/services/shared/rpcResilienceMiddleware.ts @@ -1,5 +1,5 @@ /** - * rpcResilienceMiddleware.ts — Issue #941 + * rpcResilienceMiddleware.ts — Issue #912 * * Higher-level integration layer that wires together: * - RpcCircuitBreakerService (backend/services/rpcCircuitBreaker.ts) diff --git a/backend/services/shared/rpcTimeout.ts b/backend/services/shared/rpcTimeout.ts index a8bbc556..4d003a31 100644 --- a/backend/services/shared/rpcTimeout.ts +++ b/backend/services/shared/rpcTimeout.ts @@ -1,5 +1,5 @@ /** - * rpcTimeout.ts — Issue #941 + * rpcTimeout.ts — Issue #912 * * Production-grade timeout primitives for external blockchain RPC calls. * diff --git a/jest.backend.config.js b/jest.backend.config.js index 9cd04467..2dbf9e69 100644 --- a/jest.backend.config.js +++ b/jest.backend.config.js @@ -21,4 +21,24 @@ module.exports = { ], }, moduleFileExtensions: ['ts', 'js', 'json'], + // Coverage settings — aligned with Stryker break threshold (issue #914) + collectCoverageFrom: [ + 'backend/**/*.ts', + '!backend/**/*.test.ts', + '!backend/**/*.spec.ts', + '!backend/**/__tests__/**', + '!backend/**/*.d.ts', + '!backend/migrations/**', + '!backend/server.ts', + '!backend/server/**', + ], + coverageThreshold: { + global: { + branches: 50, + functions: 60, + lines: 60, + statements: 60, + }, + }, + coverageReporters: ['text', 'lcov', 'json-summary'], }; diff --git a/jest.config.js b/jest.config.js index b5c25788..a0b271d2 100644 --- a/jest.config.js +++ b/jest.config.js @@ -24,7 +24,23 @@ module.exports = { '))', ], moduleFileExtensions: ['ts', 'tsx', 'js', 'jsx', 'json', 'node'], - collectCoverageFrom: ['src/**/*.{ts,tsx}', '!src/**/*.d.ts', '!src/**/index.ts'], + collectCoverageFrom: [ + 'src/**/*.{ts,tsx}', + '!src/**/*.d.ts', + '!src/**/index.ts', + '!src/animations/**', + '!src/i18n/**', + ], + // Minimum coverage gates — aligned with Stryker break threshold (issue #914) + coverageThreshold: { + global: { + branches: 60, + functions: 70, + lines: 70, + statements: 70, + }, + }, + coverageReporters: ['text', 'lcov', 'json-summary'], testMatch: ['**/__tests__/**/*.(test|spec).[jt]s?(x)', '**/?(*.)+(spec|test).[jt]s?(x)'], modulePathIgnorePatterns: ['/e2e'], testPathIgnorePatterns: [ diff --git a/ml-service/main.py b/ml-service/main.py index 3825e620..44b6c2c8 100644 --- a/ml-service/main.py +++ b/ml-service/main.py @@ -1,37 +1,60 @@ +""" +ml-service/main.py + +Issue #910 — Structured logging with correlation IDs for ml-service. + +FastAPI application exposing SubTrackr ML endpoints. Every HTTP request is +automatically stamped with a correlation ID (read from X-Correlation-ID header +or freshly generated) that propagates through all structured log lines for that +request via a ContextVar, making distributed tracing trivial. +""" + +import os import uuid import time import logging import json -from contextlib import asynccontextmanager from contextvars import ContextVar +from typing import Any, Dict, List, Optional from fastapi import FastAPI, HTTPException, Request, Response -from pydantic import BaseModel -from typing import List, Dict, Optional +from pydantic import BaseModel, Field + from models import ChurnPredictionModel, RevenueForecastModel +from model_registry import registry # ────────────────────────────────────────────────────────────────────────────── -# Structured logging with correlation IDs (issue #939) +# Structured logging with correlation IDs (issue #910) # ────────────────────────────────────────────────────────────────────────────── # Context var that holds the current correlation ID for the active request. +# Using ContextVar (not threading.local) so it works correctly with asyncio. _correlation_id: ContextVar[str] = ContextVar("correlation_id", default="") class StructuredLogger: - """JSON-formatted logger that automatically injects the active correlation ID.""" + """ + JSON-formatted logger that automatically injects the active correlation ID + from the current async context into every log entry. + + Usage:: + + logger.info("model_loaded", version="v1.1") + logger.error("predict_failed", subscriber=req.subscriber, error=str(e)) + """ def __init__(self, service: str = "ml-service") -> None: self._service = service self._raw = logging.getLogger(service) if not self._raw.handlers: handler = logging.StreamHandler() + # Emit the pre-serialised JSON string as-is. handler.setFormatter(logging.Formatter("%(message)s")) self._raw.addHandler(handler) self._raw.setLevel(logging.DEBUG) - def _emit(self, level: str, message: str, **extra) -> None: - entry = { + def _emit(self, level: str, message: str, **extra: Any) -> None: + entry: Dict[str, Any] = { "level": level, "message": message, "service": self._service, @@ -39,29 +62,31 @@ def _emit(self, level: str, message: str, **extra) -> None: "timestamp": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime()), **extra, } - # Strip None values to keep logs clean + # Strip None values to keep log payloads clean. entry = {k: v for k, v in entry.items() if v is not None} - getattr(self._raw, level if level != "warning" else "warning")( - json.dumps(entry) - ) - def debug(self, message: str, **extra) -> None: + # Map our level strings to the stdlib logging methods. + log_method = getattr(self._raw, level if level != "warning" else "warning", self._raw.info) + log_method(json.dumps(entry)) + + def debug(self, message: str, **extra: Any) -> None: self._emit("debug", message, **extra) - def info(self, message: str, **extra) -> None: + def info(self, message: str, **extra: Any) -> None: self._emit("info", message, **extra) - def warning(self, message: str, **extra) -> None: + def warning(self, message: str, **extra: Any) -> None: self._emit("warning", message, **extra) - def error(self, message: str, **extra) -> None: + def error(self, message: str, **extra: Any) -> None: self._emit("error", message, **extra) +# Module-level singleton logger used throughout this file. logger = StructuredLogger() # ────────────────────────────────────────────────────────────────────────────── -# Application +# FastAPI application # ────────────────────────────────────────────────────────────────────────────── app = FastAPI(title="SubTrackr ML Service", version="1.0.0") @@ -70,11 +95,11 @@ def error(self, message: str, **extra) -> None: # ── Correlation-ID middleware ────────────────────────────────────────────────── @app.middleware("http") -async def correlation_id_middleware(request: Request, call_next) -> Response: +async def correlation_id_middleware(request: Request, call_next: Any) -> Response: """ - Reads X-Correlation-ID from the incoming request (or generates a new UUID - if absent), stores it in the context var, injects it into the response, and - records basic request/response telemetry via the structured logger. + Reads X-Correlation-ID from the incoming request (or generates a new UUID4 + if absent), stores it in the ContextVar, injects it into the response header, + and records request/response telemetry through the structured logger. """ correlation_id = request.headers.get("X-Correlation-ID") or str(uuid.uuid4()) token = _correlation_id.set(correlation_id) @@ -86,8 +111,9 @@ async def correlation_id_middleware(request: Request, call_next) -> Response: path=request.url.path, ) + response: Response try: - response: Response = await call_next(request) + response = await call_next(request) except Exception as exc: logger.error( "request_error", @@ -112,10 +138,10 @@ async def correlation_id_middleware(request: Request, call_next) -> Response: # ────────────────────────────────────────────────────────────────────────────── -# Pydantic models +# Pydantic request/response models # ────────────────────────────────────────────────────────────────────────────── -class UserData(BaseModel): +class UserChurnData(BaseModel): recent_payment_failures: float baseline_logins_per_month: float recent_logins: float @@ -125,7 +151,7 @@ class UserData(BaseModel): class PredictRequest(BaseModel): subscriber: str - user_data: UserData + user_data: UserChurnData class BatchPredictItem(BaseModel): @@ -134,14 +160,10 @@ class BatchPredictItem(BaseModel): class BatchChurnPredictRequest(BaseModel): - items: List[BatchChurnPredictItem] = Field(..., min_length=1, max_length=500) + items: List[BatchPredictItem] = Field(..., min_length=1, max_length=500) -class BatchPredictRequest(BaseModel): - items: List[BatchPredictItem] - - -class Observation(BaseModel): +class RevenueObservation(BaseModel): period: str revenue: float @@ -152,11 +174,15 @@ class ForecastRequest(BaseModel): class InterventionRequest(BaseModel): - subscribers: List[str] = Field(..., min_length=1, max_length=500, description="List of subscriber IDs to evaluate") + subscribers: List[str] = Field( + ..., min_length=1, max_length=500, description="Subscriber IDs to evaluate" + ) user_data_map: Dict[str, UserChurnData] = Field( ..., description="Map of subscriber_id -> user data" ) - risk_threshold: str = Field("High", description="Minimum risk level that triggers an intervention ('High' or 'Medium')") + risk_threshold: str = Field( + "High", description="Minimum risk level that triggers an intervention ('High' or 'Medium')" + ) class RetrainRequest(BaseModel): @@ -165,7 +191,6 @@ class RetrainRequest(BaseModel): ) - # ────────────────────────────────────────────────────────────────────────────── # Model initialisation # ────────────────────────────────────────────────────────────────────────────── @@ -186,10 +211,12 @@ class RetrainRequest(BaseModel): # ────────────────────────────────────────────────────────────────────────────── @app.post("/v1/churn/predict") -async def predict_churn(req: PredictRequest): +async def predict_churn(req: PredictRequest) -> Dict[str, Any]: logger.info("predict_churn", subscriber=req.subscriber) try: - prediction = churn_model.predict_churn(req.subscriber, req.user_data.model_dump()) + prediction: Dict[str, Any] = churn_model.predict_churn( + req.subscriber, req.user_data.model_dump() + ) prediction["model_version"] = "v1.1" if custom_weights else "v1.0" return prediction except Exception as e: @@ -198,12 +225,14 @@ async def predict_churn(req: PredictRequest): @app.post("/v1/churn/predict/batch") -async def predict_churn_batch(req: BatchPredictRequest): +async def predict_churn_batch(req: BatchChurnPredictRequest) -> Dict[str, Any]: logger.info("predict_churn_batch", count=len(req.items)) - results = [] + results: List[Dict[str, Any]] = [] for item in req.items: try: - pred = churn_model.predict_churn(item.subscriber, item.user_data.model_dump()) + pred: Dict[str, Any] = churn_model.predict_churn( + item.subscriber, item.user_data.model_dump() + ) pred["ok"] = True results.append(pred) except Exception as e: @@ -221,7 +250,7 @@ async def predict_churn_batch(req: BatchPredictRequest): @app.post("/v1/churn/forecast") -async def forecast_revenue(req: ForecastRequest): +async def forecast_revenue(req: ForecastRequest) -> Dict[str, Any]: logger.info("forecast_revenue", horizon=req.horizon, observations=len(req.observations)) try: observations = [obs.model_dump() for obs in req.observations] @@ -233,22 +262,27 @@ async def forecast_revenue(req: ForecastRequest): @app.post("/v1/models/retrain") -async def retrain_model(): +async def retrain_model(req: Optional[RetrainRequest] = None) -> Dict[str, Any]: """Trigger the retraining pipeline.""" logger.info("model_retrain_triggered") - new_version = registry.retrain_model([]) + samples = (req.training_samples if req and req.training_samples else []) or [] + new_version: str = registry.retrain_model(samples) new_weights = registry.load_model(new_version) - if new_weights: + if new_weights and "feature_weights" in new_weights: churn_model.feature_weights = new_weights["feature_weights"] logger.info("model_weights_reloaded", version=new_version) return {"status": "success", "new_version": new_version} @app.get("/healthz") -async def health(): +async def health() -> Dict[str, str]: return {"status": "ok", "service": "ml-service"} +# ────────────────────────────────────────────────────────────────────────────── +# Entrypoint +# ────────────────────────────────────────────────────────────────────────────── + if __name__ == "__main__": import uvicorn diff --git a/package.json b/package.json index cfcea65b..d7849309 100644 --- a/package.json +++ b/package.json @@ -19,7 +19,10 @@ "test": "jest --passWithNoTests", "test:coverage": "jest --coverage", "performance:ci": "node scripts/check-performance-budget.js", - "mutation:test": "npx --yes @stryker-mutator/core@9.0.0 run", + "mutation:test": "npx --yes @stryker-mutator/core@9.0.0 run --config stryker.conf.json", + "mutation:test:backend": "npx --yes @stryker-mutator/core@9.0.0 run --config stryker.backend.conf.json", + "mutation:test:ci": "npx --yes @stryker-mutator/core@9.0.0 run --config stryker.conf.json --reporters progress,clear-text,json", + "mutation:test:backend:ci": "npx --yes @stryker-mutator/core@9.0.0 run --config stryker.backend.conf.json --reporters progress,clear-text,json", "dr:test": "jest --config jest.backend.config.js backend/dr/__tests__ --passWithNoTests", "dr:test:coverage": "jest --config jest.backend.config.js backend/dr/__tests__ --coverage --collectCoverageFrom=\"backend/dr/**/*.ts\"", "dr:benchmark": "jest --config jest.backend.config.js backend/dr/__tests__/dr.benchmark --no-coverage --verbose", diff --git a/reports/mutation/README.md b/reports/mutation/README.md new file mode 100644 index 00000000..2d2e9616 --- /dev/null +++ b/reports/mutation/README.md @@ -0,0 +1,37 @@ +# Mutation Testing Reports + +This directory contains Stryker mutation testing reports generated by: + +```bash +# Frontend (src/) +npm run mutation:test + +# Backend (backend/) +npm run mutation:test:backend + +# CI variants (JSON output, no dashboard upload) +npm run mutation:test:ci +npm run mutation:test:backend:ci +``` + +## Thresholds (issue #914) + +| Metric | High | Low | Break (fails CI) | +|--------|------|-----|-----------------| +| Mutation score | ≥ 80 % | ≥ 60 % | < 50 % | + +## Output files + +| Path | Description | +|------|-------------| +| `reports/mutation/frontend/mutation.html` | Interactive HTML report — frontend | +| `reports/mutation/frontend/mutation.json` | Machine-readable JSON — frontend | +| `reports/mutation/backend/mutation.html` | Interactive HTML report — backend | +| `reports/mutation/backend/mutation.json` | Machine-readable JSON — backend | + +## Configuration files + +| File | Scope | +|------|-------| +| `stryker.conf.json` | Frontend (`src/**`) | +| `stryker.backend.conf.json` | Backend (`backend/**`) | diff --git a/reports/mutation/backend/.gitkeep b/reports/mutation/backend/.gitkeep new file mode 100644 index 00000000..e69de29b diff --git a/reports/mutation/frontend/.gitkeep b/reports/mutation/frontend/.gitkeep new file mode 100644 index 00000000..e69de29b diff --git a/stryker.backend.conf.json b/stryker.backend.conf.json index 696eca43..5acc29cf 100644 --- a/stryker.backend.conf.json +++ b/stryker.backend.conf.json @@ -1,6 +1,7 @@ { "$schema": "./node_modules/@stryker-mutator/core/schema/stryker-schema.json", "schemaVersion": "1.0", + "mutate": [ "backend/**/*.ts", "!backend/**/*.test.ts", @@ -8,32 +9,61 @@ "!backend/**/__tests__/**", "!backend/**/__mocks__/**", "!backend/**/__fixtures__/**", - "!backend/**/*.d.ts" + "!backend/**/*.d.ts", + "!backend/migrations/**", + "!backend/server.ts", + "!backend/server/**" ], + "testRunner": "jest", "jest": { "projectType": "custom", - "configFile": "jest.backend.config.js" + "configFile": "jest.backend.config.js", + "enableFindRelatedTests": true }, + "checkers": ["typescript"], "typescriptChecker": { "tsconfigFile": "backend/tsconfig.json" }, - "reporters": ["progress", "clear-text", "html", "dashboard"], + + "reporters": ["progress", "clear-text", "html", "json", "dashboard"], + "htmlReporter": { + "fileName": "reports/mutation/backend/mutation.html" + }, + "jsonReporter": { + "fileName": "reports/mutation/backend/mutation.json" + }, + "coverageAnalysis": "perTest", "concurrency": 4, + "thresholds": { "high": 80, "low": 60, "break": 50 }, + "tempDirName": ".stryker-backend-tmp", "cleanTempDir": true, + "dashboard": { "project": "github.com/Smartdevs17/SubTrackr", "version": "main", "module": "backend" }, + "timeoutMS": 60000, - "plugins": ["@stryker-mutator/jest-runner", "@stryker-mutator/typescript-checker"] + "timeoutFactor": 2.0, + "maxTestRunnerReuse": 50, + + "ignorePatterns": [ + ".stryker-backend-tmp", + "node_modules" + ], + + "plugins": [ + "@stryker-mutator/jest-runner", + "@stryker-mutator/typescript-checker" + ] } diff --git a/stryker.conf.json b/stryker.conf.json index 0ebfccfe..44b0db8a 100644 --- a/stryker.conf.json +++ b/stryker.conf.json @@ -1,6 +1,7 @@ { "$schema": "./node_modules/@stryker-mutator/core/schema/stryker-schema.json", "schemaVersion": "1.0", + "mutate": [ "src/**/*.{ts,tsx}", "!src/**/*.test.{ts,tsx}", @@ -8,32 +9,61 @@ "!src/**/__tests__/**", "!src/**/__mocks__/**", "!src/**/__fixtures__/**", - "!src/**/*.d.ts" + "!src/**/*.d.ts", + "!src/**/index.ts", + "!src/animations/**", + "!src/i18n/**" ], + "testRunner": "jest", "jest": { "projectType": "custom", - "configFile": "jest.config.js" + "configFile": "jest.config.js", + "enableFindRelatedTests": true }, + "checkers": ["typescript"], "typescriptChecker": { "tsconfigFile": "tsconfig.json" }, - "reporters": ["progress", "clear-text", "html", "dashboard"], + + "reporters": ["progress", "clear-text", "html", "json", "dashboard"], + "htmlReporter": { + "fileName": "reports/mutation/frontend/mutation.html" + }, + "jsonReporter": { + "fileName": "reports/mutation/frontend/mutation.json" + }, + "coverageAnalysis": "perTest", "concurrency": 4, + "thresholds": { "high": 80, "low": 60, "break": 50 }, + "tempDirName": ".stryker-tmp", "cleanTempDir": true, + "dashboard": { "project": "github.com/Smartdevs17/SubTrackr", "version": "main", "module": "frontend" }, + "timeoutMS": 60000, - "plugins": ["@stryker-mutator/jest-runner", "@stryker-mutator/typescript-checker"] + "timeoutFactor": 2.0, + "maxTestRunnerReuse": 50, + + "ignorePatterns": [ + ".stryker-tmp", + "node_modules" + ], + + "plugins": [ + "@stryker-mutator/jest-runner", + "@stryker-mutator/typescript-checker" + ] }