LoginSignup
27
24

More than 1 year has passed since last update.

@TsuyoshiUshio@github(Ushio Tsuyoshi)

ILogger を理解する (1) - Console App

Posted at

仕事で、ILogger への移行をやることになったので、先に ILoggerのスパイクをしておこうと考えた。今回は２回に分けて書くつもりで、今回は Console App を使った ILogger の基本機能、そして、次回は、ASPNetCore とのインテグレーションを理解したいと思う。

使用したバージョン

今回使用したのは、dotnet 5 を使用している。使っているライブラリのバージョンは次の通り。

ILoggerSpike.csproj
<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" という個別の項目が出来ているのが確認できるだろう。

log
{"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"] が、各テレメトリに追加されている。

log
{"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; } を設定している。これを有効にしないと、スコープがログには出てこなくなる。

image.png

コンソールより、より多くのメタデータが追加されているのがわかる。
image.png

DI を使う

実はコンソールアプリであっても、DIを使うほうがきれいに同じことを出来る。Microsoft.Extensions.DependencyInjectionパッケージのServcieCollection を使う。BuildServiceProviderの拡張メソッドによって、`IServiceProvider のインスタンスが取得でき、そこから、ILogger のインスタンスをとればよいのでさほど大変でもない。

一つ面白いところは、services.Configure<TelemetryConfiguration>(config => config.TelemetryChannel = channel); によって、TelemetryConfiguration のチャネルがオーバライドされている。これは、のちに、　finally のセクションで、InMemoryChannel をフラッシュしている。これは、何か不慮のExceptionが起こったときでも、しっかりログをフラッシュ出来るためのコードである。オフィシャルドキュメントにこの説明が掲載されていた。

DI
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

27
24
1

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
27
24