diff --git a/docs/observability.md b/docs/observability.md new file mode 100644 index 0000000..1021c33 --- /dev/null +++ b/docs/observability.md @@ -0,0 +1,215 @@ +# Observability & Tracing Operations Guide + +## Purpose + +This guide describes the end-to-end observability stack in Disciplr backend: how request context flows from inbound HTTP through the Express middleware, the Horizon listener, and background jobs; what Prometheus metrics and structured logs are emitted; and how to correlate traces, logs, and metrics during an incident. + +**Target audience:** On-call engineers, service owners, incident commanders. +**Related runbooks:** +- [On-Call SLO and Alerting Runbook](runbooks/on-call-slo.md) — SLO targets, alert rules, escalation procedures. +- [Database Metrics & Operations](operations-metrics.md) — Prometheus scraper auth, gauge definitions, pool health. + +--- + +## Stack Summary + +| Layer | Mechanism | Emitter | +|------|-----------|---------| +| Request context | Correlation ID (generated or forwarded) | `src/middleware/logger.ts`, `src/middleware/requestLogger.ts` | +| Structured logs | Pino JSON with redaction | `src/middleware/logger.ts` | +| HTTP metrics (RED) | `prom-client` Counter + Histogram | `src/observability/httpMetrics.ts` | +| System/job/listener metrics | `prom-client` Gauges (custom registry) | `src/routes/metrics.ts` | +| Default process metrics | `prom-client` built-in collectors | `src/routes/metrics.ts` (`collectDefaultMetrics`) | + +**Tracing status:** The codebase does **not** currently use OpenTelemetry. Request identity is carried via a `correlationId` (not a W3C `traceparent`). There is no span-based distributed trace export. The correlation ID is the closest equivalent to a trace ID for log correlation; see [Correlation ID ↔ Trace ID](#correlation-id--trace-id). + +--- + +## Context Propagation Path + +### 1. Inbound HTTP → Express Middleware + +1. `httpMetricsMiddleware` (`src/app.ts:19`, `src/observability/httpMetrics.ts:38`) records request start time and emits `http_requests_total` + `http_request_duration_seconds` on `res.finish`. +2. `requestLogger` (`src/middleware/requestLogger.ts:49`) extracts or generates a `correlationId` via `getOrGenerateCorrelationId` (`src/middleware/logger.ts:103`), attaches it to `req.correlationId` and creates a Pino child logger at `req.logger`. +3. The correlation ID is derived from inbound headers in priority order: + - `x-correlation-id` + - `x-request-id` + - Generated fallback: `${Date.now()}-${random}` +4. `errorHandler` (`src/middleware/errorHandler.ts`) echoes `x-request-id` back in error responses — note it does **not** echo the generated correlation ID, so clients receiving a fallback ID cannot map the response to a log line by ID alone. + +### 2. Application Code + +Handlers should use `req.logger` (the correlation-scoped Pino child) so log lines carry the `correlationId` field. The root `logger` singleton (`src/middleware/logger.ts:88`) is shared by modules without request context (e.g., `src/security/abuse-monitor.ts`). + +**Log-line fields** (common envelope): + +``` +{ level, service: 'disciplr-backend', correlationId, event, timestamp, ... } +``` + +- `http.request` events (`requestLogger.ts:106`): `req.{method,url,path,headers,body,...}`, `res.{statusCode,headers}`, `durationMs`. +- `horizon.*` events: `contractAddress`, `lastLedger`, `attempts`, `error`, `stack`. +- `security.cors_rejected` (`src/app.ts:142`): `origin`. +- `app_error` / `unhandled_error` (`errorHandler.ts`): `code`, `status`, `method`, `path`, `requestId`, `message`. + +### 3. Horizon Listener (separate process) + +The Horizon listener runs as a **separate Node process** (`src/services/horizonListenerMain.ts`), launched via `tsx src/services/horizonListenerMain.ts`. Because it is a separate process: + +- It inherits **no** Express request context, no `req.correlationId`, no `req.logger`. +- All logging is via `console.log/warn/error(JSON.stringify({...}))` with no correlation ID and no trace ID. +- The `HorizonListener` constructor (`src/services/horizonListener.ts:40`) accepts only `config, eventProcessor, db, checkpointStore` — no logger or context bag. + +**Implication:** Events processed by the listener cannot be correlated back to an originating HTTP request via the current correlation-ID mechanism. The listener's logs are correlated by `eventId`, `contractAddress`, and `lastLedger` only. + +### 4. Background Jobs + +The in-memory job queue (`src/jobs/queue.ts`) and `BackgroundJobSystem` (`src/jobs/system.ts`) carry **no trace context**: + +- `InternalQueuedJob` (`src/jobs/queue.ts:10`) has fields `id, type, payload, attempt, maxAttempts, createdAt, runAt, leasedAt` — no `traceId`/`correlationId`. +- `runJob()` (`src/jobs/queue.ts:434`) passes only `{ jobId, attempt }` to handlers. +- Recurring scheduler jobs (`src/jobs/system.ts:276`) are timer-triggered and have no originating request. + +**Implication:** Job executions are not correlated to the request that enqueued them. Job logs must be correlated by `jobId` and `type`. + +--- + +## Correlation ID ↔ Trace ID + +There is **no OpenTelemetry trace ID** in this codebase. The `correlationId` field on Pino log lines serves as the de-facto trace identifier for log correlation within the API process. + +| Concept | Exists? | Location | +|--------|---------|----------| +| W3C `traceparent` header parsing | No | — | +| OTel span context propagation | No | — | +| `correlationId` (log-scoped) | Yes | `src/middleware/logger.ts:93-111` | +| `correlationId` on `req` | Yes | `src/middleware/requestLogger.ts:62` | +| `x-request-id` echoed in error responses | Yes | `src/middleware/errorHandler.ts` | +| `correlationId` echoed in responses | **No** | — | +| Correlation ID propagated to Horizon listener | **No** | Separate process | +| Correlation ID propagated to jobs | **No** | No context field on `InternalQueuedJob` | + +**Triage guidance:** To correlate a request during an incident, use the `correlationId` from the `http.request` log line. Search logs for that exact `correlationId` value. For the Horizon listener and jobs, correlation must be done via time window and `eventId`/`jobId` rather than a shared trace ID. + +--- + +## Exported Metrics + +All custom metrics are registered on a dedicated `prom-client` Registry (`src/routes/metrics.ts:10`, exported as `metricsRegistry`). Default process metrics (`process_*`, `nodejs_*`, `gc_*`) are also collected on this registry via `collectDefaultMetrics`. + +### HTTP RED Metrics + +Defined in `src/observability/httpMetrics.ts`. **Note:** these are registered on the **default global registry**, not the application's `metricsRegistry`, so they are not currently exposed on the `/api/metrics` scrape endpoint. + +| Name | Type | Labels | Description | +|------|------|--------|-------------| +| `http_requests_total` | Counter | `method`, `route`, `status_class` | Total inbound HTTP requests handled. | +| `http_request_duration_seconds` | Histogram | `method`, `route`, `status_class` | Latency distribution in seconds. Buckets: 0.005–10s. | + +### System Gauges + +All defined in `src/routes/metrics.ts`. Aggregate-only — no tenant/org/user labels. + +| Name | Type | Description | SLO / Alert Use | +|------|------|-------------|-----------------| +| `disciplr_job_queue_depth` | Gauge | Current depth of the background job queue | [SLO 1](runbooks/on-call-slo.md#slo-1-job-queue-depth): warning >100/5m, critical >500/2m | +| `disciplr_job_failed_total` | Gauge | Total number of failed jobs | Trend monitoring (note: semantically a counter; emitted as gauge) | +| `disciplr_db_available_connections` | Gauge | Available DB connections in pool | [SLO 2](runbooks/on-call-slo.md#slo-2-db-connection-pool): warning >80%/5m, critical >95%/1m | +| `disciplr_db_waiting_clients` | Gauge | Clients waiting for a DB connection | [SLO 2](runbooks/on-call-slo.md#slo-2-db-connection-pool): warning >2/5m | +| `disciplr_horizon_listener_lag` | Gauge | Listener lag in ledgers | [SLO 3](runbooks/on-call-slo.md#slo-3-listener-lag): warning >30/5m, critical >120/2m | +| `disciplr_outbox_relay_lag_seconds` | Gauge | Age of oldest unprocessed outbox row (s) | [SLO 4](runbooks/on-call-slo.md#slo-4-outbox-relay-lag-informational): warning >300s/10m, critical >3600s/5m | +| `disciplr_webhook_breaker_closed` | Gauge | Subscribers with closed circuit breaker | Capacity planning | +| `disciplr_webhook_breaker_open` | Gauge | Subscribers with open circuit breaker | Incident detection | +| `disciplr_webhook_breaker_half_open` | Gauge | Subscribers with half-open circuit breaker | Recovery monitoring | +| `disciplr_webhook_dispatch_in_flight` | Gauge | Webhook deliveries currently in flight | Saturation monitoring | +| `disciplr_webhook_dispatch_queue_depth` | Gauge | Webhook deliveries waiting in queue | Backpressure detection | +| `disciplr_event_throughput_events_per_sec` | Gauge | Event processing throughput (events/sec) | Throughput trending | + +### Default Process Metrics + +Enabled via `client.collectDefaultMetrics({ register })` at `src/routes/metrics.ts:13`. Includes `process_cpu_seconds_total`, `process_resident_memory_bytes`, `nodejs_heap_size_total_bytes`, `nodejs_eventloop_lag_seconds`, and GC metrics. See [prom-client docs](https://github.com/siimon/prom-client#default-metrics) for the full list. + +--- + +## Scrape Endpoint + +`GET /api/metrics` is mounted at `src/app.ts:177` behind JWT auth, admin RBAC, and a rate limiter (20 req/min). It returns the contents of the custom `metricsRegistry`. + +For scraper authentication details (token, IP allowlist, audit logging), see [Database Metrics & Operations](operations-metrics.md#prometheus-scraper-authentication). + +--- + +## Correlating Traces, Logs, and Metrics During Triage + +### Scenario: Investigating a slow request + +1. **Find the request in logs.** Search Pino JSON logs for the `correlationId` (from `x-correlation-id` header or the `http.request` log line): + ``` + jq 'select(.correlationId == "1719600000-abc123xyz")' < logs.jsonl + ``` +2. **Check HTTP RED metrics.** Query Prometheus for the route and status class: + ``` + rate(http_request_duration_seconds_sum{route="/api/vaults/:id"}[5m]) + / + rate(http_request_duration_seconds_count{route="/api/vaults/:id"}[5m]) + ``` +3. **Check system gauges at the time window.** Did the slow request coincide with pool exhaustion or queue growth? + ``` + disciplr_db_available_connections + disciplr_job_queue_depth + ``` +4. **Cross-reference the SLO runbook.** See [On-Call SLO and Alerting Runbook](runbooks/on-call-slo.md) for thresholds and remediation. + +### Scenario: Alert fired on `disciplr_horizon_listener_lag` + +1. Confirm the alert value in Prometheus. +2. Check listener logs (stdout of the `horizonListenerMain` process) for `horizon.connection_error` or `horizon.stream_error` events around the fire time. +3. Check `disciplr_db_available_connections` — listener lag often coincides with pool exhaustion. +4. Follow [SLO 3 remediation](runbooks/on-call-slo.md#slo-3-listener-lag). + +### Scenario: Alert fired on `disciplr_job_queue_depth` + +1. Check `disciplr_db_waiting_clients` and `disciplr_db_available_connections` for pool exhaustion. +2. Check `disciplr_horizon_listener_lag` — a stalled listener can starve job-producing events. +3. Inspect worker process health and logs. +4. Follow [SLO 1 remediation](runbooks/on-call-slo.md#slo-1-job-queue-depth). + +### Correlation limitations + +- **Horizon listener logs** have no `correlationId`. Correlate by time window and `eventId`/`lastLedger`. +- **Job logs** have no `correlationId`. Correlate by `jobId` and `type`. +- **HTTP RED metrics** are on the default registry, not `/api/metrics`. They must be scraped separately if needed. + +--- + +## Log Sampling & Debug Overrides + +`requestLogger` (`src/middleware/requestLogger.ts:37`) applies tail-based sampling: + +- Always logged: errors (≥500), slow requests (>`LOG_SLOW_THRESHOLD_MS`, default 1000ms), statuses in `LOG_ALWAYS_LOG_STATUS` (default `500,502,503`). +- Other requests: sampled at `LOG_SAMPLE_RATE` (default `1` = 100%). + +Admin debug overrides (require `ADMIN_API_KEY`): +- `x-debug-trace: ` forces debug-level logging. +- `x-log-level: ` with `x-admin-key: ` overrides the log level. + +--- + +## Known Gaps & Future Work + +1. **No OpenTelemetry.** No packages, SDK, or instrumentation. Correlation ID is log-only and not a W3C trace context. +2. **Correlation ID not returned in responses.** `errorHandler` echoes `x-request-id` but not the generated `correlationId`. +3. **HTTP RED metrics on wrong registry.** `http_requests_total` / `http_request_duration_seconds` are on the default registry, not the app's `metricsRegistry`, so they are not exposed on `/api/metrics`. +4. **Duplicate metric registration.** `disciplr_webhook_dispatch_in_flight` and `disciplr_webhook_dispatch_queue_depth` are declared in both `src/routes/metrics.ts` and `src/services/boundedWebhookDispatcher.ts`. +5. **`job_failed_total` typed as Gauge** despite monotonic-counter semantics. +6. **No context propagation** to the Horizon listener (separate process) or background jobs (no context field on `InternalQueuedJob`). + +--- + +## Cross-References + +- [On-Call SLO and Alerting Runbook](runbooks/on-call-slo.md) — SLO targets, alert rules, escalation. +- [Database Metrics & Operations](operations-metrics.md) — Prometheus scraper auth, gauge definitions, pool health, slow-query ring buffer. +- [Horizon Listener Architecture](horizon-listener.md) — Listener design, recovery scenarios. +- [Jobs System](jobs.md) — Background job design and configuration. +- [Operations](operations.md) — General operational procedures. diff --git a/src/tests/docs.observability.test.ts b/src/tests/docs.observability.test.ts new file mode 100644 index 0000000..9d4878c --- /dev/null +++ b/src/tests/docs.observability.test.ts @@ -0,0 +1,121 @@ +import * as fs from 'fs'; +import * as path from 'path'; +import { metricsRegistry } from '../routes/metrics.js'; +import { httpRequestsTotal, httpRequestDurationSeconds } from '../observability/httpMetrics.js'; + +describe('Observability Documentation Sync', () => { + const docPath = path.resolve(__dirname, '../../docs/observability.md'); + const doc = fs.readFileSync(docPath, 'utf8'); + + // Metric names documented in the "System Gauges" and "HTTP RED Metrics" tables. + // These must match the names registered in code. + const documentedMetrics = [ + 'http_requests_total', + 'http_request_duration_seconds', + 'disciplr_job_queue_depth', + 'disciplr_job_failed_total', + 'disciplr_db_available_connections', + 'disciplr_db_waiting_clients', + 'disciplr_horizon_listener_lag', + 'disciplr_outbox_relay_lag_seconds', + 'disciplr_webhook_breaker_closed', + 'disciplr_webhook_breaker_open', + 'disciplr_webhook_breaker_half_open', + 'disciplr_webhook_dispatch_in_flight', + 'disciplr_webhook_dispatch_queue_depth', + 'disciplr_event_throughput_events_per_sec', + ]; + + describe('documented metric names exist in the registry', () => { + it('should expose every documented custom metric on the application registry', async () => { + const registryMetrics = await metricsRegistry.getMetricsAsJSON(); + const registryNames = registryMetrics.map((m) => m.name); + + for (const name of documentedMetrics) { + // http_requests_total / http_request_duration_seconds live on the default + // registry (see observability.md "Known Gaps"); all others on the app registry. + if (name === 'http_requests_total' || name === 'http_request_duration_seconds') { + expect(httpRequestsTotal).toBeDefined(); + expect(httpRequestDurationSeconds).toBeDefined(); + continue; + } + expect(registryNames).toContain(name); + } + }); + + it('should not document any metric that is absent from code', () => { + // Extract metric names from markdown table rows: | `name` | ... + const tableRegex = /^\|\s*`([a-z0-9_]+)`\s*\|/gim; + const found = new Set(); + let match: RegExpExecArray | null; + while ((match = tableRegex.exec(doc)) !== null) { + found.add(match[1]); + } + + // Every metric name appearing in a docs table must be one we know about. + const known = new Set(documentedMetrics); + for (const name of found) { + expect(known.has(name)).toBe(true); + } + }); + }); + + describe('required sections present', () => { + const requiredSections = [ + '## Purpose', + '## Stack Summary', + '## Context Propagation Path', + '## Correlation ID', + '## Exported Metrics', + '## Scrape Endpoint', + '## Correlating Traces, Logs, and Metrics', + '## Log Sampling', + '## Known Gaps', + '## Cross-References', + ]; + + for (const section of requiredSections) { + it(`should contain the "${section}" section`, () => { + expect(doc).toContain(section); + }); + } + }); + + describe('runbook cross-link valid', () => { + it('should link to the on-call SLO runbook with a valid anchor', () => { + expect(doc).toMatch(/\[.*?\]\(runbooks\/on-call-slo\.md/); + }); + + it('should link to the operations-metrics doc', () => { + expect(doc).toMatch(/\[.*?\]\(operations-metrics\.md/); + }); + + it('should reference all four SLO runbook anchors', () => { + const anchors = [ + 'runbooks/on-call-slo.md#slo-1-job-queue-depth', + 'runbooks/on-call-slo.md#slo-2-db-connection-pool', + 'runbooks/on-call-slo.md#slo-3-listener-lag', + 'runbooks/on-call-slo.md#slo-4-outbox-relay-lag-informational', + ]; + for (const anchor of anchors) { + expect(doc).toContain(anchor); + } + }); + }); + + describe('documented metric metadata matches code', () => { + it('should document job_queue_depth as a gauge with the correct help', async () => { + const registryMetrics = await metricsRegistry.getMetricsAsJSON(); + const m = registryMetrics.find((x) => x.name === 'disciplr_job_queue_depth'); + expect(m).toBeDefined(); + expect(m?.type).toBe('gauge'); + }); + + it('should document horizon listener lag as a gauge', async () => { + const registryMetrics = await metricsRegistry.getMetricsAsJSON(); + const m = registryMetrics.find((x) => x.name === 'disciplr_horizon_listener_lag'); + expect(m).toBeDefined(); + expect(m?.type).toBe('gauge'); + }); + }); +});