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

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

# 使用したバージョン

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

```xml: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](https://docs.microsoft.com/ja-jp/dotnet/api/microsoft.extensions.logging.loggerfactory?view=dotnet-plat-ext-5.0)を使うとよい。コンソールへのロギングを実現したい場合、`Microsoft.Extensions.Logging.Console` を使えばよく、[ILoggingBuilder](https://docs.microsoft.com/ja-jp/dotnet/api/microsoft.extensions.logging.loggerfactory?view=dotnet-plat-ext-5.0) に対して、`AddConsole()` もしくは、`AddJsonConsole()` を追加すればよい。今回はフォーマットを Json で出力したかったので、`AddJsonConsole()` を使用している。これは、dotnet 5 から使えるインターフェイスなので、今回、dotnet 5 をスパイクに使用している。 `options` の設定内容は後程説明したい。このようなログのフォーマットのサポートに関しては
[Console log formatting](https://docs.microsoft.com/en-us/dotnet/core/extensions/console-log-formatter)を参照にすると良い。

```csharp
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` として、個別の項目として認識される。これは、本番運用時に、ログを検索するときに便利になると思われる。

```csharp
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 を有効にする
さて、ログを有効化するときに、スコープを定義したいときがある。特定のメソッドがどこのコールスタックの一部としてコールされたのか？が気になる場合がある。次のように記述する。このログを出力してみよう。

```csharp
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](https://docs.microsoft.com/ja-jp/dotnet/api/microsoft.extensions.logging.loggerfactory?view=dotnet-plat-ext-5.0)に次の設定をするとよい。ちなみに、`Microsoft.Extensions.Logging.ApplicationInsights` は、最新でも `2.x` であり dotnet 5 向けの`5.x`のバージョンは見当たらない。おそらく将来的にこのNuGetパッケージは違うものに移行するのかもしれない。 最近の Application Insights だと、`InstrumentationKey` より、`Connection String` を重視している感じがするが、[こちら](https://docs.microsoft.com/en-us/azure/azure-monitor/app/ilogger#console-application)の記事を見ても、ASP.Net のパッケージのネームペースが変わっている。ASP.Net Core の場合は、`Connection String` を見るようにしているようだ。だた、先ほどのドキュメントによると、コネクションストリングは、新しいAzureのリージョンに必要なもののようなので、コンソールアプリでは必要ないとも言える。

```csharp
builder.AddApplicationInsights(InstrumentationKey,
    options => { options.IncludeScopes = true; }
);
```

ここで、先ほどのスコープを有効にするために、`options => { options.IncludeScopes = true; }` を設定している。これを有効にしないと、スコープがログには出てこなくなる。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3470/57d41d87-48ed-2ebc-2ee8-d26a475630f5.png)

コンソールより、より多くのメタデータが追加されているのがわかる。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3470/1eece1a0-9f38-3f22-bbf1-6d36c6166035.png)

# DI を使う

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

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

```csharp: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 
* [Logging in .NET](https://docs.microsoft.com/en-us/dotnet/core/extensions/logging?tabs=command-line#log-level): ILogger を学ぶための決定版
* [Application Insights Logging with .NET](https://docs.microsoft.com/en-us/azure/azure-monitor/app/ilogger#console-application): Application Insights とのインテグレーションが載っている
* [Logging Providers in .NET](https://docs.microsoft.com/en-us/dotnet/core/extensions/logging-providers): ロギングプロバイダの種類や設定について書かれている