M22: implement operational observability

.env.example

@@ -25,6 +25,13 @@ OIDC_ALLOWED_EMAIL_DOMAINS=
 OIDC_AUTO_PROVISION=true
 OIDC_DEFAULT_ROLE=rental_employee
 
+# Observability: JSON logs are always enabled. Set a token only if /metrics is exposed
+# outside the private Compose network; Prometheus can send it as a bearer token.
+LOG_LEVEL=INFO
+METRICS_BEARER_TOKEN=
+GRAFANA_ADMIN_USER=admin
+GRAFANA_ADMIN_PASSWORD=change-me-before-start
+
 # Demo presentation (fictional org identity, badge/manifest, reset safety valve).
 # DEMO_ALLOW_RESET=false permanently disables POST /api/v1/demo/reset (403), independent
 # of role -- a safety valve for any environment where the dataset must not be rebuildable.

PROJECT_STATE.md

@@ -2520,3 +2520,20 @@ evidence yet."
 - Evidence: focused authentication **13 passed with zero warnings**; frontend production
   build passed; ruff clean. Exact next action: implement structured request logging,
   correlation, metrics, dashboards and alerts.
+
+## M22 — operational observability (2026-08-10)
+
+- Added UUID request correlation propagated through response headers, structured API
+  errors and machine-readable JSON request logs. Logs include UTC time, route, method,
+  status, latency and client IP; Docker rotates bounded 10 MB files.
+- Added Prometheus metrics for request rate/status, duration buckets, in-flight requests,
+  database readiness and persisted outbox state separated into real and synthetic
+  scenarios. `/metrics` supports constant-time Bearer protection if exposed beyond the
+  private Compose network.
+- Added an optional pinned Prometheus/Grafana Compose profile, provisioned datasource,
+  six-panel operational dashboard and six validated alert rules. Real failures and
+  backlogs alert; the deliberate demo retry does not.
+- Evidence: focused observability **5 passed without warnings**; ruff/mypy clean;
+  Prometheus `promtool` accepted the scrape config and all six rules; merged Compose and
+  Grafana dashboard JSON validate. Exact next action: automate verified backups,
+  retention and restore-readiness checks.

backend/app/api/routers/observability.py

@@ -0,0 +1,40 @@
+from __future__ import annotations
+
+import hmac
+
+from fastapi import APIRouter, Header, HTTPException
+from fastapi.responses import Response
+from prometheus_client import CONTENT_TYPE_LATEST, generate_latest
+from sqlalchemy import func, select
+
+from app.core.config import get_settings
+from app.core.db import SessionLocal
+from app.core.observability import OUTBOX_EVENTS
+from app.models.outbox import DEMO_SCENARIO_ERROR_CODE, OutboxEvent
+
+router = APIRouter(tags=["observability"])
+settings = get_settings()
+
+
+def _refresh_database_metrics() -> None:
+    with SessionLocal() as db:
+        rows = db.execute(
+            select(
+                OutboxEvent.delivery_status,
+                (OutboxEvent.last_error_code == DEMO_SCENARIO_ERROR_CODE).label("demo"),
+                func.count(),
+            ).group_by(OutboxEvent.delivery_status, "demo")
+        ).all()
+    OUTBOX_EVENTS.clear()
+    for status, is_demo, count in rows:
+        OUTBOX_EVENTS.labels(str(status), "synthetic" if is_demo else "operational").set(count)
+
+
+@router.get("/metrics", include_in_schema=False)
+def metrics(authorization: str | None = Header(default=None)) -> Response:
+    if settings.metrics_bearer_token:
+        supplied = authorization.removeprefix("Bearer ") if authorization else ""
+        if not hmac.compare_digest(supplied, settings.metrics_bearer_token):
+            raise HTTPException(status_code=401, detail="Metrics token required")
+    _refresh_database_metrics()
+    return Response(content=generate_latest(), media_type=CONTENT_TYPE_LATEST)

backend/app/core/config.py

@@ -61,6 +61,8 @@ class Settings(BaseSettings):
     oidc_allowed_email_domains: str = ""
     oidc_auto_provision: bool = True
     oidc_default_role: str = "rental_employee"
+    log_level: str = "INFO"
+    metrics_bearer_token: str = ""
 
 
 @lru_cache

backend/app/core/observability.py

@@ -0,0 +1,94 @@
+from __future__ import annotations
+
+import json
+import logging
+import time
+import uuid
+from contextvars import ContextVar
+from datetime import UTC, datetime
+
+from fastapi import Request
+from prometheus_client import Counter, Gauge, Histogram
+
+correlation_id_context: ContextVar[str] = ContextVar("correlation_id", default="")
+
+HTTP_REQUESTS = Counter(
+    "mobilityops_http_requests_total",
+    "Completed MobilityOps HTTP requests.",
+    ("method", "route", "status"),
+)
+HTTP_DURATION = Histogram(
+    "mobilityops_http_request_duration_seconds",
+    "MobilityOps HTTP request duration.",
+    ("method", "route"),
+    buckets=(0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10),
+)
+HTTP_IN_PROGRESS = Gauge(
+    "mobilityops_http_requests_in_progress",
+    "MobilityOps HTTP requests currently executing.",
+)
+OUTBOX_EVENTS = Gauge(
+    "mobilityops_outbox_events",
+    "Persisted outbox events by state and scenario type.",
+    ("status", "scenario"),
+)
+DATABASE_READY = Gauge(
+    "mobilityops_database_ready",
+    "Whether the canonical PostgreSQL database answered the most recent readiness probe.",
+)
+
+
+class JsonFormatter(logging.Formatter):
+    def format(self, record: logging.LogRecord) -> str:
+        payload: dict[str, object] = {
+            "timestamp": datetime.now(UTC).isoformat(),
+            "level": record.levelname.lower(),
+            "logger": record.name,
+            "message": record.getMessage(),
+        }
+        correlation_id = correlation_id_context.get()
+        if correlation_id:
+            payload["correlation_id"] = correlation_id
+        for key in ("method", "path", "status_code", "duration_ms", "client_ip"):
+            value = getattr(record, key, None)
+            if value is not None:
+                payload[key] = value
+        if record.exc_info:
+            payload["exception"] = self.formatException(record.exc_info)
+        return json.dumps(payload, separators=(",", ":"), default=str)
+
+
+def configure_logging(level: str) -> None:
+    handler = logging.StreamHandler()
+    handler.setFormatter(JsonFormatter())
+    root = logging.getLogger()
+    root.handlers = [handler]
+    root.setLevel(level.upper())
+
+
+def correlation_id_for(request: Request) -> str:
+    candidate = request.headers.get("X-Correlation-Id", "").strip()
+    try:
+        return str(uuid.UUID(candidate)) if candidate else str(uuid.uuid4())
+    except ValueError:
+        return str(uuid.uuid4())
+
+
+def route_label(request: Request) -> str:
+    route = request.scope.get("route")
+    path = getattr(route, "path", None)
+    return str(path or request.url.path)
+
+
+def request_started() -> float:
+    HTTP_IN_PROGRESS.inc()
+    return time.perf_counter()
+
+
+def request_finished(request: Request, status_code: int, started_at: float) -> float:
+    duration = time.perf_counter() - started_at
+    route = route_label(request)
+    HTTP_REQUESTS.labels(request.method, route, str(status_code)).inc()
+    HTTP_DURATION.labels(request.method, route).observe(duration)
+    HTTP_IN_PROGRESS.dec()
+    return duration

backend/app/main.py

@@ -1,3 +1,4 @@
+import logging
 import uuid
 from contextlib import asynccontextmanager
 
@@ -19,6 +20,7 @@ from app.api.routers import (
     integrations,
     knowledge,
     mcp_integrations,
+    observability,
     search,
     users,
     vehicles,
@@ -28,9 +30,19 @@ from app.api.routers.auth import bootstrap_initial_admin
 from app.core.config import PRODUCT_NAME, get_settings
 from app.core.db import SessionLocal
 from app.core.errors import AppError, error_body
+from app.core.observability import (
+    DATABASE_READY,
+    configure_logging,
+    correlation_id_context,
+    correlation_id_for,
+    request_finished,
+    request_started,
+)
 from app.services.dispatcher import start_background_dispatcher, stop_background_dispatcher
 
 settings = get_settings()
+configure_logging(settings.log_level)
+request_logger = logging.getLogger("mobilityops.request")
 
 
 @asynccontextmanager
@@ -53,6 +65,34 @@ app.add_middleware(
     https_only=settings.session_cookie_secure,
 )
 
+
+@app.middleware("http")
+async def request_observability(request: Request, call_next):
+    correlation_id = correlation_id_for(request)
+    request.state.correlation_id = correlation_id
+    token = correlation_id_context.set(correlation_id)
+    started_at = request_started()
+    status_code = 500
+    try:
+        response = await call_next(request)
+        status_code = response.status_code
+        response.headers["X-Correlation-Id"] = correlation_id
+        return response
+    finally:
+        duration = request_finished(request, status_code, started_at)
+        request_logger.info(
+            "request_completed",
+            extra={
+                "method": request.method,
+                "path": request.url.path,
+                "status_code": status_code,
+                "duration_ms": round(duration * 1000, 2),
+                "client_ip": request.client.host if request.client else None,
+            },
+        )
+        correlation_id_context.reset(token)
+
+
 app.add_middleware(
     CORSMiddleware,
     allow_origins=[o.strip() for o in settings.cors_allow_origins.split(",")],
@@ -63,21 +103,26 @@ app.add_middleware(
 
 
 @app.exception_handler(AppError)
-def handle_app_error(_request: Request, exc: AppError) -> JSONResponse:
+def handle_app_error(request: Request, exc: AppError) -> JSONResponse:
     return JSONResponse(
         status_code=exc.status_code,
-        content=error_body(exc.code, exc.message, exc.correlation_id, exc.details),
+        content=error_body(
+            exc.code,
+            exc.message,
+            request.state.correlation_id,
+            exc.details,
+        ),
     )
 
 
 @app.exception_handler(HTTPException)
-def handle_http_exception(_request: Request, exc: HTTPException) -> JSONResponse:
+def handle_http_exception(request: Request, exc: HTTPException) -> JSONResponse:
     return JSONResponse(
         status_code=exc.status_code,
         content=error_body(
             code=str(exc.status_code),
             message=str(exc.detail),
-            correlation_id=str(uuid.uuid4()),
+            correlation_id=getattr(request.state, "correlation_id", str(uuid.uuid4())),
             details={},
         ),
     )
@@ -101,6 +146,8 @@ def readiness() -> JSONResponse:
         with SessionLocal() as db:
             db.execute(text("SELECT 1"))
     except Exception:  # noqa: BLE001 -- readiness must convert infrastructure errors to 503
+        DATABASE_READY.set(0)
+    DATABASE_READY.set(1)
     return JSONResponse(
         status_code=503,
         content={"status": "not_ready", "service": "mobilityops-api", "database": "down"},
@@ -135,3 +182,4 @@ app.include_router(mcp_integrations.router)
 app.include_router(search.router)
 app.include_router(integration_status.router)
 app.include_router(users.router)
+app.include_router(observability.router)

backend/pyproject.toml

@@ -17,7 +17,8 @@ dependencies = [
   "httpx>=0.27,<1",
   "httpx2>=2.10,<3",
   "authlib>=1.6,<2",
-  "itsdangerous>=2.2,<3"
+  "itsdangerous>=2.2,<3",
+  "prometheus-client>=0.24,<1"
 ]
 
 [project.optional-dependencies]

backend/requirements.lock

@@ -76,6 +76,8 @@ pathspec==1.1.1
     # via mypy
 pluggy==1.6.0
     # via pytest
+prometheus-client==0.26.0
+    # via mobilityops-api (pyproject.toml)
 psycopg[binary]==3.3.4
     # via mobilityops-api (pyproject.toml)
 psycopg-binary==3.3.4

backend/tests/test_observability.py

@@ -0,0 +1,51 @@
+import json
+import logging
+import uuid
+
+from app.core.observability import JsonFormatter
+
+
+def test_request_correlation_id_is_echoed_and_used_in_errors(client):
+    correlation_id = str(uuid.uuid4())
+    response = client.get(
+        "/api/v1/dashboard",
+        headers={"X-Correlation-Id": correlation_id},
+    )
+    assert response.status_code == 401
+    assert response.headers["X-Correlation-Id"] == correlation_id
+    assert response.json()["error"]["correlation_id"] == correlation_id
+
+
+def test_invalid_request_correlation_id_is_replaced(client):
+    response = client.get("/health/live", headers={"X-Correlation-Id": "not-a-uuid"})
+    assert response.status_code == 200
+    assert uuid.UUID(response.headers["X-Correlation-Id"])
+
+
+def test_metrics_expose_http_database_and_outbox_state(client):
+    client.get("/health/ready")
+    response = client.get("/metrics")
+    assert response.status_code == 200
+    assert "mobilityops_http_requests_total" in response.text
+    assert "mobilityops_database_ready 1.0" in response.text
+    assert 'mobilityops_outbox_events{scenario="synthetic",status="failed"}' in response.text
+
+
+def test_metrics_token_is_enforced_when_configured(client, monkeypatch):
+    import app.api.routers.observability as router
+
+    monkeypatch.setattr(router.settings, "metrics_bearer_token", "metrics-secret")
+    assert client.get("/metrics").status_code == 401
+    assert (
+        client.get("/metrics", headers={"Authorization": "Bearer metrics-secret"}).status_code
+        == 200
+    )
+
+
+def test_json_formatter_emits_machine_readable_fields():
+    record = logging.LogRecord("mobilityops.test", logging.INFO, __file__, 1, "ready", (), None)
+    record.status_code = 200
+    payload = json.loads(JsonFormatter().format(record))
+    assert payload["message"] == "ready"
+    assert payload["status_code"] == 200
+    assert payload["timestamp"].endswith("+00:00")

compose.observability.yaml

@@ -0,0 +1,38 @@
+services:
+  prometheus:
+    image: prom/prometheus:v3.7.1
+    profiles: ["observability"]
+    command:
+      - --config.file=/etc/prometheus/prometheus.yml
+      - --storage.tsdb.retention.time=30d
+      - --web.enable-lifecycle
+    volumes:
+      - ./deploy/observability/prometheus.yml:/etc/prometheus/prometheus.yml:ro
+      - ./deploy/observability/alerts.yml:/etc/prometheus/alerts.yml:ro
+      - mobilityops-prometheus:/prometheus
+    ports:
+      - "127.0.0.1:19090:9090"
+    restart: unless-stopped
+    networks: [mobilityops]
+
+  grafana:
+    image: grafana/grafana:12.2.0
+    profiles: ["observability"]
+    environment:
+      GF_SECURITY_ADMIN_USER: ${GRAFANA_ADMIN_USER:-admin}
+      GF_SECURITY_ADMIN_PASSWORD: ${GRAFANA_ADMIN_PASSWORD:-change-me-before-start}
+      GF_USERS_ALLOW_SIGN_UP: "false"
+      GF_AUTH_ANONYMOUS_ENABLED: "false"
+    volumes:
+      - ./deploy/observability/grafana/provisioning:/etc/grafana/provisioning:ro
+      - ./deploy/observability/grafana/dashboards:/var/lib/grafana/dashboards:ro
+      - mobilityops-grafana:/var/lib/grafana
+    ports:
+      - "127.0.0.1:13000:3000"
+    depends_on: [prometheus]
+    restart: unless-stopped
+    networks: [mobilityops]
+
+volumes:
+  mobilityops-prometheus:
+  mobilityops-grafana:

compose.yaml

@@ -52,6 +52,13 @@ services:
       OIDC_ALLOWED_EMAIL_DOMAINS: ${OIDC_ALLOWED_EMAIL_DOMAINS:-}
       OIDC_AUTO_PROVISION: ${OIDC_AUTO_PROVISION:-true}
       OIDC_DEFAULT_ROLE: ${OIDC_DEFAULT_ROLE:-rental_employee}
+      LOG_LEVEL: ${LOG_LEVEL:-INFO}
+      METRICS_BEARER_TOKEN: ${METRICS_BEARER_TOKEN:-}
+    logging:
+      driver: json-file
+      options:
+        max-size: "10m"
+        max-file: "5"
     ports:
       - "8128:8000"
     depends_on:

deploy/observability/alerts.yml

@@ -0,0 +1,39 @@
+groups:
+  - name: mobilityops
+    rules:
+      - alert: MobilityOpsApiDown
+        expr: up{job="mobilityops-api"} == 0
+        for: 2m
+        labels: {severity: critical}
+        annotations:
+          summary: MobilityOps API metrics target is down
+      - alert: MobilityOpsDatabaseNotReady
+        expr: mobilityops_database_ready == 0
+        for: 2m
+        labels: {severity: critical}
+        annotations:
+          summary: MobilityOps database readiness is failing
+      - alert: MobilityOpsHighErrorRate
+        expr: sum(rate(mobilityops_http_requests_total{status=~"5.."}[5m])) / clamp_min(sum(rate(mobilityops_http_requests_total[5m])), 0.001) > 0.05
+        for: 10m
+        labels: {severity: warning}
+        annotations:
+          summary: More than 5% of MobilityOps requests return 5xx
+      - alert: MobilityOpsHighLatency
+        expr: histogram_quantile(0.95, sum by (le) (rate(mobilityops_http_request_duration_seconds_bucket[5m]))) > 2
+        for: 10m
+        labels: {severity: warning}
+        annotations:
+          summary: MobilityOps p95 API latency exceeds two seconds
+      - alert: MobilityOpsOutboxBacklog
+        expr: sum(mobilityops_outbox_events{status=~"pending|delivering",scenario="operational"}) > 10
+        for: 10m
+        labels: {severity: warning}
+        annotations:
+          summary: MobilityOps operational outbox backlog exceeds ten events
+      - alert: MobilityOpsOutboxFailure
+        expr: sum(mobilityops_outbox_events{status="failed",scenario="operational"}) > 0
+        for: 2m
+        labels: {severity: critical}
+        annotations:
+          summary: MobilityOps has a real failed outbox event

deploy/observability/grafana/dashboards/mobilityops-overview.json

@@ -0,0 +1,19 @@
+{
+  "annotations": {"list": []},
+  "editable": false,
+  "panels": [
+    {"type":"stat","title":"API target","datasource":{"type":"prometheus","uid":"prometheus"},"targets":[{"expr":"up{job=\"mobilityops-api\"}"}],"gridPos":{"h":6,"w":6,"x":0,"y":0}},
+    {"type":"stat","title":"Database ready","datasource":{"type":"prometheus","uid":"prometheus"},"targets":[{"expr":"mobilityops_database_ready"}],"gridPos":{"h":6,"w":6,"x":6,"y":0}},
+    {"type":"stat","title":"Operational outbox backlog","datasource":{"type":"prometheus","uid":"prometheus"},"targets":[{"expr":"sum(mobilityops_outbox_events{status=~\"pending|delivering\",scenario=\"operational\"})"}],"gridPos":{"h":6,"w":6,"x":12,"y":0}},
+    {"type":"stat","title":"Operational outbox failures","datasource":{"type":"prometheus","uid":"prometheus"},"targets":[{"expr":"sum(mobilityops_outbox_events{status=\"failed\",scenario=\"operational\"})"}],"gridPos":{"h":6,"w":6,"x":18,"y":0}},
+    {"type":"timeseries","title":"Requests per second","datasource":{"type":"prometheus","uid":"prometheus"},"targets":[{"expr":"sum by (status) (rate(mobilityops_http_requests_total[5m]))","legendFormat":"{{status}}"}],"gridPos":{"h":9,"w":12,"x":0,"y":6}},
+    {"type":"timeseries","title":"API latency percentiles","datasource":{"type":"prometheus","uid":"prometheus"},"targets":[{"expr":"histogram_quantile(0.50, sum by (le) (rate(mobilityops_http_request_duration_seconds_bucket[5m])))","legendFormat":"p50"},{"expr":"histogram_quantile(0.95, sum by (le) (rate(mobilityops_http_request_duration_seconds_bucket[5m])))","legendFormat":"p95"}],"gridPos":{"h":9,"w":12,"x":12,"y":6}}
+  ],
+  "schemaVersion": 41,
+  "tags": ["mobilityops"],
+  "templating": {"list": []},
+  "time": {"from":"now-6h","to":"now"},
+  "title": "MobilityOps operational overview",
+  "uid": "mobilityops-overview",
+  "version": 1
+}

deploy/observability/grafana/provisioning/dashboards/mobilityops.yml

@@ -0,0 +1,9 @@
+apiVersion: 1
+providers:
+  - name: MobilityOps
+    folder: MobilityOps
+    type: file
+    disableDeletion: true
+    editable: false
+    options:
+      path: /var/lib/grafana/dashboards

deploy/observability/grafana/provisioning/datasources/prometheus.yml

@@ -0,0 +1,9 @@
+apiVersion: 1
+datasources:
+  - name: Prometheus
+    uid: prometheus
+    type: prometheus
+    access: proxy
+    url: http://prometheus:9090
+    isDefault: true
+    editable: false

deploy/observability/prometheus.yml

@@ -0,0 +1,12 @@
+global:
+  scrape_interval: 15s
+  evaluation_interval: 15s
+
+rule_files:
+  - /etc/prometheus/alerts.yml
+
+scrape_configs:
+  - job_name: mobilityops-api
+    metrics_path: /metrics
+    static_configs:
+      - targets: ["api:8000"]

docs/17-runbook.md

@@ -30,6 +30,30 @@ make test                                  # isolated test project/database, all
 docker compose run --rm api ruff check .   # clean
 ```
 
+## Observability
+
+The API emits one JSON log record per request with UTC timestamp, method, route, status,
+duration, client IP and a UUID correlation ID. A valid incoming `X-Correlation-Id` is
+propagated into the response and API error body; invalid values are replaced. Docker log
+rotation is capped at five 10 MB files.
+
+`GET /metrics` exposes Prometheus request counters, latency histograms, in-flight work,
+database readiness and operational-versus-synthetic outbox state. The endpoint is only
+reachable inside the production Compose network. If it is exposed elsewhere, configure
+`METRICS_BEARER_TOKEN` and send it as a Bearer token.
+
+Start the optional pinned monitoring stack with:
+
+```bash
+docker compose -f compose.yaml -f compose.unraid.yaml -f compose.observability.yaml \
+  --profile observability up -d prometheus grafana
+```
+
+Prometheus listens on host loopback port 19090 and Grafana on loopback port 13000. Set a
+unique `GRAFANA_ADMIN_PASSWORD` before first start. Provisioning includes the MobilityOps
+overview dashboard and alerts for API/database outage, 5xx rate, p95 latency, real outbox
+backlog and real outbox failures. Synthetic retry scenarios never trigger outbox alerts.
+
 Never execute `pytest` inside the deployed API container: the acceptance fixtures reset
 their database deliberately. `make test` uses `compose.test.yaml`, a fixed
 `mobilityops-test` Compose project and its own disposable PostgreSQL volume, and removes