Módulo 5: Structured Logging para AI Systems

6. Debugging de Sistemas No-Determinísticos

Siguiente →

Descripción

Cuando un sistema determinístico falla, puedes reproducirlo: mismo input → mismo output → mismo error. Cuando un sistema LLM falla, esto no es automáticamente cierto: mismo input puede producir outputs distintos. Esta cápsula aborda el challenge central del debugging AI: cómo capturar suficiente contexto para reproducir un request problemático, y cómo combinar seed, temperature=0, y reproducibility logging para transformar un sistema no-determinístico en algo suficientemente determinístico para ser debuggeable.

El challenge del debugging no-determinístico

Sistema determinístico:
→ User: "Error con el input X"
→ Dev: "Reproduzco con input X"
→ Result: Mismo error, reproducible, debuggeable
→ Time to reproduce: 30 segundos

Sistema LLM no-determinístico:
→ User: "La respuesta fue rara con el input Y"
→ Dev: "Ejecuto con input Y"
→ Result: Respuesta completamente diferente, normal
→ "¿Qué modelo se usó exactamente? ¿Qué temperatura? ¿Había algún context acumulado?"
→ "No recuerdo, eso fue ayer..."
→ Time to reproduce: imposible sin logs

Sin reproducibility logging:
→ El bug existe, pero no puedes reproducirlo
→ No puedes debuggearlo
→ No puedes escribir un test para prevenir regresiones
→ No sabes cuándo está "arreglado"

Con reproducibility logging:
→ El bug ocurrió
→ Tienes el prompt exacto, modelo, temperatura, seed
→ Puedes reproducir el contexto exacto (o muy similar)
→ Puedes experimentar con fixes
→ Puedes escribir un test que captura el caso

Qué guardar para poder reproducir

# src/reproducibility.py
from dataclasses import dataclass, field
from typing import Optional, List
import hashlib
import json

@dataclass
class LLMCallContext:
    """
    Contexto completo de una llamada al LLM para reproducibilidad.
    Captura todo lo necesario para re-ejecutar el request con condiciones similares.
    """
    # Identificación
    request_id: str
    
    # Parámetros del modelo
    model: str
    temperature: float
    max_tokens: int
    seed: Optional[int] = None
    
    # El prompt (cuidado con PII)
    messages: List[dict] = field(default_factory=list)
    
    # Resultado
    raw_response: Optional[str] = None
    finish_reason: Optional[str] = None  # "stop", "length", "content_filter"
    
    # Métricas
    input_tokens: int = 0
    output_tokens: int = 0
    duration_ms: float = 0.0
    
    @property
    def messages_hash(self) -> str:
        """Hash del prompt para identificación sin exponer el contenido."""
        content = json.dumps(self.messages, sort_keys=True)
        return hashlib.sha256(content.encode()).hexdigest()[:16]
    
    @property
    def response_hash(self) -> Optional[str]:
        """Hash de la respuesta para detectar cambios."""
        if self.raw_response is None:
            return None
        return hashlib.sha256(self.raw_response.encode()).hexdigest()[:16]
    
    def to_reproduction_script(self) -> str:
        """
        Genera un script Python que puede re-ejecutar el request.
        Útil para debugging offline.
        """
        return f"""
# Reproducción del request {self.request_id}
# Generado automáticamente desde reproducibility log

from openai import OpenAI

client = OpenAI()

response = client.chat.completions.create(
    model="{self.model}",
    messages={json.dumps(self.messages, indent=4, ensure_ascii=False)},
    temperature={self.temperature},
    max_tokens={self.max_tokens},
    seed={self.seed},
)

print(response.choices[0].message.content)
"""

Cómo y cuándo loguear para reproducibilidad

# src/llm_wrapper.py (con reproducibility logging)
import structlog
from src.reproducibility import LLMCallContext

log = structlog.get_logger()

def call_llm_with_reproducibility(
    client,
    model: str,
    messages: list,
    temperature: float = 0.0,
    max_tokens: int = 500,
    seed: Optional[int] = None,
    request_id: str = None,
    debug_mode: bool = False
) -> tuple:
    """
    Llamada al LLM con logging de reproducibilidad.
    
    Siempre:
    - Hash del prompt (para identificar sin exponer)
    - model, temperature, max_tokens, seed
    - finish_reason (¿truncado? ¿stop?)
    
    Solo en ERROR:
    - Prompt truncado (primeros 500 chars)
    
    Solo en DEBUG mode:
    - Prompt completo (cuidado con PII)
    """
    ctx = LLMCallContext(
        request_id=request_id or "unknown",
        model=model,
        temperature=temperature,
        max_tokens=max_tokens,
        seed=seed,
        messages=messages
    )
    
    start = time.time()
    
    try:
        response = client.chat.completions.create(
            model=model,
            messages=messages,
            temperature=temperature,
            max_tokens=max_tokens,
            seed=seed
        )
        
        ctx.raw_response = response.choices[0].message.content
        ctx.finish_reason = response.choices[0].finish_reason
        ctx.input_tokens = response.usage.prompt_tokens
        ctx.output_tokens = response.usage.completion_tokens
        ctx.duration_ms = (time.time() - start) * 1000
        
        # INFO: hash del contexto para trazabilidad sin exponer contenido
        log.info(
            "llm_call_completed",
            model=ctx.model,
            temperature=ctx.temperature,
            seed=ctx.seed,
            messages_hash=ctx.messages_hash,
            response_hash=ctx.response_hash,
            finish_reason=ctx.finish_reason,
            input_tokens=ctx.input_tokens,
            output_tokens=ctx.output_tokens,
            duration_ms=round(ctx.duration_ms, 1)
        )
        
        # WARNING: si el response fue truncado por max_tokens
        if ctx.finish_reason == "length":
            log.warning(
                "response_truncated",
                reason="max_tokens reached",
                max_tokens=ctx.max_tokens,
                output_tokens=ctx.output_tokens,
                messages_hash=ctx.messages_hash
            )
        
        # DEBUG: prompt completo (solo si está habilitado)
        if debug_mode:
            # Solo primeros 500 chars para reducir tamaño incluso en debug
            prompt_preview = ""
            if messages:
                last_msg = messages[-1].get("content", "")
                prompt_preview = last_msg[:500]
                if len(last_msg) > 500:
                    prompt_preview += f"...[{len(last_msg)} total chars]"
            
            log.debug(
                "llm_reproducibility_context",
                model=ctx.model,
                temperature=ctx.temperature,
                seed=ctx.seed,
                max_tokens=ctx.max_tokens,
                prompt_preview=prompt_preview,
                response_preview=(ctx.raw_response or "")[:300]
            )
        
        return response, ctx
    
    except Exception as e:
        ctx.duration_ms = (time.time() - start) * 1000
        
        # ERROR: incluir más contexto porque necesitamos debuggear
        prompt_preview = ""
        if messages:
            last_msg = messages[-1].get("content", "")
            prompt_preview = last_msg[:300]  # Más contexto en error
        
        log.error(
            "llm_call_failed",
            error_type=type(e).__name__,
            error_message=str(e)[:300],
            model=ctx.model,
            temperature=ctx.temperature,
            seed=ctx.seed,
            messages_hash=ctx.messages_hash,
            prompt_preview=prompt_preview,  # En error: más contexto
            duration_ms=round(ctx.duration_ms, 1)
        )
        raise

seed: el parámetro que (casi) hace al LLM determinístico

# ¿Qué hace seed?
# Cuando especificas seed, el modelo debería producir la misma respuesta
# para el mismo input y los mismos parámetros.
# OpenAI lo llama "reproducibility" y la propiedad system_fingerprint
# confirma cuándo la implementación subyacente del modelo no cambió.

import openai

response = openai.chat.completions.create(
    model="gpt-4o-mini",
    messages=[{"role": "user", "content": "¿Cuál es la capital de Francia?"}],
    temperature=0.0,    # temperature=0 reduce varianza
    seed=42             # seed hace la respuesta reproducible
)

# system_fingerprint indica la versión del modelo:
fingerprint = response.system_fingerprint
# "fp_13c70b9f70" — si este cambia, la respuesta puede cambiar aunque seed sea igual

# Loguear el fingerprint:
log.info("llm_call_completed",
    ...,
    seed=42,
    system_fingerprint=response.system_fingerprint
)
# Si el fingerprint cambia entre dos calls con el mismo seed,
# la respuesta puede haber cambiado no por tu código sino por una
# actualización del modelo en el servidor de OpenAI.

# Importante: seed NO garantiza 100% reproducibilidad
# → Si system_fingerprint cambia, la respuesta puede cambiar
# → Es "best effort" según OpenAI
# → Para debugging funciona muy bien, no para garantías absolutas

temperature: el control de varianza

# Cómo temperature afecta la reproducibilidad:

# temperature=0.0: Completamente greedy — siempre elige el token más probable
# → Muy alta reproducibilidad (casi siempre la misma respuesta)
# → Bueno para: clasificación, extracción, análisis estructurado
# → Malo para: generación creativa, brainstorming

# temperature=0.3: Bajo pero con algo de varianza
# → Buena para: resúmenes, respuestas con cierta flexibilidad
# → Reproducibilidad moderada

# temperature=0.7 (default de muchos modelos): Alta varianza
# → Para: generación creativa
# → Baja reproducibilidad — el mismo input puede dar respuestas muy distintas

# temperature=1.0+: Muy alta varianza, a veces incoherente
# → Raramente útil en producción

# RECOMENDACIÓN para apps de análisis (como análisis de sentimiento):
# → temperature=0.0 para máxima consistencia
# → Solo usar temperature > 0 si genuinamente necesitas variedad de respuestas

response = client.chat.completions.create(
    model="gpt-4o-mini",
    messages=messages,
    temperature=0.0,   # Para análisis: siempre 0.0
    seed=42,           # Para debugging: siempre especificar
    max_tokens=500
)

Workflow completo de debugging con reproducibility logs

ESCENARIO: Usuario reporta que el análisis de sentimiento de su review
"El producto llegó tarde pero el soporte fue excelente" 
fue clasificado como "negative" cuando debería ser "mixed".

PASO 1: El usuario reporta el error con el request_id
→ Usuario: "request_id: a7b3c9d2"

PASO 2: Buscar en logs
$ jq 'select(.request_id == "a7b3c9d2")' logs.json | jq -s 'sort_by(.timestamp)'

Output:
{"event": "request_started", "request_id": "a7b3c9d2", "timestamp": "..."}
{"event": "llm_call_completed", "request_id": "a7b3c9d2",
 "messages_hash": "abc123", "model": "gpt-4o-mini",
 "temperature": 0.7, "seed": null, "finish_reason": "stop",
 "input_tokens": 156, "output_tokens": 43, "timestamp": "..."}
{"event": "request_completed", "request_id": "a7b3c9d2",
 "result": {"sentiment": "negative"}, "timestamp": "..."}

PASO 3: Identificar el problema
→ temperature=0.7 (alta varianza) — eso explica el resultado inconsistente
→ Sin seed — no podemos reproducir exactamente
→ El modelo generó "negative" en este run, pero puede generar "mixed" en otro

PASO 4: Reproducir (con low temperature para estabilizar)
$ python scripts/reproduce_request.py \
    --model "gpt-4o-mini" \
    --temperature 0.7 \
    --seed 42 \
    --messages-hash "abc123"

→ Con temperature=0.7, la respuesta varía. Confirmado: el sistema es inestable

PASO 5: Diagnosis
→ Para análisis de sentimiento, temperature=0.7 es demasiado alto
→ Fix: cambiar a temperature=0.0

PASO 6: Validar el fix
→ Con temperature=0.0, el mismo input siempre da "mixed"
→ Fix validado

PASO 7: Escribir el test de regresión
def test_mixed_sentiment_stable():
    """Input con sentimientos mixtos debe dar 'mixed', no 'negative'."""
    result = analyze_sentiment(
        "El producto llegó tarde pero el soporte fue excelente"
    )
    assert result.sentiment == "mixed"

Script de reproducción

# scripts/reproduce_from_logs.py
"""
Script que lee un request_id de los logs y genera el código
para reproducir la llamada al LLM.

Uso: python scripts/reproduce_from_logs.py <request_id> [log_file]
"""
import json
import sys
from pathlib import Path

def find_llm_call_log(request_id: str, log_file: str = "logs/app.json") -> dict:
    """Busca el log de llamada al LLM para un request_id."""
    with open(log_file) as f:
        for line in f:
            line = line.strip()
            if not line:
                continue
            try:
                entry = json.loads(line)
                if (entry.get("request_id") == request_id and
                    entry.get("event") == "llm_reproducibility_context"):
                    return entry
            except json.JSONDecodeError:
                pass
    return None

def generate_reproduction_script(log_entry: dict) -> str:
    """Genera un script Python para reproducir la llamada."""
    
    model = log_entry.get("model", "gpt-4o-mini")
    temperature = log_entry.get("temperature", 0.0)
    seed = log_entry.get("seed")
    max_tokens = log_entry.get("max_tokens", 500)
    prompt_preview = log_entry.get("prompt_preview", "[No prompt available]")
    
    seed_line = f"    seed={seed}," if seed is not None else "    # seed not available"
    
    return f'''#!/usr/bin/env python
"""
Reproducción del request: {log_entry.get("request_id")}
Generado por: scripts/reproduce_from_logs.py
NOTA: El prompt es un preview — puede estar truncado.
"""
from openai import OpenAI

client = OpenAI()

# NOTA: El prompt completo puede no estar disponible si
# el log fue generado con debug_mode=False.
# Usa el prompt real para una reproducción exacta.
prompt = """{prompt_preview}"""

response = client.chat.completions.create(
    model="{model}",
    messages=[{{"role": "user", "content": prompt}}],
    temperature={temperature},
    max_tokens={max_tokens},
{seed_line}
)

print("Response:", response.choices[0].message.content)
print("Finish reason:", response.choices[0].finish_reason)
'''

if __name__ == "__main__":
    request_id = sys.argv[1] if len(sys.argv) > 1 else None
    log_file = sys.argv[2] if len(sys.argv) > 2 else "logs/app.json"
    
    if not request_id:
        print("Usage: python reproduce_from_logs.py <request_id> [log_file]")
        sys.exit(1)
    
    entry = find_llm_call_log(request_id, log_file)
    
    if not entry:
        print(f"No reproducibility log found for request_id: {request_id}")
        print("Note: Reproducibility logs are only generated in debug_mode=True")
        sys.exit(1)
    
    script = generate_reproduction_script(entry)
    output_file = f"reproduce_{request_id}.py"
    
    with open(output_file, "w") as f:
        f.write(script)
    
    print(f"Reproduction script generated: {output_file}")
    print(f"Run: python {output_file}")

Ejercicios

Ejercicio 1: Identificar por qué no puedes reproducir

Dado este log, explica por qué es difícil reproducir exactamente el request:

{"event": "llm_call_completed", "model": "gpt-4o", "temperature": 0.8,
 "seed": null, "finish_reason": "stop", "request_id": "z9x8w7v6"}
Ver solución

Tres problemas:

  1. temperature=0.8 es alta — el modelo tiene mucha varianza en sus respuestas. Mismo input puede dar outputs muy diferentes en distintas llamadas.

  2. seed=null — sin seed, no hay forma de pedir al modelo que intente reproducir el mismo resultado. La aleatoriedad es completamente libre.

  3. No hay prompt en el log — sin el prompt exacto, ni siquiera puedes intentar reproducir. Solo tienes el hash.

Para mejorar: usar temperature=0.0 para análisis determinístico, siempre especificar seed, y en modo debug loguear el prompt.

Ejercicio 2: Diseñar la política de reproducibility logging

Para una app con usuarios reales, define:

  1. ¿Qué loguear siempre?
  2. ¿Qué loguear solo en ERROR?
  3. ¿Qué solo en DEBUG mode?
Ver guía

Siempre (INFO):

  • model, temperature, seed (si se usa)
  • messages_hash, response_hash
  • finish_reason, input_tokens, output_tokens

Solo en ERROR (necesitas más contexto para debuggear):

  • Primeros 300 chars del prompt (puede tener PII → usar con cuidado o redactar)
  • system_fingerprint (para correlacionar con cambios de modelo)
  • messages completos si la app tiene acceso legal y hay consentimiento

Solo en DEBUG mode (explícitamente habilitado):

  • Prompt completo (con redacción de PII)
  • Respuesta completa
  • Todo el objeto messages[]

Ejercicio 3: finish_reason

¿Por qué es importante loguear finish_reason?

Ver guía

finish_reason indica por qué el modelo dejó de generar:

  • "stop": terminó normalmente — lo esperado
  • "length": se alcanzó max_tokens — la respuesta fue truncada, puede estar incompleta. Esto puede causar JSON inválido si el output es JSON estructurado.
  • "content_filter": el contenido fue filtrado por la moderación de OpenAI
  • "tool_calls": el modelo quiere llamar a una herramienta

Si tu app tiene errores de parsing de JSON y el finish_reason es "length", la causa es clara: aumentar max_tokens o truncar el input.

Resumen

  • Reproducibilidad no es determinismo: no pedimos que el LLM sea 100% predecible, sino que capturemos suficiente contexto para acercarnos lo máximo posible
  • temperature=0.0 para análisis: máxima consistencia, mismos resultados en la mayoría de casos
  • seed junto a temperature=0.0: la combinación más efectiva para reproducibilidad
  • system_fingerprint: permite detectar cuándo el modelo cambió en el servidor, no en tu código
  • Siempre loguear: model, temperature, seed, messages_hash, finish_reason
  • En ERROR: más contexto (prompt preview) para poder diagnosticar
  • El workflow: request_id → logs → params → script de reproducción → diagnóstico

Recursos adicionales

  1. OpenAI — Reproducible outputs — Documentación de seed en OpenAI
  2. OpenAI API Reference — seed — Parámetro seed
  3. Temperature in LLMs — Cómo funciona temperature
  4. Debugging ML systems — Técnicas de debugging para sistemas ML
← Anterior5. JSON Logs con structlogSiguiente →7. Proyecto: AI Logging System