Open http://localhost:3000 after compose up; Loki datasource is preconfigured anonymous; Explore → Loki → query {service="backend"}
Grafana UI → Explore → Loki
truths
artifacts
key_links
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
path
provides
exports
min_lines
backend/services/logging.py
setup_logging(json_logs, log_level) — single entry-point for structlog + stdlib bridge
setup_logging
40
path
provides
contains
backend/main.py
CorrelationIDMiddleware raw-ASGI class + setup_logging() call in lifespan + middleware registered LAST
class CorrelationIDMiddleware
path
provides
contains
backend/config.py
log_level + log_json Settings fields
log_level
path
provides
contains
docker-compose.yml
loki, promtail, grafana services + loki_data and grafana_data named volumes + logging:promtail label on backend
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.
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.
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.
<threat_model>
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
</threat_model>
- 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.
<success_criteria>
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.
</success_criteria>
Create `.planning/phases/06-performance-production-hardening/06-02-SUMMARY.md` when done. Include: full-suite pytest summary, exact lines added to docker-compose.yml (count of new keys), and a one-line note confirming celery-beat was deliberately left untouched.
