pino-otel.ts · Source

pino-otel.tspackages/observability/src/pino-otel.tsraw ← src5,264 B← Back to the app
1/**
2 * @factory/observability — pino correlation bridge (TASK-0135).
3 *
4 * The spec's log requirement: pino → stdout (JSON) with `requestId` on EVERY
5 * line (the correlation id from `X-Request-Id`/generated) + `traceId`/
6 * `spanId` (the OTel span context) whenever a span is active.
7 *
8 * Implementation: a pino `redact`/serialize-adjacent bridge built from
9 * `pino.final` + child bindings is NOT used (the apps own their logger
10 * instances and pass explicit bindings). Instead this module gives:
11 *
12 *  - {@link otelLogBindings(reqId)} — the bindings object every log line
13 *    should carry: `requestId` (always; `"unknown"` when absent — the API
14 *    logger's existing convention) + `traceId`/`spanId`/`traceFlags` read
15 *    from the ACTIVE span context (absent when no span / OTel disabled —
16 *    exactOptionalPropertyTypes: keys are omitted, never `undefined`);
17 *  - {@link makeOtelPino} — a ready pino logger with those bindings applied
18 *    via a `syncMessage`-free child: every line pino emits carries them.
19 *
20 * The bridge reads ONLY `@opentelemetry/api` (global tracer) — it works with
21 * or without the SDK (no span → no trace fields, no crash).
22 */
23import { context as otelContext, trace } from "@opentelemetry/api";
24import pino from "pino";
25import type { Logger as PinoLogger } from "pino";
26import type { Writable } from "node:stream";
27 
28export interface OtelLogBindings {
29  /** The correlation id (X-Request-Id / generated uuid; "unknown" when absent). */
30  requestId: string;
31  /** W3C trace id (32 hex) — only present when a span is active. */
32  traceId?: string;
33  /** W3C span id (16 hex) — only present when a span is active. */
34  spanId?: string;
35  /** Workspace id — only present when the caller resolved one. */
36  workspaceId?: string;
37}
38 
39/**
40 * Build the correlation bindings for one log call. Safe to call at any time
41 * (no active context → just `{ requestId }`).
42 */
43export function otelLogBindings(requestId: string | undefined, workspaceId?: string): OtelLogBindings {
44  const out: OtelLogBindings = { requestId: requestId ?? "unknown" };
45  const sc = trace.getSpanContext(otelContext.active());
46  if (sc && sc.traceId && sc.spanId) {
47    out.traceId = sc.traceId;
48    out.spanId = sc.spanId;
49  }
50  if (workspaceId) out.workspaceId = workspaceId;
51  return out;
52}
53 
54export interface MakeOtelPinoOptions {
55  /** Service name — logged on every line (the NFR §7.1 `service` field). */
56  service: string;
57  /** pino level (default: the LOG_LEVEL env or `info`). */
58  level?: string;
59  /** Extra static bindings (e.g. `env`). */
60  base?: Record<string, unknown>;
61  /** Output destination (default: process.stdout; tests pass a collector). */
62  dest?: Writable;
63}
64 
65/**
66 * Create a pino logger whose EVERY line carries the correlation bindings.
67 * The per-line dynamic part (the ACTIVE span context at write time) is
68 * applied via a `pino.final`-style wrapper: pino's child bindings are
69 * per-logger-static, so the span-aware part rides on a custom
70 * `onChild`/child factory — the simplest correct shape is a `child()`
71 * factory the app calls per request, BUT the spec wants it on EVERY line
72 * (including request-less background work), so we use pino's `mixin` hook:
73 * pino calls `mixin()` on every log write and merges the returned object
74 * into the line. That is exactly "add traceId/spanId to every log line".
75 */
76export function makeOtelPino(opts: MakeOtelPinoOptions): PinoLogger {
77  const base: Record<string, unknown> = {
78    service: opts.service,
79    ...(opts.base ?? {})
80  };
81  return pino(
82    {
83      level: opts.level ?? process.env.LOG_LEVEL ?? "info",
84      // pino 9 calls the mixin on EVERY write with the WRITING logger as the
85      // third arg — so a request child's static `requestId` binding is read
86      // here and the mixin's value agrees with it (pino's default merge
87      // gives child bindings priority over the mixin anyway). Root-logger
88      // (background) lines have no requestId binding → "unknown".
89      mixin: (
90        _obj: object,
91        _level: number,
92        logger: PinoLogger
93      ): { requestId: string; traceId?: string; spanId?: string; workspaceId?: string } => {
94        const b = logger.bindings() as Record<string, unknown>;
95        const requestId = typeof b["requestId"] === "string" ? b["requestId"] : undefined;
96        const workspaceId = typeof b["workspaceId"] === "string" ? b["workspaceId"] : undefined;
97        return otelLogBindings(requestId, workspaceId);
98      },
99      base: { ...base }
100    },
101    opts.dest ?? process.stdout
102  );
103}
104 
105/**
106 * The per-REQUEST child: `logger.child(otelLogBindings(req.id))` — the
107 * request's lines carry `requestId` + the ACTIVE span's `traceId`/`spanId`
108 * (the mixin still runs, so background children of this child keep their
109 * own bindings; the child's static requestId wins over the mixin's
110 * "unknown" — pino's child precedence is child > parent > mixin… actually
111 * pino merges mixin UNDER the child's bindings, so the static requestId
112 * here shadows the mixin's — the intended behavior).
113 */
114export function requestChild(parent: PinoLogger, requestId: string | undefined, workspaceId?: string): PinoLogger {
115  return parent.child(otelLogBindings(requestId, workspaceId));
116}
117