---
phase: 06-performance-production-hardening
plan: 02
type: execute
wave: 1
depends_on:
- 06-01
files_modified:
- backend/requirements.txt
- backend/services/logging.py
- backend/config.py
- backend/main.py
- docker-compose.yml
- docker/loki/loki-config.yaml
- docker/loki/promtail-config.yaml
- backend/tests/test_logging.py
autonomous: true
requirements:
- D-01
- D-02
- D-03
user_setup:
- service: grafana
why: "Local log query UI for Loki"
env_vars: []
dashboard_config:
- task: "Open http://localhost:3000 after compose up; Loki datasource is preconfigured anonymous; Explore → Loki → query {service=\"backend\"}"
location: "Grafana UI → Explore → Loki"
must_haves:
truths:
- "Every HTTP request emits at least one structured JSON log line containing correlation_id, path, method, duration_ms (user_id added by the per-account work in 06-04)"
- "Every HTTP response carries an X-Correlation-ID header matching the bound contextvar"
- "structlog contextvars are cleared at the start of every request — no bleed between requests on the same worker"
- "docker compose up brings up loki, promtail, grafana services that read backend container stdout via the docker_sd label logging=promtail"
- "Setting LOG_JSON=true switches the renderer from ConsoleRenderer to JSONRenderer without code changes"
artifacts:
- path: "backend/services/logging.py"
provides: "setup_logging(json_logs, log_level) — single entry-point for structlog + stdlib bridge"
exports: ["setup_logging"]
min_lines: 40
- path: "backend/main.py"
provides: "CorrelationIDMiddleware raw-ASGI class + setup_logging() call in lifespan + middleware registered LAST"
contains: "class CorrelationIDMiddleware"
- path: "backend/config.py"
provides: "log_level + log_json Settings fields"
contains: "log_level"
- path: "docker-compose.yml"
provides: "loki, promtail, grafana services + loki_data and grafana_data named volumes + logging:promtail label on backend"
contains: "grafana/loki"
- path: "docker/loki/loki-config.yaml"
provides: "single-binary filesystem-mode Loki config (schema v13, tsdb)"
contains: "auth_enabled: false"
- path: "docker/loki/promtail-config.yaml"
provides: "Promtail docker_sd_configs scrape with label filter logging=promtail; ships to http://loki:3100/loki/api/v1/push"
contains: "docker_sd_configs"
key_links:
- from: "backend/main.py CorrelationIDMiddleware"
to: "structlog.contextvars"
via: "clear_contextvars() then bind_contextvars(correlation_id, path, method)"
pattern: "clear_contextvars"
- from: "docker-compose.yml backend.labels.logging"
to: "promtail-config.yaml docker_sd_configs.filters"
via: "label match logging=promtail"
pattern: "logging.*promtail"
- from: "main.py app.add_middleware(CorrelationIDMiddleware)"
to: "Starlette reverse-insertion order"
via: "registered LAST so it runs FIRST"
pattern: "add_middleware\\(CorrelationIDMiddleware"
---
Wire structured JSON logging (D-01) with correlation IDs across every FastAPI request, and stand up a local Loki+Promtail+Grafana log aggregation stack via docker-compose (D-02). Skip OpenTelemetry per D-03. Promote 5 xfail stubs from 06-01 to PASS.
Purpose: Make every request observable end-to-end with a single grep on correlation_id. The Loki stack closes Phase 6 success criterion 2 ("Structured JSON logging is emitted to stdout; a local log aggregation stack captures and queries them").
Output: setup_logging() service module, CorrelationIDMiddleware in main.py, config keys, docker/loki/{loki,promtail}-config.yaml, docker-compose additions, and all 5 logging xfail stubs flipped to PASS.
@$HOME/.claude/get-shit-done/workflows/execute-plan.md
@$HOME/.claude/get-shit-done/templates/summary.md
@.planning/phases/06-performance-production-hardening/06-CONTEXT.md
@.planning/phases/06-performance-production-hardening/06-RESEARCH.md
@.planning/phases/06-performance-production-hardening/06-PATTERNS.md
@.planning/phases/06-performance-production-hardening/06-VALIDATION.md
@CLAUDE.md
@backend/main.py
@backend/config.py
@backend/services/auth.py
@backend/tests/test_logging.py
@docker-compose.yml
From backend/main.py (current lifespan + middleware shape):
- `@asynccontextmanager async def lifespan(app: FastAPI)` — add `setup_logging(json_logs=settings.log_json, log_level=settings.log_level)` as the FIRST statement inside lifespan(), before MinIO/Redis init.
- Existing `app.add_middleware(...)` calls (in order of insertion): SecurityHeadersMiddleware → CORSMiddleware → OriginValidationMiddleware. Starlette runs middleware in REVERSE insertion order. CorrelationIDMiddleware must be registered LAST so it runs FIRST.
From backend/config.py (current Settings class):
- Uses pydantic-settings `Settings(BaseSettings)` with `model_config = SettingsConfigDict(env_file=".env", env_list_separator=",")`. Add new fields with type annotations and defaults; env vars are upper-snake-case of the field name.
From RESEARCH.md Pattern 1 / 2 (target shape):
- `setup_logging(json_logs: bool = False, log_level: str = "INFO") -> None`
- `class CorrelationIDMiddleware:` constructor `__init__(self, app: ASGIApp)` + `async def __call__(self, scope, receive, send)`. NOT BaseHTTPMiddleware.
Task 1: Add structlog dependency + create services/logging.py
backend/requirements.txt, backend/services/logging.py
- backend/requirements.txt
- backend/services/auth.py (module structure analog)
- .planning/phases/06-performance-production-hardening/06-RESEARCH.md (Pattern 1)
- .planning/phases/06-performance-production-hardening/06-PATTERNS.md (services/logging.py section)
- setup_logging(json_logs=True) installs a JSONRenderer in the root logger handler chain.
- setup_logging(json_logs=False) installs ConsoleRenderer.
- shared_processors list places structlog.contextvars.merge_contextvars FIRST.
- Stdlib loggers uvicorn and uvicorn.error propagate through the structlog formatter; uvicorn.access propagate is set to False so the middleware owns request logging.
- Calling setup_logging twice does not duplicate root handlers (idempotent — clear existing handlers before adding).
Append `structlog>=25.5.0` to backend/requirements.txt under a new comment `# Observability (Phase 6 — D-01)`.
Create backend/services/logging.py implementing `setup_logging(json_logs: bool = False, log_level: str = "INFO") -> None`. Module docstring per the services/auth.py analog: `from __future__ import annotations`, import logging + structlog + `from config import settings`, no FastAPI coupling. Build the shared_processors list in this exact order: merge_contextvars, add_log_level, add_logger_name, PositionalArgumentsFormatter, ExtraAdder, TimeStamper(fmt="iso"), StackInfoRenderer. If json_logs True, append format_exc_info to that list. Call structlog.configure(processors=shared+wrap_for_formatter, logger_factory=LoggerFactory, cache_logger_on_first_use=True). Pick JSONRenderer when json_logs else ConsoleRenderer. Build a ProcessorFormatter(foreign_pre_chain=shared, processors=[remove_processors_meta, log_renderer]). Clear existing root logger handlers, add a single StreamHandler with the formatter, set root level to log_level.upper(). For uvicorn and uvicorn.error loggers, clear handlers and set propagate=True. For uvicorn.access, clear handlers and set propagate=False.
cd backend && pip install structlog && python -c "from services.logging import setup_logging; setup_logging(json_logs=True, log_level='INFO'); import structlog; structlog.get_logger().info('hello', user_id='abc')" 2>&1 | grep -E '"event":\s*"hello"'
- `grep -c '^structlog' backend/requirements.txt` returns 1.
- `grep -c 'def setup_logging' backend/services/logging.py` returns 1.
- Module imports cleanly: `cd backend && python -c "from services.logging import setup_logging"` exits 0.
- merge_contextvars appears BEFORE add_log_level in shared_processors: `grep -nE "merge_contextvars|add_log_level" backend/services/logging.py | head -2` shows merge_contextvars first.
- JSON branch emits a JSON-shaped line: `cd backend && python -c "from services.logging import setup_logging; setup_logging(json_logs=True); import structlog; structlog.get_logger().info('e', k=1)" 2>&1 | grep -cE '^\\{.*"event":\\s*"e"'` returns ≥ 1.
- `grep -cE "uvicorn.access.*propagate.*False|propagate.*False.*uvicorn.access" backend/services/logging.py` returns ≥ 1.
structlog installed, setup_logging defined and idempotent, JSON/console branches selectable via boolean parameter.
Task 2: Wire CorrelationIDMiddleware in main.py + add config fields + promote 5 test stubs
backend/main.py, backend/config.py, backend/tests/test_logging.py
- backend/main.py (lines 65–131 — lifespan, middleware registration order)
- backend/config.py (current Settings fields and pattern)
- backend/tests/test_logging.py (the 5 xfail stubs from 06-01 — flip to real assertions)
- .planning/phases/06-performance-production-hardening/06-RESEARCH.md (Pattern 2, Pitfall 2, Anti-Patterns section)
- .planning/phases/06-performance-production-hardening/06-PATTERNS.md (main.py section — "Register LAST")
- GET /health response includes an X-Correlation-ID header that is a UUID4-shaped string.
- Two consecutive requests on the same worker produce two distinct correlation_id values (Pitfall 2 — no contextvars bleed).
- Log lines emitted during a request include correlation_id, path, method, and duration_ms keys.
- clear_contextvars() runs as the first operation inside CorrelationIDMiddleware.__call__ — a contextvar bound by a faked earlier request does not appear in the current request's log.
- CorrelationIDMiddleware is the LAST middleware registered in main.py (Starlette reverse-insertion order makes it run FIRST in the request chain).
Edit backend/config.py to append two fields inside the Settings class after the existing Cloud Storage block, before `settings = Settings()`: `log_level: str = "INFO"` and `log_json: bool = False`. Use the existing comment pattern `# Observability (Phase 6 — D-01)`. Pydantic-settings picks them up automatically as LOG_LEVEL / LOG_JSON env vars.
Edit backend/main.py:
(a) Add imports near the top: `import uuid`, `import time`, `import structlog`, `from starlette.types import ASGIApp, Receive, Scope, Send`, `from services.logging import setup_logging`.
(b) Inside the existing lifespan() function, insert as the FIRST statement (before MinIO client init): `setup_logging(json_logs=settings.log_json, log_level=settings.log_level)`.
(c) Define a new top-level class CorrelationIDMiddleware as raw ASGI — NOT BaseHTTPMiddleware. Constructor `__init__(self, app: ASGIApp) -> None` stores app on self. Async `__call__(self, scope, receive, send) -> None`: if scope type is not "http" delegate to self.app and return; generate correlation_id = str(uuid.uuid4()); capture start_ns = time.perf_counter_ns(); call structlog.contextvars.clear_contextvars() FIRST; then structlog.contextvars.bind_contextvars(correlation_id=correlation_id, path=scope.get("path",""), method=scope.get("method","")); define `async def send_with_header(message)` that on http.response.start appends (b"x-correlation-id", correlation_id.encode()) to message["headers"] (preserve existing headers); await self.app(scope, receive, send_with_header); after await, compute duration_ms = (time.perf_counter_ns() - start_ns) / 1_000_000 and bind_contextvars(duration_ms=round(duration_ms, 2)).
(d) Register the new middleware as the LAST `app.add_middleware()` call (after OriginValidationMiddleware), with a header comment `# 4. CorrelationID — added last so it runs FIRST (Starlette reverse-insertion order)`.
Edit backend/tests/test_logging.py: remove the `@pytest.mark.xfail` decorator from all 5 stubs and replace the single-line `pytest.xfail(...)` body with real assertions matching the behaviour titles set in 06-01. For tests that need a working app, use the existing async_client fixture from conftest.py.
cd backend && pytest tests/test_logging.py -v --no-header 2>&1 | tail -3 | grep -E '5 passed'
- `grep -c "log_level: str" backend/config.py` returns 1 and `grep -c "log_json: bool" backend/config.py` returns 1.
- `grep -c "class CorrelationIDMiddleware" backend/main.py` returns 1.
- `grep -cE "class CorrelationIDMiddleware\\(BaseHTTPMiddleware" backend/main.py` returns 0 (must NOT inherit BaseHTTPMiddleware).
- `grep -nE "app.add_middleware\\(CorrelationIDMiddleware" backend/main.py` returns a line number greater than the line `app.add_middleware(OriginValidationMiddleware)`.
- `grep -c "clear_contextvars" backend/main.py` returns ≥ 1.
- `grep -c "setup_logging" backend/main.py` returns ≥ 2 (one import, one call).
- All 5 tests in backend/tests/test_logging.py PASS: `cd backend && pytest tests/test_logging.py -v --no-header 2>&1 | tail -3` shows "5 passed".
- `grep -c "pytest.mark.xfail" backend/tests/test_logging.py` returns 0 (all xfail markers removed).
- Full backend suite shows no NEW failures versus the 06-01 baseline.
5 test_logging.py tests pass, no regressions, correlation_id flows from middleware to logs to response header, contextvars are cleared per request.
Task 3: Add Loki + Promtail + Grafana stack to docker-compose
docker-compose.yml, docker/loki/loki-config.yaml, docker/loki/promtail-config.yaml
- docker-compose.yml (current backend, celery-worker, celery-beat blocks)
- .planning/phases/06-performance-production-hardening/06-RESEARCH.md (Pattern 6 — Loki/Promtail/Grafana yaml blocks)
- .planning/phases/06-performance-production-hardening/06-PATTERNS.md (docker-compose.yml section)
Create docker/loki/loki-config.yaml per RESEARCH.md Pattern 6 (single-binary filesystem-mode block): auth_enabled false; server http_listen_port 3100, grpc_listen_port 9096; common instance_addr 127.0.0.1, path_prefix /loki, storage.filesystem chunks_directory /loki/chunks rules_directory /loki/rules, replication_factor 1, ring kvstore store inmemory; schema_config configs from 2020-10-24 store tsdb object_store filesystem schema v13 index prefix index_ period 24h; query_range.results_cache.cache.embedded_cache enabled true max_size_mb 100.
Create docker/loki/promtail-config.yaml per RESEARCH.md Pattern 6: server http_listen_port 9080 grpc_listen_port 0; positions filename /tmp/positions.yaml; single clients entry url http://loki:3100/loki/api/v1/push; scrape_configs[0] job_name docker with docker_sd_configs (host unix:///var/run/docker.sock, refresh_interval 5s, filters one entry name=label values=["logging=promtail"]); relabel_configs that map __meta_docker_container_name (regex "/(.*)") to label `container`, and map __meta_docker_container_label_com_docker_compose_service to label `service`.
Edit docker-compose.yml:
(a) Add three new services AFTER the existing celery-beat block, BEFORE the frontend service. Service `loki` (image grafana/loki:latest, ports "3100:3100", volumes ./docker/loki/loki-config.yaml:/etc/loki/local-config.yaml + loki_data:/loki, command "-config.file=/etc/loki/local-config.yaml"). Service `promtail` (image grafana/promtail:latest, volumes ./docker/loki/promtail-config.yaml:/etc/promtail/config.yaml + /var/lib/docker/containers:/var/lib/docker/containers:ro + /var/run/docker.sock:/var/run/docker.sock, command "-config.file=/etc/promtail/config.yaml", depends_on loki). Service `grafana` (image grafana/grafana:latest, ports "3000:3000", environment GF_AUTH_ANONYMOUS_ENABLED=true GF_AUTH_ANONYMOUS_ORG_ROLE=Admin, volumes grafana_data:/var/lib/grafana, depends_on loki).
(b) Append `loki_data:` and `grafana_data:` entries under the existing top-level `volumes:` block.
(c) Add a `labels:` map to the backend service block containing `logging: "promtail"` so promtail's docker_sd label filter matches.
(d) Add the same `logging: "promtail"` label to the celery-worker service block.
(e) Add `LOG_LEVEL=${LOG_LEVEL:-INFO}` and `LOG_JSON=${LOG_JSON:-false}` to the backend service environment block.
Do NOT modify celery-beat (it remains unhardened per Pitfall 7; it will not ship logs via promtail in this phase because that requires read-only safety considerations deferred to a later phase).
test -f docker/loki/loki-config.yaml && test -f docker/loki/promtail-config.yaml && python -c "import yaml; [yaml.safe_load(open(f)) for f in ['docker-compose.yml','docker/loki/loki-config.yaml','docker/loki/promtail-config.yaml']]" && docker compose config --quiet
- All three YAML files parse without error: `python -c "import yaml; [yaml.safe_load(open(f)) for f in ['docker-compose.yml','docker/loki/loki-config.yaml','docker/loki/promtail-config.yaml']]"` exits 0.
- `grep -c 'grafana/loki' docker-compose.yml` returns 1.
- `grep -c 'grafana/promtail' docker-compose.yml` returns 1.
- `grep -c 'grafana/grafana' docker-compose.yml` returns 1.
- `grep -cE 'logging:\\s*"?promtail"?' docker-compose.yml` returns ≥ 2 (backend + celery-worker).
- `grep -c '^ loki_data:' docker-compose.yml` returns 1 and `grep -c '^ grafana_data:' docker-compose.yml` returns 1.
- `grep -c 'LOG_JSON' docker-compose.yml` returns ≥ 1.
- `grep -c 'schema:\\s*v13' docker/loki/loki-config.yaml` returns 1.
- `grep -c 'docker_sd_configs' docker/loki/promtail-config.yaml` returns 1.
- `docker compose config --quiet` exits 0 (compose file is valid).
- celery-beat block contains NO `logging:` label and NO `read_only:` key — `awk '/^ celery-beat:/,/^ [a-z]/' docker-compose.yml | grep -cE 'logging:|read_only:'` returns 0.
Loki stack defined in compose, two backend services labelled for promtail scraping, all yaml validates, celery-beat untouched.
## Trust Boundaries
| Boundary | Description |
|----------|-------------|
| Untrusted user input → log fields | User-controlled strings (path, query params, body) may attempt log injection |
| Backend stdout → Promtail → Loki | Internal-only network; no external exposure |
| Grafana UI :3000 → local network | Anonymous admin enabled for local dev only — production hardening deferred (see RUNBOOK.md in 06-06) |
## STRIDE Threat Register
| Threat ID | Category | Component | Disposition | Mitigation Plan |
|-----------|----------|-----------|-------------|-----------------|
| T-06-02-01 | Tampering | Log injection via user-controlled strings in log fields | mitigate | structlog JSONRenderer serialises values as JSON strings — newlines and quotes are escaped automatically; no `%s` format strings concatenate user input |
| T-06-02-02 | Information Disclosure | structlog contextvars leaking user_id across requests | mitigate | clear_contextvars() is the FIRST call inside CorrelationIDMiddleware.__call__; verified by test_contextvars_cleared_between_requests in 06-01/06-02 |
| T-06-02-03 | Information Disclosure | Grafana anonymous admin exposes Loki query UI to anyone on the docker network | accept | Local dev convenience; RUNBOOK.md (06-06) documents production-time hardening (disable anonymous, add Grafana auth) |
| T-06-02-04 | Denial of Service | Loki disk fill via unbounded log retention | accept | Single-binary filesystem mode; RUNBOOK.md documents log rotation and retention tuning for production |
- 5 tests in backend/tests/test_logging.py PASS (no XFAIL).
- `grep -c "class CorrelationIDMiddleware" backend/main.py` returns 1.
- CorrelationIDMiddleware does NOT inherit BaseHTTPMiddleware.
- `docker compose config --quiet` exits 0.
- celery-beat block has neither `logging:` label nor `read_only:` key.
- All 3 YAML files (compose, loki-config, promtail-config) parse without error.
- D-01 satisfied: setup_logging emits JSON when LOG_JSON=true; correlation_id appears in every log line; X-Correlation-ID header on every response.
- D-02 satisfied: docker compose up brings loki on :3100, grafana on :3000, promtail scrapes containers labelled logging=promtail.
- D-03 satisfied: no opentelemetry dependency added, no tracing middleware introduced.
- Zero new failing tests; the 5 logging xfails from 06-01 now PASS.