English · Español

Teoría 07 — Observabilidad para el portal del learner¶

🇪🇸 La observabilidad del portal reutiliza los tres pilares de la Fase 34 (logs, métricas, trazas) pero los reduce a la escala de un solo proceso FastAPI: structlog en JSON, prometheus_client en /metrics, y OTLP opcional hacia un Tempo local. La privacidad del estudiante es restricción dura: nunca se registran contraseñas, cookies, ni el cuerpo de los notes.

Por qué importa aquí¶

El portal es pequeño — un proceso, un archivo SQLite, ≤ 50 estudiantes — pero las preguntas operativas son idénticas a las que la Fase 34 respondió para el servidor de modelos: "¿está arriba?", "¿está lento?", "¿este request falló y por qué?". Saltarse la observabilidad porque el sistema es pequeño es el error clásico: para cuando deseas tener un gráfico de latencia p95 para /login, la regresión ya está en producción. El portal reutiliza la pila de tres pilares de la Fase 34 (logs/metrics/traces) con dos adaptaciones: (a) la disciplina de PII es más estricta — los journals del estudiante son privados; (b) el audit log es una tabla de la base de datos, no una línea de log, porque es autoritativo para la revisión de seguridad (Fase 37 §05).

Los tres pilares, portados al portal¶

Logs — `structlog` con sumidero JSON¶

Misma cadena de renderer que la teoría 03 de la Fase 34, con un binding de contexto extra (request_id, student_id).

# src/miniportal/observability.py (excerpt)
import structlog

def init_logging(level: str, json_output: bool) -> None:
    processors = [
        structlog.contextvars.merge_contextvars,
        structlog.processors.add_log_level,
        structlog.processors.TimeStamper(fmt="iso", utc=True),
    ]
    processors.append(
        structlog.processors.JSONRenderer() if json_output
        else structlog.dev.ConsoleRenderer()
    )
    structlog.configure(
        processors=processors,
        wrapper_class=structlog.make_filtering_bound_logger(
            getattr(__import__("logging"), level.upper())
        ),
    )

Conjunto canónico de campos para cada línea de log del portal:

Campo	Tipo	Notas
`request_id`	str	UUID4; acuñado en el edge si falta la cabecera `X-Request-Id`.
`student_id`	int?	Bindeado tras que el middleware de auth resuelva la sesión.
`route`	str	La plantilla de ruta FastAPI emparejada (`/phase/{nn}/notes`).
`method`	str	Verbo HTTP.
`status`	int	Código de estado HTTP.
`latency_ms`	float	Tiempo de pared desde la entrada del request hasta la emisión de la respuesta.
`event`	str	Identificador estable — `request.completed`, `login.failed`, …

Línea de ejemplo emitida al final de un save de nota exitoso:

{"timestamp":"2026-05-22T18:14:03.211Z","level":"info","event":"request.completed","request_id":"3f1a…","student_id":7,"route":"/phase/13/notes","method":"POST","status":200,"latency_ms":42.7}

Una dependencia de FastAPI acuña request_id y lo bindea antes de que cualquier handler corra:

from uuid import uuid4
import structlog
from fastapi import Header

async def bind_request_id(x_request_id: str | None = Header(default=None)) -> str:
    rid = x_request_id or str(uuid4())
    structlog.contextvars.bind_contextvars(request_id=rid)
    return rid

student_id lo bindea el middleware de auth una vez verificada la cookie de sesión — nunca antes, así el tráfico anónimo se loggea como student_id: null.

Métricas — `prometheus_client` en `/metrics`¶

Un registro, tres familias, expuestas vía el endpoint ASGI estándar.

# src/miniportal/observability.py (excerpt)
from prometheus_client import (
    CollectorRegistry, Counter, Histogram, make_asgi_app,
)

def init_metrics() -> CollectorRegistry:
    reg = CollectorRegistry()
    Histogram(
        "portal_request_duration_seconds",
        "Wall-clock duration of HTTP requests.",
        labelnames=("route", "method", "status"),
        buckets=(0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0),
        registry=reg,
    )
    Counter(
        "portal_login_attempts_total",
        "Login attempts, labeled by outcome.",
        labelnames=("ok",),  # "true" / "false"
        registry=reg,
    )
    Counter(
        "portal_invite_redemptions_total",
        "Invite-token redemptions, labeled by outcome.",
        labelnames=("ok",),
        registry=reg,
    )
    Counter(
        "portal_csrf_blocks_total",
        "Requests rejected by the CSRF middleware.",
        registry=reg,
    )
    Counter(
        "portal_ratelimit_blocks_total",
        "Requests rejected by the rate-limit middleware.",
        labelnames=("scope",),  # "ip" / "session"
        registry=reg,
    )
    Histogram(
        "portal_vault_decrypt_seconds",
        "AES-256-GCM decrypt latency for minivault columns.",
        buckets=(0.0005, 0.001, 0.0025, 0.005, 0.01, 0.025, 0.05),
        registry=reg,
    )
    return reg

La cardinalidad de etiquetas se mantiene acotada: route usa la plantilla de la ruta, no la path renderizada; status es un conjunto pequeño de enteros; ok es binario. Esta es la lección de la teoría 02 de la Fase 34 (la cardinalidad de etiquetas es la trampa), aplicada al pie de la letra.

El middleware CSRF (Fase 37) y el middleware de rate-limit (Fase 33) cada uno llaman a su contador al bloquear, antes de devolver la respuesta de error. Esa es la única escritura métrica que hace cada uno — son pass-through en todo lo demás.

Trazas — OpenTelemetry vía OTLP¶

La autoinstrumentación maneja el span del request; spans manuales envuelven las tres operaciones caras: verify de Argon2, decrypt del vault, scheduling de SM-2.

# src/miniportal/observability.py (excerpt)
from opentelemetry import trace
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor

def init_tracing(otlp_endpoint: str | None) -> None:
    if otlp_endpoint is None:
        return  # tracing is opt-in via env
    provider = TracerProvider(resource=Resource.create({"service.name": "miniportal"}))
    provider.add_span_processor(
        BatchSpanProcessor(OTLPSpanExporter(endpoint=otlp_endpoint, insecure=True))
    )
    trace.set_tracer_provider(provider)

def instrument_app(app) -> None:
    FastAPIInstrumentor.instrument_app(app, excluded_urls="/health,/metrics")

Nombres de spans manuales (identificadores estables — se convierten en términos de búsqueda de Tempo):

auth.argon2_verify — envuelve la llamada de verify de argon2-cffi.
vault.decrypt — envuelve cada decrypt AES-GCM de una columna VaultBytes.
review.sm2_update — envuelve el cómputo de la siguiente revisión SM-2 en src/minireview/.

El backend Tempo corre en docker/portal-compose.yml; el endpoint OTLP por defecto es http://tempo:4317 dentro de compose, sin setear fuera.

Qué NO loggear (disciplina de PII)¶

El portal maneja secretos y contenido privado. La lista no negociable:

Sin contraseñas en bruto. Ni en logs, ni en spans, ni en etiquetas de métricas. Nunca.
Sin hashes de contraseña. La salida de Argon2id es sensible — con pepper o sin él.
Sin master pass. PORTAL_MASTER_PASS se lee una sola vez al arrancar; el nombre de la variable de entorno se loggea a nivel debug, el valor nunca.
Sin valor de cookie de sesión. La firma de la cookie es la credencial bearer; loggearla == repartir la sesión. Loggea la huella HMAC del session_id (8 hex chars) si necesitas correlación.
Sin contenido body_markdown de notas del estudiante. El journal es el espacio privado del estudiante (teoría 04 §privacy). Loggea note.size_bytes, note.length_chars, note.id — nunca el cuerpo.
Sin respuestas de examen en plaintext. Misma regla: loggea la longitud de la respuesta y el id de la pregunta, no el texto.

El audit log es separado. Lectura/escritura de rutas sensibles de admin (GET /admin/students/{id}, POST /admin/students) escribe una fila en event_log (por arquitectura §database schema). Esa fila ES el registro autoritativo para la revisión de seguridad de la Fase 37. No es una línea de log, porque las líneas de log son best-effort y se rotan; la tabla de auditoría es duradera y consultable. Los dos streams se complementan; ninguno reemplaza al otro.

Dev local vs producción¶

Preocupación	Dev	Producción
Formato del log	`ConsoleRenderer` (coloreado, humano)	`JSONRenderer` (stdout)
Métricas	`/metrics` en el mismo puerto	`/metrics` raspado por sidecar Prometheus
Tracing	Desactivado salvo que `MINIPORTAL_OTLP_ENDPOINT` esté seteado	Siempre activo; OTLP → Tempo
Nivel de log	`DEBUG`	`INFO` (eventos de auth a `WARNING` en fallo)
Sampling	100%	100% — el volumen es pequeño

Las banderas de entorno:

MINIPORTAL_LOG_LEVEL (por defecto INFO)
MINIPORTAL_LOG_JSON (por defecto 0 en dev, 1 en prod)
MINIPORTAL_OTLP_ENDPOINT (sin setear → tracing desactivado)

Contrato de implementación para `src/miniportal/observability.py`¶

El módulo expone cuatro funciones, conectadas en app.py en este orden:

from miniportal.observability import (
    init_logging, init_metrics, init_tracing, instrument_app,
)

init_logging(level=os.getenv("MINIPORTAL_LOG_LEVEL", "INFO"),
             json_output=os.getenv("MINIPORTAL_LOG_JSON") == "1")
registry = init_metrics()
init_tracing(otlp_endpoint=os.getenv("MINIPORTAL_OTLP_ENDPOINT"))

app = FastAPI(dependencies=[Depends(bind_request_id)])
instrument_app(app)
app.mount("/metrics", make_asgi_app(registry=registry))

El middleware CSRF (src/miniserve/middlewares/csrf.py) y el middleware de rate-limit (src/miniserve/middlewares/ratelimit.py) cada uno toman el registro de métricas por inyección de dependencias e incrementan portal_csrf_blocks_total / portal_ratelimit_blocks_total{scope=…} al bloquear.

Dashboards — boceto textual¶

infra/grafana/dashboards/portal.json se entrega con tres paneles apilados:

Latencia de request (arriba): histogram_quantile(0.50|0.95|0.99, sum by (le) (rate(portal_request_duration_seconds_bucket[1m]))). Tres líneas (p50/p95/p99) sobre una ventana de 6 horas.
Salud de auth (medio): dos stats — sum(rate(portal_login_attempts_total{ok="true"}[5m])) / sum(rate(portal_login_attempts_total[5m])) para la tasa de éxito de login, y sum(increase(portal_invite_redemptions_total{ok="true"}[24h])) para canjes de invite por día.
Latencia del vault (abajo): histogram_quantile(0.95, rate(portal_vault_decrypt_seconds_bucket[1m])). Una sola línea; el camino criptográfico más lento del ciclo de vida del request.

SLOs que Borja puede fijar¶

Tres números concretos, escritos como líneas de umbral en infra/grafana/dashboards/portal.json:

SLO	Objetivo	Por qué este número
p95 latencia `/login`	< 500 ms	El verify de Argon2id domina (~50 ms) + lectura de DB + firma; 500 ms da 10× de margen.
p99 latencia `/me` (dashboard)	< 200 ms	Sin Argon2 en este camino; JOINs de DB puros. 200 ms es el umbral más allá del cual la UX se siente lenta.
Tasa de éxito de canje de invite	> 99.9% / 30d	Los fallos aquí significan que un estudiante no puede hacer onboarding; este es el camino de mayor riesgo.

Si cualquier SLO se incumple durante ≥ 30 minutos, el procedimiento de deploy del lab 06 de la Fase 41 dice: escribe un postmortem de una página en experiments/41-portal-slo-burn/<date>/.

Referencias cruzadas¶

Fase 34 — la derivación original de tres pilares (docs/phase-34-observability-cost/theory/03-tracing-and-logging.md). El portal reutiliza la cadena casi al pie de la letra; si la lista de procesadores de structlog cambia allí, cambia aquí.
Fase 37 §05 — modelo de amenazas del portal. La tabla event_log (auditoría) es el artefacto contra el que se revisan esas amenazas; logs y métricas son operativos, no forenses.
Fase 33 — las convenciones de endpoints /metrics y /health se originan aquí.

Trampas comunes¶

Bindear student_id demasiado pronto. Si lo bindeas en bind_request_id, los logs anónimos reciben un id obsoleto de una sesión anterior. Bindea en el middleware de auth, tras verificar la sesión.
Etiquetas route de alta cardinalidad. Loggear route="/phase/13/notes" vs route="/phase/14/notes" por fase explota el conteo de series temporales. Usa la plantilla de la ruta (/phase/{nn}/notes); FastAPI la expone vía request.scope["route"].path.
Olvidar excluir /metrics de la autoinstrumentación. OTel trazará su propio scrape, creando un bucle de retroalimentación en el almacenamiento de trazas. El parámetro excluded_urls de arriba es obligatorio.
Loggear el valor de la cookie "solo para depurar". No lo hagas. Si necesitas correlación, hashea la firma de la cookie con HMAC-SHA256 y loggea los primeros 8 caracteres hex.
Tratar event_log como sustituto de los logs estructurados. Los dos no son intercambiables: event_log es duradero, con schema, relevante para auditoría; los logs estructurados son best-effort, sin schema rígido, operativos.

Referencia hacia adelante¶

lab/06-deploy-and-backup.md conecta este módulo al layout de producción docker-compose: un contenedor Prometheus raspa /metrics, un contenedor Tempo recibe OTLP, y un contenedor Grafana carga portal.json. La DoD del lab incluye una captura del dashboard de tres paneles durante una prueba de carga sintética de 10 estudiantes.

Siguiente: la adición al nav en mkdocs.yml (propiedad de un agente hermano), luego lab/06-deploy-and-backup.md para el cableado de producción.