- 登壇版
- ConsoleFormatter
- HttpLogging
- ConsoleFormatterOptions.IncludeScopes
- W3C Trace Context
- ExceptionHandler
- DbDataSource
- HttpClientFactory
- まとめ
- References
登壇版
.NET ラボ 2023/07/22 で発表した資料です。 スライドはこちら。 スライドはアニメーション豊かなので、スライドと本投稿合わせながら見るといいかもです。
登壇のアーカイブはこちら。 30 分程度です。
ConsoleFormatter
ログはだいた標準出力、まぁコンソールに出力しますよね。
そしてコンソールにログを出力するといっても、当然ながら複数のフォーマットがあります。
C# で現在ロガーとしてデファクト的に使われている Microsoft.Extensions.Logging
には以下のようなクラスが存在します
- SimpleConsoleFormatter
- JsonConsoleFormatter
- SystemdConsoleFormatter
これらの xxxConsoleFormatter は全て internal な class で、直接は触らずに以下のような拡張メソッドを通して設定する事になります。
var builder = WebApplication.CreateBuilder(args); builder.Logging.AddSimpleConsole(); builder.Logging.AddJsonConsole(); builder.Logging.AddSystemdConsole();
現代において実際に運用されているサービスのログって、人間が直接みるものじゃなくて、サービスに食わせるものになっています。 なので当然ながら構造化ロギングしますよね。 そのため本番環境とかだと JsonConsole とかを使う事の方が多いと思います。 SimpleComsole は開発環境のみでつかいますよ、と。
が、この記事の中で示す例は全て SimpleComsole を使ったものになっています。 理由は開発環境で SimpleComsole を使うのと同じで、ブログ示すには JsonConsole の出力は人間にとって読み辛い過ぎるので。。。
HttpLogging
ASP.NET Core のデフォルトのテンプレートは何もログを出力してくれません。 とはいえ、HTTP のリクエストとリスポンスに関する最低限度のログというのは欲しいですよね。
フレームワークに備わっている機能に頼らないでログを出力しようと思うと、素朴には Controller のアクション全てにいちいち HTTP リクエストとレスポンスに関するログを書く、という事が考えられます。 が、それをやった場合 2つほど問題があります。 まず一つ目が、そもそも Controller では使われていないパスに対する HTTP のリクエストだったり、バリデーションによって事前に弾かれるリクエスト、 つまり Controller が呼び出される以前にレスポンスを返してしまうようなリクエストに関するログが残りません。困りますね。 そして2点目が、なによりめんどくさいです。
この問題を解決してくれるのが HttpLogging
で、使い方は簡単です。
builder.Services
、つまり ServiceCollection
に対して AddHttpLogging
で HttpLoggingOptions
を設定してあげて、
UseHttpLogging
でミドルウェア (内部的には HttpLoggingMiddleware
という名前) を追加してあげます。
ここで一つ注目したいのが、この AddHttpLogging
する時のオプションに渡す HttpLoggingFields
なのですが、
この HttpLoggingFields
という enum をビット演算の or でくっつけていきます。
この RequestProperties
ってなんぞやというと、RequestPath | RequestProtocol | RequestMethod | RequestScheme
が合体したものです。
ResponseStatusCode
はそのまんまの意味。
デフォルトは RequestPropertiesAndHeaders | ResponsePropertiesAndHeaders
で、HTTP のヘッダーの情報をログに出力するようにもなります(既定だと全部のヘッダの値がログに出るわけではないのですが)。ヘッダの他にも RequestQuery
とかがあるので、クエリとかログに出力も容易にできます。
ただ、あんまりログに出し過ぎるとパフォーマンスは落ちますし、ログを溜め込むのもタダではないので、オプションちょっといじるだけでガンガンだせるからといって出し過ぎには注意しましょう。 さらに、ログを出し過ぎて個人情報とかがログに含まれると、どうやら GDPR (EU の個人情報保護の法律) に引っ掛かることもあるっぽいので気を付けましょう。
HttpLogging
を使うにはもう一ついれないといけない設定があります。
ログレベルの設定です。
appsettings.json
等で Microsoft.AspNetCore.HttpLogging
のログレベルを Information
にしてあげます。
これで一通りの準備が完了です。
実際にどういうログが出るのか、みていきましょう。
テンプレートで作成される WEB API の /WeatherForecast
を叩いた場合、こんな感じのログがでるようになります。
おー、良さそうじゃん、となりそうなんでが、実際のところあんまりそうはならないんじゃないかなと思います。 このログ、何が足りないでしょう? 何が足りないかは、同時にリクエスト叩いた場合のログを見ると一目瞭然です。
リクエストが来たことは分かります。 レスポンスが返された事も分かります。 でも、どのリクエストに対して、どのレスポンスを返したのか、これだと分かりません。
さらに、例示している /WeatherForecast
の実装はテンプレートのままなので、非常に単純なメソッドなのですが、実際には Controller にビジネスロジックが実装されているインスタンスを DI をし、それを使ってビジネスロジックを走らせ、別のサービスにリクエスト飛ばしたり、DB 叩いたり、などなどまあいろいろな事をするわけです。
そして当然ながらそれぞれで、ビジネスロジックであれこれ処理するにしても、別のサービス叩くにせよ、とにかくいろんな箇所でログを出します。
ただ、現状のようにログが素朴に出力されるだけだと、ログを出力する箇所に到達したんだな、という事が分かるだけです。 これではリクエストとは無関係の「点」です。 その「点」だと、呼び出された事は分かるけど、あるリクエストがどのように処理されたか、つまり「ソフトウェアがどう振る舞っているのか」というのは分かりません。 大事なのは点ではなく、フローです。 スタックトレースって非常に意味があるものですけど、スタックトレースの一か所だけ引っこ抜いて渡されても、別にそれに意味はない、というか情報量がほぼないですよね。 ログもそれと同じ。 大事なのは一連の処理のフローであり、ソフトウェアの振る舞いがログから追える事です。
なので、ビジネスロジックとかの処理も含めてリクエストと紐づけた状態でログに出力して、ソフトウェアの振る舞いを追えるようにしたいわけです。
実にめんどくさそうな話なのですが、ASP.NET Core では、これは1行で実現できます。
それが ConsoleFormatterOptions.IncludeScopes
です。
ConsoleFormatterOptions.IncludeScopes
ConsoleFormatterOptions.IncludeScopes
はログにスコープを含めるか否かのオプションです。
ログのスコープは何かというと、簡単にはログのコンテキストみたいなものです。
ConsoleFormatterOptions.IncludeScopes
の設定の仕方は簡単です。
AddSimpleConsole
とか AddJsonConsole
とかではオプションを設定するためにラムダを渡しますよね。
そこで渡されるオプションはそれぞれ SimpleConsoleFormatterOptions
であったり、 JsonConsoleFormatterOptions
なのですが、両方とも ConsoleFormatterOptions
を継承しています。
それぞれのベースクラスである ConsoleFormatterOptions
に IncludeScopes
は生えているプロパティですので、当然ながら両方に生えています。
なので以下のような感じで設定する事ができます。
// 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 とかが含まれるようになります。 これが嬉しい。 これらの id が何を意味しているかについては、詳しくはこちらの記事 を読んで欲しいのですが、 何はともあれこの id によって、このログはどのリクエストに紐づくログなのか、というのがわかるようになります。 つまりリクエスト毎の処理のフローをログから追えるようになります。
たとえば、同時にリクエストたたいた場合のログを見るとこの嬉しさは一目瞭然です。
一番最初の行のログはリクエストをされた時のログですが、 この TraceId が同一のログをながめれば、このリクエストに紐づく処理が追えるようになります。 レスポンスが今は2つありますが、まぁなん個でてようとも、TraceId で引けば「このリクエストはこのレスポンスを返したんだな」という感じで一意に特定が出来るわけです。
先ほども書いた通り、/WeatherForecast
の実装はテンプレートのままなので、非常に単純なメソッドなのですが、実際にはビジネスロジックが走ったりなんだりして、そこでもログを出します。
で、この SpanId や TraceId 等は、スコープ、もうちょっとプリミティブな言い方をすると、ひとつの非同期制御フローの中で伝播し続けるので、ビジネスロジックとかで出力したログにも、これらの id は含まれるようになります。
なので各リクエストがどうやって処理されたか、各リクエスト毎の一連の処理のフロー、ソフトウェアの振る舞いがログから追えるようになります。
これがオプション一ついれるだけで出来るようになるのが大変うれしいわけです。
これまでさんざん IncludeScopes
を true に設定した場合に現われる SpanId や TraceId とかの話をしていたのですが、
ここで一つ勘違いしてほしくない事があります。
それは IncludeScopes
自体は別に SpanId とか TraceId を表示するためのものではないという事です。
あくまで IncludeScopes
はその名の通り、「ログにスコープを含みます、含みません」 というオプションです。
なので以下のように logger の BeginScope を使って適当にスコープを切ってあげると
以下のようなログがでるのですが
みて欲しいのは赤で囲っている部分で、こんな感じで自分が切ったスコープが表示されるようになります。
ログのスコープはかなり便利で、例えば私が開発している OSS である AspNetCore.SignalR.OpenTelemetry では Invoke された SignalR の Hub 名 / Method 名 / InvocationId をスコープに含める事で、ログの検索性を高めています。
W3C Trace Context
で、先ほどの SpanId とか TraceId ってなんなんじゃい、という話ですが、これについては 【C#】ASP.NET Core と W3C Trace Context とお手軽ロギング。 というブログに纏めていますので、是非読んでみてください。
ExceptionHandler
まず、未処理の例外がどうやって処理されるかについて、軽く触れておきます。 未処理の例外のハンドリングは実は ENVIRONMENT 次第でデフォルトの挙動が変わってきます。
- Development
- DeveloperExceptionPageMiddleware が自動で追加される
- 例外が起きたとき HTTP の Response に stack trace が含まれたりするのは、このミドルウェアがそういう仕事をしているから。
- Staging / Production
- 未処理の例外をハンドリングするためのミドルウェアは自動で追加されない
問題は Staging / Production の方です。 これがどういう問題を引き起こすとかというと以下のような感じです。
例外が Kestrel にまで突き抜けてしまっています。
この時点で気持ち悪~~~という感じなのですが、Kestrel のところにまで例外が突き抜けてしまっているということは、リクエストパイプラインとかもはや無意味なものと化しているわけです。
なので HttpLogging
ミドルウェアが出力してくれるハズの Response に関するログも残りません。
ということで、未処理の例外をハンドリングするためのミドルウェアと、それを使うために必要なサービスを追加しましょう。
まずは AddProblemDetails
という拡張メソッドを使ってサービスを追加します。
このサービスは RFC 7807 "Problem Details for HTTP APIs" に準拠したレスポンスを作成するためのサービスだったりします。
次に UseExceptionHandler
をリクエストパイプラインに組み込みます。
ここで追加されるミドルウェアが未処理の例外をハンドリングしてくれるようになります。
で気を付けたいのは UseExceptionHandler
は UseHttpLogging()
の下に追加する事です。
そうしないと、HttpLogging
ミドルウェアが出力してくれるハズの Response に関するログが残りません。
さて、これらの設定を入れた場合どんな感じのログがでるようになるかというと、こんな感じです。
例外が Kestrel にまで突き抜けてないですし、HttpLogging
の Response に関するログがしっかり残るようになります。
よさそう。
そして副産物的に 未処理の例外が発生したときこんな感じの、RFC 7807に準拠したレスポンスを返すようになります。
レスポンスに traceId が含まれるようになるのが嬉しい。かもしれないです。 いざという時便利かもしれません。
DbDataSource
DbDataSource
をご存じでしょうか?
これは .NET 7 で追加された ADO.NET の新しい API なんですけど、大雑把にはコネクションのプロバイダーだと思っておけば概ね OK だと思います。
ただ、DbDataSource
はコネクションプールを抽象化したものではありませんよ、というのはドキュメントというかこの issue で名言されているので、ご留意ください。
よもやま話的には、この提案者は Npgsql の中の人であり、MS の中の人でもあります。
この記事では ADO.NET がどうのこうのという話ではなく、ログの話をしているわけですけど、DbDataSource
はログの面でも嬉しいのです。
とはいえ、DbDataSource
に関しては初見の人そこそこいるんじゃないかと思うので軽く紹介をしておきます。
今まで ADO.NET を通してデータベースを叩く場合って、基本的に DbConnection
を継承した各データベース固有のクラス、ポスグレだったら Npgsql の NpgsqlConnection
ですし、MySQL だったら、MySqlConnection
を new してたわけですよね。DB を叩きたい時に毎回。
そしてその際に接続文字列を毎回渡していましたが、各 DbConnection
は当然ながらコネクションプールを内部的には抱えていて、new した DbConnection
では、毎回接続文字列を解析して適切なコネクションプール選んで…とかいうまりと無駄な事をやっていたんですよね。
そこで、DbDataSource
を使う事でこういった問題が解消します。
Npgsql の場合、DbDataSource
を作る際にはビルダーパターンで組み立てるのですが、その時に接続文字列を渡します。
接続文字列に限らず、ビルダーを通して様々な設定を DbDataSource
にしてあげます。
例えばログに関するものビルダーでいろいろ設定します。
Npgsql の場合、UseLoggerFactory
というメソッドがあって、そこには loggerFactory
を渡します。
一度以後 DbDataSource
を組み上げた後は DbConnection
は毎回 new するのではなく、DbDataSource
から提供してもらう、という感じになります。
別に DbDataSource
の機能はこれだけではないのですが、こんなもんだと思っておいてください。
そして DbDataSource
から取得した DbConnection
もらって、クエリを発行します。
上の例では Dapper (QueryAsync
) を使っていますが、ADO.NET 的には結局 Command が叩かれます。
で、ログ的にはどう嬉しいかという話ですが。
少なくとも Npgsql では、 Command が叩かれた際によしなにログを出してくれるようになります。
しばしば 「Npgsql の場合」とか「Npgsql では」とか書いていますが、これはなぜかというと、別に DbDataSource
自体にログをどうしろこうしろ、みたいなという決まりはないためです。
ただ、DbDataSource
の提案者が Npgsql の中の人なだけに、別の RDBMS に対する実装でも Npgsql の実装に寄せてくると思われるので、
各実装でも DbDataSource
がサポートされたらたぶん似たような感じになるんじゃないかと思います。
実際にどんなログでるのっていうと、以下のような感じ。
ここでは、テンプレートの wethreforcast のアクションの中で、connection (DbConnection
) を叩いた場合にどんなログがでるかというとを示しているのですが、
赤で囲われているところに注目してください。
Npgsql.Command
というカテゴリで、どういうクエリが発行されました、というのがログの出力として含まれるようになります。
そして、IncludeScopes
を設定しておけば、SpanId / TraceId がちゃんとログに含まれているため、どのリクエストでどのクエリが発行されたのか一目瞭然になります。
さらに親切に duration、つまりそのクエリに何 msec かかったのかというも、よしなに表示してくれるのでログを見れば明らかにボトルネックになっているところというのは、すぐに分かるようになります。
HttpClientFactory
最後に HttpClientFactory
についても触れておきます。
そもそも HttpClient
を毎回 new して dispose するのは良くない、というのは有名な話かと思います。
この問題があるので、HttpClient
を一度 new したらそれをキャッシュして使いまわす...というのが定石です。
しかし ASP.NET Core では HttpClient
を直接 new してキャッシュする、とかはせずに HttpClientFactory
を使って HttpClient
を取得するのがベストプラクティスとなっています。
その利点については公式ドキュメントで書かれているので、そちらを読んでください。
そしてこの HttpClientFactory
、実はログの観点でも嬉しいものだったりします。
たとえば以下のようなこんな感じのコードを書いてあげます。
これは first というエンドポイントが叩かれたら httpclientfactory
から httpclient
を取得し、別のサービスの /second
というエンドポイントを叩きに行く、という感じのものになっています。
この時実際どんなログがでるかというと、以下のような感じ。
注目したいのは赤で囲っているところです。
HttpClientFactory
から取得した HttpClient
を使っている場合は、リクエストとレスポンスに関するログというのがしれっと出力されるようになります。
親切にレスポンスが返ってくるまでの時間もよしなに表示してくれます。
便利ですね!
まとめ
まとめるとこんな感じ.
- AddHttpLogging / UseHttpLogging
- Inbound HTTP request / response がログとして出力される
- LoggingFields は RequestProperties | ResponseStatusCode がオススメ。
- ログレベルの設定を忘れずに。
- ConsoleFormatterOptions.IncludeScopes
- ログのスコープが出力に含まれるようになる。
- SpanId / TraceId / ParentId が表示されて嬉しい。
- W3C Trace Context
- AddProblemDetails / UseExceptionHandler
- 未処理の例外をハンドリング / RFC 7807
- DbDataSource
- Npgsql ではすべての Command がログとして出力される
- HttpClientFactory
- Outbound HTTP request / response がログとして出力される
冒頭の HttpLogging
と HttpClientFactory
を使う事によって、inbound と outbound の HTTP リクエストに関するログが出力されるようになります。
そして DbDataSource
を使えば DB に対するクエリに関するログが出力され、
ConsoleFormatterOptions.IncludeScopes
を設定すれば、出力されたログをリクエスト単位で振る舞いを追跡できるようになる、という事でした。
今回紹介した内容だけで HTTP の inbound / outbound と、DB の操作に関するログについては、いい感じに出力されるようになりました。 なのでここまでやると、自分のアプリケーションのビジネスロジックでどのようなログを出すべきか、というのを考える事にだいぶ集中する事ができるようになるかと思います。
References
- https://github.com/dotnet/runtime/tree/v7.0.8
- https://github.com/dotnet/aspnetcore/tree/v7.0.8
- https://github.com/dotnet/runtime/issues/64812
- https://learn.microsoft.com/en-us/aspnet/core/fundamentals/http-logging/?view=aspnetcore-7.0
- https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-7.0
- https://learn.microsoft.com/en-us/aspnet/core/fundamentals/error-handling?view=aspnetcore-7.0
- https://learn.microsoft.com/en-us/dotnet/architecture/microservices/implement-resilient-applications/use-httpclientfactory-to-implement-resilient-http-requests
- https://learn.microsoft.com/en-us/dotnet/core/diagnostics/distributed-tracing-concepts
- https://www.w3.org/TR/trace-context/