ねののお庭。

かりかりもふもふ。

【C#】明日から使える ASP.NET Core ロギング術！

.NET ASP.NET Core C# .NET Core

登壇版

.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;
   options.JsonWriterOptions = new JsonWriterOptions
   {
       Indented = false
   };
});

設定した結果、どういうログがでるかというと、こんな感じ。

ログに SpanId, TraceId, ParentId とかが含まれるようになります。 これが嬉しい。 これらの id が何を意味しているかについては、詳しくはこちらの記事 を読んで欲しいのですが、 何はともあれこの id によって、このログはどのリクエストに紐づくログなのか、というのがわかるようになります。 つまりリクエスト毎の処理のフローをログから追えるようになります。

たとえば、同時にリクエストたたいた場合のログを見るとこの嬉しさは一目瞭然です。

一番最初の行のログはリクエストをされた時のログですが、 この TraceId が同一のログをながめれば、このリクエストに紐づく処理が追えるようになります。 レスポンスが今は2つありますが、まぁなん個でてようとも、TraceId で引けば「このリクエストはこのレスポンスを返したんだな」という感じで一意に特定が出来るわけです。

先ほども書いた通り、/WeatherForecast の実装はテンプレートのままなので、非常に単純なメソッドなのですが、実際にはビジネスロジックが走ったりなんだりして、そこでもログを出します。 で、この SpanId や TraceId 等は、スコープ、もうちょっとプリミティブな言い方をすると、ひとつの非同期制御フローの中で伝播し続けるので、ビジネスロジックとかで出力したログにも、これらの id は含まれるようになります。 なので各リクエストがどうやって処理されたか、各リクエスト毎の一連の処理のフロー、ソフトウェアの振る舞いがログから追えるようになります。 これがオプション一ついれるだけで出来るようになるのが大変うれしいわけです。

これまでさんざん IncludeScopes を true に設定した場合に現われる SpanId や TraceId とかの話をしていたのですが、 ここで一つ勘違いしてほしくない事があります。 それは IncludeScopes 自体は別に SpanId とか TraceId を表示するためのものではないという事です。 あくまで IncludeScopes はその名の通り、「ログにスコープを含みます、含みません」 というオプションです。 なので以下のように logger の BeginScope を使って適当にスコープを切ってあげると

以下のようなログがでるのですが

みて欲しいのは赤で囲っている部分で、こんな感じで自分が切ったスコープが表示されるようになります。

ログのスコープはかなり便利で、私が開発している OSS でも活用しています。

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