""" 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}" )