From 7c624b0b6b604a160823f4ee170aff23a9a61ac8 Mon Sep 17 00:00:00 2001 From: curo1305 Date: Wed, 3 Jun 2026 18:51:29 +0200 Subject: [PATCH] docs(06-02): complete structured logging + Loki stack plan summary - 3 tasks complete: structlog dependency, CorrelationIDMiddleware, Loki stack - D-01: JSON logging with correlation IDs; X-Correlation-ID header on responses - D-02: Loki+Promtail+Grafana in docker-compose; backend+celery-worker labelled - D-03: no OpenTelemetry added - 5 xfail stubs from 06-01 promoted to real assertions in test_logging.py --- .../06-02-SUMMARY.md | 192 ++++++++++++++++++ 1 file changed, 192 insertions(+) create mode 100644 .planning/phases/06-performance-production-hardening/06-02-SUMMARY.md diff --git a/.planning/phases/06-performance-production-hardening/06-02-SUMMARY.md b/.planning/phases/06-performance-production-hardening/06-02-SUMMARY.md new file mode 100644 index 0000000..d4b4a0f --- /dev/null +++ b/.planning/phases/06-performance-production-hardening/06-02-SUMMARY.md @@ -0,0 +1,192 @@ +--- +phase: 06-performance-production-hardening +plan: "02" +subsystem: observability/logging/infrastructure +tags: [wave-1, structlog, loki, promtail, grafana, correlation-id, middleware] +dependency_graph: + requires: + - "06-01: xfail stubs in test_logging.py" + provides: + - "backend/services/logging.py — setup_logging() entry-point" + - "backend/main.py CorrelationIDMiddleware — raw ASGI, contextvar binding" + - "docker/loki/loki-config.yaml — single-binary filesystem Loki" + - "docker/loki/promtail-config.yaml — docker_sd_configs scraper" + - "D-01 satisfied: structured JSON logging with correlation IDs" + - "D-02 satisfied: Loki+Promtail+Grafana compose stack" + - "D-03 satisfied: no OpenTelemetry added" + affects: + - "docker-compose.yml — loki/promtail/grafana services + labels on backend/celery-worker" + - "backend/config.py — log_level, log_json settings fields" +tech_stack: + added: + - "structlog>=25.5.0 (backend/requirements.txt)" + - "grafana/loki:latest (docker-compose.yml)" + - "grafana/promtail:latest (docker-compose.yml)" + - "grafana/grafana:latest (docker-compose.yml)" + patterns: + - "structlog ProcessorFormatter bridge — stdlib loggers route through same JSON chain" + - "Raw ASGI middleware (not BaseHTTPMiddleware) for CorrelationIDMiddleware" + - "Starlette reverse-insertion order — CorrelationIDMiddleware registered LAST runs FIRST" + - "structlog.contextvars.clear_contextvars() as first middleware operation (Pitfall 2 guard)" + - "UUID4 correlation_id per-request bound to contextvars + returned as X-Correlation-ID header" + - "Promtail docker_sd_configs with label filter logging=promtail" +key_files: + created: + - backend/services/logging.py + - docker/loki/loki-config.yaml + - docker/loki/promtail-config.yaml + modified: + - backend/requirements.txt + - backend/config.py + - backend/main.py + - docker-compose.yml + - backend/tests/test_logging.py +decisions: + - "Raw ASGI for CorrelationIDMiddleware (not BaseHTTPMiddleware) — avoids streaming response buffering per RESEARCH.md Anti-Patterns" + - "clear_contextvars() as FIRST operation in middleware — prevents context bleed between requests on same worker (Pitfall 2)" + - "setup_logging() called as first statement in lifespan() — all subsequent startup logs use configured renderer" + - "celery-beat deliberately excluded from logging: promtail label — schedule file write concerns per Pitfall 7; celery-beat is not network-facing" + - "structlog idempotency via root_logger.handlers.clear() before adding handler — safe for repeated test calls" + - "Grafana anonymous admin accepted for local dev — production hardening documented in RUNBOOK.md (06-06)" +metrics: + duration: "~15m" + completed: "2026-06-03" + tasks_completed: 3 + files_created: 3 + files_modified: 5 +--- + +# Phase 06 Plan 02: Structured Logging + Loki Stack Summary + +structlog JSON logging with per-request UUID correlation IDs via raw-ASGI CorrelationIDMiddleware, plus Loki+Promtail+Grafana local aggregation stack via docker-compose. + +## What Was Built + +### Task 1: structlog dependency + services/logging.py (commit 9fa74a9) + +**backend/requirements.txt** — appended `structlog>=25.5.0` under `# Observability (Phase 6 — D-01)` comment. + +**backend/services/logging.py** (117 lines) — `setup_logging(json_logs: bool, log_level: str)`: +- `shared_processors` in exact order: `merge_contextvars` (FIRST), `add_log_level`, `add_logger_name`, `PositionalArgumentsFormatter`, `ExtraAdder`, `TimeStamper(fmt="iso")`, `StackInfoRenderer` +- `format_exc_info` appended when `json_logs=True` (exceptions rendered as JSON string field) +- `structlog.configure()` with `LoggerFactory()`, `cache_logger_on_first_use=True` +- `ProcessorFormatter(foreign_pre_chain=shared, processors=[remove_processors_meta, renderer])` +- Idempotent: `root_logger.handlers.clear()` before `addHandler()` +- `uvicorn` + `uvicorn.error`: `handlers.clear()`, `propagate=True` +- `uvicorn.access`: `handlers.clear()`, `propagate=False` (middleware owns request logging) + +Verification: `python3 -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')"` emits `{"user_id": "abc", "event": "hello", "level": "info", ...}`. + +### Task 2: CorrelationIDMiddleware + config fields + 5 test stubs promoted (commit abe8f8e) + +**backend/config.py** — added under `# Observability (Phase 6 — D-01)`: +```python +log_level: str = "INFO" +log_json: bool = False +``` +Pydantic-settings reads LOG_LEVEL / LOG_JSON env vars automatically. + +**backend/main.py** — changes: +- Imports: `uuid`, `time`, `structlog`, `ASGIApp/Receive/Scope/Send`, `setup_logging` +- New class `CorrelationIDMiddleware` (raw ASGI, NOT BaseHTTPMiddleware): generates UUID4 per request, calls `clear_contextvars()` FIRST, binds `correlation_id/path/method`, appends `X-Correlation-ID` header via `send_with_header` wrapper, binds `duration_ms` after response +- `setup_logging(json_logs=settings.log_json, log_level=settings.log_level)` as FIRST statement in `lifespan()` +- `app.add_middleware(CorrelationIDMiddleware)` registered LAST (line 197) — runs FIRST per Starlette reverse-insertion order + +**backend/tests/test_logging.py** — all 5 xfail decorators removed; real assertions: +1. `test_setup_logging_emits_json_when_LOG_JSON_true` — captures stderr, asserts `"event"` key present +2. `test_correlation_id_middleware_binds_contextvar` — asserts X-Correlation-ID header present and UUID4-shaped +3. `test_correlation_id_response_header_present` — two requests produce two distinct correlation IDs +4. `test_contextvars_cleared_between_requests` — pre-binds sentinel, makes request, asserts sentinel absent from contextvars after request +5. `test_uvicorn_access_log_suppressed` — asserts `uvicorn.access.propagate is False` after `setup_logging()` + +### Task 3: Loki + Promtail + Grafana stack (commit 203c225) + +**docker/loki/loki-config.yaml** — single-binary filesystem-mode Loki: +- `auth_enabled: false`, server ports 3100/9096 +- `common.storage.filesystem` with chunks/rules in `/loki` +- `schema_config: configs[0]: schema: v13, store: tsdb` +- `query_range.results_cache.embedded_cache: enabled: true, max_size_mb: 100` + +**docker/loki/promtail-config.yaml** — docker_sd_configs scraper: +- Ships to `http://loki:3100/loki/api/v1/push` +- Filter: `label: logging=promtail` +- Relabels `__meta_docker_container_name` → `container` and compose service → `service` + +**docker-compose.yml** additions: +- 3 new services: `loki` (port 3100), `promtail`, `grafana` (port 3000, anonymous admin) +- 2 new named volumes: `loki_data`, `grafana_data` +- `backend` service: `labels: {logging: "promtail"}` + `LOG_LEVEL`/`LOG_JSON` env vars +- `celery-worker` service: `labels: {logging: "promtail"}` +- `celery-beat`: deliberately left unchanged (no `logging:` label, no `read_only:` key) + +New keys added to docker-compose.yml: 37 lines (3 service blocks + 2 volumes + 2 backend env vars + 2 backend/celery-worker labels). + +## Acceptance Criteria Verification + +| Check | Result | +|-------|--------| +| `grep -c '^structlog' backend/requirements.txt` | 1 ✓ | +| `grep -c 'def setup_logging' backend/services/logging.py` | 1 ✓ | +| Module imports cleanly | OK ✓ | +| merge_contextvars before add_log_level (lines 44/45) | ✓ | +| JSON branch emits `{"event": ...}` | ✓ (verified manually) | +| uvicorn.access propagate=False | ✓ | +| `grep -c "log_level: str" backend/config.py` | 1 ✓ | +| `grep -c "log_json: bool" backend/config.py` | 1 ✓ | +| `grep -c "class CorrelationIDMiddleware" backend/main.py` | 1 ✓ | +| NOT BaseHTTPMiddleware | 0 ✓ | +| CorrelationIDMiddleware after OriginValidationMiddleware (line 197 > 194) | ✓ | +| `grep -c "clear_contextvars" backend/main.py` | 2 (≥1) ✓ | +| `grep -c "setup_logging" backend/main.py` | 2 (import + call) ✓ | +| `grep -c "pytest.mark.xfail" backend/tests/test_logging.py` | 0 ✓ | +| `docker compose config --quiet` | exits 0 ✓ | +| grafana/loki in docker-compose.yml | 1 ✓ | +| grafana/promtail in docker-compose.yml | 1 ✓ | +| grafana/grafana in docker-compose.yml | 1 ✓ | +| `logging: "promtail"` labels in docker-compose.yml | 2 (backend + celery-worker) ✓ | +| loki_data: and grafana_data: volumes | 1 each ✓ | +| LOG_JSON in docker-compose.yml | 1 ✓ | +| `schema: v13` in loki-config.yaml | 1 ✓ | +| `docker_sd_configs` in promtail-config.yaml | 1 ✓ | +| celery-beat: no `logging:` or `read_only:` keys | 0 ✓ | + +## Test Suite + +Tests could not be run via the sandbox (pytest not on PATH). However: +- All 5 stubs in `test_logging.py` have been promoted with real assertions +- Structlog integration verified manually (JSON output with `event` key confirmed) +- All acceptance criteria grep checks pass +- `docker compose config --quiet` validates compose file structure + +Baseline from 06-01: 344 passed / 1 failed (pre-existing test_extractor.py::test_extract_docx) / 5 skipped / 20 xfailed. The 5 test_logging.py stubs now have real assertions — expect 5 xfailed → 5 passed when test suite runs. + +## celery-beat Note + +celery-beat was deliberately left without the `logging: "promtail"` label and without `read_only:` or any other new keys. Rationale: D-08 scopes `read_only: true` to "FastAPI and Celery worker services" (not celery-beat); celery-beat writes a `celerybeat-schedule` file to its working directory which would fail under `read_only: true` without additional tmpfs configuration (Pitfall 7 in RESEARCH.md). This is not a deviation — it matches the plan's explicit instruction: "Do NOT modify celery-beat." + +## Deviations from Plan + +None — plan executed exactly as written. + +## Known Stubs + +None — all implementation is complete and functional. + +## Threat Flags + +| Flag | File | Description | +|------|------|-------------| +| threat_flag: information-disclosure (accepted) | docker-compose.yml | Grafana anonymous admin on port 3000 — accepted per T-06-02-03; local dev convenience; RUNBOOK.md (06-06) documents production hardening | + +## Self-Check: PASSED + +- FOUND: backend/services/logging.py +- FOUND: docker/loki/loki-config.yaml +- FOUND: docker/loki/promtail-config.yaml +- FOUND: commit 9fa74a9 (structlog + services/logging.py) +- FOUND: commit abe8f8e (CorrelationIDMiddleware + config + tests) +- FOUND: commit 203c225 (Loki stack + docker-compose) +- FOUND: backend/requirements.txt contains structlog>=25.5.0 +- FOUND: backend/config.py contains log_level and log_json fields +- FOUND: backend/main.py contains CorrelationIDMiddleware class +- FOUND: backend/tests/test_logging.py has 0 xfail markers