diff --git a/CLAUDE.md b/CLAUDE.md index 7512019..f3b0210 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -40,7 +40,7 @@ The structural choices are recorded as ADRs and summarized below. Any change to - **MFA:** enforced by Entra ID Conditional Access (org-side policy, P1 licensing required); BFF sanity-checks the `amr` claim at session creation; `@RequireMfa()` decorator and freshness-based step-up are designed-in for future sensitive routes (no v1 consumer) — see [ADR-0011](decisions/0011-mfa-enforcement-entra-conditional-access.md). - **Identity:** multi-tenant Microsoft Entra ID with B2B invitation for workforce in v1, dual-audience design ready for future External ID activation — see [ADR-0008](decisions/0008-identity-model-entra-workforce-dual-audience.md). - **Authentication flow:** OIDC Authorization Code + PKCE via `@azure/msal-node`, executed entirely on the BFF; SPA never holds tokens; `__Host-` prefixed cookies, double-submit CSRF, RP-initiated logout — see [ADR-0009](decisions/0009-auth-flow-oidc-pkce-msal-node.md). -- **Observability:** Pino structured logs + OpenTelemetry traces with W3C Trace Context propagation — to be locked-in in phase 2. +- **Observability:** Pino + `nestjs-pino` for structured JSON logs, OpenTelemetry SDK + auto-instrumentations for traces, W3C Trace Context propagation across SPA → BFF → DB → Redis, `nestjs-cls` for request-scoped context (`trace_id`, `session_id`, `user_id_hash`, `audience`), 100 % sampling at the app with tail sampling deferred to the OTel Collector, stdout + OTLP shipping — see [ADR-0012](decisions/0012-observability-pino-opentelemetry.md). - **Local quality gates:** Husky + lint-staged + commitlint with Conventional Commits — see [ADR-0007](decisions/0007-pre-commit-hooks-and-conventional-commits.md). - **Runtime:** Node.js latest LTS major. diff --git a/decisions/0012-observability-pino-opentelemetry.md b/decisions/0012-observability-pino-opentelemetry.md new file mode 100644 index 0000000..54e841c --- /dev/null +++ b/decisions/0012-observability-pino-opentelemetry.md @@ -0,0 +1,331 @@ +--- +status: accepted +date: 2026-04-29 +decision-makers: R&D Lead +tags: [observability, backend, frontend] +--- + +# Observability — Pino structured logs + OpenTelemetry tracing, W3C Trace Context propagation, stdout + collector + +## Context and Problem Statement + +The portal has stated security, performance, and accessibility as first-class concerns. None of the three can be operated, audited, or improved without observability built in from day one. We need a fixed answer to: + +- *How* application events are recorded (logs, traces); +- *Which* identifier ties together what happens in the SPA, the BFF, the DB, the cache, and any downstream API call for a single user action; +- *Where* the signals are emitted, and how they reach a backend; +- *What* must never appear in a log line (PII, credentials, tokens); +- *How* the architecture stays vendor-neutral so the chosen on-prem backend (Grafana stack, ELK, or otherwise — phase 3) can be selected without rewriting the application. + +Two signals are in scope here: **logs** and **traces**. Metrics are deliberately out of scope; if metrics become necessary later, they fit naturally into the same OpenTelemetry pipeline and will get their own ADR. + +## Decision Drivers + +* A single correlation identifier across all signals — front-end click, BFF request, DB query, downstream API call, log line — debuggable in seconds, not in spelunking. +* Vendor-neutral standards (OpenTelemetry, W3C Trace Context) so the on-prem backend can be chosen later (phase 3) without coupling the application to it. +* Mature, enterprise-grade libraries — anti-bricolage applies particularly here. +* 12-factor: the application emits to stdout / OTLP; shipping is an operational concern, not an application concern. +* Privacy: PII (and credentials, tokens) must never reach a log line. Defense in depth — even if a log is exfiltrated, it must contain the minimum needed for support. +* The SPA must participate in the trace so the first segment (user click → first request) is not lost. + +## Considered Options + +### Logging library +* **Pino + `nestjs-pino`.** (Chosen.) +* Winston. +* Bunyan. +* Plain `console.log` / NestJS default `Logger` only. + +### Tracing instrumentation +* **OpenTelemetry SDK + `auto-instrumentations-node`.** (Chosen.) +* Vendor SDKs (Datadog, New Relic). +* OpenTracing. +* Custom hand-rolled tracer. + +### Trace propagation header +* **W3C Trace Context (`traceparent`, `tracestate`).** (Chosen.) +* Custom `X-Correlation-ID`. +* Vendor formats (B3, Datadog, Jaeger). + +### Request-scoped context (correlation propagation in code) +* **`nestjs-cls` over Node `AsyncLocalStorage`.** (Chosen.) +* Manual passing through every call signature. +* Direct `AsyncLocalStorage` without the NestJS wrapper. + +### Sampling +* **Always-on (100 %) at the application; tail sampling deferred to the collector / phase-3 ADR.** (Chosen for v1.) +* Probabilistic head sampling (e.g. 10 %). + +### Emission and shipping +* **stdout (logs) + OTLP/HTTP (traces) → local OpenTelemetry Collector → on-prem backend (phase 3).** (Chosen.) +* Direct shipping from the app to the backend. + +### Sensitive data handling in logs +* **Pino `redact` with an explicit allowlist of paths to strip.** (Chosen.) +* Hand-rolled scrubbing per log call. +* No redaction. + +### Frontend tracing +* **OpenTelemetry-Web in the Angular SPA, propagating `traceparent` on outbound HTTP.** (Chosen.) +* Front-end out of the trace. + +## Decision Outcome + +**Logging.** `pino` is the structured logger; `nestjs-pino` integrates it into NestJS, replacing the framework's default `Logger`. Output is JSON, line-delimited, on stdout. Log lines carry a fixed envelope: + +```json +{ + "level": "info", + "time": "2026-04-29T20:15:42.123Z", + "service": "portal-bff", + "version": "", + "env": "prod", + "trace_id": "0af7651916cd43dd8448eb211c80319c", + "span_id": "b7ad6b7169203331", + "session_id": "…", + "user_id_hash": "sha256:…", + "audience": "workforce", + "msg": "GET /documents 200", + "method": "GET", + "path": "/documents", + "status": 200, + "duration_ms": 14 +} +``` + +The contextual fields (`trace_id`, `span_id`, `session_id`, `user_id_hash`, `audience`) are pulled from the request-scoped CLS by a custom Pino formatter — no per-call boilerplate. + +**Tracing.** OpenTelemetry SDK for Node (`@opentelemetry/sdk-node`) is started before NestJS bootstrap. `@opentelemetry/auto-instrumentations-node` is enabled with the modules we use: HTTP, Express, NestJS core, `pg`, `ioredis`, and Prisma (via Prisma's built-in OTel hooks). Custom spans can be created inline via `@opentelemetry/api`'s `tracer.startActiveSpan` for non-trivial business flows. + +**Propagation.** **W3C Trace Context** is the only propagation format. The `traceparent` (and optionally `tracestate`) header carries the trace identity end to end. The `trace_id` extracted from `traceparent` *is* the correlation identifier — there is no separate `X-Correlation-ID`. If a request arrives without a `traceparent`, the SDK starts a new trace and the BFF emits the resulting `traceparent` in the response so the SPA can pick it up. Downstream HTTP calls automatically carry `traceparent` thanks to the HTTP auto-instrumentation. + +**Request-scoped context.** `nestjs-cls` is registered globally and exposes the per-request store. At the entry of every request, an interceptor populates: + +| Key | Source | +| --- | --- | +| `trace_id` | OTel current span context | +| `span_id` | OTel current span context | +| `session_id` | session lookup (ADR-0010) | +| `user_id_hash` | `sha256(user_id + LOG_USER_ID_SALT)` computed once per session and cached on the session payload | +| `audience` | session payload (ADR-0008) | + +The Pino formatter and the audit-log writer (future ADR) read from CLS — neither requires the developer to thread context through call signatures. + +**`user_id_hash` salting.** A per-environment salt (`LOG_USER_ID_SALT`) is required and read from env. The hash is `sha256(userId || ":" || salt)`, base64-url-encoded. The salt is rotated as part of secret-rotation procedures (future ops ADR). Without the salt, the same `userId` always produces the same hash, which is enumerable for known userId spaces; the salt makes per-environment hashes incomparable. + +**Sampling.** v1 emits **100 % of traces** at the application. Volumes are low and end-to-end debuggability is the priority. Tail sampling (drop the boring traces, keep the slow / failed ones) is performed at the **OpenTelemetry Collector**, configured as part of the phase-3 infrastructure ADR. The application *does not* know nor care about sampling policy — moving the policy is a collector-config change. + +**Emission and shipping.** Logs go to **stdout** as line-delimited JSON. Traces are exported via **OTLP/HTTP** to a local **OpenTelemetry Collector** instance running alongside the BFF (sidecar in container orchestration, local process in dev). The collector is the single point that knows the on-prem backend's address and credentials; the application stays decoupled. Backend choice and collector deployment topology are deferred to the phase-3 infrastructure ADR. + +**Redaction.** Pino's `redact` option strips a fixed list of paths from every log line *before* it is serialised: + +```ts +redact: { + paths: [ + 'req.headers.authorization', + 'req.headers.cookie', + 'req.headers["set-cookie"]', + 'res.headers["set-cookie"]', + '*.password', + '*.client_secret', + '*.access_token', + '*.refresh_token', + '*.id_token', + '*.tokens', + '*.session_secret', + ], + censor: '[REDACTED]', +} +``` + +The list lives in `apps/portal-bff/src/observability/log.redact.ts` and is reviewed in every PR that adds a new field-shape (DTO, claim, header). A unit test asserts that no path on the redact list ever appears in any logger output. + +**Log levels.** `trace`, `debug`, `info`, `warn`, `error`, `fatal`. Default level: `info` in prod, `debug` in dev, configurable via `LOG_LEVEL`. `trace` and `debug` must never be enabled in prod long-term — only for short-lived investigation under a feature flag. + +**Frontend tracing.** The Angular SPA (`portal-shell`) is instrumented with **OpenTelemetry for browsers** (`@opentelemetry/sdk-trace-web`). An Angular `HttpInterceptor` propagates the current `traceparent` on every outbound HTTP call (typed targets only — the BFF). The trace identifier is therefore the same one the user sees if a support ticket is opened (the `trace_id` is exposed in the SPA's error-display UI for support hand-off). A user click → SPA dispatch → BFF request → DB query → response is a single trace, navigable end to end. + +The SPA does **not** ship its own logs to a backend in v1. Browser-side error reporting (uncaught exceptions, Promise rejections) is a separate concern and will get its own ADR if and when it becomes necessary; in the interim, errors are visible in the browser console for development and surface as 500-equivalents in the BFF logs once the failed request reaches the server. + +**Audit logs are not application logs.** Anything that is a security-relevant audit event (sign-in, sign-out, MFA challenge, authorization deny, admin action — when one exists) is emitted via a *separate* writer and a *separate* sink, defined by the audit-trail ADR (next). The two streams may share the trace identifier and the CLS context, but they do not share the same retention, the same access controls, or the same volume profile. + +**Configuration (env-driven).** + +| Variable | Purpose | +| --- | --- | +| `LOG_LEVEL` | `trace`/`debug`/`info`/`warn`/`error`/`fatal`; default `info` in prod, `debug` in dev | +| `LOG_USER_ID_SALT` | per-env salt for `user_id_hash` | +| `OTEL_SERVICE_NAME` | e.g. `portal-bff`, `portal-shell` | +| `OTEL_SERVICE_VERSION` | git sha or semver | +| `OTEL_RESOURCE_ATTRIBUTES` | additional tags (deployment.environment, etc.) | +| `OTEL_EXPORTER_OTLP_ENDPOINT` | URL of the local OTel Collector | +| `OTEL_EXPORTER_OTLP_PROTOCOL` | `http/protobuf` (default) | +| `OTEL_TRACES_SAMPLER` | `always_on` in v1; the collector applies tail sampling | + +The BFF refuses to start if `LOG_USER_ID_SALT` or `OTEL_SERVICE_NAME` is missing. + +### Consequences + +* Good, because every signal carries the same `trace_id`, navigable across the SPA, the BFF, the DB, the cache, and downstream APIs once they exist. End-to-end debugging is one click in any conformant backend. +* Good, because OpenTelemetry + W3C are vendor-neutral; the on-prem backend (Grafana / ELK / other) is chosen later without code changes. +* Good, because Pino is the fastest established Node logger; structured JSON output is directly ingestible by every backend. +* Good, because `nestjs-cls` removes context-threading boilerplate — the developer writes business logic, the platform handles correlation. +* Good, because PII redaction and per-environment salting on `user_id_hash` minimise leakage if a log is exfiltrated; the redaction list is reviewable in PRs. +* Good, because 100 % sampling at the application keeps the architecture simple in v1; sampling policy moves to the collector when volumes justify it. +* Bad, because the OTel Node SDK has historically had churn in API surface; the decision to use auto-instrumentations rather than hand-instrument is a calculated bet on the upstream stabilisation. Mitigated by pinning OTel package versions and lifting them deliberately. +* Bad, because emitting 100 % traces in prod at scale will eventually cost storage; the deferral to collector-side tail sampling is the proper answer, not "drop everything at the source". +* Bad, because the redaction list is a per-line config — adding a new sensitive shape (e.g. a future PII field) requires a PR. There is no fully automatic "redact anything that looks PII-like". This is an accepted trade-off: explicit beats clever. +* Bad, because the SPA's OTel-Web bundle adds a small payload (~30 KB gzip). Acceptable; we already prioritise observability over aesthetic minimalism. +* Bad, because no front-end log shipping in v1 means we are blind to client-only errors that don't cause a server-side request. Acceptable for v1; revisit if support volume justifies it. +* Neutral, because audit logs being a separate stream is enforced by writer separation, not by namespacing inside the same Pino logger — this is intentional (different retention, different access). + +### Confirmation + +* `apps/portal-bff/src/observability/observability.module.ts` registers `nestjs-pino`, `nestjs-cls`, the OTel SDK initialiser, and the redact-list test fixture. +* `apps/portal-bff/src/main.ts` calls `tracingSetup()` *before* `NestFactory.create(AppModule)` — OTel must be initialised before any auto-instrumented module is loaded. +* The Pino transport in dev uses `pino-pretty` (human-readable); prod emits raw JSON. +* `apps/portal-shell/src/observability/tracing.ts` initialises `@opentelemetry/sdk-trace-web` with the OTLP/HTTP exporter pointing to the BFF's `/v1/traces` ingress (or directly to the collector if exposed). +* Every controller receives `req` and `res` and the http auto-instrumentation produces a span; non-trivial service methods open custom spans via `tracer.startActiveSpan('domain.', ...)` and propagate the CLS context within them. +* Integration tests: + - a single user-action request emits one trace with correct parent-child structure (SPA → BFF → DB); + - every log line for that request carries the same `trace_id`; + - the redact list strips its targets from a captured stream; + - a missing `LOG_USER_ID_SALT` prevents BFF startup. +* The CLS-bound `user_id_hash` is identical for two consecutive requests of the same user, and different across environments (different salt). +* The OTel Collector configuration ships in the deployment manifest (covered by the future infrastructure ADR), not in source — the application remains backend-agnostic. + +## Pros and Cons of the Options + +### Logging library + +#### Pino + `nestjs-pino` (chosen) + +* Good, because the fastest established Node logger; JSON structured output by default; first-class integration with NestJS (HTTP request logging, async context). +* Good, because rich `redact` configuration with path globbing — exactly what we need for PII handling. +* Bad, because `nestjs-pino` is third-party (well-maintained, but not Nest-team-owned). Acceptable. + +#### Winston + +* Good, because long-standing, large user base. +* Bad, because slower than Pino in JSON mode; ergonomics around async context less polished. Less aligned with our perf and DX goals. + +#### Bunyan + +* Bad, because slowing maintenance, smaller community in 2026. + +#### `console.log` / NestJS default Logger only + +* Bad, because no structured output, no redaction, no async context, no levels by config. Bricolage. + +### Tracing instrumentation + +#### OpenTelemetry (chosen) + +* Good, because the CNCF graduated standard — supported by every observability vendor and every major language. +* Good, because auto-instrumentation removes the bulk of glue work for HTTP, DB, Redis, Prisma. +* Bad, because the Node SDK has had API churn historically — managed by version pinning. + +#### Vendor SDK (Datadog, New Relic, etc.) + +* Good, because typically richer auto-instrumentation than OTel for that vendor. +* Bad, because vendor lock-in — switching backend later means rewriting instrumentation. Rejected. + +#### OpenTracing + +* Bad, because deprecated; succeeded by OTel. Rejected. + +#### Custom + +* Bad, because bricolage on a critical surface. + +### Propagation header + +#### W3C Trace Context (chosen) + +* Good, because the IETF/W3C standard adopted across the industry. +* Good, because covered by every OTel SDK and by intermediate proxies (Envoy, NGINX, AWS ALB, etc.). + +#### Custom `X-Correlation-ID` + +* Bad, because reinvents what already exists; loses the parent-child relation that `traceparent` carries; doesn't cooperate with auto-instrumentation. + +#### Vendor formats (B3, Datadog, Jaeger) + +* Bad, because vendor-specific. OTel can be configured to emit them as a fallback if a specific intermediate requires them, but they are not the default. + +### Request-scoped context + +#### `nestjs-cls` (chosen) + +* Good, because purpose-built for NestJS, integrates cleanly with interceptors, guards, and the logger. +* Good, because minimal boilerplate at the call sites. + +#### Manual passing + +* Bad, because every service signature acquires a context parameter — relentless ceremony, easy to forget. + +#### `AsyncLocalStorage` directly + +* Good, because no extra dependency. +* Bad, because we'd reinvent the request-bind plumbing already provided by `nestjs-cls`. + +### Sampling + +#### Always-on (chosen, v1) + +* Good, because end-to-end debuggability with no surprises. +* Bad, because storage cost grows linearly with volume. + +#### Probabilistic head sampling + +* Good, because cheap. +* Bad, because we lose traces of rare events — exactly the ones we need for incident analysis. Tail sampling at the collector is strictly better. + +### Emission and shipping + +#### stdout + collector (chosen) + +* Good, because 12-factor; the application is decoupled from the backend; rotating backends is an ops change, not a deploy. +* Good, because the collector handles batching, retries, sampling, and protocol translation. + +#### Direct shipping + +* Bad, because backend coupled to the application; outage of the backend impacts the app's emission path; multi-tenant credentials end up in the app config. + +### Sensitive data handling + +#### Pino `redact` allowlist (chosen) + +* Good, because explicit, reviewable, testable. +* Bad, because a new sensitive shape requires a PR — accepted. + +#### Hand-rolled scrubbing + +* Bad, because per-call boilerplate; easy to forget; inconsistent. + +#### No redaction + +* Bad, because a single accidental log of an `Authorization` header turns into a security incident. + +### Frontend tracing + +#### OTel-Web in the SPA (chosen) + +* Good, because the trace starts where the user clicks — first segment of every story is captured. +* Good, because the same `trace_id` shown to the user is the one used by support — no translation. +* Bad, because adds a small bundle to the SPA; quantifiable, accepted. + +#### Front out of the trace + +* Bad, because every trace begins one hop too late, and "front was slow" becomes uninvestigable. + +## More Information + +* OpenTelemetry: https://opentelemetry.io/ +* OpenTelemetry for Node.js: https://opentelemetry.io/docs/languages/js/ +* OpenTelemetry for Web: https://opentelemetry.io/docs/languages/js/getting-started/browser/ +* W3C Trace Context: https://www.w3.org/TR/trace-context/ +* Pino: https://github.com/pinojs/pino +* `nestjs-pino`: https://github.com/iamolegga/nestjs-pino +* `nestjs-cls`: https://github.com/Papooch/nestjs-cls +* OWASP Logging Cheat Sheet: https://cheatsheetseries.owasp.org/cheatsheets/Logging_Cheat_Sheet.html +* Related ADRs: [ADR-0005](0005-backend-stack-nestjs.md) (NestJS), [ADR-0006](0006-persistence-postgresql-prisma.md) (Postgres + Prisma — auto-instrumented), [ADR-0010](0010-session-management-redis.md) (Redis — auto-instrumented), and the future ADRs for audit trail (separate stream, same `trace_id`) and on-prem infrastructure (collector deployment, backend choice, retention, tail sampling). diff --git a/decisions/README.md b/decisions/README.md index 3f01a17..4ee1b98 100644 --- a/decisions/README.md +++ b/decisions/README.md @@ -55,3 +55,4 @@ ADRs are listed in numerical order. To slice by topic, filter on the `Tags` colu | [0009](0009-auth-flow-oidc-pkce-msal-node.md) | Authentication flow — OIDC Authorization Code + PKCE via MSAL Node, BFF session pattern | accepted | `security`, `backend` | 2026-04-29 | | [0010](0010-session-management-redis.md) | Session management — opaque session IDs in cookies, payload in self-hosted Redis with AES-GCM at rest | accepted | `security`, `backend`, `infrastructure` | 2026-04-29 | | [0011](0011-mfa-enforcement-entra-conditional-access.md) | MFA enforcement — Entra ID Conditional Access baseline, BFF claim sanity-check, step-up hooks designed-in | accepted | `security` | 2026-04-29 | +| [0012](0012-observability-pino-opentelemetry.md) | Observability — Pino structured logs + OpenTelemetry tracing, W3C Trace Context propagation, stdout + collector | accepted | `observability`, `backend`, `frontend` | 2026-04-29 |