仕事で、ILogger への移行をやることになったので、先に ILoggerのスパイクをしておこうと考えた。今回は２回に分けて書くつもりで、今回は Console App を使った ILogger の基本機能、そして、次回は、ASPNetCore とのインテグレーションを理解したいと思う。
使用したバージョン
今回使用したのは、dotnet 5 を使用している。使っているライブラリのバージョンは次の通り。
<Project Sdk="Microsoft.NET.Sdk">
<PropertyGroup>
<OutputType>Exe</OutputType>
<TargetFramework>net5</TargetFramework>
</PropertyGroup>
<ItemGroup>
<PackageReference Include="Microsoft.Extensions.Logging" Version="5.0.0" />
<PackageReference Include="Microsoft.Extensions.Logging.ApplicationInsights" Version="2.17.0" />
<PackageReference Include="Microsoft.Extensions.DependencyInjection" Version="5.0.0" />
<PackageReference Include="Microsoft.Extensions.Logging.Console" Version="5.0.0" />
</ItemGroup>
</Project>
シンプルな ILogger の使用
コンソールアプリケーションから、ILogger を使いたいときは、LoggerFactoryを使うとよい。コンソールへのロギングを実現したい場合、Microsoft.Extensions.Logging.Console を使えばよく、ILoggingBuilder に対して、AddConsole() もしくは、AddJsonConsole() を追加すればよい。今回はフォーマットを Json で出力したかったので、AddJsonConsole() を使用している。これは、dotnet 5 から使えるインターフェイスなので、今回、dotnet 5 をスパイクに使用している。 options の設定内容は後程説明したい。このようなログのフォーマットのサポートに関しては
Console log formattingを参照にすると良い。
using var loggerFactory = LoggerFactory.Create(builder =>
{
// builder.AddConsole(); // Plain
builder.AddJsonConsole(
options => options.IncludeScopes = true // Enable Scope
); // from net 5; otherwise you need to implement it.
ILogger logger = loggerFactory.CreateLogger<Program>();
logger.LogInformation(AppLogEvents.Details, "Start Program with {Id} at {RunTime}", 1, DateTime.Now);
Logging のテンプレートを使う
次のコードを見ると、なんで、Substituteを最新の形で書かないんだろうと思うかもしれない。$"{something} is substitution" の形式だ。それには理由があって、この形式で書くと、ログを出力した時に、Id = 1, Runtime = DateTime.Now として、個別の項目として認識される。これは、本番運用時に、ログを検索するときに便利になると思われる。
logger.LogInformation(AppLogEvents.Details, "Start Program with {Id} at {RunTime}", 1, DateTime.Now);
尚、AppLogEvents.Details はカスタムクラスで、単にint を定義している。これは、最初のパラメータが、EventId というもので、ログのイベントの種別を区別するための項目だからだ。 次の実行結果で、"Id":1,"RunTime":"06/26/2021 23:26:07" という個別の項目が出来ているのが確認できるだろう。
{"EventId":3000,"LogLevel":"Information","Category":"ILoggerSpike.Program","Message":"Start Program with 1 at 06/26/2021 23:26:07","State":{"Message":"Start Program with 1 at 06/26/2021 23:26:07","Id":1,"RunTime":"06/26/2021 23:26:07","{OriginalFormat}":"Start Program with {Id} at {RunTime}"},"Scopes":["simple","start console"]}
Scope を有効にする
さて、ログを有効化するときに、スコープを定義したいときがある。特定のメソッドがどこのコールスタックの一部としてコールされたのか？が気になる場合がある。次のように記述する。このログを出力してみよう。
using (logger.BeginScope("DI enabled"))
using (logger.BeginScope("start console"))
{
logger.LogInformation(AppLogEvents.Details, "Start Program with {Id} at {RunTime}", 1, DateTime.Now);
try
{
throw new CustomException("tsushi's exception thrown.");
}
catch (CustomException e)
{
logger.LogError(AppLogEvents.Error, e, "Check the host.json configuration.");
}
}
logger.LogInformation(AppLogEvents.Details, "out of scope");
"Scopes":["simple","start console"] が、各テレメトリに追加されている。
{"EventId":3000,"LogLevel":"Information","Category":"ILoggerSpike.Program","Message":"Start Program with 1 at 06/26/2021 23:26:07","State":{"Message":"Start Program with 1 at 06/26/2021 23:26:07","Id":1,"RunTime":"06/26/2021 23:26:07","{OriginalFormat}":"Start Program with {Id} at {RunTime}"},"Scopes":["simple","start console"]}
{"EventId":3001,"LogLevel":"Error","Category":"ILoggerSpike.Program","Message":"Check the host.json configuration.","Exception":"ILoggerSpike.CustomException: tsushi\u0027s exception thrown. at ILoggerSpike.Program.SimpleConsole() in C:\\Users\\tsushi\\source\\repos\\ILoggerSpike\\ILoggerSpike\\Program.cs:line 81","State":{"Message":"Check the host.json configuration.","{OriginalFormat}":"Check the host.json configuration."},"Scopes":["simple","start console"]}
{"EventId":3000,"LogLevel":"Information","Category":"ILoggerSpike.Program","Message":"out of scope","State":{"Message":"out of scope","{OriginalFormat}":"out of scope"},"Scopes":[]}
Application Insights を有効にする
ILogger はインターフェイスであり、１つのインスタンスから、複数のロギングのプロバイダに出力することができる。今回はコンソールを使ったが、Application Insights のプロバイダを使えるようにしてみよう。Microsoft.Extensions.Logging.ApplicationInsights をNuGet パッケージとして取得して、ILoggingBuilderに次の設定をするとよい。ちなみに、Microsoft.Extensions.Logging.ApplicationInsights は、最新でも 2.x であり dotnet 5 向けの5.xのバージョンは見当たらない。おそらく将来的にこのNuGetパッケージは違うものに移行するのかもしれない。 最近の Application Insights だと、InstrumentationKey より、Connection String を重視している感じがするが、こちらの記事を見ても、ASP.Net のパッケージのネームペースが変わっている。ASP.Net Core の場合は、Connection String を見るようにしているようだ。だた、先ほどのドキュメントによると、コネクションストリングは、新しいAzureのリージョンに必要なもののようなので、コンソールアプリでは必要ないとも言える。
builder.AddApplicationInsights(InstrumentationKey,
options => { options.IncludeScopes = true; }
);
ここで、先ほどのスコープを有効にするために、options => { options.IncludeScopes = true; } を設定している。これを有効にしないと、スコープがログには出てこなくなる。
コンソールより、より多くのメタデータが追加されているのがわかる。
DI を使う
実はコンソールアプリであっても、DIを使うほうがきれいに同じことを出来る。Microsoft.Extensions.DependencyInjectionパッケージのServcieCollection を使う。BuildServiceProviderの拡張メソッドによって、``IServiceProvider のインスタンスが取得でき、そこから、ILogger` のインスタンスをとればよいのでさほど大変でもない。
一つ面白いところは、services.Configure<TelemetryConfiguration>(config => config.TelemetryChannel = channel); によって、TelemetryConfiguration のチャネルがオーバライドされている。これは、のちに、 finally のセクションで、InMemoryChannel をフラッシュしている。これは、何か不慮のExceptionが起こったときでも、しっかりログをフラッシュ出来るためのコードである。オフィシャルドキュメントにこの説明が掲載されていた。
using var channel = new InMemoryChannel();
try
{
IServiceCollection services = new ServiceCollection();
services.Configure<TelemetryConfiguration>(config => config.TelemetryChannel = channel);
services.AddLogging(builder =>
{
builder.AddApplicationInsights(InstrumentationKey);
builder.AddJsonConsole(options => options.IncludeScopes = true);
});
IServiceProvider serviceProvider = services.BuildServiceProvider();
ILogger<Program> logger = serviceProvider.GetService<ILogger<Program>>();
using (logger.BeginScope("DI enabled"))
using (logger.BeginScope("start console"))
{
logger.LogInformation(AppLogEvents.Details, "Start Program with {Id} at {RunTime}", 1, DateTime.Now);
try
{
throw new CustomException("tsushi's exception thrown.");
}
catch (CustomException e)
{
logger.LogError(AppLogEvents.Error, e, "Check the host.json configuration.");
}
}
logger.LogInformation(AppLogEvents.Details, "out of scope");
}
finally
{
channel.Flush();
await Task.Delay(TimeSpan.FromMilliseconds(1000));
}
次回
今回はコンソールアプリなので、動作検証、もしくは、ユニットテストなどでの使用で使えそうな知識だったが、AspNetCore とのインテグレーションを見てみたい。今回紹介したコンセプトに加えて、ログをフィルタしたり、ログをアップデートしたりする方法を学びます。
Resource
- Logging in .NET: ILogger を学ぶための決定版
- Application Insights Logging with .NET: Application Insights とのインテグレーションが載っている
- Logging Providers in .NET: ロギングプロバイダの種類や設定について書かれている