All about Structured logging - Introduction

History (Can Skip If not interested)

Two years back(2017) i was scrolling through my twitter feed and encountered a tweet that stated.

If your logs aren’t structured, I don’t know what you’re doing.

I usually don’t care about bold statements without any facts but this time it was from David Fowler so I was curious to find out the reasoning behind that strong statement. This is how i was introduced to Structured Logging. I have worked on few different products in last 2 years for different organisations and realised most of them were not using Structured Logging in their applications due to various different reasons. So i decided to write a blog series to share my learnings about Structured Logging to answer questions that most people had regarding the structured logging and i will try to highlight the benefits of structured logging. This blog series is inspired from different blog posts by Nicholas Blumhardt and few other resources that i found online including some Pluralsight Videos.

Get Started

I decided to share my knowledge about Structured Logging using 4 Post series in the hope that someone in community can benefits from it. I tried to make these post Beginner Friendly so may some expert reader may find it too basic. This is the first post of series.

All the posts from the series:

1. All about structured logging - Introduction(This Post)
2. Using Serilog for structured logging - Fundamentals
3. Serilog Recipes - Templates, LogContext, Enriching Logs etc
4. Application Insights for Structured Logging

By conventional logging - I mean text based loggers. That produce plain string/text data as result of logging.

How Structured logging is different from conventional logging

Conventional loggers (Example NLog) emit strings and persist them to some file or some other persistent storage. These logs are series of string and usually Human Friendly messages to explain the state/events of application at a given point of time(Timestamp). They are human friendly if they are small in size but not very Machine Friendly. By machine friendly i mean if you analyze them using some Application or Code you cannot deduce much from them. Because applications are good at understanding structured information instead of just lines of text. So the goal of Structured Logging is to log information in a way that it is both Human Friendly and Machine Friendly.

If the above explanation does not make sense let me try to explain with an example.

First have a look at some vary basic logging statement. Where log a string with some user friendly text and CustomId for which the current will get logged.

//Logging statement
Log.Information("Card replacement request received for CustomerId"+ customerId);

Now we will change that to something that will log a structured information(using Serilog) instead of just a string. Please do not worry about the details of the code statement we will get back to it later.

//How it will change in stuructured logging with serilog 
Log.Information("Card replacement request received for {CustomerId}", customerId);

Few words about serilog. It’s a library available for .NET applications that can help you write your logs as structured events. It is fairly easy to setup for your applications and api to log information is also very intuitive it is preferred choice for the structure logging in applications. More details about the `Serilog’ can be found at their Website. We will explain in depth about Serilog in next post of the series.

Now we will look at difference of the results that will be generated byt the above two statements

//Normal Logging will produce something like (PSEUDO Output and be different in real world)
"2016-06-01T02:23:10Z: INFO: Card replacement request received for customer-109972"

//Where as structure logging statement will produce something like below.
{
    "time": "2016-06-01T02:23:10Z",
    "level": "INF",
    "template": " Card replacement request received for customer-109972",
    "properties": {
        "customerId": " customer-109972"
    }
}

Few things to notice:

• In structured logging output we have user friendly string message.
• Some extra properties in form of a JSON object.
• Your log output is a structured JSON object instead of a simple string.

Next question. But how these JSON objects instead of simple strings going to help make your logging any better?

Let’s introduce Sinks to answer this question.

Any storage where we can store the structured logs is known as Sinks. Most probably you will not have to write any custom code for storage logic there are lot of solutions available in community to help with that one. You can use Application Insights, Seq and many other options.

In very layman terms Sinks is some persistent storage where you can Save you logs information. It can be as simple as some file system file or some third party software like Seq.

But we can get most value from Structured Logging if we use it in conjunction of a Sink that can provide some analytics capabilities over structured event logs. Few examples of such logging platform are Application Insights/Azure Monitor by Azure and Seq. They are identical in capabilities for most Use Cases. You can choose any of them depending on your needs. Concepts that are applicable in one of these Sinks can be easily translated to one another.

Let’s have a look at a simple example to demonstrate the benefits.

So we want to search for all the log entries that were saved for CustomerId customer-109972 that are logged after 2016-06-01T02:23:10Z. Let’s see how it will be different for Conventional Logging and Structured Logging.

For Conventional Text Based logs: One approach that i can think of quick is find the log files for given date and then quickly do a text search for customer-109972 in each of the files and copy/paste all the matches into a new file for the analysis.

For Structured Logging

Now lets see what i can do if is use Structured Logging with some appropriate Sink. Actually i can query the Logging information like any database using some query language. These query languages are specific to Sink you use but they are usually SQL like to help the end user with the adaption. So my search query for the above requirement can look something like.

-- PSEUDO Example we will explore actual queries later in last post of the series
-- This one is to demonstrate the differences in approach

select * from logs where customerId = 'customer-109972' and timestamp > "2016-06-01T00:0:00Z" and timestamp < "2016-06-01T00:0:00Z"

If you think the second way to analyze logs is your preferred way and your applications and Dev-ops process can benefit from it. I think then the structured logging is a good fit for your applications.

Moreover when your logs are Machine Friendly or Structured it enables lot of capabilities like where you can create automatic Alerts, Alarms and Reports for the data getting logged into the Sink of your choice. You don’t have to write any custom code for that most of time as they provided as features of the Sinks you are using.(More on this in last post of series)

We will explore all of these mentioned features in the future post. The purpose of this post was to make a use case for the Structured Logging for your applications. Intention was to introduce Structured Logging and small insight into it’s benefits.

But before we conclude this post i just want to give you small teaser about what to come next. So i will quickly introduce the two technologies that we will using to adding structured logging to our applications.

Say Hello to Serilog

Serilog is an open source project that provided an easy to implement and clean API for .net applications. It will allow you to log information as fully structured events more on that later. If you already have a logging library in your application/ecosystem. You must be wondering how different it will be to use Serilog in your applications instead of your existing logging library.

Here is a very simple example: The credit for this sample goes to Serilog website

var position = new { Latitude = 25, Longitude = 134 };
var elapsedMs = 34;
//if something like you have in your application 
log.Information(string.format("Processed {0} and {1} in {2} ms.",position.Latitude, position.Longitude, elapsedMs);

//Good new is this will still works but there is a better way to do it using serilog 
//you can do something like below
log.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);

//But you must be wondering how it is better the above statement will emit structured event that looks like
{"Position": {"Latitude": 25, "Longitude": 134}, "Elapsed": 34}

//What about the user friendly message ??
//Don't worry that will also be emitted 
//But we discuss in more details in next post about the serilog fundamentals 

More on the Serilog and it’s capabilities later(Next Post). This was just to appeal to your curiosity if this is something that can add value to your applications.

Introduction to Application Insights/Azure Monitor

Most probably you already may have heard about the application insights and even may be using them in your applications everyday. Don’t worry if you never heard about Application Insights. It’s a product from Microsoft available under Azure Monitor. It allows you to collect logs as structured events then Visualize and Analyze the collected logs.You can create reports and alerts from the results of the analysis of logging data. On some occasions you can predict the problems using the analytics of the logged information before the problem actually becomes a reality (Continuous performance reports). We will not dwell into further details about what application insights can offer it will be covered in the future post(Last post of the series) in the series.

Time to say goodbye (Shameless Plug)

We come to an end of the first post to introduce “Structured Logging” and small teaser about its benefits. Time for me to say goodbye but i will see you guys soon with another post about “Getting Started with Serilog” in that post we will look at some code examples how you can use serilog for structured logging in your applications.

If you like my posts remember your words of appreciation goes long way in inspiring me to keep writing. If you don’t want to Miss my future post follow me on Twitter Account.