Skip to content

English · Español

03 — Tracing y logging estructurado

🇪🇸 Métricas resumen, trazas explican. Una métrica te dice "el p95 subió"; una traza te dice "esta petición concreta esperó 4 segundos en la cola del batcher porque el slot del KV cache estaba lleno". Los logs estructurados son el pegamento — trace_id une todo.

Las métricas agregan; no apuntan con precisión. Cuando la latencia p95 sube, las métricas te dicen que subió; no te dicen por qué esta petición concreta fue lenta. Ese es el trabajo del tracing.

Una traza (trace) es un árbol de spans causalmente enlazados, donde cada span representa una unidad de trabajo con un tiempo de inicio, una duración y atributos clave-valor. El árbol de la traza muestra cómo una petición lógica fluyó por las etapas del servicio.

Anatomía de un span

Un span es una 4-tupla:

{
  "trace_id": "<128-bit hex>",   # mismo en todos los spans de la traza
  "span_id":  "<64-bit hex>",     # único para este span
  "parent_span_id": "<64-bit hex>",  # el span que causó este
  "name": "decode_step",
  "start_unix_nano": 1716_xxx_xxx_xxx,
  "duration_nano": 234_000_000,
  "attributes": {"llm.model": "minigpt-v1", "llm.tokens.in": 128, "llm.tokens.out": 7},
  "events":  [{...}],  # eventos discretos dentro del span
  "status":  {"code": "OK"},
}

OpenTelemetry (OTel) define este esquema; el SDK de Python proporciona tracer.start_as_current_span(...) para emitir uno.

El árbol de traza para una petición LLM

Una jerarquía de spans razonable para una petición de la Fase 33:

http.handler              (raíz)
├── auth                  (10 ms)
├── tokenize.input        (3 ms; attrs: tokens.in=128)
├── rag.retrieve          (45 ms; attrs: docs.retrieved=3)
│   ├── embed.query       (15 ms)
│   ├── vector.search     (8 ms; attrs: top_k=10)
│   └── rerank            (20 ms)
├── llm.prefill           (180 ms; attrs: tokens.in=128, cache_misses=2)
├── llm.decode            (2400 ms)
│   ├── decode.step       (10 ms; un span por paso O muestreado)
│   ├── decode.step       (10 ms)
│   └── ...
└── format.output         (5 ms)

Este es aproximadamente el árbol de spans que construye el tracing.py de la Fase 34.

Advertencia práctica: los spans por paso explotan. Una generación de 240 tokens = 240 spans decode.step = abotargamiento. Dos opciones:

  1. Muestrear. Emitir spans decode.step para el 1% de los decodes. El span padre agregado llm.decode aún captura la duración total.
  2. Agregar. Emitir un único span llm.decode con attributes={"steps": 240, "mean_step_ms": 10.0, "max_step_ms": 18.2}.

Usamos (2) por defecto; (1) es la extensión opcional del laboratorio.

Propagación de contexto

La parte difícil de OTel en Python es asegurarse de que el trace_id y el span_id padre se propagan correctamente a través de:

  • fronteras async (await),
  • creación de tareas (asyncio.create_task),
  • fronteras de hilos (run_in_executor),
  • invocaciones de subprocesos (no en la Fase 34 — eso es Fase 31 en adelante),
  • llamadas HTTP (la instrumentación HTTP de OTel se encarga de esto para clientes/servidores).

El start_as_current_span por defecto usa los contextvars de Python, que se propagan a través de await correctamente pero no a través de asyncio.create_task a menos que lo envuelvas. El servidor de la Fase 33 usa asyncio; el laboratorio fuerza a Borja a pensar en un caso explícito (el EventSourceResponse streaming para SSE) donde la propagación de contexto se rompe si no se corrige.

Diagnóstico: spans huérfanos (spans cuyo parent_span_id no está puesto, pero cuyo nombre implica que deberían ser hijos) son el síntoma. Tempo/Jaeger los renderiza como raíces flotantes; deberían ser cero en un setup correcto.

Cardinalidad y muestreo para trazas

A diferencia de las métricas, las trazas sí pueden permitirse etiquetas por petición — el propio trace_id es la etiqueta por petición, y el backend de almacenamiento (Tempo) las indexa eficientemente. Pero aún así no quieres volumen de trazas infinito.

Estrategia de muestreo: para el volumen del currículo (tests de carga de la Fase 34 ≤100 RPS durante 5 minutos = ~30k trazas), guarda el 100%. En producción, el muestreo "head-based" (decidir en el span raíz si conservar) es el por defecto; "tail-based" (decidir después de ver la traza entera) es la variante astuta pero cara.

Para referencia adelantada a la Fase 37: el muestreo tail-based te deja conservar el 100% de las trazas fallidas o anómalas mientras tiras la mayoría de las exitosas. Así es como preservas las trazas de ataques de prompt injection para análisis forense sin reventar el almacén de trazas.

Logging estructurado

Los logs no son strings; son eventos con payloads clave-valor, serializados como JSON, una línea por evento.

structlog es la librería. El cableado:

import structlog, logging
structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        add_trace_context,                       # custom: extrae trace_id/span_id de OTel
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.add_log_level,
        structlog.processors.JSONRenderer(),
    ],
)
log = structlog.get_logger()
log.info("request.received", endpoint="/v1/completions", model="minigpt-v1")
# → {"timestamp": "2026-05-22T...", "level": "info", "trace_id": "...", "span_id": "...", "event": "request.received", "endpoint": "/v1/completions", "model": "minigpt-v1"}

Cada línea de log lleva trace_id y span_id. Esa es la magia que te deja ir de un dashboard de Grafana (un pico de métrica a las 14:32) a la traza afectada (filtra Tempo por service.name="miniserve" en el rango temporal) a las líneas de log subyacentes para esa traza.

Qué loguear, qué no loguear

Loguea:

  • Cada petición recibida (event=request.received, con method, endpoint, model, recuento de tokens del prompt).
  • Cada error (event=request.failed, con clase de error, etapa, recuento de tokens del prompt).
  • Cambios de estado significativos (event=batcher.slot.evicted, event=kv_cache.full).

NO loguees:

  • El cuerpo del prompt (PII; sensible; grande). Va en el atributo de span de traza bajo un feature flag — nunca en la métrica, nunca en el log.
  • El cuerpo del completion. Igual.
  • Eventos por token. Demasiado ruidosos.
  • Pings de health-check. Filtra en la capa del access-log.

El laboratorio hace que Borja escriba un paso log_redactor que limpia cualquier cosa que machee prompt, completion, messages, text de los payloads de log. Default-deny.

La tríada: métricas + trazas + logs unidos

Las tres señales están unidas por trace_id (y solo por trace_id). Una vez que lo tienes:

  • Haz clic en un pico de métrica en Grafana → consulta Tempo para trazas en esa ventana temporal → escoge una traza → ve el árbol de spans → haz clic en un span → consulta Loki/logs estructurados para líneas de log con ese trace_id.

La cadena es una única herramienta (Grafana) con tres fuentes de datos. El infra/compose/observability.yml de la Fase 34 levanta las tres localmente.

Langfuse: cuándo y por qué

Langfuse es una UI de tracing específica para LLM que se puede auto-alojar. Se solapa con Tempo + Loki pero añade:

  • Renderizado nativo de prompts y completions lado a lado.
  • Metadatos a nivel de token como concepto de primera clase.
  • Scoring de eval integrado (LLM-as-judge) anclado a trazas.

Para la Fase 34, Langfuse es opcional. La pila OTel + Tempo + Loki es suficiente para el DoD. Langfuse es la herramienta adecuada si la Fase 37 (prompt injection) quiere usar el almacén de trazas como fixture de test de regresión — y el laboratorio de la Fase 37 sí planea usarlo así. Punto de decisión: añadir Langfuse al fichero compose en la Fase 34 o en la Fase 37. Por defecto: posponerlo a la Fase 37.

Un ejemplo trabajado: tracing un bug real

Supón que los usuarios se quejan de que una de cada cincuenta completions está vacía (cero tokens). Investigación solo con métricas:

  1. rate(http_requests_total{status="200"}[5m]) confirma que la mayoría son 200.
  2. histogram_quantile(0.5, generation_length_tokens_bucket) es normal.
  3. Pero histogram_quantile(0.01, generation_length_tokens_bucket) muestra un pico en 0 tokens. Así que el bug es real, y está en la cola izquierda.

Sin trazas, no tienes forma de encontrar una petición mala representativa. Con trazas:

  1. En Tempo, busca spans donde llm.tokens.out = 0. Sacas 30 trazas.
  2. Escoge una. Ves: el span llm.decode terminó tras 5 ms — demasiado rápido con diferencia.
  3. Mira los atributos del span: stop_reason="immediate_eos".
  4. Filtra logs por el trace_id de esa traza. Ves: evento kv_cache.full eviction en medio del prefill, que corrompió el estado de la cache para ese slot del batch.
  5. Causa raíz encontrada en 5 minutos. Sin tracing, esto es una investigación de varios días.

Este tipo de investigación es la razón entera por la que existe el tracing. Asegúrate de que Borja experimenta al menos una de ellas en el laboratorio.

Recapitulación en un párrafo

El tracing construye un árbol de spans causal por petición vía OpenTelemetry; el logging estructurado emite eventos JSON indexados por trace_id/span_id; los dos se unen vía ese id, de modo que pico de métrica → trazas relevantes → líneas de log relevantes es un único flujo de trabajo. La propagación de contexto en Python requiere cuidado a través de asyncio.create_task y de fronteras de hilo; los spans huérfanos son el diagnóstico. No loguees prompts ni completions (PII + abotargamiento); guarda esos en atributos de span de traza bajo un feature flag. Langfuse es opcional — pospónlo a la Fase 37 a menos que la UI específica de LLM se necesite antes.

Hecha la teoría. Pasa a lab/00-prom-grafana-up.md.