logging-observability

ロギングとオブザーバビリティ

本番システム向けの構造化ログ、分散トレーシング、メトリクスを扱います。ログのフォーマットからアラートのルーティングまで、オブザーバビリティスタック全体を網羅します。

使用するタイミング

次の内容に該当する場合に有効化します：「構造化ログ」、「分散トレーシング」、「OpenTelemetry」、「OTel」、「相関 ID」、「ログレベル」、「Grafana ダッシュボード」、「アラートのしきい値」、「SLI SLO」、「Prometheus メトリクス」、「PagerDuty 連携」、「オブザーバビリティスタック」、「Winston のセットアップ」、「Pino ロガー」、「ログ集約」、「Datadog」、「Honeycomb」

**対象外：**パフォーマンスプロファイリング（CPU／メモリのフレームグラフ）｜負荷テスト｜データベースクエリの最適化｜セキュリティ監査

判断ツリー：各レベルで記録する内容

flowchart TD
    E[Event Occurs] --> Q1{Does it represent\na system failure?}
    Q1 -->|Yes| Q2{Is it recoverable\nwithout human?}
    Q2 -->|No| FATAL[FATAL: Service cannot\ncontinue — trigger pager]
    Q2 -->|Yes| ERROR[ERROR: Operation failed,\nwill retry or degrade]
    Q1 -->|No| Q3{Is it unexpected\nbut not failing?}
    Q3 -->|Yes| WARN[WARN: Unusual condition,\ncircuit breaker open,\ndeprecation used]
    Q3 -->|No| Q4{Is it a meaningful\nbusiness event?}
    Q4 -->|Yes| INFO[INFO: User action,\npayment processed,\nservice started]
    Q4 -->|No| Q5{Needed to debug\na specific issue?}
    Q5 -->|Yes| DEBUG[DEBUG: DB queries,\ncache hits/misses,\nfunction inputs]
    Q5 -->|No| TRACE[TRACE: Fine-grained\nloop iterations,\nOTel spans]

**経験則：**本番環境では INFO 以上を実行します。DEBUG はサービスごとに動的設定でのみ有効にし、本番環境で常時有効にしてはいけません。

主なパターン

構造化ログ形式（JSON）

すべてのログ行は解析可能でなければなりません。文字列の連結はログではありません。

Pino を使った Node.js：

import pino from 'pino';

const logger = pino({
  level: process.env.LOG_LEVEL ?? 'info',
  base: {
    service: 'payment-service',
    version: process.env.SERVICE_VERSION,
    env: process.env.NODE_ENV,
  },
  redact: {
    paths: ['req.headers.authorization', 'body.password', 'body.cardNumber', '*.ssn'],
    censor: '[REDACTED]',
  },
});

// Good: structured fields
logger.info({ orderId, userId, amountCents }, 'Payment processed');

// Bad: string interpolation
logger.info(`Payment processed for user ${userId} order ${orderId}`);

structlog を使った Python：

import structlog

log = structlog.get_logger()

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        structlog.stdlib.add_log_level,
        structlog.stdlib.add_logger_name,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.JSONRenderer(),
    ]
)

# Good: key-value pairs
log.info("payment_processed", order_id=order_id, user_id=user_id, amount_cents=amount)

相関 ID

すべてのリクエストには、下流のすべての呼び出しに引き継がれるトレース ID が必要です。これは、OTel を使わずに実現できる最低限の分散トレーシングです。

// Express middleware
import { randomUUID } from 'crypto';
import { AsyncLocalStorage } from 'async_hooks';

const requestContext = new AsyncLocalStorage<{ traceId: string; spanId: string }>();

export function correlationMiddleware(req, res, next) {
  const traceId = req.headers['x-trace-id'] ?? randomUUID();
  const spanId = randomUUID().slice(0, 8);

  requestContext.run({ traceId, spanId }, () => {
    res.setHeader('x-trace-id', traceId);
    next();
  });
}

// Logger that auto-includes context
export function getLogger(name: string) {
  return {
    info: (msg: string, fields?: object) => {
      const ctx = requestContext.getStore();
      logger.info({ ...ctx, ...fields, logger: name }, msg);
    },
    // ... error, warn, debug
  };
}

OpenTelemetry のセットアップ

OTel コレクターの完全な設定、言語ごとの SDK 初期化、スパン属性の規約については、references/opentelemetry-setup.md を参照してください。

最小限の Node.js ブートストラップ：

// Must be first import in entrypoint
import { NodeSDK } from '@opentelemetry/sdk-node';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node';

const sdk = new NodeSDK({
  serviceName: 'payment-service',
  traceExporter: new OTLPTraceExporter({
    url: process.env.OTEL_EXPORTER_OTLP_ENDPOINT,
  }),
  instrumentations: [getNodeAutoInstrumentations()],
});

sdk.start();

分散トレースの伝播

sequenceDiagram
    participant C as Client
    participant GW as API Gateway
    participant SVC as Payment Service
    participant DB as Database

    C->>GW: POST /checkout<br/>(no trace header)
    Note over GW: Generate trace-id: abc123<br/>span-id: 0001
    GW->>SVC: POST /payment<br/>traceparent: 00-abc123-0001-01
    Note over SVC: Inherit trace-id: abc123<br/>New span-id: 0002
    SVC->>DB: INSERT payment<br/>traceparent: 00-abc123-0002-01
    Note over DB: Inherit trace-id: abc123<br/>New span-id: 0003
    DB-->>SVC: OK (span 0003 ends)
    SVC-->>GW: 200 OK (span 0002 ends)
    GW-->>C: 200 OK (span 0001 ends)<br/>x-trace-id: abc123

W3C の traceparent ヘッダー形式は 00-{traceId}-{spanId}-{flags} です。下流へのすべての HTTP 呼び出しで、必ずこのヘッダーを伝播させてください。

参考ファイル

ファイル	内容
references/opentelemetry-setup.md	言語ごとの OTel SDK 初期化、コレクターの YAML 設定、スパン属性、コンテキスト伝播
references/alerting-patterns.md	SLI／SLO の定義、アラートのルーティング、PagerDuty の重要度マッピング、アラート疲れの防止

アンチパターン（見識を見分けるポイント）

アンチパターン 1：本番環境での PII やシークレットのログ記録

初心者の考え：「この認証の問題をデバッグするために、リクエスト本文全体をログに記録すればいい。」

**問題点：**GDPR／CCPA 違反には、世界全体の売上高の最大 4％の罰金が科されます。ログ内のシークレットは、ログ集約サービス、S3 エクスポート、監査証跡など、アクセス制御がそれぞれ異なる場所へ伝播します。console.log(req.body) を 1 回実行しただけで、何千ものユーザーパスワードが Datadog ダッシュボードに漏れるおそれがあります。

**検出方法：**ログ内で、フィールド値として password、ssn、cardNumber、authorization を検索してください（キーではありません）。いずれかが見つかった場合、PII が漏えいしています。

修正 — 許可リスト方式：

// Never log what you don't explicitly approve
const SAFE_BODY_FIELDS = ['orderId', 'productId', 'quantity', 'currency'];

logger.info({
  body: pick(req.body, SAFE_BODY_FIELDS), // only known-safe fields
  path: req.path,
  method: req.method,
}, 'Request received');

修正 — ロガー設定での秘匿化：

// Pino's redact runs before any transport
const logger = pino({
  redact: {
    paths: [
      'req.headers.authorization',
      'req.headers.cookie',
      'body.password',
      'body.*.password',   // nested objects too
      'body.cardNumber',
      'body.ssn',
      '*.token',
      '*.secret',
    ],
    censor: '[REDACTED]',
  },
});

**見識を見分けるポイント：**エキスパートは注意書きのコメントに頼らず、ロガーの初期化時に秘匿化を設定します。秘匿化は場当たり的ではなく、構造的に行う必要があります。

---

アンチパターン 2：構造化 JSON ではなく、非構造化文字列ログを使う

初心者の考え：logger.info('User ' + userId + ' purchased ' + productId + ' for $' + amount)

**問題点：**文字列に埋め込まれたデータを、ログ集約サービスでフィルタリング、集計、アラートの対象にすることはできません。amount > 1000 を検索する Grafana クエリでは、amount が文中に埋め込まれているのではなく、数値フィールドである必要があります。文字列ログは書き込み専用です。読めても、大規模にクエリすることはできません。

**影響：**1 日 1,000 万行のログが検索不能になります。インシデント発生時、エンジニアが構造化フィールドのフィルタリングではなく文字列を grep するため、MTTR（平均復旧時間）が 2 倍になります。

修正：

// Bad: string log — amount is buried in text
logger.info(`User ${userId} purchased ${productId} for $${amount}`);

// Good: structured — every field is queryable
logger.info({ userId, productId, amountDollars: amount / 100 }, 'purchase_completed');

**一貫したイベント命名：**メッセージ文字列には、snake_case の動詞と名詞を組み合わせたイベント名（payment_processed、user_signed_up、order_failed）を使います。これにより、ダッシュボードやアラートで安定した語彙を使用できます。

**見識を見分けるポイント：**ログメッセージ文字列は、ログの末尾を確認する人が読むためのものです。クエリ可能なデータはすべて構造化フィールドに格納します。出力形式が {} になるロガーのほうが、読みやすい文字列を出力するロガーより優れています。

---

アンチパターン 3：ログに記録してから例外を再送出する（二重ログ）

初心者の考え：エラーをログに記録してから再送出し、呼び出し元にも知らせます。

// BAD: log-and-throw
async function processPayment(orderId: string) {
  try {
    return await chargeCard(orderId);
  } catch (err) {
    logger.error({ err, orderId }, 'Payment failed'); // Logged here
    throw err; // And the caller logs it again
  }
}

async function handleCheckout(req, res) {
  try {
    await processPayment(req.body.orderId);
  } catch (err) {
    logger.error({ err }, 'Checkout failed'); // Same error logged twice
    res.status(500).json({ error: 'Checkout failed' });
  }
}

問題点：呼び出しの深さによって、すべてのエラーがログに2～5回表示されます。エラー件数に基づくアラートの信頼性が低下します。インシデントの振り返りも混乱を招き、エンジニアは複数の障害が発生したと考えてしまいます。ログの量にはコストがかかります（Datadog は取り込み量 1 GB ごとに課金します）。

修正 — エラーを処理する境界でのみログに記録します：

// Good: log only where you decide what to do with the error
async function processPayment(orderId: string) {
  // No try-catch: let errors propagate naturally
  return await chargeCard(orderId);
}

async function handleCheckout(req, res) {
  try {
    await processPayment(req.body.orderId);
    res.json({ success: true });
  } catch (err) {
    // One log, at the boundary where we're deciding to return 500
    logger.error({ err, orderId: req.body.orderId }, 'checkout_failed');
    res.status(500).json({ error: 'Checkout failed' });
  }
}

ルール：処理する箇所でログに記録します。伝播させる箇所ではログに記録しません。エラーオブジェクトのコールスタックに、発生元はすでに示されています。

見分け方：1つのリクエストについて、同じ traceId がエラーログに3行以上現れる場合、ログに記録してから再送出する連鎖がどこかにあります。

品質チェックリスト

[ ] All log lines are JSON (no string concatenation)
[ ] Log level strategy documented: what goes at each level
[ ] PII/secrets redacted at logger config level, not call site
[ ] Correlation IDs propagated on all outbound HTTP calls
[ ] OTel SDK initialized before any other imports
[ ] Error logs include the error object (not just message)
[ ] No log-and-throw patterns in error handling
[ ] DEBUG logs use conditional guards or sampling
[ ] SLI/SLO defined for each critical user journey
[ ] Alert routing: notify vs page threshold documented
[ ] Runbook linked from every paging alert
[ ] Log retention policy set (cost vs compliance)

出力成果物

1. ロガー設定 — Redaction ルールを含む Pino/Winston/structlog のセットアップ
2. OTel ブートストラップファイル — 自動インストルメンテーションを含む SDK 初期化
3. 相関ミドルウェア — AsyncLocalStorage のリクエストコンテキスト
4. Prometheus メトリクスモジュール — カウンター／ヒストグラム／ゲージの定義
5. Grafana ダッシュボード JSON — 4つのゴールデンシグナルパネル
6. Alertmanager ルール YAML — SLO ベースのアラート定義