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
This commit is contained in:
curo1305
@@ -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
|
||||
Reference in New Issue
Block a user