Logging in ASP NET Core with Serilog

At each stages of an application development cycle, good logs are necessary to debug and fix bugs efficiently.
Serilog is a logging framework allowing developers to log structured logs into different ouput platforms.
Today we will see how we can set it up in three parts

Serilog for ASP.NET Core
Console sink
Rolling File sink
Environment enricher

All the code discussed here can be found on my GitHub https://github.com/Kimserey/SerilogTest.

1. Serilog for ASP.NET Core

1.1 Structured logs

Logs are string messages describing an event in the system. They are built by assembling pieces of information, elapsed time or process name, into a string message. Once constructed into a message, they are written into an ouput stream, console or file for example.
The message contains the timestamp the log message. The log message being a string, all we can do to query it is a full text search query.
If our log contained the elapsed time, it would not be easy to run a under/above X ms query against it.

Structured logs cater for that by saving the logs as a structured json object where all pieces of information are kept in their original form. The advantage being that it provides full flexibility by allowing to query on the properties of each logs.
The other advantage is that it provides a unified way to allow platforms to display logs in their own way by giving them access to the raw propeties.

This is an example of structured logs:

{
  "Timestamp": "2018-02-21T09:06:26.8380962+08:00",
  "Level": "Information",
  "MessageTemplate": "Executed action {ActionName} in {ElapsedMilliseconds}ms",
  "RenderedMessage": "Executed action \"WebApplication.Controllers.ValuesController.Errors (WebApplication)\" in 1.6461ms",
  "Properties": {
    "ActionName": "WebApplication.Controllers.ValuesController.Errors (WebApplication)",
    "ElapsedMilliseconds": 1.6461000000000001,
    "EventId": {
      "Id": 2
    },
    "SourceContext": "Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker",
    "ActionId": "1f889c5e-c631-464b-992c-640202498b30",
    "RequestId": "0HLBOOSMLU5EE:00000003",
    "RequestPath": "/api/values/errors",
    "MachineName": "DESKTOP-I8R7QHH",
    "Application": "Web"
  }
}

1.2 ASP.NET Core

To start using Serilog on ASP.NET Core, we start by downloading Serilog.AspNetCore and register Serilog on the WebHostBuilder in program.cs.

WebHost.CreateDefaultBuilder(args)
    .UseStartup<Startup>()
    .UseSerilog()
    .Build();

We can already configure directly the logger from the code.

 WebHost.CreateDefaultBuilder(args)
    .UseStartup<Startup>()
    .UseSerilog((ctx, cfg) =>
    {
        cfg.ReadFrom.Configuration(ctx.Configuration)
            .MinimumLevel.Debug()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Information);
    })
    .Build();

Here we configured via code but we can also take advantage of the Configuration framework by downloading Serilog.Settings.Configuration and configure Serilog to read from configuration.

One of the advantage of using the Configuration framework is the ability to configure the logger from appsettings.json and leverage the multi environments support from appsettings.json with appsettings.Development.json/appsettings.Production.json. After installing Serilog.Settings.Configuration, we can use it with .ReadFrom().

WebHost.CreateDefaultBuilder(args)
    .UseStartup<Startup>()
    .UseSerilog((ctx, cfg) => cfg.ReadFrom.Configuration(ctx.Configuration))
    .Build();

We will see later an example of the json configuration for Serilog.

In case of errors within Serilog, it is possible to debug logs from Serilog using SelfLog.

Serilog.Debugging.SelfLog.Enable(msg => Debug.WriteLine(msg));

From the example we saw that we can configure a default minimum level of logging .MinimumLevel.Debug(). We can also override that default for certain namespaces, for example here we set the minimum level of logging for Microsoft namespace to Information. This will prevent ASP.NET Core to log all debug logs while keeping our own debug logs.

2 Console sink

Serilog alone does not write logs anywhere. It only constructs the structured logs. To write to an ouput, we need to configure a sink. The console sink is the most straight forward, Serilog.Sinks.Console. Once we installed it, we can write to console by simply adding WriteTo.Console().

 WebHost.CreateDefaultBuilder(args)
    .UseStartup<Startup>()
    .UseSerilog((ctx, cfg) =>
    {
        cfg.ReadFrom.Configuration(ctx.Configuration)
            .MinimumLevel.Debug()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
            .WriteTo.Console();
    })
    .Build();

Or configure it from appsettings.

{
  "Serilog": {
    "MinimumLevel": {
        "Default": "Debug",
        "Override": {
            "Microsoft": "Warning"
        }
    },
    "WriteTo": [
      { "Name": "Console" }
    ]
  }
}

Other properties are available on each logs. For example the SourceContext is the namespace where the log originated. If we want to display it on each log we only need to change the default template of the Console.

cfg.ReadFrom.Configuration(ctx.Configuration)
    .MinimumLevel.Debug()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
    .WriteTo.Console(outputTemplate: "[{Timestamp:HH:mm:ss.fff} {Level:u3}] {SourceContext}: {Message:lj}{NewLine}{Exception}")

From then on the logs should contain the source context.

[2018-02-21 09:06:26.837 +08:00 Web INF] Microsoft.AspNetCore.Mvc.StatusCodeResult: Executing HttpStatusCodeResult, setting HTTP status code 200

3. Rolling Files sink

Writing to console is useful while developing as most of the time we only care about what is going on during the execution and we don’t care about past executions. Logs appear live on the console thenwhen we close the application, all the logs are gone as none of them are persisted.

But in production, it is necessary to persist logs as the application will run without us monitoring it with all our attention. On top of that there are times where we can’t have access to a console in a remote system.

In those instances, the simplest way to monitor logs is through files. Saving logs to files allows us to reference back previous executions.

Similarly to Console sink providing writing to console, Rolling Files sink comes from a package Serilog.Sink.RollingFile. After installation we can configure in the same way we configured the Console log, except that we will need to provide a file path for the logs to be saved.

cfg.ReadFrom.Configuration(ctx.Configuration)
    .MinimumLevel.Debug()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
    .WriteTo.RollingFile("Logs\\Web-{Date}.log", outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} {Level:u3}] {SourceContext}: {Message:lj}{NewLine}{Exception}")

After we configured the environment we can see the log files appearing under the folder configured.

4. Environment enricher

With the sinks configured, we can see the messages outputed with predefined data like timestamp, log level of the messages and of course the message content and exception if any.
Apart from those information, our logs might be holding more data as we saw in 1). Those data are added by default, if those aren’t enough, we can also add more by using enrichers.

One of the enricher is the environment enricher which provides information about the machine name and the environment user name running the application.

Similarly as the sinks, enrichers are added using packages. For the environment enricher, we add the Serilog.Enrich.Environment. Once installed, we can then enrich our logs.

cfg.ReadFrom.Configuration(ctx.Configuration)
    .MinimumLevel.Debug()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
    .Enrich.WithMachineName()
    .Enrich.WithEnvironmentUserName()
    .WriteTo.Console(theme: AnsiConsoleTheme.Code, outputTemplate: "{MachineName} {EnvironmentUserName}: {Message:lj}{NewLine}{Exception}")

Now if we look at the log, we should be able to see the new information in the logs.

 DESKTOP-XXX DESKTOP-XXX\Kim Serey: Executed action \"WebApplication.Controllers.ValuesController.Errors (WebApplication)\" in 1.6461ms

And that conclude our simple way to write logs to console and persist them in log files using Serilog!

Conclusion

Logs are the best tools that developers have to write programs. Having a powerful logging system is important but the simplicity of it also need to be taken into consideration. Serilog provides an easy way to configure simple Console and Rolling file logs and at the same time cater for expansion of the code towards more heavy duty tools like the Elastic stack. Hope you liked this post. See you next time!

Search This Blog

Kimserey's blog