<!--
Author: Simon-Pierre Boucher
Contact: contact@spboucher.ai
-->

# Patterns — Instrumenting Observability

## Contents
- Structured logging setup (Python)
- Request-ID middleware and propagation
- RED metrics (Prometheus)
- OpenTelemetry tracing setup
- Symptom alerts (SLO burn)
- Gotchas

## Structured logging setup (Python)

```python
import structlog

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,   # injects request_id
        structlog.processors.add_log_level,
        structlog.processors.TimeStamper(fmt="iso", key="ts"),
        structlog.processors.JSONRenderer(),
    ],
)
logger = structlog.get_logger(service="orders")
logger.info("order_created", order_id=123, total_cents=4999)
```

Scrub secrets before rendering:

```python
DENYLIST = {"password", "token", "authorization", "card_number", "cvv"}
def scrub(logger, method, event_dict):
    for k in list(event_dict):
        if k.lower() in DENYLIST:
            event_dict[k] = "[redacted]"
    return event_dict
# add `scrub` before JSONRenderer in processors
```

## Request-ID middleware and propagation

```python
import uuid, structlog

@app.middleware("http")
async def request_id(request, call_next):
    rid = request.headers.get("x-request-id") or f"r-{uuid.uuid4().hex[:12]}"
    structlog.contextvars.bind_contextvars(request_id=rid)
    response = await call_next(request)
    response.headers["x-request-id"] = rid      # echo for the caller
    return response

# outbound: always forward
httpx.get(url, headers={"x-request-id": rid})
```

## RED metrics (Prometheus)

```python
from prometheus_client import Counter, Histogram

REQS = Counter("http_requests_total", "requests", ["route", "method", "status"])
# Buckets bracket the SLO (e.g. 300ms target): resolution where it matters.
LAT = Histogram("http_request_seconds", "latency", ["route"],
                buckets=[.025, .05, .1, .2, .3, .5, 1, 2, 5])

@app.middleware("http")
async def metrics(request, call_next):
    with LAT.labels(request.url.path).time():
        resp = await call_next(request)
    REQS.labels(request.url.path, request.method, resp.status_code).inc()
    return resp
```

Label values must be low-cardinality: route *templates* (`/orders/{id}`), never raw paths.

## OpenTelemetry tracing setup

```python
from opentelemetry import trace
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from opentelemetry.instrumentation.httpx import HTTPXClientInstrumentor

FastAPIInstrumentor.instrument_app(app)     # inbound spans + context extraction
HTTPXClientInstrumentor().instrument()      # outbound propagation

tracer = trace.get_tracer("orders")
with tracer.start_as_current_span("price_cart") as span:   # manual span: meaningful unit only
    span.set_attribute("cart.items", len(items))
    total = price(items)
```

Export via OTLP to the collector; configure endpoint with `OTEL_EXPORTER_OTLP_ENDPOINT`.

## Symptom alerts (SLO burn)

```yaml
# Page when error budget burns 14.4x too fast over 1h AND 5m (multiwindow).
- alert: HighErrorBurn
  expr: >
    (sum(rate(http_requests_total{status=~"5.."}[5m]))
     / sum(rate(http_requests_total[5m]))) > 14.4 * 0.001
    and
    (sum(rate(http_requests_total{status=~"5.."}[1h]))
     / sum(rate(http_requests_total[1h]))) > 14.4 * 0.001
  labels: {severity: page}
```

p99 latency against SLO: `histogram_quantile(0.99, sum(rate(http_request_seconds_bucket[5m])) by (le))`.

## Gotchas
- Averages hide pain: a 50 ms mean can coexist with a 5 s p99 — always use histograms/percentiles.
- `user_id` as a metric label = cardinality bomb; it belongs in log fields and span attributes.
- Logging inside a hot retry loop can 100x volume — first failure + final outcome, counter for the middle.
- Forgetting to *echo* X-Request-ID back means clients can't report the ID for support.
- OTel context does not cross thread/process pools automatically — use the context-propagation helpers.
- DEBUG left on in prod both leaks payloads and doubles log cost; enforce level via env config.