Skip to content

English · Español

Lab 02 — Tracing distribuido a través del camino de la petición

Objetivo: un árbol de spans OTel completo para una única petición LLM, visible en Tempo vía Grafana.

Tiempo estimado: 2-3 horas.

Prerrequisito: métricas del Lab 01 fluyendo; OTel-Collector corriendo en localhost:4317 desde el Lab 00.

Lo que produces

  • src/observability/tracing.py — setup del tracer provider de OTel + convenciones de atributos de span + un decorador/context manager trace_request.
  • src/observability/logging.py — configuración de structlog que inyecta trace_id + span_id en cada línea de log.
  • Servidor de la Fase 33 modificado para iniciar un span raíz por petición y spans hijos para tokenize / retrieve / prefill / decode / format.
  • Un único trace JSON de muestra exportado desde Tempo, comiteado a experiments/34-traces/sample-trace.json.

El contrato del árbol de spans

Cada petición de generación LLM emite exactamente esta jerarquía (spans hijos adicionales debajo de llm.decode están permitidos si implementas sampleo por paso):

http.handler
├── tokenize.input
├── rag.retrieve         (opcional — sólo si la petición disparó RAG)
│   ├── embed.query
│   ├── vector.search
│   └── rerank
├── llm.prefill
├── llm.decode
└── format.output

Contrato de atributos de span (ponlos de forma consistente, el dashboard depende de ellos):

Span Atributos
http.handler http.method, http.route, http.status_code, llm.model, llm.request.id
tokenize.input llm.tokens.in, tokenizer.name
rag.retrieve rag.docs.retrieved, rag.docs.reranked, rag.index.name
llm.prefill llm.tokens.in, llm.cache.hits, llm.cache.misses
llm.decode llm.tokens.out, llm.decode.steps, llm.decode.mean_step_ms, llm.stop_reason
format.output llm.tokens.out, output.format

TODOs

Bloque A — setup del tracer provider (tracing.py)

  • Usa opentelemetry-sdk + opentelemetry-exporter-otlp-proto-grpc.
  • Configura un TracerProvider con:
  • Atributos del recurso: service.name=miniserve, service.version=<git-sha>, deployment.environment=dev.
  • Span processor: BatchSpanProcessor exportando a OTLPSpanExporter(endpoint="localhost:4317", insecure=True).
  • Establécelo como el provider global.
  • Exporta tracer = trace.get_tracer("lynx-cortex.miniserve").

Bloque B — instrumentar el handler de petición del servidor

  • Envuelve el handler de nivel superior en with tracer.start_as_current_span("http.handler") as root_span: y establece los atributos del contrato.
  • En cada etapa del pipeline, abre un span hijo: with tracer.start_as_current_span("tokenize.input") as span: ....
  • Establece los atributos por span del contrato.
  • En excepción, span.record_exception(e); span.set_status(StatusCode.ERROR).

Bloque C — propagación de contexto a través de asyncio

  • La parte difícil. El generador de streaming de la Fase 33 usa asyncio.create_task para abanicar trabajo. Un create_task desnudo NO propaga contextvars correctamente para OTel. O bien:
  • Usa loop.create_task con context=contextvars.copy_context() (Python 3.11+), O
  • Usa opentelemetry.context.attach() / detach() manualmente dentro de la tarea.
  • Escribe un pequeño helper create_task_with_context(coro) que lo haga. Úsalo en todas partes.

Bloque D — logging estructurado con contexto de trace (logging.py)

  • Configura structlog con la cadena de processors del archivo de teoría 03:
import structlog
from opentelemetry import trace

def add_trace_context(logger, method_name, event_dict):
    span = trace.get_current_span()
    if span and span.get_span_context().is_valid:
        ctx = span.get_span_context()
        event_dict["trace_id"] = f"{ctx.trace_id:032x}"
        event_dict["span_id"] = f"{ctx.span_id:016x}"
    return event_dict

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        add_trace_context,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.add_log_level,
        structlog.processors.JSONRenderer(),
    ],
)
  • Reemplaza todas las llamadas existentes a logging.info(...) y print(...) en src/miniserve/ con log.info("event_name", k=v, ...) de structlog.
  • Redactor de logs: descarta cualquier clave cuyo nombre matchee prompt|completion|messages|text (regex). Default-deny.

Bloque E — verificar en Tempo

  • Ejecuta el servidor. Envía una única petición curl /v1/completions.
  • En Grafana → Explore → Tempo. Busca trazas de service.name=miniserve.
  • Abre la traza más reciente. Verifica que el árbol de spans matchea el contrato de arriba.
  • Clic en un span. Verifica que los atributos están puestos.
  • Exporta la traza como JSON (botón de la UI de Tempo) y comitea a experiments/34-traces/sample-trace.json.

Bloque F — verificar el join log/trace

  • Envía otra petición. Captura su trace_id del header de la respuesta (añade un header de respuesta X-Trace-Id en el middleware).
  • grep <trace_id> logs/miniserve.log (o stdout — donde sea que estés escribiendo logs).
  • Deberías ver 5-10 líneas de log todas llevando el mismo trace_id. Cuentan la historia de la petición.

Restricciones

  • No emitas spans por paso de decode por defecto. Agrega vía atributos en llm.decode. Por-paso es la extensión opcional.
  • No loguees cuerpos de prompt/completion. El cost tracker del Lab 03 observa conteos de tokens, no contenido.
  • Sin logging.basicConfig. Usa la configuración de structlog exclusivamente. Mezclar las dos es el bug de observabilidad (observability) más común.

Condiciones de parada

Hecho cuando:

  1. Una única petición produce un árbol de trace de 5-7 spans visible en Tempo.
  2. Cada span tiene los atributos del contrato de arriba.
  3. Cada línea de log emitida durante una petición lleva el mismo trace_id y span_id.
  4. experiments/34-traces/sample-trace.json comiteado.
  5. El lab de prompt-injection de la Fase 37 puede más adelante filtrar trazas por service.name="miniserve" AND llm.tokens.out=0 para encontrar anomalías (chequeo de compatibilidad hacia adelante — confirma que el esquema soporta la query).

Trampas (lee antes de debuggear)

  • Spans huérfanos en Tempo. Síntoma: los spans hijos aparecen como raíces. Causa: propagación de contexto rota a través de create_task o thread executor. Aplica el fix del Bloque C.
  • Sin spans en Tempo en absoluto. Comprueba docker compose logs otel-collector — issue común es el SDK fallando al conectar a localhost:4317 (firewall, puerto equivocado). Prueba la env var OTEL_EXPORTER_OTLP_INSECURE=true.
  • Atributos de span truncados. El SDK de OTel tiene un límite default de 128 chars en atributos string. Aumenta vía OTEL_ATTRIBUTE_VALUE_LENGTH_LIMIT=2048 si hace falta, pero idealmente no metas strings grandes en atributos — enlaza a un store separado.
  • Líneas de log sin trace_id. El log se emitió fuera de un span activo (p. ej., durante el arranque de la app). Está bien; sólo confirma que los logs del ciclo de vida de la petición todos lo tienen.

Cuándo consultar solutions/

Después de que las cinco condiciones de parada pasen. Solución en solutions/02-tracing-ref.md.

Siguiente lab: lab/03-cost-and-loadtest.md.