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

OpenTelemetryMiddleware creating nested traces

Open
#1,783 2 comments 1 reaction 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

Python 3.10
Fastapi 0.92.0
opentelemetry-sdk 1.17.0
opentelemetry-instrumentation 0.38b0
opentelemetry-instrumentation-asgi 0.38b0

Steps to reproduce
I am trying to instrument fastapi. It could be that I'm using it incorrectly,
but trace nested occurs when images or data are large (65536 bytes or more) in successive image upload requests based on the same client. (It seems to happen rarely for requests smaller than 65536 bytes)

image
The strange thing is that only the http receiving side seems to be nested.

The applied code part is as follows.

app.add_middleware(       
            OpenTelemetryMiddleware,
            excluded_urls=excluded_urls,
            default_span_details=_get_route_details,
            server_request_hook=server_request_hook,
            client_request_hook=client_request_hook,
            client_response_hook=client_response_hook,
            tracer_provider=tracer_provider,
            meter=meter,
        )

What is the expected behavior?
Every connection has a single trace (no nesting)

What is the actual behavior?
If the same client sends consecutive requests within a certain amount of time (perhaps within 5 seconds), the traces will overlap.

Additional context
As a result of the test, when the same client sends a continuous large request, trace nested occurred in receive, and currently, nested does not occur when uvicorn --timeout-keep-alive=0 setting is applied.
However, I believe trace nesting should not occur regardless of the keep-alive setting.

Finally

handle the first request finally, detach the span from use_span.

detached! _Span(name="/compare http receive", context=SpanContext(trace_id=0xae9ad8e625b834b4353e9c465a88468a, span_id=0xc3eae6f7d66214c0, trace_flags=0x01, trace_state=[], is_remote=False))

When the opentelemetry.instrumentation.utils.py:_start_internal_or_server_span function is called in the following request,
I really wonder why in the trace.get_current_span() part I get the _Span(name="/compare http receive" ... ) of the previous request.

@contextmanager
def use_span(
    span: Span,
    end_on_exit: bool = False,
    record_exception: bool = True,
    set_status_on_exception: bool = True,
) -> Iterator[Span]:
    """Takes a non-active span and activates it in the current context.

    Args:
        span: The span that should be activated in the current context.
        end_on_exit: Whether to end the span automatically when leaving the
            context manager scope.
        record_exception: Whether to record any exceptions raised within the
            context as error event on the span.
        set_status_on_exception: Only relevant if the returned span is used
            in a with/context manager. Defines whether the span status will
            be automatically set to ERROR when an uncaught exception is
            raised in the span with block. The span status won't be set by
            this mechanism if it was previously set manually.
    """
    from loguru import logger

    try:
        token = context_api.attach(context_api.set_value(_SPAN_KEY, span))
        try:
            yield span
        finally:
            context_api.detach(token)

I would appreciate it if you could guide me if I misunderstood or made a mistake.

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 by reproducing successive large uploads through OpenTelemetryMiddleware, comparing the default behavior with uvicorn --timeout-keep-alive=0. Read the referenced _start_internal_or_server_span function and the use_span context manager, then inspect how the receiving span is detached between requests. Done means consecutive requests no longer create nested receiving traces regardless of keep-alive settings.

Written by the indexing model from the issue text.

Assessment

Tech stack
fastapi, python
Domain
backend, observability-sre
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.