import json import logging from io import StringIO import structlog from opentelemetry import trace from opentelemetry.trace import NonRecordingSpan, SpanContext, TraceFlags from app.runtime.logging import configure_logging def test_application_log_is_serialized_as_json() -> None: stream = StringIO() configure_logging(stream=stream) logging.getLogger("app.test").info("application_event") payload = json.loads(stream.getvalue().splitlines()[0]) assert payload["event"] == "application_event" assert payload["level"] == "info" assert payload["logger"] == "app.test" assert isinstance(payload["timestamp"], str) assert "trace_id" not in payload assert "span_id" not in payload _reset_logging() def test_structured_context_is_preserved_and_rendered_in_event() -> None: stream = StringIO() configure_logging(stream=stream) structlog.get_logger("app.test").warning( "application_event", order_uuid="order-1", attempt=2, retryable=True, details={"code": "invalid"}, ) payload = json.loads(stream.getvalue().splitlines()[0]) assert payload["event"] == ( 'application_event attempt=2 details={"code":"invalid"} ' 'order_uuid="order-1" retryable=true' ) assert payload["order_uuid"] == "order-1" assert payload["attempt"] == 2 assert payload["retryable"] is True assert payload["details"] == {"code": "invalid"} _reset_logging() def test_uvicorn_loggers_use_shared_json_logging_setup() -> None: stream = StringIO() configure_logging(stream=stream) logging.getLogger("uvicorn.error").error("uvicorn_error_event") logging.getLogger("uvicorn.access").info("uvicorn_access_event") records = [json.loads(line) for line in stream.getvalue().splitlines()] assert [record["event"] for record in records] == [ "uvicorn_error_event", "uvicorn_access_event", ] assert [record["logger"] for record in records] == [ "uvicorn.error", "uvicorn.access", ] assert all(record["level"] in {"error", "info"} for record in records) assert all(isinstance(record["timestamp"], str) for record in records) _reset_logging() def test_active_trace_context_is_added_to_structlog_and_standard_logs() -> None: stream = StringIO() trace_id = 0x1234567890ABCDEF1234567890ABCDEF span_id = 0x1234567890ABCDEF span = NonRecordingSpan( SpanContext( trace_id=trace_id, span_id=span_id, is_remote=False, trace_flags=TraceFlags.SAMPLED, ) ) configure_logging(stream=stream) with trace.use_span(span, end_on_exit=False): structlog.get_logger("app.test").info("structured_event") logging.getLogger("app.test").info("standard_event") records = [json.loads(line) for line in stream.getvalue().splitlines()] expected_trace_id = "1234567890abcdef1234567890abcdef" expected_span_id = "1234567890abcdef" assert [record["trace_id"] for record in records] == [ expected_trace_id, expected_trace_id, ] assert [record["span_id"] for record in records] == [ expected_span_id, expected_span_id, ] assert records[0]["event"] == ( f'structured_event span_id="{expected_span_id}" ' f'trace_id="{expected_trace_id}"' ) assert records[1]["event"] == ( f'standard_event span_id="{expected_span_id}" ' f'trace_id="{expected_trace_id}"' ) _reset_logging() def _reset_logging() -> None: structlog.reset_defaults() root_logger = logging.getLogger() root_logger.handlers = [] for logger_name in ("uvicorn", "uvicorn.error", "uvicorn.access"): logging.getLogger(logger_name).handlers = []