如何利用Serilog的RequestLogging来精简ASP.NET Core的日志输出

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

Serilog RequestLogging

作者：依乐祝

译文地址： https://www.cnblogs.com/yilezhu/p/12215934.html

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

众所周知，ASP.NET Core的重要改变之一是把日志记录内置于框架中。这意味着您可以（如果需要）从自己的标准日志基础设施访问所有深层基础设施日志。缺点是有时您会收到 太多 的日志。

在这个简短的系列文章中，我将介绍如何使用 Serilog的ASP.NET Core请求日志记录功能 。在第一篇文章中，我将讲述如何将Serilog的 RequestLoggingMiddleware 添加到您的应用程序，以及它提供的好处。在后续文章中，我将描述如何进一步自定义行为。

我已经将这些帖子草拟了一段时间。从那时起， Serilog的创建者Nicholas Blumhardt就在ASP.NET Core 3.0中使用Serilog撰写了一篇详尽的博客文章 。这是一篇非常详细（至少我认为是这样）的文章，我强烈建议您阅读。您可以在他的文章中找到我在本系列文章中谈论的大部分内容，所以请查看！

原生请求日志

在本节中，首先让我们创建一个标准的ASP.NET Core 3.0的Razor pages应用，当然你也可以直接使用 dotnet new webapp 命令来进行创建。这将创建一个标准 Program.cs ，如下所示：

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文件的其他请求）（这是是开发环境请求出现的日志）：

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个日志消息，但你会看到一个 额外的 通过Serilog RequestLoggingMiddleware 汇总的日志消息，倒数第二的消息：

# 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中生成的更多基础结构日志，而不会丢失有用的信息。