De 45 Minutos de Búsqueda a 4 Minutos de Causa Raíz: OpenTelemetry en una Plataforma de Pagos

Cuando un pago falla a las 2 AM, lo primero que hace un ingeniero es abrir CloudWatch. Busca el error, encuentra una línea de log del API gateway, anota el timestamp, abre una segunda pestaña y busca en los logs del servicio de pagos por la misma ventana de tiempo, encuentra algo sospechoso, abre una tercera pestaña para los slow query logs de la base de datos, intenta correlacionar por timestamp, se da cuenta de que los relojes difieren por unos segundos entre servicios, y pasa los siguientes 45 minutos tratando de hilvanar manualmente una narrativa a través de streams de logs desconectados.

Ese era el baseline: 45 minutos de MTTD, para una plataforma de pagos procesando dinero real en tiempo real.

La solución no era más logs. Ya tenían CloudWatch. La solución era trazabilidad distribuida — un único trace ID que fluye a través de cada servicio en la cadena de un request, de modo que en lugar de hacer grep por timestamps en ocho servicios, se abre una sola vista y se ve el viaje completo: qué servicio llamó a cuál, cuánto tardó cada salto, dónde se originó el error.

Instrumentamos el stack completo con OpenTelemetry, exportamos trazas a Grafana Tempo, y en el proceso encontramos una consulta N+1 que venía sumando 200ms a cada pago durante meses. Nadie lo había notado porque nada conectaba la latencia a nivel de aplicación con el comportamiento de la base de datos.

Con Qué Trabajábamos

Ocho microservicios en EKS: un API gateway (Node.js), un orquestador de pagos (Node.js), un servicio de detección de fraude (Node.js), un worker de reconciliación (Go), un servicio de libro de cuentas (Go), un servicio de notificaciones (Node.js), un servicio de conversión de monedas (Go), y un servicio de entrega de webhooks (Node.js). La mayoría del tráfico fluía por el camino API gateway → orquestador de pagos → libro de cuentas.

El stack de observabilidad antes de empezar:

El equipo era competente. El tooling simplemente hacía imposible la correlación. No se puede hacer grep para llegar a la causa raíz cuando la información está repartida en ocho streams de logs separados sin ningún identificador compartido.

Fase 1: OpenTelemetry Collector como DaemonSet

La primera decisión fue la arquitectura de despliegue del OTEL Collector. Elegimos DaemonSet — un collector por nodo, compartido entre todos los pods en ese nodo — sobre el patrón sidecar.

La matemática es directa. Con 8 servicios en un cluster que escala automáticamente a 15–20 nodos (y teníamos Karpenter gestionando el ciclo de vida de los nodos), el enfoque sidecar significaría 30–60 procesos de collector. Un DaemonSet significa 15–20. Menos overhead de CPU, configuración centralizada, un solo lugar donde actualizar el pipeline de exportación.

La configuración completa del DaemonSet:

apiVersion: apps/v1
kind: DaemonSet
metadata:
  name: otel-collector
  namespace: monitoring
spec:
  selector:
    matchLabels:
      app: otel-collector
  template:
    metadata:
      labels:
        app: otel-collector
    spec:
      serviceAccountName: otel-collector
      tolerations:
        - key: node.kubernetes.io/not-ready
          operator: Exists
          effect: NoExecute
          tolerationSeconds: 30
        - key: node.kubernetes.io/unreachable
          operator: Exists
          effect: NoExecute
          tolerationSeconds: 30
      containers:
        - name: otel-collector
          image: otel/opentelemetry-collector-contrib:0.96.0
          args:
            - "--config=/conf/otel-collector-config.yaml"
          resources:
            requests:
              cpu: 100m
              memory: 200Mi
            limits:
              cpu: 500m
              memory: 500Mi
          ports:
            - containerPort: 4317  # OTLP gRPC
            - containerPort: 4318  # OTLP HTTP
            - containerPort: 8888  # Métricas del collector
          volumeMounts:
            - name: otel-collector-config
              mountPath: /conf
      volumes:
        - name: otel-collector-config
          configMap:
            name: otel-collector-config

La config del collector maneja el batching de trazas, lógica de retry y exportación a Grafana Tempo. También conectamos los logs a Loki con la etiqueta trace_id extraída automáticamente:

# otel-collector-config.yaml
receivers:
  otlp:
    protocols:
      grpc:
        endpoint: 0.0.0.0:4317
      http:
        endpoint: 0.0.0.0:4318

processors:
  batch:
    timeout: 10s
    send_batch_size: 1024
  memory_limiter:
    check_interval: 1s
    limit_mib: 400
    spike_limit_mib: 100
  resource:
    attributes:
      - key: k8s.cluster.name
        value: "payments-prod"
        action: upsert

exporters:
  otlp/tempo:
    endpoint: http://grafana-tempo.monitoring.svc.cluster.local:4317
    tls:
      insecure: true
  loki:
    endpoint: http://grafana-loki.monitoring.svc.cluster.local:3100/loki/api/v1/push
    labels:
      resource:
        service.name: "service_name"
        k8s.pod.name: "pod"
      record:
        traceID: "trace_id"  # Extraído como etiqueta de Loki para correlación
  prometheus:
    endpoint: "0.0.0.0:8889"
    enable_open_metrics: true  # Requerido para soporte de exemplars

service:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [memory_limiter, batch, resource]
      exporters: [otlp/tempo]
    logs:
      receivers: [otlp]
      processors: [memory_limiter, batch, resource]
      exporters: [loki]
    metrics:
      receivers: [otlp]
      processors: [memory_limiter, batch, resource]
      exporters: [prometheus]

Con esto en su lugar, cada pod en cada nodo tenía un endpoint OTEL local en http://$(NODE_IP):4317. Los servicios apuntan su SDK OTEL ahí mediante una variable de entorno NODE_IP inyectada desde el fieldRef de la spec del pod.

Fase 2: Auto-Instrumentación para Servicios Node.js

Cinco de los ocho servicios eran Node.js. En lugar de modificar cada servicio individualmente, usamos el paquete de auto-instrumentación de Node.js de OpenTelemetry — sin cambios de código, solo un cambio en cómo arranca el proceso.

El patch del deployment para todos los servicios Node.js:

# Patch aplicado a los 5 deployments Node.js
spec:
  template:
    spec:
      containers:
        - name: app
          env:
            - name: NODE_IP
              valueFrom:
                fieldRef:
                  fieldPath: status.hostIP
            - name: OTEL_EXPORTER_OTLP_ENDPOINT
              value: "http://$(NODE_IP):4317"
            - name: OTEL_SERVICE_NAME
              valueFrom:
                fieldRef:
                  fieldPath: metadata.labels['app']
            - name: OTEL_RESOURCE_ATTRIBUTES
              value: "deployment.environment=production,k8s.namespace.name=$(POD_NAMESPACE)"
            - name: POD_NAMESPACE
              valueFrom:
                fieldRef:
                  fieldPath: metadata.namespace
            - name: NODE_OPTIONS
              value: "--require @opentelemetry/auto-instrumentations-node/register"

La línea NODE_OPTIONS es la clave — le dice a Node.js que cargue el paquete de auto-instrumentación antes de que corra cualquier código de la aplicación. Esto instrumenta rutas Express, llamadas HTTP salientes, consultas PostgreSQL (cliente pg), llamadas Redis y productores/consumidores Kafka de manera automática.

Agregamos el paquete a la imagen base de Docker Node.js usada por todos los servicios:

FROM node:20-alpine
RUN npm install --save @opentelemetry/[email protected]
# ... resto del Dockerfile

Ningún servicio individual cambió su código. Los cinco servicios empezaron a emitir spans en menos de una hora.

Fase 3: Spans Manuales para Flujos Críticos de Pagos en Go

Los servicios Go necesitaron un enfoque diferente. Go no tiene equivalente a la auto-instrumentación — se instrumenta manualmente. Pero para el servicio de libro de cuentas (el camino crítico en cada pago), fuimos más allá del tracing HTTP básico. Agregamos spans personalizados alrededor de cada operación de negocio crítica.

package ledger

import (
    "context"
    "go.opentelemetry.io/otel"
    "go.opentelemetry.io/otel/attribute"
    "go.opentelemetry.io/otel/codes"
    "go.opentelemetry.io/otel/trace"
)

var tracer = otel.Tracer("accounts-ledger")

func (s *LedgerService) ProcessPayment(ctx context.Context, payment Payment) (*Receipt, error) {
    ctx, span := tracer.Start(ctx, "ledger.ProcessPayment",
        trace.WithAttributes(
            attribute.String("payment.id", payment.ID),
            attribute.String("payment.currency", payment.Currency),
            attribute.Int64("payment.amount_cents", payment.AmountCents),
            attribute.String("payment.type", string(payment.Type)),
        ),
    )
    defer span.End()

    // Validar balance del emisor — crea un span hijo automáticamente
    // porque pasamos ctx a través
    balance, err := s.getAccountBalance(ctx, payment.SenderAccountID)
    if err != nil {
        span.RecordError(err)
        span.SetStatus(codes.Error, "failed to fetch sender balance")
        return nil, err
    }

    if balance < payment.AmountCents {
        span.SetAttributes(attribute.Bool("payment.insufficient_funds", true))
        span.SetStatus(codes.Error, "insufficient funds")
        return nil, ErrInsufficientFunds
    }

    // Debitar emisor
    ctx, debitSpan := tracer.Start(ctx, "ledger.DebitSender")
    if err := s.debitAccount(ctx, payment.SenderAccountID, payment.AmountCents); err != nil {
        debitSpan.RecordError(err)
        debitSpan.SetStatus(codes.Error, "debit failed")
        debitSpan.End()
        return nil, err
    }
    debitSpan.End()

    // Acreditar destinatario
    ctx, creditSpan := tracer.Start(ctx, "ledger.CreditRecipient")
    if err := s.creditAccount(ctx, payment.RecipientAccountID, payment.AmountCents); err != nil {
        creditSpan.RecordError(err)
        creditSpan.SetStatus(codes.Error, "credit failed")
        creditSpan.End()
        return nil, err
    }
    creditSpan.End()

    receipt := &Receipt{PaymentID: payment.ID, Status: "settled"}
    span.SetAttributes(attribute.String("payment.status", "settled"))
    span.SetStatus(codes.Ok, "payment settled")
    return receipt, nil
}

El header W3C TraceContext (traceparent) fluye automáticamente a través de las llamadas del cliente HTTP gracias al wrapper de transporte otelhttp:

import "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"

// Reemplazar el transporte por defecto de http.Client con la versión instrumentada
httpClient := &http.Client{
    Transport: otelhttp.NewTransport(http.DefaultTransport),
}

Para el consumer Kafka en el servicio de reconciliación — donde el contexto de traza viene de headers de mensajes, no de headers HTTP — extrajimos el contexto explícitamente:

func (c *ReconciliationConsumer) processMessage(msg *kafka.Message) {
    // Extraer contexto de traza de los headers del mensaje Kafka
    headers := make(map[string]string)
    for _, h := range msg.Headers {
        headers[string(h.Key)] = string(h.Value)
    }
    ctx := otel.GetTextMapPropagator().Extract(
        context.Background(),
        propagation.MapCarrier(headers),
    )

    ctx, span := tracer.Start(ctx, "reconciliation.ProcessMessage")
    defer span.End()
    // ... resto del procesamiento con ctx
}

Este fue el único lugar donde la propagación W3C necesitó conexión manual. Todos los otros boundaries de servicio (HTTP) propagaron automáticamente.

Fase 4: Exemplars y el Descubrimiento del N+1

Con las trazas fluyendo, agregamos exemplars de Prometheus — la función que vincula un pico de métrica directamente con la traza que lo causó.

El orquestador de pagos en Node.js usaba prom-client para métricas. Modificamos el registro del histograma para adjuntar el trace ID actual:

const { metrics } = require('@opentelemetry/api');
const { PrometheusExporter } = require('@opentelemetry/exporter-prometheus');

// Histograma con soporte de exemplar
const paymentDuration = meter.createHistogram('payment_duration_seconds', {
  description: 'Payment processing duration',
  boundaries: [0.05, 0.1, 0.2, 0.5, 1, 2, 5],
});

// En el handler de pagos:
async function handlePayment(req, res) {
  const startTime = Date.now();
  const span = trace.getActiveSpan();
  
  try {
    const result = await processPayment(req.body);
    const duration = (Date.now() - startTime) / 1000;
    
    // Registrar con exemplar — trace ID adjuntado automáticamente
    paymentDuration.record(duration, {
      'payment.type': req.body.type,
      'payment.currency': req.body.currency,
    });
    
    res.json(result);
  } catch (err) {
    // ...
  }
}

Con los exemplars funcionando, un pico en el panel de latencia p99 de Grafana se convirtió en una investigación de un solo click. Así fue como encontramos la consulta N+1.

El Descubrimiento del N+1

Tres semanas después de que las trazas entraron en producción, notamos que el p99 de latencia de pagos tenía una línea de base persistente de 200ms que llegaba a 400ms bajo carga moderada. La métrica siempre había lucido así — simplemente no teníamos el contexto para explicarlo.

Hicimos click en el ícono de exemplar en el pico. La traza se abrió en Tempo. Lo que vimos:

POST /payments/process                    1.24s
  ├── fraud-detection.Evaluate            45ms
  ├── currency-conversion.Convert         12ms
  └── ledger.ProcessPayment              890ms
        ├── ledger.getAccountBalance       8ms   (cuenta 1)
        ├── ledger.getAccountBalance       9ms   (cuenta 2)
        ├── ledger.getAccountBalance       7ms   (cuenta 3)
        ├── ledger.getAccountBalance       8ms   (cuenta 4)
        ├── ledger.getAccountBalance       9ms   (cuenta 5)
        ├── ledger.getAccountBalance       8ms   (cuenta 6)
        ├── ledger.getAccountBalance       7ms   (cuenta 7)
        ├── ledger.getAccountBalance       9ms   (cuenta 8)
        ├── ledger.getAccountBalance       8ms   (cuenta 9)
        ├── ledger.getAccountBalance       7ms   (cuenta 10)
        ├── ledger.getAccountBalance       9ms   (cuenta 11)
        ├── ledger.getAccountBalance       8ms   (cuenta 12)
        ├── ledger.DebitSender            620ms
        └── ledger.CreditRecipient         15ms

Doce llamadas secuenciales a getAccountBalance antes del débito real. El span de DebitSender luego tardaba 620ms por sí solo.

Corrimos EXPLAIN ANALYZE sobre la consulta de débito:

EXPLAIN ANALYZE
SELECT id, balance, currency, status
FROM accounts
WHERE id = $1 AND status = 'active'
FOR UPDATE;

-- Resultado:
Seq Scan on accounts  (cost=0.00..8420.00 rows=1 width=48)
                      (actual time=614.231..614.232 rows=1 loops=1)
  Filter: ((id = '3f2a...'::uuid) AND (status = 'active'::account_status))
  Rows Removed by Filter: 284197
Planning Time: 0.087 ms
Execution Time: 614.298 ms

Scan secuencial sobre 284.000 filas en cada llamada. La tabla accounts tenía un índice sobre id pero la condición compuesta WHERE id = $1 AND status = 'active' no estaba cubierta — y el lock FOR UPDATE amplificaba el problema bajo carga concurrente.

Las doce llamadas a getAccountBalance eran un bug de lógica: la pre-validación de reconciliación iteraba cuentas que ya habían sido validadas upstream. Ese fue un fix de una línea.

El índice faltante fue un fix de dos líneas:

-- Agregamos índice compuesto para cubrir el patrón de consulta
CREATE INDEX CONCURRENTLY idx_accounts_id_status
ON accounts (id, status)
WHERE status = 'active';

-- Verificado con EXPLAIN ANALYZE después de crear el índice:
-- Index Scan using idx_accounts_id_status on accounts
-- (actual time=0.041..0.042 rows=1 loops=1)
-- Execution Time: 0.089 ms

614ms → 0.089ms por operación de débito. La línea de base de 200ms en el p99 de pagos desapareció.

Nada de esto era visible en CloudWatch. El RDS Performance Insights mostraba consultas lentas, pero sin la traza conectando el request de la API a la llamada específica a la base de datos, no había manera de saber qué servicio la estaba causando ni por qué se ejecutaba 12 veces por pago.

Los Números Finales

Después de cuatro semanas con trazas completas en producción:

La comparación de costos merece una nota: las queries de CloudWatch Logs Insights se vuelven caras rápidamente cuando se corren con frecuencia de incidente en ocho log groups. Grafana Tempo en S3 cuesta casi nada a este volumen de spans. El análisis FinOps de nuestro trabajo de observabilidad de costos confirmó que el cambio pagó la implementación dentro del primer mes.

Si el equipo necesita ahora responder automáticamente a incidentes correlacionando estas trazas con el historial de incidentes y runbooks, la arquitectura de agente SRE con RAG se construye naturalmente sobre esta base de observabilidad.

Qué Haríamos Diferente

Instrumentar los boundaries de Kafka desde el día uno, no la semana tres. Postergamos la instrumentación del consumer Kafka porque parecía un caso borde menor. No lo era — el servicio de reconciliación procesa cada retry de pago fallido, y sin contexto de traza ahí toda una categoría de incidentes seguía sin correlación. Pasamos dos semanas pensando que los reintentos eran un problema separado.

Configurar alertas de p99 por operación desde el inicio. Configuramos alertas generales de p99 pero no por nombre de span. La consulta N+1 había estado sumando 200ms a ledger.ProcessPayment durante meses. Agregá span.name como etiqueta en los histogramas de Prometheus y alertá con esa granularidad — una alerta de SLO por operación lo hubiera detectado desde el primer día.

Correr el OTEL Collector en un node group dedicado. Corrimos el DaemonSet en nodos compartidos y tuvimos dos incidentes donde los pods del collector fueron OOMKilled bajo carga pesada de telemetría — brechas en las trazas durante exactamente los incidentes en que más necesitábamos visibilidad. Un node group dedicado (un m5.large por AZ) con toleración de NodePool vale los USD 60/mes. La config de Karpenter NodePool lo hace un cambio de cinco líneas.

Validar la propagación W3C en staging antes del rollout. En producción encontramos dos servicios con un header legacy X-Request-ID que trataban como el trace ID — aparecían conectados en los logs pero generaban trazas desconectadas en Tempo. Un test de integración que afirme que el mismo trace ID aparece en spans de dos servicios hubiera detectado esto en minutos.

¿Corrés microservicios y pasás 30+ minutos por incidente reconstruyendo qué pasó? La trazabilidad distribuida es la inversión de observabilidad con mayor leverage que podés hacer. Hablemos de cómo se ve la instrumentación para tu stack.