第21章：観測できるOutbox（ログ・メトリクス・追跡）🔍📊✨
この章のゴール🎯
Outboxは「非同期であとから送る」ぶん、失敗や遅延が表に出にくいんだよね🥹 だからこの章では、困ったときに 原因へ最短でたどり着けるように、最初から観測を仕込むよ〜！🧯✨
21-1. Outboxで起きがちな“静かな事故”😱📦
次のどれか、経験したら観測の大切さが刺さるやつ👇
- Publisherが落ちてるのに誰も気づかず、未送信が積み上がる📚📈
- 送信は動いてるけど遅くて、通知が数十分遅延⏳💦
- リトライが暴走して、同じ失敗を連打🔁🔁🔁
- DLQに落ちまくってるのに、アラートが無い📮😢
- たまに二重送信が起きるけど、追跡できない🌀
これを防ぐのが、ログ📝・メトリクス📈・トレース🧵の三点セットだよ✨
21-2. 観測の“三種の神器”🧰✨
① ログ（Logs）📝
- 「何が起きた？」を文章＋構造（JSON）で残す📄
- eventId / eventType / attempt / 失敗理由が命🔑
② メトリクス（Metrics）📈
- 「どれくらい起きてる？」を数字で見る👀
- 例：未送信件数、最古の滞留時間、失敗率、リトライ回数…
③ トレース（Traces）🧵
- 「どこが遅い？どこで詰まる？」を処理の流れで見る🧭
- Outboxは API → DB → Publisher → 送信先 とまたぐから特に効くよ〜
この考え方は OpenTelemetry の公式ドキュメントでも、まずトレース＆メトリクスから始める流れになってるよ。(OpenTelemetry)
21-3. “追跡できる”ためのID設計🔗🆔✨
Outbox観測でよく使うIDはこれ👇
- eventId：OutboxレコードのID（冪等キーにもなりがち）🆔
- correlationId：業務リクエスト単位の追跡ID（注文確定1回＝1つ）🧵
- traceId / spanId：分散トレースのID（ログとつなぐ）🔍
ポイントはこれ！👇 ✅ Outboxテーブルに correlationId を必ず持たせる （できれば traceparent も持たせると、非同期の“橋渡し”ができて強い🔥）
21-4. ログ設計📝✨（まずは“構造化ログ”が最優先！）
21-4-1. ログはJSONで出そう📄✨
“あとで検索・集計・追跡できる”形が大事だよ〜！ おすすめは Pino みたいなJSONロガー🧃（もちろんWinstonでもOK） PinoはOpenTelemetry連携（trace_id / span_id の注入）もしやすい流れがあるよ。(dash0.com)
21-4-2. ログに必ず入れたい項目✅
最低限このへん入ってると、調査が爆速になるよ⚡
- correlationId 🧵
- eventId / eventType 🆔🏷️
- status（pending/processing/sent/failed…）🚦
- attempt（何回目？）🔁
- nextRetryAt（次いつ？）🕒
- errorCode / errorMessage（分類と要約）🧱
- durationMs（処理時間）⏱️
- （できれば）traceId / spanId 🔍
21-4-3. 例：AsyncLocalStorageでcorrelationIdを全ログに混ぜる🧵📝
// src/observability/logger.ts
import pino from "pino";
import { AsyncLocalStorage } from "node:async_hooks";
import { context, trace } from "@opentelemetry/api";
type RequestContext = { correlationId: string };
const als = new AsyncLocalStorage<RequestContext>();
export function runWithContext<T>(ctx: RequestContext, fn: () => T): T {
return als.run(ctx, fn);
}
export function getContext(): RequestContext | undefined {
return als.getStore();
}
export const logger = pino({
level: process.env.LOG_LEVEL ?? "info",
timestamp: pino.stdTimeFunctions.isoTime,
base: null,
mixin() {
const rc = getContext();
const span = trace.getSpan(context.active());
const sc = span?.spanContext();
return {
correlationId: rc?.correlationId,
traceId: sc?.traceId,
spanId: sc?.spanId,
};
},
});
これで、
logger.info()したログ全部に correlationId（＋traceId/spanId）が乗るよ〜！🎉
21-4-4. Outboxで“出すべきログポイント”📍📝
実装ではこのタイミングでログを置くのが王道👇
- Outbox書き込み成功（業務更新と同トランザクション後）✅
- Publisherがレコード確保（processingへ遷移した瞬間）🧲
- 送信成功（sentへ）📤✅
- 送信失敗（failed / retry予定）📤❌
- DLQ落ち（deadletterへ）📮😢
21-5. メトリクス設計📊✨（“詰まり”を数字で即発見！）
21-5-1. Outboxで“最重要”のメトリクスはこれ🥇
まずはこの4つが最強セット💪✨
- **未送信件数（backlog）**📚
- **最古の滞留時間（oldest age）**🕰️
- 成功/失敗/リトライ回数✅❌🔁
- 送信処理のレイテンシ（publish latency）⏱️
21-5-2. Prometheus向けメトリクスを最短で出す（prom-client）📈
Nodeのメトリクスは prom-client が定番で、registry.metrics() を返せばScrapeできるよ。(GitHub)
// src/observability/metrics.ts
import client from "prom-client";
export const registry = new client.Registry();
client.collectDefaultMetrics({ register: registry });
export const outboxBacklog = new client.Gauge({
name: "outbox_backlog_total",
help: "Outbox backlog by status",
labelNames: ["status"] as const,
registers: [registry],
});
export const outboxOldestAge = new client.Gauge({
name: "outbox_oldest_age_seconds",
help: "Age in seconds of the oldest pending outbox record",
registers: [registry],
});
export const publishTotal = new client.Counter({
name: "outbox_publish_total",
help: "Outbox publish attempts",
labelNames: ["result", "eventType"] as const,
registers: [registry],
});
export const publishLatency = new client.Histogram({
name: "outbox_publish_latency_seconds",
help: "Publish latency in seconds",
buckets: [0.01, 0.05, 0.1, 0.25, 0.5, 1, 2, 5, 10],
labelNames: ["result", "eventType"] as const,
registers: [registry],
});
/metrics を生やす（最小：NodeのhttpでOK）👇
// src/observability/metricsServer.ts
import http from "node:http";
import { registry } from "./metrics";
import { logger } from "./logger";
export function startMetricsServer(port = 9091) {
const server = http.createServer(async (req, res) => {
if (req.url === "/metrics") {
res.statusCode = 200;
res.setHeader("Content-Type", registry.contentType);
res.end(await registry.metrics());
return;
}
res.statusCode = 404;
res.end("not found");
});
server.listen(port, () => logger.info({ port }, "metrics server started"));
}
21-5-3. メトリクス更新のコツ🧠✨
- backlog/oldestAgeは 一定間隔でDBを見て更新（例：10秒ごと）⏱️
- publishTotal/publishLatencyは 送信のたびに更新📤
- ラベル（eventTypeなど）を増やしすぎると集計が重くなるから注意⚠️（最初は eventType くらいで十分）
21-6. トレース導入🧵🔍（Publisherの“どこが遅い？”が見える！）
21-6-1. いまのOpenTelemetry（Node/TS）事情ざっくり🧠
- 公式Getting Startedでも トレース＆メトリクス をまず扱うよ。(OpenTelemetry)
- 公式には「Nodeのログ機能は開発中で、例は載せてないよ」って明記されてるの。なのでログはロガー（Pino等）＋トレース相関が現実的だよ。(OpenTelemetry)
- JS SDK 2.0以降はサポートNode/TS条件が上がってる（Node 18.19+ / TS 5.0.4+ など）。(OpenTelemetry)
21-6-2. 自動計測（auto-instrumentations-node）で“まず見える化”✨
@opentelemetry/auto-instrumentations-node は、よくあるライブラリ群をまとめて計測してくれるメタパッケージだよ。(GitHub)
（HTTPやDBクライアントなど、基礎が勝手に取れるの嬉しい🥳）
// src/observability/otel.ts
import { NodeSDK } from "@opentelemetry/sdk-node";
import { getNodeAutoInstrumentations } from "@opentelemetry/auto-instrumentations-node";
import { ConsoleSpanExporter } from "@opentelemetry/sdk-trace-base";
import { PeriodicExportingMetricReader, ConsoleMetricExporter } from "@opentelemetry/sdk-metrics";
const sdk = new NodeSDK({
traceExporter: new ConsoleSpanExporter(),
metricReader: new PeriodicExportingMetricReader({
exporter: new ConsoleMetricExporter(),
}),
instrumentations: [getNodeAutoInstrumentations()],
});
export async function startOtel() {
await sdk.start();
process.on("SIGTERM", async () => {
await sdk.shutdown();
process.exit(0);
});
}
📌重要：**otel初期化は“できるだけ最初”**にやろうね！（http/DBを読み込んだ後だと自動計測が効かないことがあるよ）💡
21-6-3. Publisherの“自前Span”を入れる（ここが超効く🔥）
// src/publisher/publishOne.ts
import { SpanStatusCode, trace } from "@opentelemetry/api";
import { logger } from "../observability/logger";
import { publishLatency, publishTotal } from "../observability/metrics";
const tracer = trace.getTracer("outbox-publisher");
type OutboxRow = {
id: string;
eventType: string;
attempt: number;
correlationId: string;
};
export async function publishOne(row: OutboxRow, send: () => Promise<void>) {
return tracer.startActiveSpan(
"outbox.publish",
{ attributes: { "outbox.id": row.id, "outbox.event_type": row.eventType, "outbox.attempt": row.attempt } },
async (span) => {
const t0 = Date.now();
try {
logger.info({ eventId: row.id, eventType: row.eventType, attempt: row.attempt }, "publish start");
await send();
publishTotal.inc({ result: "success", eventType: row.eventType });
publishLatency.observe(
{ result: "success", eventType: row.eventType },
(Date.now() - t0) / 1000
);
span.setStatus({ code: SpanStatusCode.OK });
logger.info({ eventId: row.id, eventType: row.eventType }, "publish success");
} catch (e) {
publishTotal.inc({ result: "failed", eventType: row.eventType });
publishLatency.observe(
{ result: "failed", eventType: row.eventType },
(Date.now() - t0) / 1000
);
span.recordException(e as Error);
span.setStatus({ code: SpanStatusCode.ERROR });
logger.error({ eventId: row.id, eventType: row.eventType, err: e }, "publish failed");
throw e;
} finally {
span.end();
}
}
);
}
これでトレースを見ると、Publisher内の遅いポイントが一発でわかるよ〜！🔍✨
21-7. ログ×トレース相関（“この失敗、どの処理の途中？”が即わかる）🔗🧵
PinoやWinstonにトレースIDを混ぜる仕組み（ログ相関）が整ってきてて、trace_id/span_id をログに注入できるよ。(dash0.com) だから現実的にはこうするのが強い👇
- ログはPino（JSON）で出す📝
- トレースはOpenTelemetryで出す🧵
- ログに traceId/spanId が入るようにする（さっきの logger.ts のmixin）🔗
すると… 📌ログで error を見つける → traceId でトレースに飛ぶ → 遅い/詰まりを見る ができる！最高〜！🎉
21-8. ダッシュボード（画面）で見るべきもの📺📊✨
最初のダッシュボードは、これだけで“勝てる”よ💪
パネルおすすめ構成🧩
- backlog（pending/processing/failed）📚🚦
- oldest age（秒）🕰️
- publish success / failed（分あたり）✅❌
- publish latency（p95/p99）⏱️
- retry回数（分あたり）🔁
- DLQ増加（分あたり）📮😢
- worker heartbeat（一定時間で処理が進んでる？）💓
21-9. アラート設計（“気づけるOutbox”へ）🚨✨
最初はこの3つをアラートにすると安心度が跳ねるよ🫶
- oldest age が閾値超え（例：300秒以上が10分続く）⏳🚨
- failed が増え続ける（失敗率が一定以上）📈❌
- 成功が止まった（publish成功が0の状態が続く）🛑
“backlogが増えてる”だけだと、夜間バッチでも増えるからね💡 oldest age がいちばん素直な危険信号になりやすいよ🕰️✨
21-10. 事故ったときの調査ルート（ランブック）🧯🗺️
ケースA：backlogが増えてる📚📈
- oldest age を見る（積み上がりが“古い”か確認）🕰️
- Publisherログで
publish failedの増加を見る📝 - トレースで
outbox.publishを探して、遅い場所を特定🧵🔍 - 一時障害ならリトライ設定（バックオフ）を確認🔁⏳
ケースB：DLQが増えてる📮😢
- DLQの理由（errorCode）で分類🧱
- payloadのバージョンや必須項目の欠損を疑う🧬
- “直して再投入”の導線（運用手順）を確認🔧
21-11. “観測もテストする”🧪✅（地味だけど超効く）
Outboxは観測が命だから、ここも軽くテストしておくと強いよ✨
- 送信成功したら
publishTotal{result="success"}が増える✅📈 - 送信失敗したら
publishTotal{result="failed"}が増える❌📈 - ログに
eventId / correlationId / attemptが入ってる📝🔎 publishLatencyが観測されてる⏱️
「観測が壊れてたせいで、障害時に何も分からない」って事故、ほんとあるあるだからね🥹
21-12. AI活用ミニ型🤖✨（観測の抜け漏れチェックに超便利！）
① ログ項目チェック✅
- 「Outboxのトラブルシュートで必要なログ項目、足りてないのある？」📝
② メトリクス設計レビュー📊
- 「このOutboxのメトリクスで、詰まり/遅延/失敗を早期検知できる？改善案ある？」📈
③ アラート閾値案🚨
- 「oldest age と失敗率のアラート閾値、最初の安全な設定案を出して」🕰️
まとめ🎀
この章でやったことはこれ👇✨
- ログ：eventId/correlationId/attempt/理由を残す📝
- メトリクス：backlog・oldest age・失敗率・レイテンシを見る📊
- トレース：Publisherの遅いポイントをspanで掴む🧵
- 運用：ダッシュボードとアラートで“気づけるOutbox”へ🚨
OpenTelemetryの公式Getting Startedでも「まずトレース＆メトリクス」＋「ログはまだ発展途上」という前提が書かれてるので、いまの現実解としてこの構成がいちばん戦えるよ💪✨(OpenTelemetry)