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..9c50a8f8 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,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) diff --git a/python/tests/test_otel_correlation.py b/python/tests/test_otel_correlation.py new file mode 100644 index 00000000..d7ade078 --- /dev/null +++ b/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) 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" },