Repository navigation
feat: route all logging through a structured pino logger - #402
Conversation
Every module now logs through a component-scoped pino child (ingester:sdex, job:aggregate-refresh, ws:fanout, redis, config, webhook, route:price, startup) instead of console.*, emitted as a structured `component` field rather than a message prefix. Fastify's request logger is built from the same options so req.log is scrubbed and formatted identically. The level is configurable via LOG_LEVEL (default info, documented in .env.example): NDJSON when NODE_ENV=production, human-readable otherwise. Values of secret-looking env vars (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 auth headers are redacted via pino redact. Adds a test asserting no console.* survives in non-test source and that a connection string or API key value never reaches the output.
|
@aliyuHabibu Great news! 🎉 Based on an automated assessment of this PR, the linked Wave issue(s) no longer count against your application limits. You can now already apply to more issues while waiting for a review of this PR. Keep up the great work! 🚀 |
|
This is the one I want for #278 — pino rather than a hand-rolled wrapper, component children instead of message prefixes, a configurable It conflicts now — Heads-up on sequencing: #397 independently added a |
|
@Miracle656 Please review again. Thank you |
Miracle656
left a comment
There was a problem hiding this comment.
This is the best-engineered PR I have reviewed in this repo. It does what #278 asked and then solves the problem that issue was really about.
The scrubbing is the part that matters. Not just redacting known header names, but collecting every secret-looking value out of the environment and removing it from serialized output — and specifically including the password pulled out of a connection-string URL:
including the password embedded in a connection-string URL so that driver error messages (which often echo only the credentials) are covered too
That is the exact shape of the incident this service already had: a raw pg error echoed a Postgres connection string out of /price/twap, live for about three months. A redaction list keyed on field names would not have caught it, because the secret was inside an error message, not in a field. This would.
MIN_SECRET_LENGTH is the detail that tells me you ran it. Without it REQUIRE_API_KEY=true matches SECRET_NAME_RE, and every true in every log line gets clobbered — a scrubber that quietly corrupts ordinary output is worse than none, and it is the kind of bug you only find by looking at real logs.
Two tests are worth more than the rest put together:
leaves no console.* calls in non-test source
never passes a raw connection-string env value into a log call
Those are lint rules wearing test clothing. Without them this fix decays the first time someone adds a quick console.log while debugging, and the 65 calls come back one at a time over six months. With them, it cannot.
Also right: logger.ts does not import config.ts — config imports the logger, so it reads process.env directly, and the comment says why rather than leaving the next person to rediscover the cycle. And Fastify's request logger is built from the same options, so req.log and module logs are formatted and scrubbed identically, which is the step most implementations skip.
Merging. @jamal-exe — #397 can rebase onto this now; your ingestion field set (venue, network, pair, attempt, retryMs, durationMs) is the good part and should come across as pino calls on an ingester:* child.
main went red on the guard #402 added: × leaves no console.* calls in non-test source expected [ 'src/index.ts:154', …(9) ] to deeply equal [] My doing. #252 (price_points partitioning) was branched before #402 replaced every console.* call with a component-scoped pino logger, so merging it reintroduced ten of them — six in src/index.ts, four in src/jobs/pricePointsPartitionJob.ts. That guard is a lint rule wearing test clothing, and it caught exactly what it was written to catch: the calls do not come back all at once, they come back one merged branch at a time. Converted to `createLogger('startup')` and a new `createLogger('job:price-points-partition')` child, passing `err` as a field so pino serialises the stack rather than interpolating a message string. logger.test.ts: 9 passed. Suite: 679 passed, tsc clean. The remaining local failure on graphqlSchemaDrift is CRLF in my working copy — the committed blob is LF and CI passes it. Claude-Session: https://claude.ai/code/session_01USgemLt4Rnz4SGB1Srf3GB
Two gates now sit side by side in the MCP server and they are deliberately
separate:
ERR_URL_BLOCKED the target resolves somewhere we will never fetch —
private, loopback, link-local, metadata (Divinity-Labs#488/Divinity-Labs#407)
ERR_HOST_NOT_ALLOWED the host is reachable, but is not on the operator's
paid_call allow-list (Divinity-Labs#487/Divinity-Labs#404)
Both codes kept rather than one replacing the other: "I cannot reach there"
and "I will not pay there" are different answers and an agent should be able
to tell them apart.
The constructor keeps both initialisations, on main's `config_` parameter
name — it was renamed there to stop it shadowing the imported `config`.
Also exempts src/mcp/ from the console guard added in Divinity-Labs#402. The MCP server
speaks its protocol over stdout via StdioServerTransport, and pino's default
destination is stdout — routing these diagnostics through the logger would
interleave log lines with protocol frames and break every client parsing
them. stderr is the only stream it may write to, so console.error is correct
there. The exemption pattern accepts both path separators; a forward-slash
pattern matches nothing on Windows.
mcp.test.ts, mcp-paid-call-allowlist.test.ts, ssrf.test.ts: 41 passed.
Suite: 772 passed. The two local reds are CRLF in my working copy and a
mercurius 16.12 node_modules ahead of the lockfile, neither of them real.
Claude-Session: https://claude.ai/code/session_01USgemLt4Rnz4SGB1Srf3GB
Resolve the logging conflict in favour of main's pino logger (Divinity-Labs#402): venue ingestion failures now go through the ingester:<venue> child logger with venue, network, pair, attempt, retryMs, durationMs and err as fields, replacing the hand-rolled logEvent helper. src/logging.ts is removed and docs/logging.md now documents the pino convention.
Every module now logs through a component-scoped pino child (ingester:sdex, job:aggregate-refresh, ws:fanout, redis, config, webhook, route:price, startup) instead of console.*, emitted as a structured
componentfield rather than a message prefix. Fastify's request logger is built from the same options so req.log is scrubbed and formatted identically.The level is configurable via LOG_LEVEL (default info, documented in .env.example): NDJSON when NODE_ENV=production, human-readable otherwise. Values of secret-looking env vars (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 auth headers are redacted via pino redact.
Adds a test asserting no console.* survives in non-test source and that a connection string or API key value never reaches the output.
Summary
Type of change
Checklist
npx tsc --noEmitpassesnpm run buildpassesClose #332