Observability: logging, metrics, tracing
Cómo entender el estado interno de un sistema en producción desde sus outputs externos —logs, métricas y traces— sin tener que shipear código nuevo para responder una pregunta. Enfoque senior: qué monitorear para garantizar cada atributo de calidad, cómo trazar un request entre servicios y cómo configurar rotación/alerting sin ahogarse en ruido.
Teoría
Monitoring vs observability: por qué la distinción importa
Monitoring responde preguntas que definiste de antemano: dashboards, umbrales, alertas sobre métricas conocidas. Te dice “algo se cayó”. Observability es una propiedad del sistema: la capacidad de inferir su estado interno desde sus salidas externas, incluso para preguntas que no anticipaste, sin desplegar código nuevo.
El test honesto de observabilidad: cuando ocurre un incidente que nunca viste antes, ¿podés responder “¿por qué pasó?” solo consultando lo que el sistema ya emite? Si tenés que agregar un print, redeployar y esperar a que se repita, tu sistema no es observable.
El anti-patrón clásico: dashboards en verde (CPU OK, memoria OK, error rate OK) mientras el 12% de las transacciones se pierden silenciosamente. La causa es siempre la misma: se midió infraestructura (cpu_usage) en lugar de negocio (payment_success_rate). CPU es un síntoma; la métrica de negocio te dice si el síntoma importa.
Los 3 pilares y qué pregunta responde cada uno
| Pilar | Qué captura | Pregunta | Cardinalidad | Coste |
|---|---|---|---|---|
| Logs | Eventos discretos con contexto completo | ¿Qué pasó exactamente en este request? | Alta (cada evento) | Alto storage |
| Metrics | Valores numéricos agregados en el tiempo | ¿Cuánto / cuán seguido / qué tan rápido? | Baja (series por labels) | Bajo, barato |
| Traces | Camino de un request entre servicios | ¿Dónde se fue el tiempo? | Media (sampled) | Medio |
No son intercambiables, son complementarios y se usan en ese orden durante un incidente:
1. Metric alerta: P99 latency > 3s en los últimos 5 min
2. Trace localiza: payment-service.call_stripe() span = 5002ms ← el 92% del tiempo
3. Log explica: filtrar por trace_id → "Stripe rate limit 429, retry backoff 4800ms"
Root cause: un load test sin gate disparó el rate limit de Stripe.
Time to root cause: < 6 min.
Sin traces, el paso 2 es arqueología manual cruzando timestamps entre 12 log streams. Sin logs estructurados, el trace te lleva al servicio lento pero no al detalle (“¿por qué ese span tardó?”). Sin métricas, te enterás por un usuario y no por un dashboard. La pieza que los une es el trace_id / correlation_id: cada log debe llevarlo, cada métrica debe estar tagueada por servicio+endpoint+status, cada span forma parte de él. OpenTelemetry es el estándar que emite los tres correlacionados desde un solo SDK.
Structured logging: JSON, no texto libre
Un log de texto libre no es queryable sin regex frágiles. Un log estructurado es un objeto JSON con campos consistentes que el aggregator (ELK, Loki, CloudWatch, Datadog) indexa y filtra.
# Malo — texto libre: el collector no puede filtrar por order_id sin regex
logger.info(f"Order {order_id} created by user {user_id} in {elapsed}ms")
# Bueno — structured JSON
import structlog
log = structlog.get_logger()
log.info(
"order.created", # el "event" es una key estable, no una frase
order_id=str(order_id),
user_id=str(user_id),
elapsed_ms=elapsed,
items_count=len(order.items),
)
# Output: {"event": "order.created", "order_id": "abc", "user_id": "42",
# "elapsed_ms": 23, "timestamp": "...", "level": "info"}
Setup de structlog que produce JSON en producción y salida legible con colores en dev (el mismo pipeline, distinto renderer final):
import logging
import sys
import structlog
def configure_logging(json_logs: bool, level: str = "INFO") -> None:
shared_processors = [
structlog.contextvars.merge_contextvars, # inyecta correlation_id, etc.
structlog.processors.add_log_level,
structlog.processors.TimeStamper(fmt="iso", utc=True),
structlog.processors.StackInfoRenderer(),
structlog.processors.format_exc_info, # exc_info -> stack trace en un campo
]
renderer = (
structlog.processors.JSONRenderer() if json_logs
else structlog.dev.ConsoleRenderer()
)
structlog.configure(
processors=[*shared_processors, renderer],
wrapper_class=structlog.make_filtering_bound_logger(
logging.getLevelName(level)
),
logger_factory=structlog.PrintLoggerFactory(file=sys.stdout),
cache_logger_on_first_use=True,
)
Regla dura: nunca loguear datos sensibles (passwords, tokens, PANs de tarjeta, PII). Se loguean IDs, no valores. En sistemas regulados, un processor de redacción en el pipeline de structlog es defensa en profundidad (filtra por key: password, authorization, card_number).
Correlation / request IDs: el hilo que une todo
Un correlation ID (o request ID) es un identificador —típicamente un UUID— generado en el borde del sistema (por el cliente o por el primer servicio que recibe el request) y propagado en headers a cada servicio downstream, e incluido en cada log de ese request. Sin él, debuggear una falla multi-servicio significa correlacionar timestamps a mano entre streams distintos, quizás 10.000 líneas en una ventana de 2 segundos. Con él, hacés una query: correlation_id = abc123 y ves la cadena completa.
El mecanismo correcto en Python async es contextvars (no thread-locals: async multiplexa muchos requests en un thread; una variable global se pisaría entre corrutinas). structlog.contextvars se apoya justamente en contextvars.ContextVar, que es seguro por tarea:
from uuid import uuid4
import structlog
from starlette.types import ASGIApp, Receive, Scope, Send
class CorrelationIdMiddleware:
"""ASGI puro: no rompe streaming ni background tasks como BaseHTTPMiddleware."""
def __init__(self, app: ASGIApp) -> None:
self.app = app
async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
if scope["type"] != "http":
return await self.app(scope, receive, send)
headers = dict(scope["headers"])
incoming = headers.get(b"x-correlation-id")
correlation_id = incoming.decode() if incoming else str(uuid4())
structlog.contextvars.clear_contextvars()
structlog.contextvars.bind_contextvars(correlation_id=correlation_id)
async def send_with_header(message):
if message["type"] == "http.response.start":
message["headers"].append(
(b"x-correlation-id", correlation_id.encode())
)
await send(message)
await self.app(scope, receive, send_with_header)
A partir de este bind, todos los logs emitidos durante el request llevan correlation_id sin pasarlo explícitamente. Cuando además usás OpenTelemetry, se suele inyectar el trace_id/span_id del span activo en cada log (processor de OTel para structlog), de modo que desde un log podés saltar al trace y viceversa.
Log levels: cuándo usar cada uno
| Nivel | Cuándo | Acción esperada |
|---|---|---|
| DEBUG | Detalle de desarrollo (queries SQL, payloads). Off en prod. | Ninguna |
| INFO | Eventos de negocio normales (order.created, payment.processed) | Ninguna, es el “diario” |
| WARNING | Inesperado pero el sistema sigue (retry, cache miss, degraded mode) | Revisar si el patrón crece |
| ERROR | Falló algo que afectó a un usuario (excepción no manejada, pago rechazado) | Investigar |
| CRITICAL | El sistema no puede operar (DB caída, disco lleno) | Página inmediata |
El nivel es un filtro configurable por entorno, no una decisión de código: dev en DEBUG, prod en INFO. Esto es exactamente una de las diferencias entre local y prod deployment (junto con secrets manager, debug mode, environment). Anti-patrón: INFO verboso que loguea cada paso sin valor de ciclo de vida — infla costos de ingestión y esconde las líneas que importan.
Log rotation y configuraciones avanzadas
Los logs a archivo crecen sin límite y llenan el disco (alerta clásica: disk > 85%). La rotación cierra el archivo actual, lo archiva (a veces comprimido) y abre uno nuevo, reteniendo solo N archivos.
En Python hay dos handlers nativos:
import logging
from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler
# Por tamaño: rota al llegar a 50 MB, conserva 5 backups (app.log.1 ... app.log.5)
size_handler = RotatingFileHandler(
"app.log", maxBytes=50 * 1024 * 1024, backupCount=5, encoding="utf-8",
)
# Por tiempo: rota a medianoche, conserva 14 días
time_handler = TimedRotatingFileHandler(
"app.log", when="midnight", interval=1, backupCount=14, utc=True,
)
Trampa senior con múltiples procesos: RotatingFileHandler NO es seguro entre procesos. Con gunicorn corriendo varios workers, cada uno tiene su file descriptor; cuando uno rota (rename + reopen), los demás siguen escribiendo al inode viejo ya renombrado → logs perdidos o corruptos. Opciones correctas:
- No rotar en la app. En contenedores, logueá a stdout/stderr y dejá que el runtime rote: Docker (
json-fileconmax-size/max-file, o driverlocal), Kubernetes (rotación del kubelet), o un sidecar. Es la práctica cloud-native (Twelve-Factor: los logs son un stream de eventos, no responsabilidad de la app). logrotateexterno (VM/bare metal) con la directivacopytruncateo enviandoSIGHUP/reopen a la app; combinado conWatchedFileHandler(reabre el archivo si el inode cambió).concurrent-log-handler(ConcurrentRotatingFileHandler), que usa file locks y es multiproceso-safe si de verdad necesitás rotar en la app.
Regla mental: en prod distribuido, centralizás (los tres pilares van a un backend externo) y la rotación local pasa a ser solo un buffer de emergencia.
Métricas: RED, USE y las Four Golden Signals
Tres frameworks complementarios, cada uno para un tipo de objeto:
- RED (Tom Wilkie) — para servicios request-driven (tu API):
- Rate: requests por segundo.
- Errors: proporción de requests que fallan.
- Duration: distribución de latencia (histograma → p50/p95/p99).
- USE (Brendan Gregg) — para recursos (CPU, disco, pool de conexiones, cola):
- Utilization: % de tiempo ocupado.
- Saturation: trabajo encolado que el recurso no alcanza a procesar (la más predictiva de dolor inminente).
- Errors: errores del recurso.
- Four Golden Signals (Google SRE): Latency, Traffic, Errors, Saturation — superset práctico; es RED + saturación.
La instrumentación con prometheus_client. Prometheus scrapea (modelo pull) un endpoint /metrics; la app registra Counters, Gauges e Histogramas:
import time
from prometheus_client import Counter, Gauge, Histogram, generate_latest, CONTENT_TYPE_LATEST
from starlette.requests import Request
from starlette.responses import Response
# RED a nivel HTTP. Cuidado con la cardinalidad de labels: usa la RUTA (/orders/{id})
# no la URL con el id concreto, o explota el número de series de tiempo.
REQUESTS = Counter(
"http_requests_total", "Total HTTP requests",
["method", "route", "status"],
)
LATENCY = Histogram(
"http_request_duration_seconds", "Request latency",
["method", "route"],
buckets=(0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0),
)
IN_FLIGHT = Gauge("http_requests_in_flight", "Requests being served right now")
# Business metrics: valen más que las de infra para las decisiones de negocio.
ORDERS = Counter("orders_total", "Orders processed", ["status"]) # success|duplicate|failed
DB_POOL = Gauge("db_pool_connections", "DB pool connections", ["state"]) # active|idle
class MetricsMiddleware:
def __init__(self, app):
self.app = app
async def __call__(self, scope, receive, send):
if scope["type"] != "http":
return await self.app(scope, receive, send)
request = Request(scope)
route = request.scope.get("route")
# path template, no el path con ids -> baja cardinalidad
route_label = getattr(route, "path", request.url.path)
method = request.method
status_holder = {"code": 500}
async def send_wrapper(message):
if message["type"] == "http.response.start":
status_holder["code"] = message["status"]
await send(message)
IN_FLIGHT.inc()
start = time.perf_counter()
try:
await self.app(scope, receive, send_wrapper)
finally:
LATENCY.labels(method, route_label).observe(time.perf_counter() - start)
REQUESTS.labels(method, route_label, status_holder["code"]).inc()
IN_FLIGHT.dec()
async def metrics_endpoint(request: Request) -> Response:
return Response(generate_latest(), media_type=CONTENT_TYPE_LATEST)
| Tipo | Semántica | Ejemplo |
|---|---|---|
| Counter | Monótono, solo sube (o se resetea a 0 en restart) | requests totales, errores totales |
| Gauge | Sube y baja | conexiones activas, workers, cola pendiente |
| Histogram | Buckets de conteo → percentiles server-side vía histogram_quantile() | latencia, tamaño de payload |
| Summary | Percentiles calculados en el cliente (no agregables entre instancias) | evitá si tenés varias réplicas |
Percentiles, no promedios. El promedio de latencia esconde la cola: p50=50ms con p99=4s significa que 1 de cada 100 usuarios sufre 4 segundos. Los SLO se definen sobre percentiles (p99 < 500ms), y para eso el histograma necesita buckets alineados con tu SLO (poné un bucket exactamente en tu umbral). Para agregar percentiles entre réplicas necesitás Histogram (server-side quantiles), no Summary.
Qué monitorear por atributo de calidad
Este es el núcleo del nivel senior: no “agregar Grafana”, sino mapear cada quality attribute (requisito no funcional) a señales concretas y a un nivel de monitoreo.
| Atributo de calidad | Qué monitorear | Métrica / señal | Framework |
|---|---|---|---|
| Performance / latency | Tiempo de respuesta por endpoint y operación | http_request_duration_seconds p95/p99; span duration por servicio | RED · traces |
| Reliability / correctness | Fallos que ve el usuario | error rate (5xx / total), orders_total{status="failed"} | RED · Golden |
| Scalability / saturation | Recursos cerca del límite → dolor inminente | pool util (db_pool{state="active"} / max), queue depth, CPU run-queue, event-loop lag | USE |
| Availability | ¿Está arriba y sirviendo? | probes de health, uptime, success ratio del SLI | Golden |
| Capacity / throughput | Carga actual vs planificada | requests/s, mensajes/s en la cola | RED (Rate) |
| Security | Accesos y anomalías | auth failures/s, rate-limit hits por cliente, audit trail (p.ej. CloudTrail) | logs · métricas |
Niveles de monitoreo (hay que verbalizarlos):
- Infraestructura/host: CPU, memoria, disco, red, I/O (USE).
- Plataforma/runtime: pool de conexiones, GC, event-loop lag, workers de gunicorn, uso de heap.
- Aplicación: RED por endpoint, dependencias externas (latencia y error rate de Stripe/DB/Redis), estado de circuit breakers.
- Negocio:
payment_success_rate, órdenes/s por status, funnel de checkout — lo que de verdad importa. - Cliente / real-user (RUM): latencia percibida en el navegador/app.
La clave: CPU y RAM casi nunca son accionables por sí solos. orders_failed_total te dice que algo está mal; db_pool{state="active"} acercándose al máximo te dice que viene el agotamiento de conexiones; la saturación (queue depth, event-loop lag) es el mejor predictor temprano de degradación.
Distributed tracing cross-service
Un trace es el árbol de un request a través de uno o más servicios. Cada nodo es un span: una unidad de trabajo (un handler, una query, una llamada externa) con nombre, timestamps de inicio/fin, atributos y un parent. El trace muestra la cascada (waterfall):
Trace: POST /api/v1/checkout (total 2.30s) trace_id=4bf92f...
├─ span: order.create (order-service) 50ms
├─ span: inventory.reserve (inventory-service) 120ms
├─ span: payment.charge (payment-service) 1800ms ← 78% del tiempo
│ └─ span: http POST stripe (external) 1790ms
└─ span: notify.email (notification) 330ms
Sin traces sabés que el request tardó 2.3s, pero no si fue la DB, Stripe o la validación. Con traces, el cuello de botella salta a la vista.
Propagación de contexto es lo que hace que el trace cruce servicios. El trace context viaja en un header HTTP estándar W3C traceparent:
traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
│ └── trace-id (32 hex) ──────────┘ └ span-id (16) ┘ └ flags
version sampled=01
Cuando el servicio A llama al B, inyecta traceparent; B lo extrae y crea sus spans como hijos del span de A → un solo trace continuo. Con OpenTelemetry esto es automático si el cliente HTTP está instrumentado.
from opentelemetry import trace
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor
from opentelemetry.sdk.trace.sampling import ParentBasedTraceIdRatio
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from opentelemetry.instrumentation.httpx import HTTPXClientInstrumentor
from opentelemetry.instrumentation.sqlalchemy import SQLAlchemyInstrumentor
def configure_tracing(app, service_name: str) -> None:
provider = TracerProvider(
resource=Resource.create({"service.name": service_name}),
# Sampling: 1.0 en dev; en prod, tasa baja (p.ej. 0.05) para acotar coste,
# respetando la decisión del padre para no cortar traces a la mitad.
sampler=ParentBasedTraceIdRatio(0.05),
)
# BatchSpanProcessor: exporta en background por lotes, no bloquea el request path.
provider.add_span_processor(
BatchSpanProcessor(OTLPSpanExporter(endpoint="http://otel-collector:4317"))
)
trace.set_tracer_provider(provider)
# Auto-instrumentación: spans para HTTP entrante, cliente httpx (propaga traceparent)
# y queries SQLAlchemy, sin código manual.
FastAPIInstrumentor.instrument_app(app)
HTTPXClientInstrumentor().instrument()
SQLAlchemyInstrumentor().instrument()
tracer = trace.get_tracer(__name__)
async def check_idempotency(key: str) -> bool:
# Span manual para lógica de negocio (lo que la auto-instrumentación no ve).
with tracer.start_as_current_span("idempotency.check") as span:
span.set_attribute("idempotency.key", key)
hit = await redis.get(f"idem:{key}") is not None
span.set_attribute("idempotency.hit", hit)
return hit
Notas senior: head-based sampling (decidís al iniciar el trace) es lo default y barato pero puede descartar justo el trace del error; tail-based sampling (en el Collector, decide al final) permite quedarte con el 100% de los traces con error o alta latencia a costa de más infra. El OTel Collector como capa intermedia desacopla la app del backend (Jaeger, Tempo, X-Ray, vendor) y hace batching/filtrado/rerouting sin tocar el código.
Alerting: sintomático, no causal; y sin alert fatigue
Alertar por todo garantiza que nadie lea las alertas (alert fatigue). Principios:
- Alertá sobre síntomas visibles al usuario, no sobre causas. “Error rate > 5% por 5 min” o “p99 > 2s por 10 min” son accionables. “CPU > 90%” no lo es por sí solo: si la latencia y el error rate están bien, alto CPU es eficiencia, no un problema.
- SLO y error budget. Definís un SLI (p.ej. proporción de requests con éxito y
< 500ms), un objetivo SLO (99.9% mensual) y el complemento es tu error budget (0.1%). Alertás sobre burn rate: qué tan rápido consumís el presupuesto. Un burn rate multiventana (rápido: 1h; lento: 6h) da páginas urgentes solo cuando de verdad vas a violar el SLO, y tickets no urgentes para quemas lentas. - Severidades diferenciadas. Page (despierta a alguien) solo para pérdida de servicio o violación inminente de SLO; ticket/warning para lo que puede esperar a horario laboral.
# BUENAS alertas (accionables, sintomáticas)
- alert: HighErrorRate
expr: sum(rate(http_requests_total{status=~"5.."}[5m]))
/ sum(rate(http_requests_total[5m])) > 0.05
for: 5m
labels: { severity: page }
- alert: LatencyP99SLOBreach
expr: histogram_quantile(0.99,
sum(rate(http_request_duration_seconds_bucket[5m])) by (le)) > 0.5
for: 10m
labels: { severity: page }
- alert: DBPoolNearExhaustion # saturación = predictor temprano
expr: db_pool_connections{state="active"} / 20 > 0.9
for: 5m
labels: { severity: ticket }
# MALAS alertas (ruido)
# - cada 404: normal, los clientes piden cosas que no existen
# - spike de CPU de 30s: probablemente GC o un deploy
# - un solo request lento: outlier, no patrón
Ejercicios
Ejercicio 1 — De print a structured logging con redacción
Tenés este handler. Convertilo a structlog estructurado, sin loguear el token, y con un campo elapsed_ms.
async def login(email: str, password: str, token: str):
print(f"Login attempt for {email} with token {token}")
user = await auth.verify(email, password)
print(f"Login OK for {email}")
return user
Solución
import time
import structlog
log = structlog.get_logger()
async def login(email: str, password: str, token: str):
start = time.perf_counter()
# No se loguea el token ni el password. Solo el identificador de negocio.
log.info("auth.login.attempt", email=email)
try:
user = await auth.verify(email, password)
except AuthError:
log.warning(
"auth.login.failed", email=email,
elapsed_ms=round((time.perf_counter() - start) * 1000, 1),
)
raise
log.info(
"auth.login.ok", user_id=str(user.id), email=email,
elapsed_ms=round((time.perf_counter() - start) * 1000, 1),
)
return user
Claves: event como key estable (auth.login.ok), nunca el token/password, un nivel distinto para el fallo (warning) que para el éxito (info), y elapsed_ms como número para poder hacer histogramas/filtros. En sistemas regulados agregarías un processor global de redacción por si algún campo sensible se cuela.
Ejercicio 2 — Elegir el tipo de métrica correcto
Para cada señal, decidí Counter / Gauge / Histogram y por qué: (a) número de webhooks de pago procesados; (b) conexiones activas en el pool de DB; (c) tamaño en bytes de los payloads recibidos; (d) tasa de aciertos de cache en los últimos 5 minutos.
Solución
- (a) Counter —
payment_webhooks_total{status=...}. Solo crece; la “tasa” se deriva conrate()en Prometheus. Nunca uses Gauge para algo que solo sube: perdés la capacidad de calcular rate y las bajas por restart te confunden. - (b) Gauge —
db_pool_connections{state="active"}. Sube y baja; querés el valor instantáneo para compararlo con el máximo (saturación). - (c) Histogram —
request_payload_bytes_bucket. Querés la distribución (p50/p99), no solo el total ni el promedio; los buckets te dan percentiles agregables entre réplicas. - (d) Counter (dos) —
cache_hits_totalycache_lookups_total; el hit ratio esrate(hits[5m]) / rate(lookups[5m]). No lo modeles como Gauge de “ratio actual”: perdés poder de agregación y ventana. La regla: casi todo lo acumulable es Counter; los ratios y percentiles se calculan en la query, no se pre-agregan en la app.
Ejercicio 3 — Diseñar la alerta sobre el SLO, no sobre el síntoma
El equipo tiene una alerta “CPU > 80% por 2 min” que dispara 15 veces al día y ya nadie la mira. El SLO real del servicio es: p99 de latencia < 300ms y error rate < 1%, medido mensual. Rediseñá el alerting.
Solución
- Borrar la alerta de CPU como página. Alto CPU sin impacto en latencia/errores es eficiencia, no un incidente. A lo sumo queda como ticket si es sostenido (posible necesidad de escalar), no como page.
- Alertar sobre los SLI que definen el SLO:
histogram_quantile(0.99, ...) > 0.3for: 10m→ severidad page.- error rate
> 0.01for: 5m→ page.
- Mejor aún: burn rate del error budget. Con SLO 99% y ventana mensual, el budget es 1%. Alerta multiventana: burn rate rápido (consumís el budget de 1h en minutos) → page; burn rate lento (proyectás violar el SLO a fin de mes) → ticket. Esto elimina el ruido de picos transitorios y solo despierta a alguien cuando de verdad vas camino a violar el compromiso.
- Saturación como early warning en severidad baja:
db_pool active / max > 0.9como ticket, porque predice agotamiento antes de que se traduzca en errores.
El cambio de mentalidad: se alerta sobre lo que el usuario sufre (síntomas / SLO), no sobre causas internas que pueden o no importar.
Ejercicio 4 — Trazar un request entre dos servicios
order-service llama a payment-service vía httpx. Los traces aparecen como dos traces separados en Jaeger en lugar de uno solo con spans anidados. ¿Qué falta y cómo se arregla?
Solución
Falta la propagación del contexto. Diagnóstico y fix:
- El cliente HTTP no está instrumentado, así que no inyecta el header
traceparent. Solución:HTTPXClientInstrumentor().instrument()enorder-service— a partir de ahí cada requesthttpxllevatraceparentcon eltrace_id/span_iddel span activo. payment-servicedebe extraer ese contexto e iniciar sus spans como hijos. ConFastAPIInstrumentor.instrument_app(app)la extracción es automática (leetraceparentdel request entrante).- Verificar que ambos usan el mismo formato de propagación (W3C TraceContext es el default de OTel; si un servicio usa B3/Jaeger legacy y el otro W3C, no se entienden → configurar el mismo propagator).
- Cuidado con el sampling: si
order-serviceno samplea el trace (decisión head-based) y usásParentBased, el hijo respeta esa decisión y tampoco aparece — no es que se rompió la propagación, es que no se muestreó. Para no perder errores, tail-based sampling en el Collector.
Resultado: un único trace donde el span de payment.charge es hijo del handler de order-service, y la cascada muestra cuánto tiempo real se fue en la llamada externa.
Ejercicio 5 — Rotación de logs con gunicorn multi-worker
Tu app corre con gunicorn -w 4 y configuraste RotatingFileHandler(maxBytes=50MB, backupCount=5). En producción notás líneas de log perdidas y un app.log que a veces “reaparece” con contenido viejo. Explicá la causa y da dos soluciones production-grade.
Solución
Causa: RotatingFileHandler no es multiproceso-safe. Los 4 workers tienen file descriptors independientes al mismo archivo. Cuando el worker A alcanza 50MB, hace rename(app.log → app.log.1) y abre un app.log nuevo. Pero los workers B, C, D siguen escribiendo a su descriptor, que ahora apunta al inode renombrado (app.log.1) — o pisan el rename. Resultado: escrituras entrelazadas, líneas perdidas y archivos “resucitando”.
Soluciones:
- No rotar en la app (cloud-native / preferida). Loguear a stdout y delegar en el runtime: en Docker, driver
json-fileconmax-size=50m,max-file=5(o driverlocal); en Kubernetes, la rotación del kubelet + un collector (Fluent Bit/Vector) que centraliza en Loki/ELK. La app no gestiona archivos; los logs son un stream (Twelve-Factor). Esto además unifica los logs de todos los workers. - Rotación externa con
logrotateusandocopytruncate(trunca el archivo en su lugar sin cambiar el inode, así los descriptors siguen válidos — con una pequeña ventana de carrera aceptable), o enviandoSIGHUPa la app combinado conWatchedFileHandlerque reabre el archivo si detecta cambio de inode. - (Si de verdad hay que rotar en la app)
concurrent-log-handler(ConcurrentRotatingFileHandler), que serializa con file locks entre procesos.
La lección senior: en producción distribuida no querés que cada proceso pelee por un archivo; centralizás los tres pilares en un backend y la rotación local es a lo sumo un buffer.
Preguntas tipo entrevista (EN)
Q1 — What’s the difference between monitoring and observability?
- ❌ Wrong / trap: “They’re the same thing — dashboards and alerts.” Fails because it collapses a real distinction: dashboards are monitoring (predefined questions). It shows no grasp of why teams get burned by green dashboards while users suffer.
- ✅ Correct: Monitoring answers questions you defined in advance (thresholds, known dashboards) and tells you that something broke. Observability is a property of the system: the ability to infer internal state from external outputs — including for questions you didn’t anticipate — without shipping new code.
- ⭐ Optimal (senior): The honest test: when a novel incident happens, can you answer “why?” purely from what the system already emits? The classic failure is a green dashboard (CPU/mem/errors OK) while 12% of payments are silently lost — because you measured infrastructure, not business outcomes (
cpu_usage≠payment_success_rate). Observability requires high-cardinality, correlated telemetry (atrace_idon every log, labels on every metric, spans that stitch into traces) so you can ask new questions of live data. Monitoring is a subset — the predefined alerting layer on top.
Q2 — A customer reports their order failed. How do you investigate in production?
- ❌ Wrong / trap: “I check the server logs.” Fails: ‘the logs’ in a multi-service system is thousands of lines across streams with no way to isolate one request; it’s log archaeology, not investigation.
- ✅ Correct: I get the request’s correlation ID (usually returned in the response) and search the log aggregator for it to see the full event chain for that specific request — where it failed: validation, rate limit, idempotency, DB write.
- ⭐ Optimal (senior): I start from whichever pillar the symptom points to. If it’s a hard failure, I query the aggregator by
correlation_idand read the structured chain, including the stack trace from the failing span’s log. If it’s latency, I pull that request’s trace and read the waterfall — say 90% of time is in one DB span — then cross-reference Postgres slow-query logs for that window. Metrics give me the baseline (is this one request or a pattern?). The three correlate through thetrace_id/correlation_id, which is exactly what makes production debuggable without shipping aprintand waiting for a repro.
Q3 — Which metrics would you expose for an orders API, and why not just CPU and memory?
- ❌ Wrong / trap: “CPU, RAM, and latency.” Fails: CPU/RAM are rarely actionable on their own, and ‘latency’ as a single number (an average) hides the tail that actually hurts users.
- ✅ Correct: RED for the service — request Rate, Error rate, and Duration as a histogram for p50/p95/p99 — plus business metrics like orders per second broken down by status (success, duplicate, failed).
- ⭐ Optimal (senior): I instrument in layers and tie them to quality attributes. Business first:
orders_total{status}andpayment_success_rate— that’s the SLO signal. Application: per-endpoint latency histograms with buckets aligned to my SLO threshold, plus dependency latency/error rate (Stripe, DB). Resource/USE: DB pool utilization and queue depth — saturation is the earliest predictor of impending pain. CPU/RAM are context, not alerts:orders_failed_totaltells me something’s wrong;db_pool{state=active}near max tells me where it’ll break. I alert on the SLO, not on CPU. And I use histograms (not summaries) so percentiles aggregate across replicas.
Q4 — What is a correlation ID and why is a service without one hard to debug?
- ❌ Wrong / trap: “It’s an ID to identify requests.” True but empty — no propagation, no aggregation, no explanation of the multi-service pain it solves.
- ✅ Correct: A UUID generated at the edge (client or first service), propagated in headers to every downstream call, and attached to every log line for that request. With it, you run one query —
correlation_id = abc123— and see the whole chain instead of manually correlating timestamps across streams. - ⭐ Optimal (senior): In Python it must live in
contextvars, not thread-locals, because async multiplexes many requests on one thread — thread-locals would leak IDs between coroutines. Middleware readsX-Correlation-IDor mints a UUID, binds it viastructlog.contextvars, and every subsequent log carries it automatically; the response echoes it so the client can report it. When OpenTelemetry is in play I inject the active span’strace_id/span_idinto logs too, so I can pivot from a log line to the full distributed trace and back. Without it, a multi-service failure is a 2-second, 10k-line correlation-by-timestamp exercise.
Q5 — How does a trace follow a request across service boundaries?
- ❌ Wrong / trap: “Each service logs its trace ID and you match them up afterwards.” Fails: matching after the fact is exactly what tracing avoids; and if each service mints its own ID there’s nothing to match — you need shared context propagation.
- ✅ Correct: The trace context travels in an HTTP header — the W3C
traceparent(version-traceid-spanid-flags). The caller injects it; the callee extracts it and creates its spans as children of the caller’s span, producing one continuous trace with a proper parent/child tree. - ⭐ Optimal (senior): OpenTelemetry auto-instruments the inbound server (FastAPI) and the outbound client (httpx), so
traceparentis injected and extracted with zero manual code; SQLAlchemy/Redis instrumentation adds spans for I/O. Both sides must agree on the propagator (W3C TraceContext by default; mixing B3 and W3C breaks the chain). Sampling is the subtle part: withParentBasedhead sampling the child honors the parent’s decision, so if the root didn’t sample, the child won’t appear — that’s not a propagation bug. To never lose error traces, use tail-based sampling in the Collector, which decides after seeing the whole trace and can keep 100% of errors/slow traces while dropping the boring ones.
Q6 — How do you handle log rotation for a multi-worker Python web app?
- ❌ Wrong / trap: “Use
RotatingFileHandlerwith a max size — done.” Fails:RotatingFileHandleris not multiprocess-safe; with several gunicorn workers writing the same file, the rename-and-reopen on rotation corrupts logs and drops lines. - ✅ Correct: In containers, don’t rotate in the app at all — log to stdout and let the runtime rotate (Docker
json-filewithmax-size/max-file, or the kubelet in Kubernetes). It’s the Twelve-Factor approach: logs are an event stream, not the app’s responsibility, and it unifies all workers. - ⭐ Optimal (senior): For VM/bare-metal where files are unavoidable, use external
logrotatewithcopytruncate(keeps the inode so open descriptors stay valid) orSIGHUP+WatchedFileHandlerthat reopens on inode change; orconcurrent-log-handlerwhich locks across processes if I truly must rotate in-app. But the real senior move is that in a distributed system you centralize all three pillars into an external backend (ELK/Loki/CloudWatch) via a shipping agent, so local files are at most an emergency buffer and rotation there is trivial size-capping.
Q7 — Your alert channel fires 200 times a day and the team ignores it. How do you fix alerting?
- ❌ Wrong / trap: “Raise the thresholds so it fires less.” Fails: tuning a fundamentally cause-based alert (CPU%) just moves the noise; the problem is what you alert on, not the number.
- ✅ Correct: Alert on user-visible symptoms, not internal causes. Replace “CPU > 80%” with SLI-based alerts: error rate and p99 latency over the SLO, with a
for:duration so transient spikes don’t page. High CPU with healthy latency/errors is efficiency, not an incident. - ⭐ Optimal (senior): Move to SLO error-budget burn-rate alerting. Define the SLI (success ratio and latency), the SLO (e.g. 99.9% monthly), and the budget as the complement. Use multi-window burn rate: fast burn (budget for an hour consumed in minutes) pages; slow burn (on track to breach by month-end) opens a ticket. Differentiate severities — page only for service loss or imminent SLO breach; everything else is a ticket. Keep saturation signals (pool near max, queue depth, event-loop lag) as low-severity early warnings, since they predict pain before it becomes user-visible. The mindset shift: alert on what the user feels, not on every internal fluctuation.
Referencias
- Google SRE Book — Monitoring Distributed Systems (Four Golden Signals): https://sre.google/sre-book/monitoring-distributed-systems/
- Google SRE Workbook — Alerting on SLOs (error-budget burn rate): https://sre.google/workbook/alerting-on-slos/
- Tom Wilkie — The RED Method: https://grafana.com/blog/2018/08/02/the-red-method-how-to-instrument-your-services/
- Brendan Gregg — The USE Method: https://www.brendangregg.com/usemethod.html
- OpenTelemetry — Python docs: https://opentelemetry.io/docs/languages/python/
- W3C Trace Context (traceparent): https://www.w3.org/TR/trace-context/
- OpenTelemetry — Sampling (head vs tail): https://opentelemetry.io/docs/concepts/sampling/
- structlog documentation: https://www.structlog.org/
- prometheus_client (Python): https://prometheus.github.io/client_python/
- Python logging.handlers (RotatingFileHandler, TimedRotatingFileHandler, WatchedFileHandler): https://docs.python.org/3/library/logging.handlers.html
- concurrent-log-handler (multiprocess-safe rotation): https://pypi.org/project/concurrent-log-handler/
- The Twelve-Factor App — Logs: https://12factor.net/logs