feat: route all logging through a structured pino logger

.changeset/structured-logging.md

@@ -0,0 +1,21 @@
+---
+'lens': patch
+---
+
+Route all logging through pino (`src/logger.ts`) instead of `console.*`. Every
+module now logs through a component-scoped child logger — `ingester:sdex`,
+`job:aggregate-refresh`, `ws:fanout`, `redis`, `config`, `webhook`,
+`route:price`, … — emitted as a structured `component` field rather than a
+message prefix, so operators can filter by component without regexing text.
+Fastify's request logger is built from the same options, so `req.log` carries
+the same redaction and formatting.
+
+The level is configurable via `LOG_LEVEL` (default `info`, documented in
+`.env.example`): logs are newline-delimited JSON when `NODE_ENV=production` and
+pretty-printed for humans otherwise. Values of secret-looking environment
+variables (`DATABASE_URL`, `DIRECT_DATABASE_URL`, `REDIS_URL`, and any name
+containing `KEY`/`SECRET`/`TOKEN`/`PASSWORD`) are scrubbed from every
+serialized line, including the password inside a connection string and driver
+error messages that echo it, while request auth headers are redacted via
+pino's `redact`. A test asserts no `console.*` survives in non-test source and
+that a connection string or API key value never reaches the output.

.env.example

@@ -1,6 +1,9 @@
 # --- General ---
 # Environment: development, test, production
 NODE_ENV=development
+# Structured log level: trace, debug, info, warn, error, fatal, or silent (default: info)
+# Logs are newline-delimited JSON when NODE_ENV=production, human-readable otherwise.
+LOG_LEVEL=info
 
 # --- Server ---
 # Port to listen on (default: 3002)

package.json

@@ -40,6 +40,7 @@
     "ioredis": "^5.0.0",
     "mercurius": "^16.9.0",
     "pg": "^8.0.0",
+    "pino": "^9.14.0",
     "prom-client": "^15.1.3",
     "uuid": "^9.0.0",
     "ws": "^8.20.0",

src/__tests__/logger.test.ts

@@ -0,0 +1,161 @@
+import { describe, it, expect } from 'vitest'
+import { readFileSync, readdirSync } from 'node:fs'
+import { resolve, join, relative } from 'node:path'
+import type { DestinationStream } from 'pino'
+import { buildLogger, redactSecrets, secretValues } from '../logger'
+
+const rootDir = resolve(__dirname, '../..')
+const srcDir = resolve(rootDir, 'src')
+
+/** Collects serialized log lines in memory instead of writing to stdout. */
+function capture(): { lines: string[]; destination: DestinationStream } {
+  const lines: string[] = []
+  return { lines, destination: { write: (line: string) => { lines.push(line) } } }
+}
+
+/** Every non-test .ts file under src/. */
+function sourceFiles(dir = srcDir): string[] {
+  const files: string[] = []
+  for (const entry of readdirSync(dir, { withFileTypes: true })) {
+    const full = join(dir, entry.name)
+    if (entry.isDirectory()) {
+      if (entry.name !== '__tests__' && entry.name !== 'node_modules') {
+        files.push(...sourceFiles(full))
+      }
+    } else if (
+      entry.isFile() &&
+      entry.name.endsWith('.ts') &&
+      !entry.name.endsWith('.test.ts') &&
+      !entry.name.endsWith('.spec.ts') &&
+      !entry.name.endsWith('.d.ts')
+    ) {
+      files.push(full)
+    }
+  }
+  return files
+}
+
+describe('secret redaction', () => {
+  it('scrubs a connection string and an API key value', () => {
+    const dbUrl = 'postgresql://lens:CANARY-PASSWORD-123456@localhost:5432/lens'
+    const apiKey = 'canary-api-key-value-0123456789'
+    const env = { DATABASE_URL: dbUrl, ADMIN_API_KEY: apiKey }
+
+    const line = `oops ${dbUrl} and ${apiKey} leaked`
+    const scrubbed = redactSecrets(line, env)
+
+    expect(scrubbed).not.toContain('CANARY-PASSWORD-123456')
+    expect(scrubbed).not.toContain(apiKey)
+    expect(scrubbed).toContain('[redacted]')
+  })
+
+  it('also scrubs the password embedded in a connection string on its own', () => {
+    const dbUrl = 'postgresql://lens:S0me-CANARY-Passw0rd-long@db:5432/lens'
+    const env = { DATABASE_URL: dbUrl }
+
+    expect(secretValues(env)).toContain('S0me-CANARY-Passw0rd-long')
+    expect(redactSecrets('driver said password=S0me-CANARY-Passw0rd-long', env)).not.toContain(
+      'S0me-CANARY-Passw0rd-long'
+    )
+  })
+
+  it('ignores boolean-looking flag values so ordinary log content survives', () => {
+    const env = { REQUIRE_API_KEY: 'true' }
+    expect(secretValues(env)).toEqual([])
+    expect(redactSecrets('auth enabled: true', env)).toBe('auth enabled: true')
+  })
+})
+
+describe('structured logger output', () => {
+  it('emits JSON with a component field and a level label', () => {
+    const { lines, destination } = capture()
+    const log = buildLogger({ level: 'info', pretty: false, destination }).child({
+      component: 'ingester:amm',
+    })
+
+    log.info({ pool: 'CABCDEF', trades: 3 }, 'ingested pool trades')
+
+    expect(lines).toHaveLength(1)
+    const parsed = JSON.parse(lines[0])
+    expect(parsed.component).toBe('ingester:amm')
+    expect(parsed.level).toBe('info')
+    expect(parsed.msg).toBe('ingested pool trades')
+    expect(parsed.pool).toBe('CABCDEF')
+    expect(parsed.trades).toBe(3)
+    expect(parsed.service).toBe('lens')
+  })
+
+  it('never writes a secret value carried in an error or a field', () => {
+    const dbUrl = 'postgresql://lens:CANARY-PASSWORD-123456@localhost:5432/lens'
+    const apiKey = 'canary-api-key-value-0123456789'
+    process.env.DATABASE_URL = dbUrl
+    process.env.ADMIN_API_KEY = apiKey
+
+    const { lines, destination } = capture()
+    const log = buildLogger({ level: 'info', pretty: false, destination })
+
+    log.error({ err: new Error(`connect failed for ${dbUrl}`) }, 'twap failed')
+    log.info({ apiKey }, 'debug key')
+
+    const output = lines.join('\n')
+    expect(output).not.toContain('CANARY-PASSWORD-123456')
+    expect(output).not.toContain(apiKey)
+    expect(output).toContain('[redacted]')
+  })
+
+  it('renders human-readable lines in development mode', () => {
+    const { lines, destination } = capture()
+    const log = buildLogger({ level: 'info', pretty: true, destination }).child({
+      component: 'job:snapshot-retention',
+    })
+
+    log.info({ network: 'testnet', pruned: 4 }, 'pruned snapshots')
+
+    expect(lines).toHaveLength(1)
+    expect(lines[0]).toContain('[job:snapshot-retention]')
+    expect(lines[0]).toContain('pruned snapshots')
+    expect(lines[0]).toContain('INFO')
+    expect(() => JSON.parse(lines[0])).toThrow()
+  })
+
+  it('respects the level and drops messages below it', () => {
+    const { lines, destination } = capture()
+    const log = buildLogger({ level: 'warn', pretty: false, destination })
+
+    log.info('not emitted')
+    log.warn('emitted')
+
+    expect(lines).toHaveLength(1)
+    expect(JSON.parse(lines[0]).msg).toBe('emitted')
+  })
+})
+
+describe('logging hygiene', () => {
+  it('leaves no console.* calls in non-test source', () => {
+    const offenders: string[] = []
+    for (const file of sourceFiles()) {
+      const code = readFileSync(file, 'utf8')
+      code.split('\n').forEach((line, i) => {
+        if (/\bconsole\.\w+\s*\(/.test(line)) {
+          offenders.push(`${relative(rootDir, file)}:${i + 1}`)
+        }
+      })
+    }
+    expect(offenders).toEqual([])
+  })
+
+  it('never passes a raw connection-string env value into a log call', () => {
+    const logCall = /\b(?:log|logger|req\.log)\.(?:trace|debug|info|warn|error|fatal)\b/
+    const offenders: string[] = []
+    for (const file of sourceFiles()) {
+      const code = readFileSync(file, 'utf8')
+      code.split('\n').forEach((line, i) => {
+        if (!logCall.test(line)) return
+        if (line.includes('process.env.DATABASE_URL') || line.includes('process.env.DIRECT_DATABASE_URL')) {
+          offenders.push(`${relative(rootDir, file)}:${i + 1}`)
+        }
+      })
+    }
+    expect(offenders).toEqual([])
+  })
+})

src/__tests__/networkVenueConfig.test.ts

@@ -8,6 +8,27 @@
 
 import { StrKey } from '@stellar/stellar-sdk'
 
+// config.ts logs invalid contract ids through the structured logger; capture
+// those calls so the tests can assert on the warning without a live sink.
+const { configLogger } = vi.hoisted(() => ({
+  configLogger: {
+    trace: vi.fn(),
+    debug: vi.fn(),
+    info: vi.fn(),
+    warn: vi.fn(),
+    error: vi.fn(),
+    fatal: vi.fn(),
+    child: vi.fn(),
+  },
+}))
+
+vi.mock('../logger', () => ({
+  createLogger: () => configLogger,
+  logger: configLogger,
+  loggerOptions: () => ({}),
+  createDestination: () => ({ write: () => {} }),
+}))
+
 const ENV_KEYS = [
   'STELLAR_NETWORK',
   'SOROSWAP_ENABLED_TESTNET',
@@ -163,27 +184,31 @@ describe('per-network venue config', () => {
   })
 
   it('rejects the former 55-character mainnet Reflector default, disabling the oracle and naming the env var', async () => {
-    const warn = vi.spyOn(console, 'warn').mockImplementation(() => {})
+    configLogger.warn.mockClear()
     process.env.REFLECTOR_CONTRACT_ID_MAINNET = OLD_REFLECTOR_LITERAL
 
     const { getNetworkConfig } = await loadConfig()
 
     expect(OLD_REFLECTOR_LITERAL).toHaveLength(55)
     expect(getNetworkConfig('mainnet').oracle.enabled).toBe(false)
-    expect(warn).toHaveBeenCalledWith(expect.stringContaining('REFLECTOR_CONTRACT_ID_MAINNET'))
-    warn.mockRestore()
+    expect(configLogger.warn).toHaveBeenCalledWith(
+      expect.objectContaining({ envVar: 'REFLECTOR_CONTRACT_ID_MAINNET', value: OLD_REFLECTOR_LITERAL }),
+      expect.stringContaining('invalid Soroban contract id')
+    )
   })
 
   it('rejects the former 55-character testnet Soroswap default, disabling Soroswap and naming the env var', async () => {
-    const warn = vi.spyOn(console, 'warn').mockImplementation(() => {})
+    configLogger.warn.mockClear()
     process.env.SOROSWAP_FACTORY_ADDRESS_TESTNET = OLD_SOROSWAP_TESTNET_LITERAL
 
     const { getNetworkConfig } = await loadConfig()
 
     expect(OLD_SOROSWAP_TESTNET_LITERAL).toHaveLength(55)
     expect(getNetworkConfig('testnet').soroswap.enabled).toBe(false)
-    expect(warn).toHaveBeenCalledWith(expect.stringContaining('SOROSWAP_FACTORY_ADDRESS_TESTNET'))
-    warn.mockRestore()
+    expect(configLogger.warn).toHaveBeenCalledWith(
+      expect.objectContaining({ envVar: 'SOROSWAP_FACTORY_ADDRESS_TESTNET' }),
+      expect.stringContaining('invalid Soroban contract id')
+    )
   })
 
   it('accepts a valid 56-character Soroswap factory id', async () => {

src/__tests__/snapshotRetention.test.ts

@@ -14,6 +14,27 @@ vi.mock('bullmq', () => ({
   Worker: class {},
 }))
 
+// The retention job logs batch progress through the structured logger; capture
+// those calls without touching stdout.
+const { retentionLogger } = vi.hoisted(() => ({
+  retentionLogger: {
+    trace: vi.fn(),
+    debug: vi.fn(),
+    info: vi.fn(),
+    warn: vi.fn(),
+    error: vi.fn(),
+    fatal: vi.fn(),
+    child: vi.fn(),
+  },
+}))
+
+vi.mock('../logger', () => ({
+  createLogger: () => retentionLogger,
+  logger: retentionLogger,
+  loggerOptions: () => ({}),
+  createDestination: () => ({ write: () => {} }),
+}))
+
 import {
   pruneOldSnapshots,
   pruneAllNetworks,
@@ -81,21 +102,20 @@ describe('pruneOldSnapshots network argument', () => {
       .mockResolvedValueOnce({ rowCount: 2 })
       .mockResolvedValueOnce({ rowCount: 1 })
       .mockResolvedValueOnce({ rowCount: 0 })
-    const log = vi.spyOn(console, 'log').mockImplementation(() => {})
+    retentionLogger.info.mockClear()
     const onProgress = vi.fn()
 
-    try {
-      expect(await pruneOldSnapshots(14, 'mainnet', 2, onProgress)).toBe(3)
-      expect(mockQuery.mock.calls.map(call => call[1])).toEqual([
-        ['mainnet', 14, 2],
-        ['mainnet', 14, 2],
-        ['mainnet', 14, 2],
-      ])
-      expect(log).toHaveBeenCalledWith(expect.stringContaining('batch 2 (1 rows; 3 total)'))
-      expect(onProgress).toHaveBeenLastCalledWith({ network: 'mainnet', batch: 2, batchRows: 1, totalPruned: 3 })
-    } finally {
-      log.mockRestore()
-    }
+    expect(await pruneOldSnapshots(14, 'mainnet', 2, onProgress)).toBe(3)
+    expect(mockQuery.mock.calls.map(call => call[1])).toEqual([
+      ['mainnet', 14, 2],
+      ['mainnet', 14, 2],
+      ['mainnet', 14, 2],
+    ])
+    expect(retentionLogger.info).toHaveBeenCalledWith(
+      expect.objectContaining({ network: 'mainnet', batch: 2, rows: 1, total: 3 }),
+      'pruned retention batch'
+    )
+    expect(onProgress).toHaveBeenLastCalledWith({ network: 'mainnet', batch: 2, batchRows: 1, totalPruned: 3 })
   })
 
   it('rejects an invalid batch size before querying', async () => {

src/alerts/delivery.ts

@@ -1,4 +1,7 @@
 import { createHmac } from 'crypto'
+import { createLogger } from '../logger'
+
+const log = createLogger('webhook')
 import { fetchWithTimeout } from '../fetch'
 
 function retryDelayMs(attempt: number): number {
@@ -35,14 +38,14 @@ export async function deliverJsonWithRetries(
       return deliverJsonWithRetries(url, body, secret, attempt + 1)
     }
 
-    console.warn(`[webhook] delivery failed after ${attempt} attempts to ${url}:`, (err as Error).message)
+    log.warn({ url, attempt, err }, 'webhook delivery failed after retries')
     return
   }
 
   if (res.ok) return
 
   if (res.status >= 400 && res.status < 500) {
-    console.warn(`[webhook] client error ${res.status} from ${url} — not retrying`)
+    log.warn({ url, status: res.status }, 'webhook client error; not retrying')
     return
   }
 
@@ -51,5 +54,5 @@ export async function deliverJsonWithRetries(
     return deliverJsonWithRetries(url, body, secret, attempt + 1)
   }
 
-  console.warn(`[webhook] delivery failed after ${attempt} attempts to ${url}: HTTP ${res.status}`)
+  log.warn({ url, attempt, status: res.status }, 'webhook delivery failed after retries')
 }

src/app.ts

@@ -27,6 +27,7 @@ import { registerBasketRoutes } from './routes/basket'
 import { registerDiscoveryRoutes } from './routes/discovery'
 import { registerSettleRoute } from './routes/facilitator'
 import { getMetrics } from './metrics'
+import { loggerOptions, createDestination } from './logger'
 
 export interface BuildAppOptions {
   /**
@@ -51,7 +52,11 @@ export interface BuildAppOptions {
  * The returned app is NOT listening; the caller calls `app.listen(...)`.
  */
 export async function buildApp(options: BuildAppOptions = {}): Promise<FastifyInstance> {
-  const app = Fastify({ logger: { level: 'warn' } })
+  // Share the structured logger configuration (level, redaction, dev pretty
+  // printing) with Fastify so `req.log` is scrubbed the same way.
+  const app = Fastify({
+    logger: { ...loggerOptions(), stream: createDestination() },
+  })
 
   // Capture route registrations first, so it observes every route below
   // (including the ones registered by encapsulated plugins such as Mercurius).