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,60 @@ 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)
+
+
+def _truthy(value: str | None) -> bool:
+    return (value or "").strip().lower() in {"1", "true", "yes", "on"}
+
+
+def _otel_consumer_present() -> bool:
+    """Is there actually an OTLP consumer for bridged records?
+
+    `propagate=True` sends every bridged line to the ROOT logger's handlers. When
+    observability is installed that is the point — its `LoggingHandler` turns the
+    record into an OTLP log. When it is NOT installed but the app has called
+    `logging.basicConfig()` (Lambda, uvicorn, pytest all do), root has a plain
+    StreamHandler instead, and every smooai line gets printed a SECOND time — once
+    by our own stdout writer, once by root. That is a regression for every existing
+    Python consumer, in exchange for nothing.
+
+    So the bridge is capability-detected rather than always-on: emit only when a
+    real OTel logging handler is attached. This is the same contract the other
+    languages use — enabled means a consumer is actually registered — plus the
+    family-wide `SMOOAI_OBSERVABILITY_DISABLED` kill switch.
+    """
+    if _truthy(os.getenv("SMOOAI_OBSERVABILITY_DISABLED")):
+        return False
+    for handler in logging.getLogger().handlers:
+        cls = type(handler)
+        if (cls.__module__ or "").startswith("opentelemetry") and cls.__name__ == "LoggingHandler":
+            return True
+    return False
+
+
 class Logger:
     """
     Structured JSON logger with context, call-site, HTTP helpers, pretty printing,
@@ -402,6 +472,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 +702,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 +781,28 @@ 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)."""
+        if not _otel_consumer_present():
+            return
+        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:
+            # camelCase on the wire, matching ContextKey across TS/Go/Rust/.NET.
+            # Renaming this after anything queries it would be breaking.
+            extra["correlationId"] = 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,209 @@
+"""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] = []
+
+    # Must LOOK like observability's handler: the bridge is capability-gated on a
+    # real OTel consumer being attached, precisely so an app's own root handler
+    # (logging.basicConfig) does not double-print every line.
+    class _Capture(logging.Handler):
+        def emit(self, record: logging.LogRecord) -> None:
+            captured.append(record)
+
+    _Capture.__name__ = "LoggingHandler"
+    _Capture.__module__ = "opentelemetry.sdk._logs"
+
+    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] = []
+
+    # Same reason as the test above: shaped like observability's handler so the
+    # capability gate lets the record through.
+    class _SpanPeek(logging.Handler):
+        def emit(self, record: logging.LogRecord) -> None:
+            seen.append(trace.get_current_span().get_span_context().trace_id)
+
+    _SpanPeek.__name__ = "LoggingHandler"
+    _SpanPeek.__module__ = "opentelemetry.sdk._logs"
+
+    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
+
+
+class _FakeOtelLoggingHandler(logging.Handler):
+    """Stands in for opentelemetry.sdk._logs.LoggingHandler.
+
+    The gate identifies a real consumer by module+class name, so the test has to
+    match on the same thing rather than on an isinstance the test controls.
+    """
+
+    def __init__(self) -> None:
+        super().__init__()
+        self.records: list[logging.LogRecord] = []
+
+    def emit(self, record: logging.LogRecord) -> None:
+        self.records.append(record)
+
+
+_FakeOtelLoggingHandler.__name__ = "LoggingHandler"
+_FakeOtelLoggingHandler.__module__ = "opentelemetry.sdk._logs"
+
+
+class _PlainAppHandler(logging.Handler):
+    """A vanilla root handler, as `logging.basicConfig()` installs."""
+
+    def __init__(self) -> None:
+        super().__init__()
+        self.records: list[logging.LogRecord] = []
+
+    def emit(self, record: logging.LogRecord) -> None:
+        self.records.append(record)
+
+
+def _with_root_handler(handler: logging.Handler):
+    root = logging.getLogger()
+    root.addHandler(handler)
+    return root
+
+
+def test_no_otel_consumer_means_no_bridged_record(monkeypatch):
+    """The double-emission regression.
+
+    Without the gate, every smooai line propagates to root and an app that called
+    logging.basicConfig() prints it a second time — on top of our own stdout
+    writer. Nothing about that helps a consumer who has not installed
+    observability.
+    """
+    monkeypatch.delenv("SMOOAI_OBSERVABILITY_DISABLED", raising=False)
+    app_handler = _PlainAppHandler()
+    root = _with_root_handler(app_handler)
+    try:
+        Logger().info("hello")
+        assert app_handler.records == [], (
+            "a plain root handler received a bridged record, so every consumer "
+            "with logging.basicConfig() double-prints every line"
+        )
+    finally:
+        root.removeHandler(app_handler)
+
+
+def test_an_otel_consumer_does_receive_the_record(monkeypatch):
+    """Negative control for the test above.
+
+    If this fails, the gate is simply off and the first test proves nothing.
+    """
+    monkeypatch.delenv("SMOOAI_OBSERVABILITY_DISABLED", raising=False)
+    otel_handler = _FakeOtelLoggingHandler()
+    root = _with_root_handler(otel_handler)
+    try:
+        Logger().info("hello")
+        assert len(otel_handler.records) == 1
+        assert otel_handler.records[0].getMessage() == "hello"
+    finally:
+        root.removeHandler(otel_handler)
+
+
+def test_kill_switch_wins_over_a_present_consumer(monkeypatch):
+    monkeypatch.setenv("SMOOAI_OBSERVABILITY_DISABLED", "1")
+    otel_handler = _FakeOtelLoggingHandler()
+    root = _with_root_handler(otel_handler)
+    try:
+        Logger().info("hello")
+        assert otel_handler.records == []
+    finally:
+        root.removeHandler(otel_handler)
+
+
+def test_correlation_id_is_camel_case_on_the_wire(monkeypatch):
+    monkeypatch.delenv("SMOOAI_OBSERVABILITY_DISABLED", raising=False)
+    otel_handler = _FakeOtelLoggingHandler()
+    root = _with_root_handler(otel_handler)
+    try:
+        log = Logger()
+        log.correlation_id = "11111111-2222-3333-4444-555555555555"
+        log.info("hello")
+        rec = otel_handler.records[0]
+        assert getattr(rec, "correlationId", None) == "11111111-2222-3333-4444-555555555555"
+        assert not hasattr(rec, "correlation_id"), "snake_case leaked onto the wire"
+    finally:
+        root.removeHandler(otel_handler)