From 214a704b426f5ea1631ee9a76d4160471bb85621 Mon Sep 17 00:00:00 2001 From: Nwapu Trust Jah <152970136+Nwapu-TrustJah@users.noreply.github.com> Date: Fri, 16 Oct 2026 15:12:39 +0100 Subject: [PATCH 1/2] fix: Logs are prose, and prose cannot be searched when it matters (#240) --- src/__tests__/logger.test.ts | 87 +++++++++++++++++++ src/index.ts | 38 ++++----- src/logger.ts | 159 +++++++++++++++++++++++++++++++++++ src/middleware/requestId.ts | 35 ++++++++ 4 files changed, 297 insertions(+), 22 deletions(-) create mode 100644 src/__tests__/logger.test.ts create mode 100644 src/logger.ts create mode 100644 src/middleware/requestId.ts diff --git a/src/__tests__/logger.test.ts b/src/__tests__/logger.test.ts new file mode 100644 index 000000000..37381f9db --- /dev/null +++ b/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' }); + }); +}); diff --git a/src/index.ts b/src/index.ts index 5a73c0df2..0140d8b83 100644 --- a/src/index.ts +++ b/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({ event: "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({ event: "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({ event: "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({ event: "schema.converge.refused_destructive", route: "startup", status: 0, durationMs: 0, requestId: bootId }); process.exit(1); } } - console.log("[wraith] Database ready."); + logger.info({ event: "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({ event: "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({ event: "server.listen", route: "startup", status: 0, durationMs: 0, requestId: bootId, port: PORT }); + logger.info({ event: "server.ws_ready", route: "startup", status: 0, durationMs: 0, requestId: bootId, path: "/subscribe/:address" }); + logger.info({ event: "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({ event: "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(); +} diff --git a/src/logger.ts b/src/logger.ts new file mode 100644 index 000000000..b8067cf0f --- /dev/null +++ b/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 = {}; + for (const [i, v] of Object.entries(value as Record)) { + 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(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; + 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 }; diff --git a/src/middleware/requestId.ts b/src/middleware/requestId.ts new file mode 100644 index 000000000..a9a6129fd --- /dev/null +++ b/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; From eb725ff501817f2410254be1ba93be2f1b6c1ad9 Mon Sep 17 00:00:00 2001 From: Miracle656 Date: Sun, 18 Oct 2026 11:37:00 +0100 Subject: [PATCH 2/2] fix(logging): call logger.info(event, fields), not logger.info(object) Ten call sites in src/index.ts passed a single object where the logger declares `info(event: string, fields?: LogFields)`, so tsc refused: error TS2345: Argument of type '{ event: string; route: string; ... }' is not assignable to parameter of type 'string'. Mechanical: the event name moves out to the first argument and the rest stays as fields. Claude-Session: https://claude.ai/code/session_01USgemLt4Rnz4SGB1Srf3GB --- src/index.ts | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/src/index.ts b/src/index.ts index 0140d8b83..5ccb30fcb 100644 --- a/src/index.ts +++ b/src/index.ts @@ -39,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. - logger.info({ event: "schema.converge.start", route: "startup", status: 0, durationMs: 0, requestId: bootId }); + 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 @@ -56,22 +56,22 @@ async function main() { // unique constraint, consent and retry. If even one is anything else, // refuse exactly as before. if (onlyAddsUniqueConstraints(first.output)) { - logger.warn({ event: "schema.converge.unique_constraints_only", route: "startup", status: 0, durationMs: 0, requestId: bootId }); + logger.warn("schema.converge.unique_constraints_only", { route: "startup", status: 0, durationMs: 0, requestId: bootId }); const retry = pushSchema("--accept-data-loss"); if (!retry.ok) { - logger.error({ event: "schema.converge.constraint_failed", route: "startup", status: 0, durationMs: 0, requestId: bootId }); + logger.error("schema.converge.constraint_failed", { route: "startup", status: 0, durationMs: 0, requestId: bootId }); process.exit(1); } } else { - logger.error({ event: "schema.converge.refused_destructive", route: "startup", status: 0, durationMs: 0, requestId: bootId }); + logger.error("schema.converge.refused_destructive", { route: "startup", status: 0, durationMs: 0, requestId: bootId }); process.exit(1); } } - logger.info({ event: "schema.converge.ready", route: "startup", status: 0, durationMs: 0, requestId: bootId }); + logger.info("schema.converge.ready", { route: "startup", status: 0, durationMs: 0, requestId: bootId }); // ── Graceful shutdown ────────────────────────────────────────────────────── const shutdown = async (signal: string) => { - logger.info({ event: "shutdown.received", route: "startup", status: 0, durationMs: 0, requestId: bootId, signal }); + logger.info("shutdown.received", { route: "startup", status: 0, durationMs: 0, requestId: bootId, signal }); await prisma.$disconnect(); process.exit(0); }; @@ -89,9 +89,9 @@ async function main() { attachGraphQLSubscriptions(server); server.listen(PORT, () => { - logger.info({ event: "server.listen", route: "startup", status: 0, durationMs: 0, requestId: bootId, port: PORT }); - logger.info({ event: "server.ws_ready", route: "startup", status: 0, durationMs: 0, requestId: bootId, path: "/subscribe/:address" }); - logger.info({ event: "server.graphql_ready", route: "startup", status: 0, durationMs: 0, requestId: bootId, path: 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 ─────────────────────────────────────────────────── @@ -114,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") { - logger.info({ event: "indexer.skipped", route: "startup", status: 0, durationMs: 0, requestId: bootId }); + 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 —