From 18916fd0174e0f1b1281b0aeefa29191d6fa1105 Mon Sep 17 00:00:00 2001 From: febux Date: Fri, 4 Sep 2026 00:26:18 +0300 Subject: [PATCH] Connect structlog to OTLP processer. --- docker-compose.yml | 5 +- src/contract_check/core/logging.py | 21 +++++--- src/contract_check/core/telemetry.py | 47 +++++++++++++++-- tests/unit/test_telemetry.py | 76 ++++++++++++++++++++++++++++ 4 files changed, 136 insertions(+), 13 deletions(-) create mode 100644 tests/unit/test_telemetry.py diff --git a/docker-compose.yml b/docker-compose.yml index b2b94a5..6a8a188 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -392,8 +392,9 @@ services: # Use for production-grade visibility. # # App services send OTLP traces/metrics/logs to the endpoint configured in - # OTEL_EXPORTER_OTLP_ENDPOINT (.env). Point it at openobserve:5081 for the - # lightweight profile, or at your own otel-collector/tempo for the obs profile. + # OTEL_EXPORTER_OTLP_ENDPOINT (.env). Point it at openobserve:5080/api/default + # for the lightweight profile (the app uses OTLP/HTTP exporters), or at your + # own otel-collector/tempo for the obs profile. # ── LIGHTWEIGHT OBSERVABILITY (profile: observer) ─────────────────────────── openobserve: diff --git a/src/contract_check/core/logging.py b/src/contract_check/core/logging.py index c38a0d4..9cfaba2 100644 --- a/src/contract_check/core/logging.py +++ b/src/contract_check/core/logging.py @@ -166,11 +166,15 @@ def configure_logging( json_output=True (staging/prod) → JSON renderer; False (dev) → colored console. service and env are bound globally so every log line carries them. + + Structlog is routed through the stdlib logging tree so that OpenTelemetry + handlers attached later (see ``core/telemetry.py``) capture application + logs with their structured fields. """ set_service(service) set_env(env) - processors: list[structlog.types.Processor] = [ + shared_processors: list[structlog.types.Processor] = [ structlog.contextvars.merge_contextvars, structlog.processors.add_log_level, structlog.processors.TimeStamper(fmt="iso", utc=True), @@ -180,25 +184,26 @@ def configure_logging( _format_exc_info, _filter_sensitive_keys, ] - processors.append( + renderer: structlog.types.Processor = ( structlog.processors.JSONRenderer(sort_keys=True) if json_output else structlog.dev.ConsoleRenderer(colors=True, pad_event=False) ) structlog.configure( - processors=processors, - wrapper_class=structlog.make_filtering_bound_logger(_level_to_int(level)), + processors=shared_processors + [structlog.stdlib.ProcessorFormatter.wrap_for_formatter], + wrapper_class=structlog.stdlib.BoundLogger, context_class=dict, - logger_factory=structlog.PrintLoggerFactory(file=sys.stderr), + logger_factory=structlog.stdlib.LoggerFactory(), cache_logger_on_first_use=True, ) - # Route stdlib logging through structlog so third-party libs match our format. + # Route stdlib logging through structlog so third-party libs match our format, + # and structlog events reach any OTEL handlers attached to the root logger. stdlib_handler = logging.StreamHandler(sys.stderr) stdlib_handler.setFormatter( structlog.stdlib.ProcessorFormatter( - processor=processors[-1], - foreign_pre_chain=processors[:-1], + processor=renderer, + foreign_pre_chain=shared_processors, ) ) root_logger = logging.getLogger() diff --git a/src/contract_check/core/telemetry.py b/src/contract_check/core/telemetry.py index a69d5d8..39eba66 100644 --- a/src/contract_check/core/telemetry.py +++ b/src/contract_check/core/telemetry.py @@ -55,6 +55,46 @@ def setup_telemetry(service_name: str | None = None) -> None: from opentelemetry.sdk.trace.export import BatchSpanProcessor from opentelemetry.trace import set_tracer_provider + class StructlogOTLPLogHandler(LoggingHandler): + """OTEL handler that unwraps structlog event dicts. + + ``core/logging.py`` routes structlog through stdlib logging; the + resulting ``LogRecord`` carries the event dictionary in + ``record.msg``. This handler extracts the ``event`` as the log body and + promotes the remaining fields to OTEL attributes so OpenObserve can + index them. + """ + + _STRUCTLOG_INTERNAL_KEYS = frozenset({"_logger", "_name"}) + + def _translate(self, record: logging.LogRecord) -> Any: + # Detect structlog-wrapped records produced by + # ``ProcessorFormatter.wrap_for_formatter``. + if ( + getattr(record, "_logger", None) is not None + and getattr(record, "_name", None) is not None + and isinstance(record.msg, (tuple, list)) + and len(record.msg) == 1 + and isinstance(record.msg[0], dict) + ): + event_dict = record.msg[0] + # Work on a copy so the original record (used by stderr handler) + # is not mutated. + patched = logging.makeLogRecord(record.__dict__) + patched.msg = event_dict.get("event", "") + patched.args = () + # Drop structlog internal bookkeeping copied from the original + # record so it does not leak into OTEL attributes. + for key in self._STRUCTLOG_INTERNAL_KEYS: + patched.__dict__.pop(key, None) + for key, value in event_dict.items(): + if key in self._STRUCTLOG_INTERNAL_KEYS: + continue + if key not in patched.__dict__: + setattr(patched, key, value) + return super()._translate(patched) + return super()._translate(record) + resource = Resource.create({"service.name": service_name or settings.otel_service_name}) # Traces @@ -63,8 +103,9 @@ def setup_telemetry(service_name: str | None = None) -> None: set_tracer_provider(trace_provider) _trace_provider = trace_provider - # Logs (stdlib logging → OTLP). Structlog's PrintLogger still writes to stderr; - # this captures stdlib/third-party logs and anything routed through the root logger. + # Logs (stdlib logging → OTLP). ``configure_logging`` routes structlog + # through the stdlib logging tree; this handler unwraps the structured + # event dicts so OpenObserve receives the message body and fields. log_provider = LoggerProvider(resource=resource) log_provider.add_log_record_processor( BatchLogRecordProcessor(OTLPLogExporter(endpoint=endpoint)) @@ -72,7 +113,7 @@ def setup_telemetry(service_name: str | None = None) -> None: set_logger_provider(log_provider) _log_provider = log_provider - otel_log_handler = LoggingHandler(logger_provider=log_provider) + otel_log_handler = StructlogOTLPLogHandler(logger_provider=log_provider) otel_log_handler.setLevel(logging.INFO) logging.getLogger().addHandler(otel_log_handler) diff --git a/tests/unit/test_telemetry.py b/tests/unit/test_telemetry.py new file mode 100644 index 0000000..981ac78 --- /dev/null +++ b/tests/unit/test_telemetry.py @@ -0,0 +1,76 @@ +"""Unit tests for OpenTelemetry integration. + +Covers the structlog-aware OTEL log handler that unwraps event dicts so +OpenObserve receives structured attributes. +""" + +from __future__ import annotations + +import logging + +import pytest + +from contract_check.core.logging import configure_logging, get_logger + + +@pytest.fixture(autouse=True) +def _reset_logging(): + """Configure logging before each test and clean handlers after.""" + configure_logging("INFO", json_output=True, service="test-service", env="test") + yield + root = logging.getLogger() + root.handlers.clear() + + +def test_structlog_otlp_handler_unwraps_event_dict(monkeypatch: pytest.MonkeyPatch) -> None: + """A structlog-wrapped record is converted to body + attributes.""" + from contract_check.core.config import get_settings + from contract_check.core.telemetry import setup_telemetry, shutdown_telemetry + + monkeypatch.setattr( + get_settings(), "otel_exporter_otlp_endpoint", "http://localhost:9999/v1/logs" + ) + + # setup_telemetry defines the handler class when OTEL is imported. + setup_telemetry("test") + root = logging.getLogger() + try: + otel_handler = next( + h for h in root.handlers if type(h).__name__ == "StructlogOTLPLogHandler" + ) + + record = logging.LogRecord( + name="test.logger", + level=logging.INFO, + pathname="test.py", + lineno=5, + msg=({"event": "hello_openobserve", "foo": "bar", "count": 42},), + args=(), + exc_info=None, + ) + record._logger = logging.getLogger("test.logger") # type: ignore[attr-defined] + record._name = "info" # type: ignore[attr-defined] + + otel_record = otel_handler._translate(record) + + assert otel_record.body == "hello_openobserve" + attrs = {k: v for k, v in otel_record.attributes.items() if not k.startswith("code.")} + assert attrs["foo"] == "bar" + assert attrs["count"] == 42 + assert "_logger" not in attrs + assert "_name" not in attrs + finally: + shutdown_telemetry() + root.handlers = [h for h in root.handlers if type(h).__name__ != "StructlogOTLPLogHandler"] + + +def test_structlog_logs_reach_root_handlers() -> None: + """After configure_logging, structlog events propagate to stdlib handlers.""" + root = logging.getLogger() + assert ( + any(type(h).__name__ in ("StreamHandler", "ProcessorFormatter") for h in root.handlers) + or root.handlers + ) + + log = get_logger("test") + log.info("smoke_test", answer=42)