feat(portal-bff): observability foundations (Pino + CLS + OTel) (#70)
## Summary
Implements ADR-0012 phase 1, BFF side. The SPA wiring is a separate phase-2 PR.
The BFF now emits structured JSON logs to stdout, tagged with `trace_id` / `span_id` from the active OTel context, and exports OTLP traces over HTTP/Protobuf to the Collector that already runs in the local-dev compose. Anything Nest, Express, HTTP-out, Prisma (Postgres) or `ioredis` does is auto-spanned. A `GET /api/health` liveness endpoint is added to round things out.
## What lands
**Runtime libs added** (production deps):
- `nestjs-pino`, `pino`, `pino-http` — structured logging
- `nestjs-cls` — request-scoped context
- `@opentelemetry/api` / `sdk-node` / `resources` / `semantic-conventions`
- `@opentelemetry/exporter-trace-otlp-proto` (HTTP/Protobuf, port 4318)
- `@opentelemetry/instrumentation-{http,express,nestjs-core,pg,ioredis,pino}` — curated, **no** `auto-instrumentations-node` mass-import (anti-bricolage)
Dev: `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`). Pure side-effect module.
- `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, `X-Request-Id` honoured if inbound).
- `apps/portal-bff/src/health/{health.controller,health.module,health.controller.spec}.ts` — `GET /api/health` returning `{status, uptimeSeconds, service, version}`. Cheap liveness only — `/readiness` lands when dependencies have a readiness story.
- `apps/portal-bff/src/config/check-database-url.{ts,spec.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 character in `POSTGRES_PASSWORD` that needs URL-encoding in `DATABASE_URL`. Prisma requires a URL string (no discrete-flag escape hatch), so early validation + a 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` imports `./observability/tracing` as line 1, then uses `app.get(Logger)` from `nestjs-pino` with `bufferLogs: true` so early-bootstrap lines are not lost.
- `app.module.ts` imports `ObservabilityModule` first, then `PrismaModule`, then `HealthModule`.
- `apps/portal-bff/.env.example` promotes `LOG_LEVEL`, `OTEL_SERVICE_NAME`, `OTEL_SERVICE_VERSION`, `OTEL_EXPORTER_OTLP_ENDPOINT`, `OTEL_EXPORTER_OTLP_PROTOCOL`, `OTEL_TRACES_SAMPLER` from the "future" comment to active settings — defaults target the local-dev Collector.
- Both `apps/portal-bff/.env.example` and `infra/local/.env.example` now spell out the URL-encoding constraint on `POSTGRES_PASSWORD` with the char-by-char encoding table (`@` → `%40`, etc.).
**ADR-0012 §Confirmation** rewritten to distinguish what landed in this PR from what is wired as the corresponding feature ADRs ship (CLS keys for `session_id` / `user_id_hash` / `audience`, `LOG_USER_ID_SALT` enforcement, redact list, custom spans, SPA-side SDK, full integration tests, prod Collector config).
## Trace ↔ log correlation
Automatic via `@opentelemetry/instrumentation-pino` — every Pino record gets `trace_id` and `span_id` injected from the active OTel context. No CLS gymnastics needed for that concern.
## Verification
```bash
pnpm exec nx run-many -t lint test build # 8 projects green
pnpm audit --audit-level=moderate # 0 vulnerabilities
./infra/local/dev.sh up observability # start Collector + Jaeger
cp apps/portal-bff/.env.example apps/portal-bff/.env
pnpm nx serve portal-bff
curl http://localhost:3000/api/health
# → {"status":"ok","uptimeSeconds":N,"service":"portal-bff","version":"dev"}
```
Then hit `GET http://localhost:3000/api` once or twice and open http://localhost:16686 — the corresponding spans appear in Jaeger, and Pino logs on stdout carry the matching `trace_id`.
## Test plan
- [ ] `nx run-many -t lint test build` green on this PR's CI run.
- [ ] `pnpm audit` clean.
- [ ] BFF boots, `/api/health` returns the expected JSON.
- [ ] Pino logs in dev are colourised one-liners; in prod they would be raw JSON (toggled by `NODE_ENV=production`).
- [ ] With the local-dev stack's `--profile observability` active, traces are visible in Jaeger UI.
- [ ] Each Pino log line for a request carries the same `trace_id` as the trace span in Jaeger.
---------
Co-authored-by: Julien Gautier <julien.gautier@apf.asso.fr>
Reviewed-on: #70
This commit was merged in pull request #70.
This commit is contained in:
@@ -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 {}
|
||||
@@ -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'));
|
||||
Reference in New Issue
Block a user