From 9be42bcee1f7a556be112bbe131a66378a25358a Mon Sep 17 00:00:00 2001 From: Brent Date: Mon, 20 Jul 2026 18:13:34 -0400 Subject: [PATCH] Correlate logs to active OTel span + bridge to stdlib logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Replaces the fabricated uuid trace id with the ACTIVE OTel span's real W3C trace_id/span_id when a span is active (get_current_span().get_span_context()), falling back to the prior uuid behavior only when no span is active. Adds a spanId field to the record. Also bridges every emitted line through a dedicated stdlib `logging` logger (smooai_logger) so an installed @smooai/observability LoggingHandler on the root logger turns each line into an OTLP log record — correlated to the active span, which that handler reads. NullHandler keeps it a true no-op when observability isn't installed. The file-rotation logger no longer propagates its pretty ANSI blob to root (would otherwise leak into the OTLP bridge). Depends on opentelemetry-api ONLY — never on @smooai/observability (circular). Verified with an api-only NonRecordingSpan: a log inside the span carries that span's ids; no span → uuid fallback; the bridged line reaches root within the span context. Co-Authored-By: Claude Opus 4.8 Claude-Session: https://claude.ai/code/session_01S2bM94GAnVjYSSv1x7HKRB --- python/pyproject.toml | 3 + python/src/smooai_logger/logger.py | 64 +++++++++++++++++ python/tests/test_otel_correlation.py | 99 +++++++++++++++++++++++++++ python/uv.lock | 14 ++++ 4 files changed, 180 insertions(+) create mode 100644 python/tests/test_otel_correlation.py diff --git a/python/pyproject.toml b/python/pyproject.toml index 39b108ff..73151543 100644 --- a/python/pyproject.toml +++ b/python/pyproject.toml @@ -8,6 +8,9 @@ license = { text = "MIT" } requires-python = ">=3.12" dependencies = [ "colorist>=1.5.2", + # opentelemetry-api ONLY — read the active span for trace/span correlation. + # NEVER depend on smooai-observability (circular). + "opentelemetry-api>=1.27", "pendulum>=3.0.0", "pydantic>=2.7.0", "pydantic-extra-types>=2.0.0", diff --git a/python/src/smooai_logger/logger.py b/python/src/smooai_logger/logger.py index 5cda3d89..aa128d3b 100644 --- a/python/src/smooai_logger/logger.py +++ b/python/src/smooai_logger/logger.py @@ -13,6 +13,7 @@ import pendulum from colorist import Color, Effect +from opentelemetry import trace as _otel_trace from rich import pretty from .utils.date import now @@ -21,6 +22,20 @@ pretty.install() +def _active_span_ids() -> tuple[str, str] | None: + """Return ``(trace_id_hex, span_id_hex)`` for the active OTel span, or None. + + W3C hex: 32-char trace id, 16-char span id — the real ids the OTLP pipeline + (and @smooai/observability) records, so our logs correlate to the trace. + Returns None when no span is active, and the caller falls back to the + fabricated correlation id. Depends on ``opentelemetry-api`` only. + """ + ctx = _otel_trace.get_current_span().get_span_context() + if not ctx.is_valid: + return None + return format(ctx.trace_id, "032x"), format(ctx.span_id, "016x") + + # -------------------------------------------------------------------------------- # Environment Utilities (mirroring TypeScript) # -------------------------------------------------------------------------------- @@ -208,6 +223,7 @@ class Context(TypedDict, total=False): correlationId: str | None requestId: str | None traceId: str | None + spanId: str | None namespace: str | None service: str | None error: str | None @@ -314,6 +330,31 @@ class Level(str, Enum): FATAL = "fatal" +# -------------------------------------------------------------------------------- +# stdlib logging bridge → @smooai/observability OTLP logs +# -------------------------------------------------------------------------------- +_LEVEL_TO_PY: dict[Level, int] = { + Level.TRACE: 5, + Level.DEBUG: logging.DEBUG, + Level.INFO: logging.INFO, + Level.WARN: logging.WARNING, + Level.ERROR: logging.ERROR, + Level.FATAL: logging.CRITICAL, +} + +# Dedicated stdlib logger that forwards each emitted line into the stdlib +# `logging` facade so @smooai/observability's root LoggingHandler turns it into +# an OTLP log record (correlated to the active span, which that handler reads). +# NullHandler suppresses the "no handlers" lastResort noise when observability +# is NOT installed — a true no-op; propagate=True lets root handlers (the obs +# handler, when present) see the record. +_otel_bridge = logging.getLogger("smooai_logger") +_otel_bridge.addHandler(logging.NullHandler()) +# The smooai Logger already gates by its own level in `_log`; keep this bridge +# from re-dropping INFO/DEBUG via root's default WARNING effective level. +_otel_bridge.setLevel(1) + + class Logger: """ Structured JSON logger with context, call-site, HTTP helpers, pretty printing, @@ -402,6 +443,9 @@ def _setup_rotation_handler(self, rotation_options: RotationOptions | None = Non self._file_logger = logging.getLogger(f"{self._name}.file") self._file_logger.setLevel(logging.NOTSET) + # Don't leak the pretty ANSI file blob up to root handlers (e.g. an + # observability LoggingHandler) — the clean OTLP bridge is _bridge_to_otel. + self._file_logger.propagate = False # Determine rotation type and create appropriate handler if self._rotation_config.interval and self._rotation_config.size: @@ -629,6 +673,12 @@ def _build_record(self, lvl: Level, args: list[Any]) -> Context: rec["level"] = lvl.value rec["time"] = now().isoformat() rec["name"] = self._name + # Correlate to the ACTIVE OTel span when one exists — its real W3C + # trace/span ids replace the fabricated uuid so logs line up with traces. + # Falls back to the fabricated correlation id when no span is active. + span_ids = _active_span_ids() + if span_ids is not None: + rec["traceId"], rec["spanId"] = span_ids # reorder keys: msg, time, error, errorDetails, errors first ordered = {} for key in ["msg", "time", "error", "errorDetails", "errors"]: @@ -702,10 +752,24 @@ def _emit(self, record: Context) -> None: # emit via our file-only logger self._file_logger.handle(log_rec) + def _bridge_to_otel(self, lvl: Level, record: Context) -> None: + """Forward the line through the stdlib `logging` facade so an installed + observability LoggingHandler (on root) can turn it into an OTLP log + record. No-op when nothing consumes it (NullHandler + propagate).""" + py_level = _LEVEL_TO_PY.get(lvl, logging.INFO) + if not _otel_bridge.isEnabledFor(py_level): + return + extra: dict[str, Any] = {} + cid = record.get("correlationId") + if cid: + extra["correlation_id"] = cid + _otel_bridge.log(py_level, record.get("msg") or "", extra=extra or None) + def _log(self, lvl: Level, *args: Any) -> None: if self._is_enabled(lvl): rec = self._build_record(lvl, list(args)) self._emit(rec) + self._bridge_to_otel(lvl, rec) def trace(self, *args: Any) -> None: self._log(Level.TRACE, *args) diff --git a/python/tests/test_otel_correlation.py b/python/tests/test_otel_correlation.py new file mode 100644 index 00000000..85066275 --- /dev/null +++ b/python/tests/test_otel_correlation.py @@ -0,0 +1,99 @@ +"""OTel trace correlation + stdlib logging bridge (th-de3805). + +A log emitted inside an active OTel span must carry that span's real W3C +trace_id/span_id (so logs line up with traces), and every line must flow through +the stdlib ``logging`` facade so @smooai/observability's root LoggingHandler can +turn it into an OTLP log record. Uses ``opentelemetry-api`` only — a +``NonRecordingSpan`` with an explicit valid context, no SDK. +""" + +from __future__ import annotations + +import json +import logging +from io import StringIO +from unittest.mock import patch + +from opentelemetry import trace +from opentelemetry.trace import NonRecordingSpan, SpanContext, TraceFlags + +from smooai_logger import Logger, reset_global_context + +_TRACE_ID = 0x0AF7651916CD43DD8448EB211C80319C +_SPAN_ID = 0x00F067AA0BA902B7 + + +def _span(): + ctx = SpanContext(trace_id=_TRACE_ID, span_id=_SPAN_ID, is_remote=False, trace_flags=TraceFlags(0x01)) + return NonRecordingSpan(ctx) + + +def _emit_capture(**logger_kwargs) -> dict: + """Emit one info log and return the parsed JSON record from stdout.""" + logger = Logger(pretty_print=False, log_to_file=False, **logger_kwargs) + buf = StringIO() + with patch("smooai_logger.logger.sys.stdout", buf): + logger.info("hello") + return json.loads(buf.getvalue().strip().splitlines()[-1]) + + +def test_traceid_from_active_span(): + reset_global_context() + with trace.use_span(_span(), end_on_exit=False): + rec = _emit_capture() + assert rec["traceId"] == "0af7651916cd43dd8448eb211c80319c" + assert rec["spanId"] == "00f067aa0ba902b7" + + +def test_traceid_falls_back_to_uuid_without_span(): + reset_global_context() + rec = _emit_capture() + # No active span → fabricated uuid correlation id, no spanId. + assert rec["traceId"] == rec["correlationId"] + assert "-" in rec["traceId"] # uuid, not a 32-hex trace id + assert "spanId" not in rec + + +def test_bridge_forwards_to_stdlib_root_logger(): + reset_global_context() + captured: list[logging.LogRecord] = [] + + class _Capture(logging.Handler): + def emit(self, record: logging.LogRecord) -> None: + captured.append(record) + + handler = _Capture() + root = logging.getLogger() + root.addHandler(handler) + try: + logger = Logger(pretty_print=False, log_to_file=False) + with patch("smooai_logger.logger.sys.stdout", StringIO()): + logger.info("bridged line") + finally: + root.removeHandler(handler) + + assert any(r.getMessage() == "bridged line" for r in captured), "line did not reach the stdlib root logger" + + +def test_bridge_line_carries_span_context_for_obs(): + """The bridged stdlib record is emitted inside the span, so an obs + LoggingHandler (which reads get_current_span) correlates it. We assert the + active span is visible at emit time via a handler.""" + reset_global_context() + seen: list[int] = [] + + class _SpanPeek(logging.Handler): + def emit(self, record: logging.LogRecord) -> None: + seen.append(trace.get_current_span().get_span_context().trace_id) + + handler = _SpanPeek() + root = logging.getLogger() + root.addHandler(handler) + try: + logger = Logger(pretty_print=False, log_to_file=False) + with trace.use_span(_span(), end_on_exit=False), patch("smooai_logger.logger.sys.stdout", StringIO()): + logger.info("in span") + finally: + root.removeHandler(handler) + + assert _TRACE_ID in seen diff --git a/python/uv.lock b/python/uv.lock index a7034a3f..0799db7a 100644 --- a/python/uv.lock +++ b/python/uv.lock @@ -87,6 +87,18 @@ wheels = [ { url = "https://files.pythonhosted.org/packages/a3/46/c9cf7ff7e3c71f07ca8331c939afd09b6e59fc85a2944ea9411e8b29ce50/nodejs_wheel_binaries-22.19.0-py2.py3-none-win_arm64.whl", hash = "sha256:666a355fe0c9bde44a9221cd543599b029045643c8196b8eedb44f28dc192e06", size = 38804500, upload-time = "2025-09-12T10:33:43.302Z" }, ] +[[package]] +name = "opentelemetry-api" +version = "1.44.0" +source = { registry = "https://pypi.org/simple" } +dependencies = [ + { name = "typing-extensions" }, +] +sdist = { url = "https://files.pythonhosted.org/packages/ee/8b/aa9e2d8b8dfa7c946f7dec5d1f8f6ba8eca062f43509a06bdb5ce93d26c0/opentelemetry_api-1.44.0.tar.gz", hash = "sha256:67647e5e9566edcf421166fdf022b3537f818635daa852b289e34604dc6fb33a", size = 72406, upload-time = "2026-07-16T15:25:32.678Z" } +wheels = [ + { url = "https://files.pythonhosted.org/packages/ca/6f/a04e900f465ff3221ccc395522503e2d10e79fa21f2723c8e177aae1e0d1/opentelemetry_api-1.44.0-py3-none-any.whl", hash = "sha256:94b98c893a91b88657eaac1e3ba89618cdb85be6918196705354f34728b2cdef", size = 60018, upload-time = "2026-07-16T15:25:11.657Z" }, +] + [[package]] name = "packaging" version = "25.0" @@ -346,6 +358,7 @@ version = "3.2.3" source = { editable = "." } dependencies = [ { name = "colorist" }, + { name = "opentelemetry-api" }, { name = "pendulum" }, { name = "pydantic" }, { name = "pydantic-extra-types" }, @@ -363,6 +376,7 @@ dev = [ [package.metadata] requires-dist = [ { name = "colorist", specifier = ">=1.5.2" }, + { name = "opentelemetry-api", specifier = ">=1.27" }, { name = "pendulum", specifier = ">=3.0.0" }, { name = "pydantic", specifier = ">=2.7.0" }, { name = "pydantic-extra-types", specifier = ">=2.0.0" },