kite/.planning/phases/06-performance-production-hardening/06-02-SUMMARY.md

phase, plan, subsystem, tags, dependency_graph, tech_stack, key_files, decisions, metrics

phase	plan	subsystem	tags	dependency_graph	tech_stack	key_files	decisions	metrics
06-performance-production-hardening	02	observability/logging/infrastructure	wave-1 structlog loki promtail grafana correlation-id middleware	requires provides affects 06-01: xfail stubs in test_logging.py 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 docker-compose.yml — loki/promtail/grafana services + labels on backend/celery-worker backend/config.py — log_level, log_json settings fields	added patterns 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) 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	created modified backend/services/logging.py docker/loki/loki-config.yaml docker/loki/promtail-config.yaml backend/requirements.txt backend/config.py backend/main.py docker-compose.yml backend/tests/test_logging.py	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)	duration completed tasks_completed files_created files_modified ~15m 2026-06-03 3 3 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):

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