Serilog在 ASP.NET CORE的使用

原创
2021/01/09 08:39
阅读数 938

初始化

要用Serilog替换原生的Log,需要做如下配置:

添加Nuget:

dotnet add package Serilog.AspNetCore

修改Main方法

public static void Main(string[] args)
{
  Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Information()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
    .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)
    .Enrich.FromLogContext()
    .WriteTo.Console()
    .CreateLogger();
  try
  {
    Log.Information("Starting web host");
    CreateHostBuilder(args).Build().Run();
  }
  catch (Exception ex)
  {
    Log.Fatal(ex, "Host terminated unexpectedly");
  }
  finally
  {
    Log.Information("Ending web host");
    Log.CloseAndFlush();
  }
}

UseSerilog()

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

经过这两处修改,就完成了用Serilog对原生的Log的替换。

主动记录日志

在需要记录日志的地方通过这样的代码可以获得log实例

private readonly ILogger log = Log.Logger;

Serilog定义的日志级别有:

  • Verbose
  • Debug
  • Information
  • Warning
  • Error
  • Fatal

原生log和Serilog的输出对比

在Web API模版项目中,LogLeve为默认"Microsoft": "Information"的情况下,针对一次API请求:对比下原生log和Serilog的输出: 原生Log:

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast  
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'SerilogTest.Controllers.WeatherForecastController.Get (SerilogTest)'
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
      Route matched with {action = "Get", controller = "WeatherForecast"}. Executing controller action with signature System.Collections.Generic.IEnumerable`1[SerilogTest.WeatherForecast] Get() on controller SerilogTest.Controllers.WeatherForecastController (SerilogTest).
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'SerilogTest.WeatherForecast[]'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action SerilogTest.Controllers.WeatherForecastController.Get (SerilogTest) in 21.2528ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'SerilogTest.Controllers.WeatherForecastController.Get (SerilogTest)'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 102.3501ms 200 application/json; charset=utf-8

Serilog:

[22:12:13 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast  
[22:12:13 INF] Executing endpoint 'SerilogTest.Controllers.WeatherForecastController.Get (SerilogTest)'
[22:12:13 INF] Route matched with {action = "Get", controller = "WeatherForecast"}. Executing controller action with signature System.Collections.Generic.IEnumerable`1[SerilogTest.WeatherForecast] Get() on controller SerilogTest.Controllers.WeatherForecastController (SerilogTest).
[22:12:13 INF] Executing ObjectResult, writing value of type 'SerilogTest.WeatherForecast[]'.
[22:12:13 INF] Executed action SerilogTest.Controllers.WeatherForecastController.Get (SerilogTest) in 22.6404ms
[22:12:13 INF] Executed endpoint 'SerilogTest.Controllers.WeatherForecastController.Get (SerilogTest)'
[22:12:13 INF] Request finished in 104.071ms 200 application/json; charset=utf-8

两者Log数量都是7条,Serilog相比原生log增加了时间信息,但缺少了输出日志组件的名称,整体来看Serilog的日志要更加紧凑。

使用RequestLoggingMiddleware

每次API请求都输出这么多日志信息,其中很多信息都是不被关心的,这些信息不仅会妨碍对有用信息的查找,还会为日志的存储造成负担。Serilog提供的RequestLogging中间件可以为每个请求记录一条单一的摘要日志。 首先,添加中间件:app.UseSerilogRequestLogging()

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
  if (env.IsDevelopment())
  {
    app.UseDeveloperExceptionPage();
  }
  app.UseSerilogRequestLogging();
  ...

与管道中的其他中间件一样,顺序很重要。当请求到达RequestLoggingMiddleware中间件时,它将启动计时器,并将请求传递给后续中间件进行处理。当后面的中间件最终生成响应(或抛出异常),则响应通过中间件管道传递回到请求记录器,并在其中记录了结果并输出日志。所以这个中间件要放在尽量靠前的位置。

输出效果

倒数第二条日志就是RequestLoggingMiddleware输出的

[11:25:43 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast  
[11:25:43 INF] Executing endpoint 'SerilogTest.Controllers.WeatherForecastController.Get (SerilogTest)'
[11:25:43 INF] Route matched with {action = "Get", controller = "WeatherForecast"}. Executing controller action with signature System.Collections.Generic.IEnumerable`1[SerilogTest.WeatherForecast] Get() on controller SerilogTest.Controllers.WeatherForecastController (SerilogTest).
[11:25:43 INF] Executing ObjectResult, writing value of type 'SerilogTest.WeatherForecast[]'.
[11:25:43 INF] Executed action SerilogTest.Controllers.WeatherForecastController.Get (SerilogTest) in 22.9249ms
[11:25:43 INF] Executed endpoint 'SerilogTest.Controllers.WeatherForecastController.Get (SerilogTest)'
[11:25:43 INF] HTTP GET /weatherforecast responded 200 in 172.8042 ms
[11:25:43 INF] Request finished in 184.1417ms 200 application/json; charset=utf-8

有了RequestLoggingMiddleware输出的日志,就可以关闭系统记录的Information级别的日志了,这可以通过在Program.cs中设置LoggerConfiguration时增加MinimumLevel.Override("Microsoft", LogEventLevel.Warning)过滤器来实现:

Log.Logger = new LoggerConfiguration()
  .MinimumLevel.Information()
  .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
  .Enrich.FromLogContext()
  .WriteTo.Console()
  .CreateLogger();

之后就只会输出一条日志:

[11:25:43 INF] HTTP GET /weatherforecast responded 200 in 172.8042 ms

输出Json格式

作为一款结构化日志组件,对Json格式的支持也是必不可少的,Serilog支持如下四种渲染方式:

  • JsonFormatter
  • JsonFormatter(renderMessage: true)
  • CompactJsonFormatter
  • RenderedCompactJsonFormatter

可以在配置LoggerConfiguration时开启Json输出,这里把文本格式+四种Json格式都开启,对比下它们之间的差异

Log.Logger = new LoggerConfiguration()
  .MinimumLevel.Information()
  .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
  .Enrich.FromLogContext()
  .WriteTo.Console()
  .WriteTo.Console(new JsonFormatter())
  .WriteTo.Console(new JsonFormatter(renderMessage: true))
  .WriteTo.Console(new CompactJsonFormatter())
  .WriteTo.Console(new RenderedCompactJsonFormatter())
  .CreateLogger();

对比

// 文本
[12:58:08 INF] GET /weatherforecast responsed 200 in 60.439784 ms, localhost:5000, application/json; charset=utf-8, 1423

// JsonFormatter
{
	"Timestamp": "2020-12-27T12:58:08.2277150+08:00",
	"Level": "Information",
	"MessageTemplate": "{RequestMethod} {RequestPath} responsed {StatusCode} in {Elapsed} ms, {RequestHost}, {ContentType}, {DataLoadTime}",
	"Properties": {
		"DataLoadTime": 1423,
		"RequestHost": "localhost:5000",
		"ContentType": "application/json; charset=utf-8",
		"RequestMethod": "GET",
		"RequestPath": "/weatherforecast",
		"StatusCode": 200,
		"Elapsed": 60.439784,
		"SourceContext": "Serilog.AspNetCore.RequestLoggingMiddleware",
		"RequestId": "0HM5A4G0BVC68:00000001",
		"SpanId": "|dbf998b9-4418b3255ee44f3e.",
		"TraceId": "dbf998b9-4418b3255ee44f3e",
		"ParentId": "",
		"ConnectionId": "0HM5A4G0BVC68"
	}
}

// JsonFormatter(renderMessage: true)
{
	"Timestamp": "2020-12-27T12:58:08.2277150+08:00",
	"Level": "Information",
	"MessageTemplate": "{RequestMethod} {RequestPath} responsed {StatusCode} in {Elapsed} ms, {RequestHost}, {ContentType}, {DataLoadTime}",
	"RenderedMessage": "\"GET\" \"/weatherforecast\" responsed 200 in 60.439784 ms, \"localhost:5000\", \"application/json; charset=utf-8\", 1423",
	"Properties": {
		"DataLoadTime": 1423,
		"RequestHost": "localhost:5000",
		"ContentType": "application/json; charset=utf-8",
		"RequestMethod": "GET",
		"RequestPath": "/weatherforecast",
		"StatusCode": 200,
		"Elapsed": 60.439784,
		"SourceContext": "Serilog.AspNetCore.RequestLoggingMiddleware",
		"RequestId": "0HM5A4G0BVC68:00000001",
		"SpanId": "|dbf998b9-4418b3255ee44f3e.",
		"TraceId": "dbf998b9-4418b3255ee44f3e",
		"ParentId": "",
		"ConnectionId": "0HM5A4G0BVC68"
	}
}

// CompactJsonFormatter
{
	"@t": "2020-12-27T04:58:08.2277150Z",
	"@mt": "{RequestMethod} {RequestPath} responsed {StatusCode} in {Elapsed} ms, {RequestHost}, {ContentType}, {DataLoadTime}",
	"DataLoadTime": 1423,
	"RequestHost": "localhost:5000",
	"ContentType": "application/json; charset=utf-8",
	"RequestMethod": "GET",
	"RequestPath": "/weatherforecast",
	"StatusCode": 200,
	"Elapsed": 60.439784,
	"SourceContext": "Serilog.AspNetCore.RequestLoggingMiddleware",
	"RequestId": "0HM5A4G0BVC68:00000001",
	"SpanId": "|dbf998b9-4418b3255ee44f3e.",
	"TraceId": "dbf998b9-4418b3255ee44f3e",
	"ParentId": "",
	"ConnectionId": "0HM5A4G0BVC68"
}

// RenderedCompactJsonFormatter
{
	"@t": "2020-12-27T04:58:08.2277150Z",
	"@m": "\"GET\" \"/weatherforecast\" responsed 200 in 60.439784 ms, \"localhost:5000\", \"application/json; charset=utf-8\", 1423",
	"@i": "54a66a75",
	"DataLoadTime": 1423,
	"RequestHost": "localhost:5000",
	"ContentType": "application/json; charset=utf-8",
	"RequestMethod": "GET",
	"RequestPath": "/weatherforecast",
	"StatusCode": 200,
	"Elapsed": 60.439784,
	"SourceContext": "Serilog.AspNetCore.RequestLoggingMiddleware",
	"RequestId": "0HM5A4G0BVC68:00000001",
	"SpanId": "|dbf998b9-4418b3255ee44f3e.",
	"TraceId": "dbf998b9-4418b3255ee44f3e",
	"ParentId": "",
	"ConnectionId": "0HM5A4G0BVC68"
}
Formatter 特征
JsonFormatter 基础的Json格式,只有模版,没有日志全文
JsonFormatter(renderMessage: true) 相比JsonFormatter增加了RenderedMessage节点存储日志全文
CompactJsonFormatter 相比JsonFormatter,缩短了属性名,比如用@t代替Timestamp
RenderedCompactJsonFormatter 相比CompactJsonFormatter,有日志全文(@m),不再包含日志模版

Serilog默认只输出了如下几方面的信息:

  • RequestMethod:GET
  • RequestPath:/weatherforecast
  • StatusCode:200
  • Elapsed:172.8042 ms

日志虽然足够精简,但相比系统Log也缺少了一些有用的信息。后面Enrichment一节将介绍扩展的方法。

结构化日志

Serilog用Json格式来表示结构化日志。记录日志时使用类似C#字符串模版的方式。

默认格式

值类型、string、基于值类型或string的集合和Dictionary会被存储为Json对象的一个属性,比如:

var count = 333;
Log.Error("Retrieved {Count} records", count);

var c = new List<string> {"a", "b"};
Log.Information("list is {List}", c);

会被分别存储为:

{
	...
	"Count":333
	...
}
{
	...
	"List":["a","b"]
	...
}

@运算符

如果要记录的是一个class的实例,用上面的记录方式会强制调用ToString方法,并不会拿到内部属性的值。所以对于除值类型和基于值类型的集合、Dictionary之外的数据结构,应该使用@运算符,将这个实例内部的值存储为Json对象

var dto = new FakeDTO { A = "A",B="B"};
Log.Information("test is {FakeDTO}", dto);
// 输出:"FakeDTO":"SerilogTest.Controllers.FakeDTO"
Log.Information("test is {@FakeDTO}", dto);
// 输出:,"FakeDTO":{"A":"A","B":"B","C":null,"D":null,"E":null,"$type":"FakeDTO"}

...

public class FakeDTO
{
  public string A { get; set; }
  public string B { get; set; }
  public string C { get; set; }
  public string D { get; set; }
  public string E { get; set; }
}

自定义要保存的属性

@运算符虽然可以将类转化为Json,但如果只需要记录类中的一部分属性,比如FakeDTO只对其A和B感兴趣,可以通过在LoggerConfiguration中配置Destructure来让Json中只包含需要的属性。

Log.Logger = new LoggerConfiguration()
        ...
        .Destructure.ByTransforming<FakeDTO>(r => new {A1 = r.A, B1 = r.B})

// 输出:"FakeDTO":{"A1":"A","B1":"B"}

关于性能的注意事项

尽量使用模版的方式,而不是由自己拼接日志内容:

// Do:
Log.Information("The time is {Now}", DateTime.Now);

// Don't:
Log.Information("The time is " + DateTime.Now);

这两种方式可能在性能上会有差别,比如当提高到Log级别限制为Warning后,即使Info级别的日志不再被输出,后者仍然会执行拼接字符串的操作,而模版方式不会出现这样的问题,在日志记录较多的场合,两者将会有明显的性能差距。

Enrichment

Serilog也提供了通过Enricher扩展其请求日志信息的方法。

列举部分Enrichers

Enricher Usage
Serilog.Enrichers.Thread WithThreadId()
Serilog.Enrichers.Environment WithMachineName() and WithEnvironmentUserName()
Serilog.Enrichers.Process WithProcessId()
Serilog.Web.Classic WithHttpRequestId()
Serilog.Exceptions WithExceptionDetails()
Serilog.Enrichers.Demystify WithDemystifiedStackTraces()
Serilog.Enrichers.CorrelationId WithCorrelationId
Serilog.Enrichers.ClientInfo WithClientIp() and WithClientAgent()

要使用这些Enricher,需要在配置LoggerConfiguration的时候添加,比如:

Log.Logger = new LoggerConfiguration()
  .Enrich.WithThreadId()
  ...

自定义要扩展信息

使用Enrich.WithProperty可以更灵活地添加扩展信息,比如添加IP地址,然后在记Log的地方通过{IP}模版就可以拿到了。

.Enrich.WithProperty("IP", "127.0.0.1")

为RequestLog添加扩展信息

除了使用Serilog已经提供的Enrichers,还可以通过在引入使用RequestLoggingMiddleware时增加如下配置:

app.UseSerilogRequestLogging(options =>
{
  // Customize the message template
  options.MessageTemplate = "{RequestMethod} {RequestPath} responsed {StatusCode} in {Elapsed} ms, {RequestHost}, {ContentType}";

  // Attach additional properties to the request completion event
  options.EnrichDiagnosticContext = (diagnosticContext, httpContext) =>
  {
    diagnosticContext.Set("RequestHost", httpContext.Request.Host.Value);
    diagnosticContext.Set("ContentType", httpContext.Response.ContentType);
  };
});

这样RequestHost和ContentType就被添加到RequestLog中了,此处的MessageTemplate必须设置,否则日志中不会包含新添加的信息。

[12:03:19 INF] GET /weatherforecast responsed 200 in 62.095594 ms, localhost:5000, application/json; charset=utf-8

此外由于Serilog已经将IDiagnosticContext作为单例添加到DI容器中,因此可以从任何类中访问diagnosticContext并为某些属性设置值,但UseSerilogRequestLogging处设置值的优先级是最高的。

LogContext

使用LogContext还可以在局部动态地覆盖某些属性的值。 首先添加Enricher

Log.Logger = new LoggerConfiguration()
  .Enrich.FromLogContext()
  ...

然后就可以使用LogContext.PushProperty来进行属性覆盖了,在Log输出的Properties节点下就会增加刚才Push的属性。PushProperty会将指定的属性Push到栈顶,并返回一个IDisposeable对象,在这个IDisposeable对象被释放之前,遇到要输出的Log中存在这一属性的地方,就会从栈中拿到它的值。对于同一属性,后Push的值是优先级更高的。

var A = "A1";
log.Information("value = {A}", A); // value = A1
using (LogContext.PushProperty("A", "A2"))
{
  log.Information("value = {A}"); // value = A2
  using (LogContext.PushProperty("A", "A3"))
  {
    log.Information("value = {A}"); // value = A3
  }
  log.Information("value = {A}"); // value = A2
}
log.Information("value = {A}"); // value = {A}

Json配置

Serilog也提供了Json文件配置的方式,便于在不同的部署环境使用不同的配置。 首先添加关于Json文件的配置

var configuration = new ConfigurationBuilder()
  .SetBasePath(Directory.GetCurrentDirectory())
  .AddJsonFile("appsettings.json", optional:false)
  .AddJsonFile($"appsettings.{Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT") ?? "Production"}.json", optional: true)
  .Build();

然后前面用代码配置的方式就可以被替换掉了,使用了ReadFrom.Configuration(), sectionName指定了配置的根节点,如果没有设置sectionName则使用默认值“Serilog”。

// Log.Logger = new LoggerConfiguration()
//   .MinimumLevel.Information()
//   .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
//   .Enrich.FromLogContext()
//   .Destructure.ByTransforming<FakeDTO>(r => new {A1 = r.A, B1 = r.B})
//   .WriteTo.Console()
//   .WriteTo.Console(new RenderedCompactJsonFormatter())
//   .CreateLogger();

Log.Logger = new LoggerConfiguration()
  .ReadFrom.Configuration(configuration, sectionName: "CustomSection")
  .CreateLogger();

Json配置方式的局限

但Json配置的方式相对代码的方式也有很多局限。在用来配置日志级别、要Override的系统日志级别、Enricher、简单的WriteTo等是没有问题的。但自定义的Destructure还有JsonFormatter等还是需要用代码方式的。

{
  "CustomSection": {
    "MinimumLevel": "Information",
    "WriteTo": [
      { "Name": "Console" }
    ],
    "Override": {
      "Microsoft": "Information"
    },
    "Enrich": [ "FromLogContext", "WithMachineName" ]
    ]
  }
}

参考资料 https://github.com/serilog/serilog/wiki

展开阅读全文
加载中

作者的其它热门文章

打赏
0
0 收藏
分享
打赏
0 评论
0 收藏
0
分享
返回顶部
顶部
返回顶部
顶部