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)