Tutorial: Distributed Tracing con OpenTelemetry e LGTM Stack

Gateway (nginx:80)
├── Shop UI (:3000)
├── Shop API (:3001)
│   ├── Inventory Service (:3011)
│   ├── Payment Service (:3010)
│   └── Notification Service (:3009)
├── Keycloak (:8080)
└── Grafana LGTM (:3005)

POST /api/checkout
├─ Inventory Service  → verifica disponibilità
├─ Payment Service    → processa pagamento
├─ Inventory Service  → riserva prodotti
├─ PostgreSQL         → salva ordine
└─ Notification       → invia conferma

# Clone e avvia
git clone https://github.com/monte97/MockMart
cd MockMart
make up

# Verifica
docker ps  # tutti i container healthy
open http://localhost:3005  # Grafana

# Scenari demo
./scripts/scenario-1-silent-failure.sh   # Silent failure
./scripts/scenario-2-latency-spike.sh    # Latency spike
./scripts/scenario-3-fanout-debug.sh     # Fan-out debug (complex)

# Esplora in Grafana
# Explore → Tempo → Query TraceQL

# Clona la demo
git clone https://github.com/monte97/MockMart
cd MockMart

# Avvia lo stack
make up

# Esegui lo scenario (simula email validation failure)
./scripts/scenario-1-silent-failure.sh

{ resource.service.name = "shop-api" }

{ resource.service.name = "shop-api" && span.order_id = <ID> }

POST /api/checkout (320ms) [STATUS: OK]
├─ pg.query SELECT user (45ms) [OK]
├─ pg.query INSERT INTO orders (180ms) [OK]
└─ HTTP POST /api/notifications/order (45ms) [ERROR: 400]

{"msg":"Received order notification request","orderId":8472,"userId":"abc-123","userEmail":"mario.rossi@example.com","traceId":"...","spanId":"..."}
{"msg":"Validating email address...","orderId":8472,"userEmail":"mario.rossi@example.com","traceId":"...","spanId":"..."}
{"msg":"Cannot send notification - invalid email address","orderId":8472,"userEmail":"mario.rossi@example.com","reason":"Email validation failed: invalid domain or format","traceId":"...","spanId":"..."}

./scripts/scenario-2-latency-spike.sh

{ resource.service.name = "shop-api" && duration > 2s }

POST /api/checkout (3100ms)
├─ pg-pool.connect (3ms)
├─ pg.query:INSERT orders (2ms)
└─ POST /api/notifications/order (3050ms) ← bottleneck

POST /api/checkout (150ms)
├─ pg-pool.connect (3ms)
├─ pg.query:INSERT orders (2ms)
└─ POST /api/notifications/order (50ms)

{"msg":"Received order notification request","orderId":20,"userId":"luigi-uuid","userEmail":"luigi.verdi@example.com","traceId":"..."}
{"msg":"Processing order notification","orderId":20,"template":"order_confirmation_premium","traceId":"..."}
{"msg":"Rendering premium template...","orderId":20,"template":"order_confirmation_premium","traceId":"..."}
{"msg":"Template rendering took long","orderId":20,"renderTimeMs":3000,"traceId":"..."}
{"msg":"Email notification sent","orderId":20,"userEmail":"luigi.verdi@example.com","traceId":"..."}

{"msg":"Received order notification request","orderId":17,"userId":"mario-uuid","userEmail":"mario.rossi@example.com","traceId":"..."}
{"msg":"Processing order notification","orderId":17,"template":"order_confirmation_basic","traceId":"..."}
{"msg":"Email notification sent","orderId":17,"userEmail":"mario.rossi@example.com","traceId":"..."}

histogram_quantile(0.95,
  rate(traces_service_graph_request_server_seconds_bucket{server="shop-api"}[5m])
)

POST /api/checkout (3200ms totali)
├─ Inventory check    (??ms)
├─ Payment process    (??ms)
├─ Inventory reserve  (??ms)
├─ DB save            (??ms)
└─ Notification       (??ms)

# Esegui lo scenario che testa ogni servizio singolarmente
./scripts/scenario-3-fanout-debug.sh

3️⃣  Baseline checkout (all services normal)...
   ⏱️  Baseline: 206ms
   🔗 Trace: 3d9e2441545eb8c0c1050b51daa4489f

4️⃣  Checkout with SLOW PAYMENT SERVICE (2s delay)...
   ⏱️  With slow payment: 2117ms
   🔗 Trace: ae1799f3ed5836602288d4c39ea156a2

5️⃣  Checkout with SLOW INVENTORY SERVICE (1.5s delay)...
   ⏱️  With slow inventory: 1678ms
   🔗 Trace: 6325d443f6aa4c6f1ab1d6f7c31c0c5e

6️⃣  Checkout with SLOW NOTIFICATION SERVICE (3s delay)...
   ⏱️  With slow notification: 3138ms
   🔗 Trace: e43750f867a144eec9396095c39bb6da

📊 Results Summary:
   Scenario           | Duration | Trace ID
   -------------------|----------|----------------------------------
   Baseline (normal)  | 206ms    | 3d9e2441545eb8c0c1050b51daa4489f
   + Slow Payment     | 2117ms   | ae1799f3ed5836602288d4c39ea156a2
   + Slow Inventory   | 1678ms   | 6325d443f6aa4c6f1ab1d6f7c31c0c5e
   + Slow Notification| 3138ms   | e43750f867a144eec9396095c39bb6da

# Log dell'API
docker logs shop-api | grep "checkout"
# [10:45:23] INFO Processing checkout
# [10:45:26] INFO Order saved  ← 3 secondi dopo, ma DOVE?

# Log di ogni servizio
docker logs payment-service | grep "order"
# [10:45:23] INFO Payment processed  ← sembra veloce

docker logs inventory-service | grep "order"
# [10:45:23] INFO Stock checked
# [10:45:24] INFO Stock reserved  ← 1 secondo?

docker logs notification-service | grep "order"
# [10:45:24] INFO Notification sent  ← sembra veloce

ae1799f3ed5836602288d4c39ea156a2

{ resource.service.name = "shop-api" && duration > 2s }

POST /api/checkout (2117ms) [shop-api]
│
├─ POST /api/inventory/check (4ms) [inventory-service]
│
├─ POST /api/payments/process (2020ms) [payment-service] ← BOTTLENECK!
│
├─ POST /api/inventory/reserve (4ms) [inventory-service]
│
├─ pg.query INSERT orders (12ms) [shop-api]
│
└─ POST /api/notifications/order (55ms) [notification-service]

POST /api/checkout (206ms) [shop-api]
│
├─ POST /api/inventory/check (5ms) [inventory-service]
├─ POST /api/payments/process (85ms) [payment-service]
├─ POST /api/inventory/reserve (4ms) [inventory-service]
├─ pg.query INSERT orders (15ms) [shop-api]
└─ POST /api/notifications/order (54ms) [notification-service]

// Payment service (scenario slow payment)
{"msg":"Processing payment","orderId":18,"traceId":"..."}
{"msg":"Payment gateway slow response","orderId":18,"responseTimeMs":2000,"traceId":"..."}

// Notification service (scenario slow notification)
{"msg":"Processing order notification","orderId":24,"template":"order_confirmation_premium","traceId":"..."}
{"msg":"Template rendering took long","orderId":24,"renderTimeMs":3000,"traceId":"..."}

npm install @opentelemetry/sdk-node \
  @opentelemetry/auto-instrumentations-node \
  @opentelemetry/exporter-trace-otlp-grpc \
  @opentelemetry/resources \
  @opentelemetry/api \
  pino

// instrumentation.js - Inizializza OpenTelemetry PRIMA di qualsiasi altro import
const { NodeSDK } = require('@opentelemetry/sdk-node');
const { getNodeAutoInstrumentations } = require('@opentelemetry/auto-instrumentations-node');
const { OTLPTraceExporter } = require('@opentelemetry/exporter-trace-otlp-grpc');
const { resourceFromAttributes } = require('@opentelemetry/resources');

const serviceName = process.env.OTEL_SERVICE_NAME || 'my-service';
const otlpEndpoint = process.env.OTEL_EXPORTER_OTLP_ENDPOINT || 'http://localhost:4317';

const resource = resourceFromAttributes({
  'service.name': serviceName,
});

const sdk = new NodeSDK({
  resource,
  traceExporter: new OTLPTraceExporter({ url: otlpEndpoint }),
  instrumentations: [
    getNodeAutoInstrumentations({
      '@opentelemetry/instrumentation-fs': { enabled: false },
    }),
  ],
});

sdk.start();
console.log(`OpenTelemetry initialized for ${serviceName}`);

process.on('SIGTERM', () => {
  sdk.shutdown()
    .then(() => console.log('Tracing terminated'))
    .catch((err) => console.error('Error terminating', err))
    .finally(() => process.exit(0));
});

# --require carica instrumentation.js PRIMA di server.js
node --require ./instrumentation.js server.js

{
  "scripts": {
    "start": "node --require ./instrumentation.js server.js"
  }
}

// lib/logger.js
const pino = require('pino');

// PinoInstrumentation inietta automaticamente trace_id e span_id
const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
});

module.exports = logger;

const logger = require('./lib/logger');
const { trace } = require('@opentelemetry/api');

app.post('/api/checkout', requireAuth, async (req, res) => {
  const user = req.user;
  const cart = carts[req.session.id];

  // Log con attributi strutturati - trace_id/span_id iniettati da PinoInstrumentation
  logger.info({ userId: user.id, itemCount: cart.length }, 'Processing checkout');

  try {
    // ... inserimento ordine nel database ...
    const orderId = orderResult.rows[0].id;

    // Aggiungi order_id allo span per query TraceQL: { span.order_id = 123 }
    trace.getActiveSpan()?.setAttribute('order_id', orderId);

    logger.info({ orderId, userId: user.id, total }, 'Order saved to database');

    // Chiama notification service
    logger.info({ orderId, url: NOTIFICATION_SERVICE_URL }, 'Calling notification service');

    await axios.post(`${NOTIFICATION_SERVICE_URL}/api/notifications/order`, {...});

    logger.info({ orderId }, 'Notification sent successfully');

    res.json({ success: true, order });
  } catch (err) {
    // Gli errori includono automaticamente il trace context per correlazione
    logger.error({ error: err.message }, 'Checkout failed');
    res.status(500).json({ error: 'Checkout failed' });
  }
});

{
  "level": 30,
  "time": 1770291707877,
  "pid": 1,
  "hostname": "shop-api",
  "trace_id": "b0b197c5337c4b07f80e2ef7b130f2f4",
  "span_id": "e8815f03044501df",
  "trace_flags": "01",
  "orderId": 8472,
  "total": 99.99,
  "msg": "Order saved to database"
}

grafana:
  image: grafana/otel-lgtm:latest
  ports:
    - "3005:3000"   # Grafana UI
    - "4317:4317"   # OTLP gRPC
    - "4318:4318"   # OTLP HTTP

shop-api:
  environment:
    - OTEL_SERVICE_NAME=shop-api
    - OTEL_EXPORTER_OTLP_ENDPOINT=http://grafana:4317
  # Carica instrumentation.js PRIMA di server.js
  command: ["node", "--require", "./instrumentation.js", "server.js"]

notification-service:
  environment:
    - OTEL_SERVICE_NAME=notification-service
    - OTEL_EXPORTER_OTLP_ENDPOINT=http://grafana:4317
  command: ["node", "--require", "./instrumentation.js", "server.js"]

const { trace } = require('@opentelemetry/api');

app.post('/api/checkout', async (req, res) => {
  // ... logica checkout ...

  const orderId = result.rows[0].id;

  // --- Aggiungi attributo business allo span corrente ---
  // trace.getActiveSpan() restituisce lo span creato dall'auto-instrumentation
  // per questa richiesta HTTP (span "POST /api/checkout")
  // L'optional chaining (?.) gestisce il caso (raro) in cui non ci sia span attivo
  trace.getActiveSpan()?.setAttribute('order_id', orderId);

  // È possibile aggiungere più attributi - utili per filtering e grouping
  trace.getActiveSpan()?.setAttributes({
    'order_id': orderId,
    'user_tier': req.user.tier,        // es. "premium", "basic"
    'cart_item_count': cart.length,
    'order_total': order.total,
  });

  // ... resto del codice ...
});

# Trova tutte le trace per un ordine specifico
{ span.order_id = 8472 }

# Trova checkout lenti di utenti premium
{ span.user_tier = "premium" && duration > 1s }

# Combina con attributi standard
{ resource.service.name = "shop-api" && span.order_total > 100 }

const { trace, SpanStatusCode } = require('@opentelemetry/api');

async function processPayment(order) {
  // Ottieni il tracer (usa lo stesso nome del servizio per consistenza)
  const tracer = trace.getTracer('shop-api');

  // Crea uno span manuale - sarà child dello span HTTP corrente
  return tracer.startActiveSpan('process-payment', async (span) => {
    try {
      // Aggiungi attributi specifici di questa operazione
      span.setAttributes({
        'payment.method': order.paymentMethod,
        'payment.amount': order.total,
        'payment.currency': 'EUR',
      });

      // ... logica pagamento ...
      const result = await paymentGateway.charge(order);

      // Aggiungi risultato
      span.setAttribute('payment.transaction_id', result.transactionId);

      return result;
    } catch (error) {
      // Marca lo span come errore e registra l'eccezione
      span.setStatus({ code: SpanStatusCode.ERROR, message: error.message });
      span.recordException(error);
      throw error;
    } finally {
      // IMPORTANTE: chiudi sempre lo span
      span.end();
    }
  });
}

POST /api/checkout (850ms)
├─ pg.query:INSERT orders (15ms)
├─ process-payment (500ms)          ← span manuale
│   └─ payment.method: "credit-card"
│   └─ payment.amount: 99.99
│   └─ payment.transaction_id: "txn_123"
└─ HTTP POST /api/notifications (320ms)