サービスやジョブを横断してスケールする構造化ロギング

単一のサービスと単一のログファイルという構成は、デバッグが容易です。エラー文字列で grep し、その周辺の行を読めば、事の経緯を把握できます。そのモデルは、リクエストが2つ目のサービスに触れたり、非同期ワーカーに処理を渡したり、バックグラウンドジョブを起動したりした瞬間に破綻します。そうなると、1つのリクエストの経緯は3つのログストリームに散らばり、何千もの無関係な行が混在し、それらを結びつける糸口もなくなってしまいます。解決策は、ロギングを増やすことではありません。リクエストがどこへ行ってもそれを追跡する共有識別子を持つ構造化データとしてログを記録することです。本稿では、その実現方法を解説します。文章の代わりにJSONログ、エントリーポイントで生成され全ホップに伝播される相関ID、そして全サービスが合意する1つのスキーマです。

フリーフォームテキストログがスケールしなくなる理由

user 4021 failed to charge card, retryingのような行は、人間にとっては問題なく読めます。ログシステムにとっては、これは不透明な文字列です。もし「過去1時間に年間プランのユーザーで何件の課金失敗が発生したか」という問いに答えようとしても、それは不可能です。なぜなら、「年間プラン」や「課金失敗」といった情報が、ログ呼び出しごとに異なる文章の中に埋もれてしまっているからです。あるエンジニアはcharge failedと書き、別のエンジニアはpayment declinedと書き、また別のエンジニアはcould not billと書きます。これらは同じイベントを意味しますが、どのクエリもこれらをグループ化することはできません。

リクエストが複数のサービスにまたがる場合、より深刻な問題が現れます。APIサーバーがリクエストを受け取り、課金サービスを呼び出し、その課金サービスがワーカーのジョブをエンキューします。ワーカーで何かが失敗します。手元にはワーカーのエラーがありますが、それを元のリクエスト、ユーザー、あるいはそれを開始したAPI呼び出しに結びつけるものが何もありません。結局、タイムスタンプと当て推量で相関関係を調べ、3つのターミナルをスクロールしながらタイミングが合うことを祈る羽目になります。量が少なければ、これは煩わしいだけです。しかし、実際の量になると、これは不可能になります。なぜなら、同じ1秒間に、それぞれのストリーム内で無関係なリクエストが何十も入り混じっているからです。

フリーフォームログは、人間がそれらを順番に読むことを前提としています。分散システムは、その両方の前提を覆します。つまり、何も順番通りではなく、人間はその量を読み切ることができません。ログは、クエリ可能なデータになる必要があります。

ログは文章ではなく、データである

考え方の転換はこうです。ログ行は人が読むメッセージではなく、マシンがクエリするレコードであるということです。値を文章にフォーマットするのではなく、フィールドを出力します。イベント名はフィールドです。ユーザーIDはフィールドです。結果はフィールドです。メッセージは、もしあれば、単なるもう1つのフィールドに過ぎず、重要なものではありません。

以下に、同じ課金失敗を自由形式のテキストと構造化データで示します。

ログがフィールドになると、これまで目視で行っていた作業をログコレクターが代行します。1つのイベントタイプにフィルタリングし、任意のフィールドでグループ化し、時間枠でカウントし、結果をグラフ化します。「過去1時間に年間プランのユーザーで課金失敗が何件あったか」という問いは、不可能なgrepの代わりに、フィルタリングとグループ化になります。

Goでは、標準ライブラリにまさにこのためのlog/slogが同梱されています。重要な洞察は、値を文字列補間としてではなく、型付けされたキーと値のペアとして添付する点です。

import "log/slog"

logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
	Level: slog.LevelInfo,
}))

// Not this. The values are trapped inside a sentence.
// logger.Info(fmt.Sprintf("user %d failed to charge, retry=%v", userID, true))

// This. Every value is a field the collector can query.
logger.Info("charge failed",
	slog.String("event", "charge_failed"),
	slog.Int("user_id", userID),
	slog.String("plan", "annual"),
	slog.Bool("retry", true),
)

出力は1行に1つのJSONオブジェクトで、どのログコレクターでもネイティブにパースされます。

{"time":"2026-07-17T09:14:22+09:00","level":"INFO","msg":"charge failed","event":"charge_failed","user_id":4021,"plan":"annual","retry":true}

event フィールドが msg とは別であることに注意してください。メッセージは人間が読みやすいテキストであり、自由に変更できます。event はクエリに使用する安定したマシンキーであり、決して変更してはなりません。イベント名は一度決めたら、APIとして扱ってください。

リクエストを一つにまとめる相関ID

構造化されたフィールドは、1つのサービスをクエリ可能にします。相関IDは、システム全体を追跡可能にします。考え方はシンプルです。リクエストが最初にシステムに入ったときに、そのリクエストに一意のIDを生成します。次に、そのIDをすべてのログ行、すべてのダウンストリームサービスコール、およびリクエストが生成するすべてのジョブに添付します。すべてのサービスにわたる1つのリクエストの全行程を再構築するには、1つの値でフィルタリングします。

このIDには、trace_id、request_id、correlation_idなど、いくつかの名前があります。重要なのは、エッジで一度作成され、再生成されることはないということです。通常はHTTPミドルウェアであるエントリポイントが、それが生成される場所です。

// Middleware: reuse an inbound trace ID if a trusted upstream sent one,
// otherwise mint a fresh one. Store it on the context so every log call
// downstream can read it.
type ctxKey string

const traceIDKey ctxKey = "trace_id"

func TraceMiddleware(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		traceID := r.Header.Get("X-Trace-Id")
		if traceID == "" {
			traceID = newTraceID() // e.g. a random 16-byte hex string
		}

		ctx := context.WithValue(r.Context(), traceIDKey, traceID)

		// Bind the trace ID into a logger stored on the context, so no
		// call site has to remember to pass it.
		reqLogger := slog.With(slog.String("trace_id", traceID))
		ctx = context.WithValue(ctx, loggerKey, reqLogger)

		w.Header().Set("X-Trace-Id", traceID)
		next.ServeHTTP(w, r.WithContext(ctx))
	})
}

// Every handler pulls the request-scoped logger back off the context.
func loggerFrom(ctx context.Context) *slog.Logger {
	if l, ok := ctx.Value(loggerKey).(*slog.Logger); ok {
		return l
	}
	return slog.Default()
}

これで、リクエスト内のすべてのログ呼び出しは、エッジで一度ロガーがトレースIDとバインドされたため、自動的にトレースIDを保持するようになります。

func chargeHandler(w http.ResponseWriter, r *http.Request) {
	log := loggerFrom(r.Context())
	log.Info("charge started", slog.String("event", "charge_started"))
	// ... every line from here carries the same trace_id
}

サービスとワーカーの境界を越えたIDの伝播

1つのサービス内にのみ存在するIDは、境界では何の価値もありません。重要なのは、IDがホップを越えて存続することです。対処すべきホップは2つあります。別のサービスへの同期呼び出しと、ワーカーやジョブへの非同期ハンドオフです。

同期HTTP呼び出しの場合、呼び出し元はコンテキストからトレースIDを読み取り、送信ヘッダーに書き込みます。呼び出し先のミドルウェアはその同じヘッダーを読み取ります。これが、上記のミドルウェアが新しいIDを生成する前に X-Trace-Id をチェックする理由です。

// Outbound call: carry the trace ID forward as a header.
func callBilling(ctx context.Context, body io.Reader) (*http.Response, error) {
	req, _ := http.NewRequestWithContext(ctx, http.MethodPost, billingURL, body)
	if id, ok := ctx.Value(traceIDKey).(string); ok {
		req.Header.Set("X-Trace-Id", id)
	}
	return http.DefaultClient.Do(req)
}

非同期ハンドオフの場合、ワーカーは呼び出し元とのライブ接続なしに後で実行されるため、ヘッダーのトリックは適用されません。そのため、IDはメッセージの内部で渡されます。ジョブのペイロードにIDを入れ、ワーカーがそれを取り出して、ミドルウェアが行ったのと同じ方法でロガーを再バインドします。

// Enqueue: the trace ID rides along inside the job payload.
type ChargeJob struct {
	TraceID string `json:"trace_id"`
	UserID  int    `json:"user_id"`
}

func enqueueCharge(ctx context.Context, q Queue, userID int) error {
	id, _ := ctx.Value(traceIDKey).(string)
	return q.Push(ChargeJob{TraceID: id, UserID: userID})
}

// Worker: rebuild the request-scoped logger from the payload, so the
// worker's logs share the trace_id of the request that queued the job.
func (w *Worker) handle(job ChargeJob) {
	log := slog.With(slog.String("trace_id", job.TraceID))
	log.Info("charge job picked up", slog.String("event", "charge_job_started"))
	// ... the worker's failure now joins to the original API request
}

これにより、1つの trace_id がAPIログ、課金サービスログ、ワーカロｸﾞを関連付けます。ワーカーが失敗した場合、そのIDですべてのストリームをフィルタリングし、プロセスの境界を越えて、あたかも単一のログファイルで実行されたかのように、リクエストの完全なパスを順番に読み取ることができます。

1つのスキーマ、1つのタイムベースを、あらゆる場所で

伝播が効果を発揮するのは、すべてのサービスがフィールドについて合意している場合のみです。APIサーバーが trace_id を書き込み、ワーカーが traceId を書き込み、課金サービスが request_id を書き込む場合、それらを結合することはできず、推測に戻ってしまいます。共有スキーマこそが、サービス横断的なクエリを実際に機能させるものです。すべてのサービスがすべての行で出力する、少数の基本フィールドのセットについて合意してください。

• timestamp、フリート全体で1つのタイムベースで。異なるホストからの行が正しくソートされるように、UTCまたは単一の固定ゾーンを推奨します。混在したローカルゾーンは、順序を偽りのものにします。
• level、重要度。
• service、出力元サービスの名前。これにより、マージされたストリームから1つのサービスをフィルタリングできます。
• event、何が起こったかを示す安定したマシンキー。
• trace_id、前述の相関ID。

これら以外に、各イベントは独自のフィールドを追加します。基本セットは契約であり、追加分は自由です。基本セットを強制する最も安価な方法は、各チームが覚えていることを信頼するのではなく、すべてのサービスがインポートする共有ロガーコンストラクタに組み込むことです。フィールド名が1つのライブラリに存在すれば、それらがずれることはありません。

タイムベースは、最も一般的な静かな障害であるため、特に強調する価値があります。あるホストがローカルタイムでログを記録し、別のホストがUTCでログを記録すると、マージされたビューではイベントが誤った順序になり、実際には200ミリ秒かかったリクエストが時間を遡ったように見えることがあります。マシンタイムスタンプには1つのゾーンを選び、決して逸脱しないでください。分かりやすいローカルタイムは、ログへの書き込み時ではなく、ダッシュボードでの読み取り時にレンダリングしてください。

レベルの規律と秘密情報の排除

システムが一度導入されると、全体を使いやすく保つための2つのルールがあります。

第一に、ログレベルは慎重に使い分けることです。errorは、人間が対応する必要があることを意味すべきです。もし日常的で回復可能な状態がerrorで記録されるなら、そのレベルは意味を失い、それに基づくアラートはオオカミ少年となり、人々は決して無視すべきではない唯一のシグナルを無視することを学習してしまいます。回復可能だが注目すべき事象にはwarnを、リクエストの通常の流れにはinfoを、特定の問題を追跡しているときにのみ必要となる詳細にはdebugを使用します。成功したリトライはinfoかwarnであり、errorではありません。errorは、実際に失敗し、失敗したままの状態になった結果のために取っておきます。

第二に、秘密情報や個人データを決してログに記録しないことです。構造化ロギングは、構造体全体をフィールドとしてダンプすることが非常に簡単であるため、この罠を改善するどころか、さらに悪化させます。その構造体には、パスワードハッシュ、アクセストークン、完全なカード番号、メールアドレスが含まれている可能性があります。ログはサードパーティのコレクターに送られ、数ヶ月間保持され、生の個人データを見るべきではない人々によって読まれるため、ログ行に含まれる秘密情報は、発見されるのを待っている侵害行為となります。ロギングの境界で、機密フィールドをマスクまたは削除します。ユーザーIDはログに記録しますが、メールアドレスは決して記録しません。トークンが存在したことはログに記録しますが、トークン自体は決して記録しません。エラーオブジェクトをログに記録する際は、それを引き起こしたリクエストボディが含まれていないことを確認してください。

構造化ロギングのコスト

これらはどれも無料ではなく、トレードオフを意図的に行うために、その代償を明言する価値があります。構造化ロギングは、文章に値を埋め込むのではなく各フィールドに名前を付けるため、printfよりも記述が冗長になります。すべてのサービスコールとジョブペイロードにトレースIDを通すことは、構築し維持しなければならない配線であり、IDの伝播を忘れた単一のサービスは、まさに最もそれを望まない場所に死角を生み出します。JSONログはプレーンテキストよりもサイズが大きく、ログが大きくなると、特にinfoやdebugレベルの量では、転送、保存、保持にかかるコストが増加します。

緩和策はありふれたものです。サンプリングは、大量で価値の低い行の一部をドロップするため、成功したリクエストはそれぞれが完全な負荷を支払うことはなく、一方で失敗は引き続き完全にログに記録されます。レベルの規律により、デフォルトでdebugは本番ストレージから除外されます。共有ロギングライブラリが伝播の配線を吸収するため、個々の呼び出し箇所はシンプルに保たれます。時間が刻々と過ぎていくインシデント中に、3つのターミナルを開いてタイムスタンプを当て推量するという代替案と比較すれば、そのコストは小さいものです。サービスチェーンのどこかでリクエストが失敗した瞬間、1つの相関IDと1つのクエリ可能なスキーマが、午後いっぱいの当て推量を単一のフィルターに変え、それが回復の速さを決定するのです。