Correlate Python logs to active OTel span + bridge to stdlib logging

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",

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)

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