open-telemetry / open-telemetry/opentelemetry-python-contrib

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

Open
#3,808 2 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug
Dominant language
Python
Stars
1.1k
Forks
1.1k
Avg merge
4d 15h
Merged PRs (30d)
16

Description

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() corrupts the log factory linked list. The pythonlogging.logging.setLogRecordFactory() and logging.getLogRecordFactory() are intended to create a linked list, chaining multiple log record factories to augment information in the log records.

The record factory mechanism is also commonly used by applications.

The python logging record factory 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

Example - Before

OTHERS--->OTEL--->ORIGINAL

Example - After - corrupted linked list where the OTHERS links got cut off by LoggingInstrumentor._uninstrument()

OTHERS    OTEL--->ORIGINAL
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.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start at opentelemetry.instrumentation.logging.LoggingInstrumentor._uninstrument and its call from instrument(); reproduce the OTHERS -> OTEL -> ORIGINAL ordering with Python logging's factory APIs. Done means uninstrumenting and re-instrumenting no longer remove factories added after OTEL, with coverage for both paths. The issue does not name a source file or test.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
observability-sre
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Active
Clarity
Mostly clear
Newbie friendliness
48/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.