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

前言

前幾篇從 有效地使用 ASP.NET Core Logging - 1 介紹使用 Serilog 來記錄，並加入錯誤的處理。
有效地使用 ASP.NET Core Logging - 2 透過 Filter 去記錄每個 Page, Action 的執行時間。
在 log 中有些內容是每個訊息最好要提供的，例如機器名稱、使用者資訊。這些共通的資料我們可以透過 BeginScope 來將這些資料記錄下來。

練習實作

記錄共通要 Log 的資料

使用 ScopeInformation 來記錄共通要 Log 的資料

因為要記錄共通的資料，所以在 RMStore.Infrastructure 專案，新增 IScopeInformation interface 及實作它的 ScopeInformation Class。
HostScopeInfo 屬性提供 MachineName 及 EntryPoint ， GetUserScopeInfo Method 則透過 ClaimsPrincipal 來取得使用者的資訊。

ScopeInformation.cs

public interface IScopeInformation
{
    Dictionary<string, string> HostScopeInfo { get; }

    Dictionary<string, string> GetUserScopeInfo(ClaimsPrincipal user);
}

public class ScopeInformation : IScopeInformation
{
    public Dictionary<string, string> HostScopeInfo { get; }

    public ScopeInformation()
    {
        HostScopeInfo = new Dictionary<string, string>()
        {
            {"MachineName", Environment.MachineName },
            {"EntryPoint", Assembly.GetEntryAssembly().GetName().Name }
        };
    }

    public Dictionary<string, string> GetUserScopeInfo(ClaimsPrincipal user)
    {
        var userDict = new Dictionary<string, string>
        {
            {"UserId", user.Claims.FirstOrDefault(c => c.Type == "UserId")?.Value },
            {"UserName", user.Claims.FirstOrDefault(c => c.Type == ClaimTypes.Name)?.Value },
            {"Email", user.Claims.FirstOrDefault(c => c.Type == ClaimTypes.Email)?.Value }
        };
        return userDict;
    }
}

ILogger.BeginScope

在 RMStore.Infrastructure 專案中的 Filters, BasePage 及 Attribute 中加入 BeginScope 程式碼，以 TrackActionPerformanceFilter.cs 為例，
在建構子中注入 IScopeInformation，並宣告 2 個 IDisposable (_userScope, _hostScope) 及 1 個 IScopeInformation (_scopeInfo)。
在 OnActionExecuting 使用 BeginScope ，在 OnActionExecuted Dispose 它們。

public class TrackActionPerformanceFilter : IActionFilter
{
    private readonly ILogger<TrackActionPerformanceFilter> _logger;
    private Stopwatch _timmer;
    private readonly IScopeInformation _scopeInfo;
    private IDisposable _userScope;
    private IDisposable _hostScope;

    public TrackActionPerformanceFilter(ILogger<TrackActionPerformanceFilter> logger,
        IScopeInformation scopeInfo)
    {
        _logger = logger;
        _scopeInfo = scopeInfo;
    }

    public void OnActionExecuting(ActionExecutingContext context)
    {
        _timmer = new Stopwatch();
        _timmer.Start();
        _userScope = _logger.BeginScope(_scopeInfo.GetUserScopeInfo(context.HttpContext.User));
        _hostScope = _logger.BeginScope(_scopeInfo.HostScopeInfo);
    }

    public void OnActionExecuted(ActionExecutedContext context)
    {
        _timmer.Stop();
        if (context.Exception == null)
        {
            _logger.LogRoutePerformance(context.HttpContext.Request.Path
            , context.HttpContext.Request.Method
            , _timmer.ElapsedMilliseconds);
        }
        _userScope?.Dispose();
        _hostScope?.Dispose();
    }
}

ApiExceptionMiddleware.cs 也同樣要加入 BeginScope 。

ConfigureServices

在 WebUI 及 API 專案的 Startup.cs 的 ConfigureServices Method 中，設定 IScopeInformation

public void ConfigureServices(IServiceCollection services)
{
    services.AddSingleton<IScopeInformation, ScopeInformation>();
    // other codes....
}

執行後就可以發現在 Log 的後面，會多加入 Scope 的資訊，

在 WebUI 的錯誤訊息中是沒有 Scope 資訊的，所以可以從 Error Page 中的 Request Path 去對應它，如下，

遮掩敏感資料

針對敏感資料需要進行遮蓋才可以 Log 起來，例如 Email ，所以可以參考 ASP.NET Core – Effective Logging Github 將 Email mask 過。
所以調整 ScopeInformation Class ，在設定 Email 時，先呼叫 MaskEmailAddress ，讓 Email 只顯示前2個字，其餘的設定為 * ，如下，

public class ScopeInformation : IScopeInformation
{
    public Dictionary<string, string> HostScopeInfo { get; }

    public ScopeInformation()
    {
        HostScopeInfo = new Dictionary<string, string>()
        {
            {"MachineName", Environment.MachineName },
            {"EntryPoint", Assembly.GetEntryAssembly().GetName().Name }
        };
    }

    public Dictionary<string, string> GetUserScopeInfo(ClaimsPrincipal user)
    {
        var maskedEmail = MaskEmailAddress(user.Claims.FirstOrDefault(c => c.Type == ClaimTypes.Email)?.Value);
        var userDict = new Dictionary<string, string>
        {
            {"UserId", user.Claims.FirstOrDefault(c => c.Type == "UserId")?.Value },
            {"UserName", user.Claims.FirstOrDefault(c => c.Type == ClaimTypes.Name)?.Value },
            {"Email", maskedEmail }
        };
        return userDict;
    }

    private string MaskEmailAddress(string emailAddress)
    {
        var atIndex = emailAddress?.IndexOf('@');
        if (atIndex > 1)
        {
            return string.Format("{0}{1}***{2}", emailAddress[0], emailAddress[1],
                emailAddress.Substring(atIndex.Value));
        }
        return emailAddress;
    }
}

決定 LogLevel

目前的 Excepiton 我們是使用 LogError ，但是有些錯誤它的 LogLevel 需要更高，那要如何決定它是 Error or Critical，可以交由使用的系統來決定。

ApiExceptionOptions Class Add DetermineLogLevel

可以像原本 AddResponseDetails 一樣，在 ApiExceptionOptions Class 新增一個 Func<Exception, LogLevel> 來讓系統決定 LogLevel ，如下，

public class ApiExceptionOptions
{
    public Action<HttpContext, Exception, ApiError> AddResponseDetails { get; set; }
    public Func<Exception, LogLevel> DetermineLogLevel { get; set; }
}

從 DetermineLogLevel 取得 LogLevel

在 ApiExceptionMiddleware.cs 的 HandleExceptionAsync 要將原本直接 LogError 改成從 DetermineLogLevel 取得

private Task HandleExceptionAsync(HttpContext context, Exception exception)
{
    var error = new ApiError
    {
        Id = Guid.NewGuid().ToString(),
        Status = (short)HttpStatusCode.InternalServerError,
        Title = "api 發生錯誤，請洽管理人員"
    };
    _options.AddResponseDetails?.Invoke(context, exception, error);
    var level = _options.DetermineLogLevel?.Invoke(exception) ?? LogLevel.Error;
    var innerExMessage = GetInnermostExceptionMessage(exception);

    using (_logger.BeginScope(_scopeInfo.GetUserScopeInfo(context.User)))
    using (_logger.BeginScope(_scopeInfo.HostScopeInfo))
    {
        //_logger.LogError(exception, "api 發生錯誤!!! " + innerExMessage + " --{ErrorId}.", error.Id);
        _logger.Log(level, exception, "api 發生錯誤!!! " + innerExMessage + " --{ErrorId}.", error.Id);
    }
    var result = JsonConvert.SerializeObject(error);
    context.Response.ContentType = "application/json";
    context.Response.StatusCode = (int)HttpStatusCode.InternalServerError;
    return context.Response.WriteAsync(result);
}

依錯誤來決定 LogLevel

在 API 專案的 Startup.cs 中的 Configure 設定 UseApiExceptionHandler 就可以多設定 DetermineLogLevel，

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
    //使用自定的 Exception Handler
    app.UseApiExceptionHandler(options => { 
        options.AddResponseDetails = UpdateApiErrorResponse;
        options.DetermineLogLevel = DetermineLogLevel;
    });
    // other codes ...
}
private LogLevel DetermineLogLevel(Exception ex)
{
    if (ex.Message.StartsWith("cannot open database", StringComparison.InvariantCultureIgnoreCase) )
    {
        return LogLevel.Critical;
    }
    return LogLevel.Error;
}

所以當 api 有錯誤時，會依不同的訊息而有不同的 LogLevel，

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

目前 Log 是寫到 File 之中，如果在不同的機器或是系統，這些檔案是不容易整合，也不容易去查詢，而且對使用者來說，也缺少 UI。 所以接下來就是將 Log 寫 Seq、ELK 等系統之中，以方便使用者查詢及 Alert。

參考資料

How to include scopes when logging exceptions in ASP.NET Core