Razor Insights

Captain's Log

Written by Razor
Published on
How is your website/API doing at this precise moment in time? Is it up? Is it behaving as expected? Is it on fire? So many people think it’s okay to release software into the wild without even considering these questions - maybe ignorance is bliss after all. But seeing as data is such a trending topic in the tech scene, why do we continue to ignore the pitfalls of inadequate logging?

How is your website/API doing at this precise moment in time?

Is it up? Is it behaving as expected? Is it on fire? So many people think it’s okay to release software into the wild without even considering these questions - maybe ignorance is bliss after all. But as data is such a trending topic in the tech scene, why do we continue to ignore the pitfalls of inadequate logging?

Which framework should I use?

There are many .NET logging frameworks, two of the most common being are log4net and NLog. There are plenty of others, but they’re all very similar and lack a certain feature - structured logs. This is why Serilog outshines them all.

Serilog

Serilog has a concept called message templates, which are similar to .NET format strings, where parameters are stored in JSON. This means they can be processed intelligently as opposed to simply parsing the message text.

var command = new { Name = "Andrew Gunn" };
var elapsedMilliseconds = 10;

_logger.Information("Handled command in {ElapsedMilliseconds}ms. @{Command}", elapsedMilliseconds, command);

This example creates a single log entry and records two properties; ElapsedMilliseconds and Command.

{ "ElapsedMilliseconds": 10, "Command": { "Name": "Andrew Gunn" } }

The @ operator forces the value to be serialized instead of converting it to a string when the message is created.

10:18:24.103 [Information] Handled command in 10ms. { "Name": "Andrew Gunn" }

What/where/when should I log?

We use CQS (Command/Query Separation) where commands and queries logically distinguish reads and writes which provides us with two clean interfaces, ICommandHandler and IQueryHandler, each containing a single method called Handle. Without going into too much detail, we can add logging to ALL command handlers and ALL query handlers using just two logging decorators (one for each interface). This means that developers no longer have to worry about logging unless they want to capture something that is missed by the decorators. We can take this even further by creating a logging handler that wraps around HttpClient to gather information about calls to external systems. Do less, less often.

These centralised points for logging are great, but what about exceptions? We tend to create custom exceptions with additional data along with matching handlers that craft a bespoke response and return it to the user. In terms of an API, this is extremely powerful and means our controllers are even thinner because we’ve got some middleware that pairs up exceptions to a handler or uses a default one.

How do I know which log level to use?

As a rule of thumb, use LogInformation, and when that log level doesn’t feel right, follow these guidelines:

Log Level Description
LogError

These indicate that an exception handler doesn’t exist for the particular exception and is therefore unhandled. We only use this at the point where we pair exceptions to a handler in order to reduce false positives in the chance that the exception is handled further up.

LogWarning

These highlight an exception has been thrown but might be handled further up and only used within the logging decorators.

LogInformation

These contain important BAU information/data and can be called from anywhere although it’s recommend to keep them to a minimum and leverage decorators.

LogDebug

These contain more granular information/data that isn’t required in a production environment unless we want to carry out a deep investigation into an issue and can be used anywhere.

LogTrace

These contain low level information/data that can be called anywhere but should only be used for development purposes and therefore removed before going into the master branch.

Where do my logs go?

In the sink, obviously.

Serilog provides sinks for writing log events to storage in various formats.

Serilog has a wide variety of sinks but the ones worth pointing out are Console and Rolling File which are both pretty self-explanatory and ideal during local development.

Seq

Seq is a log server that supports structured logs and is therefore extremely powerful when combined with Serilog. As you’d expect, you can append logs to Seq using their sink.

Log.Logger = new LoggerConfiguration()
   .WriteTo.Seq("http://localhost:5341")
   .CreateLogger();

Because Seq recognises structured logs, you’re able to filter logs using a query syntax similar to SQL or C#/JavaScript. Another great feature is the ability to send notifications to Slack, HipChat, or even as an email. If that wasn’t enough, you can also utilise their API to create a custom integration.

Once you’re up and running with Seq, make sure you configure enough Signals (aka filters) to segregate the logs. We currently use one Seq instance installed on an Azure VM that receives logs from various components but we use a custom enricher to identify the source. Because Seq is installed using a standard Windows installer, you can run it locally to aid development/testing.

As of version 4.0, Seq allows you to create beautiful dashboards that can be displayed on monitors around the office to get immediate insight. We have a few of these (one for each component usually) that constantly rotate throughout the day.

Logging off

Now you’ve now got a better understanding of the importance of logging and more importantly, a few tools at your disposal, you can get to work making your systems more resilient.

If you need help putting any of this into practice, get in touch.