Node.jsオブザーバビリティ：複雑さなしでログ、メトリクス、トレースを実現

import pino from "pino";
 
const logger = pino({
  level: process.env.LOG_LEVEL || "info",
  // Redactで機密データを自動的にマスク
  redact: {
    paths: ["req.headers.authorization", "req.headers.cookie", "body.password", "body.token", "*.ssn", "*.creditCard"],
    clobberWith: "[REDACTED]",
  },
  // シリアライゼーション — フィールドの制御
  serializers: {
    req: pino.stdSerializers.req,
    res: pino.stdSerializers.res,
    err: pino.stdSerializers.err,
  },
  // タイムスタンプフォーマット — ISO 8601
  timestamp: pino.stdTimeFunctions.isoTime,
});
 
export default logger;

// リクエストスコープのロガー — リクエストIDがすべての行に付与される
app.use((req, res, next) => {
  req.log = logger.child({
    requestId: req.headers["x-request-id"] || crypto.randomUUID(),
    method: req.method,
    path: req.url,
    userAgent: req.headers["user-agent"],
  });
  next();
});
 
// ハンドラー内ではreq.logを使用
app.get("/api/orders", async (req, res) => {
  req.log.info("Fetching orders");
 
  const orders = await db.orders.findMany({
    where: { userId: req.user.id },
  });
 
  req.log.info({ orderCount: orders.length }, "Orders retrieved");
  res.json(orders);
});

// データベースモジュール
const dbLogger = logger.child({ module: "database" });
 
export async function query(sql: string, params: unknown[]) {
  const start = performance.now();
  try {
    const result = await pool.query(sql, params);
    const duration = performance.now() - start;
 
    dbLogger.info(
      {
        duration: Math.round(duration * 100) / 100,
        rowCount: result.rowCount,
        // SQLをログに記録するが、パラメータは記録しない（機密データの可能性）
        query: sql.substring(0, 200),
      },
      "Query executed",
    );
 
    return result;
  } catch (error) {
    const duration = performance.now() - start;
    dbLogger.error(
      {
        duration: Math.round(duration * 100) / 100,
        query: sql.substring(0, 200),
        err: error,
      },
      "Query failed",
    );
    throw error;
  }
}

// Redisモジュール
const cacheLogger = logger.child({ module: "cache" });
 
export async function getCached<T>(key: string): Promise<T | null> {
  try {
    const cached = await redis.get(key);
    if (cached) {
      cacheLogger.debug({ key, hit: true }, "Cache hit");
      return JSON.parse(cached);
    }
    cacheLogger.debug({ key, hit: false }, "Cache miss");
    return null;
  } catch (error) {
    cacheLogger.warn({ key, err: error }, "Cache read failed, falling back");
    return null;
  }
}

import pino from "pino";
 
const transport = pino.transport({
  targets: [
    // プロダクション：JSON→stdout（コンテナランタイムが収集）
    {
      target: "pino/file",
      options: { destination: 1 }, // stdout
      level: "info",
    },
    // 開発：整形済みの人間が読める出力
    ...(process.env.NODE_ENV === "development"
      ? [
          {
            target: "pino-pretty",
            options: {
              colorize: true,
              translateTime: "HH:MM:ss",
              ignore: "pid,hostname",
            },
            level: "debug",
          },
        ]
      : []),
  ],
});
 
const logger = pino(transport);

import promClient from "prom-client";
 
// デフォルトメトリクスの収集 — イベントループ、ヒープ、GCなど
promClient.collectDefaultMetrics({
  prefix: "myapp_",
  gcDurationBuckets: [0.001, 0.01, 0.1, 1, 2, 5],
});
 
// --- カスタムメトリクス ---
 
// HTTPリクエストの持続時間ヒストグラム
export const httpRequestDuration = new promClient.Histogram({
  name: "myapp_http_request_duration_seconds",
  help: "HTTP request duration in seconds",
  labelNames: ["method", "route", "status_code"] as const,
  buckets: [0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10],
});
 
// HTTPリクエストの合計カウンター
export const httpRequestsTotal = new promClient.Counter({
  name: "myapp_http_requests_total",
  help: "Total HTTP requests",
  labelNames: ["method", "route", "status_code"] as const,
});
 
// アクティブな接続のゲージ
export const activeConnections = new promClient.Gauge({
  name: "myapp_active_connections",
  help: "Number of active connections",
});
 
// ビジネスメトリクス
export const ordersCreated = new promClient.Counter({
  name: "myapp_orders_created_total",
  help: "Total orders created",
  labelNames: ["payment_method"] as const,
});
 
export const orderValue = new promClient.Histogram({
  name: "myapp_order_value_dollars",
  help: "Order value in dollars",
  buckets: [10, 25, 50, 100, 250, 500, 1000, 5000],
});

import { Request, Response, NextFunction } from "express";
import { httpRequestDuration, httpRequestsTotal } from "./metrics";
 
export function metricsMiddleware(req: Request, res: Response, next: NextFunction) {
  // ルートが設定される前にタイマーを開始
  const end = httpRequestDuration.startTimer();
 
  // レスポンス完了時にメトリクスを記録
  res.on("finish", () => {
    const route = req.route?.path || req.path || "unknown";
    const labels = {
      method: req.method,
      route: route,
      status_code: res.statusCode.toString(),
    };
 
    end(labels);
    httpRequestsTotal.inc(labels);
  });
 
  next();
}

import { Router } from "express";
import promClient from "prom-client";
 
const metricsRouter = Router();
 
metricsRouter.get("/metrics", async (_req, res) => {
  res.set("Content-Type", promClient.register.contentType);
  res.end(await promClient.register.metrics());
});
 
export default metricsRouter;

// REDメトリクス — すべてのサービスに必要
const httpRequestDuration = new Histogram({ ... });    // Duration
const httpRequestsTotal = new Counter({ ... });        // Rate
const httpErrorsTotal = new Counter({ ... });          // Errors
 
// USEメトリクス — インフラに必要
// collectDefaultMetrics()がNode.jsリソースの大部分をカバー
 
// ビジネスメトリクス — あなた固有のサービスに必要
const ordersCreated = new Counter({ ... });
const paymentProcessed = new Histogram({ ... });

// 良い — 低カーディナリティ
httpRequestDuration.observe(
  {
    method: "GET", // ~5の値
    route: "/api/orders", // ~50の値
    status_code: "200", // ~20の値
  },
  duration,
);
// 合計の組み合わせ：~5,000 — 問題なし
 
// 悪い — 高カーディナリティ
httpRequestDuration.observe(
  {
    method: "GET",
    url: "/api/orders/12345", // 無限の値！
    user_id: "user_4821", // 数千の値！
    status_code: "200",
  },
  duration,
);
// 合計の組み合わせ：無限 — Prometheusが爆発する

# prometheus.yml
global:
  scrape_interval: 15s
  evaluation_interval: 15s
 
scrape_configs:
  - job_name: "myapp"
    static_configs:
      - targets: ["localhost:3000"]
    metrics_path: "/metrics"
    scrape_interval: 10s

# 5分間でエラー率が5%を超えた場合のアラート
- alert: HighErrorRate
  expr: |
    rate(myapp_http_requests_total{status_code=~"5.."}[5m])
    / rate(myapp_http_requests_total[5m]) > 0.05
  for: 5m
  labels:
    severity: critical
  annotations:
    summary: "5%超のリクエストがエラーを返している"

// instrumentation.ts — これが最初にロードされる
import { NodeSDK } from "@opentelemetry/sdk-node";
import { getNodeAutoInstrumentations } from "@opentelemetry/auto-instrumentations-node";
import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http";
import { OTLPMetricExporter } from "@opentelemetry/exporter-metrics-otlp-http";
import { PeriodicExportingMetricReader } from "@opentelemetry/sdk-metrics";
import { Resource } from "@opentelemetry/resources";
import { ATTR_SERVICE_NAME, ATTR_SERVICE_VERSION } from "@opentelemetry/semantic-conventions";
 
const sdk = new NodeSDK({
  resource: new Resource({
    [ATTR_SERVICE_NAME]: "order-service",
    [ATTR_SERVICE_VERSION]: "1.2.0",
    environment: process.env.NODE_ENV || "development",
  }),
 
  // トレース — OTLPコレクターへ送信
  traceExporter: new OTLPTraceExporter({
    url: process.env.OTEL_EXPORTER_OTLP_ENDPOINT || "http://localhost:4318/v1/traces",
  }),
 
  // メトリクス — OTLPコレクターへ送信
  metricReader: new PeriodicExportingMetricReader({
    exporter: new OTLPMetricExporter({
      url: process.env.OTEL_EXPORTER_OTLP_ENDPOINT || "http://localhost:4318/v1/metrics",
    }),
    exportIntervalMillis: 30000,
  }),
 
  // 自動インストゥルメンテーション — ライブラリを自動的に計測
  instrumentations: [
    getNodeAutoInstrumentations({
      // 不要なインストゥルメンテーションを無効化
      "@opentelemetry/instrumentation-fs": { enabled: false },
      "@opentelemetry/instrumentation-dns": { enabled: false },
      // HTTP、Express、pg、ioredisなどは自動的に有効
    }),
  ],
});
 
sdk.start();
 
// グレースフルシャットダウン
process.on("SIGTERM", () => {
  sdk
    .shutdown()
    .then(() => console.log("OTel SDK shut down"))
    .catch((err) => console.error("OTel SDK shutdown error", err))
    .finally(() => process.exit(0));
});

node --import ./instrumentation.ts src/index.ts
# または
node --require ./instrumentation.js src/index.js

import { trace, SpanStatusCode } from "@opentelemetry/api";
 
const tracer = trace.getTracer("order-service");
 
export async function processOrder(orderId: string) {
  // カスタムスパンを作成
  return tracer.startActiveSpan("processOrder", async (span) => {
    try {
      span.setAttribute("order.id", orderId);
 
      // バリデーションスパン
      const validationResult = await tracer.startActiveSpan("validateOrder", async (validationSpan) => {
        const result = await validateOrder(orderId);
        validationSpan.setAttribute("validation.itemCount", result.items.length);
        validationSpan.end();
        return result;
      });
 
      // 支払い処理スパン
      const payment = await tracer.startActiveSpan("processPayment", async (paymentSpan) => {
        paymentSpan.setAttribute("payment.method", validationResult.paymentMethod);
        paymentSpan.setAttribute("payment.amount", validationResult.total);
        const result = await chargeCustomer(validationResult);
        paymentSpan.setAttribute("payment.transactionId", result.transactionId);
        paymentSpan.end();
        return result;
      });
 
      // インベントリ更新スパン
      await tracer.startActiveSpan("updateInventory", async (inventorySpan) => {
        await updateInventory(validationResult.items);
        inventorySpan.setAttribute("inventory.itemsUpdated", validationResult.items.length);
        inventorySpan.end();
      });
 
      span.setAttribute("order.status", "completed");
      span.setStatus({ code: SpanStatusCode.OK });
      return { success: true, transactionId: payment.transactionId };
    } catch (error) {
      span.setStatus({
        code: SpanStatusCode.ERROR,
        message: error instanceof Error ? error.message : "Unknown error",
      });
      span.recordException(error as Error);
      throw error;
    } finally {
      span.end();
    }
  });
}

// サービスA — ダウンストリームサービスの呼び出し
app.get("/api/orders/:id", async (req, res) => {
  // このHTTPリクエストはtraceparentヘッダーを自動的に含む
  const inventory = await fetch(`http://inventory-service/api/stock/${req.params.id}`);
  // ...
});

// サービスB — 受信リクエストからトレースコンテキストを自動的にピックアップ
app.get("/api/stock/:productId", async (req, res) => {
  // このスパンはサービスAのスパンの子として自動的にリンクされる
  const stock = await db.query("SELECT * FROM inventory WHERE product_id = $1", [req.params.productId]);
  res.json(stock);
});

# otel-collector-config.yaml
receivers:
  otlp:
    protocols:
      grpc:
        endpoint: 0.0.0.0:4317
      http:
        endpoint: 0.0.0.0:4318
 
processors:
  batch:
    timeout: 5s
    send_batch_size: 1024
  memory_limiter:
    check_interval: 1s
    limit_mib: 512
    spike_limit_mib: 128
 
exporters:
  otlp/tempo:
    endpoint: tempo:4317
    tls:
      insecure: true
  prometheus:
    endpoint: 0.0.0.0:8889
 
service:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [memory_limiter, batch]
      exporters: [otlp/tempo]
    metrics:
      receivers: [otlp]
      processors: [memory_limiter, batch]
      exporters: [prometheus]

# docker-compose.observability.yml
version: "3.8"
 
services:
  # アプリケーション
  app:
    build: .
    ports:
      - "3000:3000"
    environment:
      - OTEL_EXPORTER_OTLP_ENDPOINT=http://otel-collector:4318
      - LOG_LEVEL=info
    depends_on:
      - otel-collector
 
  # OpenTelemetry Collector
  otel-collector:
    image: otel/opentelemetry-collector-contrib:latest
    command: ["--config=/etc/otel-collector-config.yaml"]
    volumes:
      - ./otel-collector-config.yaml:/etc/otel-collector-config.yaml
    ports:
      - "4317:4317" # gRPC
      - "4318:4318" # HTTP
      - "8889:8889" # Prometheusエクスポーター
 
  # Grafana Tempo — トレースストレージ
  tempo:
    image: grafana/tempo:latest
    command: ["-config.file=/etc/tempo.yaml"]
    volumes:
      - ./tempo.yaml:/etc/tempo.yaml
 
  # Prometheus — メトリクスストレージ
  prometheus:
    image: prom/prometheus:latest
    volumes:
      - ./prometheus.yml:/etc/prometheus/prometheus.yml
    ports:
      - "9090:9090"
 
  # Grafana — ダッシュボードと可視化
  grafana:
    image: grafana/grafana:latest
    ports:
      - "3001:3000"
    environment:
      - GF_AUTH_ANONYMOUS_ENABLED=true
      - GF_AUTH_ANONYMOUS_ORG_ROLE=Admin
    volumes:
      - ./grafana/provisioning:/etc/grafana/provisioning

# grafana/provisioning/datasources/datasources.yaml
apiVersion: 1
 
datasources:
  - name: Prometheus
    type: prometheus
    access: proxy
    url: http://prometheus:9090
    isDefault: true
 
  - name: Tempo
    type: tempo
    access: proxy
    url: http://tempo:3200
    jsonData:
      tracesToLogsV2:
        datasourceUid: loki
        filterByTraceID: true
      nodeGraph:
        enabled: true

import { TraceIdRatioBasedSampler } from "@opentelemetry/sdk-trace-base";
 
const sdk = new NodeSDK({
  // トレースの10%のみ記録
  sampler: new TraceIdRatioBasedSampler(0.1),
  // ...残りの設定
});

# otel-collector-config.yaml
processors:
  tail_sampling:
    decision_wait: 10s
    policies:
      # すべてのエラーを保持
      - name: errors
        type: status_code
        status_code: { status_codes: [ERROR] }
      # 遅いトレースを保持
      - name: slow-traces
        type: latency
        latency: { threshold_ms: 1000 }
      # 残りの5%をサンプリング
      - name: randomized
        type: probabilistic
        probabilistic: { sampling_percentage: 5 }

import { trace } from "@opentelemetry/api";
 
// ログ時に現在のトレースコンテキストを自動的に含める
const loggerWithTrace = logger.child({
  get traceId() {
    return trace.getActiveSpan()?.spanContext().traceId;
  },
  get spanId() {
    return trace.getActiveSpan()?.spanContext().spanId;
  },
});
 
// ログ出力例：
// {"level":"info","traceId":"abc123","spanId":"def456","msg":"Order created"}

app.get("/healthz", async (_req, res) => {
  const health = {
    status: "ok",
    timestamp: new Date().toISOString(),
    checks: {} as Record<string, { status: string; latency?: number }>,
  };
 
  // データベースチェック
  try {
    const start = performance.now();
    await db.query("SELECT 1");
    health.checks.database = {
      status: "ok",
      latency: Math.round(performance.now() - start),
    };
  } catch {
    health.checks.database = { status: "error" };
    health.status = "degraded";
  }
 
  // Redisチェック
  try {
    const start = performance.now();
    await redis.ping();
    health.checks.redis = {
      status: "ok",
      latency: Math.round(performance.now() - start),
    };
  } catch {
    health.checks.redis = { status: "error" };
    health.status = "degraded";
  }
 
  const statusCode = health.status === "ok" ? 200 : 503;
  res.status(statusCode).json(health);
});

# 良いアラートの例
- alert: HighErrorRate
  expr: rate(http_requests_total{status=~"5.."}[5m]) / rate(http_requests_total[5m]) > 0.05
  for: 5m # 5分間持続してからアラート
  annotations:
    summary: "5%超のリクエストが失敗"
    runbook: "https://wiki.internal/runbooks/high-error-rate" # ランブック必須
 
# 悪いアラートの例
- alert: SingleError
  expr: increase(http_requests_total{status="500"}[1m]) > 0
  # for句なし、1回のエラーでアラート、深夜3時に起こされる