【C#】ASP.NET Core と W3C Trace Context とお手軽ロギング。

最初に結論。

この記事自体はアレコレ書いていますが、結論に至るまでが長いので、先に結論というか言いたい事から入ります。 とりあえず覚えておいて欲しいのはたった1つです。 それは「ConsoleFormatterOptions.IncludeScopes = true が死ぬほどお手軽かつ便利」という事です。 IncludeScopes の設定は AddSimpleConsole とか AddJsonConsole とかする際にオプションを設定するだけです。

// SimpleConsole
builder.Logging.AddSimpleConsole(options =>
{
    options.IncludeScopes = true; // <- これ
});

// JsonConsole
builder.Logging.AddJsonConsole(options =>
{
   options.IncludeScopes = true; // <- これ
   options.TimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z'";
   options.UseUtcTimestamp = true;
});

上記の IncludeScopes = true の設定に加えて、もうちょっとあれこれ設定を入れると以下のようなログが表示されます (SimpleConsole版)。 SpanId TraceId ParentId ConnectionId とかいろいろ出ていますが、これが嬉しい。 これが何を表現していて、どう便利で、内部的にどう動いてこれらが実現されているのかは、この記事を読んでいけば分かるようになります。 というわけでこのまま本編へどうぞ...!

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023
      Request:
      Protocol: HTTP/2
      Method: GET
      Scheme: https
      PathBase:
      Path: /first
info: ServiceA.Controllers.FirstController[0]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA)
      FirstController.Get()
info: System.Net.Http.HttpClient.Http2Client.LogicalHandler[100]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Start processing HTTP request GET http://localhost:5159/second
info: System.Net.Http.HttpClient.Http2Client.ClientHandler[100]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Sending HTTP request GET http://localhost:5159/second
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:196a6fb1beba1641, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6e9a81b89ca5f273 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.HttpRequestOut.Start.
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:196a6fb1beba1641, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6e9a81b89ca5f273 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.Request.
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:196a6fb1beba1641, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6e9a81b89ca5f273 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.HttpRequestOut.Stop.
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.Response.
info: System.Net.Http.HttpClient.Http2Client.ClientHandler[101]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received HTTP response headers after 2.1807ms - 200
info: System.Net.Http.HttpClient.Http2Client.LogicalHandler[101]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      End processing HTTP request after 2.2294ms - 200
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023
      Response:
      StatusCode: 200

Example のコード

GitHubにこの記事用にちょっとした Example を用意しました。 気になったらどうぞ。

github.com

そもそもログの目的とは何なのか。

ソフトウェアを実行し運用する上で極めて大事なログ。どんなソフトウェアだろうとログはトニカク大事。 にも関わらず、ログの設計に関する言及や文献というのは極めて少ないんですよね。 いろんなデザパタ、アーキテクチャについてはインターネット上でも語られまくるし、本等の文献も大量に出ている。 けど、ログについては？そうです、ログのプラクティスとかはビックリするほど語られないし本も文献もロクすっぽない。 そして役立つものはもっと少ない。 ソフトウェアを実行/運用する上で大事な事ランキングがあったら絶対上位にあるはずなんですけどね。 まぁ、めちゃんこ地味だからかもしれない。1ミリも華が無いもんね、ログ...。

そもそもログって何を目的としているのでしょうか？ それは 「ソフトウェアの振る舞いをログから理解できるようにする」 というその 1 点に尽きるのではないでしょうか。 メトリック計測したり、問題解決にログを読み込んだりと、いろいろログの使い道はあると思いますが、 結局のところ「ソフトウェアがどう振る舞っているか」を知りたくて、それを把握するためにログを出力しているわけです。

そしてサーバサイドのログについてはどうでしょうか？ サーバサイドのソフトウェアは往々にして大量にリクエストを受け付けて、並行ないし並列でそれらリクエストを処理する事になります。 並行ないし並列で処理されるため、当然この時のログは入り乱れるわけですが、「ソフトウェアの振る舞いをログから理解できるようにする」という観点からすると、 無秩序に入り乱れているログからはどう振る舞っているかトレースする事は困難です。 ではどうすれば「ソフトウェアの振る舞いをログから理解できるようにする」を実現できるかというと、各リクエストがどのように処理されているかがログから理解できれば良いです。 これの実現方法は簡単で、リクエスト毎に一意の id を払い出し、その id をログに含めるようにすればいいわけです。 とはいえ、その払い出したリクエスト毎の id をどうやって伝播するの？であったり、毎回 id を logger に投げないといけないの？とかいろいろ思うところはあるかもしれませんが、安心してください。 C# 及び ASP.NET Core にはこれを追加パッケージ無しに簡単に実現する方法があります。

また現代ではマイクロサービスを含む分散システムが当たり前になっています。 分散システムにおいては「ソフトウェアの振る舞いをログから理解できるようにする」を少し言い換え、 「各ソフトウェアの振る舞いと、複数のソフトウェア間の連携をログから理解できるようにする」といった方が分かりやすいかもしれません。 もうちょっと具体的にいうと「各リクエスト毎の分散システム全体での呼び出し経路と、各サービスでの振る舞い」をログから追える必要があります。 これの実現方法も素朴にはやはり簡単で、リクエストを受け付けたルートのサービスで一意の id を払い出し、その id 各サービスに伝播し、ログに含めてあげればいいわけです。 とはいえやはり、どうやってその払い出したリクエスト毎の id をサービス間で伝播するの? とかまぁいろいろ思うところはあるかもしれませんが、安心してください。 W3C でこのやり方は定められており、C# / ASP.NET Core ではそれに従ったトレースを追加パッケージ無しに簡単に実現する方法があります。

という事で、まずは W3C で定められた標準であるを Trace Context を見ていきましょう。 これを理解する事は分散システムであるにせよないにせよ、非常に重要です。 どれくらい重要かというと、C# の標準ライブラリに組み込まれているくらいです...!

W3C Trace Context

W3C には Trace Context と呼ばれる標準が存在します。 ちなみにこれ勧告が 2021/11/23 だったりして比較的最近の代物。 こいつが何者かは abstract を読めば雰囲気は分かります。

Abstract

This specification defines standard HTTP headers and a value format to propagate context information that enables distributed tracing scenarios. The specification standardizes how context information is sent and modified between services. Context information uniquely identifies individual requests in a distributed system and also defines a means to add and propagate provider-specific context information.

要はこの仕様、分散トレーシングを可能にするコンテキスト情報を伝播するための HTTP headers と、その value format の標準を定義されており、 そのコンテキスト情報をどうやって伝播、つまりサービス間で送信したり変更をかけたりするのかを定めています。 そしてそのコンテキスト情報は分散システムにおいて個々のリクエストを一意に識別可能にし、さらにプロバイダ固有のコンテキスト情報を追加及び伝播する事も出来るようになっている、というわけです。

abstract から分かる通り、W3C Trace Context は分散システムを主なターゲットとしているわけですが、別に分散システムじゃなくても「個々のリクエストを一意に識別可能」にしてくれるところは大変うれしい。 リクエストを最初に受けたサーバがコンテキスト情報を作成し、その id 等が分散システムではない一つのサーバの中で伝播してログに出てくるだけで、 個々のリクエストを一意に識別可能になるため、各リクエストがどのように処理されているかがログから明らかになるようになります。 なので「ソフトウェアの振る舞いをログから理解できるようにする」という方針を実現するためのベースになってくれます。

Trace Context の HTTP ヘッダとフォーマット

Trace Context には 2 つの HTTP ヘッダが定義されています。

• traceparent
  • あらゆるベンダが理解可能 (= 理解しなければいけない) な共通のフォーマット
  • 例 : traceparent: 00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-00
• tracestate
  • 各ベンダ固有の情報を載せてOKなフォーマット
  • 例 : tracestate: congo=t61rcWkgMzE

この記事では共通のフォーマットである traceparent について見ていきます。

Traceparent Header

まず定義から。DIGIT を 0-9 の数字 1 文字とし、HEXDIGLC を以下のように定義します。 HEX がついている事から分かる通り、16進のソレです。 そしてヘッダに挿入される際の name は traceparent で、value は以下のような version と version-format (各 version 毎の format) が - (delimiter) でくっ付いている形になっています。 version があがった際にフォーマットを変更できる柔軟性を持たせるために version-format になっています。 上の例でいうと、00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-00 の 00 が version で 0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-00 が version-format です。 version と version-format のそれぞれを見ていきましょう。

HEXDIGLC = DIGIT / "a" / "b" / "c" / "d" / "e" / "f"
value    = version "-" version-format

version

16 進数で2桁。現在の仕様では 00 が使われる事になっています。なお ff は禁止されています。

version         = 2HEXDIGLC   ; this document assumes version 00. Version ff is forbidden

version-format

version 00 での version-format は trace-id, parent-id, trace-flags の 3 つを合体させた代物です。

version-format   = trace-id "-" parent-id "-" trace-flags
trace-id         = 32HEXDIGLC  ; 16 bytes array identifier. All zeroes forbidden
parent-id        = 16HEXDIGLC  ; 8 bytes array identifier. All zeroes forbidden
trace-flags      = 2HEXDIGLC   ; 8 bit flags. Currently, only one bit is used. See below for details

それぞれが何を表しているかを以下でみていきます。

trace-id

trace-id は trace forest 全体での id であり、システム全体を通して分散トレースを一意に識別するためのものです。 trace-id は 16-byte array で表現されます。 例えば 0af7651916cd43dd8448eb211c80319c みたいな感じ。 全ての byte がゼロのもの (00000000000000000000000000000000) は無効とされています。

つまりログからある trace-id が吐き出されているもののみを引っこ抜けば、任意のリクエストが分散システム全体を通してどのように処理されたかを追えるようになるわけです。 ただし、trace-id だけだと経路までは分かりません。

parent-id

parent-id はリクエストの呼び出し元が知っている id です(いくつかのトレースシステムでは、これはspan-idとして知られています。span とはクライアントリクエストの実行を意味します)。 parent-id は 8-byte array で表現されます。 例えば b7ad6b7169203331 みたいな感じ。 全ての byte がゼロのもの (0000000000000000) は無効とされています。 ベンダは無効な parent-id が traceparent に含まれていた場合、無視しなければいけません (MUST)。

trace-id だけでは経路が分かりませんでしたが、parent-id を用いる事で経路も分かるようになります。

trace-flags

サンプリング、トレースレベル等の tracing flags を制御する 8-bit field。 これらのフラグは従うべき厳密なルールではないので、ここではスキップ。詳細は仕様をみてください。

用語

Distributed trace

以下原文。

A distributed trace is a set of events, triggered as a result of a single logical operation, consolidated across various components of an application. A distributed trace contains events that cross process, network and security boundaries. A distributed trace may be initiated when someone presses a button to start an action on a website - in this example, the trace will represent calls made between the downstream services that handled the chain of requests initiated by this button being pressed.

以下意訳。

分散トレース (distributed trace) は、単一の論理操作 (single logical operation) の結果としてトリガーされたイベントの集合であり、アプリケーションのさまざまなコンポーネントを横断して統合されます。 分散トレースには、プロセス、ネットワーク、セキュリティの境界を横断したイベントが含まれます。 例えば、分散トレースは、誰かがウェブサイト上でなんらかの操作をするためにボタンを押したときに開始されるかもしれません。 この場合 trace は、そのボタンが押されたことによって連鎖的に生じる downstream のサービスの呼び出し達を指します。

要するに。

図示した方が分かりやすい気がしたので、図を作りました。 ここでは分かりやすくするため、ユーザが HTTP request を飛ばし、Service A のなんらかのエンドポイントを叩いたとしましょう。 そこから A -> B -> C といった順で HTTP リクエストが叩かれます。

図1: W3C Trace Context の trace と span を分かりやすく図示

この際に発生する trace と span についてみて行きましょう。

trace は簡単です。 先ほど Distributed trace という言葉の解説しましたが、要は複数のサービスにまたがった、単一の論理操作 (single logical operation) 内で発生する呼び出しの集合が trace です。 が、trace はもともと「足跡/形跡/証拠/小道」とかいう意味なので、呼び出しの集合と捉えるよりも、単一の論理的な制御フローを指すと思った方がしっくりくるかもしれません。 そしてその trace に対して振られるのが trace-id なわけですが、これはリクエストを受け取ったルートのサービス(ここでは ServiceA)が発行し、以下全ての downstream のサービスのエンドポイントを叩く時にはヘッダに乗っけって伝播します。

次に span です。 span は span is the execution of a client request とTrace Context のドキュメント内で記述されています。 ふーん、という感じなのですが、すこし気をつけるべきなのがいくつかあります。 まず、span is the execution of a client request という文章をちゃんと読むと、span はクライアントのリクエストの実行一つ一つに振られるものだと分かります。 なので、単一の論理操作内かつ、単一のサービス内だとしても、別のサービスに HTTP リクエスト飛ばす際には、別の Span が発生している事になります。 図でいうと、Service A から Service B を叩く際に、Span1 から Service B を叩きに行くのではなく、Service A 内で Span1 から Span2 を作成し、Span2 から Service B を叩いているという事です。 そしてこれに付随して、span には親子関係がある、という点も把握しておくべきです。 親子関係にも種類があり、分類すると以下のようになります。

• サービス内での親子関係
  • ex:
    • Span1 は Span2 の親であり、Span2 は Span1 の子である
    • Span3 は Span4 の親であり、Span4 は Span3 の子である
• サービス間での親子関係
  • ex:
    • Span2 は Span3 の親であり、Span3 は Span2 の子である
    • Span4 は Span5 の親であり、Span5 は Span4 の子である

例えば、Service A から Service B を叩く際には traceparent: 00-{trace-id}-{span 2 の id}-00 といった風なヘッダがつけられ、 Service B から Service C を叩く際には traceparent: 00-{trace-id}-{span 4 の id}-00 のようなヘッダがつけられます。

という事で、ログから trace-id を引けば、単一の論理操作の内で何が呼び出されたかが一目瞭然となり、span-id / parent-id を辿れば呼び出された順序も一目瞭然なようになります。 このあたりは Example の github のレポジトリの README に実際の trace-id / span-id /parent-id が含まれているログを載せておいたので、気になる方はみてみてください。

github.com

System.Diagnostics.Activity

W3C Trace Context の雰囲気を理解したところで、C# のお話をしていきます。 C# には System.Diagnostics.Activity という .NET Core 2.0 で標準ライブラリ入りしたクラスがあります。 Activity のお仕事は、ある処理を開始した時に、それを追跡できるようにする事です。 例えば、アプリケーションが HTTP リクエストを送受信したり、キューからのタスクを処理したりしているのを追跡できるようにしたりします。

当然ながら、追跡できるように内部で id を払い出したりするのですが、Activity は2種類のフォーマットをサポートしています。 そのフォーマットは ActivityIdFormat という enum に定義されているのですが、以下みたいな定義がなされています。

public enum ActivityIdFormat
{
    Unknown = 0,
    Hierarchical = 1,
    W3C = 2
}

そう、W3C がいます。 実は Activity はサポートしているフォーマットの一つは W3C Trace Context であり、.NET 5 以降の既定のフォーマットは ActivityIdFormat.W3C だったりします。

という事で、 「やったぁ！C# の標準ライブラリに存在する Activity を使えば W3C Trace Context に対応する事ができるんだね！で、この Activity クラスをどうやって使えばいいんだい！？」 となる気がしますが、HTTP の inbound/outboud に対しては Activity を直接触って何か操作する必要はありません。 何故なら標準ライブラリと ASP.NET Core が上手い事やってくれているからです。

まず、ASP.NET Core ではリクエストの受け付け HttpContext を作成すると同時にActivity も作成します。 なおその際、リクエストの HTTP ヘッダに traceparent が含まれていたら、それの parent-id を作成した Activity インスタンスの ParentId としてセットします。 ここで重要な事が一つあります。それは作成された Activity のインスタンスは、同一の非同期制御フロー内であれば、Activity.Current で任意の箇所で取得する事が可能という事です(内部的には AsyncLocal<T> でActivity インスタンスがフローする)。 そして、C# の HttpClient の既定の構成では Activity.Current が null でなければ、送信する HTTP ヘッダに traceparent が追加されるようになっています。 もう少し厳密にいうと、 HttpClient の既定の構成で用いられる HttpClientHandler が内部で用いる SocketsHttpHandler の、そのまた内部で用いる DiagnosticsHandler という internal なクラスが Activity.Current のチェックを行って、null でなければ Activity.Current の子の Activity インスタンスを作成し、それを Start() して、送信する HttpRequestMessage の Headers にその Activity インスタンスを W3C Trace Context のフォーマットで書き込む、つまり traceparent ヘッダの trace-idと parent-id に子 Activity インスタンスの TraceId と SpanId の値を用いる、という事をしています。 (SocketsHttpHandler とか何？という人はこちらのスライドの前半ををどうぞ。) そのため、実は特段何もしなくてもコンテキスト情報は W3C Trace Context に従って、あるサービスから別のサービスにちゃんと伝播するようになっているのです。

が、実際にコンテキスト情報として trace-id や parent-id 等が伝播するようになったとしていても、ログに出てなければ正直あまり意味がありません。 というわけで、伝播する/伝播してきた trace-id や parent-id 等をログに出す必要があります。 ここで「Activity.Current 使って真心こめてログに詰め込まないといけないの？」と思うかもしれませんが、その必要はありません。 先ほど述べた通り Activity を直接さわる必要はなく、オプション一つで自動でログに出力してくれるようになります。 それがこれから紹介するオプションです。

ConsoleFormatterOptions.IncludeScopes

現在の Activity の SpanId や伝播してきた TraceId や ParentId を手間かけずによしなにログに出力してほしい！ そんな需要に応えるのが、ConsoleFormatterOptions.IncludeScopes です。 設定の仕方は簡単で、SimpleConsole / JsonConsole でこんな感じ。 なお AddJsonConsole で渡すラムダの引数は JsonConsoleFormatterOptions ですが、これは ConsoleFormatterOptions を継承しています。

// SimpleConsole
builder.Logging.AddSimpleConsole(options =>
{
    options.IncludeScopes = true; // めちゃ便利！
});

// JsonConsole
builder.Logging.AddJsonConsole(options =>
{
   options.IncludeScopes = true;
   options.TimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z'";
   options.UseUtcTimestamp = true;
});

これだけで、以下のログのように SpanId, TraceId, ParentId が出力されるようになります。 内部的には、オプションで IncludeScopes = true が設定された場合、 logger は Activity.Current が null かどうかを確認し、null で無かった場合に SpanId, TraceId, ParentId などを出力するようになっています。 なお Activity.Current は内部的に AsyncLocal<T> でフローしているので、SpanId, TraceId, ParentId が正しく出力されるのは同一の非同期制御フロー内である事に注意してください。

さて、実際のログを眺めてみましょう。 流れは 先ほど図1 と同じですが、下にもう一度図は再掲しておきます。

図1(再掲): W3C Trace Context の trace と span を分かりやすく図示

ServiceA

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023
      Request:
      Protocol: HTTP/2
      Method: GET
      Scheme: https
      PathBase:
      Path: /first
info: ServiceA.Controllers.FirstController[0]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA)
      FirstController.Get()
info: System.Net.Http.HttpClient.Http2Client.LogicalHandler[100]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Start processing HTTP request GET http://localhost:5159/second
info: System.Net.Http.HttpClient.Http2Client.ClientHandler[100]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Sending HTTP request GET http://localhost:5159/second
info: System.Net.Http.HttpClient.Http2Client.ClientHandler[101]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received HTTP response headers after 2.1807ms - 200
info: System.Net.Http.HttpClient.Http2Client.LogicalHandler[101]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      End processing HTTP request after 2.2294ms - 200
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023
      Response:
      StatusCode: 200

ServiceB

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B
      Request:
      Protocol: HTTP/2
      Method: GET
      Scheme: http
      PathBase:
      Path: /second
info: ServiceB.Controllers.SecondController[0]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB)
      SecondController.Get()
info: System.Net.Http.HttpClient.Http2Client.LogicalHandler[100]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      Start processing HTTP request GET http://localhost:5002/third
info: System.Net.Http.HttpClient.Http2Client.ClientHandler[100]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      Sending HTTP request GET http://localhost:5002/third
info: System.Net.Http.HttpClient.Http2Client.ClientHandler[101]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      Received HTTP response headers after 1.0458ms - 200
info: System.Net.Http.HttpClient.Http2Client.LogicalHandler[101]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      End processing HTTP request after 1.0795ms - 200
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B
      Response:
      StatusCode: 200

ServiceC

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      => SpanId:c7edcce747b3a145, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6203d4f905a12ddb => ConnectionId:0HMROP668PKVC => RequestPath:/third RequestId:0HMROP668PKVC:0000001B
      Request:
      Protocol: HTTP/2
      Method: GET
      Scheme: http
      PathBase:
      Path: /third
info: ServiceC.Controllers.ThirdController[0]
      => SpanId:c7edcce747b3a145, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6203d4f905a12ddb => ConnectionId:0HMROP668PKVC => RequestPath:/third RequestId:0HMROP668PKVC:0000001B => ServiceC.Controllers.ThirdController.Get (ServiceC)
      ThirdController.Get()
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      => SpanId:c7edcce747b3a145, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6203d4f905a12ddb => ConnectionId:0HMROP668PKVC => RequestPath:/third RequestId:0HMROP668PKVC:0000001B
      Response:
      StatusCode: 200

SpanId, TraceId, ParentId の順で見て生きましょう。 まず、SpanId はその Span (Activity) が作成された際に新規に id が払い出されるので、特に変わった事はありません。 新しく払い出された id だな、くらいに思っておけばいいでしょう。 そして次の TraceId は全てのログで一致している事が分かりますね。 今回ログとしてお見せしているのは、一つの論理操作にまつわる箇所だけですから、TraceId が全て一致しているのは正しいです。 当然、別の論理操作であれば、別の新しい TraceId が ServiceA にて払い出され、ServiceB, ServiceC に伝播します。

一方で、ParentId はどうでしょうか？

ServiceA の ParentId は全て 0000000000000000 と表示されています。 これは ServiceA がリクエストを受け付けるルートのサービスなので正しいです。

ServiceB の ParentId はどうでしょう。 196a6fb1beba1641 という値が表示されていますね。これは ServiceA から伝播してきた id のハズです、が...。 ServiceA のログには 196a6fb1beba1641 という文字列は見当たりません。あれ？

ServiceC の ParentId はどうでしょう。 6203d4f905a12ddb という値が表示されていますね。これは ServiceB から伝播してきた id のハズです、が...。 やはり ServiceB のログには 6203d4f905a12ddb という文字列は見当たりません。あれれ？

なんでこういう事になっているかというと、別のサービスにリクエストを飛ばす際には新しい子 Activity が作成されるわけですが、その子 Activity の id などが一切ログに現われていないからです。 要するに、ServiceA において、図でいうところの Span1 はログに現われているが、 リクエストを飛ばす直前に Span1 の子である Span2 に対応する Activity が作成されたものの、 その Span2 がログに一切現われていない、という事なのです。 なので Span2 や Span4 などのような、リクエストを飛ばす直前に作成された Activity の情報をログに出してあげるようにすれば、 ServiceB でログに現われた ParentId は、ServiceA の SpanId としてログに現われるハズです。 ということで、それをログに出していきましょう。

HttpClient 内での Activity のイベントを検知してログに出す。

で、どうすればいいのか？ というと、DiagnosticListener.AllListeners を用いる事で実現できます。 DiagnosticListener.AllListeners の型は IObservable<DiagnosticListener> ですので、IObserver<DiagnosticListener> を実装したクラスを用意して、Subscribe で渡してあげればいい。 という事で、以下のようなクラスを定義します。

で、このクラスを以下のような感じで使います。

// Program.cs

var builder = WebApplication.CreateBuilder(args);

// 色々省略

var app = builder.Build();

var loggerFactory = app.Services.GetService<ILoggerFactory>()!; // <- 追加！
DiagnosticListener.AllListeners.Subscribe(new HttpMessageHandlerActivityOvserver(loggerFactory)); // <- 追加！

すると、以下のようなログが得られます。

ServiceA

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023
      Request:
      Protocol: HTTP/2
      Method: GET
      Scheme: https
      PathBase:
      Path: /first
info: ServiceA.Controllers.FirstController[0]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA)
      FirstController.Get()
info: System.Net.Http.HttpClient.Http2Client.LogicalHandler[100]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Start processing HTTP request GET http://localhost:5159/second
info: System.Net.Http.HttpClient.Http2Client.ClientHandler[100]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Sending HTTP request GET http://localhost:5159/second
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:196a6fb1beba1641, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6e9a81b89ca5f273 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.HttpRequestOut.Start.
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:196a6fb1beba1641, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6e9a81b89ca5f273 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.Request.
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:196a6fb1beba1641, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6e9a81b89ca5f273 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.HttpRequestOut.Stop.
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.Response.
info: System.Net.Http.HttpClient.Http2Client.ClientHandler[101]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      Received HTTP response headers after 2.1807ms - 200
info: System.Net.Http.HttpClient.Http2Client.LogicalHandler[101]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023 => ServiceA.Controllers.FirstController.Get (ServiceA) => HTTP GET http://localhost:5159/second
      End processing HTTP request after 2.2294ms - 200
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      => SpanId:6e9a81b89ca5f273, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:0000000000000000 => ConnectionId:0HMROP668KHGC => RequestPath:/first RequestId:0HMROP668KHGC:00000023
      Response:
      StatusCode: 200

ServiceB

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B
      Request:
      Protocol: HTTP/2
      Method: GET
      Scheme: http
      PathBase:
      Path: /second
info: ServiceB.Controllers.SecondController[0]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB)
      SecondController.Get()
info: System.Net.Http.HttpClient.Http2Client.LogicalHandler[100]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      Start processing HTTP request GET http://localhost:5002/third
info: System.Net.Http.HttpClient.Http2Client.ClientHandler[100]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      Sending HTTP request GET http://localhost:5002/third
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:6203d4f905a12ddb, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:3bd3719aefa06118 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.HttpRequestOut.Start.
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:6203d4f905a12ddb, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:3bd3719aefa06118 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.Request.
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:6203d4f905a12ddb, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:3bd3719aefa06118 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.HttpRequestOut.Stop.
info: ServiceA.Diagnostics.HttpMessageHandlerActivityOvserver[0]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      Received activity event from HttpMessageHandler. Event name is System.Net.Http.Response.
info: System.Net.Http.HttpClient.Http2Client.ClientHandler[101]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      Received HTTP response headers after 1.0458ms - 200
info: System.Net.Http.HttpClient.Http2Client.LogicalHandler[101]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B => ServiceB.Controllers.SecondController.Get (ServiceB) => HTTP GET http://localhost:5002/third
      End processing HTTP request after 1.0795ms - 200
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      => SpanId:3bd3719aefa06118, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:196a6fb1beba1641 => ConnectionId:0HMROP668KHG0 => RequestPath:/second RequestId:0HMROP668KHG0:0000001B
      Response:
      StatusCode: 200

ServiceC

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      => SpanId:c7edcce747b3a145, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6203d4f905a12ddb => ConnectionId:0HMROP668PKVC => RequestPath:/third RequestId:0HMROP668PKVC:0000001B
      Request:
      Protocol: HTTP/2
      Method: GET
      Scheme: http
      PathBase:
      Path: /third
info: ServiceC.Controllers.ThirdController[0]
      => SpanId:c7edcce747b3a145, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6203d4f905a12ddb => ConnectionId:0HMROP668PKVC => RequestPath:/third RequestId:0HMROP668PKVC:0000001B => ServiceC.Controllers.ThirdController.Get (ServiceC)
      ThirdController.Get()
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      => SpanId:c7edcce747b3a145, TraceId:a8f8ea4153ca4595861126ed8ba98570, ParentId:6203d4f905a12ddb => ConnectionId:0HMROP668PKVC => RequestPath:/third RequestId:0HMROP668PKVC:0000001B
      Response:
      StatusCode: 200

ServiceB の一番最初の行の ParentId (196a6fb1beba1641) は、ServiceA のどこかの SpanId から伝播してきているハズです。 そして実際に ServiceA のログを見てみると、SpanId が 196a6fb1beba1641 な Activity がある事が分かりますね。 なのでログを眺めただけで、ServiceB のログの一行目は ServiceA から飛んできたリクエストなんだな～というのが分かります。

同様に ServiceC の一番最初の行の ParentId (6203d4f905a12ddb) は、ServiceB のどこかの SpanId から伝播してきているハズです。 そして実際に ServiceB のログを見てみると、SpanId が 6203d4f905a12ddb な Activity がある事が分かりますね。 なのでログを眺めただけで、 ServiceC のログの一行目は ServiceB から飛んできたリクエストなんだな～というのが分かります。

という事で、期待通りなログが出ていますね！

まとめ

とどのつまり ConsoleFormatterOptions.IncludeScopes は true にしておくと便利、というお話。 で、その IncludeScopes が便利なのは、実は裏側で Activity というクラスがせっせとお仕事していて、その Activity は既定では W3C Trace Context のフォーマットに従っているのでした。 また HttpClient も既定の構成では Activity.Current が null でなければ、自動で送信する HTTP ヘッダに traceparent という名前の値を W3C Trace Context の仕様に沿ったフォートで追加してくれるのでした。

なので、お手軽に「ソフトウェアの振る舞いをログから理解できるようにする」ないし、「各リクエスト毎の分散システム全体での呼び出し経路と、各サービスでの振る舞い」を実現するためのベースを手に入れる事ができるのです。 実際にちゃんと「ソフトウェアの振る舞いをログから理解できるようにする」を実現するためには、各サービス内でちゃんとどのようにログを取るかはしっかり考える必要があるので、これはベースにすぎないのですが、必須なベース部分がお手軽に手に入るのはいい事。 ちゃんと分散トレーシングやるなら OpenTelemetry のパッケージを突っ込んでうんぬん、みたいな話にはなるのですが、意外と何もパッケージとか追加とかしなくても、今回の事くらいは出来るんですよね。

Activity はいい仕事をしている...!

References

• https://www.w3.org/TR/trace-context/
• https://github.com/dotnet/runtime/tree/v7.0.8
• https://github.com/dotnet/runtime/blob/v7.0.8/src/libraries/System.Net.Http/src/HttpDiagnosticsGuide.md
• https://github.com/dotnet/runtime/blob/v7.0.8/src/libraries/System.Diagnostics.DiagnosticSource/src/ActivityUserGuide.md
• https://github.com/dotnet/aspnetcore/tree/v7.0.8
• https://learn.microsoft.com/en-us/dotnet/core/diagnostics/distributed-tracing-concepts
• https://learn.microsoft.com/en-us/dotnet/core/diagnostics/distributed-tracing-instrumentation-walkthroughs
• https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-7.0#automatically-log-scope-with-spanid-traceid-parentid-baggage-and-tags
• https://learn.microsoft.com/en-us/dotnet/api/microsoft.extensions.logging.console.consoleformatteroptions.includescopes?view=dotnet-plat-ext-7.0&viewFallbackFrom=net-7.0
• https://learn.microsoft.com/en-us/dotnet/api/system.diagnostics.activity?view=net-7.0