On Seq and the usefulness of Serilog

tl;dr - Seq and Serilog are an amazing combination and worth checking out

I've recently been dealing with Seq, a structured logging tool used for .NET Applications, and Serilog, a .NET wrapper for logging events to Seq. Having used Serilog and Seq a few times now, across a few different projects, I thoroughly recommend it if you're looking some really simple, clean and powerful logging.

Today's post came about due to some recent troubleshooting I had to do at a client site, as we were observing some strange behaviour with Serilog. The resulting investigation inspired me to dig into Serilog specifically, to have a look at what other cool stuff I could find. I'm also attempting a new style with the associated code for this post, hosting in its own repository on GitHub. Previously, I'd attempted hosting them within a single generic 'BlogEntryCode' repository, with readme.md files for explanations, but I think I like this form of isolation a bit better. I've also split the major stages of my investigations into separate commits:

So if you're playing along at home, you can check out each of the specific commits to see how the code was running at that point at in time. Well... here we go!

Initial setup and installation

To install Seq, simply go here and download & install the file. A default installation will be done in a flash, and you'll be up and running in no time. For Serilog, simply add the Serilog Nuget packages via Install-Package Serilog and Install-Package Serilog.Sinks.Seq. We'll add more, but those will come later.

Static Logging Configuration with Serilog

Serilog's primary pattern for configuring itself is through the static property Log.Logger, in the Serilog namespace. Using this will let you use the static property Log throughout your classes, letting you output to Seq through Information, Warning, Error and Fatal methods.

Setting up a basic configuration is fairly easy:

    Log.Logger = new LoggerConfiguration()
        .WriteTo.Seq(ConfigurationManager.AppSettings["SeqUrl"])
        .CreateLogger();

This uses the concept of a Sink, this being an external representation of something, to write to Seq, for a given Seq Instance URL (in this case, I'm storing the URL in the web.config of the application). Serilog can be used for things other than Seq, so the amount of things it can write to is pretty amazing, and very handy.

Now, in our HomeController.cs file, we can log that the Index action is being hit successfully.

    public ActionResult Index()
    {
        Log.Information("Invoking Index() Action");
        ViewBag.Title = "Home Page";
        Log.Information("Finished Index() Action");
        return View();
    }

If we go to our Seq instance, we can see the method entries there:

So personally, I'm not a fan of static anything (in fact, there's an interesting situation further down in this post which highlights why static can be troublesome at times), so I wanted to see if I could inject the ILogger interface (Serilog's interface of choice) into my controllers, through the use of Autofac...

ILogger Injection via Autofac

^{With the bonus addition of Request Correlation!}

Add the following Nuget packages to your solution, via the following:

Install-Package Autofac
Install-Package Autofac.Mvc5
Install-Package AutofacSerilogIntegration
Install-Package SerilogWeb.Classic

Once this is done, in the App_Start folder, create an IoCConfig.cs file. This is where we'll configure Autofac, Serilog and (bonus!) give Serilog Http Request correlation (so you can track http requests across the application).

There's a few new concepts with this stage, these being Serilog Enrichers, the Log Context, and how Serilog deals with Autofac.

Enrichers are classes that add extra information to the log entries. There are quite a few ways to do this, but for now we'll just focus on the basics. This works in close conjunction with the LogContext, which allows you to push properties to the context of the current Log item being pushed to Seq. The AutofacSerilogIntegration package provides an extension method used on the Autofac ContainerBuilder, for us to pass our logging implementation in.

SerilogWeb is a specific package that provides some enrichers that deal specifically with the Web side of things. This gives you out-of-the-box Http Request correlation on things like; Http Request Id, Session Id, UserNames and Request Trace Ids. If you want more information, head over to the GitHub page, and check it out.

    public static class IoCConfig
    {
        private static IContainer Container { get; set; }
        public static void Configure()
        {
            var logger = new LoggerConfiguration()
                .Enrich.FromLogContext()
                .Enrich.With<HttpRequestIdEnricher>()
                .WriteTo.Seq(ConfigurationManager.AppSettings["SeqUrl"])
                .CreateLogger();

            var builder = new ContainerBuilder();
            builder.RegisterLogger(logger);
            builder.RegisterControllers(typeof(WebApiApplication).Assembly);

            Container = builder.Build();
            DependencyResolver.SetResolver(new AutofacDependencyResolver(Container));
        }
    }

As you can see, things are starting to get a little meatier with this next step. We're calling the .Enrich property on the logger configuration class, asking Serilog to enrich all calls to Seq with the LogContext initially (so any changes we may want to make on the fly to the LogContext property will be used), and then we're specifying an out-of-the-box enricher from the SerilogWeb.Classic library, in the form of HttpRequestIdEnricher. This adds a HttpRequestId property to all calls to Seq.

After this, we're using Autofac to build our IoC container, and we're calling the extension method RegisterLogger and passing in our logger that we've configured above. This means that wherever we reference the ILogger Serilog Interface, Autofac will provide our logging configuration accordingly. Then we're registering the Controllers of our application, and setting the DependencyResolver, so things just Magically Work™.

Now, our controller changes slightly to the following:

    public class HomeController : Controller
    {
        private readonly ILogger _logger;

        public HomeController(ILogger logger)
        {
            _logger = logger;
        }
        public ActionResult Index()
        {
            _logger.Information("Invoking Index() Action with injected logger");
            ViewBag.Title = "Home Page";
            _logger.Information("Finished Index() Action with injected logger");
            return View();
        }
    }

If we build & run the application, and check our Seq logs, we should have the following:

Success! We now have a nicely injected ILogger with which to Log to our hearts content! Thats the Dream™...

... At least until things go wrong!

SelfLog and internal Serilog Exceptions

I must admit, one of my bugbears with Serilog is the fact it silently fails if your configuration is invalid, or if something else goes wrong. It will swallow the exception, and you'll be left scratching your head as to why you cant get any log output. Thankfully, Serilog provides the SelfLog property to assist in troubleshooting when things go wrong.

The usage for SelfLog is fairly straightforward. Enable it, and give it an output to write to when it realises something has gone wrong. A simple example is outputting to the Debug output window.

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

However, what I did for the commit linked above, was actually write the output to a text file:

    var location = HttpRuntime.AppDomainAppPath;
    var file = File.CreateText(location + "\\serilogexceptions.log");

    Serilog.Debugging.SelfLog.Enable(TextWriter.Synchronized(file));

Note the use of TextWriter.Synchronized, this is because the way SelfLog writes to the file by default isn't thread safe. Passing in your TextWriter to the TextWriter.Synchronized method ensures that Serilog writes to it in a safe manner.

To demonstrate this, I changed the SeqUrl application setting to an invalid url. Run the application and you should get something similar to the following:

Overall, I don't like how Serilog handles this aspect of itself. I would rather it throw an error in your face (like EntityFramework and Autofac do, when you misconfigure them), to let you know something is wrong. It's not a massive thing, just my own opinion. (It's also possible there is a way to do this, I just haven't found it yet!)

Lastly, I want to talk about ContextProperties, and the amazing way in which Serilog destructures data for logging.

Context Properties and Destructuring Log Data

In the third section, around ILogger injection, you'll notice we added .Enrich.FromLogContext to our configuration of Serilog. This lets us see any associated properties that have been pushed to the LogContext, for the given call to Seq. Personally, I find this one of the most powerful parts of Serilog. It gives us a very fine-grained control around the amount of information we push out with a log entry into Seq, and using it is very simple:

	LogContext.PushProperty("SomeProperty", "SomeValue")

The PushProperty method returns an IDisposable, so you can use this to effectively scope how long the properties hang around for. This, taken straight from the Serilog wiki, is a really good (contrived) example:

log.Information("No contextual properties");

using (LogContext.PushProperty("A", 1))
{
    log.Information("Carries property A = 1");

    using (LogContext.PushProperty("A", 2))
    using (LogContext.PushProperty("B", 1))
    {
        log.Information("Carries A = 2 and B = 1");
    }

    log.Information("Carries property A = 1, again");
}

In my PoC application, I've added a very basic json file data store, with a sample file containing player information from Counter-Strike: Global Offensive*, updated the Index view accordingly, and added a new Player view. I've scattered some logging throughout the HomeController, including when things potentially go wrong, to demonstrate the usefulness of ContextProperties.

public class HomeController : Controller
{
    private readonly ILogger _logger;
    private readonly IPlayerService _playerService;

    public HomeController(ILogger logger, IPlayerService playerService)
    {
        _logger = logger;
        _playerService = playerService;
    }
    public ActionResult Index()
    {
        _logger.Information("Attempting to load all players.");
        ViewBag.Title = "Home Page";

		var players = _playerService.GetPlayers();

        if(players.Count > 0)
        	_logger.Information("Found players");

        return View(players);
    }

    public ActionResult Player(string alias)
    {
        _logger.Information("Attempting to find player {alias}.", alias);
        var player = _playerService.GetPlayer(alias);
        if (player == null)
        {
            using (LogContext.PushProperty("PlayerCount", _playerService.GetPlayers().Count))
            _logger.Warning("Player {alias} not found. Valid players include: {players}", alias, _playerService.GetPlayers());

            _logger.Information("Redirecting to Index Action");
            return RedirectToAction("Index");
        }

        _logger.Information("Player with alias {alias} found, with name {name}", alias, player.Name);
        return View(player);
	}
}

There's a few things going on here. Initially, we're just logging informational entries to Seq, tracking when we hit the Index action, and that we've found some players to list.

When we try and hit the Player action, we log an informational entry to Seq, using handlebars in the message: _logger.Information("Attempting to find player {alias}.", alias); then passing the alias we are attempting to search for as the next argument.

This is where Serilog appends a new alias property to the log entry, and gives it a value of the next paramter passed in (in this case, our alias parameter on the action). Next, we actually try and retrieve the player from the PlayerService. If we don't find it, we log a Warning with Serilog, passing in the alias, and a players object as the second paramter.

I honestly think this part is pretty cool. Now, Serilog takes the structured data you've passed in, destructures it and appends it as a property on the log entry, storing it as raw json! We're also adding a new ContextProperty called PlayerCount, so if we were calling off to another external service, the PlayerCount property would be passed to the context of any inner calls to the ILogger interface.

If we run the application, view a player, and attempt to find an invalid player, you should see the following in your logs:

See the yellow circle in one of the log entries? This is the Warning signal recognised by Seq. Seq gives you the ability, on the right of that screenshot, to filter by different signals, which can be handy when you're in a hurry and need a quick filtered view of what's going on.

ContextProperties and Serilog destructuring are incredibly powerful tools at our disposal when interacting with Seq, and adding logging to our applications. I think it gives us a level of control and flexibility over our logging that, to be honest, I haven't seen elsewhere.

Gotchas

As is ever the case with any library, there are some Gotchas. The investigations I mentioned at the start of this post revolved around the conflicting configuration of Serilog itself. Because Serilog can be configured statically, it means that you can potentially have other sources modifying the configuration silently. We had an internal Nuget package attempting to configure its own Serilog configuration, which was throwing off our main configuration in the web application. This lead to some head-scratching as I was trying to figure out why my ContextProperties weren't being written at the times I expected. If you run into a similar situation, I think the best way of handling it would be to have the internal Nuget package expose a way to be given a logging configuration. I do believe the Autofac registrations also provide a slightly different way of solving this scenario, as you could use Modules for the internal package to provide its own logging configuration at registration time (however feel free to hit me up on Twitter if you think I'm wrong, or you have a better way!).

Wrapping up

And that's a wrap! Delving into Serilog has been quite interesting, and hopefully you've enjoyed reading this post as much as I've enjoyed writing it! I also hope this post has effectively demonstrated how darn useful Serilog and Seq are when used in conjunction with each other.

^{* If you're wondering 'Adam did you just contrive a situation so you could reference Counter-Strike in a technical blog post?' Yes. Yes I did :)}

Useful Links

Serilog Documentation

Edit: 15/6/2017 - Silly me had Add-Package instead of Install-Package :(