Serilogでクレームの情報をログに出力しよう

# 今回の内容

　認証サーバーから受け取ったクレームに含まれる情報をログの情報として合わせて出力したいという要望があります。Serilogを利用してログにクレームの情報を出力する方法について見ていきます。
# Serilogで常に特定の値をログに出力するには？

　.NETで今や標準と言ってもよいロガーのSerilogには、NLogの`MappedDiagnosticsLogicalContext`やlog4netの`LogicalThreadContext`と同じように、特定のコンテキストの中で常に特定の値をプロパティーとしてログに出力するための`LogContext`クラスが存在します。

　例えばSerilogの出力フォーマットを`JsonFormatter`に設定したうえで次のようにログを出力すると、

``` cs
using (LogContext.PushProperty("Prop1", "ほげ"))
using (LogContext.PushProperty("Prop2", "ほげほげ"))
{
    Log.Information("ログだよー");
}
```

　usingのコンテキスト内であれば、出力されたログのProperties要素の中にPushPropertyしたProp1やProp2が常に出力されるようになります。

``` json
{
  "Timestamp": "2020-11-25T08:16:49.1342176+09:00",
  "Level": "Information",
  "MessageTemplate": "ログだよー",
  "Properties": {
    "Prop2": "ほげほげ",
    "Prop1": "ほげ",
    "ActionId": "1e55d24a-bb44-479f-9a13-2233bae73eff",
    "ActionName": "TraceContextSample.WebApp2.Controllers.HomeController.Index (TraceContextSample.WebApp2)",
    "RequestId": "0HM4GPS20RBMN:00000001",
    "RequestPath": "/",
    "SpanId": "|353d86ac-4da39cde8fd02b90.",
    "TraceId": "353d86ac-4da39cde8fd02b90",
    "ParentId": ""
  }
}
```

SpanIdやTraceIdについては、[こちらの記事](https://qiita.com/karuakun/items/7f75c774a22d69590125)を参照してください。

# クレーム情報をログに吐き出すには？

　では、クレームの情報を出力するとしたらどのような方法があるでしょうか。良い、悪いは別として方法としては次の5つがぱっと思い浮かびます。1,2はべったり実装する方法なので特に詳しい説明は必要ないでしょう。修正の影響範囲が大きいのであまりお勧めはしません。

1. 各コントローラーやページでPushPropertyする
1. コントローラーのベースクラスでPushPropertyする
1. アクションフィルター（orページフィルター）でLogContextにPushPropertyする
1. ミドルウェアでLogContextにPushPropertyする（おすすめ）
1. Enricherを作ってAddPropertyIfAbsentする（おすすめ）

今回は2,3,4について説明して行きます。

# subクレームのマッピング

　ASP.NETの認証ミドルウェアは、JWTに含まれるクレーム情報をHttpContextのクレーム情報に格納してくれます。ただし、subクレームなどの一部のクレーム情報はJWTハンドラーによって変換されるため、subクレームのまま利用したい場合はStartup時にClaimTypeのマッピングをクリアしておく必要があります。

``` cs:Startup.cs
public class Startup
{
    public void ConfigureServices(IServiceCollection services)
    {
        // ... 略 ...
        JwtSecurityTokenHandler.DefaultInboundClaimTypeMap.Clear();
        // ... 略 ...
    }
}
```

# アクションフィルター（orページフィルター）でLogContextにPushPropertyする

　コントローラーに対するアクションフィルターやRazorPageに対するページフィルターを作成して、各コントローラーやページにフィルターを適用する方法です。一見コントローラーに属性を設定するだけで、実装を後から追加できるので嬉しいように見えますが、コントローラーやページの外で発生したログに関してはフィルターが適用されないため値が出力されないというデメリットがあります。

　まずはアクションフィルターを作ります。現在のHTTPContextから認証済みユーザーの認証情報を抜き出し、subクレームの情報を`LogContext`に追加しています。

``` cs:ClaimsLogFilter.cs
public class ClaimsLogFilter : ActionFilterAttribute
{
    public override void OnActionExecuting(ActionExecutingContext context)
    {
        var user = context.HttpContext.User;
        if (user.Identity.IsAuthenticated)
        {
            var ciamls = user.Identities.First().Claims;
            var userId = ciamls.FirstOrDefault(c => c.Type.ToLower() == "sub");
            if (userId != null)
            {
                LogContext.PushProperty("UserId", userId);
            }
        }
    }
}
```

　あとは、コントローラーか、アクションメソッドに属性を付けるだけですね。

``` cs:HomeController.cs
public class HomeController : Controller
{
    [Authorize]
    [ClaimsLogFilter]
    public async Task<IActionResult> Secret()
    {
    }
}
```

　場合によってStartup時にフィルターを追加して全コントローラーに適用しても良いですね。

``` cs:Startup.cs
public class Startup
{
    /// ... 略 ...

    public void ConfigureServices(IServiceCollection services)
    {
        /// ... 略 ...
        services.AddControllersWithViews(options =>
        {
            options.Filters.Add(typeof(ClaimsLogFilter));
        });
        /// ... 略 ...
    }
}
```

### 参考
- [ASP.NET Core フィルター](https://docs.microsoft.com/ja-jp/aspnet/core/mvc/controllers/filters)
- [ASP.NETCoreのRazorページのフィルターメソッド](https://docs.microsoft.com/ja-jp/aspnet/core/razor-pages/filter)

# ミドルウェアでLogContextにPushPropertyする

　ASP.NET Coreのミドルウェアを利用してリクエストのパイプラインの途中で`LogContext`にコンテキストを追加する方法です。アクションフィルター同様`HttpContext`から現在のユーザーに紐づくクレーム情報を取り出し、PushPropertyしています。

``` cs:ClaimsLoggingMiddleware.cs
public class ClaimsLoggingMiddleware
{
    private readonly RequestDelegate _next;

    public ClaimsLoggingMiddleware(RequestDelegate next)
    {
        _next = next;
    }

    public async Task Invoke(HttpContext httpContext)
    {
        var user = httpContext.User;
        if (user.Identity.IsAuthenticated)
        {
            var ciamls = user.Identities.First().Claims;
            var userId = ciamls.FirstOrDefault(c => c.Type.ToLower() == "sub");
            if (userId != null)
            {
                using (LogContext.PushProperty("UserId", userId?.Value))
                    await _next(httpContext);
            }
        }
    }
}
```

　重要なのはミドルウェアを追加するタイミングです。認証情報は`AuthenticationMiddleware`によって設定されるので、UseAuthenticationメソッドが呼ばれた後に`ClaimsLoggingMiddleware`を組み込まないと値を取得することができません（常にnullになる）。

``` cs:Startup.cs
public class Startup
{
    public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
    {
        /// ... 略 ...
        app.UseAuthentication();
        app.UseAuthorization();

        app.UseMiddleware<ClaimsLoggingMiddleware>();
        /// ... 略 ...
    }
}
```

### 参考
- [ASP.NET Core のミドルウェア](https://docs.microsoft.com/ja-jp/aspnet/core/fundamentals/middleware/)

# Enricherを作ってAddPropertyIfAbsentする

　最後にSerilogの拡張機能であるEnricher（付与）を利用する方法です。少し複雑になりますが、ログを出力するという用途から考えるとこの方法が一番正しい気がします。ただ、現時点ではHttpContextを参照するようなEnricherを利用する場合は依存関係を解決するタイミングのせいで、Loggerの初期化を遅らせる必要があるというデメリットがあります。

　まず、`ILogEventEnricher`インターフェイスを実装して、`ClaimsEnricher`クラスを作成します。アクションフィルターやミドルウェアと違い`HttpContext`を引数にもらえないので、コンストラクタに`IHttpContextAccessor`インターフェイスを受け取りDIしてもらいましょう。subクレームの参照方法は他の方法と変わらないですね。

``` cs:ClaimsEnricher.cs
public class ClaimsEnricher: ILogEventEnricher
{
    private readonly IHttpContextAccessor _httpContextAccessor;

    public ClaimsEnricher(IHttpContextAccessor httpContextAccessor)
    {
        _httpContextAccessor = httpContextAccessor;
    }
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        var user = _httpContextAccessor.HttpContext?.User;
        if (user != null && user.Identity.IsAuthenticated)
        {
            var ciamls = user.Identities.First().Claims;
            var userId = ciamls.FirstOrDefault(c => c.Type.ToLower() == "sub");
            if (userId != null)
            {
                var userIdProperty = propertyFactory.CreateProperty("UserId", userId);
                logEvent.AddPropertyIfAbsent(userIdProperty);
            }
        }
    }
}
```

　Startupでは`ClaimsEnricher`と`IHttpContextAccessor`の依存を設定します。

``` cs:Startup.cs
public class Startup
{
    public void ConfigureServices(IServiceCollection services)
    {
        // ... 略 ...
        services.AddTransient<ClaimsEnricher>();
        services.AddHttpContextAccessor();
        // ... 略 ...
    }
}
```

　プログラムのエントリーポイントでは、アプリケーションビルダーのUseSerilog初期化時に、Serilogの構成を行い、ConfigureServicesで設定した`ClaimsEnricher`をDIコンテナから取り出し適用します。残念ながらDIコンテナの初期化のタイミングの影響で、Main直後にロガーの設定ができないので、アプリケーション起動時のログは平文で出力されてしまいます。

``` cs:Program.cs
public class Program
{
    public static int Main(string[] args)
    {
        //本来はここでロガーを初期化したい。
        //Log.Logger = new LoggerConfiguration()
        //    .MinimumLevel.Information()
        //    .Enrich.FromLogContext()
        //    .WriteTo.Console(formatter: new JsonFormatter())
        //    .CreateLogger();
        try
        {
            Log.Information("Starting host...");

            CreateHostBuilder(args).Build().Run();
            return 0;
        }
        catch (Exception ex)
        {
            Log.Fatal(ex, "Host terminated unexpectedly.");
            return 1;
        }
        finally
        {
            Log.CloseAndFlush();
        }
    }

    public static IHostBuilder CreateHostBuilder(string[] args) =>
        Host.CreateDefaultBuilder(args)
            .UseSerilog(
                (context, services, configuration) =>
                configuration.
                    MinimumLevel.Information()
                    .Enrich.FromLogContext()
                    .Enrich.With(services.GetService<ClaimsEnricher>())
                    .WriteTo.Console(formatter: new JsonFormatter())

                )
            .ConfigureWebHostDefaults(webBuilder =>
            {
                webBuilder.UseStartup<Startup>();
            });
}
```            

　これに対応するために、Serilogの次？のバージョンでは、CreateBootstrapLoggerメソッドが追加され、Serilogの初期化を複数段階に分けて設定できるようになるらしいです。→ [Bootstrap logging with Serilog + ASP.NET Core](https://nblumhardt.com/2020/10/bootstrap-logger/)

### 参考
- [Injecting services into Serilog filters, enrichers, and sinks](https://nblumhardt.com/2020/09/serilog-inject-dependencies/)
- [Bootstrap logging with Serilog + ASP.NET Core](https://nblumhardt.com/2020/10/bootstrap-logger/)

# まとめ
　いろいろ方法はありますが、ミドルウェアを利用するか、Enricherを設定する方法が良さそうですね。