如何利用Serilog的RequestLogging來精簡ASP.NET Core的日誌輸出

時間 2020-01-21

標籤如何利用 serilog requestlogging 精簡 asp.net asp core 日誌輸出欄目 ASP 简体版

原文原文鏈接

這是該系列的第一篇文章：在ASP.NET Core 3.0中使用Serilog.AspNetCore。html

第1部分-使用Serilog RequestLogging來簡化ASP.NET Core的日誌輸出（本篇文章）
第2部分-使用Serilog記錄所選的端點名稱[敬請期待]
第3部分-使用Serilog.AspNetCore記錄MVC屬性[敬請期待]

做者：依樂祝ios

譯文地址：http://www.javashuo.com/article/p-oltkamfa-r.htmlgit

原文地址：https://andrewlock.net/using-serilog-aspnetcore-in-asp-net-core-3-reducing-log-verbosity/github

衆所周知，ASP.NET Core的重要改變之一是把日誌記錄內置於框架中。這意味着您能夠（若是須要）從本身的標準日誌基礎設施訪問全部深層基礎設施日誌。缺點是有時您會收到太多的日誌。web

在這個簡短的系列文章中，我將介紹如何使用Serilog的ASP.NET Core請求日誌記錄功能。在第一篇文章中，我將講述如何將Serilog的RequestLoggingMiddleware添加到您的應用程序，以及它提供的好處。在後續文章中，我將描述如何進一步自定義行爲。json

我已經將這些帖子草擬了一段時間。從那時起，Serilog的建立者Nicholas Blumhardt就在ASP.NET Core 3.0中使用Serilog撰寫了一篇詳盡的博客文章。這是一篇很是詳細（至少我認爲是這樣）的文章，我強烈建議您閱讀。您能夠在他的文章中找到我在本系列文章中談論的大部份內容，因此請查看！bash

原生請求日誌

在本節中，首先讓咱們建立一個標準的ASP.NET Core 3.0的Razor pages應用，固然你也能夠直接使用dotnet new webapp命令來進行建立。這將建立一個標準Program.cs，以下所示：app

public class Program
    {
        public static void Main(string[] args)
        {
            CreateHostBuilder(args).Build().Run();
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseStartup<Startup>();
                });
    }

還有一個Startup.cs，用於配置中間件管道，Configure以下所示：框架

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
            if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
            }
            else
            {
                app.UseExceptionHandler("/Error");
                // The default HSTS value is 30 days. You may want to change this for production scenarios, see https://aka.ms/aspnetcore-hsts.
                app.UseHsts();
            }

            app.UseHttpsRedirection();
            app.UseStaticFiles();

            app.UseRouting();

            app.UseAuthorization();

            app.UseEndpoints(endpoints =>
            {
                endpoints.MapRazorPages();
            });
        }

若是您運行該應用程序並導航至主頁，則默認狀況下，您會在控制檯中看到每一個請求都會產生許多的日誌。如下日誌是針對對主頁的單個請求生成的（此後我尚未包括對CSS和JS文件的其餘請求）（這是是開發環境請求出現的日誌）：webapp

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2 GET https://localhost:5001/
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint '/Index'
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[3]
      Route matched with {page = "/Index"}. Executing page /Index
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[101]
      Executing handler method SerilogRequestLogging.Pages.IndexModel.OnGet - ModelState is Valid
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[102]
      Executed handler method OnGet, returned result .
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[103]
      Executing an implicit handler method - ModelState is Valid
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[104]
      Executed an implicit handler method, returned result Microsoft.AspNetCore.Mvc.RazorPages.PageResult.
info: Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker[4]
      Executed page /Index in 221.07510000000002ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint '/Index'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 430.9383ms 200 text/html; charset=utf-8

單個請求就是10條日誌。如今，很清楚，它正在Development環境中運行，該環境默認狀況下將Microsoft名稱空間中的全部信息記錄在「Information」或更高的級別。若是咱們切換到Production環境，則默認模板會將Microsoft命名空間的日誌過濾到「Warning」。如今導航到默認主頁會生成如下日誌（這裏注意，若是你如今使用ASP.NET Core3.1貌似Microsoft命名空間默認日誌級別已經改成Warning）：

是的，根本沒有日誌！上一次運行中生成的全部日誌都位於Microsoft命名空間中，而且屬於「Information」級別，所以將它們所有過濾掉。就我的而言，我以爲這有點麻煩。若是生產版本僅僅只是想記錄一部份內容，而其餘相關聯的內容則不進行記錄，這將會更有用的。

一種可能的解決方案是自定義應用於每一個命名空間的過濾器。例如，您能夠將Microsoft.AspNetCore.Mvc.RazorPages命名空間限制爲「Warning」級別，而將更通用的Microsoft命名空間保留爲「Information」級別。如今，您將得到精簡後的日誌集：

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2 GET https://localhost:5001/
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint '/Index'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint '/Index'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 184.788ms 200 text/html; charset=utf-8

這些日誌中包含一些有用的信息-URL，HTTP方法，時間信息，端點等-而且沒有太多冗餘。可是，仍然使人討厭的是它們是四個單獨的日誌消息。（仍是不少，若是能精簡成一條日誌記錄是否是會好不少）

這是Serilog RequestLoggingMiddleware旨在解決的問題-爲請求中的每一個步驟建立單獨的日誌相反，它是建立一個包含全部相關信息的「摘要」日誌消息。

將Serilog添加到應用程序

使用Serilog RequestLoggingMiddleware 的一個前提條件就是您正在使用Serilog！在本節中，我將介紹將Serilog添加到ASP.NET Core應用程序中。若是您已經安裝了Serilog，請跳至下一部分。

首先安裝Serilog.AspNetCore NuGet軟件包，再加上控制檯和Seq接收器【這是一個漂亮的可視化日誌UI】，以便咱們能夠查看日誌。您能夠經過運行如下命令從命令行執行此操做：

dotnet add package Serilog.AspNetCore
dotnet add package Serilog.Sinks.Seq

如今該用Serilog替換默認日誌了。您能夠經過多種方式執行此操做，可是建議的方法是在Program.Main 執行其餘任何操做以前先配置記錄器。這與ASP.NET Core一般使用的方法背道而馳，但建議用於Serilog。結固然這會致使您的的Program.cs文件變得更長：

// Additional required namespaces
using Serilog;
using Serilog.Events;

namespace SerilogDemo
{
    public class Program
    {
        public static void Main(string[] args)
        {
            // Create the Serilog logger, and configure the sinks
            Log.Logger = new LoggerConfiguration()
               .MinimumLevel.Debug()
               .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
               .Enrich.FromLogContext()
               .WriteTo.Console()
               .WriteTo.Seq("http://localhost:5341")
               .CreateLogger();
            // Wrap creating and running the host in a try-catch block
            try
            {
                Log.Information("Starting host");
                CreateHostBuilder(args).Build().Run();
            }
            catch (Exception ex)
            {
                Log.Fatal(ex, "Host terminated unexpectedly");
            }
            finally
            {
                Log.CloseAndFlush();
            }
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .UseSerilog()
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseStartup<Startup>();
                });
    }
}

儘管這樣設置可能顯得更爲複雜，可是此設置可確保例如在appsettings.json文件格式錯誤或缺乏配置文件的狀況下仍會獲取日誌。若是如今運行您的應用程序，您將看到與咱們最初相同的10條日誌，只是格式略有不一樣：

[13:30:27 INF] Request starting HTTP/2 GET https://localhost:5001/  
[13:30:27 INF] Executing endpoint '/Index'
[13:30:27 INF] Route matched with {page = "/Index"}. Executing page /Index
[13:30:27 INF] Executing handler method SerilogRequestLogging.Pages.IndexModel.OnGet - ModelState is Valid
[13:30:27 INF] Executed handler method OnGet, returned result .
[13:30:27 INF] Executing an implicit handler method - ModelState is Valid
[13:30:27 INF] Executed an implicit handler method, returned result Microsoft.AspNetCore.Mvc.RazorPages.PageResult.
[13:30:27 INF] Executed page /Index in 168.28470000000002ms
[13:30:27 INF] Executed endpoint '/Index'
[13:30:27 INF] Request finished in 297.0663ms 200 text/html; charset=utf-8

如今，經過在應用程序生命週期的早期進行配置，咱們的日誌記錄配置的更加健壯，但實際上還沒有解決咱們提出的問題。爲此，咱們將添加RequestLoggingMiddleware。

切換到Serilog的 `RequestLoggingMiddleware`

RequestLoggingMiddleware被包含在Serilog.AspNetCore中，能夠被用於爲每一個請求添加一個單一的「摘要」日誌消息。若是您已經完成了上一節中的步驟，則添加這個中間件將變得很簡單。在您的Startup類中，在您想要記錄日誌的位置使用UseSerilogRequestLogging()進行調用：

// Additional required namespace
using Serilog;

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
    // ... Error handling/HTTPS middleware
    app.UseStaticFiles();

    app.UseSerilogRequestLogging(); // <-- Add this line

    app.UseRouting();
    app.UseAuthorization();
    app.UseEndpoints(endpoints =>
    {
        endpoints.MapRazorPages();
    });
}

與ASP.NET Core的中間件管道同樣，順序很重要。當請求到達RequestLoggingMiddleware中間件時，它將啓動計時器，並將請求傳遞給後續中間件進行處理。當後面的中間件最終生成響應（或拋出異常），則響應經過中間件管道傳遞回到請求記錄器，並在其中記錄告終果並寫入概要日誌信息。

Serilog只能記錄到達中間件的請求。在上面的例子中，我已經在StaticFilesMiddleware以後添加了RequestLoggingMiddleware 。所以若是請求被UseStaticFiles處理並使管道短路的話，日誌將不會被記錄。鑑於靜態文件中間件很是嘈雜，並且一般這是人們指望的行爲（靜態文件進行短路，不須要進行記錄），可是若是您也但願記錄對靜態文件的請求，則能夠在管道中serilog中間件移動到更早的位置。

若是咱們再一次運行該應用程序，你仍是會看到原來的10個日誌消息，但你會看到一個額外的經過SerilogRequestLoggingMiddleware彙總的日誌消息，倒數第二的消息：

# Standard logging from ASP.NET Core infrastructure
[14:15:44 INF] Request starting HTTP/2 GET https://localhost:5001/  
[14:15:44 INF] Executing endpoint '/Index'
[14:15:45 INF] Route matched with {page = "/Index"}. Executing page /Index
[14:15:45 INF] Executing handler method SerilogRequestLogging.Pages.IndexModel.OnGet - ModelState is Valid
[14:15:45 INF] Executed handler method OnGet, returned result .
[14:15:45 INF] Executing an implicit handler method - ModelState is Valid
[14:15:45 INF] Executed an implicit handler method, returned result Microsoft.AspNetCore.Mvc.RazorPages.PageResult.
[14:15:45 INF] Executed page /Index in 124.7462ms
[14:15:45 INF] Executed endpoint '/Index'

# Additional Log from Serilog
[14:15:45 INF] HTTP GET / responded 200 in 249.6985 ms

# Standard logging from ASP.NET Core infrastructure
[14:15:45 INF] Request finished in 274.283ms 200 text/html; charset=utf-8

關於此日誌，有幾點須要說明下：

它在一條消息中包含您想要的大多數相關信息-HTTP方法，URL路徑，狀態代碼，持續時間。
顯示的持續時間略短於Kestrel在後續消息中記錄的值。這是能夠預期的，由於Serilog僅在請求到達其中間件時纔開始計時，而在返回時中止計時（在生成響應以後）。
在這兩種狀況下，使用結構日誌記錄時都會記錄其餘值。例如，記錄了RequestId和SpanId（用於跟蹤功能），由於它們是日誌記錄範圍的一部分。您能夠在登陸到seq的請求的如下圖像中看到這一點。
默認狀況下，咱們確實會丟失一些信息。例如，再也不記錄終結點名稱和Razor頁面處理程序。在後續文章中，我將展現如何將它們添加到摘要日誌中。
若是想要經過``http://localhost:5341 訪問UI，你可能須要下載seq進行安裝。因爲某種不知名的緣由，可能下載會很慢。因此固然你也能夠關注公衆號「DotNetCore實戰」而後回覆關鍵字「seq」獲取下載地址。

完成整理工做所剩下的就是過濾掉咱們當前正在記錄的信息級日誌消息。在Program.cs中更新Serilog配置以添加額外的過濾器：

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
    // Filter out ASP.NET Core infrastructre logs that are Information and below
    .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning) 
    .Enrich.FromLogContext()
    .WriteTo.Console()
    .WriteTo.Seq("http://localhost:5341")
    .CreateLogger();

經過最後的更改，您如今將得到一組乾淨的請求日誌，其中包含每一個請求的摘要數據：

[14:29:53 INF] HTTP GET / responded 200 in 129.9509 ms
[14:29:56 INF] HTTP GET /Privacy responded 200 in 10.0724 ms
[14:29:57 INF] HTTP GET / responded 200 in 3.3341 ms
[14:30:54 INF] HTTP GET /Missing responded 404 in 16.7119 ms

在下一篇文章中，我將介紹如何經過記錄其餘數據來加強此日誌。

摘要

在本文中，我描述瞭如何使用Serilog.AspNetCore的請求日誌記錄中間件來減小爲每一個ASP.NET Core請求生成的日誌數，同時仍記錄摘要數據。若是您已經在使用Serilog，則很是容易啓用。只需在您的Startup.cs文件中調用UseSerilogRequestLogging()。

當請求到達此中間件時，它將啓動計時器。當後續的中間件生成響應（或引起異常）時，響應將經過中間件管道返回到請求記錄器，記錄器記錄結果並編寫摘要日誌消息。

添加請求日誌記錄中間件以後，您能夠過濾掉默認狀況下在ASP.NET Core 3.0中生成的更多基礎結構日誌，而不會丟失有用的信息。