はじめに
複数のサービスを組み合わせて提供するサービスの場合、利用者から発生したリクエストがどのサービスまで到達して、どのような結果になったのかのログを一貫したIDで確認できると追跡しやすくなります。
オレオレな仕組みとして実装するのであれば、利用者に一番近いところで生成した処理IDをHTTPヘッダーなどで引き回しつつログに出力すれば対応は可能ですが、これとほぼ同じような役割のHTTPヘッダーがW3CでTrace Contextとして定義されています。Trace Contextに対応したフレームワークであれば、前述のオレオレヘッダーを自前で引き回したりしなくとも分散トレースの仕組みを利用することができます。
この記事では、ASP.NET Coreのログとして出力される、SpanId、TraceId、ParentIdといった各種分散トレース用のIdと、W3Cで定義されているTrace Contextの関係を説明します。
ASP.NET Core 3.xにおける分散トレーシング
ASP.NET CoreでSerilogなどで構造化ログを出力した場合、下記のようにConnectionIdやRequestIdと共にSpanIdやTraceId、ParentIdといった項目が自動的に出力されていることに気がつくと思います。
{
"Timestamp": "2020-11-16T11:36:07.4064259+09:00",
"Level": "Information",
"MessageTemplate": "Executed endpoint '{EndpointName}'",
"Properties": {
"EndpointName": "TraceContextSample.Backend2.Controllers.ApiUsersController.GetContract (TraceContextSample.Backend2)",
"EventId": { "Id": 1, "Name": "ExecutedEndpoint" },
"SourceContext": "Microsoft.AspNetCore.Routing.EndpointMiddleware",
"RequestId": "0HM49R1FBA9QR:00000001",
"RequestPath": "/api/ApiUsers/1",
"SpanId": "|80590f9-4cbb08ce5d8bad25.4.e163ea97_7.90994b52_",
"TraceId": "80590f9-4cbb08ce5d8bad25",
"ParentId": "|80590f9-4cbb08ce5d8bad25.4.e163ea97_7.",
"ConnectionId": "0HM49R1FBA9QR"
}
}
これらの詳しい説明は、Improvements in .NET Core 3.0 for troubleshooting and monitoring distributed appsに記載されていますが、大まかには次のような意味合いになります。
| # | 属性名 | 意味 |
|---|---|---|
| 1 | ConnectionId | そのエンドポイントをリクエストしたセッションのIDを表します。 |
| 2 | RequestId | 今回そのエンドポイントに対してリクエストしたIDを表します。{ConnectionId}:{連番}の形式になります。 |
| 3 | TraceId | クライアントから並列、直列にエンドポイントを呼びだした際に、一連の呼び出しを識別するIDを表します。 |
| 4 | ParentId | そのエンドポイントを直接呼び出したクライアントのIDを表します。デフォルトでは |{呼び出し元のTraceId}{リクエスト連番}.の形式になります。 |
| 5 | SpanId | そのエンドポイントの処理IDを表します。デフォルトでは {ParentId}{自身の処理Id}の形式になります。 |
例えば、下記のように、コンソールアプリケーションからBFF経由で複数のWebApiをHTTP経由で呼びだすようなアプリケーションがあった場合を想定します（ここでは説明を単純にするため、フロントはWebやモバイルではなくコンソールにしています）。
このようなアプリケーションの場合、ASP.NET Coreの分散トレース機構はConsoleAppがBFFへHTTPリクエストを行う際に自動的にTraceIdを発行し、それ以降のリクエストではTraceIdを引き回しつつ、どのような呼び出し階層になっているかがわかるようなSpanIdやParentIdを自動的にログに付与するようになります。
実現している仕組み
どのように実現しているかといえば、単純にリクエストを出す際にHTTPヘッダー内にRequest-Idが存在すればそれを後続のリクエストに引き回し、存在しなければ生成してHTTPヘッダーに乗せるというようなことをしているようです。実際にConsoleAppがBFFのWebApiをリクエストした際のリクエスト本文はこのようになっています。
GET https://localhost:5021/api/ServiceUsers HTTP/1.1
Host: localhost:5021
Request-Id: |ee1e2648-42bba8b19667f176.4.
実はこの動作を自動的に行ってくれるのはASP.NET Coreのアプリケーションだけで、WinFormsやWPF、コンソールアプリケーションのHttpClientでは自動的にRequest-Idを付与してくれません。これらのアプリケーション形態の場合は、下記のようにActivityクラスを利用して明示的にここからここまでがリクエストの範囲なんだよ、ということをHttpClientに教えてあげる必要があります。
using var activity = new Activity(nameof(RunAsync)).Start();
var response = await _tokenClient.RequestTokenAsync(
new TokenSettings {AuthorityBaseUri = Constants.Authority.BaseUri},
Constants.ConsoleApp.ClientId,
Constants.ConsoleApp.ClientSecret,
new[] {Constants.Bff.ResourceName});
var data = await _bffClient.GetServiceUsersAsync(response.AccessToken);
activity.Stop();
W3C 形式のtraceparentヘッダー
Request-IdヘッダーはASP.NET Core 2.0のタイミングで追加されたヘッダーです。W3CのTrace Contextに準拠したtraceparentヘッダーに変更するには、プログラム起動時にActivity.DefaultIdFormat静的プロパティーにW3Cを設定します。
static async Task Main(string[] args)
{
Activity.DefaultIdFormat = ActivityIdFormat.W3C;
await CreateHostBuilder(args)
.Build()
.RunAsync();
}
HTTPリクエストは次のようになります。Request-Idからtraceparentに変更されていることがわかります。
GET https://localhost:5021/api/ServiceUsers HTTP/1.1
Host: localhost:5021
traceparent: 00-cd18b4710d68394a9bdfa33be609d9ab-65268765e26f6141-00
出力するログは次のようになります。
ConnectionId:0HM49TJEPBT84
SpanId:c86545271cd34d4c
TraceId:cd18b4710d68394a9bdfa33be609d9ab
RequestId:0HM49TJEPBT84:00000001
ParentId:65268765e26f6141
ConnectionId:0HM49TJEVVKGE
SpanId:d99be493ec58af4e
TraceId:cd18b4710d68394a9bdfa33be609d9ab
RequestId:0HM49TJEVVKGE:00000001
ParentId:ff6404a601698347
まとめ
ASP.NET Croeの分散トレーシング機能を利用すると、複数のWebApi呼び出しからなる分散アプリケーションを串刺してログを収集することができます。これだけでもAzureのLog AnalyticsやAWSのCloudWatch Logs Insightといった各クラウド標準のログ解析基盤で複数のログを串刺しで集計することもできますし、W3C形式のIdに変更すればサードパーティー製の分散ログ基盤に適用することができます。