feat(observability): OpenTelemetry traces and metrics

.env.example

@@ -216,3 +216,27 @@ KEYCLOAK_ADMIN_CLIENT_IDS=["opentaberna-admin-ui"]
 # How long signing keys are cached before being refetched. Keycloak rotates
 # keys, so this must expire rather than being fetched once at startup.
 KEYCLOAK_JWKS_CACHE_SECONDS=300
+
+# ----------------------------------
+# Analytics / reporting
+# ----------------------------------
+# IANA timezone the shop trades in. Analytics buckets days in this zone rather
+# than UTC, so "today" matches the operator's day.
+SHOP_TIMEZONE=Europe/Berlin
+
+# Accept anonymous shopper events from the storefront. Off by default: cloning
+# OpenTaberna must not silently start collecting anything. While false the
+# ingest endpoint returns 404.
+STOREFRONT_ANALYTICS_ENABLED=false
+
+# ----------------------------------
+# OpenTelemetry
+# ----------------------------------
+# Export traces and metrics over OTLP. Off by default, for the same reason.
+OTEL_ENABLED=false
+
+# The seam: pointing this at a vendor's collector is the whole change needed to
+# use one, because no application code imports a vendor SDK.
+OTEL_EXPORTER_OTLP_ENDPOINT=http://opentaberna-otel-collector:4318
+OTEL_SERVICE_NAME=opentaberna-api
+OTEL_METRIC_EXPORT_INTERVAL_SECONDS=30

docker-compose.dev.yml

@@ -11,6 +11,8 @@ services:
       KEYCLOAK_URL: http://opentaberna-keycloak:8080
       KEYCLOAK_PUBLIC_URL: http://localhost:8080
       STORAGE_ENDPOINT_URL: http://opentaberna-minio:9000
+      OTEL_EXPORTER_OTLP_ENDPOINT: http://opentaberna-otel-collector:4318
+      OTEL_SERVICE_NAME: opentaberna-api
     volumes:
       - stripe_webhook_secret:/run/secrets:ro
     ports:
@@ -178,6 +180,8 @@ services:
     environment:
       REDIS_URL: redis://opentaberna-redis:6379/0
       STORAGE_ENDPOINT_URL: http://opentaberna-minio:9000
+      OTEL_EXPORTER_OTLP_ENDPOINT: http://opentaberna-otel-collector:4318
+      OTEL_SERVICE_NAME: opentaberna-worker
     restart: unless-stopped
     container_name: opentaberna-worker
     healthcheck:
@@ -207,6 +211,61 @@ services:
       - "8081:8080" # GreenMail web UI
     restart: unless-stopped
 
+  # --------------------------------------------------------------------
+  # Observability (S3). Self-hosted by default; the collector is the seam,
+  # so pointing OTEL_EXPORTER_OTLP_ENDPOINT at a vendor replaces all three
+  # without touching application code.
+  # --------------------------------------------------------------------
+
+  opentaberna-otel-collector:
+    image: otel/opentelemetry-collector-contrib:0.116.1
+    command: ["--config=/etc/otel/config.yaml"]
+    volumes:
+      - ./src/docker/observability/otel-collector.yaml:/etc/otel/config.yaml:ro
+    ports:
+      - "4318:4318"   # OTLP/HTTP
+      - "8889:8889"   # Prometheus scrape target
+    restart: unless-stopped
+    container_name: opentaberna-otel-collector
+
+  opentaberna-prometheus:
+    image: prom/prometheus:v3.1.0
+    command:
+      - "--config.file=/etc/prometheus/prometheus.yml"
+      - "--storage.tsdb.retention.time=15d"
+    volumes:
+      - ./src/docker/observability/prometheus.yml:/etc/prometheus/prometheus.yml:ro
+      - prometheus_data:/prometheus
+    ports:
+      - "9090:9090"
+    restart: unless-stopped
+    container_name: opentaberna-prometheus
+    depends_on:
+      - opentaberna-otel-collector
+
+  opentaberna-grafana:
+    image: grafana/grafana:11.4.0
+    environment:
+      # Development only. The dashboard is read-only and carries no secrets,
+      # and requiring a login to look at a latency graph on your own laptop
+      # helps nobody.
+      GF_AUTH_ANONYMOUS_ENABLED: "true"
+      GF_AUTH_ANONYMOUS_ORG_ROLE: Admin
+      GF_AUTH_DISABLE_LOGIN_FORM: "true"
+      GF_USERS_DEFAULT_THEME: light
+    volumes:
+      - ./src/docker/observability/grafana/datasources:/etc/grafana/provisioning/datasources:ro
+      - ./src/docker/observability/grafana/dashboards:/etc/grafana/provisioning/dashboards:ro
+      - grafana_data:/var/lib/grafana
+    ports:
+      - "3001:3000"
+    restart: unless-stopped
+    container_name: opentaberna-grafana
+    depends_on:
+      - opentaberna-prometheus
+
 volumes:
   keycloak_data:
   stripe_webhook_secret:
+  prometheus_data:
+  grafana_data:

docs/observability.md

@@ -0,0 +1,133 @@
+# Observability
+
+OpenTelemetry traces and metrics from the API and the worker, exported over OTLP.
+
+Before this the API had structured logs and correlation IDs and nothing else.
+"The shop feels slow" could not be answered with anything but a guess, and a
+regression in one endpoint stayed invisible until somebody reported it.
+
+## OTLP is the seam
+
+No application module imports a vendor SDK. Everything speaks OTLP to a
+collector, and the collector decides where telemetry goes. Using Datadog or
+Grafana Cloud instead of the bundled stack is a change to
+`OTEL_EXPORTER_OTLP_ENDPOINT` and the collector's config — not a change to any
+service.
+
+```
+API ────┐
+        ├──▶ OTel Collector ──▶ Prometheus ──▶ Grafana
+Worker ─┘         (:4318)         (:9090)      (:3001)
+```
+
+## Off by default
+
+`OTEL_ENABLED` defaults to `false`, and while it is off `setup()` returns before
+creating an exporter — so a deployment that has not opted in opens no
+connection and sends nothing anywhere.
+
+## It must never take the application down
+
+Every step of the wiring is wrapped. A collector that is absent, unreachable or
+misconfigured produces a warning and a running API, not a failed start.
+Observability that can cause the outage it exists to diagnose is a bad trade,
+and the tests pin this: an exporter that raises on construction still leaves
+`setup()` returning `False` rather than propagating.
+
+## What is instrumented
+
+| Source | Gives you |
+|---|---|
+| FastAPI | Request rate, latency histogram, status codes, in-flight requests |
+| SQLAlchemy | Query spans and connection pool usage |
+| Redis | Command spans |
+| httpx | Outbound calls — Stripe, DHL, Keycloak |
+
+Health endpoints are excluded. A liveness probe every few seconds would
+otherwise dominate the trace volume and the request-rate metric, burying real
+traffic under a heartbeat.
+
+## Business gauges
+
+`Deployment.md` names the queue states worth alerting on. They used to be
+queries an operator had to remember to run, which means nobody ran them and the
+first sign of a stalled pipeline was a customer asking where their parcel was.
+
+| Metric | Non-zero means |
+|---|---|
+| `opentaberna.outbox.pending` | Rising: the worker is not running |
+| `opentaberna.outbox.failed` | Events never reached the queue — Redis or the poller |
+| `opentaberna.outbox.dead` | Jobs ran and gave up — usually the carrier API |
+| `opentaberna.webhooks.unprocessed` | Payments arriving, not handled. **Page on this.** |
+| `opentaberna.orders.awaiting_shipment` | The work queue, not necessarily a fault |
+
+**These are collected by the worker, on a 30-second cron.** The first version
+used observable gauges whose callbacks run on the metrics SDK's own thread — and
+the only database engine here is asynchronous, so driving it from outside the
+event loop failed. The gauges registered cleanly and then silently produced
+nothing, which is the worst kind of monitoring bug. The worker already runs a
+scheduler and holds an async session, and is the process that most needs to be
+alive for these numbers to matter.
+
+## Traces and logs are joined
+
+Every log record carries `trace_id` alongside `correlation_id`. Without it the
+two systems describe the same request and cannot be put side by side — you would
+find a slow span in Grafana and have no way to reach the log lines explaining it.
+The field is empty when tracing is off, so it is always present and a formatter
+never raises.
+
+## Running it
+
+```bash
+# in .env
+OTEL_ENABLED=true
+
+docker compose -f docker-compose.dev.yml up -d
+```
+
+| Service | URL |
+|---|---|
+| Grafana | http://localhost:3001 — anonymous, dashboard provisioned |
+| Prometheus | http://localhost:9090 |
+| Collector metrics | http://localhost:8889/metrics |
+
+Grafana is anonymous **in the development compose file only**. The dashboard is
+read-only and holds no secrets, and requiring a login to look at a latency graph
+on your own laptop helps nobody. Do not copy that setting to production.
+
+## The dashboard
+
+`OpenTaberna — Health`, provisioned from
+`src/docker/observability/grafana/dashboards/`. Three rows: the queue gauges
+above, request rate/error rate/latency percentiles, and dependency health.
+
+Two details worth keeping if you edit it:
+
+**The error-rate panel ends in `or vector(0)`.** Without it a healthy shop shows
+"No data", which is indistinguishable from a broken scrape — and is exactly the
+wrong thing to be uncertain about during an incident.
+
+**Latency panels use p95 and p99, never an average.** An average hides the slow
+tail that customers actually notice.
+
+The FastAPI instrumentation labels the path as `http_target`, not `http_route`.
+Grouping by `http_route` silently collapses every route into one unnamed series,
+which looks like a working panel. That mistake is already made and fixed here.
+
+## Production
+
+- Set `OTEL_EXPORTER_OTLP_ENDPOINT` to your collector.
+- Set `OTEL_SERVICE_NAME` per process — the worker overrides it in compose.
+- Do not expose Grafana anonymously.
+- Alert on `webhooks_unprocessed` and `outbox_failed` first: both mean money has
+  moved and the system has not noticed.
+
+## Testing
+
+- `tests/test_telemetry_unit.py` — off unless opted in, idempotent setup, and
+  every failure mode degrading to "no telemetry" rather than "no API".
+- `tests/test_telemetry_integration.py` — asserts against the collector's
+  output and Prometheus, not against the fact that setup was called. That
+  distinction caught the real bug: instrumenting the app before configuring
+  telemetry logged a clean start and produced no HTTP metrics at all.

pyproject.toml

@@ -36,6 +36,12 @@ dependencies = [
     "sqlalchemy[asyncio]>=2.0.49",
     "stripe>=15.0.1",
     "uvicorn>=0.43.0",
+    "opentelemetry-sdk>=1.44.0",
+    "opentelemetry-exporter-otlp-proto-http>=1.44.0",
+    "opentelemetry-instrumentation-fastapi>=0.65b0",
+    "opentelemetry-instrumentation-sqlalchemy>=0.65b0",
+    "opentelemetry-instrumentation-redis>=0.65b0",
+    "opentelemetry-instrumentation-httpx>=0.65b0",
 ]
 
 [project.optional-dependencies]

src/app/chore/lifespan.py

@@ -14,6 +14,8 @@
 from app.shared.database.base import Base
 from app.shared.database.engine import close_database, get_engine, init_database
 from app.shared.logger import get_logger
+from app.shared.observability import instrument_engine
+from app.shared.observability import setup as setup_telemetry
 from app.shared.storage.minio_adapter import build_minio_adapter
 
 logger = get_logger(__name__)
@@ -43,9 +45,16 @@ async def lifespan(app: FastAPI):
     # Startup: validate secrets before doing anything else
     _validate_critical_secrets()
 
+    # Telemetry before anything else, so startup itself is traced. A disabled
+    # or unreachable collector logs a warning and the API starts regardless —
+    # observability must not be able to cause the outage it exists to diagnose.
+    settings = get_settings()
+    setup_telemetry(settings)
+
     # Startup: Initialize database and create tables
     await init_database()
     engine = get_engine()
+    instrument_engine(engine, settings)
     async with engine.begin() as conn:
         # This creates all tables from SQLAlchemy models that inherit from Base
         await conn.run_sync(Base.metadata.create_all)

src/app/main.py

@@ -21,6 +21,8 @@
 from app.shared.exceptions import AppException, InternalError
 from app.shared.logger import get_logger
 from app.shared.middleware import CorrelationIDMiddleware
+from app.shared.observability import instrument_app
+from app.shared.observability import setup as setup_telemetry
 from app.shared.rate_limit import limiter
 from app.shared.responses import ErrorResponse, ValidationErrorResponse
 from app.shared.config import get_settings
@@ -127,6 +129,16 @@ async def generic_exception_handler(request: Request, exc: Exception) -> JSONRes
 
 origins = ["*"]  # Consider restricting this in a production environment
 
+# Telemetry must be configured before instrumenting, and this module is
+# imported long before lifespan startup runs — instrumenting first silently
+# produced no HTTP metrics at all. setup() is idempotent, so lifespan calling
+# it again is harmless.
+setup_telemetry(_settings)
+
+# Traces HTTP requests. Health endpoints are excluded inside instrument_app:
+# a liveness probe every few seconds would otherwise bury real traffic.
+instrument_app(app, _settings)
+
 app.add_middleware(CorrelationIDMiddleware)
 app.add_middleware(SlowAPIMiddleware)
 app.add_exception_handler(RateLimitExceeded, _rate_limit_exceeded_handler)

src/app/shared/config/settings.py

@@ -288,6 +288,31 @@ class Settings(BaseSettings):
         description="Default label format requested from DHL: 'pdf' or 'zpl'",
     )
 
+    # OpenTelemetry — see app/shared/observability
+    otel_enabled: bool = Field(
+        default=False,
+        description=(
+            "Export traces and metrics over OTLP. Off by default: a deployment "
+            "that has not opted in must send nothing anywhere."
+        ),
+    )
+    otel_exporter_otlp_endpoint: str = Field(
+        default="http://opentaberna-otel-collector:4318",
+        description=(
+            "OTLP/HTTP endpoint. This is the seam — pointing it at a vendor's "
+            "collector is the whole change needed to use one, because no "
+            "application code imports a vendor SDK."
+        ),
+    )
+    otel_service_name: str = Field(
+        default="opentaberna-api",
+        description="service.name on every span and metric",
+    )
+    otel_metric_export_interval_seconds: int = Field(
+        default=30,
+        description="Seconds between metric exports",
+    )
+
     # Analytics / reporting
     storefront_analytics_enabled: bool = Field(
         default=False,

src/app/shared/logger/filters.py

@@ -90,6 +90,7 @@ class CorrelationIdFilter(ILogFilter):
     """
 
     ATTRIBUTE = "correlation_id"
+    TRACE_ATTRIBUTE = "trace_id"
 
     def filter(self, record: logging.LogRecord) -> bool:
         """Never blocks — only enriches the record."""
@@ -100,6 +101,15 @@ def filter(self, record: logging.LogRecord) -> bool:
 
         if not hasattr(record, self.ATTRIBUTE):
             setattr(record, self.ATTRIBUTE, get_correlation_id())
+
+        # The trace id is what joins a span found in Grafana to the log lines
+        # for that same request. Without it the two systems describe the same
+        # work and cannot be put side by side. Empty when tracing is off, so
+        # the field is always present and a formatter never KeyErrors.
+        if not hasattr(record, self.TRACE_ATTRIBUTE):
+            from app.shared.observability import current_trace_id
+
+            setattr(record, self.TRACE_ATTRIBUTE, current_trace_id() or "")
         return True
 
     def sanitize(self, data: Dict[str, Any]) -> Dict[str, Any]:

src/app/shared/logger/formatters.py

@@ -39,6 +39,12 @@ def format(self, record: logging.LogRecord) -> str:
         if correlation_id:
             log_data["correlation_id"] = correlation_id
 
+        # Promoted to a top-level field so a log backend can index it and a
+        # trace found in Grafana leads straight to these lines.
+        trace_id = getattr(record, "trace_id", "")
+        if trace_id:
+            log_data["trace_id"] = trace_id
+
         # Add context data
         context = get_log_context()
         if context:
@@ -71,6 +77,7 @@ def format(self, record: logging.LogRecord) -> str:
                 "stack_info",
                 "taskName",
                 "correlation_id",
+                "trace_id",
             }
 
             extra_fields = {