有效地使用 ASP.NET Core Logging - 2

2020-08-26

前言

在有效地使用 ASP.NET Core Logging - 1 中，我們將 Log 寫到實體檔之中，並且加入錯誤的處理機制。
接下來我們要記錄每個 Page, Action 的執行時間。

練習實作

我們可以透過 Filter 來記錄 Action 及 Razor Page 的執行時間，因為 API 及 Web UI 都會使用到，所以新增 RMStore.Infrastructure 來放這些共用的 Class，也將原本在 API 中 Middleware 移到了該專案之中。

Log for Razor Pages (Global Handle)

新增 TrackPagePerformanceFilter Filter

要 Log Razor Page 執行時間，可以實作 IPageFilter，所以在 RMStore.Infrastructure 專案中新增 Filters 目錄，並新增 TrackPagePerformanceFilter.cs 實作 IPageFilter ，然後在 OnPageHandlerExecuting, OnPageHandlerExecuted 透過 Stopwatch 來記錄時間，如下，
TrackPagePerformanceFilter.cs

public class TrackPagePerformanceFilter : IPageFilter
{
    private readonly ILogger<TrackPagePerformanceFilter> _logger;
    private Stopwatch _timmer;

    public TrackPagePerformanceFilter(ILogger<TrackPagePerformanceFilter> logger)
    {
        _logger = logger;
    }

    public void OnPageHandlerExecuting(PageHandlerExecutingContext context)
    {
        _timmer = new Stopwatch();
        _timmer.Start();
    }

    public void OnPageHandlerExecuted(PageHandlerExecutedContext context)
    {
        _timmer.Stop();
        if(context.Exception == null)
        {
            _logger.LogInformation("{RouteName} {Method} took {ElapsedMilliseconds} ms."
            , context.ActionDescriptor.RelativePath
            , context.HttpContext.Request.Method
            , _timmer.ElapsedMilliseconds);
        }
    }

    public void OnPageHandlerSelected(PageHandlerSelectedContext context)
    {
        //do nothing
    }
}

在 OnPageHandlerExecuted 中判斷 context.Exception 為 null 才記錄花費時間，是為了當 Page 發生 Exception 時，就不需要記錄。

加入 Global Filters

到 RMStore.WebUI 專案的 Startup.cs ，在 ConfigureServices Method 設定，如下，
Startup.cs

// other codes ...
public void ConfigureServices(IServiceCollection services)
{
    services.Configure<CookiePolicyOptions>(options =>
    {
        options.CheckConsentNeeded = context => true;
        options.MinimumSameSitePolicy = SameSiteMode.Lax;
    });
    services.AddAuthentication(CookieAuthenticationDefaults.AuthenticationScheme)
        .AddCookie(cookieOptions => {
            cookieOptions.LoginPath = "/";
        });
    services.AddRazorPages()
        .AddRazorPagesOptions(options => {
            options.Conventions.AuthorizePage("/Product");
        })
        .AddMvcOptions(options =>
        {
            //加入 Filter 來記錄 Razor Page 執行的起迄時間
            options.Filters.Add(typeof(TrackPagePerformanceFilter));
        });
}
// other codes....

註: 因為 TrackPagePerformanceFilter 在建構時，需要 ILogger ，所以這裡要使用 typeof(TrackPagePerformanceFilter) 來加入。

Log for Razor Pages (per Page)

如果只要針對某些 Page 來記錄的話，可以透過繼承 PageModel 來 override OnPageHandlerExecuting 及 OnPageHandlerExecuted 來記錄。

新增 Base Class

在 RMStore.Infrastructure 專案中新增 BaseClasses 目錄，並新增 BasePageModel.cs ，然後 override OnPageHandlerExecuting, OnPageHandlerExecuted 透過 Stopwatch 來記錄時間，如下，

BasePageModel.cs

public class BasePageModel : PageModel
{
    private readonly ILogger _logger;
    private Stopwatch _timmer;

    public BasePageModel(ILogger logger)
    {
        _logger = logger;
    }

    public override void OnPageHandlerExecuting(PageHandlerExecutingContext context)
    {
        _timmer = new Stopwatch();
        _timmer.Start();
    }

    public override void OnPageHandlerExecuted(PageHandlerExecutedContext context)
    {
        _timmer.Stop();
        if(context.Exception == null)
        {
            _logger.LogInformation("{RouteName} {Method} took {ElapsedMilliseconds} ms."
                , context.ActionDescriptor.RelativePath
                , context.HttpContext.Request.Method
                , _timmer.ElapsedMilliseconds);
        }
    }
}

Razor Page 改繼承自 BasePageModel

在要記錄的 Razor Page 之中，直接繼承自 BasePageModel 就可以了，例如 About Page，
About.cshtml.cs

public class AboutModel : BasePageModel
{
    public AboutModel(ILogger<AboutModel> logger) : base(logger)
    {}

    public void OnGet()
    {
        throw new Exception("this is exception from about page...");
    }
}

因為 BasePageModel 需要 ILogger 來記錄，所以在建構子時，需要將它 pass 到 base 的建構子之中。

註: 如果使用 BasePageModel 時，原本 Global 使用的 Filter ，請記得要移除設定哦!

Log for Controllers (Global Handle)

針對 Controller 的 Action ，可以實作 IActionFilter ，利用 OnActionExecuting、OnActionExecuted 來 Log。

新增 TrackActionPerformanceFilter Filter

在 RMStore.Infrastructure 專案的 Filters 目錄，新增 TrackActionPerformanceFilter.cs 實作 IActionFilter，然後在 OnActionExecuting、OnActionExecuted 透過 Stopwatch 來記錄時間，如下，
TrackPagePerformanceFilter.cs

public class TrackActionPerformanceFilter : IActionFilter
{
    private readonly ILogger<TrackActionPerformanceFilter> _logger;
    private Stopwatch _timmer;

    public TrackActionPerformanceFilter(ILogger<TrackActionPerformanceFilter> logger)
    {
        _logger = logger;
    }

    public void OnActionExecuting(ActionExecutingContext context)
    {
        _timmer = new Stopwatch();
        _timmer.Start();
    }

    public void OnActionExecuted(ActionExecutedContext context)
    {
        _timmer.Stop();
        if (context.Exception == null)
        {
            _logger.LogInformation("{RouteName} {Method} took {ElapsedMilliseconds} ms."
            , context.HttpContext.Request.Path
            , context.HttpContext.Request.Method
            , _timmer.ElapsedMilliseconds);
        }
    }
}

加入 Global Filters

到 RMStore.API 專案的 Startup.cs ，在 ConfigureServices Method 設定，如下，
Startup.cs

// other codes ...
public void ConfigureServices(IServiceCollection services)
{
    var jwtSettings = Configuration.GetSection("JWT").Get<JwtSettings>();
    // Adding Authentication  
    services.AddAuthentication(options =>
    {
        options.DefaultAuthenticateScheme = JwtBearerDefaults.AuthenticationScheme;
        options.DefaultChallengeScheme = JwtBearerDefaults.AuthenticationScheme;
        options.DefaultScheme = JwtBearerDefaults.AuthenticationScheme;
    })// Adding Jwt Bearer  
    .AddJwtBearer(options =>
    {
        options.RequireHttpsMetadata = false;
        options.TokenValidationParameters = new TokenValidationParameters()
        {
            ValidateIssuer = true,
            ValidateAudience = true,
            ValidAudience = jwtSettings.ValidAudience,
            ValidIssuer = jwtSettings.ValidIssuer,
            IssuerSigningKey = new SymmetricSecurityKey(Encoding.UTF8.GetBytes(jwtSettings.Secret))
        };
    });

    services.AddDbContext<InMemoryDbContext>(options =>
                options.UseInMemoryDatabase("rmstore"));
    services.AddScoped<IProductRepository, ProductRepository>();
    services.AddControllers(options =>
    {
        options.Filters.Add(typeof(TrackActionPerformanceFilter));
    });
}
// other codes....

註: 因為 TrackActionPerformanceFilter 在建構時，需要 ILogger ，所以這裡要使用 typeof(TrackActionPerformanceFilter) 來加入。

Log for Controllers (per Controller)

如果只要針對某些 Controller 來記錄的話，可以透過繼承 ActionFilterAttribute 來 override OnActionExecuting 及 OnActionExecuted 來記錄。

新增 ActionFilterAttribute

在 RMStore.Infrastructure 專案中新增 Attributes 目錄，並新增 TrackPerformance.cs ，然後 override OnActionExecuting, OnActionExecuted 透過 Stopwatch 來記錄時間，如下，
TrackPerformance.cs

public class TrackPerformance : ActionFilterAttribute
{
    private readonly ILogger<TrackPerformance> _logger;
    private Stopwatch _timmer;

    public TrackPerformance(ILogger<TrackPerformance> logger)
    {
        _logger = logger;
    }

    public override void OnActionExecuting(ActionExecutingContext context)
    {
        _timmer = new Stopwatch();
        _timmer.Start();
    }

    public override void OnActionExecuted(ActionExecutedContext context)
    {
        _timmer.Stop();
        if (context.Exception == null)
        {
            _logger.LogInformation("{RouteName} {Method} took {ElapsedMilliseconds} ms."
            , context.HttpContext.Request.Path
            , context.HttpContext.Request.Method
            , _timmer.ElapsedMilliseconds);
        }
    }
}

Add Attribute

ActionFilterAttribute 寫好之後，就可以在要使用的 Controller 上設定 Attribute ，例如在 WeatherForecastController 加入，
WeatherForecastController.cs

[TypeFilter(typeof(TrackPerformance))]
[ApiController]
[Route("[controller]")]
public class WeatherForecastController : ControllerBase
{
    //.... codes
}

註: 這裡一樣要使用 typeof 的方式，否則會有未提供 ILogger 的錯誤哦!

High-performance logging

前面 Log 執行時間的訊息參數是一致的，而且在記錄這些時間中，最怕的是 Log 本身就花了不少的時間，所以參考 High-performance logging with LoggerMessage in ASP.NET Core 使用 LoggerMessage.Define 來避免參數的 boxing 。

所以原本訊息為 “{RouteName} {Method} took {ElapsedMilliseconds} ms.” ，而參數的型態為 string, string 及 long 。
在 RMStore.Infrastructure 專案中新增 LogMessages.cs 來定義並新增 ILogger 的擴充方法，
LogMessages.cs

public static class LogMessages
{
    private static readonly Action<ILogger, string, string, long, Exception> _routePerformance;

    static LogMessages()
    {
        _routePerformance = LoggerMessage.Define<string, string, long>(LogLevel.Information, 0
            ,"{RouteName} {Method} took {ElapsedMilliseconds} ms.");
    }

    public static void LogRoutePerformance(this ILogger logger, string pageName, string method,
        long elapsedMilliseconds)
    {
        _routePerformance(logger, pageName, method, elapsedMilliseconds, null);
    }
}

上面的 EventId 因為我們沒有定義，所以給 0。

而原本直接使用 _logger.LogInformation ，就改成 _logger.LogRoutePerformance

_logger.LogInformation("{RouteName} {Method} took {ElapsedMilliseconds} ms."
    , context.ActionDescriptor.RelativePath
    , context.HttpContext.Request.Method
    , _timmer.ElapsedMilliseconds);

改成

1
2
3

_logger.LogRoutePerformance(context.ActionDescriptor.RelativePath
    , context.HttpContext.Request.Method
    , _timmer.ElapsedMilliseconds);

測試方案為 rainmakerho/RMStore-performancelog ，請先切到 performancelog Branch(git checkout performancelog)。

參考資料

Filter methods for Razor Pages in ASP.NET Core
High-performance logging with LoggerMessage in ASP.NET Core

jsonContent: meta: false pages: false posts: title: true date: true path: true text: false raw: false content: false slug: false updated: false comments: false link: false permalink: false excerpt: false categories: false tags: true