duocthu/docs-legacy/17-observability.md

# 17 — Observability

Implementation: `rag/telemetry.py`, `rag/metrics.py`, `rag/instrumentation.py`,
`adapters/prometheus.py`, `infra/docker/{prometheus,grafana,tempo,otel}/`.
Tests: `tests/test_observability.py`.

## Signal table

| Signal | Instrumentation | Backend | Purpose |
|---|---|---|---|
| Metrics | `prometheus_client` via `adapters/prometheus.py`, exposed at `GET /metrics` | Prometheus (scrape 15 s) | Request rate/latency, decisions, abstentions, provider failures |
| Traces | OpenTelemetry SDK, OTLP/HTTP | OTel Collector → Tempo | Per-request spans with per-stage children |
| Logs | Python `logging` to stdout, uvicorn defaults | `docker logs` only | Ad-hoc debugging |
| Dashboards | Provisioned JSON | Grafana | `duocthu-observability` |
| Health | `/health`, `/ready` | Compose/K8s probes + the deploy smoke test | Liveness/readiness |
| Alerting | — | — | **Not found** |

Both metrics and tracing are optional and degrade to no-ops: a missing
`prometheus_client` yields `None` metrics rather than a service that will not
start ("observability is not a precondition for answering"), and missing
OpenTelemetry packages or `OTEL_ENABLED=false` yield a no-op tracer.

## Metrics

Names are defined in `rag/metrics.py` so, as the docstring puts it, "the numbers
on a dashboard are the numbers the domain actually decided".

| Metric | Type | Labels | Incremented in |
|---|---|---|---|
| `duocthu_requests_total` | counter | `method`, `route`, `status` (class) | `main.py` middleware |
| `duocthu_request_duration_seconds` | histogram | `method`, `route`, `status` | `main.py` middleware |
| `duocthu_stage_duration_seconds` | histogram | `stage`, `outcome` | `telemetry.stage()` |
| `duocthu_decision_total` | counter | `decision`, `reason` | `routers/rag.py` |
| `duocthu_retrieval_route_total` | counter | `route` | `InstrumentedRetrievalService` |
| `duocthu_abstention_total` | counter | `reason` | `answer.py` |
| `duocthu_generation_rejected_total` | counter | `reason` | `answer.py` |
| `duocthu_generation_served_total` | counter | — | `answer.py` |
| `duocthu_answer_extractive_total` | counter | — | `answer.py` (no-generator mode) |
| `duocthu_clarify_asked_total` | counter | `reason` | `InstrumentedRagAgent` |
| `duocthu_provider_failure_total` | counter | `provider`, `operation`, `reason` | `Instrumented{Generator,Embedder,Reranker}`, retrieval |
| `duocthu_trace_write_failed_total` | counter | — | `routers/rag.py` |

`duocthu_generation_rejected_total` is called out in the module docstring as the
one that matters: it is *the measured form of the claim that the answer layer
cannot state a figure the book does not.*

### Registered but never incremented

`duocthu_loop_retrieval_rounds_total`, `duocthu_loop_refined_total`,
`duocthu_loop_repaired_total`, `duocthu_followup_inherited_total`. Verified by
grep: their only references outside `rag/metrics.py` are the registration and
help-text tables in `adapters/prometheus.py`. They are leftovers of the ADR 0007
loop design that ADR 0008 replaced, and they will always report zero.

### Cardinality control

Every label is a bounded vocabulary. `_route_label` in `main.py` maps any
unrecognised path to the literal `"other"`, and `status` is a class
(`2xx`/`4xx`/`5xx`), not a code. `adapters/prometheus.py` normalises
stage/provider/reason values. Without this, a caller could mint unbounded time
series by varying the URL.

## Tracing

`rag/telemetry.py` configures **one** OTLP tracer provider, with
`ParentBased(TraceIdRatioBased(OTEL_SAMPLE_RATIO))` and a `BatchSpanProcessor`.
If a provider was already installed (by a host or a test) it is reused rather
than replaced.

Span structure for one request:

```
SERVER  {METHOD} {route}                       ← main.py middleware, extracts traceparent
├── rag.stage.receive
├── rag.stage.context                          ← RagAgent._get_history
├── rag.stage.understanding                    ← InstrumentedQueryUnderstander
│   └── provider.bedrock_converse.understand
├── rag.stage.routing                          ← RagAgent._route
│   ├── rag.stage.retrieval
│   │   ├── rag.stage.rerank
│   │   └── rag.stage.evidence
│   ├── rag.stage.generation
│   │   └── provider.bedrock_converse.generate
│   ├── rag.stage.grounding                    ← @traced_stage on grounding.verify
│   └── rag.stage.entailment
│       └── provider.bedrock_converse.entailment
├── rag.stage.persistence
└── rag.stage.response
```

`InstrumentedGenerator` derives the dependency-span operation name from the
current stage (`understanding` → `understand`, `generation` → `generate`,
`entailment` → `entailment`), so all three Bedrock calls are distinguishable
despite going through one adapter.

`stage()` also records `duocthu_stage_duration_seconds` and marks
`duocthu.outcome` as `ok` / `error` / `cancelled` — which answers the
"trace has no per-stage timing" gap noted in the earlier pipeline audit.

### Span attributes

`duocthu.correlation_id`, `duocthu.decision`, `duocthu.reason`,
`duocthu.citation_count`, `duocthu.generated`, `duocthu.persisted_trace_id`,
`duocthu.evidence_count`, `duocthu.turn_type`, `duocthu.needs_clarify`,
`duocthu.system_error`, `duocthu.http.status_class`, `duocthu.duration_ms`,
`duocthu.stage`, `duocthu.outcome`, `duocthu.provider`, `duocthu.operation`.

`annotate_current_span` silently drops any value that is not `str`/`bool`/
`int`/`float`, so a stray object cannot break export.

## Correlation

Three identifiers, joinable:

| Id | Origin | Carried in |
|---|---|---|
| `X-Correlation-ID` | Client, or generated; validated by regex | Request header, response header, `rag_retrieval_trace.correlation_id`, span attribute |
| OTel trace id | Sampler | `X-Trace-ID` response header, `rag_retrieval_trace.otel_trace_id`, Tempo |
| `trace_id` (application) | UUID per answer | Response body, `rag_retrieval_trace.trace_id`, `rag_answer_feedback.trace_id` |

`migrations/003` adds partial indexes on the first two, so a support request
carrying either header can be looked up.

Propagation is **stored as a context var** (`ContextVar`), which works across
FastAPI's async middleware and its sync thread-pool endpoint — the module
docstring names that as the reason for the design.

## Deployed stack

```mermaid
flowchart LR
    AI["ai-service<br/>OTEL_ENABLED=true"]
    OC["otel-collector 0.123.0<br/>memory_limiter + batch"]
    TP["tempo 2.7.2"]
    PR["prometheus v3.3.0<br/>scrape ai-service:8000/metrics"]
    GF["grafana 11.5.2<br/>127.0.0.1:3002"]
    CD["caddy → /grafana/*"]
    U[Operator]

    AI -->|"OTLP/HTTP :4318"| OC -->|"OTLP/gRPC tempo:4317"| TP
    PR -->|scrape 15s| AI
    GF --> PR
    GF --> TP
    U -->|https://realvuxbaro.me/grafana/| CD --> GF
```

Datasources are provisioned with fixed UIDs `prometheus` and `tempo`
(`infra/docker/grafana/provisioning/datasources/prometheus.yml`), and the
dashboard `duocthu-observability` is provisioned from
`infra/docker/grafana/dashboards/duocthu-grounding.json`. Exemplar storage is
enabled on Prometheus (`--enable-feature=exemplar-storage`).

## What the deploy pipeline actually verifies

`.github/workflows/deploy.yml` does not just start the stack — it asserts it:

- `prometheus:9090/-/ready`, `tempo:3200/ready` (retried 12×5 s),
  `grafana:3000/api/health`;
- both Grafana datasources exist by UID, authenticated as admin;
- the dashboard `duocthu-observability` exists;
- `https://realvuxbaro.me/grafana/login` is reachable;
- a real query is issued with a generated `X-Correlation-ID`, the returned
  `X-Trace-ID` is asserted to match `^[0-9a-f]{32}$`, then after 20 s
  `duocthu_requests_total` must be present in Prometheus **and** the exact trace
  id must be retrievable from `tempo:3200/api/traces/<id>` (retried 12×5 s).

That last assertion is the strongest evidence in the repository that tracing
works end to end in production.

## Gaps

- **No alerting.** No Alertmanager, no Prometheus rule files, no Grafana alert
  rules in the provisioning directory.
- **No log aggregation.** No Loki, no Promtail, no structured/JSON logging. Logs
  are reachable only via `docker logs`, and the level choices are odd —
  `agent.py` logs ordinary per-turn timings at `warning` because uvicorn's
  default config does not wire handlers onto the root logger.
- **No SLOs, no error budget, no burn-rate rules.**
- **`web` is not instrumented at all** — no metrics, no traces, no structured
  logs. It only forwards `traceparent`.
- **No Prometheus retention flag in the Compose overlay** (the Helm values set
  7 d; Compose relies on the image default).
- **No RED/USE dashboard beyond the single provisioned one**; its panel set was
  not audited in this pass.