Implement distributed tracing with OpenTelemetry

Introduction

When a user reports that their completion request returned an error, your first debugging move is to search your logs. If your application emits free-form text like "ERROR: Failed to process request for user 42", you grep through millions of lines hoping the message format is consistent enough to land on the right one. If it emits structured JSON like {"level": "error", "user_id": 42, "request_id": "abc-123", "trace_id": "def-456"}, you query a single field and pull every log line from every service involved in that request within seconds. Skipping this work means outages stay unresolved for hours while you reconstruct what happened from memory and intuition.

By the end of this lesson you will be able to configure structlog for JSON output, attach a correlation ID to every request via FastAPI middleware, wire OpenTelemetry tracing into your handlers, and connect both signals so a single ID jumps you from a log line straight into the matching distributed trace.

Key Terminology

• Structured logging — Emitting log entries as JSON key/value records rather than free-form text. It matters here because log aggregators index and query JSON fields far faster than regex over plain strings.
• Correlation ID — A unique identifier generated at the request entry point and propagated through every log line, service hop, and downstream call. It is the join key that ties scattered logs back to a single user request.
• OpenTelemetry (OTel) — A vendor-neutral standard for emitting traces, metrics, and logs. In this lesson it produces the spans that visualize where each request spent its time.
• Span — A single timed operation inside a trace, such as one LLM provider call. Spans nest into a tree that shows latency contributions across services.
• Trace context (trace_id / span_id) — W3C-standardized hex identifiers that flow between services. Injecting them into log entries lets a log query open the matching trace in one click.

Concepts

One request, three correlated signals

A single API request should produce structured logs, a trace, and metrics that all share a request_id and trace_id. That shared key is what turns "find every log for the request that timed out" into a one-line query instead of an archaeology project. Middleware generates the correlation ID once and binds it to the structlog context; the OpenTelemetry SDK independently produces a trace_id; both flow into your downstream backends and can be joined there (see Code Walkthrough).

Context propagation via contextvars

Python's contextvars module provides asyncio-safe per-task storage. The middleware writes the correlation ID into a ContextVar and calls structlog.contextvars.bind_contextvars; every subsequent logger.info(...) in that request automatically carries the ID without threading it through function signatures. Concurrent requests stay isolated because each asyncio task gets its own context copy.

Custom spans for LLM operations

FastAPI's automatic instrumentation gives you one span per HTTP request, but the interesting latency lives inside: the LLM call, the vector search, the prompt rendering. Wrap each meaningful operation in tracer.start_as_current_span(...) and attach attributes like llm.model and llm.prompt_tokens so the trace viewer shows where time and tokens went (see Code Walkthrough).

Connecting traces to logs

A custom structlog processor reads trace.get_current_span() and injects trace_id and span_id into every log entry. Once logs carry the trace ID, your log UI's "view trace" link works — no manual copying of IDs between tabs.

Code Walkthrough

The snippet below wires all four concepts together: structlog JSON output, the correlation-ID middleware, OpenTelemetry setup, and a custom LLM span. Read it as the minimum viable observability stack for a FastAPI GenAI service.

Code snippetpython
1# app/observability.py
2import logging
3import os
4import sys
5import uuid
6
7import structlog
8from fastapi import FastAPI, Request, Response
9from opentelemetry import trace
10from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
11from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
12from opentelemetry.sdk.resources import Resource
13from opentelemetry.sdk.trace import TracerProvider
14from opentelemetry.sdk.trace.export import BatchSpanProcessor
15from starlette.middleware.base import BaseHTTPMiddleware
16
17def _add_trace_context(logger, method_name, event_dict):
18    ctx = trace.get_current_span().get_span_context()
19    if ctx.trace_id:
20        event_dict["trace_id"] = format(ctx.trace_id, "032x")
21        event_dict["span_id"] = format(ctx.span_id, "016x")
22    return event_dict
23
24def configure_logging(level: str = "INFO") -> None:
25    processors = [
26        structlog.contextvars.merge_contextvars,
27        structlog.stdlib.add_log_level,
28        _add_trace_context,
29        structlog.processors.TimeStamper(fmt="iso"),
30        structlog.processors.JSONRenderer(),
31    ]
32    structlog.configure(processors=processors, cache_logger_on_first_use=True)
33    logging.basicConfig(stream=sys.stdout, level=level, format="%(message)s")
34
35def configure_tracing(app: FastAPI) -> None:
36    resource = Resource.create({
37        "service.name": "genai-api",
38        "deployment.environment": os.getenv("ENVIRONMENT", "dev"),
39    })
40    provider = TracerProvider(resource=resource)
41    provider.add_span_processor(BatchSpanProcessor(OTLPSpanExporter(
42        endpoint=os.getenv("OTEL_EXPORTER_OTLP_ENDPOINT", "http://otel-collector:4317"),
43    )))
44    trace.set_tracer_provider(provider)
45    FastAPIInstrumentor.instrument_app(app, excluded_urls="health,metrics")
46
47class CorrelationIDMiddleware(BaseHTTPMiddleware):
48    async def dispatch(self, request: Request, call_next) -> Response:
49        request_id = request.headers.get("X-Request-ID", str(uuid.uuid4()))
50        structlog.contextvars.clear_contextvars()
51        structlog.contextvars.bind_contextvars(
52            request_id=request_id,
53            method=request.method,
54            path=request.url.path,
55        )
56        response = await call_next(request)
57        response.headers["X-Request-ID"] = request_id
58        return response
59
60tracer = trace.get_tracer("genai-api.llm")
61log = structlog.get_logger()
62
63async def get_completion(model: str, messages: list, max_tokens: int):
64    with tracer.start_as_current_span(
65        "llm.completion",
66        attributes={"llm.model": model, "llm.max_tokens": max_tokens},
67    ) as span:
68        log.info("llm_call_started", model=model)
69        result = await call_provider(model, messages, max_tokens)
70        span.set_attribute("llm.prompt_tokens", result.usage.prompt_tokens)
71        span.set_attribute("llm.completion_tokens", result.usage.completion_tokens)
72        log.info("llm_call_finished", tokens=result.usage.completion_tokens)
73        return result

configure_logging builds the processor chain: merge_contextvars pulls bound values (the request ID) into each entry, _add_trace_context injects the OTel trace_id and span_id, TimeStamper adds an ISO timestamp, and JSONRenderer emits the final line. configure_tracing registers a global TracerProvider and turns on FastAPI auto-instrumentation, excluding noisy health endpoints. CorrelationIDMiddleware generates or reuses an X-Request-ID and binds it once per request — every log.info(...) afterwards carries it automatically with no extra plumbing. get_completion opens a custom span so the trace viewer shows LLM latency and token counts as a dedicated bar nested inside the request's HTTP span.

You'll know it works when a single curl -H "X-Request-ID: test-123" ... produces a JSON log line containing both "request_id": "test-123" and a 32-character "trace_id", and the same trace ID is searchable in your trace backend showing the llm.completion span nested under the parent HTTP span.

Do's and Don'ts

Do's

1. ✓Do bind the correlation ID once in middleware — Threading it through every function signature is brittle; contextvars propagates it automatically across async boundaries.
2. ✓Do attach domain attributes to LLM spans — llm.model, llm.prompt_tokens, and llm.finish_reason turn a plain latency view into a cost-and-quality view.
3. ✓Do exclude health and metrics endpoints from tracing — They fire thousands of times per minute and drown useful spans in noise downstream.

Don'ts

1. ✗Don't log free-form strings in production — f"user {uid} hit error {e}" cannot be queried; emit log.error("request_failed", user_id=uid, error=str(e)) instead.
2. ✗Don't put secrets or full prompts in span attributes — Trace backends are not access-controlled like your database; redact API keys, PII, and customer prompts before they leave the process.
3. ✗Don't enable DEBUG-level logging by default — Volume explodes, storage costs balloon, and signal-to-noise collapses. Gate it on an env var you can flip per pod.