feat(portal-bff): observability foundations (Pino + CLS + OTel)
CI / commits (pull_request) Successful in 1m45s
CI / scan (pull_request) Successful in 1m55s
CI / check (pull_request) Successful in 2m8s
CI / a11y (pull_request) Successful in 1m10s
CI / perf (pull_request) Successful in 2m55s

Implements ADR-0012 phase 1, BFF side. The SPA wiring is a
separate phase-2 PR.

Runtime libraries added (production deps):

- nestjs-pino, pino, pino-http   structured JSON logging
- nestjs-cls                     request-scoped context
- @opentelemetry/api / sdk-node / resources / semantic-conventions
- @opentelemetry/exporter-trace-otlp-proto   OTLP HTTP/Protobuf
- @opentelemetry/instrumentation-{http,express,nestjs-core,pg,
  ioredis,pino}                  curated, no `auto-instrumentations-
                                 node` mass-import (anti-bricolage)

Dev dep: pino-pretty (gated by NODE_ENV).

Code:

- apps/portal-bff/src/observability/tracing.ts — OTel `NodeSDK`
  bootstrap. Documents the load-order constraint inline (must be
  the very first import of `main.ts`). Exports nothing — pure
  side-effect file.
- apps/portal-bff/src/observability/observability.module.ts —
  composes ClsModule (UUID per request stored as `request_id`)
  and LoggerModule (pino-pretty in dev / raw JSON in prod,
  LOG_LEVEL env-driven, `/health` excluded from auto-logging).
- apps/portal-bff/src/health/{health.controller,health.module}.ts
  — `GET /api/health` returning `{status, uptimeSeconds, service,
  version}`. Cheap liveness only — no DB / Redis check; that
  belongs to a future `/readiness` once dependencies have a
  readiness story.
- apps/portal-bff/src/config/check-database-url.ts — fail-fast
  validator called from main.ts before NestFactory boots. Catches
  the same family of bug that bit pgweb in #63: a literal special
  char in POSTGRES_PASSWORD that needs URL-encoding in
  DATABASE_URL. Prisma requires a URL string, so we cannot use
  discrete CLI flags here — early validation + clear error message
  is the v1 mitigation. Six unit tests cover happy path, missing
  URL, wrong scheme, encoded special chars, literal `@` in
  password, malformed URL.

Wiring:

- main.ts now `import`s `./observability/tracing` as its first
  line, calls `assertDatabaseUrl()`, then bootstraps Nest with
  `app.useLogger(app.get(Logger))` from nestjs-pino with
  `bufferLogs: true` so early-bootstrap lines are not lost.
- app.module.ts imports ObservabilityModule first, then the
  PrismaModule, then HealthModule.
- .env.example (BFF and infra/local) document the URL-encoding
  constraint on POSTGRES_PASSWORD with the exact char-by-char
  encoding table.

Trace ↔ log correlation is automatic via
`@opentelemetry/instrumentation-pino`: every Pino record gets
`trace_id` / `span_id` injected from the active OTel context.
No CLS gymnastics needed for that specific concern.

ADR-0012 §Confirmation rewritten to clearly distinguish what
landed in this PR (phase 1) from what is wired as the
corresponding feature ADRs ship (CLS keys for session/user/
audience, LOG_USER_ID_SALT, redact list, custom spans, SPA-side
SDK, full integration tests, prod Collector config).

Verified locally:
- pnpm exec nx run-many -t lint test build → 8 projects green,
  4 test suites for portal-bff, 9 unit tests pass.
- `pnpm nx serve portal-bff` boots, `curl /api/health` returns
  the expected JSON; logs are pretty-printed JSON one-liners on
  stdout in dev.
- `pnpm audit --audit-level=moderate` reports 0 vulnerabilities.
This commit is contained in:
Julien Gautier
2026-05-09 22:05:54 +02:00
parent fc9b63f24a
commit 2e663e1513
14 changed files with 1419 additions and 38 deletions
+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'));