今回の内容

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

Serilogで常に特定の値をログに出力するには？

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

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

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

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

{
  "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については、こちらの記事を参照してください。

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

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

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

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

subクレームのマッピング

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

Startup.cs

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

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

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

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

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);
            }
        }
    }
}

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

HomeController.cs

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

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

Startup.cs

public class Startup
{
    /// ... 略 ...

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

参考

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

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

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になる）。

Startup.cs

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

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

参考

ASP.NET Core のミドルウェア

Enricherを作ってAddPropertyIfAbsentする

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

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

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の依存を設定します。

Startup.cs

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

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

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

参考

まとめ

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