叡揚資訊

GSS 技術部落格

在這個園地裡我們將從技術、專案管理、客戶對談面和大家分享我們多年的經驗，希望大家不管是喜歡或是有意見，都可以回饋給我們，讓我們有機會和大家對話並一起成長！
若有任何問題請來信：gss_crm@gss.com.tw

12 分鐘閱讀時間 (2306 個字)

字體大小: + –

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

經驗分享設計 .NET

2020/09/02, 週三

4256 點擊

前言

一個系統中，Log 對於開發人員來說是非常重要的，所以在系統建置之初，我一定是先把 Log 放進去。
在 ASP.NET Core 統一透過 ILogger 來記錄 Log，至於要使用那一個 Logging Provider 則可以讓我們自由選擇。
Effective Logging in ASP.NET Core 課程提到，系統中，Log 應該保有以下幾項特性，

完整及一致的資訊
當錯誤發生時，應該要可以知道是發生在那一個 Page or Route ，參數是什麼，甚至登入者是誰。
所以，完整的資訊可以避免讓我們再詢問使用者，他做了什麼事，他是怎麼做的…
保持程式碼簡潔
我們應該不會在每個地方全都加上 try…catch ，可以的話，應該使用 Global handlers, Filters 或是 Attributes ，以避免在程式碼中寫太多的 try…catch 。
易於使用
Log 除了可讓開發人員透過文字檔查看外，應該可以提供其他的方式讓測試、開發或是營運人員查看。
減少修正問題的困難度
當錯誤發時生時，可以依 Log 提供的資訊，清楚問題所在，輕易地修正錯誤。
更了解系統
好的 Log 可以讓我們更了解我們的系統，例如記錄 API 的效能資訊，呼叫次數、平均、最長及最短時間，發現異常之處。
提供處理優先順序
有了 Log 所提供的彙總資訊，可以開發人員決定那個問題或是那個部份的效能要優先處理。

練習實作

練習方案為 rainmakerho/RMStore ，請先切到 NativeConsole Branch(git checkout NativeConsole)。

使用預設的 CONSOLE LOGGING PROVIDER

啟始專案為 RMStore.WebUI 及 RMStore.API ，透過 WebUI 登入後建立 Auth Cookie 及 Token (為了練習方便，User資訊及 JWT 設定在 appSettings.json 之中。
在呼叫 API 時，會透過 StandardHttpMessageHandler Class 從 HttpContext 取出 token 放到 Header Authorization 之中，然後取回 Products 資料。
所以過程如下，

使用 SERILOG 寫到　FILE

實際使用上，會將 Log 寫到 File or DB 之中，所以可以透過 Serilog 先將 Log 寫到檔案之中。

安裝 Serilog 相關套件

所以在方案上按下右鍵選擇「管理方案的 Nuget 套件(N)…」

將套件「Serilog.Sinks.File」、「Serilog.Settings.Configuration」及「Serilog.Extensions.Hosting」加入到 RMStore.WebUI 及 RMStore.API 專案之中。

RMStore.WebUI 使用 Serilog

public class Program

{

    public static IConfiguration Configuration { get; } = new ConfigurationBuilder()

        .SetBasePath(Directory.GetCurrentDirectory())

        .AddJsonFile("appSettings.json", optional: false, reloadOnChange: true)

        .AddEnvironmentVariables()

        .Build();

    

    public static void Main(string[] args)

    {

        Log.Logger = new LoggerConfiguration()

            .ReadFrom.Configuration(Configuration)

            .CreateLogger();

        try

        {

            Log.Information(messageTemplate: "Start Web UI Application");

            var host = CreateHostBuilder(args).Build();

            host.Run();

        }

        catch (Exception ex)

        {

            Log.Fatal(ex, messageTemplate: "WebUI App GG!");

        }

        finally

        {

            Log.CloseAndFlush();

        }

        

    }



    public static IHostBuilder CreateHostBuilder(string[] args) =>

        Host.CreateDefaultBuilder(args)

            .ConfigureWebHostDefaults(webBuilder =>

            {

                webBuilder.UseStartup<Startup>();

            }).UseSerilog();

}

Log的檔案可以在 appSettings.json 中設定，所以將原本 Logging 區段換成 Serilog ，如下，

{

  "Serilog": {

    "Using": [],

    "MinimumLevel": {

      "Default": "Debug",

      "Override": {

        "Microsoft": "Warning",

        "System": "Warning"

      }

    },

    "WriteTo": [

      {

        "Name": "File",

        "Args": {

          "path": "C:\\logs\\products.json",

          "formatter": "Serilog.Formatting.Json.JsonFormatter, Serilog",

          "shared": true

        }

      }

    ]

  },

  "AllowedHosts": "*",

  "SiteUser": {

    "UserName": "TonyHo",

    "UserId": "tony",

    "Password": "hello"

  },

  "JWT": {

    "ValidAudience": "https://localhost:44330",

    "ValidIssuer": "http://localhost:56070",

    "Secret": "hello tony, how's going!"

  }

}

RMStore.API 使用 Serilog

public class Program

{

    public static IConfiguration Configuration { get; } = new ConfigurationBuilder()

        .SetBasePath(Directory.GetCurrentDirectory())

        .AddJsonFile("appSettings.json", optional: false, reloadOnChange: true)

        .AddEnvironmentVariables()

        .Build();



    public  static void Main(string[] args)

    {



        Log.Logger = new LoggerConfiguration()

            .ReadFrom.Configuration(Configuration)

            .CreateLogger();

        try

        {

            Log.Information(messageTemplate: "Start API Application");

            var host = CreateHostBuilder(args).Build();

            //application init ...

            using (var scope = host.Services.CreateScope())

            {

                var serviceProvider = scope.ServiceProvider;

                var hostingEnvironment = serviceProvider

                    .GetRequiredService<IHostEnvironment>();

                var ctx = serviceProvider.GetRequiredService<InMemoryDbContext>();

                ctx.Database.EnsureCreated();

            }

            host.Run();

        }

        catch (Exception ex)

        {

            Log.Fatal(ex, messageTemplate: "API App GG!");

        }

        finally

        {

            Log.CloseAndFlush();

        }

    }



    public static IHostBuilder CreateHostBuilder(string[] args) =>

        Host.CreateDefaultBuilder(args)

            .ConfigureWebHostDefaults(webBuilder =>

            {

                webBuilder.UseStartup<Startup>();

            }).UseSerilog();

}

Log的檔案一樣是在 appSettings.json 中設定，如下，

{

  "Serilog": {

    "Using": [],

    "MinimumLevel": {

      "Default": "Debug",

      "Override": {

        "Microsoft": "Warning",

        "System": "Warning"

      }

    },

    "WriteTo": [

      {

        "Name": "File",

        "Args": {

          "path": "C:\\logs\\products.json",

          "formatter": "Serilog.Formatting.Json.JsonFormatter, Serilog",

          "shared": true

        }

      }

    ]

  },

  "AllowedHosts": "*",

  "JWT": {

    "ValidAudience": "https://localhost:44330",

    "ValidIssuer": "http://localhost:56070",

    "Secret": "hello tony, how's going!"

  }

}

目前 RMStore.WebUI 及 RMStore.API 都是寫到同一個 Log 檔之中，所以在 WriteTo 參數是使用 shared 為 true

RMStore.Domain 加入 Log

在 ProductRepository Class 中的 GetAllProducts Method 加入 Log ，如下，

public class ProductRepository : IProductRepository

{

    private readonly InMemoryDbContext _dbContext;

    private readonly ILogger<ProductRepository> _logger;

    public ProductRepository(InMemoryDbContext dbContext, ILogger<ProductRepository> logger)

    {

        _dbContext = dbContext;

        _logger = logger;

    }

    public List<Product> GetAllProducts(string productName)

    {

        _logger.LogInformation(message: "在 Repository 中依產品名稱取得資料");

        var collection = _dbContext.Products as IQueryable<Product>;

        if (!string.IsNullOrWhiteSpace(productName))

        {

            collection = collection.Where(

                    p => p.Name.Contains(productName));

        }

        return collection.ToList();

    }

}

執行程式

執行程式後，Log 會寫到 products.json 之中，一開始是啟動 API, WebUI 的 Log ，接著是開啟登入頁，然後登入成功後，會建立 HttpClient 呼叫 API 專案取得 Products 的資料。
整個 Log 的內容蠻完整的，MessageTemplate 中的參數會對應到 Properties ， SourceContext 為寫 Log 的所在 Class，RequestId 為那次 Http Request 的 id 。

...
{"Timestamp":"2020-08-20T14:03:42.2891986+08:00","Level":"Information","MessageTemplate":"VVV登入成功","Properties":{"SourceContext":"RMStore.WebUI.Pages.IndexModel","ActionId":"a613ba8e-ba69-457e-ba94-1165a0642280","ActionName":"/Index","RequestId":"8000005f-0003-ff00-b63f-84710c7967bb","RequestPath":"/","SpanId":"|254715eb-46afbbebfb76d979.","TraceId":"254715eb-46afbbebfb76d979","ParentId":""}}

{"Timestamp":"2020-08-20T14:03:42.4928959+08:00","Level":"Information","MessageTemplate":"{UserName}({userId}) is about to call the product api go get all products. {Claims}","Properties":{"UserName":"TonyHo","userId":"tony","Claims":["http://schemas.xmlsoap.org/ws/2005/05/identity/claims/name: TonyHo","UserId: tony"],"SourceContext":"RMStore.WebUI.Pages.ProductModel","ActionId":"ead20792-138e-4286-bd2b-6a73d7ae8ea6","ActionName":"/Product","RequestId":"80000060-0003-ff00-b63f-84710c7967bb","RequestPath":"/Product","SpanId":"|254715ec-46afbbebfb76d979.","TraceId":"254715ec-46afbbebfb76d979","ParentId":""}}

{"Timestamp":"2020-08-20T14:03:42.9200703+08:00","Level":"Information","MessageTemplate":"{userId} is inside get all products API call. {Claims}","Properties":

{"Timestamp":"2020-08-20T14:03:42.9368275+08:00","Level":"Information","MessageTemplate":"在 Repository 中依產品名稱取得資料","Properties":{"SourceContext":"RMStore.Domain.ProductRepository","ActionId":"db23a253-f0c3-4e36-aa45-d5275634a914","ActionName":"RMStore.API.Controllers.ProductController.GetProducts (RMStore.API)","RequestId":"8000004d-0001-fd00-b63f-84710c7967bb","RequestPath":"/product","SpanId":"|4f552b5b-420e6f46d95b266a.","TraceId":"4f552b5b-420e6f46d95b266a","ParentId":""}}

最後方案為 rainmakerho/RMStore-serilog ，請先切到 serilog Branch(git checkout serilog)。

處理錯誤

已將 Log 寫到實體檔案之中了，所以當發生錯誤時，可以使用 Error Page 來呈現錯誤。
而 API 專案跟 WebUI 一樣，可以使用 Middleware 來 Handle Exception。

RMStore.API 使用 Middleware 來 Handle Error

在 RMStore.API 專案中，新增 Middleware 目錄，放存到 API Error 錯誤處理的相關檔案，
ApiError.cs

public class ApiError

{

    public string Id { get; set; }

    public short Status { get; set; }

    public string Code { get; set; }

    public string Links { get; set; }

    public string Title { get; set; }

    public string Detail { get; set; }

}

ApiExceptionMiddleware.cs

public class ApiExceptionMiddleware

{

    private readonly ApiExceptionOptions _options;

    private readonly RequestDelegate _next;

    private readonly ILogger<ApiExceptionMiddleware> _logger;

    public ApiExceptionMiddleware(ApiExceptionOptions options, RequestDelegate next

        , ILogger<ApiExceptionMiddleware> logger)

    {

        _options = options;

        _next = next;

        _logger = logger;

    }



    public async Task Invoke(HttpContext context)

    {

        try

        {

            await _next(context);

        }catch (Exception ex)

        {

            await HandleExceptionAsync(context, ex);

        }

    }



    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 innerExMessage = GetInnermostExceptionMessage(exception);



        _logger.LogError(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);

    }



    private string GetInnermostExceptionMessage(Exception exception)

    {

        if (exception.InnerException != null)

            return GetInnermostExceptionMessage(exception.InnerException);

        return exception.Message;

    }

}

ApiExceptionMiddlewareExtensions.cs

public static class ApiExceptionMiddlewareExtensions

{

    public static IApplicationBuilder UseApiExceptionHandler(this IApplicationBuilder builder)

    {

        var options = new ApiExceptionOptions();

        return builder.UseMiddleware<ApiExceptionMiddleware>(options);

    }



    public static IApplicationBuilder UseApiExceptionHandler(this IApplicationBuilder builder

        , Action<ApiExceptionOptions> configureOptions)

    {

        var options = new ApiExceptionOptions();

        configureOptions(options);



        return builder.UseMiddleware<ApiExceptionMiddleware>(options);

    }

}

ApiExceptionOptions.cs

public class ApiExceptionOptions

{

    public Action<HttpContext, Exception, ApiError> AddResponseDetails { get; set; }

}

所以在 RMStore.API 的 Startup.cs 就可以使用 UseApiExceptionHandler ，app.UseDeveloperExceptionPage 就不用了哦! 如下，

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)

{

    //使用自定的 Exception Handler

    app.UseApiExceptionHandler(options => options.AddResponseDetails = UpdateApiErrorResponse);

    app.UseRouting();

    app.UseAuthentication();

    app.UseAuthorization();

    app.UseEndpoints(endpoints =>

    {

        endpoints.MapControllers();

    });

}



private void UpdateApiErrorResponse(HttpContext context, Exception ex, ApiError error)

{

    if(ex.GetType().Name == typeof(SqlException).Name)

    {

        error.Detail = "這是Database的錯誤";

    }

}

RMStore.Domain 專案中 ProductRepository 加入引發 SqlException

可以在 RMStore.Domain 專案中 ProductRepository.cs 中的 GetAllProducts ，當 productName 為 error ，就會引發 SQLException
SqlExceptionCreator.cs

//https://stackoverflow.com/questions/1386962/how-to-throw-a-sqlexception-when-needed-for-mocking-and-unit-testing
public class SqlExceptionCreator

{

    private static T Construct<T>(params object[] p)

    {

        var ctors = typeof(T).GetConstructors(BindingFlags.NonPublic | BindingFlags.Instance);

        return (T)ctors.First(ctor => ctor.GetParameters().Length == p.Length).Invoke(p);

    }



    internal static SqlException NewSqlException(int number = 1)

    {

        SqlErrorCollection collection = Construct<SqlErrorCollection>();

        SqlError error = Construct<SqlError>(number, (byte)2, (byte)3, "rm-server", "Could not find stored procedure", "proc", 100, null);

        typeof(SqlErrorCollection)

            .GetMethod("Add", BindingFlags.NonPublic | BindingFlags.Instance)

            .Invoke(collection, new object[] { error });



        return typeof(SqlException)

            .GetMethod("CreateException", BindingFlags.NonPublic | BindingFlags.Static,

                null,

                CallingConventions.ExplicitThis,

                new[] { typeof(SqlErrorCollection), typeof(string) },

                new ParameterModifier[] { })

            .Invoke(null, new object[] { collection, "7.0.0" }) as SqlException;

    }

}

ProductRepository.cs : 當輸入 error 就會有 throw 一個 SqlException

public class ProductRepository : IProductRepository

{

    private readonly InMemoryDbContext _dbContext;

    private readonly ILogger<ProductRepository> _logger;

    public ProductRepository(InMemoryDbContext dbContext, ILogger<ProductRepository> logger)

    {

        _dbContext = dbContext;

        _logger = logger;

    }

    public List<Product> GetAllProducts(string productName)

    {

        _logger.LogInformation(message: "GetAllProducts({productName})", productName);

        var collection = _dbContext.Products as IQueryable<Product>;

        if (!string.IsNullOrWhiteSpace(productName))

        {

            collection = collection.Where(

                    p => p.Name.ToLower().Contains(productName.ToLower()));

        }

        if (productName == "error")

            throw SqlExceptionCreator.NewSqlException();

        return collection.ToList();

    }



}

RMStore.WebUI 專案加入錯誤處理

RMStore.WebUI 的 Startup.cs 直接使用 UseExceptionHandler ，app.UseDeveloperExceptionPage 就不用了哦! 如下，

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
    //因為會寫 Log 所以不用 UseDeveloperExceptionPage
    app.UseExceptionHandler("/Error");
    app.UseStaticFiles();
    app.UseRouting();
    app.UseAuthentication();
    app.UseAuthorization();
    app.UseEndpoints(endpoints =>
    {
        endpoints.MapRazorPages();
    });
}

StandardHttpMessageHandler 是處理呼叫 api 的地方，所以在 RMStore.API 那會傳遞 ApiError 物件過來，所以將這些內容寫到 Exception.Data 之中，如下，

public class StandardHttpMessageHandler : DelegatingHandler

{

    private readonly HttpContext _httpContext;

    private readonly ILogger _logger;





    public StandardHttpMessageHandler(HttpContext httpContext, ILogger logger)

    {

        _httpContext = httpContext;

        _logger = logger;



        InnerHandler = new SocketsHttpHandler();

    }

    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,

        CancellationToken cancellationToken)

    {

        var token = await _httpContext.GetTokenAsync(OpenIdConnectParameterNames.AccessToken);

        request.Headers.Add("Authorization", $"Bearer {token}");

        var response = await base.SendAsync(request, cancellationToken);



        if (!response.IsSuccessStatusCode)

        {

            var jsonContent = await response.Content.ReadAsStringAsync();

            string errorId = null, errorTitle = null, errorDetail = null;

            if (!string.IsNullOrWhiteSpace(jsonContent))

            {

                var error = JObject.Parse(jsonContent);



                if (error != null)

                {

                    errorId = error["Id"]?.ToString();

                    errorTitle = error["Title"]?.ToString();

                    errorDetail = error["Detail"]?.ToString();

                }

            }



            var ex = new Exception("API Failure");



            ex.Data.Add("API Route", $"GET {request.RequestUri}");

            ex.Data.Add("API Status", (int)response.StatusCode);

            ex.Data.Add("API ErrorId", errorId);

            ex.Data.Add("API Title", errorTitle);

            ex.Data.Add("API Detail", errorDetail);



            _logger.LogWarning("API Error when calling {APIRoute}: {APIStatus}," +

                " {ApiErrorId} - {Title} - {Detail}",

                $"GET {request.RequestUri}", (int)response.StatusCode,

                errorId, errorTitle, errorDetail);

            throw ex;

        }

        return response;

    }

}

Product.cshtml.cs 處理查詢產品資料，如果輸入值為 patherror ，就會給錯誤的 url 來摸擬 url 出錯的狀況。

public class ProductModel : PageModel

{

    private readonly ILogger _logger;

    private readonly IConfiguration _configuration;

    public List<Product> Products;



    [BindProperty]

    public string ProductName { get; set; } = string.Empty;



    public ProductModel(ILogger<ProductModel> logger, IConfiguration configuration)

    {

        _logger = logger;

        _configuration = configuration;

    }

    

    public async Task OnGetAsync()

    {

        await GetProducts(ProductName);

    }



    private async Task GetProducts(string productName)

    {

        var userId = User.Claims.FirstOrDefault(c => c.Type == "UserId")?.Value;

        _logger.LogInformation(message: "{UserName}({userId}) is about to call the product api go get all products. {Claims}",

            User.Identity.Name, userId, User.Claims);

        using (var http = new HttpClient(new StandardHttpMessageHandler(HttpContext, _logger)))

        {

            var apiUrl = $"https://localhost:44330/product?productName={HttpUtility.UrlEncode(productName)}";

            if(productName.ToLower() == "patherror")

            {

                apiUrl = $"https://localhost:44330/productx?productName={HttpUtility.UrlEncode(productName)}";

            }

            var response = await http.GetAsync(apiUrl);

            var productsJson = await response.Content.ReadAsStringAsync();

            Products = JsonConvert.DeserializeObject<List<Product>>(productsJson)

                    .OrderBy(p => p.ProductID).ToList();

        }

    }



    public async Task OnPostAsync()

    {

        await GetProducts(ProductName);

    }

}

因為錯誤會導到 Error 頁面，所以可以取出 HttpContext.Features.Get() 來顯示錯誤的相關資訊，
Error.cshtml