feat(api): add high-precision request duration logging middleware (#687)

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.

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<string, unknown>) => {
+        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<string, unknown>) => {
+        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');
+  });
+});

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<string, unknown>) => 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();
+  };
+}