Language: 日本語

「ログが出ないのに送信完了扱い？」監査ログの silent 破棄と OTel の沈黙を暴いた観測設計

「うちのシステムは監査ログを確実に記録できている」と自信を持って言えますか？

アプリケーションコードの中で logger.info(...) を呼び出し、例外が出ずに処理が完了していれば、「ログは問題なくログ基盤に保存された」と思ってしまいがちです。

しかし、実際のプロダクション環境では 「書き込んだ側から見ると正常終了したように見えて、実はログが 1 行も残っていなかった」 という恐ろしいサイレント障害が潜んでいます。

アノテーション基盤の監査ログと Observability 基盤を整備する中で、まさにこの「出したつもり」になっていた 2 つの重大な落とし穴に直面しました。

LOG_LEVEL=warn によって、成功した監査イベントがすべて静かに破棄されていた問題
OpenTelemetry の Diag Logger 未設定により、Cloud Trace へのエクスポート失敗（PERMISSION_DENIED）が数日間沈黙していた問題

この記事では、これらのサイレント障害のメカニズムと、Transactional Outbox パターンによる確実な配送保証、そして 「観測の仕組みは、自分自身の失敗を報告できない」という確認経路の分離原則 を解説します。

得られること

全体のログレベルを上げずに監査ログだけを確実に残す Scoped Child Logger 設計がわかる
トランザクション Outbox パターンを用いて、ドメイン変更と監査記録を atomic に担保する構造が学べる
OpenTelemetry の Diag Logger を設定し、トレースやメトリクス送信のサイレント失敗を未然に防ぐ方法が身につく！

トラブル 1: 出力レベルで消えていた成功監査イベント

本番環境のバックエンドは、ログの肥大化とコストを抑えるために LOG_LEVEL=warn で運用していました。

ここで問題になったのが 「権限操作やリソース変更の成功監査イベント」 です。監査イベントは正常系の記録であるため info レベルで出力していましたが、ロガー（Pino）のフィルタリングによって 標準出力に出る前の段階ですべて静かに破棄（drop） されていました。

【発生していたサイレント破棄】
アプリケーション
  │  監査ログを出力（level: info）
  ▼
ロガー (Pino: LOG_LEVEL=warn)
  │  閾値未満のため静かに破棄（drop）💥
  ▼
Outbox / 配送処理
  │  「例外が出なかった」ためステータスを delivered（送信完了）へ更新 😱

最もまずかったのは、Outbox の配送側が「logger 呼び出し時に例外がスローされなかったこと」をもって delivered（送信完了）として処理を完了させていたこと です。

ログ基盤（Cloud Logging）には 1 行も記録が残っていないのに、データベース上は「監査ログ記録済み」になっている。これではセキュリティ監査としてまったく意味をなしません。

解決策: Scoped Child Logger によるレベルの局所開放

全体のログレベルを info に引き上げると、通常のリクエストログやフレームワークの内部ログが大量に流れ込み、ノイズとコストが爆発します。

そこで、「監査イベントを出力する専用の Child Logger だけ、level: 'info' を強制する」 構造に改修しました。

// 監査イベント専用の Child Logger
export class AuditLogger {
  private readonly childLogger: Logger;

  constructor(parentLogger: Logger) {
    // 親が LOG_LEVEL=warn でも、この child だけは info を通過させる
    this.childLogger = parentLogger.child({
      module: "audit",
      level: "info",
    });
  }

  logAuditEvent(event: AuditEvent): void {
    this.childLogger.info(event);
  }
}

親ロガーの閾値（warn）を維持したまま、監査イベントだけをピンポイントで標準出力 ➔ ログ基盤へ確実に届けることができます。

トランザクション Outbox による Atomic な記録保証

監査ログをアプリケーションのインライン処理で外部 API に直接送ろうとすると、以下のような不整合が発生します。

DB のコミットには成功したが、外部ログ基盤への送信がタイムアウトして監査が抜ける
外部ログ基盤への送信には成功したが、DB のトランザクションがロールバックされ、「実際には行われていない操作の監査ログ」が残る

この不整合を防ぐため、Transactional Outbox パターン を採用しました。

【 1 つの DB トランザクション 】
  ├─ ドメインテーブルの更新（Task の作成・更新など）
  └─ outbox テーブルへの監査イベント書き込み ⚡️

【 非同期 Relay プロセス 】
  ├─ 1. 未送信の outbox 行を SELECT
  ├─ 2. ログ基盤へ配送（HTTP / PubSub）
  └─ 3. 送信成功後、delivered に更新（失敗時はリトライ）

// ドメインの変更と監査記録を同一トランザクションでコミット
await prisma.$transaction(async (tx) => {
  // 1. ドメインの更新
  const task = await tx.task.update({
    where: { id: taskId },
    data: { status: "COMPLETED" },
  });

  // 2. 監査イベントを outbox テーブルへ書き込み
  await tx.auditOutbox.create({
    data: {
      eventId: generateEventId(),
      eventType: "task.completed",
      actorId,
      payload: { taskId, status: "COMPLETED" },
      status: "PENDING",
    },
  });
});

Outbox 設計のポイント

Atomic 保証: ドメイン変更がロールバックされたら、Outbox への書き込みも自動的に消滅します。
At-Least-Once 配送と冪等性: Relay は失敗時にリトライを行うため、一時的なネットワーク障害があっても確実に配送されます。二重送信に備えて、受け側は eventId で重複排除（deduplication）を行います。

トラブル 2: OpenTelemetry の Diag Logger 未設定による沈黙

観測基盤の整備中にもう 1 つ、同じ「サイレント失敗」を踏みました。

それは OpenTelemetry SDK の Diag Logger が未設定だったこと です。

本番環境で Cloud Trace へのスパンエクスポートを設定していたのですが、Service Account の IAM 権限（roles/cloudtrace.agent）が不足しており、バックグラウンドでのエクスポートが PERMISSION_DENIED で全滅していました。

しかし、OpenTelemetry の BatchSpanProcessor はアプリケーションのメインスレッドをブロックしないよう設計されているため、エクスポートに失敗しても例外を throw しません。

Diag Logger を明示的に初期化していなかったため、エラーログが標準出力にすら出ず、数日間にわたってトレースが一切保存されていない状態を誰も検知できませんでした。

解決策: SDK 起動前の Diag Logger 設定

import { diag, DiagConsoleLogger, DiagLogLevel } from "@opentelemetry/api";

// ⚠️ 必ず sdk.start() より前に Diag Logger を設定する！
diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.ERROR);

// その後 SDK を初期化
const sdk = new NodeSDK({
  traceExporter: new TraceExporter(),
  // ...
});
sdk.start();

これにより、エクスポート失敗や認証エラーが発生した瞬間に Cloud Logging へ ERROR ログが出力され、即座にアラートで検知できるようになりました。

観測の原則: 確認経路を分離する

今回のトラブルから得られた教訓は、すべて 1 つの原則に帰結します。

「観測のための仕組みは、自分自身の失敗を自分自身で報告できない」

観測対象	配送する側	配送を確認・検知する側
監査ログの記録	アプリケーション本体	非同期 Relay プロセス & Outbox テーブル
ログレベルの整合性	ロガー（Pino）	Log-based Metric と型付けされた契約テスト
OTel トレース送信	Trace Exporter	OTel Diag Logger & Cloud Logging アラート

書き込んだ本人は「関数を呼んだ」という事実しか知ることができません。本当に届いたかどうかを確かめるには、「配送するプロセスとは別の確認経路（Outbox、Diag Logger、独立したメトリクス）」 を外側に用意する必要があります。

「動いているはず」を疑い、配送と確認の境界を分けること。これこそが、本番環境で信頼できる Observability を手に入れるための設計の要です。