El módulo 5 terminó con una pregunta incómoda: tenemos siete servicios desplegados en Kubernetes con canary y GitOps, pero si mañana la saga de un pedido se atasca, ¿cómo lo sabremos? En el monolito la respuesta era "mira el log del servidor": un proceso, un fichero, un grep. En TechCorp ahora hay decenas de pods que arrancan y mueren, una petición atraviesa tres o cuatro servicios y una saga sigue viva minutos después de que la petición HTTP haya terminado. Esta lección construye las dos primeras patas de la observabilidad —logs estructurados y métricas— sobre la librería @techcorp/comun-http y los manifiestos que ya tenemos, y deja la tercera, las trazas, para 06-02.

1. Los tres pilares de la observabilidad y por qué "mirar el log" ya no basta
2. Logging estructurado con pino: ampliar crearLogger
3. Qué no loguear: redacción de datos sensibles
4. Recolección de logs en Kubernetes: Promtail/Alloy y Loki
5. Consultas LogQL: seguir a ped-88213 por varios servicios
6. Métricas: tipos, método RED y método USE
7. Instrumentación con prom-client: GET /metrics en la librería
8. Métricas de negocio: pedidos, saga y outbox
9. Prometheus en Kubernetes y consultas PromQL básicas
10. Dashboards en Grafana y correlación logs ↔ métricas
11. Coste y cardinalidad

Monitorizar es comprobar que el sistema hace lo que esperamos (¿responde POST /v1/pedidos? ¿en cuánto tiempo?). Observar es poder responder preguntas que no habíamos previsto ("¿por qué el pedido de Ana Ruiz lleva 20 minutos en STOCK_RESERVADO?") a partir de lo que el sistema emite. Se apoya en tres señales complementarias:

En el monolito, log y traza eran casi lo mismo: una petición era un hilo de ejecución dentro de un proceso. En microservicios cambian tres cosas: hay muchos procesos efímeros (un kubectl logs solo muestra un pod, y los pods de un rolling de 05-04 desaparecen con sus logs: hay que sacarlos del contenedor y centralizarlos); una acción atraviesa varios servicios (POST /v1/pedidos pasa por el gateway, Pedidos, Catálogo y Clientes, y la saga sigue por RabbitMQ en Inventario, Pagos y Notificaciones: nada se lee sin un identificador común, el X-Request-Id de 03-01 y el eventoId de 03-02); y el volumen (el catálogo en Black Friday multiplica ×20: leer logs a mano no escala, y las métricas resumen millones de peticiones en unos pocos números).

Regla del módulo: los logs cuentan el detalle, las métricas cuentan la tendencia y las trazas cuentan el camino. Las tres se unen por identificadores comunes.

Un log "de texto" (Pedido ped-88213 creado para c-1024) es fácil de leer y casi imposible de consultar. Un log estructurado es un objeto JSON por línea: cada campo se puede filtrar y agregar. En 04-02 la librería ya ofrecía crearLogger({servicio}) con pino; ahora fijamos su forma definitiva:

Línea a línea:

• level: nivel: el umbral. Viene de LOG_NIVEL (04-03), info en producción y debug en local. Por debajo del umbral pino ni siquiera serializa el objeto: bajar el nivel no cuesta CPU.
• base: campos fijos que se añaden a cada línea. servicio es obligatorio (servicio-pedidos); version (la etiqueta de la imagen, 05-03) permite comparar el canary con la versión estable.
• messageKey: 'mensaje' y formatters.level: renombramos las claves inglesas para que todo el JSON esté en el mismo idioma que nuestros identificadores; timestamp en ISO lo entienden Loki y Grafana sin configuración; redact lo vemos en el apartado 3.

Los niveles y cuándo usarlos:

Los campos estándar que acordamos entre los cuatro equipos, para que las consultas de Loki sean iguales en todos los servicios:

Para no repetir esos campos en cada llamada usamos loggers hijos (logger.child(...)). Así queda el caso de uso de 04-04:

En el consumidor de la saga (mensajeria/consumidorSaga.js) el hijo se crea a partir del mensaje: logger.child({ eventoId: evento.id, tipoEvento: evento.tipo, pedidoId: evento.datos.pedidoId, cola: 'pedidos.saga' }). Salida real de una línea (una por fila, sin saltos):

Logs de acceso con pino-http. Una línea por petición HTTP, generada por el middleware y no a mano. Va en la plantilla de la librería, justo después de middlewareRequestId() para que use el mismo req.id:

• genReqId: si no lo indicáramos, pino-http generaría su propio id y perderíamos la correlación con X-Request-Id; autoLogging.ignore evita loguear las sondas de Kubernetes (05-02), que llaman a /health/* cada 5-10 s.
• customLogLevel: un 5xx se ve como error sin que nadie tenga que acordarse; los serializers reducen req/res a método, ruta y código (pino-http añade además responseTime en ms).

Un log centralizado lo lee mucha gente y se conserva semanas. Lo que entra en él debe poder leerse sin permisos especiales. En TechCorp queda prohibido loguear: datos personales más allá del identificador (clienteId sí; nombre, correo o dirección de Ana Ruiz, no); datos de pago (número de tarjeta, CVV, tokens del PSP); credenciales (cabecera Authorization, cookies, contraseñas, RABBITMQ_URL completa, que contiene usuario y contraseña); y cuerpos completos de peticiones en info (en debug solo si pasan por la redacción).

La opción redact de pino lo hace por nosotros: cualquier propiedad que coincida con paths se sustituye por [REDACTADO] antes de serializar. *.tarjeta significa "una clave tarjeta en cualquier objeto de primer nivel". Un ejemplo:

La redacción es una red de seguridad, no una licencia: la regla es no pasar esos datos al logger. El tratamiento completo (cifrado, secretos, auditoría) es de 07-03; aquí basta con que el logger no los filtre.

Los servicios escriben a stdout (decisión de 05-01: doce factores, sin ficheros en el contenedor). El kubelet guarda esa salida en /var/log/containers/*.log del nodo, y un agente desplegado como DaemonSet (un pod por nodo) la lee, le añade las etiquetas de Kubernetes y la envía al almacén central. En TechCorp el almacén es Loki (misma familia que Grafana y Prometheus, indexa solo etiquetas y guarda el texto comprimido: barato y suficiente para nuestro volumen) y el agente es Promtail o su sucesor Grafana Alloy.

Fragmento de la configuración de Promtail (Helm values.yaml, instalado por el equipo de Plataforma en el namespace observabilidad):

• clients.url: a dónde empuja las líneas; Loki es un Service más del clúster. pipelineStages: cri separa el envoltorio del runtime; json extrae nivel y servicio; labels promociona solo esos a etiquetas; el resto (requestId, pedidoId) se queda en el texto y se filtra en consulta.
• extraRelabelConfigs: convierte las labels app y version del pod (las mismas del Deployment de 05-02) en etiquetas de Loki. Por eso consultamos por {app="servicio-pedidos"}.

¿Por qué no promocionar requestId a etiqueta? Porque cada valor distinto crea una serie nueva y Loki se degrada con millones de ellas: etiquetas para lo que tiene pocos valores (app, version, nivel, namespace), texto para lo que tiene infinitos (requestId, pedidoId). La misma regla reaparecerá con Prometheus en el apartado 11.

Alternativas equivalentes, para reconocerlas cuando aparezcan:

LogQL tiene dos partes: un selector de etiquetas entre llaves y una tubería de filtros. Las consultas que el equipo de Luis usa a diario:

1. |= es "contiene el texto": la creación, el evento en el outbox, cada paso de la saga.
2. | json parsea la línea y deja filtrar por campo exacto; el resultado son las líneas de gateway, Pedidos, Catálogo y Clientes en orden temporal. Es el motivo por el que 03-01 insistió en propagar X-Request-Id: sin él, esta consulta no existe.
3. =~ es una expresión regular sobre la etiqueta; line_format reduce cada línea a lo que interesa.
4. Si devuelve vacío y Pedidos muestra "evento publicado", el problema está entre el relay del outbox y la cola inventario.pedidos (03-02).
5. LogQL también agrega; útil para explorar, pero para lo que se vigila de forma permanente conviene una métrica de verdad, que es lo que sigue.

Una métrica es un número con nombre y etiquetas, muestreado periódicamente (Prometheus raspa —scrape— cada servicio cada 15-30 s). Prometheus define cuatro tipos:

Dos métodos nos dicen qué medir sin inventar:

• RED, para servicios (lo que hace el equipo de Pedidos): Rate (peticiones/s), Errors (proporción de fallos), Duration (latencia, con percentiles). Con estas tres por servicio y por ruta se ve el 90 % de los problemas.
• USE, para recursos (lo que mira el equipo de Plataforma): Utilization (% de CPU, memoria, disco), Saturation (cola de espera: mensajes en RabbitMQ, conexiones esperando en el pool de pg), Errors (errores del recurso). Kubernetes ya expone CPU y memoria por pod a través de cAdvisor y kube-state-metrics; nosotros aportamos las de RabbitMQ y los pools.

prom-client es la librería oficial de Prometheus para Node.js. Igual que hicimos con el logger, la instrumentación HTTP vive una vez en @techcorp/comun-http y todos los servicios la reciben:

Explicación:

• Un Registry propio por servicio, con servicio como etiqueta por defecto: todas las series llevan servicio="servicio-pedidos" sin repetirlo.
• collectDefaultMetrics añade gratis process_cpu_seconds_total, nodejs_heap_size_used_bytes, nodejs_eventloop_lag_seconds… Este último es oro en Node: si sube, el hilo único está bloqueado (06-04).
• http_requests_total{metodo, ruta, codigo}: el contador RED. La etiqueta ruta usa la plantilla de Express (/v1/pedidos/:id), nunca la URL real, o crearíamos una serie por pedido (apartado 11). Si ninguna ruta casó (404), etiquetamos desconocida.
• http_request_duration_seconds: histograma con buckets de 10 ms a 5 s. El bucket de 2 s coincide con TIMEOUT_HTTP_MS=2000 (03-01): así vemos cuántas peticiones rozan el límite.
• startTimer() devuelve una función que, al llamarla con las etiquetas, observa los segundos transcurridos; se llama en finish, cuando la respuesta ya se ha enviado. manejadorMetrics sirve el texto en formato Prometheus.

En crearApp de la plantilla (04-02) el orden queda: middlewareRequestId() → middlewareLogAcceso({logger}) → metricas.middleware → rutas → middlewareErrores({logger}), y una ruta app.get('/metrics', metricas.manejadorMetrics). Salida de curl localhost:3002/metrics (recortada):

Cada _bucket{le="0.25"} cuenta las peticiones que tardaron ≤ 0,25 s (acumulado): 1.240 de 1.287. De ahí sale el p95 en el apartado 9.

Las métricas RED dicen que el servicio responde; las de negocio dicen que la tienda vende. Se declaran en el propio servicio contra el mismo registro:

• pedidos_creados_total se incrementa en el caso de uso tras confirmar la transacción; pedidos_cancelados_total{motivo} en el consumidor de la saga al procesar pedido.cancelado (solo tres valores de motivo: cardinalidad controlada).
• saga_duracion_segundos: al cerrar el pedido, sagaDuracion.observe((ahora - pedido.creado_en) / 1000); los buckets llegan hasta 900 s porque una reserva expira a los 15 minutos (02-05); en 06-05 será la base del SLI "confirmado en < 60 s". outbox_pendientes con collect() consulta la tabla cuando Prometheus raspa: es la métrica que delata un relay caído (los pedidos se crean pero sus eventos no salen).

RabbitMQ se mide con su plugin rabbitmq_prometheus (puerto 15692), que el chart de Helm de 05-02 activa con metrics.enabled: true. Expone, entre otras, rabbitmq_queue_messages_ready{queue="inventario.pedidos"} (mensajes esperando consumidor) y la misma para pedidos.saga.dlq. Una DLQ con mensajes es siempre una anomalía (03-02), y en 06-05 será una alerta.

Prometheus descubre qué raspar mediante la API de Kubernetes. Con el operador (kube-prometheus-stack, instalado por Plataforma) se declara un ServiceMonitor por servicio, junto al Service de 05-02:

Sin operador, la alternativa son anotaciones en el Pod (prometheus.io/scrape: "true", prometheus.io/port: "3002", prometheus.io/path: "/metrics") que la configuración clásica de kubernetes_sd_configs interpreta. El ServiceMonitor va en la base de Kustomize de cada servicio; los servicios nuevos lo heredan de la plantilla.

Las consultas PromQL que responden a las preguntas RED (todas ejecutables en Grafana → Explore):

1. rate calcula la pendiente del contador en la ventana; 5 m suaviza el ruido. Nunca se grafica un contador en bruto.
2. El numerador filtra por regex de código, el denominador es el total; ambos agregados por la misma etiqueta para que la división case.
3. Se agrega la tasa de cada bucket (le debe conservarse) y histogram_quantile interpola el percentil. Se puede agregar entre pods porque los buckets son sumables; con un summary no podríamos.
4. Devuelve solo las series cuyo valor supera 100: vacío si todo va bien. Es la forma de una condición de alerta, que 06-05 convertirá en PrometheusRule.
5. increase es rate × ventana: da unidades, no unidades/s.
6. Una DLQ con mensajes es siempre una anomalía (03-02).

Grafana lee Prometheus y Loki como datasources. Convenimos dos dashboards, versionados como JSON en techcorp/plataforma/observabilidad/dashboards/ y cargados por un ConfigMap con la etiqueta grafana_dashboard: "1" (el sidecar del chart los importa):

Dashboard "RED por servicio" con una variable $servicio (valores de label_values(http_requests_total, servicio)) y cuatro paneles: peticiones/s, % de 5xx, p50/p95/p99, y CPU/memoria del pod (USE) para correlacionar. Lo esencial del JSON de un panel:

expr es la consulta del apartado 9 con la variable; legendFormat nombra cada línea por ruta; thresholds pinta de rojo por encima de 300 ms, el objetivo que se formalizará en 06-05.

Dashboard "Saga de pedidos" (equipo de Luis): pedidos creados/h, cancelados por motivo (barras apiladas), p95 de saga_duracion_segundos, outbox_pendientes, mensajes listos en inventario.pedidos/pagos.stock/pedidos.saga y sus DLQ, y un panel de estado con la consulta SQL directa a PostgreSQL (SELECT estado, count(*) FROM pedidos WHERE creado_en > now() - interval '1 hour' GROUP BY estado), que muestra cuántos pedidos hay en cada estado (PENDIENTE, STOCK_RESERVADO, PAGADO, CONFIRMADO, CANCELADO). Un montón creciente en STOCK_RESERVADO es la firma de "Pagos no responde".

Correlación. Métricas y logs comparten servicio/app y version (labels de Kubernetes) y el tiempo. El flujo típico: el panel de errores sube a las 10:21 → clic en el punto → "Explore" con {app="servicio-pedidos", nivel="error"} en la misma ventana → aparece la línea con requestId y err.codigo=DEPENDENCIA_NO_DISPONIBLE → segunda consulta por ese requestId en todo el namespace → se ve que Catálogo devolvió 503. Grafana permite configurar ese salto (métrica → logs) como data link del panel; el salto de logs a trazas (trace_id) lo añadimos en 06-02.

Cada combinación distinta de etiquetas es una serie que Prometheus guarda en memoria. http_requests_total con 6 métodos × 15 rutas × 8 códigos × 20 pods son 14.400 series: bien. Si alguien añade pedidoId como etiqueta, con 3.000 pedidos/día son 3.000 series nuevas cada día por pod: en un mes Prometheus se queda sin memoria. Reglas:

• Etiquetas con pocos valores conocidos (servicio, ruta plantilla, codigo, motivo, cola). Nunca identificadores (pedidoId, clienteId, requestId, eventoId), URLs completas ni cuerpos.
• Los identificadores van al log (texto, no etiqueta de Loki) y a la traza (06-02). Ese reparto es la razón de que las tres señales existan.
• Vigilar el coste: count({__name__=~".+"}) en Prometheus da el número total de series; el volumen de Loki se controla con retención (30 días en TechCorp), con no loguear /health y con LOG_NIVEL=info por defecto (debug en producción multiplica el volumen por 10-50 y se activa solo puntualmente con un cambio de ConfigMap).

• Concatenar en el mensaje lo que debería ser un campo (log.info('pedido ' + id + ' creado')). Después no se puede filtrar por pedidoId. El mensaje es constante; el contexto va en el objeto.
• Perder el requestId en el camino. Si un servicio genera el suyo en vez de propagar el recibido, la consulta cruzada de LogQL se corta ahí. middlewareRequestId() reutiliza el entrante; los clientes HTTP (04-04) lo reenvían; los eventos llevan eventoId y, además, el requestId origen en cabeceras.
• Loguear las sondas y /metrics. Miles de líneas inútiles al día por pod.
• URLs reales como etiqueta ruta. Explosión de cardinalidad. Usar la plantilla de Express y desconocida para 404.
• Consejo: en desarrollo, LOG_NIVEL=debug y node src/servidor.js | npx pino-pretty para leer los logs de forma legible sin cambiar el formato de producción.

El consumidor de inventario.pedidos recibe pedido.creado y reserva stock. Escribe el fragmento que crea el logger hijo con los campos estándar del apartado 2 y emite: un info al recibir, un warn si la reserva falla por falta de stock (con productoId y solicitado/disponible), y un error si falla la base de datos. Escribe después la consulta LogQL que muestre solo las faltas de stock del producto p-501 en la última hora.

Marta pregunta: "si el relay del outbox de Pedidos muere pero el pod sigue vivo, ¿qué panel lo mostraría y qué consulta lo demuestra?". Responde con la métrica, la consulta PromQL y la consulta LogQL que confirmaría la causa.

Ejercicio 1

(El selector de tiempo "última hora" se elige en Grafana; en la consulta no hace falta.)

Ejercicio 2

La métrica es outbox_pendientes (gauge con collect()): sigue creciendo porque POST /v1/pedidos sigue insertando filas y nadie las publica. Consulta: outbox_pendientes{servicio="servicio-pedidos"} > 100 (o su pendiente: deriv(outbox_pendientes[10m]) > 0). Complementaria: rate(pedidos_creados_total[5m]) > 0 y a la vez rabbitmq_queue_messages_ready{queue="inventario.pedidos"} == 0 durante minutos. En el dashboard de la saga se vería el panel de outbox_pendientes subiendo y el de estado con todos los pedidos nuevos en PENDIENTE. Causa en Loki: {app="servicio-pedidos"} | json | mensaje=~"relay.*" mostraría el último "lote publicado" hace demasiado tiempo o un error del canal de RabbitMQ; si el relay murió sin loguear, la ausencia de líneas es la pista. En 06-05 esto será una alerta.

Hemos dado a TechCorp sus dos primeras señales de observabilidad. Los logs son JSON estructurado con pino, con campos comunes (servicio, version, nivel, requestId, pedidoId, eventoId), redacción de datos sensibles y una línea de acceso por petición vía pino-http; salen por stdout, Promtail/Alloy los etiqueta con app/version y Loki los guarda, de modo que {namespace="techcorp"} | json | requestId="..." reconstruye una petición a través de varios servicios. Las métricas viven en @techcorp/comun-http (http_requests_total, http_request_duration_seconds en GET /metrics) y en cada servicio (pedidos_creados_total, pedidos_cancelados_total{motivo}, saga_duracion_segundos, outbox_pendientes), Prometheus las raspa mediante ServiceMonitor y Grafana las muestra en los dashboards RED y de la saga; el precio a pagar es la disciplina de cardinalidad: identificadores en los logs, nunca en las etiquetas. Lo que todavía no vemos es el camino: sabemos que POST /v1/pedidos tarda 250 ms en el p95, pero no cuánto de ese tiempo se fue en Catálogo, en Clientes o en PostgreSQL, ni cómo unir la petición HTTP con la saga que sigue por RabbitMQ. Esa es la tercera señal, las trazas distribuidas con OpenTelemetry, y es la lección siguiente.