掲載内容は個人の見解であり、所属する企業を代表するものではありません.
私の所属は営業部門なのですが技術者的なロールでもあるので、お客様と会話の中でトラブルシュートになることも多々あります。 多くの場合は PoC や検証段階で「うまく動かないんだけど助けて」ってやつなんですが、たまに本番環境でのご相談も舞い込んできます。 そんなトラシューで重要なのが「ログ」なんですが、このログの出し方がわからない、あるいは確認方法がわからないとなるとやれることが限られてきます。 まあログ出力は割と初歩的な話ではありますし、検索すれば公式ドキュメントがあっさり引っかかりますよね。 ただ昨今のアプリケーション フレームワークは割と高機能になってしまっているせいか、結局のところ自分のアプリケーションではどうすればログが出せるのかわかりにくかったりします。
この手の相談は結構な頻度でいただくのでちょっとまとめてみようかなと思ったんですが、実行環境やフレームワークによってお作法も様々ですので、網羅するのはちょっと辛い。 というわけで、ASP.NET Core で作ったアプリを Azure App Service や Azure Containr Apps にデプロイする前提でまとめてみようと思いました。
参考にするドキュメントが多岐に渡るので、ここにまとめておきます。
ここでは ASP.NET Core Razor Pages を題材にしていきます。
Razor Pages 以外の ASP.NET Core 系のアプリケーション(MVC, API, Blazor, Minimal API, etc…)であれば概ね同じお作法になりますし、
HostApplicationBuilder
を使う各種アプリケーション(MAUI とか汎用ホストとか)であれば大体一緒になると思います。
要は Program.cs で HogeHogeBuilder.Build()
とかやってて、その前後に DependencyInjection したり Midlleware を組み込んでリクエストパイプラインを構築してるアレです。
というわけで、Razor Pages な Web アプリを作ってみます。 もちろん Visual Studio のプロジェクトテンプレートを使っても OK です。
dotnet new webapp -o aspnet-logging-sample
出来上がったら何も書き換えずに徐に実行します。
コンソールで dotnet run
するか VS や VSCode で F5(デバッグ実行)してください。
そうすると起動したコンソールやデバッガーの出力に以下のような表示が出ると思います。
info: Microsoft.Hosting.Lifetime[14]
Now listening on: https://localhost:7105
info: Microsoft.Hosting.Lifetime[14]
Now listening on: http://localhost:5202
info: Microsoft.Hosting.Lifetime[0]
Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
Content root path: /Users/username/source/aspnet-logging-sample
これがデフォルトで確認できる ログ ですね。 ブラウザーで URL を開いてやれば画面は表示されますが、その後もこのログが書き加わる事はありません。 (デバッガをアタッチしてる場合はちょろちょろと出てきますが、そっちは割愛)
出力内容としては以下の項目の繰り返しになっていることがわかります。
loglevel: カテゴリー名[eventid]
ログ出力されたメッセージ(複数行の場合もある)
ここでカテゴリー名は「名前空間で修飾されたクラス名」になっており、どこのコードが出力してるログが欲しいか?という観点からとても重要なポイントになってきます。
ここで出力されている表記は Console ログプロバイダーが決めてるフォーマットですので、違うログプロバイダーを使用すれば別のフォーマットになっている場合もあります。 もちろんカスタムのログプロバイダーを実装して、好みの出力先やフォーマットにすることも可能です。
ではここから、このログ出力をリッチにしていきたいと思いますが、まずはコードをなるべく書き換えずにやれることを探ります。
本番系のトラブルだと「ログ出力コードを書き加えて調査しましょう」とかなかなか難しいものがあります。
デフォルトで取れるログってのは大事ですよね。
開発時にログのことをあまり考慮してなくて、後付けで必要になっちゃうこともあるわけです。
プレーンな Console アプリでもない限り、多くの .NET アプリはなんらかのフレームワークの上で動いています。 ここでは ASP.NET Core Razor Pages がそのフレームワークです。 つまり開発者が書いていないコードも沢山動いているわけですので、そこからログを吐いてることが期待できます。
さてログの設定ですが、プロジェクト作成(dotnet new
)時に勝手に作成される構成ファイル、appsettings.json と appsettings.Development.json に記載があります。
ここでは開発環境ということで appsettings.Development.json を見てみましょう。
ログに関係するセクションだけ抜粋。
"Logging": {
"LogLevel": {
"Default": "Information",
"Microsoft.AspNetCore": "Warning"
}
}
既定では「Information」ログレベルなんですが、Microsoft.AspNetCore だけは「Warning」以上のログレベルしか出力されません。 つまり ASP.NET Core フレームワークのログは警告が必要だなーという時しかログが出てこないわけですね。 先程の確認ではちゃんとページが表示されて正常稼働していたので、何も出てこないのが正しかったわけです。
このログレベルですが定義としては以下のようになっており、構成ファイルで指定したログレベル「以上」のものが出力されます。
Trace | Debug | Information | Warning | Error | Critical | None |
---|---|---|---|---|---|---|
0 | 1 | 2 | 3 | 4 | 5 | 6 |
というわけで、appsettings.Development.json ファイルの Logging:LogLevel:Microsoft.AspNetCore
の値を Information
に書き換えます。
改めてアプリを起動してブラウザで表示してみてください。
(ちなみにここで欲張って Trace とか Debug を指定すると、心が折れるほど大量に出力されますのでご注意ください)
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5202/ - - -
warn: Microsoft.AspNetCore.HttpsPolicy.HttpsRedirectionMiddleware[3]
Failed to determine the https port for redirect.
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Executing endpoint '/Index'
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[103]
Route matched with {page = "/Index"}. Executing page /Index
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[105]
Executing handler method aspnet_logging_sample.Pages.IndexModel.OnGet - ModelState is Valid
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[108]
Executed handler method OnGet, returned result .
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[107]
Executing an implicit handler method - ModelState is Valid
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[109]
Executed an implicit handler method, returned result Microsoft.AspNetCore.Mvc.RazorPages.PageResult.
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[104]
Executed page /Index in 260.5577ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Executed endpoint '/Index'
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5202/aspnet_logging_sample.styles.css - - -
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished HTTP/1.1 GET http://localhost:5202/ - 200 - text/html;+charset=utf-8 399.7447ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished HTTP/1.1 GET http://localhost:5202/aspnet_logging_sample.styles.css - 404 0 - 3.1639ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[16]
Request reached the end of the middleware pipeline without being handled by application code. Request path: GET http://localhost:5202/aspnet_logging_sample.styles.css, Response status code: 404
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5202/css/site.css?v=pAGv4ietcJNk_EwsQZ5BN9-K4MuNYS2a9wl4Jw-q9D0 - - -
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5202/js/site.js?v=hRQyftXiu1lLX2P9Ly9xa4gHJgLeR1uGN5qegUobtGo - - -
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5202/lib/bootstrap/dist/css/bootstrap.min.css - - -
info: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[6]
The file /css/site.css was not modified
info: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[6]
The file /js/site.js was not modified
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished HTTP/1.1 GET http://localhost:5202/js/site.js?v=hRQyftXiu1lLX2P9Ly9xa4gHJgLeR1uGN5qegUobtGo - 304 - text/javascript 3.5195ms
info: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[6]
The file /lib/bootstrap/dist/css/bootstrap.min.css was not modified
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished HTTP/1.1 GET http://localhost:5202/lib/bootstrap/dist/css/bootstrap.min.css - 304 - text/css 8.9015ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished HTTP/1.1 GET http://localhost:5202/css/site.css?v=pAGv4ietcJNk_EwsQZ5BN9-K4MuNYS2a9wl4Jw-q9D0 - 304 - text/css 14.9807ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5202/lib/bootstrap/dist/js/bootstrap.bundle.min.js - - -
info: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[6]
The file /lib/bootstrap/dist/js/bootstrap.bundle.min.js was not modified
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished HTTP/1.1 GET http://localhost:5202/lib/bootstrap/dist/js/bootstrap.bundle.min.js - 304 - text/javascript 0.4539ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:5202/lib/jquery/dist/jquery.min.js - - -
info: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[6]
The file /lib/jquery/dist/jquery.min.js was not modified
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished HTTP/1.1 GET http://localhost:5202/lib/jquery/dist/jquery.min.js - 304 - text/javascript 0.3545ms
とりあえず出力された中から差分になるものをべたっと貼りましたが、Information でもそれなりに辛いですね。 いくつかピックアップしてみると以下の情報が取れていることが分かります。
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Executing endpoint '/Index'
上記からは /Index
へのリクエストが到着して適切な Middleware にルーティングしようとしていることがわかります。
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[105]
Executing handler method aspnet_logging_sample.Pages.IndexModel.OnGet - ModelState is Valid
上記からは テンプレートで生成された IndexModel(Index.cshtml + Index.cshtml.cs)
クラスの OnGet
メソッドで処理していrることが分かります。
info: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[6]
The file /css/site.css was not modified
上記からは 静的ファイルであるスタイルシート /css/site.css
は RazorPages ではなく StaticFileMiddleware
が処理していることがわかります。
その他のスタイルシートや JavaScript も同様で大量に出てきてますね。
さて3度の飯よりログが好きな人でなければこの分量は辛いと思いますので、もうちょっと必要な箇所に絞り込んでみましょう。 例えば開発したコードに問題があるならルーティングや実際に処理してるページ周りのログは欲しいと思います。 一方 CSS や JS 等の静的ファイルへのリクエストに対してはただコンテンツを返すだけですから、そこで問題になることは少ないでしょうし、 これらのコンテンツのデバッグはブラウザでやれますので、不要なケースも多いのではないでしょうか。
というわけで、Microsoft.AspNetCore
配下のカテゴリーは原則として Warning
レベルに上げて(戻して)しまい、
詳細情報の欲しい Microsoft.AspNetCore.Routing
と Microsoft.AspNetCore.Mvc.RazorPages
を追記して Information
レベルに下げます。
"Logging": {
"LogLevel": {
"Default": "Information",
"Microsoft.AspNetCore": "Warning",
"Microsoft.AspNetCore.Routing": "Information",
"Microsoft.AspNetCore.Mvc.RazorPages": "Information"
}
}
何度もログを貼っても辛いので割愛しますが、前回よりもかなり絞り込まれた出力になっていると思います。 このカテゴリー名によるフィルターは前方一致し、より詳細な方で上書きできますので、うまく設定して必要な情報を取れるようにしましょう。
上記の通り内部的に出力されているログは大量にあるのですが、カテゴリー(=クラス名)単位でフィルターがかかっていて出力されてない状態なのですが、どんなカテゴリー何が出てるかなんてわからないですよね。開発環境であればとりあえず最低の Trace
で出してしまってじっくり読んでみるのもいいと思います。
ただ本番環境ではパフォーマンス的にもストレージ的にも辛いことになりますので、開発環境でなるべく必要なカテゴリを絞り込んでからピンポイントに設定しましょう。
ここまでは分かり易さのために appsettings.Development.json でログ出力設定を切り替えましたが、このファイルは通常ソースコード管理システムに登録して共有されていることが多いでしょう。
一時的に手元で編集しただけのつもりで、うっかり git add .
して git commit
して git push
して仲間に迷惑をかけてしまう事故を起こしたりしがちです(ですよね?)
つまりあまり個人の開発端末ででごちゃごちゃいじるのには向いていません。
ログ出力設定をを開発端末だけで試したい場合はシークレット マネージャーを使うと良いでしょう。 一般的には外部 API やサービスへ接続する際のパスワードの機微情報を管理するために使いますが、 開発端末固有の設定情報を持てるのでこういうケースでも便利です。
Visual Studio の場合はソリューション エクスプローラーでプロジェクトを右クリックして「ユーザーシークレットの管理」とかいうメニュー(うろ覚え)を選ぶだけで良いのですが、コマンドでやる場合は以下のようになります。 詳細はドキュメントを参照してください。
# まずはユーザーシークレットを初期化
$ dotnet user-secrets init
Set UserSecretsId to 'guid-of-user-secret-id' for MSBuild project '/Users/username/source/projdir/projectName.csproj'.
# 生成された GUID 形式の UserSecretsId をもとにディレクトリと secrets.json を作成
# {guid-of-user-secret-id} の部分は読み替えてください。
$ mkdir ~/.microsoft/usersecrets/guid-of-user-secret-id
$ touch ~/.microsoft/usersecrets/guid-of-user-secret-id/secrets.json
作成した secrets.json を適当なエディタで編集して、appsettigs.json および appsettings.Develpment.json に対する差分の追記ないしは上書きします。 例えば RazorPages 系だけさらにログレベルを下げたい場合は以下のようになります。 (appsetting.Development.json は元に戻す想定)
{
"Logging": {
"LogLevel": {
"Microsoft.AspNetCore.Mvc.RazorPages": "Trace"
}
}
}
また動作確認して出力されてるログの情報を確認してみてください。 ここでは割愛します。
これは全ての開発者が見るべきだな、本番環境でも常に出力されるべきだな、 という項目は appsettings.Development.json や appsettings.json に転記すると良いのではないでしょうか。
なお
dotnet user-secrets init
で生成したユーザーシークレット ID の GUID 値はプロジェクトファイル(.csproj)に記載されています。 ターミナルが消えてしまってもそちらで値は確認できますのでご安心を。<Project Sdk="Microsoft.NET.Sdk.Web"> <PropertyGroup> <UserSecretsId>guid-of-user-secret-id</UserSecretsId> </PropertyGroup> </Project>
なお構成設定の上書きは環境変数で行うことも可能です。 ただこれは開発環境というよりは本番環境向けかなと思いますので後ほど。
ここまではもともとフレームワークが出力しているけれど表示されていなかったログを表示する方法でした。 また設定変更だけですのでソースコードに手を入れにくい(入れらなない)時でも使える方法です。 ここからは若干のコード変更も伴いますが、共通的に(最小限のカスタマイズで)追加のログが取れるようにする方法を紹介していきます。
ASP.NET のアプリケーションを作ってるわけですから、なんらかのクライアントから HTTP(S) のプロトコルで通信が行われているはずです。 通信プロトコルレベルでの処理はフレームワークがやってくれてますので通常はあまり意識することはないんですが、 トラブルシュートとなるとプロトコルレベルまで深掘りしたいこともあるでしょう。 というわけでHTTPのログを増やしたいと思います。
まずは Program.cs に記述されたスタートアップ コードをカスタマイズします。
// Dependency Injection コンテナに HttpLogging サービスを組み込んでから
builder.Services.AddHttpLogging( c => {
/*ここで詳細なカスタマイズを行う*/
});
// アプリケーションをビルドして、
var app = builder.Build();
// ミドルウェアの先頭で HttpLogging モジュールを組み込む
app.UseHttpLogging();
これで内部的にはログを吐くようになりますので、上記と同様にフィルターを外してやります。
カテゴリとしては Microsoft.AspNetCore.HttpLogging
名前空間あたりのフィルターをざっくり Information
まで下げてやります。
これも大量に出ますので前述の secrets.json で設定すると良いでしょう。
"Logging": {
"LogLevel": {
"Microsoft.AspNetCore.HttpLogging": "Information"
}
}
そうすると以下のように通信ログが混じってきます。
これまでもログに含まれていた、ユーザーリクエストを最終的に処理している EndpointMiddleware
のログと一緒に、
HttpLoggingMiddleware
が出力する HTTP レベルでの通信ログが確認できますね。
info: Microsoft.Hosting.Lifetime[0]
Content root path: /Users/ainaba/source/aspnet-logging-sample
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
Request:
Protocol: HTTP/1.1
Method: GET
Scheme: http
PathBase:
Path: /
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7
Connection: keep-alive
Host: localhost:5202
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/121.0.0.0 Safari/537.36 Edg/121.0.0.0
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Executing endpoint '/Index'
... 中略 ...
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
Request:
Protocol: HTTP/1.1
Method: GET
Scheme: http
PathBase:
Path: /aspnet_logging_sample.styles.css
Accept: text/css,*/*;q=0.1
Connection: keep-alive
Host: localhost:5202
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/121.0.0.0 Safari/537.36 Edg/121.0.0.0
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Executed endpoint '/Index'
ログ出力の内容の詳細はスタートアップコードの中で、AddHttpLogging
に渡しているラムダ式の中でカスタマイズできます。
具体的な方法はドキュメントを参照してください。
こちらも同じくHTTPレベルの通信ログなのですが、W3C 標準形式のログファイルが欲しい場合もあるでしょう。
その場合はリクエスト パイプラインを構成しているミドルウェアの先頭に W3CLogger
ミドルウェアを追加します。
// Dependency Injection コンテナに W3CLogger サービスを組み込んで
HttpLogging サービスを組み込んでから
builder.Services.AddW3CLogging( c => {
/*ここで詳細なカスタマイズを行う*/
});
// アプリケーションをビルドして、
var app = builder.Build();
// ミドルウェアの先頭で HttpLogging モジュールを組み込む
app.UseW3cLogging();
AddW3CLogging
で何も構成しない場合は
W3CLoggerOption.LogDirectory
の既定値である ./logs/
配下、すなわちコンテンツルート下の logs ディレクトリにテキストファイルとして出力されます。
#Version: 1.0
#Start-Date: 2024-02-24 08:37:32
#Fields: date time c-ip s-computername s-ip s-port cs-method cs-uri-stem cs-uri-query sc-status time-taken cs-version cs-host cs(User-Agent) cs(Referer)
2024-02-24 08:37:31 ::1 ainaba2401mbp ::1 5202 GET / - 200 234.9835 HTTP/1.1 localhost:5202 Mozilla/5.0+(Macintosh;+Intel+Mac+OS+X+10_15_7)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/121.0.0.0+Safari/537.36+Edg/121.0.0.0 -
2024-02-24 08:37:31 ::1 ainaba2401mbp ::1 5202 GET /aspnet_logging_sample.styles.css - 404 2.3617 HTTP/1.1 localhost:5202 Mozilla/5.0+(Macintosh;+Intel+Mac+OS+X+10_15_7)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/121.0.0.0+Safari/537.36+Edg/121.0.0.0 http://localhost:5202/
2024-02-24 08:37:31 ::1 ainaba2401mbp ::1 5202 GET /css/site.css ?v=pAGv4ietcJNk_EwsQZ5BN9-K4MuNYS2a9wl4Jw-q9D0 304 2.182 HTTP/1.1 localhost:5202 Mozilla/5.0+(Macintosh;+Intel+Mac+OS+X+10_15_7)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/121.0.0.0+Safari/537.36+Edg/121.0.0.0 http://localhost:5202/
2024-02-24 08:37:31 ::1 ainaba2401mbp ::1 5202 GET /js/site.js ?v=hRQyftXiu1lLX2P9Ly9xa4gHJgLeR1uGN5qegUobtGo 304 0.9233 HTTP/1.1 localhost:5202 Mozilla/5.0+(Macintosh;+Intel+Mac+OS+X+10_15_7)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/121.0.0.0+Safari/537.36+Edg/121.0.0.0 http://localhost:5202/
(以下省略)
この W3CLogger はこれまで暗黙的に使っていた Microsoft.Extensions.Logging
の仕組みとは異なります。
つまり Console プロバイダーに出力されることもなく、カテゴリーによるフィルターをかける事も出来ず、複数のモジュールから出力されるログとマージされて出ることもありません。
またまた HTTP ですが、今度はアプリケーションから外部の Web API を呼び出すアウトバウンド側の通信ログになります。
通常この手のケースでは System.Net.Http.HttpClient
を使うと思います。
こういった「自分でコードを書いていないクラスライブラリ」も内部的にはログを吐いてる可能性がありますので、それをどうにかして収集したいものです。
さて名前空間から分かる通り HttpClient
は ASP.NET Core フレームワークの一部ではありません。
が、一定のお作法に則って利用することで、同じ Microsoft.Extensions.Logging
の仕組みに沿ってログを出力することが可能です。
そのお作法とは「Dependency Injection を使用してサービスとして注入してもらうこと」です。
もし既存コードがそうなってればラッキー、設定変更だけでログが出せるでしょう。
まず Program.cs でサービスを組み込みます。
builder.Services.AddHttpClient();
実際に HttpClient
を使用して外部 Web API を呼び出すコードは以下のようになります。
ここではユーザーコードのログ( _logger.LogInformation
で書いてるログ)とともに出力しています。
ユーザーコードのログの書き方は後の方でもう少し詳しく解説します。
private readonly ILogger<IndexModel> _logger;
private readonly IHttpClientFactory _httpClientFactory;
//DI でサービスとして IHttpClientFactory を注入してもらい、
public IndexModel(ILogger<IndexModel> logger, IHttpClientFactory factory) {
_logger = logger;
_httpClientFactory = factory;
}
//HttpClient が必要な箇所で CreateClient して利用します。
public async Task OnGet() {
_logger.LogInformation(1, "Calling httpbin");
// リクエスト用のデータを作っておいて
var request = new HttpRequestMessage( HttpMethod.Get, "https://httpbin.org/image/png" ) {
Headers = {
{ HeaderNames.Accept, "image/png" }
}};
// HttpClient のインスタンスを作ってもらい
var client = _httpClientFactory.CreateClient();
// API を呼び出す
var response = await client.SendAsync(request);
_logger.LogInformation(2, "Status Code = {status}", response.StatusCode);
}
そうすると以下のようなログが出力されます。
今回追加されたのは System.Net.Http.HttpClient.Default
配下のカテゴリーです。
自分のコードでは明示的に書いていない Web API の URL やレスポンスタイムなんかが勝手に出力されてますね。
info: aspnet_logging_sample.Pages.IndexModel[1]
Calling httpbin
info: System.Net.Http.HttpClient.Default.LogicalHandler[100]
Start processing HTTP request GET https://httpbin.org/image/png
info: System.Net.Http.HttpClient.Default.ClientHandler[100]
Sending HTTP request GET https://httpbin.org/image/png
info: System.Net.Http.HttpClient.Default.ClientHandler[101]
Received HTTP response headers after 783.0029ms - 200
info: System.Net.Http.HttpClient.Default.LogicalHandler[101]
End processing HTTP request after 799.4202ms - 200
info: aspnet_logging_sample.Pages.IndexModel[2]
Status Code = OK
既定の appsettings.{Development}.json では Default
カテゴリのログレベルが Information
になっているので、
特にフィルター定義をいじらなくても出力されているはずです。
もし出力されない場合は System.Net.Http
配下のカテゴリがフィルターで除去される設定になっていないか確認しましょう。
ここでは最もシンプルなサンプルを載せていますので、カテゴリが
System.Net.Http.HttpClient.Default.xxx
になっています。 名前付きクライアントや型指定されたクライアントを利用する場合は、この Default の部分がその名前に変わりますので、ピンポイントにフィルターをかけられるでしょう。
ちなみにコンストラクターで IHttpClientFactory
ではなく HttpClient
を注入してもらう場合にもログは生成されます。
ただ IHttpClientFactory
を使用した方が
メリットが多いので、
そちらを利用することをお勧めします。
なお HttpClient
のコンストラクタを使って自力でインスタンスを生成している場合には、いくらフィルターを設定したところでログがでませんのでご注意ください。
つまり「外部 API 呼び出しのログが出なくて困っている」ということは、DI を使わずに自力で new
してしまっている可能性が高いです。
その場合はコード修正をお勧めします。
// これだと自動でログが出ない
var client = new HttpClient();
var response = await client.SendAsync(request);
さて外部のクラスライブラリの第2弾です。
前述のように Web API を呼び出す時に HttpClient
のような汎用的なライブラリではなく、
Web API の提供元やサードパーティから提供されている SDK を使用できる場合はその方が便利です。
例えば Azure が提供している各種サービス、より具体的には Storage Blob、Storage Queue、Key Vault, Azure OpenAI Service、Computer Vision などが該当します。
これらの REST API の仕様を読み込んで直接呼び出すのは辛いですよね。
仕方なく HttpClient
で頑張るケースの無くはないですが、基本的には
Azure SDK for .NET
を使うのではないでしょうか。
ただその場合には内部的に通信に使われている(かもしれない)HttpClient
のライフサイクルに関与することが難しいわけです。
こういった SDK を使う場合のログ出力のお作法は SDK 次第になるのですが、
Azure SDK for .NET の場合は HttpClient
の場合と同様に Microsoft.Extensions.Logging
の仕組みに合わせることが可能です。
結果から言えばこれも Dependency Injection を使用しているかが勝負です。
例えば Storage Blob を使用したい場合で解説していきます。 まず追加のライブラリが必要なので、プロジェクトにパッケージを追加します。
# Blob を使いたいだけならコレだけでもいいのですが、
dotnet add package Azure.Storage.Blob
# Blob のクライアントをサービスに組み込むためにコレが必要
dotnet add Microsoft.Extensions.Azure
次に Program.cs でサービスを登録します。
//AddAzureClients の中で各種サービスのクライアントを登録しておく
builder.Services.AddAzureClients( acbuilder => {
// BlobServiceClient を名前付きで登録
acbuilder
.AddBlobServiceClient("connection-strings-goes-here")
.WithName("myStorage");
});
実際に Blob を呼び出す場所ではインスタンスを挿入してもらって利用します
private readonly IAzureClientFactory<BlobServiceClient> _blobSvcClientFactory;
// DI から BlobServiceClient を生成するための IAzureClientFactory を挿入してもらって
public IndexModel(ILogger<IndexModel> logger, IAzureClientFactory<BlobServiceClient> bfactory) {
_logger = logger;
_blobSvcClientFactory = bfactory;
}
public async Task OnGet() {
// 名前付きのクライアントとして登録してあるので、呼び出す時に名前指定で CreateClient して利用する
var bsClient = _blobSvcClientFactory.CreateClient("myStorage");
// あとは普通に使うだけ
var container = bsClient.GetBlobContainerClient("containerName");
await foreach (var blob in container.GetBlobsAsync())
{
_logger.LogInformation(3, "{name} is {size} bytes", blob.Name, blob.Properties.ContentLength);
}
}
ここでは Blob コンテナに保存されている Blob の一覧をログ出力しているので以下のような結果が出てきます。
Azure.Core
カテゴリとして Information
レベルのログとして、
利用している Blob サービス REST API の URL などが勝手に出力されてることが確認できます。
info: Azure.Core[1]
Request [eb856509-2d61-4fa9-a83d-e2899a066af4] GET https://storageName.blob.core.windows.net/containerName?restype=container&comp=list
x-ms-version:2023-11-03
Accept:application/xml
x-ms-client-request-id:eb856509-2d61-4fa9-a83d-e2899a066af4
x-ms-return-client-request-id:true
User-Agent:azsdk-net-Storage.Blobs/12.19.1 (.NET 8.0.1; Darwin 23.3.0 Darwin Kernel Version 23.3.0: Wed Dec 20 21:28:58 PST 2023; root:xnu-10002.81.5~7/RELEASE_X86_64)
x-ms-date:Sat, 24 Feb 2024 10:36:20 GMT
Authorization:REDACTED
client assembly: Azure.Storage.Blobs
info: Azure.Core[5]
Response [eb856509-2d61-4fa9-a83d-e2899a066af4] 200 OK (01.6s)
Transfer-Encoding:chunked
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:f4ebea53-401e-002b-5b0d-678cad000000
x-ms-client-request-id:eb856509-2d61-4fa9-a83d-e2899a066af4
x-ms-version:2023-11-03
Date:Sat, 24 Feb 2024 10:36:20 GMT
Content-Type:application/xml
info: aspnet_logging_sample.Pages.IndexModel[3]
00f93a9c-003b-4700-bd8f-d28df16214ff is 43857 bytes
info: aspnet_logging_sample.Pages.IndexModel[3]
041b142e-0a45-4b80-aabf-73833c1cf286 is 43857 bytes
info: aspnet_logging_sample.Pages.IndexModel[3]
042712ce-ccd5-4cb4-8e35-855eb8dfaebc is 43857 bytes
以下省略
なお DI だけではログ出力できないパターンもあるようですが、そういった場合の対処方法もあるようですので、詳細はドキュメントを参照してください。
よく使われるクラスライブラリの第3弾は Entity Framework Core です。 データベース アクセスするアプリは多いですからね。
ここまで読んでいただいた方にはオチが見えてるでしょうが、
お作法としては Entity Framework で使用するクライアントである DbContext
派生クラスを
AddDbContext
で DI サービスに登録し、
自分で new
せずに利用することです。
実際のサンプルコードやログ出力は割愛します。
面倒になったとも言う。
さてフレームワークやらライブラリやらのログは(お作法にさえ則っていれば)出力できるので、 それで大まかな処理の流れはつかめると思います。 そして最終的に疑うべきは自分で書いたコードでしょう。
当然ながら明示的にログを出力するコードを記述しない限り勝手にログは吐いてくれません。 というわけでここからはログ出力するための方法ですが、前述のフレームワークと同じ仕組みに則ることをおすすめします。 あっちこっちに出てるログを突き合わせて解析するなんて茨の道を歩かないで済むに越したことはありません。
Razor Pages の場合は生成した cshtml.cs
のコンストラクターで ILogger<T>
インタフェースなオブジェクトが Injection されてることがわかりますので迷うことはありません。
あとはログを出したい場所で ILogger
のメソッドを呼び出して、必要な情報を出力してください。
他のフレームワークやテンプレでは Injection されてないこともありますので、その場合は追加してあげてください。
public class IndexModel : PageModel {
// Dependency Injection によって自動挿入されるログモジュール
private readonly ILogger<IndexModel> _logger;
public IndexModel(ILogger<IndexModel> logger) {
_logger = logger;
}
// Get /Index 時に呼び出されるロジック。各メソッドの第1引数はEventID、第2引数がメッセージ。
public void OnGet() {
_logger.LogCritical(999, "Index.cshtml.cs の OnGet が呼ばれました(Crit)");
_logger.LogError(888,"Index.cshtml.cs の OnGet が呼ばれました(Err)");
_logger.LogWarning(777, "Index.cshtml.cs の OnGet が呼ばれました(Warn)");
_logger.LogInformation(666, "Index.cshtml.cs の OnGet が呼ばれました(Info)");
_logger.LogDebug(555,"Index.cshtml.cs の OnGet が呼ばれました(Debug)");
_logger.LogTrace(444,"Index.cshtml.cs の OnGet が呼ばれました(Trace)");
}
}
そうすると ASP.NET Core やライブラリが自動的に出してるログに混じって、以下のようにログが出力されると思います。
crit: aspnet_logging_sample.Pages.IndexModel[999]
Index.cshtml.cs の OnGet が呼ばれました(Crit)
fail: aspnet_logging_sample.Pages.IndexModel[888]
Index.cshtml.cs の OnGet が呼ばれました(Err)
warn: aspnet_logging_sample.Pages.IndexModel[777]
Index.cshtml.cs の OnGet が呼ばれました(Warn)
info: aspnet_logging_sample.Pages.IndexModel[666]
Index.cshtml.cs の OnGet が呼ばれました(Info)
Default
カテゴリのログレベルが Information
になっているのでそれ以上のログレベルしか出力されていませんが、
これまで同様にフィルターの設定を変えてあげることで出力を増減することができます。
例えば各ページの既定のログレベルは Warning
まで引き上げておき、挙動の怪しい IndexModel
だけログレベルを Trace
まで下げて出力を詳細化したい場合の設定は以下のようになります。
これで Debug
や Trace
レベルまで表示されるようになるでしょう。
"Logging": {
"LogLevel": {
"aspnet_logging_sample.Pages": "Warning",
"aspnet_logging_sample.Pages.IndexModel": "Trace",
}
}
上記のユーザーコードでログ出力していた IndexModel は Razor Pages なので、そもそも Dependency Injection によって生成されたインスタンスでした。 これは Program.cs のテンプレートで最初から以下のコード(抜粋)が記述されていたから成り立っているわけです。
// Razor Page をサービスとして組み込んで
builder.Services.AddRazorPages();
// アプリをビルドし
var app = builder.Build();
// URL で指定されるルートに対して各ページを割り当てて処理をする
app.MapRazorPages();
HTTP リクエストが ASP.NET Core フレームワークに到着すると、そのルートに一致する各 Razor Page のインスタンスが DI によって自動生成され、そのコンストラクタで要求されてる ILogger<T>
のインスタンスも自動生成されて注入されていたわけです。
だからコンストラクタに ILogger<T>
の引数を追加しておくだけでよかったんですね。
つまりここまで例に挙げてきた HttpClient
や BlobServiceClient
などと同様の仕組みなわけです。
と言うわけで、Razor Page じゃない自作クラスに関しても、同じ仕組みに乗っかってやれば良いことになります。
例えば以下のような MyBizLogic
クラスを作って、IndexModel
に直接書いていたロジックを切り出します。
public class MyBizLogic
{
private readonly ILogger<MyBizLogic> _logger;
private readonly IHttpClientFactory _httpClientFactory;
private readonly IAzureClientFactory<BlobServiceClient> _blobSvcClientFactory;
// コンストラクタで挿入して欲しいオブジェクトを引数に加えて、
public MyBizLogic(ILogger<MyBizLogic> logger,
IHttpClientFactory hcfactory,
IAzureClientFactory<BlobServiceClient> bfactory)
{
_logger = logger;
_httpClientFactory = hcfactory;
_blobSvcClientFactory = bfactory;
}
public async Task DoSomething()
{
// Web API を呼び出したり
_logger.LogInformation(1, "Calling httpbin");
var request = new HttpRequestMessage( HttpMethod.Get, "https://httpbin.org/image/png" )
{
Headers = {
{ "Accept", "image/png" }
}
};
var client = _httpClientFactory.CreateClient();
var response = await client.SendAsync(request);
_logger.LogInformation(2, "Status Code = {status}", response.StatusCode);
// Blob Service の呼び出したり
var bsClient = _blobSvcClientFactory.CreateClient("myStorage");
var container = bsClient.GetBlobContainerClient("images");
await foreach (var blob in container.GetBlobsAsync())
{
_logger.LogInformation(3, "{name} is {size} bytes", blob.Name, blob.Properties.ContentLength);
} }
}
これを Razor Pages から new
したら元も子もないので、
// Program.cs で自作クラスもサービスとして DI コンテナに登録しておいて
builder.Services.AddTransient<MyBizLogic>();
このクラスを利用する Razor Page ではインスタンスを注入してもらえば良いわけです。
private readonly MyBizLogic _bizLogic;
// 自作クラスをコンストラクタ引数で受けて
public IndexModel(ILogger<IndexModel> logger , MyBizLogic bizLogic)
{
_logger = logger;
_bizLogic = bizLogic;
}
// new しないで呼び出します。
public async Task OnGet()
{
_logger.LogInformation(666, "Index.cshtml.cs の OnGet が呼ばれました(Info)");
await _bizLogic.DoSomething();
}
ILogger
なインスタンスを上位層から引き渡してあげなくても、同じようにログが出るわけですね。
以下は一部だけに抜粋していますが、ASP.NET Core も 自作の Razor Page やビジネスロジッククラスも、 HttpClient による外部 API 呼び出しも、Azure SDK を使用した Blob サービスの呼び出しも、 一元的にログに出力できています。
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Executing endpoint '/Index'
info: aspnet_logging_sample.Pages.IndexModel[666]
Index.cshtml.cs の OnGet が呼ばれました(Info)
info: aspnet_logging_sample.MyBizLogic[1]
Calling httpbin
info: System.Net.Http.HttpClient.Default.LogicalHandler[100]
Start processing HTTP request GET https://httpbin.org/image/png
info: System.Net.Http.HttpClient.Default.LogicalHandler[101]
End processing HTTP request after 1252.8823ms - 200
info: aspnet_logging_sample.MyBizLogic[2]
Status Code = OK
info: Azure.Core[1]
Request [64184627-a71c-4c41-8402-7ba007fc36f1] GET https://appmigaistrage.blob.core.windows.net/images?restype=container&comp=list
info: Azure.Core[5]
Response [64184627-a71c-4c41-8402-7ba007fc36f1] 200 OK (01.6s)
改めて重要なのはログのカテゴリー(=名前空間とクラス名)と、それによるフィルターです。
自作のコードの場合、カテゴリ名は DI フレームワークに挿入してもらう ILogger<T>
の Generic 型引数 T
で決まりますので、汎用の ILogger
を使わないようにしましょう。
この型引数(上記では IndexModel
や MyBizLogic
)が正しく指定されているからこそ、どのコードが出力したログかが分かるわけですし、それによって適切なフィルターもかけられるわけです。
つまり他のページのコードをコピペして「型引数を書き換え忘れる」とかもってのほかです。 これが間違っているとどこから出てきたログなのかわからないで情報としての信頼性を失いますし、 フィルターを調整しても思うように表示されたりされなかったりするのでトラブルシュートの効率が極端に下がります。
皆さんもお気をつけください(反省)
さて出すべきものは出したので、運用環境でどうやって取得するかです。 よく考えたらコレが本題です。
Azure App Service を作成して作成したアプリケーションをデプロイしてみます。
これまでは開発環境だったので dotnet run
したコンソールや Visual Studio (Code) のデバッグウインドウでログを確認できていたのですが、
App Service ではどうしましょう?
まずおすすめは Application Insights です。 App Service を作成時に一緒に作成しているケースも多いでしょうし、後から有効化するのも簡単です。 コンソールで確認してた時と同じログが出てますが、クエリで収集したり絞り込んだりできるのが良いですね。
App Service の設定で「アプリケーションのログ記録」を有効にすることでファイルベースでログを確認することも可能です。
と、思いきや、これを使用するには ASP.NET Core 側でも一定の構成が必要です。 まず必要なパッケージを組み込みます。
dotnet add package Microsoft.AspNetCore.AzureAppServices.HostingStartup
dotnet add package Microsoft.AspNetCore.AzureAppServicesIntegration
dotnet add package Microsoft.Extensions.Logging.AzureAppServices
サービスとして組み込みます。
builder.Logging.AddAzureWebAppDiagnostics();
builder.Services.Configure<AzureFileLoggerOptions>(options =>
{
options.FileName = "azure-diagnostics-";
options.FileSizeLimit = 50 * 1024;
options.RetainedFileCountLimit = 5;
});
builder.Services.Configure<AzureBlobLoggerOptions>(options =>
{
options.BlobName = "log.txt";
});
こうすると App Service の $Env:Home\LogFiles\Application
、
あるいは指定した Blob コンテナにログファイルが出力されます。
また ファイルシステムのアプリケーションログを有効にした場合には、ログストリームの画面でも確認できるようになります。
ただログストリームは割と遅延というかタイムラグがあるのがちょっとストレスですね。
ログの確認方法としては上記の通りなのですが、App Service には本番環境としてデプロイされているので、 appsettings.Development.json や sercrets.json で設定したフィルター条件は失われ、 appsettings.json に記載した値のみが有効になっています。
ただ本番環境にデプロイ済みのファイルである appsettings.json を、しかも運用中に書き換えるのはよろしくないケースも多いでしょう。
こういう場合は設定値を環境変数で上書きすることが可能です。
環境変数は json ファイルのようなツリー構造を持ちませんが、下記のように :
でセクションを区切ってパラメータを指定することでフィルターを調整できます。
Logging:LogLevel:FilterName=LogLevel
コンテナアプリの場合は標準出力にログを出すことが一般的です。 つまり上記のサンプルのように Console ログプロバイダーが動いてれば、あとは実行環境側で集めてやるだけです。
Azure Container App のメニューに「ログ ストリーム」があるので、そちらで確認するのが手っ取り早いでしょう。
App Service の場合と同様に、フィルターとしては appsettings.json に記載されたフィルター設定が有効になっていますので、それを環境変数で上書きすることで調整可能です。
注意点としては Linux 環境の場合には環境変数の名前として :
(コロン)が使えませんので、__
(アンダースコア2つ)で区切ってやります。
Logging__LogLevel__FilterName=LogLevel
ログ ストリームだけですと収集中に Azure Portal とにらめっこする羽目になりますので、外部ストレージに永続化しておきましょう。 Container Apps 環境 の診断設定を開くとアプリがコンソールに出力したログを Log Analytics や Blob に転送することが可能です。 (Container App 個別の設定ではありませんのでご注意) Kusto でクエリがかけられるようになるまで若干の遅延がありますが、事後調査できるので便利ですね。
Log Analytics に出力されたログを眺めていると「ログレベルやカテゴリの行」と「ログのメッセージ行」がバラバラになっていることが分かります。
またタイムスタンプ TimeGenerated
が全く同じなので、ソートしても順不同になってしまっており、特にメッセージ行が複数にわたる場合はとてもツラいことになっています。
Container Apps としては「ログ」としての塊を意識してるわけではなく、標準出力や標準エラーに出てきた文字を転送してるだけなので仕方ないのですが、アプリケーションからコンソール出力のフォーマットを調整してやった方が見やすいでしょう。
さて、そもそもなぜ ILogger
への書き込みがログに出力されていたかといえば、Program.cs で WebApplication Builder が既定でログ プロバイダーというサービスが自動で組み込まれていたからです。
// 既定でいくつかの Console 等のログプロバイダーが組み込まれている。
var builder = WebApplication.CreateBuilder(args);
// App Service のアプリケーション ログに出力したいときは追加のプロバイダーを組み込んだ
builder.Logging.AddAzureWebAppDiagnostics();
既定で組み込まれている ConsoleLoggerProvider クラスは SimpleConsoleFormatterOption に指定されている既定値で動作しています。 このカスタマイズは Program.cs で実装するか、appsettings.json や環境変数の設定でカスタマイズ可能です。
今回はとりあえず1行で出力できればいいので、プログラム修正をせずに以下を設定してみます。 これ以外のフォーマット オプションもありますので、詳細はドキュメントを参照してください。
"Logging": {
"LogLevel":{
"Default": "Information"
},
"Console": {
"FormatterName": "simple",
"FormatterOptions": {
"SingleLine": true
}
}
}
さて dotnet run
してログの出方を確認すると、1行に収まるようにフォーマットが変わっていることが分かります。
info: Microsoft.Hosting.Lifetime[14] Now listening on: https://localhost:7105
info: Microsoft.Hosting.Lifetime[14] Now listening on: http://localhost:5202
info: Microsoft.Hosting.Lifetime[0] Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0] Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0] Content root path: C:\Users\ainaba\source\repos\aspnetcore-logging-sample
crit: aspnet_logging_sample.Pages.IndexModel[999] Index.cshtml.cs の OnGet が呼ばれました(Crit)
fail: aspnet_logging_sample.Pages.IndexModel[888] Index.cshtml.cs の OnGet が呼ばれました(Err)
warn: aspnet_logging_sample.Pages.IndexModel[777] Index.cshtml.cs の OnGet が呼ばれました(Warn)
info: aspnet_logging_sample.Pages.IndexModel[666] Index.cshtml.cs の OnGet が呼ばれました(Info)
info: aspnet_logging_sample.MyBizLogic[1] Calling httpbin
info: System.Net.Http.HttpClient.Default.LogicalHandler[100] Start processing HTTP request GET https://httpbin.org/image/png
info: System.Net.Http.HttpClient.Default.ClientHandler[100] Sending HTTP request GET https://httpbin.org/image/png
Azure Container Apps では環境変数で指定してあげてください。 ログストリームや Log Analytics でクエリをかけてやれば、もうちょっと見やすくなっていることがわかるでしょう。
# 環境変数の場合
Logging__Console__FormatterName=simple
Logging__Console__FormatterOptions__SingleLine=true
なお上記で Logging:LogLevel
の兄弟セクションとして Logging:Console
を追加していますが、これは Console ログ プロバイダー向けの設定を行うセクションです。
ここではフォーマッターの設定変更のみを行っていますが、ログ プロバイダー固有のログ レベル フィルターを指定することが可能です。
つまり出力先に応じてログの詳細度を変えることが可能ですので、トラブルシュートの状況に合わせてご活用ください。
App Service の場合は Application Insights を有効化するだけで自動的にデータが反映されました。 これは自動インストル メンテーションなどと呼ばれます。 しかし Azure Container Apps の場合はこの機能がありませんので、アプリの中から明示的に行う必要があります。
前述のとおり、「ログをどのように出力するか?」を決めているのはログ プロバイダーですので、 Application Insights ログプロバイダー を組み込んでやればいいわけです。 詳細はドキュメントを参照していただければと思いますが、大まかには以下のようになります。
# 追加のライブラリを読み込んで
dotnet add package Microsoft.Extensions.Logging.ApplicationInsights
// サービスにログプロバイダーを追加
builder.Logging.AddApplicationInsights(
configureTelemetryConfiguration: (config) =>
config.ConnectionString = "APPLICATIONINSIGHTS_CONNECTION_STRING" );
渋いテーマの割には割と長大な文章になってしましました。
端的にいえば ASP.NET Core のお作法?に則って、つまり Dependency Injections と ILogger