From a867d5e36eeb67bc53d87c346cc7037b991df0a8 Mon Sep 17 00:00:00 2001 From: Vadim Korolik Date: Thu, 18 Jun 2026 19:55:56 +0000 Subject: [PATCH] fix(observability-python): prevent logging recursion with coexisting agents The SDK attaches an OpenTelemetry LoggingHandler to the root logger, so it sees every log record in the process. When another logging instrumentation is also present (e.g. the New Relic Python agent) this could recurse: - NR leaves a non-serializable attribute (_nr_original_message, a function wrapper) on every LogRecord. OTel attribute validation rejects the type and emits its own WARNING, which NR re-dispatches through the root logger where it is re-captured -> unbounded feedback loop / log storm. - Any log emitted synchronously by our own export pipeline (attribute warnings, exporter errors) was re-captured by our handler. Introduce LDLoggingHandler, a hardened LoggingHandler that: - drops non-serializable record attributes before OTel validation, and - guards emit() against re-entrancy via a context-local flag. Also make root-logger registration idempotent so repeated initialization in one process (repeated set_config, gunicorn preload+worker, test suites) never stacks duplicate handlers that double-export every record. Adds regression tests covering all three behaviors. Co-Authored-By: Claude Opus 4.8 --- .../ldobserve/_otel/configuration.py | 17 ++- .../ldobserve/_otel/logging_handler.py | 97 ++++++++++++++++ .../ldobserve/_otel/test_logging_handler.py | 105 ++++++++++++++++++ 3 files changed, 217 insertions(+), 2 deletions(-) create mode 100644 sdk/@launchdarkly/observability-python/ldobserve/_otel/logging_handler.py create mode 100644 sdk/@launchdarkly/observability-python/ldobserve/_otel/test_logging_handler.py diff --git a/sdk/@launchdarkly/observability-python/ldobserve/_otel/configuration.py b/sdk/@launchdarkly/observability-python/ldobserve/_otel/configuration.py index c5ad8aa12c..39602bb0c9 100644 --- a/sdk/@launchdarkly/observability-python/ldobserve/_otel/configuration.py +++ b/sdk/@launchdarkly/observability-python/ldobserve/_otel/configuration.py @@ -29,6 +29,10 @@ ) from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler +from ldobserve._otel.logging_handler import ( + LDLoggingHandler, + install_on_root_logger, +) from opentelemetry.sdk.resources import Resource from opentelemetry.sdk.trace import TracerProvider import opentelemetry._logs as _logs @@ -132,7 +136,12 @@ def __init__(self, project_id: str, config: _ProcessedConfig): # The log handler is always created even if logging is not instrumented. # This allows directly logging to OpenTelemetry. - self._log_handler = LoggingHandler( + # + # LDLoggingHandler is a hardened LoggingHandler: it is safe to install on + # the root logger alongside other logging instrumentation (e.g. the New + # Relic agent) because it guards against re-entrancy and never forwards + # non-serializable record attributes. See logging_handler.py. + self._log_handler = LDLoggingHandler( level=self._config.log_level, logger_provider=self._logger_provider ) @@ -158,7 +167,11 @@ def __init__(self, project_id: str, config: _ProcessedConfig): # If log_correlation is false, then the LoggingInstrumentor will not # configure basic logging. If it does, then this call has no effect. logging.basicConfig(level=self._config.log_level) - logging.getLogger().addHandler(self._log_handler) + # Registration is idempotent: if the SDK is initialized more than + # once in the same process (e.g. a repeated set_config, a test suite, + # or a gunicorn preload + worker) this never stacks duplicate handlers + # on the root logger, which would double-export every log record. + install_on_root_logger(self._log_handler) metric_reader = PeriodicExportingMetricReader( exporter=OTLPMetricExporter( diff --git a/sdk/@launchdarkly/observability-python/ldobserve/_otel/logging_handler.py b/sdk/@launchdarkly/observability-python/ldobserve/_otel/logging_handler.py new file mode 100644 index 0000000000..673e483a15 --- /dev/null +++ b/sdk/@launchdarkly/observability-python/ldobserve/_otel/logging_handler.py @@ -0,0 +1,97 @@ +"""A hardened OpenTelemetry logging handler. + +The SDK attaches a :class:`~opentelemetry.sdk._logs.LoggingHandler` to the root +logger so that application logs are exported to LaunchDarkly. Because the handler +lives on the root logger it sees *every* log record in the process, including +records produced by other logging instrumentation (the New Relic agent, Datadog, +Sentry, ...) and records produced synchronously by our own export pipeline. + +Two failure modes follow from that, both of which this handler defends against: + +1. **Foreign record attributes.** Other logging instrumentation stashes + arbitrary objects on the :class:`logging.LogRecord` (for example the New Relic + agent leaves ``record._nr_original_message``, a function wrapper). When the + stock handler forwards those attributes, OpenTelemetry's attribute validation + rejects the non-serializable value and emits its own ``WARNING`` log. If + another agent re-dispatches that warning back through the root logger, it is + re-captured here, producing a new warning, and so on -- an unbounded feedback + loop. We drop attribute values that are not valid OpenTelemetry types before + they ever reach validation. + +2. **Re-entrancy.** Any log emitted *while we are inside* ``emit`` (an attribute + warning, an exporter error, a gRPC log) must not be captured again by this + handler, or a single application log can recurse. A context-local guard makes + re-entrant calls a no-op. + +Together these make the handler safe to run alongside any other logging +instrumentation without disabling log capture. +""" + +import contextvars +import logging +import typing + +from opentelemetry.sdk._logs import LoggingHandler + +# Set while this handler is emitting a record. Any log produced synchronously by +# the emit/export pipeline re-enters ``emit`` with this flag set and is dropped, +# which breaks otherwise-unbounded recursion. A module-level ContextVar (rather +# than per-instance state) also guards the case where more than one LD handler +# ends up on the root logger. +_in_emit: contextvars.ContextVar[bool] = contextvars.ContextVar( + "ldobserve_in_emit", default=False +) + +# Types OpenTelemetry accepts as attribute values (or sequences thereof). +_VALID_ATTRIBUTE_TYPES = (bool, bytes, int, float, str) + + +def _is_valid_attribute_value(value: typing.Any) -> bool: + if isinstance(value, _VALID_ATTRIBUTE_TYPES): + return True + if isinstance(value, (list, tuple)): + return all(isinstance(item, _VALID_ATTRIBUTE_TYPES) for item in value) + return False + + +class LDLoggingHandler(LoggingHandler): + """An :class:`~opentelemetry.sdk._logs.LoggingHandler` that is safe to + install on the root logger alongside other logging instrumentation.""" + + def emit(self, record: logging.LogRecord) -> None: + # Re-entrancy guard: drop records produced while we are already emitting. + if _in_emit.get(): + return + token = _in_emit.set(True) + try: + super().emit(record) + finally: + _in_emit.reset(token) + + def _get_attributes( + self, record: logging.LogRecord + ) -> typing.Dict[str, typing.Any]: + # Never forward foreign / non-serializable record attributes (e.g. the + # New Relic agent's ``_nr_original_message`` function wrapper); they would + # fail OpenTelemetry's attribute validation and trigger a warning that can + # feed back into the root logger. + attributes = super()._get_attributes(record) + return { + key: value + for key, value in attributes.items() + if _is_valid_attribute_value(value) + } + + +def install_on_root_logger(handler: LDLoggingHandler) -> None: + """Install ``handler`` on the root logger, idempotently. + + Any previously installed :class:`LDLoggingHandler` is removed first, so that + repeated SDK initialization in the same process never stacks duplicate + handlers on the root logger (which would double-export every log record). + """ + root_logger = logging.getLogger() + for existing in list(root_logger.handlers): + if isinstance(existing, LDLoggingHandler): + root_logger.removeHandler(existing) + root_logger.addHandler(handler) diff --git a/sdk/@launchdarkly/observability-python/ldobserve/_otel/test_logging_handler.py b/sdk/@launchdarkly/observability-python/ldobserve/_otel/test_logging_handler.py new file mode 100644 index 0000000000..bf2222317c --- /dev/null +++ b/sdk/@launchdarkly/observability-python/ldobserve/_otel/test_logging_handler.py @@ -0,0 +1,105 @@ +import logging + +import pytest +from opentelemetry.sdk._logs import LoggerProvider +from opentelemetry.sdk._logs.export import ( + InMemoryLogExporter, + SimpleLogRecordProcessor, +) + +from ldobserve._otel.logging_handler import ( + LDLoggingHandler, + install_on_root_logger, +) + + +def _make_handler(provider: LoggerProvider) -> LDLoggingHandler: + return LDLoggingHandler(level=logging.NOTSET, logger_provider=provider) + + +def test_get_attributes_drops_non_serializable_values(): + """Foreign / non-serializable record attributes (e.g. the New Relic agent's + ``_nr_original_message`` function wrapper) must not be forwarded -- they fail + OpenTelemetry attribute validation and seed a logging feedback loop.""" + handler = _make_handler(LoggerProvider()) + + record = logging.LogRecord( + name="app", + level=logging.WARNING, + pathname=__file__, + lineno=1, + msg="hello", + args=None, + exc_info=None, + ) + # mimic the attributes a coexisting logging instrumentation leaves behind + record._nr_original_message = lambda: "wrapped" # function wrapper + record.some_object = object() + record.ok_str = "value" + record.ok_int = 7 + record.ok_seq = ["a", "b"] + + attributes = handler._get_attributes(record) + + assert "_nr_original_message" not in attributes + assert "some_object" not in attributes + assert attributes["ok_str"] == "value" + assert attributes["ok_int"] == 7 + assert attributes["ok_seq"] == ["a", "b"] + + +def test_emit_is_not_reentrant(): + """A log produced synchronously by the export pipeline must not be captured + again by the handler, otherwise a single application log recurses.""" + exporter = InMemoryLogExporter() + provider = LoggerProvider() + provider.add_log_record_processor(SimpleLogRecordProcessor(exporter)) + handler = _make_handler(provider) + + export_calls = {"count": 0} + original_export = exporter.export + + def logging_export(batch): + # Simulate a pipeline component that logs synchronously during export + # (the real OTLP exporter does exactly this on connection errors). + export_calls["count"] += 1 + logging.getLogger("pipeline.exporter").warning( + "synchronous export log %d", export_calls["count"] + ) + return original_export(batch) + + exporter.export = logging_export + + root = logging.getLogger() + install_on_root_logger(handler) + old_level = root.level + root.setLevel(logging.DEBUG) + try: + logging.getLogger("app").warning("application log line") + finally: + root.setLevel(old_level) + root.removeHandler(handler) + + # Without the re-entrancy guard the synchronous export log re-enters emit and + # recurses unboundedly. With it, only the bounded set of distinct records is + # exported. The exact count is small and finite -- never a runaway loop. + assert export_calls["count"] <= 3 + assert exporter.export.__name__ == "logging_export" + + +def test_install_on_root_logger_is_idempotent(): + """Repeated installation must not stack duplicate LD handlers on the root + logger (which would double-export every record).""" + root = logging.getLogger() + before = [h for h in root.handlers if isinstance(h, LDLoggingHandler)] + handlers = [_make_handler(LoggerProvider()) for _ in range(3)] + try: + for handler in handlers: + install_on_root_logger(handler) + ld_handlers = [h for h in root.handlers if isinstance(h, LDLoggingHandler)] + # exactly one LD handler remains -- the most recently installed one + assert len(ld_handlers) == len(before) + 1 + assert ld_handlers[-1] is handlers[-1] + finally: + for handler in handlers: + root.removeHandler(handler)