From e59ac5f9cca4fba9f3be0b6eba1d2e4a5c220416 Mon Sep 17 00:00:00 2001 From: ravendevhub Date: Sat, 29 Aug 2026 13:53:09 +0630 Subject: [PATCH] feat(api): add high-precision request duration logging middleware (#687) - Measure HTTP request durations using monotonic high-resolution timers - Emit structured access logs with method, path, status, durationMs, and requestId - Sanitize query strings and paths preventing secret leakage in access logs - Add unit test suite in request-duration-logger.test.ts and docs in docs/API_REQUEST_DURATION_LOGGING.md --- docs/API_REQUEST_DURATION_LOGGING.md | 33 +++++++++ .../src/api/request-duration-logger.test.ts | 73 +++++++++++++++++++ listener/src/api/request-duration-logger.ts | 60 +++++++++++++++ 3 files changed, 166 insertions(+) create mode 100644 docs/API_REQUEST_DURATION_LOGGING.md create mode 100644 listener/src/api/request-duration-logger.test.ts create mode 100644 listener/src/api/request-duration-logger.ts diff --git a/docs/API_REQUEST_DURATION_LOGGING.md b/docs/API_REQUEST_DURATION_LOGGING.md new file mode 100644 index 00000000..70415726 --- /dev/null +++ b/docs/API_REQUEST_DURATION_LOGGING.md @@ -0,0 +1,33 @@ +# ⏱️ API Request Duration & Latency Logging + +This document details the high-precision request duration and structured access logging middleware for NotifyChain (Issue #687). + +--- + +## 1. Overview & Low Overhead + +To detect slow queries, database latency regressions, and network bottlenecks without introducing latency overhead, the request duration logger records high-resolution monotonic timestamps (`process.hrtime.bigint()`) on request entry and computes elapsed time when response streaming finishes (`res.on('finish')`). + +--- + +## 2. Structured Log Schema + +```json +{ + "level": "info", + "message": "HTTP GET /api/v1/health 200 - 1.45ms", + "method": "GET", + "path": "/api/v1/health", + "statusCode": 200, + "durationMs": 1.45, + "requestId": "req-9b1deb4d-3b7d-4bad-9bdd-2b0d7b3dcb6d", + "ip": "127.0.0.1", + "contentLength": 128 +} +``` + +--- + +## 3. Redaction & Privacy + +Query parameters containing secrets or private tokens (e.g. `?token=S...`) are automatically sanitized using `redactString` before emission to log transports. diff --git a/listener/src/api/request-duration-logger.test.ts b/listener/src/api/request-duration-logger.test.ts new file mode 100644 index 00000000..778990ee --- /dev/null +++ b/listener/src/api/request-duration-logger.test.ts @@ -0,0 +1,73 @@ +import { EventEmitter } from 'events'; +import { Request, Response, NextFunction } from 'express'; +import { createRequestDurationLogger } from './request-duration-logger'; + +describe('API Request Duration Logging (Issue #687)', () => { + test('measures request duration and logs structured metadata on finish', (done) => { + const mockLogger = { + info: jest.fn((msg: string, meta?: Record) => { + expect(msg).toContain('HTTP GET /api/v1/health 200'); + expect(meta?.method).toBe('GET'); + expect(meta?.path).toBe('/api/v1/health'); + expect(meta?.statusCode).toBe(200); + expect(meta?.durationMs).toBeGreaterThanOrEqual(0); + expect(meta?.requestId).toBe('req-12345'); + done(); + }), + }; + + const middleware = createRequestDurationLogger(mockLogger); + + const req = { + method: 'GET', + originalUrl: '/api/v1/health', + headers: { 'x-request-id': 'req-12345' }, + ip: '127.0.0.1', + } as unknown as Request; + + const resEmitter = new EventEmitter(); + const res = Object.assign(resEmitter, { + statusCode: 200, + getHeader: jest.fn().mockReturnValue('128'), + }) as unknown as Response; + + const next = jest.fn() as NextFunction; + + middleware(req, res, next); + expect(next).toHaveBeenCalledTimes(1); + + // Simulate completion + setTimeout(() => { + resEmitter.emit('finish'); + }, 10); + }); + + test('redacts sensitive secrets in query strings before logging', (done) => { + const secret = 'SCZANGBA5YHTNYVVV4C3U252E2B6P6IRKD45DCAHSKV2U2B6P6IRKD45'; + const mockLogger = { + info: jest.fn((msg: string, meta?: Record) => { + expect(msg).not.toContain(secret); + expect(meta?.path).not.toContain(secret); + expect(meta?.path).toContain('S[REDACTED_STELLAR_SECRET_KEY]'); + done(); + }), + }; + + const middleware = createRequestDurationLogger(mockLogger); + + const req = { + method: 'GET', + originalUrl: `/api/v1/export?token=${secret}`, + headers: {}, + } as unknown as Request; + + const resEmitter = new EventEmitter(); + const res = Object.assign(resEmitter, { + statusCode: 200, + getHeader: jest.fn(), + }) as unknown as Response; + + middleware(req, res, jest.fn()); + resEmitter.emit('finish'); + }); +}); diff --git a/listener/src/api/request-duration-logger.ts b/listener/src/api/request-duration-logger.ts new file mode 100644 index 00000000..13638d41 --- /dev/null +++ b/listener/src/api/request-duration-logger.ts @@ -0,0 +1,60 @@ +/** + * API Request Duration & Access Logging Middleware (Issue #687) + * + * Measures HTTP request execution duration with millisecond precision, + * logging structured access records without exposing sensitive query tokens or credentials. + */ + +import { Request, Response, NextFunction } from 'express'; +import logger from '../utils/logger'; +import { redactString } from '../utils/redact'; + +export interface RequestDurationLogData { + method: string; + path: string; + statusCode: number; + durationMs: number; + requestId?: string; + ip?: string; + contentLength?: number; +} + +/** + * Creates Express middleware that measures and logs API request durations. + */ +export function createRequestDurationLogger( + customLogger: { info: (msg: string, meta?: Record) => void } = logger +) { + return (req: Request, res: Response, next: NextFunction): void => { + const startTime = process.hrtime.bigint(); + + res.on('finish', () => { + const endTime = process.hrtime.bigint(); + // Calculate elapsed milliseconds with 2 decimal precision + const durationMs = Number((endTime - startTime) / BigInt(10000)) / 100; + + // Sanitize URL/path to prevent leaking secrets in query params + const rawUrl = req.originalUrl || req.url || '/'; + const sanitizedPath = redactString(rawUrl); + + const logData: RequestDurationLogData = { + method: req.method, + path: sanitizedPath, + statusCode: res.statusCode, + durationMs, + requestId: (req.headers['x-request-id'] as string) || (req as unknown as { id?: string }).id, + ip: req.ip || req.socket.remoteAddress, + contentLength: res.getHeader('content-length') + ? parseInt(String(res.getHeader('content-length')), 10) + : undefined, + }; + + const level = res.statusCode >= 500 ? 'error' : res.statusCode >= 400 ? 'warn' : 'info'; + const message = `HTTP ${req.method} ${sanitizedPath} ${res.statusCode} - ${durationMs.toFixed(2)}ms`; + + customLogger.info(message, logData); + }); + + next(); + }; +}