Lachlan B's Blog

Using Seq and Asp Dot Net Core

I am unabashed in how awesome I think Seq is. For troubleshooting stuff in production, this thing is a goldmine. Let's say I have some code:


public int Divide(int x, int y)
{
    int z = x / y;
    return z;
}

int result = Divide(10, 5);

With Seq it's extremely easy to add some logging that gives you all the information you need to troubleshoot this function when it's running in production:

I won't go into any more detail about Seq, you can read about it yourself, so here's how I set it up.

Setting up Serilog and Seq for Logging

We are going to use ASP.NET Core's standard logging, Serilog as the implementation, and Seq as a serilog sink. This gives us the most flexibility!

First off you only need to add two NuGet packages:

Install-Package Serilog.Sinks.Seq
Install-Package Serilog.AspNetCore

Once you have done that, open your Program.cs class and change your Main function to look something like this:


using System;
using System.IO;
using System.Reflection;
using System.Runtime.InteropServices;

using Serilog;
using Serilog.Events;

using Microsoft.Extensions.Configuration;
using Microsoft.AspNetCore;
using Microsoft.AspNetCore.Hosting;

namespace MyApp
{
    public class Program
    {
        public static int Main(string[] args)
        {
            // yes this is deliberately outside of the try catch because if this
            // fails there's no point in calling the logger :)

            Log.Logger = new LoggerConfiguration()
                .MinimumLevel.Verbose()
                .MinimumLevel.Override("Microsoft", LogEventLevel.Error)
                .Enrich.With(new LogEnricher())
                .WriteTo.Seq("myseqserver.com:5341", apiKey: "MyAppsApiKey")
                .CreateLogger();
                    
            try
            {
                Log.Information("Starting up My Project");

                BuildWebHost(args).Run();

                return 0;
            }
            catch (Exception ex)
            {
                Log.Fatal(ex, "My Project terminated unexpectedly");
                return 1;
            }
            finally
            {
                // need to flush and close the log otherwise we might miss some
                Log.CloseAndFlush();
            }
        }
        
        public static IWebHost BuildWebHost(string[] args) =>
            WebHost.CreateDefaultBuilder(args)
                    .UseStartup()
                    .UseSerilog()
                    .Build();
    }
}

If you want to customise the Properties that are automatically added, you will need my custom LogEnricher. But you don't need this.


class LogEnricher : ILogEventEnricher
{
    public void Enrich(LogEvent le, ILogEventPropertyFactory lepf)
    {
        // these properties are created by asp.net core, I don't need them
        // so I'm going to remove them

        le.RemovePropertyIfPresent("SourceContext");
        le.RemovePropertyIfPresent("RequestId");
        le.RemovePropertyIfPresent("RequestPath");
        le.RemovePropertyIfPresent("ActionId");
        le.RemovePropertyIfPresent("ActionName");

        // however I definitely want to know machine name for each log entry:

        le.AddPropertyIfAbsent(lepf.CreateProperty("MachineName", Environment.MachineName));
    }
}

Writing a log

To write a log within a class, you can inject it into your controller (or any other class) by adding it to the constructor:


using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Logging;

namespace MyApp
{
    [Route("")]
    public class MathsController : Controller
    {
        private ILogger<MathsController> _log;

        public MathsController(ILogger<MathsController> log)
        {
            _log = log;
        }

        [HttpGet("v1/divide")]
        public int Divide(int x, int y)
        {
            int z = x / y;
            _log.LogInformation("Dividing {x} by {y} gives us {z}", inputs.x, inputs.y, z);
            return z;
        }
    }
}

You don't have to use dependency injection. However it's quite useful if you want to write a unit test for the Divide function, but you don't want it writing a log every time you run the unit test. In that case, you can just pass through an implementation of ILogger that doesn't do anything, using the great Moq library:


using Microsoft.Extensions.Logging;
using Moq;
using NUnit.Framework;

namespace MathsTests
{
    [TestFixture]
    public class Tests
    {
        [Test]
        public void TestDivide()
        {
            var logger = new Mock<Logger<MathsController>>();
            var mathsController = new MathsController(logger.Object);

            var result = mathsController.Divide(10, 2);

            Assert.IsTrue(5, result);
        }
    }
}

But having said that, if you don't want to use dependency injection, or if you wish to use Serilog's more fancy features, you can directly access the Serilog.Log singleton:


Serilog
    .Log
    .ForContext("Current Base Directory", AppDomain.CurrentDomain.BaseDirectory)
    .Information("Dividing {x} by {y} equals {z}", x, y, z);

Global Error Handling

For WebApi methods, you can implement a global exception handler by creating your own Middleware like so:



public class ErrorHandlingMiddleware
{
    private readonly RequestDelegate next;

    public ErrorHandlingMiddleware(RequestDelegate next)
    {
        this.next = next;
    }

    public async Task Invoke(HttpContext context /* other dependencies */)
    {
        try
        {
            await next(context);
        }
        catch (Exception ex)
        {
            Serilog
                .Log
                .ForContext(new ExceptionEnricher(context))
                .Error(ex, "Global error {Message}", ex.Message);
        }
    }
}

and then to use it, add it before your call to .UseMvc() inside your app's Startup.cs:


public void Configure(IApplicationBuilder app, IHostingEnvironment env)
{
    if (env.IsDevelopment())
    {
        app.UseDeveloperExceptionPage();
    }
    app.UseMiddleware(typeof(ErrorHandlingMiddleware));
    app.UseMvc();
}

Which means you'll get some lovely error handling in your logs:

Request Input Validation and Logging

If you wish to automatically validate inputs using DataAnnotations and log any validation errors, you can create your own ActionFilter like so:


public class ValidateModelStateAttribute : ActionFilterAttribute
{
    public override void OnActionExecuting(ActionExecutingContext context)
    {
        if (!context.ModelState.IsValid)
        {
            Serilog
                .Log
                .ForContext(new BadRequestEnricher(context.ModelState))
                .Warning("Bad Request to {Path}, bad fields: {NumberOfBadFields}",
                    context.HttpContext.Request.Path, context.ModelState.ErrorCount);

            // return a 400 Bad Request result
            context.Result = new BadRequestObjectResult(context.ModelState);
        }
    }
}

class BadRequestEnricher : ILogEventEnricher
{
    ModelStateDictionary _modelState;
    public BadRequestEnricher(ModelStateDictionary modelState)
    {
        _modelState = modelState;
    }

    public void Enrich(LogEvent le, ILogEventPropertyFactory lepf)
    {
        foreach (var key in _modelState.Keys)
        {
            string message = _modelState[key].Errors[0]?.ErrorMessage;
            le.AddPropertyIfAbsent(
                lepf.CreateProperty("Invalid" + key, message ));
        }
    }
}

You can then either add this attribute to your Api or you can add it to run for all routes by editing your Startup.cs:


public void ConfigureServices(IServiceCollection services)
{
    services
        .AddMvc(options =>
        {
            options.Filters.Add(typeof(ValidateModelStateAttribute));
        })

This should mean that if you use Data Annotaions on your input objects like so:


    public class DivideInputDTO
    {
        [Range(0, 100)]
        public int x { get; set; }
        public int y { get; set; }
    }
    
    [HttpGet("v1/divide")]
    public int Divide(DivideInputDTO inputs)
    {
        int z = inputs.x / inputs.y;
        _log.LogInformation("Dividing {x} by {y} gives us {z}", inputs.x, inputs.y, z);
        return z;
    }

(BTW can you spot the "bug"? Let me give you a minute...)

...

(Yes, there is no validation on the y property! Divide by zero is still possible!)

Anyway, you will now log lovely validation messages:

Is that it?

I'm quite happy with this setup and it's been serving me well. What have I missed? I'm sure something else obvious!

Many thanks to Bron's serilog in aspnet core article and of course the aspnet core serilog docs, and also of course Seq's own using serilog and using aspnet core.