P1: Structured JSON logging with request correlation ids (#172)

[dkijania]

What & why

Part of the production-readiness epic (#163). Closes #172.

Logging used console.info/error and an inspect(..., {colors:true}) error dump — TTY-oriented, not aggregation-friendly — with no request ids, and was entangled with the Jaeger toggle.

Changes

• logger.ts — a pino structured logger: JSON lines, ISO timestamps, level from LOG_LEVEL (invalid values fall back to info instead of throwing at startup), independent of tracing.
• useRequestLogging plugin — assigns each request a correlation id (honouring an inbound X-Request-Id) and emits one structured access line per request with method, path, status, durationMs. Probe endpoints (/healthcheck, /readiness) are skipped to avoid orchestrator noise.
• GraphQL execution errors now log as structured JSON tagged with the same requestId.
• console.* in the entry point replaced with the logger.

New dependency: pino.

Testing

• npm run build — clean
• npm run test:unit — all pass; new tests cover level parsing/fallback and prove (through Yoga) the access-line shape, X-Request-Id correlation, and probe-path suppression
• npm run lint / npx prettier --debug-check . — clean

🤖 Generated with Claude Code

[SanabriaRusso]

Verdict: MERGEABLE ✅

No secret leak, no log-injection, no downstream breakage. The findings below are all optional.

What I checked

• HARD CONSTRAINT Add Actions resolver support #1 (error text is load-bearing). maskedErrors is untouched — src/server/server.ts at head passes no maskedErrors option, and plugins.ts:38-56 only reads args.result.errors inside useLogger's logFn, which cannot mutate the result. Ran the real thing: POST { protocolState { epoch } } still returns 200 with {"errors":[{"message":"Cannot query field \"protocolState\" on type \"Query\".","locations":[...]}]} — byte-identical to main. mina-explorer-api/app/upstream/graphql.py SCHEMA_ERROR_MARKERS and mina-explorer/src/services/api/bestChainFilter.ts (includes('inBestChain')) keep working. Validation errors never even reach the logFn — envelop's useLogger only hooks onExecute/onSubscribe, so a failed validation short-circuits before it.
• Secrets / PII. PG_CONN is never logged — startup emits {port} only (src/index.ts:17). No headers, no Authorization, no client IP, no cookies, and no config dump anywhere. Full query text is no longer logged: plugins.ts dropped inspect(contextValue.params) (which carried the whole query string) and now logs only variableValues, and only on the error path. That's a net reduction vs main. Nothing logs per-resolver or per-row; one info line per request at ~4 req/s is nothing.
• Correlation-id log injection — not exploitable. pino escapes it. lib/tools.js:88 _asString bails to JSON.stringify whenever it sees a char < 32 (and unconditionally for strings > 100 chars). Confirmed with pino 10.3.1: x-request-id: evil"}\n{"level":"info","msg":"forged comes out as "requestId":"evil\"}\n{\"level\":\"info\",\"msg\":\"forged" — one line, valid JSON, no forged record. The id is generated via randomUUID() when the header is absent (request-logging.ts:47).
• Flush on exit — fine, and no conflict with P1: Graceful shutdown — drain, flush traces, uncaught handlers (#170) #188. pino() with no destination builds buildSafeSonicBoom({ fd: 1 }) (pino.js → lib/tools.js:365), i.e. stdout, sync: false, minLength: 0. Because sync is falsy, on-exit-leak-free registers a process.on('exit') handler that calls stream.flushSync(). Verified end-to-end: logger.error(...) immediately followed by process.exit(1) still prints. So src/index.ts's process.exit(0)/process.exit(1) lose nothing, and P1: Graceful shutdown — drain, flush traces, uncaught handlers (#170) #188 will not need to add a flush.
• CORS / preflight (Add a Dockerfile to build and run the server #2) and query shapes (Update opentelemetry npm plugin to use @opentelemetry/sdk-trace-base instead #3) untouched. OPTIONS still answers 204 with Access-Control-Allow-Origin. Single module-level logger instance, stdout, default level info.
• CI is honest. test:unit globs ./build/tests/unit/*test.js, so tests/unit/logging.test.ts really runs.

Non-blocking nits

1. LOG_LEVEL=fatal turns yoga's own logging all the way up. This PR's doc change (docs/getting-started.md:179) now advertises trace | fatal | silent, but src/server/server.ts:9 still does process.env.LOG_LEVEL as LogLevel and hands the raw string to yoga, whose table is {debug:0, info:1, warn:2, error:3, silent:4} (@graphql-yoga/logger). Measured:

LOG_LEVEL=info    yoga emits: info,warn,error
LOG_LEVEL=error   yoga emits: error
LOG_LEVEL=fatal   yoga emits: debug,info,warn,error   <-- score undefined
LOG_LEVEL=trace   yoga emits: debug,info,warn,error

An operator setting fatal to quiet things gets yoga's two per-request debug lines (Parsing request to extract GraphQL parameters, Processing GraphQL Parameters) as ANSI-coloured non-JSON.

2. Same fix covers this: yoga still emits multi-line ANSI stack blocks that no aggregator can parse. Pre-existing, not a regression — but it's the gap between the PR title and reality. Every masked execution error produces the clean pino line plus ~15 lines of \x1b[31mERR\x1b[0m Error: ... at executeField (...) on the side. logging accepts a YogaLogger object (graphql-yoga/cjs/server.js:104-112), so route it through pino and delete the cast:

// src/server/server.ts
import { inspect } from 'node:util';
import { logger } from './logger.js';

const yogaLog =
  (level: 'debug' | 'info' | 'warn' | 'error') =>
  (...args: unknown[]) => {
    const err = args.find((a): a is Error => a instanceof Error);
    const msg = args
      .filter((a) => !(a instanceof Error))
      .map((a) => (typeof a === 'string' ? a : inspect(a, { depth: 3 })))
      .join(' ');
    logger[level](err ? { err } : {}, msg || 'yoga');
  };

const yoga = createYoga<GraphQLContext>({
  schema,
  logging: {
    debug: yogaLog('debug'),
    info: yogaLog('info'),
    warn: yogaLog('warn'),
    error: yogaLog('error'),
  },
  // ...unchanged
});

LOG_LEVEL then flows through createLogger() only, which already validates it — one source of truth, and nit 1 disappears.

3. Cap the inbound X-Request-Id. Not injection (see above), but it is unbounded: I sent an 8000-char header and got all 8000 chars into the access line, and into every error line for that request. Node's default maxHeaderSize is 16 KiB, so that's ~80x log-byte amplification per request, plus an unbounded-cardinality field for Loki/Elastic.

// src/server/request-logging.ts
/** Max characters kept from an inbound X-Request-Id. */
const MAX_REQUEST_ID_LENGTH = 128;
/** Printable ASCII only, minus quote and backslash. */
const UNSAFE_REQUEST_ID_CHARS = /[^\x20-\x7e]|["\\]/g;

function sanitizeRequestId(raw: string | null): string {
  if (!raw) return randomUUID();
  const cleaned = raw
    .replace(UNSAFE_REQUEST_ID_CHARS, '')
    .slice(0, MAX_REQUEST_ID_LENGTH)
    .trim();
  return cleaned.length > 0 ? cleaned : randomUUID();
}

then onRequest: const id = sanitizeRequestId(request.headers.get('x-request-id'));

Test:

test('caps and sanitises an inbound X-Request-Id', async () => {
  const entries: Entry[] = [];
  const yoga = serverWith(entries);
  await yoga.fetch('http://localhost/', {
    method: 'POST',
    headers: {
      'content-type': 'application/json',
      'x-request-id': `bad"\u0007id${'A'.repeat(500)}`,
    },
    body: JSON.stringify({ query: '{ __typename }' }),
  });
  const id = entries[0].obj.requestId as string;
  assert.strictEqual(id.length, 128);
  assert.match(id, /^[\x20-\x7e]+$/);
  assert.ok(!id.includes('"'));
});

test('generates an id when the inbound header is blank', async () => {
  const entries: Entry[] = [];
  const yoga = serverWith(entries);
  await yoga.fetch('http://localhost/', {
    method: 'POST',
    headers: { 'content-type': 'application/json', 'x-request-id': '   ' },
    body: JSON.stringify({ query: '{ __typename }' }),
  });
  assert.match(entries[0].obj.requestId as string, /^[0-9a-f-]{36}$/);
});

4. The error log lost the stack and the Postgres error fields. errors: args.result.errors goes through pino's stringify → JSON.stringify → GraphQLError.prototype.toJSON(), which returns only {message, locations, path}. Side-by-side on a thrown Error carrying code: '42P01':

main: [ Error: relation "blocks" does not exist \n at ... (full stack) \n { path, locations, extensions } ]
PR:   "errors":[{"message":"relation \"blocks\" does not exist","locations":[...],"path":["blocks"]}]

Message survives (good), but originalError — the Postgres code, routine, severity, and the stack — is gone. That's the stuff you want at 3am. Cheap fix:

errors: args.result.errors.map((e: GraphQLError) => ({
  message: e.message,
  path: e.path,
  locations: e.locations,
  stack: e.originalError?.stack ?? e.stack,
  code: (e.originalError as { code?: string } | undefined)?.code,
})),

5. Browser preflights get an access line with no requestId and no durationMs. options.plugins are appended last (graphql-yoga/cjs/server.js:215), after useCORS, whose onRequest calls endResponse() + stopEarly() for OPTIONS — so useRequestLogging's onRequest never runs, while onResponse still does. Measured: {"method":"OPTIONS","path":"/","status":204}. Since mina-explorer POSTs Content-Type: application/json cross-origin, every explorer query is preceded by one of these, so roughly half your access lines will be id-less. Backfill lazily:

onResponse({ request, response }) {
  const path = pathOf(request.url);
  if (QUIET_PATHS.has(path)) return;
  let id = requestIds.get(request);
  if (id === undefined) {
    // CORS/health-check short-circuited onRequest.
    id = sanitizeRequestId(request.headers.get('x-request-id'));
    requestIds.set(request, id);
  }
  // ...

6. Docs still tell operators to look for the old startup line. The message is now {"level":"info",...,"port":"8080","msg":"server started"}, but docs/getting-started.md lines 50, 92, 150, 199 still say Server is running on port: 8080. Nothing in CI or the compose healthcheck greps for it (checked), so it's docs-only.

7. Minor. base: { service } replaces pino's default { pid, hostname } — consider base: { pid, hostname, service } so you can tell pods apart before the collector adds labels. Also JAEGER_SERVICE_NAME naming the logger sits oddly with "independent of tracing"; a SERVICE_NAME ?? JAEGER_SERVICE_NAME ?? 'archive-api' chain would read better. And /readiness in QUIET_PATHS has no matching endpoint yet — server.ts only registers healthCheckEndpoint: '/healthcheck' — harmless, presumably staged for #188.

8. FYI on the downstream side. mina-explorer-api already mints an x-request-id (app/observability.py:252) but does not forward it upstream — app/upstream/graphql.py:233 posts with json=payload and no headers=. One line there gives you end-to-end correlation now that this PR honours the header. Separately, the id is not echoed in the HTTP response, so there is nothing to add to Access-Control-Expose-Headers and browsers can't read it — fine as-is, just noting it if you later decide to echo it.

9. Mechanical. The branch is CONFLICTING / DIRTY against main — the lockfile still carries 0.0.5 → 0.0.6 while main is at 0.0.9. Needs a rebase before it can merge.

Automated second-pass review — focus: downstream compatibility with mina-explorer / mina-explorer-api.

[SanabriaRusso]

Approving on the basis of the second-pass review comment above: no mid-to-high severity security, compatibility, or degradation issue found, and the downstream contract with mina-explorer / mina-explorer-api holds — GraphQL validation error text reaches errors[].message verbatim, the browser SPA's cross-origin access is preserved, and the real consumer query shapes (including the 2000-block analytics query and the 500-row page crawl) still pass.

Two things this approval does not mean:

• It does not close the non-blocking items in the review comment. Several are worth fixing before or shortly after merge; they are written up there with patches.
• It does not by itself mean the branch is ready to merge. main requires branches to be up to date, so this needs an update-branch (or a rebase, if the branch is conflicting) first, and a few PRs in this series have cross-PR ordering constraints called out in their review comments.

Automated second-pass review — focus: downstream compatibility with mina-explorer / mina-explorer-api.

[SanabriaRusso]

Approving. Both round-1 carry-forwards are fixed, and I verified each one by running it rather than by reading.

(a) LOG_LEVEL=fatal no longer emits debug. The fix at src/server/server.ts:15-38 is the right one: stop handing yoga a level string it doesn't recognise (which is what triggered its fallback) and hand it an explicit YogaLogger whose methods delegate to pino, where LOG_LEVEL actually gates output. Against real graphql-yoga@4.0.4 + pino@10.3.1:

config	output for one POST
createYoga({ logging: 'fatal' }) (main)	3 DEBUG lines — Parsing request to extract GraphQL parameters, Processing GraphQL Parameters, Processing GraphQL Parameters done.
this PR, pino level: 'fatal'	0 lines emitted, 0 leaked to console

src/server/logger.ts:10-18 also lowercases and allow-lists the level set, so both fatal and silent — the two the docs advertise — now behave, and the pre-existing LOG_LEVEL=Info (capital I) in .env.example.compose:7 is handled by the .toLowerCase().

(b) Inbound X-Request-Id is capped and sanitized. sanitizeRequestId() (src/server/request-logging.ts:26-33) strips /[^\x20-\x7e]|["\\]/g before slicing to 128 and trimming, so it closes the header-injection vector as well as the log-injection one — at the source, before the value reaches any sink. Nine adversarial inputs:

input	result
8000 × A	len 128
abc\r\nX-Evil: 1	abcX-Evil: 1
abc\n{"level":"fatal"}	abc{level:fatal}
a"b\c	abc
" " / ""	generated UUID
a\u0000b	ab
3000 × x\r\n	len 128

Round-1 "verified OK" items all survived the rebase. PG_CONN appears nowhere in the diff. The stack/code fields added by 83f5f2ab are safe — postgres/cjs/src/connection.js:389 composes a query error's stack as err.stack + query.origin, i.e. a JS call-site stack, not the SQL and not the DSN; code is the SQLSTATE. Error text is byte-identical (only the logging option changed; maskedErrors untouched) — confirmed live: a throwing resolver returns Unexpected error. at HTTP 200 while the server log holds the real message. And main's full-query inspect(..., { depth: null, colors: true }) dump is still gone, ANSI codes included.

Correlation confirmed working end to end. With x-request-id: client-abc-123 on a failing query, both the envelop error line and the access line carried requestId: "client-abc-123" — one distinct id across both, because args.args.contextValue.request is the same Request object the onRequest hook keyed the WeakMap on. A request with no inbound id gets a UUID (tests/unit/logging.test.ts:96-105).

Non-blocking nits

1. The id isn't echoed back in a response header. The docs don't promise it, so not a blocker — and since nothing echoes the value, the injection concern is moot either way. But it's the other half of correlation: an operator holding a client-side failure has no id to grep for. I confirmed yoga's Response headers are mutable in onResponse and that it works on all three shapes (POST 200, healthcheck 200, OPTIONS 204):

   onResponse({ request, response }) {
     const path = pathOf(request.url);
     let id = requestIds.get(request);
     // ... existing backfill ...
     response.headers.set('x-request-id', id); // already sanitized => safe to echo
     if (QUIET_PATHS.has(path)) return;
     log.info({ requestId: id, /* ... */ }, 'request completed');
   }

   The headers.set needs to sit before the QUIET_PATHS early-return if probes should carry it too. Note that if you do add this, #184 pins allowedHeaders: ['content-type'], so a browser client wanting to send x-request-id would need that list widened — reading it back is unaffected.

2. Log volume: one info line per non-probe request — at the README's ~800 req/s, ~800 lines/s to stdout. It is configurable (LOG_LEVEL=warn keeps errors, drops access lines), which is why this isn't blocking, but that also silences server started and there's no dedicated access-log toggle. Worth one doc line saying LOG_LEVEL=warn is how you turn access logging off.

3. useRequestLogging() is pushed unconditionally (plugins.ts:18), not behind ENABLE_LOGGING (which still gates only Jaeger). Intentional per the description, but it is a behaviour change from main, which had no per-request line at all.

4. yogaLog (server.ts:16-27) still runs args.find/filter/map/join on every yoga debug call before pino drops it — 3 calls/request at info. Strings only, so negligible; a logger.isLevelEnabled(level) guard would zero it.

5. Once #191 lands, QUIET_PATHS should probably gain /metrics — useMetrics short-circuits onRequest, but the backfill at request-logging.ts:63-70 logs the scrape anyway.

Merge note — the one that matters. src/server/server.ts conflicts with #195, and it is a conflict where a naive resolution silently loses something. Both PRs edit the same createYoga options object: this PR replaces logging: LOG_LEVEL with the YogaLogger object; #195 keeps logging: LOG_LEVEL, splits out buildYoga, and adds maskedErrors: { isDev: false }. Resolving toward either side alone re-breaks the other — LOG_LEVEL=fatal starts emitting debug again, or the dev-mode connection-string leak comes back. The correct merged result keeps all three:

function buildYoga(context: GraphQLContext, plugins: Plugin[]) {
  return createYoga<GraphQLContext>({
    schema,
    logging: {
      debug: yogaLog('debug'), info: yogaLog('info'),
      warn: yogaLog('warn'),  error: yogaLog('error'),
    },
    graphqlEndpoint: '/',
    landingPage: false,
    healthCheckEndpoint: '/healthcheck',
    graphiql: process.env.ENABLE_GRAPHIQL === 'true' ? true : false,
    maskedErrors: { isDev: false },
    plugins,
    cors: { origin: process.env.CORS_ORIGIN ?? '*', methods: ['GET', 'POST'] },
    context,
  });
}

The #195 side is the more dangerous half to drop, because its own test suite would still pass without it. src/server/plugins.ts also conflicts with #185 and #191 (all three insert at index 0 of buildPlugins) — textual only, no semantic conflict, but keep this PR's rewritten useLogger logFn in the resolution.

Downstream: no impact on mina-explorer or mina-explorer-api. Error text and statuses are unchanged; only operator log output format changed, and the docs are updated in step. No consumer parses those lines.

[SanabriaRusso]

Not re-approving this one. I approved 83f5f2a and intended to restore that approval after the force-push, but the rebase introduced a regression that was not in the commit I reviewed. The application code is still good — this is entirely about package-lock.json.

Blocker: the rebase stripped resolved + integrity from 1570 of 1586 lockfile entries

The commit I approved touched the lockfile with 138 insertions and no deletions — just pino and its dependency subtree. The current head rewrites it wholesale: 21,878 → 19,434 lines, with 1,586 "resolved" and 1,586 "integrity" lines deleted and only 16 of each added back.

                lock lines   "resolved"   "integrity"
  origin/main        21878         1586          1586
  #190 head          19434           16            16

Every other open PR in this batch retains full metadata (#182/#184/#185/#188/#193/#195/#196 = 1586, #183 = 1602, #194 = 1579). This is #190 alone.

The shape of the damage, e.g. node_modules/graphql:

     "node_modules/graphql": {
-      "version": "16.8.1",
-      "resolved": "https://registry.npmjs.org/graphql/-/graphql-16.8.1.tgz",
-      "integrity": "sha512-59LZHPdGZVh695Ud9lRzPBVTtlX9ZCV150Er2W43ro37wVof0ctenSaskPPjN7lVTIN8mSZt8PHUNKZuNQUuxw==",
+      "version": "16.14.2",
+      "license": "MIT",

resolved/integrity replaced by license. That substitution is the signature of npm install re-deriving the tree from an already-populated node_modules instead of from the registry: npm reads each package's local package.json (hence license) and has no download to record. The only 16 entries that kept their hashes are the ones actually fetched for this PR — pino, sonic-boom, thread-stream, split2, @pinojs/redact and friends. node_modules/fsevents was also dropped, which points at the tree having been assembled on a non-macOS host.

Why this blocks rather than being a nit

1. It removes supply-chain verification from npm ci for 1570 packages. With no integrity hash there is nothing to check a tarball against; npm resolves by name@version and installs whatever the registry returns. This lands directly on top of #192, which merged three days ago for the express purpose of hardening the supply chain, and it silently guts the guarantee that PR was buying.
2. It is invisible in CI. All nine checks are green on this head, and they will stay green — installs still succeed, they just stop being verified. Nothing in the pipeline asserts integrity coverage.
3. It smuggles in unrelated version movement. graphql 16.8.1 → 16.14.2 and other transitive bumps ride along with no provenance recorded. #183 makes the same graphql bump with hashes intact; these two lockfiles will conflict, and resolving toward this one loses the metadata for the whole tree.

To unblock

Regenerate the lockfile from the registry rather than from a local tree, on a branch rebased onto current main:

rm -rf node_modules package-lock.json
npm install            # or: npm install --package-lock-only

Then confirm before pushing — this should print 1586 + pino's subtree, not 16:

grep -c '"integrity":' package-lock.json

If a private registry or proxy .npmrc was in play, that is the likely cause and is worth checking either way, since CI writes a live GCP token into .npmrc on some build paths.

---

The rest of the PR is unchanged and still good

The application diff is byte-identical to what I approved — logger.ts, request-logging.ts, the plugins.ts insertion, server.ts, and tests/unit/logging.test.ts all match line for line. Everything from round 2 stands:

• LOG_LEVEL=fatal: main emits 3 DEBUG lines per request; this PR emits 0.
• X-Request-Id is length-capped and character-sanitized (strips everything outside printable ASCII plus quote/backslash) before slicing, which closes header injection as well as log injection. Nine adversarial inputs tested.
• No secret leak: the new stack/code fields carry a JS call-site stack and the SQLSTATE, not the SQL or the DSN.

Non-blocking, as before: the request id is not echoed in a response header (the other half of correlation), and ~800 access lines/s at benchmark load is only silenceable via LOG_LEVEL=warn, which also silences startup.

Merge-train note that still applies: merge #195 before this PR. Both rewrite src/server/server.ts; #195 adds maskedErrors: { isDev: false } and this PR swaps logging: LOG_LEVEL for a YogaLogger object. Dropping #195's maskedErrors during conflict resolution is silent — its tests still pass with NODE_ENV unset, and only the NODE_ENV=development password leak comes back.

Happy to re-approve as soon as the lockfile is regenerated; nothing else here needs to change.