Add structure to your log entries and bring your logs up to date

It used to be that logging was a bit of an after thought where a few statements such as ‘Connecting to the database’ or ‘Invalid user login’ were written to a text file that was rarely looked at.  Well things have moved on a fair bit since then.

Part 1 of 2.  Go here for part 2

Serilog and Seq

Serilog is a modern structured logging solution that allows you to add context to your logs so that you can easily track a particular execution path.  Seq (pronounced ‘seek’) gives you the ability to host, display and search those logs.

For instance, imagine a customer calling and saying that when they log into your swanky portal and go to their profile page they don’t see their address.  With structured logging you could easily highlight all the logged api calls made by that customer, filter to the profile page and follow the execution path through to the address query to see the actual data returned.

So simple!

To add a context to Serilog and log to it, you just use

LogContext.PushProperty("customerName", customerName);

Any further logging will now happen in that context, such as

logger.Information("Getting customer profile");
...
logger.Information("Customer address: {customerAddress}", customerAddress);

These two informational logs will now be tagged with the customer name. Notice also how Serilog uses a format similar to C# 6.0 string interpolation to embed variables. Doing it this way means you can filter by the variable in your logs.

An example

Here is a snapshot of a single log entry on our Seq server.

A seq view of a serilog entry, highlighting the use of a tagged context.

It is from a system we created to track users through online shops and it highlights several things;

• We are logging the entry point of all our API calls
• We have set tagging on Seq to display the entry point name at the beginning of the log entry (in this case it is ‘api/customers’) – this will then be displayed at the beginning of every subsequent log entry created during the execution of that particular api
• We have assigned a unique id to every httpRequest that comes through which can also be tagged or filtered
• We can also tag or filter by the Shop that was being tracked by the system

If I tell Seq to limit the log display to only ‘api/customer’ and also to filter by the httpRequestId I get the following (click to view full size);

Tracking the path of an api call through your code using Serilog and Seq

I can now see that the call to ‘customers/api’ generated three further calls from our server to external apis (to our analytics server). Clicking on any of those will show me the details of the call or the response as we embedded the information in the log.

If I had instead chosen to tag and filter by the shop name I could see all activity related to a particular online shop.

What is great about this is how easy it is to quickly narrow down the exact log entries you are looking for and having done so, inspect the state of whatever variables you chose to embed in your log.

Go try it yourself!

I strongly recommend you to go and try out both Serilog and Seq.  In the second part of this blog I show how we used Owin and middleware to create the entry point logging.

If you want to know even more, take a look this Pluralsight course.

Have fun!