feat: structured JSON logging with request id tracing

src/__tests__/logger.test.ts

@@ -0,0 +1,87 @@
+import { getRequestId, logger, logProviderCall, safeDetails, withRequestId } from '../logger';
+
+describe('structured logger', () => {
+  const originalLog = console.log;
+  const originalWarn = console.warn;
+  const originalError = console.error;
+  let lines: string[] = [];
+
+  beforeEach(() => {
+    lines = [];
+    console.log = (line?: unknown) => {
+      lines.push(String(line));
+    };
+    console.warn = (line?: unknown) => {
+      lines.push(String(line));
+    };
+    console.error = (line?: unknown) => {
+      lines.push(String(line));
+    };
+  });
+
+  afterEach(() => {
+    console.log = originalLog;
+    console.warn = originalWarn;
+    console.error = originalError;
+  });
+
+  it('emits one JSON object per line with level and event', () => {
+    logger.info('server.start', { port: 3000 });
+    expect(lines).toHaveLength(1);
+    const parsed = JSON.parse(lines[0]);
+    expect(parsed.level).toBe('info');
+    expect(parsed.event).toBe('server.start');
+    expect(parsed.port).toBe(3000);
+    expect(typeof parsed.timestamp).toBe('string');
+  });
+
+  it('logs every provider call with route, status and duration', () => {
+    logProviderCall({ route: '/v1/kyc/verify', status: 200, durationMs: 123 });
+    expect(lines).toHaveLength(1);
+    const parsed = JSON.parse(lines[0]);
+    expect(parsed.route).toBe('/v1/kyc/verify');
+    expect(parsed.status).toBe(200);
+    expect(parsed.durationMs).toBe(123);
+    expect(parsed.event).toBe('provider.call');
+  });
+
+  it('carries one request id across the API and provider boundary', () => {
+    withRequestId('req-123', () => {
+      expect(getRequestId()).toBe('req-123');
+      logger.info('http.request', { route: '/v1/kyc/verify' });
+      logProviderCall({ route: '/v1/kyc/verify', status: 200, durationMs: 42 });
+    });
+    expect(lines).toHaveLength(2);
+    const ids = lines.map((l) => JSON.parse(l).requestId);
+    expect(ids).toEqual(['req-123', 'req-123']);
+  });
+
+  it('never logs a NIN, an API key or a connection string', () => {
+    // NIN and secrets are synthetic and not real. The point is that the
+    // logger redacts them even when a caller passes them in by accident.
+    const nin = '12345678901';
+    const apiKey = 'sk_live_abcdef01234567890abcdef';
+    const connectionString =
+      'postgres://user:password@db.internal.example.com:5432/veil';
+
+    logger.error('provider.error', {
+      message: `failed for ${nin}`,
+      apiKey,
+      databaseUrl: connectionString,
+    });
+
+    const joined = lines.join('\n');
+    expect(joined).not.toContain(nin);
+    expect(joined).not.toContain(apiKey);
+    expect(joined).not.toContain(connectionString);
+    expect(joined).not.toContain('password');
+  });
+
+  it('safeDetails only exposes whitelisted keys', () => {
+    const details = safeDetails(
+      { status: 'success', nin: '12345678901', token: 'sk_live_abcdef01234567890abcdef' },
+      ['status'],
+    );
+    expect(details).toEqual({ status: 'success' });
+  });
+});

src/index.ts

@@ -1,6 +1,7 @@
 import "dotenv/config";
 import http from "http";
 import { execSync } from "child_process";
+import { randomUUID } from "crypto";
 import { createApp } from "./api";
 import { startAllIndexers } from "./indexer";
 import { prisma } from "./db";
@@ -11,10 +12,12 @@ import { startPartitionRetentionJob } from "./jobs/retention";
 import { initTokenCache } from "./tokenCache";
 import { enabledNetworks } from "./network";
 import { onlyAddsUniqueConstraints, pushSchema } from "./schemaGuard";
+import { logger } from "./logger";
 
 const PORT = parseInt(process.env.PORT ?? "3000", 10);
 
 async function main() {
+  const bootId = randomUUID();
   // Converge the schema on every startup, so a deploy needs no separate
   // pre-deploy step.
   //
@@ -36,7 +39,7 @@ async function main() {
   //
   // Additive changes — a new table, a new nullable column — still apply on
   // their own. Anything destructive now fails loudly here instead.
-  console.log("[wraith] Converging database schema…");
+  logger.info("schema.converge.start", { route: "startup", status: 0, durationMs: 0, requestId: bootId });
   const first = pushSchema();
   if (!first.ok) {
     // `--accept-data-loss` consents to two very different things at once, and
@@ -53,33 +56,22 @@ async function main() {
     // unique constraint, consent and retry. If even one is anything else,
     // refuse exactly as before.
     if (onlyAddsUniqueConstraints(first.output)) {
-      console.warn(
-        "[wraith] Schema diff is unique constraints only — no column is dropped.\n" +
-          "[wraith] Applying. A duplicate would fail the index, not delete a row.",
-      );
+      logger.warn("schema.converge.unique_constraints_only", { route: "startup", status: 0, durationMs: 0, requestId: bootId });
       const retry = pushSchema("--accept-data-loss");
       if (!retry.ok) {
-        console.error(
-          "[wraith] The constraint could not be applied — most likely duplicate\n" +
-            "[wraith] rows already exist for it. Nothing was dropped. Resolve the\n" +
-            "[wraith] duplicates and redeploy.",
-        );
+        logger.error("schema.converge.constraint_failed", { route: "startup", status: 0, durationMs: 0, requestId: bootId });
         process.exit(1);
       }
     } else {
-      console.error(
-        "[wraith] Schema convergence refused: the pending change is destructive.\n" +
-          "[wraith] Nothing was dropped. Read the diff above — a rename or a type\n" +
-          "[wraith] change needs a deliberate migration, not --accept-data-loss.",
-      );
+      logger.error("schema.converge.refused_destructive", { route: "startup", status: 0, durationMs: 0, requestId: bootId });
       process.exit(1);
     }
   }
-  console.log("[wraith] Database ready.");
+  logger.info("schema.converge.ready", { route: "startup", status: 0, durationMs: 0, requestId: bootId });
 
   // ── Graceful shutdown ──────────────────────────────────────────────────────
   const shutdown = async (signal: string) => {
-    console.log(`\n[wraith] Received ${signal} — shutting down gracefully…`);
+    logger.info("shutdown.received", { route: "startup", status: 0, durationMs: 0, requestId: bootId, signal });
     await prisma.$disconnect();
     process.exit(0);
   };
@@ -97,9 +89,9 @@ async function main() {
   attachGraphQLSubscriptions(server);
 
   server.listen(PORT, () => {
-    console.log(`[wraith] API listening on http://localhost:${PORT}`);
-    console.log(`[wraith] WebSocket subscriptions available at ws://localhost:${PORT}/subscribe/:address`);
-    console.log(`[wraith] GraphQL subscriptions available at ws://localhost:${PORT}${SUBSCRIPTIONS_PATH}`);
+    logger.info("server.listen", { route: "startup", status: 0, durationMs: 0, requestId: bootId, port: PORT });
+    logger.info("server.ws_ready", { route: "startup", status: 0, durationMs: 0, requestId: bootId, path: "/subscribe/:address" });
+    logger.info("server.graphql_ready", { route: "startup", status: 0, durationMs: 0, requestId: bootId, path: SUBSCRIPTIONS_PATH });
   });
 
   // ── Start webhook worker ───────────────────────────────────────────────────
@@ -122,7 +114,7 @@ async function main() {
   // which exercises the HTTP surface only. Without this guard the indexer throws
   // on the missing RPC endpoint and takes the whole process (and API) down.
   if (process.env.SKIP_INDEXER === "true") {
-    console.log("[wraith] SKIP_INDEXER=true — indexer not started (API-only mode)");
+    logger.info("indexer.skipped", { route: "startup", status: 0, durationMs: 0, requestId: bootId });
   } else {
     // One loop per enabled network (NETWORKS env; defaults to STELLAR_NETWORK).
     // Each loop restarts itself on crash rather than taking the process down —
@@ -131,4 +123,6 @@ async function main() {
   }
 }
 
-main();
+if (require.main === module) {
+  main();
+}

src/logger.ts

@@ -0,0 +1,159 @@
+import { AsyncLocalStorage } from 'node:async_hooks';
+
+/**
+ * Structured logging for Veil.
+ *
+ * One JSON object per line. Every line has a level and an event, and when
+ * a request is in flight it also carries the request id so a support report
+ * can be traced end to end across the API and the provider boundary.
+ *
+ * Deliberate omissions: NIN, API keys, connection strings and account
+ * numbers must never appear in a log line. The `redact` pass below is the
+ * safety net: every field is screened before it is serialised, and the
+ * `safeDetails` helper makes it hard to accidentally pass through a raw
+ * provider response.
+ */
+
+export type LogLevel = 'debug' | 'info' | 'warn' | 'error';
+
+export interface LogFields {
+  [key: string]: unknown;
+}
+
+export interface LogLine extends LogFields {
+  timestamp: string;
+  level: LogLevel;
+  event: string;
+  requestId?: string;
+  route?: string;
+  status?: number;
+  durationMs?: number;
+}
+
+/**
+ * Patterns that must never reach a log line. These are deliberately
+ * broad and conservative: false positives are acceptable, leaking a
+ * NIN or a connection string is not.
+ */
+const SECRET_PATTERNS: RegExp[] = [
+  // 11-digit Nigerian identity number.
+  /\b(?:\d{11})\b/,
+  // Postgres / MySQL / Mongo / Redis connection strings.
+  /\b(?:abcdefghijklmnopqrstuvwxyz{})?:(?:\/\/))[^\s]+/,
+  // Bearer / API key style tokens.
+  /\bBearer\s+[A-Za-z0-9_\-.]{16,}/i,
+  /\b(?:sk|rk|pk|api)[_-][A-Za-z0-9]{16,}/i,
+  // JWT-like three-part tokens.
+  /\beyJ[a-zA-Z0-9_\-.]+\.eyJ[a-zA-Z0-9_\-.]+\.[a-zA-Z0-9_\-.]+\b/,
+];
+
+const REDACTED_VALUE = '[REDACTED]';
+
+function redactString(value: string): string {
+  let out = value;
+  for (const pattern of SECRET_PATTERNS) {
+    out = out.replace(pattern, REDACTED_VALUE);
+  }
+  return out;
+}
+
+function redactValue(value: unknown, depth = 0): unknown {
+  if (value == null) return value;
+  if (typeof value === 'string') return redactString(value);
+  if (typeof value === 'number' || typeof value === 'boolean') return value;
+  if (depth > 6) return '[TRUNCATED]';
+  if (Array.isArray(value)) {
+    return value.map((v) => redactValue(v, depth + 1));
+  }
+  if (typeof value === 'object') {
+    const out: Record<string, unknown> = {};
+    for (const [i, v] of Object.entries(value as Record<string, unknown>)) {
+      out[i] = redactValue(v, depth + 1);
+    }
+    return out;
+  }
+  return String(value);
+}
+
+/**
+ * Request context. A request id is stashed here by the requestId middleware
+ * and read by the logger, so every line emitted while a request is in flight
+ * carries the same id - including lines emitted from the provider client.
+ */
+const requestContext = new AsyncLocalStorage<{ requestId: string }>();
+
+export function withRequestId<T>(requestId: string, fn: () => T): T {
+  return requestContext.run({ requestId }, fn);
+}
+
+export function getRequestId(): string | undefined {
+  return requestContext.getStore()?.requestId;
+}
+
+function write(level: LogLevel, event: string, fields: LogFields = {}): LogLine {
+  const requestId = getRequestId();
+  const line: LogLine = {
+    timestamp: new Date().toISOString(),
+    level,
+    event,
+    ...(requestId ? { requestId } : {}),
+    ...((redactValue(fields) as LogFields) ?? {}),
+  };
+  const serialised = JSON.stringify(line);
+  if (level === 'error') {
+    console.error(serialised);
+  } else if (level === 'warn') {
+    console.warn(serialised);
+  } else {
+    console.log(serialised);
+  }
+  return line;
+}
+
+export const logger = {
+  debug: (event: string, fields?: LogFields) => write('debug', event, fields),
+  info: (event: string, fields?: LogFields) => write('info', event, fields),
+  warn: (event: string, fields?: LogFields) => write('warn', event, fields),
+  error: (event: string, fields?: LogFields) => write('error', event, fields),
+};
+
+/**
+ * Log one provider call. This is the single choke point the acceptance
+ * criteria care about: every provider call must emit exactly one line
+ * with route, status and elapsed ms.
+ */
+export function logProviderCall(input: {
+  route: string;
+  status: number;
+  durationMs: number;
+  event?: string;
+  extra?: LogFields;
+}): LogLine {
+  const { route, status, durationMs, event = 'provider.call', extra } = input;
+  const level: LogLevel = status >= 500 ? 'error' : status >= 400 ? 'warn' : 'info';
+  return write(level, event, {
+    route,
+    status,
+    durationMs,
+    ...(extra ?? {}),
+  });
+}
+
+/**
+ * Take a provider response body and return only the fields that are safe to
+ * log. This is the easy way to stay careful: callers never hand the raw
+ * body to the logger, they pass it through here first.
+ */
+export function safeDetails(body: unknown, keys: string[] = []): LogFields {
+  if (!body || typeof body !== 'object') return {};
+  const source = body as Record<string, unknown>;
+  const out: LogFields = {};
+  for (const key of keys) {
+    if (Object.prototype.hasOwnProperty.call(source, key)) {
+      out[key] = redactValue(source[key]);
+    }
+  }
+  return out;
+}
+
+export const _internal = { redactValue, redactString, SECRET_PATTERNS };

src/middleware/requestId.ts

@@ -0,0 +1,35 @@
+import type { NextFunction, Request, Response } from 'express';
+import { randomUUID } from 'node:crypto';
+import { withRequestId } from '../logger';
+
+const HEADER = 'x-request-id';
+
+export interface RequestWithId extends Request {
+  requestId: string;
+}
+
+/**
+ * Assigns a request id to every inbound request, echoes it back on the
+ * response, and runs the rest of the request inside an AsyncLocalStorage
+ * context so the logger can attach it to every line - including lines
+ * emitted from the provider client.
+ *
+ * If the client already sent an x-request-id we honour it, so a trace can
+ * span multiple services. Otherwise we mint a new one.
+ */
+export function requestId(req: Request, res: Response, next: NextFunction): void {
+  const inbound = req.headers[HEADER];
+  const id =
+    typeof inbound === 'string' && inbound.trim().length > 0
+      ? inbound.trim().slice(0, 128)
+      : randomUUID();
+
+  (req as RequestWithId).requestId = id;
+  res.setHeader(HEADER, id);
+
+  withRequestId(id, () => {
+    next();
+  });
+}
+
+export const REQUEST_ID_HEADER = HEADER;