Exploring Serilog v2 - ASP.Net Core • Get Amongst It!

This is the next post in a series re-discovering Serilog v2.

In this post, ASP.Net Core will be the focus. Along with .Net Core, ASP.Net Core has experienced significant changes over the past few years. As such Serilog has adapted accordingly.

In this post, tooling is as follows.

dotnet --info

.NET Command Line Tools (2.1.4)

Product Information:
 Version:            2.1.4
 Commit SHA-1 hash:  5e8add2190

Runtime Environment:
 OS Name:     Mac OS X
 OS Version:  10.12
 OS Platform: Darwin
 RID:         osx.10.12-x64
 Base Path:   /usr/local/share/dotnet/sdk/2.1.4/

Microsoft .NET Core Shared Framework Host

  Version  : 2.0.5
  Build    : 17373eb129b3b05aa18ece963f8795d65ef8ea54

To start, create a new project ASP.NET project using the Web API template. And spin it up, and hit the http://localhost:5000/api/values endpoint.

dotnet new webapi -n example-api
cd example-api
dotnet run

Hosting environment: Production
Now listening on: http://localhost:5000
Application started. Press Ctrl+C to shut down.

As you can see from the console output above, you do not get a lot of information from the default setup.

Open the appsettings.json file and update the default logging levels to information.

{
  "Logging": {
    "IncludeScopes": false,
    "Debug": {
      "LogLevel": {
        "Default": "Information"
      }
    },
    "Console": {
      "LogLevel": {
        "Default": "Information"
      }
    }
  }
}

Now run the app, and once again hit the http://localhost:5000/api/values endpoint.

info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
      User profile is available. Using '/Users/matthewerbs/.aspnet/DataProtection-Keys' as key repository; keys will not be encrypted at rest.
Hosting environment: Production
Content root path: /Users/matthewerbs/Code/blog/scratch/aspnet/example-api
Now listening on: http://localhost:5000
Application started. Press Ctrl+C to shut down.
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:5000/api/values
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Executing action method example_api.Controllers.ValuesController.Get (example-api) with arguments ((null)) - ModelState is Valid
info: Microsoft.AspNetCore.Mvc.Internal.ObjectResultExecutor[1]
      Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action example_api.Controllers.ValuesController.Get (example-api) in 45.156ms
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 123.375ms 200 application/json; charset=utf-8

Not a great deal better and certainly not helping in a production system. Let’s now add some Serilog goodness.

dotnet add package Serilog.AspNetCore
dotnet add package Serilog.Sinks.Console
dotnet add package Serilog.Sinks.File
dotnet add package Serilog.Settings.Configuration

Open the Program.cs and update with the following.

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 example_api
{
    public class Program
    {
        public static void Main(string[] args)
        {
            Log.Logger = new LoggerConfiguration()
                .MinimumLevel.Information()
                .Enrich.FromLogContext()
                .WriteTo.Console()
                .CreateLogger();

            try
            {
                Log.Information("Starting web host");
                BuildWebHost(args).Run();
                return 0;
            }
            catch (Exception ex)
            {
                Log.Fatal(ex, "Host terminated unexpectedly");
                return 1;
            }
            finally
            {
                Log.Information("Flushing logs");
                Log.CloseAndFlush();
            }
        }

        public static IWebHost BuildWebHost(string[] args) =>
            WebHost.CreateDefaultBuilder(args)
                .UseKestrel()
                .UseStartup<Startup>()
                .UseSerilog() // <- Plug Serilog into the pipeline
                .Build();
    }
}

The code above triggers a number of key changes.

The try/catch wraps one of the most important parts of any application. The setup of the application’s logging infrastructure. If this is not working, there are dark days ahead.
.UseSerilog() is the key area in which Serilog is pushed into the logging pipeline of ASP.Net Core.

Running the app again will provide slightly more readable output.

[09:55:55 INF] Starting web host
[09:55:56 INF] User profile is available. Using '/Users/matthewerbs/.aspnet/DataProtection-Keys' as key repository; keys will not be encrypted at rest.
Hosting environment: Production
Content root path: /Users/matthewerbs/Code/blog/exploring-serilog/aspnet/example-api
Now listening on: http://localhost:5000
Application started. Press Ctrl+C to shut down.
[09:56:03 INF] Request starting HTTP/1.1 GET http://localhost:5000/api/values
[09:56:03 INF] Executing action method example_api.Controllers.ValuesController.Get (example-api) with arguments (null) - ModelState is Valid
[09:56:03 INF] Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
[09:56:03 INF] Executed action example_api.Controllers.ValuesController.Get (example-api) in 51.13ms
[09:56:03 INF] Request finished in 123.563ms 200 application/json; charset=utf-8

Now for a few more changes. Firstly, change the setup of the app to source configuration from an appsettings.json file.

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;
using Serilog.Events;
using Serilog.Core;
using Serilog;

namespace example_api
{
    public class Program
    {
        // ASP.Net Core configuration
        public static IConfiguration Configuration { get; } = new ConfigurationBuilder()
            .SetBasePath(Directory.GetCurrentDirectory())
            .AddJsonFile("appsettings.json", optional: false, reloadOnChange: true)
            .Build();

        public static void Main(string[] args)
        { 
            // Apply the config to the logger
            Log.Logger = new LoggerConfiguration()
                .ReadFrom.Configuration(Configuration)
                .CreateLogger();
 
            try
            {
                Log.Information("Starting web host");
                BuildWebHost(args).Run();
                return;
            }
            catch (Exception ex)
            {
                Log.Fatal(ex, "Host terminated unexpectedly");
                return;
            }
            finally
            {
                Log.Information("Flushing logs");
                Log.CloseAndFlush();
            }
        }

        public static IWebHost BuildWebHost(string[] args) =>
            WebHost.CreateDefaultBuilder(args)
                .UseStartup<Startup>()
                .UseSerilog() // <- Plug Serilog into the pipeline
                .UseKestrel()
                .Build();
    }
}

Secondly, update the appsettings.json file (below). This will add a number of instructions.

Sets the minumum level to Information whilst also reducing some of the noise created from the Microsoft and System namespaces.
Sets up the Console & File sink as destinations.
Adds some property enrichment.

{
  "Serilog": {
    "MinimumLevel": {
      "Default": "Debug",
      "Override": {
        "Microsoft": "Debug",
        "System": "Debug"
      }
    },
    "Using": [
      "Serilog.Sinks.Console",
      "Serilog.Sinks.File"
    ],
    "Enrich": [
      "FromLogContext"
    ],
    "WriteTo": [{
        "Name": "File",
        "Args": {
          "path": "serilog-configuration-sample.txt"
        }
      },
      {
        "Name": "Console",
        "Args": {
          "outputTemplate": "[{Timestamp} [{Level}] {Message}{NewLine}{Exception} {Properties}",
          "theme": "Serilog.Sinks.SystemConsole.Themes.SystemConsoleTheme::Literate, Serilog.Sinks.Console"
        }
      }
    ],
    "Properties": {
      "Application": "Exploring Serilog v2"
    }
  }
}

Finally, let’s add a simple middleware class to add some basic HTTP information on a request. Add a new file called SimpleSerilogMiddleware.cs and the following code.

using Microsoft.AspNetCore.Http;
using Serilog;
using Serilog.Events;
using System;
using System.Diagnostics;
using System.Linq;
using System.Threading.Tasks;

namespace example_api
{
    class SimpleSerilogMiddleware
    {
        static readonly ILogger Log = Serilog.Log.ForContext<SimpleSerilogMiddleware>();

        readonly RequestDelegate _next;

        public SimpleSerilogMiddleware(RequestDelegate next)
        {
            if (next == null) throw new ArgumentNullException(nameof(next));
            _next = next;
        }

        public async Task Invoke(HttpContext httpContext)
        {
            if (httpContext == null) throw new ArgumentNullException(nameof(httpContext));
 
            await _next(httpContext);
            var statusCode = httpContext.Response?.StatusCode;
            Log.Information("{client} {protocol} {path} {code} {length} ", httpContext.Connection.RemoteIpAddress, httpContext.Request.Method, httpContext.Request.Protocol, httpContext.Request.Path, httpContext.Response?.StatusCode, httpContext.Response?.ContentLength);
        }
    }
}

And wire it up via Startup.cs

public void Configure(IApplicationBuilder app, IHostingEnvironment env)
{
   ...
   app.UseMiddleware<SimpleSerilogMiddleware>();
   ...
}

Run the app one last time and curl a few routes, the following is an example output.

[14:20:59 INF] 127.0.0.1 GET HTTP/1.1 /api/values 200
[14:21:00 INF] 127.0.0.1 GET HTTP/1.1 /api/values 200

Considering the number of changes between ASP.Net Core, .Net Core and Serilog over the past few years, it is comforting to think such a simple setup gives you such extensibility.

The example in full can be found over at GitHub.

Get Amongst It!

Tags

Exploring Serilog v2 - ASP.Net Core

Get Amongst It!!