curo1305
abe8f8ee90
- backend/config.py: add log_level: str = "INFO" and log_json: bool = False fields under Observability (Phase 6 — D-01) comment; pydantic-settings reads LOG_LEVEL / LOG_JSON env vars automatically - backend/main.py: add imports (uuid, time, structlog, ASGIApp/Receive/Scope/Send, setup_logging); add CorrelationIDMiddleware raw-ASGI class (NOT BaseHTTPMiddleware — avoids streaming buffering); call setup_logging() as first lifespan statement; register CorrelationIDMiddleware LAST so it runs FIRST (Starlette reverse order) - backend/tests/test_logging.py: remove all 5 xfail decorators; replace single-line bodies with real assertions for JSON renderer, contextvar binding, X-Correlation-ID header, no-bleed between requests, uvicorn.access propagate=False
109 lines
4.8 KiB
Python
109 lines
4.8 KiB
Python
"""
|
|
Structured logging tests — D-01, D-02.
|
|
|
|
Promoted from xfail scaffold (06-01) to real assertions by plan 06-02.
|
|
"""
|
|
from __future__ import annotations
|
|
|
|
import logging
|
|
|
|
import pytest
|
|
import structlog
|
|
|
|
|
|
# ── D-01: JSON renderer wired through ProcessorFormatter ─────────────────────
|
|
|
|
async def test_setup_logging_emits_json_when_LOG_JSON_true(capsys):
|
|
"""setup_logging(json_logs=True) installs JSONRenderer through
|
|
ProcessorFormatter and the root logger emits JSON to stdout."""
|
|
from services.logging import setup_logging
|
|
|
|
setup_logging(json_logs=True, log_level="INFO")
|
|
structlog.get_logger("test").info("probe_event", check_key="check_value")
|
|
|
|
captured = capsys.readouterr()
|
|
output = captured.err # logging.StreamHandler writes to stderr by default
|
|
assert '"event"' in output, f"Expected JSON with 'event' key, got: {output!r}"
|
|
assert "probe_event" in output, f"Expected 'probe_event' in output, got: {output!r}"
|
|
|
|
|
|
# ── D-02: CorrelationIDMiddleware binds structlog contextvars ─────────────────
|
|
|
|
async def test_correlation_id_middleware_binds_contextvar(async_client):
|
|
"""CorrelationIDMiddleware binds correlation_id, path, and method into
|
|
structlog.contextvars for every inbound HTTP request."""
|
|
# Make a request — if the middleware is wired, structlog contextvars are
|
|
# bound. We verify indirectly by checking the X-Correlation-ID header
|
|
# (the middleware also sets that from the same correlation_id it binds).
|
|
response = await async_client.get("/health")
|
|
assert response.status_code == 200
|
|
assert "x-correlation-id" in response.headers, (
|
|
"X-Correlation-ID header missing — CorrelationIDMiddleware may not be "
|
|
"registered or may not be binding contextvars correctly."
|
|
)
|
|
cid = response.headers["x-correlation-id"]
|
|
# UUID4 format: 8-4-4-4-12 hex chars
|
|
import re
|
|
assert re.match(
|
|
r"^[0-9a-f]{8}-[0-9a-f]{4}-4[0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$",
|
|
cid,
|
|
), f"correlation_id is not a UUID4: {cid!r}"
|
|
|
|
|
|
async def test_correlation_id_response_header_present(async_client):
|
|
"""Every HTTP response includes an X-Correlation-ID header set to the
|
|
correlation_id bound by CorrelationIDMiddleware."""
|
|
r1 = await async_client.get("/health")
|
|
r2 = await async_client.get("/health")
|
|
|
|
assert "x-correlation-id" in r1.headers, "First request missing X-Correlation-ID"
|
|
assert "x-correlation-id" in r2.headers, "Second request missing X-Correlation-ID"
|
|
|
|
cid1 = r1.headers["x-correlation-id"]
|
|
cid2 = r2.headers["x-correlation-id"]
|
|
|
|
# Each request must receive its own unique correlation ID
|
|
assert cid1 != cid2, (
|
|
f"Both requests received the same correlation_id ({cid1!r}) — "
|
|
"CorrelationIDMiddleware is not generating a fresh UUID per request."
|
|
)
|
|
|
|
|
|
async def test_contextvars_cleared_between_requests(async_client):
|
|
"""Pitfall 2 guard: clear_contextvars() runs first in the middleware so
|
|
user_id from a prior request never bleeds into the next request's log context."""
|
|
# Manually bind a sentinel value into structlog contextvars to simulate
|
|
# a "leftover" context from a previous request.
|
|
structlog.contextvars.bind_contextvars(sentinel_bleed_test="should_not_appear")
|
|
|
|
# Make a new request — CorrelationIDMiddleware must clear_contextvars() first.
|
|
response = await async_client.get("/health")
|
|
assert response.status_code == 200
|
|
|
|
# After the request, the middleware has run clear_contextvars(). The sentinel
|
|
# we pre-bound should have been wiped. Verify by checking that the contextvars
|
|
# map no longer contains our sentinel (it may contain new keys bound by the
|
|
# middleware itself, e.g. correlation_id, path, method).
|
|
ctx = structlog.contextvars.get_contextvars()
|
|
assert "sentinel_bleed_test" not in ctx, (
|
|
f"Bleed detected: 'sentinel_bleed_test' still in contextvars after request. "
|
|
f"clear_contextvars() may not be running as the first middleware operation. "
|
|
f"Context: {ctx}"
|
|
)
|
|
|
|
|
|
# ── D-01 / uvicorn log suppression ───────────────────────────────────────────
|
|
|
|
async def test_uvicorn_access_log_suppressed():
|
|
"""uvicorn.access propagate=False after setup_logging() so the
|
|
CorrelationIDMiddleware owns request logging and access lines are not doubled."""
|
|
from services.logging import setup_logging
|
|
|
|
setup_logging(json_logs=False, log_level="INFO")
|
|
access_logger = logging.getLogger("uvicorn.access")
|
|
assert access_logger.propagate is False, (
|
|
"uvicorn.access.propagate should be False after setup_logging() to prevent "
|
|
"duplicate request log lines. Currently: "
|
|
f"propagate={access_logger.propagate}"
|
|
)
|