Enhancing ASP.NET Core Logging Pipeline with Serilog

Introduction

In this post, I would like to show how we can switch out the default logging pipeline in favor of Serilog which has a lot more providers implemented by the community and also provides a way to log structured data.

The Backstory

For those of you who have created projects in ASP.NET Core 1.1 or earlier, you might remember the Program.cs file looking like this:

using System;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Hosting;

namespace WebApplication1
{
    public class Program
    {
        public static void Main(string[] args)
        {
            var host = new WebHostBuilder()
                .UseKestrel()
                .UseContentRoot(Directory.GetCurrentDirectory())
                .UseIISIntegration()
                .UseStartup()
                .UseApplicationInsights()
                .Build();

            host.Run();
        }
    }
}

As you can see, during previous versions of ASP.NET Core, the setup for the entry point of the application used to be more explicit. Now, starting from ASP.NET Core 2.0 and higher, the default Program.cs file looks like this:

using System;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using System.Threading.Tasks;
using Microsoft.AspNetCore;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.Logging;

namespace WebApplication1
{
    public class Program
    {
        public static void Main(string[] args)
        {
            CreateWebHostBuilder(args).Build().Run();
        }

        public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
            WebHost.CreateDefaultBuilder(args)
                .UseStartup();
    }
}

Though the default builder cleans up the code nicely, it does add some default (as the name implies) configurations that aren’t all that obvious.

If we take a look at what WebHost.CreateDefaultBuilder actually does, we will see the following:

public static IWebHostBuilder CreateDefaultBuilder(string[] args)
{
    var builder = new WebHostBuilder();

    if (string.IsNullOrEmpty(builder.GetSetting(WebHostDefaults.ContentRootKey)))
    {
        builder.UseContentRoot(Directory.GetCurrentDirectory());
    }

    if (args != null)
    {
        builder.UseConfiguration(new ConfigurationBuilder().AddCommandLine(args).Build());
    }

    builder.UseKestrel((builderContext, options) =>
        {
            options.Configure(builderContext.Configuration.GetSection("Kestrel"));
        })
        .ConfigureAppConfiguration((hostingContext, config) =>
        {
            var env = hostingContext.HostingEnvironment;

            config.AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)
                  .AddJsonFile($"appsettings.{env.EnvironmentName}.json", 
                                              optional: true, reloadOnChange: true);

            if (env.IsDevelopment())
            {
                var appAssembly = Assembly.Load(new AssemblyName(env.ApplicationName));
                if (appAssembly != null)
                {
                    config.AddUserSecrets(appAssembly, optional: true);
                }
            }

            config.AddEnvironmentVariables();

            if (args != null)
            {
                config.AddCommandLine(args);
            }
        })
        // THIS IS THE PART WE'RE INTERESTED IN. (INTEREST!!!)
        .ConfigureLogging((hostingContext, logging) =>
        {
            logging.AddConfiguration(hostingContext.Configuration.GetSection("Logging"));
            logging.AddConsole();
            logging.AddDebug();
        })
        .ConfigureServices((hostingContext, services) =>
        {
            // Fallback
            services.PostConfigure(options =>
            {
                if (options.AllowedHosts == null || options.AllowedHosts.Count == 0)
                {
                    // "AllowedHosts": "localhost;127.0.0.1;[::1]"
                    var hosts = hostingContext.Configuration["AllowedHosts"]?.Split
                                (new[] { ';' }, StringSplitOptions.RemoveEmptyEntries);
                    // Fall back to "*" to disable.
                    options.AllowedHosts = (hosts?.Length > 0 ? hosts : new[] { "*" });
                }
            });
            // Change notification
            services.AddSingleton<IOptionsChangeTokenSource>(
                new ConfigurationChangeTokenSource(hostingContext.Configuration));

            services.AddTransient();
        })
        .UseIISIntegration()
        .UseDefaultServiceProvider((context, options) =>
        {
            options.ValidateScopes = context.HostingEnvironment.IsDevelopment();
        });

    return builder;
}

Well, that sure is a whole lot of configuration for a start, good thing it’s hidden behind such an easy call like CreateDefaultBuilder.

Now, if we look in the code snippet above (I marked it with INTEREST!!! so it’s easy to find), you will see that by default, the configuration setups so that logging is sent to the console and to the debug channel, we won’t be needing this since we’ll be using a different console and there’s no use in having two providers write to the same console at the same time.

The Changes

So the first change we will make is the following:

public class Program
{
    public static void Main(string[] args)
    {
        CreateWebHostBuilder(args).Build().Run();
    }

    public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
        WebHost.CreateDefaultBuilder(args)
            .ConfigureLogging(
                (webHostBuilderContext, loggingBuilder) =>
                    {
                        loggingBuilder.ClearProviders();
                    })
            .UseStartup();
}

With this change, we’re clearing out both the console and the debug providers, so essentially now we don’t have any logging set up.

Now we’re going to add the following Nuget packages (note that only two of them are required for this to work, all the other sinks are up to your own choice):

• Serilog (this is the main package and is required)
• Serilog.Extensions.Logging (this is used to integrate with the ASP.NET Core pipeline, it will also install Serilog as a dependency)
• Serilog.Sinks.ColoredConsole (this package adds a colored console out that makes it easier to distinguish between logging levels and messages, also this will install Serilog as a dependency)
• Serilog.Enrichers.Demystify (this package is in pre-release but it makes it so that long stack traces from exceptions that cover async methods turn into a stack trace that is more developer friendly)

With these packages installed, we’re going to change the Program.cs file again and it will end up looking like this:

namespace WebApplication1
{
    using System;

    using Microsoft.AspNetCore;
    using Microsoft.AspNetCore.Hosting;
    using Microsoft.Extensions.Logging;

    using Serilog;
    using Serilog.Extensions.Logging;

    public class Program
    {
        public static void Main(string[] args)
        {
            CreateWebHostBuilder(args).Build().Run();
        }

        public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
            WebHost.CreateDefaultBuilder(args)
                .ConfigureLogging(
                    (webHostBuilderContext, loggingBuilder) =>
                        {
                            loggingBuilder.ClearProviders();

                            Serilog.Debugging.SelfLog.Enable(Console.Error); // this outputs 
                              // internal Serilog errors to the console in case something 
                              // breaks with one of the Serilog extensions or the framework itself

                            Serilog.ILogger logger = new LoggerConfiguration()
                                .Enrich.FromLogContext() // this adds more information 
                                    // to the output of the log, like when receiving http requests, 
                                    // it will provide information about the request
                                .Enrich.WithDemystifiedStackTraces() // this will change the 
                                    // stack trace of an exception into a more readable form 
                                    // if it involves async
                                .MinimumLevel.Verbose()   // this gives the minimum level to log, 
                                                          // in production the level would be higher
                                .WriteTo.ColoredConsole() // one of the logger pipeline elements 
                                                          // for writing out the log message
                                .CreateLogger();

                            loggingBuilder.AddProvider(new SerilogLoggerProvider
                                     (logger)); // this adds the serilog provider from the start
                        })
                .UseStartup();
    }
}

Now we have integrated Serilog into the main pipeline for logging used by all the components from ASP.NET Core. Notice that we also have access to the webHostBuilderContext which has a Configuration property which allows us to read from the application configuration so that we can set up a more complex pipeline, and there is also a nuget package that allows Serilog to read from an appsettings.json file.

Optionally, Serilog also allows that a log message carry some additional properties, for that, we would need to change the default outputTemplate from this "{Timestamp:yyyy-MM-dd HH:mm:ss} {Level:u3} {Message}{NewLine}{Exception}" to this "{Timestamp:yyyy-MM-dd HH:mm:ss} {Level} {Properties} {Message}{NewLine}{Exception}"; Notice the Properties template placeholder, this is where serilog will place all additional information that is not in the actual message, like data from the http request. To see how this change would look, see the following:

Serilog.ILogger logger = new LoggerConfiguration()
    .Enrich.FromLogContext()             // this adds more information to the output of the log, 
                                         // like when receiving http requests, it will provide 
                                         // information about the request
    .Enrich.WithDemystifiedStackTraces() // this will change the stack trace of an exception 
                                         // into a more readable form if it involves async
    .MinimumLevel.Verbose()              // this gives the minimum level to log, in production 
                                         // the level would be higher
    .WriteTo.ColoredConsole(outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss} 
             {Level} {Properties} {Message}{NewLine}{Exception}") // one of the logger pipeline 
                                                  // elements for writing out the log message
    .CreateLogger();

Conclusion

Note that there are as many ways to set up a logging pipeline as there are applications, this is just my personal preference.

Also, in case you were wondering why I opted to make the changes inside the Program.cs file instead of the Startup.Configure() method, as some examples show it online, is because I believe that if the default logging is set up in its own dedicated function, this should as well, also this introduces Seriloger earlier in the process than by using the Startup method, which in turn provides more information.

I hope you enjoyed this post and that it will help you better debug and maintain your applications.

Thank you and see you next time.
Cheers!

CodeProject