opentelemetry-instrumentation-logging: LoggingInstrumentor._uninstrument breaks the log factory linked list

[vkruglik-aka]

Describe your environment

OS: Ubuntu, OS X, all OSs
Python version: 3.11.13
Package version: 0.58b0

What happened?

Concerning opentelemetry.instrumentation.logging.LoggingInstrumentor ...

LoggingInstrumentor._uninstrument() breaks the log factory linked list. The pythonlogging.logging.setLogRecordFactory() and logging.getLogRecordFactory() are intended to create a linked list, chaining multiple unrelated log record factories to augment information in the log records.

This python logging mechanism does not support removing (i.e. uninstrumenting) of any link in the chain. Once added, it MUST NOT be removed, or bad things happen.

LoggingInstrumentor._uninstrument() is implemented as if it's the only custom log record factory in the entire application. When it executes, it cuts off any of the custom log factories that were added after it.
As you can see from the current implementation below, it sets _old_factory node as the current log record factory, effectively cutting off any custom application or other libraries' factories from the linked list.

    def _uninstrument(self, **kwargs):
        if LoggingInstrumentor._old_factory:
            logging.setLogRecordFactory(LoggingInstrumentor._old_factory)
            LoggingInstrumentor._old_factory = None

A more

Steps to Reproduce

See description in "What Happened?" section.

Expected Result

LoggingInstrumentor._uninstrument() MUST NOT cut off other custom log factories that were added after LoggingInstrumentor._instrument()

Actual Result

LoggingInstrumentor._uninstrument() cuts off other custom log factories that were added after LoggingInstrumentor._instrument().

Additionally, LoggingInstrumentor._uninstrument() is called by LoggingInstrumentor.instrument(), where it also cuts off other links in the linked list of custom log factories.

Additional context

If uninstrumenting is needed for some reason, then a safe solution would be to implement this logging augmentation as a python logging filter instead of a log record factory and allow applications to add/remove the logging filter using python logging API. For example:

In opentelementry.instrumentation.logging:

class LoggingInstrumentorFilter(logging.Filter):
        def filter(self, record):
            record.otelSpanID = "0"
            record.otelTraceID = "0"
            record.otelTraceSampled = False

            ...

            return True

An application can then add and remove the filter to a specific logger or handler. Typical applications would likely add it to the root logger, but that may not be the case for all applications. An application needs to be in control of this. Below example adds and removes the filter to/from the root logger, thereby causing the filter to be executed for ALL loggers. The application has control to which logger or handler to instrument with the filter.

        otel_logging_instrumentor_filter = LoggingInstrumentorFilter()
        logging.root.addFilter(otel_logging_instrumentor_filter)

        ...

       # Later, if the application needs to remove this filter for some reason:
       logging.root.removeFilter(otel_logging_instrumentor_filter)

For example:

import logging
from typing import Optional

class LoggingInstrumentorFilter(logging.Filter):
    def __init__(self, *args, **kwargs) -> None:
        super().__init__(*args, **kwargs)

        # We track the last updated record to avoid redundant updates.
        #
        # NOTE: A filter may be invoked multiple times for the same record in some
        # logging configurations, such as when an application adds the filter
        # to multiple log handlers.
        self._last_updated_record: Optional[logging.LogRecord] = None

    def filter(self, record: logging.LogRecord) -> bool:
        if record is self._last_updated_record:
            # Already updated this record, skip
            return True

        self._last_updated_record = record

        record.otelSpanID = "0"
        record.otelTraceID = "0"
        record.otelTraceSampled = False

        span = get_current_span()

        if span != INVALID_SPAN:
            ctx = span.get_span_context()
            if ctx != INVALID_SPAN_CONTEXT:
                record.otelSpanID = format(ctx.span_id, "016x")
                record.otelTraceID = format(ctx.trace_id, "032x")
                record.otelTraceSampled = ctx.trace_flags.sampled

        return True

In addition, it would be very helpful to add the otelParentSpanID into the log record, using logic like this:

from opentelemetry.sdk import trace as sdk_trace
from opentelemetry.trace import INVALID_SPAN, get_current_span

record.otelParentSpanID = "0"

span: sdk_trace.Span = get_current_span()
if span != INVALID_SPAN:
    ctx = span.get_span_context()
    if ctx != INVALID_SPAN_CONTEXT:
         ...

         # NOTE: We can get a NonRecordingSpan that has no parent attribute when
         #  sampling is disabled.
         if (parent_ctx := getattr(span, 'parent', None) ) is not None:
             record.otelParentSpanID = format(parent_ctx.span_id, "016x") 

Would you like to implement a fix?

None

Tip

_{React with 👍 to help prioritize this issue. Please use comments to provide useful context, avoiding +1 or me too, to help us triage it. Learn more here.}