Python Testing & Debugging Beyond unittestAdvanced Python testing playbooks
Debugging & Performance

Tracing a Request Through a Test with OpenTelemetry

Logs tell you what happened; traces tell you what happened inside what. When an integration test fails because a request took the wrong branch, a trace shows the whole path: the handler span, the database query spans under it, the outbound HTTP call to the pricing service that returned an error, and the retry that followed. Each span carries timing, attributes and status, and the parent-child structure makes the order of events and their nesting explicit in a way interleaved log lines never do.

OpenTelemetry makes that tree available inside a test with very little setup. An in-memory exporter collects finished spans instead of sending them anywhere; the test can then assert that required attributes are present, or — more often — print the tree when the test fails so the next person to debug it can see where the request went. The main pitfalls are global state (the tracer provider can be set only once per process) and asynchronous export, both of which have simple fixes.

Prerequisites

Solution

Python
# conftest.py
import pytest
from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter

_EXPORTER = InMemorySpanExporter()

def pytest_configure(config):
    provider = TracerProvider()
    provider.add_span_processor(SimpleSpanProcessor(_EXPORTER))   # synchronous export
    trace.set_tracer_provider(provider)                           # once per process

@pytest.fixture
def spans():
    _EXPORTER.clear()
    yield _EXPORTER
    _EXPORTER.clear()

def render_tree(finished):
    by_parent = {}
    for s in finished:
        by_parent.setdefault(s.parent.span_id if s.parent else None, []).append(s)
    lines = []
    def walk(parent, depth):
        for s in sorted(by_parent.get(parent, []), key=lambda s: s.start_time):
            ms = (s.end_time - s.start_time) / 1e6
            lines.append(f"{'  ' * depth}{s.name}  {ms:.1f} ms  {s.status.status_code.name}")
            walk(s.context.span_id, depth + 1)
    walk(None, 0)
    return "\n".join(lines)
Python
# test_checkout_trace.py
from opentelemetry.trace import StatusCode

def test_checkout_marks_pricing_failure(client, spans, pricing_down):
    resp = client.post("/checkout", json={"cart": "c1"})
    assert resp.status_code == 503, render_tree(spans.get_finished_spans())

    finished = {s.name: s for s in spans.get_finished_spans()}
    call = finished["POST pricing"]
    assert call.status.status_code is StatusCode.ERROR
    assert call.attributes["http.response.status_code"] == 500
    assert finished["checkout"].attributes["cart.id"] == "c1"
Plain text
AssertionError:
checkout  48.2 ms  ERROR
  SELECT carts  1.9 ms  UNSET
  POST pricing  20.4 ms  ERROR
  POST pricing  22.1 ms  ERROR
A request's span tree captured in a test A root span named checkout contains three child spans laid out on a timeline: a SELECT carts database span, then two POST pricing HTTP spans, both marked as errors, showing a retry. The in-memory exporter collects all four finished spans so the test can assert on them or print the tree. One request, one tree checkout 48.2 ms · ERROR SELECT carts · 1.9 ms POST pricing · 500 POST pricing (retry) · 500 time →
The tree shows at a glance that the failure came from pricing, that it was retried once, and how long each step took.

Why this works

The SDK's TracerProvider sends every finished span to its processors. SimpleSpanProcessor exports each span synchronously as it ends, so by the time the request returns, every span it created is already in the in-memory exporter. The production default, BatchSpanProcessor, exports on a background thread in batches, which is efficient but means a test can finish before its spans arrive; in tests, synchronous export removes that race.

The provider is set in pytest_configure because OpenTelemetry's global provider can be set only once — later calls log a warning and are ignored. Setting it at session start guarantees every tracer created by application code or instrumentation libraries during the run uses the test provider. The function-scoped fixture then only needs to clear the exporter, so each test sees just its own spans.

Instrumentation libraries do the rest. HTTPXClientInstrumentor().instrument() wraps outgoing requests in client spans with standard attributes; SQLAlchemyInstrumentor().instrument(engine=engine) does the same for queries. Because they use the global provider, their spans land in the same exporter and nest under whatever span was current when the call was made.

Traces as a debugging attachment

Most tests should not assert on spans at all. Span names and attributes change as instrumentation libraries evolve, and asserting on them couples tests to observability details. The more durable use is as a debugging aid: when a test fails, print the tree.

A hook in conftest.py can do that automatically for every test that uses the spans fixture:

Python
@pytest.hookimpl(hookwrapper=True)
def pytest_runtest_makereport(item, call):
    outcome = yield
    rep = outcome.get_result()
    if rep.when == "call" and rep.failed and "spans" in item.fixturenames:
        rep.sections.append(("trace", render_tree(_EXPORTER.get_finished_spans())))

The failure report then contains a "trace" section next to captured logs and stdout. For flaky integration tests in particular, where the failure is rare and the logs are noisy, a compact tree of what the request did — which calls, in which order, how long each took, which failed — is often the fastest route to the cause.

Assert on spans only where tracing itself is a requirement: a dashboard depends on cart.id being set, an alert depends on errors being marked with StatusCode.ERROR, a service-level objective depends on a span existing for every checkout. Those assertions protect real consumers of the telemetry and are worth their maintenance cost.

Where the trace appears in a failure report A pytest failure report for a failing test contains stacked sections: the assertion error, captured log call, captured stdout, and a trace section added by a report hook, which shows the span tree of the request that the test made. A failure report with the trace attached E assert 200 == 503 Captured log call Captured stdout call trace — checkout ▸ SELECT ▸ POST pricing ×2
Attached automatically, the tree turns a bare assertion error into a readable account of the request.

Following a request across services in an integration test

The in-memory exporter captures spans from one process. Integration tests often start the service under test in a subprocess or container, and the interesting spans are produced there. Two approaches keep the whole path visible.

The first is to run a collector for the test session. Start an OpenTelemetry Collector container (or the lightweight Jaeger all-in-one image) in a session fixture, point the service's OTEL_EXPORTER_OTLP_ENDPOINT at it, and query the collector's API at the end of a failing test for all spans with the test's trace id. The test process starts the trace — its HTTP client instrumentation injects a traceparent header into the request — and the service continues it, so everything shares one trace id and can be retrieved as a single tree.

The second is lighter: have the service write spans to a file with the console exporter, one JSON object per line, into a directory the test can read. After a failure, the test loads the file, filters by trace id and renders the same tree. There is no extra container, and the file doubles as a CI artefact.

In both cases, the key detail is propagation. Without the traceparent header, the service starts a new trace for every request and the test cannot find its spans. The HTTP client instrumentation adds the header automatically; hand-built requests with a bare socket or a mocked transport need opentelemetry.propagate.inject(headers) called explicitly.

One trace across the test and the service The test process starts a trace and its HTTP client injects a traceparent header into the request. The service process continues the same trace and exports its spans to a collector or a file. After a failure, the test retrieves all spans with its trace id and renders a single tree covering both processes. traceparent ties the two processes together test process starts trace abc… service process continues trace abc… collector or file spans by trace id traceparent on failure: fetch and render the whole tree
With propagation in place, the failing test can show spans from every process the request touched.

Using span timings to explain slow tests

Spans also answer a question that is awkward with other tools: why is this particular test slow? A profiler shows where CPU time goes, but integration tests are usually slow because they wait — on the database, on HTTP calls, on retries with backoff. Span durations measure exactly that waiting, per operation.

Rendering the tree for a slow test often makes the problem obvious. A test that takes three seconds might show a single fast request followed by two pricing calls of a second each, revealing that the fake pricing service was configured with a realistic timeout the test never needed. Another might show forty sequential SELECT spans where one query with a join would do — an N+1 query pattern that is equally slow in production. Neither would stand out in a --durations report, which only gives the test's total time.

A small addition to the report hook — appending the tree when a test exceeds a duration threshold, not only when it fails — turns this into a routine check. Slow tests then carry their own explanation in the CI output.

Edge cases and failure modes

  • Provider already set. If application import code calls set_tracer_provider before pytest_configure, the test provider is ignored. Make application setup skip provider creation when one exists, or gate it behind an environment variable.
  • Spans from other tests. Background threads that finish after their test leak spans into the next one. Join threads in teardown, or filter by trace id.
  • Async context propagation. Spans started in asyncio tasks nest correctly only if context propagates; tasks created with create_task copy context automatically, but thread pools do not — use contextvars.copy_context().run.
  • xdist. Each worker process has its own provider and exporter; nothing needs sharing, but do not expect spans from one worker in another.
  • Sampling. A sampler configured from the environment may drop spans. Use ALWAYS_ON in the test provider.

Frequently Asked Questions

How do I capture OpenTelemetry spans in a pytest test? Configure a TracerProvider with a SimpleSpanProcessor and an InMemorySpanExporter in a fixture, run the code under test, then read exporter.get_finished_spans(). Clear the exporter between tests.

Why are no spans exported in my test? Usually because the global tracer provider was set before the test fixture ran, since OpenTelemetry allows setting it only once, or because a BatchSpanProcessor has not flushed. Use SimpleSpanProcessor in tests and set the provider once per session.

Should tests assert on spans? Only where tracing is part of the contract, such as required attributes for dashboards or error status on failures. Otherwise use spans as a debugging aid attached to failing tests rather than as assertions.

← Back to Logging and Observability for Debugging