English · Español

Break 00 — Emitir logs sin correlación de request-id, debuggear una traza multi-tenant¶

🇪🇸 Sin request-id, los logs de dos peticiones concurrentes se interleavan y no puedes separar "qué le pasó al estudiante A" de "qué le pasó al estudiante B". Este /break quita ese campo, dispara una carga de 8 clientes y muestra que la traza es ilegible.

Lo que harás¶

Eliminar el campo request_id del emisor de logs estructurados de modo que las peticiones concurrentes interleaven sus líneas de log de forma indistinguible. Dirigir el servidor con un script de carga multi-tenant y observar cómo el log de auditoría se vuelve inservible.

Paso 1 — Localiza el logger¶

src/miniobs/logging.py            # el logger estructurado (Fase 34 lab 01)
src/miniserve/middleware.py       # el middleware de request-id que lo inyecta

Paso 2 — Introduce el bug¶

En src/miniobs/logging.py, el formateador JSON incluye actualmente request_id desde el context-local. Quítalo:

# OLD
extra = {
    "request_id": ctx.get("request_id"),
    "student_id": ctx.get("student_id"),
    "ts": ts,
    ...
}

# NEW (the broken version)
extra = {
    # "request_id": ctx.get("request_id"),   # commented out
    "student_id": ctx.get("student_id"),
    "ts": ts,
    ...
}

Una línea comentada. El middleware sigue generando el id; el formateador simplemente deja de incluirlo.

Paso 3 — Registra el break¶

learners/borja/phase-34/notes/breaks.md:

- bug-id: 34-01
  concept: log correlation / multi-tenant trace
  symptom: under 8 concurrent students, the audit log shows interleaved lines
           with no way to attribute "which log line belongs to which request".
  hidden_cause: logging.py's JSON formatter no longer emits the request_id field.
                The middleware still generates the id, but it never reaches stdout.
  hint_1: "Tail the audit log under load. Can you trace a single request end-to-end?"
  hint_2: "What field would you `jq` on to filter for one request?"
  hint_3: "diff src/miniobs/logging.py against last week's commit. What disappeared?"
  fix_diff: uncomment the request_id line in logging.py's formatter.

Paso 4 — Verifica que es observable¶

Ejecuta la prueba de carga trazada del lab 02 con 8 estudiantes concurrentes. Esperado antes del break:

$ jq 'select(.request_id == "req-abc123")' audit.log
{"ts":"2026-05-23T10:00:01Z","request_id":"req-abc123","student_id":"alice","event":"tutor.received"}
{"ts":"2026-05-23T10:00:01Z","request_id":"req-abc123","student_id":"alice","event":"tutor.tokenized"}
{"ts":"2026-05-23T10:00:01Z","request_id":"req-abc123","student_id":"alice","event":"tutor.completed","latency_ms":148}

Tras el break:

$ jq 'select(.request_id == "req-abc123")' audit.log
# (empty — the field doesn't exist)

$ tail -n 8 audit.log
{"ts":"...","student_id":"alice","event":"tutor.received"}
{"ts":"...","student_id":"bob","event":"tutor.received"}
{"ts":"...","student_id":"alice","event":"tutor.tokenized"}
{"ts":"...","student_id":"carol","event":"tutor.received"}
{"ts":"...","student_id":"bob","event":"tutor.tokenized"}
{"ts":"...","student_id":"alice","event":"tutor.completed","latency_ms":148}
{"ts":"...","student_id":"carol","event":"tutor.completed","latency_ms":1320}
{"ts":"...","student_id":"bob","event":"tutor.completed","latency_ms":910}

Las líneas pertenecen al mismo estudiante en algunos casos (alice) pero no puedes saber cuál de las dos peticiones de alice terminó a 148 ms, especialmente cuando alice reintenta.

Los tests tests/phase34/test_logging.py::test_request_id_present se ponen en rojo.

Paso 5 — El momento didáctico¶

La correlación por request-id es el campo más importante en un sistema multi-tenant. Sin él:

El tracing distribuido (Fase 34 teoría 03) es imposible.
El soporte al cliente ("¿qué le pasó al estudiante X a las 10:03?") requiere adivinar.
Debuggear un único outlier de latencia desde un flame graph es no-determinista.

El fix es una línea descomentada; la lección es que el esquema del log es una interfaz, igual que el esquema de la API, y eliminar un campo de él es un cambio breaking.

Hard rules respetadas¶

Bug único e instructivo.
Reversible en 1 línea.
Observable: la aserción del test se pone en rojo, el filtro de jq devuelve vacío.
Sin impacto de seguridad.
Sin test modificado.

Siguiente: cuando esté verde, lee ../theory/03-tracing-and-logging.md para el esquema canónico.