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

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

原生请求日志

将Serilog添加到应用程序

切换到Serilog的 RequestLoggingMiddleware

摘要

切换到Serilog的 `RequestLoggingMiddleware`