From 9be42bcee1f7a556be112bbe131a66378a25358a Mon Sep 17 00:00:00 2001 From: Brent Date: Mon, 20 Jul 2026 18:13:34 -0400 Subject: [PATCH 1/2] 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" }, From 0255f85188882bbff2c5213b0f62e3e76bd90194 Mon Sep 17 00:00:00 2001 From: Brent Date: Tue, 11 Aug 2026 07:15:15 -0400 Subject: [PATCH 2/2] Gate the OTLP bridge on a real consumer, and put correlationId on the wire in camelCase MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two review findings, both cheaper now than after five packages publish. 1. DOUBLE EMISSION — a regression for every existing Python consumer. The bridge logger propagates to root, so it only helps when observability's `LoggingHandler` is attached there. When it is NOT, but the app has called `logging.basicConfig()` — Lambda, uvicorn and pytest all do — root has a plain StreamHandler, and every smooai line is printed a SECOND time on top of our own stdout writer. In exchange for nothing. `_otel_consumer_present()` capability-detects a real OTel logging handler before emitting, and honours the family-wide `SMOOAI_OBSERVABILITY_DISABLED` kill switch. This is the same "enabled means a consumer is registered" contract the other languages use, rather than Python's always-on. Proven, not asserted: deleting the gate fails `test_no_otel_consumer_means_no_bridged_record` with "a plain root handler received a bridged record" and fails the kill-switch test. The paired `test_an_otel_consumer_does_receive_the_record` is the negative control — if the gate were simply always-off, it would fail instead. 2. `extra["correlation_id"]` was the only snake_case key on the wire; every other language emits camelCase (`ContextKey` in TS/Go/Rust/.NET). Renamed to `correlationId` before anything queries it, since changing it later is breaking. The PR's two existing bridge tests asserted delivery to ANY root handler — which is precisely the double-emission behaviour — so they now use an OTel-shaped handler and assert the contract that actually matters. 62 tests pass. Co-Authored-By: Claude Opus 5 (1M context) --- python/src/smooai_logger/logger.py | 35 +++++++- python/tests/test_otel_correlation.py | 110 ++++++++++++++++++++++++++ 2 files changed, 144 insertions(+), 1 deletion(-) diff --git a/python/src/smooai_logger/logger.py b/python/src/smooai_logger/logger.py index aa128d3b..9c50a8f8 100644 --- a/python/src/smooai_logger/logger.py +++ b/python/src/smooai_logger/logger.py @@ -355,6 +355,35 @@ class Level(str, Enum): _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, @@ -756,13 +785,17 @@ 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: - extra["correlation_id"] = 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: diff --git a/python/tests/test_otel_correlation.py b/python/tests/test_otel_correlation.py index 85066275..d7ade078 100644 --- a/python/tests/test_otel_correlation.py +++ b/python/tests/test_otel_correlation.py @@ -58,10 +58,16 @@ 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) @@ -82,10 +88,15 @@ def test_bridge_line_carries_span_context_for_obs(): 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) @@ -97,3 +108,102 @@ def emit(self, record: logging.LogRecord) -> None: 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)