docs(014-full-observability): plan, research, data model, contract, quickstart
Documents the exact hook point chosen for each of the 3 dead observability primitives (access log, request-duration histogram, tracer provider) and the 11 named business-health metrics, verified against the real current code rather than assumed — including a pre-existing SLA-run status data quality gap surfaced along the way (documented, not fixed here). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
saqib mir
co-authored by
Claude Sonnet 5
Claude Sonnet 5
parent
09ba56d3af
commit
5a0fe9f847
@@ -0,0 +1,54 @@
|
||||
# Contract: `/metrics` output
|
||||
|
||||
This feature adds no new HTTP endpoints — `GET /metrics` already exists and its response shape
|
||||
(Prometheus text exposition format) is unchanged. This document is the contract for its
|
||||
**content**: which metric series a consumer (Prometheus, or any scraper) can rely on after this
|
||||
feature ships, replacing the usual per-endpoint request/response contract for a feature with no
|
||||
new routes.
|
||||
|
||||
## Guarantees
|
||||
|
||||
1. Every metric already exposed today (the default `prom-client` process metrics, and
|
||||
`supporthub_http_request_duration_seconds`) continues to appear, with the same name and label
|
||||
set — FR-010. `supporthub_http_request_duration_seconds` gains real observations where today
|
||||
it has none; its metric name/labels/type do not change.
|
||||
2. Each of the eleven new series in [data-model.md](../data-model.md#metrics-prometheus-via-prom-client)
|
||||
appears on `/metrics` from process start (a `Counter`/`Histogram` with zero observations
|
||||
still exports its metadata — `# HELP`/`# TYPE` lines — even before its first increment; a
|
||||
consumer's dashboard/alert config can reference it immediately without waiting for the first
|
||||
event).
|
||||
3. No metric name or label value is derived from unbounded, request-supplied input — every
|
||||
label is one of: a fixed small enum (`outcome`, `resolved_by`, `matched`), a route pattern
|
||||
(bounded by the number of registered routes), a tool name (bounded by the tool registry), an
|
||||
error code or category ID (bounded by admin-configured product data, not raw user text).
|
||||
This is a deliberate constraint, not an incidental one — unbounded label cardinality is a
|
||||
well-known way to make a Prometheus deployment fall over, and every label chosen in
|
||||
data-model.md was checked against this before being finalized.
|
||||
4. `/health`, `/health/live`, `/health/ready` response shapes are unchanged (FR-010) — this
|
||||
feature does not touch `health.service.ts` or `health.routes.ts`.
|
||||
|
||||
## Example (illustrative, not exhaustive)
|
||||
|
||||
```text
|
||||
# HELP supporthub_http_request_duration_seconds Duration of HTTP requests in seconds
|
||||
# TYPE supporthub_http_request_duration_seconds histogram
|
||||
supporthub_http_request_duration_seconds_bucket{method="POST",route="/tickets",status_code="201",le="0.1"} 3
|
||||
supporthub_http_request_duration_seconds_count{method="POST",route="/tickets",status_code="201"} 3
|
||||
|
||||
# HELP supporthub_ai_session_outcomes_total Count of AI support sessions by terminal outcome
|
||||
# TYPE supporthub_ai_session_outcomes_total counter
|
||||
supporthub_ai_session_outcomes_total{outcome="resolved"} 12
|
||||
supporthub_ai_session_outcomes_total{outcome="escalated"} 4
|
||||
|
||||
# HELP supporthub_sla_run_outcomes_total Count of SLA runs by outcome
|
||||
# TYPE supporthub_sla_run_outcomes_total counter
|
||||
supporthub_sla_run_outcomes_total{outcome="met"} 9
|
||||
supporthub_sla_run_outcomes_total{outcome="breached"} 1
|
||||
```
|
||||
|
||||
## Verification
|
||||
|
||||
Integration tests assert against this contract by scraping `GET /metrics` (a real
|
||||
`app.inject` call, real registry) before and after driving each metric's real underlying event
|
||||
through the real API, parsing the specific series' value out of the text response and asserting
|
||||
it moved by exactly the expected amount — never by mocking `prom-client` or the registry itself.
|
||||
@@ -0,0 +1,72 @@
|
||||
# Data Model: Full Observability
|
||||
|
||||
No Prisma schema changes — every entity here is in-process or exported to an external
|
||||
observability sink, never persisted to Postgres.
|
||||
|
||||
## Request Context Store
|
||||
|
||||
`AsyncLocalStorage<RequestContextSnapshot>`, populated once per request in
|
||||
`request-context.plugin.ts`'s existing `onRequest` hook (the same hook that already builds
|
||||
`request.reqContext`), read by `logger.ts`'s Pino `mixin` function on every subsequent log call
|
||||
made anywhere during that request's handling.
|
||||
|
||||
| Field | Type | Notes |
|
||||
|---|---|---|
|
||||
| `requestId` | `string` | Same value already assigned to `request.reqContext.requestId` |
|
||||
| `correlationId` | `string` | Same value already assigned to `request.reqContext.correlationId` |
|
||||
|
||||
## Access Log Line (shape, not a stored entity)
|
||||
|
||||
Emitted once per completed request via the existing `logger` singleton from the new
|
||||
`onResponse` hook.
|
||||
|
||||
| Field | Type | Notes |
|
||||
|---|---|---|
|
||||
| `method` | `string` | HTTP method |
|
||||
| `route` | `string` | Parameterized route pattern (`request.routeOptions.url`), not the raw URL |
|
||||
| `statusCode` | `number` | Response status |
|
||||
| `durationMs` | `number` | `reply.elapsedTime` |
|
||||
| `requestId` / `correlationId` | `string` | Via the mixin, same as every other line for this request |
|
||||
| `event` | `string` | Fixed value `"http_request_completed"` — lets log queries filter to access-log lines specifically |
|
||||
|
||||
Log level: `info` for 2xx/3xx, `warn` for 4xx, `error` for 5xx — mirrors the existing
|
||||
error-handler's own level choices (`app.ts`) so severity is consistent across both sources of
|
||||
request-outcome logging.
|
||||
|
||||
## Metrics (Prometheus, via `prom-client`)
|
||||
|
||||
All registered in `infrastructure/observability/metrics.ts` on the existing default registry
|
||||
(`metricsRegistry`, already exposed at `GET /metrics`), all prefixed `supporthub_` to match the
|
||||
existing histogram and default-metrics prefix.
|
||||
|
||||
| Metric name | Type | Labels | Incremented/observed when |
|
||||
|---|---|---|---|
|
||||
| `supporthub_http_request_duration_seconds` | Histogram *(existing, now actually observed)* | `method`, `route`, `status_code` | Every completed HTTP request |
|
||||
| `supporthub_ai_session_outcomes_total` | Counter | `outcome` (`resolved` \| `escalated`) | An AI support session reaches a terminal `resolved`/`escalated` status |
|
||||
| `supporthub_ticket_resolutions_total` | Counter | `resolved_by` (`ai` \| `human`) | A ticket reaches `RESOLVED`, labeled from the ticket's `Resolution.resolvedBy` |
|
||||
| `supporthub_ticket_resolution_duration_seconds` | Histogram | — | A ticket reaches `RESOLVED` — observes `resolvedAt - ticket.createdAt` |
|
||||
| `supporthub_ticket_first_response_duration_seconds` | Histogram | — | The first `AGENT_MESSAGE` is posted on a ticket — observes `firstResponseAt - ticket.createdAt` |
|
||||
| `supporthub_sla_run_outcomes_total` | Counter | `outcome` (`met` \| `breached`) | An SLA run completes on time (`met`) or is flagged by the breach sweep (`breached`) |
|
||||
| `supporthub_escalations_total` | Counter | `reason` | An `ESCALATION_TRIGGERED` domain event fires (already published unconditionally today) |
|
||||
| `supporthub_problems_created_total` | Counter | `category_id` (or `uncategorized`) | A `Problem` row is created (at ticket-intake time) |
|
||||
| `supporthub_known_error_lookups_total` | Counter | `code` | A valid error code's known issues are looked up |
|
||||
| `supporthub_knowledge_retrieval_outcomes_total` | Counter | `matched` (`true` \| `false`) | The AI's `searchProductKnowledge` tool call returns zero vs. one-or-more results |
|
||||
| `supporthub_tool_invocations_total` | Counter | `tool`, `outcome` (`success` \| `failed`) | Every AI tool-call result, any tool |
|
||||
|
||||
Deliberately **not** separate metrics (per spec.md's Assumptions): "recurring problems" and
|
||||
"most common errors" are read directly off `supporthub_problems_created_total` and
|
||||
`supporthub_known_error_lookups_total` respectively via a monitoring stack's own `topk`/`rate`
|
||||
query — no additional "top N" metric or logic is computed by this application.
|
||||
|
||||
## Traces / Spans (exported, not persisted)
|
||||
|
||||
| Span | Parent | Attributes | Created in |
|
||||
|---|---|---|---|
|
||||
| `ticket.create` | (root) | `ticket.id`, `product.externalProductId` | `ticketing/tickets/service/tickets.service.ts` |
|
||||
| `ai.escalation` | `ticket.create` (if within the same request) or its own root (async paths) | `ticket.id`, `session.id` | `ai-support/sessions/service/session.service.ts`, around the escalation branch |
|
||||
| `orchestration.assignment` | `ai.escalation` (via the `TICKET_UPDATED`/`HUMAN_ESCALATION` subscriber) | `ticket.id`, `strategy` | `orchestration/orchestration` + `orchestration/assignments`, wrapping the existing `handleHumanEscalation` call |
|
||||
|
||||
Span context propagation across the domain-event bus relies on the OpenTelemetry Context API's
|
||||
own async-local propagation — since `eventBus.publish(...)` is `await`ed synchronously within
|
||||
the same call chain (confirmed in `tickets.service.ts`/`escalation.service.ts`), no manual
|
||||
context-carrying payload field is needed.
|
||||
@@ -0,0 +1,152 @@
|
||||
# Implementation Plan: Full Observability
|
||||
|
||||
**Branch**: `014-full-observability` | **Date**: 2026-09-07 | **Spec**: [spec.md](./spec.md)
|
||||
|
||||
**Input**: Feature specification from `specs/014-full-observability/spec.md`
|
||||
|
||||
## Summary
|
||||
|
||||
Wires three already-scaffolded-but-inert observability primitives into something real: a
|
||||
per-request structured access log (none exists today — Fastify's own request logging is fully
|
||||
disabled), the existing-but-never-observed request-duration histogram, and a real OpenTelemetry
|
||||
tracer provider behind the existing-but-never-called `getTracer()` helper. Adds eleven live
|
||||
Prometheus counters/histograms for the business-health metrics `docs/09-testing-observability-
|
||||
cicd.md` names, each wired at one existing choke point per metric (an event-bus subscriber where
|
||||
one already exists for the transition, a single already-existing method otherwise) rather than
|
||||
scattered across every call site. No new endpoints, no schema changes, no `supporthub-web` work
|
||||
— see research.md for the exact hook point chosen for each of the fourteen instrumentation
|
||||
targets (3 infra + 11 named metrics) and why.
|
||||
|
||||
## Technical Context
|
||||
|
||||
**Language/Version**: TypeScript 5.4 / Node.js 20+ (unchanged).
|
||||
|
||||
**Primary Dependencies**: New — `@opentelemetry/exporter-trace-otlp-http` (OTLP/HTTP span
|
||||
export), `@opentelemetry/resources` (service-name resource attribute). Reused, already
|
||||
installed — `@opentelemetry/api`, `@opentelemetry/sdk-trace-base` (provider, processors, and
|
||||
both the console and in-memory exporters used here all come from this one package), `prom-client`,
|
||||
`pino`. Reused Node built-in — `async_hooks`' `AsyncLocalStorage`.
|
||||
|
||||
**Storage**: No schema change. All new state is either in-process (Prometheus metric registry,
|
||||
the ALS request-context store, the tracer provider) or exported to wherever tracing is
|
||||
configured to send it — no new Postgres/Redis reads or writes beyond a handful of existing-table
|
||||
lookups already needed to label a metric correctly (e.g. `resolutionRepository.findByTicketId`
|
||||
to distinguish AI vs. human resolution).
|
||||
|
||||
**Testing**: Vitest — unit tests for the ALS-based logger mixin (a log call inside a request
|
||||
context carries requestId/correlationId; one outside carries neither) and for the
|
||||
SLA-compliance metric's "don't double-count an already-breached run as met" guard. Integration
|
||||
tests against real Postgres/Redis for: the access-log line's presence/shape (captured via a
|
||||
`logger.info` spy, same technique as 013's password-reset test), `/metrics` scraped before/after
|
||||
real traffic showing the duration histogram and each of the eleven business counters/histograms
|
||||
change by the expected amount when their real underlying event is driven through the real API,
|
||||
and a real multi-span trace (read back from the test-environment `InMemorySpanExporter`) for the
|
||||
two named cross-module paths.
|
||||
|
||||
**Target Platform**: Same Fastify modular monolith. Modifies
|
||||
`infrastructure/observability/*` (logger, metrics, tracing, a new request-context store) and
|
||||
`plugins/request-context.plugin.ts` (the new `onResponse` hook); adds small, single-call-site
|
||||
instrumentation lines inside `ai-support/sessions`, `ai-support/knowledge`, `ai-support/tools`,
|
||||
`ticketing/tickets`, `ticketing/messages`, `orchestration/sla`, and a handful of new subscribers
|
||||
in `src/events/handlers/index.ts`. No module gains a new public export surface beyond what
|
||||
`getTracer()` already exposed.
|
||||
|
||||
**Project Type**: Backend service — single project.
|
||||
|
||||
**Performance Goals**: The `onResponse` hook adds one Pino log call and one histogram `.observe`
|
||||
per request — both already-paid-for infrastructure (the logger and the metric object already
|
||||
exist), no new I/O on the request hot path. Trace export runs via `BatchSpanProcessor` (out of
|
||||
the request's own async chain) so span export latency never adds to response time. Metric
|
||||
increments at the eleven business hook points are in-memory counter operations, not database
|
||||
writes — the handful of read lookups needed for correct labeling (e.g. the resolution lookup for
|
||||
#3/#4) are single-row, already-indexed reads on tables these modules already query routinely.
|
||||
|
||||
**Constraints**: FR-007 — tracing must degrade gracefully; the API must start and serve traffic
|
||||
normally with no collector configured or reachable. FR-009 — no new human-facing endpoint,
|
||||
dashboard, or aggregation logic; every FR-008 metric is a raw counter/histogram for an external
|
||||
scraper, full stop. FR-010 — `/health*` and the existing histogram's shape on `/metrics` must
|
||||
not change for any existing consumer (only new metrics are added, nothing existing is renamed or
|
||||
removed).
|
||||
|
||||
**Scale/Scope**: Zero new routes. Three modified observability infrastructure files plus one new
|
||||
request-context store. Eleven new metric definitions plus their one-choke-point instrumentation
|
||||
call each. Two new dependencies. No schema migration, no new module.
|
||||
|
||||
## Constitution Check
|
||||
|
||||
*GATE: Must pass before Phase 0 research. Re-check after Phase 1 design.*
|
||||
|
||||
| Principle / Section | Check | Result |
|
||||
|---|---|---|
|
||||
| I. SaaS Is the Sole Identity & Access Authority | Not applicable — no identity/access surface touched. | PASS — N/A |
|
||||
| II. Configuration Over Hardcoding | The tracing exporter destination (`OTEL_EXPORTER_OTLP_ENDPOINT`) is env-driven, not hardcoded per environment; no business policy value is introduced by this feature (no SLA/routing/threshold numbers). | PASS |
|
||||
| III. Layered Architecture With Enforced Module Boundaries | No new module; existing module boundaries unchanged (each metric's instrumentation call lives inside the module that already owns the event, per research.md's per-metric table). The two repository-layer instrumentation calls (#1/#2, AI session status) are a deliberate, disclosed exception — see research.md §5's justification: observability calls are already a cross-cutting concern used from any layer in this codebase (e.g. `logger.error` inside `tool-executor.ts`), not the kind of business-logic leakage this principle targets. | PASS |
|
||||
| IV. AI Recommends, Deterministic Policy Decides | Not applicable — no AI decision logic changed, only observation of its outcomes. | PASS — N/A |
|
||||
| V. Evidence-Based Verification | Not applicable. | PASS — N/A |
|
||||
| VI. Durable Audit & History | Directly implements this principle's own stated requirement — "every log line MUST carry a request ID/correlation ID" is written in the constitution today but not actually true until this feature (FR-001/FR-002). | PASS — this feature closes a pre-existing constitutional gap |
|
||||
| VII. Concurrency-Safe, Durable Job Handling | The first-response-time metric (#5) has a benign, disclosed race (two concurrent first `AGENT_MESSAGE`s could both read "zero prior messages" and both observe) — acceptable because it is a best-effort observability metric, not the assignment/SLA correctness this principle is protecting; no persisted state or business decision depends on it. | PASS |
|
||||
| VIII. Problem and Ticket Are Separate, Related Entities | Not applicable — no model change. | PASS — N/A |
|
||||
| Technology & Platform Constraints | Two new dependencies (both OpenTelemetry, both already in the stack's declared technology list — "OpenAPI" aside, tracing itself was always part of the stated stack via the pre-existing `@opentelemetry/api`/`sdk-trace-base` dependencies) — no new infrastructure category introduced. | PASS |
|
||||
|
||||
No violations requiring Complexity Tracking justification.
|
||||
|
||||
## Project Structure
|
||||
|
||||
### Documentation (this feature)
|
||||
|
||||
```text
|
||||
specs/014-full-observability/
|
||||
├── plan.md
|
||||
├── research.md
|
||||
├── data-model.md
|
||||
├── quickstart.md
|
||||
├── contracts/
|
||||
│ └── metrics-contract.md
|
||||
└── tasks.md
|
||||
```
|
||||
|
||||
### Source Code (repository root)
|
||||
|
||||
```text
|
||||
supporthub-api/
|
||||
├── src/
|
||||
│ ├── infrastructure/
|
||||
│ │ └── observability/
|
||||
│ │ ├── logger.ts # MODIFIED — mixin reads the new ALS store
|
||||
│ │ ├── metrics.ts # MODIFIED — 11 new Counter/Histogram definitions
|
||||
│ │ ├── tracing.ts # MODIFIED — real provider init, exporter selection
|
||||
│ │ └── request-context.store.ts # NEW — AsyncLocalStorage<RequestContext>
|
||||
│ ├── plugins/
|
||||
│ │ └── request-context.plugin.ts # MODIFIED — onResponse access-log + histogram hook,
|
||||
│ │ onRequest now runs the rest of the request
|
||||
│ │ inside the ALS store
|
||||
│ ├── events/
|
||||
│ │ └── handlers/index.ts # MODIFIED — 3 new subscribers (human-resolution +
|
||||
│ │ resolution-time on TICKET_UPDATED/RESOLVED,
|
||||
│ │ escalation-rate on ESCALATION_TRIGGERED)
|
||||
│ └── modules/
|
||||
│ ├── ai-support/
|
||||
│ │ ├── sessions/repository/session.repository.ts # MODIFIED — AI resolution/escalation
|
||||
│ │ ├── knowledge/service/error-codes.service.ts # MODIFIED — most-common-errors
|
||||
│ │ └── tools/service/tools.service.ts # MODIFIED — tool-failure + knowledge-
|
||||
│ │ effectiveness
|
||||
│ ├── ticketing/
|
||||
│ │ ├── tickets/service/tickets.service.ts # MODIFIED — recurring-problems, plus
|
||||
│ │ │ the two named trace spans
|
||||
│ │ └── messages/service/messages.service.ts # MODIFIED — first-response-time
|
||||
│ └── orchestration/
|
||||
│ └── sla/service/sla.service.ts # MODIFIED — SLA-compliance
|
||||
└── tests/
|
||||
├── unit/observability/ # ALS mixin, SLA-compliance double-count guard
|
||||
└── integration/observability/ # access log, /metrics scrape assertions (11 metrics
|
||||
+ duration histogram), cross-module trace
|
||||
```
|
||||
|
||||
**Structure Decision**: Single project, no new module. All changes are surgical additions inside
|
||||
`infrastructure/observability` (the module that already owns this concern) plus one small,
|
||||
justified instrumentation line inside each of six existing business modules, following the
|
||||
per-metric hook points research.md already identified against the real, current code.
|
||||
|
||||
## Complexity Tracking
|
||||
|
||||
*No constitution violations — table intentionally omitted.*
|
||||
@@ -0,0 +1,70 @@
|
||||
# Quickstart: Full Observability
|
||||
|
||||
Manual verification steps for each user story, against a running instance backed by real
|
||||
Postgres/Redis (the throwaway Docker containers already used throughout this project's test
|
||||
suite work equally well for a manual run).
|
||||
|
||||
## Scenario 1 — Per-request access log (User Story 1)
|
||||
|
||||
1. Start the API. Send any request (e.g. `GET /health`).
|
||||
2. **Expected**: exactly one log line appears with `event: "http_request_completed"`, the
|
||||
request's method, route, status code, and a `requestId`.
|
||||
3. Send a request to a route that triggers additional internal logging (e.g. a login attempt).
|
||||
4. **Expected**: every log line produced while handling that request — the access-log line and
|
||||
any domain log lines — carries the same `requestId`/`correlationId`.
|
||||
5. Send a request to a route that doesn't exist.
|
||||
6. **Expected**: a 404 access-log line is still emitted (not silently dropped).
|
||||
|
||||
## Scenario 2 — Live request-health metrics (User Story 2)
|
||||
|
||||
1. Send a mix of successful and failing requests (e.g. a valid login, then three wrong-password
|
||||
logins).
|
||||
2. Scrape `GET /metrics`.
|
||||
3. **Expected**: `supporthub_http_request_duration_seconds_count` has observations labeled
|
||||
`route="/auth/login"` with both `status_code="200"` and `status_code="401"` present, letting
|
||||
an operator compute the error rate for that route from these two series alone.
|
||||
|
||||
## Scenario 3 — Cross-module trace (User Story 3)
|
||||
|
||||
1. With the API running in a mode where tracing exports to the console (no
|
||||
`OTEL_EXPORTER_OTLP_ENDPOINT` configured), drive a request that escalates a ticket to a human
|
||||
and triggers automatic orchestration/assignment.
|
||||
2. **Expected**: console output shows a `ticket.create`-or-`ai.escalation` root span and an
|
||||
`orchestration.assignment` child span sharing the same trace ID, with the child's start time
|
||||
at or after the parent's.
|
||||
3. Stop the (nonexistent) collector / leave `OTEL_EXPORTER_OTLP_ENDPOINT` pointed at an
|
||||
unreachable address.
|
||||
4. **Expected**: the API still starts and serves requests normally; only a logged export-failure
|
||||
warning appears, nothing surfaces to any HTTP response.
|
||||
|
||||
## Scenario 4 — Business-health metrics (User Story 4)
|
||||
|
||||
For each metric, scrape `/metrics`, note the current value, drive the real event, scrape again,
|
||||
and confirm the expected series moved by exactly one (or by the expected duration observation):
|
||||
|
||||
1. Complete an AI session without escalating → `supporthub_ai_session_outcomes_total{outcome="resolved"}` +1.
|
||||
2. Complete an AI session that escalates, then have a human agent resolve the ticket →
|
||||
`supporthub_ai_session_outcomes_total{outcome="escalated"}` +1, and once resolved,
|
||||
`supporthub_ticket_resolutions_total{resolved_by="human"}` +1.
|
||||
3. Resolve any ticket → `supporthub_ticket_resolution_duration_seconds` gains one new observation.
|
||||
4. Post the first agent reply on a ticket → `supporthub_ticket_first_response_duration_seconds`
|
||||
gains one new observation.
|
||||
5. Let an SLA run complete on time, and separately let one breach (via the existing breach-sweep
|
||||
test helper) → `supporthub_sla_run_outcomes_total{outcome="met"}` and
|
||||
`{outcome="breached"}` each +1 respectively.
|
||||
6. Trigger an escalation → `supporthub_escalations_total{reason="<the actual reason>"}` +1.
|
||||
7. Create a ticket for a categorized problem →
|
||||
`supporthub_problems_created_total{category_id="<id>"}` +1.
|
||||
8. Look up a valid error code's known issues →
|
||||
`supporthub_known_error_lookups_total{code="<code>"}` +1.
|
||||
9. Have the AI's `searchProductKnowledge` tool return zero results, then results →
|
||||
`supporthub_knowledge_retrieval_outcomes_total{matched="false"}` then `{matched="true"}`,
|
||||
each +1 in turn.
|
||||
10. Have any AI tool invocation fail → `supporthub_tool_invocations_total{tool="<name>",
|
||||
outcome="failed"}` +1.
|
||||
|
||||
## What "done" looks like
|
||||
|
||||
All four scenarios pass against a real Postgres/Redis, `/health*` and the existing
|
||||
`supporthub_http_request_duration_seconds` metric's shape are unchanged for any existing
|
||||
consumer, and the API starts and serves traffic normally with no tracing collector configured.
|
||||
@@ -0,0 +1,172 @@
|
||||
# Research: Full Observability
|
||||
|
||||
All decisions below were made against the actual current code (grep/read), not assumption —
|
||||
several existing pieces (the histogram, `getTracer()`) are dead scaffolding that looked complete
|
||||
from their exports alone but do nothing today.
|
||||
|
||||
## 1. Per-request access log
|
||||
|
||||
**Decision**: Add an `onResponse` hook (Fastify fires this for every completed response,
|
||||
including 404s and early replies from other hooks like the rate limiter, satisfying the FR-001
|
||||
edge case) that logs one line via the existing `logger` singleton: `{method, route, statusCode,
|
||||
durationMs, requestId, correlationId}`. `route` uses `request.routeOptions.url` (the
|
||||
parameterized pattern, e.g. `/tickets/:id`) rather than `request.url`, to keep label/log
|
||||
cardinality bounded — the raw URL contains IDs. `reply.elapsedTime` (Fastify's own built-in
|
||||
per-request timer) supplies duration with no manual `Date.now()` bookkeeping.
|
||||
|
||||
**Why not Fastify's built-in request logger**: `app.ts` deliberately sets `logger: false` and
|
||||
routes all logging through the shared Pino `logger` singleton (see its own comment: "Managed
|
||||
centrally via Pino logger instance"). Re-enabling Fastify's built-in logger would mean two
|
||||
independent logging paths with two different configurations; a hook that calls the existing
|
||||
singleton keeps one path.
|
||||
|
||||
**Where**: `request-context.plugin.ts` already owns the per-request lifecycle (it's the one
|
||||
place with an `onRequest` hook establishing `reqContext`) — its `onResponse` counterpart is
|
||||
added in the same file, not a new plugin, so request-lifecycle logging concerns stay together.
|
||||
|
||||
## 2. Attaching request ID/correlation ID to every log line (FR-002)
|
||||
|
||||
**Decision**: `AsyncLocalStorage<RequestContext>`, populated in the same `onRequest` hook that
|
||||
already builds `reqContext`, combined with Pino's `mixin` option (a function called for every
|
||||
log line, merging its return value into that line) reading from the store. This makes every
|
||||
call through the existing shared `logger` singleton automatically carry `requestId`/
|
||||
`correlationId` with **zero changes to any existing call site** — dozens of `logger.info/warn/
|
||||
error(...)` calls across every module already pass ad hoc fields but not always `requestId`
|
||||
consistently.
|
||||
|
||||
**Why not `request.log`**: Fastify's per-request child logger (`request.log`) is the standard
|
||||
Fastify idiom for this, but it would require passing `request` (or `request.log`) into every
|
||||
service/repository/mapper that currently imports the plain `logger` singleton directly — a
|
||||
sweeping, high-risk refactor across nearly every module for a feature whose whole point is
|
||||
*reducing* risk. The ALS+mixin approach reaches the same outcome (every log line correlated)
|
||||
without touching a single existing call site.
|
||||
|
||||
**Merge order**: Pino applies `mixin()`'s fields before merging the call's own object, so an
|
||||
explicit `requestId` passed at a call site (several already do this manually, e.g.
|
||||
`app.ts`'s error handler) still wins — no behavior change for those call sites, just now
|
||||
redundant (harmless).
|
||||
|
||||
## 3. Request-duration histogram + request-count
|
||||
|
||||
**Decision**: `httpRequestDurationHistogram.observe({method, route, status_code},
|
||||
reply.elapsedTime / 1000)` in the same `onResponse` hook. Prometheus histograms automatically
|
||||
expose a `<name>_count` and `<name>_sum` per label combination — FR-004's "compute error rate
|
||||
per route/status" is satisfied by that built-in output; no separate counter metric is added, to
|
||||
avoid two metrics tracking overlapping information.
|
||||
|
||||
## 4. Distributed tracing
|
||||
|
||||
**Decision**: Initialize a real `BasicTracerProvider` (from the already-installed
|
||||
`@opentelemetry/sdk-trace-base` — no new dependency for the SDK itself) at process start, with
|
||||
`trace.setGlobalTracerProvider(...)` so the existing, previously-inert `getTracer()` helper
|
||||
starts returning a working tracer with zero change to its own signature. Exporter selection is
|
||||
config-driven (`OTEL_EXPORTER_OTLP_ENDPOINT`, following the OpenTelemetry project's own standard
|
||||
env var name rather than inventing a new one):
|
||||
|
||||
- Set → `OTLPTraceExporter` (new dependency: `@opentelemetry/exporter-trace-otlp-http`, the
|
||||
lighter HTTP/JSON variant, avoiding the gRPC exporter's heavier dependency footprint), wrapped
|
||||
in a `BatchSpanProcessor`.
|
||||
- Unset (local dev, and any environment that hasn't configured a collector) →
|
||||
`ConsoleSpanExporter` (part of `sdk-trace-base`, zero extra dependency) wrapped in a
|
||||
`SimpleSpanProcessor`, so spans are visible immediately without standing up a collector.
|
||||
- Test environment → `InMemorySpanExporter` (also part of `sdk-trace-base`, built specifically
|
||||
for tests) wrapped in a `SimpleSpanProcessor` — this lets integration tests assert on real,
|
||||
actually-exported span data (names, parent/child nesting, attributes) with a real
|
||||
`TracerProvider` doing real work, the only substitution is *where the spans end up*, the same
|
||||
"real infrastructure, substitute only the destination" pattern already used for Pino's
|
||||
transport (`pino-pretty` in development, plain JSON otherwise).
|
||||
|
||||
**New dependencies**: `@opentelemetry/exporter-trace-otlp-http`, `@opentelemetry/resources` (for
|
||||
a `service.name: supporthub-api` resource attribute — without it, every span is anonymous in
|
||||
whatever backend receives them).
|
||||
|
||||
**Graceful degradation (FR-007)**: `BatchSpanProcessor`'s own export failures are caught and
|
||||
logged by the OpenTelemetry SDK internally (it never throws into application code); nothing in
|
||||
this feature needs to add its own try/catch around span creation for this to hold, but the SDK's
|
||||
internal diagnostic logger is wired to `logger.warn` (via `diag.setLogger`) so export failures
|
||||
are visible in this project's own log stream rather than swallowed silently.
|
||||
|
||||
**Where spans are added (FR-006)**: two entry points, wrapping already-existing method calls
|
||||
rather than restructuring them:
|
||||
- `ai-support/sessions/service/session.service.ts`'s escalation path — a span around the call
|
||||
that ultimately triggers `orchestrationService.handleHumanEscalation` (via the
|
||||
`TICKET_UPDATED` → `HUMAN_ESCALATION` domain-event subscriber in
|
||||
`src/events/handlers/index.ts`), and a child span inside
|
||||
`orchestration/orchestration`'s and `orchestration/assignments`'s own handling — showing the
|
||||
AI-diagnosis → escalation → assignment path as one connected trace.
|
||||
- `ticketing/tickets/service/tickets.service.ts`'s ticket-creation method — a root span for
|
||||
ticket intake, with the domain-event-driven downstream reactions (SLA-run creation, etc.)
|
||||
as child spans, per FR-006's second named path.
|
||||
|
||||
Trace context propagates across the event-bus's synchronous `await eventBus.publish(...)` calls
|
||||
for free (both publisher and subscriber run within the same Node async-context chain the OTel
|
||||
context API rides on — no manual context passing needed, since nothing here crosses a process/
|
||||
queue boundary; BullMQ jobs are explicitly out of scope for this feature's two named paths).
|
||||
|
||||
## 5. The eleven named business-health metrics (FR-008) — instrumentation points
|
||||
|
||||
Each is a `prom-client` `Counter` or `Histogram`, registered once in
|
||||
`infrastructure/observability/metrics.ts` alongside the existing histogram, and incremented/
|
||||
observed at one single already-existing choke point per metric — chosen specifically to avoid
|
||||
scattering an instrumentation call across every one of a metric's several call sites.
|
||||
|
||||
| # | Metric | Type | Hook point (file : method) | Label(s) |
|
||||
|---|---|---|---|---|
|
||||
| 1 | AI resolution rate | Counter | `ai-support/sessions/repository/session.repository.ts` : `updateStatus`, when `status === 'resolved'` | — |
|
||||
| 2 | AI escalation rate | Counter | same method, when `status === 'escalated'` | — |
|
||||
| 3 | Human resolution rate | Counter | new `TICKET_UPDATED` subscriber (`events/handlers/index.ts`) on `newStatus === 'RESOLVED'`, looking up `resolutionRepository.findByTicketId` for `resolvedBy` | `resolvedBy !== 'ai'` only |
|
||||
| 4 | Average resolution time | Histogram | same subscriber — observes `resolvedAt - ticket.createdAt` | — |
|
||||
| 5 | First response time | Histogram | `ticketing/messages/service/messages.service.ts` : `post`, when `type === 'AGENT_MESSAGE'` and no prior `AGENT_MESSAGE` exists for the ticket | — |
|
||||
| 6 | SLA compliance | Counter | `orchestration/sla/service/sla.service.ts` : `complete` (outcome `met`, only if the run wasn't already `breached`) and `runBreachDetectionSweep` (outcome `breached`) | `outcome` |
|
||||
| 7 | Escalation rate | Counter | new `ESCALATION_TRIGGERED` subscriber (`events/handlers/index.ts`) — this event is already published unconditionally on every escalation (`escalation.service.ts`) but "for audit, not for logic" (its own comment) and has zero subscribers today | `reason` |
|
||||
| 8 | Recurring problems | Counter | `ticketing/tickets/service/tickets.service.ts` — the ticket-creation method's existing `problemsRepo.create(...)` call | `categoryId` (or `uncategorized`) |
|
||||
| 9 | Most common errors | Counter | `ai-support/knowledge/service/error-codes.service.ts` : `findKnownIssuesByErrorCode`, after a valid code is confirmed to exist | `code` |
|
||||
| 10 | Knowledge effectiveness | Counter | `ai-support/tools/service/tools.service.ts`'s single `executeTool(...)` call site, when `block.name === 'searchProductKnowledge'` | `matched` (results non-empty vs empty) |
|
||||
| 11 | Tool failure rate | Counter | same call site, every tool invocation | `tool`, `outcome` |
|
||||
|
||||
**Why the event bus for #3, #4, #7 instead of editing `resolutions.service.ts`/
|
||||
`escalation.service.ts` directly**: those two modules' domain events (`TICKET_UPDATED` with
|
||||
`newStatus`, and `ESCALATION_TRIGGERED`) are already published unconditionally for every
|
||||
relevant transition (confirmed by reading `tickets.service.ts` and `escalation.service.ts`
|
||||
directly) specifically so that a new concern reacting to "a ticket resolved" or "an escalation
|
||||
happened" never needs to modify the module that owns the transition — the exact precedent
|
||||
`src/events/handlers/index.ts`'s existing four subscribers already establish for 005/007/008.
|
||||
Metrics is exactly this kind of concern.
|
||||
|
||||
**Why the repository layer for #1/#2 instead of the event bus**: AI-session resolved/escalated
|
||||
is not currently published as a domain event at all (only ticket-level and escalation-level
|
||||
events exist) and `session.service.ts` calls `this.sessions.updateStatus(...)` from ten
|
||||
different branches — adding a domain-event publish there to reuse the event-bus pattern would
|
||||
mean either introducing a new event type used by exactly one subscriber (this feature) or
|
||||
touching all ten call sites to route through a new shared wrapper. Instrumenting the one
|
||||
repository method both approaches would have to fire through instead is the minimal, lowest-risk
|
||||
option. This mirrors how `logger` calls already appear directly inside repository/service code
|
||||
throughout this codebase (e.g. `tool-executor.ts`'s `logger.error`) — observability calls are
|
||||
already treated as a cross-cutting concern usable from any layer, not something Constitution
|
||||
Principle III's "repository is Prisma-only" rule was written to police (that rule targets
|
||||
business-logic leakage and direct Prisma access from the wrong layer, not a metrics increment
|
||||
alongside an existing Prisma call).
|
||||
|
||||
**A pre-existing correctness note surfaced while researching #6**: `sla.service.ts`'s
|
||||
`complete()` only skips its update when the run is *already* `'completed'` — not when it is
|
||||
`'breached'` — so a run that breached and then later resolved would have its `status`
|
||||
overwritten from `'breached'` back to `'completed'` in the database, silently losing the breach
|
||||
record. This is a pre-existing 008/012 behavior, not something this feature changes (the SLA
|
||||
run's persisted status is out of scope for an observability feature) — the metric itself reads
|
||||
`run.status` *before* calling `complete()`'s own update, so the metric is accurate (correctly
|
||||
counted as `breached`, never double-counted as `met`) regardless of this separate, pre-existing
|
||||
data-quality gap. Documented in this feature's own checklist Notes as a discovered issue for a
|
||||
future fix, the same way 013-auth-hardening documented the `orchestration-strategies.test.ts`
|
||||
bug it found without fixing it.
|
||||
|
||||
## 6. Test strategy for the eleven metrics and tracing
|
||||
|
||||
**Decision**: Integration tests scrape the real `/metrics` endpoint's text output (a real
|
||||
`app.inject({method: 'GET', url: '/metrics'})` call, no mocking) before and after driving the
|
||||
real underlying event through the real API (create a ticket, resolve an AI session, trigger an
|
||||
escalation, etc. — exactly as every prior feature's integration suite already does against real
|
||||
Postgres/Redis), asserting the specific metric line's value increased by the expected amount.
|
||||
Tracing is verified by reading back spans from the `InMemorySpanExporter` (test-environment
|
||||
exporter, per §4) after a real cross-module request, asserting span names and parent/child
|
||||
`spanId`/`parentSpanId` relationships — a real trace, produced by a real `TracerProvider`, just
|
||||
captured in memory instead of shipped to a collector.
|
||||
Reference in New Issue
Block a user