feat(portal-bff): observability foundations (Pino + CLS + OTel) #70

Merged
julien merged 1 commits from feat/portal-bff/observability-foundations into main 2026-05-09 22:28:18 +02:00
14 changed files with 1419 additions and 38 deletions
+32 -10
View File
@@ -4,7 +4,35 @@
# Postgres connection (per ADR-0006)
# Local dev default: dockerised Postgres on port 5432, schema 'public'.
DATABASE_URL="postgresql://portal:portal@localhost:5432/portal_dev?schema=public"
# Username / password / db must match infra/local/.env (POSTGRES_USER /
# POSTGRES_PASSWORD / POSTGRES_DB) — those are the source of truth,
# this is the BFF view of the same connection.
#
# IMPORTANT — URL encoding. The password is part of the URL userinfo
# segment, so any of these characters must be URL-encoded:
# @ → %40 # → %23 : → %3A / → %2F ? → %3F
# % → %25 & → %26 = → %3D + → %2B ; → %3B
# i.e. if your POSTGRES_PASSWORD is "p@ss#1", DATABASE_URL must read
# "postgresql://portal:p%40ss%231@localhost:5432/portal_dev?schema=public"
# The BFF aborts at boot with a clear error if it detects an unencoded
# special character (see apps/portal-bff/src/config/check-database-url.ts).
DATABASE_URL="postgresql://portal:portal_dev_change_me@localhost:5432/portal_dev?schema=public"
# Observability (per ADR-0012)
# All OTEL_* keys are honoured by the OpenTelemetry SDK directly — see
# apps/portal-bff/src/observability/tracing.ts for the bootstrap.
# Pino log level: 'info' in prod, 'debug' in dev (default if unset).
LOG_LEVEL=debug
OTEL_SERVICE_NAME=portal-bff
OTEL_SERVICE_VERSION=dev
# Default endpoint targets the Collector provisioned in
# infra/local/dev.compose.yml. The /v1/traces suffix is required by
# the HTTP/Protobuf transport.
OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4318/v1/traces
OTEL_EXPORTER_OTLP_PROTOCOL=http/protobuf
# v1 samples 100 % at the app; tail sampling is delegated to the
# Collector (per ADR-0012). Override only for spike investigations.
OTEL_TRACES_SAMPLER=always_on
# Future env vars introduced by upcoming phases / ADRs:
#
@@ -28,15 +56,9 @@ DATABASE_URL="postgresql://portal:portal@localhost:5432/portal_dev?schema=public
# MFA (ADR-0011):
# MFA_FRESHNESS_SECONDS (default 600)
#
# Observability (ADR-0012):
# LOG_LEVEL ('info' in prod, 'debug' in dev)
# LOG_USER_ID_SALT (per-environment salt)
# OTEL_SERVICE_NAME ('portal-bff')
# OTEL_SERVICE_VERSION
# OTEL_RESOURCE_ATTRIBUTES
# OTEL_EXPORTER_OTLP_ENDPOINT
# OTEL_EXPORTER_OTLP_PROTOCOL ('http/protobuf')
# OTEL_TRACES_SAMPLER ('always_on' in v1)
# Observability — additional keys to be wired as features land:
# LOG_USER_ID_SALT (per-environment salt for hashing user_id
# in CLS context — needed once auth lands)
#
# Audit trail (ADR-0013):
# AUDIT_DATABASE_URL (separate creds, role 'audit_writer')
+3 -1
View File
@@ -2,9 +2,11 @@ import { Module } from '@nestjs/common';
import { PrismaModule } from 'nestjs-prisma';
import { AppController } from './app.controller';
import { AppService } from './app.service';
import { ObservabilityModule } from '../observability/observability.module';
import { HealthModule } from '../health/health.module';
@Module({
imports: [PrismaModule.forRoot({ isGlobal: true })],
imports: [ObservabilityModule, PrismaModule.forRoot({ isGlobal: true }), HealthModule],
controllers: [AppController],
providers: [AppService],
})
@@ -0,0 +1,44 @@
import { assertDatabaseUrl } from './check-database-url';
describe('assertDatabaseUrl', () => {
const original = process.env['DATABASE_URL'];
afterEach(() => {
if (original === undefined) {
delete process.env['DATABASE_URL'];
} else {
process.env['DATABASE_URL'] = original;
}
});
it('passes for a well-formed URL with a URL-safe password', () => {
process.env['DATABASE_URL'] = 'postgresql://user:safePass123@localhost:5432/db?schema=public';
expect(() => assertDatabaseUrl()).not.toThrow();
});
it('passes for a password whose special chars are URL-encoded', () => {
// Original password contained `@` and `#` — encoded as %40 and %23.
process.env['DATABASE_URL'] = 'postgresql://user:p%40ss%23word@localhost:5432/db';
expect(() => assertDatabaseUrl()).not.toThrow();
});
it('throws when DATABASE_URL is unset', () => {
delete process.env['DATABASE_URL'];
expect(() => assertDatabaseUrl()).toThrow(/not set/);
});
it('throws when DATABASE_URL has the wrong scheme', () => {
process.env['DATABASE_URL'] = 'mysql://user:pass@localhost/db';
expect(() => assertDatabaseUrl()).toThrow(/postgresql:/);
});
it('throws when the password contains a literal @ (multiple @ in URL)', () => {
process.env['DATABASE_URL'] = 'postgresql://user:p@ss@localhost:5432/db';
expect(() => assertDatabaseUrl()).toThrow(/URL-encoding/);
});
it('throws on a fundamentally malformed URL', () => {
process.env['DATABASE_URL'] = 'not a url at all';
expect(() => assertDatabaseUrl()).toThrow(/not a valid URL/);
});
});
@@ -0,0 +1,54 @@
/**
* Sanity-check `DATABASE_URL` early in bootstrap so a malformed value
* fails fast with a clear, actionable message instead of an opaque
* Prisma error deep into the request lifecycle.
*
* The most common malformation is a literal special character in
* POSTGRES_PASSWORD that the contributor forgot to URL-encode (`@`,
* `#`, `:`, `/`, `?`, `%`, `&`, `=`, `+`, `;` all require it). This
* is the same family of bug that bit pgweb in #63 — pgweb's compose
* was switched to discrete CLI flags to bypass URL parsing entirely,
* but Prisma requires a URL string, so we have no equivalent escape
* hatch here. Documentation + early validation are the v1 fix.
*/
const URL_ENCODE_HINT =
'If POSTGRES_PASSWORD contains special characters (@ # : / ? % & = + ;), ' +
'they must be URL-encoded in DATABASE_URL — e.g., "@" → "%40", "#" → "%23". ' +
'See apps/portal-bff/.env.example for the canonical form.';
export function assertDatabaseUrl(): void {
const raw = process.env['DATABASE_URL'];
if (!raw) {
throw new Error(
'DATABASE_URL is not set. Copy apps/portal-bff/.env.example to ' +
'apps/portal-bff/.env and adjust.',
);
}
let parsed: URL;
try {
parsed = new URL(raw);
} catch {
throw new Error(`DATABASE_URL is not a valid URL. ${URL_ENCODE_HINT}`);
}
if (parsed.protocol !== 'postgresql:' && parsed.protocol !== 'postgres:') {
throw new Error(
`DATABASE_URL must use the "postgresql://" scheme; got "${parsed.protocol}".`,
);
}
// Heuristic — multiple "@" before the path almost always means the
// password contains a literal "@" that should have been encoded.
// Splitting on the parsed pathname isolates the userinfo+host
// segment without depending on scheme-specific quirks.
const beforePath = raw.split(parsed.pathname || '/')[0] ?? raw;
const atCount = (beforePath.match(/@/g) ?? []).length;
if (atCount > 1) {
throw new Error(
`DATABASE_URL has ${atCount} "@" before the database path — your password almost ` +
`certainly needs URL-encoding. ${URL_ENCODE_HINT}`,
);
}
}
@@ -0,0 +1,26 @@
import { Test, TestingModule } from '@nestjs/testing';
import { HealthController } from './health.controller';
describe('HealthController', () => {
let app: TestingModule;
beforeAll(async () => {
app = await Test.createTestingModule({
controllers: [HealthController],
}).compile();
});
describe('liveness', () => {
it('returns status ok with process metadata', () => {
const controller = app.get<HealthController>(HealthController);
const result = controller.liveness();
expect(result).toMatchObject({
status: 'ok',
service: expect.any(String),
version: expect.any(String),
});
expect(result.uptimeSeconds).toBeGreaterThanOrEqual(0);
});
});
});
@@ -0,0 +1,26 @@
import { Controller, Get } from '@nestjs/common';
/**
* Liveness endpoint. Returns 200 OK with minimal process metadata.
* Intentionally cheap (no DB / Redis / downstream check) so it can
* be hit by container orchestrators (Kubernetes, Compose healthcheck)
* without amplifying load on backing services.
*
* A separate `/readiness` endpoint will land alongside the first
* dependency that has a readiness story to tell (Postgres pool warm,
* Redis connection established, etc.).
*/
@Controller('health')
export class HealthController {
private readonly startedAt = Date.now();
@Get()
liveness(): { status: 'ok'; uptimeSeconds: number; service: string; version: string } {
return {
status: 'ok',
uptimeSeconds: Math.floor((Date.now() - this.startedAt) / 1000),
service: process.env['OTEL_SERVICE_NAME'] ?? 'portal-bff',
version: process.env['OTEL_SERVICE_VERSION'] ?? 'dev',
};
}
}
@@ -0,0 +1,7 @@
import { Module } from '@nestjs/common';
import { HealthController } from './health.controller';
@Module({
controllers: [HealthController],
})
export class HealthModule {}
+23 -4
View File
@@ -1,9 +1,25 @@
import { Logger, ValidationPipe } from '@nestjs/common';
// MUST be the very first import — see apps/portal-bff/src/observability/tracing.ts
// for the reasoning. Anything `import`ed above this line bypasses the
// OpenTelemetry auto-instrumentations and is silently un-traced.
import './observability/tracing';
import { ValidationPipe } from '@nestjs/common';
import { NestFactory } from '@nestjs/core';
import { Logger } from 'nestjs-pino';
import { AppModule } from './app/app.module';
import { assertDatabaseUrl } from './config/check-database-url';
// Fail fast on a malformed DATABASE_URL (most often a special char in
// the password that needs URL-encoding) rather than letting Prisma
// surface a cryptic "invalid connection string" error mid-request.
assertDatabaseUrl();
async function bootstrap() {
const app = await NestFactory.create(AppModule);
// `bufferLogs: true` holds early-bootstrap log lines until the
// Pino-based Logger is wired in below, so we don't lose anything
// emitted before `app.useLogger()`.
const app = await NestFactory.create(AppModule, { bufferLogs: true });
app.useLogger(app.get(Logger));
app.useGlobalPipes(
new ValidationPipe({
@@ -18,9 +34,12 @@ async function bootstrap() {
const globalPrefix = 'api';
app.setGlobalPrefix(globalPrefix);
const port = process.env['PORT'] || 3000;
const port = process.env['PORT'] ?? 3000;
await app.listen(port);
Logger.log(`Application is running on: http://localhost:${port}/${globalPrefix}`);
app
.get(Logger)
.log(`Application is running on: http://localhost:${port}/${globalPrefix}`, 'Bootstrap');
}
bootstrap();
@@ -0,0 +1,83 @@
/**
* Observability wiring for the BFF (per ADR-0012).
*
* Composes:
* - `nestjs-cls` for request-scoped context. v1 stores `request_id`
* (UUID per inbound request); `session_id`, `user_id_hash`, and
* `audience` keys are reserved for future ADR-0009 / ADR-0010
* work and are populated by guards/interceptors as those modules
* land.
* - `nestjs-pino` for structured JSON logs. In dev (`NODE_ENV !==
* 'production'`) we pipe through `pino-pretty` so the developer
* sees colourised, human-readable lines on stdout. In prod the
* raw JSON output is shipped via the container runtime's stdout
* pipeline (per ADR-0012 §"stdout + OTLP shipping").
*
* Trace ↔ log correlation: handled outside this module by
* `@opentelemetry/instrumentation-pino` (loaded in `tracing.ts`),
* which auto-injects `trace_id` / `span_id` into every Pino log
* record from the active OTel context.
*/
import { Module } from '@nestjs/common';
import { ClsModule } from 'nestjs-cls';
import { LoggerModule } from 'nestjs-pino';
import { randomUUID } from 'node:crypto';
const isProduction = process.env['NODE_ENV'] === 'production';
const logLevel = process.env['LOG_LEVEL'] ?? (isProduction ? 'info' : 'debug');
@Module({
imports: [
ClsModule.forRoot({
global: true,
middleware: {
mount: true,
generateId: true,
// UUID v4 per request — exposed to logs as `request_id` and
// available everywhere via `cls.get('request_id')`. Stored
// under the conventional `id` key by nestjs-cls; we
// surface it through Pino's `customProps` below.
idGenerator: () => randomUUID(),
},
}),
LoggerModule.forRoot({
pinoHttp: {
level: logLevel,
// Pretty-print only in dev. In prod the JSON stream is
// consumed by the container runtime / Collector.
...(isProduction
? {}
: {
transport: {
target: 'pino-pretty',
options: {
singleLine: true,
translateTime: 'SYS:HH:MM:ss.l',
},
},
}),
// Hide some noise that has nothing to do with the work being
// done. Health-check pings would drown out everything else.
autoLogging: {
ignore: (req) => req.url === '/api/health' || req.url === '/health',
},
// Re-key the request id so it surfaces under `request_id`
// (snake_case, ADR-0012 convention) instead of pino's
// default `req.id` / `reqId`.
customProps: () => ({}),
genReqId: (req) => {
// Honour an inbound `X-Request-Id` header when present —
// useful for end-to-end tracing across systems that propagate
// it. Otherwise generate a fresh UUID v4. The same id is
// used by the CLS middleware above (Nest-Pino integrates
// with nestjs-cls automatically when both modules are
// imported).
const incoming = req.headers['x-request-id'];
return typeof incoming === 'string' && incoming.length > 0 ? incoming : randomUUID();
},
},
}),
],
})
export class ObservabilityModule {}
@@ -0,0 +1,80 @@
/**
* OpenTelemetry SDK bootstrap for the BFF (per ADR-0012).
*
* IMPORTANT — module load order
* ─────────────────────────────
* This file must be `import`ed (or `require`d) BEFORE any other module
* that creates HTTP clients, DB clients, web frameworks, etc. The
* auto-instrumentations work by patching modules at require time; they
* miss anything already loaded into Node's module cache. In `main.ts`
* we therefore have:
*
* import './observability/tracing'; // first line, no other imports above it
* // ... rest of the bootstrap ...
*
* Anything else above that line will be silently un-instrumented.
*
* What this enables, out of the box
* ─────────────────────────────────
* - HTTP, Express, NestJS request spans (incoming and outgoing)
* - PostgreSQL spans via Prisma (the underlying `pg` driver)
* - Redis (`ioredis`) spans — wired in advance for ADR-0010 / ADR-0014
* - Pino log records auto-decorated with the active `trace_id`/`span_id`
* so log lines correlate with traces in the backend
*
* Sampling is 100% at the app per ADR-0012; tail sampling is delegated
* to the OTel Collector. Transport is OTLP HTTP/Protobuf (`port 4318`)
* to match the .env.example default and avoid the gRPC binary
* dependency (`@grpc/grpc-js`).
*/
import { NodeSDK } from '@opentelemetry/sdk-node';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-proto';
import { resourceFromAttributes } from '@opentelemetry/resources';
import { ATTR_SERVICE_NAME, ATTR_SERVICE_VERSION } from '@opentelemetry/semantic-conventions';
import { HttpInstrumentation } from '@opentelemetry/instrumentation-http';
import { ExpressInstrumentation } from '@opentelemetry/instrumentation-express';
import { NestInstrumentation } from '@opentelemetry/instrumentation-nestjs-core';
import { PgInstrumentation } from '@opentelemetry/instrumentation-pg';
import { IORedisInstrumentation } from '@opentelemetry/instrumentation-ioredis';
import { PinoInstrumentation } from '@opentelemetry/instrumentation-pino';
const serviceName = process.env['OTEL_SERVICE_NAME'] ?? 'portal-bff';
const serviceVersion = process.env['OTEL_SERVICE_VERSION'] ?? 'dev';
const otlpEndpoint =
process.env['OTEL_EXPORTER_OTLP_ENDPOINT'] ?? 'http://localhost:4318/v1/traces';
const sdk = new NodeSDK({
resource: resourceFromAttributes({
[ATTR_SERVICE_NAME]: serviceName,
[ATTR_SERVICE_VERSION]: serviceVersion,
}),
traceExporter: new OTLPTraceExporter({ url: otlpEndpoint }),
instrumentations: [
new HttpInstrumentation(),
new ExpressInstrumentation(),
new NestInstrumentation(),
new PgInstrumentation(),
new IORedisInstrumentation(),
new PinoInstrumentation(),
],
});
sdk.start();
// Graceful shutdown on container-stop signals so in-flight spans get a
// chance to flush to the collector. The 2s timeout is generous in dev
// and fast enough not to block container teardown in prod.
const shutdown = (signal: string): void => {
sdk
.shutdown()
.catch((err) => {
// Best-effort cleanup — log to stderr because Pino may itself
// be in the middle of shutting down.
process.stderr.write(`OpenTelemetry shutdown error on ${signal}: ${String(err)}\n`);
})
.finally(() => process.exit(0));
};
process.once('SIGTERM', () => shutdown('SIGTERM'));
process.once('SIGINT', () => shutdown('SIGINT'));
@@ -188,18 +188,25 @@ The BFF refuses to start if `LOG_USER_ID_SALT` or `OTEL_SERVICE_NAME` is missing
### 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.<verb>', ...)` 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.
**Wired in the BFF foundation PR (phase 1):**
- `apps/portal-bff/src/observability/tracing.ts` initialises the OTel `NodeSDK` with the OTLP HTTP/Protobuf exporter (target: `OTEL_EXPORTER_OTLP_ENDPOINT`, default `http://localhost:4318/v1/traces`).
- `apps/portal-bff/src/main.ts` `import`s `./observability/tracing` as its very first line — anything above it bypasses auto-instrumentation.
- `apps/portal-bff/src/observability/observability.module.ts` registers `nestjs-cls` (mounted as global middleware, populates `request_id` as a per-request UUID) and `nestjs-pino` (`LoggerModule`, `pino-pretty` in dev / raw JSON in prod, `LOG_LEVEL` env-driven, `/health` excluded from auto-logging).
- Auto-instrumentations active in v1: HTTP, Express, NestJS, PostgreSQL (`pg` driver under Prisma), IORedis (pre-wired for ADR-0010 / ADR-0014), and Pino. The Pino instrumentation auto-decorates every log record with `trace_id` and `span_id` from the active OTel context, so log ↔ trace correlation is automatic.
- `apps/portal-bff/src/health/health.controller.ts` exposes `GET /api/health` (cheap liveness — process metadata only, no DB / Redis / downstream check).
- `apps/portal-bff/.env.example` declares `LOG_LEVEL`, `OTEL_SERVICE_NAME`, `OTEL_SERVICE_VERSION`, `OTEL_EXPORTER_OTLP_ENDPOINT`, `OTEL_EXPORTER_OTLP_PROTOCOL`, `OTEL_TRACES_SAMPLER` with sensible dev defaults.
**Wired as the corresponding features land:**
- CLS keys `session_id`, `user_id_hash`, `audience` — populated by guards/interceptors when ADR-0009 / ADR-0010 land.
- `LOG_USER_ID_SALT` enforced (BFF refuses to start without it) — same trigger.
- Pino `redact` list for PII paths — wired alongside the first DTO that carries a redactable field.
- Custom spans `tracer.startActiveSpan('domain.<verb>', …)` — added per service method that warrants one (creating a row, calling a downstream, etc.).
- SPA-side `@opentelemetry/sdk-trace-web` initialiser, OTLP/HTTP exporter targeting the Collector, `traceparent` header propagated to the BFF — phase-2 PR.
- Integration tests: full SPA → BFF → DB trace with correct parent-child structure; every log line for one request carries the same `trace_id`; redact list strips its targets — wired with the auth + first real screen.
- A separate `/readiness` endpoint that probes Postgres / Redis / OBO cache — wired with the first dependency that has a readiness story to tell.
- OTel Collector deployment configuration in the runtime manifest — phase 3b on-prem ADR. The application stays backend-agnostic (any OTLP-capable Collector works).
## Pros and Cons of the Options
+8 -1
View File
@@ -5,7 +5,14 @@
# $EDITOR .env
# ---------------------------------------------------------------- Postgres
# `POSTGRES_PASSWORD` is mandatory — the compose refuses to boot without it.
# `POSTGRES_PASSWORD` is mandatory — the compose refuses to boot
# without it.
#
# Picking a password — keep it URL-safe in dev. The BFF reads its
# Postgres URL via `DATABASE_URL` and Prisma demands the URL form;
# any `@`, `#`, `:`, `/`, `?`, `%`, `&`, `=`, `+`, `;` in the
# password must be URL-encoded in `apps/portal-bff/.env`. Easiest
# avoided by sticking to alphanumerics + `-_.~` in dev.
POSTGRES_USER=portal
POSTGRES_PASSWORD=portal_dev_change_me
POSTGRES_DB=portal_dev
+16
View File
@@ -96,6 +96,7 @@
"jsonc-eslint-parser": "^2.1.0",
"lint-staged": "^17.0.0",
"nx": "22.7.1",
"pino-pretty": "^13.1.3",
"postcss": "^8.5.12",
"prettier": "^3.8.1",
"prisma": "^6.19.3",
@@ -119,11 +120,26 @@
"@nestjs/common": "^11.0.0",
"@nestjs/core": "^11.0.0",
"@nestjs/platform-express": "^11.0.0",
"@opentelemetry/api": "^1.9.1",
"@opentelemetry/exporter-trace-otlp-proto": "^0.217.0",
"@opentelemetry/instrumentation-express": "^0.65.0",
"@opentelemetry/instrumentation-http": "^0.217.0",
"@opentelemetry/instrumentation-ioredis": "^0.65.0",
"@opentelemetry/instrumentation-nestjs-core": "^0.63.0",
"@opentelemetry/instrumentation-pg": "^0.69.0",
"@opentelemetry/instrumentation-pino": "^0.63.0",
"@opentelemetry/resources": "^2.7.1",
"@opentelemetry/sdk-node": "^0.217.0",
"@opentelemetry/semantic-conventions": "^1.40.0",
"@prisma/client": "^6.19.3",
"axios": "^1.6.0",
"class-transformer": "^0.5.1",
"class-validator": "^0.15.1",
"nestjs-cls": "^6.2.0",
"nestjs-pino": "^4.6.1",
"nestjs-prisma": "^0.27.0",
"pino": "^10.3.1",
"pino-http": "^11.0.0",
"reflect-metadata": "^0.2.0",
"rxjs": "~7.8.0"
}
+998 -10
View File
File diff suppressed because it is too large Load Diff