Initialize the

To replace the native Log with Serilog, do the following:

Adding Nuget:

dotnet add package Serilog.AspNetCore
Copy the code

Modify Main method

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(); }}Copy the code

UseSerilog()

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

With these two changes, you are done replacing the native Log with Serilog.

Active Logging

Log instances can be obtained by such code where logging is required

private readonly ILogger log = Log.Logger;
Copy the code

Serilog defines the following log levels:

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

Output comparison of native log and Serilog

In the Web API template project, LogLeve is default “Microsoft”: “Information”, for an API request: compare the output of native log and Serilog:

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.2528 ms info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1] Executed endpoint 'SerilogTest.Controllers.WeatherForecastController.Get (SerilogTest)' info: Microsoft. AspNetCore. Hosting. Diagnostics [2] Request finished in 102.3501 ms 200 application/json; charset=utf-8Copy the code

Serilog:

[22:12:13 INF] Request starting HTTP / 1.1 GET http://localhost:5000/weatherforecast [22:12:13 INF] Executing the 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.6404 ms [22:12:13 INF] Executed the endpoint 'SerilogTest. Controllers. WeatherForecastController. Get (SerilogTest)' [22:12:13 INF] Request finished in 104.071 200 ms application/json; charset=utf-8Copy the code

Both have seven logs. Serilog has more time information than native Log, but it lacks the name of the component that produces the Log. Serilog logs are generally more compact.

Using RequestLoggingMiddleware

Each API request outputs so much log information, much of it unconcerned, that it not only hinders the search for useful information, but also burdens log storage. Serilog provides RequestLogging middleware that logs a single summary log for each request. First, add the middleware: app. UseSerilogRequestLogging ()

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

As with other middleware in the pipeline, order is important. When a request reaches the RequestLoggingMiddleware middleware, it starts a timer and passes the request on to subsequent middleware for processing. When the later middleware finally generates a response (or throws an exception), the response is piped back through the middleware to the request logger, where the result is recorded and logged. So the middleware should be placed as far forward as possible.

The output effect

The penultimate log is from RequestLoggingMiddleware

[11:25:43 INF] Request starting HTTP / 1.1 GET http://localhost:5000/weatherforecast [11:25:43 INF] Executing the 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.9249 ms / 11:25:43 INF Executed the 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.1417 MS 200 Application /json; charset=utf-8Copy the code

With the logs in RequestLoggingMiddleware, you can turn off the information-level logs logged by the system, This can be done by adding the minimumLevel. Override(“Microsoft”, logEventLevel. Warning) filter when LoggerConfiguration is set in program.cs:

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

It then outputs only one log:

[11:25:43 INF] HTTP GET/WeatherForecast 27 in 172.8042 msCopy the code

Output Json format

As a structured logging component, support for the Json format is also essential. Serilog supports the following four rendering methods:

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

Json output can be enabled when LoggerConfiguration is configured. Here, the text format and the four Json formats are enabled to compare the differences between them

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();
Copy the code

contrast

// text [12:58:08 INF] GET/Forecast 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": "The 2020-12-27 T12: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 ":" 0 hm5a4g0bvc68} / / RenderedCompactJsonFormatter "{" @ t" : "the 2020-12-27 T04:58:08. 2277150 z", "@" 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" }Copy the code
Formatter Characteristics of the
JsonFormatter Basic Json format, only template, no full log
JsonFormatter(renderMessage: true) RenderedMessage node is added to store the full text of logs compared to JsonFormatter
CompactJsonFormatter Shortened attribute names compared to JsonFormatter, such as @t instead of Timestamp
RenderedCompactJsonFormatter Compared to the CompactJsonFormatter, there is the full log (@m), no longer contains the log template

By default, Serilog outputs only the following information:

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

While the Log is compact enough, it also lacks some useful information compared to the system Log. Methods of extension are described later in the Enrichment section.

Structured log

Serilog represents structured logs in Json format. Use a C# string template for logging.

The default format

Value types, strings, collections based on value types or strings, and dictionaries are stored as properties of Json objects, such as:

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

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

Will be stored as:

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

The @ operator.

If you want to log an instance of class, this method forces the ToString method to be called and does not get the values of the internal attributes. So for data structures other than value types and collections based on value types and dictionaries, use the @ operator to store the values inside the instance as Json objects

var dto = new FakeDTO { A = "A",B="B"}; Log.Information("test is {FakeDTO}", dto); / / output: "FakeDTO" : "SerilogTest. Controllers. FakeDTO" the Information (" the test is {@ FakeDTO} ", dto); : / / output, "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; }}Copy the code

Customize the attributes to save

The @ operator can convert A class to Json, but if you only need to record A few attributes of the class, such as FakeDTO, which is only interested in A and B, you can configure the Destructure in LoggerConfiguration to make the Json contain only the desired attributes.

Log.Logger = new LoggerConfiguration() ... . Destructure. ByTransforming < FakeDTO > (r = > new B1 = {A1 = state Richard armitage, r. B}) / / output: "FakeDTO" : {" A1 ":" A ", "B1" : "B"}Copy the code

Performance considerations

Try to use templates rather than concatenating log content yourself:

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

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

There may be performance differences between the two methods. For example, when the Log level is raised to Warning, the latter will still perform concatenating string operations even if the Info level logs are no longer output, while the template method will not have such problems. There will be a significant performance difference between the two methods in the case of many logs.

Enrichment

Serilog also provides a way to extend its request log information with Enricher.

Enumerate partial 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()

To use Enricher, you need to add it when configuring LoggerConfiguration, such as:

Log.Logger = new LoggerConfiguration()
  .Enrich.WithThreadId()
  ...
Copy the code

Customization extends information

Enrich.WithProperty gives you more flexibility to add extended information, such as adding IP addresses, which can then be retrieved from the {IP} template where you Log.

. Enrich. WithProperty (" IP ", "127.0.0.1)"Copy the code

Add extended information to the RequestLog

In addition to using the Enrichers that Serilog already provides, you can also add the following configuration when introducing the use of 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);
  };
});
Copy the code

The RequestHost and ContentType are then added to the RequestLog, where the MessageTemplate must be set otherwise the log will not contain the newly added information.

[12:03:19 INF] GET/Forecast responsed 200 in 62.095594 ms, localhost:5000, Application /json; charset=utf-8Copy the code

Furthermore, since Serilog has added IDiagnosticContext as a singleton to the DI container, diagnosticContext can be accessed from any class and values can be set for certain properties, However, the values set at UseSerilogRequestLogging have the highest priority.

LogContext

You can also use LogContext to locally overwrite the values of some properties dynamically. First add Enricher

Log.Logger = new LoggerConfiguration()
  .Enrich.FromLogContext()
  ...
Copy the code

You can then override the Properties using logContext.pushProperty, adding the Properties you just pushed under the Properties node in the Log output. PushProperty pushes the specified property to the top of the stack and returns an IDisposeable object. Before the IDisposeable object is released, the value of the property is retrieved from the stack when it is encountered in the Log to be output. For the same attribute, the post-push value is of higher priority.

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}
Copy the code

Json configuration

Serilog also provides a way to configure Json files so that different configurations can be used in different deployment environments. First add the configuration for the Json file

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

Readfrom. Configuration() is used, sectionName specifies the root node of the Configuration, and the default value “Serilog” is used if sectionName is not set.

// 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();
Copy the code

Limitations of the Json configuration mode

However, the way Json is configured has many limitations compared to the way code is configured. There is no problem with log levels used to configure, system log levels to Override, Enricher, simple WriteTo, and so on. But custom DeStructures and JsonFormatter and so on still need to be coded.

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

Copy the code

Resources github.com/serilog/ser…