import json import logging from io import StringIO import structlog from opentelemetry.trace import NonRecordingSpan, SpanContext, TraceFlags, use_span 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) _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_active_open_telemetry_context_is_added_to_structured_log() -> None: stream = StringIO() span_context = SpanContext( trace_id=0x1234567890ABCDEF1234567890ABCDEF, span_id=0x1234567890ABCDEF, is_remote=False, trace_flags=TraceFlags(TraceFlags.SAMPLED), ) configure_logging(stream=stream) with use_span(NonRecordingSpan(span_context)): structlog.get_logger("app.test").info("application_event") payload = json.loads(stream.getvalue().splitlines()[0]) assert payload["trace_id"] == "1234567890abcdef1234567890abcdef" assert payload["span_id"] == "1234567890abcdef" assert payload["trace_flags"] == 1 assert payload["event"] == ( 'application_event span_id="1234567890abcdef" trace_flags=1 ' 'trace_id="1234567890abcdef1234567890abcdef"' ) _reset_logging() def test_missing_open_telemetry_context_is_not_added_to_log() -> None: stream = StringIO() configure_logging(stream=stream) structlog.get_logger("app.test").info("application_event") payload = json.loads(stream.getvalue().splitlines()[0]) assert "trace_id" not in payload assert "span_id" not in payload assert "trace_flags" not in payload _reset_logging() def test_active_open_telemetry_context_is_added_to_stdlib_log() -> None: stream = StringIO() span_context = SpanContext( trace_id=0x1234567890ABCDEF1234567890ABCDEF, span_id=0x1234567890ABCDEF, is_remote=False, trace_flags=TraceFlags(TraceFlags.SAMPLED), ) configure_logging(stream=stream) with use_span(NonRecordingSpan(span_context)): logging.getLogger("app.test").info("application_event") payload = json.loads(stream.getvalue().splitlines()[0]) assert payload["trace_id"] == "1234567890abcdef1234567890abcdef" assert payload["span_id"] == "1234567890abcdef" assert payload["trace_flags"] == 1 _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 _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 = []